On Tue, 2009-07-21 at 01:17 +0430, Marinko Tarlac wrote:

you need to search inside radacct table to see is there any session with acctstoptime = NULL for fr 2.x or acctstoptime= 0 for 1.x version for spec. user

I'm by no means a freeradius expert, but that was what I thought as well. Thanks for the info. Regards, Ranbir -- Kanwar Ranbir Sandhu Linux 2.6.27.25-170.2.72.fc10.x86_64 x86_64 GNU/Linux 21:15:49 up 3 days, 3:46, 3 users, load average: 0.41, 0.30, 0.22

On Mon, 2009-07-20 at 22:54 +0100, Ivan Kalik wrote:

I can't see anything good coming from those changes - only bad. I would be very surprised if that simultaneous use check works properly. It checks local IP pool and not something related to the NAS.

I finally found out why the changes were made. When doing a "AAA" test from the E120 with the default dialup.conf and with simultaneous checking enabled, radacct would show three entries for that same session. Two would show the acctstoptime as NULL, and the third entry would show the actual acct stop time. The next time a AAA test from the Juniper is run, freeradius replies that there is already an active session. I'm guessing it's because of the other two entries in the radacct table that still have a NULL. The changes "worked" in that afterwards only one update would be made to radacct. However, I don't believe simultaneous checking was actually working - the changes just resolved the issue of multiple records for the same session. So, why are there multiple records for the same session being created in radacct at all? We obviously have something misconfigured, but I can't put my finger on it. Here's the freeradius debug output for the initial AAA, and the second AAA requests that get rejected: rad_recv: Access-Request packet from host 1.2.3.4 port 50000, id=49, length=256 User-Password = "password" User-Name = "test1@blah.ca" Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285" Service-Type = Framed-User Framed-Protocol = PPP ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Calling-Station-Id = "#company-E120-1#this is a description#100#412" Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 543424924 NAS-Port-Id = "atm 2/0.42:100.412" NAS-IP-Address = 1.2.3.4 NAS-Identifier = "company-E120-1" server yaknet { +- entering group authorize {...} ++[preprocess] returns ok sql_xlat expand: %{User-Name} -> test1@blah.ca sql_set_user escaped user --> 'test1@blah.ca' expand: select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}" -> select groupname from radhuntgroup where nasipaddress="1.2.3.4" rlm_sql (sql): Reserving sql socket id: 3 sql_xlat finished rlm_sql (sql): Released sql socket id: 3 expand: %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} -> dyn_agas1 ++[request] returns ok ++[chap] returns noop ++[mschap] returns noop [suffix] Looking up realm "blah.ca" for User-Name = "test1@blah.ca" [suffix] Found realm "blah.ca" [suffix] Adding Stripped-User-Name = "test1" [suffix] Adding Realm = "blah.ca" [suffix] Authentication realm is LOCAL. ++[suffix] returns ok [eap] No EAP-Message, not doing EAP ++[eap] returns noop [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' rlm_sql (sql): Reserving sql socket id: 2 [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test1@blah.ca' ORDER BY id [sql] User found in radcheck table [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test1@blah.ca' ORDER BY id [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'test1@blah.ca' ORDER BY priority [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dyn_agas1' ORDER BY id [sql] User found in group dyn_agas1 [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dyn_agas1' ORDER BY id rlm_sql (sql): Released sql socket id: 2 ++[sql] returns ok ++[expiration] returns noop ++[logintime] returns noop [pap] Found existing Auth-Type, not changing it. ++[pap] returns noop Found Auth-Type = PAP +- entering group PAP {...} [pap] login attempt with password "password" [pap] Using clear text password "password" [pap] User authenticated successfully ++[pap] returns ok +- entering group session {...} [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' [sql] expand: SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL -> SELECT COUNT(*) FROM radacct WHERE username = 'test1@blah.ca' AND acctstoptime IS NULL rlm_sql (sql): Reserving sql socket id: 1 rlm_sql (sql): Released sql socket id: 1 ++[sql] returns ok +- entering group post-auth {...} rlm_sql (sql): Reserving sql socket id: 0 [sqlippool] expand: %{User-Name} -> test1@blah.ca [sqlippool] sql_set_user escaped user --> 'test1@blah.ca' [sqlippool] expand: START TRANSACTION -> START TRANSACTION [sqlippool] expand: UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '%{Nas-IP-Address}' -> UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '1.2.3.4' [sqlippool] expand: SELECT framedipaddress FROM radippool WHERE pool_name = '%{control:Pool-Name}' AND (expiry_time < NOW() OR expiry_time IS NULL) ORDER BY (username <> '%{User-Name}'), (callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE -> SELECT framedipaddress FROM radippool WHERE pool_name = 'static_pool' AND (expiry_time < NOW() OR expiry_time IS NULL) ORDER BY (username <> 'test1@blah.ca'), (callingstationid <> '=23company-E120-1=23this is a description=23100=23412'), expiry_time LIMIT 1 FOR UPDATE [sqlippool] expand: UPDATE radippool SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{NAS-Port}', callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress = '4.5.6.7' AND expiry_time IS NULL -> UPDATE radippool SET nasipaddress = '1.2.3.4', pool_key = '543424924', callingstationid = '=23company-E120-1=23this is a description=23100=23412', username = 'test1@blah.ca', expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress = '4.5.6.7' AND expiry_time IS NULL [sqlippool] Allocated IP 4.5.6.7 [0240e844] [sqlippool] expand: COMMIT -> COMMIT rlm_sql (sql): Released sql socket id: 0 [sqlippool] expand: Allocated IP: %{reply:Framed-IP-Address} from %{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name}) -> Allocated IP: 4.5.6.7 from static_pool (did cli #company-E120-1#this is a description#100#412 port 543424924 user test1@blah.ca) Allocated IP: 4.5.6.7 from static_pool (did cli #company-E120-1#this is a description#100#412 port 543424924 user test1@blah.ca) ++[sqlippool] returns ok [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' [sql] expand: %{User-Password} -> password [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test1@blah.ca', 'password', 'Access-Accept', '2009-07-21 12:47:40') rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test1@blah.ca', 'password', 'Access-Accept', '2009-07-21 12:47:40') rlm_sql (sql): Reserving sql socket id: 4 rlm_sql (sql): Released sql socket id: 4 ++[sql] returns ok ++[exec] returns noop } # server yaknet Sending Access-Accept of id 49 to 1.2.3.4 port 50000 Framed-Protocol := PPP Framed-MTU := 1492 X-Ascend-Client-Primary-DNS := 204.11.120.147 X-Ascend-Client-Secondary-DNS := 204.11.120.148 Framed-IP-Netmask := 255.255.255.255 Framed-Route := "68.232.64.1" Framed-IP-Address = 4.5.6.7 Finished request 0. Going to the next request Waking up in 4.9 seconds. rad_recv: Accounting-Request packet from host 1.2.3.4 port 50125, id=22, length=280 Acct-Status-Type = Start User-Name = "test1@blah.ca" Event-Timestamp = "Jul 21 2009 07:45:44 EDT" Acct-Delay-Time = 0 NAS-Identifier = "company-E120-1" Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285" NAS-IP-Address = 1.2.3.4 Service-Type = Framed-User Framed-Protocol = PPP Framed-Compression = None ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Framed-IP-Address = 4.5.6.7 Framed-IP-Netmask = 255.255.255.255 Calling-Station-Id = "#company-E120-1#this is a description#100#412" Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 543424924 NAS-Port-Id = "atm 2/0.42:100.412" Acct-Authentic = RADIUS server yaknet { +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 543424924,Client-IP-Address = 1.2.3.4,NAS-IP-Address = 1.2.3.4,Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285",User-Name = "test1@blah.ca"' [acct_unique] Acct-Unique-Session-ID = "e5a2f56451e30514". ++[acct_unique] returns ok [suffix] Looking up realm "blah.ca" for User-Name = "test1@blah.ca" [suffix] Found realm "blah.ca" [suffix] Adding Stripped-User-Name = "test1" [suffix] Adding Realm = "blah.ca" [suffix] Accounting realm is LOCAL. ++[suffix] returns ok +- entering group accounting {...} [detail] expand: /var/log/radius/radacct/detail -> /var/log/radius/radacct/detail [detail] /var/log/radius/radacct/detail expands to /var/log/radius/radacct/detail [detail] expand: %t -> Tue Jul 21 12:47:40 2009 ++[detail] returns ok rlm_sql (sql): Reserving sql socket id: 3 [sqlippool] expand: %{User-Name} -> test1@blah.ca [sqlippool] sql_set_user escaped user --> 'test1@blah.ca' [sqlippool] expand: START TRANSACTION -> START TRANSACTION [sqlippool] expand: UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '%{NAS-IP-Address}' AND pool_key = '%{NAS-Port}' -> UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '1.2.3.4' AND pool_key = '543424924' [sqlippool] expand: COMMIT -> COMMIT rlm_sql (sql): Released sql socket id: 3 ++[sqlippool] returns ok [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', rlm_sql (sql): Reserving sql socket id: 2 rlm_sql (sql): Released sql socket id: 2 ++[sql] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> test1@blah.ca attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated } # server yaknet Sending Accounting-Response of id 22 to 1.2.3.4 port 50125 Finished request 1. Cleaning up request 1 ID 22 with timestamp +263 Going to the next request Waking up in 4.8 seconds. rad_recv: Accounting-Request packet from host 1.2.3.4 port 50125, id=23, length=346 Acct-Status-Type = Interim-Update User-Name = "test1@blah.ca" Event-Timestamp = "Jul 21 2009 07:45:44 EDT" Acct-Delay-Time = 0 NAS-Identifier = "company-E120-1" Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285" NAS-IP-Address = 1.2.3.4 Service-Type = Framed-User Framed-Protocol = PPP Framed-Compression = None ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Framed-IP-Address = 4.5.6.7 Framed-IP-Netmask = 255.255.255.255 Calling-Station-Id = "#company-E120-1#this is a description#100#412" Acct-Input-Gigawords = 0 Acct-Input-Octets = 0 Acct-Output-Gigawords = 0 Acct-Output-Octets = 0 ERX-Input-Gigapkts = 0 Acct-Input-Packets = 0 ERX-Output-Gigapkts = 0 Acct-Output-Packets = 0 Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 543424924 NAS-Port-Id = "atm 2/0.42:100.412" Acct-Authentic = RADIUS Acct-Session-Time = 0 server yaknet { +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 543424924,Client-IP-Address = 1.2.3.4,NAS-IP-Address = 1.2.3.4,Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285",User-Name = "test1@blah.ca"' [acct_unique] Acct-Unique-Session-ID = "e5a2f56451e30514". ++[acct_unique] returns ok [suffix] Looking up realm "blah.ca" for User-Name = "test1@blah.ca" [suffix] Found realm "blah.ca" [suffix] Adding Stripped-User-Name = "test1" [suffix] Adding Realm = "blah.ca" [suffix] Accounting realm is LOCAL. ++[suffix] returns ok +- entering group accounting {...} [detail] expand: /var/log/radius/radacct/detail -> /var/log/radius/radacct/detail [detail] /var/log/radius/radacct/detail expands to /var/log/radius/radacct/detail [detail] expand: %t -> Tue Jul 21 12:47:40 2009 ++[detail] returns ok rlm_sql (sql): Reserving sql socket id: 1 [sqlippool] expand: %{User-Name} -> test1@blah.ca [sqlippool] sql_set_user escaped user --> 'test1@blah.ca' [sqlippool] expand: START TRANSACTION -> START TRANSACTION [sqlippool] expand: UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '%{Nas-IP-Address}' AND pool_key = '%{NAS-Port}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}' -> UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '1.2.3.4' AND pool_key = '543424924' AND username = 'test1@blah.ca' AND callingstationid = '=23company-E120-1=23this is a description=23100=23412' AND framedipaddress = '4.5.6.7' [sqlippool] expand: COMMIT -> COMMIT rlm_sql (sql): Released sql socket id: 1 ++[sqlippool] returns ok [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' [sql] expand: %{Acct-Input-Gigawords} -> 0 [sql] expand: %{Acct-Input-Octets} -> 0 [sql] expand: %{Acct-Output-Gigawords} -> 0 [sql] expand: %{Acct-Output-Octets} -> 0 [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 = '4.5.6.7', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0' WHERE acctsessionid = 'erx atm 2/0.42:100.412:0001049285' AND username = 'test1@yaktes rlm_sql (sql): Reserving sql socket id: 0 [sql] expand: %{Acct-Session-Time} -> 0 [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: %{Acct-Input-Gigawords} -> 0 [sql] expand: %{Acct-Input-Octets} -> 0 [sql] expand: %{Acct-Output-Gigawords} -> 0 [sql] expand: %{Acct-Output-Octets} -> 0 [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) 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-Input-Octe rlm_sql (sql): Released sql socket id: 0 ++[sql] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> test1@blah.ca attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated } # server yaknet Sending Accounting-Response of id 23 to 1.2.3.4 port 50125 Finished request 2. Cleaning up request 2 ID 23 with timestamp +263 Going to the next request Waking up in 4.8 seconds. Cleaning up request 0 ID 49 with timestamp +263 Ready to process requests. rad_recv: Accounting-Request packet from host 1.2.3.4 port 50125, id=24, length=352 Acct-Status-Type = Stop User-Name = "test1@blah.ca" Event-Timestamp = "Jul 21 2009 07:45:53 EDT" Acct-Delay-Time = 0 NAS-Identifier = "company-E120-1" Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285" NAS-IP-Address = 1.2.3.4 Service-Type = Framed-User Framed-Protocol = PPP Framed-Compression = None ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Framed-IP-Address = 4.5.6.7 Framed-IP-Netmask = 255.255.255.255 Calling-Station-Id = "#company-E120-1#this is a description#100#412" Acct-Input-Gigawords = 1 Acct-Input-Octets = 305419896 Acct-Output-Gigawords = 1 Acct-Output-Octets = 324506182 ERX-Input-Gigapkts = 1 Acct-Input-Packets = 610800471 ERX-Output-Gigapkts = 1 Acct-Output-Packets = 2271560481 Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 543424924 NAS-Port-Id = "atm 2/0.42:100.412" Acct-Authentic = RADIUS Acct-Session-Time = 10 Acct-Terminate-Cause = Admin-Reset server yaknet { +- entering group preacct {...} ++[preprocess] returns ok [acct_unique] Hashing 'NAS-Port = 543424924,Client-IP-Address = 1.2.3.4,NAS-IP-Address = 1.2.3.4,Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285",User-Name = "test1@blah.ca"' [acct_unique] Acct-Unique-Session-ID = "e5a2f56451e30514". ++[acct_unique] returns ok [suffix] Looking up realm "blah.ca" for User-Name = "test1@blah.ca" [suffix] Found realm "blah.ca" [suffix] Adding Stripped-User-Name = "test1" [suffix] Adding Realm = "blah.ca" [suffix] Accounting realm is LOCAL. ++[suffix] returns ok +- entering group accounting {...} [detail] expand: /var/log/radius/radacct/detail -> /var/log/radius/radacct/detail [detail] /var/log/radius/radacct/detail expands to /var/log/radius/radacct/detail [detail] expand: %t -> Tue Jul 21 12:47:49 2009 ++[detail] returns ok rlm_sql (sql): Reserving sql socket id: 4 [sqlippool] expand: %{User-Name} -> test1@blah.ca [sqlippool] sql_set_user escaped user --> 'test1@blah.ca' [sqlippool] expand: START TRANSACTION -> START TRANSACTION [sqlippool] expand: UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '%{Nas-IP-Address}' AND pool_key = '%{NAS-Port}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}' -> UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '1.2.3.4' AND pool_key = '543424924' AND username = 'test1@blah.ca' AND callingstationid = '=23company-E120-1=23this is a description=23100=23412' AND framedipaddress = '4.5.6.7' [sqlippool] expand: COMMIT -> COMMIT [sqlippool] expand: Released IP %{Framed-IP-Address} (did %{Called-Station-Id} cli %{Calling-Station-Id} user %{User-Name}) -> Released IP 4.5.6.7 (did cli #company-E120-1#this is a description#100#412 user test1@blah.ca) Released IP 4.5.6.7 (did cli #company-E120-1#this is a description#100#412 user test1@blah.ca) rlm_sql (sql): Released sql socket id: 4 ++[sqlippool] returns ok [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' [sql] expand: %{Acct-Input-Gigawords} -> 1 [sql] expand: %{Acct-Input-Octets} -> 305419896 [sql] expand: %{Acct-Output-Gigawords} -> 1 [sql] expand: %{Acct-Output-Octets} -> 324506182 [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}' -> UPDATE radacct SET acctstoptime = '2009-07-21 12:47:49', acctsessiontime = '10', acctinputoctets = '1' << 32 | '305419896', acctoutputoctets = '1' << 3 rlm_sql (sql): Reserving sql socket id: 3 [sql] expand: %{Acct-Session-Time} -> 10 [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: %{Acct-Input-Gigawords} -> 1 [sql] expand: %{Acct-Input-Octets} -> 305419896 [sql] expand: %{Acct-Output-Gigawords} -> 1 [sql] expand: %{Acct-Output-Octets} -> 324506182 [sql] expand: %{Acct-Delay-Time} -> 0 [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) 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), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Inpu rlm_sql (sql): Released sql socket id: 3 ++[sql] returns ok [attr_filter.accounting_response] expand: %{User-Name} -> test1@blah.ca attr_filter: Matched entry DEFAULT at line 12 ++[attr_filter.accounting_response] returns updated } # server yaknet Sending Accounting-Response of id 24 to 1.2.3.4 port 50125 Finished request 3. Cleaning up request 3 ID 24 with timestamp +272 Going to the next request Ready to process requests. rad_recv: Access-Request packet from host 1.2.3.4 port 50000, id=50, length=256 User-Password = "password" User-Name = "test1@blah.ca" Acct-Session-Id = "erx atm 2/0.42:100.413:0001049286" Service-Type = Framed-User Framed-Protocol = PPP ERX-Pppoe-Description = "pppoe 12:34:56:78:9a:bc" Calling-Station-Id = "#company-E120-1#this is a description#100#413" Connect-Info = "speed:UBR:12000" NAS-Port-Type = xDSL NAS-Port = 543424925 NAS-Port-Id = "atm 2/0.42:100.413" NAS-IP-Address = 1.2.3.4 NAS-Identifier = "company-E120-1" server yaknet { +- entering group authorize {...} ++[preprocess] returns ok sql_xlat expand: %{User-Name} -> test1@blah.ca sql_set_user escaped user --> 'test1@blah.ca' expand: select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}" -> select groupname from radhuntgroup where nasipaddress="1.2.3.4" rlm_sql (sql): Reserving sql socket id: 2 sql_xlat finished rlm_sql (sql): Released sql socket id: 2 expand: %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} -> dyn_agas1 ++[request] returns ok ++[chap] returns noop ++[mschap] returns noop [suffix] Looking up realm "blah.ca" for User-Name = "test1@blah.ca" [suffix] Found realm "blah.ca" [suffix] Adding Stripped-User-Name = "test1" [suffix] Adding Realm = "blah.ca" [suffix] Authentication realm is LOCAL. ++[suffix] returns ok [eap] No EAP-Message, not doing EAP ++[eap] returns noop [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' rlm_sql (sql): Reserving sql socket id: 1 [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test1@blah.ca' ORDER BY id [sql] User found in radcheck table [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test1@blah.ca' ORDER BY id [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'test1@blah.ca' ORDER BY priority [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dyn_agas1' ORDER BY id [sql] User found in group dyn_agas1 [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dyn_agas1' ORDER BY id rlm_sql (sql): Released sql socket id: 1 ++[sql] returns ok ++[expiration] returns noop ++[logintime] returns noop [pap] Found existing Auth-Type, not changing it. ++[pap] returns noop Found Auth-Type = PAP +- entering group PAP {...} [pap] login attempt with password "password" [pap] Using clear text password "password" [pap] User authenticated successfully ++[pap] returns ok +- entering group session {...} [sql] expand: %{User-Name} -> test1@blah.ca [sql] sql_set_user escaped user --> 'test1@blah.ca' [sql] expand: SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL -> SELECT COUNT(*) FROM radacct WHERE username = 'test1@blah.ca' AND acctstoptime IS NULL rlm_sql (sql): Reserving sql socket id: 0 [sql] expand: SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL -> SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = 'test1@blah.ca' AND acctstoptime IS NULL checkrad: No NAS type, or type "other" not checking checkrad: No NAS type, or type "other" not checking rlm_sql (sql): Released sql socket id: 0 ++[sql] returns ok } # server yaknet Using Post-Auth-Type Reject +- entering group REJECT {...} [attr_filter.access_reject] expand: %{User-Name} -> test1@blah.ca attr_filter: Matched entry DEFAULT at line 11 ++[attr_filter.access_reject] returns updated Delaying reject of request 4 for 1 seconds Going to the next request Waking up in 0.9 seconds. Sending delayed reject for request 4 Sending Access-Reject of id 50 to 1.2.3.4 port 50000 Reply-Message := "\r\nYou are already logged in - access denied\r\n\n" Waking up in 4.9 seconds. Cleaning up request 4 ID 50 with timestamp +360 Ready to process requests. -- Kanwar Ranbir Sandhu Linux 2.6.27.25-170.2.72.fc10.x86_64 x86_64 GNU/Linux 12:54:47 up 3 days, 19:25, 3 users, load average: 1.51, 1.38, 1.36

On Tue, 2009-07-21 at 19:13 +0100, Ivan Kalik wrote:

...

So, why are there multiple records for the same session being created in radacct at all? We obviously have something misconfigured, but I can't put my finger on it.

Hard to say. Are those queries running on the server or has your mailer or editor cut off parts of them? Those in the debug shouldn't run at all.

It was a straight copy and paste from the debug. Evolution can be a pain, but I'm fairly certain it didn't cut anything off (apart from the ugly wrapping).

I can see that updates and stop packets run both update and insert (alt) queries. That would mean that update didn't match any records. There might be issues with mysql safe characters in your acct id:

...

Acct-Session-Id = "erx atm 2/0.42:100.412:0001049285"

Have a look and see what is actually in the database.

The DB shows the exact same Acct-Session-Id that is in the packets themselves. Below are the three rows that get entered into radacct when the AAA test is run from the E120. Is it the "=" in the callingstationid field that's throwing things off? erx atm 2/0.42:100.416:000104929 58eb6e48d17d83d4 test1@blah.ca blah.ca 1.2.3.4 543424928 xDSL 2009-07-21 14:39:47 NULL 0 RADIUS speed:UBR:12000 0 0 =23company-E120-1=23this is a description=23100= Framed-User PPP 4.5.6.7 0 0 erx atm 2/0.42:100.416:000104929 58eb6e48d17d83d4 test1@blah.ca blah.ca 1.2.3.4 543424928 xDSL 2009-07-21 14:39:47 NULL 0 RADIUS NULL 0 0 =23company-E120-1=23this is a description=23100= Framed-User PPP 4.5.6.7 0 NULL erx atm 2/0.42:100.416:000104929 58eb6e48d17d83d4 test1@blah.ca blah.ca 1.2.3.4 543424928 xDSL 2009-07-21 14:39:55 2009-07-21 14:40:05 10 RADIUS speed:UBR:12000 4600387192 4619473478 =23company-E120-1=23this is a description=23100= Admin-Reset Framed-User PPP 4.5.6.7 0 0 NULL Regards, Ranbir -- Kanwar Ranbir Sandhu Linux 2.6.27.25-170.2.72.fc10.x86_64 x86_64 GNU/Linux 14:32:20 up 3 days, 21:03, 3 users, load average: 1.52, 1.59, 1.60

On Tue, 2009-07-21 at 15:58 -0400, Kanwar Ranbir Sandhu wrote:

On Tue, 2009-07-21 at 15:00 -0400, Kanwar Ranbir Sandhu wrote:

...

The DB shows the exact same Acct-Session-Id that is in the packets themselves. Below are the three rows that get entered into radacct when the AAA test is run from the E120. Is it the "=" in the callingstationid field that's throwing things off?

erx atm 2/0.42:100.416:000104929 58eb6e48d17d83d4 test1@blah.ca blah.ca 1.2.3.4 543424928 xDSL 2009-07-21 14:39:47 NULL 0 RADIUS speed:UBR:12000 0 0 =23company-E120-1=23this is a description=23100= Framed-User PPP 4.5.6.7 0 0

I just realized that it's not actually just an "=". The complete string is "=23", which is ASCII for "#". I added the "#" to the safe characters list, and now in mysql I can see the "=23" replaced with hash marks. This is good.

Unfortunately, I'm still seeing 3 rows for every AAA attempt.

HA! I figured it out: the acctsessionid field was truncating the Acct-Session-Id attribute being received from the NAS. I bumped the field up to 100 characters, and viola, the default SQL queries in dialup.conf started working. Yeah! We actually had the same problem with the callingstationid field. I'd recommend the radacct table have an increased field size for acctsessionid and callingstationid. I know it can be tweaked by the user afterwards, but if it was larger to begin with, problems like the ones I encountered wouldn't crop up. Thanks, Ranbir -- Kanwar Ranbir Sandhu Linux 2.6.27.25-170.2.72.fc10.x86_64 x86_64 GNU/Linux 16:20:40 up 3 days, 22:51, 3 users, load average: 2.01, 1.85, 1.73

On Tue, 2009-07-21 at 23:30 +0100, Ivan Kalik wrote:

...

HA! I figured it out: the acctsessionid field was truncating the Acct-Session-Id attribute being received from the NAS. I bumped the field up to 100 characters, and viola, the default SQL queries in dialup.conf started working. Yeah!

We actually had the same problem with the callingstationid field.

I'd recommend the radacct table have an increased field size for acctsessionid and callingstationid. I know it can be tweaked by the user afterwards, but if it was larger to begin with, problems like the ones I encountered wouldn't crop up.

Why? Most companies have sane administartors who don't create such problems for themselves.

Well, I'm not a network guy, so I don't know how much control we have over the length of those attributes. If they're configurable, I can recommend to the real network guy to make some changes on the NAS end. At least I now know what's been going on. It's no fun being new to freeradius and trying to figure out what things are blowing up. :) Thanks, Ranbir -- Kanwar Ranbir Sandhu Linux 2.6.27.25-170.2.72.fc10.x86_64 x86_64 GNU/Linux 19:26:39 up 4 days, 1:57, 3 users, load average: 1.97, 1.90, 1.64

Phil Mayers wrote:

After the 2nd outage this caused (we rely on near realtime accounting) I looked into it, and found that postgresql suffers no performance benefit from using "varchar(n)" and I simply altered all the "varchar" fields to type "text". We have since experienced no such problems. So, at the very least I'd recommend changing the default postgresql accounting schema.

Patch?

radheck/radgroupcheck are obviously a different matter, and capping the length of those fields (which after all go into AVPs) makes sense. I would still recommend varchar(253) rather than some arbitrary shorter length though.

Sure. Alan DeKok.

Phil Mayers wrote:

I must admit, I'd assumed someone had a specific reason for the field sizes being what they are, and didn't want to pre-empt them. But if there isn't such a reason, I'll knock one up.

Nothing depends on the fields being specific sizes. If it's possible to make them "large enough", that's a good patch. Alan DeKok.

Ivan Kalik wrote:

Nothing in freeradius. But on the database side? Radacct is a big chunk as it is. Most people keep at least 3 months worth of data and than can be quite a few GB. There is significant impact on database performance at the time of daily backup. Proposed changes would increase radacct size by 10-20%. That's a few more minutes of poorly responsive database.

This may be true for other DBs, for it's not for postgres: http://www.nabble.com/Re%3A-Disadvantages-to-using-"text"-p17109220.html I'm only suggesting changing the postgres schema. I realise the OP may not have been using postgres - this is a bit of a digression on my part. Obviously if you're actually *putting* more data in the fields the table would get bigger, but the alternative is either a failed or truncated insert. The former is a pretty big deal, and the latter is at best very confusing.

Increasing field sizes to 250 characters when huge majority of people would do fine with only one tenth of that field is not a very good design solution. Perhaps adding a second schema where these fields are maxed up (large_fields_schema.sql)?

PS. I must appologize, it was not my intention to imply that if your

;o) No probs

Ya, I'm using mysql. I'm not familiar enough with mysql to know if a "text" field is slower/faster/no different to varchar() field. Anyone here on the list know any better?

There will be no significant impact on performance. There might be marginal advantage with varchar due to the way text fields are stored. There will be (significant) impact on index size depending on chosen index field length.

If no one replies, I'll have to do some investigation of my own.

Test it anyway. Ivan Kalik Kalik Informatika ISP

On Wed, 2009-07-22 at 10:27 +0100, Ivan Kalik wrote:

...

PS. I must appologize, it was not my intention to imply that if your equipment generates large ids admin is insane by default. My comments were related to that specific case where admin shot himself in the foot by appending text to basic id causing database filed overflow.

No worries. In my case, I simply do not know if we have control over the length of those attributes. Frankly, I assumed whatever was coming in was the default setup in the NAS. Perhaps it isn't.

I am afraid not. NAS admin took manual instructions quite literally and hardcoded even comments like #this is a description# into the station id. Also, I suspect that only the last number is the accounting id generated by the NAS while the text before really belongs in the NAS-Identifiier rather than accounting id field. Ivan Kalik Kalik Informatika ISP