Bug 236250

Summary: AOL: certutil failed on virtual token
Product: Red Hat Certificate System Reporter: Bob Lord <blord>
Component: Tools - JavaAssignee: Christina Fu <cfu>
Status: CLOSED WONTFIX QA Contact: Chandrasekar Kannan <ckannan>
Severity: medium Docs Contact:
Priority: medium    
Version: 7.2CC: benl, klamb, mrhodes, rrelyea
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-11-06 23:37:00 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 445047    
Attachments:
Description Flags
Luna Logs obtained from Red Hat's Lab environment none

Description Thomas Kwan 2007-04-12 17:48:08 UTC 
When Fu runs certutil on the virtual token, certutil returns I/O error.

Enter Password or Pin for "epki-cs72-VT-cam":
certutil: problem printing certificate nicknames: An I/O error occurred during
security authorization.

Fu said that if he runs certutil on the hardware token directly, it will work.
Comment 1 Thomas Kwan 2007-04-12 17:49:13 UTC 
I asked Marco to obtain the NSS's PKCS#11 debug log from Fu. 

>
>
>-1208191296[959b550]: Loaded library a.out (init)
>-1208191296[959b550]: Loaded library /usr/lib/dirsec/libfreebl3.so (load lib)
>-1208191296[959b550]: Loaded library /usr/lib/libCryptoki2.so (load lib)
>-1208191296[959b550]: C_Initialize
>-1208191296[959b550]:   pInitArgs = 0xf0d170
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetInfo
>-1208191296[959b550]:   pInfo = 0xbff5efa0
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSlotList
>-1208191296[959b550]:   tokenPresent = 0x0
>-1208191296[959b550]:   pSlotList = 0x0
>-1208191296[959b550]:   pulCount = 0xbff5ef9c
>-1208191296[959b550]:   *pulCount = 0x2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSlotList
>-1208191296[959b550]:   tokenPresent = 0x0
>-1208191296[959b550]:   pSlotList = 0x9749f90
>-1208191296[959b550]:   pulCount = 0xbff5ef9c
>-1208191296[959b550]:   *pulCount = 0x2
>-1208191296[959b550]:   slotID[0] = 1
>-1208191296[959b550]:   slotID[1] = 2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSlotInfo
>-1208191296[959b550]:   slotID = 0x1
>-1208191296[959b550]:   pInfo = 0xbff5eee0
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetTokenInfo
>-1208191296[959b550]:   slotID = 0x1
>-1208191296[959b550]:   pInfo = 0xbff5ee20
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetMechanismList
>-1208191296[959b550]:   slotID = 0x1
>-1208191296[959b550]:   pMechanismList = 0x0
>-1208191296[959b550]:   pulCount = 0xbff5ed78
>-1208191296[959b550]:   *pulCount = 0x76
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetMechanismList
>-1208191296[959b550]:   slotID = 0x1
>-1208191296[959b550]:   pMechanismList = 0x97481f8
>-1208191296[959b550]:   pulCount = 0xbff5ed78
>-1208191296[959b550]:   *pulCount = 0x76
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_OpenSession
>-1208191296[959b550]:   slotID = 0x1
>-1208191296[959b550]:   flags = 0x4
>-1208191296[959b550]:   pApplication = 0x974a6d8
>-1208191296[959b550]:   Notify = 0xeb41da
>-1208191296[959b550]:   phSession = 0xbff5ee10
>-1208191296[959b550]:   *phSession = 0x1
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GenerateRandom
>-1208191296[959b550]:   hSession = 0x1
>-1208191296[959b550]:   RandomData = 0xbff5edd0
>-1208191296[959b550]:   ulRandomLen = 32
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_SeedRandom
>-1208191296[959b550]:   hSession = 0x1
>-1208191296[959b550]:   pSeed = 0xbff5edd0
>-1208191296[959b550]:   ulSeedLen = 32
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsInit
>-1208191296[959b550]:   hSession = 0x1
>-1208191296[959b550]:   pTemplate = 0xbff5eeb0
>-1208191296[959b550]:   ulCount = 1
>-1208191296[959b550]:     CKA_CLASS = CKO_NETSCAPE_BUILTIN_ROOT_LIST [4]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjects
>-1208191296[959b550]:   hSession = 0x1
>-1208191296[959b550]:   phObject = 0xbff5ee70
>-1208191296[959b550]:   ulMaxObjectCount = 1
>-1208191296[959b550]:   pulObjectCount = 0xbff5ee68
>-1208191296[959b550]:   *pulObjectCount = 0x0
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsFinal
>-1208191296[959b550]:   hSession = 0x1
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSlotInfo
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   pInfo = 0xbff5eee0
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetTokenInfo
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   pInfo = 0xbff5ee20
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetMechanismList
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   pMechanismList = 0x0
>-1208191296[959b550]:   pulCount = 0xbff5ed78
>-1208191296[959b550]:   *pulCount = 0x76
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetMechanismList
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   pMechanismList = 0x97492e8
>-1208191296[959b550]:   pulCount = 0xbff5ed78
>-1208191296[959b550]:   *pulCount = 0x76
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_OpenSession
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   flags = 0x4
>-1208191296[959b550]:   pApplication = 0x97483d8
>-1208191296[959b550]:   Notify = 0xeb41da
>-1208191296[959b550]:   phSession = 0xbff5ee10
>-1208191296[959b550]:   *phSession = 0x2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GenerateRandom
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   RandomData = 0xbff5edd0
>-1208191296[959b550]:   ulRandomLen = 32
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_SeedRandom
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pSeed = 0xbff5edd0
>-1208191296[959b550]:   ulSeedLen = 32
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsInit
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pTemplate = 0xbff5eeb0
>-1208191296[959b550]:   ulCount = 1
>-1208191296[959b550]:     CKA_CLASS = CKO_NETSCAPE_BUILTIN_ROOT_LIST [4]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjects
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   phObject = 0xbff5ee70
>-1208191296[959b550]:   ulMaxObjectCount = 1
>-1208191296[959b550]:   pulObjectCount = 0xbff5ee68
>-1208191296[959b550]:   *pulObjectCount = 0x0
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsFinal
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSlotInfo
>-1208191296[959b550]:   slotID = 0x1
>-1208191296[959b550]:   pInfo = 0xbff5ef00
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSessionInfo
>-1208191296[959b550]:   hSession = 0x1
>-1208191296[959b550]:   pInfo = 0xbff5eee0
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSessionInfo
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pInfo = 0xbff5f100
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_Login
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   userType = 0x1
>-1208191296[959b550]:   pPin = 0x974b9e0
>-1208191296[959b550]:   ulPinLen = 8
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetMechanismList
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   pMechanismList = 0x0
>-1208191296[959b550]:   pulCount = 0xbff5f058
>-1208191296[959b550]:   *pulCount = 0x76
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetMechanismList
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   pMechanismList = 0x9751460
>-1208191296[959b550]:   pulCount = 0xbff5f058
>-1208191296[959b550]:   *pulCount = 0x76
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_OpenSession
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   flags = 0x4
>-1208191296[959b550]:   pApplication = 0x97483d8
>-1208191296[959b550]:   Notify = 0xeb41da
>-1208191296[959b550]:   phSession = 0xbff5ed80
>-1208191296[959b550]:   *phSession = 0x3
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_CreateObject
>-1208191296[959b550]:   hSession = 0x3
>-1208191296[959b550]:   pTemplate = 0xbff5ee60
>-1208191296[959b550]:   ulCount = 4
>-1208191296[959b550]:   phObject = 0x9752a64
>-1208191296[959b550]:     CKA_CLASS = CKO_SECRET_KEY [4]
>-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5ef30 [4]
>-1208191296[959b550]:     CKA_ENCRYPT = CK_TRUE [1]
>-1208191296[959b550]:     CKA_VALUE = 0x974b9e0 [8]
>-1208191296[959b550]:   *phObject = 0x0
>-1208191296[959b550]:   rv = 0xd1
>-1208191296[959b550]: C_FindObjectsInit
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pTemplate = 0xbff5eea0
>-1208191296[959b550]:   ulCount = 2
>-1208191296[959b550]:     CKA_CLASS = CKO_PUBLIC_KEY [4]
>-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5eecc [4]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjects
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   phObject = 0xbff5ee70
>-1208191296[959b550]:   ulMaxObjectCount = 1
>-1208191296[959b550]:   pulObjectCount = 0xbff5ee68
>-1208191296[959b550]:   *pulObjectCount = 0x1
>-1208191296[959b550]:   phObject[0] = 0x3
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsFinal
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x3
>-1208191296[959b550]:   pTemplate = 0xbff5eea0
>-1208191296[959b550]:   ulCount = 2
>-1208191296[959b550]:     CKA_ID = 0x0 [20]
>-1208191296[959b550]:     CKA_CLASS = 0x0 [4]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x3
>-1208191296[959b550]:   pTemplate = 0xbff5eea0
>-1208191296[959b550]:   ulCount = 2
>-1208191296[959b550]:     CKA_ID = 0x9752fb8 [20]
>-1208191296[959b550]:     CKA_CLASS = CKO_PUBLIC_KEY [4]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsInit
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pTemplate = 0xbff5eea0
>-1208191296[959b550]:   ulCount = 2
>-1208191296[959b550]:     CKA_ID = 0x9752fb8 [20]
>-1208191296[959b550]:     CKA_CLASS = CKO_PRIVATE_KEY [4]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjects
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   phObject = 0xbff5ee60
>-1208191296[959b550]:   ulMaxObjectCount = 1
>-1208191296[959b550]:   pulObjectCount = 0xbff5ee58
>-1208191296[959b550]:   *pulObjectCount = 0x1
>-1208191296[959b550]:   phObject[0] = 0x4
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsFinal
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x4
>-1208191296[959b550]:   pTemplate = 0xbff5ee70
>-1208191296[959b550]:   ulCount = 1
>-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5ee6c [4]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x4
>-1208191296[959b550]:   pTemplate = 0xbff5ee60
>-1208191296[959b550]:   ulCount = 1
>-1208191296[959b550]:     CKA_TOKEN = CK_TRUE [1]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x4
>-1208191296[959b550]:   pTemplate = 0xbff5ee60
>-1208191296[959b550]:   ulCount = 1
>-1208191296[959b550]:     CKA_PRIVATE = CK_TRUE [1]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetSessionInfo
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pInfo = 0xbff5ee30
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x3
>-1208191296[959b550]:   pTemplate = 0xbff5ee50
>-1208191296[959b550]:   ulCount = 4
>-1208191296[959b550]:     CKA_CLASS = CKO_PUBLIC_KEY [4]
>-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5eeb8 [4]
>-1208191296[959b550]:     CKA_MODULUS = 0x0 [256]
>-1208191296[959b550]:     CKA_PUBLIC_EXPONENT = 0x0 [3]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x3
>-1208191296[959b550]:   pTemplate = 0xbff5ee50
>-1208191296[959b550]:   ulCount = 4
>-1208191296[959b550]:     CKA_CLASS = CKO_PUBLIC_KEY [4]
>-1208191296[959b550]:     CKA_KEY_TYPE = 0x9754120 [4]
>-1208191296[959b550]:     CKA_MODULUS = 0x9754128 [256]
>-1208191296[959b550]:     CKA_PUBLIC_EXPONENT = 0x9754228 [3]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetAttributeValue
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   hObject = 0x4
>-1208191296[959b550]:   pTemplate = 0xbff5eda0
>-1208191296[959b550]:   ulCount = 1
>-1208191296[959b550]:     CKA_PRIVATE = CK_TRUE [1]
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_GetMechanismInfo
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   type = 0x1
>-1208191296[959b550]:   pInfo = 0xbff5ed50
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_UnwrapKey
>-1208191296[959b550]:   hSession = 0x3
>-1208191296[959b550]:   pMechanism = 0xbff5ed70
>-1208191296[959b550]:   hUnwrappingKey = 0x4
>-1208191296[959b550]:   pWrappedKey = 0x9754920
>-1208191296[959b550]:   ulWrappedKeyLen = 256
>-1208191296[959b550]:   pTemplate = 0xbff5ec90
>-1208191296[959b550]:   ulAttributeCount = 4
>-1208191296[959b550]:   phKey = 0x9752a64
>-1208191296[959b550]:     CKA_CLASS = CKO_SECRET_KEY [4]
>-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5ed8c [4]
>-1208191296[959b550]:     CKA_ENCRYPT = CK_TRUE [1]
>-1208191296[959b550]:     CKA_VALUE_LEN = 0xbff5ed88 [4]
>-1208191296[959b550]:       mechanism = 0x1
>-1208191296[959b550]:   *phKey = 0x0
>-1208191296[959b550]:   rv = 0x12
>-1208191296[959b550]: C_OpenSession
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   flags = 0x4
>-1208191296[959b550]:   pApplication = 0x97483d8
>-1208191296[959b550]:   Notify = 0xeb41da
>-1208191296[959b550]:   phSession = 0xbff5ebe0
>-1208191296[959b550]:   *phSession = 0x4
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_DecryptInit
>-1208191296[959b550]:   hSession = 0x4
>-1208191296[959b550]:   pMechanism = 0xbff5ed70
>-1208191296[959b550]:   hKey = 0x4
>-1208191296[959b550]:       mechanism = 0x1
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_Decrypt
>-1208191296[959b550]:   hSession = 0x4
>-1208191296[959b550]:   pEncryptedData = 0x9754920
>-1208191296[959b550]:   ulEncryptedDataLen = 256
>-1208191296[959b550]:   pData = 0x9755b88
>-1208191296[959b550]:   pulDataLen = 0xbff5ec3c
>-1208191296[959b550]:   *pulDataLen = 0x8
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_CloseSession
>-1208191296[959b550]:   hSession = 0x4
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_CreateObject
>-1208191296[959b550]:   hSession = 0x3
>-1208191296[959b550]:   pTemplate = 0xbff5ec90
>-1208191296[959b550]:   ulCount = 4
>-1208191296[959b550]:   phObject = 0x9752a64
>-1208191296[959b550]:     CKA_CLASS = CKO_SECRET_KEY [4]
>-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5ed8c [4]
>-1208191296[959b550]:     CKA_ENCRYPT = CK_TRUE [1]
>-1208191296[959b550]:     CKA_VALUE = 0x9755b88 [8]
>-1208191296[959b550]:   *phObject = 0x0
>-1208191296[959b550]:   rv = 0xd1
>-1208191296[959b550]: C_CloseSession
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_FindObjectsInit
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pTemplate = 0xbff5ef50
>-1208191296[959b550]:   ulCount = 2
>-1208191296[959b550]:     CKA_TOKEN = CK_TRUE [1]
>-1208191296[959b550]:     CKA_CLASS = CKO_CERTIFICATE [4]
>-1208191296[959b550]:   rv = 0xb3
>-1208191296[959b550]: C_FindObjectsInit
>-1208191296[959b550]:   hSession = 0x2
>-1208191296[959b550]:   pTemplate = 0xbff5f080
>-1208191296[959b550]:   ulCount = 2
>-1208191296[959b550]:     CKA_TOKEN = CK_TRUE [1]
>-1208191296[959b550]:     CKA_CLASS = CKO_CERTIFICATE [4]
>-1208191296[959b550]:   rv = 0xb3
>-1208191296[959b550]: C_CloseAllSessions
>-1208191296[959b550]:   slotID = 0x1
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_CloseSession
>-1208191296[959b550]:   hSession = 0x3
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_CloseAllSessions
>-1208191296[959b550]:   slotID = 0x2
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: C_Finalize
>-1208191296[959b550]:   pReserved = 0x0
>-1208191296[959b550]:   rv = 0x0
>-1208191296[959b550]: Unloaded library /usr/lib/libCryptoki2.so
>
Comment 2 Thomas Kwan 2007-04-12 17:50:00 UTC 
Can you ask Fu to run certutil with debug on the hardware token directly?
NSS will perform some simple tests at startup. (certutil is an application
that uses NSS). Looks like it failed in the following places:

The unwrap operation failed:

-1208191296[959b550]: C_UnwrapKey
-1208191296[959b550]:   hSession = 0x3
-1208191296[959b550]:   pMechanism = 0xbff5ed70
-1208191296[959b550]:   hUnwrappingKey = 0x4
-1208191296[959b550]:   pWrappedKey = 0x9754920
-1208191296[959b550]:   ulWrappedKeyLen = 256
-1208191296[959b550]:   pTemplate = 0xbff5ec90
-1208191296[959b550]:   ulAttributeCount = 4
-1208191296[959b550]:   phKey = 0x9752a64
-1208191296[959b550]:     CKA_CLASS = CKO_SECRET_KEY [4]
-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5ed8c [4]
-1208191296[959b550]:     CKA_ENCRYPT = CK_TRUE [1]
-1208191296[959b550]:     CKA_VALUE_LEN = 0xbff5ed88 [4]
-1208191296[959b550]:       mechanism = 0x1
-1208191296[959b550]:   *phKey = 0x0
-1208191296[959b550]:   rv = 0x12

The creation of a symmetric key failed:

-1208191296[959b550]: C_CreateObject
-1208191296[959b550]:   hSession = 0x3
-1208191296[959b550]:   pTemplate = 0xbff5ec90
-1208191296[959b550]:   ulCount = 4
-1208191296[959b550]:   phObject = 0x9752a64
-1208191296[959b550]:     CKA_CLASS = CKO_SECRET_KEY [4]
-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5ed8c [4]
-1208191296[959b550]:     CKA_ENCRYPT = CK_TRUE [1]
-1208191296[959b550]:     CKA_VALUE = 0x9755b88 [8]
-1208191296[959b550]:   *phObject = 0x0
-1208191296[959b550]:   rv = 0xd1

It also failed to locate a certificate:

-1208191296[959b550]: C_FindObjectsInit
-1208191296[959b550]:   hSession = 0x2
-1208191296[959b550]:   pTemplate = 0xbff5ef50
-1208191296[959b550]:   ulCount = 2
-1208191296[959b550]:     CKA_TOKEN = CK_TRUE [1]
-1208191296[959b550]:     CKA_CLASS = CKO_CERTIFICATE [4]
-1208191296[959b550]:   rv = 0xb3

I want to see if running certutil on the hardware token directly
will have those errors.
Comment 3 Bob Relyea 2007-04-13 17:58:07 UTC 
What is the actual certutil command. that is being run? (are we listing certs,
keys ?).

Some problems I see:

C_CreateObject
>-1208191296[959b550]:   hSession = 0x3
>-1208191296[959b550]:   pTemplate = 0xbff5ee60
>-1208191296[959b550]:   ulCount = 4
>-1208191296[959b550]:   phObject = 0x9752a64
>-1208191296[959b550]:     CKA_CLASS = CKO_SECRET_KEY [4]
>-1208191296[959b550]:     CKA_KEY_TYPE = 0xbff5ef30 [4]
>-1208191296[959b550]:     CKA_ENCRYPT = CK_TRUE [1]
>-1208191296[959b550]:     CKA_VALUE = 0x974b9e0 [8]
>-1208191296[959b550]:   *phObject = 0x0
>-1208191296[959b550]:   rv = 0xd1

Why are we getting CKR_TEMPLATE_INCONSISTANT here? does the value not match the
Keytype (hard to tell since we don't actually print out the key_type value here.

What looks like is happenning is the token claims to do some symetric algorithm
that NSS needs to verify, but the token seems to be broken (doesn't like our key
template). After a heroic effort to load the key in (using and RSA key
exchange), the unwrap fails with CKR_ATTRIBUTE_TYPE_INVALID. NSS again tries to
hand unwrap and insert the key which fails again.

Since the token claims to do an algorithm and it doesn't seem to support NSS
finally punts on the token. For some reason NSS does continue to try the find,
but at this point NSS as closed the session (See C_CloseSession just for for the
failed C_FindObjectsInit), so the 0xb3 (CKR_INVALID_SESSION) is correct behavior
on the PKCS #11 module.

You should be able to work around the issue by turning off the offending
symetric cipher in the virtual token. 

I would very much like to know why both the CreateObject and Unwrap are failing,
though, I doubt there's a bug in the NSS code (it's quite old), but I would like
to hear the justification for why these operations were rejected.

bob
Comment 4 Thomas Kwan 2007-04-26 23:56:03 UTC 
I have enabled debug by using the following instructions:

Then, I ran certutil, it works in our environment, and here is the log that
shows the operations in question:

14:51:03 24969--1207974208:STRTUnwrapKey {Sesn=5 Mech=(CKM_RSA_PKCS,"")        
Obj=7 "01941ab8d265aea6e98ec9c4678b838f480b049c9f4d70a866eafbe3456fa5de3       
4baa464e96c7e83c6a6a6e26886c90b0175229a24c6890ac8c2cb1ee1ee6c0e03ec8c1d2       
df6422348d574a44153d0a42c6a0762d32ce182db67d1080e19f0d2b4dcb772a6fe5202e       
f2739602e9dfa56600a4abc9eb90e07f0a4c8076b88be69" AttrList={CKA_CLASS="04       
000000" CKA_KEY_TYPE="13000000" CKA_ENCRYPT="01" CKA_VALUE_LEN="08000000       
" } }

Note that CreateObject also failed in my certutil, but it did not affect the
certutil operation:

14:51:03 24969--1207974208:STRTCreateObject {Sesn=5 AttrList={CKA_CLASS=       
"04000000" CKA_KEY_TYPE="13000000" CKA_ENCRYPT="01" CKA_VALUE="ec5b25c2b       
53b4376" } }
14:51:03 24969--1207974208:FINICreateObject ***CKR_TEMPLATE_INCONSISTENT       
***(90ms) {Obj=0 }

14:51:03 24969--1207974208:FINIUnwrapKey CKR_OK(90ms) {Obj=46 }
Comment 5 Thomas Kwan 2007-04-26 23:57:21 UTC 
Instructions are here:

How do you enable debug in Safenet's Lunasa?

You need to obtain the debug library cklog-3.2.0-0.i386.rpm from SafeNet. This
RPM should contain /usr/lunasa/lib/libcklog2.so. To enable debug, you must make
sure you have the following settings in your /etc/Chrystoki.conf:

 Chrystoki2 = {
    LibUNIX=/usr/lunasa/lib/libcklog2.so;
 }
 CkLog2 = {
    LibUNIX=/usr/lunasa/lib/libCryptoki2.so;
    Enabled=1;
    File=/tmp/luna.txt;
    Error=/tmp/err.txt;
    Format=0;
    NewFormat=1;
 }
 Luna = {
   DefaultTimeOut=500000;
   PEDTimeout1=100000;
   PEDTimeout2=100000;
 }
 CardReader = {
   RemoteCommand=1;
 }
 LunaSA Client = {
   ServerPort01 = 1792;
   ServerName01 = lunasa2;
   ClientPrivKeyFile = /usr/lunasa/cert/client/spoonboyKey.pem;
   ClientCertFile = /usr/lunasa/cert/client/spoonboy.pem;
   ServerPort00 = 1792;
   ServerName00 = lunasa1;
   NetClient=1;
   ServerCAFile=/usr/lunasa/cert/server/CAFile.pem;
   SSLConfigFile=/usr/lunasa/bin/openssl.cnf;
   ReceiveTimeout=20000;
 }
 Misc = {
       NetscapeCustomize=1023;
 }

After that, you also need to add libcklogs to your secmod.db by issuing

 modutil -dbdir . -nocertdb -add lunasa -libfile /usr/lunasa/lib/libcklog2.so

Note that if you are getting the following error, you must have something wrong
in your /etc/Chrystoki.conf

 /usr/bin/modutil: line 45: 24944 Segmentation fault      (core dumped)
${dir}/${COMMAND} "$@"


Run modutil list to confirm if you can still see the tokens:

 modutil -dbdir . -nocertdb -list

 Using database directory ....
 Listing of PKCS #11 Modules
 -----------------------------------------------------------
 1. NSS Internal PKCS #11 Module
        slots: 2 slots attached
       status: loaded
        slot: NSS Internal Cryptographic Services
       token: NSS Generic Crypto Services
        slot: NSS User Private Key and Certificate Services
       token: NSS Certificate DB
 2. lunasa
       library name: /usr/lunasa/lib/libcklog2.so
        slots: 3 slots attached
       status: loaded
        slot: LunaNet Slot
       token: lunasa1-ca
        slot: LunaNet Slot
       token: lunasa1-tks
        slot: LunaNet Slot
       token: lunasa2-ca
 -----------------------------------------------------------

To trigger some debug log, you can use certutil as follows:

 certutil -d . -L -h lunasa1-ca

The debug log should be in /tmp/luna.txt
Comment 6 Thomas Kwan 2007-04-27 00:02:43 UTC 
I also tried creating a self-signed certificate in *our* virtual token
environment, it worked also.

[root@spoonboy alias]# certutil -d . -h virtual-lunasa -S -n testkey -s "CN=x"
-c "CN=x" -x -m 1 -t "CTu,CTu,CTu"
Enter Password or Pin for "virtual-lunasa":

A random seed must be generated that will be used in the
creation of your key.  One of the easiest ways to create a
random seed is to use the timing of keystrokes on a keyboard.

To begin, type keys on the keyboard until this progress meter
is full.  DO NOT USE THE AUTOREPEAT FUNCTION ON YOUR KEYBOARD!


Continue typing until the progress meter is full:

|************************************************************|

Finished.  Press enter to continue:


Generating key.  This may take a few moments...

[root@spoonboy alias]# certutil -d . -h virtual-lunasa -L Enter Password or Pin
for "virtual-lunasa":
...
virtual-lunasa:testkey                                       CTu,Cu,Cu
Comment 7 Thomas Kwan 2007-04-27 00:06:55 UTC 
Here is the action item for AOL:

1) Install the debug library as in comment #5
2) Run certutil on the virtual token, and it should fail
3) Then, look in the /etc/luna.txt log to find the Unwrap operation
4) Send the STRTUnwrapKey request and response to AOL and Safenet so that we can
investigate why the PKCS#11 driver was returning 0x12 (CKR_ATTRIBUTE_TYPE_INVALID)
Comment 8 Thomas Kwan 2007-04-27 00:11:52 UTC 
For COmment #7, Step 2) - Run certutil (list operation i.e. -L) ...
Comment 9 Thomas Kwan 2007-04-27 00:14:41 UTC 
Created attachment 153563 [details]
Luna Logs obtained from Red Hat's Lab environment

Included this so that we can comparing ours to AOL's in future.
Comment 10 Thomas Kwan 2007-04-27 00:21:13 UTC 
Ken, regarding to comment 7 again, 

Modification:

Step 2) Run certutil (list operation i.e. -L) on the virtual token
Step 3) The log file is in /tmp/luna.txt

Then, continue on comment 7, add the following steps:

5) clean up /tmp/luna.txt
6) run certutil (list operation) on the regular token (this should work)
7) Copy /tmp/luna.txt to /tmp/luna-good.txt
8) Send us /tmp/luna-good.txt as well
Comment 11 Thomas Kwan 2007-04-27 01:56:36 UTC 
Message from Safenet

Anup Marwaha wrote:

> Thanks for this... I assume that with this CKA_KEY_TYPE value the
> C_UnwrapKey call succeeds?

Yes

> However, CKA_KEY_TYPE="13000000" still does not
> map to anything for me... is there anyway to know what exactly are you
> passing?
>  
>
In the log, I see CKA_CLASS="04000000" CKA_KEY_TYPE="13000000" CKA_ENCRYPT="01"
CKA_VALUE_LEN="08000000"

I think we are passing in CKO_SECRET_KEY (0x00000004), and luna log shows
"04000000".
So it is possible that CKA_KEY_TYPE="13000000" means "00000013" (CKK_DES)??

thomas
Comment 12 Thomas Kwan 2007-04-27 02:35:08 UTC 
Anup,

The NSS (our security library) code that does the verification is here.

http://ftp.mozilla.org/pub/mozilla.org/security/nss/releases/NSS_3_2_1_RTM/src/nss-3.2.1/mozilla/security/nss/lib/pk11wrap/pk11slot.c

The test starts in the function pk11_CheckVerifyTest. If the test failed, NSS
returns I/O error.

In the function PK11_VerifySlotMechanisms, NSS verifies
a set of mechanisms that the hardware token claims to support. The verification
is done by generating a key in the token (you can see that in PK11_VerifyMechanism).
It tries to generate a DES key which failed in both in our lab and in AOL's
environment, then the code tries to find a RSA public key, and then find the
corresponding
private key on the hardware token, and then it tries to unwrap a test key on the
token.
The unwrapping of the test key failed in AOL's environment, but it works in ours.

thomas
Comment 13 Bob Relyea 2007-04-27 23:02:10 UTC 
re comment 13.

there appears to be endian issues with the output. It's probably outputing the
raw bytes, not the integer value. That would make CLASS=4 KEY_TYPE=13 and
VALUE_LEN=8.

These all appear to be correct (SECRET_KEY, CKK_DES and 8 bytes).
Comment 14 Red Hat Bugzilla 2007-10-27 15:29:19 UTC 
User nkwan's account has been closed
Comment 15 Red Hat Bugzilla 2007-10-27 15:41:36 UTC 
User nkwan's account has been closed