EAP Auth failing with CVS Head

18 Dec 2007

      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