"[eap] = reject" after "Calling eap_md5 to process EAP data"
Zeus Panchenko
zeus at ibs.dn.ua
Mon Jul 6 19:56:36 CEST 2015
hi,
I am trying to configure MAC auth by implementing EAP/MD5 as it is described here:
http://wiki.freeradius.org/modules/Rlm_eap#My-Userbase-is-in-LDAP-and-I-want-to-use-EAP-MD5-authentication
FR v.3.0.8 is on FreeBSD 10.1R
supplicant is on FreeBSD 10.1R connected (by wire) to FR wia switch
but something is wrong and I can not understand what ... please help me to see what I do not see ...
as backend I have LDAP and in it, userPassword format is Cleartext-Password (for the sample from the debug bellow it is `00-25-90-D9-76-2C'
as I understand from the debug bellow, I successfully pass authorization but fail to authenticate against eap_md5 ...
why?
---[ quotation start ]-------------------------------------------
Mon Jul 6 20:27:36 2015 : Debug: (0) Received Access-Request Id 200 from 192.168.0.1:49205 to 192.168.0.254:1812 length 137
Mon Jul 6 20:27:36 2015 : Debug: (0) NAS-IP-Address = 192.168.0.1
Mon Jul 6 20:27:36 2015 : Debug: (0) NAS-Port-Type = Ethernet
Mon Jul 6 20:27:36 2015 : Debug: (0) NAS-Port = 14
Mon Jul 6 20:27:36 2015 : Debug: (0) User-Name = '002590d9762c'
Mon Jul 6 20:27:36 2015 : Debug: (0) Acct-Session-Id = '050002C0'
Mon Jul 6 20:27:36 2015 : Debug: (0) Called-Station-Id = '5C-A4-8A-6F-33-C6'
Mon Jul 6 20:27:36 2015 : Debug: (0) Calling-Station-Id = '00-25-90-D9-76-2C'
Mon Jul 6 20:27:36 2015 : Debug: (0) EAP-Message = 0x0200001101303032353930643937363263
Mon Jul 6 20:27:36 2015 : Debug: (0) Message-Authenticator = 0xa54f71eb9a3b95ad330025032c88cedb
Mon Jul 6 20:27:36 2015 : Debug: (0) session-state: No State attribute
Mon Jul 6 20:27:36 2015 : Debug: (0) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Jul 6 20:27:36 2015 : Debug: (0) authorize {
Mon Jul 6 20:27:36 2015 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0
Mon Jul 6 20:27:36 2015 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0
Mon Jul 6 20:27:36 2015 : Debug: (0) [preprocess] = ok
Mon Jul 6 20:27:36 2015 : Debug: (0) policy rewrite_called_station_id {
...
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: User object found at DN "uid=00-25-90-D9-76-2C,authorizedService=802.1x-mac at xyz,uid=jdoe,ou=People,dc=xyz"
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: Processing user attributes
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: control:Cleartext-Password += '00-25-90-D9-76-2C'
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: control:Password-With-Header += '00-25-90-D9-76-2C'
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Service-Type := Framed-User
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Tunnel-Type := VLAN
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Tunnel-Medium-Type := IEEE-802
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: reply:Tunnel-Private-Group-Id := 'VLAN3499'
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: Attribute "radiusCheckAttributes" not found in LDAP object
Mon Jul 6 20:27:36 2015 : Debug: (1) ldap: Attribute "radiusReplyAttributes" not found in LDAP object
Mon Jul 6 20:27:36 2015 : Debug: rlm_ldap (ldap): Released connection (4)
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from ldap (rlm_ldap) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [ldap] = updated
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Peer sent code Response (2) ID 1 length 34
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [eap] = updated
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling files (rlm_files) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) files: Searching for user in group "disabled"
...
Mon Jul 6 20:27:36 2015 : Debug: (1) files: User is not a member of "disabled"
Mon Jul 6 20:27:36 2015 : Debug: (1) files: Searching for user in group "auth-mac"
...
Mon Jul 6 20:27:36 2015 : Debug: (1) files: EXPAND (&(radiusGroupName=auth-mac)(|(&(cn=%{%{Stripped-User-Name}:-%{Calling-Station-Id}})(|(authorizedService=802.1x at xyz)(authorizedService=802.1x-mac at xyz)))(&(cn=%{User-Name})(authorizedService=802.1x-eap-tls at xyz)))(|(cn=%{Stripped-User-Name})(cn=%{User-Name})(cn=%{Calling-Station-Id})))-76-2C)(|(authorizedService=802.1x at xyz)(authorizedService=802.1x-mac at xyz)))(&(cn=002590d9762c)(authorizedService=802.1x-eap-tls at xyz)))(|(cn=)(cn=002590d9762c)(cn=00-25-90-D9-76-2C))) EXPAND TMPL LITERAL
Mon Jul 6 20:27:36 2015 : Debug: (1) files: Performing search in "ou=People,dc=xyz" with filter "(&(radiusGroupName=auth-mac)(|(&(cn=00-25-90-D9-76-2C)(|(authorizedService=802.1x at xyz)(authorizedService=802.1x-mac at xyz)))(&(cn=002590d9762c)(authorizedService=802.1x-eap-tls at xyz)))(|(cn=)(cn=002590d9762c)(cn=00-25-90-D9-76-2C)))", scope "sub"
Mon Jul 6 20:27:36 2015 : Debug: (1) files: User found in group object "ou=People,dc=xyz"
Mon Jul 6 20:27:36 2015 : Debug: rlm_ldap (ldap): Released connection (4)
Mon Jul 6 20:27:36 2015 : Debug: (1) files: users: Matched entry DEFAULT at line 238
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: FROM 2 TO 4 MAX 6
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: Examining Reply-Message
Mon Jul 6 20:27:36 2015 : Debug: %{User-Name}, you are comming as MAC Auth object.
Mon Jul 6 20:27:36 2015 : Debug: Parsed xlat tree:
Mon Jul 6 20:27:36 2015 : Debug: attribute --> User-Name
Mon Jul 6 20:27:36 2015 : Debug: literal --> , you are comming as MAC Auth object.
Mon Jul 6 20:27:36 2015 : Debug: (1) files: EXPAND %{User-Name}, you are comming as MAC Auth object.
Mon Jul 6 20:27:36 2015 : Debug: (1) files: --> 002590d9762c, you are comming as MAC Auth object.
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: APPENDING Reply-Message FROM 0 TO 4
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: Examining Fall-Through
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: APPENDING Fall-Through FROM 1 TO 5
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: TO in 4 out 6
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[0] = Service-Type
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[1] = Tunnel-Type
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[2] = Tunnel-Medium-Type
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[3] = Tunnel-Private-Group-Id
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[4] = Reply-Message
Mon Jul 6 20:27:36 2015 : Debug: (1) files: ::: to[5] = Fall-Through
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from files (rlm_files) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [files] = ok
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling expiration (rlm_expiration) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from expiration (rlm_expiration) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [expiration] = noop
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: calling logintime (rlm_logintime) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authorize]: returned from logintime (rlm_logintime) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [logintime] = noop
Mon Jul 6 20:27:36 2015 : Debug: (1) if (notfound){
Mon Jul 6 20:27:36 2015 : Debug: (1) if (notfound) -> FALSE
Mon Jul 6 20:27:36 2015 : Debug: (1) if (reject){
Mon Jul 6 20:27:36 2015 : Debug: (1) if (reject) -> FALSE
Mon Jul 6 20:27:36 2015 : Debug: (1) } # authorize = updated
Mon Jul 6 20:27:36 2015 : Debug: (1) Found Auth-Type = EAP
Mon Jul 6 20:27:36 2015 : Debug: (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Jul 6 20:27:36 2015 : Debug: (1) authenticate {
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Expiring EAP session with state 0xeb89e5b7eb88e1eb
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Finished EAP session with state 0xeb89e5b7eb88e1eb
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Previous EAP request found for state 0xeb89e5b7eb88e1eb, released from the list
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Peer sent method MD5 (4)
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: EAP MD5 (4)
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Calling eap_md5 to process EAP data
Mon Jul 6 20:27:36 2015 : Debug: (1) eap: Freeing handler
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [eap] = reject
Mon Jul 6 20:27:36 2015 : Debug: (1) } # authenticate = reject
Mon Jul 6 20:27:36 2015 : Debug: (1) Failed to authenticate the user
Mon Jul 6 20:27:36 2015 : Debug: (1) Using Post-Auth-Type Reject
...
Mon Jul 6 20:27:36 2015 : Debug: (1) Post-Auth-Type REJECT {
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 1
Mon Jul 6 20:27:36 2015 : Debug: %{User-Name}
Mon Jul 6 20:27:36 2015 : Debug: Parsed xlat tree:
Mon Jul 6 20:27:36 2015 : Debug: attribute --> User-Name
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: EXPAND %{User-Name}
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: --> 002590d9762c
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Matched entry DEFAULT at line 17
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Service-Type" allowed by 0 rules, disallowed by 0 rules
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Type" allowed by 0 rules, disallowed by 0 rules
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Medium-Type" allowed by 0 rules, disallowed by 0 rules
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Private-Group-Id" allowed by 0 rules, disallowed by 0 rules
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Reply-Message = '002590d9762c, you are comming as MAC Auth object.' allowed by Reply-Message =* ''
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Reply-Message" allowed by 1 rules, disallowed by 0 rules
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: EAP-Message = 0x04010004 allowed by EAP-Message =* 0x
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x
Mon Jul 6 20:27:36 2015 : Debug: (1) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [attr_filter.access_reject] = updated
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: calling eap (rlm_eap) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) modsingle[post-auth]: returned from eap (rlm_eap) for request 1
Mon Jul 6 20:27:36 2015 : Debug: (1) [eap] = noop
Mon Jul 6 20:27:36 2015 : Debug: (1) policy remove_reply_message_if_eap {
Mon Jul 6 20:27:36 2015 : Debug: (1) if (&reply:EAP-Message && &reply:Reply-Message) {
Mon Jul 6 20:27:36 2015 : Debug: (1) if (&reply:EAP-Message && &reply:Reply-Message) -> TRUE
Mon Jul 6 20:27:36 2015 : Debug: (1) if (&reply:EAP-Message && &reply:Reply-Message) {
Mon Jul 6 20:27:36 2015 : Debug: (1) update reply {
Mon Jul 6 20:27:36 2015 : Debug: (1) &Reply-Message !* ANY
Mon Jul 6 20:27:36 2015 : Debug: (1) } # update reply = noop
Mon Jul 6 20:27:36 2015 : Debug: (1) } # if (&reply:EAP-Message && &reply:Reply-Message) = noop
Mon Jul 6 20:27:36 2015 : Debug: (1) ... skipping else for request 1: Preceding "if" was taken
Mon Jul 6 20:27:36 2015 : Debug: (1) } # policy remove_reply_message_if_eap = noop
Mon Jul 6 20:27:36 2015 : Debug: (1) } # Post-Auth-Type REJECT = updated
Mon Jul 6 20:27:36 2015 : Debug: (1) Delaying response for 1.000000 seconds
Mon Jul 6 20:27:36 2015 : Debug: Waking up in 0.3 seconds.
Mon Jul 6 20:27:36 2015 : Debug: Waking up in 0.6 seconds.
---[ quotation end ]-------------------------------------------
--
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/20150706/b30326bf/attachment-0001.sig>
More information about the Freeradius-Users
mailing list