{"action":"created","issue":{"url":"https://api.github.com/repos/OpenSC/libp11/issues/72","repository_url":"https://api.github.com/repos/OpenSC/libp11","labels_url":"https://api.github.com/repos/OpenSC/libp11/issues/72/labels{/name}","comments_url":"https://api.github.com/repos/OpenSC/libp11/issues/72/comments","events_url":"https://api.github.com/repos/OpenSC/libp11/issues/72/events","html_url":"https://github.com/OpenSC/libp11/issues/72","id":138290060,"number":72,"title":"problem with tests/evp-sign.c","user":{"login":"mouse07410","id":5923577,"avatar_url":"https://avatars.githubusercontent.com/u/5923577?v=3","gravatar_id":"","url":"https://api.github.com/users/mouse07410","html_url":"https://github.com/mouse07410","followers_url":"https://api.github.com/users/mouse07410/followers","following_url":"https://api.github.com/users/mouse07410/following{/other_user}","gists_url":"https://api.github.com/users/mouse07410/gists{/gist_id}","starred_url":"https://api.github.com/users/mouse07410/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mouse07410/subscriptions","organizations_url":"https://api.github.com/users/mouse07410/orgs","repos_url":"https://api.github.com/users/mouse07410/repos","events_url":"https://api.github.com/users/mouse07410/events{/privacy}","received_events_url":"https://api.github.com/users/mouse07410/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":31,"created_at":"2016-03-03T20:35:06Z","updated_at":"2016-03-12T17:37:54Z","closed_at":"2016-03-12T08:07:17Z","body":"@mtrojnar very possibly (likely) this is **not** a `libp11` bug (and I posted it to openssl-users list). Especially since all the tests run by `make check` pass fine (with the current release of [SoftHSMv2](https://github.com/opendnssec/SoftHSMv2)). Also, my shell scripts that use `openssl` CLI for all the operations on the token, all work fine.  \r\n\r\nStill, it **might** be somehow related, and I'd love some guidance/help in any case.\r\n\r\nI am trying to write code that uses OpenSSL EVP to sign/verify and/or encrypt/decrypt stuff. My code works when I use functions defined in `openssl/apps/apps.c`, but fails when I try to use EVP methods directly. \r\n\r\nSo I tried to run `tests/.libs/evp-sign` (since it presumably makes the EVP calls correctly and in the right sequence, and it's been proven to work at least with SoftHSMv2) to sanity-check. When I try `tests/.libs/evp-sign` on my RSA hardware token, it fails:\r\n```\r\n$ tests/.libs/evp-sign default xxxxxxxx /opt/local/etc/openssl/openssl.cnf \"pkcs11:object=SIGN%20key;object-type=private\" \"pkcs11:object=SIGN%20pubkey;object-type=public\" /Library/OpenSC/lib/opensc-pkcs11.dylib \r\nAt main.c:261:\r\n- SSL error:FFFFFFFF8000A001:Vendor defined:PKCS11_rsa_sign:Cancel: p11_rsa.c:148\r\n$ tests/.libs/evp-sign ctrl xxxxxxxx /opt/local/etc/openssl/openssl.cnf \"pkcs11:object=SIGN%20key;object-type=private\" \"pkcs11:object=SIGN%20pubkey;object-type=public\" /Library/OpenSC/lib/opensc-pkcs11.dylib \r\nAt main.c:261:\r\n- SSL error:FFFFFFFF8000A001:Vendor defined:PKCS11_rsa_sign:Cancel: p11_rsa.c:148\r\n$\r\n```\r\n\r\nIn both cases the `opensc-debug.log` shows authentication problem:\r\n```\r\n......\r\n [opensc-pkcs11] reader-pcsc.c:389:pcsc_detect_card_presence: returning with: 5\r\n [opensc-pkcs11] sec.c:206:sc_pin_cmd: returning with: 0 (Success)\r\n [opensc-pkcs11] card-piv.c:2221:piv_set_security_env: called\r\n [opensc-pkcs11] card-piv.c:2252:piv_set_security_env: returning with: 0 (Success\r\n)\r\n [opensc-pkcs11] sec.c:72:sc_set_security_env: returning with: 0 (Success)\r\n [opensc-pkcs11] card-piv.c:2352:piv_compute_signature: called\r\n [opensc-pkcs11] card-piv.c:2281:piv_validate_general_authentication: called\r\n [opensc-pkcs11] card-piv.c:454:piv_general_io: called\r\n [opensc-pkcs11] card-piv.c:2410:piv_compute_signature: returning with: -1211 (Security status not satisfied)\r\n [opensc-pkcs11] sec.c:58:sc_compute_signature: returning with: -1211 (Security status not satisfied)\r\n [opensc-pkcs11] card-piv.c:2221:piv_set_security_env: called\r\n [opensc-pkcs11] card-piv.c:2252:piv_set_security_env: returning with: 0 (Success)\r\n [opensc-pkcs11] sec.c:72:sc_set_security_env: returning with: 0 (Success)\r\n......\r\n```\r\n\r\nThere is no record of successful authentication.  My code uses encrypt/decrypt, but the failure is the same, and in a similar place. `evp-sign` fails in `pkcs11_private_encrypt()` (to sign with a private key, an operation that requires PIN-unlock), and my code fails in `pkcs11_private_decrypt() (again, an operation with a private key that requires unlock)...\r\n\r\nFor comparison, here's what in the log when I use my code linked with compiled `apps.c` (and `libcrypto`, of course):\r\n```\r\n [opensc-pkcs11] reader-pcsc.c:389:pcsc_detect_card_presence: returning with: 5\r\n [opensc-pkcs11] sec.c:206:sc_pin_cmd: returning with: 0 (Success)\r\n [opensc-pkcs11] sec.c:206:sc_pin_cmd: returning with: 0 (Success)\r\n [opensc-pkcs11] card-piv.c:2221:piv_set_security_env: called\r\n [opensc-pkcs11] card-piv.c:2252:piv_set_security_env: returning with: 0 (Success)\r\n [opensc-pkcs11] sec.c:72:sc_set_security_env: returning with: 0 (Success)\r\n [opensc-pkcs11] card-piv.c:2417:piv_decipher: called\r\n [opensc-pkcs11] card-piv.c:2281:piv_validate_general_authentication: called\r\n [opensc-pkcs11] card-piv.c:454:piv_general_io: called\r\n [opensc-pkcs11] card-piv.c:2419:piv_decipher: returning with: 256\r\n [opensc-pkcs11] sec.c:44:sc_decipher: returning with: 256\r\n [opensc-pkcs11] card-piv.c:2819:piv_finish: called\r\n [opensc-pkcs11] ctx.c:818:sc_release_context: called\r\n```\r\n\r\nIn case it helps, here's the offending code:\r\n```\r\nint unwrap(const unsigned char *in, const size_t inlen, unsigned char **out, size_t *olen, ENGINE **e) {\r\n\tint rv = -1;\r\n\tEVP_PKEY *privkey = NULL;\r\n\tEVP_PKEY_CTX *ctx = NULL;\r\n\tPW_CB_DATA cb_data;\r\n\tchar *key_pass = NULL;\r\n\r\n\tcb_data.password = NULL;\r\n\tcb_data.prompt_info = \"pkcs11:object=KEY%20MAN%20key;object-type=private\";\r\n\r\n\tsetup_ui();\r\n\r\n\tui_method = ui_console_with_default;\r\n\tui_extra = key_pass;\r\n\r\n\t/* Load engine */\r\n\tif (*e == NULL) {\r\n\t\t*e = load_engine(\"pkcs11\");\r\n\t\tif (*e == NULL) {\r\n\t\t\tfprintf(stderr, \"unwrap: failed to instantiate pkcs11 engine\\n\");\r\n\t\t\tgoto end;\r\n\t\t}\r\n\t}\r\n\r\n\tprivkey = ENGINE_load_private_key(*e, \"id_03\", ui_method, ui_extra);\r\n\tif (privkey == NULL) {\r\n\t\tfprintf(stderr, \"unwrap: failed to get handle to privkey id_03\\n\");\r\n\t\tgoto end;\r\n\t}\r\n\tprintf(\"unwrap: loaded privkey of size %1d\\n\", EVP_PKEY_size(privkey));\r\n\r\n\t/* Create context */\r\n\tctx = EVP_PKEY_CTX_new(privkey, NULL);\r\n\tEVP_PKEY_free(privkey);\r\n\tif (ctx == NULL) {\r\n\t\tfprintf(stderr, \"unwrap: failed to create context\\n\");\r\n\t\tgoto end;\r\n\t}\r\n\trv = EVP_PKEY_decrypt_init(ctx);\r\n\tEVP_PKEY_CTX_set_rsa_padding(ctx, RSA_PKCS1_PADDING);\r\n\tif (rv <= 0) {\r\n\t\tfprintf(stderr, \"unwrap: failed to initialize decrypt_ctx (rv=%d\\n\", rv);\r\n\t\tgoto end;\r\n\t}\r\n\r\n\t/* Unwrap the encrypted key */\r\n\t*olen = 0;\r\n\trv = EVP_PKEY_decrypt(ctx, NULL, olen, in, inlen);\r\n\tif ((rv <= 0) || (*olen == 0)) {\r\n\t\tfprintf(stderr, \"unwrap: failed to get required output buf len (rv=%d)\\n\", rv);\r\n\t\tgoto end;\r\n\t}\r\n\tprintf(\"unwrap: allocating %1lu bytes...\\n\", *olen);\r\n\t*out = OPENSSL_malloc(*olen);\r\n\tif (*out == NULL) {\r\n\t\tfprintf(stderr, \"unwrap: failed to allocate output buf (%1lu bytes)\\n\", *olen);\r\n\t\trv = -1;\r\n\t\tgoto end;\r\n\t}\r\n\trv = EVP_PKEY_decrypt(ctx, *out, olen, in, inlen);\r\n\tif (rv <= 0) {\r\n\t\tOPENSSL_free(*out);\r\n        *out = NULL;\r\n\t\tfprintf(stderr, \"unwrap: failed to decrypt (rv=%d)\\n\", rv);\r\n\t\tgoto end;\r\n\t}\r\n\tprintf(\"unwrap: decrypt returned %d (%1lu bytes)\\n\", rv, *olen);\r\n\r\n\t/* Cleanup - tear down OpenSSL constructs used */\r\nend:\r\n\tERR_print_errors_fp(stderr);\r\n\tif (ctx == NULL)\r\n\t\tEVP_PKEY_CTX_free(ctx);\r\n\t//unload_engine(e);\r\n\t//clean_openssl();\r\n\r\n\treturn rv;\r\n}\r\n```\r\nand its output:\r\n```\r\nunwrap: loaded privkey of size 256\r\nunwrap: allocating 256 bytes...\r\nunwrap: decrypt returned 1 (0 bytes)\r\nunwrapping returned 1\r\nDecrypted symmetric key (0 bytes):\r\n\r\n140735154045776:error:80008001:Vendor defined:PKCS11_rsa_decrypt:Cancel:p11_rsa.c:181:\r\n```\r\n\r\nIn case it matters, here's the `rsa-evp-sign.softhsm.log`:\r\n```\r\nCurrent directory: /Users/ur20980/src/libp11/tests\r\nSource directory: .\r\nOutput directory: output.40351\r\n-n * Initializing smart card... \r\nok\r\nUsing slot 0 with a present token (0x0)\r\nUsing slot 0 with a present token (0x0)\r\nUsing slot 0 with a present token (0x0)\r\n***************\r\nListing objects\r\n***************\r\nUsing slot 0 with a present token (0x0)\r\nPublic Key Object; RSA 2048 bits\r\n  label:      server-key\r\n  ID:         00010203\r\n  Usage:      encrypt, verify, wrap\r\nCertificate Object, type = X.509 cert\r\n  label:      server-key\r\n  ID:         00010203\r\nPrivate Key Object; RSA \r\n  label:      server-key\r\n  ID:         00010203\r\n  Usage:      decrypt, sign, unwrap\r\nSignature created\r\nSignature verified\r\nSignature created\r\nSignature verified\r\nSignature created\r\nSignature verified\r\nSignature created\r\nSignature verified\r\nSignature created\r\nSignature verified\r\nSignature created\r\nSignature verified\r\nPASS rsa-evp-sign.softhsm (exit status: 0)\r\n```"},"comment":{"url":"https://api.github.com/repos/OpenSC/libp11/issues/comments/195779074","html_url":"https://github.com/OpenSC/libp11/issues/72#issuecomment-195779074","issue_url":"https://api.github.com/repos/OpenSC/libp11/issues/72","id":195779074,"user":{"login":"dengert","id":865329,"avatar_url":"https://avatars.githubusercontent.com/u/865329?v=3","gravatar_id":"","url":"https://api.github.com/users/dengert","html_url":"https://github.com/dengert","followers_url":"https://api.github.com/users/dengert/followers","following_url":"https://api.github.com/users/dengert/following{/other_user}","gists_url":"https://api.github.com/users/dengert/gists{/gist_id}","starred_url":"https://api.github.com/users/dengert/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dengert/subscriptions","organizations_url":"https://api.github.com/users/dengert/orgs","repos_url":"https://api.github.com/users/dengert/repos","events_url":"https://api.github.com/users/dengert/events{/privacy}","received_events_url":"https://api.github.com/users/dengert/received_events","type":"User","site_admin":false},"created_at":"2016-03-12T17:37:54Z","updated_at":"2016-03-12T17:37:54Z","body":"Ran four tests using OmniKey 3821 pin pad reader and SRC3500 non-pin pad reader, with two PIV cards one of which had problems with the VERIFY Lc=0x00. \r\n\r\nWith pin pad reader, was using:\r\nevp-sign default \"\"  $OPENSSL_CONF \"pkcs11:object=SIGN%20key;object-type=private\" \"pkcs11:object=SIGN%20pubkey;object-type=public\" /opt/smartcard/lib/opensc-pkcs11.so\r\n\r\nThe pin was requested twice on the pin pad reader, once for the initial C_login  and once for the C_Login (...,CKU_CONTEXT_SPECIFIC, ...) C_Login. \r\nWhen using the non-pinpad reader, the C_login was called twice, but evp-sign was provided with the PIN so no prompts were needed. \r\n\r\nThe C_login (...,CKU_CONTEXT_SPECIFIC, ...) is called just before the crypto operation, then negating any issue with the VERIFY Lc=0x00 interfering with the \"PIN Always\". \r\n\r\nAll worked as expected. \r\n\r\nNice PR.\r\n\r\n\r\n"}}