#3206 Nightly test failure in ipa-server-install while calling pki-server acme-deploy (with pki nightly repo)
Closed: fixed 3 years ago by frenaud. Opened 3 years ago by frenaud.

FreeIPA nightly tests are failing in ipa-server-install in the pkispawn step, when using pki nightly copr repo. See the PR #353, with the following report and logs.

ipa-server-install logs:

2020-08-16T20:29:32Z DEBUG Starting external process
2020-08-16T20:29:32Z DEBUG args=['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmps1az97js']
2020-08-16T20:30:06Z DEBUG Process finished, return code=1
2020-08-16T20:30:06Z DEBUG stdout=Loading deployment configuration from /tmp/tmps1az97js.
WARNING: The 'pki_ssl_server_token' in [CA] has been deprecated. Use 'pki_sslserver_token' instead.
Installation log: /var/log/pki/pki-ca-spawn.20200816202933.log
Installing CA into /var/lib/pki/pki-tomcat.

Installation failed: Command failed: /usr/sbin/runuser -u pkiuser -- /usr/lib/jvm/jre-openjdk/bin/java -classpath /usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/tomcat-servlet-api.jar:/usr/share/pki/ca/webapps/ca/WEB-INF/lib/*:/var/lib/pki/pki-tomcat/common/lib/*:/usr/share/pki/lib/* -Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory -Dcatalina.base=/var/lib/pki/pki-tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp -Djava.util.logging.config.file=/etc/pki/pki-tomcat/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dcom.redhat.fips=false org.dogtagpki.server.cli.PKIServerCLI ca-db-init --setup-schema --create-database --create-base --create-containers --setup-db-manager --setup-vlv-indexes

Please check pkispawn logs in /var/log/pki/pki-ca-spawn.20200816202933.log

2020-08-16T20:30:06Z DEBUG stderr=Notice: Trust flag u is set automatically if the private key is present.
Exception in thread "main" java.io.FileNotFoundException: /usr/share/pki/acme/database/ldap/schema.ldif (No such file or directory)
    at java.io.FileInputStream.open0(Native Method)
    at java.io.FileInputStream.open(FileInputStream.java:195)
    at java.io.FileInputStream.<init>(FileInputStream.java:138)
    at java.io.FileInputStream.<init>(FileInputStream.java:93)
    at netscape.ldap.util.LDIF.<init>(Unknown Source)
    at com.netscape.cms.servlet.csadmin.LDAPConfigurator.importSchemaFile(LDAPConfigurator.java:522)
    at com.netscape.cms.servlet.csadmin.LDAPConfigurator.setupSchema(LDAPConfigurator.java:90)
    at org.dogtagpki.server.cli.SubsystemDBInitCLI.execute(SubsystemDBInitCLI.java:129)
    at org.dogtagpki.cli.CommandCLI.execute(CommandCLI.java:57)
    at org.dogtagpki.cli.CLI.execute(CLI.java:352)
    at org.dogtagpki.cli.CLI.execute(CLI.java:352)
    at org.dogtagpki.cli.CLI.execute(CLI.java:352)
    at org.dogtagpki.server.cli.PKIServerCLI.execute(PKIServerCLI.java:86)
    at org.dogtagpki.server.cli.PKIServerCLI.main(PKIServerCLI.java:92)
ERROR: CalledProcessError: Command '['/usr/sbin/runuser', '-u', 'pkiuser', '--', '/usr/lib/jvm/jre-openjdk/bin/java', '-classpath', '/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/tomcat-servlet-api.jar:/usr/share/pki/ca/webapps/ca/WEB-INF/lib/*:/var/lib/pki/pki-tomcat/common/lib/*:/usr/share/pki/lib/*', '-Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory', '-Dcatalina.base=/var/lib/pki/pki-tomcat', '-Dcatalina.home=/usr/share/tomcat', '-Djava.endorsed.dirs=', '-Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp', '-Djava.util.logging.config.file=/etc/pki/pki-tomcat/logging.properties', '-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager', '-Dcom.redhat.fips=false', 'org.dogtagpki.server.cli.PKIServerCLI', 'ca-db-init', '--setup-schema', '--create-database', '--create-base', '--create-containers', '--setup-db-manager', '--setup-vlv-indexes']' returned non-zero exit status 1.
  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 840, in spawn
    subsystem.init_database(
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 915, in init_database
    self.run(cmd, as_current_user=as_current_user)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 1137, in run
    subprocess.run(cmd, check=True)
  File "/usr/lib64/python3.8/subprocess.py", line 512, in run
    raise CalledProcessError(retcode, process.args,


2020-08-16T20:30:06Z CRITICAL Failed to configure CA instance: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmps1az97js'] returned non-zero exit status 1: 'Notice: Trust flag u is set automatically if the private key is present.\nException in thread "main" java.io.FileNotFoundException: /usr/share/pki/acme/database/ldap/schema.ldif (No such file or directory)\n\tat java.io.FileInputStream.open0(Native Method)\n\tat java.io.FileInputStream.open(FileInputStream.java:195)\n\tat java.io.FileInputStream.<init>(FileInputStream.java:138)\n\tat java.io.FileInputStream.<init>(FileInputStream.java:93)\n\tat netscape.ldap.util.LDIF.<init>(Unknown Source)\n\tat com.netscape.cms.servlet.csadmin.LDAPConfigurator.importSchemaFile(LDAPConfigurator.java:522)\n\tat com.netscape.cms.servlet.csadmin.LDAPConfigurator.setupSchema(LDAPConfigurator.java:90)\n\tat org.dogtagpki.server.cli.SubsystemDBInitCLI.execute(SubsystemDBInitCLI.java:129)\n\tat org.dogtagpki.cli.CommandCLI.execute(CommandCLI.java:57)\n\tat org.dogtagpki.cli.CLI.execute(CLI.java:352)\n\tat org.dogtagpki.cli.CLI.execute(CLI.java:352)\n\tat org.dogtagpki.cli.CLI.execute(CLI.java:352)\n\tat org.dogtagpki.server.cli.PKIServerCLI.execute(PKIServerCLI.java:86)\n\tat org.dogtagpki.server.cli.PKIServerCLI.main(PKIServerCLI.java:92)\nERROR: CalledProcessError: Command \'[\'/usr/sbin/runuser\', \'-u\', \'pkiuser\', \'--\', \'/usr/lib/jvm/jre-openjdk/bin/java\', \'-classpath\', \'/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/tomcat-servlet-api.jar:/usr/share/pki/ca/webapps/ca/WEB-INF/lib/*:/var/lib/pki/pki-tomcat/common/lib/*:/usr/share/pki/lib/*\', \'-Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory\', \'-Dcatalina.base=/var/lib/pki/pki-tomcat\', \'-Dcatalina.home=/usr/share/tomcat\', \'-Djava.endorsed.dirs=\', \'-Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp\', \'-Djava.util.logging.config.file=/etc/pki/pki-tomcat/logging.properties\', \'-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager\', \'-Dcom.redhat.fips=false\', \'org.dogtagpki.server.cli.PKIServerCLI\', \'ca-db-init\', \'--setup-schema\', \'--create-database\', \'--create-base\', \'--create-containers\', \'--setup-db-manager\', \'--setup-vlv-indexes\']\' returned non-zero exit status 1.\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 840, in spawn\n    subsystem.init_database(\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 915, in init_database\n    self.run(cmd, as_current_user=as_current_user)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 1137, in run\n    subprocess.run(cmd, check=True)\n  File "/usr/lib64/python3.8/subprocess.py", line 512, in run\n    raise CalledProcessError(retcode, process.args,\n\n')
2020-08-16T20:30:06Z CRITICAL See the installation logs and the following files/directories for more information:
2020-08-16T20:30:06Z CRITICAL   /var/log/pki/pki-tomcat
2020-08-16T20:30:06Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dogtaginstance.py", line 201, in spawn_instance
    ipautil.run(args, nolog=nolog_list)
  File "/usr/lib/python3.8/site-packages/ipapython/ipautil.py", line 597, in run
    raise CalledProcessError(
ipapython.ipautil.CalledProcessError: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmps1az97js'] returned non-zero exit status 1: 'Notice: Trust flag u is set automatically if the private key is present.\nException in thread "main" java.io.FileNotFoundException: /usr/share/pki/acme/database/ldap/schema.ldif (No such file or directory)\n\tat java.io.FileInputStream.open0(Native Method)\n\tat java.io.FileInputStream.open(FileInputStream.java:195)\n\tat java.io.FileInputStream.<init>(FileInputStream.java:138)\n\tat java.io.FileInputStream.<init>(FileInputStream.java:93)\n\tat netscape.ldap.util.LDIF.<init>(Unknown Source)\n\tat com.netscape.cms.servlet.csadmin.LDAPConfigurator.importSchemaFile(LDAPConfigurator.java:522)\n\tat com.netscape.cms.servlet.csadmin.LDAPConfigurator.setupSchema(LDAPConfigurator.java:90)\n\tat org.dogtagpki.server.cli.SubsystemDBInitCLI.execute(SubsystemDBInitCLI.java:129)\n\tat org.dogtagpki.cli.CommandCLI.execute(CommandCLI.java:57)\n\tat org.dogtagpki.cli.CLI.execute(CLI.java:352)\n\tat org.dogtagpki.cli.CLI.execute(CLI.java:352)\n\tat org.dogtagpki.cli.CLI.execute(CLI.java:352)\n\tat org.dogtagpki.server.cli.PKIServerCLI.execute(PKIServerCLI.java:86)\n\tat org.dogtagpki.server.cli.PKIServerCLI.main(PKIServerCLI.java:92)\nERROR: CalledProcessError: Command \'[\'/usr/sbin/runuser\', \'-u\', \'pkiuser\', \'--\', \'/usr/lib/jvm/jre-openjdk/bin/java\', \'-classpath\', \'/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/tomcat-servlet-api.jar:/usr/share/pki/ca/webapps/ca/WEB-INF/lib/*:/var/lib/pki/pki-tomcat/common/lib/*:/usr/share/pki/lib/*\', \'-Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory\', \'-Dcatalina.base=/var/lib/pki/pki-tomcat\', \'-Dcatalina.home=/usr/share/tomcat\', \'-Djava.endorsed.dirs=\', \'-Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp\', \'-Djava.util.logging.config.file=/etc/pki/pki-tomcat/logging.properties\', \'-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager\', \'-Dcom.redhat.fips=false\', \'org.dogtagpki.server.cli.PKIServerCLI\', \'ca-db-init\', \'--setup-schema\', \'--create-database\', \'--create-base\', \'--create-containers\', \'--setup-db-manager\', \'--setup-vlv-indexes\']\' returned non-zero exit status 1.\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 840, in spawn\n    subsystem.init_database(\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 915, in init_database\n    self.run(cmd, as_current_user=as_current_user)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 1137, in run\n    subprocess.run(cmd, check=True)\n  File "/usr/lib64/python3.8/subprocess.py", line 512, in run\n    raise CalledProcessError(retcode, process.args,\n\n')

pki-ca-spawn logs:

2020-08-16 20:30:06 ERROR: CalledProcessError: Command '['/usr/sbin/runuser', '-u', 'pkiuser', '--', '/usr/lib/jvm/jre-openjdk/bin/java', '-classpath', '/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/tomcat-servlet-api.jar:/usr/share/pki/ca/webapps/ca/WEB-INF/lib/*:/var/lib/pki/pki-tomcat/common/lib/*:/usr/share/pki/lib/*', '-Djavax.sql.DataSource.Factory=org.apache.commons.dbcp.BasicDataSourceFactory', '-Dcatalina.base=/var/lib/pki/pki-tomcat', '-Dcatalina.home=/usr/share/tomcat', '-Djava.endorsed.dirs=', '-Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp', '-Djava.util.logging.config.file=/etc/pki/pki-tomcat/logging.properties', '-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager', '-Dcom.redhat.fips=false', 'org.dogtagpki.server.cli.PKIServerCLI', 'ca-db-init', '--setup-schema', '--create-database', '--create-base', '--create-containers', '--setup-db-manager', '--setup-vlv-indexes']' returned non-zero exit status 1.
  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 840, in spawn
    subsystem.init_database(
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 915, in init_database
    self.run(cmd, as_current_user=as_current_user)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 1137, in run
    subprocess.run(cmd, check=True)
  File "/usr/lib64/python3.8/subprocess.py", line 512, in run
    raise CalledProcessError(retcode, process.args,

Installed packages:
- pki-base-10.10.0-0.1.alpha1.20200814013225UTC.13406396.fc32.noarch


Note: this is blocking our tests using the nightly dogtagpki copr repo @pki/master

@edewata -- Please take a look. Looks like a bug in the pki-acme split.

Metadata Update from @cipherboy:
- Custom field component adjusted to None
- Custom field feature adjusted to None
- Custom field origin adjusted to None
- Custom field proposedmilestone adjusted to None
- Custom field proposedpriority adjusted to None
- Custom field reviewer adjusted to None
- Custom field type adjusted to None
- Custom field version adjusted to None

3 years ago

Or, since IPA merged ACME: https://github.com/freeipa/freeipa/pull/4723 -- might need to fix IPA.

With a more recent build pki build (10.10.0-0.1.alpha1.20200909013458UTC.eac41b), ipa-server-install is failing later, in the pki-server acme-deploy step. Please see PR #394, with logs:

[ipatests.pytest_ipa.integration.host.Host.master.cmd29] Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [1/31]: configuring certificate server instance
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [2/31]: Add ipa-pki-wait-running
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [3/31]: secure AJP connector
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [4/31]: reindex attributes
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [5/31]: exporting Dogtag certificate store pin
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [6/31]: stopping certificate server instance to update CS.cfg
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [7/31]: backing up CS.cfg
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [8/31]: disabling nonces
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [9/31]: set up CRL publishing
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [10/31]: enable PKIX certificate path discovery and validation
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [11/31]: deploying ACME service
[ipatests.pytest_ipa.integration.host.Host.master.cmd29]   [error] CalledProcessError: CalledProcessError(Command ['pki-server', 'acme-deploy'] returned non-zero exit status 1: 'ERROR: Error reading file \'/usr/share/pki/acme/conf/Catalina/localhost/acme.xml\': failed to load external entity "/usr/share/pki/acme/conf/Catalina/localhost/acme.xml"\n')
[ipatests.pytest_ipa.integration.host.Host.master.cmd29] CalledProcessError(Command ['pki-server', 'acme-deploy'] returned non-zero exit status 1: 'ERROR: Error reading file \'/usr/share/pki/acme/conf/Catalina/localhost/acme.xml\': failed to load external entity "/usr/share/pki/acme/conf/Catalina/localhost/acme.xml"\n')
[ipatests.pytest_ipa.integration.host.Host.master.cmd29] The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information
[ipatests.pytest_ipa.integration.host.Host.master.cmd29] Exit code: 1

Metadata Update from @frenaud:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

3 years ago

Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new
issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.

This issue has been cloned to GitHub and is available here:
https://github.com/dogtagpki/pki/issues/3323

If you want to receive further updates on the issue, please navigate to the
GitHub issue and click on Subscribe button.

Thank you for understanding, and we apologize for any inconvenience.

Login to comment on this ticket.

Metadata