BiTel

sa.radius.connection.withoutBreak=0

dhcp.disable.mode=1

sa.radius.connection.withoutBreak=1
radius.serviceName.disable=L4REDIRECT,OPENGARDEN
sa.radius.service.disable=L4REDIRECT,OPENGARDEN

radius.disable.accessCodes=
radius.disable.attributes=

radius.disable.accessCodes=
radius.disable.attributes=

mq 05-23/16:44:04  INFO [event-proc-p-2-t-1] InetConnectionManager - Update connection: InetConnection [id=13916-13915, iface=2:584503288, sessId=0/0/2/1001_22D6D004, start=23.05.2014 12:24:24, uname=ISG-10MBPS, addr=[IpAddress:null]]
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 1
xid: -1537920000, secs: 0, flags: 0
Client IP: 109.XXX.49.122
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 109.XXX.49.254
Client MAC: {001560BBCB17}
  Host name{12}={hp-notebook}
  Parameter request list{55}={1, 28, 2, 3, 15, 6, 12, 44, 47}
  Agent information{82}=
    sub{1}={000404B10000}
    sub{2}={0006000B46CA4F00}

dhcp 05-23/16:44:06 DEBUG [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - OP_BOOT_REQUEST
dhcp 05-23/16:44:06 DEBUG [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - Found device by giaddr id=13
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - REQUEST_AFTER_PREPROCESS:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 1
xid: -1537920000, secs: 0, flags: 0
Client IP: 109.XXX.49.122
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 109.XXX.49.254
Client MAC: {001560BBCB17}
  Host name{12}={hp-notebook}
  Parameter request list{55}={1, 28, 2, 3, 15, 6, 12, 44, 47}
  Agent information{82}=
    sub{1}={000404B10000}
    sub{2}={0006000B46CA4F00}
Common options: {agentRemoteId=[B@1a684bf2}
dhcp 05-23/16:44:06 DEBUG [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - Found subDevice by identifier id=16
dhcp 05-23/16:44:06 DEBUG [dhcpLstnr-p-9-t-6] InetDhcpProcessor - DHCP_REQUEST
dhcp 05-23/16:44:06 DEBUG [dhcpLstnr-p-9-t-6] InetDhcpProcessor - request.giaddr= 109.XXX.49.254, clientAddress=/109.XXX.49.254:67
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetDhcpDevice - Search serv on deviceId: 16; 1; interfaceId: 0
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetDhcpProcessor - InetServ found: ContractId: 35; servId: 33
        L2 cisco catalyst mixed network): 000b46ca4f00 [10.112.1.2]: (0
        Options [] TariffModuleTreeSet [5:21.05.2014-?; ]
        Device state: 0; optionSet:3,4
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetApplication - inetServ[id=33] deviceState not active (accessCode=0).
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetDhcpProcessor - Stopping session with deviceState= 1 and accessCode=10
mq 05-23/16:44:06 DEBUG [dhcpLstnr-p-9-t-6] EventProcessor - Request, timeout 5000 : Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingManageEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: -1; type: 2; deviceId: 16; connectionId: 13947; timestamp: 1400845446795
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ServiceActivatorSet - Connecting to device
connection 05-23/16:44:06 DEBUG [sa-p-11-t-12] AcknowledgeConsumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; type: 2; deviceId: 16; connectionId: 13947; timestamp: 1400845446805
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ServiceActivatorDeviceWorker - Do task deviceId: 16; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; type: 2; deviceId: 16; connectionId: 13947; timestamp: 1400845446805
connection 05-23/16:44:06  INFO [sa-p-11-t-12] InetApplication - TariffOptionMap: {}
connection 05-23/16:44:06  INFO [sa-p-11-t-12] InetApplication - OptionSet: [3, 4]
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=5; inetServId: 33; call: true; oldState: 0; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ServiceActivatorDeviceWorker - Processing deviceId:16; command ServiceActivatorEvent type=5; inetServId: 33; call: true; oldState: 0; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ServiceActivatorSet - Invoking onAccountingStop
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ISGIPServiceActivator - onAccountingStop
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ISGServiceActivator - Connection close mode 3
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ISGServiceActivator - Connection close (logoff)
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ISGServiceActivator - Send logoff CoA:
Packet type: CoA-Request
Identifier: 1
Authenticator: {0B 87 78 F0 13 96 87 60 27 6B EC B9 A9 B7 1F 65}
Attributes:
  User-Name=109.XXX.49.122
  Framed-IP-Address=109.XXX.49.122
  Acct-Session-Id=0/0/2/1001_22DB8C77
  cisco-avpair=subscriber:command=account-logoff

connection 05-23/16:44:06  INFO [sa-p-11-t-12] RadiusClient - Sending to /10.XXX.198.31:1700
Packet type: CoA-Request
Identifier: 1
Authenticator: {0B 87 78 F0 13 96 87 60 27 6B EC B9 A9 B7 1F 65}
Attributes:
  User-Name=109.XXX.49.122
  Framed-IP-Address=109.XXX.49.122
  Acct-Session-Id=0/0/2/1001_22DB8C77
  cisco-avpair=subscriber:command=account-logoff

connection 05-23/16:44:06  INFO [sa-p-11-t-12] DatagramChannelListener - ru.bitel.bgbilling.kernel.network.radius.RadiusClient$RadiusDatagramChannelListener socket init ok.
connection 05-23/16:44:06  INFO [sa-p-11-t-12] ServiceActivatorDeviceWorker - Process event type[5] result=true
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetConnectionManager - Remove connection: InetConnection [id=13947-0, iface=16:0, sessId=a4553400, start=23.05.2014 16:37:46, uname=null, addr=109.XXX.49.122]
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetConnectionKeyMap - Remove connection remove 109.XXX.49.122
dhcp 05-23/16:44:06  INFO [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - RESPONSE:
Message type: BOOT_RESPONSE
Dhcp message type: DHCP NAK{6}
htype: 1, hlen: 6, hops: 1
xid: -1537920000, secs: 0, flags: 0
Client IP: 109.XXX.49.122
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 109.XXX.49.254
Client MAC: {001560BBCB17}
  Agent information{82}=
    sub{1}={000404B10000}
    sub{2}={0006000B46CA4F00}

dhcp 05-23/16:44:06 DEBUG [dhcpLstnr-p-9-t-6] ProcessorRequest - Sending to /109.XXX.49.254:67

   @Override
   public Object connectionModify( ServiceActivatorEvent e )
       throws Exception
   {
      logger.debug( "connectionModify" );
 
      if( e.getConnection().getDeviceId() != this.deviceId )
      {
         logger.debug( "Skip " + e.getConnection() + " " + this.deviceId );
         e.setConnectionStateModified( true );
         return null;
      }
 
      return super.connectionModify( e );
   }

   @Override
   public Object connectionModify( ServiceActivatorEvent e )
       throws Exception
   {
      logger.debug( "connectionModify" );
 
      if( e.getConnection().getDeviceId() != this.deviceId )
      {
         logger.debug( "Skip " + e.getConnection() + " " + this.deviceId );
         return null;
      }
 
      return super.connectionModify( e );
   }

@Override
   public Object connectionModify( ServiceActivatorEvent e )
       throws Exception
   {
      logger.debug( "connectionModify" );
 
      if( e.getConnection().getDeviceId() != this.deviceId )
      {
         logger.debug( "Skip " + e.getConnection() + " " + this.deviceId );
         return null;
      }
 
      return super.connectionModify( e );
   }

public Object connectionModify( ServiceActivatorEvent e )
    throws Exception
{
   logger.debug( "connectionModify" );

   if( e.getConnection().getDeviceId() != this.deviceId )
   {
      logger.debug( "Skip " + e.getConnection() + " " + this.deviceId );
      e.setConnectionStateModified( true ); // modification by Amir
      return null;
   }

   return super.connectionModify( e );
}

mq 05-26/15:14:17 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGBillingServer Event[ru.bitel.bgbilling.kernel.event.events.system.SystemLimitChangedEvent] moduleId: 0; pluginId: no; cid: 35; scid: -1; userId: 0; timestamp: 1401099257543
connection 05-26/15:14:17  INFO [sa-p-11-t-11] ServiceActivatorSet - Connecting to device
connection 05-26/15:14:17 DEBUG [sa-p-11-t-11] AcknowledgeConsumer - Caught BGBillingServer:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaStateModifyEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; deviceId: 16; inetServId: 33; connectionId: 0; state: 0; accessCode: 12; timestamp: 1401099257551
connection 05-26/15:14:17  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Do task deviceId: 16; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaStateModifyEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; deviceId: 16; inetServId: 33; connectionId: 0; state: 0; accessCode: 12; timestamp: 1401099257551
connection 05-26/15:14:17  INFO [sa-p-11-t-11] InetApplication - TariffOptionMap: {}
connection 05-26/15:14:17  INFO [sa-p-11-t-11] InetApplication - OptionSet: [3, 4]
connection 05-26/15:14:17  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 33; call: true; oldState: 1; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-26/15:14:17  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Processing deviceId:16; command ServiceActivatorEvent type=2; inetServId: 33; call: true; oldState: 1; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-26/15:14:17  INFO [sa-p-11-t-11] ServiceActivatorSet - Invoking serviceModify
connection 05-26/15:14:17  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 05-26/15:14:17  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Changing InetServ:33 state and/or options
mq 05-26/15:14:17 DEBUG [sa-p-11-t-11] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 2; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 16; inetServId: 33; state: 0; optionSet: ; timestamp: 1401099257580
mq 05-26/15:14:17 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGInetAccess Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 2; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 16; inetServId: 33; state: 0; optionSet: ; timestamp: 1401099257580
mq 05-26/15:14:17  INFO [event-proc-p-2-t-1] InetServRuntimeMap - Taked event: Event[ru.bitel.bgbilling.modules.inet.access.event.InetServDeviceStateAndOptionsModifiedEvent] moduleId: 2; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 16; inetServId: 33; state: 0; optionSet: ; timestamp: 1401099257580
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ServiceActivatorSet - Connecting to device
connection 05-26/15:14:19 DEBUG [sa-p-11-t-6] AcknowledgeConsumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaStateModifyEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; deviceId: 2; inetServId: 33; connectionId: 14207; state: 0; accessCode: 10; timestamp: 1401099259099
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ServiceActivatorDeviceWorker - Do task deviceId: 2; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaStateModifyEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; deviceId: 2; inetServId: 33; connectionId: 14207; state: 0; accessCode: 10; timestamp: 1401099259099
connection 05-26/15:14:19  INFO [sa-p-11-t-6] InetApplication - TariffOptionMap: {}
connection 05-26/15:14:19  INFO [sa-p-11-t-6] InetApplication - OptionSet: [3, 4]
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 33; call: true; oldState: 1; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ServiceActivatorDeviceWorker - Processing deviceId:2; command ServiceActivatorEvent type=2; inetServId: 33; call: true; oldState: 1; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ServiceActivatorSet - Invoking connectionModify
connection 05-26/15:14:19 DEBUG [sa-p-11-t-6] ISGIPServiceActivator - connectionModify
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ISGServiceActivator - Connection modify: oldState: 1; newState: 0; oldOptionSet: [3, 4]; newOptionSet: [3, 4]
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ISGServiceActivator - Send deactivate service CoA:
Packet type: CoA-Request
Identifier: 22
Authenticator: {41 9D BB 71 96 1D 3E 57 BD DD F5 15 87 C4 A4 F5}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=ISG-10MBPS
  cisco-avpair=subscriber:command=deactivate-service

connection 05-26/15:14:19  INFO [sa-p-11-t-6] RadiusClient - Sending to /10.100.198.31:1700
Packet type: CoA-Request
Identifier: 22
Authenticator: {41 9D BB 71 96 1D 3E 57 BD DD F5 15 87 C4 A4 F5}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=ISG-10MBPS
  cisco-avpair=subscriber:command=deactivate-service

connection 05-26/15:14:19  INFO [sa-p-11-t-6] ISGServiceActivator - Send deactivate service CoA:
Packet type: CoA-Request
Identifier: 23
Authenticator: {40 CD 14 41 34 BB 86 A5 6B A0 1A 79 9F D3 AC 91}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=ISG-LOCAL
  cisco-avpair=subscriber:command=deactivate-service

connection 05-26/15:14:19  INFO [sa-p-11-t-6] RadiusClient - Sending to /10.100.198.31:1700
Packet type: CoA-Request
Identifier: 23
Authenticator: {40 CD 14 41 34 BB 86 A5 6B A0 1A 79 9F D3 AC 91}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=ISG-LOCAL
  cisco-avpair=subscriber:command=deactivate-service

connection 05-26/15:14:19  INFO [sa-p-11-t-6] ISGServiceActivator - Send activate service CoA:
Packet type: CoA-Request
Identifier: 24
Authenticator: {96 2C 50 E7 E4 84 99 F1 E8 CD 4E 2E DF 69 DA 88}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=L4REDIRECT
  cisco-avpair=subscriber:command=activate-service

connection 05-26/15:14:19  INFO [sa-p-11-t-6] RadiusClient - Sending to /10.100.198.31:1700
Packet type: CoA-Request
Identifier: 24
Authenticator: {96 2C 50 E7 E4 84 99 F1 E8 CD 4E 2E DF 69 DA 88}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=L4REDIRECT
  cisco-avpair=subscriber:command=activate-service

connection 05-26/15:14:19 DEBUG [sa-p-11-t-11] AcknowledgeConsumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaStateModifyEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; deviceId: 16; inetServId: 33; connectionId: 14202; state: 0; accessCode: 10; timestamp: 1401099259109
connection 05-26/15:14:19  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Do task deviceId: 16; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaStateModifyEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; deviceId: 16; inetServId: 33; connectionId: 14202; state: 0; accessCode: 10; timestamp: 1401099259109
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ISGServiceActivator - Send activate service CoA:
Packet type: CoA-Request
Identifier: 25
Authenticator: {1A C8 28 E5 CB CF 53 78 8C 90 3C D0 5E 62 9C B3}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=OPENGARDEN
  cisco-avpair=subscriber:command=activate-service

connection 05-26/15:14:19  INFO [sa-p-11-t-6] RadiusClient - Sending to /10.100.198.31:1700
Packet type: CoA-Request
Identifier: 25
Authenticator: {1A C8 28 E5 CB CF 53 78 8C 90 3C D0 5E 62 9C B3}
Attributes:
  User-Name=109.XXX.49.104
  Framed-IP-Address=109.XXX.49.104
  Acct-Session-Id=0/0/2/1001_2325EA11
  cisco-avpair=subscriber:service-name=OPENGARDEN
  cisco-avpair=subscriber:command=activate-service

connection 05-26/15:14:19  INFO [sa-p-11-t-11] InetApplication - TariffOptionMap: {}
connection 05-26/15:14:19  INFO [sa-p-11-t-11] InetApplication - OptionSet: [3, 4]
connection 05-26/15:14:19  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=2; inetServId: 33; call: true; oldState: 1; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-26/15:14:19  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Processing deviceId:16; command ServiceActivatorEvent type=2; inetServId: 33; call: true; oldState: 1; newState: 0; oldOptionSet: 3,4; newOptionSet: 3,4
connection 05-26/15:14:19  INFO [sa-p-11-t-11] ServiceActivatorSet - Invoking connectionModify
connection 05-26/15:14:19 DEBUG [sa-p-11-t-11] ISGIPServiceActivator - connectionModify
connection 05-26/15:14:19 DEBUG [sa-p-11-t-11] ISGIPServiceActivator - Skip InetConnection [id=14202-0, iface=16:0, sessId=aa45454f, start=26.05.2014 15:07:41, uname=null, addr=109.XXX.49.104] 2
connection 05-26/15:14:19  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Process event type[2] result=true
connection 05-26/15:14:19  INFO [sa-p-11-t-11] ServiceActivatorDeviceWorker - Changing InetConnection:14202 state and/or options
connection 05-26/15:14:19  INFO [sa-p-11-t-6] ServiceActivatorDeviceWorker - Process event type[2] result=true
mq 05-26/15:14:19 DEBUG [sa-p-11-t-11] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.access.event.InetConnectionDeviceStateAndOptionsModifiedEvent] moduleId: 2; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 16; connectionId: 14202; optionSet: ; timestamp: 1401099259113
mq 05-26/15:14:19 DEBUG [event-proc-p-2-t-1] Consumer - Caught from BGInetAccess Event[ru.bitel.bgbilling.modules.inet.access.event.InetConnectionDeviceStateAndOptionsModifiedEvent] moduleId: 2; pluginId: no; cid: global; scid: -1; userId: -1; deviceId: 16; connectionId: 14202; optionSet: ; timestamp: 1401099259113
radius 05-26/15:14:20  INFO [hrlydtlggr-p-6-t-1] HourlyDataLoggerTracker - Checking data log files to close [hours=2]...
radius 05-26/15:14:20 DEBUG [hrlydtlggr-p-6-t-1] HourlyDataLogEntry - Last modified: 1401098853000 : -1
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Checking data log files to close [hours=2]...
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098360000 : 1401098360000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_12/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098326000 : 1401098326000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_9/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098392000 : 1401098392000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098360000 : 1401098360000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_10/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098367000 : 1401098367000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_11/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098326000 : 1401098326000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_4/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098510000 : 1401098510000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_12/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098476000 : 1401098476000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_9/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098518000 : 1401098518000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098444000 : 1401098444000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_10/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098517000 : 1401098517000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_11/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:21 DEBUG [hrlydtlggr-p-8-t-1] HourlyDataLogEntry - Last modified: 1401098476000 : 1401098476000
dhcp 05-26/15:14:21  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Remove dataLog file from writers map [/usr/local/BGInetAccess/data/dhcp/source_4/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_12/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 776
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_12/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_9/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 942
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_9/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 754
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_10/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 819
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_10/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_11/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 775
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_11/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_4/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 878
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_4/2014/2014-05/2014-05-26/log_2014-05-26-14.004.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_12/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 817
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_12/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_9/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 1107
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_9/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 863
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_10/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 1056
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_10/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_11/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 815
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_11/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl] was closed
dhcp 05-26/15:14:23  INFO [hrlydtlggr-p-8-t-1] HourlyDataLoggerTracker - Close dataLog file [/usr/local/BGInetAccess/data/dhcp/source_4/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl]
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 2
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Close ZLIBWritableChannel...
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] ZLIBWritableChannel - Deflating... 131088 1041
dhcp 05-26/15:14:23 DEBUG [hrlydtlggr-p-8-t-1] DataLog - DataLog file [data/dhcp/source_4/2014/2014-05/2014-05-26/log_2014-05-26-15.000.bgdl] was closed
connection 05-26/15:14:24 DEBUG [sa-p-11-t-6] EventWorker - Waiting 5000 millis for last future results will done...
connection 05-26/15:14:24  INFO [sa-p-11-t-11] ServiceActivatorSet - Disconnecting from device
connection 05-26/15:14:29  INFO [sa-p-11-t-6] EventWorker - Timeout waiting futures
connection 05-26/15:14:29 ERROR [sa-p-11-t-6] EventWorker - java.util.concurrent.TimeoutException
ru.bitel.bgbilling.common.BGException: java.util.concurrent.TimeoutException
        at ru.bitel.bgbilling.kernel.event.AsyncEventWorker.doTasks(AsyncEventWorker.java:92)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.runWorker(ServiceActivatorDeviceWorker.java:179)
        at ru.bitel.bgbilling.kernel.event.EventWorker.internalRunWorker(EventWorker.java:115)
        at ru.bitel.bgbilling.modules.inet.access.sa.ServiceActivatorDeviceWorker.runImpl(ServiceActivatorDeviceWorker.java:117)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
        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: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.util.concurrent.TimeoutException
        ... 15 more
connection 05-26/15:14:29  INFO [sa-p-11-t-6] ServiceActivatorSet - Disconnecting from device
connection 05-26/15:14:29  INFO [sa-p-11-t-6] ServiceActivatorDeviceWorker - Execution error - waiting 60000ms for next try.
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 1
xid: -1438300849, secs: 0, flags: 0
Client IP: 109.XXX.49.104
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 109.XXX.49.254
Client MAC: {001560BBCB17}
  Host name{12}={hp-notebook}
  Parameter request list{55}={1, 28, 2, 3, 15, 6, 12, 44, 47}
  Agent information{82}=
    sub{1}={000404B10000}
    sub{2}={0006000B46CA4F00}

dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - OP_BOOT_REQUEST
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - Found device by giaddr id=13
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - REQUEST_AFTER_PREPROCESS:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Request{3}
htype: 1, hlen: 6, hops: 1
xid: -1438300849, secs: 0, flags: 0
Client IP: 109.XXX.49.104
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 109.XXX.49.254
Client MAC: {001560BBCB17}
  Host name{12}={hp-notebook}
  Parameter request list{55}={1, 28, 2, 3, 15, 6, 12, 44, 47}
  Agent information{82}=
    sub{1}={000404B10000}
    sub{2}={0006000B46CA4F00}
Common options: {agentRemoteId=[B@214fdcf3}
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - Found subDevice by identifier id=16
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] InetDhcpProcessor - DHCP_REQUEST
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] InetDhcpProcessor - request.giaddr= 109.XXX.49.254, clientAddress=/109.XXX.49.254:67
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] InetDhcpDevice - Search serv on deviceId: 16; 1; interfaceId: 0
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] InetDhcpProcessor - InetServ found: ContractId: 35; servId: 33
        L2 cisco catalyst mixed network): 000b46ca4f00 [10.112.1.2]: (0
        Options [] TariffModuleTreeSet [9:21.05.2014-?; ]
        Device state: 0; optionSet:3,4
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] InetApplication - inetServ[id=33] deviceState not active (accessCode=0).
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] InetDhcpProcessor - Updating of existing connection: InetConnection [id=14202-0, iface=16:0, sessId=aa45454f, start=26.05.2014 15:07:41, uname=null, addr=109.XXX.49.104]
mq 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] EventProcessor - Publish: Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingManageEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: -1; type: 3; deviceId: 16; connectionId: 14202; timestamp: 1401099271045
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] InetAbstractDhcpProcessor - RESPONSE:
Message type: BOOT_RESPONSE
Dhcp message type: DHCP ACK{5}
htype: 1, hlen: 6, hops: 1
xid: -1438300849, secs: 0, flags: 0
Client IP: 109.XXX.49.104
Your IP: 109.XXX.49.104
Server IP: 0.0.0.0
Relay IP: 109.XXX.49.254
Client MAC: {001560BBCB17}
  Agent information{82}=
    sub{1}={000404B10000}
    sub{2}={0006000B46CA4F00}
  Router{3}=109.XXX.49.254
  Subnet mask{1}=255.255.255.0
  DNS{6}={6D7F0135}
  IP Address Lease Time{51}=300
  Server Identifier{54}={00000000}

dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] ProcessorRequest - Sending to /109.XXX.49.254:67
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] HourlyDataLogger - Create log file...
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] HourlyLogFileUtils - Next log file: /usr/local/BGInetAccess/data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-15.001.bgdl
dhcp 05-26/15:14:31  INFO [dhcpLstnr-p-9-t-6] HourlyDataLogEntry - Create dataLog file: /usr/local/BGInetAccess/data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-15.001.bgdl
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] BGDataLog - DataLog file [data/dhcp/source_16/2014/2014-05/2014-05-26/log_2014-05-26-15.001.bgdl] was opened
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] DataLog - Writing TLV finished(3)=[0]
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] DataLog - Writing TLV buffer(4)=[type=chunked, size=131072]
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] DataLog - Writing TLV compression(5)=[type=zlib, level=1, strategy=1]
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] DataLog - Writing TLV distributed(6)=[1]
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] DataLog - Writing TLV streaming(7)=[1]
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] BGDataLog - Header length=51
dhcp 05-26/15:14:31 DEBUG [dhcpLstnr-p-9-t-6] ZLIBWritableChannel - ZLIBWritableChannel bufferLength=131088
mq 05-26/15:14:31 DEBUG [event-proc-p-2-t-1] Consumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; type: 3; deviceId: 16; connectionId: 14202; timestamp: 1401099271055
access 05-26/15:14:36 DEBUG [access-p-5-t-1] SessionCountManager - Run SessionCountManager...
access 05-26/15:15:08 DEBUG [access-p-5-t-1] SessionCountManager - Run SessionCountManager...
radius 05-26/15:15:18 DEBUG [setup-sched-p-1-t-1] RadiusProcessor - After clean old rad sessions: 0
mq 05-26/15:15:23 DEBUG [event-proc-p-2-t-1] Consumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent] moduleId: 2; pluginId: no; cid: 35; scid: -1; userId: 0; type: 3; deviceId: 2; connectionId: 14207; timestamp: 1401099323805

connection 05-26/16:14:22  INFO [sa-p-11-t-5] ISGServiceActivator - Send activate service CoA:
Packet type: CoA-Request
Identifier: 45
Authenticator: {51 1D D4 4A 97 37 62 27 92 6A D2 51 43 AF F6 1B}
Attributes:
  User-Name=109.XXX.49.206
  Framed-IP-Address=109.XXX.49.206
  Acct-Session-Id=0/0/2/1001_2326A1F8
  cisco-avpair=subscriber:service-name=ISG-10MBPS
  cisco-avpair=subscriber:command=activate-service

connection 05-26/16:14:22  INFO [sa-p-11-t-5] RadiusClient - Sending to /10.100.198.31:1700
Packet type: CoA-Request
Identifier: 45
Authenticator: {51 1D D4 4A 97 37 62 27 92 6A D2 51 43 AF F6 1B}
Attributes:
  User-Name=109.XXX.49.206
  Framed-IP-Address=109.XXX.49.206
  Acct-Session-Id=0/0/2/1001_2326A1F8
  cisco-avpair=subscriber:service-name=ISG-10MBPS
  cisco-avpair=subscriber:command=activate-service

connection 05-26/16:14:22  INFO [sa-p-11-t-5] ISGServiceActivator - Send activate service CoA:
Packet type: CoA-Request
Identifier: 46
Authenticator: {84 80 12 1E F7 1C A4 1A 64 0B 9A E7 52 BF 96 46}
Attributes:
  User-Name=109.XXX.49.206
  Framed-IP-Address=109.XXX.49.206
  Acct-Session-Id=0/0/2/1001_2326A1F8
  cisco-avpair=subscriber:service-name=ISG-LOCAL
  cisco-avpair=subscriber:command=activate-service

connection 05-26/16:14:22  INFO [sa-p-11-t-5] RadiusClient - Sending to /10.100.198.31:1700
Packet type: CoA-Request
Identifier: 46
Authenticator: {84 80 12 1E F7 1C A4 1A 64 0B 9A E7 52 BF 96 46}
Attributes:
  User-Name=109.XXX.49.206
  Framed-IP-Address=109.XXX.49.206
  Acct-Session-Id=0/0/2/1001_2326A1F8
  cisco-avpair=subscriber:service-name=ISG-LOCAL
  cisco-avpair=subscriber:command=activate-service

Type: IP, UID: 1816, State: authen, Identity: 109.XXX.49.206
IPv4 Address: 109.XXX.49.206
Session Up-time: 00:23:53, Last Changed: 00:03:03
Switch-ID: 8337682

Policy information:
  Authentication status: authen
  Active services associated with session:
    name "OPENGARDEN"
    name "L4REDIRECT"
  Rules, actions and conditions executed:
    subscriber rule-map IPoE-ISG
      condition always event session-start
        10 authorize aaa list ipoe-isg-aaa identifier source-ip-address
    subscriber rule-map default-internal-rule
      condition always event service-start
        1 service-policy type service identifier service-name
    subscriber rule-map default-internal-rule
      condition always event service-start
        1 service-policy type service identifier service-name
    subscriber rule-map IPoE-ISG
      condition always event service-stop
        1 service-policy type service unapply identifier service-name
        10 log-session-state
    subscriber rule-map IPoE-ISG
      condition always event service-stop
        1 service-policy type service unapply identifier service-name
        10 log-session-state
    subscriber rule-map default-internal-rule
      condition always event service-start
        1 service-policy type service identifier service-name
    subscriber rule-map default-internal-rule
      condition always event service-start
        1 service-policy type service identifier service-name

Classifiers:
Class-id    Dir   Packets    Bytes                  Pri.  Definition
0           In    238        30363                  0    Match Any
1           Out   302        217183                 0    Match Any
61470       In    10         1894                   20   Match ACL traffic-for-redirect
61472       In    0          0                      40   Match ACL limited-upstream-domonet
61473       Out   8          801                    40   Match ACL limited-downstream-domonet
4294967294  In    0          0                      -    Drop
4294967295  Out   82         4048                   -    Drop

Features:

Idle Timeout:
Class-id   Dir  Timeout value   Idle-Time            Source
0          In   900             00:02:36             Peruser

Accounting:
Class-id   Dir  Packets    Bytes                 Source
0          In   278        35247                 Peruser
1          Out  254        219620                Peruser
61472      In   0          0                     OPENGARDEN
61473      Out  8          801                   OPENGARDEN

L4 Redirect:
Class-id   Rule cfg  Definition                               Source
61470      #1   SVC  to group NO-MONEY                        L4REDIRECT

Policing:
Class-id   Dir  Avg. Rate   Normal Burst  Excess Burst Source
61472      In   1024000     192000        384000       OPENGARDEN
61473      Out  1024000     192000        384000       OPENGARDEN

Configuration Sources:
Type  Active Time  AAA Service ID  Name
SVC   00:03:03     -               L4REDIRECT
SVC   00:03:03     2298484156      OPENGARDEN
USR   00:23:53     -               Peruser
INT   00:23:53     -               GigabitEthernet0/0/2.1001