BiTel

Форум BiTel		 bgbilling.ru     docs.bitel.ru     wiki.bitel.ru     dbinfo.bitel.ru     bgcrm.ru     billing.bitel.ru     bitel.ru    
Текущее время: 21 июн 2025, 05:10

Сообщения без ответов | Активные темы


Список форумов » BGBilling » Модули Интернета » Модуль Inet

Часовой пояс: UTC + 5 часов [ Летнее время ]



Начать новую тему Ответить на тему  Страница 1 из 2
  [ Сообщений: 32 ]  На страницу 1, 2  След.
  Версия для печати Пред. тема | След. тема 
Автор Сообщение
Cromeshnic
 Заголовок сообщения: [BUG?] Иногда не подключается турбо
СообщениеДобавлено: 29 июл 2014, 14:42 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Вопрос: как работает сплит сессии по т.опции одновременно с connectionModify?

Схема такая: в 8:00 утра проходит скрипт, который определённым клиентам подключает тарифную опцию "Турбо ускорение" на день. Клиентов таких стало много, скрипт работает каждый день минут по 10 - там добавлен таймаут, насколько помню, чтобы радиус-сервер не загибался. А опция имеет режим активации "с текущего часа", т.е. подключается немного "задним числом" - с 8:00.
Так вот, в модуле Inet некоторым клиентам ISG-сервис TURBO подлключается, а некоторым - нет. При этом на сервисе опция модуля Inet прописана. Клиенты всегда одни и те же (вероятно, зависит от их порядка в списке). Т.е. иногда не уходит CoA. Если тому же клиенту сбросить сессию, то ISG-сервис TURBO выдаётся. В 19:00 скрипт отключает всем эти тарифные опции - при этом всем CoA на отключение ISG-сервиса TURBO уходит нормально, даже тем, кому он не включился.

Я думаю, это как-то связано со сплитом сессии при подключении тарифной опции, и, возможно, с режимомо "с текущего часа", т.к. сплит при этом происходит задним числом.

v 5.2

Щас приложу логи.


Последний раз редактировалось Cromeshnic 29 июл 2014, 15:20, всего редактировалось 2 раз(а).

Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 29 июл 2014, 15:14 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Вот логи из all.log по сервису, которому CoA не ушло:
(должна подключиться опция модуля 103 - сервис IPOE-TURBO5M)

Код:
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 189494; scid: -1; userId: 0; deviceId: 23; inetServId: 10411; connectionId: 0; options: 103,155,349,74,15; timestamp: 1406588526048
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 10411; call: true; oldState: 1; newState: 1; oldOptionSet: 155,203,74,15; newOptionSet: 103,155,349,74,15
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Processing deviceId:23; command ServiceActivatorEvent type=2; inetServId: 10411; call: true; oldState: 1; newState: 1; oldOptionSet: 155,203,74,15; newOptionSet: 103,155,349,74,15
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorSet - Invoking serviceModify
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Changing InetServ:10411 state and/or options
mq 07-29/08:02:06  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 23; inetServId: 10411; state: -1000; optionSet: 103,155,349,74,15; timestamp: 1406588526135
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 189494; scid: -1; userId: 0; deviceId: 23; inetServId: 10411; connectionId: 3764; options: 103,155,349,74,15; timestamp: 1406588526051


Вот лог по сервису, где всё ок:
(подключается опция модуля 104 - сервис IPOE-TURBO10M)
Код:
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorSet - Connecting to device
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 183740; scid: -1; userId: 0; deviceId: 21; inetServId: 9614; connectionId: 0; options: 33,350,196,104,165,74; timestamp: 1406588806390
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9614; call: true; oldState: 1; newState: 1; oldOptionSet: 33,266,196,74,165; newOptionSet: 33,350,196,104,165,74
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9614; call: true; oldState: 1; newState: 1; oldOptionSet: 33,266,196,74,165; newOptionSet: 33,350,196,104,165,74
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorSet - Invoking serviceModify
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Changing InetServ:9614 state and/or options
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 183740; scid: -1; userId: 0; deviceId: 21; inetServId: 9614; connectionId: 2260; options: 33,350,196,104,165,74; timestamp: 1406588806393
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9614; call: true; oldState: 1; newState: 1; oldOptionSet: 33,266,196,74,165; newOptionSet: 33,350,196,104,165,74
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9614; call: true; oldState: 1; newState: 1; oldOptionSet: 33,266,196,74,165; newOptionSet: 33,350,196,104,165,74
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorSet - Invoking connectionModify
mq 07-29/08:06:46  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9614; state: -1000; optionSet: 33,196,350,74,165,104; timestamp: 1406588806583
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ISGServiceActivator - Connection modify: oldState: 1; newState: 1; oldOptionSet: [33, 266, 196, 74, 165]; newOptionSet: [33, 350, 196, 104, 165, 74]
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ISGServiceActivator - Sending commands to deactivate services (mode=1): []
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ISGServiceActivator - Sending commands to activate services (mode=1): [IPOE-TURBO10M]
connection 07-29/08:06:46  INFO [sa-p-12-t-2] RadiusClient - Sending to /x.x.x.x:1700
Packet type: CoA-Request
Identifier: 157
Authenticator: {54 C0 F4 F8 AB 43 F6 F5 69 3B C4 B0 41 BA E7 21}
Attributes:
  User-Name=nas-port:x.x.x.x:0/0/3/106.2011
  Acct-Session-Id=0/0/3/106.2011_8300000000148F16
  cisco-SSG-Command-Code=\0xbIPOE-TURBO10M

connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 07-29/08:06:46  INFO [sa-p-12-t-2] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 183740; scid: -1; userId: 0; deviceId: 21; inetServId: 9614; connectionId: 0; options: 33,350,196,104,165,74; timestamp: 1406588806552
connection 07-29/08:06:46  INFO [rds-clnt-/x.x.x.x-1700] RadiusClient - Recieved from /x.x.x.x:1700
Packet type: CoA-ACK
Identifier: 157
Authenticator: {9A 13 E3 F9 96 2C DF 09 10 CE E2 97 5D 6A 68 21}
Attributes:
  cisco-SSG-Command-Code=\0xbIPOE-TURBO10M
  cisco-SSG-Account-Info=Sy.y.y.y
  cisco-SSG-Account-Info=$IGigabitEthernet0/0/3.20110106


В первом случае не было "Invoking connectionModify", т.е. как будто бы не было коннекшена, хотя фактически он был - на устройстве сессия не рвалась. Возможно в этот момент был сплит сессии?

Код:
mysql> select id, connectionId, sessionStart, sessionStop from inet_session_log_28_201407 where servId=10411 and parentId=0 and date(sessionStart) ='2014-07-29';
+-------+--------------+---------------------+---------------------+
| id    | connectionId | sessionStart        | sessionStop         |
+-------+--------------+---------------------+---------------------+
| 33381 |         3764 | 2014-07-29 00:00:00 | 2014-07-29 07:59:59 |
| 34611 |         3764 | 2014-07-29 08:00:00 | 2014-07-29 17:26:07 |
+-------+--------------+---------------------+---------------------+
2 rows in set (0.00 sec)
Вернуться к началу
 Профиль  
 
stark
СообщениеДобавлено: 29 июл 2014, 16:05 
Не в сети
Разработчик

Зарегистрирован: 08 ноя 2007, 01:05
Сообщения: 8343
Откуда: Уфа
Карма: 238
Cromeshnic писал(а):
Вопрос: как работает сплит сессии по т.опции одновременно с connectionModify?

Схема такая: в 8:00 утра проходит скрипт, который определённым клиентам подключает тарифную опцию "Турбо ускорение" на день. Клиентов таких стало много, скрипт работает каждый день минут по 10 - там добавлен таймаут, насколько помню, чтобы радиус-сервер не загибался. А опция имеет режим активации "с текущего часа", т.е. подключается немного "задним числом" - с 8:00.
Так вот, в модуле Inet некоторым клиентам ISG-сервис TURBO подлключается, а некоторым - нет. При этом на сервисе опция модуля Inet прописана. Клиенты всегда одни и те же (вероятно, зависит от их порядка в списке). Т.е. иногда не уходит CoA. Если тому же клиенту сбросить сессию, то ISG-сервис TURBO выдаётся. В 19:00 скрипт отключает всем эти тарифные опции - при этом всем CoA на отключение ISG-сервиса TURBO уходит нормально, даже тем, кому он не включился.

Я думаю, это как-то связано со сплитом сессии при подключении тарифной опции, и, возможно, с режимомо "с текущего часа", т.к. сплит при этом происходит задним числом.

v 5.2

Щас приложу логи.


А почему нельзя без всяких планировщиков просто установить действующую опцию для нужных клиентов и в тарифе прописать правила для этой опции в определенным часы.
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 29 июл 2014, 16:25 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Это делалось ещё на dialup и для многих клиентов ещё в dialup работает - там нужно CoA отправлять по событию смены опции, а не по часам. Мб ещё были какие-то соображения, не помню. В данном случае непринципиально. Даже если сделать обычную турбокнопку, которую врубают из личного кабинета, то наверняка будет подобная картина.
Вернуться к началу
 Профиль  
 
Amir
СообщениеДобавлено: 29 июл 2014, 19:47 
Не в сети
Разработчик
Аватара пользователя

Зарегистрирован: 19 дек 2006, 21:04
Сообщения: 5970
Карма: 256
Цитата:
connection 07-29/08:02:06 INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 189494; scid: -1; userId: 0; deviceId: 23; inetServId: 10411; connectionId: 0; options: 103,155,349,74,15; timestamp: 1406588526048
connection 07-29/08:02:06 INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 10411; call: true; oldState: 1; newState: 1; oldOptionSet: 155,203,74,15; newOptionSet: 103,155,349,74,15
connection 07-29/08:02:06 INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Processing deviceId:23; command ServiceActivatorEvent type=2; inetServId: 10411; call: true; oldState: 1; newState: 1; oldOptionSet: 155,203,74,15; newOptionSet: 103,155,349,74,15
connection 07-29/08:02:06 INFO [sa-p-12-t-8] ServiceActivatorSet - Invoking serviceModify
connection 07-29/08:02:06 INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 07-29/08:02:06 INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Changing InetServ:10411 state and/or options
mq 07-29/08:02:06 INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 23; inetServId: 10411; state: -1000; optionSet: 103,155,349,74,15; timestamp: 1406588526135
connection 07-29/08:02:06 INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 189494; scid: -1; userId: 0; deviceId: 23; inetServId: 10411; connectionId: 3764; options: 103,155,349,74,15; timestamp: 1406588526051
А что дальше? Последняя строчка это как раз вроде бы изменение соединения. Т.е. Accounting как-будто команду послал нормально.
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 29 июл 2014, 21:30 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
О, не заметил connectionId

Но дальше я не нашел в логах ничего.
Хотя завтра ещё поищу.
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 30 июл 2014, 07:49 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Вот кусок grep "sa-p-12-t-8" all.log.bkp :

Код:
connection 07-29/08:02:06  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 189494; scid: -1; userId: 0; deviceId: 23; inetServId: 10411; connectionId: 3764; options: 103,155,349,74,15; timestamp: 1406588526051
connection 07-29/08:02:11  INFO [sa-p-12-t-8] ServiceActivatorSet - Disconnecting from device
connection 07-29/08:02:42  INFO [sa-p-12-t-8] ServiceActivatorSet - Connecting to device
connection 07-29/08:02:42  INFO [sa-p-12-t-8] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 192161; scid: -1; userId: 0; deviceId: 23; inetServId: 10387; connectionId: 0; options: 103,154,349,74,14; timestamp: 1406588562678


- нет ничего интересного.
Последняя строчка - обработка уже другого сервиса.

Сегодня то же самое. Причём, не включается у большинства.
Сбрасывал сессии вручную - при подключении атрибут выдаётся.
Сделал выборку, чтобы отлавливать таких клиентов:
Код:
select cto.cid from contract_tariff_option cto left join inet_serv_28 s on cto.cid=s.contractId and s.parentId=0 left join inet_connection_28 con on s.id=con.servId and con.username like 'IPOE-TURBO%' where cto.option_id=39 and not s.id is null and cto.time_to is null and con.id is null group by cto.cid;


В хелпдеске тему создать?
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 30 июл 2014, 09:01 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Включил дебаг, зарядил бэкап all.log на завтрашнее утро, чтобы не затёрся
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 31 июл 2014, 07:04 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Ну естественно сегодня всё отработало отлично - непонятно, почему.
Access/Accounting не перегружал, но вчера сбросил все такие сессии - наверное с этим связано как-то.

Код:
mysql> select cto.cid from contract_tariff_option cto left join inet_serv_28 s on cto.cid=s.contractId and s.parentId=0 left join inet_connection_28 con on s.id=con.servId and con.username like 'IPOE-TURBO%' where cto.option_id=39 and not s.id is null and cto.time_to is null and con.id is null group by cto.cid;
Empty set (0.00 sec)
Вернуться к началу
 Профиль  
 
Amir
СообщениеДобавлено: 31 июл 2014, 20:52 
Не в сети
Разработчик
Аватара пользователя

Зарегистрирован: 19 дек 2006, 21:04
Сообщения: 5970
Карма: 256
Кстати, а в самом соединении (inet_connection) deviceOptionIds при этом был как-будто отработало нормально (т.е. опция добавилась в это поле)? Или же там правильно отображалось, без этой опции?
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 04 авг 2014, 08:21 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Во, сегодня опять.
Счас посмотрю логи и пр.

Код:
mysql> select cto.cid from contract_tariff_option cto left join inet_serv_28 s on cto.cid=s.contractId and s.parentId=0 left join inet_connection_28 con on s.id=con.servId and con.username like 'IPOE-TURBO%' where cto.option_id=39 and not s.id is null and cto.time_to is null and con.id is null group by cto.cid;
+--------+
| cid    |
+--------+
| 143037 |
| 143138 |
| 143172 |
| 143340 |
| 143366 |
| 143636 |
| 143708 |
| 166205 |
| 171471 |
| 175395 |
| 180271 |
| 186198 |
| 187802 |
| 189156 |
| 189494 |
| 190711 |
| 192161 |
| 192466 |
| 193383 |
| 193883 |
| 193920 |
| 194377 |
| 196206 |
| 197296 |
| 197403 |
| 200947 |
| 201596 |
| 201600 |
| 202203 |
| 202654 |
+--------+
30 rows in set (0.17 sec)

mysql> select cto.cid from contract_tariff_option cto left join inet_serv_28 s on cto.cid=s.contractId and s.parentId=0 left join inet_connection_28 con on s.id=con.servId and con.username like 'IPOE-TURBO%' where cto.option_id=39 and not s.id is null and cto.time_to is null and not con.id is null group by cto.cid;
+--------+
| cid    |
+--------+
| 183740 |
| 192466 |
| 194741 |
+--------+
3 rows in set (0.02 sec)
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 04 авг 2014, 08:23 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Amir писал(а):
Кстати, а в самом соединении (inet_connection) deviceOptionIds при этом был как-будто отработало нормально (т.е. опция добавилась в это поле)? Или же там правильно отображалось, без этой опции?


Есть: id опции =104

Код:
mysql> select * from inet_connection_28 where id=10343;
+-------+----------+----------+------------+---------------+---------------------------------+---------------------------------------+------+------------+--------+-----------------+------------------+--------------+-----------+---------------------+-------------+-------------------+--------+
| id    | parentId | deviceId | devicePort | agentDeviceId | acctSessionId                   | username                              | type | accessCode | servId | calledStationId | callingStationId | ipResourceId | ipAddress | connectionStart     | deviceState | deviceOptions     | status |
+-------+----------+----------+------------+---------------+---------------------------------+---------------------------------------+------+------------+--------+-----------------+------------------+--------------+-----------+---------------------+-------------+-------------------+--------+
| 10343 |        0 |       21 |    2697525 |             0 | 0/0/2/177.2211_8300000000292935 | nas-port:x.x.x.x:0/0/2/177.2211 |    2 |          0 |   9515 |                 |                  |            0 | NULL      | 2014-07-30 10:17:59 |           1 | 17,74,104,157,350 |      1 |
+-------+----------+----------+------------+---------------+---------------------------------+---------------------------------------+------+------------+--------+-----------------+------------------+--------------+-----------+---------------------+-------------+-------------------+--------+
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 04 авг 2014, 08:41 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Ага, вот оно!
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] InetSaOptionsModifyEvent - InetConnection deviceOptions already [17, 157, 350, 104, 74]

Т.е. он считает, что опции уже применены, хотя это было не так:

connection 08-04/08:01:08 INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,205,157,74; newOptionSet: 17,157,350,104,74

Возможно, это связано с тем, что у меня 2 ServiceActivator-а на разных уровнях:
Вложение:
DeviceTree.png
DeviceTree.png [ 5.64 КБ | Просмотров: 9961 ]


Верхний - самописный для SCE: определяем по набору опций packageId и отправляем в ActiveMQ событие на смену (дальше его ловит внешнее приложение) - он отработал:
Код:
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorSet - Invoking serviceModify
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] ProfileExtractor - monitor = 0 < * == (def)[monitor:off] ==> *{0} >
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] ProfileExtractor - packageId = 158 < * == [speed:sce-speed:turbo10M] ==> * == (def)[p2p:on] ==> * == (def)[social:on] ==> *{158} >
mq 08-04/08:01:08 DEBUG [sa-p-12-t-10] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407106868796
mq 08-04/08:01:08 DEBUG [sa-p-12-t-10] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407106868868
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Process event type[2] result=true


А ISGServiceActivator - нет.

Вот весь лог:
Код:
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 17,157,350,104,74; timestamp: 1407106868777
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 17,157,350,104,74; timestamp: 1407106868777
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,205,157,74; newOptionSet: 17,157,350,104,74
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,205,157,74; newOptionSet: 17,157,350,104,74
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorSet - Invoking serviceModify
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] ProfileExtractor - monitor = 0 < * == (def)[monitor:off] ==> *{0} >
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] ProfileExtractor - packageId = 158 < * == [speed:sce-speed:turbo10M] ==> * == (def)[p2p:on] ==> * == (def)[social:on] ==> *{158} >
mq 08-04/08:01:08 DEBUG [sa-p-12-t-10] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407106868796
mq 08-04/08:01:08 DEBUG [sa-p-12-t-10] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407106868868
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Changing InetServ:9515 state and/or options
mq 08-04/08:01:08 DEBUG [sa-p-12-t-10] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,157,350,104,74; timestamp: 1407106868880
mq 08-04/08:01:08 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGInetAccess-Inet-IPoE Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,157,350,74,104; timestamp: 1407106868880
mq 08-04/08:01:08  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,157,350,74,104; timestamp: 1407106868880
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 10343; options: 17,157,350,104,74; timestamp: 1407106868780
connection 08-04/08:01:08  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 10343; options: 17,157,350,104,74; timestamp: 1407106868780
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] InetSaOptionsModifyEvent - InetConnection deviceOptions already [17, 157, 350, 104, 74]
connection 08-04/08:01:08 DEBUG [sa-p-12-t-10] ServiceActivatorDeviceWorker - Skip event
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 04 авг 2014, 21:56 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
up?
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 05 авг 2014, 07:34 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Судя по истории сессий, опции как-то некорректно работают.

С 8:00 до 19:00 должна быть опция 104, в остальное время -нет.
Разрывы в другое время, кроме 0, 8 и 19 часов - руками сбрасывал, чтобы включить турбо.

Код:
mysql> select sessionStart, sessionStop, deviceOptions from inet_session_log_28_201407 where servId=9515 and parentId=0 order by sessionStart;
+---------------------+---------------------+-------------------+
| sessionStart        | sessionStop         | deviceOptions     |
+---------------------+---------------------+-------------------+
| 2014-07-16 17:12:53 | 2014-07-16 19:00:55 | 17,74,157,205     |
| 2014-07-16 19:00:56 | 2014-07-16 23:59:59 | 17,74,157,205     |
| 2014-07-17 00:00:00 | 2014-07-17 07:59:59 | 17,74,157,205     |
| 2014-07-17 08:00:00 | 2014-07-17 19:00:55 | 17,74,104,157,350 |
| 2014-07-17 19:00:56 | 2014-07-17 23:59:59 | 17,74,104,157,350 |
| 2014-07-18 00:00:00 | 2014-07-18 07:59:59 | 17,74,104,157,350 |
| 2014-07-18 08:00:00 | 2014-07-18 19:00:55 | 17,74,104,157,350 |
| 2014-07-18 19:00:56 | 2014-07-18 23:59:59 | 17,74,104,157,350 |
| 2014-07-19 00:00:00 | 2014-07-19 07:59:59 | 17,74,104,157,350 |
| 2014-07-19 08:00:00 | 2014-07-19 19:00:54 | 17,74,104,157,350 |
| 2014-07-19 19:00:55 | 2014-07-19 23:59:59 | 17,74,104,157,350 |
| 2014-07-20 00:00:00 | 2014-07-20 07:59:59 | 17,74,104,157,350 |
| 2014-07-20 08:00:00 | 2014-07-20 19:00:53 | 17,74,104,157,350 |
| 2014-07-20 19:00:54 | 2014-07-20 23:59:59 | 17,74,104,157,350 |
| 2014-07-21 00:00:00 | 2014-07-21 07:59:59 | 17,74,104,157,350 |
| 2014-07-21 08:00:00 | 2014-07-21 19:00:59 | 17,74,104,157,350 |
| 2014-07-21 19:01:00 | 2014-07-21 23:59:59 | 17,74,104,157,350 |
| 2014-07-22 00:00:00 | 2014-07-22 07:59:59 | 17,74,104,157,350 |
| 2014-07-22 08:00:00 | 2014-07-22 19:01:00 | 17,74,104,157,350 |
| 2014-07-22 19:01:01 | 2014-07-22 23:59:59 | 17,74,104,157,350 |
| 2014-07-23 00:00:00 | 2014-07-23 07:59:59 | 17,74,104,157,350 |
| 2014-07-23 08:00:00 | 2014-07-23 19:00:58 | 17,74,104,157,350 |
| 2014-07-23 19:00:59 | 2014-07-23 23:59:59 | 17,74,104,157,350 |
| 2014-07-24 00:00:00 | 2014-07-24 07:59:59 | 17,74,104,157,350 |
| 2014-07-24 08:00:00 | 2014-07-24 19:00:57 | 17,74,104,157,350 |
| 2014-07-24 19:00:58 | 2014-07-24 23:59:59 | 17,74,104,157,350 |
| 2014-07-25 00:00:00 | 2014-07-25 07:59:59 | 17,74,104,157,350 |
| 2014-07-25 08:00:00 | 2014-07-25 19:01:01 | 17,74,104,157,350 |
| 2014-07-25 19:01:02 | 2014-07-25 23:59:59 | 17,74,104,157,350 |
| 2014-07-26 00:00:00 | 2014-07-26 07:59:59 | 17,74,104,157,350 |
| 2014-07-26 08:00:00 | 2014-07-26 19:00:51 | 17,74,104,157,350 |
| 2014-07-26 19:00:52 | 2014-07-26 23:59:59 | 17,74,104,157,350 |
| 2014-07-27 00:00:00 | 2014-07-27 07:59:59 | 17,74,104,157,350 |
| 2014-07-27 08:00:00 | 2014-07-27 19:00:55 | 17,74,104,157,350 |
| 2014-07-27 19:00:56 | 2014-07-27 23:59:59 | 17,74,104,157,350 |
| 2014-07-28 00:00:00 | 2014-07-28 07:59:59 | 17,74,104,157,350 |
| 2014-07-28 08:00:00 | 2014-07-28 19:00:55 | 17,74,104,157,350 |
| 2014-07-28 19:00:56 | 2014-07-28 23:59:59 | 17,74,104,157,350 |
| 2014-07-29 00:00:00 | 2014-07-29 07:59:59 | 17,74,104,157,350 |
| 2014-07-29 08:00:00 | 2014-07-29 19:01:00 | 17,74,104,157,350 |
| 2014-07-29 19:01:01 | 2014-07-29 23:59:59 | 17,74,104,157,350 |
| 2014-07-30 00:00:00 | 2014-07-30 07:59:59 | 17,74,104,157,350 |
| 2014-07-30 08:00:00 | 2014-07-30 10:17:58 | 17,74,104,157,350 |
| 2014-07-30 10:17:59 | 2014-07-30 19:00:56 | 17,74,157,205     |
| 2014-07-30 19:00:57 | 2014-07-30 23:59:59 | 17,74,157,205     |
| 2014-07-31 00:00:00 | 2014-07-31 07:59:59 | 17,74,157,205     |
| 2014-07-31 08:00:00 | 2014-07-31 23:59:59 | 17,74,104,157,350 |
+---------------------+---------------------+-------------------+
47 rows in set (0.78 sec)



Код:
mysql> select sessionStart, sessionStop, deviceOptions from inet_session_log_28_201408 where servId=9515 and parentId=0 order by sessionStart;
+---------------------+---------------------+-------------------+
| sessionStart        | sessionStop         | deviceOptions     |
+---------------------+---------------------+-------------------+
| 2014-08-01 00:00:00 | 2014-08-01 07:59:59 | 17,74,104,157,350 |
| 2014-08-01 08:00:00 | 2014-08-01 19:00:50 | 17,74,104,157,350 |
| 2014-08-01 19:00:51 | 2014-08-01 23:59:59 | 17,74,104,157,350 |
| 2014-08-02 00:00:00 | 2014-08-02 07:59:59 | 17,74,104,157,350 |
| 2014-08-02 08:00:00 | 2014-08-02 19:00:54 | 17,74,104,157,350 |
| 2014-08-02 19:00:55 | 2014-08-02 23:59:59 | 17,74,104,157,350 |
| 2014-08-03 00:00:00 | 2014-08-03 07:59:59 | 17,74,104,157,350 |
| 2014-08-03 08:00:00 | 2014-08-03 19:00:52 | 17,74,104,157,350 |
| 2014-08-03 19:00:53 | 2014-08-03 23:59:59 | 17,74,104,157,350 |
| 2014-08-04 00:00:00 | 2014-08-04 07:59:59 | 17,74,104,157,350 |
| 2014-08-04 08:00:00 | 2014-08-04 11:46:31 | 17,74,104,157,350 |
| 2014-08-04 11:46:32 | 2014-08-04 19:00:43 | 17,74,157,205     |
| 2014-08-04 19:00:44 | 2014-08-04 23:59:59 | 17,74,157,205     |
| 2014-08-05 00:00:00 | 2014-08-05 07:59:59 | 17,74,157,205     |
+---------------------+---------------------+-------------------+
14 rows in set (0.05 sec)


Вот тут странно:
| 2014-08-04 08:00:00 | 2014-08-04 11:46:31 | 17,74,104,157,350 |
- реально турбо не было подключено (вчерашние логи выше). Тут логично: на предыдущей сессии они были, поэтому похоже и выдал "deviceOptions already ..."
| 2014-08-04 11:46:32 | 2014-08-04 19:00:43 | 17,74,157,205 |
- это я руками сбросил и турбо ушло через Access-Accept. Но почему тогда опция 104 не прописалась, если была получена при авторизации сессии???

ps. Сегодня у всех снова отработало нормально - видимо потому, что я опять всех сбросил вчера.
Вернуться к началу
 Профиль  
 
Amir
СообщениеДобавлено: 05 авг 2014, 17:55 
Не в сети
Разработчик
Аватара пользователя

Зарегистрирован: 19 дек 2006, 21:04
Сообщения: 5970
Карма: 256
А скорость при этом в 19 точно всем отключается? Т.е. у этих, у кого осталось 104 - тоже?
Вернуться к началу
 Профиль  
 
Amir
СообщениеДобавлено: 05 авг 2014, 18:31 
Не в сети
Разработчик
Аватара пользователя

Зарегистрирован: 19 дек 2006, 21:04
Сообщения: 5970
Карма: 256
Нужно посмотреть в логах для сессии, в которой опция 104 осталась после 19:00, посылалось ли CoA по ней, пришел ли ответ (например, NAK) или не пришел.
Посмотреть, правильные ли тарифные опции в памяти у этой сессии через accounting.sh servmap.
Посмотреть, какие опции в памяти у этой сессии через accounting.sh sesslist.
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 05 авг 2014, 20:11 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Сейчас гляну.
Вообще, там часто NAK приходит, т.к. у сервиса ISG для дневной турбокнопки стоит дополнительно sessionTimeout 11 часов
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 05 авг 2014, 20:40 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
NaK нету, сессий в sesslist с опциями 104 или 105 нет, всё чинно, играет кристина агилера, будто в рай попал.
Снял servmap (Access & Accounting), conlist, sssionlist, скопировал кой-какие логи, завтра посмотрю, что будет утром
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 06 авг 2014, 06:49 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Сегодня снова всё в порядке
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 07 авг 2014, 12:11 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Сегодня всё плохо.
Вчера утром было хорошо.

1. Позавчера вечером (05.08.2014) опция была отключена по трекеру сессий (SessionTrackingWorker) в 19:00:01 ещё до отключения опции (а тарифе вложенные избыточные условия на наличие опции и фильтр по времени). Событие на отключение опции упало уже в 19:09, поэтому всё прошло гладко.

2. Вчера же вечером (06.08.2014) трекер сессий отработал только в 20:11. ISG-сессия турбо завершилась в 19:00 с копейками по таймауту циски. Затем в 19:09 было обработано событие смены тарифной опции, но, судя по логам, ничего не сделало (почему???). Возможно, это связано с тем, что время отключения опции было 19:00:52 - видимо, в ActiveMQ пробка из сообщений. Трекер же прошел в 20:11, отправил CoA и получил NAK, т.к. сессия уже давно сама завершилась.

3. Утром снова получаем: InetConnection deviceOptions already [17, 157, 350, 104, 74]

Вот Access:
- Вчера вечером:
Код:
connection 08-06/19:01:10  INFO [sa-p-12-t-10] ServiceActivatorSet - Connecting to device
connection 08-06/19:01:10 DEBUG [sa-p-12-t-10] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; type: 2; deviceId: 21; connectionId: 13914; timestamp: 1407319270533
connection 08-06/19:01:10  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; type: 2; deviceId: 21; connectionId: 13914; timestamp: 1407319270533
connection 08-06/19:01:10  INFO [sa-p-12-t-10] InetApplication - TariffOptionMap: {39=cto: 520765-39: 06.08.2014 08:00:00.0 - null, 40=cto: 51293-40: 09.11.2012 10:47:45.0 - null}
connection 08-06/19:01:10  INFO [sa-p-12-t-10] InetApplication - OptionSet: [17, 205, 157, 74]
connection 08-06/19:01:10  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=5; inetServId: 9515; call: true; oldState: 0; newState: 0; oldOptionSet: 17,205,157,74; newOptionSet: 17,205,157,74
connection 08-06/19:01:10  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=5; inetServId: 9515; call: true; oldState: 0; newState: 0; oldOptionSet: 17,205,157,74; newOptionSet: 17,205,157,74
connection 08-06/19:01:10  INFO [sa-p-12-t-10] ServiceActivatorSet - Invoking onAccountingStop
connection 08-06/19:01:10  INFO [sa-p-12-t-10] ServiceActivatorDeviceWorker - Process event type[5] result=true
mq 08-06/19:01:10 DEBUG [event-proc-p-2-t-1] Consumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; type: 2; deviceId: 21; connectionId: 13914; timestamp: 1407319270533
mq 08-06/19:09:09 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGScheduler Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407319252450
mq 08-06/19:09:09  INFO [event-proc-p-2-t-1] ContractRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407319252450
mq 08-06/19:09:09 DEBUG [event-proc-p-2-t-1] ContractTariffOptionList - Create:
                ContractTariffOption: 40: 09.11.2012 10:47:45.0 - null
                ContractTariffOption: 39: 31.07.2014 08:00:00.0 - 31.07.2014 19:00:51.999
                ContractTariffOption: 39: 01.08.2014 08:00:00.0 - 01.08.2014 19:00:50.999
                ContractTariffOption: 39: 02.08.2014 08:00:00.0 - 02.08.2014 19:00:54.999
                ContractTariffOption: 39: 03.08.2014 08:00:00.0 - 03.08.2014 19:00:52.999
                ContractTariffOption: 39: 04.08.2014 08:00:00.0 - 04.08.2014 19:00:43.999
                ContractTariffOption: 39: 05.08.2014 08:00:00.0 - 05.08.2014 19:00:50.999
                ContractTariffOption: 39: 06.08.2014 08:00:00.0 - 06.08.2014 19:00:51.999
mq 08-06/19:09:09  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407319252450


и ещё потом в 20:11 (!):

Код:
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 08-06/20:11:39 DEBUG [sa-p-12-t-12] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 17,205,157,74; timestamp: 1407323499180
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 17,205,157,74; timestamp: 1407323499180
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,74,104; newOptionSet: 17,205,157,74
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,74,104; newOptionSet: 17,205,157,74
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorSet - Invoking serviceModify
connection 08-06/20:11:39 DEBUG [sa-p-12-t-12] ProfileExtractor - monitor = 0 < * == (def)[monitor:off] ==> *{0} >
connection 08-06/20:11:39 DEBUG [sa-p-12-t-12] ProfileExtractor - packageId = 108 < * == [speed:sce-speed:econom-08] ==> * == (def)[p2p:on] ==> * == (def)[social:on] ==> *{108} >
mq 08-06/20:11:39 DEBUG [sa-p-12-t-12] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407323499782
mq 08-06/20:11:39 DEBUG [sa-p-12-t-12] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407323499858
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Changing InetServ:9515 state and/or options
mq 08-06/20:11:39 DEBUG [sa-p-12-t-12] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,205,157,74; timestamp: 1407323499867
connection 08-06/20:11:39 DEBUG [sa-p-12-t-12] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 12725; options: 17,205,157,74; timestamp: 1407323499195
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 12725; options: 17,205,157,74; timestamp: 1407323499195
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,74,104; newOptionSet: 17,205,157,74
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,74,104; newOptionSet: 17,205,157,74
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorSet - Invoking connectionModify
connection 08-06/20:11:39 DEBUG [sa-p-12-t-12] ProfileExtractor - monitor = 0 < * == (def)[monitor:off] ==> *{0} >
connection 08-06/20:11:39 DEBUG [sa-p-12-t-12] ProfileExtractor - packageId = 108 < * == [speed:sce-speed:econom-08] ==> * == (def)[p2p:on] ==> * == (def)[social:on] ==> *{108} >
mq 08-06/20:11:39 DEBUG [sa-p-12-t-12] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407323499886
mq 08-06/20:11:39 DEBUG [sa-p-12-t-12] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407323499962
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ISGServiceActivator - Connection modify: oldState: 1; newState: 1; oldOptionSet: [17, 157, 350, 74, 104]; newOptionSet: [17, 205, 157, 74]
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ISGServiceActivator - Sending commands to deactivate services (mode=1): [IPOE-TURBO10M]
connection 08-06/20:11:39  INFO [sa-p-12-t-12] ISGServiceActivator - Sending commands to activate services (mode=1): []
connection 08-06/20:11:39  INFO [sa-p-12-t-12] RadiusClient - Sending to /x.x.x.x:1700
Packet type: CoA-Request
Identifier: 254
Authenticator: {3A 03 82 E2 17 FC EE B8 B2 84 B9 39 3E F7 99 15}
Attributes:
  User-Name=nas-port:x.x.x.x:0/0/2/177.2211
  Acct-Session-Id=0/0/2/177.2211_8300000000317AEA
  cisco-SSG-Command-Code=\0xcIPOE-TURBO10M

connection 08-06/20:11:39  INFO [sa-p-12-t-12] ServiceActivatorDeviceWorker - Process event type[2] result=true

connection 08-06/20:11:39  INFO [rds-clnt-/x.x.x.x-1700] RadiusClient - Recieved from /x.x.x.x:1700
Packet type: CoA-NAK
Identifier: 254
Authenticator: {E3 E2 BF A9 A7 98 D9 31 11 5C C0 FD CB 33 10 5E}
Attributes:
  Error-Cause=405
  Reply-Message=Push invoke failed
  cisco-SSG-Command-Code=\0x1057;nas-port:x.x.x.x:0/0/2/177.2211;IPOE-TURBO10M
  cisco-SSG-Account-Info=Sy.y.y.y
  cisco-SSG-Account-Info=$IGigabitEthernet0/0/2.22110177


- Сегодня утром:

Код:
mq 08-07/08:01:04 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGScheduler Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407366064099
mq 08-07/08:01:04  INFO [event-proc-p-2-t-1] ContractRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407366064099
mq 08-07/08:01:04 DEBUG [event-proc-p-2-t-1] ContractRuntimeMap - Tariff option was activated: 39 07.08.2014 08:00:00.0 - 01.01.1970 08:00:00.0
mq 08-07/08:01:04 DEBUG [event-proc-p-2-t-1] ContractTariffOptionList - Create:
                ContractTariffOption: 40: 09.11.2012 10:47:45.0 - null
                ContractTariffOption: 39: 31.07.2014 08:00:00.0 - 31.07.2014 19:00:51.999
                ContractTariffOption: 39: 01.08.2014 08:00:00.0 - 01.08.2014 19:00:50.999
                ContractTariffOption: 39: 02.08.2014 08:00:00.0 - 02.08.2014 19:00:54.999
                ContractTariffOption: 39: 03.08.2014 08:00:00.0 - 03.08.2014 19:00:52.999
                ContractTariffOption: 39: 04.08.2014 08:00:00.0 - 04.08.2014 19:00:43.999
                ContractTariffOption: 39: 05.08.2014 08:00:00.0 - 05.08.2014 19:00:50.999
                ContractTariffOption: 39: 06.08.2014 08:00:00.0 - 06.08.2014 19:00:51.999
                ContractTariffOption: 39: 07.08.2014 08:00:00.0 - null
mq 08-07/08:01:04  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407366064099
connection 08-07/08:01:04  INFO [sa-p-12-t-5] ServiceActivatorSet - Connecting to device
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorSet - Connecting to device
connection 08-07/08:01:15 DEBUG [sa-p-12-t-6] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 17,157,350,104,74; timestamp: 1407366075220
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 17,157,350,104,74; timestamp: 1407366075220
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 205,17,157,74; newOptionSet: 17,157,350,104,74
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 205,17,157,74; newOptionSet: 17,157,350,104,74
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorSet - Invoking serviceModify
connection 08-07/08:01:15 DEBUG [sa-p-12-t-6] ProfileExtractor - monitor = 0 < * == (def)[monitor:off] ==> *{0} >
connection 08-07/08:01:15 DEBUG [sa-p-12-t-6] ProfileExtractor - packageId = 158 < * == [speed:sce-speed:turbo10M] ==> * == (def)[p2p:on] ==> * == (def)[social:on] ==> *{158} >
mq 08-07/08:01:15 DEBUG [sa-p-12-t-6] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407366075240
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorDeviceWorker - Changing InetServ:9515 state and/or options
mq 08-07/08:01:15 DEBUG [sa-p-12-t-6] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,157,350,104,74; timestamp: 1407366075403
mq 08-07/08:01:15 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGInetAccess-Inet-IPoE Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,157,350,74,104; timestamp: 1407366075403
connection 08-07/08:01:15 DEBUG [sa-p-12-t-6] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 12725; options: 17,157,350,104,74; timestamp: 1407366075231
connection 08-07/08:01:15  INFO [sa-p-12-t-6] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 12725; options: 17,157,350,104,74; timestamp: 1407366075231
connection 08-07/08:01:15 DEBUG [sa-p-12-t-6] InetSaOptionsModifyEvent - InetConnection deviceOptions already [17, 157, 350, 104, 74]
connection 08-07/08:01:15 DEBUG [sa-p-12-t-6] ServiceActivatorDeviceWorker - Skip event


В connection.log аккаунтинга трекер сессий нашел изменение опций только в 20:11:
Код:
08-06/20:11:39  INFO [accwrkr-1-p-13-t-1] connection - 12725:54663 Sending events to modify serv & connection options to: 205,17,157,74


Позавчера вечером, для сравнения, CoA ушло по событию от трекера сессий аккаунтинга:
Код:
08-05/19:00:01  INFO [accwrkr-1-p-13-t-1] connection - 12725:51697 Sending events to modify serv & connection options to: 17,205,157,74


Access:
Код:
connection 08-05/19:00:07 DEBUG [sa-p-12-t-9] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 205,17,157,74; timestamp: 1407232801861
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 0; options: 205,17,157,74; timestamp: 1407232801861
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,104,74; newOptionSet: 205,17,157,74
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,104,74; newOptionSet: 205,17,157,74
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorSet - Invoking serviceModify
connection 08-05/19:00:07 DEBUG [sa-p-12-t-9] ProfileExtractor - monitor = 0 < * == (def)[monitor:off] ==> *{0} >
connection 08-05/19:00:07 DEBUG [sa-p-12-t-9] ProfileExtractor - packageId = 108 < * == [speed:sce-speed:econom-08] ==> * == (def)[p2p:on] ==> * == (def)[social:on] ==> *{108} >
mq 08-05/19:00:07 DEBUG [sa-p-12-t-9] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407232807373
mq 08-05/19:00:07 DEBUG [sa-p-12-t-9] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407232807483
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Changing InetServ:9515 state and/or options
mq 08-05/19:00:07 DEBUG [sa-p-12-t-9] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 205,17,157,74; timestamp: 1407232807495
connection 08-05/19:00:07 DEBUG [sa-p-12-t-9] AcknowledgeConsumer - Caught BGInetAccounting-Inet-IPoE:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 12725; options: 205,17,157,74; timestamp: 1407232801890
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Do task deviceId: 21; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaOptionsModifyEvent] moduleId: 28; pluginId: no; cid: 186198; scid: -1; userId: 0; deviceId: 21; inetServId: 9515; connectionId: 12725; options: 205,17,157,74; timestamp: 1407232801890
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,104,74; newOptionSet: 205,17,157,74
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Processing deviceId:21; command ServiceActivatorEvent type=2; inetServId: 9515; call: true; oldState: 1; newState: 1; oldOptionSet: 17,157,350,104,74; newOptionSet: 205,17,157,74
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorSet - Invoking connectionModify
connection 08-05/19:00:07 DEBUG [sa-p-12-t-9] ProfileExtractor - monitor = 0 < * == (def)[monitor:off] ==> *{0} >
connection 08-05/19:00:07 DEBUG [sa-p-12-t-9] ProfileExtractor - packageId = 108 < * == [speed:sce-speed:econom-08] ==> * == (def)[p2p:on] ==> * == (def)[social:on] ==> *{108} >
mq 08-05/19:00:07 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGInetAccess-Inet-IPoE Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,205,157,74; timestamp: 1407232807495
mq 08-05/19:00:07  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 28; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 21; inetServId: 9515; state: -1000; optionSet: 17,205,157,74; timestamp: 1407232807495
mq 08-05/19:00:07 DEBUG [sa-p-12-t-9] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407232807532
mq 08-05/19:00:07 DEBUG [sa-p-12-t-9] EventProcessor - Publish: Event[ru.dsi.bgbilling.sce.event.events.SubscriberModifiedEvent] moduleId: no; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1407232807560
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ISGServiceActivator - Connection modify: oldState: 1; newState: 1; oldOptionSet: [17, 157, 350, 104, 74]; newOptionSet: [205, 17, 157, 74]
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ISGServiceActivator - Sending commands to deactivate services (mode=1): [IPOE-TURBO10M]
connection 08-05/19:00:07  INFO [sa-p-12-t-9] ISGServiceActivator - Sending commands to activate services (mode=1): []
connection 08-05/19:00:07  INFO [sa-p-12-t-9] RadiusClient - Sending to /x.x.x.x:1700
Packet type: CoA-Request
Identifier: 198
Authenticator: {A2 B9 39 B2 38 13 17 83 89 DF E2 4E D2 08 EC A8}
Attributes:
  User-Name=nas-port:x.x.x.x:0/0/2/177.2211
  Acct-Session-Id=0/0/2/177.2211_8300000000317AEA
  cisco-SSG-Command-Code=\0xcIPOE-TURBO10M

connection 08-05/19:00:07  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 08-05/19:00:07  INFO [rds-clnt-/x.x.x.x-1700] RadiusClient - Recieved from /x.x.x.x:1700
Packet type: CoA-ACK
Identifier: 198
Authenticator: {F8 BB E4 85 82 ED FB 7B 57 49 61 89 6D 28 CB 7E}
Attributes:
  cisco-SSG-Command-Code=\0xcIPOE-TURBO10M
  cisco-SSG-Account-Info=Sy.y.y.y
  cisco-SSG-Account-Info=$IGigabitEthernet0/0/2.22110177

...


mq 08-05/19:08:58 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGScheduler Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407232851355
mq 08-05/19:08:58  INFO [event-proc-p-2-t-1] ContractRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407232851355
mq 08-05/19:08:58 DEBUG [event-proc-p-2-t-1] ContractTariffOptionList - Create:
                ContractTariffOption: 40: 09.11.2012 10:47:45.0 - null
                ContractTariffOption: 39: 31.07.2014 08:00:00.0 - 31.07.2014 19:00:51.999
                ContractTariffOption: 39: 01.08.2014 08:00:00.0 - 01.08.2014 19:00:50.999
                ContractTariffOption: 39: 02.08.2014 08:00:00.0 - 02.08.2014 19:00:54.999
                ContractTariffOption: 39: 03.08.2014 08:00:00.0 - 03.08.2014 19:00:52.999
                ContractTariffOption: 39: 04.08.2014 08:00:00.0 - 04.08.2014 19:00:43.999
                ContractTariffOption: 39: 05.08.2014 08:00:00.0 - 05.08.2014 19:00:50.999
mq 08-05/19:08:58  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.tariff.option.server.event.ContractTariffOptionChangedEvent] moduleId: 0; pluginId: no; cid: 186198; scid: -1; userId: 0; timestamp: 1407232851355


ps. А вот это к нашему случаю имеет какое-нибудь отношение?
Цитата:
1036 13.12.2012 14:09:09 ДОБАВЛЕНО Inet: Добавлен параметр serv.checkOptions=1, для дополнительной проверки, что текущие опции сервиса на устройстве совпадают с необходимыми.

У меня в конфиге нет такого
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 07 авг 2014, 12:22 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
2 вопроса:
- почему ConnectionModify не отрабатывает при событии отключения тарифной опции? (мб потому что отрабатывает позже даты закрытия опции?)
- почему Access не меняет набор текущих опций для коннекта на вечерний? Неужели из-за NAK?
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 07 авг 2014, 12:31 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Ну и 3 вопрос: почему трекер отработал только через час?
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 07 авг 2014, 12:32 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Сейчас поставил трекер в TRACE - он довольно шустрый:

Код:
08-07/15:31:32 TRACE [accwrkr-1-p-13-t-1] SessionTrackingWorker - Run connection tracker...
08-07/15:31:42 TRACE [accwrkr-1-p-13-t-1] SessionTrackingWorker - Run connection tracker...
08-07/15:31:42 DEBUG [accwrkr-1-p-13-t-1] SessionTrackingWorker - Tracked 530 sessions for 125 ms.
08-07/15:31:42 TRACE [accwrkr-1-p-13-t-1] SessionTrackingWorker - Run connection tracker...
08-07/15:31:52 TRACE [accwrkr-1-p-13-t-1] SessionTrackingWorker - Run connection tracker...
08-07/15:31:52 DEBUG [accwrkr-1-p-13-t-1] SessionTrackingWorker - Tracked 527 sessions for 123 ms.
Вернуться к началу
 Профиль  
 
Amir
СообщениеДобавлено: 07 авг 2014, 14:35 
Не в сети
Разработчик
Аватара пользователя

Зарегистрирован: 19 дек 2006, 21:04
Сообщения: 5970
Карма: 256
Цитата:
Ну и 3 вопрос: почему трекер отработал только через час?
Похоже, что он отработал в 19 часов, но т.к. опция уже была отключена Cisco ответила Nak - Access решил, что попытка не удалась и не сменил набор опций в deviceOptions. Сейчас дальше Accounting не посылает снова команд в mq, пока набор опций опять не изменится, или пока Accounting не будет перезапущен. Может быть в 20 часов Accounting перезапускали?

Возможно действительно дело в Nak из-за того что сервис сам отключается ранее. Если не перезапускать Accounting, то сейчас он отправит команду один раз, Access попробует выполнить, получит Nak - не изменит deviceOptions, но команду посчитает выполненной (невыполненной он считает если ответ не пришел). Далее меняется набор опций опять, а Access думает что набор опций совпадает.

Как вариант - для начала попробовать таймаут сервиса у Cisco поставить больше, чтобы биллинг сам отключал при нормальной работе.
Вернуться к началу
 Профиль  
 
Amir
СообщениеДобавлено: 07 авг 2014, 15:00 
Не в сети
Разработчик
Аватара пользователя

Зарегистрирован: 19 дек 2006, 21:04
Сообщения: 5970
Карма: 256
Быстро сделать чтобы deviceOptions все равно менялись при Nak - в ISGServiceActivator.sendCommands в начале поменять Object result = null; на Future<Boolean> result = null;
перед return result; добавить
Код:
      if( result != null )
      {
         final Future<Boolean> delegate = result;
         result = new Future<Boolean>()
         {
            @Override
            public boolean cancel( boolean mayInterruptIfRunning )
            {
               return delegate.cancel( mayInterruptIfRunning );
            }

            @Override
            public boolean isCancelled()
            {
               return delegate.isCancelled();
            }

            @Override
            public boolean isDone()
            {
               return delegate.isDone();
            }

            @Override
            public Boolean get()
               throws InterruptedException, ExecutionException
            {
               delegate.get();
               return Boolean.TRUE;
            }

            @Override
            public Boolean get( long timeout, TimeUnit unit )
               throws InterruptedException, ExecutionException, TimeoutException
            {
               delegate.get( timeout, unit );
               return Boolean.TRUE;
            }
         };
      }
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 07 авг 2014, 15:05 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Ага, похоже дело всё-таки в NAK.

Я не знал просто, как ServiceActivator работает - зависит ли смена опций в памяти от того, что вернёт ему циска, или он просто отправляет пакеты и сразу меняет.
Похоже, всё-таки первый вариант, т.к. в логах не хватает таких строчек (после CoA-ACK):

Код:
08-06/08:05:34  INFO [sa-p-12-t-3] EventWorker - Future is done
08-06/08:05:34  INFO [sa-p-12-t-3] ServiceActivatorDeviceWorker - Changing InetConnection:2260 state and/or options


Другой вопрос, должно ли оно так работать? Мб (если действительно так) делать несколько попыток ретрансмита и потом всё-таки менять опции, например? Ну т.е. более активно как-то на такую ошибку реагировать..

Поставил 13 часов таймаут
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 07 авг 2014, 15:06 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Amir писал(а):
Быстро сделать чтобы deviceOptions все равно менялись при Nak ....


Спасибо, попробую завтра.
Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 07 авг 2014, 15:08 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
зы. Никак не могу нарадоваться на свой справочник сервисов ISG :)
Вложение:
turbo11h.PNG
turbo11h.PNG [ 23.27 КБ | Просмотров: 9890 ]


Вернуться к началу
 Профиль  
 
Cromeshnic
СообщениеДобавлено: 11 авг 2014, 08:44 
Не в сети
Клиент
Аватара пользователя

Зарегистрирован: 20 апр 2009, 12:03
Сообщения: 3092
Откуда: Иркутск
Карма: 338
Проблем вроде бы нет пока, код менять не стал.
Хотелось бы знать, будем ли меняться логика обработки Future при смене опций?
Вернуться к началу
 Профиль  
 
Показать сообщения за:  Поле сортировки  
Начать новую тему Ответить на тему  Страница 1 из 2
  [ Сообщений: 32 ]  На страницу 1, 2  След.

Список форумов » BGBilling » Модули Интернета » Модуль Inet

Часовой пояс: UTC + 5 часов [ Летнее время ]

Кто сейчас на конференции

Сейчас этот форум просматривают: нет зарегистрированных пользователей и гости: 1

Вы не можете начинать темы
Вы не можете отвечать на сообщения
Вы не можете редактировать свои сообщения
Вы не можете удалять свои сообщения
Вы не можете добавлять вложения

Найти:
Перейти:  
cron
POWERED_BY
Русская поддержка phpBB
[ Time : 0.165s | 78 Queries | GZIP : On ]