Re: NSS 3.12.5: Error '-8023' ... how to track it down?
On Thu, Jan 13, 2011 at 2:53 AM, Bernhard Thalmayr wrote: > > It might be helpfull if SSLTRACE and PKCS#11 could log a timestamp to help > in correlation. You can add 'timestamp' to the NSPR_LOG_MODULES environment variable. See http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25306 This should add timestamps to PKCS #11 logging. I don't know if SSLTRACE is based on NSPR logging... Wan-Teh -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
Re: NSS 3.12.5: Error '-8023' ... how to track it down?
On Wed, Jan 12, 2011 at 2:38 PM, Robert Relyea wrote: > On 01/12/2011 01:26 PM, Bernhard Thalmayr wrote: >> 331569088[1bd1610]: C_UnwrapKey >> 331569088[1bd1610]: hSession = 0x6 >> 331569088[1bd1610]: pMechanism = 0x7fffcd592ea0 >> 331569088[1bd1610]: hUnwrappingKey = 0x8 >> 331569088[1bd1610]: pWrappedKey = 0x36ac9bc >> 331569088[1bd1610]: ulWrappedKeyLen = 48 >> 331569088[1bd1610]: pTemplate = 0x7fffcd592cf0 >> 331569088[1bd1610]: ulAttributeCount = 6 >> 331569088[1bd1610]: phKey = 0x36bfd58 >> 331569088[1bd1610]: CKA_SIGN = CK_TRUE [1] >> 331569088[1bd1610]: CKA_VERIFY = CK_TRUE [1] >> 331569088[1bd1610]: CKA_CLASS = CKO_SECRET_KEY [8] >> 331569088[1bd1610]: CKA_KEY_TYPE = 0x10 [8] >> 331569088[1bd1610]: CKA_DERIVE = CK_TRUE [1] >> 331569088[1bd1610]: CKA_VALUE_LEN = 3000 [8] >> 331569088[1bd1610]: mechanism = CKM_DES3_ECB >> 331569088[1bd1610]: *phKey = 0x54 > The extra data here is dumping out interesting values inside the > parameters passed to C_UnwrapKey. The list of CKA_ = X are > dumping out the template sent in pTemplate. CKA_VALUE_LEN looks wrong to > me, I don't know if tehre is some byteswap issue here. I looked into the CKA_VALUE_LEN issue. I found that our PKCS #11 logger prints CKA_VALUE_LEN as a hex dump. So 3000 [8] means a sequence of 8 bytes: 0x30 0x00 0x00 0x00 0x00 0x00 0x00 0x00 On a little-endian system (such as x86/x64), this is 48 decimal, which is the length of the SSL/TLS master secret. I filed an NSS bug https://bugzilla.mozilla.org/show_bug.cgi?id=625491 to improve the logging of CKA_VALUE_LEN, with a patch. Wan-Teh -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
Re: NSS 3.12.5: Error '-8023' ... how to track it down?
On 01/13/2011 10:46 AM, Bernhard Thalmayr wrote: > Hi again, > > today I a built a debug version of NSS 3.12.8 (as I haven't found > 3.12.9 yet) I wouldn't expect 3.12.9 to fix the problem, as you seem to be running into a unique issue. > > The issue is still there, but occours much later then with 3.12.5. Hmm, I'm not sure what changes between 3.12.8 and 3.12.5 would generate this. What is the actual client software you are running? I sounds like someone is overwriting some buffers and causing very bizarre behavior. > > Server (with lib using NSS) ran about 1.5 hours before the issue > occoured. During this time 911 SSL connections have been done. The > last 6 failed (and then I stopped). > > It seems SSLTRACE log has been truncated ... is there a limit? (It > shows much less connections as the lib's log does). > > PKCS#11 logger now seems to be ok, but shows 'CKR_DEVICE_ERRORS' for > other functions as for 3.12.5. > > 822564800[1581690]: C_OpenSession > 822564800[1581690]: slotID = 0x1 > 822564800[1581690]: flags = 0x4 > 822564800[1581690]: pApplication = 0x1884150 > 822564800[1581690]: Notify = 0x30468315 > 822564800[1581690]: phSession = 0x7fffb77fd208 > 822564800[1581690]: *phSession = 0x1884150 > 822564800[1581690]: rv = CKR_DEVICE_ERROR > 822564800[1581690]: C_DigestInit > 822564800[1581690]: hSession = 0x1 > 822564800[1581690]: pMechanism = 0x7fffb77fd260 > 822564800[1581690]: mechanism = CKM_MD5 > 822564800[1581690]: rv = CKR_DEVICE_ERROR > 822564800[1581690]: C_OpenSession > 822564800[1581690]: slotID = 0x1 > 822564800[1581690]: flags = 0x4 > 822564800[1581690]: pApplication = 0x1884150 > 822564800[1581690]: Notify = 0x30468315 > 822564800[1581690]: phSession = 0x7fffb77fd208 > 822564800[1581690]: *phSession = 0x1884150 > 822564800[1581690]: rv = CKR_DEVICE_ERROR > 822564800[1581690]: C_DigestInit > 822564800[1581690]: hSession = 0x1 > 822564800[1581690]: pMechanism = 0x7fffb77fd260 > 822564800[1581690]: mechanism = CKM_SHA_1 > 822564800[1581690]: rv = CKR_DEVICE_ERROR > ... > .. > > Once the 'CKR_DEVICE_ERROR' occoured it seems to be unrecoverable. > > Could this be a file-system problem? That sounds like exactly the behavior of the FIPS token if it hits the unrecoverable error state, but clearly you are using Slot 1, not Slot 3 (the FIPS slot). None of this matches anything I would expect to see with NSS talking to softoken.;(. > > TIA, > Bernhard -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
Re: NSS 3.12.5: Error '-8023' ... how to track it down?
Hi again, today I a built a debug version of NSS 3.12.8 (as I haven't found 3.12.9 yet) The issue is still there, but occours much later then with 3.12.5. Server (with lib using NSS) ran about 1.5 hours before the issue occoured. During this time 911 SSL connections have been done. The last 6 failed (and then I stopped). It seems SSLTRACE log has been truncated ... is there a limit? (It shows much less connections as the lib's log does). PKCS#11 logger now seems to be ok, but shows 'CKR_DEVICE_ERRORS' for other functions as for 3.12.5. 822564800[1581690]: C_OpenSession 822564800[1581690]: slotID = 0x1 822564800[1581690]: flags = 0x4 822564800[1581690]: pApplication = 0x1884150 822564800[1581690]: Notify = 0x30468315 822564800[1581690]: phSession = 0x7fffb77fd208 822564800[1581690]: *phSession = 0x1884150 822564800[1581690]: rv = CKR_DEVICE_ERROR 822564800[1581690]: C_DigestInit 822564800[1581690]: hSession = 0x1 822564800[1581690]: pMechanism = 0x7fffb77fd260 822564800[1581690]: mechanism = CKM_MD5 822564800[1581690]: rv = CKR_DEVICE_ERROR 822564800[1581690]: C_OpenSession 822564800[1581690]: slotID = 0x1 822564800[1581690]: flags = 0x4 822564800[1581690]: pApplication = 0x1884150 822564800[1581690]: Notify = 0x30468315 822564800[1581690]: phSession = 0x7fffb77fd208 822564800[1581690]: *phSession = 0x1884150 822564800[1581690]: rv = CKR_DEVICE_ERROR 822564800[1581690]: C_DigestInit 822564800[1581690]: hSession = 0x1 822564800[1581690]: pMechanism = 0x7fffb77fd260 822564800[1581690]: mechanism = CKM_SHA_1 822564800[1581690]: rv = CKR_DEVICE_ERROR ... .. Once the 'CKR_DEVICE_ERROR' occoured it seems to be unrecoverable. Could this be a file-system problem? TIA, Bernhard -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
Re: Firefox PSM locks NSS
> If your module locks the DB while in R/W > mode, that would explain it. Even that is bad, but it's not as bad a > user experience when you have the friendly flag set. NSS will access opensc driver following pkcs11.txt configuration which is the same for Chromium, Firefox and the certutil tool I'm also using for testing. > Try it with FF. No newness, every access after the start of the driver sesion by the PSM of Firefox gets locked. > If your module locks the DB while in R/W mode, that would explain it. Thats why I think it's something related to the pkcs11.txt Irune Prado :: Zylk.net - - Mensaje original - De: "Nelson B Bolyard" Para: "mozilla's crypto code discussion list" Enviados: Jueves, 13 de Enero 2011 13:16:07 Asunto: Re: Firefox PSM locks NSS On 2011-01-13 03:58 PDT, Irune Prado Alberdi wrote: > I've tried the same test with Chromium and it worked correctly as > Wan-Teh said. The database does not get locked. [snip] > I had to activate the FRIENDLY flag in order Chrome to correctly obtain > the smartcard's certificate. I'm new to Chrome so maybe there's another > way to do this. Firefox doesn't require it and asks for the PIN. That's a big clue, I think. The friendly flag tells NSS that the module supports a "read only" mode wherein it is not necessary to login to read the certificates and other "public objects" on the device. Without that, NSS assumes that the device only supports read/write mode, and login is necessary to go any access. If your module locks the DB while in R/W mode, that would explain it. Even that is bad, but it's not as bad a user experience when you have the friendly flag set. Try it with FF. -- /Nelson Bolyard -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
Re: Firefox PSM locks NSS
On 2011-01-13 03:58 PDT, Irune Prado Alberdi wrote: > I've tried the same test with Chromium and it worked correctly as > Wan-Teh said. The database does not get locked. [snip] > I had to activate the FRIENDLY flag in order Chrome to correctly obtain > the smartcard's certificate. I'm new to Chrome so maybe there's another > way to do this. Firefox doesn't require it and asks for the PIN. That's a big clue, I think. The friendly flag tells NSS that the module supports a "read only" mode wherein it is not necessary to login to read the certificates and other "public objects" on the device. Without that, NSS assumes that the device only supports read/write mode, and login is necessary to go any access. If your module locks the DB while in R/W mode, that would explain it. Even that is bad, but it's not as bad a user experience when you have the friendly flag set. Try it with FF. -- /Nelson Bolyard -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
Re: Firefox PSM locks NSS
Hiya,
I've tried the same test with Chromium and it worked correctly as Wan-Teh said.
The database does not get locked.
My Firefox profile NSS files are soft links to the shared ones, as explained in
the NSS Shared Howto document
https://wiki.mozilla.org/NSS_Shared_DB_Howto
Could it be a matter of my pkcs11.txt configuration? I've built everything with
the modutils tool (create new database, add opensc module for my smartcard and
set FRIENDLY flag) but maybe Firefox needs some other flag not to get locked
that I've not considered.
$ cat ~/.pki/nssdb/pkcs11.txt
library=
name=NSS Internal PKCS #11 Module
parameters=configdir='sql:.' certPrefix='' keyPrefix='' secmod='' flags=
updatedir='' updateCertPrefix='' updateKeyPrefix='' updateid=''
updateTokenDescription=''
NSS=Flags=internal,critical trustOrder=75 cipherOrder=100
slotParams=(1={slotFlags=[RSA,DSA,DH,RC2,RC4,DES,RANDOM,SHA1,MD5,MD2,SSL,TLS,AES,Camellia,SEED,SHA256,SHA512]
askpw=any timeout=30})
library=./libnssckbi.so
name=Root Certs
NSS=trustOrder=100
library=/usr/lib/opensc/opensc-pkcs11.so
name=izenpe
NSS=slotParams={0x=[slotFlags=PublicCerts ]
0x0001=[slotFlags=PublicCerts rootFlags=hasRootTrust]
0x0002=[slotFlags=PublicCerts ] 0x0003=[slotFlags=PublicCerts ]
0x0004=[slotFlags=PublicCerts ] 0x0005=[slotFlags=PublicCerts ]
0x0006=[slotFlags=PublicCerts ] 0x0007=[slotFlags=PublicCerts ]
0x0008=[slotFlags=PublicCerts ] 0x0009=[slotFlags=PublicCerts ]
0x000a=[slotFlags=PublicCerts ] 0x000b=[slotFlags=PublicCerts ]
0x000c=[slotFlags=PublicCerts ] 0x000d=[slotFlags=PublicCerts ]
0x000e=[slotFlags=PublicCerts ] 0x000f=[slotFlags=PublicCerts ] }
I had to activate the FRIENDLY flag in order Chrome to correctly obtain the
smartcard's certificate. I'm new to Chrome so maybe there's another way to do
this. Firefox doesn't require it and asks for the PIN.
Irune Prado :: Zylk.net
-
--
dev-tech-crypto mailing list
dev-tech-crypto@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-tech-crypto
Re: NSS 3.12.5: Error '-8023' ... how to track it down?
Thanks a lot for the detailed explanation Robert - much appreciated. Please see my comments in line, some stuff deleted for brevity. On 01/12/2011 11:38 PM, Robert Relyea wrote: --- snip --- 331569088[1bd1610]: C_UnwrapKey 331569088[1bd1610]: hSession = 0x6 331569088[1bd1610]: pMechanism = 0x7fffcd592ea0 331569088[1bd1610]: hUnwrappingKey = 0x8 331569088[1bd1610]: pWrappedKey = 0x36ac9bc 331569088[1bd1610]: ulWrappedKeyLen = 48 331569088[1bd1610]: pTemplate = 0x7fffcd592cf0 331569088[1bd1610]: ulAttributeCount = 6 331569088[1bd1610]: phKey = 0x36bfd58 331569088[1bd1610]: CKA_SIGN = CK_TRUE [1] 331569088[1bd1610]: CKA_VERIFY = CK_TRUE [1] 331569088[1bd1610]: CKA_CLASS = CKO_SECRET_KEY [8] 331569088[1bd1610]: CKA_KEY_TYPE = 0x10 [8] 331569088[1bd1610]: CKA_DERIVE = CK_TRUE [1] 331569088[1bd1610]: CKA_VALUE_LEN = 3000 [8] 331569088[1bd1610]: mechanism = CKM_DES3_ECB 331569088[1bd1610]: *phKey = 0x54 The extra data here is dumping out interesting values inside the parameters passed to C_UnwrapKey. The list of CKA_ = X are dumping out the template sent in pTemplate. CKA_VALUE_LEN looks wrong to me, I don't know if tehre is some byteswap issue here. I've checked nearly every C_UnwrapKey function trace in the log ... each of them is showing 'CKA_VALUE_LEN = 3000 [8]'. Every C_DeriveKey function trace shows 'CKA_VALUE_LEN = 1000 [8]' mechansim CKM_DES3_ECB means you are using DES to do unwrap, so this appears to be a restart operation, rather than a full handshake. Looking at the SSLTrace file this seems to be the case. I don't know if I can correlate the SSLTRACE file with the PKCS#11 log file, but it seems the issue only appears in restart operations. Full handshakes don't show the issue. from SSLTRACE log = 10891: SSL[107778448]: sending client-hello SSL: Lookup1: sid=0x36a9080 10891: SSL[107778448]: client, found session-id: [Len: 16] 20 4d 2d a6 3a 3c 67 1a 60 c8 e5 18 0d ea d4 e2M-.:It might be helpfull if SSLTRACE and PKCS#11 could log a timestamp to help in correlation. Or is there already a way to correlate it? 331569088[1bd1610]: rv = CKR_OK 331569088[1bd1610]: C_DeriveKey 331569088[1bd1610]: slotID = 0x1 331569088[1bd1610]: flags = 0x4 331569088[1bd1610]: pApplication = 0331569088 331569088[1bd1610]: Notify = 0x13231f333 331569088[1bd1610]: phSession = 0x7fffc 331569088[1bd1610]: phKey = 0x36c1618 331569088[1bd1610]: CKA_CLASS = CKO_SECRET_KEY [8] 331569088[1bd1610]: CKA_KEY_TYPE = 0x12 [8] 331569088[1bd1610]: *phSession = 0x132317f8 331569088[1bd1610]: rv = CKR_DEVICE_ERROR 331569088[1bd1610]: mechanism = CKM_TLS_KEY_AND_MAC_DERIVE Here you are deriving the SSL session keys. A session handle of 0x132317f8 is pretty large, but not unexpected in a server that has been running a while. Well the server is only running 22 minutes until the issue arises ... might this be 'a while'? During this time only 28 'send client_hello handshake' messages appear in the SSLTRACE log. 19 of them show 'closing, rv=0 errno=0', 1 'closing, rv=0 errno=-5966', the others 'closing, rv=0 errno=-8023'. So no much connection at all. CKR_DEVICE_ERROR can happen in a CKM_TLS_KEY_AND_MAC_DERIVE in a couple of pathological cases: 1) if the underlying object structure is hosed. 2) if the key object looks bogus (a token Object that isn't known or stored, for instance). This object should be a token object. Unfortunately it looks like the logging program did not out put hKey (or it did, but we ran into some overwrite do to threading... the missing new lines after the pApplication, Nofiy, and phSession) seems to indicate that. (In fact Notify should be pNotify, and that looks like part of a C_OpenSession() call, not a C_DeriveKey()... which makes some of the conclusions we are trying to draw questionable. 331569088[1bd1610]: C_DigestInit 331569088[1bd1610]: hSession = 0x1 331569088[1bd1610]: pMechanism = 0x7fffcd593290 331569088[1bd1610]: mechanism = CKM_MD5 331569088[1bd1610]: rv = CKR_DEVICE_ERROR I can see no place where NSC_Digest can even return CKR_DEVICE_ERROR So I can not trust the log? 331569088[1bd1610]: C_OpenSession 331569088[1bd1610]: slotID = 0x1 331569088[1bd1610]: flags = 0x4 331569088[1bd1610]: pApplication = 0x4bdff70 331569088[1bd1610]: Notify = 0x13231f30 331569088[1bd1610]: phSession = 0x7fffcd593228 331569088[1bd1610]: *phSession = 0x132317f8 331569088[1bd1610]: rv = CKR_DEVICE_ERROR This looks like a normal C_OpenSession call...). OS is CentOS 5.5 64bit. Arg, I just remembered. CentOS 5.5 will likely be following RHEL 5.5 in having an NSS 3.11 softoken. This is only the OS ... the library is not using NSS/NSPR from the OS. It is using a bundled one. strings libsoftokn3.so | grep -i header $Header: NSS 3.12.4.5 (debug) Jan 10 2011 17:14:10 I've just checked and NSC_DigestInit still cannot return CKR_DE
Re: Firefox PSM locks NSS
It's a fact that the 'izenpe' token is the one that's causing Firefox to lock the NSS files. It is a pkcs#11 module based on opensc drivers. I've tested shareable NSS with a JSS-based program, watching the opensc logs, and the pkcs#11 module gets the smartcard locked and unlocked atomically for each certificate query operation. Conversely, when the pkcs#11 module gets started via Firefox the pkcs#11 module locks the smartcard until the browser is closed, disabling any concurrent access to the NSS certificates, so as making it non-shareable. Initially the pkcs#11 token session does not get started when opening Firefox. It gets started manually starting / terminating the session through the PSM manager, or and this is IMHO the worst case, while surfing an SSL client-based authentication where the certificate it's stored in the smartcard. This behaviour is informed in the opensc configuration file # By default, the OpenSC PKCS#11 module will # try to lock this card once you have authenticated # to the card via C_Login. This is done so that no # other user can connect to the card and perform # crypto operations (which may be possible because # you have already authenticated with the card). # # However, this also means that no other application # that _you_ run can use the card until your application # has done a C_Logout or C_Finalize. In the case of # Netscape or Mozilla, this does not happen until # you exit the browser. # Default: false #lock_login = false; Is there any information I could read about why the PSM locks the driver until exit, instead of making an atomic needy use of it? Thanks in advance, Irune :: Zylk.net - Mensaje original - De: "Wan-Teh Chang" Para: "mozilla's crypto code discussion list" Enviados: Jueves, 13 de Enero 2011 3:32:43 Asunto: Re: Firefox PSM locks NSS On Tue, Jan 11, 2011 at 4:48 AM, Irune Prado Alberdi wrote: > > While if I terminate the pkcs11 session in firefox I can successfully acces > the token > > $ certutil -d sql:. -K -h izenpe > certutil: Checking token "Builtin Object Token" in slot "NSS Builtin Objects" > certutil: no keys found > certutil: Checking token "NSS Generic Crypto Services" in slot "NSS Internal > Cryptographic Services" > certutil: no keys found > certutil: Checking token "NSS Certificate DB" in slot "NSS User Private Key > and Certificate Services" > certutil: no keys found > certutil: Checking token "IZENPE" in slot "Gemplus GemPC Twin 00 00" > Enter Password or Pin for "IZENPE": > < 0> rsa ad22bafb47cd03a443ee3c04e4914f5cc52a PRUEBAS EFACTUR > Perhaps it's the "IZENPE" token, not the NSS sqlite3 DB, that blocks certutil. The first slot, "NSS Builtin Objects", doesn't use sqlite3, so this shows a later slot can block certutil from output anything. So any later slot, not just the NSS DB slot, could be the cause of the blocking. Wan-Teh -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto -- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
