Hi everyone, we are having an issue on our FreeRadius setup where our redundant servers will maybe once, twice a day create duplicate accounting entries. I have switched the servers to debug for a full day and caught one of these incidents in the log file, see attached.
The strange thing is it only happens maybe once a day, regardless of realm or user, and the other couple of hundred accounting requests are fine. Can anyone see why this particular one would bounce back and forth? Our setup consists of two virtually identical FreeRadius2 servers, each with their own mySQL database, so each of them is capable of doing Auth and Acct, and proxies Acct to the other one. Also I changed the acct_update_alt query to write to a failover table since I thought this was the alt query being triggered, but this does not make a difference. Still duplicates in radacct table. Thanks! Marius __________________________________________ Marius Pesé Senior Software Developer B.Sc. Computer Science [cid:[email protected]]<http://www.mindspring.co.za/> Unit 5, Doncaster Office Park Mindspring Computing Punters Way, Kenilworth P O Box 46926 Cape Town, South Africa Glosderry 7702 Phone: +27 21 657 1780 Fax : +27 21 671 7599 Cell : 072 100 70 73 E-mail: [email protected]<mailto:[email protected]>
<<inline: image003.jpg>>
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 = "[email protected]"
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 = "[email protected]"'
[acct_unique] Acct-Unique-Session-ID = "bf140131ce2e1d1f".
++[acct_unique] returns ok
[suffix] Looking up realm "msp.co.za" for User-Name = "[email protected]"
[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} -> [email protected]
++[radutmp] returns ok
[sql] expand: %{User-Name} -> [email protected]
[sql] sql_set_user escaped user --> '[email protected]'
[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 = '[email protected]
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 = '[email protected]' 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} -> [email protected]
[sql_log] expand: %{%{User-Name}:-DEFAULT} -> [email protected]
[sql_log] sql_set_user escaped user --> '[email protected]'
[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} -> [email protected]
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.- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
