rad_recv: Accounting-Request packet from host 196.43.1.87 port 1820, id=1, length=261 Acct-Session-Id = "3/0/0/5.159_00A0493F" Framed-Protocol = PPP Framed-IP-Address = 41.144.110.38 User-Name = "abacus@msp.co.za" X-Ascend-Connect-Progress = LAN-Session-Up X-Ascend-PreSession-Time = 3 X-Ascend-Xmit-Rate = 4096000 X-Ascend-Data-Rate = 4096000 Acct-Session-Time = 3404 Acct-Input-Octets = 970 Acct-Output-Octets = 994 X-Ascend-Pre-Input-Octets = 86 X-Ascend-Pre-Output-Octets = 91 Acct-Input-Packets = 62 Acct-Output-Packets = 62 X-Ascend-Pre-Input-Packets = 5 X-Ascend-Pre-Output-Packets = 6 Acct-Authentic = RADIUS Acct-Status-Type = Interim-Update NAS-Port-Type = Virtual NAS-Port = 805634207 NAS-Port-Id = "3/0/0/5.159" Connect-Info = "AutoShapedVC" Calling-Station-Id = "0182932392" Class = "NL1" Service-Type = Framed-User NAS-IP-Address = 196.43.27.100 X-Ascend-Session-Svr-Key = "01FB51D4" Acct-Delay-Time = 5 Telkom-Access-Type = "DSL" Proxy-State = 0x3436 +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 805634207,Client-IP-Address = 196.43.1.87,NAS-IP-Address = 196.43.27.100,Acct-Session-Id = "3/0/0/5.159_00A0493F",User-Name = "abacus@msp.co.za"' [acct_unique] Acct-Unique-Session-ID = "bf140131ce2e1d1f". ++[acct_unique] returns ok [suffix] Looking up realm "msp.co.za" for User-Name = "abacus@msp.co.za" [suffix] Found realm "msp.co.za" [suffix] Adding Stripped-User-Name = "abacus" [suffix] Adding Realm = "msp.co.za" [suffix] Proxying request from user abacus to realm msp.co.za [suffix] Preparing to proxy accounting request to realm "msp.co.za" ++[suffix] returns updated ++[files] returns noop +- entering group accounting {...} [radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp [radutmp] expand: %{User-Name} -> abacus@msp.co.za ++[radutmp] returns ok [sql] expand: %{User-Name} -> abacus@msp.co.za [sql] sql_set_user escaped user --> 'abacus@msp.co.za' [sql] expand: %{Acct-Input-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Input-Octets} -> 970 [sql] expand: %{Acct-Output-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Output-Octets} -> 994 [sql] expand: UPDATE radacct SET framedipaddress = '%{Framed-IP-Address}', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}' -> UPDATE radacct SET framedipaddress = '41.144.110.38', acctsessiontime = '3404', acctinputoctets = '0' << 32 | '970', acctoutputoctets = '0' << 32 | '994' WHERE acctsessionid = '3/0/0/5.159_00A0493F' AND username = 'abacus@msp.co.za rlm_sql (sql): xlat failed. rlm_sql (sql): Reserving sql socket id: 5 rlm_sql_mysql: query: UPDATE radacct SET framedipaddress = '41.144.110.38', acctsessiontime = '3404', acctinputoctets = '0' << 32 | '970', acctoutputoctets = '0' << 32 | '994' WHERE acctsessionid = '3/0/0/5.159_00A0493F' AND username = 'abacus@msp.co.za' AND nasipaddress = '196.43.27.100' rlm_sql (sql): Released sql socket id: 5 ++[sql] returns ok [sql_log] Processing sql_log_accounting [sql_log] expand: %{User-Name} -> abacus@msp.co.za [sql_log] expand: %{%{User-Name}:-DEFAULT} -> abacus@msp.co.za [sql_log] sql_set_user escaped user --> 'abacus@msp.co.za' [sql_log] expand: %{Acct-Input-Gigawords} -> [sql_log] ... expanding second conditional [sql_log] expand: %{Acct-Input-Octets} -> 970 [sql_log] expand: %{Acct-Output-Gigawords} -> [sql_log] ... expanding second conditional [sql_log] expand: %{Acct-Output-Octets} -> 994 [sql_log] expand: UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', AcctOutputOctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND Username = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'; -> UPDATE radacct SET FramedIPAddress = '41.144.110.38', AcctSessionTime = '3404', AcctInputOctets = '0' << 32 | '970', AcctOutputOctets = '0' << 32 | '994' WHERE AcctSessionId = '3/0/0/5.159_00A0493F' AND Username = 'abacus@msp [sql_log] expand: /var/log/radius/sql_log -> /var/log/radius/sql_log ++[sql_log] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> abacus@msp.co.za attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated WARNING: Empty section. Using default return values. Sending Accounting-Request of id 46 to 196.25.102.32 port 1646 Acct-Session-Id = "3/0/0/5.159_00A0493F" Framed-Protocol = PPP Framed-IP-Address = 41.144.110.38 User-Name = "abacus" X-Ascend-Connect-Progress = LAN-Session-Up X-Ascend-PreSession-Time = 3 X-Ascend-Xmit-Rate = 4096000 X-Ascend-Data-Rate = 4096000 Acct-Session-Time = 3404 Acct-Input-Octets = 970 Acct-Output-Octets = 994 X-Ascend-Pre-Input-Octets = 86 X-Ascend-Pre-Output-Octets = 91 Acct-Input-Packets = 62 Acct-Output-Packets = 62 X-Ascend-Pre-Input-Packets = 5 X-Ascend-Pre-Output-Packets = 6 Acct-Authentic = RADIUS Acct-Status-Type = Interim-Update NAS-Port-Type = Virtual NAS-Port = 805634207 NAS-Port-Id = "3/0/0/5.159" Connect-Info = "AutoShapedVC" Calling-Station-Id = "0182932392" Class = "NL1" Service-Type = Framed-User NAS-IP-Address = 196.43.27.100 X-Ascend-Session-Svr-Key = "01FB51D4" Acct-Delay-Time = 5 Telkom-Access-Type = "DSL" Proxy-State = 0x3436 Proxy-State = 0x31 Proxying request 490 to home server 196.25.102.32 port 1646 Sending Accounting-Request of id 46 to 196.25.102.32 port 1646 Acct-Session-Id = "3/0/0/5.159_00A0493F" Framed-Protocol = PPP Framed-IP-Address = 41.144.110.38 User-Name = "abacus" X-Ascend-Connect-Progress = LAN-Session-Up X-Ascend-PreSession-Time = 3 X-Ascend-Xmit-Rate = 4096000 X-Ascend-Data-Rate = 4096000 Acct-Session-Time = 3404 Acct-Input-Octets = 970 Acct-Output-Octets = 994 X-Ascend-Pre-Input-Octets = 86 X-Ascend-Pre-Output-Octets = 91 Acct-Input-Packets = 62 Acct-Output-Packets = 62 X-Ascend-Pre-Input-Packets = 5 X-Ascend-Pre-Output-Packets = 6 Acct-Authentic = RADIUS Acct-Status-Type = Interim-Update NAS-Port-Type = Virtual NAS-Port = 805634207 NAS-Port-Id = "3/0/0/5.159" Connect-Info = "AutoShapedVC" Calling-Station-Id = "0182932392" Class = "NL1" Service-Type = Framed-User NAS-IP-Address = 196.43.27.100 X-Ascend-Session-Svr-Key = "01FB51D4" Acct-Delay-Time = 5 Telkom-Access-Type = "DSL" Proxy-State = 0x3436 Proxy-State = 0x31 Going to the next request Waking up in 0.9 seconds. rad_recv: Accounting-Response packet from host 196.25.102.32 port 1646, id=46, length=27 Proxy-State = 0x3436 Proxy-State = 0x31 WARNING: Empty section. Using default return values. Sending Accounting-Response of id 1 to 196.43.1.87 port 1820 Proxy-State = 0x3436 Finished request 490. Cleaning up request 490 ID 1 with timestamp +58101 Going to the next request Ready to process requests. rad_recv: Accounting-Request packet from host 196.25.102.32 port 1647, id=214, length=255 Acct-Session-Id = "3/0/0/5.159_00A0493F" Framed-Protocol = PPP Framed-IP-Address = 41.144.110.38 User-Name = "abacus" X-Ascend-Connect-Progress = LAN-Session-Up X-Ascend-PreSession-Time = 3 X-Ascend-Xmit-Rate = 4096000 X-Ascend-Data-Rate = 4096000 Acct-Session-Time = 3404 Acct-Input-Octets = 970 Acct-Output-Octets = 994 X-Ascend-Pre-Input-Octets = 86 X-Ascend-Pre-Output-Octets = 91 Acct-Input-Packets = 62 Acct-Output-Packets = 62 X-Ascend-Pre-Input-Packets = 5 X-Ascend-Pre-Output-Packets = 6 Acct-Authentic = RADIUS Acct-Status-Type = Interim-Update NAS-Port-Type = Virtual NAS-Port = 805634207 NAS-Port-Id = "3/0/0/5.159" Connect-Info = "AutoShapedVC" Calling-Station-Id = "0182932392" Class = "NL1" Service-Type = Framed-User NAS-IP-Address = 196.43.27.100 X-Ascend-Session-Svr-Key = "01FB51D4" Acct-Delay-Time = 15 Telkom-Access-Type = "DSL" Proxy-State = 0x323437 Proxy-State = 0x30 +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 805634207,Client-IP-Address = 196.25.102.32,NAS-IP-Address = 196.43.27.100,Acct-Session-Id = "3/0/0/5.159_00A0493F",User-Name = "abacus"' [acct_unique] Acct-Unique-Session-ID = "ce8cb1eb64b4e4ce". ++[acct_unique] returns ok [suffix] No '@' in User-Name = "abacus", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop ++[files] returns noop +- entering group accounting {...} [radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp [radutmp] expand: %{User-Name} -> abacus ++[radutmp] returns ok [sql] expand: %{User-Name} -> abacus [sql] sql_set_user escaped user --> 'abacus' [sql] expand: %{Acct-Input-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Input-Octets} -> 970 [sql] expand: %{Acct-Output-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Output-Octets} -> 994 [sql] expand: UPDATE radacct SET framedipaddress = '%{Framed-IP-Address}', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}' -> UPDATE radacct SET framedipaddress = '41.144.110.38', acctsessiontime = '3404', acctinputoctets = '0' << 32 | '970', acctoutputoctets = '0' << 32 | '994' WHERE acctsessionid = '3/0/0/5.159_00A0493F' AND username = 'abacus' rlm_sql (sql): xlat failed. rlm_sql (sql): Reserving sql socket id: 4 rlm_sql_mysql: query: UPDATE radacct SET framedipaddress = '41.144.110.38', acctsessiontime = '3404', acctinputoctets = '0' << 32 | '970', acctoutputoctets = '0' << 32 | '994' WHERE acctsessionid = '3/0/0/5.159_00A0493F' AND username = 'abacus' AND nasipaddress = '196.43.27.100' [sql] expand: %{Acct-Session-Time} -> 3404 [sql] expand: %{Acct-Delay-Time} -> 15 [sql] expand: %{Acct-Input-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Input-Octets} -> 970 [sql] expand: %{Acct-Output-Gigawords} -> [sql] ... expanding second conditional [sql] expand: %{Acct-Output-Octets} -> 994 [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctsessiontime, acctauthentic, connectinfo_start, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, servicetype, framedprotocol, framedipaddress, acctstartdelay, xascendsessionsvrkey, class) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Inp rlm_sql (sql): xlat failed. rlm_sql_mysql: query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctsessiontime, acctauthentic, connectinfo_start, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, servicetype, framedprotocol, framedipaddress, acctstartdelay, xascendsessionsvrkey, class) VALUES ('3/0/0/5.159_00A0493F', 'ce8cb1eb64b4e4ce', 'abacus', '', '196.43.27.100', '805634207', 'Virtual', DATE_SUB('2011-04-05 09:07:25', INTERVAL (3404 + 15) SECOND), '3404', 'RADIUS', '', '0' << 32 | '970', '0' << 32 | '994', '', '0182932392', 'Framed-User', 'PPP', '41.144.110.38', '0', '01FB51D4', 'NL1') rlm_sql (sql): Released sql socket id: 4 ++[sql] returns ok [sql_log] Processing sql_log_accounting [sql_log] expand: %{User-Name} -> abacus [sql_log] expand: %{%{User-Name}:-DEFAULT} -> abacus [sql_log] sql_set_user escaped user --> 'abacus' [sql_log] expand: %{Acct-Input-Gigawords} -> [sql_log] ... expanding second conditional [sql_log] expand: %{Acct-Input-Octets} -> 970 [sql_log] expand: %{Acct-Output-Gigawords} -> [sql_log] ... expanding second conditional [sql_log] expand: %{Acct-Output-Octets} -> 994 [sql_log] expand: UPDATE radacct SET FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', AcctOutputOctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE AcctSessionId = '%{Acct-Session-Id}' AND Username = '%{SQL-User-Name}' AND NASIPAddress = '%{NAS-IP-Address}'; -> UPDATE radacct SET FramedIPAddress = '41.144.110.38', AcctSessionTime = '3404', AcctInputOctets = '0' << 32 | '970', AcctOutputOctets = '0' << 32 | '994' WHERE AcctSessionId = '3/0/0/5.159_00A0493F' AND Username = 'abacus' [sql_log] expand: /var/log/radius/sql_log -> /var/log/radius/sql_log ++[sql_log] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> abacus attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated Sending Accounting-Response of id 214 to 196.25.102.32 port 1647 Proxy-State = 0x323437 Proxy-State = 0x30 Finished request 491. Cleaning up request 491 ID 214 with timestamp +58114 Going to the next request Ready to process requests.