Bug 1812169 - Running ipa-replica-install fails with Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server. Failed to authenticate to CA REST API).)
Summary: Running ipa-replica-install fails with Certificate issuance failed (CA_UNREAC...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: freeipa
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: IPA Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 1817918
TreeView+ depends on / blocked
 
Reported: 2020-03-10 17:01 UTC by Jan Pazdziora
Modified: 2020-04-05 00:15 UTC (History)
12 users (show)

Fixed In Version: freeipa-4.8.6-1.fc32
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1817918 (view as bug list)
Environment:
Last Closed: 2020-04-05 00:15:22 UTC
Type: Bug


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Fedora Pagure freeipa issue 8221 0 None None None 2020-03-10 21:42:24 UTC

Description Jan Pazdziora 2020-03-10 17:01:06 UTC
Description of problem:

On Fedora 32 and rawhide, running ipa-replica-install fails with
Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)

Version-Release number of selected component (if applicable):

freeipa-server-4.8.4-8.fc33.x86_64

How reproducible:

Deterministic.

Steps to Reproduce:
1. Have IPA master setup with
   ipa-server-install -U -r EXAMPLE.TEST --setup-dns --no-forwarders --no-ntp -p Secret123 -a Secret123
2. Edit /etc/resolv.conf for the nameserver to point to the IPA master machine.
3. On the replica machine, run
   ipa-replica-install -U --skip-conncheck --principal admin --setup-ca --no-ntp --principal admin@EXAMPLE.TEST --admin-password=Secret123

Actual results:

  [26/41]: creating DS keytab
  [27/41]: ignore time skew for initial replication
  [28/41]: setting up initial replication
Starting replication, please wait until this has completed.
Update in progress, 4 seconds elapsed
Update succeeded

  [29/41]: prevent time skew after initial replication
  [30/41]: adding sasl mappings to the directory
  [31/41]: updating schema
  [32/41]: setting Auto Member configuration
  [33/41]: enabling S4U2Proxy delegation
  [34/41]: initializing group membership
  [35/41]: adding master entry
  [36/41]: initializing domain level
  [37/41]: configuring Posix uid/gid generation
  [38/41]: adding replication acis
  [39/41]: activating sidgen plugin
  [40/41]: activating extdom plugin
  [41/41]: configuring directory to start on boot
Done configuring directory server (dirsrv).
Configuring Kerberos KDC (krb5kdc)
  [1/5]: configuring KDC
  [2/5]: adding the password extension to the directory
  [3/5]: creating anonymous principal
  [4/5]: starting the KDC
  [5/5]: configuring KDC to start on boot
Done configuring Kerberos KDC (krb5kdc).
Configuring kadmin
  [1/2]: starting kadmin 
  [2/2]: configuring kadmin to start on boot
Done configuring kadmin.
Configuring directory server (dirsrv)
  [1/3]: configuring TLS for DS instance
  [error] RuntimeError: Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)
Your system may be partly configured.
Run /usr/sbin/ipa-server-install --uninstall to clean up.

Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)
The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information

Expected results:

No error, IPA replica setup.

Additional info:

The ipareplica-install.log ends with

2020-03-10T16:58:16Z DEBUG step duration: kadmin __enable 0.21 sec
2020-03-10T16:58:16Z DEBUG Done configuring kadmin.
2020-03-10T16:58:16Z DEBUG service duration: kadmin 0.34 sec
2020-03-10T16:58:16Z DEBUG Backing up system configuration file '/etc/ipa/default.conf'
2020-03-10T16:58:16Z DEBUG Saving Index File to '/var/lib/ipa/sysrestore/sysrestore.index'
2020-03-10T16:58:16Z DEBUG Writing configuration file /etc/ipa/default.conf
2020-03-10T16:58:16Z DEBUG [global]
basedn = dc=example,dc=test
host = ipa-replica2.example.test
realm = EXAMPLE.TEST
domain = example.test
xmlrpc_uri = https://ipa-master.example.test/ipa/xml
ldap_uri = ldapi://%2Fvar%2Frun%2Fslapd-EXAMPLE-TEST.socket
mode = production
enable_ra = True
ra_plugin = dogtag
dogtag_version = 10



2020-03-10T16:58:16Z DEBUG Configuring directory server (dirsrv)
2020-03-10T16:58:16Z DEBUG   [1/3]: configuring TLS for DS instance
2020-03-10T16:58:16Z DEBUG Loading Index file from '/var/lib/ipa/sysrestore/sysrestore.index'
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/bin/certutil', '-d', 'sql:/etc/dirsrv/slapd-EXAMPLE-TEST/', '-L', '-n', 'EXAMPLE.TEST IPA CA', '-a', '-f', '/etc/dirsrv/slapd-EXAMPLE-TEST/pwdfile.txt']
2020-03-10T16:58:16Z DEBUG Process finished, return code=255
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=certutil: Could not find cert: EXAMPLE.TEST IPA CA
: PR_FILE_NOT_FOUND_ERROR: File not found

2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/bin/certutil', '-d', 'sql:/etc/dirsrv/slapd-EXAMPLE-TEST/', '-N', '-f', '/etc/dirsrv/slapd-EXAMPLE-TEST/pwdfile.txt', '-@', '/etc/dirsrv/slapd-EXAMPLE-TEST/pwdfile.txt']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/sbin/restorecon', '-F', '/etc/dirsrv/slapd-EXAMPLE-TEST/']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/sbin/restorecon', '-F', '/etc/dirsrv/slapd-EXAMPLE-TEST/cert9.db']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/sbin/restorecon', '-F', '/etc/dirsrv/slapd-EXAMPLE-TEST/key4.db']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/sbin/restorecon', '-F', '/etc/dirsrv/slapd-EXAMPLE-TEST/pkcs11.txt']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/sbin/selinuxenabled']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/sbin/restorecon', '-F', '/etc/dirsrv/slapd-EXAMPLE-TEST/pwdfile.txt']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG Starting external process
2020-03-10T16:58:16Z DEBUG args=['/usr/bin/certutil', '-d', 'sql:/etc/dirsrv/slapd-EXAMPLE-TEST/', '-A', '-n', 'EXAMPLE.TEST IPA CA', '-t', 'CT,C,C', '-a', '-f', '/etc/dirsrv/slapd-EXAMPLE-TEST/pwdfile.txt']
2020-03-10T16:58:16Z DEBUG Process finished, return code=0
2020-03-10T16:58:16Z DEBUG stdout=
2020-03-10T16:58:16Z DEBUG stderr=
2020-03-10T16:58:16Z DEBUG certmonger request is in state dbus.String('NEWLY_ADDED_READING_KEYINFO', variant_level=1)
2020-03-10T16:58:21Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:58:26Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:58:31Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:58:36Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:58:41Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:58:46Z DEBUG wait_for_request raised request timed out
2020-03-10T16:58:46Z DEBUG Cert request 20200310165816 failed: TIMEOUT (None)
2020-03-10T16:58:46Z DEBUG 20200310165816 not in final state, continue waiting
2020-03-10T16:58:56Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:59:01Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:59:06Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:59:11Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:59:16Z DEBUG certmonger request is in state dbus.String('SUBMITTING', variant_level=1)
2020-03-10T16:59:21Z DEBUG certmonger request is in state dbus.String('CA_UNREACHABLE', variant_level=1)
2020-03-10T16:59:21Z DEBUG Cert request 20200310165816 failed: CA_UNREACHABLE (Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)
2020-03-10T16:59:21Z DEBUG Giving up on cert request 20200310165816
2020-03-10T16:59:21Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 603, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 589, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 864, in __enable_ssl
    certmonger.request_and_wait_for_cert(
  File "/usr/lib/python3.8/site-packages/ipalib/install/certmonger.py", line 365, in request_and_wait_for_cert
    raise RuntimeError(
RuntimeError: Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)

2020-03-10T16:59:21Z DEBUG   [error] RuntimeError: Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)
2020-03-10T16:59:21Z DEBUG   File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 179, in execute
    return_value = self.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/cli.py", line 340, in run
    return cfgr.run()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 360, in run
    return self.execute()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 386, in execute
    for rval in self._executor():
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 460, in _handle_execute_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 655, in _configure
    next(executor)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 431, in __runner
    exc_handler(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 460, in _handle_execute_exception
    self._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 518, in _handle_exception
    self.__parent._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 515, in _handle_exception
    super(ComponentBase, self)._handle_exception(exc_info)
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 450, in _handle_exception
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 421, in __runner
    step()
  File "/usr/lib/python3.8/site-packages/ipapython/install/core.py", line 418, in <lambda>
    step = lambda: next(self.__gen)
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 81, in run_generator_with_yield_from
    six.reraise(*exc_info)
  File "/usr/lib/python3.8/site-packages/six.py", line 703, in reraise
    raise value
  File "/usr/lib/python3.8/site-packages/ipapython/install/util.py", line 59, in run_generator_with_yield_from
    value = gen.send(prev_value)
  File "/usr/lib/python3.8/site-packages/ipapython/install/common.py", line 65, in _install
    for unused in self._installer(self.parent):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/__init__.py", line 597, in main
    replica_install(self)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 402, in decorated
    func(installer)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/server/replicainstall.py", line 1285, in install
    ds.enable_ssl()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 330, in enable_ssl
    self.start_creation()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 603, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 589, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dsinstance.py", line 864, in __enable_ssl
    certmonger.request_and_wait_for_cert(
  File "/usr/lib/python3.8/site-packages/ipalib/install/certmonger.py", line 365, in request_and_wait_for_cert
    raise RuntimeError(

2020-03-10T16:59:21Z DEBUG The ipa-replica-install command failed, exception: RuntimeError: Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)
2020-03-10T16:59:21Z ERROR Certificate issuance failed (CA_UNREACHABLE: Server at https://ipa-master.example.test/ipa/xml failed request, will retry: 4016 (RPC failed at server.  Failed to authenticate to CA REST API).)
2020-03-10T16:59:21Z ERROR The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information

Comment 1 Jan Pazdziora 2020-03-10 17:01:32 UTC
I see the same failure on Fedora 32.

Comment 2 Alexander Bokovoy 2020-03-10 17:15:44 UTC
What tomcat version do you have?

In rawhide it is a known issue with tomcat 9.0.31 which enforces use of a secret-protected setup for AJP proxy. I'm currently working on a fix for upstream.

Comment 3 Jan Pazdziora 2020-03-10 17:17:24 UTC
It's tomcat-9.0.31-1.fc33.noarch.

Comment 4 Alexander Bokovoy 2020-03-10 21:42:24 UTC
Upstream PR: https://github.com/freeipa/freeipa/pull/4337

Comment 7 Lukas Slebodnik 2020-03-16 16:05:38 UTC
(In reply to Florence Blanc-Renaud from comment #6)
> Fixed upstream
> ipa-4-8:
> https://pagure.io/freeipa/c/1deb1010b245df6c363c5655f9a548bdf4dbc040
> https://pagure.io/freeipa/c/d4d8b98c3588b212db6a26610e690cccb3af84ca
> 

Backporting these patches does not seems to be enough for rawhide.

The installation on master will fails

Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes
  [1/30]: configuring certificate server instance
Failed to configure CA instance: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmpchj5vgwk'] returned non-zero exit status 1: 'Notice: Trust flag u is set automatically if the private key is present.\nERROR: CalledProcessError: Command \'[\'sudo\', \'-u\', \'pkiuser\', \'/usr/lib/jvm/jre-1.8.0-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\', \'org.dogtagpki.server.cli.PKIServerCLI\', \'ca-db-remove\', \'--force\']\' died with <Signals.SIGABRT: 6>.\n  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 562, in main\n    scriptlet.spawn(deployer)\n  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 747, in spawn\n    subsystem.remove_database(force=True)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 932, in remove_database\n    self.run(cmd, as_current_user=as_current_user)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 980, 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')
See the installation logs and the following files/directories for more information:
  /var/log/pki/pki-tomcat
  [error] RuntimeError: CA configuration failed.
CA configuration failed.

Comment 8 Lukas Slebodnik 2020-03-16 16:09:50 UTC
For some reason jdk crashed

2020-03-16T12:18:37Z DEBUG Starting external process
2020-03-16T12:18:37Z DEBUG args=['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmpchj5vgwk']
2020-03-16T12:18:43Z DEBUG Process finished, return code=1
2020-03-16T12:18:43Z DEBUG stdout=#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007fba2b65afbe, pid=24003, tid=0x00007fba2904a700
#
# JRE version: OpenJDK Runtime Environment (8.0_242-b08) (build 1.8.0_242-b08)
# Java VM: OpenJDK 64-Bit Server VM (25.242-b08 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# V  [libjvm.so+0x701fbe]  JNIHandleBlock::oops_do(OopClosure*)+0xae
#
# Core dump written. Default location: /tmp/hsperfdata_pkiuser/core or core.24003
#
# An error report file with more information is saved as:
# /tmp/hsperfdata_pkiuser/hs_err_pid24003.log
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#
Installation log: /var/log/pki/pki-ca-spawn.20200316131837.log
Loading deployment configuration from /tmp/tmpchj5vgwk.
WARNING: The 'pki_ssl_server_token' in [CA] has been deprecated. Use 'pki_sslserver_token' instead.
Installing CA into /var/lib/pki/pki-tomcat.

Installation failed: Command failed: sudo -u pkiuser /usr/lib/jvm/jre-1.8.0-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.b
ase=/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/logg
ing.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager org.dogtagpki.server.cli.PKIServerCLI ca-db-remove --force

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

2020-03-16T12:18:43Z DEBUG stderr=Notice: Trust flag u is set automatically if the private key is present.
ERROR: CalledProcessError: Command '['sudo', '-u', 'pkiuser', '/usr/lib/jvm/jre-1.8.0-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', 'org.dogtagpki.server.cli.PKIServerCLI', 'ca-db-remove', '--force']' died with <Signals.SIGABRT: 6>.
  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 562, in main
    scriptlet.spawn(deployer)
  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 747, in spawn
    subsystem.remove_database(force=True)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 932, in remove_database
    self.run(cmd, as_current_user=as_current_user)
  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 980, in run
    subprocess.run(cmd, check=True)
  File "/usr/lib64/python3.8/subprocess.py", line 512, in run
    raise CalledProcessError(retcode, process.args,



2020-03-16T12:18:43Z CRITICAL Failed to configure CA instance: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'CA', '-f', '/tmp/tmpchj5vgwk'] returned non-zero exit status 1: 'Notice: Trust flag u is set automatically if the private key is present.\nERROR: CalledProcessError: Command \'[\'sudo\', \'-u\', \'pkiuser\', \'/usr/lib/jvm/jre-1.8.0-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\', \'org.dogtagpki.server.cli.PKIServerCLI\', \'ca-db-remove\', \'--force\']\' died with <Signals.SIGABRT: 6>.\n  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 562, in main\n    scriptlet.spawn(deployer)\n  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 747, in spawn\n    subsystem.remove_database(force=True)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 932, in remove_database\n    self.run(cmd, as_current_user=as_current_user)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 980, 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-03-16T12:18:43Z CRITICAL See the installation logs and the following files/directories for more information:
2020-03-16T12:18:43Z CRITICAL   /var/log/pki/pki-tomcat
2020-03-16T12:18:43Z DEBUG Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dogtaginstance.py", line 193, 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/tmpchj5vgwk'] returned non-zero exit status 1: 'Notice: Trust flag u is set automatically if the private key is present.\nERROR: CalledProcessError: Command \'[\'sudo\', \'-u\', \'pkiuser\', \'/usr/lib/jvm/jre-1.8.0-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\', \'org.dogtagpki.server.cli.PKIServerCLI\', \'ca-db-remove\', \'--force\']\' died with <Signals.SIGABRT: 6>.\n  File "/usr/lib/python3.8/site-packages/pki/server/pkispawn.py", line 562, in main\n    scriptlet.spawn(deployer)\n  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 747, in spawn\n    subsystem.remove_database(force=True)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 932, in remove_database\n    self.run(cmd, as_current_user=as_current_user)\n  File "/usr/lib/python3.8/site-packages/pki/server/subsystem.py", line 980, 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')

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 603, in start_creation
    run_step(full_msg, method)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/service.py", line 589, in run_step
    method()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/cainstance.py", line 596, in __spawn_instance
    DogtagInstance.spawn_instance(
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dogtaginstance.py", line 195, in spawn_instance
    self.handle_setup_error(e)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/dogtaginstance.py", line 503, in handle_setup_error
    raise RuntimeError("%s configuration failed." % self.subsystem)
RuntimeError: CA configuration failed.

Comment 9 Florence Blanc-Renaud 2020-03-16 16:50:12 UTC
Hi Lukas,
the issue you mention is a different one, already reported in https://pagure.io/dogtagpki/issue/3130 ipa-server-install fails in pkispawn step with a java coredump.
The above ticket mentions https://bugzilla.redhat.com/show_bug.cgi?id=1813550 java segmentation faults during package builds in rawhide which is a java-1.8.0-openjdk problem.

Is it OK for you to move back this BZ to POST?

Comment 10 Lukas Slebodnik 2020-03-17 08:52:14 UTC
Last time when I tried, I was able to install at least master without patch (just replica failed)
But I failed to install even maser with patch. I did not dive into details but
it seems suspicious for me.

If you are sure it is unrelated then feel free to move to POST
otherwise I would prefer at lest something functional in rawhide.

Comment 11 Jan Pazdziora 2020-03-19 07:52:45 UTC
Is it expected that the Java segfault issue seems non-deterministic?

Comment 12 Lukas Slebodnik 2020-03-27 08:56:32 UTC
(In reply to Lukas Slebodnik from comment #10)
> Last time when I tried, I was able to install at least master without patch
> (just replica failed)
> But I failed to install even maser with patch. I did not dive into details
> but
> it seems suspicious for me.
> 
> If you are sure it is unrelated then feel free to move to POST
> otherwise I would prefer at lest something functional in rawhide.

I cannot reproduce issue with new jdk and new freeipa.
The bug can be closed.

Comment 13 Florence Blanc-Renaud 2020-03-27 09:19:42 UTC
Thanks Lukas for checking. Moving back to POST.

Comment 14 Lukas Slebodnik 2020-03-27 09:26:10 UTC
(In reply to Florence Blanc-Renaud from comment #13)
> Thanks Lukas for checking. Moving back to POST.

Is there any reason why the state cannot be to closed -> rawhide?

Comment 15 Alexander Bokovoy 2020-03-27 10:57:32 UTC
It is fixed also in F32, so we can attach it to F32 update: https://bodhi.fedoraproject.org/updates/FEDORA-2020-e3a79248dc

Comment 16 Fedora Update System 2020-03-27 10:58:00 UTC
FEDORA-2020-e3a79248dc has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-e3a79248dc

Comment 17 Jan Pazdziora 2020-03-27 13:22:49 UTC
I confirm that I no longer see the problem with freeipa-server-4.8.5-2.fc32.x86_64 and freeipa-server-4.8.5-2.fc33.x86_64. So the fix was likely somewhere else than freeipa-4.8.6-1.fc32, so attaching to https://bodhi.fedoraproject.org/updates/FEDORA-2020-e3a79248dc does not seem corect.

Comment 18 Alexander Bokovoy 2020-03-27 15:02:27 UTC
You don't see the issue because JDK crash is fixed. FreeIPA 4.8.5 fixed the AJP issue, 4.8.6 contains a fix that was needed for an edge case of restarting httpd as part of dogtag configuration before it was configured. So both are applicable here.

Comment 19 Fedora Update System 2020-03-28 14:58:57 UTC
FEDORA-2020-e3a79248dc has been pushed to the Fedora 32 testing repository.
In short time you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-e3a79248dc`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-e3a79248dc

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 20 Fedora Update System 2020-04-05 00:15:22 UTC
FEDORA-2020-e3a79248dc has been pushed to the Fedora 32 stable repository.
If problem still persists, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.