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

Tue Jun 23 22:32:14 CEST 2015

Arran Cudbard-Bell <a.cudbardb at freeradius.org> wrote:
> > please, help me to be sure I understand `radiusd -X' output right way ...
> I agree, it does look like an MTU issue. But that's v2 output, which we no longer support.
> Upgrade to v3.0.x preferably v3.0.x HEAD as I just added a bunch of
> useful debug output, and provide debug output from that.

I have upgraded to freeradius3-3.0.8 (not head since I install it from
ports and it the last one available) and result looks the same ...

PKI used is the one, created during the installation

bellow is the output:

in `radiusd -X' I see this
---[ quotation start ]-------------------------------------------
...
(141) files: Processing radiusGroupName value "ethernet" as a group name
rlm_ldap (ldap): Released connection (24)
(141) files: User is not a member of "bootp"
(141) files: users: Matched entry DEFAULT at line 288
(141) files: EXPAND %{User-Name}, you have came from %{NAS-IP-Address} copper port %{NAS-Port}.
(141) files:    --> jdoe-eap, you have came from 192.168.0.1 copper port 14.
(141)     [files] = ok
rlm_ldap (ldap): Reserved connection (24)
(141) ldap: EXPAND (&(cn=%{%{Stripped-User-Name}:-%{User-Name}})(|(authorizedService=802.1x-mac at xyz)(authorizedService=802.1x-eap at xyz)(authorizedService=802.1x at xyz)))
(141) ldap:    --> (&(cn=jdoe-eap)(|(authorizedService=802.1x-mac at xyz)(authorizedService=802.1x-eap at xyz)(authorizedService=802.1x at xyz)))
(141) ldap: Performing search in "ou=People,dc=xyz" with filter "(&(cn=jdoe-eap)(|(authorizedService=802.1x-mac at xyz)(authorizedService=802.1x-eap at xyz)(authorizedService=802.1x at xyz)))", scope "sub"
(141) ldap: Waiting for search result...
(141) ldap: User object found at DN "uid=jdoe-eap,authorizedService=802.1x-eap at xyz,uid=it-jdoe,ou=People,dc=xyz"
(141) ldap: Processing user attributes
(141) ldap:     control:Password-With-Header += 'jdoe-eap'
(141) ldap:     reply:Tunnel-Type := VLAN
(141) ldap:     reply:Tunnel-Medium-Type := IEEE-802
(141) ldap:     reply:Tunnel-Private-Group-ID := '3495'
rlm_ldap (ldap): Released connection (24)
(141)     [ldap] = updated
(141)     [expiration] = noop
(141)     [logintime] = noop
(141) pap: No {...} in Password-With-Header, re-writing to Cleartext-Password
(141) pap: Removing &control:Password-With-Header
(141) pap: WARNING: Auth-Type already set.  Not setting to PAP
(141)     [pap] = noop
(141)     if (notfound){
(141)     if (notfound) -> FALSE
(141)     if (reject){
(141)     if (reject) -> FALSE
(141)   } # authorize = updated
(141) Found Auth-Type = EAP
(141) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(141)   authenticate {
(141) eap: Expiring EAP session with state 0x6aedf5cd69e3f8dd
(141) eap: Finished EAP session with state 0x6aedf5cd69e3f8dd
(141) eap: Previous EAP request found for state 0x6aedf5cd69e3f8dd, released from the list
(141) eap: Peer sent method TLS (13)
(141) eap: EAP TLS (13)
(141) eap: Calling eap_tls to process EAP data
(141) eap_tls: Authenticate
(141) eap_tls: processing EAP-TLS
(141) eap_tls: Received TLS ACK
(141) eap_tls: Received TLS ACK
(141) eap_tls: ACK handshake fragment handler
(141) eap_tls: eaptls_verify returned 1 
(141) eap_tls: eaptls_process returned 13 
(141) eap: EAP session adding &reply:State = 0x6aedf5cd6ee2f8dd
(141)     [eap] = handled
(141)   } # authenticate = handled
(141) Using Post-Auth-Type Challenge
(141) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(141) Sent Access-Challenge Id 0 from 192.168.0.254:1812 to 192.168.0.1:49205 length 1032
(141)   Reply-Message = 'jdoe-eap, you have came from 192.168.0.1 copper port 14.'
(141)   Tunnel-Type := VLAN
(141)   Tunnel-Medium-Type := IEEE-802
(141)   Tunnel-Private-Group-Id := '3495'
(141)   EAP-Message = 0x010f03790d8000000b33696361746520417574686f7269747982 ...
(141)   Message-Authenticator = 0x00000000000000000000000000000000
(141)   State = 0x6aedf5cd6ee2f8dd653acce97afb91c3
(141) Finished request
Waking up in 0.3 seconds.
Waking up in 4.6 seconds.
(141) <done>: Cleaning up request packet ID 0 with timestamp +1513
Ready to process requests
...
---[ quotation end   ]-------------------------------------------

wpa_supplicant debug shows this:
---[ quotation start ]-------------------------------------------
...
1435088855.951675: EAPOL: Received EAP-Packet frame
1435088855.951676: EAPOL: SUPP_BE entering state REQUEST
1435088855.951677: EAPOL: getSuppRsp
1435088855.951678: EAP: EAP entering state RECEIVED
1435088855.951683: EAP: Received EAP-Request id=106 method=13 vendor=0 vendorMethod=0
1435088855.951685: EAP: EAP entering state METHOD
1435088855.951687: SSL: Received packet(len=889) - Flags 0x80
1435088855.951688: SSL: TLS Message Length: 2867
1435088855.951706: SSL: (where=0x1001 ret=0x1)
1435088855.951708: SSL: SSL_connect:SSLv3 read server hello A
1435088855.951922: 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 Certificate Authority'
1435088855.951932: 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'
1435088855.951934: EAP: Status notification: remote certificate verification (param=success)
1435088855.952016: 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'
1435088855.952020: 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'
1435088855.952302: EAP: Status notification: remote certificate verification (param=success)
1435088855.952308: SSL: (where=0x1001 ret=0x1)
1435088855.952310: SSL: SSL_connect:SSLv3 read server certificate A
1435088855.952395: SSL: (where=0x1001 ret=0x1)
1435088855.952397: SSL: SSL_connect:SSLv3 read server key exchange A
1435088855.952416: SSL: (where=0x1001 ret=0x1)
1435088855.952417: SSL: SSL_connect:SSLv3 read server certificate request A
1435088855.952419: SSL: (where=0x1001 ret=0x1)
1435088855.952420: SSL: SSL_connect:SSLv3 read server done A
1435088855.952506: SSL: (where=0x1001 ret=0x1)
1435088855.952509: SSL: SSL_connect:SSLv3 write client certificate A
1435088855.953325: SSL: (where=0x1001 ret=0x1)
1435088855.953328: SSL: SSL_connect:SSLv3 write client key exchange A
1435088855.955164: SSL: (where=0x1001 ret=0x1)
1435088855.955167: SSL: SSL_connect:SSLv3 write certificate verify A
1435088855.955232: SSL: (where=0x1001 ret=0x1)
1435088855.955234: SSL: SSL_connect:SSLv3 write change cipher spec A
1435088855.955251: SSL: (where=0x1001 ret=0x1)
1435088855.955252: SSL: SSL_connect:SSLv3 write finished A
1435088855.955256: SSL: (where=0x1001 ret=0x1)
1435088855.955257: SSL: SSL_connect:SSLv3 flush data
1435088855.955259: SSL: (where=0x1002 ret=0xffffffff)
1435088855.955260: SSL: SSL_connect:error in SSLv3 read finished A
1435088855.955262: SSL: SSL_connect - want more data
1435088855.955263: SSL: 2651 bytes pending from ssl_out
1435088855.955266: SSL: 2651 bytes left to be sent out (of total 2651 bytes)
1435088855.955267: SSL: sending 1398 bytes, more fragments will follow
1435088855.955269: EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
1435088855.955271: EAP: EAP entering state SEND_RESPONSE
1435088855.955273: EAP: EAP entering state IDLE
1435088855.955274: EAPOL: SUPP_BE entering state RESPONSE
1435088855.955275: EAPOL: txSuppRsp
1435088855.955277: TX EAPOL: dst=01:80:c2:00:00:03
1435088855.955279: TX EAPOL - hexdump(len=1412): 01 00 05 80 
...
1435088885.940665: EAPOL: Received EAP-Packet frame
1435088885.940667: EAPOL: SUPP_BE entering state REQUEST
1435088885.940668: EAPOL: getSuppRsp
1435088885.940669: EAP: EAP entering state RECEIVED
1435088885.940676: EAP: Received EAP-Request id=106 method=13 vendor=0 vendorMethod=0
1435088885.940678: EAP: EAP entering state RETRANSMIT
1435088885.940680: EAP: EAP entering state SEND_RESPONSE
1435088885.940681: EAP: EAP entering state IDLE
1435088885.940682: EAPOL: SUPP_BE entering state RESPONSE
1435088885.940683: EAPOL: txSuppRsp
1435088885.940685: TX EAPOL: dst=01:80:c2:00:00:03
1435088885.940687: TX EAPOL - hexdump(len=1412): 01 ...
...
---[ quotation end   ]-------------------------------------------

MTU tried (inteface is ethernet, not tun) are 1500 and 1250

what am I missing?

-- 
Zeus V. Panchenko				jid:zeus at im.ibs.dn.ua
IT Dpt., I.B.S. LLC					  GMT+2 (EET)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 180 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20150623/ffd5745c/attachment.sig>