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

Ошибки в логах v 5.2 inet 1354 от 19.01.2015 (CRM)
http://forum.bitel.ru/viewtopic.php?f=44&t=10099		 Страница 1 из 1
Автор:  Cromeshnic [ 21 янв 2015, 09:40 ]
Заголовок сообщения:  Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Обновился вчера на 5.2 до крайней версии:

Сервер: вер. 5.2 сборка 1616 от 11.12.2014 18:58:11
os: Linux; java: Java HotSpot(TM) 64-Bit Server VM, v.1.6.0_22
inet вер. 5.2 сборка 1354 от 19.01.2015 16:28:32

Код:
#./access_status.sh
Java Runtime: Sun Microsystems Inc. Java HotSpot(TM) 64-Bit Server VM [1.6.0_22] /opt/sun-jdk-1.6.0.22/jre
  Runtime name: 23434@bg1.dsi.srv
  Java endorsed dirs: /lib/endorsed:/etc/java-config-2/current-system-vm/lib/endorsed
  OS: Linux 2.6.33-gentoo [amd64], file.encoding: UTF-8, user.name: root
  Heap sizes: current=245248k  free=243967k  max=3639104k
Kernel version 5.2 build 1616 from 11.12.2014 18:58:11
Inet version 5.2 build 1354 from 19.01.2015 16:28:32


Смотрю логи в BGInetAccess-Inet-IPoE (mid=28), вижу ошибки.
Сегодня в 8:49 переоформляли договор cid : 188306->217721:

Код:
connection 01-21/08:49:01  INFO [sa-p-12-t-9] ServiceActivatorSet - Connecting to device
connection 01-21/08:49:01  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaServModifyEvent] moduleId: 28; pluginId: no; cid: 188306; scid: -1; userId: -1; oldInetServ: IPoE: asr1 - Te0/1/0.14120297; newInetServ: null; newInetServState: 0; newInetServOptionList: ; timestamp: 1421801341959
connection 01-21/08:49:01 ERROR [sa-p-12-t-9] InetSaServModifyEvent -
java.lang.NullPointerException
        at ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaServModifyEvent.toSaEvent(InetSaServModifyEvent.java:265)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.doTask(ServiceActivatorDeviceWorker.java:277)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.internalDoTaskImpl(AsyncEventWorker.java:209)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.notify(AsyncEventWorker.java:199)
        at ru.bitel.bgbilling.kernel.event.AcknowledgeConsumer.onMessage0(AcknowledgeConsumer.java:83)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.internalDoTask(AsyncEventWorker.java:174)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.doTasks(AsyncEventWorker.java:107)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.runWorker(ServiceActivatorDeviceWorker.java:203)
        at ru.bitel.bgbilling.kernel.event.EventWorker.internalRunWorker(EventWorker.java:139)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.runImpl(ServiceActivatorDeviceWorker.java:133)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
connection 01-21/08:49:01  INFO [sa-p-12-t-9] InetApplication - TariffOptionMap: {}
connection 01-21/08:49:02  INFO [sa-p-12-t-9] InetApplication - OptionSet: [155, 203, 74, 15]
connection 01-21/08:49:02  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=3; inetServId: 10333; call: true; oldState: 0; newState: 0; oldOptionSet: 155,203,74,15; newOptionSet: 155,203,74,15
connection 01-21/08:49:02  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Processing deviceId:23; command ServiceActivatorEvent type=3; inetServId: 10333; call: true; oldState: 0; newState: 0; oldOptionSet: 155,203,74,15; newOptionSet: 155,203,74,15
connection 01-21/08:49:02  INFO [sa-p-12-t-9] ServiceActivatorSet - Invoking serviceCancel
connection 01-21/08:49:02  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Process event type[3] result=true
connection 01-21/08:49:02  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Do task deviceId: 23; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaServModifyEvent] moduleId: 28; pluginId: no; cid: 217721; scid: -1; userId: -1; oldInetServ: null; newInetServ: IPoE: asr1 - Te0/1/0.14120297; newInetServState: -1; newInetServOptionList: ; timestamp: 1421801342577
connection 01-21/08:49:02  INFO [sa-p-12-t-9] InetServRuntimeMap - Adding new InetServRuntime: 10899
connection 01-21/08:49:02  INFO [sa-p-12-t-9] InetServRuntimeMap - Loading inetServ from database.
connection 01-21/08:49:02  WARN [sa-p-12-t-9] ContractRuntimeMap - Contract id=217721 not found
connection 01-21/08:49:02 ERROR [sa-p-12-t-9] InetServRuntimeMap - Contract not found with id=217721 but inetServ exist
connection 01-21/08:49:02 ERROR [sa-p-12-t-9] ServiceActivatorDeviceWorker - Device:23 - null
java.lang.NullPointerException
        at ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaServModifyEvent.toSaEvent(InetSaServModifyEvent.java:248)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.doTask(ServiceActivatorDeviceWorker.java:277)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.internalDoTaskImpl(AsyncEventWorker.java:209)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.notify(AsyncEventWorker.java:199)
        at ru.bitel.bgbilling.kernel.event.AcknowledgeConsumer.onMessage0(AcknowledgeConsumer.java:83)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.internalDoTask(AsyncEventWorker.java:174)
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.doTasks(AsyncEventWorker.java:107)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.runWorker(ServiceActivatorDeviceWorker.java:203)
        at ru.bitel.bgbilling.kernel.event.EventWorker.internalRunWorker(EventWorker.java:139)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.runImpl(ServiceActivatorDeviceWorker.java:133)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)

...

Сессия поднялась потом в 09:02 из апдейта, так что перерыва связи вроде не было, да и не жаловался никто.
Просто вот эксепшены в логах увидел.
Автор:  Cromeshnic [ 21 янв 2015, 09:49 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
А вот ещё интересное: завёл отдельную ветку устройств для PPPoE, повесил на неё свои Access и Accounting. Сервисов пока ещё не заводил, т.е. работает вхолостую.
В BGInetAccess-Inet-PPPoE вижу ошибки такого вида:

Код:
mq 01-21/08:00:02  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: 10121; state: -1000; optionSet: 488,114,458,66,422; timestamp: 1421798402102
mq 01-21/08:00:02 ERROR [event-proc-p-2-t-1] InetConnectionManager - InetServRuntime not found with id=10121
mq 01-21/08:00:02 ERROR [event-proc-p-2-t-1] Consumer -
java.lang.NullPointerException
        at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.notify(InetConnectionManager.java:302)
        at ru.bitel.bgbilling.kernel.event.AbstractConsumer.notify(AbstractConsumer.java:345)
        at ru.bitel.bgbilling.kernel.event.Consumer.notify(Consumer.java:1)
        at ru.bitel.bgbilling.kernel.event.Consumer.onMessage0(Consumer.java:112)
        at ru.bitel.bgbilling.kernel.event.Consumer$EventListenerRunnable.runImpl(Consumer.java:51)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)


Т.е. Access ветки устройств PPPoE получает ивенты обновления сервисов чужой ветки устройств и не может их найти в своём кэше.

ps. В BGInetAccounting-Inet-PPPoE error.log чистый
Автор:  Cromeshnic [ 21 янв 2015, 09:52 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
В остальном везде error.log Access/Accounting-ов чистые за ночь после вечернего обновления :)
Автор:  Amir [ 21 янв 2015, 17:51 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
А на какое число переоформляли? Текущее, прошлое, будущее?
Автор:  Cromeshnic [ 22 янв 2015, 07:10 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Переоформление было с 20.01 (т.е. задним числом).
(Саму кнопку тыкали 21.01, старый договор закрыли 19.01, новый открыли 20.01)
Автор:  Cromeshnic [ 28 янв 2015, 12:38 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Или вот ещё проскакивает иногда в scheduler.mq.log:
Код:
01-28/13:00:20 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGInetAccounting-VPN Event[ru.bitel.bgbilling.modules.inet.accounting.recalculate.event.response.RecalculateResponseEvent] moduleId: 30; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1422421218884
01-28/13:00:20  INFO [event-proc-p-2-t-1] InetRecalculateResponseEventProcessor - get respone from applicationId=5
01-28/13:00:20 ERROR [event-proc-p-2-t-1] InetRecalculateResponseEventProcessor - unknown applicationId :5


BGInetAccounting-VPN - это app.id=5 и mid=30
Автор:  stark [ 28 янв 2015, 12:41 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Cromeshnic писал(а):
Или вот ещё проскакивает иногда в scheduler.mq.log:
Код:
01-28/13:00:20 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGInetAccounting-VPN Event[ru.bitel.bgbilling.modules.inet.accounting.recalculate.event.response.RecalculateResponseEvent] moduleId: 30; pluginId: no; cid: global; scid: -1; userId: 0; timestamp: 1422421218884
01-28/13:00:20  INFO [event-proc-p-2-t-1] InetRecalculateResponseEventProcessor - get respone from applicationId=5
01-28/13:00:20 ERROR [event-proc-p-2-t-1] InetRecalculateResponseEventProcessor - unknown applicationId :5


BGInetAccounting-VPN - это app.id=5 и mid=30


А вы на нем запускали переобсчет?
Автор:  Cromeshnic [ 28 янв 2015, 13:11 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Я лично не запускал - скорее всего при переоформлении автоматом запустилось.

01-28/13:00:01 INFO [pool-1-thread-9] InetRecalculator - init application ids: 5,6
01-28/13:00:01 INFO [pool-1-thread-4] InetRecalculator - init application ids: 5,6
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - available application ids: 5,6
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - real calculate application ids: 5
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - executing calulatePastMonth
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - available application ids: 5,6
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - real calculate application ids: 5
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - executing calulatePastMonth
01-28/13:00:19 INFO [pool-1-thread-4] InetRecalculator - calulatePastMonth end
01-28/13:00:19 INFO [pool-1-thread-9] InetRecalculator - calulatePastMonth end
01-28/13:00:19 INFO [pool-1-thread-4] InetRecalculator - RunTask finished time=20409 ms.
01-28/13:00:19 INFO [pool-1-thread-9] InetRecalculator - RunTask finished time=21424 ms.
Автор:  stark [ 28 янв 2015, 13:34 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Cromeshnic писал(а):
Я лично не запускал - скорее всего при переоформлении автоматом запустилось.

01-28/13:00:01 INFO [pool-1-thread-9] InetRecalculator - init application ids: 5,6
01-28/13:00:01 INFO [pool-1-thread-4] InetRecalculator - init application ids: 5,6
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - available application ids: 5,6
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - real calculate application ids: 5
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - executing calulatePastMonth
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - available application ids: 5,6
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - real calculate application ids: 5
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - executing calulatePastMonth
01-28/13:00:19 INFO [pool-1-thread-4] InetRecalculator - calulatePastMonth end
01-28/13:00:19 INFO [pool-1-thread-9] InetRecalculator - calulatePastMonth end
01-28/13:00:19 INFO [pool-1-thread-4] InetRecalculator - RunTask finished time=20409 ms.
01-28/13:00:19 INFO [pool-1-thread-9] InetRecalculator - RunTask finished time=21424 ms.


Ясно, 2 обсчета за прошлый месяц запустились параллельно. За текущий месяц не дает запускать параллельно, а за прошлый дает. Исправим, по идее за прошлый можно параллельно запускать, но у нас ошибка в этом случае.
Автор:  Amir [ 28 янв 2015, 21:36 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Цитата:
Смотрю логи в BGInetAccess-Inet-IPoE (mid=28), вижу ошибки.
Сегодня в 8:49 переоформляли договор cid : 188306->217721:
Выложили.

Цитата:
А вот ещё интересное: завёл отдельную ветку устройств для PPPoE, повесил на неё свои Access и Accounting. Сервисов пока ещё не заводил, т.е. работает вхолостую.
В BGInetAccess-Inet-PPPoE вижу ошибки такого вида:
По умолчанию Access слушает события о старте/стопе/апдейте со всех Accounting'ов. Что-то не помню сейчас зачем. Ошибка ни на что не влияет, просто захламляет логи. Можно указать в конфиге корневого устройства access.group=1 и перезапустить Access, будет слушать только свои Accounting'и.
Автор:  stark [ 29 янв 2015, 12:48 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015
Cromeshnic писал(а):
Я лично не запускал - скорее всего при переоформлении автоматом запустилось.

01-28/13:00:01 INFO [pool-1-thread-9] InetRecalculator - init application ids: 5,6
01-28/13:00:01 INFO [pool-1-thread-4] InetRecalculator - init application ids: 5,6
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - available application ids: 5,6
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - real calculate application ids: 5
01-28/13:00:10 INFO [pool-1-thread-9] InetRecalculator - executing calulatePastMonth
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - available application ids: 5,6
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - real calculate application ids: 5
01-28/13:00:11 INFO [pool-1-thread-4] InetRecalculator - executing calulatePastMonth
01-28/13:00:19 INFO [pool-1-thread-4] InetRecalculator - calulatePastMonth end
01-28/13:00:19 INFO [pool-1-thread-9] InetRecalculator - calulatePastMonth end
01-28/13:00:19 INFO [pool-1-thread-4] InetRecalculator - RunTask finished time=20409 ms.
01-28/13:00:19 INFO [pool-1-thread-9] InetRecalculator - RunTask finished time=21424 ms.


Исправлено, обновление выложено.
Автор:  Cromeshnic [ 29 янв 2015, 12:54 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015 (CRM)
Цитата:
ИСПРАВЛЕНО Исключили возможность параллельного запуска переобсчета в inet.

А как именно? Они будут по-очереди выполняться?
При переоформлении с кучей субов, например, создаётся куча задач на переобсчёт - для каждого суба и каждого модуля, насколько я помню.
Автор:  stark [ 29 янв 2015, 12:59 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015 (CRM)
Cromeshnic писал(а):
Цитата:
ИСПРАВЛЕНО Исключили возможность параллельного запуска переобсчета в inet.

А как именно? Они будут по-очереди выполняться?
При переоформлении с кучей субов, например, создаётся куча задач на переобсчёт - для каждого суба и каждого модуля, насколько я помню.


Это было быстрое решение проблемы, пока написал для себя TODO чтобы решить ее нормально. По сути оно работало, просто получалось что в планировщике при получения сигнала о завершения одной задачи, вторая задача тоже как бы завершалась и писалась в лог, что выполнена. Но реально она выполнялась на accounting и ответ о завершении приходил позже и писалась ошибка в лог. Пока просто решили вопрос в лоб - добавили синхронизацию, это временное решение.
Автор:  stark [ 30 янв 2015, 19:34 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015 (CRM)
Cromeshnic писал(а):
Цитата:
ИСПРАВЛЕНО Исключили возможность параллельного запуска переобсчета в inet.

А как именно? Они будут по-очереди выполняться?
При переоформлении с кучей субов, например, создаётся куча задач на переобсчёт - для каждого суба и каждого модуля, насколько я помню.



Добавили параллельную обработку, будет в следующем обновлении(видимо уже не раньше понедельника). Надо будет не забыть обновить все accounting-сервера, там события изменились.
Автор:  Cromeshnic [ 05 фев 2015, 08:45 ]
Заголовок сообщения:  Re: Ошибки в логах v 5.2 inet 1354 от 19.01.2015 (CRM)
Вчера обновился - за ночь ошибок не было
Страница 1 из 1 Часовой пояс: UTC + 5 часов [ Летнее время ]
Powered by phpBB® Forum Software © phpBB Group
http://www.phpbb.com/