По истечении lease-time связь теряется на несколько сек и начинается новая сессия.
Код:
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)