radiusd debug understanding help needed (EAP session for state 0x... did not finish)

Thu Jun 25 14:32:10 CEST 2015

> On 25 Jun 2015, at 03:52, Zeus Panchenko <zeus at ibs.dn.ua> wrote:
> 
> Signed PGP part
> Arran Cudbard-Bell <a.cudbardb at freeradius.org> wrote:
> >
> > Upgrade to v3.0.x HEAD as I just added a bunch of useful debug output, and provide the debug output from that.
> >
> 
> I have upgraded to the rev 627f748a0f
> 
> > radiusd -v
> radiusd: FreeRADIUS Version 3.0.9, for host amd64-portbld-freebsd10.1, built on Jun 24 2015 at 11:20:18
> 
> 
> test shows the same behaviour :(
> since overal size of debug is rather big, I uploaded it to dropbox, here is URL:
> 
> https://www.dropbox.com/sh/ts63g3iv4ckwsof/AADkbTFJGUvqbvGlN9gSFXaSa?dl=0

I answered you off list yesterday...

The other issue you may want to look for is whether IP fragmentation is being performed correctly, so you'll
need PCAPs from the AP and intermediary routers up to the RADIUS server.

For the benefit of the list users, here's my original response:

Mmm, but with better debugging. The key bits of extra info, are the flags set in the EAP-TLS fragments, the indicated size and actual size of the fragments, and the incoming/outgoing EAP packet IDs.

The key with MTU issues is to look at the last request/response between the supplicant. Usually you'll see a packet go out from the server, and never reach the supplicant, or a packet be sent by the supplicant and never reach the server.

In this case it's the supplicant's fragment not reaching the server. We see it respond to the EAP request with ID 153, by packing up the first fragment of its certificate chain, and sending it.

The size of that fragment, is pretty big, 1398 bytes. I think only fragments up to 1020 bytes are guaranteed to be handled by the authenticator.

1435137443.632654: EAP: EAP entering state RECEIVED
1435137443.632657: EAP: Received EAP-Request id=154 method=13 vendor=0 vendorMethod=0
1435137443.632659: EAP: EAP entering state METHOD
1435137443.632660: SSL: Received packet(len=889) - Flags 0x80
1435137443.632661: SSL: TLS Message Length: 2867
1435137443.632685: SSL: (where=0x1001 ret=0x1)
1435137443.632686: SSL: SSL_connect:SSLv3 read server hello A
1435137443.632988: TLS: tls_verify_cb - preverify_ok=1 err=0 (ok) ca_cert_verify=1 depth=1 buf='/C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress=admin at example.com/CN=Example Certificat
e Authority'
1435137443.632996: igb0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress=admin at example.com/CN=Example Certificate Authority'
1435137443.632999: EAP: Status notification: remote certificate verification (param=success)
1435137443.633114: TLS: tls_verify_cb - preverify_ok=1 err=0 (ok) ca_cert_verify=1 depth=0 buf='/C=FR/ST=Radius/O=Example Inc./CN=Example Server Certificate/emailAddress=admin at example.com'
1435137443.633120: igb0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/C=FR/ST=Radius/O=Example Inc./CN=Example Server Certificate/emailAddress=admin at example.com'
1435137443.633297: EAP: Status notification: remote certificate verification (param=success)
1435137443.633307: SSL: (where=0x1001 ret=0x1)
1435137443.633309: SSL: SSL_connect:SSLv3 read server certificate A
1435137443.633421: SSL: (where=0x1001 ret=0x1)
1435137443.633423: SSL: SSL_connect:SSLv3 read server key exchange A
1435137443.633444: SSL: (where=0x1001 ret=0x1)
1435137443.633446: SSL: SSL_connect:SSLv3 read server certificate request A
1435137443.633447: SSL: (where=0x1001 ret=0x1)
1435137443.633449: SSL: SSL_connect:SSLv3 read server done A
1435137443.633541: SSL: (where=0x1001 ret=0x1)
1435137443.633544: SSL: SSL_connect:SSLv3 write client certificate A
1435137443.634368: SSL: (where=0x1001 ret=0x1)
1435137443.634372: SSL: SSL_connect:SSLv3 write client key exchange A
1435137443.636241: SSL: (where=0x1001 ret=0x1)
1435137443.636245: SSL: SSL_connect:SSLv3 write certificate verify A
1435137443.636315: SSL: (where=0x1001 ret=0x1)
1435137443.636317: SSL: SSL_connect:SSLv3 write change cipher spec A
1435137443.636336: SSL: (where=0x1001 ret=0x1)
1435137443.636338: SSL: SSL_connect:SSLv3 write finished A
1435137443.636345: SSL: (where=0x1001 ret=0x1)
1435137443.636346: SSL: SSL_connect:SSLv3 flush data
1435137443.636348: SSL: (where=0x1002 ret=0xffffffff)
1435137443.636349: SSL: SSL_connect:error in SSLv3 read finished A
1435137443.636351: SSL: SSL_connect - want more data
1435137443.636353: SSL: 2651 bytes pending from ssl_out
1435137443.636356: SSL: 2651 bytes left to be sent out (of total 2651 bytes)
1435137443.636358: SSL: sending 1398 bytes, more fragments will follow
1435137443.636360: EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
1435137443.636362: EAP: EAP entering state SEND_RESPONSE
1435137443.636363: EAP: EAP entering state IDLE
1435137443.636364: EAPOL: SUPP_BE entering state RESPONSE
1435137443.636365: EAPOL: txSuppRsp
1435137443.636368: TX EAPOL: dst=01:80:c2:00:00:03
1435137443.636370: TX EAPOL - hexdump(len=1412): 01 00 05 80 02 9a 05 80 0d c0 00 00 0a 5b ...

In request 6, we'd expect to see the server receiving that TLS fragment, but we don't. We instead see the supplicant restarting authentication. Looking at the timestamps, probably after timing out receiving a response from the server.

So yes, this is definitely an MTU issue on the path from the Supplicant to the RADIUS server.

I'm guessing as you have wpa_supplicant set to wired, you're doing wired 802.1X? So your switch is junk, and you either need to call the vendor and complain, or get a new switch.

I've seen this exact same problem problem with Meraki access points. There's absolutely nothing you can do to fix it, because there's no MTU negotiation mechanism in EAP, and most supplicants do not expose an MTU control. So a vendor fix is the only option.

The issue only shows up when doing EAP-TLS because all the packets sent supplicant to authenticator for PEAP and TTLS-PAP are relatively small. EAP-TLS however, requires the supplicant to send large chunks of certificate.

Could you provide the make/model of the device (if it really is a switch), or the version if it's a software authenticator, just for my own edification.

If it's software we might be able to submit a patch.

-Arran

Arran Cudbard-Bell <a.cudbardb at freeradius.org>
FreeRADIUS development team

FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 872 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20150625/90938b92/attachment.sig>