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
Companion dogtag issue: https://pagure.io/dogtagpki/issue/3208
See also https://pagure.io/dogtagpki/issue/3182
After pagure=>github migration: https://github.com/dogtagpki/pki/issues/3299
Closing as duplicate of https://pagure.io/freeipa/issue/8476 Nightly test failure in CA/KRA install on replica: java.io.FilePermission
Metadata Update from @frenaud: - Issue close_status updated to: duplicate - Issue status updated to: Closed (was: Open)