Bug 1814242 - Upgrade to 10.8.3 breaks PKI Tomcat Server
Summary: Upgrade to 10.8.3 breaks PKI Tomcat Server
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: dogtag-pki
Version: 31
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Dinesh Prasanth
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1820318 (view as bug list)
Depends On:
Blocks: 1817247
TreeView+ depends on / blocked
 
Reported: 2020-03-17 13:04 UTC by Thomas Höll
Modified: 2020-05-06 05:07 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1817247 (view as bug list)
Environment:
Last Closed: 2020-05-06 03:07:30 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Thomas Höll 2020-03-17 13:04:29 UTC
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

Comment 1 Dinesh Prasanth 2020-03-17 13:48:12 UTC
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`?

Comment 2 Thomas Höll 2020-03-18 07:15:06 UTC
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.

Comment 3 Dinesh Prasanth 2020-03-19 21:16:22 UTC
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

Comment 4 Thomas Höll 2020-03-20 06:55:38 UTC
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

Comment 5 Thomas Höll 2020-03-20 07:37:20 UTC
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

Comment 6 Thomas Höll 2020-03-20 07:40:35 UTC
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.

Comment 7 Dinesh Prasanth 2020-03-20 15:05:40 UTC
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.

Comment 8 Thomas Höll 2020-03-23 06:51:32 UTC
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?

Comment 9 Dinesh Prasanth 2020-03-23 15:09:05 UTC
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. :-)

Comment 10 Thomas Höll 2020-03-23 17:13:58 UTC
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!

Comment 11 Endi Sukma Dewata 2020-03-25 15:07:07 UTC
https://pagure.io/dogtagpki/issue/3168

Comment 12 Dinesh Prasanth 2020-03-25 20:03:01 UTC
Fixed via PR: https://github.com/dogtagpki/pki/pull/355

Comment 13 Dinesh Prasanth 2020-04-02 18:59:00 UTC
*** Bug 1820318 has been marked as a duplicate of this bug. ***

Comment 14 Fedora Update System 2020-04-27 16:34:53 UTC
FEDORA-2020-2239716ed2 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2020-2239716ed2

Comment 15 Fedora Update System 2020-04-27 16:34:56 UTC
FEDORA-2020-74a0edb49c has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-74a0edb49c

Comment 16 Fedora Update System 2020-04-27 16:34:57 UTC
FEDORA-2020-ebe88a5cc4 has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2020-ebe88a5cc4

Comment 17 Fedora Update System 2020-04-28 03:23:54 UTC
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.

Comment 18 Fedora Update System 2020-04-28 03:46:08 UTC
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.

Comment 19 Fedora Update System 2020-04-28 03:52:07 UTC
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.

Comment 20 Fedora Update System 2020-05-06 03:07:30 UTC
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.

Comment 21 Fedora Update System 2020-05-06 04:29:45 UTC
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.

Comment 22 Fedora Update System 2020-05-06 05:07:41 UTC
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.


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