Bug 1850445
| Summary: | kinit switches servers after password change | |||
|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | François Cami <fcami> | |
| Component: | sssd | Assignee: | sssd-maintainers <sssd-maintainers> | |
| Status: | CLOSED NOTABUG | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | |
| Severity: | unspecified | Docs Contact: | ||
| Priority: | unspecified | |||
| Version: | 32 | CC: | abokovoy, atikhono, jhrozek, j, lslebodn, mzidek, nalin, npmccallum, pbrezina, rharwood, sbose, ssorce, sssd-maintainers | |
| Target Milestone: | --- | |||
| Target Release: | --- | |||
| Hardware: | Unspecified | |||
| OS: | Unspecified | |||
| Whiteboard: | ||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | ||
| Doc Text: | Story Points: | --- | ||
| Clone Of: | ||||
| : | 1881630 (view as bug list) | Environment: | ||
| Last Closed: | 2021-02-23 14:24:58 UTC | Type: | Bug | |
| Regression: | --- | Mount Type: | --- | |
| Documentation: | --- | CRM: | ||
| Verified Versions: | Category: | --- | ||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | ||
| Cloudforms Team: | --- | Target Upstream Version: | ||
| Embargoed: | ||||
| Bug Depends On: | ||||
| Bug Blocks: | 1881630 | |||
|
Description
François Cami
2020-06-24 10:29:02 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 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 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.) 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. 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. (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 Moving to sssd based on #c6. ipatests PR to collect that kdcinfo file: https://github.com/freeipa/freeipa/pull/5128 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 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. 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 (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 Hi, it looks like the test is now working as expected, closing this ticket. bye, Sumit |