Hi, EAP Auth appears to be failing for no reason with CVS head. It probably has something to do with " rlm_eap: Request found, released from the list rlm_eap: Response appears to match, but EAP type is wrong. rlm_eap: Failed in handler" and the random "Failed to remember handler" errors in the latter part of the eap conversation. Stripped out all the auth stuff, as nothing interestings happening there. rad_recv: Access-Request packet from host 139.184.9.177 port 1024, id=172, length=205 Framed-MTU = 1480 NAS-IP-Address = 139.184.9.177 NAS-Identifier = "hp-e-lh-opp2-sw1" User-Name = "az50" Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 32 NAS-Port-Type = Ethernet NAS-Port-Id = "32" Called-Station-Id = "00-16-35-15-d9-00" Calling-Station-Id = "00-30-4f-13-c0-d5" Connect-Info = "CONNECT Ethernet 10Mbps Half duplex" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "700" EAP-Message = 0x02c9000901617a3530 Message-Authenticator = 0x05c64e6b0dac8c846e05d9b1fd5fa85b rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: EAP Identity rlm_eap: processing type tls rlm_eap_tls: Initiate rlm_eap_tls: Start returned 1 ++[eap] returns handled } # server default-outer Sending Access-Challenge of id 172 to 139.184.9.177 port 1024 EAP-Message = 0x01ca00061920 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x000000000000000000000000000000ca Finished request 4652. Going to the next request Waking up in 0.9 seconds. rad_recv: Access-Request packet from host 139.184.9.177 port 1024, id=173, length=326 Framed-MTU = 1480 NAS-IP-Address = 139.184.9.177 NAS-Identifier = "hp-e-lh-opp2-sw1" User-Name = "az50" Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 32 NAS-Port-Type = Ethernet NAS-Port-Id = "32" Called-Station-Id = "00-16-35-15-d9-00" Calling-Station-Id = "00-30-4f-13-c0-d5" Connect-Info = "CONNECT Ethernet 10Mbps Half duplex" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "700" State = 0x000000000000000000000000000000ca EAP-Message = 0x02ca007019800000006616030100610100005d03014767d5da7a32145e74125d7a71e8160a090 Message-Authenticator = 0x17dabfdeff86fc11cf9b67b4cb4a79f7 rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: Request found, released from the list rlm_eap: EAP/peap rlm_eap: processing type peap rlm_eap_peap: Authenticate rlm_eap_tls: processing TLS TLS Length 102 rlm_eap_tls: Length Included eaptls_verify returned 11 (other): before/accept initialization TLS_accept: before/accept initialization rlm_eap_tls: <<< TLS 1.0 Handshake [length 0061], ClientHello TLS_accept: SSLv3 read client hello A rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello TLS_accept: SSLv3 write server hello A rlm_eap_tls: >>> TLS 1.0 Handshake [length 0387], Certificate TLS_accept: SSLv3 write certificate A rlm_eap_tls: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone TLS_accept: SSLv3 write server done A TLS_accept: SSLv3 flush data TLS_accept: Need to read more data: SSLv3 read client certificate A In SSL Handshake Phase In SSL Accept mode eaptls_process returned 13 rlm_eap_peap: EAPTLS_HANDLED ++[eap] returns handled } # server default-outer Sending Access-Challenge of id 173 to 139.184.9.177 port 1024 EAP-Message = 0x01cb03ea1900160301004a0200004603014767d4ca221348ec33831b5e1237d96758443c78cc6 EAP-Message = 0x69636174696f6e205365727669636573204469766973696f6e3121301f0603550403131854686 EAP-Message = 0x7365782e61632e756b30819f300d06092a864886f70d010101050003818d0030818902818100b EAP-Message = 0x74655072656d69756d53657276657243412e63726c303206082b0601050507010104263024302 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x000000000000000000000000000000cb Finished request 4653. Going to the next request Waking up in 0.9 seconds. rad_recv: Access-Request packet from host 139.184.9.177 port 1024, id=174, length=406 Framed-MTU = 1480 NAS-IP-Address = 139.184.9.177 NAS-Identifier = "hp-e-lh-opp2-sw1" User-Name = "az50" Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 32 NAS-Port-Type = Ethernet NAS-Port-Id = "32" Called-Station-Id = "00-16-35-15-d9-00" Calling-Station-Id = "00-30-4f-13-c0-d5" Connect-Info = "CONNECT Ethernet 10Mbps Half duplex" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "700" State = 0x000000000000000000000000000000cb EAP-Message = 0x02cb00c01980000000b61603010086100000820080903b024e4ef1444d865b3ba9fe889d55c51 Message-Authenticator = 0xbb7239c8e5207baf3ee395e1cbd00ed9 rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: Request found, released from the list rlm_eap: EAP/peap rlm_eap: processing type peap rlm_eap_peap: Authenticate rlm_eap_tls: processing TLS TLS Length 182 rlm_eap_tls: Length Included eaptls_verify returned 11 rlm_eap_tls: <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange TLS_accept: SSLv3 read client key exchange A rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001] rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished TLS_accept: SSLv3 read finished A rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001] TLS_accept: SSLv3 write change cipher spec A rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished TLS_accept: SSLv3 write finished A TLS_accept: SSLv3 flush data (other): SSL negotiation finished successfully SSL Connection Established eaptls_process returned 13 rlm_eap_peap: EAPTLS_HANDLED ++[eap] returns handled } # server default-outer Sending Access-Challenge of id 174 to 139.184.9.177 port 1024 EAP-Message = 0x01cc003119001403010001011603010020944b4cc1d4e768a91014c75284543d28f718dc21594 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x000000000000000000000000000000cc Finished request 4654. Going to the next request Waking up in 0.9 seconds. rad_recv: Access-Request packet from host 139.184.9.177 port 1024, id=175, length=220 Framed-MTU = 1480 NAS-IP-Address = 139.184.9.177 NAS-Identifier = "hp-e-lh-opp2-sw1" User-Name = "az50" Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 32 NAS-Port-Type = Ethernet NAS-Port-Id = "32" Called-Station-Id = "00-16-35-15-d9-00" Calling-Station-Id = "00-30-4f-13-c0-d5" Connect-Info = "CONNECT Ethernet 10Mbps Half duplex" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "700" State = 0x000000000000000000000000000000cc EAP-Message = 0x02cc00061900 Message-Authenticator = 0x8fd36e4dd5036fb3db8f1c51d3be8504 server default-outer { rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: Request found, released from the list rlm_eap: EAP/peap rlm_eap: processing type peap rlm_eap_peap: Authenticate rlm_eap_tls: processing TLS rlm_eap_tls: Received EAP-TLS ACK message rlm_eap_tls: ack handshake is finished eaptls_verify returned 3 eaptls_process returned 3 rlm_eap_peap: EAPTLS_SUCCESS ++[eap] returns handled } # server default-outer Sending Access-Challenge of id 175 to 139.184.9.177 port 1024 EAP-Message = 0x01cd002019001703010015e57797d900ee292b962234b6f37d92cb3f85c18f61 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x000000000000000000000000000000cd Finished request 4655. Going to the next request Waking up in 0.8 seconds. rad_recv: Access-Request packet from host 139.184.9.177 port 1024, id=176, length=246 Framed-MTU = 1480 NAS-IP-Address = 139.184.9.177 NAS-Identifier = "hp-e-lh-opp2-sw1" User-Name = "az50" Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 32 NAS-Port-Type = Ethernet NAS-Port-Id = "32" Called-Station-Id = "00-16-35-15-d9-00" Calling-Station-Id = "00-30-4f-13-c0-d5" Connect-Info = "CONNECT Ethernet 10Mbps Half duplex" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "700" State = 0x000000000000000000000000000000cd EAP-Message = 0x02cd002019001703010015e7034ffdee4ee0731618f96749b903e144d03fa5b6 Message-Authenticator = 0x03b0c8eb9f3f7134743039eee658ac84 rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: Request found, released from the list rlm_eap: EAP/peap rlm_eap: processing type peap rlm_eap_peap: Authenticate rlm_eap_tls: processing TLS eaptls_verify returned 7 rlm_eap_tls: Done initial handshake eaptls_process returned 7 rlm_eap_peap: EAPTLS_OK rlm_eap_peap: Session established. Decoding tunneled attributes. rlm_eap_peap: Identity - az50 PEAP: Got tunneled EAP-Message EAP-Message = 0x02cd000901617a3530 PEAP: Got tunneled identity of az50 PEAP: Setting default EAP type for tunneled EAP session. PEAP: Setting User-Name to az50 PEAP: Sending tunneled request EAP-Message = 0x02cd000901617a3530 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "az50" Framed-MTU = 1480 NAS-IP-Address = 139.184.9.177 NAS-Identifier = "hp-e-lh-opp2-sw1" Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 32 NAS-Port-Type = Ethernet NAS-Port-Id = "32" Called-Station-Id = "00163515d900" Calling-Station-Id = "00304f13c0d5" Connect-Info = "CONNECT Ethernet 10Mbps Half duplex" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "700" Called-Station-SSID = "" SS-Flags = "0100000000" NAS-Flags = "010000110000000" Supplicant-Flags = "0000000000" server default-inner { +- entering group authorize ++? if (("%{User-Name}" =~ /([^-]+)-emergency-/) || ("%{User-Name}" =~ /\\\\?([^@\\\\]+)@?([-[:alnum: expand: %{User-Name} -> az50 ?? Evaluating ("%{User-Name}" =~ /([^-]+)-emergency-/) -> FALSE expand: %{User-Name} -> az50 ?? Evaluating ("%{User-Name}" =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) -> TRUE ++? if (("%{User-Name}" =~ /([^-]+)-emergency-/) || ("%{User-Name}" =~ /\\\\?([^@\\\\]+)@?([-[:alnum: ++- entering if (("%{User-Name}" =~ /([^-]+)-emergency-/) || ("%{User-Name}" =~ /\\\\?([^@\\\\]+)@?([ +++? if (!"%{2}"||("%{2}" == 'sussex.ac.uk')) expand: %{2} -> ? Evaluating "" -> TRUE ? Skipping ("%{2}" == "sussex.ac.uk") +++? if (!"%{2}"||("%{2}" == 'sussex.ac.uk')) -> TRUE +++- entering if (!"%{2}"||("%{2}" == 'sussex.ac.uk')) expand: %{1} -> az50 ++++[request] returns notfound +++- if (!"%{2}"||("%{2}" == 'sussex.ac.uk')) returns notfound +++ ... skipping else for request 4656: Preceding "if" was taken ++- if (("%{User-Name}" =~ /([^-]+)-emergency-/) || ("%{User-Name}" =~ /\\\\?([^@\\\\]+)@?([-[:alnum: ++ ... skipping else for request 4656: Preceding "if" was taken rlm_ldap: - authorize rlm_ldap: performing user authorization for az50 expand: %{Stripped-User-Name} -> az50 expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=az50) expand: ou=unix ,ou=uscs, o=University of Sussex -> ou=unix ,ou=uscs, o=University of Sussex rlm_ldap: ldap_get_conn: Checking Id: 0 rlm_ldap: ldap_get_conn: Got Id: 0 rlm_ldap: performing search in ou=unix ,ou=uscs, o=University of Sussex, with filter (uid=az50) rlm_ldap: checking if remote access for az50 is allowed by uosRadiusAccountEnabled rlm_ldap: Added Crypt-Password = xxxxxx in check items rlm_ldap: looking for check items in directory... rlm_ldap: LDAP attribute ntPassword as RADIUS attribute NT-Password == xxxxxxx rlm_ldap: looking for reply items in directory... WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correc rlm_ldap: user az50 authorized to use remote access rlm_ldap: ldap_release_conn: Release Id: 0 ++[ldap] returns ok ++? if ("%{Service-Type}" != 'Authenticate-Only') expand: %{Service-Type} -> Framed-User ? Evaluating ("%{Service-Type}" != 'Authenticate-Only') -> TRUE ++? if ("%{Service-Type}" != 'Authenticate-Only') -> TRUE ++- entering if ("%{Service-Type}" != 'Authenticate-Only') expand: %{Stripped-User-Name} -> az50 expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> az50 rlm_sql (sql): sql_set_user escaped user --> 'az50' rlm_sql (sql): Reserving sql socket id: 24 expand: SELECT id, username, attribute, value, op FROM radcheck WHERE use expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-N rlm_sql (sql): Released sql socket id: 24 rlm_sql (sql): User az50 not found +++[sql] returns notfound ++- if ("%{Service-Type}" != 'Authenticate-Only') returns notfound expand: %{Stripped-User-Name} -> az50 expand: %{%{Stripped-User-Name}:-%{User-Name}} -> az50 users: Matched entry DEFAULT at line 55 expand: %{Framed-MTU} -> 1480 expand: %{%{Framed-MTU}:-1400}} -> 1480} users: Matched entry DEFAULT at line 63 expand: %{SS-Flags} -> 0100000000 users: Matched entry DEFAULT at line 126 expand: %{Stripped-User-Name} -> az50 expand: %{NAS-Identifier} -> hp-e-lh-opp2-sw1 expand: %{Called-Station-SSID} -> expand: User %{%{Stripped-User-Name}:-%{User-Name}} authenticated for ResNet access on NAS:% ++[files] returns ok rlm_eap: EAP packet type response id 205 length 9 rlm_eap: No EAP Start, assuming it's an on-going EAP conversation ++[eap] returns updated ++[mschap] returns noop rlm_pap: Found existing Auth-Type, not changing it. ++[pap] returns noop rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: EAP Identity rlm_eap: processing type mschapv2 rlm_eap_mschapv2: Issuing Challenge ++[eap] returns handled } # server default-inner PEAP: Got tunneled reply RADIUS code 11 Service-Type = Framed-User Framed-MTU = 1480 Framed-Routing = None Framed-Protocol = PPP Framed-Compression = Van-Jacobson-TCP-IP Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "603" Reply-Message = "User az50 authenticated for ResNet access on NAS:hp-e-lh-opp2-sw1 SSID:none EAP-Message = 0x01ce001e1a01ce001910d42070cc55ce5df2a45a688b493da789617a3530 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x000000000000000000000000000000ce PEAP: Processing from tunneled session code 0x3cd370 11 Service-Type = Framed-User Framed-MTU = 1480 Framed-Routing = None Framed-Protocol = PPP Framed-Compression = Van-Jacobson-TCP-IP Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "603" Reply-Message = "User az50 authenticated for ResNet access on NAS:hp-e-lh-opp2-sw1 SSID:none EAP-Message = 0x01ce001e1a01ce001910d42070cc55ce5df2a45a688b493da789617a3530 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x000000000000000000000000000000ce PEAP: Got tunneled Access-Challenge rlm_eap: Failed to remember handler! ++[eap] returns handled } # server default-outer Sending Access-Challenge of id 176 to 139.184.9.177 port 1024 EAP-Message = 0x01ce00351900170301002a1f3ece511d49e35f24c46327f02a781c1d7b4b7fb1b74b4b613e671 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x000000000000000000000000000000ce Finished request 4656. Going to the next request Waking up in 0.8 seconds. rad_recv: Access-Request packet from host 139.184.9.177 port 1024, id=177, length=300 Framed-MTU = 1480 NAS-IP-Address = 139.184.9.177 NAS-Identifier = "hp-e-lh-opp2-sw1" User-Name = "az50" Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 32 NAS-Port-Type = Ethernet NAS-Port-Id = "32" Called-Station-Id = "00-16-35-15-d9-00" Calling-Station-Id = "00-30-4f-13-c0-d5" Connect-Info = "CONNECT Ethernet 10Mbps Half duplex" Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "700" State = 0x000000000000000000000000000000ce EAP-Message = 0x02ce00561900170301004bd3fc0b2ab96fbcceb05f1a3ad2ce073af9eb3df121ac4de457cbf72 Message-Authenticator = 0x7118ed090c49f2cb7633ff8477649ca4 rad_check_password: Found Auth-Type EAP auth: type "EAP" +- entering group authenticate rlm_eap: Request found, released from the list rlm_eap: Response appears to match, but EAP type is wrong. rlm_eap: Failed in handler ++[eap] returns invalid auth: Failed to validate the user. } # server default-outer Found Post-Auth-Type Reject +- entering group REJECT rlm_sql (sql): Processing sql_postauth expand: %{Stripped-User-Name} -> az50 expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> az50 rlm_sql (sql): sql_set_user escaped user --> 'az50' expand: INSERT INTO radpostauth (`us' rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth ' rlm_sql (sql): Reserving sql socket id: 23 rlm_sql (sql): Released sql socket id: 23 ++[sql] returns ok expand: %{User-Name} -> az50 attr_filter: Matched entry DEFAULT at line 11 ++[attr_filter.access_reject] returns updated rlm_sql (sql_roaming): Processing sql_postauth expand: %{Stripped-User-Name} -> az50 expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> az50 rlm_sql (sql_roaming): sql_set_user escaped user --> 'az50' expand: %{NAS-Port} -> 32 expand: INSERT INTO roaming_events (`uid`, `hw_address`,`event_typ rlm_sql (sql_roaming) in sql_postauth: query is INSERT INTO roaming_events rlm_sql (sql_roaming): Reserving sql socket id: 3 rlm_sql (sql_roaming): Released sql socket id: 3 ++[sql_roaming] returns ok Delaying reject of request 4657 for 1 seconds Going to the next request Waking up in 0.8 seconds. -- Arran Cudbard-Bell (A.Cudbard-Bell@sussex.ac.uk) Authentication, Authorisation and Accounting Officer Infrastructure Services | ENG1 E1-1-08 University Of Sussex, Brighton EXT:01273 873900 | INT: 3900