EAP Auth failing with CVS Head
Arran Cudbard-Bell
A.Cudbard-Bell at sussex.ac.uk
Tue Dec 18 15:25:04 CET 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 at sussex.ac.uk)
Authentication, Authorisation and Accounting Officer
Infrastructure Services | ENG1 E1-1-08
University Of Sussex, Brighton
EXT:01273 873900 | INT: 3900
More information about the Freeradius-Users
mailing list