search

OpenSC / OpenSC.tokend

Tokend module for OS X with support for all cards supported by OpenSC
Other
36 stars 20 forks source link

Current sha2 branch lost the ability to RSA-sign #22

Closed mouse07410 closed 7 years ago

mouse07410 commented 8 years ago

Happens now consistently. Prompts for a PIN, reports that cannot sign. Debugging output is insufficient (this is at debug=3;)

======================================================================
0x7fff70f99300 22:32:09.140733193388597 [tokend] reader-pcsc.c:190:pcsc_internal_transmit: called
0x7fff70f99300 22:32:09.4294967893 [tokend] apdu.c:187:sc_apdu_log:
Incoming APDU data [    2 bytes] =====================================
90 00 ..
======================================================================
0x7fff70f99300 22:32:09.140733193388629 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success)
0x7fff70f99300 22:32:09.120259084885 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success)
0x7fff70f99300 22:32:09.-4294966699 [tokend] card.c:434:sc_unlock: called
0x7fff70f99300 22:32:09.597 [tokend] sec.c:206:sc_pin_cmd: returning with: 0 (Success)
0x7fff70f99300 22:32:09.597 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result 0
0x7fff70f99300 22:32:09.317106025398869 [tokend] pkcs15-pin.c:594:sc_pkcs15_pincache_add: called
0x7fff70f99300 22:32:09.317106025398869 [tokend] pkcs15-pin.c:618:sc_pkcs15_pincache_add: caching refused (user consent)
0x7fff70f99300 22:32:09.4294967893 [tokend] card.c:434:sc_unlock: called
0x7fff70f99300 22:32:09.597 [tokend] reader-pcsc.c:574:pcsc_unlock: called
0x7fff70f99300 22:32:09.598 [tokend] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x7fff70f99300 22:32:09.598 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:203:_verifyPIN:   In OpenSCToken::verify returned 0 for pin 1
0x7fff70f99300 22:32:09.6011854084296933974 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:168:verifyPIN:   PIN verified
0x7fff70f99300 22:32:09.3473459727243936342 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:219:generateSignature: In OpenSCKeyHandle::generateSignature()
0x7fff70f99300 22:32:19.860 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:19.140733193388892 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:19.860 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:19.4294968156 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
0x7fff70f99300 22:32:19.4294968166 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:19.140733193388902 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:19.870 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:19.4294968166 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
0x7fff70f99300 22:32:19.4294968174 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:19.140733193388910 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:19.878 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:19.4294968174 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
0x7fff70f99300 22:32:19.4294968216 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:19.140733193388952 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:19.920 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:19.4294968216 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
0x7fff70f99300 22:32:20.4294967988 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:20.140733193388724 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:20.692 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:20.4294967988 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
0x7fff70f99300 22:32:20.4294968005 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:20.140733193388741 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:20.709 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:20.4294968005 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
0x7fff70f99300 22:32:20.4294968013 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:20.140733193388749 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:20.717 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:20.4294968013 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
0x7fff70f99300 22:32:20.4294968071 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl()
0x7fff70f99300 22:32:20.140733193388807 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1)
0x7fff70f99300 22:32:20.775 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked()
0x7fff70f99300 22:32:20.4294968071 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified
dengert commented 8 years ago

Note "user_consent" The card enforces this and policies of the card issuer want user to enter PIN again, so OpenSC will not cache the PIN.

Is there a missing sc_unlock? Did the splitting of the generateSignature into RSA and EC loose passing back the return codes?

What does a trace with the previous code show about "user_consent" and does tokend prompt foe the PIN for each signature?

On 12/2/2015 9:36 PM, Mouse wrote:

Happens now consistently. Prompts for a PIN, reports that cannot sign. Debugging output is insufficient (this is at |debug=3;|)

|====================================================================== 0x7fff70f99300 22:32:09.140733193388597 [tokend] reader-pcsc.c:190:pcsc_internal_transmit: called 0x7fff70f99300 22:32:09.4294967893 [tokend] apdu.c:187:sc_apdu_log: Incoming APDU data [ 2 bytes] ===================================== 90 00 .. ====================================================================== 0x7fff70f99300 22:32:09.140733193388629 [tokend] apdu.c:399:sc_single_transmit: returning with: 0 (Success) 0x7fff70f99300 22:32:09.120259084885 [tokend] apdu.c:552:sc_transmit: returning with: 0 (Success) 0x7fff70f99300 22:32:09.-4294966699 [tokend] card.c:434:sc_unlock: called 0x7fff70f99300 22:32:09.597 [tokend] sec.c:206:sc_pin_cmd: returning with: 0 (Success) 0x7fff70f99300 22:32:09.597 [tokend] pkcs15-pin.c:368:sc_pkcs15_verify_pin: PIN cmd result 0 0x7fff70f99300 22:32:09.317106025398869 [tokend] pkcs15-pin.c:594:sc_pkcs15_pincache_add: called 0x7fff70f99300 22:32:09.317106025398869 [tokend] pkcs15-pin.c:618:sc_pkcs15_pincache_add: caching refused (user consent) 0x7fff70f99300 22:32:09.4294967893 [tokend] card.c:434:sc_unlock: called 0x7fff70f99300 22:32:09.597 [tokend] reader-pcsc.c:574:pcsc_unlock: called 0x7fff70f99300 22:32:09.598 [tokend] pkcs15-pin.c:373:sc_pkcs15_verify_pin: returning with: 0 (Success) 0x7fff70f99300 22:32:09.598 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:203:_verifyPIN: In OpenSCToken::verify returned 0 for pin 1 0x7fff70f99300 22:32:09.6011854084296933974 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:168:verifyPIN: PIN verified 0x7fff70f99300 22:32:09.3473459727243936342 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCKeyHandle.cpp:219:generateSignature: In OpenSCKeyHandle::generateSignature() 0x7fff70f99300 22:32:19.860 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:19.140733193388892 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:19.860 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:19.4294968156 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified 0x7fff70f99300 22:32:19.4294968166 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:19.140733193388902 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:19.870 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:19.4294968166 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified 0x7fff70f99300 22:32:19.4294968174 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:19.140733193388910 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:19.878 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:19.4294968174 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified 0x7fff70f99300 22:32:19.4294968216 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:19.140733193388952 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:19.920 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:19.4294968216 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified 0x7fff70f99300 22:32:20.4294967988 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:20.140733193388724 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:20.692 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:20.4294967988 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified 0x7fff70f99300 22:32:20.4294968005 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:20.140733193388741 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:20.709 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:20.4294968005 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified 0x7fff70f99300 22:32:20.4294968013 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:20.140733193388749 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:20.717 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:20.4294968013 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified 0x7fff70f99300 22:32:20.4294968071 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:354:getAcl: In OpenSCToken::getAcl() 0x7fff70f99300 22:32:20.140733193388807 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:136:pinStatus: In OpenSCToken::pinStatus for pinNum (1) 0x7fff70f99300 22:32:20.775 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:152:isLocked: In OpenSCToken::isLocked() 0x7fff70f99300 22:32:20.4294968071 [tokend] /Users/uri/src/OpenSC/OpenSC.tokend/OpenSC/OpenSCToken.cpp:139:pinStatus: In OpenSCToken::pinStatus Verified |

— Reply to this email directly or view it on GitHub https://github.com/OpenSC/OpenSC.tokend/issues/22.

Douglas E. Engert DEEngert@gmail.com

mouse07410 commented 8 years ago

On Dec 3, 2015, at 7:19 , Doug Engert notifications@github.com wrote:

Note "user_consent" The card enforces this and policies of the card issuer want user to enter PIN again, so OpenSC will not cache the PIN.

Yes I understand.

Is there a missing sc_unlock?

I don’t know.

Did the splitting of the generateSignature into RSA and EC loose passing back the return codes?

I don’t know. This splitting appears to have caused much more damage than one would think possible from looking at the code. Practically no lines in the “sub-functions seem executed, after the very initial debug print at the entry of the method…

I don’t understand why this seemingly innocuous change broke it so completely, and frankly don’t have too much time to dig for its roots - which also are very non-obvious. Plus, delving into this would screw up my Git structure again, and I’m not comfortable enough with it to endeavor these drastic code sweeps.

What does a trace with the previous code show about "user_consent" and does tokend prompt for the PIN for each signature?

It prompted me for the PIN consistently, verified it OK according to the log, and then said that it cannot sign because my cert has problems. It’s all plausible, except that this very cert works quite well with this same code before “generateSignature()” was split into sub-functions.

mouse07410 commented 7 years ago

A ton of things changed since this report was submitted, and I'm tracking my fork that doesn't exhibit this problem. As this point this issue doesn't seem to serve any useful purpose. Closing it.