On 01/12/2011 01:26 PM, Bernhard Thalmayr wrote: > So here we go ... the PCKS#11 logger shows the following > > 331569088[1bd1610]: C_DigestUpdate > 331569088[1bd1610]: hSession = 0x88 > 331569088[1bd1610]: pPart = 0x6e580a4 > 331569088[1bd1610]: ulPartLen = 70 > 331569088[1bd1610]: rv = CKR_OK
This says you called C_DigestUpdate with a session handle of 0x88 and to digest 70 bytes of data at memory location 0x63580a4. The function returned CKR_OK. The rest are pretty similar, I'll add additional notes as appropriate.... > 331569088[1bd1610]: C_GetMechanismInfo > 331569088[1bd1610]: slotID = 0x1 > 331569088[1bd1610]: type = 0x132 > 331569088[1bd1610]: pInfo = 0x7fffcd592e70 > 331569088[1bd1610]: rv = CKR_OK From this, it appears you are using the internal crypto slot rather than the internal key/certificate store slot. This would be expected if you are doing SSL, which is what appears to be happening here. > 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 = 3000000000000000 [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_XXXX = XXXXX 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. 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. > 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. 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 > 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. I've just checked and NSC_DigestInit still cannot return CKR_DEVICE_ERROR in NSS 3.11 -- unless you are running in FIPS mode. This is possible, but seem extremely unlikely since you are using slotid=1 (FIPS slot ID is 3). In FIPS mode, any call can fail with CKR_DEVICE_ERROR if the token is in 'fatalError' mode. That happens if any of the following fail: 1) the Random number generator. 2) the Seeding the random number generator. 3) generating a key pair fails with CKR_GENERAL_ERROR 4) power on self check fails at init time. It can be reset by reinitializing the token. If this is what is happening, you should be getting NSS messages in your syslog. I don't think FIPS is your issue here looking at the logs, however. bob > > Could someone please help me understand the trace? > > > I've also gathered an SSLTRACE log if needed. > > TIA, > Bernhard > > >
-- dev-tech-crypto mailing list dev-tech-crypto@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-tech-crypto
