Bug 1999052
| Summary: | pki instance creation fails for IPA server in FIPS mode | |||
|---|---|---|---|---|
| Product: | Red Hat Enterprise Linux 9 | Reporter: | Kaleem <ksiddiqu> | |
| Component: | pki-core | Assignee: | Jack Magne <jmagne> | |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | PKI QE <bugzilla-pkiqe> | |
| Severity: | unspecified | Docs Contact: | ||
| Priority: | unspecified | |||
| Version: | 9.0 | CC: | aakkiang, abokovoy, ahughes, ckelley, cpinjani, frenaud, jmagne, mbalao, mharmsen, pcech, pvlasin, rcritten, rhcs-maint, sgehwolf, ssorce, tscherf, zzambers | |
| Target Milestone: | rc | Keywords: | Regression, TestBlocker, Triaged | |
| Target Release: | --- | |||
| Hardware: | Unspecified | |||
| OS: | Unspecified | |||
| Whiteboard: | ||||
| Fixed In Version: | pki-core-11.0.0-0.6.beta1.el9_b | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | ||
| Clone Of: | ||||
| : | 2001576 2002989 (view as bug list) | Environment: | ||
| Last Closed: | 2021-12-07 21:33:05 UTC | Type: | Bug | |
| Regression: | --- | Mount Type: | --- | |
| Documentation: | --- | CRM: | ||
| Verified Versions: | Category: | --- | ||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | ||
| Cloudforms Team: | --- | Target Upstream Version: | ||
| Embargoed: | ||||
| Bug Depends On: | ||||
| Bug Blocks: | 2002989, 2184486 | |||
|
Description
Kaleem
2021-08-30 10:29:34 UTC
systemd journal ------------------ Aug 30 07:20:17 master.testrelm.test systemd[1]: Stopping PKI Tomcat Server pki-tomcat... Aug 30 07:20:17 master.testrelm.test server[10096]: Java virtual machine used: /usr/lib/jvm/jre-11-openjdk/bin/java Aug 30 07:20:17 master.testrelm.test server[10096]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/ant.jar:/usr/share/java/ant-lau> Aug 30 07:20:17 master.testrelm.test server[10096]: main class used: org.apache.catalina.startup.Bootstrap Aug 30 07:20:17 master.testrelm.test server[10096]: flags used: -Dcom.redhat.fips=false Aug 30 07:20:17 master.testrelm.test server[10096]: options used: -Dcatalina.base=/var/lib/pki/pki-tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/lib/p> Aug 30 07:20:17 master.testrelm.test server[10096]: arguments used: stop Aug 30 07:20:17 master.testrelm.test server[10096]: WARNING: Problem with JAR file [/usr/share/pki/server/common/lib/commons-collections.jar], exists: [false], canRead: [false] Aug 30 07:20:18 master.testrelm.test systemd[1]: pki-tomcatd: Deactivated successfully. Aug 30 07:20:18 master.testrelm.test systemd[1]: Stopped PKI Tomcat Server pki-tomcat. Aug 30 07:20:18 master.testrelm.test systemd[1]: pki-tomcatd: Consumed 27.146s CPU time. Aug 30 07:25:06 master.testrelm.test systemd[1]: Starting PKI Tomcat Server pki-tomcat... Aug 30 07:25:09 master.testrelm.test pki-server[14891]: ProviderException: Initialization failed Aug 30 07:25:09 master.testrelm.test systemd[1]: pki-tomcatd: Control process exited, code=exited, status=255/EXCEPTION Aug 30 07:25:09 master.testrelm.test systemd[1]: pki-tomcatd: Failed with result 'exit-code'. Aug 30 07:25:09 master.testrelm.test systemd[1]: Failed to start PKI Tomcat Server pki-tomcat. Aug 30 07:25:09 master.testrelm.test systemd[1]: pki-tomcatd: Consumed 1.854s CPU time. The same error can be seen on rawhide, please see https://pagure.io/freeipa/issue/8883 and https://github.com/dogtagpki/pki/issues/3560. On rawhide, the journal contains more information: Aug 28 11:02:53 master.ipa.test systemd[1]: Created slice Slice /system/pki-tomcatd. Aug 28 11:02:53 master.ipa.test systemd[1]: Starting PKI Tomcat Server pki-tomcat... Aug 28 11:02:56 master.ipa.test java[31357]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock Aug 28 11:02:56 master.ipa.test pki-server[31357]: java.security.ProviderException: Could not initialize NSS Aug 28 11:02:56 master.ipa.test pki-server[31357]: at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.<init>(SunPKCS11.java:217) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11$1.run(SunPKCS11.java:112) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11$1.run(SunPKCS11.java:109) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/java.security.AccessController.doPrivileged(Native Method) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.configure(SunPKCS11.java:109) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/sun.security.jca.ProviderConfig$3.run(ProviderConfig.java:251) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/sun.security.jca.ProviderConfig$3.run(ProviderConfig.java:242) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/java.security.AccessController.doPrivileged(Native Method) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:242) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:222) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/sun.security.jca.ProviderList.loadAll(ProviderList.java:315) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/sun.security.jca.ProviderList.removeInvalid(ProviderList.java:332) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/sun.security.jca.Providers.getFullProviderList(Providers.java:174) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at java.base/java.security.Security.insertProviderAt(Security.java:391) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at org.mozilla.jss.CryptoManager.initialize(CryptoManager.java:589) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at org.mozilla.jss.CryptoManager.initialize(CryptoManager.java:495) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at com.netscape.cmstools.cli.MainCLI.init(MainCLI.java:507) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at com.netscape.cmstools.nss.NSSCertExportCLI.execute(NSSCertExportCLI.java:75) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at org.dogtagpki.cli.CommandCLI.execute(CommandCLI.java:58) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at org.dogtagpki.cli.CLI.execute(CLI.java:357) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at org.dogtagpki.cli.CLI.execute(CLI.java:357) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at org.dogtagpki.cli.CLI.execute(CLI.java:357) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:656) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:694) Aug 28 11:02:56 master.ipa.test pki-server[31357]: Caused by: java.io.FileNotFoundException: /etc/pki/nssdb/secmod.db Aug 28 11:02:56 master.ipa.test pki-server[31357]: at jdk.crypto.cryptoki/sun.security.pkcs11.Secmod.initialize(Secmod.java:223) Aug 28 11:02:56 master.ipa.test pki-server[31357]: at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.<init>(SunPKCS11.java:212) Aug 28 11:02:56 master.ipa.test pki-server[31357]: ... 23 more Aug 28 11:02:56 master.ipa.test systemd[1]: pki-tomcatd: Control process exited, code=exited, status=255/EXCEPTION Aug 28 11:02:56 master.ipa.test systemd[1]: pki-tomcatd: Failed with result 'exit-code'. Aug 28 11:02:56 master.ipa.test systemd[1]: Failed to start PKI Tomcat Server pki-tomcat. Aug 28 11:02:56 master.ipa.test audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=pki-tomcatd@pki-tomcat comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Aug 28 11:02:56 master.ipa.test systemd[1]: pki-tomcatd: Consumed 2.815s CPU time. This is interesting, I can see this file on rhel-9: /etc/pki/nssdb/secmod.db It is part fo nss pacakge: rpm -qf /etc/pki/nssdb/secmod.db nss-3.67.0-13.el9.x86_64 which is required by openjdk package: rpm -qp --requires java-11-openjdk-headless-11.0.12.0.7-0.el9.x86_64.rpm | grep nss libnss3.so()(64bit) libnss3.so(NSS_3.53)(64bit) If you have some custom setup where /etc/pki/nssdb is "SQL-only", you may be facing this issue [1]. Adding "sql:" prefix to nssSecmodDirectory in nss.fips.cfg should fix this issue. (Also just creating dummy /etc/pki/nssdb/secmod.db file should probably fix this issue in that case.) [1] https://bugzilla.redhat.com/show_bug.cgi?id=1760437 FIPS support is not complete in Beta, it should work to some degree for most modules, but OpenSSL3.0 FIPS support requires manual configuration changes currently and may not be enforcing all the correct algorithms that we will enforce on 9.0 GA. So, testing may be challenging at this time. (In reply to zzambers from comment #7) > This is interesting, I can see this file on rhel-9: > /etc/pki/nssdb/secmod.db > > It is part fo nss pacakge: > rpm -qf /etc/pki/nssdb/secmod.db > nss-3.67.0-13.el9.x86_64 > > which is required by openjdk package: > rpm -qp --requires java-11-openjdk-headless-11.0.12.0.7-0.el9.x86_64.rpm | > grep nss > libnss3.so()(64bit) > libnss3.so(NSS_3.53)(64bit) > > If you have some custom setup where /etc/pki/nssdb is "SQL-only", you may be > facing this issue [1]. > Adding "sql:" prefix to nssSecmodDirectory in nss.fips.cfg should fix this > issue. > (Also just creating dummy /etc/pki/nssdb/secmod.db file should probably fix > this issue in that case.) > > [1] https://bugzilla.redhat.com/show_bug.cgi?id=1760437 Both in RHEL9 and in Fedora NSS already defaults to SQL storage -- since 2018: https://fedoraproject.org/wiki/Changes/NSSDefaultFileFormatSql (In reply to Alexander Bokovoy from comment #10) > Both in RHEL9 and in Fedora NSS already defaults to SQL storage -- since > 2018: https://fedoraproject.org/wiki/Changes/NSSDefaultFileFormatSql Openjdk itself also reacts to "sql:" prefix, see: [1][2]. It (currently) requires secmod.db file to exist, unless "sql:" prefix is used. [1] https://github.com/openjdk/jdk11u/blob/63fc945c1d4cdc893d89796804acfe0ce9341860/src/jdk.crypto.cryptoki/share/classes/sun/security/pkcs11/Secmod.java#L220 [2] https://github.com/openjdk/jdk11u/blob/63fc945c1d4cdc893d89796804acfe0ce9341860/src/jdk.crypto.cryptoki/share/native/libj2pkcs11/j2secmod.c#L105 I think this is a part of a problem -- since NSS already for three years is defaulting to SQL format and considers old data to be a 'one time backup', once you see key4.db and pkcs11.txt in the database directory, you need to stop thinking that secmod.db is required or used anymore. CCing our security guy While in FIPS mode, OpenJDK opens the NSS DB in read-only mode. The assumption there is that it'll be run with a non-privileged user, while only privileged users should be able to write on the /etc/pki/nssdb directory. So automatic migration won't work in this case, and there could be partially-migrated DBs. OpenJDK is able to handle SQL DBs, when the "sql:" prefix is specified in the 'nssSecmodDirectory' parameter (nss.fips.cfg). I believe that we should now make the change in the default value to SQL. The user can always modify the value back to the legacy DB. @ksiddiqu could you please try if adding "sql:" prefix to value of nssSecmodDirectory ( nssSecmodDirectory = sql:/etc/pki/nssdb ) in nss.fips.cfg (/etc/java/java-11-openjdk/java-11-openjdk-.../conf/security/nss.fips.cfg) fixes this issue? (In reply to zzambers from comment #15) > @ksiddiqu could you please try if adding "sql:" prefix to value > of nssSecmodDirectory ( nssSecmodDirectory = sql:/etc/pki/nssdb ) in > nss.fips.cfg > (/etc/java/java-11-openjdk/java-11-openjdk-.../conf/security/nss.fips.cfg) > fixes this issue? If confirmed this fixes the bug, can we move this bug to java-11-openjdk and request an exception to add this to the default config? Thanks. (In reply to zzambers from comment #15) > @ksiddiqu could you please try if adding "sql:" prefix to value > of nssSecmodDirectory ( nssSecmodDirectory = sql:/etc/pki/nssdb ) in > nss.fips.cfg > (/etc/java/java-11-openjdk/java-11-openjdk-.../conf/security/nss.fips.cfg) > fixes this issue? @zzambers Still the same issue even after the suggested change [root@master ~]# cat /etc/java/java-11-openjdk/java-11-openjdk-11.0.12.0.7-2.el9.x86_64/conf/security/nss.fips.cfg name = NSS-FIPS nssLibraryDirectory = /usr/lib64 nssSecmodDirectory = sql:/etc/pki/nssdb nssDbMode = readOnly nssModule = fips [root@master ~]# Configuring certificate server (pki-tomcatd). Estimated time: 3 minutes [1/28]: configuring certificate server instance Failed to configure CA instance 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. The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information [root@master ~]# journalctl -u pki-tomcatd -- Journal begins at Thu 2021-09-02 03:21:35 EDT, ends at Thu 2021-09-02 03:34:08 EDT. -- Sep 02 03:33:13 master.testrealm.test systemd[1]: Starting PKI Tomcat Server pki-tomcat... Sep 02 03:33:16 master.testrealm.test pki-server[7266]: ProviderException: Initialization failed Sep 02 03:33:16 master.testrealm.test systemd[1]: pki-tomcatd: Control process exited, code=exited, status=255/EXCEPTION Sep 02 03:33:16 master.testrealm.test systemd[1]: pki-tomcatd: Failed with result 'exit-code'. Sep 02 03:33:16 master.testrealm.test systemd[1]: Failed to start PKI Tomcat Server pki-tomcat. Sep 02 03:33:16 master.testrealm.test systemd[1]: pki-tomcatd: Consumed 2.136s CPU time. [root@master ~]# [root@master ~]# rpm -q ipa-server java-11-openjdk pki-ca ipa-server-4.9.6-6.el9.x86_64 java-11-openjdk-11.0.12.0.7-2.el9.x86_64 pki-ca-11.0.0-0.4.alpha1.el9.noarch [root@master ~]# Today I have been experimenting with ipa. I was able to reproduce the issue. My findings are following: FEDORA RAWHIDE: Issue on fedora rawhide [1] is separate issue as fedora rawhide no longer has legacy nss db files. Adding "sql:" prefix fixed problem for current rpms. ( java-11-openjdk-11.0.12.0.7-4.fc36.x86_64 - btw. does not include patches, which cause problems on rhel el9) RHEL-9: On rhel-9 problem is different. I was able to get little more info by adding "--debug" parameter to appropriate command in pki-tomcatd@.service systemd file ( ExecStartPre=/usr/sbin/pki-server --debug migrate %i ): Sep 02 13:27:30 master.example.com systemd[1]: Starting PKI Tomcat Server pki-tomcat... Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading instance type: pki-tomcatd Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading instance: pki-tomcat Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading password config: /etc/pki/pki-tomcat/password.conf Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg Sep 02 13:27:30 master.example.com pki-server[13630]: INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat Sep 02 13:27:30 master.example.com pki-server[13630]: DEBUG: - user: pkiuser Sep 02 13:27:30 master.example.com pki-server[13630]: DEBUG: - group: pkiuser Sep 02 13:27:30 master.example.com pki-server[13630]: DEBUG: Command: pki -d /etc/pki/pki-tomcat/alias -C /tmp/tmpp768it62/password.txt nss-cert-export --with-chain --format PEM Server-Cert cert-pki-ca /etc/pki/pki-tomcat/alias/ca.crt Sep 02 13:27:32 master.example.com pki-server[13633]: ProviderException: Initialization failed Sep 02 13:27:32 master.example.com pki-server[13630]: Traceback (most recent call last): Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/server/pkiserver.py", line 41, in <module> Sep 02 13:27:32 master.example.com pki-server[13630]: cli.execute(sys.argv) Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/server/cli/__init__.py", line 145, in execute Sep 02 13:27:32 master.example.com pki-server[13630]: super(PKIServerCLI, self).execute(args) Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/cli/__init__.py", line 217, in execute Sep 02 13:27:32 master.example.com pki-server[13630]: module.execute(module_args) Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/server/cli/migrate.py", line 98, in execute Sep 02 13:27:32 master.example.com pki-server[13630]: instance.init() Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/server/instance.py", line 840, in init Sep 02 13:27:32 master.example.com pki-server[13630]: super(PKIInstance, self).init() Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/server/__init__.py", line 324, in init Sep 02 13:27:32 master.example.com pki-server[13630]: self.export_ca_cert() Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/server/__init__.py", line 275, in export_ca_cert Sep 02 13:27:32 master.example.com pki-server[13630]: nssdb.extract_ca_cert(ca_path, nickname) Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/nssdb.py", line 1792, in extract_ca_cert Sep 02 13:27:32 master.example.com pki-server[13630]: self.export_cert_from_db(nickname, ca_path, include_chain=True, Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib/python3.9/site-packages/pki/nssdb.py", line 1386, in export_cert_from_db Sep 02 13:27:32 master.example.com pki-server[13630]: subprocess.check_call(cmd) Sep 02 13:27:32 master.example.com pki-server[13630]: File "/usr/lib64/python3.9/subprocess.py", line 373, in check_call Sep 02 13:27:32 master.example.com pki-server[13630]: raise CalledProcessError(retcode, cmd) Sep 02 13:27:32 master.example.com pki-server[13630]: subprocess.CalledProcessError: Command '['pki', '-d', '/etc/pki/pki-tomcat/alias', '-C', '/tmp/tmpp768it62/password.txt', 'nss-cert-export', '--with-chain', '--format', 'PEM', 'Server-Cert cert-pki-ca', '/etc/pki/pki-tomcat/alias/ca.crt']' returned non-zero exit status 255. Sep 02 13:27:32 master.example.com systemd[1]: pki-tomcatd: Control process exited, code=exited, status=255/EXCEPTION Sep 02 13:27:32 master.example.com systemd[1]: pki-tomcatd: Failed with result 'exit-code'. Sep 02 13:27:32 master.example.com systemd[1]: Failed to start PKI Tomcat Server pki-tomcat. Sep 02 13:27:32 master.example.com systemd[1]: pki-tomcatd: Consumed 1.623s CPU time. It creates pki process which then creates java process. I tried to edit code of pki (python) by adding parameter to disable FIPS providers (-Dcom.redhat.fips=false) for java process it creates (to see what happens), which fixed this issue. However I don't yet know why pki does not work with FIPS enabled openjdk with latest patches. Unfortunately we get very little output from java, which is not very helpful (exception probably comes from: [3], Why is there no stacktrace?): ProviderException: Initialization failed [1] https://bugzilla.redhat.com/show_bug.cgi?id=1999052#c3 [2] https://github.com/dogtagpki/pki/blob/03fdf6bc24369462b81d40a1906e00e4f4f038f6/base/common/python/pki/cli/main.py#L115 [3] https://github.com/openjdk/jdk11u/blob/63fc945c1d4cdc893d89796804acfe0ce9341860/src/jdk.crypto.cryptoki/share/classes/sun/security/pkcs11/SunPKCS11.java#L381 Ok, eventually I was able to get steps to reproduce this (based on output higher) without ipa and full stack trace: Steps to reproduce: mkdir /tmp/nssdb echo "nss.SECret.123" > /tmp/nssdb/password.txt certutil -N -d /tmp/nssdb -f /tmp/nssdb/password.txt pki --debug -d /tmp/nssdb -C /tmp/nssdb/password.txt nss-cert-export --with-chain --format PEM 'Server-Cert cert-pki-ca' /etc/pki/pki-tomcat/alias/ca.crt Output of pki with full stacktrace: INFO: PKI options: --debug -d /tmp/nssdb -C /tmp/nssdb/password.txt INFO: PKI command: nss-cert-export nss-cert-export --with-chain --format PEM Server-Cert cert-pki-ca /etc/pki/pki-tomcat/alias/ca.crt INFO: Java command: /usr/lib/jvm/jre-11-openjdk/bin/java -cp /usr/share/pki/lib/* -Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties com.netscape.cmstools.cli.MainCLI -d /tmp/nssdb -C /tmp/nssdb/password.txt --debug nss-cert-export --with-chain --format PEM Server-Cert cert-pki-ca /etc/pki/pki-tomcat/alias/ca.crt INFO: Server URL: https://master.example.com:8443 INFO: Loading NSS password from /tmp/nssdb/password.txt INFO: NSS database: /tmp/nssdb INFO: Message format: null INFO: Command: nss-cert-export --with-chain --format PEM "Server-Cert cert-pki-ca" /etc/pki/pki-tomcat/alias/ca.crt INFO: Module: nss INFO: Module: cert INFO: Module: export INFO: Initializing NSS java.security.ProviderException: Initialization failed at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.<init>(SunPKCS11.java:404) at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11$1.run(SunPKCS11.java:117) at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11$1.run(SunPKCS11.java:114) at java.base/java.security.AccessController.doPrivileged(Native Method) at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.configure(SunPKCS11.java:114) at java.base/sun.security.jca.ProviderConfig$3.run(ProviderConfig.java:251) at java.base/sun.security.jca.ProviderConfig$3.run(ProviderConfig.java:242) at java.base/java.security.AccessController.doPrivileged(Native Method) at java.base/sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:242) at java.base/sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:222) at java.base/sun.security.jca.ProviderList.loadAll(ProviderList.java:315) at java.base/sun.security.jca.ProviderList.removeInvalid(ProviderList.java:332) at java.base/sun.security.jca.Providers.getFullProviderList(Providers.java:174) at java.base/java.security.Security.insertProviderAt(Security.java:391) at org.mozilla.jss.CryptoManager.initialize(CryptoManager.java:589) at org.mozilla.jss.CryptoManager.initialize(CryptoManager.java:495) at com.netscape.cmstools.cli.MainCLI.init(MainCLI.java:516) at com.netscape.cmstools.nss.NSSCertExportCLI.execute(NSSCertExportCLI.java:75) at org.dogtagpki.cli.CommandCLI.execute(CommandCLI.java:58) at org.dogtagpki.cli.CLI.execute(CLI.java:357) at org.dogtagpki.cli.CLI.execute(CLI.java:357) at org.dogtagpki.cli.CLI.execute(CLI.java:357) at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:665) at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:701) Caused by: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_PIN_INCORRECT at jdk.crypto.cryptoki/sun.security.pkcs11.wrapper.PKCS11.C_Login(Native Method) at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.<init>(SunPKCS11.java:388) ... 23 more ERROR: Command: /usr/lib/jvm/jre-11-openjdk/bin/java -cp /usr/share/pki/lib/* -Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties com.netscape.cmstools.cli.MainCLI -d /tmp/nssdb -C /tmp/nssdb/password.txt --debug nss-cert-export --with-chain --format PEM Server-Cert cert-pki-ca /etc/pki/pki-tomcat/alias/ca.crt Traceback (most recent call last): File "/usr/lib/python3.9/site-packages/pki/cli/main.py", line 266, in <module> cli.execute(sys.argv) File "/usr/lib/python3.9/site-packages/pki/cli/main.py", line 253, in execute self.execute_java(cmd_args) File "/usr/lib/python3.9/site-packages/pki/cli/main.py", line 151, in execute_java subprocess.check_call(cmd, stdout=stdout) File "/usr/lib64/python3.9/subprocess.py", line 373, in check_call raise CalledProcessError(retcode, cmd) subprocess.CalledProcessError: Command '['/usr/lib/jvm/jre-11-openjdk/bin/java', '-cp', '/usr/share/pki/lib/*', '-Djava.util.logging.config.file=/usr/share/pki/etc/logging.properties', 'com.netscape.cmstools.cli.MainCLI', '-d', '/tmp/nssdb', '-C', '/tmp/nssdb/password.txt', '--debug', 'nss-cert-export', '--with-chain', '--format', 'PEM', 'Server-Cert cert-pki-ca', '/etc/pki/pki-tomcat/alias/ca.crt']' returned non-zero exit status 255. btw. certificates I am trying to export in reproducer are not present in nssdb, but it does not matter as it dies before it gets to that. Expected result here are that exceptions saying certificates not found. :) (In reply to zzambers from comment #19) > java.security.ProviderException: Initialization failed > at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.<init>(SunPKCS11.java:404) > at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11$1.run(SunPKCS11.java:117) > at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11$1.run(SunPKCS11.java:114) > at java.base/java.security.AccessController.doPrivileged(Native Method) > at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.configure(SunPKCS11.java:114) > at java.base/sun.security.jca.ProviderConfig$3.run(ProviderConfig.java:251) > at java.base/sun.security.jca.ProviderConfig$3.run(ProviderConfig.java:242) > at java.base/java.security.AccessController.doPrivileged(Native Method) > at java.base/sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:242) > at java.base/sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:222) > at java.base/sun.security.jca.ProviderList.loadAll(ProviderList.java:315) > at java.base/sun.security.jca.ProviderList.removeInvalid(ProviderList.java:332) > at java.base/sun.security.jca.Providers.getFullProviderList(Providers.java:174) > at java.base/java.security.Security.insertProviderAt(Security.java:391) > at org.mozilla.jss.CryptoManager.initialize(CryptoManager.java:589) https://github.com/dogtagpki/jss/blob/v5.0.0-alpha1/src/main/java/org/mozilla/jss/CryptoManager.java#L589 > at org.mozilla.jss.CryptoManager.initialize(CryptoManager.java:495) > at com.netscape.cmstools.cli.MainCLI.init(MainCLI.java:516) https://github.com/dogtagpki/pki/blob/9f4097501957d941e905688b8326a941b1c859fb/base/tools/src/main/java/com/netscape/cmstools/cli/MainCLI.java#L516 > at com.netscape.cmstools.nss.NSSCertExportCLI.execute(NSSCertExportCLI.java:75) > at org.dogtagpki.cli.CommandCLI.execute(CommandCLI.java:58) > at org.dogtagpki.cli.CLI.execute(CLI.java:357) > at org.dogtagpki.cli.CLI.execute(CLI.java:357) > at org.dogtagpki.cli.CLI.execute(CLI.java:357) > at com.netscape.cmstools.cli.MainCLI.execute(MainCLI.java:665) > at com.netscape.cmstools.cli.MainCLI.main(MainCLI.java:701) https://github.com/dogtagpki/pki/blob/9f4097501957d941e905688b8326a941b1c859fb/base/tools/src/main/java/com/netscape/cmstools/cli/MainCLI.java#L701 > Caused by: sun.security.pkcs11.wrapper.PKCS11Exception: CKR_PIN_INCORRECT > at jdk.crypto.cryptoki/sun.security.pkcs11.wrapper.PKCS11.C_Login(Native Method) > at jdk.crypto.cryptoki/sun.security.pkcs11.SunPKCS11.<init>(SunPKCS11.java:388) > ... 23 more Seems like a clash between jss and patched pkcs11 FIPS mode provider. But even though, this bug was triggered by change in openjdk, I don't think this is something to be fixed in openjdk. (I think change in openjdk, more or less, just makes NSS init more eager.) Problem, as I see it, is, that dogtagpki actually adds 3rd security party provider (JSS) and inserts in into list of security providers (see my stacktrace analysis higher [1]). But JSS clashes with with pkcs11 provider used by openjdk in FIPS mode, as both providers act as binding to underlying NSS library. I have found this commit in dogtagpki, which prevents switch to redhat's pkcs11 fips mode provider setup (when in FIPS mode) in tomcat config, to avoid "race" between these 2 providers (See: [2]). I think we see different form of the same issue here. From technical perspective pki can be patched to use the same solution as tomcat config. That is to pass -Dcom.redhat.fips=true parameter to java executable. I have already tested this and it fixes the issue (for more details see: [3]). But as I said, this is technical perspective, when it comes to effect on FIPS conformance, I can't judge that. ( But seems tomcat config is already doing that anyway and that config is OK with FIPS according to commit message. ) [1] https://bugzilla.redhat.com/show_bug.cgi?id=1999052#c21 [2] https://github.com/dogtagpki/pki/commit/ca428b43651e8f7e3d28ef32c9a50c50aa3f83c9 [3] https://bugzilla.redhat.com/show_bug.cgi?id=1999052#c18 * 3rd party security provider I can reproduce it on rhel-8 with this openjdk build: java-1.8.0-openjdk-1.8.0.302.b08-3.el8 I have made clone of this bug for RHEL-8.5: https://bugzilla.redhat.com/show_bug.cgi?id=2001576 Thank you, Zdenek. Regarding FIPS and JSS, JSS is a wrapper over NSS library, not a separate crypto provider in itself. It relies on FIPS state of NSS. I think historically SunPKCS11 library was not enough for PKI for its CA operations, thus JSS was born. If the scope of the change is to enforce -Dcom.redhat.fips=false for Java processes started by PKI, then this is something that should be handled in pki-core, probably. Most of PKI team is in US and are on PTO due to Labor Day holiday. Chris, can you handle the change similar to https://github.com/dogtagpki/pki/commit/ca428b43651e8f7e3d28ef32c9a50c50aa3f83c9 ? (In reply to Alexander Bokovoy from comment #33) > Thank you, Zdenek. > > Regarding FIPS and JSS, JSS is a wrapper over NSS library, not a separate > crypto provider in itself. It relies on FIPS state of NSS. I think > historically SunPKCS11 library was not enough for PKI for its CA operations, > thus JSS was born. > > If the scope of the change is to enforce -Dcom.redhat.fips=false for Java > processes started by PKI, then this is something that should be handled in > pki-core, probably. > > Most of PKI team is in US and are on PTO due to Labor Day holiday. > Chris, can you handle the change similar to > https://github.com/dogtagpki/pki/commit/ > ca428b43651e8f7e3d28ef32c9a50c50aa3f83c9 ? I think this is the right move, at least in the short term. While having both JSS and the SunPKCS11 provider using NSS at the same time may have worked to some degree before, it would still be prone to issues like this. The change we added to the OpenJDK FIPS support makes the SunPKCS11 provider login to NSS eagerly at initialisation. Prior to this change, it was only logging in as part of an actual operation being performed. The change was necessary, because some operations would not login to the NSS provider and thus fail. The error we see here is because JSS is trying to login after the SunPKCS11 provider has already logged in. This could have happened under the previous setup if a SunPKCS11 operation which involved login happened prior to the JSS provider logging in i.e. it was always fragile. How does JSS insert itself into the provider stack if it is not a regular provider? It may be that the right long term solution is to use JSS as the FIPS provider instead of PKCS11 when available, and then it can take advantage of the OpenJDK FIPS work to ensure exclusive use of that provider. At present, the OpenJDK FIPS support works by switching the list of providers in java.security with those specified by a series of fips.provider.n properties, where n is the provider number. These are defined in java.security as follows: # Security providers used when global crypto-policies are set to FIPS. # fips.provider.1=SunPKCS11 ${java.home}/conf/security/nss.fips.cfg fips.provider.2=SUN fips.provider.3=SunEC fips.provider.4=SunJSSE It may be that the best long term solution for JSS is to be fips.provider.1 instead of SunPKCS11, rather than trying to race with it. With SunPKCS11 absent from the provider list, there would be no such competition between the two. Let me know if that seems feasible and there is some way we can help to make it happen. |