Issue #7494: kinit with OTP not working in dual IP stack environments - freeipa

freeipa

#7494 kinit with OTP not working in dual IP stack environments

Opened 6 years ago by dsommers. Modified 5 years ago

Issue

When IPA server and IPA client is in a dual stack IPv4/IPv6 kinit -T is not working on accounts with OTP enabled. Logging in via console/GUI logins/ssh/su/etc works fine with OTP tokens. In these cases (going via sssd), the user is properly asked for both "First token" and "Second token".

When setting the IPv4 only address to the IPA server in /etc/hosts it works when entering password+OTP code.

Update: Forgot to mention that sssd based authentication seem to prefer IPv4 while kinit prefer IPv6 (which should be the correct behaviour) .

Steps to Reproduce

Configure an IPA environment with both IPv4 and IPv6 addresses and ensure firewalling is not blocking any of the IPA ports on either IP stacks.
Configure an IPA account with OTP enforced
Run kinit -T $KEYSTORAGE $USERNAME

Actual behavior

Locally on the client:

$  KRB5_TRACE=/dev/stderr kinit -T KEYRING:persistent:2001:krb_ccache_s9ZZLSs admin
[18933] 1523615279.896925: Resolving unique ccache of type KEYRING
[18933] 1523615279.896926: Getting initial credentials for admin@EXAMPLE.ORG
[18933] 1523615279.896927: FAST armor ccache: KEYRING:persistent:2001:krb_ccache_s9ZZLSs
[18933] 1523615279.896928: Retrieving davids@EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: from KEYRING:persistent:2001:krb_ccache_s9ZZLSs with result: -1765328243/Matching credential not found
[18933] 1523615279.896930: Sending request (179 bytes) to EXAMPLE.ORG
[18933] 1523615279.896931: Resolving hostname ipa.example.org.
[18933] 1523615279.896932: Resolving hostname ipa.example.org.
[18933] 1523615279.896933: Initiating TCP connection to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896934: Sending TCP request to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896935: Received answer (258 bytes) from stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896936: Terminating TCP connection to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896937: Response was from master KDC
[18933] 1523615279.896938: Received error from KDC: -1765328359/Additional pre-authentication required
[18933] 1523615279.896939: Upgrading to FAST due to presence of PA_FX_FAST in reply
[18933] 1523615279.896940: FAST armor ccache: KEYRING:persistent:2001:krb_ccache_s9ZZLSs
[18933] 1523615279.896941: Retrieving davids@EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: from KEYRING:persistent:2001:krb_ccache_s9ZZLSs with result: -1765328243/Matching credential not found
[18933] 1523615279.896942: Getting credentials davids@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG using ccache KEYRING:persistent:2001:krb_ccache_s9ZZLSs
[18933] 1523615279.896943: Retrieving davids@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG from KEYRING:persistent:2001:krb_ccache_s9ZZLSs with result: 0/Success
[18933] 1523615279.896944: Armor ccache sesion key: aes256-cts/2230
[18933] 1523615279.896946: Creating authenticator for davids@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG, seqnum 0, subkey aes256-cts/45BE, session key aes256-cts/2230
[18933] 1523615279.896948: FAST armor key: aes256-cts/B725
[18933] 1523615279.896950: Encoding request body and padata into FAST request
[18933] 1523615279.896951: Sending request (995 bytes) to EXAMPLE.ORG
[18933] 1523615279.896952: Resolving hostname ipa.example.org.
[18933] 1523615279.896953: Resolving hostname ipa.example.org.
[18933] 1523615279.896954: Initiating TCP connection to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896955: Sending TCP request to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896956: Received answer (619 bytes) from stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896957: Terminating TCP connection to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615279.896958: Response was from master KDC
[18933] 1523615279.896959: Received error from KDC: -1765328359/Additional pre-authentication required
[18933] 1523615279.896960: Decoding FAST response
[18933] 1523615279.896963: Processing preauth types: 16, 15, 14, 136, 147, 141, 133, 137
[18933] 1523615279.896964: Received cookie: MIT
Enter OTP Token Value: 
[18933] 1523615291.293967: Preauth module otp (141) (real) returned: 0/Success
[18933] 1523615291.293968: Produced preauth for next request: 133, 142
[18933] 1523615291.293969: Encoding request body and padata into FAST request
[18933] 1523615291.293970: Sending request (1128 bytes) to EXAMPLE.ORG
[18933] 1523615291.293971: Resolving hostname ipa.example.org.
[18933] 1523615291.293972: Resolving hostname ipa.example.org.
[18933] 1523615291.293973: Initiating TCP connection to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615291.293974: Sending TCP request to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615291.293975: Received answer (619 bytes) from stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615291.293976: Terminating TCP connection to stream xxxx:xxxx:xxxx:647::2015:88
[18933] 1523615291.293977: Response was from master KDC
[18933] 1523615291.293978: Received error from KDC: -1765328360/Preauthentication failed
[18933] 1523615291.293979: Decoding FAST response
[18933] 1523615291.293981: Preauth tryagain input types: 16, 15, 14, 136, 147, 141, 133, 137
kinit: Preauthentication failed while getting initial credentials

IPA server side, /var/log/krb5kdc.log

Apr 13 12:27:59 ipa.example.org krb5kdc[1688](info): AS_REQ (8 etypes {18 17 20 19 16 23 25 26}) xxxx:xxxx:xxxx:357::1001: NEEDED_PREAUTH: admin@EXAMPLE.ORG for krbtgt/EXAMPLE.ORG@EXAMPLE.ORG, Additional pre-authentication required
Apr 13 12:27:59 ipa.example.org krb5kdc[1688](info): closing down fd 11
Apr 13 12:27:59 ipa.example.org krb5kdc[1688](info): AS_REQ (8 etypes {18 17 20 19 16 23 25 26}) xxxx:xxxx:xxxx:357::1001: NEEDED_PREAUTH: admin@EXAMPLE.ORG for krbtgt/EXAMPLE.ORG@EXAMPLE.ORG, Additional pre-authentication required
Apr 13 12:27:59 ipa.example.org krb5kdc[1688](info): closing down fd 11
Apr 13 12:28:11 ipa.example.org krb5kdc[1688](info): preauth (otp) verify failure: Generic preauthentication failure
Apr 13 12:28:11 ipa.example.org krb5kdc[1688](info): AS_REQ (8 etypes {18 17 20 19 16 23 25 26}) xxxx:xxxx:xxxx:357::1001: PREAUTH_FAILED: admin@EXAMPLE.ORG for krbtgt/EXAMPLE.ORG@EXAMPLE.ORG, Preauthentication failed
Apr 13 12:28:11 ipa.example.org krb5kdc[1688](info): closing down fd 11

journalctl -u ipa-otpd

Apr 13 12:28:11 ipa.example.org ipa-otpd[13957]: admin@EXAMPLE.ORG: user query start
Apr 13 12:28:11 ipa.example.org ipa-otpd[13957]: admin@EXAMPLE.ORG: user query end: uid=admin,cn=users,cn=accounts,dc=example,dc=org
Apr 13 12:28:11 ipa.example.org ipa-otpd[13957]: admin@EXAMPLE.ORG: bind start: uid=admin,cn=users,cn=accounts,dc=example,dc=org
Apr 13 12:28:11 ipa.example.org ipa-otpd[13957]: admin@EXAMPLE.ORG: bind end: Invalid credentials
Apr 13 12:28:11 ipa.example.org ipa-otpd[13957]: admin@EXAMPLE.ORG: response sent: Access-Reject

For comparison when using su - admin going via sssd. This is from `/var/log/sssd/

(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [main] (0x0400): krb5_child started.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [unpack_buffer] (0x1000): total buffer size: [175]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [unpack_buffer] (0x0100): cmd [241] uid [2000] gid [2000] validate [true] enterprise principal [false] offline [false] UPN [admin@EXAMPLE.ORG]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [unpack_buffer] (0x0100): ccname: [KEYRING:persistent:2000] old_ccname: [KEYRING:persistent:2000] keytab: [/etc/krb5.keytab]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [switch_creds] (0x0200): Switch user to [2000][2000].
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [switch_creds] (0x0200): Switch user to [0][0].
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [k5c_check_old_ccache] (0x4000): Ccache_file is [KEYRING:persistent:2000] and is not active and TGT is  valid.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [k5c_precreate_ccache] (0x4000): Recreating ccache
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [k5c_setup_fast] (0x0100): Fast principal is set to [host/optimus.example.org@EXAMPLE.ORG]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [find_principal_in_keytab] (0x4000): Trying to find principal host/optimus.example.org@EXAMPLE.ORG in keytab.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [match_principal] (0x1000): Principal matched to the sample (host/optimus.example.org@EXAMPLE.ORG).
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [check_fast_ccache] (0x0200): FAST TGT is still valid.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [become_user] (0x0200): Trying to become user [2000][2000].
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [main] (0x2000): Running as [2000][2000].
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [k5c_setup] (0x2000): Running as [2000][2000].
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [set_lifetime_options] (0x0100): No specific renewable lifetime requested.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [set_lifetime_options] (0x0100): No specific lifetime requested.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [set_canonicalize_option] (0x0100): Canonicalization is set to [true]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [main] (0x0400): Will perform online auth
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [tgt_req_child] (0x1000): Attempting to get a TGT
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [get_and_save_tgt] (0x0400): Attempting kinit for realm [EXAMPLE.ORG]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14277: Getting initial credentials for admin@EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14278: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14279: Retrieving host/optimus.example.org@EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.ORG with result: -1765328243/Matching credential not found
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14281: Sending request (179 bytes) to EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14282: Initiating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14283: Sending TCP request to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14284: Received answer (258 bytes) from stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14285: Terminating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14286: Response was from master KDC
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14287: Received error from KDC: -1765328359/Additional pre-authentication required
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14288: Upgrading to FAST due to presence of PA_FX_FAST in reply
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14289: FAST armor ccache: MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14290: Retrieving host/optimus.example.org@EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.ORG with result: -1765328243/Matching credential not found
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14291: Getting credentials host/optimus.example.org@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG using ccache MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14292: Retrieving host/optimus.example.org@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG from MEMORY:/var/lib/sss/db/fast_ccache_EXAMPLE.ORG with result: 0/Success
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14293: Armor ccache sesion key: aes256-cts/12DB
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14295: Creating authenticator for host/optimus.example.org@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG, seqnum 0, subkey aes256-cts/496E, session key aes256-cts/12DB
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14297: FAST armor key: aes256-cts/6761
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14299: Encoding request body and padata into FAST request
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14300: Sending request (1062 bytes) to EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14301: Initiating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14302: Sending TCP request to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14303: Received answer (619 bytes) from stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14304: Terminating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14305: Response was from master KDC
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14306: Received error from KDC: -1765328359/Additional pre-authentication required
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14307: Decoding FAST response
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14310: Processing preauth types: 16, 15, 14, 136, 147, 141, 133, 137
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14311: Received cookie: MIT
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_krb5_responder] (0x4000): Got question [otp].
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14312: Preauth module otp (141) (real) returned: 0/Success
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14313: Produced preauth for next request: 133, 142
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14314: Encoding request body and padata into FAST request
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14315: Sending request (1216 bytes) to EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14316: Initiating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14317: Sending TCP request to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14318: Received answer (1051 bytes) from stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14319: Terminating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14320: Response was from master KDC
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14321: Decoding FAST response
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14322: Processing preauth types: (empty)
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14323: Produced preauth for next request: (empty)
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14324: Salt derived from principal: EXAMPLE.ORGadmin
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14325: AS key determined by preauth: aes256-cts/6761
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14326: FAST reply key: aes256-cts/C6ED
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14327: Decrypted AS reply; session key is: aes256-cts/1A3F
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14328: FAST negotiation: available
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_krb5_expire_callback_func] (0x2000): exp_time: [60340238]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [validate_tgt] (0x2000): Found keytab entry with the realm of the credential.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14329: Retrieving host/optimus.example.org@EXAMPLE.ORG from MEMORY:/etc/krb5.keytab (vno 0, enctype 0) with result: 0/Success
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14330: Resolving unique ccache of type MEMORY
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14331: Initializing MEMORY:91GCyjK with default princ admin@EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14332: Storing admin@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG in MEMORY:91GCyjK
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14333: Getting credentials admin@EXAMPLE.ORG -> host/optimus.example.org@EXAMPLE.ORG using ccache MEMORY:91GCyjK
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14334: Retrieving admin@EXAMPLE.ORG -> host/optimus.example.org@EXAMPLE.ORG from MEMORY:91GCyjK with result: -1765328243/Matching credential not found
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14335: Retrieving admin@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG from MEMORY:91GCyjK with result: 0/Success
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14336: Starting with TGT for client realm: admin@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14337: Requesting tickets for host/optimus.example.org@EXAMPLE.ORG, referrals on
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14338: Generated subkey for TGS request: aes256-cts/8FCB
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14339: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, des3-cbc-sha1, rc4-hmac, camellia128-cts, camellia256-cts
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14341: Encoding request body and padata into FAST request
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14342: Sending request (1105 bytes) to EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14343: Initiating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14344: Sending TCP request to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14345: Received answer (1005 bytes) from stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14346: Terminating TCP connection to stream 172.26.17.215:88
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14347: Response was from master KDC
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14348: Decoding FAST response
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14349: FAST reply key: aes256-cts/BE8F
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14350: TGS reply is for admin@EXAMPLE.ORG -> host/optimus.example.org@EXAMPLE.ORG with session key aes256-cts/9916
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14351: TGS request result: 0/Success
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14352: Received creds for desired service host/optimus.example.org@EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14353: Storing admin@EXAMPLE.ORG -> host/optimus.example.org@EXAMPLE.ORG in MEMORY:91GCyjK
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14354: Creating authenticator for admin@EXAMPLE.ORG -> host/optimus.example.org@EXAMPLE.ORG, seqnum 0, subkey (null), session key aes256-cts/9916
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14356: Retrieving host/optimus.example.org@EXAMPLE.ORG from MEMORY:/etc/krb5.keytab (vno 1, enctype aes256-cts) with result: 0/Success
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14357: Decrypted AP-REQ with specified server principal host/optimus.example.org@EXAMPLE.ORG: aes256-cts/592B
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14358: AP-REQ ticket: admin@EXAMPLE.ORG -> host/optimus.example.org@EXAMPLE.ORG, session key aes256-cts/9916
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14359: Negotiated enctype based on authenticator: aes256-cts
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14360: Initializing MEMORY:rd_req2 with default princ admin@EXAMPLE.ORG
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14361: Storing admin@EXAMPLE.ORG -> host/optimus.example.org@EXAMPLE.ORG in MEMORY:rd_req2
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14362: Destroying ccache MEMORY:91GCyjK
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [validate_tgt] (0x0400): TGT verified using key for [host/optimus.example.org@EXAMPLE.ORG].
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_child_krb5_trace_cb] (0x4000): [20651] 1523616550.14363: Destroying ccache MEMORY:rd_req2
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_get_ccache_name_for_principal] (0x4000): Location: [KEYRING:persistent:2000]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [sss_get_ccache_name_for_principal] (0x4000): tmp_ccname: [KEYRING:persistent:2000:krb_ccache_zc1pUYr]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [create_ccache] (0x4000): Initializing ccache of type [KEYRING]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [create_ccache] (0x4000): CC supports switch
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [create_ccache] (0x4000): returning: 0
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [safe_remove_old_ccache_file] (0x0400): New and old ccache file are the same, none will be deleted.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [k5c_send_data] (0x0200): Received error code 0
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [pack_response_packet] (0x2000): response packet size: [141]
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [k5c_send_data] (0x4000): Response sent.
(Fri Apr 13 12:49:10 2018) [[sssd[krb5_child[20651]]]] [main] (0x0400): krb5_child completed successfully

After enforcing IPv4 only (via /etc/hosts) , this is what happens with kinit -T

$ KRB5_TRACE=/dev/stderr kinit -T KEYRING:persistent:2001:krb_ccache_s9ZZLSs admin
[26455] 1523619309.395464: Getting initial credentials for admin@EXAMPLE.ORG
[26455] 1523619309.395465: FAST armor ccache: KEYRING:persistent:2001:krb_ccache_s9ZZLSs
[26455] 1523619309.395466: Retrieving davids@EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: from KEYRING:persistent:2001:krb_ccache_s9ZZLSs with result: -1765328243/Matching credential not found
[26455] 1523619309.395468: Sending request (179 bytes) to EXAMPLE.ORG
[26455] 1523619309.395469: Initiating TCP connection to stream 172.26.17.215:88
[26455] 1523619309.395470: Sending TCP request to stream 172.26.17.215:88
[26455] 1523619309.395471: Received answer (258 bytes) from stream 172.26.17.215:88
[26455] 1523619309.395472: Terminating TCP connection to stream 172.26.17.215:88
[26455] 1523619309.395473: Response was from master KDC
[26455] 1523619309.395474: Received error from KDC: -1765328359/Additional pre-authentication required
[26455] 1523619309.395475: Upgrading to FAST due to presence of PA_FX_FAST in reply
[26455] 1523619309.395476: FAST armor ccache: KEYRING:persistent:2001:krb_ccache_s9ZZLSs
[26455] 1523619309.395477: Retrieving davids@EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: from KEYRING:persistent:2001:krb_ccache_s9ZZLSs with result: -1765328243/Matching credential not found
[26455] 1523619309.395478: Getting credentials davids@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG using ccache KEYRING:persistent:2001:krb_ccache_s9ZZLSs
[26455] 1523619309.395479: Retrieving davids@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG from KEYRING:persistent:2001:krb_ccache_s9ZZLSs with result: 0/Success
[26455] 1523619309.395480: Armor ccache sesion key: aes256-cts/2230
[26455] 1523619309.395482: Creating authenticator for davids@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG, seqnum 0, subkey aes256-cts/CC1E, session key aes256-cts/2230
[26455] 1523619309.395484: FAST armor key: aes256-cts/0941
[26455] 1523619309.395486: Encoding request body and padata into FAST request
[26455] 1523619309.395487: Sending request (995 bytes) to EXAMPLE.ORG
[26455] 1523619309.395488: Initiating TCP connection to stream 172.26.17.215:88
[26455] 1523619309.395489: Sending TCP request to stream 172.26.17.215:88
[26455] 1523619309.395490: Received answer (619 bytes) from stream 172.26.17.215:88
[26455] 1523619309.395491: Terminating TCP connection to stream 172.26.17.215:88
[26455] 1523619309.395492: Response was from master KDC
[26455] 1523619309.395493: Received error from KDC: -1765328359/Additional pre-authentication required
[26455] 1523619309.395494: Decoding FAST response
[26455] 1523619309.395497: Processing preauth types: 16, 15, 14, 136, 147, 141, 133, 137
[26455] 1523619309.395498: Received cookie: MIT
Enter OTP Token Value: 
[26455] 1523619319.238330: Preauth module otp (141) (real) returned: 0/Success
[26455] 1523619319.238331: Produced preauth for next request: 133, 142
[26455] 1523619319.238332: Encoding request body and padata into FAST request
[26455] 1523619319.238333: Sending request (1149 bytes) to EXAMPLE.ORG
[26455] 1523619319.238334: Initiating TCP connection to stream 172.26.17.215:88
[26455] 1523619319.238335: Sending TCP request to stream 172.26.17.215:88
[26455] 1523619319.238336: Received answer (1051 bytes) from stream 172.26.17.215:88
[26455] 1523619319.238337: Terminating TCP connection to stream 172.26.17.215:88
[26455] 1523619319.238338: Response was from master KDC
[26455] 1523619319.238339: Decoding FAST response
[26455] 1523619319.238340: Processing preauth types: (empty)
[26455] 1523619319.238341: Produced preauth for next request: (empty)
[26455] 1523619319.238342: Salt derived from principal: EXAMPLE.ORGadmin
[26455] 1523619319.238343: AS key determined by preauth: aes256-cts/0941
[26455] 1523619319.238344: FAST reply key: aes256-cts/0F26
[26455] 1523619319.238345: Decrypted AS reply; session key is: aes256-cts/3054
[26455] 1523619319.238346: FAST negotiation: available
[26455] 1523619319.238347: Initializing KEYRING:persistent:2001:krb_ccache_yg3rBBj with default princ admin@EXAMPLE.ORG
[26455] 1523619319.238348: Storing admin@EXAMPLE.ORG -> krbtgt/EXAMPLE.ORG@EXAMPLE.ORG in KEYRING:persistent:2001:krb_ccache_yg3rBBj
[26455] 1523619319.238349: Storing config in KEYRING:persistent:2001:krb_ccache_yg3rBBj for krbtgt/EXAMPLE.ORG@EXAMPLE.ORG: fast_avail: yes
[26455] 1523619319.238350: Storing admin@EXAMPLE.ORG -> krb5_ccache_conf_data/fast_avail/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: in KEYRING:persistent:2001:krb_ccache_yg3rBBj
[26455] 1523619319.238351: Storing config in KEYRING:persistent:2001:krb_ccache_yg3rBBj for krbtgt/EXAMPLE.ORG@EXAMPLE.ORG: pa_type: 141
[26455] 1523619319.238352: Storing admin@EXAMPLE.ORG -> krb5_ccache_conf_data/pa_type/krbtgt\/EXAMPLE.ORG\@EXAMPLE.ORG@X-CACHECONF: in KEYRING:persistent:2001:krb_ccache_yg3rBBj

Version/Release/Distribution

Server: Scientific Linux 7.4 x86_64

 $ rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server
package freeipa-server is not installed
package freeipa-client is not installed
ipa-server-4.5.0-22.sl7_4.x86_64
ipa-client-4.5.0-22.sl7_4.x86_64
389-ds-base-1.3.6.1-28.el7_4.x86_64
pki-ca-10.4.1-17.el7_4.noarch
krb5-server-1.15.1-8.el7.x86_64

Client: RHEL 7.5 x86_64

 $ rpm -q freeipa-server freeipa-client ipa-server ipa-client 389-ds-base pki-ca krb5-server
package freeipa-server is not installed
package freeipa-client is not installed
package ipa-server is not installed
ipa-client-4.5.4-10.el7.x86_64
package 389-ds-base is not installed
package pki-ca is not installed
package krb5-server is not installed

abbra commented 6 years ago

@npmccallum, @rharwood any ideas why IPv6 incoming packets are failing for OTP?

rharwood commented 6 years ago

Looks like a failed LDAP bind. I'm not sure how to get more logging out of that; maybe someone else knows?

dsommers commented 6 years ago

Looks like a failed LDAP bind. I'm not sure how to get more logging out of that; maybe someone else knows?

On the IPA server?

rharwood commented 6 years ago

Yes, I want the logs from the bind attempt.

Metadata Update from @stlaz:
- Issue priority set to: normal
- Issue set to the milestone: FreeIPA 4.8

6 years ago

cheimes commented 5 years ago

@rharwood You can set the global debug level for libldap with

int level = LDAP_DEBUG_TRACE;
ldap_set_option(NULL, LDAP_OPT_DEBUG_LEVEL, &level);

Metadata

Assignee

None

Tags

None

Blocking

None

Depending on

None

Priority

normal

Milestone

FreeIPA 4.8

None

affects_doc

None

source

None

knownissue

None

type

None

blockedby

None

test_case

None

component

None

blocking

None

on_review

None

keywords

None

test_coverage

None

reviewer

None

external_tracker

None

rhbz

None

tester

None

changelog

None

design

None

freeipa

Source Code

#7494 kinit with OTP not working in dual IP stack environments Opened 6 years ago by dsommers. Modified 5 years ago

Close issue as:

Issue

Steps to Reproduce

Actual behavior

Version/Release/Distribution

Metadata

#7494 kinit with OTP not working in dual IP stack environments

Opened 6 years ago by dsommers. Modified 5 years ago