[Sssd-maintainers] [Bug 1881630] New: ipatests-only: kinit_as_user should collect kdcinfo.REALM on failure

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(a)redhat.com
          Reporter: fcami(a)redhat.com
        QA Contact: ipa-qe(a)redhat.com
                CC: abokovoy(a)redhat.com, atikhono(a)redhat.com,
                    extras-qa(a)fedoraproject.org, jhrozek(a)redhat.com,
                    lslebodn(a)redhat.com, mzidek(a)redhat.com,
                    nalin(a)redhat.com, npmccallum(a)redhat.com,
                    pbrezina(a)redhat.com, rcritten(a)redhat.com,
                    rharwood(a)redhat.com, sbose(a)redhat.com,
                    ssorce(a)redhat.com,
                    sssd-maintainers(a)lists.fedoraproject.org,
                    tibbs(a)math.uh.edu, tscherf(a)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(a)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(a)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(a)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(a)IPA.TEST ->
kadmin/changepw(a)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(a)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/3966b...

--- 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/3966b...

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
-- 
You are receiving this mail because:
You are on the CC list for the bug.