BiTel

radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 102
Authenticator: {18 D0 AE A1 06 94 9B 75 59 4D DE 57 D7 D5 8E AA}
Attributes:
  User-Name=00:25:b3:57:8a:1f
  NAS-Port-Id=2/1 vlan-id 340 clips 131175
  NAS-Identifier=Redback-IPOE-SLAV-L3
  User-Password=Redback
  NAS-IP-Address=192.168.244.77
  NAS-Port=553648468
  Service-Type=5
  NAS-Port-Type=5
  Called-Station-Id=10.248.192.254
  Platform-Type=4
  UNKNOWN[2352-201]={01 0A F8 C0 FE}
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 A9 00 B0}
  DHCP-Option={3D 3D 07 01 00 25 B3 57 8A 1F}
  DHCP-Option={0C 0C 06 48 50 2D 6B 69 72}
  Agent-Circuit-Id={00 04 03 21 00 01}
  OS-Version=11.1.2.9
  Mac-Addr=00-25-b3-57-8a-1f
  DHCP-Vendor-Class-Id=MSFT 5.0
  NAS-Real-Port=553648468
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 A9 00 B0}
  UNKNOWN[3561--1]={01 08 00 04 03 21 00 01}

radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] InetRadiusProcessor - REQUEST_AFTER_PREPROCESS:
Packet type: Access-Request
Identifier: 102
Authenticator: {18 D0 AE A1 06 94 9B 75 59 4D DE 57 D7 D5 8E AA}
Attributes:
  User-Name=0006c8be19a900b0:000403210001
  NAS-Port-Id=2/1 vlan-id 340 clips 131175
  NAS-Identifier=Redback-IPOE-SLAV-L3
  User-Password=Redback
  NAS-IP-Address=192.168.244.77
  NAS-Port=553648468
  Service-Type=5
  Calling-Station-Id=0025b3578a1f
  NAS-Port-Type=5
  Called-Station-Id=10.248.192.254
  Platform-Type=4
  UNKNOWN[2352-201]={01 0A F8 C0 FE}
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 A9 00 B0}
  DHCP-Option={3D 3D 07 01 00 25 B3 57 8A 1F}
  DHCP-Option={0C 0C 06 48 50 2D 6B 69 72}
  Agent-Circuit-Id={00 04 03 21 00 01}
  OS-Version=11.1.2.9
  Mac-Addr=00-25-b3-57-8a-1f
  DHCP-Vendor-Class-Id=MSFT 5.0
  NAS-Real-Port=553648468
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 A9 00 B0}
  UNKNOWN[3561--1]={01 08 00 04 03 21 00 01}
Common options: {agentRemoteId={c8be19a900b0}, agentCircuitId={000403210001}}
radius 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] RadiusProcessor - Create new radius session.
radius 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] InetNas - agentRemoteId=java.nio.DirectByteBufferR[pos=0 lim=6 cap=6]
radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] InetNas - Found agentDevice:12
radius 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] InetNas - findServ agentDeviceRuntime=ru.bitel.bgbilling.modules.inet.runtime.device.InetDeviceRuntime@73cb4cae
radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] InetNas - Search serv on deviceId=12; interfaceId=1
radius 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] InetRadiusProcessor - Password verification disabled.
radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] InetRadiusProcessor - [username=0006c8be19a900b0:000403210001] Authenticated as inetServId:6
radius 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] InetRadiusProcessor - Identifier from request: null
radius 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] InetRadiusProcessor - MAC-address from request:
radius 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] InetAccountingPeriodList - Create:
      AccountingPeriod: 4: 01.04.2014 00:00:00.0 - 30.04.2014 23:59:59.999
radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] InetApplication - inetServ[id=6] balance ok: 0.00 [-100000.00]
radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] InetUtils - Alive session count 2>1
radius 04-01/15:43:03  INFO [rdsLstnr-p-8-t-2] InetConnectionManager - Close duplicate session method 8
mq 04-01/15:43:03 DEBUG [rdsLstnr-p-8-t-2] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaConnectionCloseEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; deviceId: 9; inetServId: 6; connectionId: 203; timestamp: 1396327383669
connection 04-01/15:43:03  INFO [sa-p-13-t-6] ServiceActivatorSet - Connecting to device
connection 04-01/15:43:03 DEBUG [sa-p-13-t-6] AcknowledgeConsumer - Caught BGInetAccess:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaConnectionCloseEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; deviceId: 9; inetServId: 6; connectionId: 203; timestamp: 1396327383669
connection 04-01/15:43:03  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Do task deviceId: 9; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaConnectionCloseEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; deviceId: 9; inetServId: 6; connectionId: 203; timestamp: 1396327383669
connection 04-01/15:43:03  INFO [sa-p-13-t-6] InetApplication - TariffOptionMap: {}
connection 04-01/15:43:03  INFO [sa-p-13-t-6] InetApplication - OptionSet: [2]
connection 04-01/15:43:03  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 6; call: true; oldState: 1; newState: 0; oldOptionSet: 2; newOptionSet: 2
connection 04-01/15:43:03  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Processing deviceId:9; command ServiceActivatorEvent type=2; inetServId: 6; call: true; oldState: 1; newState: 0; oldOptionSet: 2; newOptionSet: 2
connection 04-01/15:43:03  INFO [sa-p-13-t-6] ServiceActivatorSet - Invoking connectionClose
connection 04-01/15:43:03  INFO [sa-p-13-t-6] SmartEdgeServiceActivator - Connection close
connection 04-01/15:43:03  INFO [sa-p-13-t-6] SmartEdgeServiceActivator - Connection close impl
connection 04-01/15:43:03  INFO [sa-p-13-t-6] SmartEdgeServiceActivator - Send PoD:
Packet type: Disconnect-Request
Identifier: 1
Authenticator: {35 1E C5 5D F8 6E F6 8C 77 B8 77 90 E7 8E 72 59}
Attributes:
  Acct-Session-Id=0100FFFF78000066-533A43C2

connection 04-01/15:43:03  INFO [sa-p-13-t-6] RadiusClient - Sending to /192.168.244.77:1700
Packet type: Disconnect-Request
Identifier: 1
Authenticator: {35 1E C5 5D F8 6E F6 8C 77 B8 77 90 E7 8E 72 59}
Attributes:
  Acct-Session-Id=0100FFFF78000066-533A43C2

connection 04-01/15:43:03  INFO [sa-p-13-t-6] DatagramChannelListener - ru.bitel.bgbilling.kernel.network.radius.RadiusClient$RadiusDatagramChannelListener socket init ok.
connection 04-01/15:43:03  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 04-01/15:43:03  INFO [rds-clnt-/192.168.244.77-1700] RadiusClient - Recieved from /192.168.244.77:1700
Packet type: Disconnect-ACK
Identifier: 1
Authenticator: {26 4E E7 1F 57 F7 27 D9 A7 04 C7 21 CD 99 51 87}
Attributes:
  Error-Cause=200
  Event-Timestamp=1396327383

connection 04-01/15:43:04 DEBUG [sa-p-13-t-6] AcknowledgeConsumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; type: 2; deviceId: 9; connectionId: 204; timestamp: 1396327384739
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Do task deviceId: 9; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; type: 2; deviceId: 9; connectionId: 204; timestamp: 1396327384739
connection 04-01/15:43:04  INFO [sa-p-13-t-6] InetApplication - TariffOptionMap: {}
connection 04-01/15:43:04  INFO [sa-p-13-t-6] InetApplication - OptionSet: [2]
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=5; inetServId: 6; call: true; oldState: 0; newState: 0; oldOptionSet: 2; newOptionSet: 2
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Processing deviceId:9; command ServiceActivatorEvent type=5; inetServId: 6; call: true; oldState: 0; newState: 0; oldOptionSet: 2; newOptionSet: 2
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorSet - Invoking onAccountingStop
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Process event type[5] result=true
mq 04-01/15:43:04 DEBUG [event-proc-p-2-t-1] Consumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; type: 2; deviceId: 9; connectionId: 204; timestamp: 1396327384739
mq 04-01/15:43:04  INFO [event-proc-p-2-t-1] InetConnectionManager - Remove connection: InetConnection [id=204-203, iface=9:553648468, sessId=0100FFFF78000066-533A43C2-RSE-SVC-EXT-SLAV-L3-F3A84ED7, start=01.04.2014 15:42:42, uname=RSE-SVC-EXT-SLAV-L3, addr=[IpAddress:null]]
mq 04-01/15:43:04 DEBUG [event-proc-p-2-t-1] InetAbstractDhcpProcessor - Skip service connection
mq 04-01/15:43:04  INFO [event-proc-p-2-t-1] InetDhcpHelperProcessor - Remove connection remove 9:12:1:
connection 04-01/15:43:04 DEBUG [sa-p-13-t-6] AcknowledgeConsumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; type: 2; deviceId: 9; connectionId: 203; timestamp: 1396327384895
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Do task deviceId: 9; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; type: 2; deviceId: 9; connectionId: 203; timestamp: 1396327384895
connection 04-01/15:43:04  INFO [sa-p-13-t-6] InetApplication - TariffOptionMap: {}
connection 04-01/15:43:04  INFO [sa-p-13-t-6] InetApplication - OptionSet: [2]
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=5; inetServId: 6; call: true; oldState: 1; newState: 1; oldOptionSet: 2; newOptionSet: 2
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Processing deviceId:9; command ServiceActivatorEvent type=5; inetServId: 6; call: true; oldState: 1; newState: 1; oldOptionSet: 2; newOptionSet: 2
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorSet - Invoking onAccountingStop
connection 04-01/15:43:04  INFO [sa-p-13-t-6] ServiceActivatorDeviceWorker - Process event type[5] result=true
mq 04-01/15:43:05 DEBUG [event-proc-p-2-t-1] Consumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent] moduleId: 11; pluginId: no; cid: 6793; scid: -1; userId: 0; type: 2; deviceId: 9; connectionId: 203; timestamp: 1396327384895
mq 04-01/15:43:05  INFO [event-proc-p-2-t-1] InetConnectionManager - Remove connection: InetConnection [id=203-0, iface=9:553648468, sessId=0100FFFF78000066-533A43C2, start=01.04.2014 15:42:42, uname=0006c8be19a900b0:000403210001, addr=10.248.192.1]
mq 04-01/15:43:05  INFO [event-proc-p-2-t-1] InetDhcpHelperProcessor - Remove connection remove 9:12:1:000F1FAB34B2
connection 04-01/15:43:09 DEBUG [sa-p-13-t-6] EventWorker - Waiting 5000 millis for last future results will done...
connection 04-01/15:43:09  INFO [sa-p-13-t-6] EventWorker - Future is done
connection 04-01/15:43:09  INFO [sa-p-13-t-6] ServiceActivatorSet - Disconnecting from device
radius 04-01/15:43:13  INFO [rdsLstnr-p-8-t-3] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 102
Authenticator: {18 D0 AE A1 06 94 9B 75 59 4D DE 57 D7 D5 8E AA}
Attributes:
  User-Name=00:25:b3:57:8a:1f
  NAS-Port-Id=2/1 vlan-id 340 clips 131175
  NAS-Identifier=Redback-IPOE-SLAV-L3
  User-Password=Redback
  NAS-IP-Address=192.168.244.77
  NAS-Port=553648468
  Service-Type=5
  NAS-Port-Type=5
  Called-Station-Id=10.248.192.254
  Platform-Type=4
  UNKNOWN[2352-201]={01 0A F8 C0 FE}
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 A9 00 B0}
  DHCP-Option={3D 3D 07 01 00 25 B3 57 8A 1F}
  DHCP-Option={0C 0C 06 48 50 2D 6B 69 72}
  Agent-Circuit-Id={00 04 03 21 00 01}
  OS-Version=11.1.2.9
  Mac-Addr=00-25-b3-57-8a-1f
  DHCP-Vendor-Class-Id=MSFT 5.0
  NAS-Real-Port=553648468
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 A9 00 B0}
  UNKNOWN[3561--1]={01 08 00 04 03 21 00 01}


radius 04-01/15:43:13  INFO [rdsLstnr-p-8-t-3] InetRadiusProcessor - REQUEST_AFTER_PREPROCESS:
Packet type: Access-Request
Identifier: 102
Authenticator: {18 D0 AE A1 06 94 9B 75 59 4D DE 57 D7 D5 8E AA}
Attributes:
  User-Name=0006c8be19a900b0:000403210001
  NAS-Port-Id=2/1 vlan-id 340 clips 131175
  NAS-Identifier=Redback-IPOE-SLAV-L3
  User-Password=Redback
  NAS-IP-Address=192.168.244.77
  NAS-Port=553648468
  Service-Type=5
  Calling-Station-Id=0025b3578a1f
  NAS-Port-Type=5
  Called-Station-Id=10.248.192.254
  Platform-Type=4
  UNKNOWN[2352-201]={01 0A F8 C0 FE}
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 A9 00 B0}
  DHCP-Option={3D 3D 07 01 00 25 B3 57 8A 1F}
  DHCP-Option={0C 0C 06 48 50 2D 6B 69 72}
  Agent-Circuit-Id={00 04 03 21 00 01}
  OS-Version=11.1.2.9
  Mac-Addr=00-25-b3-57-8a-1f
  DHCP-Vendor-Class-Id=MSFT 5.0
  NAS-Real-Port=553648468
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 A9 00 B0}
  UNKNOWN[3561--1]={01 08 00 04 03 21 00 01}
Common options: {agentRemoteId={c8be19a900b0}, agentCircuitId={000403210001}}
radius 04-01/15:43:13 DEBUG [rdsLstnr-p-8-t-3] RadiusProcessor - Create new radius session.
radius 04-01/15:43:13 DEBUG [rdsLstnr-p-8-t-3] InetNas - agentRemoteId=java.nio.DirectByteBufferR[pos=0 lim=6 cap=6]
radius 04-01/15:43:13  INFO [rdsLstnr-p-8-t-3] InetNas - Found agentDevice:12
radius 04-01/15:43:13 DEBUG [rdsLstnr-p-8-t-3] InetNas - findServ agentDeviceRuntime=ru.bitel.bgbilling.modules.inet.runtime.device.InetDeviceRuntime@73cb4cae
radius 04-01/15:43:13  INFO [rdsLstnr-p-8-t-3] InetNas - Search serv on deviceId=12; interfaceId=1
radius 04-01/15:43:13 DEBUG [rdsLstnr-p-8-t-3] InetRadiusProcessor - Password verification disabled.
radius 04-01/15:43:13  INFO [rdsLstnr-p-8-t-3] InetRadiusProcessor - [username=0006c8be19a900b0:000403210001] Authenticated as inetServId:6
radius 04-01/15:43:21 DEBUG [rdsLstnr-p-8-t-3] ProcessorRequest - Sending to /192.168.244.77:1812
radius 04-01/15:43:21  INFO [rdsLstnr-p-8-t-3] InetRadiusListenerWorker - RESPONSE:
Packet type: Access-Reject
Identifier: 102
Authenticator: {71 A1 92 51 39 25 B8 48 4F 31 1A 17 9A D7 A3 36}
Attributes:

Process time auth: 8008

radius 04-01/15:43:21 ERROR [rdsLstnr-p-8-t-3] RadiusListenerWorker - Lock wait timeout for ContractRuntime[6793]@1632886976
java.lang.RuntimeException: Lock wait timeout for ContractRuntime[6793]@1632886976
   at ru.bitel.common.util.CheckReentrantLock.tryLockEx(CheckReentrantLock.java:88)
   at ru.bitel.bgbilling.kernel.contract.runtime.ContractRuntime.tryLockEx(ContractRuntime.java:173)
   at ru.bitel.bgbilling.modules.inet.runtime.InetServRuntime.tryLockEx(InetServRuntime.java:572)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authenticationImpl(InetRadiusProcessor.java:608)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authentication(InetRadiusProcessor.java:469)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authentication(InetRadiusProcessor.java:1)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:438)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.accessRequestImpl(InetRadiusProcessor.java:385)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.accessRequestImpl(InetRadiusProcessor.java:1)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:423)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:59)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:1)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:228)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:147)
   at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
   at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
   at java.lang.Thread.run(Thread.java:662)
   at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
Caused by: java.lang.RuntimeException: OwnerThread: Thread[rdsLstnr-p-8-t-2,5,main]
   at sun.misc.Unsafe.park(Native Method)
   at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1011)
   at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1303)
   at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:227)
   at java.util.concurrent.FutureTask.get(FutureTask.java:91)
   at ru.bitel.common.concurrent.ConcurrentUtils.awaitFutures(ConcurrentUtils.java:38)
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.forceConnectionStop(InetConnectionManager.java:1129)
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.closeDuplicateSession(InetConnectionManager.java:1079)
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.checkDuplicateSession(InetConnectionManager.java:966)
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.checkSessionCountLimit(InetConnectionManager.java:799)
   at ru.bitel.bgbilling.modules.inet.access.Access.checkSessionCountLimitImpl(Access.java:385)
   at ru.bitel.bgbilling.modules.inet.runtime.InetApplication.checkSessionCountLimit(InetApplication.java:1099)
   at ru.bitel.bgbilling.modules.inet.runtime.InetApplication.authorizationOld(InetApplication.java:710)
   at ru.bitel.bgbilling.modules.inet.runtime.InetApplication.authorization(InetApplication.java:732)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authorization(InetRadiusProcessor.java:831)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authenticationImpl(InetRadiusProcessor.java:611)
   ... 17 more
radius 04-01/15:43:23 ERROR [rdsLstnr-p-8-t-2] InetRadiusProcessor - Timeout exceed!
ru.bitel.bgbilling.common.BGException: Timeout exceed!
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.forceConnectionStop(InetConnectionManager.java:1141)
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.closeDuplicateSession(InetConnectionManager.java:1079)
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.checkDuplicateSession(InetConnectionManager.java:966)
   at ru.bitel.bgbilling.modules.inet.access.InetConnectionManager.checkSessionCountLimit(InetConnectionManager.java:799)
   at ru.bitel.bgbilling.modules.inet.access.Access.checkSessionCountLimitImpl(Access.java:385)
   at ru.bitel.bgbilling.modules.inet.runtime.InetApplication.checkSessionCountLimit(InetApplication.java:1099)
   at ru.bitel.bgbilling.modules.inet.runtime.InetApplication.authorizationOld(InetApplication.java:710)
   at ru.bitel.bgbilling.modules.inet.runtime.InetApplication.authorization(InetApplication.java:732)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authorization(InetRadiusProcessor.java:831)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authenticationImpl(InetRadiusProcessor.java:611)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authentication(InetRadiusProcessor.java:469)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authentication(InetRadiusProcessor.java:1)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:438)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.accessRequestImpl(InetRadiusProcessor.java:385)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.accessRequestImpl(InetRadiusProcessor.java:1)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:423)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:59)
   at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:1)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:228)
   at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:147)
   at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
   at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
   at java.lang.Thread.run(Thread.java:662)
   at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
radius 04-01/15:43:23  INFO [rdsLstnr-p-8-t-2] InetRadiusProcessor - Return code=100
radius 04-01/15:43:23  INFO [rdsLstnr-p-8-t-2] InetRadiusProcessor - RESPONSE_BEFORE_POSTPROCESS:
Packet type: Access-Reject
Identifier: 102
Authenticator: {}
Attributes:
  Reply-Message=100

Process time auth: 20243

radius 04-01/15:43:23 DEBUG [rdsLstnr-p-8-t-2] ProcessorRequest - Sending to /192.168.244.77:1812
radius 04-01/15:43:23  INFO [rdsLstnr-p-8-t-2] InetRadiusListenerWorker - RESPONSE:
Packet type: Access-Reject
Identifier: 102
Authenticator: {0A E3 07 52 96 7F 63 7B A5 86 56 C5 A1 B0 16 2F}
Attributes:
  Reply-Message=100

Process time auth: 20281

radius 04-01/15:43:28  INFO [rdsLstnr-p-8-t-4] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 103
Authenticator: {7E 68 E8 82 BF BE 2B 30 CC ED E2 4E 76 F0 45 9C}
Attributes:
  User-Name=00:25:b3:57:8a:1f
  NAS-Port-Id=2/1 vlan-id 340 clips 131176
  NAS-Identifier=Redback-IPOE-SLAV-L3
  User-Password=Redback
  NAS-IP-Address=192.168.244.77
  NAS-Port=553648468
  Service-Type=5
  NAS-Port-Type=5
  Called-Station-Id=10.248.192.254
  Platform-Type=4
  UNKNOWN[2352-201]={01 0A F8 C0 FE}
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 A9 00 B0}
  DHCP-Option={3D 3D 07 01 00 25 B3 57 8A 1F}
  DHCP-Option={0C 0C 06 48 50 2D 6B 69 72}
  Agent-Circuit-Id={00 04 03 21 00 01}
  OS-Version=11.1.2.9
  Mac-Addr=00-25-b3-57-8a-1f
  DHCP-Vendor-Class-Id=MSFT 5.0
  NAS-Real-Port=553648468
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 A9 00 B0}
  UNKNOWN[3561--1]={01 08 00 04 03 21 00 01}


radius 04-01/15:43:28  INFO [rdsLstnr-p-8-t-4] InetRadiusProcessor - REQUEST_AFTER_PREPROCESS:
Packet type: Access-Request
Identifier: 103
Authenticator: {7E 68 E8 82 BF BE 2B 30 CC ED E2 4E 76 F0 45 9C}
Attributes:
  User-Name=0006c8be19a900b0:000403210001
  NAS-Port-Id=2/1 vlan-id 340 clips 131176
  NAS-Identifier=Redback-IPOE-SLAV-L3
  User-Password=Redback
  NAS-IP-Address=192.168.244.77
  NAS-Port=553648468
  Service-Type=5
  Calling-Station-Id=0025b3578a1f
  NAS-Port-Type=5
  Called-Station-Id=10.248.192.254
  Platform-Type=4
  UNKNOWN[2352-201]={01 0A F8 C0 FE}
  Medium-Type=11
  Agent-Remote-Id={00 06 C8 BE 19 A9 00 B0}
  DHCP-Option={3D 3D 07 01 00 25 B3 57 8A 1F}
  DHCP-Option={0C 0C 06 48 50 2D 6B 69 72}
  Agent-Circuit-Id={00 04 03 21 00 01}
  OS-Version=11.1.2.9
  Mac-Addr=00-25-b3-57-8a-1f
  DHCP-Vendor-Class-Id=MSFT 5.0
  NAS-Real-Port=553648468
  UNKNOWN[3561--1]={02 0A 00 06 C8 BE 19 A9 00 B0}
  UNKNOWN[3561--1]={01 08 00 04 03 21 00 01}
Common options: {agentRemoteId={c8be19a900b0}, agentCircuitId={000403210001}}
radius 04-01/15:43:28 DEBUG [rdsLstnr-p-8-t-4] RadiusProcessor - Create new radius session.