Stale sessions
Stelio Gouveia
stelio at skyrove.com
Wed Jun 14 00:51:44 CEST 2006
Thank you Carlos for your reply,
your post has been most helpful to reinforce my understanding of
freeradius.
According to your reply i am going to assume that the only field that
need to be updated is the AcctStopTime field.
To be honest i dont really understand the logic behind the
Interrim-Interval and the query you've provided.
I am using a Authentication backend but i simply test to see if the
AcctStopTime is NULL, in which case i update the AcctStopTime with Start
+ Session.
Could you provide some information about what areas of radius could
impact on the SQL session handling method?
As requested by Alan, the radius debug dump when i do get an error:
I typically would get 2 accepts and 1 reject in successions
THE ACCEPT
Waking up in 4 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:32776, id=15, length=68
User-Name = "testuser"
User-Password = "password"
NAS-IP-Address = 255.255.255.255
NAS-Port = 1812
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 7
modcall[authorize]: module "preprocess" returns ok for request 7
modcall[authorize]: module "chap" returns noop for request 7
modcall[authorize]: module "mschap" returns noop for request 7
modcall[authorize]: module "suffix" returns noop for request 7
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 7
users: Matched entry DEFAULT at line 152
modcall[authorize]: module "files" returns ok for request 7
radius_xlat: 'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat: ' ??SELECT id, UserName, Attribute, Value, Op ??FROM
radcheck ??WHERE Username = 'testuser' ??ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql_postgresql: query: ??SELECT id, UserName, Attribute, Value,
Op ??FROM radcheck ??WHERE Username = 'testuser' ??ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat: 'SELECT radgroupcheck.id, radgroupcheck.GroupName,
??radgroupcheck.Attribute, radgroupcheck.Value,radgroupcheck.Op ??FROM
radgroupcheck, usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupcheck.GroupName
??ORDER BY radgroupcheck.id'
rlm_sql_postgresql: query: SELECT radgroupcheck.id,
radgroupcheck.GroupName, ??radgroupcheck.Attribute,
radgroupcheck.Value,radgroupcheck.Op ??FROM radgroupcheck, usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupcheck.GroupName ??ORDER BY
radgroupcheck.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat: 'REMOVED FROM DUMP TO CUTDOWN SIZE...'
rlm_sql_postgresql: query: REMOVED FROM DUMP TO CUTDOWN SIZE...
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql: Failed to create the pair: Unknown value for attribute
ChilliSpot-Max-Output-Octets
rlm_sql (sql): Error getting data from database
radius_xlat: 'SELECT radgroupreply.id, radgroupreply.GroupName,
radgroupreply.Attribute, ??radgroupreply.Value, radgroupreply.Op
??FROM radgroupreply,usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupreply.GroupName
??ORDER BY radgroupreply.id'
rlm_sql_postgresql: query: SELECT radgroupreply.id,
radgroupreply.GroupName, radgroupreply.Attribute,
??radgroupreply.Value, radgroupreply.Op ??FROM radgroupreply,usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupreply.GroupName ??ORDER BY
radgroupreply.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): Released sql socket id: 4
modcall[authorize]: module "sql" returns ok for request 7
modcall: leaving group authorize (returns ok) for request 7
rad_check_password: Found Auth-Type Local
auth: type Local
auth: user supplied User-Password matches local User-Password
Processing the session section of radiusd.conf
modcall: entering group session for request 7
radius_xlat: 'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat: 'SELECT COUNT(*) FROM radacct WHERE
UserName='testuser' AND AcctStopTime IS NULL'
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql_postgresql: query: SELECT COUNT(*) FROM radacct WHERE
UserName='testuser' AND AcctStopTime IS NULL
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): Released sql socket id: 3
modcall[session]: module "sql" returns ok for request 7
modcall: leaving group session (returns ok) for request 7
Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 7
radius_xlat:
'/usr/local/var/log/radius/radacct/127.0.0.1/reply-detail-20060613'
rlm_detail:
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/reply-detail-%Y%m%d
expands to /usr/local/var/log/radius/radacct/127.0.0.1/reply-detail-20060613
modcall[post-auth]: module "reply_log" returns ok for request 7
rlm_sql (sql): Processing sql_postauth
radius_xlat: 'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat: 'INSERT into radpostauth (username, pass, reply,
authdate) ??values ('testuser', 'password', 'Access-Accept',
NOW())'
radius_xlat: '/usr/local/var/log/radius/sqltrace.sql'
rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth
(username, pass, reply, authdate) ??values ('testuser',
'password', 'Access-Accept', NOW())
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql_postgresql: query: INSERT into radpostauth (username, pass,
reply, authdate) ??values ('testuser', 'password',
'Access-Accept', NOW())
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: affected rows = 1
rlm_sql (sql): Released sql socket id: 2
modcall[post-auth]: module "sql" returns ok for request 7
modcall: leaving group post-auth (returns ok) for request 7
Sending Access-Accept of id 15 to 127.0.0.1 port 32776
Finished request 7
Going to the next request
--- Walking the entire request list ---
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 6 ID 11 with timestamp 448eb25e
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 7 ID 15 with timestamp 448eb261
Nothing to do. Sleeping until we see a request.
THE REJECT
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:32776, id=253, length=68
User-Name = "testuser"
User-Password = "password"
NAS-IP-Address = 255.255.255.255
NAS-Port = 1812
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 5
modcall[authorize]: module "preprocess" returns ok for request 5
modcall[authorize]: module "chap" returns noop for request 5
modcall[authorize]: module "mschap" returns noop for request 5
modcall[authorize]: module "suffix" returns noop for request 5
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 5
users: Matched entry DEFAULT at line 152
modcall[authorize]: module "files" returns ok for request 5
radius_xlat: 'testuser'
rlm_sql (sql): sql_set_user escaped user --> 'testuser'
radius_xlat: ' ??SELECT id, UserName, Attribute, Value, Op ??FROM
radcheck ??WHERE Username = 'testuser' ??ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql_postgresql: query: ??SELECT id, UserName, Attribute, Value,
Op ??FROM radcheck ??WHERE Username = 'testuser' ??ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat: 'SELECT radgroupcheck.id, radgroupcheck.GroupName,
??radgroupcheck.Attribute, radgroupcheck.Value,radgroupcheck.Op ??FROM
radgroupcheck, usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupcheck.GroupName
??ORDER BY radgroupcheck.id'
rlm_sql_postgresql: query: SELECT radgroupcheck.id,
radgroupcheck.GroupName, ??radgroupcheck.Attribute,
radgroupcheck.Value,radgroupcheck.Op ??FROM radgroupcheck, usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupcheck.GroupName ??ORDER BY
radgroupcheck.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat: '...'
rlm_sql_postgresql: query: REMOVED CODE
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql: Failed to create the pair: Unknown value for attribute
ChilliSpot-Max-Output-Octets
rlm_sql (sql): Error getting data from database
radius_xlat: 'SELECT radgroupreply.id, radgroupreply.GroupName,
radgroupreply.Attribute, ??radgroupreply.Value, radgroupreply.Op
??FROM radgroupreply,usergroup ??WHERE usergroup.Username =
'testuser' AND usergroup.GroupName = radgroupreply.GroupName
??ORDER BY radgroupreply.id'
rlm_sql_postgresql: query: SELECT radgroupreply.id,
radgroupreply.GroupName, radgroupreply.Attribute,
??radgroupreply.Value, radgroupreply.Op ??FROM radgroupreply,usergroup
??WHERE usergroup.Username = 'testuser' AND
usergroup.GroupName = radgroupreply.GroupName ??ORDER BY
radgroupreply.id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): Released sql socket id: 1
modcall[authorize]: module "sql" returns ok for request 5
modcall: leaving group authorize (returns ok) for request 5
rad_check_password: Found Auth-Type Local
auth: type Local
auth: No password configured for the user
auth: Failed to validate the user.
Delaying request 5 for 1 seconds
Finished request 5
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:32776, id=253, length=68
Sending Access-Reject of id 253 to 127.0.0.1 port 32776
--- Walking the entire request list ---
Waking up in 3 seconds...
--- Walking the entire request list ---
Cleaning up request 4 ID 249 with timestamp 448eb1c7
Cleaning up request 5 ID 253 with timestamp 448eb1c7
Nothing to do. Sleeping until we see a request.
Carlos Sobrinho wrote:
> On Monday 12 June 2006 15:32, Alan DeKok wrote:
>
>> Stelio Gouveia <stelio at skyrove.com> wrote:
>>
>>> I have noticed that you cant rely on the sql method, even thou there is
>>> a simul_count_query! In my case when i encounter a stale session i set
>>> the AcctStopTime = AcctStartTime + AcctSessionTime. Although this seems
>>> to work most of the time, its not fool proof as can be seen in this case
>>> study:
>>>
>
> I did something similar. In case of a stalled session, my Authentication
> Backend tests this:
> $sql = "
> SELECT RadAcctId,
> UserName,
> TIME_TO_SEC(TIMEDIFF(NOW(),
> ADDTIME(AcctStartTime,SEC_TO_TIME(AcctSessionTime)))) AS Stalled
> FROM radacct
> WHERE AcctStopTime = 0 AND
> TIME_TO_SEC(TIMEDIFF(NOW(), ADDTIME(AcctStartTime,SEC_TO_TIME(AcctSessionTime)))) > 300 AND
> UserName='$key'
> ";
>
> Since I have Interrim-Interval to 120s, if its stalled its bigger than 300.
> Then I just UPDATE the StopTime to the Start+Session.
>
> I get a stalled session for every user every time my NAS crash/reboot...
> I just put a string "For security reasons... please wait 5m" in the login page.
>
> Best Regards
> C.Sobrinho
>
>
>> RADIUS accounting isn't foolproof because packets can be lost.
>>
>> Don't blame the server. It can't maker perfect decisions when it
>> has imperfect information.
>>
>> Alan DeKok.
>>
>> -
>> List info/subscribe/unsubscribe? See
>> http://www.freeradius.org/list/users.html
>>
>
>
More information about the Freeradius-Users
mailing list