On Fri, May 9, 2014 at 9:45 PM, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
Git pull... I haven't fixed anything, but i've added a format marker, so it'll show where in the string it found the non modhex char.
It'll only show up with -Xx because of the policy we introduced about not showing sensitive strings with -X, after a couple of accidental postings of passwords to GitHub and the list.
I tested with your string and it came back fine, so i'm a little confused. Here's my output (with -Xx).
Received Access-Request Id 50 from 127.0.0.1:54741 to 127.0.0.1:1812 length 91 Code: 1 Id: 50 Length: 91 Vector: d6f8b36def2807b39afba22805bd09f5 Data: 01 05 66 6f 6f 02 42 d9 dc 63 29 40 fb 89 6d 8d 9c 24 bf 8b 63 a4 dd e0 72 05 bb 58 38 ab 56 7c 40 ec d8 51 8e 98 49 cd a9 e4 4e 76 1a 53 0c 14 67 29 a2 98 c4 8d ad 1a ce 51 70 e8 bb 44 70 ed ae 8e ff c6 8d 1a 8a User-Name = 'foo' User-Password = 'testingpasswordccccccdbkebjkgfkgdrvthntvckrnifbicgrdgrldigl' Fri May 9 18:40:54 2014 : Debug: (0) # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default Fri May 9 18:40:54 2014 : Debug: (0) authorize { Fri May 9 18:40:54 2014 : Debug: (0) modsingle[authorize]: calling yubikey (rlm_yubikey) for request 0 Fri May 9 18:40:54 2014 : Debug: (0) yubikey : request:Yubikey-OTP := 'ccccccdbkebjkgfkgdrvthntvckrnifbicgrdgrldigl' Fri May 9 18:40:54 2014 : Debug: (0) yubikey : request:User-Password := 'testingpassword' Fri May 9 18:40:54 2014 : Debug: (0) modsingle[authorize]: returned from yubikey (rlm_yubikey) for request 0 Fri May 9 18:40:54 2014 : Debug: (0) [yubikey] = ok
and your debug was was:
Fri May 9 16:41:15 2014 : Debug: (0) yubikey : User-Password (aes-block) value contains non modhex chars
Meaning it found a char outside of "cbdefghijklnrtuv" in the AES block portion, but were using the same string, so I don't see how that works.
Are you sure you did not change anything else? Output is different this time and I'm doing the same thing with the same config. I'm starting it by running "freeradius -Xx" as you suggested. Looks like the authorize section worked correctly (it set Auth-Type to yubikey), but then authentication part fails (BAD_SERVER_SIGNATURE): Received Access-Request Id 222 from 127.0.0.1:33290 to 127.0.0.1:1812 length 121 User-Name = 'fes' User-Password = 'testingpasswordccccccdbkebjebenhetldrkgtbitjlhfhbjnvbhhhiee' NAS-IP-Address = 172.16.35.65 NAS-Port = 0 Message-Authenticator = 0x60e2d3f93d66ace0b8842f7e06c873ee Sat May 10 00:46:30 2014 : Debug: (0) # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat May 10 00:46:30 2014 : Debug: (0) authorize { Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [preprocess] = ok Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: calling yubikey (rlm_yubikey) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) yubikey : request:Yubikey-OTP := 'ccccccdbkebjebenhetldrkgtbitjlhfhbjnvbhhhiee' Sat May 10 00:46:30 2014 : Debug: (0) yubikey : request:User-Password := 'testingpassword' Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: returned from yubikey (rlm_yubikey) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [yubikey] = ok Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Sat May 10 00:46:30 2014 : Debug: rlm_ldap (ldap): Reserved connection (4) Sat May 10 00:46:30 2014 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) Sat May 10 00:46:30 2014 : Debug: Parsed xlat tree: Sat May 10 00:46:30 2014 : Debug: literal --> (uid= Sat May 10 00:46:30 2014 : Debug: if { Sat May 10 00:46:30 2014 : Debug: attribute --> Stripped-User-Name Sat May 10 00:46:30 2014 : Debug: { Sat May 10 00:46:30 2014 : Debug: ref 2 Sat May 10 00:46:30 2014 : Debug: list 1 Sat May 10 00:46:30 2014 : Debug: tag -128 Sat May 10 00:46:30 2014 : Debug: } Sat May 10 00:46:30 2014 : Debug: } Sat May 10 00:46:30 2014 : Debug: else { Sat May 10 00:46:30 2014 : Debug: attribute --> User-Name Sat May 10 00:46:30 2014 : Debug: { Sat May 10 00:46:30 2014 : Debug: ref 2 Sat May 10 00:46:30 2014 : Debug: list 1 Sat May 10 00:46:30 2014 : Debug: tag -128 Sat May 10 00:46:30 2014 : Debug: } Sat May 10 00:46:30 2014 : Debug: } Sat May 10 00:46:30 2014 : Debug: literal --> ) Sat May 10 00:46:30 2014 : Debug: (0) ldap : EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}}) Sat May 10 00:46:30 2014 : Debug: (0) ldap : --> (uid=fes) Sat May 10 00:46:30 2014 : Debug: ou=People,dc=escaux,dc=com Sat May 10 00:46:30 2014 : Debug: Parsed xlat tree: Sat May 10 00:46:30 2014 : Debug: literal --> ou=People,dc=escaux,dc=com Sat May 10 00:46:30 2014 : Debug: (0) ldap : EXPAND ou=People,dc=escaux,dc=com Sat May 10 00:46:30 2014 : Debug: (0) ldap : --> ou=People,dc=escaux,dc=com Sat May 10 00:46:30 2014 : Debug: (0) ldap : Performing search in 'ou=People,dc=escaux,dc=com' with filter '(uid=fes)', scope 'sub' Sat May 10 00:46:30 2014 : Debug: (0) ldap : Waiting for search result... Sat May 10 00:46:30 2014 : Debug: (0) ldap : User object found at DN "uid=fes,ou=People,dc=escaux,dc=com" Sat May 10 00:46:30 2014 : Debug: (0) ldap : Processing user attributes Sat May 10 00:46:30 2014 : Debug: (0) ldap : control:Password-With-Header += ''{CRYPT}$6$rounds=1000$czjqtQQw5Sx6BURM$67zg9ok5r8IVTQNcQkdx1Mbi5A75gbHgt5I3oI/Z038MPg8htLLswallK.ou/r914j/0Tkwyuf92ZHsVg1DTz.'' Sat May 10 00:46:30 2014 : Debug: (0) ldap : Attribute "ntPassword" not found in LDAP object Sat May 10 00:46:30 2014 : Debug: rlm_ldap (ldap): Released connection (4) Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [ldap] = ok Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [expiration] = noop Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [logintime] = noop Sat May 10 00:46:30 2014 : Debug: (0) } # authorize = ok Sat May 10 00:46:30 2014 : Debug: (0) Found Auth-Type = yubikey Sat May 10 00:46:30 2014 : Debug: (0) # Executing group from file /etc/freeradius/sites-enabled/default Sat May 10 00:46:30 2014 : Debug: (0) Auth-Type yubikey { Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authenticate]: calling yubikey (rlm_yubikey) for request 0 Sat May 10 00:46:30 2014 : Debug: rlm_yubikey (yubikey): Reserved connection (4) Sat May 10 00:46:30 2014 : ERROR: (0) yubikey : Server response signature was invalid (BAD_SERVER_SIGNATURE) Sat May 10 00:46:30 2014 : Debug: rlm_yubikey (yubikey): Released connection (4) Sat May 10 00:46:30 2014 : Debug: (0) modsingle[authenticate]: returned from yubikey (rlm_yubikey) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [yubikey] = fail Sat May 10 00:46:30 2014 : Debug: (0) } # Auth-Type yubikey = fail Sat May 10 00:46:30 2014 : Debug: (0) Failed to authenticate the user. Sat May 10 00:46:30 2014 : Debug: (0) Using Post-Auth-Type Reject Sat May 10 00:46:30 2014 : Debug: (0) # Executing group from file /etc/freeradius/sites-enabled/default Sat May 10 00:46:30 2014 : Debug: (0) Post-Auth-Type REJECT { Sat May 10 00:46:30 2014 : Debug: (0) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0 Sat May 10 00:46:30 2014 : Debug: %{User-Name} Sat May 10 00:46:30 2014 : Debug: Parsed xlat tree: Sat May 10 00:46:30 2014 : Debug: attribute --> User-Name Sat May 10 00:46:30 2014 : Debug: { Sat May 10 00:46:30 2014 : Debug: ref 2 Sat May 10 00:46:30 2014 : Debug: list 1 Sat May 10 00:46:30 2014 : Debug: tag -128 Sat May 10 00:46:30 2014 : Debug: } Sat May 10 00:46:30 2014 : Debug: (0) attr_filter.access_reject : EXPAND %{User-Name} Sat May 10 00:46:30 2014 : Debug: (0) attr_filter.access_reject : --> fes Sat May 10 00:46:30 2014 : Debug: (0) attr_filter.access_reject : Matched entry DEFAULT at line 11 Sat May 10 00:46:30 2014 : Debug: (0) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [attr_filter.access_reject] = updated Sat May 10 00:46:30 2014 : Debug: (0) modsingle[post-auth]: calling eap (rlm_eap) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) eap : Request didn't contain an EAP-Message, not inserting EAP-Failure Sat May 10 00:46:30 2014 : Debug: (0) modsingle[post-auth]: returned from eap (rlm_eap) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [eap] = noop Sat May 10 00:46:30 2014 : Debug: (0) remove_reply_message_if_eap remove_reply_message_if_eap { Sat May 10 00:46:30 2014 : Debug: (0) if (reply:EAP-Message && reply:Reply-Message) Sat May 10 00:46:30 2014 : Debug: (0) if (reply:EAP-Message && reply:Reply-Message) -> FALSE Sat May 10 00:46:30 2014 : Debug: (0) else else { Sat May 10 00:46:30 2014 : Debug: (0) modsingle[post-auth]: calling noop (rlm_always) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) modsingle[post-auth]: returned from noop (rlm_always) for request 0 Sat May 10 00:46:30 2014 : Debug: (0) [noop] = noop Sat May 10 00:46:30 2014 : Debug: (0) } # else else = noop Sat May 10 00:46:30 2014 : Debug: (0) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop Sat May 10 00:46:30 2014 : Debug: (0) } # Post-Auth-Type REJECT = updated Sat May 10 00:46:30 2014 : Debug: (0) Delaying response for 1 seconds Sat May 10 00:46:30 2014 : Debug: Waking up in 0.2 seconds. Sat May 10 00:46:30 2014 : Debug: Waking up in 0.7 seconds. Sat May 10 00:46:31 2014 : Debug: (0) Sending delayed response Sending Access-Reject Id 222 from 127.0.0.1:1812 to 127.0.0.1:33290 Sat May 10 00:46:31 2014 : Debug: Waking up in 3.9 seconds. Sat May 10 00:46:35 2014 : Debug: (0) Cleaning up request packet ID 222 with timestamp +14 Sat May 10 00:46:35 2014 : Info: Ready to process requests. Thanks a lot for your time. Frederic