[RADIATOR] Unsupported EAP Response 26

michael.filz at zv-extern.fraunhofer.de michael.filz at zv-extern.fraunhofer.de
Tue Sep 10 15:15:16 UTC 2019 

Hi,

I'm trying to update our slightly out-of-date Radiator from 4.18 to the
current 4.23, but I've hit a snag. After some debugging, the problem
seems to originate from the EAP part of the authentication. We have
been running the same config for ages and it worked find in 4.18, so I
suspect there might be a bug in 4.23 or possibly a bug in our config
that got never triggered before...
The relevant config sniplet (everything else are just logging settings
and a few endpoint configurations):


<AuthBy LDAP2>
        Identifier      authby-withoutrealm
        UsernameMatchesWithoutRealm
	<REDACTED>
        NoDefault
        HoldServerConnection
        UseSSL
        SSLCAFile <REDACTED>
        EAPType MSCHAP-V2
        Timeout 2
        FailureBackoffTime 2
</AuthBy>


<Handler TunnelledByPEAP=1,EAP-Message=/<REDACTED>/i>
        AuthBy authby-withrealm
        PostAuthHook file:"%D/AuthLogHook.pm"
</Handler>

<Handler Realm=/<REDACTED>/i>
        Identifier RADIUS_PROXY

        <AuthBy FILE>
                EAPType                 PEAP
                Filename                %D/dot1x_anon
                EAPAnonymous            anonymous@<REDACTED>
                EAPTLS_CAFile           %D/cert/<REDACTED>
                EAPTLS_CertificateFile  %D/cert/<REDACTED>
                EAPTLS_CertificateType  PEM
                EAPTLS_PrivateKeyFile   %D/cert/<REDACTED>
                EAPTLS_PrivateKeyPassword      <REDACTED>
                EAPTLS_PEAPVersion      0
                EAPTLS_MaxFragmentSize  1024
                EAPTTLS_NoAckRequired
                AutoMPPEKeys
                EAPTLS_NoCheckId 
                EAPTLS_SessionResumption        0
        </AuthBy>
</Handler>


The PostAuthHook only does some logging.
We are running Radiator in docker and I tried a couple of OS variants.
Namely:

* 4.18 on centos 7 (from source) - works flawlessly
* 4.23 on debian (stretch, buster, bullseye) from official deb - fail
* 4.23 on centos 7 (from source) - fail

The error is always the same for 4.23 and not present in 4.18. The
configuration has not been changed, the source installation between
4.18 and 4.23 on centos differes only in the source archive (Radiator
4.18 vs 4.23); all other variables remain the same. Reproducability is
100%.

I hope anyone can tell me if there's a bug or otherwise where I went
wrong. Sanitized Log from a single connection attempt below. As you can
see MSCHAP-V2 is actually successful, but due to the EAP error, which
doesn't seem to make much sense to me, the client is rejected.

Tue Sep 10 13:20:13 2019: DEBUG: Radius::JSON backend is JSON version 2.59
Tue Sep 10 13:20:13 2019: DEBUG: SCTP socket API extensions not available
Tue Sep 10 13:20:13 2019: DEBUG: Finished reading configuration file '/etc/radiator/radius.cfg'
Tue Sep 10 13:20:13 2019: DEBUG: Reading dictionary file '/etc/radiator/dictionary'
Tue Sep 10 13:20:13 2019: INFO: Using Net::SSLeay 1.88 with SSL/TLS library version 0x100020bf (OpenSSL 1.0.2k-fips  26 Jan 2017)
Tue Sep 10 13:20:13 2019: DEBUG: This system is IPv6 capable. IPv6 capability provided by: core
Tue Sep 10 13:20:13 2019: DEBUG: Creating authentication port 0.0.0.0:1812
Tue Sep 10 13:20:13 2019: DEBUG: Creating accounting port 0.0.0.0:1813
Tue Sep 10 13:20:13 2019: NOTICE: Server started: Radiator 4.23 on radiator-test-01
Tue Sep 10 13:20:15 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:15 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:15 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:15 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:15 2019: DEBUG: Handling with EAP: code 2, 0, 32, 1
Tue Sep 10 13:20:15 2019: DEBUG: Response type 1
Tue Sep 10 13:20:15 2019: DEBUG: Initialised SSL library: Net::SSLeay 1.88, OpenSSL 1.0.2k-fips  26 Jan 2017
Tue Sep 10 13:20:15 2019: DEBUG: Radius::AuthFILE  setting EAPTLS_Ciphers to: DEFAULT:!EXPORT:!LOW
Tue Sep 10 13:20:15 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:15 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:15 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:15 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:15 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:15 2019: DEBUG: Handling with EAP: code 2, 1, 295, 25
Tue Sep 10 13:20:15 2019: DEBUG: Response type 25
Tue Sep 10 13:20:15 2019: DEBUG: EAP TLS SSL_accept result: -1, 2, 8592
Tue Sep 10 13:20:15 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:15 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:15 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:15 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:15 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:15 2019: DEBUG: Handling with EAP: code 2, 2, 6, 25
Tue Sep 10 13:20:15 2019: DEBUG: Response type 25
Tue Sep 10 13:20:15 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:15 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 3, 6, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 4, 6, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 5, 6, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 6, 6, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 7, 328, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP TLS SSL_accept result: 1, 0, 3
Tue Sep 10 13:20:16 2019: DEBUG: EAP PEAP TLS Session accepted: TLSv1.2 AES256-GCM-SHA384
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 8, 6, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 9, 62, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP PEAP inner authentication request for anonymous@<REDACTED>
Tue Sep 10 13:20:16 2019: DEBUG: PEAP Tunnelled request Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'TunnelledByPEAP=1,EAP-Message=/<REDACTED>/i', Identifier ''
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthLDAP2: authby-withoutrealm
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 9, 31, 1
Tue Sep 10 13:20:16 2019: DEBUG: Response type 1
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP MSCHAP-V2 Challenge
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy LDAP2 result: CHALLENGE, EAP MSCHAP-V2 Challenge
Tue Sep 10 13:20:16 2019: DEBUG: entering authloghook
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP MSCHAP-V2 Challenge
Tue Sep 10 13:20:16 2019: DEBUG: Returned PEAP tunnelled packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 10, 116, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP PEAP inner authentication request for anonymous@<REDACTED>
Tue Sep 10 13:20:16 2019: DEBUG: PEAP Tunnelled request Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'TunnelledByPEAP=1,EAP-Message=/<REDACTED>/i', Identifier ''
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthLDAP2: authby-withoutrealm
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 10, 85, 26
Tue Sep 10 13:20:16 2019: DEBUG: Response type 26
Tue Sep 10 13:20:16 2019: INFO: Connecting to <REDACTED>
Tue Sep 10 13:20:16 2019: INFO: Connected to <REDACTED>
Tue Sep 10 13:20:16 2019: INFO: Attempting to bind to LDAP server <REDACTED>
Tue Sep 10 13:20:16 2019: DEBUG: LDAP got <REDACTED>
Tue Sep 10 13:20:16 2019: DEBUG: Radius::AuthLDAP2 looks for match with '<USER>' [anonymous@<REDACTED>]
Tue Sep 10 13:20:16 2019: DEBUG: Radius::AuthLDAP2 ACCEPT: : '<USER>' [anonymous@<REDACTED>]
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP MSCHAP V2 Challenge: Success
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy LDAP2 result: CHALLENGE, EAP MSCHAP V2 Challenge: Success
Tue Sep 10 13:20:16 2019: DEBUG: entering authloghook
Tue Sep 10 13:20:16 2019: DEBUG: leaving authloghook
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP MSCHAP V2 Challenge: Success
Tue Sep 10 13:20:16 2019: DEBUG: Returned PEAP tunnelled packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 11, 37, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP PEAP inner authentication request for anonymous@<REDACTED>
Tue Sep 10 13:20:16 2019: DEBUG: PEAP Tunnelled request Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 11, 6, 26
Tue Sep 10 13:20:16 2019: DEBUG: Response type 26
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 1, Unsupported EAP Response 26
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: REJECT, Unsupported EAP Response 26
Tue Sep 10 13:20:16 2019: INFO: Access rejected for anonymous@<REDACTED>: Unsupported EAP Response 26
Tue Sep 10 13:20:16 2019: DEBUG: EAP Failure, elapsed time 0.076625
Tue Sep 10 13:20:16 2019: DEBUG: Returned PEAP tunnelled packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 3, EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: CHALLENGE, EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: Access challenged for anonymous@<REDACTED>: EAP PEAP inner authentication redispatched to a Handler
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:
Tue Sep 10 13:20:16 2019: DEBUG: Handling request with Handler 'Realm=/<REDACTED>/i', Identifier 'RADIUS_PROXY'
Tue Sep 10 13:20:16 2019: DEBUG: SessINTERNAL: Deleting session for anonymous@<REDACTED>, 127.0.0.1,
Tue Sep 10 13:20:16 2019: DEBUG: Handling with Radius::AuthFILE:
Tue Sep 10 13:20:16 2019: DEBUG: Handling with EAP: code 2, 12, 46, 25
Tue Sep 10 13:20:16 2019: DEBUG: Response type 25
Tue Sep 10 13:20:16 2019: DEBUG: EAP Failure, elapsed time 0.196773
Tue Sep 10 13:20:16 2019: DEBUG: EAP result: 1, PEAP Authentication Failure
Tue Sep 10 13:20:16 2019: DEBUG: AuthBy FILE result: REJECT, PEAP Authentication Failure
Tue Sep 10 13:20:16 2019: INFO: Access rejected for anonymous@<REDACTED>: PEAP Authentication Failure
Tue Sep 10 13:20:16 2019: DEBUG: Packet dump:

More information about the radiator mailing list