otp over radius preauthentication

Frederic Van Espen frederic.ve at gmail.com
Fri May 9 12:36:39 EDT 2014


Hello Greg,

On Fri, May 9, 2014 at 5:09 PM, Greg Hudson <ghudson at mit.edu> wrote:
> On 05/08/2014 02:50 PM, Frederic Van Espen wrote:
>> May 08 20:43:17 obelix-clone krb5kdc[21126](info): preauth (otp)
>> verify failure: Connection timed out
>> May 08 20:43:17 obelix-clone krb5kdc[21126](info): AS_REQ (6 etypes
>> {18 17 16 23 25 26}) 172.16.35.65: PREAUTH_FAILED:
>> fes at ICT-DEV.ESCAUX.COM for
>> krbtgt/ICT-DEV.ESCAUX.COM at ICT-DEV.ESCAUX.COM, Preauthentication failed
>
> I think this is the root cause of your problem--FreeRADIUS is returning
> successfully, but it's doing so too slowly.
>
> You can try bumping up the "timeout" variable in your [otp] config
> section, or you can try to figure out why FreeRADIUS is taking so long.
>  Five seconds seems like a long time.  There are no timestamps in the
> FreeRADIUS logs, so I can't verify that it's actually taking a long time
> or figure out where it's all being spent.
>


That's what I though too at first but it is not the case. See below
the debugging output and wireshark output ordered sequentially on the
same console. You can see that from the time the packet arrives at
freeradius until the response there is less than one second. The time
between 18:26:58 and 18:27:04 is me typing the user password + OTP.
Only 3 seconds later do we see the timeout in the kdc log:

==> kerberos/krb5kdc.log <==
May 09 18:26:58 obelix-clone krb5kdc[21569](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: NEEDED_PREAUTH:
fes at ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.ESCAUX.COM at ICT-DEV.ESCAUX.COM, Additional
pre-authentication required

18:27:04.570719 172.16.35.65 -> 172.16.35.65 RADIUS 153
Access-Request(1) (id=142, l=111)
==> freeradius/radius.log <==
Fri May  9 18:27:04 2014 : Debug: (0) # Executing section authorize
from file /etc/freeradius/sites-enabled/default
Fri May  9 18:27:04 2014 : Debug: (0)   authorize {
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: returned
from preprocess (rlm_preprocess) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   [preprocess] = ok
Fri May  9 18:27:04 2014 : Debug: (0)    if (User-Password =~
/^(.*)([cbdefghijklnrtuv]{44})$/)
Fri May  9 18:27:04 2014 : Debug: (0) %{0}: Inserting new value
"testingpasswordccccccdbkebjdlhjlurfkdvidbdnvkgukkkvjreduill"
Fri May  9 18:27:04 2014 : Debug: (0) %{1}: Inserting new value
"testingpassword"
Fri May  9 18:27:04 2014 : Debug: (0) %{2}: Inserting new value
"ccccccdbkebjdlhjlurfkdvidbdnvkgukkkvjreduill"
Fri May  9 18:27:04 2014 : Debug: (0) %{3}: Was empty
Fri May  9 18:27:04 2014 : Debug: (0) %{4}: Was empty
Fri May  9 18:27:04 2014 : Debug: (0) %{5}: Was empty
Fri May  9 18:27:04 2014 : Debug: (0) %{6}: Was empty
Fri May  9 18:27:04 2014 : Debug: (0) %{7}: Was empty
Fri May  9 18:27:04 2014 : Debug: (0) %{8}: Was empty
Fri May  9 18:27:04 2014 : Debug: (0)    if (User-Password =~
/^(.*)([cbdefghijklnrtuv]{44})$/)  -> TRUE
Fri May  9 18:27:04 2014 : Debug: (0)   if (User-Password =~
/^(.*)([cbdefghijklnrtuv]{44})$/)  {
Fri May  9 18:27:04 2014 : Debug: (0)    update request {
Fri May  9 18:27:04 2014 : Debug: (0) EXPAND %{2}
Fri May  9 18:27:04 2014 : Debug: (0)    -->
ccccccdbkebjdlhjlurfkdvidbdnvkgukkkvjreduill
Fri May  9 18:27:04 2014 : Debug: (0) User-Password :=
'"ccccccdbkebjdlhjlurfkdvidbdnvkgukkkvjreduill"'
Fri May  9 18:27:04 2014 : Debug: (0)    } # update request = noop
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authenticate]:
calling yubikey (rlm_yubikey) for request 0
Fri May  9 18:27:04 2014 : Debug: (0) yubikey : No Yubikey-OTP
attribute found, falling back to User-Password
Fri May  9 18:27:04 2014 : Debug: rlm_yubikey (yubikey): Reserved connection (4)
Fri May  9 18:27:04 2014 : Debug: rlm_yubikey (yubikey): Released connection (4)
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authenticate]:
returned from yubikey (rlm_yubikey) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)    [yubikey.authenticate] = ok
Fri May  9 18:27:04 2014 : Debug: (0)     if (ok)
Fri May  9 18:27:04 2014 : Debug: (0)     if (ok)  -> TRUE
Fri May  9 18:27:04 2014 : Debug: (0)    if (ok)  {
Fri May  9 18:27:04 2014 : Debug: (0)     update request {
Fri May  9 18:27:04 2014 : Debug: (0) EXPAND %{1}
Fri May  9 18:27:04 2014 : Debug: (0)    --> testingpassword
Fri May  9 18:27:04 2014 : Debug: (0) User-Password := '"testingpassword"'
Fri May  9 18:27:04 2014 : Debug: (0)     } # update request = noop
Fri May  9 18:27:04 2014 : Debug: (0)    } # if (ok)  = noop
Fri May  9 18:27:04 2014 : Debug: (0)   } # if (User-Password =~
/^(.*)([cbdefghijklnrtuv]{44})$/)  = ok
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: calling
ldap (rlm_ldap) for request 0
Fri May  9 18:27:04 2014 : Debug: rlm_ldap (ldap): Reserved connection (4)
Fri May  9 18:27:04 2014 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri May  9 18:27:04 2014 : Debug: Parsed xlat tree:
Fri May  9 18:27:04 2014 : Debug: literal --> (uid=
Fri May  9 18:27:04 2014 : Debug: if {
Fri May  9 18:27:04 2014 : Debug: attribute --> Stripped-User-Name
Fri May  9 18:27:04 2014 : Debug: {
Fri May  9 18:27:04 2014 : Debug: ref  2
Fri May  9 18:27:04 2014 : Debug: list 1
Fri May  9 18:27:04 2014 : Debug: tag -128
Fri May  9 18:27:04 2014 : Debug: }
Fri May  9 18:27:04 2014 : Debug: }
Fri May  9 18:27:04 2014 : Debug: else {
Fri May  9 18:27:04 2014 : Debug: attribute --> User-Name
Fri May  9 18:27:04 2014 : Debug: {
Fri May  9 18:27:04 2014 : Debug: ref  2
Fri May  9 18:27:04 2014 : Debug: list 1
Fri May  9 18:27:04 2014 : Debug: tag -128
Fri May  9 18:27:04 2014 : Debug: }
Fri May  9 18:27:04 2014 : Debug: }
Fri May  9 18:27:04 2014 : Debug: literal --> )
Fri May  9 18:27:04 2014 : Debug: (0) ldap : EXPAND
(uid=%{%{Stripped-User-Name}:-%{User-Name}})
Fri May  9 18:27:04 2014 : Debug: (0) ldap :    --> (uid=fes)
Fri May  9 18:27:04 2014 : Debug: ou=People,dc=escaux,dc=com
Fri May  9 18:27:04 2014 : Debug: Parsed xlat tree:
Fri May  9 18:27:04 2014 : Debug: literal --> ou=People,dc=escaux,dc=com
Fri May  9 18:27:04 2014 : Debug: (0) ldap : EXPAND ou=People,dc=escaux,dc=com
Fri May  9 18:27:04 2014 : Debug: (0) ldap :    --> ou=People,dc=escaux,dc=com
Fri May  9 18:27:04 2014 : Debug: (0) ldap : Performing search in
'ou=People,dc=escaux,dc=com' with filter '(uid=fes)', scope 'sub'
Fri May  9 18:27:04 2014 : Debug: (0) ldap : Waiting for search result...
Fri May  9 18:27:04 2014 : Debug: (0) ldap : User object found at DN
"uid=fes,ou=People,dc=escaux,dc=com"
Fri May  9 18:27:04 2014 : Debug: (0) ldap : Processing user attributes
Fri May  9 18:27:04 2014 : Debug: (0) ldap :
control:Password-With-Header +=
''{CRYPT}$6$rounds=1000$czjqtQQw5Sx6BURM$67zg9ok5r8IVTQNcQkdx1Mbi5A75gbHgt5I3oI/Z038MPg8htLLswallK.ou/r914j/0Tkwyuf92ZHsVg1DTz.''
Fri May  9 18:27:04 2014 : Debug: (0) ldap : Attribute "ntPassword"
not found in LDAP object
Fri May  9 18:27:04 2014 : Debug: rlm_ldap (ldap): Released connection (4)
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: returned
from ldap (rlm_ldap) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   [ldap] = ok
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: calling
expiration (rlm_expiration) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: returned
from expiration (rlm_expiration) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   [expiration] = noop
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: calling
logintime (rlm_logintime) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: returned
from logintime (rlm_logintime) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   [logintime] = noop
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: calling
pap (rlm_pap) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authorize]: returned
from pap (rlm_pap) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   [pap] = updated
Fri May  9 18:27:04 2014 : Debug: (0)  } #  authorize = updated
Fri May  9 18:27:04 2014 : Debug: (0) Found Auth-Type = PAP
Fri May  9 18:27:04 2014 : Debug: (0) # Executing group from file
/etc/freeradius/sites-enabled/default
Fri May  9 18:27:04 2014 : Debug: (0)  Auth-Type PAP {
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authenticate]:
calling pap (rlm_pap) for request 0
Fri May  9 18:27:04 2014 : Debug: (0) pap : Login attempt with
password "testingpassword"
Fri May  9 18:27:04 2014 : Debug: (0) pap : Comparing with "known
good" Crypt-Password
"$6$rounds=1000$czjqtQQw5Sx6BURM$67zg9ok5r8IVTQNcQkdx1Mbi5A75gbHgt5I3oI/Z038MPg8htLLswallK.ou/r914j/0Tkwyuf92ZHsVg1DTz."
Fri May  9 18:27:04 2014 : Debug: (0) pap : User authenticated successfully
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[authenticate]:
returned from pap (rlm_pap) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   [pap] = ok
Fri May  9 18:27:04 2014 : Debug: (0)  } # Auth-Type PAP = ok
Fri May  9 18:27:04 2014 : Debug: (0) # Executing section post-auth
from file /etc/freeradius/sites-enabled/default
Fri May  9 18:27:04 2014 : Debug: (0)   post-auth {
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[post-auth]: calling
exec (rlm_exec) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[post-auth]: returned
from exec (rlm_exec) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   [exec] = noop
Fri May  9 18:27:04 2014 : Debug: (0)   remove_reply_message_if_eap
remove_reply_message_if_eap {
Fri May  9 18:27:04 2014 : Debug: (0)     if (reply:EAP-Message &&
reply:Reply-Message)
Fri May  9 18:27:04 2014 : Debug: (0)     if (reply:EAP-Message &&
reply:Reply-Message)  -> FALSE
Fri May  9 18:27:04 2014 : Debug: (0)    else else {
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[post-auth]: calling
noop (rlm_always) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)   modsingle[post-auth]: returned
from noop (rlm_always) for request 0
Fri May  9 18:27:04 2014 : Debug: (0)     [noop] = noop
Fri May  9 18:27:04 2014 : Debug: (0)    } # else else = noop
Fri May  9 18:27:04 2014 : Debug: (0)   } #
remove_reply_message_if_eap remove_reply_message_if_eap = noop
Fri May  9 18:27:04 2014 : Debug: (0)  } #  post-auth = noop
Fri May  9 18:27:04 2014 : Debug: (0) Finished request
Fri May  9 18:27:04 2014 : Debug: Waking up in 4.9 seconds.
18:27:04.946594 172.16.35.65 -> 172.16.35.65 RADIUS 62
Access-Accept(2) (id=142, l=20)

==> kerberos/krb5kdc.log <==
May 09 18:27:05 obelix-clone krb5kdc[21569](info): DISPATCH: repeated
(retransmitted?) request from 172.16.35.65, resending previous
response
May 09 18:27:05 obelix-clone krb5kdc[21569](info): closing down fd 15
May 09 18:27:07 obelix-clone krb5kdc[21569](info): preauth (otp)
verify failure: Connection timed out
May 09 18:27:07 obelix-clone krb5kdc[21569](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: PREAUTH_FAILED:
fes at ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.ESCAUX.COM at ICT-DEV.ESCAUX.COM, Preauthentication failed

==> freeradius/radius.log <==
Fri May  9 18:27:09 2014 : Debug: (0) Cleaning up request packet ID
142 with timestamp +13
Fri May  9 18:27:09 2014 : Info: Ready to process requests.





There is no firewall on the local machine blocking connections or
anything, and as AFAIK no selinux activated.

Any other ideas?


>
> This side issue is making it a little harder to diagnose the main issue.
>  You are prompted again because the library attempts to retry against
> the master KDC, in case the initial request was against a slave KDC with
> outdated information.  There are two problems here:
>
> 1. In your setup there is only one KDC, so retrying against the master
> is pointless.
> 2. At least in this case, it would be better if the library reused the
> response from the first prompt, instead of prompting twice.
>
> Problem #2 is a difficult design problem, but we can fix #1 easily
> enough through configuration.  The library tries to determine if the
> first request went to the master KDC and suppresses the fallback if so,
> but in your setup it's getting confused.
>
> According to logs, your first request is sent to
> kerberos.ict-dev.escaux.com (172.16.35.65) and your second is sent to
> obelix-clone.ict-dev.escaux.com (also 172.16.35.65).  These are the same
> IP address, but we only compare hostnames.
>
> The name of the KDC for the first request (kerberos.ict-dev.escaux.com)
> is coming from the "kdc" relation in krb5.conf.  The name of the master
> KDC is coming from a SRV record:
>
>     $ host -t srv _kerberos-master._udp.ict-dev.escaux.com
>     _kerberos-master._udp.ICT-DEV.ESCAUX.COM has SRV record 0 0 88
> obelix-clone.ict-dev.escaux.com.
>
> If you put "master_kdc = kerberos.ict-dev.escaux.com" in your realm
> section, that should suppress the spurious master KDC fallback, as the
> library will be able to more easily tell that the master KDC is the same
> as the one it tried in the first request.

Thank you for this detailed explanation. Adding master_kdc to the
realm section indeed stops it from doing the same all over again.

Cheers,

Frederic


More information about the Kerberos mailing list