simultaneous checking
Kanwar Ranbir Sandhu
m3freak at thesandhufamily.ca
Tue Jul 21 19:15:43 CEST 2009
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 at 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 at blah.ca
sql_set_user escaped user --> 'test1 at 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 at 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 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at 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 at 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 at 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 at 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 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at blah.ca'
[sql] expand: SELECT COUNT(*) FROM radacct
WHERE username = '%{SQL-User-Name}' AND
acctstoptime IS NULL -> SELECT COUNT(*)
FROM radacct WHERE username =
'test1 at 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 at blah.ca
[sqlippool] sql_set_user escaped user --> 'test1 at 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 at 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 at 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 at 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 at blah.ca)
++[sqlippool] returns ok
[sql] expand: %{User-Name} -> test1 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at 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 at 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 at 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 at 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 at blah.ca"'
[acct_unique] Acct-Unique-Session-ID = "e5a2f56451e30514".
++[acct_unique] returns ok
[suffix] Looking up realm "blah.ca" for User-Name = "test1 at 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 at blah.ca
[sqlippool] sql_set_user escaped user --> 'test1 at 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 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at 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 at 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 at 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 at blah.ca"'
[acct_unique] Acct-Unique-Session-ID = "e5a2f56451e30514".
++[acct_unique] returns ok
[suffix] Looking up realm "blah.ca" for User-Name = "test1 at 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 at blah.ca
[sqlippool] sql_set_user escaped user --> 'test1 at 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 at 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 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at 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 at 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 at 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 at 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 at blah.ca"'
[acct_unique] Acct-Unique-Session-ID = "e5a2f56451e30514".
++[acct_unique] returns ok
[suffix] Looking up realm "blah.ca" for User-Name = "test1 at 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 at blah.ca
[sqlippool] sql_set_user escaped user --> 'test1 at 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 at 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 at blah.ca)
Released IP 4.5.6.7 (did cli #company-E120-1#this is a
description#100#412 user test1 at blah.ca)
rlm_sql (sql): Released sql socket id: 4
++[sqlippool] returns ok
[sql] expand: %{User-Name} -> test1 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at 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 at 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 at 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 at blah.ca
sql_set_user escaped user --> 'test1 at 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 at 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 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at 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 at 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 at 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 at 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 at blah.ca
[sql] sql_set_user escaped user --> 'test1 at blah.ca'
[sql] expand: SELECT COUNT(*) FROM radacct
WHERE username = '%{SQL-User-Name}' AND
acctstoptime IS NULL -> SELECT COUNT(*)
FROM radacct WHERE username =
'test1 at 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 at 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 at 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
More information about the Freeradius-Users
mailing list