Server returns Access-Accept but client is not authenticated

[Clement Ogedengbe]

Many Thanks

Clement Ogedengbe
Network Support Officer
Information & Learning Services
University of Worcester
01905 54 2258


-----Original Message-----
From: Clement Ogedengbe 
Sent: 05 December 2013 10:34
To: 'FreeRadius users mailing list'
Subject: RE: Running RADIUS in permanent debug mode with rotating log

One of our radius servers started acting strange and there has been no config change except that we updated the DELL hardware storage firmware of the server.

MSCHAP authentication request returns Access-Accept, but the client does not get authenticated. We have two servers with similar config. Authentication request sent to the other server is OK. I ant figure out what the issue is.

Extract of log below:


Going to the next request
Waking up in 2.1 seconds.
rad_recv: Access-Request packet from host 10.255.253.2 port 35521, id=81, length=189 Cleaning up request 73 ID 81 with timestamp +270
        Proxy-State = 0x00000002
        User-Name = "ogec1"
        Framed-MTU = 1300
        Calling-Station-Id = "90-a4-de-49-e0-60"
        Called-Station-Id = "a4-18-75-79-b0-50:eduroam"
        NAS-IP-Address = 10.255.252.248
        NAS-Identifier = "XXX_WLC5"
        Service-Type = Framed-User
        MS-CHAP-Challenge = 0x2d710de1e7c6f6dfebb86195af7b5842
        MS-CHAP2-Response = 0x0000f8bd757bd0a4523c2f2e52575cb5d549000000000000000031c8fc0bb6f978154d90d4e54bd3093e3a8f96d367dd7dde
# Executing section authorize from file /etc/freeradius/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
[mschap] Found MS-CHAP attributes.  Setting 'Auth-Type  = mschap'
++[mschap] returns ok
Sending Access-Request of id 35 to 193.62.48.61 port 1812
        Proxy-State = 0x00000002
        User-Name = "ogec1"
        Framed-MTU = 1300
        Calling-Station-Id = "90-a4-de-49-e0-60"
        Called-Station-Id = "a4-18-75-79-b0-50:eduroam"
        NAS-IP-Address = 10.255.252.248
        NAS-Identifier = "XXX_WLC5"
        Service-Type = Framed-User
        MS-CHAP-Challenge = 0x2d710de1e7c6f6dfebb86195af7b5842
        MS-CHAP2-Response = 0x0000f8bd757bd0a4523c2f2e52575cb5d549000000000000000031c8fc0bb6f978154d90d4e54bd3093e3a8f96d367dd7dde
        Domain-Name = "XXXX.AC.UK"
        Message-Authenticator = 0x00000000000000000000000000000000
        Proxy-State = 0x3831
rad_recv: Access-Accept packet from host 193.62.48.61 port 1812, id=35, length=189
        MS-CHAP2-Success = 0x00533d34383638323832443935343639393934463836374330323636383934463332463336374339354239
        MS-MPPE-Recv-Key = 0x283d0adb1d7c75073e65a97484b6254b
        MS-MPPE-Send-Key = 0x3896bcce7a7467cf3bfe790c5ccc4111
        MS-MPPE-Encryption-Policy = 0x00000002
        MS-MPPE-Encryption-Types = 0x00000004
        Proxy-State = 0x00000002
        Proxy-State = 0x3831
# Executing section post-proxy from file /etc/freeradius/sites-enabled/default
+- entering group post-proxy {...}
[eap] No pre-existing handler found
++[eap] returns noop
Found Auth-Type = MSCHAP
Found Auth-Type = Accept
Warning:  Found 2 auth-types on request for user 'ogec1'
Auth-Type = Accept, accepting the user
Login OK: [ogec1] (from client bsc1 port 0 cli 90-a4-de-49-e0-60) # Executing section post-auth from file /etc/freeradius/sites-enabled/default
+- entering group post-auth {...}
[reply_log]     expand: /usr/local/var/log/radius/radacct/%Y%m%d/reply-detail -> /usr/local/var/log/radius/radacct/20131205/reply-detail
[reply_log] /usr/local/var/log/radius/radacct/%Y%m%d/reply-detail expands to /usr/local/var/log/radius/radacct/20131205/reply-detail
[reply_log]     expand: %{Packet-Src-IP-Address} Returned from %{home_server:ipaddr} for User %{User-Name} - %t -> 10.255.253.2 Returned from 193.62.48.61 for User ogec1 - Thu Dec$
++[reply_log] returns ok
[f_ticks]       expand: %{reply:Packet-Type} -> Access-Accept
[f_ticks]       expand: f_ticks.%{%{reply:Packet-Type}:-format} -> f_ticks.Access-Accept
[f_ticks]       expand: /usr/local/var/log/radius/radacct/%Y%m%d/linelog -> /usr/local/var/log/radius/radacct/20131205/linelog
[f_ticks]       expand: Access accepted for %{User-Name} at %{NAS-IP-Address} received from %{Packet-Src-IP-Address} proxied to %{home_server:ipaddr}  # CSI=%{Calling-Station-Id} $
++[f_ticks] returns ok
++[exec] returns noop
Sending Access-Accept of id 81 to 10.255.253.2 port 35521
        MS-CHAP2-Success = 0x00533d34383638323832443935343639393934463836374330323636383934463332463336374339354239
        MS-MPPE-Recv-Key = 0x283d0adb1d7c75073e65a97484b6254b
        MS-MPPE-Send-Key = 0x3896bcce7a7467cf3bfe790c5ccc4111
        MS-MPPE-Encryption-Policy = 0x00000002
        MS-MPPE-Encryption-Types = 0x00000004
        Proxy-State = 0x00000002
Finished request 75.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.255.253.2 port 35521, id=81, length=192