RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1881630 - ipatests-only: kinit_as_user should collect kdcinfo.REALM on failure
Summary: ipatests-only: kinit_as_user should collect kdcinfo.REALM on failure
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: ipa
Version: 8.3
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: 8.0
Assignee: François Cami
QA Contact: ipa-qe
URL:
Whiteboard:
Depends On: 1850445
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-09-22 19:09 UTC by François Cami
Modified: 2020-11-03 20:45 UTC (History)
16 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1850445
Environment:
Last Closed: 2020-10-27 13:23:05 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)

Description François Cami 2020-09-22 19:09:28 UTC 
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
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
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: 
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 -> kadmin/changepw, 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
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-b5f9-11ea-89ba-fa163eef7a64/report.html

--- 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-b5f9-11ea-89ba-fa163eef7a64/test_integration-test_adtrust_install.py-TestIpaAdTrustInstall-test_add_agent_not_allowed/

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
Comment 2 François Cami 2020-10-27 13:23:05 UTC 
Closing as this improvement is test-only and fixed upstream ( https://pagure.io/freeipa/issue/8510 ).
Note You need to log in before you can comment on or make changes to this bug.