Radius Timeout instead of Access-Reject

[Antonio Modesto]

Hi,

I work at an ISP in Brazil, our main radius server is running freeradius
1.X. I'm configuring a new server with freeradius 2.X and doing some tests
to see if I find any problem before putting it on production. So far I've
found a little problem that doesn't disable me to put it in production, but
can confuse in case of a radius failure. When an authentication failure
happens, on the nas it appears that the radius server is not responding, it
shows a "Radius timeout" message, here is the output of the radius debug:



rad_recv: Access-Request packet from host 192.168.2.100 port 35710, id=86,
length=145
    Service-Type = Framed-User
    Framed-Protocol = PPP
    NAS-Port = 124
    NAS-Port-Type = Ethernet
    User-Name = "modesto"
    Calling-Station-Id = "BC:AE:C5:9C:87:C5"
    Called-Station-Id = "isimples"
    NAS-Port-Id = "LAN"
    CHAP-Challenge = 0x246ed4d8e9cffc10c7c5120963c5d990
    CHAP-Password = 0x0134931ed7c1c7fda0493d9663d658e789
    NAS-Identifier = "REDE_ISIMPLES"
    NAS-IP-Address = 192.168.2.100
# Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
[chap] Setting 'Auth-Type := CHAP'
++[chap] returns ok
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "modesto", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
[files] users: Matched entry DEFAULT at line 172
++[files] returns ok
[sql]     expand: %{User-Name} -> modesto
[sql] sql_set_user escaped user --> 'modesto'
rlm_sql (sql): Reserving sql socket id: 0
[sql]     expand: SELECT id, UserName, Attribute, Value, op           FROM
radcheck           WHERE Username = '%{SQL-User-Name}'       AND ativo='S'
ORDER BY id -> SELECT id, UserName, Attribute, Value, op           FROM
radcheck           WHERE Username = 'modesto'       AND ativo='S' ORDER BY
id
[sql]     expand: SELECT GroupName FROM usergroup WHERE
UserName='%{SQL-User-Name}' -> SELECT GroupName FROM usergroup WHERE
UserName='modesto'
rlm_sql (sql): Released sql socket id: 0
[sql] User modesto not found
++[sql] returns notfound
sql_xlat
    expand: %{User-Name} -> modesto
sql_set_user escaped user --> 'modesto'
    expand:  SELECT nas_pool_name FROM naspool WHERE
nas_ip=INET_ATON('%{NAS-IP-Address}') ->  SELECT nas_pool_name FROM naspool
WHERE nas_ip=INET_ATON('192.168.2.100')
rlm_sql (sql): Reserving sql socket id: 4
SQL query did not return any results
rlm_sql (sql): Released sql socket id: 4
    expand: %{sql: SELECT nas_pool_name FROM naspool WHERE
nas_ip=INET_ATON('%{NAS-IP-Address}')} ->
++[control] returns notfound
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.  Authentication
may fail because of this.
++[pap] returns noop
Found Auth-Type = CHAP
# Executing group from file /usr/local/etc/raddb/sites-enabled/default
+- entering group CHAP {...}
[chap] login attempt by "modesto" with CHAP password
[chap] Cleartext-Password is required for authentication
++[chap] returns invalid
Failed to authenticate the user.
Login incorrect (rlm_chap: Clear text password not available):
[modesto/<CHAP-Password>] (from client teste port 124 cli BC:AE:C5:9C:87:C5)
Using Post-Auth-Type Reject
# Executing group from file /usr/local/etc/raddb/sites-enabled/default
+- entering group REJECT {...}
[attr_filter.access_reject]     expand: %{User-Name} -> modesto
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.
rad_recv: Access-Request packet from host 192.168.2.100 port 35710, id=86,
length=145
Waiting to send Access-Reject to client teste port 35710 - ID: 86
Waking up in 0.6 seconds.
rad_recv: Access-Request packet from host 192.168.2.100 port 35710, id=86,
length=145
Waiting to send Access-Reject to client teste port 35710 - ID: 86
Waking up in 0.3 seconds.
Sending delayed reject for request 4
Sending Access-Reject of id 86 to 192.168.2.100 port 35710
Waking up in 4.9 seconds.
Cleaning up request 4 ID 86 with timestamp +41
Ready to process requests.
**

The freeradius server is running on a FreeBSD 9-STABLE Jail, there is no
firewall rules in the middle that could prevent the packet from being sent.


Regards.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120807/aa0a0102/attachment.html>