[krbdev.mit.edu #8580] kinit fails for OTP users when using KdcProxy with both IPv4&6 DNS

Thu Apr 20 00:49:18 EDT 2017

I'm running krb5-util 1.15 on Debian/Stretch and Ubuntu/Zesty.  I'm
working to get my laptop running with KdcProxy, so I can authenticate
externally and use the ticket to access my VPN.  I had this working some
weeks ago, but now it fails (probably since I've added IPv6 to my DynDNS
- at least that's my guess now after looking at the traces).

Here's a kinit-trace from a failed try:

Enter OTP Token Value: 
[20855] 1492630771.827372: Preauth module otp (141) (real) returned: 0/Success
[20855] 1492630771.827403: Produced preauth for next request: 133, 142
[20855] 1492630771.827427: Encoding request body and padata into FAST request
[20855] 1492630771.827624: Sending request (1152 bytes) to EXAMPLE.ORG
[20855] 1492630771.827681: Resolving hostname freeipa1.example.org
[20855] 1492630771.839716: TLS certificate name matched "freeipa1.example.org"
[20855] 1492630771.843982: Sending HTTPS request to https fd23:e163:19f7:1234:5054:ff:fe85:ba0d:443
[20855] 1492630772.838077: TLS certificate name matched "freeipa1.example.org"
[20855] 1492630772.848431: Sending HTTPS request to https 192.168.30.121:443
[20855] 1492630772.860504: Received answer (0 bytes) from https 192.168.30.121:443
[20855] 1492630772.860538: Terminating TCP connection to https fd23:e163:19f7:1234:5054:ff:fe85:ba0d:443
[20855] 1492630772.860731: Terminating TCP connection to https 192.168.30.121:443
[20855] 1492630772.860926: Response was not from master KDC
[20855] 1492630772.860995: Processing preauth types: 136, 141, 133, 137
[20855] 1492630772.861009: Received cookie: MIT
[20855] 1492630772.861070: Retrying AS request with master KDC
[20855] 1492630772.861087: Getting initial credentials for jochen at EXAMPLE.ORG
[20855] 1492630772.861138: FAST armor ccache: FILE:/home/jochen/.byobu/krb5cc_1004
[20855] 1492630772.861383: Retrieving jkellner at EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG at X-CACHECONF: from FILE:/home/jochen/.byobu/krb5cc_1004 with result: 0/Success
[20855] 1492630772.861406: Read config in FILE:/home/jochen/.byobu/krb5cc_1004 for krbtgt/EXAMPLE.ORG at EXAMPLE.ORG: fast_avail: yes
[20855] 1492630772.861423: Using FAST due to armor ccache negotiation result
[20855] 1492630772.861476: Getting credentials jkellner at EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG at EXAMPLE.ORG using ccache FILE:/home/jochen/.byobu/krb5cc_1004
[20855] 1492630772.861610: Retrieving jkellner at EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG at EXAMPLE.ORG from FILE:/home/jochen/.byobu/krb5cc_1004 with result: 0/Success
[20855] 1492630772.861647: Armor ccache sesion key: aes256-cts/70B6
[20855] 1492630772.861716: Creating authenticator for jkellner at EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG at EXAMPLE.ORG, seqnum 0, subkey aes256-cts/BEBB, session key aes256-cts/70B6
[20855] 1492630772.861883: FAST armor key: aes256-cts/3600
[20855] 1492630772.861931: Encoding request body and padata into FAST request
[20855] 1492630772.862073: Sending request (957 bytes) to EXAMPLE.ORG (master)
kinit: Generic preauthentication failure while getting initial credentials

Here we opened two connections to the KdcProxy, one with IPv4 and one
with IPv6.  And since the OTP is probably already used by the first
connection, we finally fail.  So, we should try one connection only -
the time between the first and second connect above is about a second.
This seems to be to short to get a valid answer.

If I use only one DNS record, e.g. IPv4, I get (a request seems to take
about two seconds - which looks reasonable: IPA -> ipa-otp -> radius ->
privacyidea):

Enter OTP Token Value: 
[29898] 1492631435.928189: Preauth module otp (141) (real) returned: 0/Success
[29898] 1492631435.928218: Produced preauth for next request: 133, 142
[29898] 1492631435.928239: Encoding request body and padata into FAST request
[29898] 1492631435.928427: Sending request (1152 bytes) to EXAMPLE.ORG
[29898] 1492631435.928478: Resolving hostname freeipa1.example.org
[29898] 1492631435.949930: TLS certificate name matched "freeipa1.example.org"
[29898] 1492631435.974021: Sending HTTPS request to https 192.168.30.121:443
[29898] 1492631437.999513: Received answer (1001 bytes) from https 192.168.30.121:443
[29898] 1492631437.999551: Terminating TCP connection to https 192.168.30.121:443
[29898] 1492631437.999800: Response was not from master KDC
[29898] 1492631437.999871: Decoding FAST response
[29898] 1492631438.38: Processing preauth types: (empty)
[29898] 1492631438.62: Produced preauth for next request: (empty)
[29898] 1492631438.84: Salt derived from principal: EXAMPLE.ORGjochen
[29898] 1492631438.114: AS key determined by preauth: aes256-cts/5322
[29898] 1492631438.206: FAST reply key: aes256-cts/0473
[29898] 1492631438.314: Decrypted AS reply; session key is: aes256-cts/D560
[29898] 1492631438.370: FAST negotiation: available
[29898] 1492631438.418: Initializing FILE:/home/jochen/.byobu/krb5cc_1004 with default princ jochen at EXAMPLE.ORG
[29898] 1492631438.732: Storing jochen at EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG at EXAMPLE.ORG in FILE:/home/jochen/.byobu/krb5cc_1004
[29898] 1492631438.887: Storing config in FILE:/home/jochen/.byobu/krb5cc_1004 for krbtgt/EXAMPLE.ORG at EXAMPLE.ORG: fast_avail: yes
[29898] 1492631438.965: Storing jochen at EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG at X-CACHECONF: in FILE:/home/jochen/.byobu/krb5cc_1004
[29898] 1492631438.1041: Storing config in FILE:/home/jochen/.byobu/krb5cc_1004 for krbtgt/EXAMPLE.ORG at EXAMPLE.ORG: pa_type: 141
[29898] 1492631438.1106: Storing jochen at EXAMPLE.ORG -> krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG at X-CACHECONF: in FILE:/home/jochen/.byobu/krb5cc_1004
Authenticated to Kerberos v5

My best guess right now is, that we add all IP addresses we resolve to
with add_connection(), and try all, but with OTP we shouldn't - at least
not without a longer timeout.

    837     /* Add each address with the specified or preferred transport. */
    838     retval = 0;
    839     for (a = addrs; a != 0 && retval == 0; a = a->ai_next) {
    840         retval = add_connection(conns, transport, defer, a, ind, realm,
    841                                 entry->hostname, portbuf, entry->uri_path,
    842                                 udpbufp);
    843     }
    844 
    845     /* For TCP_OR_UDP entries, add each address again with the non-preferred
    846      * transport, unless we are avoiding UDP.  Flag these as deferred. */
    847     if (retval == 0 && entry->transport == TCP_OR_UDP && strategy != NO_UDP) {
    848         transport = (strategy == UDP_FIRST) ? TCP : UDP;
    849         for (a = addrs; a != 0 && retval == 0; a = a->ai_next) {
    850             a->ai_socktype = socktype_for_transport(transport);
    851             retval = add_connection(conns, transport, TRUE, a, ind, realm,
    852                                     entry->hostname, portbuf,
    853                                     entry->uri_path, udpbufp);
    854         }
    855     }

Maybe also related to the timeout handling in k5_sendto().

What is somewhat confusing for me is that a non-OTP user works fine and
is using only one connection (Ah, IPA delivers an answer quite fast, 0.1
seconds):

Password for jkellner at EXAMPLE.ORG: 
[712] 1492631696.492223: Preauth module encrypted_challenge (138) (real) returned: 0/Success
[712] 1492631696.492251: Produced preauth for next request: 133, 138
[712] 1492631696.492273: Encoding request body and padata into FAST request
[712] 1492631696.492449: Sending request (1177 bytes) to EXAMPLE.ORG
[712] 1492631696.492498: Resolving hostname freeipa1.example.org
[712] 1492631696.501412: TLS certificate name matched "freeipa1.example.org"
[712] 1492631696.504821: Sending HTTPS request to https fd23:e163:19f7:1234:5054:ff:fe85:ba0d:443
[712] 1492631696.607254: Received answer (1038 bytes) from https fd23:e163:19f7:1234:5054:ff:fe85:ba0d:443
[712] 1492631696.607289: Terminating TCP connection to https fd23:e163:19f7:1234:5054:ff:fe85:ba0d:443
[712] 1492631696.607520: Response was not from master KDC
[712] 1492631696.607581: Decoding FAST response
[712] 1492631696.607758: Processing preauth types: 19, 138
[712] 1492631696.607780: Selected etype info: etype aes256-cts, salt "EXAMPLE.ORGjkellner", params ""
[712] 1492631696.607920: Preauth module encrypted_challenge (138) (real) returned: 0/Success
[712] 1492631696.607933: Produced preauth for next request: (empty)
[712] 1492631696.607954: AS key determined by preauth: aes256-cts/B73C
[712] 1492631696.608031: FAST reply key: aes256-cts/239E
[712] 1492631696.608129: Decrypted AS reply; session key is: aes256-cts/DC1E
[712] 1492631696.608183: FAST negotiation: available
[712] 1492631696.608223: Initializing FILE:/home/jochen/.byobu/krb5cc_1004 with default princ jkellner at EXAMPLE.ORG
[712] 1492631696.608521: Storing jkellner at EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG at EXAMPLE.ORG in FILE:/home/jochen/.byobu/krb5cc_1004
[712] 1492631696.608638: Storing config in FILE:/home/jochen/.byobu/krb5cc_1004 for krbtgt/EXAMPLE.ORG at EXAMPLE.ORG: fast_avail: yes
[712] 1492631696.608702: Storing jkellner at EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG at X-CACHECONF: in FILE:/home/jochen/.byobu/krb5cc_1004
[712] 1492631696.608769: Storing config in FILE:/home/jochen/.byobu/krb5cc_1004 for krbtgt/EXAMPLE.ORG at EXAMPLE.ORG: pa_type: 138
[712] 1492631696.608825: Storing jkellner at EXAMPLE.ORG -> krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG at X-CACHECONF: in FILE:/home/jochen/.byobu/krb5cc_1004
Authenticated to Kerberos v5

What do you think is the best way to handle it?  For now I could go back
to IPv4 only for DynDNS, but that's only a band-aid.

Jochen

-- 
This space is intentionally left blank.