freeradius and yubikeys
Frederic Van Espen
frederic.ve at gmail.com
Sat May 10 01:04:31 CEST 2014
On Fri, May 9, 2014 at 9:45 PM, Arran Cudbard-Bell
<a.cudbardb at 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
More information about the Freeradius-Users
mailing list