We have a setup using the Aladdin eToken PRO USB device for certificate storage using opensc/openct to interface it with openvpn. Works fine but with pkcs11-helper 1.08 we need to enter the PIN code twice at openvpn startup and then once at each renegotiation. Confirmed with various versions of openvpn (2.1.4/2.2.1), opensc (0.11.13, 0.12.1) and openct (0.6.20), common thing is that it works with pkcs11-helper 1.07 (the PIN caching seems ok and only asks for the pin code once at startup and no more) but with pkcs11-helper 1.08 the PIN caching does not work.
Attached is a log from openvpn with verbosity 99 (gives a lot of info) using pkcs11-helper 1.08. It contains the startup and a couple of renegotiations filtered to only include lines with pkcs in them. /Jonatan
Fri Aug 5 09:37:04 2011 us=441187 pkcs12_file = '[UNDEF]' Fri Aug 5 09:37:04 2011 us=441666 pkcs11_providers = /usr/lib/opensc-pkcs11.so Fri Aug 5 09:37:04 2011 us=441680 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441694 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441708 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441721 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441734 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441748 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441761 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441775 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441788 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441802 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441815 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441828 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441842 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441856 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441869 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441883 pkcs11_protected_authentication = DISABLED Fri Aug 5 09:37:04 2011 us=441897 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=441911 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=441924 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=441938 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=441951 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=441965 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=441978 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=441992 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442005 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442019 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442039 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442053 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442067 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442080 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442093 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442107 pkcs11_private_mode = 00000000 Fri Aug 5 09:37:04 2011 us=442120 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442134 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442147 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442165 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442179 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442193 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442206 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442220 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442233 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442246 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442260 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442273 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442286 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442300 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442313 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442326 pkcs11_cert_private = DISABLED Fri Aug 5 09:37:04 2011 us=442340 pkcs11_pin_cache_period = -1 Fri Aug 5 09:37:04 2011 us=442354 pkcs11_id = 'OpenSC\x20Project/PKCS\x2315/28088614271A/OpenSC\x20Card\x20\x28Jonatan02\x20VPN\x29/46' Fri Aug 5 09:37:04 2011 us=442368 pkcs11_id_management = DISABLED Fri Aug 5 09:37:04 2011 us=442956 OpenVPN 2.2.1 x86_64-linux-gnu [SSL] [LZO2] [EPOLL] [PKCS11] [eurephia] built on Jul 1 2011 Fri Aug 5 09:37:04 2011 us=443026 PKCS#11: pkcs11_initialize - entered Fri Aug 5 09:37:04 2011 us=443191 PKCS#11: pkcs11_initialize - return 0-'CKR_OK' Fri Aug 5 09:37:04 2011 us=443215 PKCS#11: pkcs11_addProvider - entered - provider='/usr/lib/opensc-pkcs11.so', private_mode=00000000 Fri Aug 5 09:37:04 2011 us=443229 PKCS#11: Adding PKCS#11 provider '/usr/lib/opensc-pkcs11.so' Fri Aug 5 09:37:04 2011 us=443254 PKCS#11: pkcs11h_addProvider entry version='1.08', pid=8158, reference='/usr/lib/opensc-pkcs11.so', provider_location='/usr/lib/opensc-pkcs11.so', allow_protected_auth=0, mask_private_mode=00000000, cert_is_private=0 Fri Aug 5 09:37:04 2011 us=443269 PKCS#11: Adding provider '/usr/lib/opensc-pkcs11.so'-'/usr/lib/opensc-pkcs11.so' Fri Aug 5 09:37:06 2011 us=158 PKCS#11: pkcs11h_addProvider Provider '/usr/lib/opensc-pkcs11.so' manufacturerID 'OpenSC (www.opensc-project.org)' Fri Aug 5 09:37:06 2011 us=217 PKCS#11: _pkcs11h_slotevent_notify entry Fri Aug 5 09:37:06 2011 us=242 PKCS#11: _pkcs11h_slotevent_notify return Fri Aug 5 09:37:06 2011 us=267 PKCS#11: Provider '/usr/lib/opensc-pkcs11.so' added rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=285 PKCS#11: pkcs11h_addProvider return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=302 PKCS#11: pkcs11_addProvider - return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=714 PKCS#11: SSL_CTX_use_pkcs11 - entered - ssl_ctx=0x72ddf0, pkcs11_id_management=0, pkcs11_id='OpenSC\x20Project/PKCS\x2315/28088614271A/OpenSC\x20Card\x20\x28Jonatan02\x20VPN\x29/46' Fri Aug 5 09:37:06 2011 us=745 PKCS#11: pkcs11h_certificate_deserializeCertificateId entry p_certificate_id=0x7fff40fa3b98, sz='OpenSC\x20Project/PKCS\x2315/28088614271A/OpenSC\x20Card\x20\x28Jonatan02\x20VPN\x29/46' Fri Aug 5 09:37:06 2011 us=763 PKCS#11: _pkcs11h_certificate_newCertificateId entry p_certificate_id=0x7fff40fa1b48 Fri Aug 5 09:37:06 2011 us=776 PKCS#11: _pkcs11h_certificate_newCertificateId return rv=0-'CKR_OK', *p_certificate_id=0x72e760 Fri Aug 5 09:37:06 2011 us=792 PKCS#11: pkcs11h_token_deserializeTokenId entry p_token_id=0x72e760, sz='OpenSC\x20Project/PKCS\x2315/28088614271A/OpenSC\x20Card\x20\x28Jonatan02\x20VPN\x29' Fri Aug 5 09:37:06 2011 us=808 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7fff40fa1af8 Fri Aug 5 09:37:06 2011 us=820 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x72eda0 Fri Aug 5 09:37:06 2011 us=853 PKCS#11: pkcs11h_token_deserializeTokenId return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=869 PKCS#11: pkcs11h_certificate_deserializeCertificateId return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=886 PKCS#11: pkcs11h_certificate_create entry certificate_id=0x72e760, user_data=(nil), mask_prompt=00000003, pin_cache_period=-1, p_certificate=0x7fff40fa3b90 Fri Aug 5 09:37:06 2011 us=904 PKCS#11: pkcs11h_certificate_duplicateCertificateId entry to=0x72ebb0 form=0x72e760 Fri Aug 5 09:37:06 2011 us=921 PKCS#11: pkcs11h_certificate_duplicateCertificateId return rv=0-'CKR_OK', *to=0x72f210 Fri Aug 5 09:37:06 2011 us=933 PKCS#11: _pkcs11h_session_getSessionByTokenId entry token_id=0x72f640, p_session=0x72ebc0 Fri Aug 5 09:37:06 2011 us=943 PKCS#11: Creating a new session Fri Aug 5 09:37:06 2011 us=958 PKCS#11: pkcs11h_token_duplicateTokenId entry to=0x72fac8 form=0x72f640 Fri Aug 5 09:37:06 2011 us=970 PKCS#11: pkcs11h_token_duplicateTokenId return rv=0-'CKR_OK', *to=0x72fb30 Fri Aug 5 09:37:06 2011 us=992 PKCS#11: _pkcs11h_session_getSessionByTokenId return rv=0-'CKR_OK', *p_session=0x72fab0 Fri Aug 5 09:37:06 2011 us=1005 PKCS#11: pkcs11h_certificate_create return rv=0-'CKR_OK' *p_certificate=0x72ebb0 Fri Aug 5 09:37:06 2011 us=1018 PKCS#11: pkcs11h_openssl_createSession - entry Fri Aug 5 09:37:06 2011 us=1079 PKCS#11: pkcs11h_openssl_createSession - return openssl_session=0x72ffc0 Fri Aug 5 09:37:06 2011 us=1093 PKCS#11: pkcs11h_openssl_session_getRSA - entry openssl_session=0x72ffc0 Fri Aug 5 09:37:06 2011 us=1105 PKCS#11: pkcs11h_openssl_session_getX509 - entry openssl_session=0x72ffc0 Fri Aug 5 09:37:06 2011 us=1117 PKCS#11: pkcs11h_openssl_getX509 - entry certificate=0x72ebb0 Fri Aug 5 09:37:06 2011 us=1179 PKCS#11: pkcs11h_certificate_getCertificateBlob entry certificate=0x72ebb0, certificate_blob=(nil), *p_certificate_blob_size=0000000000000000 Fri Aug 5 09:37:06 2011 us=1193 PKCS#11: __pkcs11h_certificate_loadCertificate entry certificate=0x72ebb0 Fri Aug 5 09:37:06 2011 us=1204 PKCS#11: _pkcs11h_session_validate entry session=0x72fab0 Fri Aug 5 09:37:06 2011 us=1216 PKCS#11: _pkcs11h_session_validate return rv=179-'CKR_SESSION_HANDLE_INVALID' Fri Aug 5 09:37:06 2011 us=1227 PKCS#11: __pkcs11h_certificate_loadCertificate return rv=179-'CKR_SESSION_HANDLE_INVALID' Fri Aug 5 09:37:06 2011 us=1239 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=0x72ebb0, public_only=1, session_mutex_locked=0 Fri Aug 5 09:37:06 2011 us=1290 PKCS#11: _pkcs11h_session_login entry session=0x72fab0, is_publicOnly=1, readonly=1, user_data=(nil), mask_prompt=00000003 Fri Aug 5 09:37:06 2011 us=1308 PKCS#11: _pkcs11h_session_logout entry session=0x72fab0 Fri Aug 5 09:37:06 2011 us=1325 PKCS#11: _pkcs11h_session_logout return Fri Aug 5 09:37:06 2011 us=1341 PKCS#11: _pkcs11h_session_reset entry session=0x72fab0, user_data=(nil), mask_prompt=00000003, p_slot=0x7fff40fa1968 Fri Aug 5 09:37:06 2011 us=1357 PKCS#11: _pkcs11h_session_reset Expected token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:06 2011 us=1369 PKCS#11: _pkcs11h_session_getSlotList entry provider=0x71af00, token_present=1, pSlotList=0x7fff40fa14e8, pulCount=0x7fff40fa14e0 Fri Aug 5 09:37:06 2011 us=1436 PKCS#11: _pkcs11h_session_getSlotList return rv=0-'CKR_OK' *pulCount=3 Fri Aug 5 09:37:06 2011 us=1454 PKCS#11: Cannot get token information for provider 'OpenSC (www.opensc-project.org)' slot -1 rv=224-'CKR_TOKEN_NOT_PRESENT' Fri Aug 5 09:37:06 2011 us=1469 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7fff40fa14d8 Fri Aug 5 09:37:06 2011 us=1480 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7fff40fa1378 Fri Aug 5 09:37:06 2011 us=1492 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x7304b0 Fri Aug 5 09:37:06 2011 us=1504 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x7304b0 Fri Aug 5 09:37:06 2011 us=1515 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (VPN-token)' Fri Aug 5 09:37:06 2011 us=1531 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x7304b0 Fri Aug 5 09:37:06 2011 us=1542 PKCS#11: pkcs11h_token_freeTokenId return Fri Aug 5 09:37:06 2011 us=1554 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7fff40fa14d8 Fri Aug 5 09:37:06 2011 us=1565 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7fff40fa1378 Fri Aug 5 09:37:06 2011 us=1576 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x7304b0 Fri Aug 5 09:37:06 2011 us=1588 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x7304b0 Fri Aug 5 09:37:06 2011 us=1599 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:06 2011 us=1610 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x7304b0 Fri Aug 5 09:37:06 2011 us=1620 PKCS#11: pkcs11h_token_freeTokenId return Fri Aug 5 09:37:06 2011 us=1662 PKCS#11: _pkcs11h_session_reset return rv=0-'CKR_OK', *p_slot=2 Fri Aug 5 09:37:06 2011 us=1680 PKCS#11: _pkcs11h_session_login return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=1692 PKCS#11: _pkcs11h_certificate_resetSession return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=1702 PKCS#11: __pkcs11h_certificate_loadCertificate entry certificate=0x72ebb0 Fri Aug 5 09:37:06 2011 us=1713 PKCS#11: _pkcs11h_session_validate entry session=0x72fab0 Fri Aug 5 09:37:06 2011 us=1725 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1312529825 Fri Aug 5 09:37:06 2011 us=1735 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=1748 PKCS#11: _pkcs11h_session_findObjects entry session=0x72fab0, filter=0x7fff40fa1a40, filter_attrs=2, p_objects=0x7fff40fa1a90, p_objects_found=0x7fff40fa1a88 Fri Aug 5 09:37:06 2011 us=1774 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=1 Fri Aug 5 09:37:06 2011 us=1788 PKCS#11: _pkcs11h_session_getObjectAttributes entry session=0x72fab0, object=7521888, attrs=0x7fff40fa1a70, count=1 Fri Aug 5 09:37:06 2011 us=1809 PKCS#11: _pkcs11h_session_getObjectAttributes return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=1822 PKCS#11: _pkcs11h_certificate_isBetterCertificate entry current=(nil), current_size=0000000000000000, newone=0x730600, newone_size=0000000000000471 Fri Aug 5 09:37:06 2011 us=1840 PKCS#11: _pkcs11h_certificate_isBetterCertificate return is_better=1 Fri Aug 5 09:37:06 2011 us=1855 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7fff40fa1a70, count=1 Fri Aug 5 09:37:06 2011 us=1867 PKCS#11: _pkcs11h_session_freeObjectAttributes return Fri Aug 5 09:37:06 2011 us=1881 PKCS#11: __pkcs11h_certificate_updateCertificateIdDescription entry certificate_id=0x72f210 Fri Aug 5 09:37:06 2011 us=2187 PKCS#11: __pkcs11h_certificate_updateCertificateIdDescription return displayName='/C=SE/ST=Vastra Gotaland/O=SGS Studentbostader/OU=SGS Datanatgrupp (DNG7-RIPE)/CN=jonatan on OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:06 2011 us=2211 PKCS#11: __pkcs11h_certificate_loadCertificate return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=2226 PKCS#11: pkcs11h_certificate_getCertificateBlob return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=2241 PKCS#11: pkcs11h_certificate_getCertificateBlob entry certificate=0x72ebb0, certificate_blob=0x7304d0, *p_certificate_blob_size=0000000000000471 Fri Aug 5 09:37:06 2011 us=2255 PKCS#11: pkcs11h_certificate_getCertificateBlob return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=2377 PKCS#11: pkcs11h_openssl_getX509 - return rv=0-'CKR_OK', x509=0x730060 Fri Aug 5 09:37:06 2011 us=2511 PKCS#11: pkcs11h_openssl_session_getX509 - return x509=0x732bc0 Fri Aug 5 09:37:06 2011 us=2620 PKCS#11: pkcs11h_openssl_session_getRSA - return rsa=0x732780 Fri Aug 5 09:37:06 2011 us=2641 PKCS#11: pkcs11h_openssl_session_getX509 - entry openssl_session=0x72ffc0 Fri Aug 5 09:37:06 2011 us=2760 PKCS#11: pkcs11h_openssl_session_getX509 - return x509=0x7329c0 Fri Aug 5 09:37:06 2011 us=2882 PKCS#11: pkcs11h_certificate_freeCertificateId entry certificate_id=0x72e760 Fri Aug 5 09:37:06 2011 us=2901 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x72eda0 Fri Aug 5 09:37:06 2011 us=2914 PKCS#11: pkcs11h_token_freeTokenId return Fri Aug 5 09:37:06 2011 us=2927 PKCS#11: pkcs11h_certificate_freeCertificateId return Fri Aug 5 09:37:06 2011 us=2941 PKCS#11: pkcs11h_openssl_freeSession - entry openssl_session=0x72ffc0, count=2 Fri Aug 5 09:37:06 2011 us=2954 PKCS#11: pkcs11h_openssl_freeSession - return Fri Aug 5 09:37:06 2011 us=2967 PKCS#11: SSL_CTX_use_pkcs11 - return ok=1, rv=0 Fri Aug 5 09:37:06 2011 us=147063 PKCS#11: __pkcs11h_openssl_dec entered - flen=36, from=0x7fff40fa3be0, to=0x757936, rsa=0x732780, padding=1 Fri Aug 5 09:37:06 2011 us=147071 PKCS#11: Performing signature Fri Aug 5 09:37:06 2011 us=147079 PKCS#11: pkcs11h_certificate_signAny entry certificate=0x72ebb0, mech_type=1, source=0x7fff40fa3be0, source_size=0000000000000024, target=0x757936, *p_target_size=0000000000000024 Fri Aug 5 09:37:06 2011 us=147084 PKCS#11: Getting key attributes Fri Aug 5 09:37:06 2011 us=147089 PKCS#11: __pkcs11h_certificate_getKeyAttributes entry certificate=0x72ebb0 Fri Aug 5 09:37:06 2011 us=147095 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7fff40fa39b0, count=4 Fri Aug 5 09:37:06 2011 us=147100 PKCS#11: _pkcs11h_session_freeObjectAttributes return Fri Aug 5 09:37:06 2011 us=147106 PKCS#11: Get private key attributes failed: 130:'CKR_OBJECT_HANDLE_INVALID' Fri Aug 5 09:37:06 2011 us=147111 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=0x72ebb0, public_only=0, session_mutex_locked=1 Fri Aug 5 09:37:06 2011 us=147117 PKCS#11: _pkcs11h_session_getObjectById entry session=0x72fab0, class=3, id=0x72ec40, id_size=0000000000000001, p_handle=0x72ebc8 Fri Aug 5 09:37:06 2011 us=147123 PKCS#11: _pkcs11h_session_validate entry session=0x72fab0 Fri Aug 5 09:37:06 2011 us=147128 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1312529826 Fri Aug 5 09:37:06 2011 us=147133 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' Fri Aug 5 09:37:06 2011 us=147139 PKCS#11: _pkcs11h_session_findObjects entry session=0x72fab0, filter=0x7fff40fa38f0, filter_attrs=2, p_objects=0x7fff40fa3928, p_objects_found=0x7fff40fa3920 Fri Aug 5 09:37:06 2011 us=147153 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=0 Fri Aug 5 09:37:06 2011 us=147159 PKCS#11: _pkcs11h_session_getObjectById return rv=512-'CKR_FUNCTION_REJECTED', *p_handle=ffffffffffffffff Fri Aug 5 09:37:06 2011 us=147165 PKCS#11: _pkcs11h_session_login entry session=0x72fab0, is_publicOnly=0, readonly=1, user_data=(nil), mask_prompt=00000003 Fri Aug 5 09:37:06 2011 us=147170 PKCS#11: _pkcs11h_session_logout entry session=0x72fab0 Fri Aug 5 09:37:06 2011 us=147177 PKCS#11: _pkcs11h_session_logout return Fri Aug 5 09:37:06 2011 us=147182 PKCS#11: _pkcs11h_session_reset entry session=0x72fab0, user_data=(nil), mask_prompt=00000003, p_slot=0x7fff40fa3918 Fri Aug 5 09:37:06 2011 us=147188 PKCS#11: _pkcs11h_session_reset Expected token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:06 2011 us=147194 PKCS#11: _pkcs11h_session_getSlotList entry provider=0x71af00, token_present=1, pSlotList=0x7fff40fa3498, pulCount=0x7fff40fa3490 Fri Aug 5 09:37:06 2011 us=147241 PKCS#11: _pkcs11h_session_getSlotList return rv=0-'CKR_OK' *pulCount=3 Fri Aug 5 09:37:06 2011 us=147250 PKCS#11: Cannot get token information for provider 'OpenSC (www.opensc-project.org)' slot -2 rv=224-'CKR_TOKEN_NOT_PRESENT' Fri Aug 5 09:37:06 2011 us=147259 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7fff40fa3488 Fri Aug 5 09:37:06 2011 us=147265 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7fff40fa3328 Fri Aug 5 09:37:06 2011 us=147270 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x761230 Fri Aug 5 09:37:06 2011 us=147276 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x761230 Fri Aug 5 09:37:06 2011 us=147281 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (VPN-token)' Fri Aug 5 09:37:06 2011 us=147287 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x761230 Fri Aug 5 09:37:06 2011 us=147292 PKCS#11: pkcs11h_token_freeTokenId return Fri Aug 5 09:37:06 2011 us=147297 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7fff40fa3488 Fri Aug 5 09:37:06 2011 us=147307 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7fff40fa3328 Fri Aug 5 09:37:06 2011 us=147312 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x761230 Fri Aug 5 09:37:06 2011 us=147318 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x761230 Fri Aug 5 09:37:06 2011 us=147323 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:06 2011 us=147328 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x761230 Fri Aug 5 09:37:06 2011 us=147332 PKCS#11: pkcs11h_token_freeTokenId return Fri Aug 5 09:37:06 2011 us=147338 PKCS#11: _pkcs11h_session_reset return rv=0-'CKR_OK', *p_slot=2 Fri Aug 5 09:37:06 2011 us=147343 PKCS#11: Calling pin_prompt hook for 'OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:07 2011 us=643394 PKCS#11: pin_prompt hook return rv=0 Fri Aug 5 09:37:07 2011 us=723210 PKCS#11: _pkcs11h_session_login C_Login rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723266 PKCS#11: _pkcs11h_session_login return rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723281 PKCS#11: _pkcs11h_session_getObjectById entry session=0x72fab0, class=3, id=0x72ec40, id_size=0000000000000001, p_handle=0x72ebc8 Fri Aug 5 09:37:07 2011 us=723293 PKCS#11: _pkcs11h_session_validate entry session=0x72fab0 Fri Aug 5 09:37:07 2011 us=723305 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1312529827 Fri Aug 5 09:37:07 2011 us=723315 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723328 PKCS#11: _pkcs11h_session_findObjects entry session=0x72fab0, filter=0x7fff40fa38f0, filter_attrs=2, p_objects=0x7fff40fa3928, p_objects_found=0x7fff40fa3920 Fri Aug 5 09:37:07 2011 us=723352 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=1 Fri Aug 5 09:37:07 2011 us=723365 PKCS#11: _pkcs11h_session_getObjectById return rv=0-'CKR_OK', *p_handle=00726e50 Fri Aug 5 09:37:07 2011 us=723376 PKCS#11: _pkcs11h_certificate_resetSession return rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723389 PKCS#11: _pkcs11h_session_getObjectAttributes entry session=0x72fab0, object=7499344, attrs=0x7fff40fa39b0, count=4 Fri Aug 5 09:37:07 2011 us=723405 PKCS#11: _pkcs11h_session_getObjectAttributes return rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723416 PKCS#11: Key attributes loaded (00000003) Fri Aug 5 09:37:07 2011 us=723427 PKCS#11: _pkcs11h_session_freeObjectAttributes entry attrs=0x7fff40fa39b0, count=4 Fri Aug 5 09:37:07 2011 us=723438 PKCS#11: _pkcs11h_session_freeObjectAttributes return Fri Aug 5 09:37:07 2011 us=723450 PKCS#11: __pkcs11h_certificate_getKeyAttributes return rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723467 PKCS#11: pkcs11h_certificate_sign entry certificate=0x72ebb0, mech_type=1, source=0x7fff40fa3be0, source_size=0000000000000024, target=0x757936, *p_target_size=0000000000000024 Fri Aug 5 09:37:07 2011 us=723480 PKCS#11: __pkcs11h_certificate_doPrivateOperation entry certificate=0x72ebb0, op=0, mech_type=1, source=0x7fff40fa3be0, source_size=0000000000000024, target=0x757936, *p_target_size=0000000000000024 Fri Aug 5 09:37:07 2011 us=723492 PKCS#11: _pkcs11h_certificate_validateSession entry certificate=0x72ebb0 Fri Aug 5 09:37:07 2011 us=723503 PKCS#11: _pkcs11h_session_validate entry session=0x72fab0 Fri Aug 5 09:37:07 2011 us=723514 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1312529827 Fri Aug 5 09:37:07 2011 us=723525 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723536 PKCS#11: _pkcs11h_certificate_validateSession return rv=0-'CKR_OK' Fri Aug 5 09:37:07 2011 us=723557 PKCS#11: __pkcs11h_certificate_doPrivateOperation init rv=0 Fri Aug 5 09:37:07 2011 us=723570 PKCS#11: __pkcs11h_certificate_doPrivateOperation op rv=336 Fri Aug 5 09:37:07 2011 us=723582 PKCS#11: Private key operation failed rv=336-'CKR_BUFFER_TOO_SMALL' Fri Aug 5 09:37:07 2011 us=723593 PKCS#11: _pkcs11h_certificate_resetSession entry certificate=0x72ebb0, public_only=0, session_mutex_locked=1 Fri Aug 5 09:37:07 2011 us=723619 PKCS#11: _pkcs11h_session_login entry session=0x72fab0, is_publicOnly=0, readonly=1, user_data=(nil), mask_prompt=00000003 Fri Aug 5 09:37:07 2011 us=723631 PKCS#11: _pkcs11h_session_logout entry session=0x72fab0 Fri Aug 5 09:37:07 2011 us=723646 PKCS#11: _pkcs11h_session_logout return Fri Aug 5 09:37:07 2011 us=723658 PKCS#11: _pkcs11h_session_reset entry session=0x72fab0, user_data=(nil), mask_prompt=00000003, p_slot=0x7fff40fa3818 Fri Aug 5 09:37:07 2011 us=723670 PKCS#11: _pkcs11h_session_reset Expected token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:07 2011 us=723682 PKCS#11: _pkcs11h_session_getSlotList entry provider=0x71af00, token_present=1, pSlotList=0x7fff40fa3398, pulCount=0x7fff40fa3390 Fri Aug 5 09:37:07 2011 us=723762 PKCS#11: _pkcs11h_session_getSlotList return rv=0-'CKR_OK' *pulCount=3 Fri Aug 5 09:37:07 2011 us=723780 PKCS#11: Cannot get token information for provider 'OpenSC (www.opensc-project.org)' slot -3 rv=224-'CKR_TOKEN_NOT_PRESENT' Fri Aug 5 09:37:07 2011 us=723795 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7fff40fa3388 Fri Aug 5 09:37:07 2011 us=723806 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7fff40fa3228 Fri Aug 5 09:37:07 2011 us=723818 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x761460 Fri Aug 5 09:37:07 2011 us=723830 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x761460 Fri Aug 5 09:37:07 2011 us=723842 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (VPN-token)' Fri Aug 5 09:37:07 2011 us=723854 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x761460 Fri Aug 5 09:37:07 2011 us=723864 PKCS#11: pkcs11h_token_freeTokenId return Fri Aug 5 09:37:07 2011 us=723876 PKCS#11: _pkcs11h_token_getTokenId entry p_token_id=0x7fff40fa3388 Fri Aug 5 09:37:07 2011 us=723887 PKCS#11: _pkcs11h_token_newTokenId entry p_token_id=0x7fff40fa3228 Fri Aug 5 09:37:07 2011 us=723898 PKCS#11: _pkcs11h_token_newTokenId return rv=0-'CKR_OK', *p_token_id=0x761460 Fri Aug 5 09:37:07 2011 us=723909 PKCS#11: _pkcs11h_token_getTokenId return rv=0-'CKR_OK', *p_token_id=0x761460 Fri Aug 5 09:37:07 2011 us=723920 PKCS#11: _pkcs11h_session_reset Found token manufacturerID='OpenSC Project' model='PKCS#15', serialNumber='28088614271A', label='OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:07 2011 us=723931 PKCS#11: pkcs11h_token_freeTokenId entry certificate_id=0x761460 Fri Aug 5 09:37:07 2011 us=723941 PKCS#11: pkcs11h_token_freeTokenId return Fri Aug 5 09:37:07 2011 us=723953 PKCS#11: _pkcs11h_session_reset return rv=0-'CKR_OK', *p_slot=2 Fri Aug 5 09:37:07 2011 us=723964 PKCS#11: Calling pin_prompt hook for 'OpenSC Card (Jonatan02 VPN)' Fri Aug 5 09:37:09 2011 us=290147 PKCS#11: pin_prompt hook return rv=0 Fri Aug 5 09:37:09 2011 us=369976 PKCS#11: _pkcs11h_session_login C_Login rv=0-'CKR_OK' Fri Aug 5 09:37:09 2011 us=370019 PKCS#11: _pkcs11h_session_login return rv=0-'CKR_OK' Fri Aug 5 09:37:09 2011 us=370041 PKCS#11: _pkcs11h_session_getObjectById entry session=0x72fab0, class=3, id=0x72ec40, id_size=0000000000000001, p_handle=0x72ebc8 Fri Aug 5 09:37:09 2011 us=370057 PKCS#11: _pkcs11h_session_validate entry session=0x72fab0 Fri Aug 5 09:37:09 2011 us=370068 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1312529829 Fri Aug 5 09:37:09 2011 us=370080 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' Fri Aug 5 09:37:09 2011 us=370092 PKCS#11: _pkcs11h_session_findObjects entry session=0x72fab0, filter=0x7fff40fa37f0, filter_attrs=2, p_objects=0x7fff40fa3828, p_objects_found=0x7fff40fa3820 Fri Aug 5 09:37:09 2011 us=370116 PKCS#11: _pkcs11h_session_findObjects return rv=0-'CKR_OK', *p_objects_found=1 Fri Aug 5 09:37:09 2011 us=370129 PKCS#11: _pkcs11h_session_getObjectById return rv=0-'CKR_OK', *p_handle=00726e50 Fri Aug 5 09:37:09 2011 us=370155 PKCS#11: _pkcs11h_certificate_resetSession return rv=0-'CKR_OK' Fri Aug 5 09:37:09 2011 us=370167 PKCS#11: _pkcs11h_certificate_validateSession entry certificate=0x72ebb0 Fri Aug 5 09:37:09 2011 us=370177 PKCS#11: _pkcs11h_session_validate entry session=0x72fab0 Fri Aug 5 09:37:09 2011 us=370188 PKCS#11: _pkcs11h_session_validate session->pin_expire_time=0, time=1312529829 Fri Aug 5 09:37:09 2011 us=370199 PKCS#11: _pkcs11h_session_validate return rv=0-'CKR_OK' Fri Aug 5 09:37:09 2011 us=370209 PKCS#11: _pkcs11h_certificate_validateSession return rv=0-'CKR_OK' Fri Aug 5 09:37:09 2011 us=370226 PKCS#11: __pkcs11h_certificate_doPrivateOperation init rv=0 Fri Aug 5 09:37:10 2011 us=255441 PKCS#11: __pkcs11h_certificate_doPrivateOperation op rv=0 Fri Aug 5 09:37:10 2011 us=255508 PKCS#11: __pkcs11h_certificate_doPrivateOperation return rv=0-'CKR_OK', *p_target_size=0000000000000100 Fri Aug 5 09:37:10 2011 us=255526 PKCS#11: pkcs11h_certificate_sign return rv=0-'CKR_OK', *p_target_size=0000000000000100 Fri Aug 5 09:37:10 2011 us=255542 PKCS#11: pkcs11h_certificate_signAny return rv=0-'CKR_OK', *p_target_size=0000000000000100 Fri Aug 5 09:37:10 2011 us=255561 PKCS#11: __pkcs11h_openssl_dec - return rv=0-'CKR_OK' Fri Aug 5 09:37:12 2011 us=831739 PKCS#11: __pkcs11h_forkFixup entry pid=8169, activate_slotevent=1 Fri Aug 5 09:37:14 2011 us=391200 PKCS#11: __pkcs11h_forkFixup return Fri Aug 5 09:37:14 2011 us=396007 PKCS#11: __pkcs11h_forkFixup entry pid=8177, activate_slotevent=1 Fri Aug 5 09:37:15 2011 us=950789 PKCS#11: __pkcs11h_forkFixup return Fri Aug 5 09:37:15 2011 us=952788 PKCS#11: __pkcs11h_forkFixup entry pid=8180, activate_slotevent=1 Fri Aug 5 09:37:17 2011 us=505721 PKCS#11: __pkcs11h_forkFixup return Fri Aug 5 09:37:17 2011 us=507881 PKCS#11: __pkcs11h_forkFixup entry pid=8190, activate_slotevent=1 Fri Aug 5 09:37:19 2011 us=64830 PKCS#11: __pkcs11h_forkFixup return Fri Aug 5 09:37:19 2011 us=66941 PKCS#11: __pkcs11h_forkFixup entry pid=8193, activate_slotevent=1 Fri Aug 5 09:37:20 2011 us=620694 PKCS#11: __pkcs11h_forkFixup return Fri Aug 5 09:37:20 2011 us=622847 PKCS#11: __pkcs11h_forkFixup entry pid=8196, activate_slotevent=1 Fri Aug 5 09:37:22 2011 us=178150 PKCS#11: __pkcs11h_forkFixup return
_______________________________________________ opensc-devel mailing list opensc-devel@lists.opensc-project.org http://www.opensc-project.org/mailman/listinfo/opensc-devel
