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