Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Can't decrypt with pkcs11-tool #765

Closed
cesarkuroiwa opened this issue May 18, 2016 · 55 comments · Fixed by #1496
Closed

Can't decrypt with pkcs11-tool #765

cesarkuroiwa opened this issue May 18, 2016 · 55 comments · Fixed by #1496

Comments

@cesarkuroiwa
Copy link

Expected behaviour

Should decrypt an encrypted file with the private key from a smartcard

Actual behaviour

% pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -v --input-file encrypted.bin --id 9352 -l            Using slot 1 with a present token (0x1)
Logging in to "OpenSC Card".
Please enter User PIN: 
Using decrypt algorithm RSA-PKCS
error: PKCS11 function C_Decrypt failed: rv = CKR_DATA_LEN_RANGE (0x21)

Aborting.

PS: We recently update from opensc 0.11 to 0.15 and this stopped working, including when using OpenSSL engine.

@dengert
Copy link
Member

dengert commented May 18, 2016

How big is the encrypted.bin file?
The pkcs11-tool --decrypt is RSA key, so the length must be less than k-11 where k is the key size in bytes.
If the file is large, normally a symmetric key is used to encrypt the data, then the symmetric key is encrypted with RSA,
then the decrypt recovers the symmetric key, and the key decrypt the data.

Not sure why it worked with 0.11 but not 015.
Add -v six times, and send the output to the list. Note the PIN and decrypted data may appear in the output.

On 5/18/2016 8:28 AM, cesarkuroiwa wrote:

  Expected behaviour

Should decrypt an encrypted file with the private key from a smartcard

  Actual behaviour

|% pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -v --input-file encrypted.bin --id 9352 -l Using slot 1 with a present token (0x1) Logging in to "OpenSC Card". Please enter User PIN:
Using decrypt algorithm RSA-PKCS error: PKCS11 function C_Decrypt failed: rv = CKR_DATA_LEN_RANGE (0x21) Aborting. |

PS: We recently update from opensc 0.11 to 0.15 and this stopped working, including when using OpenSSL engine.


You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub #765

Douglas E. Engert [email protected]

@cesarkuroiwa
Copy link
Author

The size of the encrypted file is 128 bytes, but the size of the original message is much smaller (only 8 bytes). The size of the RSA key is 1024 bits.

Just ran the command with -vvvvvv and the output was the same:

% pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -vvvvvv -l --input-file encrypted.bin --id 9352
Using slot 1 with a present token (0x1)
Logging in to "OpenSC Card".
Please enter User PIN: 
Using decrypt algorithm RSA-PKCS
error: PKCS11 function C_Decrypt failed: rv = CKR_DATA_LEN_RANGE (0x21)

Aborting.

@dengert
Copy link
Member

dengert commented May 18, 2016

the -vvvvvvvv should hav we produced a debug trace.
Can you edit the opensc.conf and look for debug = and debug_file - and changes these to get a trace?

On 5/18/2016 1:50 PM, cesarkuroiwa wrote:

The size of the encrypted file is 128 bytes, but the size of the original message is much smaller (only 8 bytes). The size of the RSA key is 1024 bits.

Just ran the command with -vvvvvv and the output was the same:

|% pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -vvvvvv -l --input-file encrypted.bin --id 9352 Using slot 1 with a present token (0x1) Logging in to "OpenSC Card". Please enter User
PIN: Using decrypt algorithm RSA-PKCS error: PKCS11 function C_Decrypt failed: rv = CKR_DATA_LEN_RANGE (0x21) Aborting. |


You are receiving this because you commented.
Reply to this email directly or view it on GitHub #765 (comment)

Douglas E. Engert [email protected]

@frankmorgner
Copy link
Member

actually you must set the debug level in opensc.conf instead of via -v

@frankmorgner
Copy link
Member

What is an "OpenSC card"?

You upgraded from 0.11? What have you done in the last 7 years???

@cesarkuroiwa
Copy link
Author

Hi,
I updated the debug level to 6 and then ran the program and it printed a whole bunch of stuff to the debug file. Here is what I think is the most relevant part, right after I enter the PIN number:

0x801807400 09:52:33.315 [opensc-pkcs11] pkcs11-session.c:259:C_Login: C_Login(0x80182e520, 1)
0x801807400 09:52:33.316 [opensc-pkcs11] pkcs11-session.c:279:C_Login: C_Login() slot->login_user 38654705663
0x801807400 09:52:33.316 [opensc-pkcs11] pkcs11-session.c:288:C_Login: C_Login() userType 1
0x801807400 09:52:33.316 [opensc-pkcs11] framework-pkcs15.c:1409:pkcs15_login: pkcs15-login: userType 0x1, PIN length 6
0x801807400 09:52:33.316 [opensc-pkcs11] pkcs15-pin.c:295:sc_pkcs15_verify_pin: called
0x801807400 09:52:33.316 [opensc-pkcs11] pkcs15-pin.c:296:sc_pkcs15_verify_pin: PIN(type:0;method:1;len:)
0x801807400 09:52:33.316 [opensc-pkcs11] card.c:352:sc_lock: called
0x801807400 09:52:33.316 [opensc-pkcs11] reader-pcsc.c:519:pcsc_lock: called
0x801807400 09:52:33.316 [opensc-pkcs11] card.c:650:sc_select_file: called; type=2, path=3f005015
0x801807400 09:52:33.316 [opensc-pkcs11] card-starcos.c:370:starcos_select_file: called
0x801807400 09:52:33.316 [opensc-pkcs11] card-starcos.c:380:starcos_select_file: current path (path, valid): 3f005015 (len: 4)
0x801807400 09:52:33.316 [opensc-pkcs11] card-starcos.c:473:starcos_select_file: cache hit
0x801807400 09:52:33.316 [opensc-pkcs11] card.c:678:sc_select_file: returning with: 0 (Success)
0x801807400 09:52:33.316 [opensc-pkcs11] sec.c:159:sc_pin_cmd: called
0x801807400 09:52:33.316 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x801807400 09:52:33.316 [opensc-pkcs11] card.c:352:sc_lock: called
0x801807400 09:52:33.316 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x801807400 09:52:33.316 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x801807400 09:52:33.316 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:0, INS:20, P1:0, P2:83, data(8) 0x7fffffffb680
0x801807400 09:52:33.316 [opensc-pkcs11] reader-pcsc.c:251:pcsc_transmit: reader 'Gemalto PC Twin Reader 00 00'
0x801807400 09:52:33.316 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   13 bytes] =====================================
00 20 00 83 08 31 32 33 34 35 36 00 00 . ...123456..
======================================================================
0x801807400 09:52:33.316 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x801807400 09:52:33.438 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x801807400 09:52:33.438 [opensc-pkcs11] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x801807400 09:52:33.438 [opensc-pkcs11] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x801807400 09:52:33.438 [opensc-pkcs11] card.c:392:sc_unlock: called
0x801807400 09:52:33.438 [opensc-pkcs11] card-starcos.c:1234:starcos_check_sw: sw1 = 0x90, sw2 = 0x00
0x801807400 09:52:33.438 [opensc-pkcs11] sec.c:206:sc_pin_cmd: returning with: 0 (Success)
0x801807400 09:52:33.438 [opensc-pkcs11] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result 0
0x801807400 09:52:33.438 [opensc-pkcs11] pkcs15-pin.c:594:sc_pkcs15_pincache_add: called
0x801807400 09:52:33.438 cannot lock memory, sensitive data may be paged to disk
0x801807400 09:52:33.438 [opensc-pkcs11] pkcs15-pin.c:634:sc_pkcs15_pincache_add: PIN() cached
0x801807400 09:52:33.438 [opensc-pkcs11] card.c:392:sc_unlock: called
0x801807400 09:52:33.438 [opensc-pkcs11] reader-pcsc.c:556:pcsc_unlock: called
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:1513:pkcs15_login: PKCS15 verify PIN returned 0
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:1522:pkcs15_login: Check if pkcs15 object list can be completed.
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-session.c:290:C_Login: fLogin() rv 0
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:336:C_FindObjectsInit: C_FindObjectsInit(slot = 1)
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:337:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = CKO_PRIVATE_KEY
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:337:C_FindObjectsInit: C_FindObjectsInit(): CKA_ID = 9352
0x801807400 09:52:33.441 [opensc-pkcs11] misc.c:139:session_start_operation: called
0x801807400 09:52:33.441 [opensc-pkcs11] misc.c:140:session_start_operation: Session 0x80182e520, type 0
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x80182e460
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:3320:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:3320:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:384:C_FindObjectsInit: Object 1/25355360: Attribute 0x0 matches.
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:3320:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:3320:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:384:C_FindObjectsInit: Object 1/25355360: Attribute 0x102 matches.
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:389:C_FindObjectsInit: Object 1/25355360 matches
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:393:C_FindObjectsInit: realloc for 32 handles
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:358:C_FindObjectsInit: Object with handle 0x80182e4c0
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:3847:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x801807400 09:52:33.441 [opensc-pkcs11] framework-pkcs15.c:3847:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: Object 1/25355456: Attribute 0x0 does NOT match.
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:406:C_FindObjectsInit: 1 matching objects
0x801807400 09:52:33.441 [opensc-pkcs11] misc.c:161:session_get_operation: called
0x801807400 09:52:33.441 [opensc-pkcs11] misc.c:161:session_get_operation: called
0x801807400 09:52:33.441 [opensc-pkcs11] pkcs11-object.c:59:sc_find_release: freeing 32 handles used 1  at 0x80181cf00
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.441 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:391:slot_get_token: Slot(id=0x1): get token
0x801807400 09:52:33.442 [opensc-pkcs11] slot.c:409:slot_get_token: Slot-get-token returns OK
0x801807400 09:52:33.442 [opensc-pkcs11] framework-pkcs15.c:3320:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x801807400 09:52:33.442 [opensc-pkcs11] framework-pkcs15.c:3320:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
0x801807400 09:52:33.442 [opensc-pkcs11] misc.c:139:session_start_operation: called
0x801807400 09:52:33.442 [opensc-pkcs11] misc.c:140:session_start_operation: Session 0x80182e520, type 4
0x801807400 09:52:33.442 [opensc-pkcs11] pkcs11-object.c:862:C_DecryptInit: C_DecryptInit() = CKR_OK
0x801807400 09:52:33.442 [opensc-pkcs11] misc.c:161:session_get_operation: called
0x801807400 09:52:33.442 [opensc-pkcs11] framework-pkcs15.c:3618:pkcs15_prkey_decrypt: Initiating decryption.
0x801807400 09:52:33.442 [opensc-pkcs11] card.c:352:sc_lock: called
0x801807400 09:52:33.442 [opensc-pkcs11] reader-pcsc.c:519:pcsc_lock: called
0x801807400 09:52:33.442 [opensc-pkcs11] pkcs15-sec.c:95:sc_pkcs15_decipher: called
0x801807400 09:52:33.442 [opensc-pkcs11] padding.c:283:sc_get_encoding_flags: called
0x801807400 09:52:33.442 [opensc-pkcs11] padding.c:287:sc_get_encoding_flags: iFlags 0x2, card capabilities 0x800001FA
0x801807400 09:52:33.442 [opensc-pkcs11] padding.c:316:sc_get_encoding_flags: pad flags 0x0, secure algorithm flags 0x2
0x801807400 09:52:33.442 [opensc-pkcs11] padding.c:317:sc_get_encoding_flags: returning with: 0 (Success)
0x801807400 09:52:33.442 [opensc-pkcs11] card.c:352:sc_lock: called
0x801807400 09:52:33.442 [opensc-pkcs11] pkcs15-sec.c:44:select_key_file: called
0x801807400 09:52:33.442 [opensc-pkcs11] card.c:650:sc_select_file: called; type=2, path=3f005015
0x801807400 09:52:33.442 [opensc-pkcs11] card-starcos.c:370:starcos_select_file: called
0x801807400 09:52:33.442 [opensc-pkcs11] card-starcos.c:380:starcos_select_file: current path (path, valid): 3f005015 (len: 4)
0x801807400 09:52:33.442 [opensc-pkcs11] card-starcos.c:473:starcos_select_file: cache hit
0x801807400 09:52:33.442 [opensc-pkcs11] card.c:678:sc_select_file: returning with: 0 (Success)
0x801807400 09:52:33.442 [opensc-pkcs11] pkcs15-sec.c:80:select_key_file: returning with: 0 (Success)
0x801807400 09:52:33.442 [opensc-pkcs11] sec.c:68:sc_set_security_env: called
0x801807400 09:52:33.442 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x801807400 09:52:33.442 [opensc-pkcs11] card.c:352:sc_lock: called
0x801807400 09:52:33.442 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x801807400 09:52:33.442 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x801807400 09:52:33.442 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:0, INS:22, P1:81, P2:B8, data(6) 0x7fffffffd670
0x801807400 09:52:33.442 [opensc-pkcs11] reader-pcsc.c:251:pcsc_transmit: reader 'Gemalto PC Twin Reader 00 00'
0x801807400 09:52:33.442 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [   11 bytes] =====================================
00 22 81 B8 06 84 01 91 80 01 02 .".........
======================================================================
0x801807400 09:52:33.442 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x801807400 09:52:33.456 [opensc-pkcs11] card.c:392:sc_unlock: called
0x801807400 09:52:33.456 [opensc-pkcs11] sec.c:72:sc_set_security_env: returning with: 0 (Success)
0x801807400 09:52:33.456 [opensc-pkcs11] sec.c:40:sc_decipher: called
0x801807400 09:52:33.456 [opensc-pkcs11] iso7816.c:952:iso7816_decipher: called
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x801807400 09:52:33.456 [opensc-pkcs11] card.c:352:sc_lock: called
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:10, INS:2A, P1:80, P2:86, data(128) 0x801821740
0x801807400 09:52:33.456 [opensc-pkcs11] reader-pcsc.c:251:pcsc_transmit: reader 'Gemalto PC Twin Reader 00 00'
0x801807400 09:52:33.456 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [  133 bytes] =====================================
10 2A 80 86 80 00 07 85 4B F0 8D 21 02 34 B4 E3 .*......K..!.4..
BF 50 5E 3E 41 F8 C2 77 23 7E 97 9E 17 74 53 9B .P^>A..w#~...tS.
D5 73 5C B8 76 42 59 2E C9 AE 24 4B 12 88 AD 1D .s\.vBY...$K....
51 7E 36 78 C4 C5 5A 4F 7B BD 2D 6A 0E 1F D7 2D Q~6x..ZO{.-j...-
5A 68 1D 4A D3 26 FE 19 5D 8D 9B 9D 95 38 B6 C5 Zh.J.&..]....8..
C3 17 D7 33 E3 E7 41 7F 5B 42 20 F1 D1 2E E5 37 ...3..A.[B ....7
A4 DC 2F CC C4 8A 46 4D EA 06 62 DE 45 0E B3 C7 ../...FM..b.E...
8B 87 67 59 CC 54 FB E8 9E 19 C3 86 02 3B 31 89 ..gY.T.......;1.
09 78 48 ED 58                                  .xH.X
======================================================================
0x801807400 09:52:33.456 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x801807400 09:52:33.552 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
67 00 g.
======================================================================
0x801807400 09:52:33.552 [opensc-pkcs11] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x801807400 09:52:33.552 [opensc-pkcs11] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x801807400 09:52:33.552 [opensc-pkcs11] card-starcos.c:1234:starcos_check_sw: sw1 = 0x67, sw2 = 0x00
0x801807400 09:52:33.552 [opensc-pkcs11] iso7816.c:139:iso7816_check_sw: Wrong length
0x801807400 09:52:33.552 [opensc-pkcs11] card.c:392:sc_unlock: called
0x801807400 09:52:33.552 [opensc-pkcs11] iso7816.c:976:iso7816_decipher: APDU transmit failed: -1206 (Wrong length)
0x801807400 09:52:33.552 [opensc-pkcs11] sec.c:44:sc_decipher: returning with: -1206 (Wrong length)
0x801807400 09:52:33.552 [opensc-pkcs11] card.c:392:sc_unlock: called
0x801807400 09:52:33.552 [opensc-pkcs11] pkcs15-sec.c:169:sc_pkcs15_decipher: sc_decipher() failed: -1206 (Wrong length)
0x801807400 09:52:33.552 [opensc-pkcs11] card.c:392:sc_unlock: called
0x801807400 09:52:33.552 [opensc-pkcs11] reader-pcsc.c:556:pcsc_unlock: called
0x801807400 09:52:33.562 [opensc-pkcs11] framework-pkcs15.c:3660:pkcs15_prkey_decrypt: Decryption complete. Result -1206.
0x801807400 09:52:33.562 [opensc-pkcs11] misc.c:61:sc_to_cryptoki_error_common: libopensc return value: -1206 (Wrong length)
0x801807400 09:52:33.562 [opensc-pkcs11] pkcs11-object.c:885:C_Decrypt: C_Decrypt() = CKR_DATA_LEN_RANGE
0x801807400 09:52:33.562 [opensc-pkcs11] pkcs11-global.c:291:C_Finalize: C_Finalize()
0x801807400 09:52:33.562 [opensc-pkcs11] ctx.c:776:sc_cancel: called
0x801807400 09:52:33.562 [opensc-pkcs11] reader-pcsc.c:599:pcsc_cancel: called
0x801807400 09:52:33.562 [opensc-pkcs11] slot.c:157:card_removed: Gemalto PC Twin Reader 00 00: card removed
0x801807400 09:52:33.562 [opensc-pkcs11] slot.c:419:slot_token_removed: slot_token_removed(0x1)
0x801807400 09:52:33.562 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 1
0x801807400 09:52:33.562 [opensc-pkcs11] pkcs11-session.c:98:sc_pkcs11_close_session: real C_CloseSession(0x80182e520)
0x801807400 09:52:33.562 [opensc-pkcs11] pkcs15-pin.c:690:sc_pkcs15_pincache_clear: called
0x801807400 09:52:33.562 [opensc-pkcs11] apdu.c:563:sc_transmit_apdu: called
0x801807400 09:52:33.562 [opensc-pkcs11] card.c:352:sc_lock: called
0x801807400 09:52:33.562 [opensc-pkcs11] reader-pcsc.c:519:pcsc_lock: called
0x801807400 09:52:33.562 [opensc-pkcs11] apdu.c:530:sc_transmit: called
0x801807400 09:52:33.562 [opensc-pkcs11] apdu.c:384:sc_single_transmit: called
0x801807400 09:52:33.562 [opensc-pkcs11] apdu.c:389:sc_single_transmit: CLA:0, INS:A4, P1:0, P2:C, data(2) 0x7fffffffdbb0
0x801807400 09:52:33.562 [opensc-pkcs11] reader-pcsc.c:251:pcsc_transmit: reader 'Gemalto PC Twin Reader 00 00'
0x801807400 09:52:33.562 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Outgoing APDU data [    7 bytes] =====================================
00 A4 00 0C 02 3F 00 .....?.
======================================================================
0x801807400 09:52:33.562 [opensc-pkcs11] reader-pcsc.c:184:pcsc_internal_transmit: called
0x801807400 09:52:33.569 [opensc-pkcs11] apdu.c:187:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x801807400 09:52:33.569 [opensc-pkcs11] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x801807400 09:52:33.569 [opensc-pkcs11] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x801807400 09:52:33.569 [opensc-pkcs11] card.c:392:sc_unlock: called
0x801807400 09:52:33.569 [opensc-pkcs11] reader-pcsc.c:556:pcsc_unlock: called
0x801807400 09:52:33.571 [opensc-pkcs11] card-starcos.c:1234:starcos_check_sw: sw1 = 0x90, sw2 = 0x00
0x801807400 09:52:33.571 [opensc-pkcs11] framework-pkcs15.c:1388:pkcs15_release_token: pkcs15_release_token() not implemented
0x801807400 09:52:33.571 [opensc-pkcs11] slot.c:419:slot_token_removed: slot_token_removed(0x2)
0x801807400 09:52:33.571 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x2) 0
0x801807400 09:52:33.571 [opensc-pkcs11] slot.c:419:slot_token_removed: slot_token_removed(0x3)
0x801807400 09:52:33.571 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x3) 0
0x801807400 09:52:33.571 [opensc-pkcs11] slot.c:419:slot_token_removed: slot_token_removed(0x4)
0x801807400 09:52:33.571 [opensc-pkcs11] pkcs11-session.c:126:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x4) 0
0x801807400 09:52:33.571 [opensc-pkcs11] pkcs15.c:1263:sc_pkcs15_unbind: called
0x801807400 09:52:33.571 [opensc-pkcs11] pkcs15-pin.c:690:sc_pkcs15_pincache_clear: called
0x801807400 09:52:33.571 [opensc-pkcs11] misc.c:61:sc_to_cryptoki_error_common: libopensc return value: 0 (Success)
0x801807400 09:52:33.571 [opensc-pkcs11] card.c:294:sc_disconnect_card: called
0x801807400 09:52:33.571 [opensc-pkcs11] reader-pcsc.c:506:pcsc_disconnect: called
0x801807400 09:52:33.627 [opensc-pkcs11] card.c:315:sc_disconnect_card: returning with: 0 (Success)
0x801807400 09:52:33.627 [opensc-pkcs11] ctx.c:799:sc_release_context: called
0x801807400 09:52:33.627 [opensc-pkcs11] reader-pcsc.c:747:pcsc_finish: called

@cesarkuroiwa
Copy link
Author

Hi
Just to add some new information, I recently made some new tests on my ubuntu 14.04 with the opensc package, which is on version 0.13.

Since pkcs11-tool still doesn't have the command '--decrypt' in this version, I used the openssl engine, and to my astonishment, it actually worked. So apparently there's something different with the new version 0.15.

# openssl 
OpenSSL> engine -t dynamic -pre SO_PATH:/usr/lib/ssl/engines/engine_pkcs11.so -pre LIST_ADD:1 -pre LOAD -pre MODULE_PATH:/usr/lib/x86_64-linux-gnu/opensc-pkcs11.so -pre VERBOSE
(dynamic) Dynamic engine loading support
[Success]: SO_PATH:/usr/lib/ssl/engines/engine_pkcs11.so
[Success]: LIST_ADD:1
[Success]: LOAD
[Success]: MODULE_PATH:/usr/lib/x86_64-linux-gnu/opensc-pkcs11.so
[Success]: VERBOSE
Loaded: (pkcs11) pkcs11 engine
initializing engine
     [ available ]
OpenSSL> rsautl  -encrypt -engine pkcs11 -keyform engine -inkey 1:6507 -pubin -in input.txt -out out.crypt
initializing engine
GOST engine already loaded
GOST engine already loaded
engine "pkcs11" set.
Looking in slot 1 for key: 6507
Found 2 slots
[18446744073709551615] Virtual hotplug slot       no tok          
[1] Gemalto PC Twin Reader 00  login             (OpenSC Card)
Found slot:  Gemalto PC Twin Reader 00 00
Found token: OpenSC Card
Found 0 certificate:
PKCS#11 token PIN: 
Found 1 key:
   1 P  Private Key
OpenSSL> rsautl -decrypt -engine pkcs11 -keyform engine -inkey 1:6507 -in out.crypt
engine "pkcs11" set.
Looking in slot 1 for key: 6507
Found 2 slots
[18446744073709551614] Virtual hotplug slot       no tok          
[1] Gemalto PC Twin Reader 00  login             (OpenSC Card)
Found slot:  Gemalto PC Twin Reader 00 00
Found token: OpenSC Card
Found 0 certificate:
Found 1 key:
   1 P  Private Key
testing opensc
OpenSSL> 

@dengert
Copy link
Member

dengert commented May 19, 2016

What might also be helpful is a opensc debug trace using the older OpenSC 0.11 that used to work for you if you still have a version of it.

On 5/19/2016 4:10 PM, cesarkuroiwa wrote:

Hi
Just to add some new information, I recently made some new tests on my ubuntu 14.04 with the opensc package, which is on version 0.13.

Since pkcs11-tool still doesn't have the command '--decrypt' in this version, I used the openssl engine, and to my astonishment, it actually worked. So apparently there's something different with the
new version 0.15.

|# openssl OpenSSL> engine -t dynamic -pre SO_PATH:/usr/lib/ssl/engines/engine_pkcs11.so -pre LIST_ADD:1 -pre LOAD -pre MODULE_PATH:/usr/lib/x86_64-linux-gnu/opensc-pkcs11.so -pre VERBOSE (dynamic)
Dynamic engine loading support [Success]: SO_PATH:/usr/lib/ssl/engines/engine_pkcs11.so [Success]: LIST_ADD:1 [Success]: LOAD [Success]: MODULE_PATH:/usr/lib/x86_64-linux-gnu/opensc-pkcs11.so
[Success]: VERBOSE Loaded: (pkcs11) pkcs11 engine initializing engine [ available ] OpenSSL> rsautl -encrypt -engine pkcs11 -keyform engine -inkey 1:6507 -pubin -in input.txt -out out.crypt
initializing engine GOST engine already loaded GOST engine already loaded engine "pkcs11" set. Looking in slot 1 for key: 6507 Found 2 slots [18446744073709551615] Virtual hotplug slot no tok [1]
Gemalto PC Twin Reader 00 login (OpenSC Card) Found slot: Gemalto PC Twin Reader 00 00 Found token: OpenSC Card Found 0 certificate: PKCS#11 token PIN: Found 1 key: 1 P Private Key OpenSSL> rsautl
-decrypt -engine pkcs11 -keyform engine -inkey 1:6507 -in out.crypt engine "pkcs11" set. Looking in slot 1 for key: 6507 Found 2 slots [18446744073709551614] Virtual hotplug slot no tok [1] Gemalto PC
Twin Reader 00 login (OpenSC Card) Found slot: Gemalto PC Twin Reader 00 00 Found token: OpenSC Card Found 0 certificate: Found 1 key: 1 P Private Key testing opensc OpenSSL> |


You are receiving this because you commented.
Reply to this email directly or view it on GitHub #765 (comment)

Douglas E. Engert [email protected]

@cesarkuroiwa
Copy link
Author

Unfortunately, I don't have the trace from version 0.11, but what I could get is the trace from the working test with version 0.13, using openssl engine:

0x7f60da448740 18:32:20.650 [opensc-pkcs11] pkcs11-session.c:259:C_Login: C_Login(0x1fe4150, 1)
0x7f60da448740 18:32:20.650 [opensc-pkcs11] pkcs15-pin.c:293:sc_pkcs15_verify_pin: called
0x7f60da448740 18:32:20.650 [opensc-pkcs11] pkcs15-pin.c:294:sc_pkcs15_verify_pin: PIN(0x1fe41b0;len:6)
0x7f60da448740 18:32:20.650 [opensc-pkcs11] pkcs15-pin.c:295:sc_pkcs15_verify_pin: Auth(type:0;method:1)
0x7f60da448740 18:32:20.650 [opensc-pkcs11] pkcs15-pin.c:299:sc_pkcs15_verify_pin: PIN value validated
0x7f60da448740 18:32:20.650 [opensc-pkcs11] card.c:315:sc_lock: called
0x7f60da448740 18:32:20.650 [opensc-pkcs11] reader-pcsc.c:517:pcsc_lock: called
0x7f60da448740 18:32:20.650 [opensc-pkcs11] card.c:610:sc_select_file: called; type=2, path=3f005015
0x7f60da448740 18:32:20.650 [opensc-pkcs11] card-starcos.c:368:starcos_select_file: called
0x7f60da448740 18:32:20.651 [opensc-pkcs11] card-starcos.c:378:starcos_select_file: current path (path, valid): 3f005015 (len: 4)
0x7f60da448740 18:32:20.651 [opensc-pkcs11] card-starcos.c:471:starcos_select_file: cache hit
0x7f60da448740 18:32:20.651 [opensc-pkcs11] card.c:638:sc_select_file: returning with: 0 (Success)
0x7f60da448740 18:32:20.651 [opensc-pkcs11] sec.c:157:sc_pin_cmd: called
0x7f60da448740 18:32:20.651 [opensc-pkcs11] apdu.c:687:sc_transmit_apdu: called
0x7f60da448740 18:32:20.651 [opensc-pkcs11] card.c:315:sc_lock: called
0x7f60da448740 18:32:20.651 [opensc-pkcs11] apdu.c:654:sc_transmit: called
0x7f60da448740 18:32:20.651 [opensc-pkcs11] apdu.c:509:sc_single_transmit: called
0x7f60da448740 18:32:20.651 [opensc-pkcs11] apdu.c:514:sc_single_transmit: CLA:0, INS:20, P1:0, P2:83, data(8) 0x7fff8b660be0
0x7f60da448740 18:32:20.651 [opensc-pkcs11] reader-pcsc.c:249:pcsc_transmit: reader 'Gemalto PC Twin Reader 00 00'
0x7f60da448740 18:32:20.651 [opensc-pkcs11] apdu.c:185:sc_apdu_log: 
Outgoing APDU data [   13 bytes] =====================================
00 20 00 83 08 31 32 33 34 35 36 00 00 . ...123456..
======================================================================
0x7f60da448740 18:32:20.651 [opensc-pkcs11] reader-pcsc.c:182:pcsc_internal_transmit: called
0x7f60da448740 18:32:20.766 [opensc-pkcs11] apdu.c:185:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x7f60da448740 18:32:20.766 [opensc-pkcs11] apdu.c:524:sc_single_transmit: returning with: 0 (Success)
0x7f60da448740 18:32:20.766 [opensc-pkcs11] apdu.c:676:sc_transmit: returning with: 0 (Success)
0x7f60da448740 18:32:20.766 [opensc-pkcs11] card.c:353:sc_unlock: called
0x7f60da448740 18:32:20.766 [opensc-pkcs11] card-starcos.c:1232:starcos_check_sw: sw1 = 0x90, sw2 = 0x00
0x7f60da448740 18:32:20.766 [opensc-pkcs11] sec.c:204:sc_pin_cmd: returning with: 0 (Success)
0x7f60da448740 18:32:20.766 [opensc-pkcs11] pkcs15-pin.c:367:sc_pkcs15_verify_pin: PIN cmd result 0
0x7f60da448740 18:32:20.766 [opensc-pkcs11] pkcs15-pin.c:590:sc_pkcs15_pincache_add: called
0x7f60da448740 18:32:20.766 [opensc-pkcs11] pkcs15-pin.c:630:sc_pkcs15_pincache_add: PIN() cached
0x7f60da448740 18:32:20.766 [opensc-pkcs11] card.c:353:sc_unlock: called
0x7f60da448740 18:32:20.766 [opensc-pkcs11] reader-pcsc.c:554:pcsc_unlock: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs15-pin.c:372:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x7f60da448740 18:32:20.774 [opensc-pkcs11] framework-pkcs15.c:1464:pkcs15_login: PKCS15 verify PIN returned 0
0x7f60da448740 18:32:20.774 [opensc-pkcs11] framework-pkcs15.c:1473:pkcs15_login: Check if pkcs15 object list can be completed.
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:342:C_FindObjectsInit: C_FindObjectsInit(slot = 1)
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:343:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = CKO_PRIVATE_KEY
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:138:session_start_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:139:session_start_operation: Session 0x1fe4150, type 0
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:364:C_FindObjectsInit: Object with handle 0x1fd76b0
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:390:C_FindObjectsInit: Object 1/33388208: Attribute 0x0 matches.
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:395:C_FindObjectsInit: Object 1/33388208 matches
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:399:C_FindObjectsInit: realloc for 32 handles
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:364:C_FindObjectsInit: Object with handle 0x1fd7e80
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:383:C_FindObjectsInit: Object 1/33390208: Attribute 0x0 does NOT match.
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:412:C_FindObjectsInit: 1 matching objects
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:160:session_get_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_KEY_TYPE = CKK_RSA
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_LABEL = Private Key
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_ID = 6507
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_ID = 6507
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:160:session_get_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:160:session_get_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:58:sc_find_release: freeing 32 handles used 1  at 0x1fe42c0
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:342:C_FindObjectsInit: C_FindObjectsInit(slot = 1)
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:343:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = CKO_PUBLIC_KEY
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:138:session_start_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:139:session_start_operation: Session 0x1fe4150, type 0
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:364:C_FindObjectsInit: Object with handle 0x1fd76b0
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:383:C_FindObjectsInit: Object 1/33388208: Attribute 0x0 does NOT match.
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:364:C_FindObjectsInit: Object with handle 0x1fd7e80
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:390:C_FindObjectsInit: Object 1/33390208: Attribute 0x0 matches.
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:395:C_FindObjectsInit: Object 1/33390208 matches
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:399:C_FindObjectsInit: realloc for 32 handles
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:412:C_FindObjectsInit: 1 matching objects
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:160:session_get_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33390208: CKA_KEY_TYPE = CKK_RSA
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd7e80) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33390208: CKA_LABEL = Public Key
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd7e80) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33390208: CKA_ID = 6507
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd7e80) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33390208: CKA_ID = 6507
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd7e80) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:160:session_get_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] misc.c:160:session_get_operation: called
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:58:sc_find_release: freeing 32 handles used 1  at 0x1fe42c0
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_SENSITIVE = TRUE
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_EXTRACTABLE = FALSE
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] framework-pkcs15.c:3173:pkcs15_prkey_get_attribute: use friend public key data 0x1fd7770
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_MODULUS = B4DF3A3120CE557C938A1E76EDC5BA7421F261CC75EA67D7B057EBC521E9E3C5
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.774 [opensc-pkcs11] framework-pkcs15.c:3173:pkcs15_prkey_get_attribute: use friend public key data 0x1fd7770
0x7f60da448740 18:32:20.774 [opensc-pkcs11] pkcs11-object.c:243:C_GetAttributeValue: Object 33388208: CKA_PUBLIC_EXPONENT = 010001
0x7f60da448740 18:32:20.775 [opensc-pkcs11] pkcs11-object.c:265:C_GetAttributeValue: C_GetAttributeValue(hSession=0x1fe4150, hObject=0x1fd76b0) = CKR_OK
0x7f60da448740 18:32:20.775 [opensc-pkcs11] misc.c:138:session_start_operation: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] misc.c:139:session_start_operation: Session 0x1fe4150, type 4
0x7f60da448740 18:32:20.775 [opensc-pkcs11] pkcs11-object.c:903:C_DecryptInit: C_DecryptInit() = CKR_OK
0x7f60da448740 18:32:20.775 [opensc-pkcs11] misc.c:160:session_get_operation: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] framework-pkcs15.c:3453:pkcs15_prkey_decrypt: Initiating decryption.
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card.c:315:sc_lock: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] reader-pcsc.c:517:pcsc_lock: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] pkcs15-sec.c:93:sc_pkcs15_decipher: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] padding.c:273:sc_get_encoding_flags: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] padding.c:277:sc_get_encoding_flags: iFlags 0x2, card capabilities 0x800001FA
0x7f60da448740 18:32:20.775 [opensc-pkcs11] padding.c:306:sc_get_encoding_flags: pad flags 0x0, secure algorithm flags 0x2
0x7f60da448740 18:32:20.775 [opensc-pkcs11] padding.c:307:sc_get_encoding_flags: returning with: 0 (Success)
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card.c:315:sc_lock: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] pkcs15-sec.c:42:select_key_file: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card.c:610:sc_select_file: called; type=2, path=3f005015
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card-starcos.c:368:starcos_select_file: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card-starcos.c:378:starcos_select_file: current path (path, valid): 3f005015 (len: 4)
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card-starcos.c:471:starcos_select_file: cache hit
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card.c:638:sc_select_file: returning with: 0 (Success)
0x7f60da448740 18:32:20.775 [opensc-pkcs11] pkcs15-sec.c:78:select_key_file: returning with: 0 (Success)
0x7f60da448740 18:32:20.775 [opensc-pkcs11] sec.c:66:sc_set_security_env: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] apdu.c:687:sc_transmit_apdu: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] card.c:315:sc_lock: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] apdu.c:654:sc_transmit: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] apdu.c:509:sc_single_transmit: called
0x7f60da448740 18:32:20.775 [opensc-pkcs11] apdu.c:514:sc_single_transmit: CLA:0, INS:22, P1:81, P2:B8, data(6) 0x7fff8b662c70
0x7f60da448740 18:32:20.775 [opensc-pkcs11] reader-pcsc.c:249:pcsc_transmit: reader 'Gemalto PC Twin Reader 00 00'
0x7f60da448740 18:32:20.775 [opensc-pkcs11] apdu.c:185:sc_apdu_log: 
Outgoing APDU data [   11 bytes] =====================================
00 22 81 B8 06 84 01 91 80 01 02 .".........
======================================================================
0x7f60da448740 18:32:20.775 [opensc-pkcs11] reader-pcsc.c:182:pcsc_internal_transmit: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:185:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:524:sc_single_transmit: returning with: 0 (Success)
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:676:sc_transmit: returning with: 0 (Success)
0x7f60da448740 18:32:20.788 [opensc-pkcs11] card.c:353:sc_unlock: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] sec.c:70:sc_set_security_env: returning with: 0 (Success)
0x7f60da448740 18:32:20.788 [opensc-pkcs11] sec.c:38:sc_decipher: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] iso7816.c:836:iso7816_decipher: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:687:sc_transmit_apdu: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] card.c:315:sc_lock: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:654:sc_transmit: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:509:sc_single_transmit: called
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:514:sc_single_transmit: CLA:0, INS:2A, P1:80, P2:86, data(129) 0x1fe4f90
0x7f60da448740 18:32:20.788 [opensc-pkcs11] reader-pcsc.c:249:pcsc_transmit: reader 'Gemalto PC Twin Reader 00 00'
0x7f60da448740 18:32:20.788 [opensc-pkcs11] apdu.c:185:sc_apdu_log: 
Outgoing APDU data [  135 bytes] =====================================
00 2A 80 86 81 00 64 04 ED 5E 84 7D 98 BA 73 14 .*....d..^.}..s.
E8 54 51 21 D6 2C 80 4C C2 2C D5 1C FC B1 31 67 .TQ!.,.L.,....1g
ED D5 DA 0F AB 00 DA A4 F8 00 98 1F 33 B8 26 27 ............3.&'
99 E0 C0 F4 E9 CB 4D 97 69 FF A3 F5 04 3B 37 A1 ......M.i....;7.
D0 CC F7 1D 2E B2 2F 55 20 4D D6 FF 06 DC 69 CD ....../U M....i.
07 8C 28 C4 FB BE 40 06 86 D9 01 97 F6 06 E4 7C ..(...@........|
20 66 94 0A 98 32 0C 2C 98 BA 92 D7 38 AA 5D 6F  f...2.,....8.]o
51 31 B2 98 B4 7A C9 88 78 E8 26 F6 63 A5 3E E1 Q1...z..x.&.c.>.
16 C1 B4 BA DB 6C 00                            .....l.
======================================================================
0x7f60da448740 18:32:20.788 [opensc-pkcs11] reader-pcsc.c:182:pcsc_internal_transmit: called
0x7f60da448740 18:32:21.178 [opensc-pkcs11] apdu.c:185:sc_apdu_log: 
Incoming APDU data [   17 bytes] =====================================
74 65 73 74 69 6E 67 20 6F 70 65 6E 73 63 0A 90 testing opensc..
00                                              .
======================================================================
0x7f60da448740 18:32:21.178 [opensc-pkcs11] apdu.c:524:sc_single_transmit: returning with: 0 (Success)
0x7f60da448740 18:32:21.178 [opensc-pkcs11] apdu.c:676:sc_transmit: returning with: 0 (Success)
0x7f60da448740 18:32:21.178 [opensc-pkcs11] card.c:353:sc_unlock: called
0x7f60da448740 18:32:21.178 [opensc-pkcs11] iso7816.c:866:iso7816_decipher: returning with: 15
0x7f60da448740 18:32:21.178 [opensc-pkcs11] sec.c:42:sc_decipher: returning with: 15
0x7f60da448740 18:32:21.178 [opensc-pkcs11] card.c:353:sc_unlock: called
0x7f60da448740 18:32:21.178 [opensc-pkcs11] pkcs15-sec.c:176:sc_pkcs15_decipher: returning with: 15
0x7f60da448740 18:32:21.178 [opensc-pkcs11] card.c:353:sc_unlock: called
0x7f60da448740 18:32:21.178 [opensc-pkcs11] reader-pcsc.c:554:pcsc_unlock: called
0x7f60da448740 18:32:21.185 [opensc-pkcs11] framework-pkcs15.c:3495:pkcs15_prkey_decrypt: Decryption complete. Result 15.
0x7f60da448740 18:32:21.185 [opensc-pkcs11] pkcs11-object.c:926:C_Decrypt: C_Decrypt() = CKR_OK

@dengert
Copy link
Member

dengert commented May 19, 2016

Also can you run pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so -O
with both the old and new versions of OpenSC to see if they see the same object ids.

@mouse07410
Copy link
Contributor

mouse07410 commented May 19, 2016

I'm not sure what's wrong with the OP's installation, but here's what I observe:

$ opensc-tool --version
OpenSC-0.16.0-rc2, rev: db54dd8, commit-time: 2016-05-16 11:55:36 +0200
$ pkcs11-rsa-encr-demo
Generating random file for this test...
openssl enc -a -e -salt -in /tmp/derive.19080.file.txt -out /tmp/derive.19080.file.txt.enc -kfile /tmp/derive.19080.pass.plain
pkcs15-tool --read-certificate 03 -o /tmp/derive.19080.enc.cert
Using reader with a card: Gemalto Prox Dual USB PC Link Reader(2)
openssl rsautl -encrypt -in /tmp/derive.19080.pass.plain -out /tmp/derive.19080.pass.enc    -inkey /tmp/derive.19080.enc.cert -keyform PEM -certin
pkcs11-tool --module /Library/OpenSC/lib/opensc-pkcs11.so --decrypt -m RSA-PKCS --id 03 -i /tmp/derive.19080.pass.enc -o /tmp/derive.19080.pass.dec
Using slot 1 with a present token (0x4)
Logging in to "PIV_II (PIV Card Holder pin)".
Please enter User PIN: 
Using decrypt algorithm RSA-PKCS
openssl enc -a -d -salt -in /tmp/derive.19080.file.txt.enc -out /tmp/derive.19080.file.txt.dec -kfile /tmp/derive.19080.pass.dec
Original and decrypted keys  match
Original and decrypted files match
$

It may be complicated needlessly, but still demonstrates the basic functionality.

I get the same successful results with the current master.

@dengert
Copy link
Member

dengert commented May 19, 2016

Problem appears to be related to card-starcos.c:
149 /* we need read_binary&friends with max 128 bytes per read */
150 card->max_send_size = 128;
151 card->max_recv_size = 128;
152 }

The 2 traces sent are only partial traces, and so the max_send_size and max_recv_size
are not shown in either trace.

With card->max_send_size=128 it looks like apdu.c tries to use chaining
apdu.c:389:sc_single_transmit: CLA:10, INS:2A, P1:80, P2:86, data(128) 0x801821740
With status words 67:00, looks like chaining may not be supported.

in the older version that worked, the APDU sent was:
apdu.c:514:sc_single_transmit: CLA:0, INS:2A, P1:80, P2:86, data(129) 0x1fe4f90
No chaining and (CLA:00) the data is 129 bytes.

based in the comments to fix read_binary, setting max_send and max_recv_size may be the wrong way to fix read_binary.

@frankmorgner @viktorTarasov We have made changes recently to how max_send_size and max_recv_size are handled. Does card-startcos.c need to be updated?

@frankmorgner
Copy link
Member

It's very likely that max_send_size and max_recv_size need to be correctly initialized. Does someone have an up to date manual for that card?

@frankmorgner
Copy link
Member

@cesarkuroiwa you still have not given the type of card you are using. We don't even know which ATR it has.

@cesarkuroiwa
Copy link
Author

Hi guys
Sorry I've been away for a while and thanks a lot for all the attention

I'm not sure if this will be helpful, but here goes some info on the reader and card:

% opensc-tool -i
OpenSC 0.15.0 [gcc  4.7.4]
Enabled features: zlib readline openssl pcsc(libpcsclite.so.1)

% opensc-tool -a
Using reader with a card: Gemalto PC Twin Reader 00 00
3b:b7:18:00:c0:3e:31:fe:65:53:50:4b:32:34:90:00:25

% opensc-tool -l
# Detected readers (pcsc)
Nr.  Card  Features  Name
0    Yes             Gemalto PC Twin Reader 00 00

@dengert
Copy link
Member

dengert commented May 20, 2016

The ATR maps to SC_CARD_TYPE_STARCOS_GENERIC. But e-mail from 2006 indicates the
ATR is for SPK 2.4, but the SPK 2.3 code is being used to avoid having to change code.

The max_send_size = 128 was in the code as of 0.11.2 (oldest tag is git).

The driver uses the iso7816.c for many functions and the iso7816.c fixup_transceive_length() will use sc_get_max_send_size(card) and set SC_APDU_FLAGS_CHAINING if needed. That appears to be what is happening with the decrypt operation and the card can not handle chaining or a length of 128 with decrypt. The card had no problem with length 129 with pass versions of OpenSC so the
max_send_size for a crypto operation is not limited to 128 by the card.

Many older card drivers set max_send_size. (card-atrust-acos.c and card-miocos.c have comments about limiting read and write binary.) It looks like in the past, this may have been to control the size used with read and write binary, but not to control the size of a crypto operation. But with newer OpenSC code the meaning of max_send_size is now being applied to the crypto operations too. This appears to be the source of the current problem.

sc_write_binary() will use sc_get_max_send_size(card) and break up a write_binary into multiple smaller operations.

Do we need a max_send_binary_size and max_recv_binary_size that only used by sc_read_binary and sc_write_binary. These could be less then the max_send_size and max_recv_size?

@frankmorgner
Copy link
Member

If that's the case, one solution for starcos would be to set max_send_size/max_recv_size only when entering starcos' read/write binary and to reset it when exiting the two functions.

However,. I'd prefer checking the manual over fishing in troubled waters.

@dengert
Copy link
Member

dengert commented May 25, 2016

I think think there may be more troubled waters then just this card. There are 12 other card drivers
that set max_send_size and/or max_receive_size, and have simiiar problems.

dengert@82d6891

is an attempt to setup a framework to solve the problem for all 13 drivers. It is only addressing the card-statrcos.c for now. It needs to be tested.

https://github.com/cesarkuroiwa can you try this and see if it fixes your problem?
Can you run any test that will do a read binary, for example reading a certificate. You may need to look at the opensc-debug.log to see if the read is really limited to 128.

@cesarkuroiwa
Copy link
Author

Hi
Just to give a small update of what we've noticed in our tests with different versions of opensc, it seems that it stopped working on version 0.15.
On versions 0.13 and 0.14, the decrypt operations that we tested worked fine, apparently

@frankmorgner
Copy link
Member

@cesarkuroiwa It would be nice if you could track down the problem to a specific commit, e.g. with git bisect

@frankmorgner
Copy link
Member

@dengert we still need to figure out what the actual problem is, here, before applying any fixes. From a card's perspective it simply does not make much sense to have a low limit for incoming/outgoing data of a read binary, but to have a high limit for signature creation or for deciphering.

I suspect that @cesarkuroiwa 's card could safely choose a higher value of max_send_size/max_recv_size. And I suspect that there is a starcos APDU to find out the actual limit.

@dengert
Copy link
Member

dengert commented May 25, 2016

On 5/25/2016 3:35 PM, Frank Morgner
  wrote:


  @dengert we still need to figure out
    what the actual problem is, here, before applying any fixes.
    From a card's perspective it simply does not make much sense to
    have a low limit for incoming/outgoing data of a read binary,
    but to have a high limit for signature creation or for
    deciphering.


Using git bisect would be helpful, as would reading the manual. But
when did anything smart card vendors do made much sense :-) 

4 drivers have similar comments about read_binary restrictions:

$grep friends card-*
card-atrust-acos.c:    /* we need read_binary&friends with max
128 bytes per read */
card-entersafe.c:    /* we need read_binary&friends with max 224
bytes per read */
card-miocos.c:    /* read_binary and friends shouldn't do more than
244 bytes
card-starcos.c:        /* we need read_binary&friends with max
128 bytes per read */

17 card drivers  set odd sizes and even one comment on contradicting
the manual!  

$ grep "max_.*_size.*=" card-*
card-acos5.c:    card->max_recv_size = 128;
card-acos5.c:    card->max_send_size = 128;
card-akis.c:    card->max_recv_size = 244;
card-akis.c:    card->max_send_size = 244;
card-atrust-acos.c:    card->max_send_size = 128;
card-atrust-acos.c:    card->max_recv_size = 128;
card-authentic.c:        card->max_send_size = 255;
card-authentic.c:    card->max_send_size = save_max_send;
card-authentic.c:    if (card->sm_ctx.sm_mode == SM_MODE_TRANSMIT
&& card->max_send_size == 0)
card-authentic.c:        card->max_send_size = 239;
card-cardos.c:        card->max_send_size = data_field_length -
6;
card-cardos.c:        card->max_send_size = data_field_length -
3;
card-cardos.c:    card->max_recv_size = data_field_length - 2;
card-dnie.c:    card->max_send_size = (255 - 12);    /* manual
says 255, but we need 12 extra bytes when encoding */
card-dnie.c:    card->max_recv_size = 255;
card-entersafe.c:    card->max_send_size = 224;
card-entersafe.c:    card->max_recv_size = 224;
card-epass2003.c:    card->max_recv_size = 0xD8;
card-epass2003.c:    card->max_send_size = 0xE8;
card-gpk.c:    card->max_recv_size = 252;
card-iasecc.c:    card->max_send_size = sizes->send;
card-iasecc.c:    card->max_recv_size = sizes->recv;
card-iasecc.c:        card->max_send_size -= 5;
card-miocos.c:    card->max_send_size = 244;
card-miocos.c:    card->max_recv_size = 244;
card-myeid.c:    card->max_recv_size = 255;
card-myeid.c:    card->max_send_size = 255;
card-openpgp.c:                priv->max_challenge_size =
bebytes2ushort(blob->data + 2);
card-openpgp.c:                priv->max_cert_size =
bebytes2ushort(blob->data + 4);
card-openpgp.c:                card->max_send_size =
bebytes2ushort(blob->data + 6);
card-openpgp.c:                card->max_recv_size =
bebytes2ushort(blob->data + 8);
card-sc-hsm.c:        card->max_send_size = 248;        // 255 -
7 because of TLV in odd ins UPDATE BINARY
card-sc-hsm.c:    card->max_send_size = 1431;        // 1439
buffer size - 8 byte TLV because of odd ins in UPDATE BINARY
card-sc-hsm.c:    card->max_recv_size = 0;        // Card
supports sending with extended length APDU and without limit
card-starcos.c:        card->max_write_binary_size = 128;   (with
my mod)
card-starcos.c:        card->max_read_binary_size = 128;    (with
my mod)
card-westcos.c:    card->max_send_size = 240;
card-westcos.c:    card->max_recv_size = 240;


and it looks like my mod should also change in sc_update_binary and
sc_erase_binary.




  I suspect that @c



  esarkuroiwa
    's card could safely choose a higher value of max_send_size/max_recv_size.
    And I suspect that there is a starcos APDU to find out the
    actual limit.
  —
    You are receiving this because you were mentioned.
    Reply to this email directly or view
      it on GitHub









-- 

Douglas E. Engert [email protected]

@hkkobayashi
Copy link

@dengert [Cesar and I work together]
I applied your patch to version 0.15.0 and it worked!

% pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -v --input-file out.crypt --id 9352 -l
Using slot 1 with a present token (0x1)
Logging in to "OpenSC Card".
Please enter User PIN: 
Using decrypt algorithm RSA-PKCS
1234567890 1234567890 1234567890 1234567890

I've also tried it against 0.16.0rc1 and it printed a different error message:

% pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -v --input-file out.crypt --id 9352 -l
Using slot 0 with a present token (0x0)
Logging in to "OpenSC Card".
Please enter User PIN: 
error: PKCS11 function C_Login failed: rv = CKR_FUNCTION_NOT_SUPPORTED (0x54)

Aborting.

@dengert
Copy link
Member

dengert commented May 25, 2016

On 5/25/2016 6:08 PM, hkkobayashi
  wrote:


  @dengert [Cesar and I work together]

    I applied your patch
    to version 0.15.0 and it worked!
  % pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -v --input-file out.crypt --id 9352 -l

Using slot 1 with a present token (0x1)
Logging in to "OpenSC Card".
Please enter User PIN:
Using decrypt algorithm RSA-PKCS
1234567890 1234567890 1234567890 1234567890

  I've also tried it against 0.16.0rc1 and it printed a different
    error message:
  % pkcs11-tool --module /usr/local/lib/opensc-pkcs11.so --decrypt -v --input-file out.crypt --id 9352 -l

Using slot 0 with a present token (0x0)
Logging in to "OpenSC Card".
Please enter User PIN:
error: PKCS11 function C_Login failed: rv = CKR_FUNCTION_NOT_SUPPORTED (0x54)

Aborting.

getting a opensc-debug output would help:

https://github.com/OpenSC/OpenSC/wiki/Using-OpenSC

Also please try patch against: 

https://github.com/OpenSC/OpenSC/tree/towards-opensc-0.16.0





  —
    You are receiving this because you were mentioned.
    Reply to this email directly or view
      it on GitHub









-- 

Douglas E. Engert [email protected]

@hkkobayashi
Copy link

@dengert Debug output for patched 0.16.0rc1 and patched towards-0.16.0 are available: opensc-debug-0.16.0rc1.log opensc-debug-towards-0.16.0.log

@dengert
Copy link
Member

dengert commented May 26, 2016

The read_binary using 128 looks like it worked.

card-starcos.c:1709:starcos_pin_cmd: only supported for STARCOS 3.4 cards

CHECK_ONLY_SUPPORTED_V3_4(card);

This looks like it should not be here.

19bbfc7
implemented a starcos_pin_cmd(). It looked like previous versions just used the default iso_dvr pin_cmd. The new code in effect will only work for 3.4 cards, and fail for all older cards.

https://github.com/fancycode can you suggest a fix for this problem?

What is different abont a pin_cmd and a 3.4 pin_cmd?

@viktorTarasov
Copy link
Member

viktorTarasov commented May 26, 2016

@cesarkuroiwa @hkkobayashi Could you try decipher without fixing-transceive-length (comment in the line https://github.com/OpenSC/OpenSC/blob/towards-opensc-0.16.0/src/libopensc/iso7816.c#L952) ?
Use, please, towards-0.16.0 branch.

Afaik, earlier, the decision to use APDU-CHAIN was made on the card driver level,
not in the common ISO part, as it now implemented.

@viktorTarasov
Copy link
Member

I pushed to towards_0.16.0 few debug messages more.

@cesarkuroiwa @hkkobayashi Now for the decipher test the line to comment in is https://github.com/OpenSC/OpenSC/blob/towards-opensc-0.16.0/src/libopensc/iso7816.c#L955

@dengert
Copy link
Member

dengert commented May 26, 2016

What about line:
https://github.com/OpenSC/OpenSC/blob/towards-opensc-0.16.0/src/libopensc/iso7816.c#L911
in iso7816_compute_signature should that be removed too?

@viktorTarasov
Copy link
Member

@dengert I think yes. Will be waiting for test results from @cesarkuroiwa and @hkkobayashi.

@frankmorgner
Copy link
Member

@cesarkuroiwa could you please check whether #765 retrieves the correct maximum of the transceive length for your card?

@cesarkuroiwa
Copy link
Author

@frankmorgner, I am not very intimate with the inner workings of OpenSC, so I have to say I don't understand much of what you're saying.

What I can say is that we're currently running @dengert 's patch on top of release 0.15, and it seems to be working fine.

@frankmorgner
Copy link
Member

I have a starcos card that announces its io buffer length in EF.ATR. With #765 this value is taken for max_send_size/max_receive_size. If you card supports extended length, this should fix your problem, @cesarkuroiwa.

@frankmorgner
Copy link
Member

(Found this hint in my manual, actually)

@frankmorgner
Copy link
Member

@cesarkuroiwa, sorry, I posted a bad link. Please check whether #812 gets the correct length of IO buffers for your card (82d6891 should not be needed anymore).

@gabrielmuller
Copy link
Contributor

gabrielmuller commented Oct 4, 2018

This solution doesn't seem to work with STARCOS SPK 2.3, which needs more than 128 bytes (129 for decryption), but doesn't have an EF.ATR file (verbose logs show Cannot select EF(ATR) file: -1201 (File not found)). This means I can't use the PKCS15 decipher functionality with 2.3 in the most recent version. I have been able to make it work temporarily by increasing the max send size to 129 bytes and changing Le to 0x00.

I'm thinking of two possible ways to properly fix this:

  • Add a more specific label for this card, something like SC_CARD_TYPE_STARCOS_V2_3 instead of SC_CARD_TYPE_STARCOS_GENERIC, and manually set the max send size to something that works in practice.
  • Find out how 2.3 works in order to implement a more robust solution. I have no manuals, so any insight here would be appreciated.

I have attached two logs, one running in 0.11.4 where the decryption is successful, another in 0.19 which fails because the data field is 128 bytes instead of 129.
11.log
19.log

Any thoughts?

frankmorgner added a commit to frankmorgner/OpenSC that referenced this issue Oct 5, 2018
frankmorgner added a commit to frankmorgner/OpenSC that referenced this issue Oct 5, 2018
@frankmorgner
Copy link
Member

@gabrielmuller please try #1496

@gabrielmuller
Copy link
Contributor

#1496 almost works. It sends 129 bytes of data, but there are some problems:

  • There's a stray else at line 1689 that has to be removed
  • Le probably needs to be zero, otherwise the card throws Wrong length. I hard-coded it to apdu.le = 256 after the fixup_transceive_length() call and it works.

I'm not sure why the card expects response length zero (or is it 256?) so I'll leave the fix to your best judgement. I've included a log with Le = 0x00 which works and one with the default Le size (max recv size, or 0x80), which doesn't.
works.txt
wrong_length.txt

frankmorgner added a commit to frankmorgner/OpenSC that referenced this issue Oct 8, 2018
@frankmorgner
Copy link
Member

@gabrielmuller should work now

@gabrielmuller
Copy link
Contributor

Wrong length again, this time I believe because it's sending Lc in three bytes and Le in two. Here's the relevant part:

0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] apdu.c:390:sc_single_transmit: returning with: 0 (Success)
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] apdu.c:543:sc_transmit: returning with: 0 (Success)
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] card.c:465:sc_unlock: called
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] sec.c:79:sc_set_security_env: returning with: 0 (Success)
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] sec.c:43:sc_decipher: called
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] iso7816.c:976:iso7816_decipher: called
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] iso7816.c:979:iso7816_decipher: ISO7816 decipher: in-len 128, out-len 1024
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] apdu.c:554:sc_transmit_apdu: called
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] card.c:415:sc_lock: called
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] card.c:455:sc_lock: returning with: 0 (Success)
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] apdu.c:521:sc_transmit: called
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] apdu.c:371:sc_single_transmit: called
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] apdu.c:378:sc_single_transmit: CLA:0, INS:2A, P1:80, P2:86, data(129) 0x5575d8373810
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] reader-pcsc.c:284:pcsc_transmit: reader 'Gemalto PC Twin Reader (9E282F27) 00 00'
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] reader-pcsc.c:285:pcsc_transmit: 
Outgoing APDU (138 bytes):
00 2A 80 86 00 00 81 00 88 0A BA 72 4A 1F CA C9 .*.........rJ...
AA B2 E3 75 DD F8 0B D4 57 0C 24 83 F7 69 2C 6B ...u....W.$..i,k
2D 31 55 A0 8C 20 10 31 9D 3B 55 87 45 2D 80 FF -1U.. .1.;U.E-..
91 5F 26 6E 02 15 57 59 37 D0 4D 4D FA 53 9B 36 ._&n..WY7.MM.S.6
9B 56 DB 59 F0 F8 1F 53 05 57 CB 80 14 F2 BD 90 .V.Y...S.W......
35 BC A2 93 EA AF F2 FC 78 E4 30 01 12 D0 51 17 5.......x.0...Q.
E4 15 6C 8E ED 1C F4 A9 E9 67 F3 4E B3 E4 06 91 ..l......g.N....
31 92 7F 29 34 D1 AF 9F 8C 55 96 7C 9D CD EB E6 1..)4....U.|....
E4 99 17 39 DB 9B F8 A3 04 00                   ...9......
0x7fefdf74c180 09:34:20.188 [pkcs15-crypt] reader-pcsc.c:213:pcsc_internal_transmit: called
0x7fefdf74c180 09:34:20.216 [pkcs15-crypt] reader-pcsc.c:294:pcsc_transmit: 
Incoming APDU (2 bytes):
67 00 g.

@gabrielmuller
Copy link
Contributor

Changing outlen from 1024 to 256 fixes this. What do you think?

@frankmorgner
Copy link
Member

I think the problem is that extended length is not supported, I've adapted the pull request...

@gabrielmuller
Copy link
Contributor

Now it's failing sc_check_apdu:

0x7f3ea6fe8180 10:34:23.124 [pkcs15-crypt] iso7816.c:979:iso7816_decipher: ISO7816 decipher: in-len 128, out-len 1024
0x7f3ea6fe8180 10:34:23.124 [pkcs15-crypt] apdu.c:554:sc_transmit_apdu: called
0x7f3ea6fe8180 10:34:23.124 [pkcs15-crypt] apdu.c:261:sc_check_apdu: failed length check for short APDU
0x7f3ea6fe8180 10:34:23.124 [pkcs15-crypt] apdu.c:339:sc_check_apdu: Invalid Case 4 short APDU:
cse=04 cla=00 ins=2a p1=80 p2=86 lc=129 le=1024
resp=0x7ffe5750bee0 resplen=1024 data=0x55a1c4022810 datalen=129
0x7f3ea6fe8180 10:34:23.124 [pkcs15-crypt] iso7816.c:1003:iso7816_decipher: APDU transmit failed: -1300 (Invalid arguments)
0x7f3ea6fe8180 10:34:23.124 [pkcs15-crypt] card-starcos.c:1707:starcos_decipher: returning with: -1300 (Invalid arguments)

This 1024 value comes from pkcs15-crypt.c:decipher and gets passed down until a consistency check fails. Is there a reason for it to be 1024?

@dengert
Copy link
Member

dengert commented Oct 10, 2018

pkcs15-crypt.c is passing in a 1024 byte buffer, big enough for any decipher. (8192 bit RSA for example).
It is has not determined the size. The max RSA key size registered by card-starcos.c is 2048 bits so max data returned would be 256 bytes.

So to handle a 2048 bit RSA key and send the padding byte would require 257 bytes. The card must then support either extended APDU or command chaining. It may depend on the card, so this comment may be wrong:

/* Starcos doesn't support chaining for PSO:DEC, so we just _hope_
1670                          * that both, the reader and the card are able to send enough data.
1671                          * (data is prefixed with 1 byte padding content indicator) */
Invalid Case 4 short APDU:
cse=04 cla=00 ins=2a p1=80 p2=86 lc=129 le=1024

says opensc did not like the apdu, as it says it is a short APDU, so lc and le are limited to 255 and 256

@gabrielmuller
Copy link
Contributor

Here's something that works:

  • When max_recv_size < outlen, instead of changing max_recv_size to outlen, change outlen to the max (because apparently outlen was set to 1024 and never changed from its default value, so it shouldn't hurt to change it.)

  • Change the initial 2.3 max_recv_size from 128 to 256.

Is this a sensible solution?

@dengert
Copy link
Member

dengert commented Oct 10, 2018

It may for your card, but break others. The driver can support many cards some older some newer.
Look at starcos_init to see what it does with max_recv_size. It looks like it set the max_recv_sive to 128 becauses of some read binary restriction and the max RSA key size of your card appears to be 1024 bits. So we are back to 2016 were the read binary restriction sill have not been addressed.

I do not have any of these cards.

Frank has made many changes which make sense.

@frankmorgner
Copy link
Member

I've made a change to keep the short length limit...

Yes, it could be possible to raise the 128 byte limit, but since I don't have a manual of starcos 2.x for verification, I'd like to leave it as is.

@gabrielmuller
Copy link
Contributor

It's working now. Thank you!

frankmorgner added a commit that referenced this issue Oct 11, 2018
@zlovik
Copy link

zlovik commented Feb 8, 2019

Hello everybody.
What about GIDS applet?
I'm not sure but I think I have the same problem with GIDS also.

$opensc-tool --version -a -n
OpenSC-0.19.0-265-g928fbf2f, rev: 928fbf2f, commit-time: 2019-02-04 16:01:56 +0100
Using reader with a card: ACS ACR 38U-CCID
3b:f8:13:00:00:81:31:fe:45:4a:43:4f:50:76:32:34:31:b7
GIDS Smart Card

$pkcs11-tool -O -p 1234
Using slot 1 with a present token (0x4)
Private Key Object; RSA 
  label:      Private Key 00
  ID:         00
  Usage:      decrypt, sign
Public Key Object; RSA 2048 bits
  label:      Private Key 00
  ID:         00
  Usage:      encrypt, verify

$pkcs11-tool --id 0 --decrypt -p 1234 -m RSA-PKCS --input-file ./enc_dec_tests/data2048.crypt --module /usr/local/lib/opensc-pkcs11.so
Using slot 1 with a present token (0x4)
Using decrypt algorithm RSA-PKCS
error: PKCS11 function C_Decrypt failed: rv = CKR_DATA_LEN_RANGE (0x21)
Aborting.

gids_decrypt.log

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
8 participants