https://bugzilla.redhat.com/show_bug.cgi?id=1881630

Bug ID: 1881630 Summary: ipatests-only: kinit_as_user should collect kdcinfo.REALM on failure Product: Red Hat Enterprise Linux 8 Version: 8.3 Status: NEW Component: ipa Assignee: twoerner@redhat.com Reporter: fcami@redhat.com QA Contact: ipa-qe@redhat.com CC: abokovoy@redhat.com, atikhono@redhat.com, extras-qa@fedoraproject.org, jhrozek@redhat.com, lslebodn@redhat.com, mzidek@redhat.com, nalin@redhat.com, npmccallum@redhat.com, pbrezina@redhat.com, rcritten@redhat.com, rharwood@redhat.com, sbose@redhat.com, ssorce@redhat.com, sssd-maintainers@lists.fedoraproject.org, tibbs@math.uh.edu, tscherf@redhat.com Depends On: 1850445 Target Milestone: rc Classification: Red Hat Pool ID: sst_identity_management_rhel_8

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.

See https://pagure.io/freeipa/issue/8510 for details.

+++ This bug was initially created as a clone of Bug #1850445 +++

kinit switches KDC for each action. It would be better if it kept track of which KDC to use, because on password change, it sometimes contacts one KDC to change the password and then another one, immediately, to get a TGT, which fails because replication between the two KDCs has not completed yet.

DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:513 RUN KRB5_TRACE=/dev/stdout kinit nonadmin DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325347: Resolving unique ccache of type KCM DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325348: Getting initial credentials for nonadmin@IPA.TEST DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325350: Sending unauthenticated request DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325351: Sending request (172 bytes) to IPA.TEST DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325352: Resolving hostname master.ipa.test DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325353: Initiating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325354: Sending TCP request to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325355: Received answer (147 bytes) from stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325356: Terminating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325357: Response was from master KDC DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325358: Received error from KDC: -1765328361/Password has expired DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325359: Principal expired; getting changepw ticket DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325360: Getting initial credentials for nonadmin@IPA.TEST DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325361: Setting initial creds service to kadmin/changepw DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325363: Sending unauthenticated request DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325364: Sending request (172 bytes) to IPA.TEST (master) DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325365: Resolving hostname master.ipa.test DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325366: Initiating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325367: Sending TCP request to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325368: Received answer (496 bytes) from stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325369: Terminating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325370: Received error from KDC: -1765328359/Additional pre-authentication required DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325373: Preauthenticating using KDC method data DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325374: 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.cmd64:transport.py:557 [24275] 1592990743.325375: Selected etype info: etype aes256-cts, salt ".#7bJ)L)J"mP,T7", params "" DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325376: Received cookie: MIT1\x00\x00\x00\x01\xe0w\xf7\xd1|$\xa4\x14\x01\xea\x08\x0c\xe7\xf6&\xd6\xb0\x8d\xd1\x9dw/\x98\x14\x81\xe2\xf372\xc5\xb6\xc0k^\xd1\x9b\xe3R\xd4?^\x11\xecyd\x05\xb5>\x93\xdd\x94\x0e\x0a\xc7.\xb2\x84E\xb7El\x87\xbaa\x9b\xae\x9e\xa6d\xf4\xf7m\xf4W\x11~]\xfecR@[\xef\xdc3W\x1f\xe8\xa7\x07\xae\xd5\x12\x15\xc4\xa2\xb6\xa0\x0b\xab\x09cv\x8741s\x18\xc9\xee\xa9\x13Qu\xd6+\xb7\xe9\xf8V\xf0\xf9@\x95\xbb\x8c\x9d\x92\xcb\xbd DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325377: PKINIT client has no configured identity; giving up DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325378: Preauth module pkinit (147) (info) returned: 0/Success DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325379: PKINIT client received freshness token from KDC DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325380: Preauth module pkinit (150) (info) returned: 0/Success DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325381: PKINIT client has no configured identity; giving up DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325382: Preauth module pkinit (16) (real) returned: 22/Invalid argument DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325383: SPAKE challenge received with group 1, pubkey 1B0BEF657989B0A997331DC1C3FE27B3DDA988E0CCDE4AD1953E63654308BB8A DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 Password for nonadmin@IPA.TEST: DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325384: SPAKE key generated with pubkey E7799A68439AF32E18B1899FA0D7145F70FD5345C6F59F5EB4463754CE1C45C3 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325385: SPAKE algorithm result: F305A9105E6AE9531D6F6041EE348B146FB937039B3FFA1BD3A614638269AA91 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325386: SPAKE final transcript hash: 273E7D21D701511A5FEB8D9EE1A817D34F4CFE0DA9849260A6D3654B59A7A965 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325387: Sending SPAKE response DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325388: Preauth module spake (151) (real) returned: 0/Success DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325389: Produced preauth for next request: PA-FX-COOKIE (133), PA-SPAKE (151) DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325390: Sending request (431 bytes) to IPA.TEST (master) DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325391: Resolving hostname master.ipa.test DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325392: Initiating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325393: Sending TCP request to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325394: Received answer (1521 bytes) from stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325395: Terminating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325396: AS key determined by preauth: aes256-cts/108D DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325397: Decrypted AS reply; session key is: aes256-cts/755F DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325398: FAST negotiation: available DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325399: Attempting password change; 3 tries remaining DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 Password expired. You must change it now. DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 Enter new password: DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 Enter it again: DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325401: Creating authenticator for nonadmin@IPA.TEST -> kadmin/changepw@IPA.TEST, seqnum 0, subkey aes256-cts/D865, session key aes256-cts/755F DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325403: Sending DNS URI query for _kpasswd.IPA.TEST. DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325404: No URI records found DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325405: Sending DNS SRV query for _kpasswd._udp.IPA.TEST. DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325406: SRV answer: 0 100 464 "replica0.ipa.test." DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325407: SRV answer: 0 100 464 "master.ipa.test." DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325408: Sending DNS SRV query for _kpasswd._tcp.IPA.TEST. DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325409: SRV answer: 0 100 464 "replica0.ipa.test." DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325410: SRV answer: 0 100 464 "master.ipa.test." DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325411: Resolving hostname replica0.ipa.test. DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325412: Resolving hostname master.ipa.test. DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325413: Resolving hostname replica0.ipa.test. DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325414: Initiating TCP connection to stream 192.168.122.43:464 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325415: Sending TCP request to stream 192.168.122.43:464 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325416: Received answer (236 bytes) from stream 192.168.122.43:464 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325417: Terminating TCP connection to stream 192.168.122.43:464 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325418: Read AP-REP, time 1592990743.325402, subkey aes256-cts/D865, seqnum 469261493 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325419: Getting initial TGT with changed password DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325420: Getting initial credentials for nonadmin@IPA.TEST DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325422: Sending unauthenticated request DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325423: Sending request (172 bytes) to IPA.TEST (master) DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325424: Resolving hostname master.ipa.test DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325425: Initiating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325426: Sending TCP request to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 kinit: Password has expired while getting initial credentials DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325427: Received answer (147 bytes) from stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325428: Terminating TCP connection to stream 192.168.122.35:88 DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:557 [24275] 1592990743.325429: Received error from KDC: -1765328361/Password has expired DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd64:transport.py:217 Exit code: 1 ERROR ipatests.pytest_ipa.integration.host.Host.master.cmd64:host.py:199 stderr: kinit: Password has expired while getting initial credentials

full logs: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/3966b69a...

--- Additional comment from Sumit Bose on 2020-06-24 15:43:03 UTC ---

Hi,

do you know if SSSD is running during the test? If yes, can you check if /var/lib/sss/pubconf/kdcinfo.IPA.TEST exists and contains one or more IP addresses of IPA servers? This file is read by SSSD's locator plugin which should make sure libkrb5 uses the same KDC for a long time.

bye, Sumit

--- Additional comment from François Cami on 2020-06-24 16:22:57 UTC ---

Hi Sumit,

The machine logs for the test are available at: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/3966b69a...

The timestamp for the error is 1592990743.325347 (Wednesday, June 24, 2020 9:25:43.325 AM) and the journal seems to imply SSSD was started at this point. Sadly the VMs used for the test are ephemeral and the above test fails only sporadically. I will add a step to display /var/lib/sss/pubconf/kdcinfo.IPA.TEST similarly to the way I added KRB5_TRACE=/dev/stdout to get more information.

Thanks, François

--- Additional comment from Robbie Harwood on 2020-06-25 19:09:32 UTC ---

Would also like to see the sssd information.

(I will note that krb5 expects there to be a single master_kdc that is authoratative for password changes. If that address resolves to multiple KDCs, they need to agree on the state of the world.)

--- Additional comment from François Cami on 2020-06-25 19:36:57 UTC ---

Robbie, do you need more information than what is seen in the PR: https://github.com/freeipa/freeipa/pull/4853 Especially: https://github.com/freeipa/freeipa/pull/4853#issuecomment-649235842

The test blows up very sporadically. I've triggered it 16 times today without any issue. If within a month I haven't seen it red, I will trigger a 100+ run and we might get a bad run with interesting logs.

--- Additional comment from Robbie Harwood on 2020-06-25 20:51:09 UTC ---

Ah sorry, race condition - I started my comment before yours appeared. I've subscribed to the issue. Per #c3, I think that master_kdc isn't being correctly used - it seems like Sumit is investigating where the multiple values come from.

--- Additional comment from Sumit Bose on 2020-06-26 11:30:23 UTC ---

(In reply to Robbie Harwood from comment #5)

Ah sorry, race condition - I started my comment before yours appeared. I've subscribed to the issue. Per #c3, I think that master_kdc isn't being correctly used - it seems like Sumit is investigating where the multiple values come from.

Hi,

in the current logs there was only one IP address and this will be used for the master as well. As long there is a kdcinfo file SSSD's Kerberos locator plugin should use the data and iirc libkrb5 will always ask the available locator plugins first before trying other methods to find a KDC. Since the KRB5_TRACE output in the description has e.g. 'Sending DNS URI query for _kpasswd.IPA.TEST.' I would expect that the kdcinfo file did not exist in this run. Maybe SSSD had some delays when trying to connect to the IPA server and as a result the creation of the kdcinfo file was delayed as wel?

bye, Sumit

--- Additional comment from Robbie Harwood on 2020-09-10 17:31:13 UTC ---

Moving to sssd based on #c6.

--- Additional comment from François Cami on 2020-09-22 18:58:49 UTC ---

ipatests PR to collect that kdcinfo file: https://github.com/freeipa/freeipa/pull/5128

Referenced Bugs:

https://bugzilla.redhat.com/show_bug.cgi?id=1850445 [Bug 1850445] kinit switches servers after password change