[Mod_nss-list] Inconsistent SSL issues with HSM

[George]

We have been troubleshooting SSL issues using Apache with mod_nss and
Safenet HSMs for quite a while, so hopefully you can provide some insight.

Red Hat Enterprise Linux Server release 7.6 (Maipo)
httpd.x86_64                      2.4.6-90.el7
@rhel-7-server-rpms
mod_nss.x86_64                    1.0.14-12.el7
 @rhel-7-server-rpms
nss.x86_64                        3.36.0-7.1.el7_6
@rhel-7-server-rpms

Apache is configured with mod_nss and Safenet libcryptoki, using TLSv1.2.
We see that in a seemingly random fashion, the Apache worker suddenly can't
talk to the HSM anymore, and can't recover from that. All subsequent
requests handled by this worker fail with the same error message. Only way
to recover is to kill the worker (or restart whole Apache):

[Tue Sep 24 20:21:19.375686 2019] [:error] [pid 2646] SSL Library Error:
-8152 The key does not support the requested operation

Packet captures show that the incoming TLS Client Hello that triggers the
error is identical to a successful one. We have noticed, nevertheless, that
there *might* be some correspondence with TLS session reuse. There have
been several instances in which a worker fails with this error soon after
handling a resumed TLS session (so the worker receives a Client Hello with
a session-id, successfully handles the request without renegotiation but
fails soon after on a subsequent request). Anyway, I couldn't find any way
to effectively disable TLS session reuse in mod_nss (can that be done??)

We have also sniffed the PKCS11 conversation between NSS and the HSM and
can we see where the problem occurs. It looks that the Apache worker is
trying to perform operations on an invalid object handle (pay attention to
hObject=0x00001A60). PID 2646 is the Apache worker that failed in the
example before:

pid(2646) tid(140580153710720) time(24/09/2019,20:21:19.313)     >
C_GetAttributeValue hSession=0x00020001 hObject=0x00001A60
pTemplate=0x0x7ffe7173b7c0 count=1
pid(2646) tid(140580153710720) time(24/09/2019,20:21:19.348)     <<
C_GetAttributeValue rv=0x00000082{object handle invalid}
pTemplate=0x0x7ffe7173b7c0

pid(2646) tid(140580153710720) time(24/09/2019,20:21:19.357)     >
C_SignInit hSession=0x0002005B
pMechanism=0x0x7ffe7173b760{type=0x1{RSA_PKCS} pParam=0x(nil) paramLen=0}
hObject=0x00001A60
pid(2646) tid(140580153710720) time(24/09/2019,20:21:19.374)     <<
C_SignInit rv=0x00000060{key handle invalid}


That object handler 0x00001A60 seems to have been explicitly destroyed by
the same process more than 2 hours before in this example:

pid(2646) tid(140580153710720) time(24/09/2019,18:00:09.521)     >
C_DestroyObject hSession=0x00020001 hObject=0x00001A60
pid(2646) tid(140580153710720) time(24/09/2019,18:00:09.523)     <
C_DestroyObject rv=0x00000000{success}


Any further information or ideas are welcome.

Best regards!

George
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/mod_nss-list/attachments/20200221/ec180cb3/attachment.htm>