Bug 844488 - Opensc - SSH Agent admitted failure to sign using the key
Summary: Opensc - SSH Agent admitted failure to sign using the key
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Fedora
Classification: Fedora
Component: opensc
Version: 18
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Tomas Mraz
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-07-30 21:24 UTC by Peter Zagar
Modified: 2014-02-05 12:02 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-02-05 12:02:35 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Peter Zagar 2012-07-30 21:24:20 UTC
Description of problem:
SSH Agent admitted failure to sign using the key

Version-Release number of selected component (if applicable):
Version opensc-0.12.0-4.fc16.x86_64.rpm works for me.
This was true for F15, F16 and now for F17.
Installing any newer version produces an error. I tried every new version that came out.

How reproducible:
Install opensc version newer than opensc-0.12.0-4.fc16.x86_64.rpm (this is the last version that works for me).

Steps to Reproduce:
1. [user@workstation ~]$ exec /usr/bin/ssh-agent $SHELL
2. [user@workstation ~]$ ssh-add -s /usr/lib64/opensc-pkcs11.so
   Card added: /usr/lib64/opensc-pkcs11.so
3. Try to connect to server using SecureCard
  
Actual results:
Connect fails.
----------
ssh root@server
Agent admitted failure to sign using the key.
root@server's password: 
----------

Expected results:
Connection success.
----------
ssh root@server
[root@server]#
----------

Additional info:

Installed Packages
----------
opensc.x86_64                                         0.12.2-4.fc17                                @fedora    
pcsc-lite.x86_64                                      1.8.3-1.fc17                                 @anaconda-0
pcsc-lite-ccid.x86_64                                 1.4.6-1.fc17                                 @anaconda-0
pcsc-lite-libs.x86_64                                 1.8.3-1.fc17                                 @anaconda-0
pcsc-perl.x86_64                                      1.4.12-3.fc17                                @fedora    
pcsc-tools.x86_64                                     1.4.17-3.fc17                                @fedora 

Reader info
----------
[user@workstation ~]$ opensc-tool --list-readers
# Detected readers (pcsc)
Nr.  Card  Features  Name
0    Yes             Gemalto USB Shell Token V2 00 00
----------

Keys found by ssh:
----------
[user@workstation ~]$ ssh-add -l
1024 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx /usr/lib64/opensc-pkcs11.so (RSA)
2048 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx /usr/lib64/opensc-pkcs11.so (RSA)
1024 xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx /usr/lib64/opensc-pkcs11.so (RSA)
----------

Keys info:
----------
[user@workstation ~]$ pkcs15-tool --list-keys
Using reader with a card: Gemalto USB Shell Token V2 00 00
Private RSA Key [Digital Signature]
	Object Flags   : [0x3], private, modifiable
	Usage          : [0x2C], sign, signRecover, unwrap
	Access Flags   : [0x0]
	ModLength      : 1024
	Key ref        : -1 (0xFFFFFFFF)
	Native         : yes
	Path           : xxxxxxxxxx01
	Auth ID        : 01
	ID             : 11

Private RSA Key [Non Repudiation]
	Object Flags   : [0x3], private, modifiable
	Usage          : [0x200], nonRepudiation
	Access Flags   : [0x0]
	ModLength      : 1024
	Key ref        : -1 (0xFFFFFFFF)
	Native         : yes
	Path           : xxxxxxxxxx02
	Auth ID        : 01
	ID             : 33
----------

Debug output
----------
[peter@workstation ~]$ ssh -v root@server
OpenSSH_5.9p1, OpenSSL 1.0.0j-fips 10 May 2012
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 50: Applying options for *
debug1: Connecting to server [192.168.1.100] port 22.
debug1: Connection established.
debug1: identity file /home/user/.ssh/id_rsa type -1
debug1: identity file /home/user/.ssh/id_rsa-cert type -1
debug1: identity file /home/user/.ssh/id_dsa type -1
debug1: identity file /home/user/.ssh/id_dsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.1p1 Debian-5
debug1: match: OpenSSH_5.1p1 Debian-5 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.9
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr hmac-md5 none
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: RSA xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx
debug1: Host 'server' is known and matches the RSA host key.
debug1: Found key in /home/user/.ssh/known_hosts:35
debug1: ssh_rsa_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,password
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /usr/lib64/opensc-pkcs11.so
debug1: Server accepts key: pkalg ssh-rsa blen 151
Agent admitted failure to sign using the key.
debug1: Offering RSA public key: /usr/lib64/opensc-pkcs11.so
debug1: Authentications that can continue: publickey,password
debug1: Offering RSA public key: /usr/lib64/opensc-pkcs11.so
debug1: Authentications that can continue: publickey,password
debug1: Trying private key: /home/user/.ssh/id_rsa
debug1: Trying private key: /home/user/.ssh/id_dsa
debug1: Next authentication method: password
----------

Comment 1 Peter Zagar 2012-07-30 21:42:26 UTC
Sorry, don't know if this really qualifies for a Security Sensitive Bug. Please edit if necessary.

Comment 2 Kurt Seifried 2012-07-31 04:42:24 UTC
Can you post any details on how the card is setup? What commands did you use to create the SSH key(s) on it?

I'm just wondering because, your card shows:

Key ref        : -1 (0xFFFFFFFF)

which seems odd, my card shows entries like:

Key ref        : 2 (0x2)

Comment 3 Peter Zagar 2012-07-31 06:02:46 UTC
This is a standard card setup released by our company's CA. If you need any specific detail let me know exactly what would you need and i will try to get the information. I don't know what this "Key ref" parameter actually describes?

Comment 4 Tomas Mraz 2012-08-06 09:30:36 UTC
I do not think this is a security sensitive bug.

Comment 5 Kalev Lember 2012-08-06 09:33:16 UTC
Ticking the "Security Sensitive Bug" makes the ticket unavailable for public view. I just pointed upstream to this ticket and they are unable to read it. Can you uncheck this, please?

Comment 6 Kalev Lember 2012-08-06 10:11:11 UTC
Can you enable opensc debugging, and generate a log?

The debug logging can be enabled by editing /etc/opensc.conf and setting "debug = 9" and uncommenting "debug_file = ".


Also, just a wild stab in the dark -- can you try the opensc build at http://koji.fedoraproject.org/koji/taskinfo?taskID=4362793 ?
I can see that 0.12.2-4 was built against openssl 1.0.1, which later got downgraded back to 1.0 in F17. The scratch build above is now properly rebuilt against openssl 1.0, without any opensc code changes. ABI changes between openssl versions can possibly lead to hard-to-diagnose bugs like this, for example when struct sizes change.

Comment 7 Peter Zagar 2012-08-17 05:55:52 UTC
Ok, last sections of debug log:

0x7fcb808d0800 07:47:23.617 [opensc-pkcs11] card.c:330:sc_unlock: called
0x7fcb808d0800 07:47:23.617 [opensc-pkcs11] iso7816.c:150:iso7816_read_binary: returning with: 30
0x7fcb808d0800 07:47:23.617 [opensc-pkcs11] card.c:455:sc_read_binary: returning with: 30
0x7fcb808d0800 07:47:23.617 [opensc-pkcs11] card.c:330:sc_unlock: called
0x7fcb808d0800 07:47:23.617 [opensc-pkcs11] card.c:452:sc_read_binary: returning with: 798
0x7fcb808d0800 07:47:23.617 [opensc-pkcs11] card.c:330:sc_unlock: called
0x7fcb808d0800 07:47:23.617 [opensc-pkcs11] reader-pcsc.c:548:pcsc_unlock: called
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] pkcs15.c:1944:sc_pkcs15_read_file: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode: called, left=794, depth 0
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'tbsCertificate', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry: decoding 'tbsCertificate'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode:  called, left=514, depth 1
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'version', tag 0x21000000, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'version'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode:   called, left=3, depth 2
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'version', tag 0x2
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:   decoding 'version'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1162:asn1_decode_entry:   decoding 'version' returned 2
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'serialNumber', tag 0x2
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'serialNumber'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'signature', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'signature'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'issuer', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'issuer'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'validity', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'validity'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'subject', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'subject'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'subjectPublicKeyInfo', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'subjectPublicKeyInfo'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] pkcs15-pubkey.c:869:sc_pkcs15_pubkey_from_spki: sc_pkcs15_pubkey_from_spki 0x7fcb81fd1553:290
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode: called, left=290, depth 0
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'algorithm', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry: decoding 'algorithm'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode:  called, left=13, depth 1
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'algorithm', tag 0x6
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'algorithm'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'nullParam', tag 0x5, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'nullParam'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'subjectPublicKey', tag 0x3
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry: decoding 'subjectPublicKey'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] pkcs15-pubkey.c:894:sc_pkcs15_pubkey_from_spki: DEE pk_alg.algorithm=0
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode: called, left=270, depth 0
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'publicKeyCoefficients', tag 0x1000010, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry: decoding 'publicKeyCoefficients'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode:  called, left=266, depth 1
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'modulus', tag 0x2
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'modulus'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'exponent', tag 0x2
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'exponent'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'extensions', tag 0x21000003, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'extensions'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode:   called, left=51, depth 2
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'x509v3', tag 0x1000010, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:   decoding 'x509v3'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode:    called, left=49, depth 3
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'certificatePolicies', tag 0x1000010, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:    decoding 'certificatePolicies'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'subjectKeyIdentifier', tag 0x1000010, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:    decoding 'subjectKeyIdentifier'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'crlDistributionPoints', tag 0x1000010, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:    decoding 'crlDistributionPoints'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'authorityKeyIdentifier', tag 0x1000010, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1359:asn1_decode: not present
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'keyUsage', tag 0x1000010, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1359:asn1_decode: not present
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'signatureAlgorithm', tag 0x1000010
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry: decoding 'signatureAlgorithm'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1322:asn1_decode:  called, left=13, depth 1
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'algorithm', tag 0x6
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'algorithm'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'nullParam', tag 0x5, OPTIONAL
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry:  decoding 'nullParam'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1345:asn1_decode: Looking for 'signatureValue', tag 0x3
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1138:asn1_decode_entry: decoding 'signatureValue'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1394:asn1_decode: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1424:asn1_encode_entry: encoding 'serialNumber'
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1429:asn1_encode_entry: type=4, tag=0x02, parm=0x7fcb81fca8f0, len=3
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] asn1.c:1605:asn1_encode_entry: length of encoded item=5
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] framework-pkcs15.c:576:pkcs15_create_pkcs11_objects: Found 0 data objects
0x7fcb808d0800 07:47:23.620 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 0
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:593:__pkcs15_prkey_bind_related: Object is a private key and has id 11
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 1
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:593:__pkcs15_prkey_bind_related: Object is a private key and has id 33
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 2
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:635:__pkcs15_cert_bind_related: Object is a certificate and has id 11
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:664:__pkcs15_cert_bind_related: Associating object 0 as private key
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:654:__pkcs15_cert_bind_related: Associating object 6 (id 38383935353137393834353238363130353131) as issuer
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 3
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 4
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:635:__pkcs15_cert_bind_related: Object is a certificate and has id 33
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:664:__pkcs15_cert_bind_related: Associating object 1 as private key
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:654:__pkcs15_cert_bind_related: Associating object 6 (id 38383935353137393834353238363130353131) as issuer
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 5
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 6
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:635:__pkcs15_cert_bind_related: Object is a certificate and has id 38383935353137393834353238363130353131
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:685:pkcs15_bind_related_objects: Looking for objects related to object 7
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] slot.c:293:slot_allocate: Allocated slot 0x1 for card in reader Gemalto USB Shell Token V2 00 00
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:844:pkcs15_init_slot: Initialized token 'Electronic ID (PIN1)' in slot 0x1
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:994:pkcs15_create_tokens: Adding private key 0 to PIN 0
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fc80f0
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fcfb00
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fcfb60
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fd18e0
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fd1940
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:994:pkcs15_create_tokens: Adding private key 1 to PIN 0
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fcaa70
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fd07f0
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:753:pkcs15_add_object: Setting object handle of 0x0 to 0x7fcb81fd1070
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:1046:pkcs15_create_tokens: All tokens created
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] slot.c:261:card_detect: Gemalto USB Shell Token V2 00 00: Detection ended
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-global.c:259:C_Initialize: C_Initialize() = CKR_OK
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-global.c:329:C_GetInfo: C_GetInfo()
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-global.c:375:C_GetSlotList: C_GetSlotList(token=1, plug-n-play)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:870:pcsc_detect_readers: called
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:878:pcsc_detect_readers: Probing pcsc readers
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:1023:pcsc_detect_readers: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] slot.c:188:card_detect: Gemalto USB Shell Token V2 00 00: Detecting smart card
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] sc.c:195:sc_detect_card_presence: called
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:364:pcsc_detect_card_presence: called
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:277:refresh_attributes: Gemalto USB Shell Token V2 00 00 check
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:293:refresh_attributes: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:369:pcsc_detect_card_presence: returning with: 1
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] sc.c:200:sc_detect_card_presence: returning with: 1
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] slot.c:261:card_detect: Gemalto USB Shell Token V2 00 00: Detection ended
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-global.c:411:C_GetSlotList: was only a size inquiry (1)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-global.c:375:C_GetSlotList: C_GetSlotList(token=1, refresh)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] slot.c:188:card_detect: Gemalto USB Shell Token V2 00 00: Detecting smart card
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] sc.c:195:sc_detect_card_presence: called
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:364:pcsc_detect_card_presence: called
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:277:refresh_attributes: Gemalto USB Shell Token V2 00 00 check
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:293:refresh_attributes: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] reader-pcsc.c:369:pcsc_detect_card_presence: returning with: 1
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] sc.c:200:sc_detect_card_presence: returning with: 1
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] slot.c:261:card_detect: Gemalto USB Shell Token V2 00 00: Detection ended
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-global.c:428:C_GetSlotList: returned 1 slots
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] framework-pkcs15.c:332:C_GetTokenInfo: C_GetTokenInfo(1)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] sec.c:157:sc_pin_cmd: called
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] sec.c:204:sc_pin_cmd: returning with: -1408 (Not supported)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-session.c:57:C_OpenSession: C_OpenSession(0x1)
0x7fcb808d0800 07:47:23.621 [opensc-pkcs11] pkcs11-session.c:83:C_OpenSession: C_OpenSession handle: 0x7fcb81fd1b70
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] pkcs11-session.c:86:C_OpenSession: C_OpenSession() = CKR_OK
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] pkcs11-session.c:259:C_Login: C_Login(0x7fcb81fd1b70, 1)
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] pkcs15-pin.c:234:sc_pkcs15_verify_pin: called
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] pkcs15-pin.c:235:sc_pkcs15_verify_pin: PIN(0x7fcb81fba0d0;len:8)
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] card.c:292:sc_lock: called
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] reader-pcsc.c:511:pcsc_lock: called
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] sec.c:157:sc_pin_cmd: called
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] apdu.c:525:sc_transmit_apdu: called
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] card.c:292:sc_lock: called
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] reader-pcsc.c:243:pcsc_transmit: reader 'Gemalto USB Shell Token V2 00 00'
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] apdu.c:184:sc_apdu_log: 
Outgoing APDU data [   13 bytes] =====================================
[edited]
======================================================================
0x7fcb808d0800 07:47:23.622 [opensc-pkcs11] reader-pcsc.c:176:pcsc_internal_transmit: called
0x7fcb808d0800 07:47:23.688 [opensc-pkcs11] apdu.c:184:sc_apdu_log: 
Incoming APDU data [    2 bytes] =====================================
[edited]
======================================================================
0x7fcb808d0800 07:47:23.688 [opensc-pkcs11] card.c:330:sc_unlock: called
0x7fcb808d0800 07:47:23.688 [opensc-pkcs11] sec.c:204:sc_pin_cmd: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.688 [opensc-pkcs11] pkcs15-pin.c:509:sc_pkcs15_pincache_add: called
0x7fcb808d0800 07:47:23.688 [opensc-pkcs11] pkcs15-pin.c:543:sc_pkcs15_pincache_add: PIN(PIN1) cached
0x7fcb808d0800 07:47:23.689 [opensc-pkcs11] card.c:330:sc_unlock: called
0x7fcb808d0800 07:47:23.689 [opensc-pkcs11] reader-pcsc.c:548:pcsc_unlock: called
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs15-pin.c:296:sc_pkcs15_verify_pin: returning with: 0 (Success)
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] framework-pkcs15.c:1186:pkcs15_login: PKCS15 verify PIN returned 0
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] framework-pkcs15.c:1195:pkcs15_login: Check if pkcs15 object list can be completed.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:307:C_FindObjectsInit: C_FindObjectsInit(slot = 1)
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:308:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = CKO_PUBLIC_KEY
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] misc.c:136:session_start_operation: called
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] misc.c:137:session_start_operation: Session 0x7fcb81fd1b70, type 0
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fc80f0
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114158352: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fcfb00
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114127104: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fcfb60
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:357:C_FindObjectsInit: Object 1/-2114127008: Attribute 0x0 matches.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:362:C_FindObjectsInit: Object 1/-2114127008 matches
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:367:C_FindObjectsInit: realloc for 32 handles
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd18e0
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114119456: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd1940
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:357:C_FindObjectsInit: Object 1/-2114119360: Attribute 0x0 matches.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:362:C_FindObjectsInit: Object 1/-2114119360 matches
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fcaa70
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114147728: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd07f0
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114123792: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd1070
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:357:C_FindObjectsInit: Object 1/-2114121616: Attribute 0x0 matches.
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:362:C_FindObjectsInit: Object 1/-2114121616 matches
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:380:C_FindObjectsInit: 3 matching objects
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] misc.c:158:session_get_operation: called
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035928928: CKA_ID = <size inquiry>
0x7fcb808d0800 07:47:23.691 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035928928: CKA_MODULUS = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035928928: CKA_PUBLIC_EXPONENT = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:235:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fcb81fd1b70, hObject=0x7fcb81fcfb60) = CKR_OK
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035928928: CKA_ID = 11
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035928928: CKA_MODULUS = 977B15370F4E8371D3546891BD3ACFDEE1F92051BABD4985DA15B4F9531A534E
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035928928: CKA_PUBLIC_EXPONENT = 010001
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:235:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fcb81fd1b70, hObject=0x7fcb81fcfb60) = CKR_OK
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] misc.c:158:session_get_operation: called
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035936576: CKA_ID = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035936576: CKA_MODULUS = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035936576: CKA_PUBLIC_EXPONENT = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:235:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fcb81fd1b70, hObject=0x7fcb81fd1940) = CKR_OK
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035936576: CKA_ID = 38383935353137393834353238363130353131
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035936576: CKA_MODULUS = BCA3260196E59DAC1A0202397CACDC064C374AAE074875E8271CA431FD0AA723
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035936576: CKA_PUBLIC_EXPONENT = 010001
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:235:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fcb81fd1b70, hObject=0x7fcb81fd1940) = CKR_OK
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] misc.c:158:session_get_operation: called
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035934320: CKA_ID = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035934320: CKA_MODULUS = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035934320: CKA_PUBLIC_EXPONENT = <size inquiry>
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:235:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fcb81fd1b70, hObject=0x7fcb81fd1070) = CKR_OK
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035934320: CKA_ID = 33
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035934320: CKA_MODULUS = 93F5F0505CD942207C4942AA4A9CB591CBF66A371C9F81C2A8E39A99E381D7FB
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:213:C_GetAttributeValue: Object 140512035934320: CKA_PUBLIC_EXPONENT = 03
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:235:C_GetAttributeValue: C_GetAttributeValue(hSession=0x7fcb81fd1b70, hObject=0x7fcb81fd1070) = CKR_OK
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] misc.c:158:session_get_operation: called
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] misc.c:158:session_get_operation: called
0x7fcb808d0800 07:47:23.692 [opensc-pkcs11] pkcs11-object.c:60:sc_find_release: freeing 32 handles used 3  at 0x7fcb81fd1d20
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:307:C_FindObjectsInit: C_FindObjectsInit(slot = 1)
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:308:C_FindObjectsInit: C_FindObjectsInit(): CKA_CLASS = CKO_PRIVATE_KEY
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:308:C_FindObjectsInit: C_FindObjectsInit(): CKA_ID = 11
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:308:C_FindObjectsInit: C_FindObjectsInit(): CKA_SIGN = TRUE
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] misc.c:136:session_start_operation: called
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] misc.c:137:session_start_operation: Session 0x7fcb81fd1b70, type 0
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fc80f0
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:357:C_FindObjectsInit: Object 1/-2114158352: Attribute 0x0 matches.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:357:C_FindObjectsInit: Object 1/-2114158352: Attribute 0x102 matches.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:357:C_FindObjectsInit: Object 1/-2114158352: Attribute 0x108 matches.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:362:C_FindObjectsInit: Object 1/-2114158352 matches
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:367:C_FindObjectsInit: realloc for 32 handles
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fcfb00
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114127104: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fcfb60
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114127008: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd18e0
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114119456: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd1940
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114119360: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fcaa70
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:357:C_FindObjectsInit: Object 1/-2114147728: Attribute 0x0 matches.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114147728: Attribute 0x102 does NOT match.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd07f0
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114123792: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:329:C_FindObjectsInit: Object with handle 0x7fcb81fd1070
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:350:C_FindObjectsInit: Object 1/-2114121616: Attribute 0x0 does NOT match.
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:380:C_FindObjectsInit: 1 matching objects
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] misc.c:158:session_get_operation: called
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] misc.c:158:session_get_operation: called
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:60:sc_find_release: freeing 32 handles used 1  at 0x7fcb81fb9110
0x7fcb808d0800 07:47:41.968 [opensc-pkcs11] pkcs11-object.c:594:C_SignInit: C_SignInit() = CKR_MECHANISM_INVALID

Comment 8 Peter Zagar 2012-08-17 06:00:41 UTC
(In reply to comment #6)

> Also, just a wild stab in the dark -- can you try the opensc build at
> http://koji.fedoraproject.org/koji/taskinfo?taskID=4362793 ?
> I can see that 0.12.2-4 was built against openssl 1.0.1, which later got
> downgraded back to 1.0 in F17. The scratch build above is now properly
> rebuilt against openssl 1.0, without any opensc code changes. ABI changes
> between openssl versions can possibly lead to hard-to-diagnose bugs like
> this, for example when struct sizes change.

How do i download this build? I cannot seem to find the actual package to download it.

Comment 9 Tomas Mraz 2012-08-17 07:08:54 UTC
(In reply to comment #8)
> (In reply to comment #6)
> 
> > Also, just a wild stab in the dark -- can you try the opensc build at
> > http://koji.fedoraproject.org/koji/taskinfo?taskID=4362793 ?
> > I can see that 0.12.2-4 was built against openssl 1.0.1, which later got
> > downgraded back to 1.0 in F17. The scratch build above is now properly
> > rebuilt against openssl 1.0, without any opensc code changes. ABI changes
> > between openssl versions can possibly lead to hard-to-diagnose bugs like
> > this, for example when struct sizes change.
> 
> How do i download this build? I cannot seem to find the actual package to
> download it.

The build was already deleted. I don't believe it will help but I did another scratch build for you:
http://koji.fedoraproject.org/koji/taskinfo?taskID=4398121

Comment 10 Peter Zagar 2012-08-17 16:08:10 UTC
Indeed, it seems there is no difference, debug log ends with the same lines:

0x7f7e34bcb800 17:56:46.546 [opensc-pkcs11] pkcs11-object.c:594:C_SignInit: C_SignInit() = CKR_MECHANISM_INVALID

Comment 11 Peter Zagar 2013-01-25 09:23:28 UTC
Hi all, here's an update on this matter.
I tried it with another reader. No success.
I tried a card with different version of the chip. SUCCESS.

Description of problem:
SSH Agent admitted failure to sign using the key

Version-Release number of selected component (if applicable):
Version opensc-0.12.0-4.fc16.x86_64.rpm works for me.
This was true for F15, F16, F17 and now for F18.
Installing any newer version produces an error. I tried every new version that came out.

How reproducible:
Install opensc version newer than opensc-0.12.0-4.fc16.x86_64.rpm (this is the last version that works for me).

Steps to Reproduce:
1. [user@workstation ~]$ exec /usr/bin/ssh-agent $SHELL
2. [user@workstation ~]$ ssh-add -s /usr/lib64/opensc-pkcs11.so
   Card added: /usr/lib64/opensc-pkcs11.so
3. Try to connect to server using SecureCard
  
Actual results:
Connect fails.
----------
ssh root@server
Agent admitted failure to sign using the key.
root@server's password: 
----------
OR:
----------
ssh -I /usr/lib/opensc-pkcs11.so root@server
Enter PIN for 'Electronic ID (PIN1)': 
C_SignInit failed: 112
ssh_rsa_sign: RSA_sign failed: error:25066067:DSO support routines:DLFCN_LOAD:could not load the shared library
Received disconnect from 192.168.2.22: 2: Too many authentication failures for root
----------


Expected results:
Connection success.
----------
ssh root@server
[root@server]#
----------

Additional info:

Installed Packages
----------
opensc.x86_64                       0.12.2-6.fc18                        @fedora
pcsc-lite.x86_64                       1.8.7-1.fc18                    installed
pcsc-lite-ccid.x86_64                  1.4.8-1.fc18                    installed
pcsc-lite-libs.x86_64                  1.8.7-1.fc18                    installed
pcsc-perl.x86_64                       1.4.12-5.fc18                   installed
pcsc-tools.x86_64                      1.4.17-4.fc18                   installed

Reader info
----------
[user@workstation ~]$ opensc-tool --list-readers
# Detected readers (pcsc)
Nr.  Card  Features  Name
0    No              OMNIKEY AG CardMan 3021 00 00
1    Yes             Gemalto USB Shell Token V2 01 00
----------


So apparently, it goes like this (the card names are from Nexus Personal):
- opensc-0.12.0-4.fc16.x86_64.rpm works only with card "SetCOS 4.3"
- opensc-0.12.2-6.fc18.x86_64.rpm works only with card "SetCOS 4.4.1"
- neither of them works with card "Gemalto Classic Applet V3"

I think this problem is connected somehow with the drivers.

opensc-tool --info
opensc 0.12.2 [gcc  4.7.1 20120720 (Red Hat 4.7.1-5)]
Enabled features: zlib readline openssl pcsc(libpcsclite.so.1)

opensc-tool --list-drivers
Configured card drivers:
  cardos           Siemens CardOS
  flex             Schlumberger Multiflex/Cryptoflex
  cyberflex        Schlumberger Cyberflex
  gpk              Gemplus GPK
  gemsafeV1        driver for the Gemplus GemSAFE V1 applet
  miocos           MioCOS 1.1
  mcrd             MICARDO 2.1 / EstEID 1.0 - 3.0
  asepcos          Athena ASEPCOS
  starcos          STARCOS SPK 2.3/2.4
  tcos             TCOS 3.0
  openpgp          OpenPGP card
  jcop             JCOP cards with BlueZ PKCS#15 applet
  oberthur         Oberthur AuthentIC.v2/CosmopolIC.v4
  authentic        Oberthur AuthentIC v3.1
  iasecc           IAS-ECC
  belpic           Belpic cards
  ias              IAS
  incrypto34       Incard Incripto34
  acos5            ACS ACOS5 card
  akis             TUBITAK UEKAE AKIS
  entersafe        entersafe
  rutoken          Rutoken driver
  rutoken_ecp      Rutoken ECP driver
  westcos          WESTCOS compatible cards
  myeid            MyEID cards with PKCS#15 applet
  setcos           Setec cards
  muscle           MuscleApplet
  atrust-acos      A-Trust ACOS cards
  piv              PIV-II  for multiple cards
  itacns           Italian CNS
  javacard         JavaCard (without supported applet)
  default          Default driver for unknown cards

My question to all is, has setcos driver changed from opensc 0.12.0 to opensc 0.12.2?

Comment 12 Ray Holme 2013-03-07 13:41:24 UTC
I also got this same problem. The interesting thing is that ALL was working fine up till I installed the most recent updates for fedora 18 using "yum update". This problem started then. I am not sure if it helps to add my 2 cents, but here is a slightly edited version of the ssh -v log (removed my RSH key and server name and IP). In addition I tacked on the results of a couple "ls -l" commands as I wanted to see what ssh was complaining about.

--- output of ssh -v
OpenSSH_6.1p1, OpenSSL 1.0.1e-fips 11 Feb 2013
debug1: Reading configuration data /home/ray/.ssh/config
debug1: /home/ray/.ssh/config line 16: Applying options for lnwprod
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 50: Applying options for *
debug1: Connecting to SOME_MACHINE.com [SOME_IP_ADDR] port 22.
debug1: Connection established.
debug1: identity file /home/ray/.ssh/id_rsa type 1
debug1: identity file /home/ray/.ssh/id_rsa-cert type -1
debug1: identity file /home/ray/.ssh/id_dsa type -1
debug1: identity file /home/ray/.ssh/id_dsa-cert type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_4.3
debug1: match: OpenSSH_4.3 pat OpenSSH_4*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.1
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: server->client aes128-ctr hmac-md5 none
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: RSA MY_SECRET_KEY_REMOVED
debug1: Host 'SOME_MACHINE.com' is known and matches the RSA host key.
debug1: Found key in /home/ray/.ssh/known_hosts:12
debug1: ssh_rsa_verify: signature correct
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: Roaming not allowed by server
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,gssapi-with-mic,password
debug1: Next authentication method: gssapi-with-mic
debug1: Unspecified GSS failure.  Minor code may provide more information
Credentials cache file '/run/user/1000/krb5cc_6ccfcd85452fac11a7aff9665137a9fc/tkt' not found

debug1: Unspecified GSS failure.  Minor code may provide more information
Credentials cache file '/run/user/1000/krb5cc_6ccfcd85452fac11a7aff9665137a9fc/tkt' not found

debug1: Unspecified GSS failure.  Minor code may provide more information

debug1: Unspecified GSS failure.  Minor code may provide more information
Credentials cache file '/run/user/1000/krb5cc_6ccfcd85452fac11a7aff9665137a9fc/tkt' not found

debug1: Next authentication method: publickey
debug1: Offering RSA public key: /home/ray/.ssh/id_rsa
debug1: Server accepts key: pkalg ssh-rsa blen 279
Agent admitted failure to sign using the key.
debug1: Trying private key: /home/ray/.ssh/id_dsa
debug1: Next authentication method: password
ray's password: 
debug1: Authentication succeeded (password).
Authenticated to SOME_MACHINE.com ([SOME_IP_ADDR]:22).
debug1: channel 0: new [client-session]
debug1: Entering interactive session.
debug1: Sending environment.
debug1: Sending env XMODIFIERS = @im=none
debug1: Sending env LANG = en_US.UTF-8
Last login: Thu Mar  7 08:18:41 2013 from cpe-74-78-75-119.maine.res.rr.com
[ray@SOME_MACHINE ~]$ debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: channel 0: forcing write
logout
debug1: channel 0: free: client-session, nchannels 1
debug1: fd 1 clearing O_NONBLOCK
Connection to SOME_MACHINE.com closed.
Transferred: sent 2296, received 2344 bytes, in 3.4 seconds
Bytes per second: sent 684.4, received 698.7
debug1: Exit status 0

------information AFTER the ssh is done about file not found

ls -ld /run/user/1000/krb5cc_6ccfcd85452fac11a7aff9665137a9fc/
drwx------. 2 ray staff 60 Mar  6 15:41 /run/user/1000/krb5cc_6ccfcd85452fac11a7aff9665137a9fc/
ls -l /run/user/1000/krb5cc_6ccfcd85452fac11a7aff9665137a9fc/
total 4
-rw-------. 1 ray staff 4 Mar  6 15:41 primary

Comment 13 Ray Holme 2013-03-07 13:44:16 UTC
OOPS - I should say that my machine is fedora 18, but the target machine(s) are fedora 12 (yea, I know - we are working on that). BUT AGAIN, this was working fine last week before I "yum update"d my box.

Comment 14 Ray Holme 2013-03-22 14:07:40 UTC
*** Bug 922038 has been marked as a duplicate of this bug. ***

Comment 15 Fedora End Of Life 2013-12-21 08:40:01 UTC
This message is a reminder that Fedora 18 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 18. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '18'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 18's end of life.

Thank you for reporting this issue and we are sorry that we may not be 
able to fix it before Fedora 18 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior to Fedora 18's end of life.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 16 Fedora End Of Life 2014-02-05 12:02:38 UTC
Fedora 18 changed to end-of-life (EOL) status on 2014-01-14. Fedora 18 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.