168262 - Expose NSS's PKCS#11 logging function

Status: RESOLVED WONTFIX

(JSS Graveyard :: Library, defect)

Description

[thomask]

In the new NSS library, they have a feature where all the PKCS#11 transaction 
can be logged to a file, and this feature can only be activated by envornment 
variable.

It may be a good idea to expose API at JSS level to activate it. For example,

  CryptoManager.enableLogging("/tmp/nss.log");

Comment 1

[thomask]

Simiarly, we will be useful if we can enable
ssl logging via JSS.

CryptoManager.enableSSLLogging("/tmp/ssl.log");

Comment 2

[Jamie Nicolson]

Rename JSS 3.2.1 to JSS 3.3.

Comment 3

[Jamie Nicolson]

The way the logging is implemented is they put a dummy PKCS #11 module between
NSS and the real PKCS #11 module. That layer prints out log messages. The
logging layer has to be installed when the module is installed, that is, at
NSS_Init time. It may be possible to do this after initialization, but not with
the current version of NSS. Why can't you just set it up at initialization time?

What kind of logging did you have in mind for SSL? The only logging I see in SSL
currently is SSL_DBG messages. I have listed them below. Would they suffice?

Either way, there will need to be changes in NSS to support these new APIs.

ssl3con.c:              SSL_DBG(("%d: SSL3[%d]: SendRecord, tried to get %d bytes",
ssl3con.c:      SSL_DBG(("%d: SSL3[%d]: bad v2 client hello message, len=%d
should=%d",
ssl3con.c:              SSL_DBG(("%d: SSL3[%d]: go to async cert handler",
ssl3con.c:    SSL_DBG(("%d: SSL3[%d]: peer certificate is no good: error=%d",
ssl3con.c:      SSL_DBG(("%d: SSL3[%d]: HandleRecord, resuming handshake",
ssl3con.c:          SSL_DBG(("%d: SSL3[%d]: HandleRecord, tried to get %d bytes",
ssl3con.c:      SSL_DBG(("%d: SSL3[%d]: mac check failed", SSL_GETPID(), ss->fd));
ssl3con.c:      SSL_DBG(("%d: SSL3[%d]: bogus content type=%d",
ssl3gthr.c:         SSL_DBG(("%d: SSL3[%d]: recv error %d", SSL_GETPID(), ss->fd,
sslauth.c:      SSL_DBG(("%d: SSL[%d]: bad socket in PeerCertificate",
sslauth.c:      SSL_DBG(("%d: SSL[%d]: bad socket in PeerCertificate",
sslauth.c:      SSL_DBG(("%d: SSL[%d]: bad socket in SecurityStatus",
sslauth.c:      SSL_DBG(("%d: SSL[%d]: bad socket in AuthCertificateHook",
sslauth.c:      SSL_DBG(("%d: SSL[%d]: bad socket in GetClientAuthDataHook",
sslauth.c:      SSL_DBG(("%d: SSL[%d]: bad socket in GetClientAuthDataHook",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: Can't handshake! both v2 and v3 disabled.",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: ssl2_GetSendBuffer failed, tried to
get %d bytes",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: ssl2_CreateSessionCypher: unknown cipher=%d",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: keySize=%d ckLen=%d max session key size=%d",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: ssl2_ServerSetupSessionCypher: unknown
cipher=%d",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: odd secret key size, keySize=%d ckLen=%d!",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: strange encryption block",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: no cipher overlap", SSL_GETPID(), ss->fd));
sslcon.c:       SSL_DBG(("%d: SSL[%d]: decode of server certificate fails",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: extract public key failed: error=%d",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: dup client-finished message",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: bad connection-id", SSL_GETPID(),
ss->fd));
sslcon.c:           SSL_DBG(("%d: SSL[%d]: dup server-finished message",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: bad server-finished message, len=%d",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: bad cert request message: code len=%d",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: unknown message %d",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: client, huh? hit=%d certLen=%d csLen=%d",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: no cipher overlap",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: client, huh? certLen=%d csLen=%d",
sslcon.c:                   SSL_DBG(("%d: SSL[%d]: go to async cert handler",
sslcon.c:               SSL_DBG(("%d: SSL[%d]: server certificate is no good:
error=%d",
sslcon.c:           SSL_DBG(("%d: SSL[%d]: server certificate is no good: error=%d",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: protocol size mismatch dataLen=%d",
sslcon.c:       SSL_DBG(("%d: SSL[%d]: bad client hello message, len=%d should=%d",
sslgathr.c:         SSL_DBG(("%d: SSL[%d]: recv error %d", SSL_GETPID(), ss->fd,
sslgathr.c:             SSL_DBG(("%d: SSL[%d]: sender, count=%d blockSize=%d",
sslgathr.c:             SSL_DBG(("%d: SSL[%d]: mac check failed, seq=%d",
sslimpl.h:#define SSL_DBG(b) if (ssl_debug) ssl_Trace b
sslimpl.h:#define SSL_DBG(b)
sslinfo.c:      SSL_DBG(("%d: SSL[%d]: bad socket in SSL_GetChannelInfo",
sslsecur.c:     SSL_DBG(("%d: SSL[%d]: bad socket in ResetHandshake",
SSL_GETPID(), s));
sslsecur.c:     SSL_DBG(("%d: SSL[%d]: bad socket in RedoHandshake",
SSL_GETPID(), fd));
sslsecur.c:     SSL_DBG(("%d: SSL[%d]: bad socket in HandshakeCallback",
sslsecur.c:     SSL_DBG(("%d: SSL[%d]: bad socket in ForceHandshake",
sslsecur.c:     SSL_DBG(("%d: SSL[%d]: connect failed, errno=%d",
sslsecur.c:     SSL_DBG(("%d: SSL[%d]: bad socket in SSLBadCertHook",
sslsecur.c:     SSL_DBG(("%d: SSL[%d]: bad socket in SSLSetURL",
sslsnce.c:          SSL_DBG(("%d: SSL: masterKeyLen=%d cipherArgLen=%d",
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in Enable", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in Enable", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in CipherPrefSet",
SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in CipherPrefGet",
SSL_GETPID(), fd));
sslsock.c:          SSL_DBG(("%d: SSL[%d]: bad model socket in ssl_ImportFD", 
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in accept", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: accept failed, errno=%d",
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in connect", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in bind", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in listen", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in shutdown", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in close", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in recv", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in send", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in read", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in write", SSL_GETPID(), fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in getpeername", SSL_GETPID(),
fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in getsockname", SSL_GETPID(),
fd));
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in SSL_SetCacheIndex",
sslsock.c:      SSL_DBG(("%d: SSL[%d]: bad socket in SSL_Poll",

Comment 4

[thomask]

1/ Last time we were debugging the configuration daemon (the one that setup and 
configure CMS). We had problem passing the environment variables to the 
configuration daemon. The daemon was started by a cgi that is started by the web 
server. I did try to put the environment variable in the web server's 
configuration file, and hope that will be passed down into the daemon. No 
luck. Since the daemon has JSS access, it will be easier to enable logging via 
JSS API.


2/ Would be like to be able to specify a filename for the SSL logging? 
Currently, it just go to the standard out. On windows, the server is started as 
a service which does not have access to the standard out.

Comment 5

[BMO Automation]

JSS development has moved from the Mozilla community to the Dogtag PKI community. Please re-file this bug at https://github.com/dogtagpki/jss if it is still relevant. Thank you!