freeipa

Clone
Source Code
GIT

#8510 create_active_user and kinit_as_user should collect kdcinfo.REALM on failure
Closed: fixed 3 years ago by frenaud. Opened 3 years ago by fcami.

Closed: fixed
Reopen Issue

When requesting a tgt fails after a password reset, collecting:

/var/lib/sss/pubconf/kdcinfo.$REALM

will help determine how SSSD was selecting which KRB5KDC to use.
Sample failure:

INFO     ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport:transport.py:391 RUN KRB5_TRACE=/dev/stdout kinit nonadmin
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:513 RUN KRB5_TRACE=/dev/stdout kinit nonadmin
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844338: Resolving unique ccache of type KCM
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844339: Getting initial credentials for nonadmin@IPA.TEST
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844341: Sending unauthenticated request
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844342: Sending request (172 bytes) to IPA.TEST
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844343: Resolving hostname master.ipa.test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844344: Initiating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844345: Sending TCP request to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844346: Received answer (146 bytes) from stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844347: Terminating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844348: Response was from master KDC
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844349: Received error from KDC: -1765328361/Password has expired
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844350: Principal expired; getting changepw ticket
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844351: Getting initial credentials for nonadmin@IPA.TEST
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844352: Setting initial creds service to kadmin/changepw
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844354: Sending unauthenticated request
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844355: Sending request (172 bytes) to IPA.TEST (master)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844356: Resolving hostname master.ipa.test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844357: Initiating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844358: Sending TCP request to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844359: Received answer (495 bytes) from stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844360: Terminating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844361: Received error from KDC: -1765328359/Additional pre-authentication required
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844364: Preauthenticating using KDC method data
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844365: Processing preauth types: PA-PK-AS-REQ (16), PA-FX-FAST (136), PA-ETYPE-INFO2 (19), PA-PKINIT-KX (147), PA-SPAKE (151), PA-ENC-TIMESTAMP (2), PA_AS_FRESHNESS (150), PA-FX-COOKIE (133)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844366: Selected etype info: etype aes256-cts, salt "wes{Lc39)7r=u!-M", params ""
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844367: Received cookie: MIT1\x00\x00\x00\x01\xd7@\xd1\xc4h\xd2"\xd4\xa8\xb4\xed;\xc9\x8b\x1cq\xc3\xf5\x8b\xd6\xae\xa8\x99\xceA\x80\xce\x8cq,w\xba\xcc\x92\xa7Y\xcf\xac\xb1\xfb\xbaT6&\xc4n\x80*.\x9b\x0a\x86\xf9\xce\xce\xaa\xd1\x0d)\xca\xfe\x0b\xe9_\xc5;0\xa6\x83\xdd\xf6f\x9a=\x88Lh\xbc\x12x\xc6\x0c\xb4\x19\xb6\xaauLc\xce\x15\x07l\x16\x93\x8fy\xd1\x9a\xf9\x18PZ$\xc4\xd6\x19\x12\xe8\x88]$\x1d\xea\xf6\x86\x93\xc3\x99K\xe2\xb4\xd7\x02\xf5\xe4\x10\xde\xb5\xd8
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844368: PKINIT client has no configured identity; giving up
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844369: Preauth module pkinit (147) (info) returned: 0/Success
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844370: PKINIT client received freshness token from KDC
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844371: Preauth module pkinit (150) (info) returned: 0/Success
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844372: PKINIT client has no configured identity; giving up
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844373: Preauth module pkinit (16) (real) returned: 22/Invalid argument
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844374: SPAKE challenge received with group 1, pubkey 1B9B313A43995549B59BA4F51F9066335DCE3334D97FDAB096576A1BA1D822E1
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 Password for nonadmin@IPA.TEST: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844375: SPAKE key generated with pubkey B20F03BC7D1A61B59DA95F8CC5665CAF2F0F0A300849DC56B28E31E9ECC2EAE1
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844376: SPAKE algorithm result: C32A756E241A83E9D42D57D829987E91FF18BC0953622EA64E1EB3FA445A4E4F
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844377: SPAKE final transcript hash: C8D1B059189BFFB29661F6829F8914FA10671B34E5682D6FC8E1F56C3784AA1C
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844378: Sending SPAKE response
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844379: Preauth module spake (151) (real) returned: 0/Success
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844380: Produced preauth for next request: PA-FX-COOKIE (133), PA-SPAKE (151)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844381: Sending request (431 bytes) to IPA.TEST (master)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844382: Resolving hostname master.ipa.test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844383: Initiating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844384: Sending TCP request to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844385: Received answer (1521 bytes) from stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844386: Terminating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844387: AS key determined by preauth: aes256-cts/9104
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844388: Decrypted AS reply; session key is: aes256-cts/B14E
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844389: FAST negotiation: available
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844390: Attempting password change; 3 tries remaining
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 Password expired.  You must change it now.
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 Enter new password: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 Enter it again: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844392: Creating authenticator for nonadmin@IPA.TEST -> kadmin/changepw@IPA.TEST, seqnum 0, subkey aes256-cts/8C14, session key aes256-cts/B14E
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844394: Sending DNS URI query for _kpasswd.IPA.TEST.
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844395: No URI records found
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844396: Sending DNS SRV query for _kpasswd._udp.IPA.TEST.
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844397: SRV answer: 0 100 464 "replica0.ipa.test."
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844398: SRV answer: 0 100 464 "master.ipa.test."
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844399: Sending DNS SRV query for _kpasswd._tcp.IPA.TEST.
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844400: SRV answer: 0 100 464 "replica0.ipa.test."
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844401: SRV answer: 0 100 464 "master.ipa.test."
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844402: Resolving hostname replica0.ipa.test.
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844403: Resolving hostname master.ipa.test.
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844404: Resolving hostname replica0.ipa.test.
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844405: Initiating TCP connection to stream 192.168.122.249:464
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795651.844406: Sending TCP request to stream 192.168.122.249:464
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049108: Received answer (236 bytes) from stream 192.168.122.249:464
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049109: Terminating TCP connection to stream 192.168.122.249:464
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049110: Read AP-REP, time 1600795651.844393, subkey aes256-cts/8C14, seqnum 216537285
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049111: Getting initial TGT with changed password
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049112: Getting initial credentials for nonadmin@IPA.TEST
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049114: Sending unauthenticated request
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049115: Sending request (172 bytes) to IPA.TEST (master)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049116: Resolving hostname master.ipa.test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049117: Initiating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049118: Sending TCP request to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049119: Received answer (147 bytes) from stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049120: Terminating TCP connection to stream 192.168.122.146:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 [23614] 1600795652.049121: Received error from KDC: -1765328361/Password has expired
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:557 kinit: Password has expired while getting initial credentials
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd65:transport.py:217 Exit code: 1
ERROR    ipatests.pytest_ipa.integration.host.Host.master.cmd65:host.py:199 stderr: kinit: Password has expired while getting initial credentials

Metadata Update from @fcami:
- Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/5128
3 years ago

Metadata Update from @fcami:
- Custom field rhbz adjusted to https://bugzilla.redhat.com/show_bug.cgi?id=1881630
3 years ago

the code changes in the PR result in the following:

INFO     ipatests.pytest_ipa.integration.tasks:tasks.py:2020 Collecting kdcinfo log from: master.ipa.test
INFO     ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport:transport.py:436 GET /var/lib/sss/pubconf/kdcinfo.IPA.TEST
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd68:transport.py:513 RUN ['cat', '/var/lib/sss/pubconf/kdcinfo.IPA.TEST']
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd68:transport.py:217 Exit code: 0
INFO     ipatests.pytest_ipa.integration.tasks:tasks.py:2027 kdcinfo master.ipa.test contains:
b'192.168.122.69\n'

whether the kinit succeeds or not, provided kinit_as_user was called with krb5_trace=True.

Metadata Update from @fcami:
- Custom field changelog adjusted to Sometimes, requesting a TGT after a password reset fails because SSSD seems to select different hosts for these two sequential tasks, leaving no time for replication to replicate the password hashes. Add debug information to the test suites that exhibit the problem and always display the kdcinfo file maintained by SSSD that contains the KRB5KDC IP it should be pinned to.
3 years ago

The new version only breaks when the kinit's return code is >0.
Failing to retrieve the kdcinfo file is not an issue for IPA per se.

Another run showing empty kdcinfo:

[ipatests.pytest_ipa.integration.tasks] Collecting kdcinfo log from: master.ipa.test
[ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport] GET /var/lib/sss/pubconf/kdcinfo.IPA.TEST
[ipatests.pytest_ipa.integration.host.Host.master.cmd68] RUN ['cat', '/var/lib/sss/pubconf/kdcinfo.IPA.TEST']
[ipatests.pytest_ipa.integration.host.Host.master.cmd68] cat: /var/lib/sss/pubconf/kdcinfo.IPA.TEST: No such file or directory
[ipatests.pytest_ipa.integration.host.Host.master.cmd68] Exit code: 1
ipa: WARNING: Exception collecting kdcinfo.IPA.TEST: File '/var/lib/sss/pubconf/kdcinfo.IPA.TEST' could not be read
SSSD is able to function without this file but logon attempts immediately after a password change might break.

master:

  • a63eeaa ipatests: add check_if_sssd_is_online
  • 884e0d3 ipatests: add get_kdcinfo
  • e0586f3 ipatests: create_active_user improvements
  • 5d95794 ipatests: kinit_as_user improvements

ipa-4-8:

  • 03ac127 ipatests: add check_if_sssd_is_online
  • 27bcd30 ipatests: add get_kdcinfo
  • cc9380f ipatests: create_active_user improvements
  • cd15ceb ipatests: kinit_as_user improvements

Metadata Update from @frenaud:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)
3 years ago

Login to comment on this ticket.

Metadata

tests test-failure

None
None
None
None
None
None
None
None
None
None
None
None
None
https://github.com/freeipa/freeipa/pull/5128
None
None
None
None
https://bugzilla.redhat.com/show_bug.cgi?id=1881630
None
Sometimes, requesting a TGT after a password reset fails because SSSD seems to select different hosts for these two sequential tasks, leaving no time for replication to replicate the password hashes. Add debug information to the test suites that exhibit the problem and always display the kdcinfo file maintained by SSSD that contains the KRB5KDC IP it should be pinned to.
None
Powered by Pagure 5.13.3
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.