Bug 1850445 - kinit switches servers after password change
Summary: kinit switches servers after password change
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: sssd
Version: 32
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: sssd-maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 1881630
TreeView+ depends on / blocked
 
Reported: 2020-06-24 10:29 UTC by François Cami
Modified: 2021-02-23 14:24 UTC (History)
13 users (show)

Fixed In Version:
Clone Of:
: 1881630 (view as bug list)
Environment:
Last Closed: 2021-02-23 14:24:58 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)

Description François Cami 2020-06-24 10:29:02 UTC 
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
Comment 1 Sumit Bose 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
Comment 2 François Cami 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
Comment 3 Robbie Harwood 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.)
Comment 4 François Cami 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.
Comment 5 Robbie Harwood 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.
Comment 6 Sumit Bose 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
Comment 7 Robbie Harwood 2020-09-10 17:31:13 UTC 
Moving to sssd based on #c6.
Comment 8 François Cami 2020-09-22 18:58:49 UTC 
ipatests PR to collect that kdcinfo file: https://github.com/freeipa/freeipa/pull/5128
Comment 9 François Cami 2020-09-24 13:24:16 UTC 

One failed run:
http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/521a5fdc-fe3f-11ea-b659-fa163e7f018b/report.html

has that kdcinfo.$REALM file empty:

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.cmd67:transport.py:513 RUN KRB5_TRACE=/dev/stdout kinit nonadmin
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192214: Getting initial credentials for nonadmin
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192216: Sending unauthenticated request
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192217: Sending request (172 bytes) to IPA.TEST
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192218: Resolving hostname master.ipa.test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192219: Initiating TCP connection to stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192220: Sending TCP request to stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192221: Received answer (496 bytes) from stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192222: Terminating TCP connection to stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192223: Response was from master KDC
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192224: Received error from KDC: -1765328359/Additional pre-authentication required
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192227: Preauthenticating using KDC method data
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192228: 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.cmd67:transport.py:557 [23969] 1600937074.192229: Selected etype info: etype aes256-cts, salt "R!;ANF.whlO2MsA]", params ""
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192230: Received cookie: MIT1\x00\x00\x00\x01\xa9W\x96\xfa\xaa:~\x80x\x07\xe3s\xa5e\x95\x15\x0d\xa9\xc4\xa4\x8bw\xb6\xfa\xff\xc0\xad>\xfd\xe0@\x85\xba\xe67\xa0\x91z\x1c\xd7\x1d\xe5\x9c\xb9\xe1\xe4b\x0f\x89g2\xc5JxVl~\xda\xa5\xb7^uQ\xc7i\x04\xde\x15v\xa8c\x01\xd6\xd4L\xb6\xaf\x08\xaa\xca\x9c\xaa\xcbe\xcd`N\xb1\xbcJ\x88"\xf0,x\x9dYv\xef\xd8^\xf2\x1c\xa6(\xc1\x9c8w&N\xdc\xcf\x91\xc7Dc6\xf9z\x09\x8d\x9c\xe0\x9e\xff\xd2\xefo\x17
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192231: PKINIT client has no configured identity; giving up
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192232: Preauth module pkinit (147) (info) returned: 0/Success
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192233: PKINIT client received freshness token from KDC
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192234: Preauth module pkinit (150) (info) returned: 0/Success
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192235: PKINIT client has no configured identity; giving up
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192236: Preauth module pkinit (16) (real) returned: 22/Invalid argument
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192237: SPAKE challenge received with group 1, pubkey 26E528056D2A8DA13EC403B64DF777B4B24CB70E8EF9ECDD8E4C19749ABCEF42
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 Password for nonadmin: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192238: SPAKE key generated with pubkey 647A1BFAC43D0FCBDD1C23322589ACA1D977A6DC74B741827249D1BFFE2F773C
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192239: SPAKE algorithm result: 53231FC1FF68F4761CD6D90DDEAB2BA162CCF43A32428D07432C59168858A838
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192240: SPAKE final transcript hash: 7F8E20C8E83645406A86C1A359BC28195BC1D9C12A90E86F4854CF4486AC8C2E
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192241: Sending SPAKE response
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192242: Preauth module spake (151) (real) returned: 0/Success
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192243: Produced preauth for next request: PA-FX-COOKIE (133), PA-SPAKE (151)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192244: Sending request (431 bytes) to IPA.TEST
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192245: Resolving hostname master.ipa.test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192246: Initiating TCP connection to stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192247: Sending TCP request to stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192248: Received answer (1521 bytes) from stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192249: Terminating TCP connection to stream 192.168.122.106:88
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192250: Response was from master KDC
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192251: AS key determined by preauth: aes256-cts/48AA
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192252: Decrypted AS reply; session key is: aes256-cts/4F58
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192253: FAST negotiation: available
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192254: Initializing KCM:0 with default princ nonadmin
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192255: Storing nonadmin -> krbtgt/IPA.TEST in KCM:0
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192256: Storing config in KCM:0 for krbtgt/IPA.TEST: fast_avail: yes
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192257: Storing nonadmin -> krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.TEST\@IPA.TEST@X-CACHECONF: in KCM:0
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192258: Storing config in KCM:0 for krbtgt/IPA.TEST: pa_type: 151
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 [23969] 1600937074.192259: Storing nonadmin -> krb5_ccache_conf_data/pa_type/krbtgt\/IPA.TEST\@IPA.TEST@X-CACHECONF: in KCM:0
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:217 Exit code: 0
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:557 cat: /var/lib/sss/pubconf/kdcinfo.IPA.TEST: No such file or directory
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd68:transport.py:217 Exit code: 1
Comment 10 François Cami 2020-09-24 21:02:45 UTC 
Another failed run (test code slightly changed to continue execution):
http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/b4b29442-fea4-11ea-b6de-fa163ebb6b2b/report.html

[ipatests.pytest_ipa.integration.host.Host.master.cmd67] Password for nonadmin: 
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561281: SPAKE key generated with pubkey D44D37FE29E02B8771396C7EEAFF3B68E7FBFB948C01942FDBF966F7114A095C
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561282: SPAKE algorithm result: 1C72AE453C7FB02F8420FEFB3BCC0DD41F8FEDD102EB014212C955CF4F484990
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561283: SPAKE final transcript hash: A38471527EC416C471738CEFBEE0931CC4017FE64253B3FDB766428EE4FBC3CB
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561284: Sending SPAKE response
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561285: Preauth module spake (151) (real) returned: 0/Success
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561286: Produced preauth for next request: PA-FX-COOKIE (133), PA-SPAKE (151)
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561287: Sending request (431 bytes) to IPA.TEST
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561288: Resolving hostname master.ipa.test
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561289: Initiating TCP connection to stream 192.168.122.190:88
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561290: Sending TCP request to stream 192.168.122.190:88
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561291: Received answer (1521 bytes) from stream 192.168.122.190:88
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561292: Terminating TCP connection to stream 192.168.122.190:88
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561293: Response was from master KDC
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561294: AS key determined by preauth: aes256-cts/3D70
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561295: Decrypted AS reply; session key is: aes256-cts/EBCD
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561296: FAST negotiation: available
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561297: Initializing KCM:0 with default princ nonadmin
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561298: Storing nonadmin -> krbtgt/IPA.TEST in KCM:0
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561299: Storing config in KCM:0 for krbtgt/IPA.TEST: fast_avail: yes
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561300: Storing nonadmin -> krb5_ccache_conf_data/fast_avail/krbtgt\/IPA.TEST\@IPA.TEST@X-CACHECONF: in KCM:0
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561301: Storing config in KCM:0 for krbtgt/IPA.TEST: pa_type: 151
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] [24096] 1600980648.561302: Storing nonadmin -> krb5_ccache_conf_data/pa_type/krbtgt\/IPA.TEST\@IPA.TEST@X-CACHECONF: in KCM:0
[ipatests.pytest_ipa.integration.host.Host.master.cmd67] Exit code: 0
[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.
Comment 11 François Cami 2020-09-25 08:36:42 UTC 
Hi,
Please see the two logs above. In some cases the kdcinfo file is not present (but "luckily" sssd picked the right server these two times).
I need to know whether the absence of the kdcinfo file should be considered a hard failure.
See https://github.com/freeipa/freeipa/pull/5128
Thanks 
François
Comment 12 Sumit Bose 2020-09-29 06:03:09 UTC 
(copy of my comment form the github ticket)

Hi,

I think the reason why the kdcinfo file is missing in some cases is that SSSD is offline or not online yet. If SSSD was started only shortly before the test depending on DNS lookups and other network operations SSSD might not be completely online and hence the kdcinfo file was not created yet.

You can check the online status with 'sssctl domain-status --online IPA.TEST'. But you should do this before checking if the kdcinfo file is present because if you check it afterwards SSSD might be already online when calling sssctl. Otherwise there is a race as well but here if sssctl says offline you know at least that it might happen that SSSD is offline when you try to check the prescence of the kdcinfo file.

HTH

bye,
Sumit
Comment 13 Sumit Bose 2021-02-23 14:24:58 UTC 
Hi,

it looks like the test is now working as expected, closing this ticket.

bye,
Sumit
Note You need to log in before you can comment on or make changes to this bug.