Description of problem: Upgrade to pki-base 10.8.3 breaks CA Version-Release number of selected component (if applicable): 10.8.3 How reproducible: unknown, don't want to try on other instances Steps to Reproduce: 1. update pki-* packages to 10.8.3 Actual results: PKI Tomcat Server fails to start Expected results: PKI Tomcat Server is running Additional info: sudo -u pkiuser /usr/sbin/pki-server upgrade --validate pki-tomcat ERROR: Upgrade incomplete: see /var/log/pki/pki-server-upgrade-10.8.3.log re-running ipa-server-upgrade doesn't fix the problem. Unfortunately, I deleted /var/log/pki/pki-server-upgrade-10.8.3.log, but I think it said that the admin CA profile needs to be fixed
Hello Thomas, Can you provide following information? 1. What version of IPA are you running? 2. Can you attach /var/log/pki/pki-tomcat/ca/debug-<date>.log ? 3. Did you try `ipactl restart` rather than restarting manually? 4. What do you see in `journalctl -u pki-tomcatd@pki-tomcat`?
Hi, (In reply to Dinesh Prasanth from comment #1) > Hello Thomas, > > Can you provide following information? > > 1. What version of IPA are you running? 4.8.4-2.fc31 > 2. Can you attach /var/log/pki/pki-tomcat/ca/debug-<date>.log ? There is no log file created, because the server doesn't start. Reason for this is the upgrade check in /usr/lib/systemd/system/pki-tomcatd@.service: ExecStartPre=/usr/sbin/pki-server upgrade --validate %i If I execute this command I get the following output: $ sudo -u pkiuser /usr/sbin/pki-server upgrade --validate pki-tomcat ERROR: Upgrade incomplete: see /var/log/pki/pki-server-upgrade-10.8.3.log When I comment out the ExecStartPre line, the server starts and I assume(!) it's working properly. I could resubmit a certificate request which was handled correctly. > 3. Did you try `ipactl restart` rather than restarting manually? Yes, same result. I also tried running ipa-server-upgrade. This is successful, as long as I comment out the ExecStartPre line. It doesn't fix anything tho. > 4. What do you see in `journalctl -u pki-tomcatd@pki-tomcat`? Mar 18 07:59:31 xxxxx.xxx.xxxxx.xx pki-server[6520]: ERROR: Upgrade incomplete: see /var/log/pki/pki-server-upgrade-10.8.3.log Mar 18 07:59:31 xxxxx.xxx.xxxxx.xx systemd[1]: pki-tomcatd: Control process exited, code=exited, status=1/FAILURE Mar 18 07:59:31 xxxxx.xxx.xxxxx.xx systemd[1]: pki-tomcatd: Failed with result 'exit-code'. Mar 18 07:59:31 xxxxx.xxx.xxxxx.xx systemd[1]: Failed to start PKI Tomcat Server pki-tomcat. Without the ExecStartPre check the server starts and I get the following: Mar 18 08:00:45 xxxxx.xxx.xxxxx.xx pki-server[6551]: pki-tomcat instance migrated Mar 18 08:00:45 xxxxx.xxx.xxxxx.xx pki-server[6551]: ---------------------------- Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx systemd[1]: Started PKI Tomcat Server pki-tomcat. Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=pki-tomcatd@pki-tomcat comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx server[6658]: Java virtual machine used: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx server[6658]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/lib/java/commons-daemon.jar Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx server[6658]: main class used: org.apache.catalina.startup.Bootstrap Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx server[6658]: flags used: -Djava.library.path=/usr/lib64/nuxwdog-jni Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx server[6658]: options used: -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=/var/lib/pki/pki-tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.security.manager -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy Mar 18 08:00:46 xxxxx.xxx.xxxxx.xx server[6658]: arguments used: start Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx systemd[1]: Started PC/SC Smart Card Daemon. Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=pcscd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00000000 auth.c:137:IsClientAuthorized() Process 6658 (user: 17) is NOT authorized for action: access_pcsc Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00000184 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00025468 auth.c:137:IsClientAuthorized() Process 6658 (user: 17) is NOT authorized for action: access_pcsc Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00000185 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00025040 auth.c:137:IsClientAuthorized() Process 6658 (user: 17) is NOT authorized for action: access_pcsc Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00000360 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00024304 auth.c:137:IsClientAuthorized() Process 6658 (user: 17) is NOT authorized for action: access_pcsc Mar 18 08:00:48 xxxxx.xxx.xxxxx.xx pcscd[6679]: 00000444 winscard_svc.c:335:ContextThread() Rejected unauthorized PC/SC client Mar 18 08:01:01 xxxxx.xxx.xxxxx.xx CROND[6734]: (root) CMD (run-parts /etc/cron.hourly) Mar 18 08:01:01 xxxxx.xxx.xxxxx.xx run-parts[6737]: (/etc/cron.hourly) starting 0anacron Mar 18 08:01:01 xxxxx.xxx.xxxxx.xx run-parts[6743]: (/etc/cron.hourly) finished 0anacron Mar 18 08:01:13 xxxxx.xxx.xxxxx.xx sssd_be[4353]: GSSAPI client step 1 Mar 18 08:01:13 xxxxx.xxx.xxxxx.xx sssd_be[4353]: GSSAPI client step 1 Mar 18 08:01:13 xxxxx.xxx.xxxxx.xx sssd_be[4353]: GSSAPI client step 1 Mar 18 08:01:13 xxxxx.xxx.xxxxx.xx sssd_be[4353]: GSSAPI client step 2 Mar 18 08:01:49 xxxxx.xxx.xxxxx.xx systemd[1]: pcscd.service: Succeeded.
Hi Thomas, I discussed this with my team. Without the logs we can't predict what went wrong. Can you try running `pki-server upgrade --debug` and attach the output and log file? Thanks
Hi, there's obviously a problem with the EC admin certificate config: INFO: Upgrading PKI server INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: Loading subsystem: ca INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Loading subsystem: ca INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg DEBUG: Current version: 10.8.2 DEBUG: Target version: 10.8.3 DEBUG: Upgrade path: DEBUG: - 10.8.2 DEBUG: - 10.8.3 Upgrading from version 10.8.2 to 10.8.3: 1. Fix EC admin certificate profile (Yes/No) [Y]: INFO: Loading instance: pki-tomcat INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf INFO: Loading password config: /etc/pki/pki-tomcat/password.conf INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat INFO: Loading subsystem: ca INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Upgrading pki-tomcat instance INFO: Loading subsystem: ca INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Upgrading ca subsystem INFO: Upgrading pki-tomcat/ca subsystem DEBUG: Command: mkdir /var/log/pki/server/upgrade/10.8.2/1/oldfiles/var DEBUG: Command: mkdir /var/log/pki/server/upgrade/10.8.2/1/oldfiles/var/lib DEBUG: Command: mkdir /var/log/pki/server/upgrade/10.8.2/1/oldfiles/var/lib/pki DEBUG: Command: mkdir /var/log/pki/server/upgrade/10.8.2/1/oldfiles/var/lib/pki/pki-tomcat DEBUG: Command: mkdir /var/log/pki/server/upgrade/10.8.2/1/oldfiles/var/lib/pki/pki-tomcat/ca DEBUG: Command: mkdir /var/log/pki/server/upgrade/10.8.2/1/oldfiles/var/lib/pki/pki-tomcat/ca/conf INFO: Saving /var/lib/pki/pki-tomcat/ca/conf/CS.cfg DEBUG: Command: cp /var/lib/pki/pki-tomcat/ca/conf/CS.cfg /var/log/pki/server/upgrade/10.8.2/1/oldfiles/var/lib/pki/pki-tomcat/ca/conf/CS.cfg INFO: Current path: None ERROR: expected str, bytes or os.PathLike object, not NoneType Traceback (most recent call last): File "/usr/lib/python3.7/site-packages/pki/server/upgrade.py", line 124, in upgrade_subsystems self.upgrade_subsystem(instance, subsystem) File "/usr/share/pki/server/upgrade/10.8.2/01-FixECAdminCertProfile.py", line 33, in upgrade_subsystem dirname = os.path.dirname(path) File "/usr/lib64/python3.7/posixpath.py", line 156, in dirname p = os.fspath(p) TypeError: expected str, bytes or os.PathLike object, not NoneType Failed upgrading pki-tomcat/ca subsystem. Continue (Yes/No) [Y]? n
I was able to reproduce this on another machine (similar configuration). The error is the same. /var/log/pki/pki-server-upgrade-10.8.3.log: Upgrading PKI server configuration on Fri 20 Mar 2020 08:12:02 AM CET. WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/1/oldfiles/var/lib/pki/pki-tomcat WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/2/oldfiles/etc/pki/pki-tomcat WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/2/oldfiles/etc/pki/pki-tomcat WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/2/oldfiles/etc/pki/pki-tomcat WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/4/oldfiles/etc/pki/pki-tomcat WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/4/oldfiles/etc/pki/pki-tomcat WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/5/oldfiles/etc/pki/pki-tomcat WARNING: Directory already exists: /var/log/pki/server/upgrade/10.8.0/6/oldfiles/etc/pki/pki-tomcat ERROR: expected str, bytes or os.PathLike object, not NoneType ERROR: Upgrade failed in pki-tomcat/ca: expected str, bytes or os.PathLike object, not NoneType Upgrading from version 10.7.3 to 10.8.0: No upgrade scriptlets. Tracker has been set to version 10.8.0. Upgrading from version 10.8.0 to 10.8.2: 1. Fix common folder 2. Remove LDAP setup files from instance folder 3. Fix links to default Tomcat files 4. Remove unused UserDatabase from server.xml 5. Remove pki.policy from instance folder 6. Remove empty custom.policy from instance folder Upgrading from version 10.8.2 to 10.8.3: 1. Fix EC admin certificate profile Failed upgrading pki-tomcat/ca subsystem. Continue (Yes/No) [Y]? ERROR: EOF when reading a line
Also, I noticed some segfaults in dirsrv during/after upgrade: [Fri Mar 20 08:25:43 2020] ns-slapd[133256]: segfault at 68 ip 00007f1c2c2aef0c sp 00007ffcdc212e60 error 4 in libback-ldbm.so[7f1c2c26a000+76000] [Fri Mar 20 08:25:43 2020] Code: 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 48 89 e2 48 c7 04 24 00 00 00 00 e8 6f 29 fc ff 48 8b 04 24 48 89 ef 48 8b 40 68 <ff> 50 68 48 8b 4c 24 08 64 48 33 0c 25 28 00 00 00 75 06 48 83 c4 [Fri Mar 20 08:25:48 2020] ns-slapd[133301]: segfault at 68 ip 00007fd0d9a6ef0c sp 00007fff8acb20a0 error 4 in libback-ldbm.so[7fd0d9a2a000+76000] [Fri Mar 20 08:25:48 2020] Code: 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 48 89 e2 48 c7 04 24 00 00 00 00 e8 6f 29 fc ff 48 8b 04 24 48 89 ef 48 8b 40 68 <ff> 50 68 48 8b 4c 24 08 64 48 33 0c 25 28 00 00 00 75 06 48 83 c4 [Fri Mar 20 08:25:49 2020] ns-slapd[133341]: segfault at 68 ip 00007f3dc637ff0c sp 00007ffe6435b1f0 error 4 in libback-ldbm.so[7f3dc633b000+76000] [Fri Mar 20 08:25:49 2020] Code: 48 8b 04 25 28 00 00 00 48 89 44 24 08 31 c0 48 89 e2 48 c7 04 24 00 00 00 00 e8 6f 29 fc ff 48 8b 04 24 48 89 ef 48 8b 40 68 <ff> 50 68 48 8b 4c 24 08 64 48 33 0c 25 28 00 00 00 75 06 48 83 c4 I'm note sure if it's related somehow.
Thomas, Thanks for the logs. The error seems to be due to None value here: https://github.com/dogtagpki/pki/blob/master/base/server/upgrade/10.8.2/01-FixECAdminCertProfile.py#L33 That is, `profile.caECAdminCert.config` property is missing in your CS.cfg. Hence you see the error. I don't think segfaults in dirsrv are causing the failure. As a workaround, you can set the following property (after replacing the values in the [] that match your config) ```` profile.caECAdminCert.config=[PKI_INSTANCE_PATH]/[PKI_SUBSYSTEM_TYPE]/profiles/ca/caAdminCert.cfg ```` For example, my installation has: ```` profile.caECAdminCert.config=/var/lib/pki/pki-tomcat/ca/profiles/ca/caAdminCert.cfg ```` I'll check and see if we need to roll out an update.
Hi Dinesh, thank you for the workaround! I was able to upgrade the PKI server and it's running fine now. Can you tell me why that property was missing in CS.cfg? I never changed any setting there. Since my other instance is still at 10.7.3 and working, should I wait for an update or just apply the workaround?
Thomas, Glad to hear that it worked. I don't have an answer for why the property went missing. Did someone remove it manually? Check and see if that property is available in your other instances. If so, the upgrade should be smooth. If not, you might have to apply the work around. The (ugly) update I planned was to ignore the missing property and let the upgrade roll. PS: OpenQE hasn't got this bug. I haven't seen anyone else reporting. So, I guess I'll wait a week or two before I close/fix this issue. :-)
Hi Dinesh, I checked my other instance and found the property also to be missing. The only similar properties are these: profile.caECDirUserCert.class_id=caEnrollImpl profile.caECDirUserCert.config=/var/lib/pki/pki-tomcat/ca/profiles/ca/caECDirUserCert.cfg profile.caECDualCert.class_id=caEnrollImpl profile.caECDualCert.config=/var/lib/pki/pki-tomcat/ca/profiles/ca/caECDualCert.cfg profile.caECUserCert.class_id=caEnrollImpl profile.caECUserCert.config=/var/lib/pki/pki-tomcat/ca/profiles/ca/caECUserCert.cfg I have no idea, why that property is missing. Nobody touched that file, I swear ;-). Given that the same problem occurred in two different setups makes a configuration mistake really unlikely. Anyways, I added the property before the upgrade and everything went smooth. So if it's just me who's affected that's bad luck then I guess ;-) Thanks for the help tho!
https://pagure.io/dogtagpki/issue/3168
Fixed via PR: https://github.com/dogtagpki/pki/pull/355
*** Bug 1820318 has been marked as a duplicate of this bug. ***
FEDORA-2020-2239716ed2 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-2239716ed2
FEDORA-2020-74a0edb49c has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-74a0edb49c
FEDORA-2020-ebe88a5cc4 has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2020-ebe88a5cc4
FEDORA-2020-2239716ed2 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-2239716ed2` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-2239716ed2 See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
FEDORA-2020-ebe88a5cc4 has been pushed to the Fedora 30 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-ebe88a5cc4` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-ebe88a5cc4 See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
FEDORA-2020-74a0edb49c has been pushed to the Fedora 31 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-74a0edb49c` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-74a0edb49c See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
FEDORA-2020-74a0edb49c has been pushed to the Fedora 31 stable repository. If problem still persists, please make note of it in this bug report.
FEDORA-2020-2239716ed2 has been pushed to the Fedora 32 stable repository. If problem still persists, please make note of it in this bug report.
FEDORA-2020-ebe88a5cc4 has been pushed to the Fedora 30 stable repository. If problem still persists, please make note of it in this bug report.