Access-reject tiemout

[Patrice TCHERKEZIAN]

Hi !,

I experiment a strange problem which have appeared since some weeks.

All Access-Reject sent to my AC/AP by the radius server take a lot of time
to arrive and there is a timeout on my AC/AP.
This is very strange because all Access-Accept are well-received without any
timeout and any error by the AC/AP.
And, I test on my lan with Ntradping, and the same problem of timeout
appears after an Access-Reject.
But also, when I launch Freeradius on debug mode, there is no timeout and
all Access-Reject are well-received.

This is the configuration I use :
freeradius 1.0.3
database : Postgresql release 8.0.3
Access Controller/Access Point colubris(CN3200)

Thank you for your help.

Sincerily,
Patrice Tcherkezian

------------------------------------------------------------
Below, an debug output with a successful connection :
------------------------------------------------------------

rad_recv: Access-Request packet from host 192.168.10.60:2631, id=8,
length=48
User-Name = "estelle"
CHAP-Password = 0x438c4b60518a10782d6e01d0cf399bdc14
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
modcall[authorize]: module "preprocess" returns ok for request 0
rlm_chap: Setting 'Auth-Type := CHAP'
modcall[authorize]: module "chap" returns ok for request 0
modcall[authorize]: module "mschap" returns noop for request 0
rlm_realm: No '@' in User-Name = "estelle", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[authorize]: module "suffix" returns noop for request 0
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 0
radius_xlat: 'estelle'
rlm_sql (sql): sql_set_user escaped user --> 'estelle'
radius_xlat: 'SELECT radcheck.id, radcheck.UserName, radcheck.Attribute,
radcheck.Value, radcheck.Op ??FROM radcheck , "user" ??WHERE
radcheck.Username = 'estelle' AND radcheck.Username = "user".Username AND
"user".state_account = 1 ??ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
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 = 'estelle' AND
usergroup.GroupName = radgroupcheck.GroupName ??ORDER BY radgroupcheck.id'
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat: 'SELECT id, UserName, Attribute, Value, Op ??FROM radreply
??WHERE Username = 'estelle' ??ORDER BY id'
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat: 'SELECT radgroupreply.id, radgroupreply.GroupName,
radgroupreply.Attribute, ??radgroupreply.Value, radgroupreply.Op ??FROM
radgroupreply,usergroup ??WHERE usergroup.Username = 'estelle' 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 0
modcall: group authorize returns ok for request 0
rad_check_password: Found Auth-Type Local
auth: type Local
auth: user supplied CHAP-Password matches local User-Password
Login OK: [estelle] (from client postedario port 0)
Processing the post-auth section of radiusd.conf
modcall: entering group post-auth for request 0
rlm_sql (sql): Processing sql_postauth
radius_xlat: 'estelle'
rlm_sql (sql): sql_set_user escaped user --> 'estelle'
radius_xlat: 'INSERT into radpostauth (username, pass, reply,
authdate,mac_address,ip_user,hotspot_name) ??values ('estelle',
'Chap-Password', 'Access-Accept', NOW(),'', NULLIF('', '')::inet,'')'
rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth (username,
pass, reply, authdate,mac_address,ip_user,hotspot_name) ??values ('estelle',
'Chap-Password', 'Access-Accept', NOW(),'', NULLIF('', '')::inet,'')
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: affected rows = 1
rlm_sql (sql): Released sql socket id: 3
modcall[post-auth]: module "sql" returns ok for request 0
modcall: group post-auth returns ok for request 0
Sending Access-Accept of id 8 to 192.168.10.60:2631
Session-Timeout := 4813
Idle-Timeout := 600
Framed-Protocol := PPP
Service-Type := Framed-User
Framed-MTU := 1500
Colubris-AVPair += "use-access-list=visiteurs"
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...

------------------------------------------------------------
Below, an debug output with a refused connection :
------------------------------------------------------------

rad_recv: Access-Request packet from host 192.168.10.60:2638, id=9,
length=46
User-Name = "voila"
CHAP-Password = 0x4f2988cb3ca0e0e7bfd22eea9dda72b19f
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
modcall[authorize]: module "preprocess" returns ok for request 1
rlm_chap: Setting 'Auth-Type := CHAP'
modcall[authorize]: module "chap" returns ok for request 1
modcall[authorize]: module "mschap" returns noop for request 1
rlm_realm: No '@' in User-Name = "voila", looking up realm NULL
rlm_realm: No such realm "NULL"
modcall[authorize]: module "suffix" returns noop for request 1
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 1
radius_xlat: 'voila'
rlm_sql (sql): sql_set_user escaped user --> 'voila'
radius_xlat: 'SELECT radcheck.id, radcheck.UserName, radcheck.Attribute,
radcheck.Value, radcheck.Op ??FROM radcheck , "user" ??WHERE
radcheck.Username = 'voila' AND radcheck.Username = "user".Username AND
"user".state_account = 1 ??ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): User voila not found in radcheck
radius_xlat: 'SELECT radgroupcheck.id, radgroupcheck.GroupName,
??radgroupcheck.Attribute, radgroupcheck.Value,radgroupcheck.Op ??FROM
radgroupcheck, usergroup ??WHERE usergroup.Username = 'voila' AND
usergroup.GroupName = radgroupcheck.GroupName ??ORDER BY radgroupcheck.id'
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
radius_xlat: 'SELECT radgroupreply.id, radgroupreply.GroupName,
radgroupreply.Attribute, ??radgroupreply.Value, radgroupreply.Op ??FROM
radgroupreply,usergroup ??WHERE usergroup.Username = 'voila' AND
usergroup.GroupName = radgroupreply.GroupName ??ORDER BY radgroupreply.id'
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: affected rows =
rlm_sql (sql): User voila not found in radgroupcheck
rlm_sql (sql): User not found
rlm_sql (sql): Released sql socket id: 2
modcall[authorize]: module "sql" returns notfound for request 1
modcall: group authorize returns ok for request 1
rad_check_password: Found Auth-Type CHAP
auth: type "CHAP"
Processing the authenticate section of radiusd.conf
modcall: entering group Auth-Type for request 1
rlm_chap: login attempt by "voila" with CHAP password
rlm_chap: Could not find clear text password for user voila
modcall[authenticate]: module "chap" returns invalid for request 1
modcall: group Auth-Type returns invalid for request 1
auth: Failed to validate the user.
Login incorrect (rlm_chap: Clear text password not available):
[voila/<CHAP-Password>] (from client postedario port 0)
Processing the post-auth section of radiusd.conf
modcall: entering group Post-Auth-Type for request 1
rlm_sql (sql): Processing sql_postauth
radius_xlat: 'voila'
rlm_sql (sql): sql_set_user escaped user --> 'voila'
radius_xlat: 'INSERT into radpostauth (username, pass, reply,
authdate,mac_address,ip_user,hotspot_name) ??values ('voila',
'Chap-Password', 'Access-Reject', NOW(),'', NULLIF('', '')::inet,'')'
rlm_sql (sql) in sql_postauth: query is INSERT into radpostauth (username,
pass, reply, authdate,mac_address,ip_user,hotspot_name) ??values ('voila',
'Chap-Password', 'Access-Reject', NOW(),'', NULLIF('', '')::inet,'')
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: affected rows = 1
rlm_sql (sql): Released sql socket id: 1
modcall[post-auth]: module "sql" returns ok for request 1
modcall: group Post-Auth-Type returns ok for request 1
Delaying request 1 for 1 seconds
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Sending Access-Reject of id 9 to 192.168.10.60:2638
Waking up in 4 seconds...
--- Walking the entire request list ---
Cleaning up request 1 ID 9 with timestamp 42efb05d
Nothing to do. Sleeping until we see a request.