#8477 [PKI] Nightly test failure in test_installation.py::TestADTrustInstall::test_replica1_all_components_adtrust
Opened 4 months ago by fcami. Modified 2 months ago

During testing_master_testing Nightly PR #367 pkispawn failed (ipa-replica-install) on replica1.

logs

master logs seem OK:

2020-08-23 05:57:42 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PKIRealm: Authenticating user admin-replica1.ipa.test with password
2020-08-23 05:57:42 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PasswdUserDBAuthentication: authenticating UID: admin-replica1.ipa.test
2020-08-23 05:57:42 [ajp-nio-127.0.0.1-8009-exec-7] INFO: UGSubsystem: retrieving user uid=admin-replica1.ipa.test,ou=People,o=ipaca
2020-08-23 05:57:42 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PasswdUserDBAuthentication: DN: uid=admin-replica1.ipa.test,ou=people,o=ipaca
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: UID admin-replica1.ipa.test authenticated.
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: UGSubsystem: retrieving user uid=admin-replica1.ipa.test,ou=People,o=ipaca
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PKIRealm: User DN: uid=admin-replica1.ipa.test,ou=people,o=ipaca
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PKIRealm: Roles:
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PKIRealm: - Security Domain Administrators
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PKIRealm: - Enterprise CA Administrators
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: PKIRealm: - Enterprise KRA Administrators
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: AAclAuthz: Granting login permission for certServer.ca.account
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: Creating session 296F58A734F26030CD63AC8CBD5504AA
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: Principal:
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: - ID: admin-replica1.ipa.test
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: - Full Name: admin-replica1.ipa.test
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: - Email: 
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO: - Roles:
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO:   - Enterprise CA Administrators
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO:   - Enterprise KRA Administrators
2020-08-23 05:57:43 [ajp-nio-127.0.0.1-8009-exec-7] INFO:   - Security Domain Administrators
2020-08-23 05:58:01 [ajp-nio-127.0.0.1-8009-exec-8] INFO: AAclAuthz: Granting read permission for certServer.securitydomain.domainxml
2020-08-23 05:58:01 [ajp-nio-127.0.0.1-8009-exec-8] INFO: UGSubsystem: retrieving user uid=admin-replica1.ipa.test,ou=People,o=ipaca
2020-08-23 05:58:01 [ajp-nio-127.0.0.1-8009-exec-8] INFO: SecurityDomainSessionTable: added session entry 6228613448663968649

logs on replica1 show:

2020-08-23T05:57:39Z DEBUG Waiting 300 seconds for uid=admin-replica1.ipa.test,ou=people,o=ipaca to appear on ldap://master.ipa.test:389
2020-08-23T05:57:40Z DEBUG Successfully logged in as uid=admin-replica1.ipa.test,ou=people,o=ipaca
2020-08-23T05:57:40Z DEBUG Waiting up to 300 seconds for replication (ldap://master.ipa.test:389) cn=Enterprise CA Administrators,ou=groups,o=ipaca (uniqueMember=uid=admin-replica1.ipa.test,ou=people,o=ipaca)
2020-08-23T05:57:40Z DEBUG Entry found [LDAPEntry(ipapython.dn.DN('cn=Enterprise CA Administrators,ou=groups,o=ipaca'), {'uniquemember': [b'uid=admin,ou=People,o=ipaca', b'uid=admin-replica1.ipa.test,ou=people,o=ipaca']})]
2020-08-23T05:57:40Z DEBUG Waiting up to 300 seconds for replication (ldap://master.ipa.test:389) cn=Enterprise KRA Administrators,ou=groups,o=ipaca (uniqueMember=uid=admin-replica1.ipa.test,ou=people,o=ipaca)
2020-08-23T05:57:40Z DEBUG Entry found [LDAPEntry(ipapython.dn.DN('cn=Enterprise KRA Administrators,ou=groups,o=ipaca'), {'uniquemember': [b'uid=admin,ou=People,o=ipaca', b'uid=admin-replica1.ipa.test,ou=people,o=ipaca']})]
2020-08-23T05:57:40Z DEBUG Waiting up to 300 seconds for replication (ldap://master.ipa.test:389) cn=Security Domain Administrators,ou=groups,o=ipaca (uniqueMember=uid=admin-replica1.ipa.test,ou=people,o=ipaca)
2020-08-23T05:57:40Z DEBUG Entry found [LDAPEntry(ipapython.dn.DN('cn=Security Domain Administrators,ou=groups,o=ipaca'), {'uniquemember': [b'uid=admin,ou=People,o=ipaca', b'uid=admin-replica1.ipa.test,ou=people,o=ipaca']})]
2020-08-23T05:57:40Z DEBUG step duration: pki-tomcatd setup_admin 1.14 sec

so the user was replicated. The attempt fails later:

2020-08-23T05:59:04Z DEBUG stderr=Notice: Trust flag u is set automatically if the private key is present.
WARNING: Unable to modify o=ipaca: netscape.ldap.LDAPException: error result (20); Type or value exists
PKIException: Internal Server Error
ERROR: CalledProcessError: Command '['pki', '-d', '/etc/pki/pki-tomcat/alias', '-f', '/etc/pki/pki-tomcat/password.conf', '-U', 'https://master.ipa.test:443', 'ca-range-request', 'request', '--session', '6228613448663968649', '--output-format', 'json']' returned non-zero exit status 255.
  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 575, in main
    scriptlet.spawn(deployer)
  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 854, in spawn
    subsystem.update_ranges(master_url, deployer.install_token)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 975, in update_ranges
    request_range = self.request_range(master_url, 'request', install_token)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 967, in request_range
    output = subprocess.check_output(cmd)
  File "/usr/lib64/python3.8/subprocess.py", line 411, in check_output
    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,
  File "/usr/lib64/python3.8/subprocess.py", line 512, in run
    raise CalledProcessError(retcode, process.args,


2020-08-23T05:59:04Z CRITICAL Failed to configure CA instance: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmpruyozfju'] returned non-zero exit status 1: 'Notice: Trust flag u is set automatically if the private key is present.\nWARNING: Unable to modify o=ipaca: netscape.ldap.LDAPException: error result (20); Type or value exists\nPKIException: Internal Server Error\nERROR: CalledProcessError: Command \'[\'pki\', \'-d\', \'/etc/pki/pki-tomcat/alias\', \'-f\', \'/etc/pki/pki-tomcat/password.conf\', \'-U\', \'https://master.ipa.test:443\', \'ca-range-request\', \'request\', \'--session\', \'6228613448663968649\', \'--output-format\', \'json\']\' returned non-zero exit status 255.\n  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 575, in main\n    scriptlet.spawn(deployer)\n  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 854, in spawn\n    subsystem.update_ranges(master_url, deployer.install_token)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 975, in update_ranges\n    request_range = self.request_range(master_url, \'request\', install_token)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 967, in request_range\n    output = subprocess.check_output(cmd)\n  File "/usr/lib64/python3.8/subprocess.py", line 411, in check_output\n    return run(*popenargs, stdout=PIPE, timeout=timeout, check=True,\n  File "/usr/lib64/python3.8/subprocess.py", line 512, in run\n    raise CalledProcessError(retcode, process.args,\n\n')
2020-08-23T05:59:04Z CRITICAL See the installation logs and the following files/directories for more information:
2020-08-23T05:59:04Z CRITICAL   /var/log/pki/pki-tomcat

Login to comment on this ticket.

Metadata