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

Отваливаются сессии
http://forum.bitel.ru/viewtopic.php?f=44&t=11031		 Страница 1 из 2
Автор:  sergey-xxi [ 26 окт 2015, 12:23 ]
Заголовок сообщения:  Отваливаются сессии
У некоторых абонентов стали отваливаться сессии, причем заметили закономерность.
Приблизительно каждые 2 часа.
Код:
Time: 26.10.2015 08:50:14
Packet type: Accounting-Request
Identifier: 5
Authenticator: {A0 D7 6C E5 02 A9 AB EB 69 A2 04 CC CF 60 D9 8E}
Attributes:
  User-Name=a8:f9:4b:0b:91:d5
  NAS-Identifier=RedBack
  NAS-IP-Address=192.168.1.2
  NAS-Port=33751040
  Service-Type=5
  Acct-Input-Octets=1263868
  Acct-Output-Octets=1533827
  Acct-Status-Type=2
  Acct-Session-Time=7875
  Acct-Input-Packets=13373
  Acct-Session-Id=0102FFFF78005F91-562DA6B6
  Acct-Authentic=1
  Acct-Interim-Interval=9000
  Acct-Terminate-Cause=17
  NAS-Port-Id=2/3 clips 221230
  Acct-Output-Packets=9151
  Event-Timestamp=1445840250
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  NAS-Port-Type=5
  Called-Station-Id=ххх.ххх.ххх.ххх
  Acct-Mcast-Out-Packets-64={00 00 00 00 00 00 00 00}
  DHCP-Max-Leases=1
  UNKNOWN[2352-201]={01 B2 D4 83 00}
  Session-Error-Msg=DHCP IP-host mismatch
  Session-Error-Code=196
  Acct-Output-Octets-64={00 00 00 00 00 17 67 83}
  Acct-Input-Octets-64={00 00 00 00 00 13 48 FC}
  Acct-Output-Packets-64={00 00 00 00 00 00 23 BF}
  Acct-Input-Packets-64={00 00 00 00 00 00 34 3D}
  Acct-Mcast-In-Octets-64={00 00 00 00 00 00 00 00}
  Assigned-IP-Address=10.21.80.69
  Acct-Mcast-In-Packets-64={00 00 00 00 00 00 00 00}
  Acct-Mcast-Out-Octets-64={00 00 00 00 00 00 00 00}
  Qos-Policing-Profile-Name=DEF-IPOE-IN
  Acct-Update-Reason=2
  Mac-Addr=a8-f9-4b-0b-91-d5
  Acct-Mcast-In-Octets=0
  Acct-Mcast-Out-Octets=0
  Qos-Metering-Profile-Name=DEF-IPOE-OUT
  Acct-Mcast-In-Packets=0
  Acct-Mcast-Out-Packets=0
  Platform-Type=4
  Medium-Type=11
  Agent-Remote-Id={00 00 00 00 06 A8 F9 4B 89 07 19}
  Agent-Circuit-Id={21 09 0B B8 00 00 00 00 00 00 0C}
  IP-Interface-Name=clients
  NAT-Policy-Name=nat-policy
  OS-Version=6.5.1.5
  NAS-Real-Port=33751040
  UNKNOWN[3561--1]={02 0D 00 00 00 00 06 A8 F9 4B 89 07 19}
  UNKNOWN[3561--1]={01 0D 21 09 0B B8 00 00 00 00 00 00 0C}


В логах акцесса есть ошибки
Код:
dhcp 10-26/08:34:22 ERROR [dhcpLstnr-p-11-t-9] WorkerTask - ru.bitel.bgbilling.kernel.network.dhcp.DhcpPacket.clearSubOptions()V
java.lang.NoSuchMethodError: ru.bitel.bgbilling.kernel.network.dhcp.DhcpPacket.clearSubOptions()V
        at ru.clink.bgbilling.inet.serv.SmartEdgeClipsProtocolHandler.preprocessDhcpRequest(SmartEdgeClipsProtocolHandler.java:106)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processOption82Request(InetAbstractDhcpProcessor.java:489)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processRequest(InetAbstractDhcpProcessor.java:250)
        at ru.bitel.bgbilling.kernel.network.dhcp.DhcpListenerWorker.runImpl(DhcpListenerWorker.java:89)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)
Автор:  Amir [ 26 окт 2015, 22:12 ]
Заголовок сообщения:  Re: Отваливаются сессии
Возможно дело в этой ошибке (т.к. происходит в предобработке DHCP-запроса).
Судя по ошибке в вашем (нестандартном) SmartEdgeClipsProtocolHandler используется метод DhcpPacket.clearSubOptions, который мы когда-то удалили.

Либо поправить этот дин. класс, либо выкладывается обновление, где этот метод вернули.


Какой у вас leaseTime?
Автор:  sergey-xxi [ 27 окт 2015, 12:34 ]
Заголовок сообщения:  Re: Отваливаются сессии
dhcp.option.leaseTime=9000
Автор:  sergey-xxi [ 02 ноя 2015, 03:17 ]
Заголовок сообщения:  Re: Отваливаются сессии
Не подскажите как лучше подправить дин класс, обновление вероятно может сломать наш нестандартный SmartEdgeClipsProtocolHandler?
Автор:  stark [ 03 ноя 2015, 11:24 ]
Заголовок сообщения:  Re: Отваливаются сессии
sergey-xxi писал(а):
Не подскажите как лучше подправить дин класс, обновление вероятно может сломать наш нестандартный SmartEdgeClipsProtocolHandler?

вы наш класс меняли? лучше была отнаследоваться и создать свой.
Автор:  sergey-xxi [ 17 ноя 2015, 19:40 ]
Заголовок сообщения:  Re: Отваливаются сессии
Несколько лет назад вы нам подправили обработчик 82 опции для оборудования Eltex PON. На текущей версии биллинга подправленный вами обработчик не компилируется.
Код:
cannot find symbol
  symbol:   method clearSubOptions()
  location: variable request of type ru.bitel.bgbilling.kernel.network.dhcp.DhcpPacket   /bgbill/server/dyn/ru/clink/bgbilling/inet/serv/SmartEdgeClipsProtocolHandler.java   106   17

Если мы сейчас перейдем на стандартный обработчик не возникнет ли проблем?
Автор:  stark [ 17 ноя 2015, 19:49 ]
Заголовок сообщения:  Re: Отваливаются сессии
sergey-xxi писал(а):
Несколько лет назад вы нам подправили обработчик 82 опции для оборудования Eltex PON. На текущей версии биллинга подправленный вами обработчик не компилируется.
Код:
cannot find symbol
  symbol:   method clearSubOptions()
  location: variable request of type ru.bitel.bgbilling.kernel.network.dhcp.DhcpPacket   /bgbill/server/dyn/ru/clink/bgbilling/inet/serv/SmartEdgeClipsProtocolHandler.java   106   17

Если мы сейчас перейдем на стандартный обработчик не возникнет ли проблем?


Обновитесь. там вернули этот метод 26.10.2015.
Автор:  sergey-xxi [ 18 ноя 2015, 15:28 ]
Заголовок сообщения:  Re: Отваливаются сессии
Обновились, в логах ошибки у некоторых абонентов и сессии не стартуют.

access.log
Код:
dhcp 11-18/12:14:52 ERROR [dhcpLstnr-p-11-t-5] InetDhcpHelperProcessor - Not found params for request: 2:C04A005C3A25 (pattern: $remoteId:$mac, servSearchMod
e: 1, deviceId: 2, agentDeviceId: 2, mac: C04A005C3A25)
dhcp 11-18/12:15:04 ERROR [dhcpLstnr-p-11-t-9] InetDhcpHelperProcessor - Not found params for request: 2:C04A005C3A25 (pattern: $remoteId:$mac, servSearchMod
e: 1, deviceId: 2, agentDeviceId: 2, mac: C04A005C3A25)
radius 11-18/12:15:06 ERROR [rdsLstnr-p-9-t-7] InetRadiusProcessor -
java.lang.NullPointerException
        at ru.clink.bgbilling.inet.serv.SmartEdgeClipsProtocolHandler.setAgentOptions(SmartEdgeClipsProtocolHandler.java:49)
        at ru.bitel.bgbilling.modules.inet.dyn.device.redback.SmartEdgeClipsProtocolHandler.preprocessAccessRequest(SmartEdgeClipsProtocolHandler.java:219)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.preprocessAccessRequest(InetRadiusProcessor.java:366)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.preprocessAccessRequest(InetRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:399)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:65)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:277)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:152)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)




accouting.log
Код:
radius 11-18/12:32:37 ERROR [rdsLstnr-p-8-t-3] InetRadiusProcessor - InetServ not found for username=00:25:56:bd:53:1e
radius 11-18/12:32:46 ERROR [rdsLstnr-p-8-t-6] InetRadiusProcessor -
java.lang.NullPointerException
        at ru.clink.bgbilling.inet.serv.SmartEdgeClipsProtocolHandler.setAgentOptions(SmartEdgeClipsProtocolHandler.java:49)
        at ru.bitel.bgbilling.modules.inet.dyn.device.redback.SmartEdgeClipsProtocolHandler.preprocessAccountingRequestImpl(SmartEdgeClipsProtocolHandler.jav
a:253)
        at ru.bitel.bgbilling.modules.inet.dyn.device.redback.SmartEdgeProtocolHandler.preprocessAccountingRequest(SmartEdgeProtocolHandler.java:75)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.preprocessAccountingRequest(InetRadiusProcessor.java:384)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.preprocessAccountingRequest(InetRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accountingRequest(RadiusProcessor.java:526)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accountingRequest(InetRadiusListenerWorker.java:186)
        at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accountingRequest(InetRadiusListenerWorker.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processAccountingRequest(RadiusListenerWorker.java:332)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:303)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:152)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)
Автор:  Amir [ 18 ноя 2015, 16:01 ]
Заголовок сообщения:  Re: Отваливаются сессии
Можете отправить код ru.clink.bgbilling.inet.serv.SmartEdgeClipsProtocolHandler в личку?
Автор:  sergey-xxi [ 18 ноя 2015, 17:50 ]
Заголовок сообщения:  Re: Отваливаются сессии
Отправил, смотрите.
Да еще заметили, что после перезагрузки клиентского оборудования сессии появились.
Автор:  Amir [ 18 ноя 2015, 18:07 ]
Заголовок сообщения:  Re: Отваливаются сессии
Код:
      byte[] remoteId = request.getByteAttribute( radiusVendor, Agent_Remote_Id, null );

      // dlink
      if( remoteId.length == 8 )
У вас ошибку писало здесь. Т.е. такая ошибка в логах появляется когда атрибута Agent_Remote_Id нет в RADIUS-пакете.
Автор:  sergey-xxi [ 18 ноя 2015, 18:32 ]
Заголовок сообщения:  Re: Отваливаются сессии
в нашем SmartEdgeClipsProtocolHandler 3 типа обработки.
Сейчас в стандартном обработчике реализованы данные типы обработки?
Автор:  Amir [ 18 ноя 2015, 18:51 ]
Заголовок сообщения:  Re: Отваливаются сессии
Нет, у вас разный формат agentRemoteId - тут пока только в ProtocolHandler парсить.
Но тут и ситуация не стандартная - у вас похоже и не должны RADIUS-пакеты без Agent-Remote-Id приходить - не понятно с чего такие были.
Автор:  sergey-xxi [ 18 ноя 2015, 19:19 ]
Заголовок сообщения:  Re: Отваливаются сессии
теперь новая проблема, сессии у большинства абонентов держаться ровно 4500сек и сессия обрывается.
В аккаутинге пишет следующее:
Код:
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-7] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 211
Authenticator: {C7 88 F0 EA 04 4C D8 4B D5 79 42 EB 88 A6 68 89}
Attributes:
  User-Name=00:22:15:2e:3d:b0
  NAS-Identifier=RedBack
  NAS-IP-Address=192.168.1.25
  NAS-Port=33751040
  Service-Type=5
  Acct-Input-Octets=1135688
  Acct-Output-Octets=9339923
  Acct-Status-Type=102
  Acct-Session-Time=4502
  Acct-Input-Packets=5675
  Acct-Session-Id=0102FFFF7800BBFD-564C6795-SE-514F1D8E
  Acct-Authentic=1
  Acct-Interim-Interval=9000
  Acct-Multi-Session-Id=0102FFFF7800BBFD-564C6795
  Acct-Terminate-Cause=3
  NAS-Port-Id=2/3 clips 245443
  Acct-Output-Packets=11232
  Event-Timestamp=1447852332
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  NAS-Port-Type=5
  Called-Station-Id=xxx.xxx.xxx.xxx
  Acct-Mcast-Out-Packets-64={00 00 00 00 00 00 00 00}
  DHCP-Max-Leases=1
  UNKNOWN[2352-201]={01 B2 D4 83 00}
  Session-Error-Msg=Session down
  UNKNOWN[2352-202]={3D 3D 07 01 00 22 15 2E 3D B0}
  UNKNOWN[2352-202]={0C 0C 0A 53 65 72 67 65 79 2D 78 78 69}
  Session-Error-Code=33
  Acct-Output-Octets-64={00 00 00 00 00 8E 84 13}
  Acct-Input-Octets-64={00 00 00 00 00 11 54 48}
  Acct-Output-Packets-64={00 00 00 00 00 00 2B E0}
  Acct-Input-Packets-64={00 00 00 00 00 00 16 2B}
  Acct-Mcast-In-Octets-64={00 00 00 00 00 00 00 00}
  Service-Parameter=Rate=60000 Burst=7500000
  Assigned-IP-Address=yyy.yyy.yyy.yyy
  Acct-Mcast-In-Packets-64={00 00 00 00 00 00 00 00}
  Acct-Mcast-Out-Octets-64={00 00 00 00 00 00 00 00}
  Acct-Update-Reason=25
  Mac-Addr=00-22-15-2e-3d-b0
  Acct-Mcast-In-Octets=0
  Acct-Mcast-Out-Octets=0
  Acct-Mcast-In-Packets=0
  Acct-Mcast-Out-Packets=0
  Platform-Type=4
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 BB 0E 80}
  Agent-Circuit-Id={00 04 03 E7 00 0B}
  IP-Interface-Name=clients
  Service-Name=SE
  Service-Options:0=1
  OS-Version=6.5.1.5
  UNKNOWN[2352-125]={4D 53 46 54 20 35 2E 30}
  NAS-Real-Port=33751040
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[3561--1]={01 08 00 04 03 E7 00 0B}

radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-7] InetRadiusProcessor - REQUEST_AFTER_PREPROCESS:
Packet type: Accounting-Request
Identifier: 211
Authenticator: {C7 88 F0 EA 04 4C D8 4B D5 79 42 EB 88 A6 68 89}
Attributes:
  User-Name=00:22:15:2e:3d:b0
  NAS-Identifier=RedBack
  NAS-IP-Address=192.168.1.25
  NAS-Port=33751040
  Service-Type=5
  Acct-Input-Octets=1135688
  Acct-Output-Octets=9339923
  Acct-Status-Type=2
  Acct-Session-Time=4502
  Acct-Input-Packets=5675
  Acct-Session-Id=0102FFFF7800BBFD-564C6795-SE-514F1D8E
  Acct-Authentic=1
  Acct-Interim-Interval=9000
  Acct-Multi-Session-Id=0102FFFF7800BBFD-564C6795
  Acct-Terminate-Cause=3
  NAS-Port-Id=2/3 clips 245443
  Acct-Output-Packets=11232
  Event-Timestamp=1447852332
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  NAS-Port-Type=5
  Called-Station-Id=xxx.xxx.xxx.xxx
  Acct-Mcast-Out-Packets-64={00 00 00 00 00 00 00 00}
  DHCP-Max-Leases=1
  UNKNOWN[2352-201]={01 B2 D4 83 00}
  Session-Error-Msg=Session down
  UNKNOWN[2352-202]={3D 3D 07 01 00 22 15 2E 3D B0}
  UNKNOWN[2352-202]={0C 0C 0A 53 65 72 67 65 79 2D 78 78 69}
  Session-Error-Code=33
  Acct-Output-Octets-64={00 00 00 00 00 8E 84 13}
  Acct-Input-Octets-64={00 00 00 00 00 11 54 48}
  Acct-Output-Packets-64={00 00 00 00 00 00 2B E0}
  Acct-Input-Packets-64={00 00 00 00 00 00 16 2B}
  Acct-Mcast-In-Octets-64={00 00 00 00 00 00 00 00}
  Service-Parameter=Rate=60000 Burst=7500000
  Assigned-IP-Address=yyy.yyy.yyy.yyy
  Acct-Mcast-In-Packets-64={00 00 00 00 00 00 00 00}
  Acct-Mcast-Out-Octets-64={00 00 00 00 00 00 00 00}
  Acct-Update-Reason=25
  Mac-Addr=00-22-15-2e-3d-b0
  Acct-Mcast-In-Octets=0
  Acct-Mcast-Out-Octets=0
  Acct-Mcast-In-Packets=0
  Acct-Mcast-Out-Packets=0
  Platform-Type=4
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 BB 0E 80}
  Agent-Circuit-Id={00 04 03 E7 00 0B}
  IP-Interface-Name=clients
  Service-Name=SE
  Service-Options:0=1
  OS-Version=6.5.1.5
  UNKNOWN[2352-125]={4D 53 46 54 20 35 2E 30}
  NAS-Real-Port=33751040
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[3561--1]={01 08 00 04 03 E7 00 0B}
Common options: {macAddress=00-22-15-2e-3d-b0, parentAcctSessionId=0102FFFF7800BBFD-564C6795, serviceName=SE}
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-7] InetRadiusProcessor - Session 0102FFFF7800BBFD-564C6795-SE-514F1D8E found.
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-7] InetNas - Stopping NasConnection
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-7] connection - 2214761:3732161 Stopping NasConnection
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-7] InetConnectionRuntime - Stopping connection with id=2214761
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-7] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 211
Authenticator: {27 CD BF FD C5 18 E3 34 B7 18 B2 74 45 A8 CE 58}
Attributes:
2

radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 212
Authenticator: {7D 81 52 0B 1E 99 4C 69 E4 D7 AD 2D 0B 7C FB 4D}
Attributes:
  User-Name=00:22:15:2e:3d:b0
  NAS-Identifier=RedBack
  NAS-IP-Address=192.168.1.25
  NAS-Port=33751040
  Service-Type=5
  Acct-Input-Octets=1240193
  Acct-Output-Octets=9497171
  Acct-Status-Type=2
  Acct-Session-Time=4502
  Acct-Input-Packets=5675
  Acct-Session-Id=0102FFFF7800BBFD-564C6795
  Acct-Authentic=1
  Acct-Interim-Interval=9000
  Acct-Terminate-Cause=15
  NAS-Port-Id=2/3 clips 245443
  Acct-Output-Packets=11232
  Event-Timestamp=1447852332
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  NAS-Port-Type=5
  Called-Station-Id=xxx.xxx.xxx.xxx
  Acct-Mcast-Out-Packets-64={00 00 00 00 00 00 00 00}
  DHCP-Max-Leases=1
  UNKNOWN[2352-201]={01 B2 D4 83 00}
  Session-Error-Msg=DHCP lease nack'ed
  UNKNOWN[2352-202]={3D 3D 07 01 00 22 15 2E 3D B0}
  UNKNOWN[2352-202]={0C 0C 0A 53 65 72 67 65 79 2D 78 78 69}
  Session-Error-Code=197
  Acct-Output-Octets-64={00 00 00 00 00 90 EA 53}
  Acct-Input-Octets-64={00 00 00 00 00 12 EC 81}
  Acct-Output-Packets-64={00 00 00 00 00 00 2B E0}
  Acct-Input-Packets-64={00 00 00 00 00 00 16 2B}
  Acct-Input-Packets-64={00 00 00 00 00 00 16 2B}
  Acct-Mcast-In-Octets-64={00 00 00 00 00 00 00 00}
  Assigned-IP-Address=yyy.yyy.yyy.yyy
  Acct-Mcast-In-Packets-64={00 00 00 00 00 00 00 00}
  Acct-Mcast-Out-Octets-64={00 00 00 00 00 00 00 00}
  Qos-Policing-Profile-Name=DEF-IPOE-IN
  Acct-Update-Reason=2
  Mac-Addr=00-22-15-2e-3d-b0
  Acct-Mcast-In-Octets=0
  Acct-Mcast-Out-Octets=0
  Qos-Metering-Profile-Name=DEF-IPOE-OUT
  Acct-Mcast-In-Packets=0
  Acct-Mcast-Out-Packets=0
  Platform-Type=4
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 BB 0E 80}
  Agent-Circuit-Id={00 04 03 E7 00 0B}
  IP-Interface-Name=clients
  NAT-Policy-Name=nat-policy
  OS-Version=6.5.1.5
  UNKNOWN[2352-125]={4D 53 46 54 20 35 2E 30}
  NAS-Real-Port=33751040
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[3561--1]={01 08 00 04 03 E7 00 0B}

radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] SmartEdgeClipsProtocolHandler - Parse as DLink
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] InetRadiusProcessor - REQUEST_AFTER_PREPROCESS:
Packet type: Accounting-Request
Identifier: 212
Authenticator: {7D 81 52 0B 1E 99 4C 69 E4 D7 AD 2D 0B 7C FB 4D}
Attributes:
  User-Name=0006c8be19bb0e80:000403e7000b
  NAS-Identifier=RedBack
  NAS-IP-Address=192.168.1.25
  NAS-Port=33751040
  Service-Type=5
  Acct-Input-Octets=1240193
  Acct-Output-Octets=9497171
  Acct-Status-Type=2
  Acct-Session-Time=4502
  Acct-Input-Packets=5675
  Acct-Session-Id=0102FFFF7800BBFD-564C6795
  Acct-Authentic=1
  Acct-Interim-Interval=9000
  Acct-Terminate-Cause=15
  NAS-Port-Id=2/3 clips 245443
  Acct-Output-Packets=11232
  Event-Timestamp=1447852332
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  Calling-Station-Id=0022152e3db0
  NAS-Port-Type=5
  Called-Station-Id=xxx.xxx.xxx.xxx
  Acct-Mcast-Out-Packets-64={00 00 00 00 00 00 00 00}
  DHCP-Max-Leases=1
  UNKNOWN[2352-201]={01 B2 D4 83 00}
  Session-Error-Msg=DHCP lease nack'ed
  UNKNOWN[2352-202]={3D 3D 07 01 00 22 15 2E 3D B0}
  UNKNOWN[2352-202]={0C 0C 0A 53 65 72 67 65 79 2D 78 78 69}
  Session-Error-Code=197
  Acct-Output-Octets-64={00 00 00 00 00 90 EA 53}
  Acct-Input-Octets-64={00 00 00 00 00 12 EC 81}
  Acct-Output-Packets-64={00 00 00 00 00 00 2B E0}
  Acct-Input-Packets-64={00 00 00 00 00 00 16 2B}
  Acct-Mcast-In-Octets-64={00 00 00 00 00 00 00 00}
  Assigned-IP-Address=yyy.yyy.yyy.yyy
  Acct-Mcast-In-Packets-64={00 00 00 00 00 00 00 00}
  Acct-Mcast-Out-Octets-64={00 00 00 00 00 00 00 00}
  Qos-Policing-Profile-Name=DEF-IPOE-IN
  Acct-Update-Reason=2
  Mac-Addr=00-22-15-2e-3d-b0
  Acct-Mcast-In-Octets=0
  Acct-Mcast-Out-Octets=0
  Qos-Metering-Profile-Name=DEF-IPOE-OUT
  Acct-Mcast-In-Packets=0
  Acct-Mcast-Out-Packets=0
  Platform-Type=4
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 BB 0E 80}
  Agent-Circuit-Id={00 04 03 E7 00 0B}
  IP-Interface-Name=clients
  NAT-Policy-Name=nat-policy
  OS-Version=6.5.1.5
  UNKNOWN[2352-125]={4D 53 46 54 20 35 2E 30}
  NAS-Real-Port=33751040
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[3561--1]={01 08 00 04 03 E7 00 0B}
Common options: {agentRemoteId={c8be19bb0e80}, macAddress=00-22-15-2e-3d-b0, agentCircuitId={03e7000b}}
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] InetRadiusProcessor - Session 0102FFFF7800BBFD-564C6795 found.
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] InetNas - Stopping NasConnection
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] connection - 2214760:3732160 Stopping NasConnection
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] InetConnectionRuntime - Stopping connection with id=2214760
radius 11-18/15:45:18  INFO [rdsLstnr-p-8-t-1] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 212
Authenticator: {24 8A C6 2F 32 E8 71 EB 6F C3 45 01 B3 1E F1 F9}
Attributes:

Process time stop: 2

где он берет это время, у нас в настройках lease-time=9000
Автор:  Amir [ 18 ноя 2015, 20:12 ]
Заголовок сообщения:  Re: Отваливаются сессии
Какой билд до этого был?
Можете дать доступ?
Посмотрите в логах какие DHCP-пакеты с таким же MAC-адресом (00-22-15-2e-3d-b0 -> 0022152e3db0) и какие еще сообщения при обработке этих DHCP-пакетов прямо перед этими RADIUS-стоп-пакетами.
Автор:  sergey-xxi [ 18 ноя 2015, 20:45 ]
Заголовок сообщения:  Re: Отваливаются сессии
Сейчас поставили стандартный обработчик, все "вроде" заработало. В аккцесе есть ошибки.

Код:
dhcp 11-18/10:26:39 ERROR [dhcpLstnr-p-11-t-5] WorkerTask - ru.bitel.bgbilling.kernel.network.dhcp.DhcpPacket.clearSubOptions()V
java.lang.NoSuchMethodError: ru.bitel.bgbilling.kernel.network.dhcp.DhcpPacket.clearSubOptions()V
        at ru.clink.bgbilling.inet.serv.SmartEdgeClipsProtocolHandler.preprocessDhcpRequest(SmartEdgeClipsProtocolHandler.java:106)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processOption82Request(InetAbstractDhcpProcessor.java:489)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processRequest(InetAbstractDhcpProcessor.java:250)
        at ru.bitel.bgbilling.kernel.network.dhcp.DhcpListenerWorker.runImpl(DhcpListenerWorker.java:89)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)

Предыдущий был 915 билд
Данные для доступа отправлю вам в личку чуть позже.
Автор:  Amir [ 18 ноя 2015, 21:12 ]
Заголовок сообщения:  Re: Отваливаются сессии
Опять ругается на то что метода нет. Посмотрел сейчас - в update_6.1 этот метод есть.
Может быть InetAccess не обновили после обновления биллинга?
Он может не обновиться если находится на другой машине и время между машинами сильно расходится - тогда в выводе будут ошибки.
Автор:  sergey-xxi [ 19 ноя 2015, 12:06 ]
Заголовок сообщения:  Re: Отваливаются сессии
Ошибся, эта ошибка сейчас сыпет в акцессе:
Код:
dhcp 11-19/08:52:15 ERROR [dhcpLstnr-p-11-t-7] DhcpListenerWorker - 7
java.lang.ArrayIndexOutOfBoundsException: 7
        at ru.bitel.bgbilling.modules.inet.api.server.InetUtils.parseInt(InetUtils.java:573)
        at ru.bitel.bgbilling.modules.inet.runtime.device.AbstractInetDeviceRuntime.getOption82InterfaceId(AbstractInetDeviceRuntime.java:299)
        at ru.bitel.bgbilling.modules.inet.runtime.device.InetDeviceRuntime.getOption82InterfaceId(InetDeviceRuntime.java:1)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.getKey2(InetDhcpHelperProcessor.java:140)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.processOption82RequestImpl(InetDhcpHelperProcessor.java:652)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processOption82Request(InetAbstractDhcpProcessor.java:504)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processRequest(InetAbstractDhcpProcessor.java:253)
        at ru.bitel.bgbilling.kernel.network.dhcp.DhcpListenerWorker.runImpl(DhcpListenerWorker.java:89)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)

Заметили такую проблему - некоторых сессий нет в биллинге (хотя на редбеке они остались) после перехода времени 24-00, и у абонента все продолжает работать.
Автор:  sergey-xxi [ 19 ноя 2015, 12:08 ]
Заголовок сообщения:  Re: Отваливаются сессии
Код:
bg access # ./access_status.sh
Java Runtime: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM [1.7.0_60] /opt/jdk-1.7/jre
  Runtime name: 16832@bg
  Java endorsed dirs: /lib/endorsed:/opt/jdk-1.7/lib/endorsed
  OS: Linux 3.10.17-gentoo [amd64], file.encoding: ANSI_X3.4-1968, user.name: root
  Heap sizes: current=92160k  free=90654k  max=1359872k
Kernel version 6.1.1105 / 10.11.2015 13:08:28
Inet version 6.1.720 / 10.11.2015 13:08:37
Radius:
  accounting-requests per minute start: 0; stop: 0; update: 0
  access-requests per minute accept: 1; reject: 0
  ignore per minute access-request: 0; accounting-update: 0
Antispam ban count: 0; used per minute: 0
Автор:  sergey-xxi [ 19 ноя 2015, 12:42 ]
Заголовок сообщения:  Re: Отваливаются сессии
Ошибка возникает у небольшого количества абонентов по всей видимости из-за отсутствия в DHCP-запросах опции agentRemoteId:
Код:
dhcp 11-19/09:18:56  INFO [dhcpLstnr-p-11-t-1] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 2
xid: 463908858, secs: 17230, flags: 0
Client IP: 178.212.132.10
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.12.247
Client MAC: {F0D1A908E42C}
  IP Address Lease Time{51}=86400
  Host name{12}={airport-express}
  Parameter request list{55}={1, 2, 3, 15, 6, 12, 44}
  {57}={05DC}
  {61}={01F0D1A908E42C}
  Agent information{82}=
    sub{1}={322F33}

dhcp 11-19/09:18:56  INFO [dhcpLstnr-p-11-t-1] InetAbstractDhcpProcessor - agentRemoteId is empty
dhcp 11-19/09:18:56  INFO [dhcpLstnr-p-11-t-1] InetAbstractDhcpProcessor - REQUEST_AFTER_PREPROCESS:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 2
xid: 463908858, secs: 17230, flags: 0
Client IP: 178.212.132.10
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.12.247
Client MAC: {F0D1A908E42C}
  IP Address Lease Time{51}=86400
  Host name{12}={airport-express}
  Parameter request list{55}={1, 2, 3, 15, 6, 12, 44}
  {57}={05DC}
  {61}={01F0D1A908E42C}
  Agent information{82}=
    sub{1}={322F33}

dhcp 11-19/09:18:56 ERROR [dhcpLstnr-p-11-t-1] DhcpListenerWorker - 7
java.lang.ArrayIndexOutOfBoundsException: 7
        at ru.bitel.bgbilling.modules.inet.api.server.InetUtils.parseInt(InetUtils.java:573)
        at ru.bitel.bgbilling.modules.inet.runtime.device.AbstractInetDeviceRuntime.getOption82InterfaceId(AbstractInetDeviceRuntime.java:299)
        at ru.bitel.bgbilling.modules.inet.runtime.device.InetDeviceRuntime.getOption82InterfaceId(InetDeviceRuntime.java:1)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.getKey2(InetDhcpHelperProcessor.java:140)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.processOption82RequestImpl(InetDhcpHelperProcessor.java:652)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processOption82Request(InetAbstractDhcpProcessor.java:504)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processRequest(InetAbstractDhcpProcessor.java:253)
        at ru.bitel.bgbilling.kernel.network.dhcp.DhcpListenerWorker.runImpl(DhcpListenerWorker.java:89)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)

Странно, что на одном и том же коммутаторе есть проблемные сессии, и нормальные в которых присылается agentRemoteId.
Автор:  sergey-xxi [ 19 ноя 2015, 12:56 ]
Заголовок сообщения:  Re: Отваливаются сессии
полная картина:
Код:
dhcp 11-19/09:40:29  INFO [dhcpLstnr-p-11-t-7] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 2
xid: -2110835645, secs: 0, flags: 0
Client IP: 0.0.0.0
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.12.247
Client MAC: {001111111111}
  {61}={01001111111111}
  Requested IP Address{50}=10.21.85.220
  Server Identifier{54}={C0A80CFD}
  Host name{12}={Sergey-xxi}
  {81}={0000005365726765792D7878692E}
  {60}={4D53465420352E30}
  Parameter request list{55}={1, 15, 3, 6, 44, 46, 47, 31, 33, -7, 43}
  Agent information{82}=
    sub{1}={000403E70009}
    sub{2}={0006C8BE19BB0E80}

dhcp 11-19/09:40:29  INFO [dhcpLstnr-p-11-t-7] InetAbstractDhcpProcessor - RESPONSE:
Message type: BOOT_RESPONSE
Dhcp message type: DHCP ACK{5}
htype: 1, hlen: 6, hops: 2
xid: -2110835645, secs: 0, flags: 0
Client IP: 0.0.0.0
Your IP: 10.21.85.220
Server IP: 0.0.0.0
Relay IP: 192.168.12.247
Client MAC: {001111111111}
  Agent information{82}=
    sub{1}={000403E70009}
    sub{2}={0006C8BE19BB0E80}
  IP Address Lease Time{51}=60
  Server Identifier{54}={00000000}
  Subnet mask{1}=255.255.248.0
  DNS{6}={C0A80C0308080808}
  Router{3}=10.21.80.1

mq 11-19/09:40:29  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2214061-2214060, iface=2:33751040, sessId=0102FFFF7800BC2A-564C5BE0-SE-9EA7EEEB, start=18.11.2015 13:40:19, uname=SE, addr=[IpAddr
ess:null]]
mq 11-19/09:40:30  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2216887-2216886, iface=2:33751040, sessId=0102FFFF7800AC16-564C7EF5-SE-B5F578CA, start=18.11.2015 16:10:00, uname=SE, addr=[IpAddr
ess:null]]
mq 11-19/09:40:30  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2218321-2218320, iface=2:33751040, sessId=0102FFFF780104F3-564C9791-SE-2D77F3D0, start=18.11.2015 17:55:00, uname=SE, addr=[IpAddr
ess:null]]
mq 11-19/09:40:30  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2214352-2214351, iface=2:33751040, sessId=0102FFFF7800BCE4-564C5F65-SE-D4588D50, start=18.11.2015 13:55:20, uname=SE, addr=[IpAddr
ess:null]]
mq 11-19/09:40:31  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2213660-2213659, iface=2:33751040, sessId=0102FFFF7800BB27-564C585E-SE-6916E356, start=18.11.2015 13:25:21, uname=SE, addr=[IpAddr
ess:null]]
dhcp 11-19/09:40:59  INFO [dhcpLstnr-p-11-t-2] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 2
xid: -613756049, secs: 0, flags: 0
Client IP: 10.21.85.220
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.12.247
Client MAC: {001111111111}
  {61}={01001111111111}
  Host name{12}={Sergey-xxi}
  {81}={0000005365726765792D7878692E}
  {60}={4D53465420352E30}
  Parameter request list{55}={1, 15, 3, 6, 44, 46, 47, 31, 33, -7, 43}
  Agent information{82}=
    sub{1}={322F33}

dhcp 11-19/09:40:59  INFO [dhcpLstnr-p-11-t-2] InetAbstractDhcpProcessor - agentRemoteId is empty
dhcp 11-19/09:40:59  INFO [dhcpLstnr-p-11-t-2] InetAbstractDhcpProcessor - REQUEST_AFTER_PREPROCESS:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 2
xid: -613756049, secs: 0, flags: 0
Client IP: 10.21.85.220
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.12.247
Client MAC: {001111111111}
  {61}={01001111111111}
  Host name{12}={Sergey-xxi}
  {81}={0000005365726765792D7878692E}
  {60}={4D53465420352E30}
  Parameter request list{55}={1, 15, 3, 6, 44, 46, 47, 31, 33, -7, 43}
  Agent information{82}=
    sub{1}={322F33}

dhcp 11-19/09:40:59 ERROR [dhcpLstnr-p-11-t-2] DhcpListenerWorker - 7
java.lang.ArrayIndexOutOfBoundsException: 7
        at ru.bitel.bgbilling.modules.inet.api.server.InetUtils.parseInt(InetUtils.java:573)
        at ru.bitel.bgbilling.modules.inet.runtime.device.AbstractInetDeviceRuntime.getOption82InterfaceId(AbstractInetDeviceRuntime.java:299)
        at ru.bitel.bgbilling.modules.inet.runtime.device.InetDeviceRuntime.getOption82InterfaceId(InetDeviceRuntime.java:1)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.getKey2(InetDhcpHelperProcessor.java:140)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.processOption82RequestImpl(InetDhcpHelperProcessor.java:652)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processOption82Request(InetAbstractDhcpProcessor.java:504)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processRequest(InetAbstractDhcpProcessor.java:253)
        at ru.bitel.bgbilling.kernel.network.dhcp.DhcpListenerWorker.runImpl(DhcpListenerWorker.java:89)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)
Автор:  sergey-xxi [ 30 ноя 2015, 12:28 ]
Заголовок сообщения:  Re: Отваливаются сессии
up
Автор:  sergey-xxi [ 01 дек 2015, 14:31 ]
Заголовок сообщения:  Re: Отваливаются сессии
По истечении lease-time связь теряется на несколько сек и начинается новая сессия.
access.log
Код:
dhcp 11-30/23:19:33  INFO [dhcpLstnr-p-11-t-9] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 1
xid: -1071592494, secs: 0, flags: 0
Client IP: yyy.yyy.yyy.yyy
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  {61}={01001111111113}
  Host name{12}={Sergey-xxi}
  {81}={0000005365726765792D7878692E}
  {60}={4D53465420352E30}
  Parameter request list{55}={1, 15, 3, 6, 44, 46, 47, 31, 33, -7, 43}
  Agent information{82}=
    sub{1}={322F3120766C616E2D696420393939}

dhcp 11-30/23:19:33  INFO [dhcpLstnr-p-11-t-9] InetAbstractDhcpProcessor - agentRemoteId is empty
dhcp 11-30/23:19:33  INFO [dhcpLstnr-p-11-t-9] InetAbstractDhcpProcessor - REQUEST_AFTER_PREPROCESS:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 1
xid: -1071592494, secs: 0, flags: 0
Client IP: yyy.yyy.yyy.yyy
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  {61}={01001111111113}
  Host name{12}={Sergey-xxi}
  {81}={0000005365726765792D7878692E}
  {60}={4D53465420352E30}
  Parameter request list{55}={1, 15, 3, 6, 44, 46, 47, 31, 33, -7, 43}
  Agent information{82}=
    sub{1}={322F3120766C616E2D696420393939}

dhcp 11-30/23:19:33 ERROR [dhcpLstnr-p-11-t-9] InetDhcpHelperProcessor - Not found params for request: 2:001111111113 (pattern: $remoteId:$mac, servSearchMod
e: 1, deviceId: 2, agentDeviceId: 2, mac: 001111111113)
dhcp 11-30/23:19:33  INFO [dhcpLstnr-p-11-t-9] InetAbstractDhcpProcessor - RESPONSE_BEFORE_POSTPROCESS:
Message type: BOOT_RESPONSE
Dhcp message type: DHCP NAK{6}
htype: 1, hlen: 6, hops: 1
xid: -1071592494, secs: 0, flags: 0
Client IP: yyy.yyy.yyy.yyy
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  Agent information{82}=
    sub{1}={322F3120766C616E2D696420393939}

dhcp 11-30/23:19:33  INFO [dhcpLstnr-p-11-t-9] InetAbstractDhcpProcessor - RESPONSE:
Message type: BOOT_RESPONSE
Dhcp message type: DHCP NAK{6}
htype: 1, hlen: 6, hops: 1
xid: -1071592494, secs: 0, flags: 0
Client IP: yyy.yyy.yyy.yyy
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  Agent information{82}=
    sub{1}={322F3120766C616E2D696420393939}

mq 11-30/23:19:33  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2253302-2253301, iface=2:33751040, sessId=0102FFFF
7800246F-5658346C-SE-8087C175, start=27.11.2015 13:19:19, uname=SE, addr=[IpAddress:null]]
mq 11-30/23:19:34  INFO [event-proc-p-2-t-1] InetConnectionManager - Remove connection: InetConnection [id=2255476-2255475, iface=2:553649127, sessId=0100FFF
F780027F8-565CB3D4-SE-21A43CBC, start=30.11.2015 23:12:03, uname=SE, addr=[IpAddress:null]]
mq 11-30/23:19:34  INFO [event-proc-p-2-t-1] InetConnectionManager - Remove connection: InetConnection [id=2255475-0, iface=2:553649127, sessId=0100FFFF78002
7F8-565CB3D4, start=30.11.2015 23:12:03, uname=0006c8be19bb0e80:000403e7000b, addr=yyy.yyy.yyy.yyy]
mq 11-30/23:19:34  INFO [event-proc-p-2-t-1] InetDhcpHelperProcessor - Remove connection remove 4:001111111113 yyy.yyy.yyy.yyy: true
connection 11-30/23:19:34  INFO [sa-p-15-t-31] ServiceActivatorSet - Connecting to device
connection 11-30/23:19:34  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Do task deviceId: 2; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.Inet
SaAccountingEvent] moduleId: 14; pluginId: no; cid: 89; scid: -1; userId: 0; type: 2; deviceId: 2; connectionId: 2255475; timestamp: 1448914774187
connection 11-30/23:19:34  INFO [sa-p-15-t-31] InetApplication - TariffOptionMap: {}
connection 11-30/23:19:34  INFO [sa-p-15-t-31] InetApplication - OptionSet: [11]
connection 11-30/23:19:34  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=5; inetServId: 4708; call: tru
e; oldState: 1; newState: 1; oldOptionSet: 11; newOptionSet: 11
connection 11-30/23:19:34  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Processing deviceId:2; command ServiceActivatorEvent type=5; inetServId: 4708;
call: true; oldState: 1; newState: 1; oldOptionSet: 11; newOptionSet: 11
connection 11-30/23:19:34  INFO [sa-p-15-t-31] ServiceActivatorSet - Invoking onAccountingStop
connection 11-30/23:19:34  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Process event type[5] result=true
mq 11-30/23:19:36  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2254706-2254705, iface=2:33751040, sessId=0102FFFF
7800266C-565AFE16-SE-0A32C53D, start=29.11.2015 16:04:19, uname=SE, addr=[IpAddress:null]]
mq 11-30/23:19:36  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=2254872-2254871, iface=2:33751040, sessId=0102FFFF
780026C1-565BDF1E-SE-73EBF49B, start=30.11.2015 08:04:28, uname=SE, addr=[IpAddress:null]]
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 144
Authenticator: {A5 7F 0C 1D 7A 99 AA 40 40 B5 C5 A6 4C FC EC 57}
Attributes:
  User-Name=00:11:11:11:11:13
  NAS-Port-Id=2/1 vlan-id 999 clips 141305
  NAS-Identifier=RedBack
  User-Password=Redback
  NAS-IP-Address=192.168.1.2
  NAS-Port=553649127
  Service-Type=5
  NAS-Port-Type=5
  Platform-Type=4
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[2352-202]={3D 3D 07 01 00 11 11 11 11 13}
  UNKNOWN[2352-202]={0C 0C 0A 53 65 72 67 65 79 2D 78 78 69}
  Agent-Circuit-Id={00 04 03 E7 00 0B}
  OS-Version=6.5.1.5
  Mac-Addr=00-11-11-11-11-13
  UNKNOWN[2352-125]={4D 53 46 54 20 35 2E 30}
  NAS-Real-Port=553649127
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[3561--1]={01 08 00 04 03 E7 00 0B}

radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusProcessor - REQUEST_AFTER_PREPROCESS:
Packet type: Access-Request
Identifier: 144
Authenticator: {A5 7F 0C 1D 7A 99 AA 40 40 B5 C5 A6 4C FC EC 57}
Attributes:
  User-Name=0006c8be19bb0e80:000403e7000b
  NAS-Port-Id=2/1 vlan-id 999 clips 141305
  NAS-Identifier=RedBack
  User-Password=Redback
  NAS-IP-Address=192.168.1.2
  NAS-Port=553649127
  Service-Type=5
  Calling-Station-Id=001111111113
  NAS-Port-Type=5
  Platform-Type=4
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[2352-202]={3D 3D 07 01 00 11 11 11 11 13}
  UNKNOWN[2352-202]={0C 0C 0A 53 65 72 67 65 79 2D 78 78 69}
  Agent-Circuit-Id={00 04 03 E7 00 0B}
  OS-Version=6.5.1.5
  Mac-Addr=00-11-11-11-11-13
  UNKNOWN[2352-125]={4D 53 46 54 20 35 2E 30}
  NAS-Real-Port=553649127
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 BB 0E 80}
  UNKNOWN[3561--1]={01 08 00 04 03 E7 00 0B}
Common options: {agentRemoteId={c8be19bb0e80}, macAddress=00-11-11-11-11-13, agentCircuitId={03e7000b}}
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetNas - Found agentDevice:4
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetNas - Search serv on deviceId=4; interfaceId=11
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetNas - Search child serv by mac on device=001111111113
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusProcessor - [username=0006c8be19bb0e80:000403e7000b] Authenticated as inetServId:4708
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetApplication - TariffOptionMap: {}
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetApplication - inetServ[id=4708] balance ok: -267833.95 [-10000000.00]
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetConnectionManager - Check for duplicate session 001111111113
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetApplication - OptionSet: [11]
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusProcessor - Set ip from serv
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusProcessor - Write new waiting connection to DB
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusProcessor - New connection id=2255478
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusProcessor - Return code=0
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetDhcpHelperProcessor - Put auth accept 4:001111111113 yyy.yyy.yyy.yyy
radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusProcessor - RESPONSE_BEFORE_POSTPROCESS:
Packet type: Access-Accept
Identifier: 144
Authenticator: {}
Attributes:
  Acct-Interim-Interval=90000
  Framed-IP-Address=yyy.yyy.yyy.yyy
  DHCP-Max-Leases=1
  Service-Name:1=SE
  Service-Options:1=1
  Service-Parameter:1=Rate=60000 Burst=7500000
  IP-Interface-Name=clients

Process time auth: 2

radius 11-30/23:19:38  INFO [rdsLstnr-p-9-t-2] InetRadiusListenerWorker - RESPONSE:
Packet type: Access-Accept
Identifier: 144
Authenticator: {D1 6B F8 D4 61 E2 C3 63 17 F6 96 60 AB 40 A1 EE}
Attributes:
  Acct-Interim-Interval=90000
  DHCP-Max-Leases=1
  Service-Name:1=SE
  Service-Options:1=1
  Service-Parameter:1=Rate=60000 Burst=7500000
  IP-Interface-Name=clients

Process time auth: 2

connection 11-30/23:19:38  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Do task deviceId: 2; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.Inet
SaAccountingEvent] moduleId: 14; pluginId: no; cid: 89; scid: -1; userId: 0; type: 1; deviceId: 2; connectionId: 2255478; timestamp: 1448914778149
connection 11-30/23:19:38  INFO [sa-p-15-t-31] InetApplication - TariffOptionMap: {}
connection 11-30/23:19:38  INFO [sa-p-15-t-31] InetApplication - OptionSet: [11]
connection 11-30/23:19:38  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=4; inetServId: 4708; call: tru
e; oldState: 1; newState: 1; oldOptionSet: 11; newOptionSet: 11
connection 11-30/23:19:38  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Processing deviceId:2; command ServiceActivatorEvent type=4; inetServId: 4708;
call: true; oldState: 1; newState: 1; oldOptionSet: 11; newOptionSet: 11
connection 11-30/23:19:38  INFO [sa-p-15-t-31] ServiceActivatorSet - Invoking onAccountingStart
connection 11-30/23:19:38  INFO [sa-p-15-t-31] ServiceActivatorDeviceWorker - Process event type[4] result=true
mq 11-30/23:19:38  INFO [event-proc-p-2-t-1] InetConnectionManager - Add connection: InetConnection [id=2255478-0, iface=2:553649127, sessId=0100FFFF780027F9
-565CB59B, start=30.11.2015 23:19:38, uname=0006c8be19bb0e80:000403e7000b, addr=yyy.yyy.yyy.yyy]
mq 11-30/23:19:38  INFO [event-proc-p-2-t-1] InetDhcpHelperProcessor - Put connection add 4:001111111113 yyy.yyy.yyy.yyy
mq 11-30/23:19:38  INFO [event-proc-p-2-t-1] InetConnectionManager - Add connection: InetConnection [id=2255479-2255478, iface=2:553649127, sessId=0100FFFF78
0027F9-565CB59B-SE-3CC29F72, start=30.11.2015 23:19:38, uname=SE, addr=[IpAddress:null]]
dhcp 11-30/23:19:38  INFO [dhcpLstnr-p-11-t-8] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Discover{1}
htype: 1, hlen: 6, hops: 1
xid: -796120194, secs: 0, flags: 0
Client IP: 0.0.0.0
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  {116}={01}
  {61}={01001111111113}
  Host name{12}={Sergey-xxi}
  {60}={4D53465420352E30}
  Parameter request list{55}={1, 15, 3, 6, 44, 46, 47, 31, 33, -7, 43}
  Agent information{82}=
    sub{1}={000403E7000B}
    sub{2}={0006C8BE19BB0E80}

dhcp 11-30/23:19:38  INFO [dhcpLstnr-p-11-t-8] InetAbstractDhcpProcessor - RESPONSE:
Message type: BOOT_RESPONSE
Dhcp message type: DHCP Offer{2}
htype: 1, hlen: 6, hops: 1
xid: -796120194, secs: 0, flags: 0
Client IP: 0.0.0.0
Your IP: yyy.yyy.yyy.yyy
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  Agent information{82}=
    sub{1}={000403E7000B}
    sub{2}={0006C8BE19BB0E80}
  IP Address Lease Time{51}=900
  Server Identifier{54}={00000000}
  Subnet mask{1}=255.255.248.0
  Router{3}=xxx.xxx.xxx.xxx
  DNS{6}={08080808C0A80C03}

dhcp 11-30/23:19:38  INFO [dhcpLstnr-p-11-t-5] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 1
xid: -796120194, secs: 0, flags: 0
Client IP: 0.0.0.0
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  {61}={01001111111113}
  Requested IP Address{50}=yyy.yyy.yyy.yyy
  Server Identifier{54}={C0A80CFD}
  Host name{12}={Sergey-xxi}
  {81}={0000005365726765792D7878692E}
  {60}={4D53465420352E30}
  Parameter request list{55}={1, 15, 3, 6, 44, 46, 47, 31, 33, -7, 43}
  Agent information{82}=
    sub{1}={000403E7000B}
    sub{2}={0006C8BE19BB0E80}

dhcp 11-30/23:19:38  INFO [dhcpLstnr-p-11-t-5] InetAbstractDhcpProcessor - RESPONSE:
Message type: BOOT_RESPONSE
Dhcp message type: DHCP ACK{5}
htype: 1, hlen: 6, hops: 1
xid: -796120194, secs: 0, flags: 0
Client IP: 0.0.0.0
Your IP: yyy.yyy.yyy.yyy
Server IP: 0.0.0.0
Relay IP: 192.168.1.2
Client MAC: {001111111113}
  Agent information{82}=
    sub{1}={000403E7000B}
    sub{2}={0006C8BE19BB0E80}
  IP Address Lease Time{51}=900
  Server Identifier{54}={00000000}
  Subnet mask{1}=255.255.248.0
  Router{3}=xxx.xxx.xxx.xxx
  DNS{6}={08080808C0A80C03}

dhcp 11-30/23:19:38  INFO [dhcpLstnr-p-11-t-5] HourlyDataLogEntry - Create dataLog file: /bgbill/access/data/dhcp/source_4/2015/2015-11/2015-11-30/log_2015-1
1-30-23.001.bgdl


проскакивает ошибка
Код:
dhcp 11-30/23:19:32 ERROR [dhcpLstnr-p-11-t-4] DhcpListenerWorker - 7
java.lang.ArrayIndexOutOfBoundsException: 7
        at ru.bitel.bgbilling.modules.inet.api.server.InetUtils.parseInt(InetUtils.java:573)
        at ru.bitel.bgbilling.modules.inet.runtime.device.AbstractInetDeviceRuntime.getOption82InterfaceId(AbstractInetDeviceRuntime.java:299)
        at ru.bitel.bgbilling.modules.inet.runtime.device.InetDeviceRuntime.getOption82InterfaceId(InetDeviceRuntime.java:1)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.getKey2(InetDhcpHelperProcessor.java:140)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetDhcpHelperProcessor.processOption82RequestImpl(InetDhcpHelperProcessor.java:652)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processOption82Request(InetAbstractDhcpProcessor.java:504)
        at ru.bitel.bgbilling.modules.inet.dhcp.InetAbstractDhcpProcessor.processRequest(InetAbstractDhcpProcessor.java:253)
        at ru.bitel.bgbilling.kernel.network.dhcp.DhcpListenerWorker.runImpl(DhcpListenerWorker.java:89)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)
Автор:  Amir [ 01 дек 2015, 17:29 ]
Заголовок сообщения:  Re: Отваливаются сессии
Если рассматривать пример выше, то там при разборе DHCP и RADIUS пакетов он находит различающиеся агентские устройства - для DHCP устройство с ID=2:
Agent information{82}=
sub{1}={322F3120766C616E2D696420393939}
InetAbstractDhcpProcessor - agentRemoteId is empty
Not found params for request: 2:001111111113 (pattern: $remoteId:$mac, servSearchMod

Для RADIUS-пакета - устройство с ID=4:
Common options: {agentRemoteId={c8be19bb0e80}, macAddress=00-11-11-11-11-13, agentCircuitId={03e7000b}}

Похоже что DHCP-пакеты в стадии REBIND приходят с каким-то другим option82 - там строка в HEX: 2/1 vlan-id 999 и не видно agentRemoteId.
Автор:  Amir [ 01 дек 2015, 17:51 ]
Заголовок сообщения:  Re: Отваливаются сессии
REBIND мало отличается, от обычного DHCP-пакета, потому странно.
Вот у RENEW может быть другое поведение - он может быть отправлен напрямую на адрес serverIdentifier (если указан). Можно было бы предположить, что RENEW приходит на 192.168.1.2, а тот пересылает биллингу, а при обычных пакетах запрос идет от коммутатора уровнем ниже с уже добавленными опциями 82, но у вас serverIdentifier равен 0.0.0.0 (поэтому RENEW должен посылаться широковещательно), а в пакете Client IP не равен 0.0.0.0 (потому это не похоже на RENEW-запрос, а на REBIND).
Автор:  sergey-xxi [ 01 дек 2015, 18:43 ]
Заголовок сообщения:  Re: Отваливаются сессии
В настройках указано dhcp.option.serverIdentifier=0.0.0.0
Автор:  Amir [ 01 дек 2015, 19:06 ]
Заголовок сообщения:  Re: Отваливаются сессии
Цитата:
В настройках указано dhcp.option.serverIdentifier=0.0.0.0
Да, в каких-то случаях указывают 0.0.0.0 (в этом случае RENEW-запросы ), в каких-то адрес последнего релей-агента, в других - адрес DHCP-сервера биллинга. Видимо зависит от схемы сети и оборудования. Но это должно влиять на стадию RENEW - а запрос в логе похож на REBIND, т.к. поле Client IP!=0.0.0.0.
Автор:  sergey-xxi [ 01 дек 2015, 19:16 ]
Заголовок сообщения:  Re: Отваливаются сессии
leasetime указан 15 минут, разрыв сессий происходит каждые 7,5 минут. Поэтому это наверное RENEW-запросы.
Автор:  Amir [ 01 дек 2015, 19:37 ]
Заголовок сообщения:  Re: Отваливаются сессии
Да, Вы правы - перепутал, Client IP как раз должен быть не равен 0.0.0.0 и в RENEW и в REBIND. Отличие в том что RENEW идет unicast'ом.

serverIdentifier ранее не пробовали менять? Возможно стоит попробовать указать адрес DHCP-сервера InetAccess.
Также в конфиге должна быть включена обработка прямых RENEW-запросов (dhcp.renew=1).
Автор:  Amir [ 01 дек 2015, 19:40 ]
Заголовок сообщения:  Re: Отваливаются сессии
В данном RENEW запросе присутствует option82, поэтому DHCP-сервер пытается использовать эти значения.
В случае когда option82 нет и это RENEW запрос, пришедший напрямую - DHCP-сервер идентифицирует сессию по запрашиваемому IP-адресу.
Страница 1 из 2 Часовой пояс: UTC + 5 часов [ Летнее время ]
Powered by phpBB® Forum Software © phpBB Group
http://www.phpbb.com/