The nightly tests failed on ipa-4-8 while establishing subdomain or treedomain trusts. See PR224 with the following report:
Failed test_integration/test_trust.py::TestTrust::test_establish_external_subdomain_trust Failed test_integration/test_trust.py::TestTrust::test_establish_external_treedomain_trust
In both cases the test failed during ipa trust-add command with the error
ipa trust-add
INFO ipatests.pytest_ipa.integration.host.Host.master.IPAOpenSSHTransport:transport.py:391 RUN ['ipa', 'trust-add', '--type', 'ad', 'child.ad.test', '--range-type', 'ipa-ad-trust', '--external=True', '--admin', 'Administrator', '--password'] DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd361:transport.py:513 RUN ['ipa', 'trust-add', '--type', 'ad', 'child.ad.test', '--range-type', 'ipa-ad-trust', '--external=True', '--admin', 'Administrator', '--password'] DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd361:transport.py:557 ipa: ERROR: error on server 'master.ipa.test': Fetching domains from trusted forest failed. See details in the error_log DEBUG ipatests.pytest_ipa.integration.host.Host.master.cmd361:transport.py:217 Exit code: 1
or
The error_log for httpd contains the following:
ipa: ERROR: Helper fetch_domains was called for forest child.ad.test, return code is 1 ipa: ERROR: Standard output from the helper: --- ipa: ERROR: Error output from the helper: Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/ipaserver/dcerpc.py", line 852, in __gen_lsa_connection result = lsa.lsarpc(binding, self.parm, self.creds) samba.NTSTATUSError: (3221225581, 'The attempted logon is invalid. This is either due to a bad username or authentication information.') During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/libexec/ipa/oddjob/com.redhat.idm.trust-fetch-domains", line 313, in <module> domains = dcerpc.fetch_domains( File "/usr/lib/python3.8/site-packages/ipaserver/dcerpc.py", line 1524, in fetch_domains domains = communicate(td) File "/usr/lib/python3.8/site-packages/ipaserver/dcerpc.py", line 1484, in communicate td.init_lsa_pipe(td.info['dc']) File "/usr/lib/python3.8/site-packages/ipaserver/dcerpc.py", line 876, in init_lsa_pipe self._pipe = self.__gen_lsa_connection(binding) File "/usr/lib/python3.8/site-packages/ipaserver/dcerpc.py", line 855, in __gen_lsa_connection raise assess_dcerpc_error(e) ipalib.errors.RemoteRetrieveError: CIFS server communication error: code "3221225581", message "The attempted logon is invalid. This is either due to a bad username or authentication information." (both may be "None")
Need to check if it's a test error or if there is a regression.
Metadata Update from @frenaud: - Issue tagged with: test-failure, tests
Also happened in [testing_master_latest] in PR #229. Available logs.
So I reproduced it with a smaller set of commands. It looks like a regression in the server referral refactoring code:
[root@master ~]# export KRB5_TRACE=/dev/stderr [root@master ~]# kinit Administrator@win2016.test [37510] 1592376572.747289: Resolving unique ccache of type KCM [37510] 1592376572.747290: Getting initial credentials for Administrator@win2016.test [37510] 1592376572.747292: Sending unauthenticated request [37510] 1592376572.747293: Sending request (187 bytes) to win2016.test [37510] 1592376572.747294: Sending DNS URI query for _kerberos.win2016.test. [37510] 1592376572.747295: No URI records found [37510] 1592376572.747296: Sending DNS SRV query for _kerberos._udp.win2016.test. [37510] 1592376572.747297: SRV answer: 0 100 88 "ad1.win2016.test." [37510] 1592376572.747298: Sending DNS SRV query for _kerberos._tcp.win2016.test. [37510] 1592376572.747299: SRV answer: 0 100 88 "ad1.win2016.test." [37510] 1592376572.747300: Resolving hostname ad1.win2016.test. [37510] 1592376572.747301: Resolving hostname ad1.win2016.test. [37510] 1592376572.747302: Initiating TCP connection to stream 10.0.103.61:88 [37510] 1592376572.747303: Sending TCP request to stream 10.0.103.61:88 [37510] 1592376572.747304: Received answer (186 bytes) from stream 10.0.103.61:88 [37510] 1592376572.747305: Terminating TCP connection to stream 10.0.103.61:88 [37510] 1592376572.747306: Sending DNS URI query for _kerberos.win2016.test. [37510] 1592376572.747307: No URI records found [37510] 1592376572.747308: Sending DNS SRV query for _kerberos-master._tcp.win2016.test. [37510] 1592376572.747309: No SRV records found [37510] 1592376572.747310: Response was not from master KDC [37510] 1592376572.747311: Received error from KDC: -1765328359/Additional pre-authentication required [37510] 1592376572.747314: Preauthenticating using KDC method data [37510] 1592376572.747315: Processing preauth types: PA-PK-AS-REQ (16), PA-PK-AS-REP_OLD (15), PA-ETYPE-INFO2 (19), PA-ENC-TIMESTAMP (2) [37510] 1592376572.747316: Selected etype info: etype aes256-cts, salt "WIN2016.TESTAdministrator", params "" [37510] 1592376572.747317: PKINIT client has no configured identity; giving up [37510] 1592376572.747318: PKINIT client has no configured identity; giving up [37510] 1592376572.747319: Preauth module pkinit (16) (real) returned: 22/Invalid argument Password for Administrator@win2016.test: [37510] 1592376576.013797: AS key obtained for encrypted timestamp: aes256-cts/1064 [37510] 1592376576.013799: Encrypted timestamp (for 1592376575.582361): plain 301AA011180F32303230303631373036343933355AA105020308E2D9, encrypted BC4A850FF7C250D1A6E3487B0C3F3F3C91DCCD3CC76E5081CB22A422E1BB2B330FC21313121D4BE3CAF09A7295276FECDA40D989AF26A056 [37510] 1592376576.013800: Preauth module encrypted_timestamp (2) (real) returned: 0/Success [37510] 1592376576.013801: Produced preauth for next request: PA-ENC-TIMESTAMP (2) [37510] 1592376576.013802: Sending request (267 bytes) to win2016.test [37510] 1592376576.013803: Sending DNS URI query for _kerberos.win2016.test. [37510] 1592376576.013804: No URI records found [37510] 1592376576.013805: Sending DNS SRV query for _kerberos._udp.win2016.test. [37510] 1592376576.013806: SRV answer: 0 100 88 "ad1.win2016.test." [37510] 1592376576.013807: Sending DNS SRV query for _kerberos._tcp.win2016.test. [37510] 1592376576.013808: SRV answer: 0 100 88 "ad1.win2016.test." [37510] 1592376576.013809: Resolving hostname ad1.win2016.test. [37510] 1592376576.013810: Resolving hostname ad1.win2016.test. [37510] 1592376576.013811: Initiating TCP connection to stream 10.0.103.61:88 [37510] 1592376576.013812: Sending TCP request to stream 10.0.103.61:88 [37510] 1592376576.013813: Received answer (1578 bytes) from stream 10.0.103.61:88 [37510] 1592376576.013814: Terminating TCP connection to stream 10.0.103.61:88 [37510] 1592376576.013815: Sending DNS URI query for _kerberos.win2016.test. [37510] 1592376576.013816: No URI records found [37510] 1592376576.013817: Sending DNS SRV query for _kerberos-master._tcp.win2016.test. [37510] 1592376576.013818: No SRV records found [37510] 1592376576.013819: Response was not from master KDC [37510] 1592376576.013820: Processing preauth types: PA-ETYPE-INFO2 (19) [37510] 1592376576.013821: Selected etype info: etype aes256-cts, salt "WIN2016.TESTAdministrator", params "" [37510] 1592376576.013822: Produced preauth for next request: (empty) [37510] 1592376576.013823: AS key determined by preauth: aes256-cts/1064 [37510] 1592376576.013824: Decrypted AS reply; session key is: aes256-cts/FA19 [37510] 1592376576.013825: FAST negotiation: unavailable [37510] 1592376576.013826: Initializing KCM:0:2245 with default princ Administrator@WIN2016.TEST [37510] 1592376576.013827: Storing Administrator@WIN2016.TEST -> krbtgt/WIN2016.TEST@WIN2016.TEST in KCM:0:2245 [37510] 1592376576.013828: Storing config in KCM:0:2245 for krbtgt/WIN2016.TEST@WIN2016.TEST: pa_type: 2 [37510] 1592376576.013829: Storing Administrator@WIN2016.TEST -> krb5_ccache_conf_data/pa_type/krbtgt\/WIN2016.TEST\@WIN2016.TEST@X-CACHECONF: in KCM:0:2245 [root@master ~]# kvno cifs/ad1.win2016.test [37514] 1592376584.912314: Getting credentials Administrator@WIN2016.TEST -> cifs/ad1.win2016.test@IPA.TEST using ccache KCM:0:2245 [37514] 1592376584.912315: Retrieving Administrator@WIN2016.TEST -> cifs/ad1.win2016.test@IPA.TEST from KCM:0:2245 with result: -1765328243/Matching credential not found [37514] 1592376584.912316: Retrieving Administrator@WIN2016.TEST -> krbtgt/IPA.TEST@IPA.TEST from KCM:0:2245 with result: -1765328243/Matching credential not found [37514] 1592376584.912317: Retrieving Administrator@WIN2016.TEST -> krbtgt/WIN2016.TEST@WIN2016.TEST from KCM:0:2245 with result: 0/Success [37514] 1592376584.912318: Starting with TGT for client realm: Administrator@WIN2016.TEST -> krbtgt/WIN2016.TEST@WIN2016.TEST [37514] 1592376584.912319: Retrieving Administrator@WIN2016.TEST -> krbtgt/IPA.TEST@IPA.TEST from KCM:0:2245 with result: -1765328243/Matching credential not found [37514] 1592376584.912320: Requesting TGT krbtgt/IPA.TEST@WIN2016.TEST using TGT krbtgt/WIN2016.TEST@WIN2016.TEST [37514] 1592376584.912321: Generated subkey for TGS request: aes256-cts/335A [37514] 1592376584.912322: etypes requested in TGS request: aes256-cts, aes256-sha2, camellia256-cts, aes128-cts, aes128-sha2, camellia128-cts [37514] 1592376584.912324: Encoding request body and padata into FAST request [37514] 1592376584.912325: Sending request (1698 bytes) to WIN2016.TEST [37514] 1592376584.912326: Sending DNS URI query for _kerberos.WIN2016.TEST. [37514] 1592376584.912327: No URI records found [37514] 1592376584.912328: Sending DNS SRV query for _kerberos._udp.WIN2016.TEST. [37514] 1592376584.912329: SRV answer: 0 100 88 "ad1.win2016.test." [37514] 1592376584.912330: Sending DNS SRV query for _kerberos._tcp.WIN2016.TEST. [37514] 1592376584.912331: SRV answer: 0 100 88 "ad1.win2016.test." [37514] 1592376584.912332: Resolving hostname ad1.win2016.test. [37514] 1592376584.912333: Resolving hostname ad1.win2016.test. [37514] 1592376584.912334: Initiating TCP connection to stream 10.0.103.61:88 [37514] 1592376584.912335: Sending TCP request to stream 10.0.103.61:88 [37514] 1592376584.912336: Received answer (1660 bytes) from stream 10.0.103.61:88 [37514] 1592376584.912337: Terminating TCP connection to stream 10.0.103.61:88 [37514] 1592376584.912338: Sending DNS URI query for _kerberos.WIN2016.TEST. [37514] 1592376584.912339: No URI records found [37514] 1592376584.912340: Sending DNS SRV query for _kerberos-master._tcp.WIN2016.TEST. [37514] 1592376584.912341: No SRV records found [37514] 1592376584.912342: Response was not from master KDC [37514] 1592376584.912343: Decoding FAST response [37514] 1592376584.912344: FAST reply key: aes256-cts/B41F [37514] 1592376584.912345: TGS reply is for Administrator@WIN2016.TEST -> krbtgt/IPA.TEST@WIN2016.TEST with session key aes256-cts/1A74 [37514] 1592376584.912346: TGS request result: 0/Success [37514] 1592376584.912347: Storing Administrator@WIN2016.TEST -> krbtgt/IPA.TEST@WIN2016.TEST in KCM:0:2245 [37514] 1592376584.912348: Received TGT for service realm: krbtgt/IPA.TEST@WIN2016.TEST [37514] 1592376584.912349: Requesting tickets for cifs/ad1.win2016.test@IPA.TEST, referrals on [37514] 1592376584.912350: Generated subkey for TGS request: aes256-cts/5CB9 [37514] 1592376584.912351: etypes requested in TGS request: aes256-cts, aes256-sha2, camellia256-cts, aes128-cts, aes128-sha2, camellia128-cts [37514] 1592376584.912353: Encoding request body and padata into FAST request [37514] 1592376584.912354: Sending request (1693 bytes) to IPA.TEST [37514] 1592376584.912355: Initiating TCP connection to stream 10.0.103.29:88 [37514] 1592376584.912356: Sending TCP request to stream 10.0.103.29:88 [37514] 1592376584.912357: Received answer (435 bytes) from stream 10.0.103.29:88 [37514] 1592376584.912358: Terminating TCP connection to stream 10.0.103.29:88 [37514] 1592376584.912359: Response was from master KDC [37514] 1592376584.912360: Decoding FAST response [37514] 1592376584.912361: TGS request result: -1765328377/Server cifs/ad1.win2016.test@IPA.TEST not found in Kerberos database [37514] 1592376584.912362: Requesting tickets for cifs/ad1.win2016.test@IPA.TEST, referrals off [37514] 1592376584.912363: Generated subkey for TGS request: aes256-cts/BA3A [37514] 1592376584.912364: etypes requested in TGS request: aes256-cts, aes256-sha2, camellia256-cts, aes128-cts, aes128-sha2, camellia128-cts [37514] 1592376584.912366: Encoding request body and padata into FAST request [37514] 1592376584.912367: Sending request (1693 bytes) to IPA.TEST [37514] 1592376584.912368: Initiating TCP connection to stream 10.0.103.29:88 [37514] 1592376584.912369: Sending TCP request to stream 10.0.103.29:88 [37514] 1592376584.912370: Received answer (435 bytes) from stream 10.0.103.29:88 [37514] 1592376584.912371: Terminating TCP connection to stream 10.0.103.29:88 [37514] 1592376584.912372: Response was from master KDC [37514] 1592376584.912373: Decoding FAST response [37514] 1592376584.912374: TGS request result: -1765328377/Server cifs/ad1.win2016.test@IPA.TEST not found in Kerberos database kvno: Server cifs/ad1.win2016.test@IPA.TEST not found in Kerberos database while getting credentials for cifs/ad1.win2016.test@IPA.TEST [root@master ~]# cat /etc/krb5.conf includedir /etc/krb5.conf.d/ includedir /var/lib/sss/pubconf/krb5.include.d/ [logging] default = FILE:/var/log/krb5libs.log kdc = FILE:/var/log/krb5kdc.log admin_server = FILE:/var/log/kadmind.log [libdefaults] default_realm = IPA.TEST dns_lookup_realm = false dns_lookup_kdc = true rdns = false ticket_lifetime = 24h forwardable = true udp_preference_limit = 0 default_ccache_name = KEYRING:persistent:%{uid} [realms] IPA.TEST = { kdc = master.ipa.test:88 master_kdc = master.ipa.test:88 admin_server = master.ipa.test:749 default_domain = ipa.test pkinit_anchors = FILE:/var/lib/ipa-client/pki/kdc-ca-bundle.pem pkinit_pool = FILE:/var/lib/ipa-client/pki/ca-bundle.pem } [domain_realm] .ipa.test = IPA.TEST ipa.test = IPA.TEST master.ipa.test = IPA.TEST [dbmodules] IPA.TEST = { db_library = ipadb.so } [plugins] certauth = { module = ipakdb:kdb/ipadb.so enable_only = ipakdb } [root@master ~]# cat /var/lib/sss/pubconf/krb5.include.d/domain_realm_ipa_test [domain_realm] .win2016.test = WIN2016.TEST win2016.test = WIN2016.TEST [capaths] WIN2016.TEST = { IPA.TEST = WIN2016.TEST } IPA.TEST = { WIN2016.TEST = WIN2016.TEST } [root@master ~]# kvno -S cifs ad1.win2016.test [37533] 1592376644.800655: Getting credentials Administrator@WIN2016.TEST -> cifs/ad1.win2016.test@WIN2016.TEST using ccache KCM:0:2245 [37533] 1592376644.800656: Retrieving Administrator@WIN2016.TEST -> cifs/ad1.win2016.test@WIN2016.TEST from KCM:0:2245 with result: -1765328243/Matching credential not found [37533] 1592376644.800657: Retrieving Administrator@WIN2016.TEST -> krbtgt/WIN2016.TEST@WIN2016.TEST from KCM:0:2245 with result: 0/Success [37533] 1592376644.800658: Starting with TGT for client realm: Administrator@WIN2016.TEST -> krbtgt/WIN2016.TEST@WIN2016.TEST [37533] 1592376644.800659: Requesting tickets for cifs/ad1.win2016.test@WIN2016.TEST, referrals on [37533] 1592376644.800660: Generated subkey for TGS request: aes256-cts/E70F [37533] 1592376644.800661: etypes requested in TGS request: aes256-cts, aes256-sha2, camellia256-cts, aes128-cts, aes128-sha2, camellia128-cts [37533] 1592376644.800663: Encoding request body and padata into FAST request [37533] 1592376644.800664: Sending request (1711 bytes) to WIN2016.TEST [37533] 1592376644.800665: Sending DNS URI query for _kerberos.WIN2016.TEST. [37533] 1592376644.800666: No URI records found [37533] 1592376644.800667: Sending DNS SRV query for _kerberos._udp.WIN2016.TEST. [37533] 1592376644.800668: SRV answer: 0 100 88 "ad1.win2016.test." [37533] 1592376644.800669: Sending DNS SRV query for _kerberos._tcp.WIN2016.TEST. [37533] 1592376644.800670: SRV answer: 0 100 88 "ad1.win2016.test." [37533] 1592376644.800671: Resolving hostname ad1.win2016.test. [37533] 1592376644.800672: Resolving hostname ad1.win2016.test. [37533] 1592376644.800673: Initiating TCP connection to stream 10.0.103.61:88 [37533] 1592376644.800674: Sending TCP request to stream 10.0.103.61:88 [37533] 1592376644.800675: Received answer (1739 bytes) from stream 10.0.103.61:88 [37533] 1592376644.800676: Terminating TCP connection to stream 10.0.103.61:88 [37533] 1592376644.800677: Sending DNS URI query for _kerberos.WIN2016.TEST. [37533] 1592376644.800678: No URI records found [37533] 1592376644.800679: Sending DNS SRV query for _kerberos-master._tcp.WIN2016.TEST. [37533] 1592376644.800680: No SRV records found [37533] 1592376644.800681: Response was not from master KDC [37533] 1592376644.800682: Decoding FAST response [37533] 1592376644.800683: FAST reply key: aes256-cts/477B [37533] 1592376644.800684: TGS reply is for Administrator@WIN2016.TEST -> cifs/ad1.win2016.test@WIN2016.TEST with session key aes256-cts/CDC2 [37533] 1592376644.800685: TGS request result: 0/Success [37533] 1592376644.800686: Received creds for desired service cifs/ad1.win2016.test@WIN2016.TEST [37533] 1592376644.800687: Storing Administrator@WIN2016.TEST -> cifs/ad1.win2016.test@WIN2016.TEST in KCM:0:2245 cifs/ad1.win2016.test@WIN2016.TEST: kvno = 3
The failure doesn't happen anymore: - fedora-latest-ipa-4-8 report - fedora-previous-ipa-4-8 report - fedora-latest report - fedora-previous report
hence closing as fixed.
Metadata Update from @frenaud: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Login to comment on this ticket.