radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 185
Authenticator: {48 CF 89 79 10 4F C2 E9 65 32 7D 40 ED 91 93 F6}
Attributes:
  User-Name=a12.200@CVLAN
  NAS-Port-Id=2/4 vlan-id 12:200
  NAS-Identifier=Redback-CVLAN
  User-Password=Redback
  NAS-IP-Address=10.189.2.1
  NAS-Port=604029128
  Service-Type=2
  NAS-Port-Type=1
  Platform-Type=4
  OS-Version=6.2.1.2

radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] AbstractRadiusProtocolHandler - State is enable (from attributes)
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetRadiusProcessor - REQUEST_AFTER_PREPROCESS:
Packet type: Access-Request
Identifier: 185
Authenticator: {48 CF 89 79 10 4F C2 E9 65 32 7D 40 ED 91 93 F6}
Attributes:
  User-Name=12.200
  NAS-Port-Id=2/4 vlan-id 12:200
  NAS-Identifier=Redback-CVLAN
  User-Password=Redback
  NAS-IP-Address=10.189.2.1
  NAS-Port=604029128
  Service-Type=2
  NAS-Port-Type=1
  Platform-Type=4
  OS-Version=6.2.1.2
Common options: {agentRemoteId=2D6964203132, vlanId=200, deviceState=1}
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] RadiusProcessor - Create new radius session.
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] InetNas - agentRemoteId=2D6964203132
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetNas - Found agentDevice:4
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetNas - Search serv on deviceId=4; vlanId=200
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetRadiusProcessor - [username=12.200] Authenticated as inetServId:332
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] InetRadiusProcessor - Identifier from request: null
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] InetRadiusProcessor - MAC-address from request:
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] InetAccountingPeriodList - Create:
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] InetAccountingPeriodList - AccountingPeriod: 6: 02.11.2012 00:00:00.0 - 30.11.2012 23:59:59.999
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetApplication - inetServ[id=332] balance ok: 3267.18 [-3000.00]
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] ContractTariffOptionList - Create:
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetApplication - TariffOptionMap: {}
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetRadiusProcessor - Return code=0
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] InetRadiusProcessor - RESPONSE_BEFORE_POSTPROCESS:
Packet type: Access-Accept
Identifier: 185
Authenticator: {}
Attributes:
  Acct-Interim-Interval=900
  Service-Type=2
  Framed-IP-Address=10.96.0.10
  DHCP-Max-Leases=2
  Context-Name=CVLAN
  Bind-Type=4
  IP-Interface-Name=CLIENTS

Process time auth: 27

radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] HourlyDataLogger - Create log file...
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] HourlyLogFileUtils - Next log file: /opt/BGInetAccess/data/radius/source_2/2012/2012-11/2012-11-27/log_2012-11-27-23.001.bgdl
radius 11-27/23:30:43  INFO [rdsLstnr-p-8-t-1] HourlyDataLogEntry - Create dataLog file: /opt/BGInetAccess/data/radius/source_2/2012/2012-11/2012-11-27/log_2012-11-27-23.001.bgdl
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] BGDataLog - DataLog file [data/radius/source_2/2012/2012-11/2012-11-27/log_2012-11-27-23.001.bgdl] was opened
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] DataLog - Writing TLV finished(3)=[0]
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] DataLog - Writing TLV buffer(4)=[type=chunked, size=524288]
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] DataLog - Writing TLV compression(5)=[type=zlib, level=1, strategy=1]
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] DataLog - Writing TLV distributed(6)=[1]
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] DataLog - Writing TLV streaming(7)=[1]
radius 11-27/23:30:43 DEBUG [rdsLstnr-p-8-t-1] BGDataLog - Header length=51
radius 11-27/23:30:44 DEBUG [rdsLstnr-p-8-t-1] ZLIBWritableChannel - ZLIBWritableChannel bufferLength=524304
radius 11-27/23:30:44 DEBUG [rdsLstnr-p-8-t-1] ProcessorRequest - Sending to /10.189.2.1:1812
radius 11-27/23:30:44  INFO [rdsLstnr-p-8-t-1] InetRadiusListenerWorker - RESPONSE:
Packet type: Access-Accept
Identifier: 185
Authenticator: {F1 C4 DF A2 C2 FC 11 BE 14 8A 7C 3E D5 A2 3D FF}
Attributes:
  Acct-Interim-Interval=900
  Service-Type=2
  DHCP-Max-Leases=2
  Context-Name=CVLAN
  Bind-Type=4
  IP-Interface-Name=CLIENTS

Process time auth: 100

connection 11-27/23:30:44  INFO [sa-p-12-t-9] ServiceActivatorSet - Connecting to device
connection 11-27/23:30:44 DEBUG [sa-p-12-t-9] AcknowledgeConsumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 3; pluginId: no; cid: 62; scid: -1; userId: 0; type: 1; deviceId: 2; connectionId: 1414; timestamp: 1354037444159
connection 11-27/23:30:44  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Do task deviceId: 2; Event[ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent] moduleId: 3; pluginId: no; cid: 62; scid: -1; userId: 0; type: 1; deviceId: 2; connectionId: 1414; timestamp: 1354037444159
connection 11-27/23:30:44  INFO [sa-p-12-t-9] InetApplication - TariffOptionMap: {}
connection 11-27/23:30:44  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Command result event: ServiceActivatorEvent type=4; inetServId: 332; call: true; oldState: 1; newState: 1; oldOptionSet: 11; newOptionSet: 11
connection 11-27/23:30:44  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Processing deviceId:2; command ServiceActivatorEvent type=4; inetServId: 332; call: true; oldState: 1; newState: 1; oldOptionSet: 11; newOptionSet: 11
connection 11-27/23:30:44  INFO [sa-p-12-t-9] ServiceActivatorSet - Invoking onAccountingStart
connection 11-27/23:30:44  INFO [sa-p-12-t-9] ServiceActivatorDeviceWorker - Process event type[4] result=true
mq 11-27/23:30:44 DEBUG [event-proc-p-2-t-1] Consumer - Caught BGInetAccounting:Event[ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent] moduleId: 3; pluginId: no; cid: 62; scid: -1; userId: 0; type: 1; deviceId: 2; connectionId: 1414; timestamp: 1354037444159
mq 11-27/23:30:44  INFO [event-proc-p-2-t-1] InetConnectionManager - Add connection: InetConnection [id=1414-0, iface=2:604029128, sessId=0103FFFF38000100-50B54EEC, start=27.11.2012 23:30:44, uname=12.200, addr=[IpAddress:null]]
dhcp 11-27/23:30:44 DEBUG [dhcpLstnr-p-10-t-1] InetDhcpDeviceMap - Found device by giaddr id=2
dhcp 11-27/23:30:44  INFO [dhcpLstnr-p-10-t-1] InetAbstractDhcpProcessor - REQUEST:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Discover{1}
htype: 1, hlen: 6, hops: 1
xid: -233062115, secs: 2, flags: -32768
Client IP: 0.0.0.0
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 10.96.0.1
Client MAC: {D4CA6D298D14}
  {61}={01D4CA6D298D14}
  Parameter request list{55}={1, 121, 3, 33, 6, 42}
  Host name{12}={MikroTik}
  Agent information{82}=
    sub{1}={322F3420766C616E2D69642031323A323030}
    sub{2}={6131322E3230304043564C414E}

dhcp 11-27/23:30:44  INFO [dhcpLstnr-p-10-t-1] InetAbstractDhcpProcessor - REQUEST_AFTER_PREPROCESS:
Message type: BOOT_REQUEST
Dhcp message type: DHCP Discover{1}
htype: 1, hlen: 6, hops: 1
xid: -233062115, secs: 2, flags: -32768
Client IP: 0.0.0.0
Your IP: 0.0.0.0
Server IP: 0.0.0.0
Relay IP: 10.96.0.1
Client MAC: {D4CA6D298D14}
  {61}={01D4CA6D298D14}
  Parameter request list{55}={1, 121, 3, 33, 6, 42}
  Host name{12}={MikroTik}
  Agent information{82}=
    sub{1}={2D6964203132}
    sub{2}={000000C8}

dhcp 11-27/23:30:44 DEBUG [dhcpLstnr-p-10-t-1] InetAbstractDhcpProcessor - OP_BOOT_REQUEST
dhcp 11-27/23:30:44 DEBUG [dhcpLstnr-p-10-t-1] InetDhcpProcessor - DHCP_DISCOVER
dhcp 11-27/23:30:44 DEBUG [dhcpLstnr-p-10-t-1] InetDhcpProcessor - request.giaddr= 10.96.0.1, clientAddress=/10.189.2.1:67
dhcp 11-27/23:30:44  INFO [dhcpLstnr-p-10-t-1] InetDhcpDevice - Search serv on deviceId: 2; [I@55f805f6; vlanId: 200
dhcp 11-27/23:30:44  INFO [dhcpLstnr-p-10-t-1] InetDhcpProcessor - InetServ not found.