Nightly test failure in ipa-server-install while calling pki-server acme-deploy (with pki nightly repo)

pki-bot commented 4 years ago

This issue was migrated from Pagure Issue #3206. Originally filed by frenaud (@flo-renaud) on 2020-08-17 09:38:42:

Closed at 2020-09-24 04:03:37 as fixed
Assigned to nobody

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

pki-bot commented 4 years ago

Comment from frenaud (@flo-renaud) at 2020-08-17 09:41:33

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

pki-bot commented 4 years ago

Comment from cipherboy (@cipherboy) at 2020-08-17 10:30:07

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

pki-bot commented 4 years ago

Comment from cipherboy (@cipherboy) at 2020-08-17 10:30:08

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

pki-bot commented 4 years ago

Comment from cipherboy (@cipherboy) at 2020-08-17 10:34:18

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

pki-bot commented 4 years ago

Comment from cipherboy (@cipherboy) at 2020-08-24 15:22:01

One fix is being considered here: https://github.com/freeipa/freeipa/pull/5039

pki-bot commented 4 years ago

Comment from frenaud (@flo-renaud) at 2020-09-10 12:26:19

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

pki-bot commented 4 years ago

Comment from frenaud (@flo-renaud) at 2020-09-24 04:03:37

Fixed with https://pagure.io/freeipa/c/c0461eb37ccf0b87b05f81380cf60dffdd26a3dc?branch=master on freeipa side: spec: require pki-acme if pki-ca >= 10.10

pki-bot commented 4 years ago

Comment from frenaud (@flo-renaud) at 2020-09-24 04:03:38

Metadata Update from @flo-renaud:

Issue close_status updated to: fixed
Issue status updated to: Closed (was: Open)

pki-bot / pki-issues-final

Nightly test failure in ipa-server-install while calling pki-server acme-deploy (with pki nightly repo) #2755