[Pki-users] Dogtag Installation 10.6 on RHEL 8 Failing against NCipher HSM

David Etchen david.etchen at nccgroup.com
Mon Jul 1 22:13:07 UTC 2019


Hi All,

I'm doing a basic CA installation of Dogtag 10.6 on RHEL 8 using an NCipher Connect HSM.
Installed Packages
Name         : pki-ca
Version      : 10.6.9
Release      : 2.module+el8+2728+a4ad6bba
Arch         : noarch
Size         : 2.3 M
Source       : pki-core-10.6.9-2.module+el8+2728+a4ad6bba.src.rpm

The installation runs through fine generating the private keys and public certs.
I'm using:
pkispawn -f ca.cfg -s CA -vv

But when it comes to near the end where it tries to fireup the final instance it fails.

>From what I gather from the logs is that it's having trouble understanding which private key is associated with the certificate.

I've had a look in the nssdb and I can see the public and private certs
[root@ ~]# certutil -L -d /var/lib/pki/pki-tomcat/alias -h accelerator -P accelerator

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

accelerator:ca_signing                                       u,u,u
accelerator:ca_ocsp_signing                                  u,u,u
accelerator:subsystem                                        u,u,u
accelerator:ca_audit_signing                                 u,u,u
accelerator:sslserver                                        u,u,u


[root@ ~]# certutil -K -d /var/lib/pki/pki-tomcat/alias -h accelerator -P accelerator
certutil: Checking token "accelerator" in slot "XXXX-XXXX-XXXX Rt1"
< 0> rsa      53d1f55d8615a5bba2f65e24e506a51cc1830803   ca_signing
< 1> rsa      90d57df4f4fd65f3d54c6ee4461c141af59d9ead   ca_ocsp_signing
< 2> rsa      3a9abb6b503489a6ebc4601bd4e3358626502325   accelerator:sslserver
< 3> rsa      c707ad2ca6ab592c5f2658e92808a2d1952cd2eb   subsystem
< 4> rsa      105f918fe93883fcba4a14319b8511b24bee9f7d   ca_audit_signing

Debug console output from pkispawn:
configuration : INFO     Removing temp SSL server cert from internal token: sslserver
pki.nssdb     : DEBUG    Command: certutil -F -d /var/lib/pki/pki-tomcat/alias -f /tmp/tmppzqg2r_k/password.txt -n sslserver
configuration : INFO     Importing permanent SSL server cert into accelerator token: sslserver
pki.nssdb     : DEBUG    Command: certutil -A -d /var/lib/pki/pki-tomcat/alias -h accelerator -P accelerator -f /tmp/tmpbt1mgtq4/password.txt -n sslserver -a -i /tmp/tmp6nd6b9ne/sslserver.crt -t
certutil: could not change trust on certificate: SEC_ERROR_TOKEN_NOT_LOGGED_IN: The operation failed because the PKCS#11 token is not logged in.
pki.nssdb     : WARNING  certutil returned non-zero exit code (bug #1393668)
pkihelper     : INFO     Starting pki-tomcat instance
pkihelper     : DEBUG    Command: systemctl daemon-reload
pkihelper     : DEBUG    Command: systemctl start pki-tomcatd at pki-tomcat.service<mailto:pki-tomcatd at pki-tomcat.service>
pkihelper     : INFO     FIPS mode is enabled on this operating system.
pkispawn      : INFO     Checking server at http://sc.test.com:8080/ca
pkispawn      : INFO     Waiting for server to start (1s)
pkispawn      : INFO     Waiting for server to start (2s)
pkispawn      : INFO     Waiting for server to start (3s)
pkispawn      : INFO     Waiting for server to start (4s)

Installation failed:
<!doctype html><html lang="en"><head><title>HTTP Status 500 - Internal Server Error</title><style type="text/css">h1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} h2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} h3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} body {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} b {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} p {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;} a {color:black;} a.name {color:black;} .line {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP Status 500 - Internal Server Error</h1><hr class="line" /><p><b>Type</b> Exception Report</p><p><b>Message</b> Subsystem unavailable</p><p><b>Description</b> The server encountered an unexpected condition that prevented it from fulfilling the request.</p><p><b>Exception</b></p><pre>javax.ws.rs.ServiceUnavailableException: Subsystem unavailable
        com.netscape.cms.tomcat.ProxyRealm.findSecurityConstraints(ProxyRealm.java:150)
        org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483)
        com.netscape.cms.tomcat.ExternalAuthenticationValve.invoke(ExternalAuthenticationValve.java:82)
        org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:651)
        org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
        org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:414)
        org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:754)
        org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1376)
        org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        java.lang.Thread.run(Thread.java:748)
</pre><p><b>Note</b> The full stack trace of the root cause is available in the server logs.</p><hr class="line" /><h3>Apache Tomcat/9.0.7.redhat-10</h3></body></html>

Debug output from /var/log/pki/pki-tomcat/ca/debug.log
2019-07-01 14:00:57 [main] FINE: CertificateAuthority: size: 977 bytes
2019-07-01 14:00:57 [main] FINE: CertificateAuthority: subject DN: CN=CA Signing Certificate,OU=pki-tomcat,O=sc.test.com
2019-07-01 14:00:57 [main] FINE: CertificateAuthority: issuer DN: CN=CA Signing Certificate,OU=pki-tomcat,O=sc.test.com
2019-07-01 14:00:57 [main] FINE: CA SigningUnit.init(ca, ca.signing, null)
2019-07-01 14:00:57 [main] FINE: Setting ca.signing.newNickname=accelerator:ca_signing
2019-07-01 14:00:57 [main] FINE: SigningUnit: Loading certificate accelerator:ca_signing
2019-07-01 14:00:57 [main] FINE: SigningUnit: certificate serial number: 1
2019-07-01 14:00:57 [main] FINE: SigningUnit: Loading private key
2019-07-01 14:00:57 [main] FINE: SigningUnit: private key ID: 53d1f55d8615a5bba2f65e24e506a51cc1830803
2019-07-01 14:00:57 [main] SEVERE: Exception: Algorithm SHA256withRSA is not supported for the signing token and key
Algorithm SHA256withRSA is not supported for the signing token and key
        at com.netscape.ca.SigningUnit.checkSigningAlgorithmFromName(SigningUnit.java:249)
        at com.netscape.ca.SigningUnit.init(SigningUnit.java:186)
        at com.netscape.ca.CertificateAuthority.initSigUnit(CertificateAuthority.java:1722)
        at com.netscape.ca.CertificateAuthority.init(CertificateAuthority.java:547)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:975)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:833)
        at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:826)
        at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:491)
        at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:149)
        at javax.servlet.GenericServlet.init(GenericServlet.java:158)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
        at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:170)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:123)
        at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1112)
        at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1079)
        at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:971)
        at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4788)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5100)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:742)
        at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:130)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:151)
        at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:141)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:716)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:703)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:630)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1839)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:525)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:424)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1585)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:308)
        at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:123)
        at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:424)
        at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:367)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:966)
        at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:839)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1427)
        at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1417)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)
        at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:943)
        at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:258)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardService.startInternal(StandardService.java:422)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:770)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:682)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:350)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:492)
Caused by: java.security.InvalidKeyException: org.mozilla.jss.crypto.NoSuchItemOnTokenException: Key is not present on this token
        at org.mozilla.jss.pkcs11.PK11Signature.engineInitSign(PK11Signature.java:78)
        at org.mozilla.jss.crypto.Signature.initSign(Signature.java:55)
        at com.netscape.ca.SigningUnit.checkSigningAlgorithmFromName(SigningUnit.java:235)
        ... 68 more

I noticed the entry
pki.nssdb     : DEBUG    Command: certutil -A -d /var/lib/pki/pki-tomcat/alias -h accelerator -P accelerator -f /tmp/tmpbt1mgtq4/password.txt -n sslserver -a -i /tmp/tmp6nd6b9ne/sslserver.crt -t
certutil: could not change trust on certificate: SEC_ERROR_TOKEN_NOT_LOGGED_IN: The operation failed because the PKCS#11 token is not logged in.
pki.nssdb     : WARNING  certutil returned non-zero exit code (bug #1393668)

However I believe this relates to an old bug as it indicates using nss with pkcs11 interfaces will fail but when I look in the nssdb the cert is present.

The issue I think is around the system getting access to the private key for the ca_signing cert
Caused by: java.security.InvalidKeyException: org.mozilla.jss.crypto.NoSuchItemOnTokenException: Key is not present on this token

Could it be as simple as it's looking in the local store instead of the HSM backed location as this does have certificates present for some reason.
[root@ ~]# certutil -L -d /var/lib/pki/pki-tomcat/alias

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

ca_signing                                                   CT,C,C
ca_audit_signing                                             ,,P

[root@ ~]# certutil -K -d /var/lib/pki/pki-tomcat/alias
certutil: Checking token "NSS Certificate DB" in slot "NSS User Private Key and Certificate Services"
Enter Password or Pin for "NSS Certificate DB":
certutil: no keys found

As expected the local nssdb does not have the keys present.

Any ideas or pointers would be greatly appreciated.
Oh just to add this works on RHEL 7.6 with dogtag 10.5.9

Also not sure why it thinks I'm running in FIPS mode. When I check it seems to suggest not.
[root@ ~]# sysctl crypto.fips_enabled
crypto.fips_enabled = 0

Thanks
Dave Etchen

________________________________
David Etchen
Senior Systems Engineer
NCC Group
XYZ Building, 2 Hardman Boulevard, Spinningfields, Manchester, M3 3AQ

Telephone: +44 7703 501 120<tel:+44%207703%20501%20120>
Mobile: +44 7703 501 120<tel:+44%207703%20501%20120>
Website: www.nccgroup.trust<http://www.nccgroup.trust>
Twitter: @NCCGroupplc<https://twitter.com/NCCGroupplc>
        [https://www.nccgroup.trust/static/img/emaillogo/ncc-group-logo.png]  <http://www.nccgroup.trust/>
________________________________

This email is sent for and on behalf of NCC Group. NCC Group is the trading name of NCC Services Limited (Registered in England CRN: 2802141). The ultimate holding company is NCC Group plc (Registered in England CRN: 4627044). This email may be confidential and/or legally privileged.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/pki-users/attachments/20190701/bfc4872b/attachment.htm>


More information about the Pki-users mailing list