[RADIATOR] PEAP internal session resumption breaks some clients

Thu Aug 27 01:32:41 CDT 2015

We have a Windows 7 client that in certain locations around campus periodically gets booted off wireless and prompts the user to re-enter his credentials.

Each time this happens, my normal RADIUS logs show:
2015-08-26T21:57:09.002570-05:00 radius1.cites.illinois.edu radius.auth2[36852]:  [wireless] Auth FAIL for aaronb (Outer EAP Identity aaronb) on 3C-A9-F4-63-1E-44 ... because: PEAP Authentication Failure
2015-08-26T21:57:09.002192-05:00 radius1.cites.illinois.edu radius.auth2[36852]:  Access rejected for aaronb: PEAP Authentication Failure
2015-08-26T21:56:58.258927-05:00 radius1.cites.illinois.edu radius.auth2[36852]:  [wireless] Auth OK for aaronb (Outer EAP Identity aaronb) on 3C-A9-F4-63-1E-44 ...
but the detailed auth logs for the inner handlers don't indicate any inner auth taking place at 21:57:09.

I was able to capture one occurrence of this with trace 4 enabled; output for the last two requests from this client are shown below.  Note "EAP PEAP Session resumed" in the penultimate request, which from EAP_25.pm indicates that we're re-using the inner PEAP authentication as well as the outer TLS session; my hypothesis is that the client OS feels somehow shortchanged by not having the opportunity to go through MSCHAPv2 again, and doesn't respond as Radiator expects it to, so instead of doing a full inner authentication we end up with an Access-Reject (which is definitely worse from a user experience viewpoint).

The trace I captured appears to indicate at least five other clients having the same problem (an "EAP PEAP Session resumed" shortly followed by "PEAP Authentication Failure") on the same RADIUS server during a 15-minute time period, but we unfortunately don't have access to those clients to confirm their OS versions (or even that the user-visible symptoms are the same).  All I can say for certain is that their MAC addresses begin with:
D0-7E-35-
48-5D-60-
60-57-18-
3C-A9-F4- (ours)
08-11-96-
8C-70-5A-
in case that's of any interest.

There are plenty of other clients in our environment that do _not_ have this problem (i.e. are able to succesfully resume a PEAP session and get Access-Accept); nonetheless, because it's having a negative impact on some clients I've had to disable EAPTLS_SessionResumption.

I'm interested to know if anybody else has observed this, or has suggestions on how to get more information about what exactly is going wrong (it's clear PEAP doesn't like the supplicant's last RADIUS request / EAP Response, but it's not clear exactly why).

Pragmatically, it would be nice if I could keep TLS resumption on but set a different config option to disable only the PEAP inner-auth resumption (letting the clients go through their MSCHAPv2 again so they can be happy).

Thanks,
David

Wed Aug 26 21:57:08 2015 955437: DEBUG: Packet dump:
*** Received from 127.0.0.1 port 46141 ....
Code:       Access-Request
Identifier: 110
Authentic:  ]<180>t<194><248>H$<228><130><228><213><233><156><163><175><5>
Attributes:
        User-Name = "aaronb"
        NAS-IP-Address = 172.21.128.213
        NAS-Port = 2083
        Called-Station-Id = "00-90-0B-33-0D-83:822i-URH-IllinoisNet"
        Calling-Station-Id = "3C-A9-F4-63-1E-44"
        Framed-MTU = 1250
        NAS-Port-Type = Wireless-IEEE-802-11
        Framed-Compression = None
        Connect-Info = "CONNECT Unknown radio"
        Chargeable-User-Identity = ""
        EAP-Message = <2><4><0>E<25><128><0><0><0>;<20><3><1><0><1><1><22><3><1><0>0<214><:<163>=<185><232><185>c<217><216><184><160>(<132>7<206><253><174><3><224><201><220>]<228><19>A><186><213><1
93><127><248><235><26><11>=<201><187><136>2x<142><211><218><159>sk
        Message-Authenticator = <216><147>K<137><222><142><193>z<135><18><4><165><185><223>><232>
        X-CLIENT_MAC = "3ca9f4631e44"
        X-SSID = "822i-URH-IllinoisNet"
        X-Client-Identifier = "wireless"
        X-Client-IP = "172.21.128.213"
        X-Timestamp = 1440644228
        X-RecvFromPort = 34730
        X-Id = 45
        X-Proxy-Timestamp = 1440644228
        X-Proxy-Timeout = 30

Wed Aug 26 21:57:08 2015 955937: DEBUG: Handling request with Handler 'X-Client-Identifier=wireless, Request-Type=Access-Request', Identifier 'wireless'
Wed Aug 26 21:57:08 2015 956075: DEBUG:  Deleting session for aaronb, 172.21.128.213, 2083
Wed Aug 26 21:57:08 2015 956163: DEBUG: Handling with Radius::AuthFILE: wireless-mac_block
Wed Aug 26 21:57:08 2015 956279: DEBUG: Radius::AuthFILE looks for match with 3ca9f4631e44 [aaronb]
Wed Aug 26 21:57:08 2015 956349: DEBUG: Radius::AuthFILE REJECT: No such user: 3ca9f4631e44 [aaronb]
Wed Aug 26 21:57:08 2015 956459: DEBUG: AuthBy FILE result: ACCEPT, No such user
Wed Aug 26 21:57:08 2015 956538: DEBUG: Handling with Radius::AuthFILE: wireless-eapOuter
Wed Aug 26 21:57:08 2015 956673: DEBUG: Handling with EAP: code 2, 4, 69, 25
Wed Aug 26 21:57:08 2015 956751: DEBUG: Response type 25
Wed Aug 26 21:57:08 2015 956922: DEBUG: EAP TLS SSL_accept result: 1, 0, 3
Wed Aug 26 21:57:08 2015 957066: DEBUG: EAP result: 3, EAP PEAP Session resumed
Wed Aug 26 21:57:08 2015 957145: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Session resumed
Wed Aug 26 21:57:08 2015 957222: DEBUG: Setting request attribute: inner_identity = 'aaronb'
Wed Aug 26 21:57:08 2015 957301: DEBUG: @{$context->{start_time}} is 1440644228.820164
Wed Aug 26 21:57:08 2015 957391: DEBUG: Access challenged for aaronb: EAP PEAP Session resumed
Wed Aug 26 21:57:08 2015 957644: DEBUG: Packet dump:
*** Sending to 127.0.0.1 port 46141 ....
Code:       Access-Challenge
Identifier: 110
Authentic:  <28>L<184><4><189>R<185><236>T<166><170><186><197><136>p<1>
Attributes:
        EAP-Message = <1><5><0>+<25><0><23><3><1><0> _L.<222><211>DXx<8><223>`<237>k<164>R<234><245><11><22>qg<147><252>9<214>5<29>&"<219><174><193>
        Message-Authenticator = <0><0><0><0><0><0><0><0><0><0><0><0><0><0><0><0>

...

Wed Aug 26 21:57:08 2015 999811: DEBUG: Packet dump:
*** Received from 127.0.0.1 port 46141 ....
Code:       Access-Request
Identifier: 112
Authentic:  b<10><23><234>lP<212><202><210>.<4> <234>$\<154>
Attributes:
        User-Name = "aaronb"
        NAS-IP-Address = 172.21.128.213
        NAS-Port = 2083
        Called-Station-Id = "00-90-0B-33-0D-83:822i-URH-IllinoisNet"
        Calling-Station-Id = "3C-A9-F4-63-1E-44"
        Framed-MTU = 1250
        NAS-Port-Type = Wireless-IEEE-802-11
        Framed-Compression = None
        Connect-Info = "CONNECT Unknown radio"
        Chargeable-User-Identity = ""
        EAP-Message = <2><5><0>+<25><0><23><3><1><0> Ys<235><30>z1^O<227><198>wT<238><132><166><177>{<10><194><224><241><142><164><249>CJ<213>Ey<2><O
        Message-Authenticator = .<199><143><12><211><152><155>.<27><167><17><196>s(<159><146>
        X-CLIENT_MAC = "3ca9f4631e44"
        X-SSID = "822i-URH-IllinoisNet"
        X-Client-Identifier = "wireless"
        X-Client-IP = "172.21.128.213"
        X-Timestamp = 1440644228
        X-RecvFromPort = 34730
        X-Id = 46
        X-Proxy-Timestamp = 1440644228
        X-Proxy-Timeout = 30

Wed Aug 26 21:57:09 2015 000354: DEBUG: Handling request with Handler 'X-Client-Identifier=wireless, Request-Type=Access-Request', Identifier 'wireless'
Wed Aug 26 21:57:09 2015 000510: DEBUG:  Deleting session for aaronb, 172.21.128.213, 2083
Wed Aug 26 21:57:09 2015 000603: DEBUG: Handling with Radius::AuthFILE: wireless-mac_block
Wed Aug 26 21:57:09 2015 000728: DEBUG: Radius::AuthFILE looks for match with 3ca9f4631e44 [aaronb]
Wed Aug 26 21:57:09 2015 000799: DEBUG: Radius::AuthFILE REJECT: No such user: 3ca9f4631e44 [aaronb]
Wed Aug 26 21:57:09 2015 000900: DEBUG: AuthBy FILE result: ACCEPT, No such user
Wed Aug 26 21:57:09 2015 000976: DEBUG: Handling with Radius::AuthFILE: wireless-eapOuter
Wed Aug 26 21:57:09 2015 001119: DEBUG: Handling with EAP: code 2, 5, 43, 25
Wed Aug 26 21:57:09 2015 001197: DEBUG: Response type 25
Wed Aug 26 21:57:09 2015 001358: DEBUG: EAP Failure, elapsed time 0.18118
Wed Aug 26 21:57:09 2015 001472: DEBUG: EAP result: 1, PEAP Authentication Failure
Wed Aug 26 21:57:09 2015 001551: DEBUG: AuthBy FILE result: REJECT, PEAP Authentication Failure
Wed Aug 26 21:57:09 2015 001649: DEBUG: Setting request attribute: inner_identity = 'aaronb'
Wed Aug 26 21:57:09 2015 001770: DEBUG: @{$context->{start_time}} is 1440644228.820164
Wed Aug 26 21:57:09 2015 001868: INFO: Access rejected for aaronb: PEAP Authentication Failure
Wed Aug 26 21:57:09 2015 002801: DEBUG: Packet dump:
*** Sending to 127.0.0.1 port 46141 ....
Code:       Access-Reject
Identifier: 112
Authentic:  3xwbX<234>-<213><161>T<222><132><187>W<176><177>
Attributes:
        EAP-Message = <4><5><0><4>
        Message-Authenticator = <0><0><0><0><0><0><0><0><0><0><0><0><0><0><0><0>
        Reply-Message = "Request Denied"