forum.bitel.ru
http://forum.bitel.ru/

Обработка пакета авторизации (РЕШЕНО)
http://forum.bitel.ru/viewtopic.php?f=19&t=9587
Страница 1 из 1

Автор:  Угрюмов Роман [ 18 авг 2014, 17:17 ]
Заголовок сообщения:  Обработка пакета авторизации (РЕШЕНО)

Господа!
У нас используется схема авторизации с Opt82 с авторизацией по Id устройства:порт
Для этого написан специальный скрипт, алгоритм работы которого кратко выглядит так:

Код:
public class SmartEdgeClipsProtocolHandler
extends ru.bitel.bgbilling.modules.inet.dyn.device.redback.SmartEdgeClipsProtocolHandler
implements RadiusProtocolHandler, DhcpProtocolHandler
{
   protected void setAgentOptions( RadiusPacket request )
   {
            1) Вычислить из пакета Id устройства
            2) Если устройства с таким Id нет, то создать его.
            3) Вычислить из пакета порт
            4) Если такого порта(интерфейса) на устройстве нет, то создать интерфейс
            5) Найти договор с сервисом, у которого данный Id устройства:порт
            6) Если такого договора нет, то создать договор и установить на нем сервис с Id устройства:порт
         }
   @Override public void preprocessDhcpRequest( DhcpPacket request, DhcpPacket response )  throws Exception
   {
        }
}

Все работает устройства порты и договора создаются автоматически при подключении каждого нового клиента

Но! Иногда биллинг вызывает функцию setAgentOptions( RadiusPacket request ) без всякого пакета авторизации! Из логов я сегодня увидел, что произошло что-то

Код:
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] ContractRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.event.events.ContractStatusModifiedEvent] moduleId: 0; pluginId: no; cid: 90911; scid: -1; userId: 0; timestamp: 1408356571255
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Caught event: Event[ru.bitel.bgbilling.kernel.event.events.ContractStatusModifiedEvent] moduleId: 0; pluginId: no; cid: 90911; scid: -1; userId: 0; timestamp: 1408356571255
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] ContractRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.event.events.ContractStatusModifiedEvent] moduleId: 0; pluginId: no; cid: 90911; scid: -1; userId: 0; timestamp: 1408356571255
connection 08-18/14:09:31  INFO [sa-p-14-t-15] ServiceActivatorSet - Connecting to device
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Caught event: Event[ru.bitel.bgbilling.modules.inet.api.server.event.InetServModifiedEvent] moduleId: 1; pluginId: no; cid: 90911; scid: -1; userId: -1; timestamp: 1408356571317
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Adding new InetServRuntime: 204
connection 08-18/14:09:31  INFO [sa-p-14-t-15] ServiceActivatorDeviceWorker - Do task deviceId: 85; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaServModifyEvent] moduleId: 1; pluginId: no; cid: 90911; scid: -1; userId: -1; oldInetServ: null; newInetServ: 4:13090004; newInetServState: 1; newInetServOptionList: ; timestamp: 1408356571319
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Loading inetServ from database.
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Adding InetServRuntime: 204
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] InetServRuntimeMap - ContractId: 90911; status: 0; servId: 204
   4:13090004
   Options [] TariffModuleTreeSet [10:18.08.2014-…; ]
   Device state: -1; optionSet:
connection 08-18/14:09:31  INFO [sa-p-14-t-15] InetServRuntimeMap - Reload InetServRuntime: 204
connection 08-18/14:09:31  INFO [sa-p-14-t-15] InetServRuntimeMap - Removing InetServRuntime: 204
connection 08-18/14:09:31  INFO [sa-p-14-t-15] InetServRuntimeMap - Adding InetServRuntime: 204
connection 08-18/14:09:31  INFO [sa-p-14-t-15] InetServRuntimeMap - ContractId: 90911; status: 0; servId: 204
   4:13090004
   Options [] TariffModuleTreeSet [10:18.08.2014-…; ]
   Device state: -1; optionSet:
connection 08-18/14:09:31  WARN [sa-p-14-t-15] InetApplication - Accounting period not found for inetServ:204
connection 08-18/14:09:31  INFO [sa-p-14-t-15] InetApplication - OptionSet: []
connection 08-18/14:09:31  INFO [sa-p-14-t-15] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=1; inetServId: 204; call: true; oldState: -1; newState: 1; oldOptionSet: ; newOptionSet:
connection 08-18/14:09:31  INFO [sa-p-14-t-15] ServiceActivatorDeviceWorker - Processing deviceId:85; command ServiceActivatorEvent type=1; inetServId: 204; call: true; oldState: -1; newState: 1; oldOptionSet: ; newOptionSet:
connection 08-18/14:09:31  INFO [sa-p-14-t-15] ServiceActivatorSet - Invoking serviceCreate
connection 08-18/14:09:31  INFO [sa-p-14-t-15] ServiceActivatorDeviceWorker - Process event type[1] result=true
connection 08-18/14:09:31  INFO [sa-p-14-t-15] ServiceActivatorDeviceWorker - Changing InetServ:204 state and/or options
mq 08-18/14:09:31  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Caught event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 1; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 85; inetServId: 204; state: 1; optionSet: ; timestamp: 1408356571585


В результате чего у меня в 14:09:31 создалось устройство c id=13090004, порт = 4 и договор cid=90911 !!!!
В устройстве GPON 13090004 в этот момент ни в один порт не было воткнуто ни одного кабеля!!! Последний раз в 4-порту был WiFi роутер где то в обед два дня назад (подправил 19:34 а то не понятно)!
В логах BGInetAccess radius.log нет никаких сообщений о создании устройства, порта и договора в 14:09:31!
Что происходит? Как добиться что бы не было "самопроизвольного запуска" setAgentOptions( RadiusPacket request ) ???

Автор:  stark [ 18 авг 2014, 17:31 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

Если это наш SmartEdgeClipsProtocolHandler, то этом метод может вызываться если пришел radius access или accounting. Посмотрите логи radius не было ли запроса на авторизацию.

Зачем столько восклицательных знаков?

Автор:  Угрюмов Роман [ 18 авг 2014, 17:40 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

stark писал(а):
Если это наш SmartEdgeClipsProtocolHandler, то этом метод может вызываться если пришел radius access или accounting. Посмотрите логи radius не было ли запроса на авторизацию.

Да это ваш SmartEdgeClipsProtocolHandler, в котором я переписал функции под свои задачи

В radius.log Access - сервера пакетов на авторизацию нет:
Код:
08-18/14:08:30  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Checking data log files to close [hours=1]...
08-18/14:16:30  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Checking data log files to close [hours=1]...
08-18/14:16:30  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/radius/source_2/2014/2014-08/2014-08-18/log_2014-08-18-14.000.bgdl]


В radius.log Accounting сервера тоже нет пакетов в 14:09:31

Автор:  Amir [ 18 авг 2014, 20:04 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

Добавьте в ваш setAgentOption дополнительное логирование, чтобы потом grep'om можно было найти, когда и кем вызывался.

Вроде бы еще предобработка preprocessAccountingRequest вызывается при переобработке RADIUS-логов.

Автор:  Угрюмов Роман [ 18 авг 2014, 20:49 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

Метод setAgentOptions у меня залогирован по самое небалуйся. Завтра в личку кину его текст. Когда метод вызывается по приходу пакета авторизации, то в логе Access сервера я вижу все свои отладочные сообщения, которые пишу в лог.
В том то и весь прикол, что этот метод вызывается (скорее всего ИМХО) еще где-то, при этом записи в лог нет. Парадокс! Договор, устройство, порт создается корректно! Я вам и лог вышлю за 14:09:31.

Автор:  Угрюмов Роман [ 19 авг 2014, 12:22 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

У меня еще смутные подозрения. А может быть так, что Java-машина после редактирования и перекомпиляции кода в BGBilling и перезагрузки BGAccess берет код из кэша? То есть то что было до внесения изменений и компиляции?

Автор:  Amir [ 19 авг 2014, 13:14 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

Да, но не совсем так - ProtocolHandler и ServiceActivator используются старые пока не нажмете перечитать конфигурацию на серверах или не перезапустите Access/Accounting.

Автор:  Угрюмов Роман [ 19 авг 2014, 14:33 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

Amir! Биллинг вызывает дважды обработчик
Код:
protected void setAgentOptions( RadiusPacket request )
при приходе пакета авторизации!!!

как я это вычислил. Я навтыкал в обработчик массу logger.info( "текст сообщения" ); и смотрю что происходит.
В 11:33:53 пришел пакет авторизации, скрипт начал его обрабатывать. Алгоритм проверил, что есть устройство, но на данном устройстве нет порта, на котором клиент собирается авторизоваться.
Алгоритм создает порт и устанавливает:

Код:
request.setOption( InetRadiusProcessor.AGENT_REMOTE_ID, deviceIdString); //Поиск агента по серийному номеру
request.setOption( InetRadiusProcessor.INTERFACE_ID, devicePort ); //Поиск по порту

Где
Код:
deviceIdString = "AUTOCREATE"; //Авторизуемся на специальном договоре с сервисом в статусе Отключено, что бы получить Reject и
devicePort = 1; // заставить устройство еще раз выслать пакет авторизации

В этот момент ветка алгоритма, где создается договор не отрабатывает. Через 2-3 секунды должен прийти снова запрос на авторизацию. Тогда устройство и порт будут уже существовать. Алгоритм создает договор и авторизует на нем клиента.
Внимание!!! В 11:33:53 в логах MQ я вижу:
Код:
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntimeMap - (Re)loading InetDeviceRuntimeMap
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntime - Reload protocolHandler class for device: RootType: Root
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntime - Reload SA classes for device: RootType: Root
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntime - Reload protocolHandler class for device: Redback: RedBack [172.16.98.7]
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntime - Reload SA classes for device: Redback: RedBack [172.16.98.7]
08-19/11:33:53  WARN [event-proc-p-2-t-1] RadiusDictionary - Radius attribute Deactivate-Service-Name:1 not found in dictionary!
....
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntime - Reload protocolHandler class for device: QTech GPON: 13090004
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntime - Reload SA classes for device: QTech GPON: 13090004
08-19/11:33:53  WARN [event-proc-p-2-t-1] RadiusDictionary - Radius attribute Deactivate-Service-Name:1 not found in dictionary!
....
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDeviceRuntimeMap - Load inetDeviceRuntimeMap complete. Loaded 27 inetDevices.
08-19/11:33:53  INFO [AccessReload-1] Access - childrenDeviceIds=[68, 1, 32, 2, 33, 38, 67, 76, 12, 75, 85, 17, 16, 84, 19, 18, 86, 20, 23, 22, 25, 24, 27, 29, 28, 31, 30]
08-19/11:33:53  INFO [AccessReload-1] InetConnectionManager - Loading connections from database.
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDhcpDeviceMap - Load DHCP relay list, types: [2].
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetDhcpDeviceMap - Loaded device: 2
08-19/11:33:53  INFO [pool-5-thread-1] InetDhcpDeviceMap - Bind device: 2; 172.16.98.7
08-19/11:33:53  INFO [event-proc-p-2-t-1] ContractRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.event.events.ContractStatusModifiedEvent] moduleId: 0; pluginId: no; cid: 90923; scid: -1; userId: 0; timestamp: 1408433633752
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Caught event: Event[ru.bitel.bgbilling.kernel.event.events.ContractStatusModifiedEvent] moduleId: 0; pluginId: no; cid: 90923; scid: -1; userId: 0; timestamp: 1408433633752
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Caught event: Event[ru.bitel.bgbilling.modules.inet.api.server.event.InetServModifiedEvent] moduleId: 1; pluginId: no; cid: 90923; scid: -1; userId: -1; timestamp: 1408433633804
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Adding new InetServRuntime: 216
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Loading inetServ from database.
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Adding InetServRuntime: 216
08-19/11:33:53  INFO [event-proc-p-2-t-1] InetServRuntimeMap - ContractId: 90923; status: 0; servId: 216
   1:13090004
   Options [] TariffModuleTreeSet [10:19.08.2014-…; ]
   Device state: -1; optionSet:
08-19/11:33:54  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Caught event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 1; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 85; inetServId: 216; state: 1; optionSet: ; timestamp: 1408433634128
08-19/11:33:55  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Caught event: Event[ru.bitel.bgbilling.modules.inet.api.server.event.InetAccountingPeriodModifiedEvent] moduleId: 1; pluginId: no; cid: 90923; scid: -1; userId: 0; timestamp: 1408433635405
08-19/11:33:57  INFO [event-proc-p-2-t-1] InetConnectionManager - Add connection: InetConnection [id=45643-0, iface=2:50528256, sessId=0202FFFF78001818-53F2FD45, start=19.08.2014 11:33:57, uname=0006001fce109dc5:000e0064000701515445431309000401, addr=185.23.81.2]

То есть в 11:33:53 совершенно логично вызвался обработчик для обработки пакета авторизации, в котором я создал порт. И каким то чудом, сразу же еще раз повторно вызвался обработчик setAgentOptions! Поскольку устройство и порт уже есть, то стала отрабатываться ветка создания договора на устройстве 13090004!!!
Вот строчка
08-19/11:33:53 INFO [event-proc-p-2-t-1] InetServRuntimeMap - ContractId: 90923; status: 0; servId: 216 1:13090004
cid=90923 это как раз этот договор, servId=216 это сервис на этом договоре!
Причем в логах Access radius.log нет никаких сообщений от этого повторного запуска!!! На первый запуск при приходе пакета есть записи лога, а при повторном нет. Но запуск есть!!! Договор создается!

Это я к тому написал, что регулярно у меня появляются "фантомные договора" которые создаются в функции setAgentOptions, которая вызывается биллингов БЕЗ ПРИХОДА ПАКЕТА АВТОРИЗАЦИИ!!!
я завтра уезжаю в отпуск на неделю. Буду на работе 28 августа. Готов заплатить из личных средств за разрешение данной проблемы (но что бы директор не знал :-) )

Автор:  stark [ 19 авг 2014, 14:48 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

там же эту функция вызывается не только на пакет авторизации, но и start-пакет например. Может быть в этом причина ?

Автор:  Угрюмов Роман [ 19 авг 2014, 14:59 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

stark писал(а):
там же эту функция вызывается не только на пакет авторизации, но и start-пакет например. Может быть в этом причина ?

Нашел!!! В 11:33:53 Пришел еще Accounting-пакет
Код:
radius 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 91
Authenticator: {D7 2E 48 A7 7F D3 6F 68 F0 C8 44 AE FB 12 C0 A3}
....
radius 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] SmartEdgeClipsProtocolHandler - AutoCreate routine started!!!
radius 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] SmartEdgeClipsProtocolHandler - Set comment: АвтоСоздан  19.08.2014  11:33:53
radius 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] CommonKernelEventProcessor - Process event cid:0; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 0; scid: -1; userId: 0; timestamp: 1408433633746
radius 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] CommonKernelEventProcessor - Process event cid:90923; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 90923; scid: -1; userId: 0; timestamp: 1408433633784
radius 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] SmartEdgeClipsProtocolHandler - inetServUpdate! deviceId:85 cid: 90923
script 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] ScriptEventListener - Caught event: ru.bitel.bgbilling.modules.inet.api.server.event.InetServChangingEvent
script 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] ScriptEventListener - Process time => 7
script 08-19/11:33:53  INFO [rdsLstnr-p-8-t-7] ScriptEventListener - ClipsLoginGenerator Start! deviceId = 85 inetServ.getTypeId() = 1
Setting userName:1:13090004
...

Вот тут я и создал договор! Теперь все начинает проясняться!!!
Как отличить в обработчике, на какой пакет он был вызван? То есть как отличить пакет авторизации от Accounting -пакета?
Это оно getCode() Получение типа пакета (например, ACCESS_REQUEST ACCOUNTING_REQUEST). ?

Автор:  stark [ 19 авг 2014, 15:14 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

Угрюмов Роман писал(а):
Вот тут я и создал договор! Теперь все начинает проясняться!!!
Как отличить в обработчике, на какой пакет он был вызван? То есть как отличить пакет авторизации от Accounting -пакета?
Это оно getCode() Получение типа пакета (например, ACCESS_REQUEST ACCOUNTING_REQUEST). ?


Да.

Код:
if ( packet.getCode() == RadiusPacket.ACCESS_REQUEST ) )
{
..
}


Автор:  Угрюмов Роман [ 19 авг 2014, 15:58 ]
Заголовок сообщения:  Re: Обработка пакета авторизации от ОТСУТСТВУЮЩЕГО устройств

Это была эпопея... Нет слов выразить благодарность за помощь в отлавливании глюка. Мой скрипт реагировал на Accounting пакеты. Теперь все вроде должно работать. (тьфу тьфу тьфу)

Страница 1 из 1 Часовой пояс: UTC + 5 часов [ Летнее время ]
Powered by phpBB® Forum Software © phpBB Group
http://www.phpbb.com/