Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss
otp over radius preauthentication
325 views
Skip to first unread message
Frederic Van Espen
May 8, 2014, 2:50:15 PM5/8/14
to kerb...@mit.edu
Dear list,
I'm trying to set up otp over radius preauthentication (with a
yubikey) and am hitting some issue I can't wrap my head around.
The PKINIT part seems to work fine, i.e. I can do kinit -n -c ./armor
which gives me ticket cache with a ticket I can use for FAST armor.
I then run kinit -T ./armor <username>. This prompts me for the OTP
Token. I this point I enter the password of the user, immediately
followed by the OTP from the yubikey. In the FreeRADIUS logs I see
that the OTP is first validated correctly and then the user password
is properly authenticated against LDAP:
==> kerberos/krb5kdc.log <==
May 08 20:42:55 obelix-clone krb5kdc[21126](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: NEEDED_PREAUTH:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Additional
pre-authentication required
==> freeradius/radius.log <==
Waking up in 0.9 seconds.
Thread 3 got semaphore
Thread 3 handling request 2, (1 handled so far)
[<thread>] # Executing section authorize from file
/etc/freeradius/sites-enabled/default
[<thread>] +- entering group authorize {...}
++[preprocess] returns ok
rlm_perl: OTP is valid: ccccccdbkebjtfevnkcrnuugntghbhthjdlkfvjdfnll
rlm_perl: fes has valid OTP: ccccccdbkebjtfevnkcrnuugntghbhthjdlkfvjdfnll
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
++[perl] returns ok
++? if (ok)
? Evaluating (ok) -> TRUE
++? if (ok) -> TRUE
++- entering if (ok) {...}
+++[control] returns ok
++- if (ok) returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "fes", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.
Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = LDAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group LDAP {...}
[ldap] login attempt by "fes" with password "testingpassword"
[ldap] expand: %{Stripped-User-Name} ->
[ldap] ... expanding second conditional
[ldap] expand: %{User-Name} -> fes
[ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=fes)
[ldap] expand: ou=People,dc=escaux,dc=com -> ou=People,dc=escaux,dc=com
[ldap] ldap_get_conn: Checking Id: 0
[ldap] ldap_get_conn: Got Id: 0
[ldap] performing search in ou=People,dc=escaux,dc=com, with filter (uid=fes)
[ldap] ldap_release_conn: Release Id: 0
[ldap] user DN: uid=fes,ou=People,dc=escaux,dc=com
[ldap] (re)connect to localhost:389, authentication 1
[ldap] bind as uid=fes,ou=People,dc=escaux,dc=com/testingpassword to
localhost:389
[ldap] waiting for bind result ...
[ldap] Bind was successful
[ldap] user fes authenticated succesfully
++[ldap] returns ok
# Executing section post-auth from file /etc/freeradius/sites-enabled/default
+- entering group post-auth {...}
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
rlm_perl: Added pair Ldap-UserDn = uid=fes,ou=People,dc=escaux,dc=com
rlm_perl: Added pair Auth-Type = LDAP
++[perl] returns ok
++[exec] returns noop
Finished request 2.
Going to the next request
Thread 3 waiting to be assigned a request
==> kerberos/krb5kdc.log <==
May 08 20:43:02 obelix-clone krb5kdc[21126](info): DISPATCH: repeated
(retransmitted?) request from 172.16.35.65, resending previous
response
May 08 20:43:02 obelix-clone krb5kdc[21126](info): closing down fd 15
==> freeradius/radius.log <==
Waking up in 4.6 seconds.
==> kerberos/krb5kdc.log <==
May 08 20:43:03 obelix-clone krb5kdc[21126](info): preauth (otp)
verify failure: Connection timed out
May 08 20:43:03 obelix-clone krb5kdc[21126](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: PREAUTH_FAILED:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
May 08 20:43:03 obelix-clone krb5kdc[21126](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: NEEDED_PREAUTH:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Additional
pre-authentication required
==> freeradius/radius.log <==
Cleaning up request 2 ID 62 with timestamp +194
Ready to process requests.
Even when tracing the requests to FreeRADIUS I see that the
Access-Accept packet is sent by radius.
However, at this point it prompts again for the OTP token. Again I
enter the users password, followed by the yubikey token, resulting in
this in the logs:
Waking up in 0.9 seconds.
Thread 2 got semaphore
Thread 2 handling request 3, (1 handled so far)
[<thread>] # Executing section authorize from file
/etc/freeradius/sites-enabled/default
[<thread>] +- entering group authorize {...}
++[preprocess] returns ok
rlm_perl: OTP is valid: ccccccdbkebjgeeelkhnctrvehrbuciddfjkuvdhjvir
rlm_perl: fes has valid OTP: ccccccdbkebjgeeelkhnctrvehrbuciddfjkuvdhjvir
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
++[perl] returns ok
++? if (ok)
? Evaluating (ok) -> TRUE
++? if (ok) -> TRUE
++- entering if (ok) {...}
+++[control] returns ok
++- if (ok) returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "fes", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.
Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = LDAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group LDAP {...}
[ldap] login attempt by "fes" with password "testingpassword"
[ldap] expand: %{Stripped-User-Name} ->
[ldap] ... expanding second conditional
[ldap] expand: %{User-Name} -> fes
[ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=fes)
[ldap] expand: ou=People,dc=escaux,dc=com -> ou=People,dc=escaux,dc=com
[ldap] ldap_get_conn: Checking Id: 0
[ldap] ldap_get_conn: Got Id: 0
[ldap] performing search in ou=People,dc=escaux,dc=com, with filter (uid=fes)
[ldap] ldap_release_conn: Release Id: 0
[ldap] user DN: uid=fes,ou=People,dc=escaux,dc=com
[ldap] (re)connect to localhost:389, authentication 1
[ldap] bind as uid=fes,ou=People,dc=escaux,dc=com/testingpassword to
localhost:389
[ldap] waiting for bind result ...
[ldap] Bind was successful
[ldap] user fes authenticated succesfully
++[ldap] returns ok
# Executing section post-auth from file /etc/freeradius/sites-enabled/default
+- entering group post-auth {...}
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
rlm_perl: Added pair Ldap-UserDn = uid=fes,ou=People,dc=escaux,dc=com
rlm_perl: Added pair Auth-Type = LDAP
++[perl] returns ok
++[exec] returns noop
Finished request 3.
Going to the next request
Thread 2 waiting to be assigned a request
Waking up in 4.6 seconds.
==> kerberos/krb5kdc.log <==
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:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
==> freeradius/radius.log <==
Cleaning up request 3 ID 145 with timestamp +208
Ready to process requests.
During all this, here's the trace output of kinit:
fes@obelix-clone:~$ KRB5_TRACE=/dev/stderr kinit -T ./armor fes
[21218] 1399574575.801684: Getting initial credentials for
f...@ICT-DEV.ESCAUX.COM
[21218] 1399574575.815821: FAST armor ccache: ./armor
[21218] 1399574575.816193: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krb5_ccache_conf_data/fast_avail/krbtgt\/ICT-DEV.ESCAUX.COM\@ICT-DEV.ESCAUX.COM@X-CACHECONF:
from FILE:./armor with result: 0/Success
[21218] 1399574575.816290: Read config in FILE:./armor for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM: fast_avail: yes
[21218] 1399574575.816386: Using FAST due to armor ccache negotiation result
[21218] 1399574575.816488: Getting credentials
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM using ccache FILE:./armor
[21218] 1399574575.816631: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM from FILE:./armor with
result: 0/Success
[21218] 1399574575.816744: Armor ccache sesion key: aes256-cts/5CFB
[21218] 1399574575.816890: Creating authenticator for
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, seqnum 0, subkey
aes256-cts/BC7E, session key aes256-cts/5CFB
[21218] 1399574575.817176: FAST armor key: aes256-cts/2F12
[21218] 1399574575.817293: Encoding request body and padata into FAST request
[21218] 1399574575.817440: Sending request (988 bytes) to ICT-DEV.ESCAUX.COM
[21218] 1399574575.817549: Resolving hostname kerberos.ict-dev.escaux.com
[21218] 1399574575.817919: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574575.819180: Received answer (633 bytes) from dgram
172.16.35.65:88
[21218] 1399574575.851231: Response was not from master KDC
[21218] 1399574575.851287: Received error from KDC:
-1765328359/Additional pre-authentication required
[21218] 1399574575.851301: Decoding FAST response
[21218] 1399574575.851425: Processing preauth types: 16, 15, 14, 136,
147, 141, 133, 137
[21218] 1399574575.851433: Received cookie: MIT
[21218] 1399574575.851479: PKINIT client has no configured identity; giving up
[21218] 1399574575.851538: Preauth module pkinit (147) (info)
returned: 0/Success
[21218] 1399574575.851564: PKINIT client has no configured identity; giving up
[21218] 1399574575.851575: Preauth module pkinit (16) (real) returned:
22/Invalid argument
[21218] 1399574575.851597: PKINIT client has no configured identity; giving up
[21218] 1399574575.851607: Preauth module pkinit (14) (real) returned:
22/Invalid argument
[21218] 1399574575.851628: PKINIT client has no configured identity; giving up
[21218] 1399574575.851640: Preauth module pkinit (14) (real) returned:
22/Invalid argument
Enter OTP Token Value:
[21218] 1399574581.453094: Preauth module otp (141) (real) returned: 0/Success
[21218] 1399574581.453111: Produced preauth for next request: 133, 142
[21218] 1399574581.453120: Encoding request body and padata into FAST request
[21218] 1399574581.453253: Sending request (1178 bytes) to ICT-DEV.ESCAUX.COM
[21218] 1399574581.453305: Resolving hostname kerberos.ict-dev.escaux.com
[21218] 1399574581.453440: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574582.454048: Initiating TCP connection to stream 172.16.35.65:88
[21218] 1399574582.454251: Sending TCP request to stream 172.16.35.65:88
[21218] 1399574582.454957: TCP error receiving from stream
172.16.35.65:88: 104/Connection reset by peer
[21218] 1399574582.454973: Terminating TCP connection to stream 172.16.35.65:88
[21218] 1399574583.957324: Received answer (633 bytes) from dgram
172.16.35.65:88
[21218] 1399574583.979364: Response was not from master KDC
[21218] 1399574583.979462: Received error from KDC:
-1765328360/Preauthentication failed
[21218] 1399574583.979474: Decoding FAST response
[21218] 1399574583.979594: Preauth tryagain input types: 16, 14, 14,
136, 147, 141, 133, 137
[21218] 1399574583.979633: Retrying AS request with master KDC
[21218] 1399574583.979644: Getting initial credentials for
f...@ICT-DEV.ESCAUX.COM
[21218] 1399574583.979691: FAST armor ccache: ./armor
[21218] 1399574583.979798: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krb5_ccache_conf_data/fast_avail/krbtgt\/ICT-DEV.ESCAUX.COM\@ICT-DEV.ESCAUX.COM@X-CACHECONF:
from FILE:./armor with result: 0/Success
[21218] 1399574583.979811: Read config in FILE:./armor for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM: fast_avail: yes
[21218] 1399574583.979820: Using FAST due to armor ccache negotiation result
[21218] 1399574583.979839: Getting credentials
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM using ccache FILE:./armor
[21218] 1399574583.979890: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM from FILE:./armor with
result: 0/Success
[21218] 1399574583.979910: Armor ccache sesion key: aes256-cts/5CFB
[21218] 1399574583.979945: Creating authenticator for
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, seqnum 0, subkey
aes256-cts/4335, session key aes256-cts/5CFB
[21218] 1399574583.980034: FAST armor key: aes256-cts/2FC1
[21218] 1399574583.980058: Encoding request body and padata into FAST request
[21218] 1399574583.980128: Sending request (988 bytes) to
ICT-DEV.ESCAUX.COM (master)
[21218] 1399574583.999156: Resolving hostname obelix-clone.ict-dev.escaux.com.
[21218] 1399574583.999279: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574584.1295: Received answer (631 bytes) from dgram 172.16.35.65:88
[21218] 1399574584.1359: Received error from KDC:
-1765328359/Additional pre-authentication required
[21218] 1399574584.1373: Decoding FAST response
[21218] 1399574584.1470: Processing preauth types: 16, 15, 14, 136,
147, 141, 133, 137
[21218] 1399574584.1478: Received cookie: MIT
[21218] 1399574584.1522: PKINIT client has no configured identity; giving up
[21218] 1399574584.1556: Preauth module pkinit (147) (info) returned: 0/Success
[21218] 1399574584.1581: PKINIT client has no configured identity; giving up
[21218] 1399574584.1593: Preauth module pkinit (16) (real) returned:
22/Invalid argument
[21218] 1399574584.1613: PKINIT client has no configured identity; giving up
[21218] 1399574584.1623: Preauth module pkinit (14) (real) returned:
22/Invalid argument
[21218] 1399574584.1776: PKINIT client has no configured identity; giving up
[21218] 1399574584.1795: Preauth module pkinit (14) (real) returned:
22/Invalid argument
Enter OTP Token Value:
[21218] 1399574595.404839: Preauth module otp (141) (real) returned: 0/Success
[21218] 1399574595.404855: Produced preauth for next request: 133, 142
[21218] 1399574595.404863: Encoding request body and padata into FAST request
[21218] 1399574595.404965: Sending request (1178 bytes) to
ICT-DEV.ESCAUX.COM (master)
[21218] 1399574595.425367: Resolving hostname obelix-clone.ict-dev.escaux.com.
[21218] 1399574595.425460: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574597.928793: Received answer (633 bytes) from dgram
172.16.35.65:88
[21218] 1399574597.928867: Received error from KDC:
-1765328360/Preauthentication failed
[21218] 1399574597.928878: Decoding FAST response
[21218] 1399574597.928986: Preauth tryagain input types: 16, 14, 14,
136, 147, 141, 133, 137
kinit: Preauthentication failed while getting initial credentials
Also here's krb5.conf:
root@obelix-clone:~# cat /etc/krb5.conf
[libdefaults]
default_realm = ICT-DEV.ESCAUX.COM
# The following krb5.conf variables are only for MIT Kerberos.
krb4_config = /etc/krb.conf
krb4_realms = /etc/krb.realms
kdc_timesync = 1
ccache_type = 4
forwardable = true
proxiable = true
# The following encryption type specification will be used by MIT Kerberos
# if uncommented. In general, the defaults in the MIT Kerberos code are
# correct and overriding these specifications only serves to disable new
# encryption types as they are added, creating interoperability problems.
#
# Thie only time when you might need to uncomment these lines and change
# the enctypes is if you have local software that will break on ticket
# caches containing ticket encryption types it doesn't know about (such as
# old versions of Sun Java).
# default_tgs_enctypes = des3-hmac-sha1
# default_tkt_enctypes = des3-hmac-sha1
# permitted_enctypes = des3-hmac-sha1
# The following libdefaults parameters are only for Heimdal Kerberos.
v4_instance_resolve = false
v4_name_convert = {
host = {
rcmd = host
ftp = ftp
}
plain = {
something = something-else
}
}
fcc-mit-ticketflags = true
[kdcdefaults]
kdc_tcp_ports = 88
restrict_anonymous_to_tgt = true
[realms]
ICT-DEV.ESCAUX.COM = {
kdc = kerberos.ict-dev.escaux.com:88
admin_server = kerberos.ict-dev.escaux.com
default_domain = ict-dev.escaux.com
pkinit_identity = FILE:/etc/krb5kdc/kdc.pem,/etc/krb5kdc/kdckey.pem
pkinit_anchors = FILE:/usr/local/share/ca-certificates/cacert.pem
}
ATHENA.MIT.EDU = {
kdc = kerberos.mit.edu:88
kdc = kerberos-1.mit.edu:88
kdc = kerberos-2.mit.edu:88
admin_server = kerberos.mit.edu
default_domain = mit.edu
}
MEDIA-LAB.MIT.EDU = {
kdc = kerberos.media.mit.edu
admin_server = kerberos.media.mit.edu
}
ZONE.MIT.EDU = {
kdc = casio.mit.edu
kdc = seiko.mit.edu
admin_server = casio.mit.edu
}
MOOF.MIT.EDU = {
kdc = three-headed-dogcow.mit.edu:88
kdc = three-headed-dogcow-1.mit.edu:88
admin_server = three-headed-dogcow.mit.edu
}
CSAIL.MIT.EDU = {
kdc = kerberos-1.csail.mit.edu
kdc = kerberos-2.csail.mit.edu
admin_server = kerberos.csail.mit.edu
default_domain = csail.mit.edu
krb524_server = krb524.csail.mit.edu
}
IHTFP.ORG = {
kdc = kerberos.ihtfp.org
admin_server = kerberos.ihtfp.org
}
GNU.ORG = {
kdc = kerberos.gnu.org
kdc = kerberos-2.gnu.org
kdc = kerberos-3.gnu.org
admin_server = kerberos.gnu.org
}
1TS.ORG = {
kdc = kerberos.1ts.org
admin_server = kerberos.1ts.org
}
GRATUITOUS.ORG = {
kdc = kerberos.gratuitous.org
admin_server = kerberos.gratuitous.org
}
DOOMCOM.ORG = {
kdc = kerberos.doomcom.org
admin_server = kerberos.doomcom.org
}
ANDREW.CMU.EDU = {
kdc = kerberos.andrew.cmu.edu
kdc = kerberos2.andrew.cmu.edu
kdc = kerberos3.andrew.cmu.edu
admin_server = kerberos.andrew.cmu.edu
default_domain = andrew.cmu.edu
}
CS.CMU.EDU = {
kdc = kerberos.cs.cmu.edu
kdc = kerberos-2.srv.cs.cmu.edu
admin_server = kerberos.cs.cmu.edu
}
DEMENTIA.ORG = {
kdc = kerberos.dementix.org
kdc = kerberos2.dementix.org
admin_server = kerberos.dementix.org
}
stanford.edu = {
kdc = krb5auth1.stanford.edu
kdc = krb5auth2.stanford.edu
kdc = krb5auth3.stanford.edu
master_kdc = krb5auth1.stanford.edu
admin_server = krb5-admin.stanford.edu
default_domain = stanford.edu
}
UTORONTO.CA = {
kdc = kerberos1.utoronto.ca
kdc = kerberos2.utoronto.ca
kdc = kerberos3.utoronto.ca
admin_server = kerberos1.utoronto.ca
default_domain = utoronto.ca
}
[domain_realm]
.mit.edu = ATHENA.MIT.EDU
mit.edu = ATHENA.MIT.EDU
.media.mit.edu = MEDIA-LAB.MIT.EDU
media.mit.edu = MEDIA-LAB.MIT.EDU
.csail.mit.edu = CSAIL.MIT.EDU
csail.mit.edu = CSAIL.MIT.EDU
.whoi.edu = ATHENA.MIT.EDU
whoi.edu = ATHENA.MIT.EDU
.stanford.edu = stanford.edu
.slac.stanford.edu = SLAC.STANFORD.EDU
.toronto.edu = UTORONTO.CA
.utoronto.ca = UTORONTO.CA
.ict-dev.escaux.com = ICT-DEV.ESCAUX.COM
ict-dev.escaux.com = ICT-DEV.ESCAUX.COM
[login]
krb4_convert = true
krb4_get_tickets = false
[logging]
kdc = FILE:/var/log/kerberos/krb5kdc.log
admin_server = FILE:/var/log/kerberos/kadmin.log
default = FILE:/var/log/kerberos/krb5lib.log
[otp]
DEFAULT = {
server = 172.16.35.65:1812
secret = /etc/krb5kdc/radius-secret
timeout = 5
retries = 1
strip_realm = true
}
I'm really at a loss here and could use some experienced eyes that can
help me set this up. I have looked at the guides of the few people
that explained how to set this up but have not seen anyone running
into the same issue.
Any help would be greatly appreciated!
Cheers,
Frederic
I'm trying to set up otp over radius preauthentication (with a
yubikey) and am hitting some issue I can't wrap my head around.
The PKINIT part seems to work fine, i.e. I can do kinit -n -c ./armor
which gives me ticket cache with a ticket I can use for FAST armor.
I then run kinit -T ./armor <username>. This prompts me for the OTP
Token. I this point I enter the password of the user, immediately
followed by the OTP from the yubikey. In the FreeRADIUS logs I see
that the OTP is first validated correctly and then the user password
is properly authenticated against LDAP:
==> kerberos/krb5kdc.log <==
May 08 20:42:55 obelix-clone krb5kdc[21126](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: NEEDED_PREAUTH:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Additional
pre-authentication required
==> freeradius/radius.log <==
Waking up in 0.9 seconds.
Thread 3 got semaphore
Thread 3 handling request 2, (1 handled so far)
[<thread>] # Executing section authorize from file
/etc/freeradius/sites-enabled/default
[<thread>] +- entering group authorize {...}
++[preprocess] returns ok
rlm_perl: OTP is valid: ccccccdbkebjtfevnkcrnuugntghbhthjdlkfvjdfnll
rlm_perl: fes has valid OTP: ccccccdbkebjtfevnkcrnuugntghbhthjdlkfvjdfnll
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
++[perl] returns ok
++? if (ok)
? Evaluating (ok) -> TRUE
++? if (ok) -> TRUE
++- entering if (ok) {...}
+++[control] returns ok
++- if (ok) returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "fes", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.
Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = LDAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group LDAP {...}
[ldap] login attempt by "fes" with password "testingpassword"
[ldap] expand: %{Stripped-User-Name} ->
[ldap] ... expanding second conditional
[ldap] expand: %{User-Name} -> fes
[ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=fes)
[ldap] expand: ou=People,dc=escaux,dc=com -> ou=People,dc=escaux,dc=com
[ldap] ldap_get_conn: Checking Id: 0
[ldap] ldap_get_conn: Got Id: 0
[ldap] performing search in ou=People,dc=escaux,dc=com, with filter (uid=fes)
[ldap] ldap_release_conn: Release Id: 0
[ldap] user DN: uid=fes,ou=People,dc=escaux,dc=com
[ldap] (re)connect to localhost:389, authentication 1
[ldap] bind as uid=fes,ou=People,dc=escaux,dc=com/testingpassword to
localhost:389
[ldap] waiting for bind result ...
[ldap] Bind was successful
[ldap] user fes authenticated succesfully
++[ldap] returns ok
# Executing section post-auth from file /etc/freeradius/sites-enabled/default
+- entering group post-auth {...}
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
rlm_perl: Added pair Ldap-UserDn = uid=fes,ou=People,dc=escaux,dc=com
rlm_perl: Added pair Auth-Type = LDAP
++[perl] returns ok
++[exec] returns noop
Finished request 2.
Going to the next request
Thread 3 waiting to be assigned a request
==> kerberos/krb5kdc.log <==
May 08 20:43:02 obelix-clone krb5kdc[21126](info): DISPATCH: repeated
(retransmitted?) request from 172.16.35.65, resending previous
response
May 08 20:43:02 obelix-clone krb5kdc[21126](info): closing down fd 15
==> freeradius/radius.log <==
Waking up in 4.6 seconds.
==> kerberos/krb5kdc.log <==
May 08 20:43:03 obelix-clone krb5kdc[21126](info): preauth (otp)
verify failure: Connection timed out
May 08 20:43:03 obelix-clone krb5kdc[21126](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: PREAUTH_FAILED:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
May 08 20:43:03 obelix-clone krb5kdc[21126](info): AS_REQ (6 etypes
{18 17 16 23 25 26}) 172.16.35.65: NEEDED_PREAUTH:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Additional
pre-authentication required
==> freeradius/radius.log <==
Cleaning up request 2 ID 62 with timestamp +194
Ready to process requests.
Even when tracing the requests to FreeRADIUS I see that the
Access-Accept packet is sent by radius.
However, at this point it prompts again for the OTP token. Again I
enter the users password, followed by the yubikey token, resulting in
this in the logs:
Waking up in 0.9 seconds.
Thread 2 got semaphore
Thread 2 handling request 3, (1 handled so far)
[<thread>] # Executing section authorize from file
/etc/freeradius/sites-enabled/default
[<thread>] +- entering group authorize {...}
++[preprocess] returns ok
rlm_perl: OTP is valid: ccccccdbkebjgeeelkhnctrvehrbuciddfjkuvdhjvir
rlm_perl: fes has valid OTP: ccccccdbkebjgeeelkhnctrvehrbuciddfjkuvdhjvir
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
++[perl] returns ok
++? if (ok)
? Evaluating (ok) -> TRUE
++? if (ok) -> TRUE
++- entering if (ok) {...}
+++[control] returns ok
++- if (ok) returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "fes", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
[pap] WARNING! No "known good" password found for the user.
Authentication may fail because of this.
++[pap] returns noop
Found Auth-Type = LDAP
# Executing group from file /etc/freeradius/sites-enabled/default
+- entering group LDAP {...}
[ldap] login attempt by "fes" with password "testingpassword"
[ldap] expand: %{Stripped-User-Name} ->
[ldap] ... expanding second conditional
[ldap] expand: %{User-Name} -> fes
[ldap] expand: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) -> (uid=fes)
[ldap] expand: ou=People,dc=escaux,dc=com -> ou=People,dc=escaux,dc=com
[ldap] ldap_get_conn: Checking Id: 0
[ldap] ldap_get_conn: Got Id: 0
[ldap] performing search in ou=People,dc=escaux,dc=com, with filter (uid=fes)
[ldap] ldap_release_conn: Release Id: 0
[ldap] user DN: uid=fes,ou=People,dc=escaux,dc=com
[ldap] (re)connect to localhost:389, authentication 1
[ldap] bind as uid=fes,ou=People,dc=escaux,dc=com/testingpassword to
localhost:389
[ldap] waiting for bind result ...
[ldap] Bind was successful
[ldap] user fes authenticated succesfully
++[ldap] returns ok
# Executing section post-auth from file /etc/freeradius/sites-enabled/default
+- entering group post-auth {...}
rlm_perl: Added pair User-Name = fes
rlm_perl: Added pair NAS-Identifier = obelix-clone
rlm_perl: Added pair User-Password = testingpassword
rlm_perl: Added pair Service-Type = Authenticate-Only
rlm_perl: Added pair NAS-IP-Address = 172.16.35.65
rlm_perl: Added pair Ldap-UserDn = uid=fes,ou=People,dc=escaux,dc=com
rlm_perl: Added pair Auth-Type = LDAP
++[perl] returns ok
++[exec] returns noop
Finished request 3.
Going to the next request
Thread 2 waiting to be assigned a request
Waking up in 4.6 seconds.
==> kerberos/krb5kdc.log <==
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:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
==> freeradius/radius.log <==
Cleaning up request 3 ID 145 with timestamp +208
Ready to process requests.
During all this, here's the trace output of kinit:
fes@obelix-clone:~$ KRB5_TRACE=/dev/stderr kinit -T ./armor fes
[21218] 1399574575.801684: Getting initial credentials for
f...@ICT-DEV.ESCAUX.COM
[21218] 1399574575.815821: FAST armor ccache: ./armor
[21218] 1399574575.816193: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krb5_ccache_conf_data/fast_avail/krbtgt\/ICT-DEV.ESCAUX.COM\@ICT-DEV.ESCAUX.COM@X-CACHECONF:
from FILE:./armor with result: 0/Success
[21218] 1399574575.816290: Read config in FILE:./armor for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM: fast_avail: yes
[21218] 1399574575.816386: Using FAST due to armor ccache negotiation result
[21218] 1399574575.816488: Getting credentials
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM using ccache FILE:./armor
[21218] 1399574575.816631: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM from FILE:./armor with
result: 0/Success
[21218] 1399574575.816744: Armor ccache sesion key: aes256-cts/5CFB
[21218] 1399574575.816890: Creating authenticator for
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, seqnum 0, subkey
aes256-cts/BC7E, session key aes256-cts/5CFB
[21218] 1399574575.817176: FAST armor key: aes256-cts/2F12
[21218] 1399574575.817293: Encoding request body and padata into FAST request
[21218] 1399574575.817440: Sending request (988 bytes) to ICT-DEV.ESCAUX.COM
[21218] 1399574575.817549: Resolving hostname kerberos.ict-dev.escaux.com
[21218] 1399574575.817919: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574575.819180: Received answer (633 bytes) from dgram
172.16.35.65:88
[21218] 1399574575.851231: Response was not from master KDC
[21218] 1399574575.851287: Received error from KDC:
-1765328359/Additional pre-authentication required
[21218] 1399574575.851301: Decoding FAST response
[21218] 1399574575.851425: Processing preauth types: 16, 15, 14, 136,
147, 141, 133, 137
[21218] 1399574575.851433: Received cookie: MIT
[21218] 1399574575.851479: PKINIT client has no configured identity; giving up
[21218] 1399574575.851538: Preauth module pkinit (147) (info)
returned: 0/Success
[21218] 1399574575.851564: PKINIT client has no configured identity; giving up
[21218] 1399574575.851575: Preauth module pkinit (16) (real) returned:
22/Invalid argument
[21218] 1399574575.851597: PKINIT client has no configured identity; giving up
[21218] 1399574575.851607: Preauth module pkinit (14) (real) returned:
22/Invalid argument
[21218] 1399574575.851628: PKINIT client has no configured identity; giving up
[21218] 1399574575.851640: Preauth module pkinit (14) (real) returned:
22/Invalid argument
Enter OTP Token Value:
[21218] 1399574581.453094: Preauth module otp (141) (real) returned: 0/Success
[21218] 1399574581.453111: Produced preauth for next request: 133, 142
[21218] 1399574581.453120: Encoding request body and padata into FAST request
[21218] 1399574581.453253: Sending request (1178 bytes) to ICT-DEV.ESCAUX.COM
[21218] 1399574581.453305: Resolving hostname kerberos.ict-dev.escaux.com
[21218] 1399574581.453440: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574582.454048: Initiating TCP connection to stream 172.16.35.65:88
[21218] 1399574582.454251: Sending TCP request to stream 172.16.35.65:88
[21218] 1399574582.454957: TCP error receiving from stream
172.16.35.65:88: 104/Connection reset by peer
[21218] 1399574582.454973: Terminating TCP connection to stream 172.16.35.65:88
[21218] 1399574583.957324: Received answer (633 bytes) from dgram
172.16.35.65:88
[21218] 1399574583.979364: Response was not from master KDC
[21218] 1399574583.979462: Received error from KDC:
-1765328360/Preauthentication failed
[21218] 1399574583.979474: Decoding FAST response
[21218] 1399574583.979594: Preauth tryagain input types: 16, 14, 14,
136, 147, 141, 133, 137
[21218] 1399574583.979633: Retrying AS request with master KDC
[21218] 1399574583.979644: Getting initial credentials for
f...@ICT-DEV.ESCAUX.COM
[21218] 1399574583.979691: FAST armor ccache: ./armor
[21218] 1399574583.979798: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krb5_ccache_conf_data/fast_avail/krbtgt\/ICT-DEV.ESCAUX.COM\@ICT-DEV.ESCAUX.COM@X-CACHECONF:
from FILE:./armor with result: 0/Success
[21218] 1399574583.979811: Read config in FILE:./armor for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM: fast_avail: yes
[21218] 1399574583.979820: Using FAST due to armor ccache negotiation result
[21218] 1399574583.979839: Getting credentials
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM using ccache FILE:./armor
[21218] 1399574583.979890: Retrieving
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM from FILE:./armor with
result: 0/Success
[21218] 1399574583.979910: Armor ccache sesion key: aes256-cts/5CFB
[21218] 1399574583.979945: Creating authenticator for
WELLKNOWN/ANONYMOUS@WELLKNOWN:ANONYMOUS ->
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, seqnum 0, subkey
aes256-cts/4335, session key aes256-cts/5CFB
[21218] 1399574583.980034: FAST armor key: aes256-cts/2FC1
[21218] 1399574583.980058: Encoding request body and padata into FAST request
[21218] 1399574583.980128: Sending request (988 bytes) to
ICT-DEV.ESCAUX.COM (master)
[21218] 1399574583.999156: Resolving hostname obelix-clone.ict-dev.escaux.com.
[21218] 1399574583.999279: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574584.1295: Received answer (631 bytes) from dgram 172.16.35.65:88
[21218] 1399574584.1359: Received error from KDC:
-1765328359/Additional pre-authentication required
[21218] 1399574584.1373: Decoding FAST response
[21218] 1399574584.1470: Processing preauth types: 16, 15, 14, 136,
147, 141, 133, 137
[21218] 1399574584.1478: Received cookie: MIT
[21218] 1399574584.1522: PKINIT client has no configured identity; giving up
[21218] 1399574584.1556: Preauth module pkinit (147) (info) returned: 0/Success
[21218] 1399574584.1581: PKINIT client has no configured identity; giving up
[21218] 1399574584.1593: Preauth module pkinit (16) (real) returned:
22/Invalid argument
[21218] 1399574584.1613: PKINIT client has no configured identity; giving up
[21218] 1399574584.1623: Preauth module pkinit (14) (real) returned:
22/Invalid argument
[21218] 1399574584.1776: PKINIT client has no configured identity; giving up
[21218] 1399574584.1795: Preauth module pkinit (14) (real) returned:
22/Invalid argument
Enter OTP Token Value:
[21218] 1399574595.404839: Preauth module otp (141) (real) returned: 0/Success
[21218] 1399574595.404855: Produced preauth for next request: 133, 142
[21218] 1399574595.404863: Encoding request body and padata into FAST request
[21218] 1399574595.404965: Sending request (1178 bytes) to
ICT-DEV.ESCAUX.COM (master)
[21218] 1399574595.425367: Resolving hostname obelix-clone.ict-dev.escaux.com.
[21218] 1399574595.425460: Sending initial UDP request to dgram 172.16.35.65:88
[21218] 1399574597.928793: Received answer (633 bytes) from dgram
172.16.35.65:88
[21218] 1399574597.928867: Received error from KDC:
-1765328360/Preauthentication failed
[21218] 1399574597.928878: Decoding FAST response
[21218] 1399574597.928986: Preauth tryagain input types: 16, 14, 14,
136, 147, 141, 133, 137
kinit: Preauthentication failed while getting initial credentials
Also here's krb5.conf:
root@obelix-clone:~# cat /etc/krb5.conf
[libdefaults]
default_realm = ICT-DEV.ESCAUX.COM
# The following krb5.conf variables are only for MIT Kerberos.
krb4_config = /etc/krb.conf
krb4_realms = /etc/krb.realms
kdc_timesync = 1
ccache_type = 4
forwardable = true
proxiable = true
# The following encryption type specification will be used by MIT Kerberos
# if uncommented. In general, the defaults in the MIT Kerberos code are
# correct and overriding these specifications only serves to disable new
# encryption types as they are added, creating interoperability problems.
#
# Thie only time when you might need to uncomment these lines and change
# the enctypes is if you have local software that will break on ticket
# caches containing ticket encryption types it doesn't know about (such as
# old versions of Sun Java).
# default_tgs_enctypes = des3-hmac-sha1
# default_tkt_enctypes = des3-hmac-sha1
# permitted_enctypes = des3-hmac-sha1
# The following libdefaults parameters are only for Heimdal Kerberos.
v4_instance_resolve = false
v4_name_convert = {
host = {
rcmd = host
ftp = ftp
}
plain = {
something = something-else
}
}
fcc-mit-ticketflags = true
[kdcdefaults]
kdc_tcp_ports = 88
restrict_anonymous_to_tgt = true
[realms]
ICT-DEV.ESCAUX.COM = {
kdc = kerberos.ict-dev.escaux.com:88
admin_server = kerberos.ict-dev.escaux.com
default_domain = ict-dev.escaux.com
pkinit_identity = FILE:/etc/krb5kdc/kdc.pem,/etc/krb5kdc/kdckey.pem
pkinit_anchors = FILE:/usr/local/share/ca-certificates/cacert.pem
}
ATHENA.MIT.EDU = {
kdc = kerberos.mit.edu:88
kdc = kerberos-1.mit.edu:88
kdc = kerberos-2.mit.edu:88
admin_server = kerberos.mit.edu
default_domain = mit.edu
}
MEDIA-LAB.MIT.EDU = {
kdc = kerberos.media.mit.edu
admin_server = kerberos.media.mit.edu
}
ZONE.MIT.EDU = {
kdc = casio.mit.edu
kdc = seiko.mit.edu
admin_server = casio.mit.edu
}
MOOF.MIT.EDU = {
kdc = three-headed-dogcow.mit.edu:88
kdc = three-headed-dogcow-1.mit.edu:88
admin_server = three-headed-dogcow.mit.edu
}
CSAIL.MIT.EDU = {
kdc = kerberos-1.csail.mit.edu
kdc = kerberos-2.csail.mit.edu
admin_server = kerberos.csail.mit.edu
default_domain = csail.mit.edu
krb524_server = krb524.csail.mit.edu
}
IHTFP.ORG = {
kdc = kerberos.ihtfp.org
admin_server = kerberos.ihtfp.org
}
GNU.ORG = {
kdc = kerberos.gnu.org
kdc = kerberos-2.gnu.org
kdc = kerberos-3.gnu.org
admin_server = kerberos.gnu.org
}
1TS.ORG = {
kdc = kerberos.1ts.org
admin_server = kerberos.1ts.org
}
GRATUITOUS.ORG = {
kdc = kerberos.gratuitous.org
admin_server = kerberos.gratuitous.org
}
DOOMCOM.ORG = {
kdc = kerberos.doomcom.org
admin_server = kerberos.doomcom.org
}
ANDREW.CMU.EDU = {
kdc = kerberos.andrew.cmu.edu
kdc = kerberos2.andrew.cmu.edu
kdc = kerberos3.andrew.cmu.edu
admin_server = kerberos.andrew.cmu.edu
default_domain = andrew.cmu.edu
}
CS.CMU.EDU = {
kdc = kerberos.cs.cmu.edu
kdc = kerberos-2.srv.cs.cmu.edu
admin_server = kerberos.cs.cmu.edu
}
DEMENTIA.ORG = {
kdc = kerberos.dementix.org
kdc = kerberos2.dementix.org
admin_server = kerberos.dementix.org
}
stanford.edu = {
kdc = krb5auth1.stanford.edu
kdc = krb5auth2.stanford.edu
kdc = krb5auth3.stanford.edu
master_kdc = krb5auth1.stanford.edu
admin_server = krb5-admin.stanford.edu
default_domain = stanford.edu
}
UTORONTO.CA = {
kdc = kerberos1.utoronto.ca
kdc = kerberos2.utoronto.ca
kdc = kerberos3.utoronto.ca
admin_server = kerberos1.utoronto.ca
default_domain = utoronto.ca
}
[domain_realm]
.mit.edu = ATHENA.MIT.EDU
mit.edu = ATHENA.MIT.EDU
.media.mit.edu = MEDIA-LAB.MIT.EDU
media.mit.edu = MEDIA-LAB.MIT.EDU
.csail.mit.edu = CSAIL.MIT.EDU
csail.mit.edu = CSAIL.MIT.EDU
.whoi.edu = ATHENA.MIT.EDU
whoi.edu = ATHENA.MIT.EDU
.stanford.edu = stanford.edu
.slac.stanford.edu = SLAC.STANFORD.EDU
.toronto.edu = UTORONTO.CA
.utoronto.ca = UTORONTO.CA
.ict-dev.escaux.com = ICT-DEV.ESCAUX.COM
ict-dev.escaux.com = ICT-DEV.ESCAUX.COM
[login]
krb4_convert = true
krb4_get_tickets = false
[logging]
kdc = FILE:/var/log/kerberos/krb5kdc.log
admin_server = FILE:/var/log/kerberos/kadmin.log
default = FILE:/var/log/kerberos/krb5lib.log
[otp]
DEFAULT = {
server = 172.16.35.65:1812
secret = /etc/krb5kdc/radius-secret
timeout = 5
retries = 1
strip_realm = true
}
I'm really at a loss here and could use some experienced eyes that can
help me set this up. I have looked at the guides of the few people
that explained how to set this up but have not seen anyone running
into the same issue.
Any help would be greatly appreciated!
Cheers,
Frederic
Greg Hudson
May 9, 2014, 11:09:43 AM5/9/14
to Frederic Van Espen, kerb...@mit.edu
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:
> f...@ICT-DEV.ESCAUX.COM for
> krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
I think this is the root cause of your problem--FreeRADIUS is returning
> 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:
> f...@ICT-DEV.ESCAUX.COM for
> krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
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.
> However, at this point it prompts again for the OTP token.
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.
Frederic Van Espen
May 9, 2014, 12:36:39 PM5/9/14
to Greg Hudson, kerb...@mit.edu
Hello Greg,
On Fri, May 9, 2014 at 5:09 PM, Greg Hudson <ghu...@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:
>> f...@ICT-DEV.ESCAUX.COM for
>> krbtgt/ICT-DEV.E...@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
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
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
May 09 18:27:07 obelix-clone krb5kdc[21569](info): preauth (otp)
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?
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
On Fri, May 9, 2014 at 5:09 PM, Greg Hudson <ghu...@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:
>> f...@ICT-DEV.ESCAUX.COM for
>> krbtgt/ICT-DEV.E...@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.
>
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:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Additional
pre-authentication required
18:27:04.570719 172.16.35.65 -> 172.16.35.65 RADIUS 153
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Additional
pre-authentication required
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
response
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:
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
==> freeradius/radius.log <==
f...@ICT-DEV.ESCAUX.COM for
krbtgt/ICT-DEV.E...@ICT-DEV.ESCAUX.COM, Preauthentication failed
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?
realm section indeed stops it from doing the same all over again.
Cheers,
Frederic
Greg Hudson
May 15, 2014, 3:04:28 PM5/15/14
to Frederic Van Espen, kerb...@mit.edu
On 05/09/2014 12:36 PM, Frederic Van Espen wrote:
> That's what I though too at first but it is not the case.
[...]
> That's what I though too at first but it is not the case.
> Any other ideas?
I talked to the author of the OTP KDC plugin about this today, and we
have only vague conjectures at this point. We might be able to figure
out what's going on with a raw packet dump of the kinit exchange from
the KDC's perspective. The list server will scrub attachments, but if
you can send me a raw packet dump privately I will see what I can do.
Frederic Van Espen
May 16, 2014, 2:51:22 AM5/16/14
to Greg Hudson, kerb...@mit.edu
> I talked to the author of the OTP KDC plugin about this today, and we
> have only vague conjectures at this point. We might be able to figure
> out what's going on with a raw packet dump of the kinit exchange from
> the KDC's perspective. The list server will scrub attachments, but if
> you can send me a raw packet dump privately I will see what I can do.
Of course! For the sake of completeness, I still cc'ed the list. I
> have only vague conjectures at this point. We might be able to figure
> out what's going on with a raw packet dump of the kinit exchange from
> the KDC's perspective. The list server will scrub attachments, but if
> you can send me a raw packet dump privately I will see what I can do.
attached a pcap trace of the packets that are exchanged. I traced on
both port 88 (krb) and 1812 (radius). Here's what you'll find in the
trace:
- First an anonymous pkinit to obtain the armor ticket
- Then otp preauth.
I did these tests locally on one and the same machine. So the client
machine is the same as the server.
Let me know if there is anything else that could help you.
Greg Hudson
May 17, 2014, 1:24:23 PM5/17/14
to Frederic Van Espen, kerb...@mit.edu
On 05/16/2014 02:51 AM, Frederic Van Espen wrote:
> Of course! For the sake of completeness, I still cc'ed the list. I
> attached a pcap trace of the packets that are exchanged.
I discovered a fencepost error in our code which causes the KDC to time
> Of course! For the sake of completeness, I still cc'ed the list. I
> attached a pcap trace of the packets that are exchanged.
out after 2.5 seconds instead of five seconds. But that's not your
primary problem; something is causing the KDC to discard the RADIUS reply.
Since the reply packet looks well-formed and has the same ID as the
request, the obvious culprit is the response authenticator. Per RFC
2865, this is supposed to be
MD5(Code+ID+Length+RequestAuth+Attributes+Secret), or in the case of
this packet trace:
MD5(02 4d 0014 f9b07553bdb3fcc249900650c0105cf2 <secret>)
I don't have your RADIUS secret, so I can't verify that the response
authenticator (bdc29c3024044ded5482d102f6628e4a) is correct. If the
checksum generated by FreeRADIUS is correct, then something else is
wrong; if it is incorrect, then we need to figure out why.
We do have automated tests which use the krb5 OTP RADIUS code against
pyrad, so it seems odd that we would have an interoperability issue like
this against FreeRADIUS. I think if FreeRADIUS and krb5 were using
different secrets, we would have trouble sooner (FreeRADIUS wouldn't be
able to decrypt the password), so I'm not really sure what's going on.
Frederic Van Espen
May 18, 2014, 7:01:31 AM5/18/14
to Greg Hudson, kerb...@mit.edu
On Sat, May 17, 2014 at 7:24 PM, Greg Hudson <ghu...@mit.edu> wrote:
> On 05/16/2014 02:51 AM, Frederic Van Espen wrote:
>> Of course! For the sake of completeness, I still cc'ed the list. I
>> attached a pcap trace of the packets that are exchanged.
>
> I discovered a fencepost error in our code which causes the KDC to time
> out after 2.5 seconds instead of five seconds. But that's not your
> primary problem; something is causing the KDC to discard the RADIUS reply.
>
> Since the reply packet looks well-formed and has the same ID as the
> request, the obvious culprit is the response authenticator. Per RFC
> 2865, this is supposed to be
> MD5(Code+ID+Length+RequestAuth+Attributes+Secret), or in the case of
> this packet trace:
>
> MD5(02 4d 0014 f9b07553bdb3fcc249900650c0105cf2 <secret>)
>
> I don't have your RADIUS secret, so I can't verify that the response
> authenticator (bdc29c3024044ded5482d102f6628e4a) is correct. If the
> checksum generated by FreeRADIUS is correct, then something else is
> wrong; if it is incorrect, then we need to figure out why.
I will gladly share the radius secret since it is only a lab setup: testing123
> On 05/16/2014 02:51 AM, Frederic Van Espen wrote:
>> Of course! For the sake of completeness, I still cc'ed the list. I
>> attached a pcap trace of the packets that are exchanged.
>
> I discovered a fencepost error in our code which causes the KDC to time
> out after 2.5 seconds instead of five seconds. But that's not your
> primary problem; something is causing the KDC to discard the RADIUS reply.
>
> Since the reply packet looks well-formed and has the same ID as the
> request, the obvious culprit is the response authenticator. Per RFC
> 2865, this is supposed to be
> MD5(Code+ID+Length+RequestAuth+Attributes+Secret), or in the case of
> this packet trace:
>
> MD5(02 4d 0014 f9b07553bdb3fcc249900650c0105cf2 <secret>)
>
> I don't have your RADIUS secret, so I can't verify that the response
> authenticator (bdc29c3024044ded5482d102f6628e4a) is correct. If the
> checksum generated by FreeRADIUS is correct, then something else is
> wrong; if it is incorrect, then we need to figure out why.
I tried to calculate the response authenticator myself but I'm not
sure if the secret is just concatenated plaintext, or if it are the
ascii hex values, or if there is some extra padding added.
> We do have automated tests which use the krb5 OTP RADIUS code against
> pyrad, so it seems odd that we would have an interoperability issue like
> this against FreeRADIUS. I think if FreeRADIUS and krb5 were using
> different secrets, we would have trouble sooner (FreeRADIUS wouldn't be
> able to decrypt the password), so I'm not really sure what's going on.
automated test, but now I'm getting segfaults in krb5kdc. The segfault
appears when I do 'setstr fes otp [{"type":yubikey}]'
When I reset it like: 'setstr fes otp [{}]', and change the otp type
back to DEFAULT in krb5.conf I don't see a segfault any more.
Here's the relevant part in krb5.conf:
[otp]
yubikey = {
server = 127.0.0.1:1812
secret = /etc/krb5kdc/radius-secret
strip_realm = true
}
[plugins]
kdcpreauth = {
enable_only = otp
enable_only = pkinit
}
and the dmesg output:
May 18 12:45:13 obelix-clone kernel: [3374376.898313] krb5kdc[3175]:
segfault at fffffffffffffff0 ip 00007fc6ea041f70 sp 00007fffab558588
error 5 in libkrb5support.so.0.1[7fc6ea03b000+b000]
How can I enable core dumps so we can look at a backtrace?
I should mention that I'm using krb5 1.12.1 from the debian sid
distribution that I compiled myself on wheezy. I'm trying a manual
build from the downloaded source tree right now.
Thanks,
Frederic
Frederic Van Espen
May 18, 2014, 7:50:21 AM5/18/14
to Greg Hudson, kerb...@mit.edu
On Sun, May 18, 2014 at 1:01 PM, Frederic Van Espen
<frede...@gmail.com> wrote:
> I should mention that I'm using krb5 1.12.1 from the debian sid
> distribution that I compiled myself on wheezy. I'm trying a manual
> build from the downloaded source tree right now.
Same problem when built from the downloaded source tree:
<frede...@gmail.com> wrote:
> I should mention that I'm using krb5 1.12.1 from the debian sid
> distribution that I compiled myself on wheezy. I'm trying a manual
> build from the downloaded source tree right now.
May 18 13:45:15 obelix-clone kernel: [3377978.456956] krb5kdc[25864]:
segfault at fffffffffffffff0 ip 00007fcbd85a3e30 sp 00007fffe4bd3098
error 5 in libkrb5support.so.0.1[7fcbd859d000+b000]
Frederic
0 new messages