search

dogtagpki / pki

The Dogtag Certificate System is an enterprise-class Certificate Authority (CA) which supports all aspects of certificate lifecycle management, including key archival, OCSP and smartcard management.
https://www.dogtagpki.org
GNU General Public License v2.0
358 stars 134 forks source link

pkispawn fails to configure the KrA instance #3341

Open fcami opened 3 years ago

fcami commented 3 years ago

report

pki-kra-spawn log

Short log:

DEBUG: Command: pki -d /etc/pki/pki-tomcat/alias -f /etc/pki/pki-tomcat/password.conf -U https://master.ipa.test:443 --ignore-cert-status UNTRUSTED_ISSUER ca-cert-signing-export --pkcs7\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\', \'--ignore-cert-status\', \'UNTRUSTED_ISSUER\', \'ca-cert-signing-export\', \'--pkcs7\']\' 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 756, in spawn\n    pem_chain = self.get_cert_chain(instance, issuing_ca)\n  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 543, in get_cert_chain\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')

Long log:

Failed to configure KRA instance: CalledProcessError(Command ['/usr/sbin/pkispawn', '-s', 'KRA', '-f', '/tmp/tmp053u5uuy', '--debug'] returned non-zero exit status 1: 'INFO: Connecting to LDAP server at ldaps://master.ipa.test:636\nINFO: Connecting to LDAP server at ldaps://master.ipa.test:636\nINFO: Connecting to security domain at https://master.ipa.test:443\nINFO: Getting security domain info\nINFO: Logging into security domain IPA\nDEBUG: Installing Maven dependencies: False\nINFO: BEGIN spawning KRA subsystem in pki-tomcat instance\nINFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Setting up pkiuser group\nINFO: Reusing existing pkiuser group with GID 17\nINFO: Setting up pkiuser user\nINFO: Reusing existing pkiuser user with UID 17\nDEBUG: Retrieving UID for \'pkiuser\'\nDEBUG: UID of \'pkiuser\' is 17\nDEBUG: Retrieving GID for \'pkiuser\'\nDEBUG: GID of \'pkiuser\' is 17\nINFO: Initialization\nINFO: Setting up infrastructure\nINFO: Creating /etc/sysconfig/pki/tomcat/pki-tomcat\nINFO: Creating /etc/sysconfig/pki/tomcat/pki-tomcat/kra\nDEBUG: Command: mkdir -p /etc/sysconfig/pki/tomcat/pki-tomcat/kra\nDEBUG: Command: chmod 770 /etc/sysconfig/pki/tomcat/pki-tomcat/kra\nDEBUG: Command: chown 17:17 /etc/sysconfig/pki/tomcat/pki-tomcat/kra\nINFO: Creating /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg\nDEBUG: Command: cp -p /usr/share/pki/server/etc/default.cfg /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg\nDEBUG: Command: chmod 660 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg\nDEBUG: Command: chown 17:17 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/default.cfg\nDEBUG: Command: touch /etc/sysconfig/pki/tomcat/pki-tomcat/kra/deployment.cfg\nDEBUG: Command: chmod 660 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/deployment.cfg\nDEBUG: Command: chown 17:17 /etc/sysconfig/pki/tomcat/pki-tomcat/kra/deployment.cfg\nINFO: Creating /var/lib/pki/pki-tomcat\nINFO: Creating /var/lib/pki/pki-tomcat/kra\nDEBUG: Command: mkdir -p /var/lib/pki/pki-tomcat/kra\nDEBUG: Command: chmod 770 /var/lib/pki/pki-tomcat/kra\nDEBUG: Command: chown 17:17 /var/lib/pki/pki-tomcat/kra\nINFO: Preparing pki-tomcat instance\nINFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Creating /etc/pki/pki-tomcat\nWARNING: Directory already exists: /etc/pki/pki-tomcat\nINFO: Creating /etc/pki/pki-tomcat/password.conf\nINFO: Reusing server NSS database password\nINFO: Using specified internal database password\nINFO: Reusing replication manager password\nINFO: Installing pki-tomcat instance\nINFO: Creating KRA subsystem\nINFO: Creating /var/log/pki/pki-tomcat/kra\nDEBUG: Command: mkdir /var/log/pki/pki-tomcat/kra\nINFO: Creating /var/log/pki/pki-tomcat/kra/archive\nDEBUG: Command: mkdir /var/log/pki/pki-tomcat/kra/archive\nINFO: Creating /var/log/pki/pki-tomcat/kra/signedAudit\nDEBUG: Command: mkdir /var/log/pki/pki-tomcat/kra/signedAudit\nINFO: Creating /etc/pki/pki-tomcat/kra\nDEBUG: Command: mkdir /etc/pki/pki-tomcat/kra\nINFO: Creating /etc/pki/pki-tomcat/kra/CS.cfg\nDEBUG: Command: cp /usr/share/pki/kra/conf/CS.cfg /etc/pki/pki-tomcat/kra/CS.cfg\nINFO: Creating /etc/pki/pki-tomcat/kra/registry.cfg\nINFO: Creating /var/lib/pki/pki-tomcat/kra/conf\nDEBUG: Command: ln -s /etc/pki/pki-tomcat/kra /var/lib/pki/pki-tomcat/kra/conf\nINFO: Creating /var/lib/pki/pki-tomcat/kra/logs\nDEBUG: Command: ln -s /var/log/pki/pki-tomcat/kra /var/lib/pki/pki-tomcat/kra/logs\nINFO: Creating /var/lib/pki/pki-tomcat/kra/registry\nDEBUG: Command: ln -s /etc/sysconfig/pki/tomcat/pki-tomcat /var/lib/pki/pki-tomcat/kra/registry\nINFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Getting transport cert info from CS.cfg\nINFO: Getting storage cert info from CS.cfg\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting subsystem cert info from CS.cfg\nINFO: Getting audit_signing cert info from CS.cfg\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg\nINFO: Deploying /kra web application\nINFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Creating /var/lib/pki/pki-tomcat/kra/webapps\nDEBUG: Command: mkdir -p /var/lib/pki/pki-tomcat/kra/webapps\nDEBUG: Command: chmod 770 /var/lib/pki/pki-tomcat/kra/webapps\nDEBUG: Command: chown 17:17 /var/lib/pki/pki-tomcat/kra/webapps\nINFO: Setting up ownerships, permissions, and ACLs on /var/lib/pki/pki-tomcat/kra/webapps\nINFO: Creating /etc/pki/pki-tomcat/Catalina/localhost/kra.xml\nINFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Creating password file: /etc/pki/pki-tomcat/pfile\nINFO: Updating /etc/pki/pki-tomcat/password.conf\nDEBUG: Command: chmod 660 /etc/pki/pki-tomcat/password.conf\nDEBUG: Command: chown 17:17 /etc/pki/pki-tomcat/password.conf\nDEBUG: Command: ln -s /var/lib/pki/pki-tomcat/alias /var/lib/pki/pki-tomcat/kra/alias\nINFO: Removing /etc/pki/pki-tomcat/pfile\nDEBUG: Command: rm -f /etc/pki/pki-tomcat/pfile\nINFO: Getting transport cert info from CS.cfg\nINFO: Getting storage cert info from CS.cfg\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting subsystem cert info from CS.cfg\nINFO: Getting audit_signing cert info from CS.cfg\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg\nINFO: Creating /root/.dogtag/pki-tomcat/kra\nDEBUG: Command: mkdir -p /root/.dogtag/pki-tomcat/kra\nDEBUG: Command: chmod 755 /root/.dogtag/pki-tomcat/kra\nDEBUG: Command: chown 0:0 /root/.dogtag/pki-tomcat/kra\nINFO: Creating password file: /root/.dogtag/pki-tomcat/kra/password.conf\nINFO: Updating /root/.dogtag/pki-tomcat/kra/password.conf\nDEBUG: Command: chmod 660 /root/.dogtag/pki-tomcat/kra/password.conf\nDEBUG: Command: chown 0:0 /root/.dogtag/pki-tomcat/kra/password.conf\nINFO: Storing PKCS #12 password in /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf\nINFO: Updating /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf\nDEBUG: Command: chmod 660 /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf\nDEBUG: Command: chown 17:17 /root/.dogtag/pki-tomcat/kra/pkcs12_password.conf\nWARNING: Directory already exists: /var/lib/ipa/tmp-niqtzfra\nDEBUG: Command: certutil -N -d /var/lib/ipa/tmp-niqtzfra -f /root/.dogtag/pki-tomcat/kra/password.conf\nINFO: Creating SELinux contexts\nINFO: Generating system keys\nINFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Configuring subsystem\nINFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nDEBUG: Setting ephemeral requests to true\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/kra/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/kra/conf/registry.cfg\nINFO: Joining existing domain\nINFO: Getting install token\nINFO: Using CA at https://master.ipa.test:443\nINFO: Retrieving CA certificate chain from https://master.ipa.test:443\nDEBUG: Command: pki -d /etc/pki/pki-tomcat/alias -f /etc/pki/pki-tomcat/password.conf -U https://master.ipa.test:443 --ignore-cert-status UNTRUSTED_ISSUER ca-cert-signing-export --pkcs7\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\', \'--ignore-cert-status\', \'UNTRUSTED_ISSUER\', \'ca-cert-signing-export\', \'--pkcs7\']\' 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 756, in spawn\n    pem_chain = self.get_cert_chain(instance, issuing_ca)\n  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 543, in get_cert_chain\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')
See the installation logs and the following files/directories for more information:
  /var/log/pki/pki-tomcat
KRA configuration failed.
SilleBille commented 3 years ago

hmmm. I'm not sure if I'm looking at the right place. But, my initial investigation shows the error in Dirsrv logs:

[03/Oct/2020:09:32:42.477153616 +0000] - ERR - attrcrypt_unwrap_key - Failed to unwrap key for cipher AES
[03/Oct/2020:09:32:42.480435848 +0000] - ERR - attrcrypt_cipher_init - Symmetric key failed to unwrap with the private key; Cert might have been renewed since the key is wrapped.  To recover the encrypted contents, keep the wrapped symmetric key value.
[03/Oct/2020:09:32:42.643436711 +0000] - ERR - attrcrypt_unwrap_key - Failed to unwrap key for cipher 3DES
[03/Oct/2020:09:32:42.644598462 +0000] - ERR - attrcrypt_cipher_init - Symmetric key failed to unwrap with the private key; Cert might have been renewed since the key is wrapped.  To recover the encrypted contents, keep the wrapped symmetric key value.
[03/Oct/2020:09:32:42.647994200 +0000] - ERR - attrcrypt_init - All prepared ciphers are not available. Please disable attribute encryption.
[03/Oct/2020:09:32:42.817731801 +0000] - ERR - attrcrypt_unwrap_key - Failed to unwrap key for cipher AES
[03/Oct/2020:09:32:42.818865405 +0000] - ERR - attrcrypt_cipher_init - Symmetric key failed to unwrap with the private key; Cert might have been renewed since the key is wrapped.  To recover the encrypted contents, keep the wrapped symmetric key value.
[03/Oct/2020:09:32:42.978169315 +0000] - ERR - attrcrypt_unwrap_key - Failed to unwrap key for cipher 3DES
[03/Oct/2020:09:32:42.979390985 +0000] - ERR - attrcrypt_cipher_init - Symmetric key failed to unwrap with the private key; Cert might have been renewed since the key is wrapped.  To recover the encrypted contents, keep the wrapped symmetric key value.
[03/Oct/2020:09:32:42.980148539 +0000] - ERR - attrcrypt_init - All prepared ciphers are not available. Please disable attribute encryption.

I believe I have seen this error before (i think). Looking at the installed packages:

pki-base-10.9.0-0.4.fc32.noarch
pki-base-java-10.9.0-0.4.fc32.noarch
pki-ca-10.9.0-0.4.fc32.noarch
pki-kra-10.9.0-0.4.fc32.noarch
pki-server-10.9.0-0.4.fc32.noarch
pki-symkey-10.9.0-0.4.fc32.x86_64
pki-tools-10.9.0-0.4.fc32.x86_64

Is there any reason why IPA tests are executed with 10.9.0-0.4 packages? The latest stable version available on Fedora is 10.9.4-1

flo-renaud commented 3 years ago

@SilleBille the kra spawn error happens at 2020-10-03 09:34:27:

2020-10-03 09:34:21 DEBUG: Command: pki -d /etc/pki/pki-tomcat/alias -f /etc/pki/pki-tomcat/password.conf -U https://master.ipa.test:443 --ignore-cert-status UNTRUSTED_ISSUER ca-cert-signing-export --pkcs7
2020-10-03 09:34:27 ERROR: CalledProcessError: Command '['pki', '-d', '/etc/pki/pki-tomcat/alias', '-f', '/etc/pki/pki-tomcat/password.conf', '-U', 'https://master.ipa.test:443', '--ignore-cert-status', 'UNTRUSTED_ISSUER', 'ca-cert-signing-export', '--pkcs7']' 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 756, in spawn
    pem_chain = self.get_cert_chain(instance, issuing_ca)
  File "/usr/lib/python3.8/site-packages/pki/server/deployment/scriptlets/configuration.py", line 543, in get_cert_chain
    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,

and at the same time, the pki/debug logs show the following:

2020-10-03 09:34:27 [ajp-nio-127.0.0.1-8009-exec-4] SEVERE: Allocate exception for servlet [Resteasy]
java.security.AccessControlException: access denied ("java.io.FilePermission" "/usr/share/pki/server/webapps/pki/WEB-INF/lib/pki-cmsbundle.jar" "read")

It is really similar to https://github.com/dogtagpki/pki/issues/3299