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

Support D-Trust Card 4.1 (Std. RSA 2ca) #2784

Closed
hamarituc opened this issue May 23, 2023 · 19 comments · Fixed by #2943
Closed

Support D-Trust Card 4.1 (Std. RSA 2ca) #2784

hamarituc opened this issue May 23, 2023 · 19 comments · Fixed by #2943

Comments

@hamarituc
Copy link
Contributor

Problem Description

The D-Trust Signature Card 4.1 is currently not supported by OpenSC.

Proposed Resolution

It would be great if this card type is supported by OpenSC. This is merely a feature request than a bug report.

Steps to reproduce

Try to sign some data:

$ echo "Sign me" | pkcs11-tool --slot 1 -a Signaturzertifikat -s -m RSA-PKCS -p XXX
Using signature algorithm RSA-PKCS
error: PKCS11 function C_Login failed: rv = CKR_OPERATION_NOT_INITIALIZED (0x91)
Aborting.

Logs

Card type:

$ opensc-tool --name
Using reader with a card: Alcor Micro AU9540 00 00
Atos CardOS

Card infos:

$ cardos-tool -i
Using reader with a card: Alcor Micro AU9540 00 00
3b:d2:18:00:81:31:fe:58:c9:04:11
Info : CardOS V5.4     2019
Serial number: 0a 00 33 06 00 0f 3f 51
OS Version: 201.4 (unknown Version)
Current life cycle: 16 (operational)
Security Status of current DF:
07 .
Free memory : 1402
ATR Status: 0x0 ROM-ATR
Packages installed:
E1 0B 53 06 03 04 13 02 C9 04 8F 01 01 ..S..........
Ram size: 7, Eeprom size: 118, cpu type: 78, chip config: 63, chip manufacturer: 5
Free eeprom memory: 69120
Current Maximum Data Field Length: 437
Complete chip production data:
CC 78 33 13 03 00 01 00 98 00 00 06 0C 0A 00 00 .x3.............
00 00 00 00 00 00 00 61 75 38 37 67 FF FF FF 78 .......au87g...x
01 51 82 78 05 1E 07 00 00 83 3C 05 E7 55 2D 86 .Q.x......<..U-.
01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00 00 00 00 00 00 00 00 00 00 00 00             ............
System keys: PackageLoadKey (version 0x00, retries 10)
System keys: StartKey (version 0xff, retries 10)
Path to current DF:
01 01 ..

PKCS#15 information:

$ pkcs15-tool -D   
Using reader with a card: Alcor Micro AU9540 00 00
PKCS#15 Card [D-TRUST Card 4.1 Std. RSA 2ca]:
        Version        : 1
        Serial number  : 9276003211600214693f
        Manufacturer ID: D-TRUST GmbH (C)
        Flags          : Login required, PRN generation


PIN [Card-PIN]
        Object Flags   : [0x03], private, modifiable
        Auth ID        : 04
        ID             : 03
        Flags          : [0x1811], case-sensitive, initialized, exchangeRefData
        Length         : min_len:6, max_len:12, stored_len:0
        Pad char       : 0x00
        Reference      : 3 (0x03)
        Type           : UTF-8

PIN [Card-PUK]
        Object Flags   : [0x03], private, modifiable
        ID             : 04
        Flags          : [0x859], case-sensitive, unblock-disabled, initialized, unblockingPin, exchangeRefData
        Length         : min_len:8, max_len:8, stored_len:0
        Pad char       : 0x00
        Reference      : 4 (0x04)
        Type           : UTF-8

PIN [Signature-PIN]
        Object Flags   : [0x03], private, modifiable
        Auth ID        : 04
        ID             : 07
        Flags          : [0x2813], case-sensitive, local, initialized, exchangeRefData
        Length         : min_len:6, max_len:12, stored_len:0
        Pad char       : 0x00
        Reference      : 135 (0x87)
        Type           : UTF-8
        Path           : 3f000101

Private RSA Key [Authentisierungsschluessel]
        Object Flags   : [0x01], private
        Usage          : [0x2E], decrypt, sign, signRecover, unwrap
        Access Flags   : [0x00]
        Algo_refs      : 0
        ModLength      : 3072
        Key ref        : 3 (0x03)
        Native         : yes
        Path           : 3f000102
        Auth ID        : 03
        ID             : 03
        MD:guid        : 24396187-0b7f-7436-943e-1cd936753e1b

Private RSA Key [Signaturschluessel]
        Object Flags   : [0x01], private
        Usage          : [0x200], nonRepudiation
        Access Flags   : [0x00]
        Algo_refs      : 0
        ModLength      : 3072
        Key ref        : 2 (0x02)
        Native         : yes
        Path           : 3f000101
        Auth ID        : 07
        ID             : 02
        MD:guid        : 93b5ef55-5bb6-373a-8e62-3af96e87bdcb

X.509 Certificate [Authentisierungszertifikat]
        Object Flags   : [0x02], modifiable
        Authority      : no
        Path           : 3f0001030204
        ID             : 03
        Encoded serial : 02 03 591704

X.509 Certificate [Signaturzertifikat]
        Object Flags   : [0x02], modifiable
        Authority      : no
        Path           : 3f0001030201
        ID             : 02
        Encoded serial : 02 10 5EC484D0F04C13BF3AA907038C2FADCC

X.509 Certificate [CA-Zertifikat fuer Authentisierung]
        Object Flags   : [0x02], modifiable
        Authority      : yes
        Path           : 3f0001030205
        ID             : 03
        Encoded serial : 02 03 0FE54B

X.509 Certificate [Root-CA-Zertifikat fuer Authentisierung]
        Object Flags   : [0x02], modifiable
        Authority      : yes
        Path           : 3f0001030206
        ID             : 03
        Encoded serial : 02 03 0FE529

X.509 Certificate [CA-Zertifikat fuer Signatur]
        Object Flags   : [0x02], modifiable
        Authority      : yes
        Path           : 3f0001030202
        ID             : 02
        Encoded serial : 02 10 69F4C9580F580F631488B9632371E72E

X.509 Certificate [Root-CA-Zertifikat fuer Signatur]
        Object Flags   : [0x02], modifiable
        Authority      : yes
        Path           : 3f0001030203
        ID             : 02
        Encoded serial : 02 10 6BC22A5479D8EA68A9C5A27A909BA938

PKCS#11 information

$ pkcs11-tool -T         
Available slots:
Slot 0 (0x0): Alcor Micro AU9540 00 00
  token label        : D-TRUST Card 4.1 S... (Card-PIN)
  token manufacturer : D-TRUST GmbH (C)
  token model        : PKCS#15 emulated
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 0.0
  firmware version   : 0.0
  serial num         : 003211600214693f
  pin min/max        : 6/12
Slot 1 (0x1): Alcor Micro AU9540 00 00
  token label        : D-TRUST Card ... (Signature-PIN)
  token manufacturer : D-TRUST GmbH (C)
  token model        : PKCS#15 emulated
  token flags        : login required, token initialized, PIN initialized
  hardware version   : 0.0
  firmware version   : 0.0
  serial num         : 003211600214693f
  pin min/max        : 6/12

$ pkcs11-tool --slot 1 -O
Certificate Object; type = X.509 cert
  label:      Signaturzertifikat
  subject:    DN: C=DE, O=Technische Universit\xC3\xA4t Chemnitz, CN=Mario Haustein, GN=Mario, SN=Haustein/serialNumber=SIDWM936447608422322
  serial:     5EC484D0F04C13BF3AA907038C2FADCC
  ID:         02
Public Key Object; RSA 3072 bits
  label:      Signaturzertifikat
  ID:         02
  Usage:      encrypt, verify
  Access:     local
Certificate Object; type = X.509 cert
  label:      CA-Zertifikat fuer Signatur
  subject:    DN: C=DE, O=D-Trust GmbH, CN=D-TRUST CA 3-21-1 2021/organizationIdentifier=NTRDE-HRB74346
  serial:     69F4C9580F580F631488B9632371E72E
  ID:         02
Public Key Object; RSA 4096 bits
  label:      CA-Zertifikat fuer Signatur
  ID:         02
  Usage:      encrypt, verify
  Access:     local
Certificate Object; type = X.509 cert
  label:      Root-CA-Zertifikat fuer Signatur
  subject:    DN: C=DE, O=D-Trust GmbH, CN=D-TRUST Root CA 3 2021
  serial:     6BC22A5479D8EA68A9C5A27A909BA938
  ID:         02
Public Key Object; RSA 4096 bits
  label:      Root-CA-Zertifikat fuer Signatur
  ID:         02
  Usage:      encrypt, verify
  Access:     local

OpenSC version:

$ opensc-tool --version
OpenSC-0.23.0-204-g33b7736c, rev: 33b7736c, commit-time: 2023-05-17 09:05:01 +0200

Please tell which information is required for a further analysis.

@Jakuje
Copy link
Member

Jakuje commented May 24, 2023

next steps would be getting a debug log to see what code is being used and what are the actual failures. Use either environment variable OPENSC_DEBUG=9 or respective option in opensc.conf. Note, that the PIN might be visible in the logs in plaintext as well as in hexadecimal so you might want to redact the values.

@hamarituc
Copy link
Contributor Author

echo "Sign me" | OPENSC_DEBUG=9 pkcs11-tool --slot 1 -a Signaturzertifikat -s -m RSA-PKCS -p XXX &> log.txt

See log.txt. For further analysis please tell which parts of the log might be of interest to avoid posting 6000+ lines of log.

Thank you for reviewing.

@dengert
Copy link
Member

dengert commented May 24, 2023

Looks like card is enforcing CKA_ALWAYS_AUTHENTICATE on the card. (older cards may not have enforced this)
But the driver maybe request the PIN at the wrong time or doing other operations to the card between the:
Line 6523 P:21170; T:0x140574649179648 09:35:35.665 [opensc-pkcs11] pkcs11-session.c:347:C_Login: C_Login(0x5606cdbfcb00, 2)

P:21170; T:0x140574649179648 09:35:35.700 [opensc-pkcs11] pkcs15-pin.c:455:sc_pkcs15_verify_pin_with_session_pin: PIN cmd result 0
P:21170; T:0x140574649179648 09:35:35.700 [opensc-pkcs11] pkcs15-pin.c:761:sc_pkcs15_pincache_add: called
P:21170; T:0x140574649179648 09:35:35.700 [opensc-pkcs11] pkcs15-pin.c:789:sc_pkcs15_pincache_add: caching refused (user consent) 

and when there is a failure line 6664:

Incoming APDU (2 bytes):
69 82 i.

OpenSC can cache the pin in the driver, but does not when the key is listed as user_consent Can you test with
use_pin_caching = true; and pin_cache_ignore_user_consent = true; in opensc.conf.
See man opensc.conf

@hamarituc
Copy link
Contributor Author

Looks like card is enforcing CKA_ALWAYS_AUTHENTICATE on the card. (older cards may not have enforced this)

This type of card requires to input a PIN for each signature. There are D-Trust cards which allow to compute 100 or an unlimited number of signatures with a single PIN input, but they are more expensive and I don't have one available.

Can you test with use_pin_caching = true; and pin_cache_ignore_user_consent = true; in opensc.conf.

I tested it. It now fails with CKR_USER_NOT_LOGGED_IN. Here you find the log starting at the output of Using signature algorithm RSA-PKCS. All log lines before this output are the same as above (except timestamps, PIDs, pointers etc.).

Using signature algorithm RSA-PKCS
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:377:sc_pkcs11_sign_init: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:382:sc_pkcs11_sign_init: mechanism 0x1, key-type 0x0
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] misc.c:267:session_start_operation: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] misc.c:268:session_start_operation: Session 0x55b471741d50, type 1
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:504:sc_pkcs11_signature_init: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:4638:pkcs15_prkey_can_do: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:4639:pkcs15_prkey_can_do: check hardware capabilities: CK_MECHANISM_TYPE=0x1 (CKM) and CKF_xxx=0x800
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:4647:pkcs15_prkey_can_do: returning with: 84
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:558:sc_pkcs11_signature_init: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:411:sc_pkcs11_sign_init: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] pkcs11-object.c:697:C_SignInit: C_SignInit() = CKR_OK
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 94233485834176: CKA_ALWAYS_AUTHENTICATE = FALSE
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] pkcs11-object.c:294:C_GetAttributeValue: C_GetAttributeValue(hSession=0x55b471741d50, hObject=0x55b47172f7c0) = CKR_OK
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:653:sc_pkcs11_signature_size: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:489:sc_pkcs11_sign_size: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:421:sc_pkcs11_sign_update: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:568:sc_pkcs11_signature_update: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:569:sc_pkcs11_signature_update: data part length 8
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:578:sc_pkcs11_signature_update: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:437:sc_pkcs11_sign_update: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:447:sc_pkcs11_sign_final: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] mechanism.c:588:sc_pkcs11_signature_final: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:4180:pkcs15_prkey_sign: Initiating signing operation, mechanism 0x1.
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] reader-pcsc.c:688:pcsc_lock: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] framework-pkcs15.c:4329:pkcs15_prkey_sign: Selected flags 102. Now computing signature for 8 bytes. 512 bytes reserved.
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] pkcs15-sec.c:607:sc_pkcs15_compute_signature: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] pkcs15-sec.c:660:sc_pkcs15_compute_signature: supported algorithm flags 0x80000101, private key usage 0x200
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] padding.c:642:sc_get_encoding_flags: called
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] padding.c:646:sc_get_encoding_flags: iFlags 0x102, card capabilities 0x80000101
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] padding.c:702:sc_get_encoding_flags: pad flags 0x102, secure algorithm flags 0x1
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] padding.c:703:sc_get_encoding_flags: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.695 [opensc-pkcs11] pkcs15-sec.c:731:sc_pkcs15_compute_signature: DEE flags:0x00000102 alg_info->flags:0x80000101 pad:0x00000102 sec:0x00000001
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] padding.c:567:sc_pkcs1_encode: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] padding.c:573:sc_pkcs1_encode: hash algorithm 0x100, pad algorithm 0x2
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] padding.c:597:sc_pkcs1_encode: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] pkcs15-sec.c:86:select_key_file: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffc386b3652
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:10940; T:0x140056999390720 14:16:14.696 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] pkcs15-sec.c:123:select_key_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffc386b38df
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:10940; T:0x140056999390720 14:16:14.702 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] pkcs15-pin.c:816:sc_pkcs15_pincache_revalidate: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] pkcs15-pin.c:363:sc_pkcs15_verify_pin_with_session_pin: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] pkcs15-pin.c:364:sc_pkcs15_verify_pin_with_session_pin: PIN(type:0; method:1; value(0x55b4717457e0:10)
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffc386b35b2
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:10940; T:0x140056999390720 14:16:14.709 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] sec.c:203:sc_pin_cmd: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card-cardos.c:1501:cardos_pin_cmd: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card-cardos.c:1506:cardos_pin_cmd: PIN_CMD(cmd:0, ref:135)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card-cardos.c:1507:cardos_pin_cmd: PIN1(max:12, min:6)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card-cardos.c:1510:cardos_pin_cmd: PIN2(max:0, min:0)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:20, P1:0, P2:87, data(10) 0x7ffc386b3620
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (15 bytes):
00 20 00 87 0A XX XX XX XX XX XX XX XX XX XX . ...XXXXXXXXXX

P:10940; T:0x140056999390720 14:16:14.717 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] card-cardos.c:1522:cardos_pin_cmd: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] sec.c:259:sc_pin_cmd: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] pkcs15-pin.c:455:sc_pkcs15_verify_pin_with_session_pin: PIN cmd result 0
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] pkcs15-pin.c:761:sc_pkcs15_pincache_add: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] pkcs15-pin.c:805:sc_pkcs15_pincache_add: PIN(Signature-PIN) cached
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] pkcs15-pin.c:477:sc_pkcs15_verify_pin_with_session_pin: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] pkcs15-pin.c:855:sc_pkcs15_pincache_revalidate: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] pkcs15-sec.c:86:select_key_file: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffc386b3652
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:10940; T:0x140056999390720 14:16:14.744 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] pkcs15-sec.c:123:select_key_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffc386b38df
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:10940; T:0x140056999390720 14:16:14.750 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs15-sec.c:169:use_key: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs15-sec.c:771:sc_pkcs15_compute_signature: use_key() failed: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs15-sec.c:784:sc_pkcs15_compute_signature: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] reader-pcsc.c:740:pcsc_unlock: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:4348:pkcs15_prkey_sign: Sign complete. Result -1211.
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:607:sc_pkcs11_signature_final: returning with: 257
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:464:sc_pkcs11_sign_final: returning with: 257
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs11-object.c:745:C_Sign: C_Sign() = CKR_USER_NOT_LOGGED_IN
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:377:sc_pkcs11_sign_init: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:382:sc_pkcs11_sign_init: mechanism 0x1, key-type 0x0
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] misc.c:267:session_start_operation: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] misc.c:268:session_start_operation: Session 0x55b471741d50, type 1
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:504:sc_pkcs11_signature_init: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:4638:pkcs15_prkey_can_do: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:4639:pkcs15_prkey_can_do: check hardware capabilities: CK_MECHANISM_TYPE=0x1 (CKM) and CKF_xxx=0x800
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:4647:pkcs15_prkey_can_do: returning with: 84
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:558:sc_pkcs11_signature_init: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:411:sc_pkcs11_sign_init: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs11-object.c:697:C_SignInit: C_SignInit() = CKR_OK
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 94233485834176: CKA_ALWAYS_AUTHENTICATE = FALSE
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs11-object.c:294:C_GetAttributeValue: C_GetAttributeValue(hSession=0x55b471741d50, hObject=0x55b47172f7c0) = CKR_OK
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:421:sc_pkcs11_sign_update: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:568:sc_pkcs11_signature_update: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:569:sc_pkcs11_signature_update: data part length 8
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:578:sc_pkcs11_signature_update: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:437:sc_pkcs11_sign_update: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] pkcs11-object.c:767:C_SignUpdate: C_SignUpdate() = CKR_OK
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] framework-pkcs15.c:3917:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:10940; T:0x140056999390720 14:16:14.757 [opensc-pkcs11] mechanism.c:653:sc_pkcs11_signature_size: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] mechanism.c:489:sc_pkcs11_sign_size: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] mechanism.c:447:sc_pkcs11_sign_final: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] mechanism.c:588:sc_pkcs11_signature_final: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] framework-pkcs15.c:4180:pkcs15_prkey_sign: Initiating signing operation, mechanism 0x1.
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] reader-pcsc.c:688:pcsc_lock: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] framework-pkcs15.c:4329:pkcs15_prkey_sign: Selected flags 102. Now computing signature for 8 bytes. 512 bytes reserved.
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] pkcs15-sec.c:607:sc_pkcs15_compute_signature: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] pkcs15-sec.c:660:sc_pkcs15_compute_signature: supported algorithm flags 0x80000101, private key usage 0x200
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] padding.c:642:sc_get_encoding_flags: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] padding.c:646:sc_get_encoding_flags: iFlags 0x102, card capabilities 0x80000101
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] padding.c:702:sc_get_encoding_flags: pad flags 0x102, secure algorithm flags 0x1
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] padding.c:703:sc_get_encoding_flags: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] pkcs15-sec.c:731:sc_pkcs15_compute_signature: DEE flags:0x00000102 alg_info->flags:0x80000101 pad:0x00000102 sec:0x00000001
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] padding.c:567:sc_pkcs1_encode: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] padding.c:573:sc_pkcs1_encode: hash algorithm 0x100, pad algorithm 0x2
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] padding.c:597:sc_pkcs1_encode: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] pkcs15-sec.c:86:select_key_file: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffc386b3662
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:10940; T:0x140056999390720 14:16:14.758 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] pkcs15-sec.c:123:select_key_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffc386b38ef
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:10940; T:0x140056999390720 14:16:14.764 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] pkcs15-pin.c:816:sc_pkcs15_pincache_revalidate: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] pkcs15-pin.c:363:sc_pkcs15_verify_pin_with_session_pin: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] pkcs15-pin.c:364:sc_pkcs15_verify_pin_with_session_pin: PIN(type:0; method:1; value(0x55b471747800:10)
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffc386b35c2
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:10940; T:0x140056999390720 14:16:14.771 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] sec.c:203:sc_pin_cmd: called
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card-cardos.c:1501:cardos_pin_cmd: called
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card-cardos.c:1506:cardos_pin_cmd: PIN_CMD(cmd:0, ref:135)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card-cardos.c:1507:cardos_pin_cmd: PIN1(max:12, min:6)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card-cardos.c:1510:cardos_pin_cmd: PIN2(max:0, min:0)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.777 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.778 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:20, P1:0, P2:87, data(10) 0x7ffc386b3630
P:10940; T:0x140056999390720 14:16:14.778 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.778 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (15 bytes):
00 20 00 87 0A XX XX XX XX XX XX XX XX XX XX . ...XXXXXXXXXX

P:10940; T:0x140056999390720 14:16:14.778 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] card-cardos.c:1522:cardos_pin_cmd: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] sec.c:259:sc_pin_cmd: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] pkcs15-pin.c:455:sc_pkcs15_verify_pin_with_session_pin: PIN cmd result 0
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] pkcs15-pin.c:761:sc_pkcs15_pincache_add: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] pkcs15-pin.c:805:sc_pkcs15_pincache_add: PIN(Signature-PIN) cached
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] pkcs15-pin.c:477:sc_pkcs15_verify_pin_with_session_pin: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] pkcs15-pin.c:855:sc_pkcs15_pincache_revalidate: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] pkcs15-sec.c:86:select_key_file: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffc386b3662
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:10940; T:0x140056999390720 14:16:14.804 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.810 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] pkcs15-sec.c:123:select_key_file: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] card.c:471:sc_lock: called
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffc386b38ef
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:10940; T:0x140056999390720 14:16:14.811 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] pkcs15-sec.c:169:use_key: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] pkcs15-sec.c:771:sc_pkcs15_compute_signature: use_key() failed: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] pkcs15-sec.c:784:sc_pkcs15_compute_signature: returning with: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] card.c:523:sc_unlock: called
P:10940; T:0x140056999390720 14:16:14.819 [opensc-pkcs11] reader-pcsc.c:740:pcsc_unlock: called
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] framework-pkcs15.c:4348:pkcs15_prkey_sign: Sign complete. Result -1211.
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1211 (Security status not satisfied)
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] mechanism.c:607:sc_pkcs11_signature_final: returning with: 257
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] mechanism.c:464:sc_pkcs11_sign_final: returning with: 257
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] pkcs11-object.c:809:C_SignFinal: C_SignFinal() = CKR_USER_NOT_LOGGED_IN
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] pkcs11-global.c:415:C_Finalize: C_Finalize()
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] ctx.c:966:sc_cancel: called
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] reader-pcsc.c:790:pcsc_cancel: called
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] slot.c:191:card_removed: Alcor Micro AU9540 00 00: card removed
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x0)
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x0) 1
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] framework-pkcs15.c:1729:pkcs15_release_token: pkcs15_release_token() not implemented
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x1)
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 1
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] pkcs11-session.c:109:sc_pkcs11_close_session: real C_CloseSession(0x55b471741d50)
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] framework-pkcs15.c:1729:pkcs15_release_token: pkcs15_release_token() not implemented
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x2)
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x2) 0
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x3)
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x3) 0
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] sc.c:340:sc_detect_card_presence: called
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] reader-pcsc.c:470:pcsc_detect_card_presence: called
P:10940; T:0x140056999390720 14:16:14.820 [opensc-pkcs11] reader-pcsc.c:362:refresh_attributes: Alcor Micro AU9540 00 00 check
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] reader-pcsc.c:387:refresh_attributes: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] reader-pcsc.c:478:pcsc_detect_card_presence: returning with: 5
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] sc.c:351:sc_detect_card_presence: returning with: 5
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] pkcs15.c:1371:sc_pkcs15_unbind: called
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] pkcs15-pin.c:863:sc_pkcs15_pincache_clear: called
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] card.c:414:sc_disconnect_card: called
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] card-cardos.c:403:cardos_finish: called
P:10940; T:0x140056999390720 14:16:14.821 [opensc-pkcs11] card-cardos.c:411:cardos_finish: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.822 [opensc-pkcs11] reader-pcsc.c:673:pcsc_disconnect: Alcor Micro AU9540 00 00:SCardDisconnect returned: 0x00000000
P:10940; T:0x140056999390720 14:16:14.822 [opensc-pkcs11] card.c:434:sc_disconnect_card: returning with: 0 (Success)
P:10940; T:0x140056999390720 14:16:14.822 [opensc-pkcs11] ctx.c:990:sc_release_context: called
P:10940; T:0x140056999390720 14:16:14.822 [opensc-pkcs11] reader-pcsc.c:977:pcsc_finish: called
error: PKCS11 function C_SignFinal failed: rv = CKR_USER_NOT_LOGGED_IN (0x101)
Aborting.

@jurajsarinay
Copy link
Contributor

doing other operations to the card between

I have come across (not necessarily CardOS based) cards that did not tolerate any SELECT in the sequence VERIFY -> MSE SET -> PSO. In your log there is a SELECT in between due to select_key_file(). There is a path set on the private key.

It should not be a problem, sometimes it is. It should not be necessary either. The appropriate file application will have been selected anyway, as the same path is tied to the corresponding PIN. Also, there is a private key reference in the MSE SET.

Can you please run a test with this single SELECT disabled? For example like this:

diff --git a/src/libopensc/pkcs15-sec.c b/src/libopensc/pkcs15-sec.c
index f408556a..cdbe5836 100644
--- a/src/libopensc/pkcs15-sec.c
+++ b/src/libopensc/pkcs15-sec.c
@@ -140,13 +140,13 @@ static int use_key(struct sc_pkcs15_card *p15card,
        LOG_TEST_RET(p15card->card->ctx, r, "sc_lock() failed");
 
        do {
-               if (path.len != 0 || path.aid.len != 0) {
-                       r = select_key_file(p15card, obj, senv);
-                       if (r < 0) {
-                               sc_log(p15card->card->ctx,
-                                               "Unable to select private key file");
-                       }
-               }
+               /* if (path.len != 0 || path.aid.len != 0) {
+                *      r = select_key_file(p15card, obj, senv);
+                *      if (r < 0) {
+                *              sc_log(p15card->card->ctx,
+                *                              "Unable to select private key file");
+                *      }
+               }*/
                if (r == SC_SUCCESS)
                        r = sc_set_security_env(p15card->card, senv, 0);
 

@jurajsarinay
Copy link
Contributor

I have also come across (CardOS 5.4 based) cards that expected MSE RESTORE instead of MSE SET.

If you have any software (or a PKCS#11 library to use with pks11-tool --module) known to produce signatures, try to run it with pcsc-spy and check how the MSE command should look like.

This log too will contain your PIN code(s), please handle it carefully. Look for a line with an APDU that starts with 00 22. Does it differ from the command OpenSC sends (i.e. 00 22 41 B6 06 84 01 02 95 01 40)?

@hamarituc
Copy link
Contributor Author

Can you please run a test with this single SELECT disabled? For example like this:

Four calls to select_key_file() are now gone from the log, but the result is the same. The caching features from #2784 (comment) are still enabled. Disabling them leads to CKR_OPERATION_NOT_INITIALIZED as initially reported. Here is the log.

Using signature algorithm RSA-PKCS
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:377:sc_pkcs11_sign_init: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:382:sc_pkcs11_sign_init: mechanism 0x1, key-type 0x0
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] misc.c:267:session_start_operation: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] misc.c:268:session_start_operation: Session 0x557fb2f87cf0, type 1
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:504:sc_pkcs11_signature_init: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:4660:pkcs15_prkey_can_do: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:4661:pkcs15_prkey_can_do: check hardware capabilities: CK_MECHANISM_TYPE=0x1 (CKM) and CKF_xxx=0x800
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:4669:pkcs15_prkey_can_do: returning with: 84
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:558:sc_pkcs11_signature_init: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:411:sc_pkcs11_sign_init: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] pkcs11-object.c:697:C_SignInit: C_SignInit() = CKR_OK
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 94006951761760: CKA_ALWAYS_AUTHENTICATE = FALSE
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] pkcs11-object.c:294:C_GetAttributeValue: C_GetAttributeValue(hSession=0x557fb2f87cf0, hObject=0x557fb2f75760) = CKR_OK
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:653:sc_pkcs11_signature_size: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:489:sc_pkcs11_sign_size: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:421:sc_pkcs11_sign_update: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:568:sc_pkcs11_signature_update: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:569:sc_pkcs11_signature_update: data part length 8
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:578:sc_pkcs11_signature_update: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:437:sc_pkcs11_sign_update: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:447:sc_pkcs11_sign_final: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] mechanism.c:588:sc_pkcs11_signature_final: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:4202:pkcs15_prkey_sign: Initiating signing operation, mechanism 0x1.
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] reader-pcsc.c:690:pcsc_lock: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] framework-pkcs15.c:4351:pkcs15_prkey_sign: Selected flags 102. Now computing signature for 8 bytes. 512 bytes reserved.
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] pkcs15-sec.c:607:sc_pkcs15_compute_signature: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] pkcs15-sec.c:660:sc_pkcs15_compute_signature: supported algorithm flags 0x80000101, private key usage 0x200
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] padding.c:642:sc_get_encoding_flags: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] padding.c:646:sc_get_encoding_flags: iFlags 0x102, card capabilities 0x80000101
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] padding.c:702:sc_get_encoding_flags: pad flags 0x102, secure algorithm flags 0x1
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] padding.c:703:sc_get_encoding_flags: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] pkcs15-sec.c:731:sc_pkcs15_compute_signature: DEE flags:0x00000102 alg_info->flags:0x80000101 pad:0x00000102 sec:0x00000001
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] padding.c:567:sc_pkcs1_encode: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] padding.c:573:sc_pkcs1_encode: hash algorithm 0x100, pad algorithm 0x2
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] padding.c:597:sc_pkcs1_encode: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffe2be6510f
P:4509; T:0x140446534069760 14:31:40.348 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.349 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:4509; T:0x140446534069760 14:31:40.349 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] pkcs15-pin.c:816:sc_pkcs15_pincache_revalidate: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] pkcs15-pin.c:363:sc_pkcs15_verify_pin_with_session_pin: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] pkcs15-pin.c:364:sc_pkcs15_verify_pin_with_session_pin: PIN(type:0; method:1; value(0x557fb2f8b780:10)
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffe2be64de2
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:4509; T:0x140446534069760 14:31:40.355 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] sec.c:203:sc_pin_cmd: called
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] card-cardos.c:1501:cardos_pin_cmd: called
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] card-cardos.c:1506:cardos_pin_cmd: PIN_CMD(cmd:0, ref:135)
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] card-cardos.c:1507:cardos_pin_cmd: PIN1(max:12, min:6)
P:4509; T:0x140446534069760 14:31:40.361 [opensc-pkcs11] card-cardos.c:1510:cardos_pin_cmd: PIN2(max:0, min:0)
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:20, P1:0, P2:87, data(10) 0x7ffe2be64e50
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (15 bytes):
00 20 00 87 0A XX XX XX XX XX XX XX XX XX XX . ...XXXXXXXXXX

P:4509; T:0x140446534069760 14:31:40.362 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] card-cardos.c:1522:cardos_pin_cmd: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] sec.c:259:sc_pin_cmd: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] pkcs15-pin.c:455:sc_pkcs15_verify_pin_with_session_pin: PIN cmd result 0
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] pkcs15-pin.c:761:sc_pkcs15_pincache_add: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] pkcs15-pin.c:805:sc_pkcs15_pincache_add: PIN(Signature-PIN) cached
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] pkcs15-pin.c:477:sc_pkcs15_verify_pin_with_session_pin: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] pkcs15-pin.c:855:sc_pkcs15_pincache_revalidate: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffe2be6510f
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:4509; T:0x140446534069760 14:31:40.388 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] pkcs15-sec.c:169:use_key: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] pkcs15-sec.c:771:sc_pkcs15_compute_signature: use_key() failed: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] pkcs15-sec.c:784:sc_pkcs15_compute_signature: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] reader-pcsc.c:742:pcsc_unlock: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] framework-pkcs15.c:4370:pkcs15_prkey_sign: Sign complete. Result -1211.
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] mechanism.c:607:sc_pkcs11_signature_final: returning with: 257
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] mechanism.c:464:sc_pkcs11_sign_final: returning with: 257
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] pkcs11-object.c:745:C_Sign: C_Sign() = CKR_USER_NOT_LOGGED_IN
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] mechanism.c:377:sc_pkcs11_sign_init: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] mechanism.c:382:sc_pkcs11_sign_init: mechanism 0x1, key-type 0x0
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] misc.c:267:session_start_operation: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] misc.c:268:session_start_operation: Session 0x557fb2f87cf0, type 1
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] mechanism.c:504:sc_pkcs11_signature_init: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] framework-pkcs15.c:4660:pkcs15_prkey_can_do: called
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] framework-pkcs15.c:4661:pkcs15_prkey_can_do: check hardware capabilities: CK_MECHANISM_TYPE=0x1 (CKM) and CKF_xxx=0x800
P:4509; T:0x140446534069760 14:31:40.395 [opensc-pkcs11] framework-pkcs15.c:4669:pkcs15_prkey_can_do: returning with: 84
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:558:sc_pkcs11_signature_init: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:411:sc_pkcs11_sign_init: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] pkcs11-object.c:697:C_SignInit: C_SignInit() = CKR_OK
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 94006951761760: CKA_ALWAYS_AUTHENTICATE = FALSE
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] pkcs11-object.c:294:C_GetAttributeValue: C_GetAttributeValue(hSession=0x557fb2f87cf0, hObject=0x557fb2f75760) = CKR_OK
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:421:sc_pkcs11_sign_update: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:568:sc_pkcs11_signature_update: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:569:sc_pkcs11_signature_update: data part length 8
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:578:sc_pkcs11_signature_update: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:437:sc_pkcs11_sign_update: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] pkcs11-object.c:767:C_SignUpdate: C_SignUpdate() = CKR_OK
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] framework-pkcs15.c:3939:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:653:sc_pkcs11_signature_size: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:489:sc_pkcs11_sign_size: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:447:sc_pkcs11_sign_final: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] mechanism.c:588:sc_pkcs11_signature_final: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] framework-pkcs15.c:4202:pkcs15_prkey_sign: Initiating signing operation, mechanism 0x1.
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] reader-pcsc.c:690:pcsc_lock: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] framework-pkcs15.c:4351:pkcs15_prkey_sign: Selected flags 102. Now computing signature for 8 bytes. 512 bytes reserved.
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] pkcs15-sec.c:607:sc_pkcs15_compute_signature: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] pkcs15-sec.c:660:sc_pkcs15_compute_signature: supported algorithm flags 0x80000101, private key usage 0x200
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] padding.c:642:sc_get_encoding_flags: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] padding.c:646:sc_get_encoding_flags: iFlags 0x102, card capabilities 0x80000101
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] padding.c:702:sc_get_encoding_flags: pad flags 0x102, secure algorithm flags 0x1
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] padding.c:703:sc_get_encoding_flags: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] pkcs15-sec.c:731:sc_pkcs15_compute_signature: DEE flags:0x00000102 alg_info->flags:0x80000101 pad:0x00000102 sec:0x00000001
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] padding.c:567:sc_pkcs1_encode: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] padding.c:573:sc_pkcs1_encode: hash algorithm 0x100, pad algorithm 0x2
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] padding.c:597:sc_pkcs1_encode: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffe2be6511f
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:4509; T:0x140446534069760 14:31:40.396 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.405 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:4509; T:0x140446534069760 14:31:40.405 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.405 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.405 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] pkcs15-pin.c:816:sc_pkcs15_pincache_revalidate: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] pkcs15-pin.c:363:sc_pkcs15_verify_pin_with_session_pin: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] pkcs15-pin.c:364:sc_pkcs15_verify_pin_with_session_pin: PIN(type:0; method:1; value(0x557fb2f8d7a0:10)
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f000101
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card-cardos.c:657:cardos_select_file: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:A4, P1:8, P2:C, data(2) 0x7ffe2be64df2
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 A4 08 0C 02 01 01 .......

P:4509; T:0x140446534069760 14:31:40.406 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] iso7816.c:736:iso7816_select_file: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card-cardos.c:661:cardos_select_file: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] sec.c:203:sc_pin_cmd: called
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card-cardos.c:1501:cardos_pin_cmd: called
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card-cardos.c:1506:cardos_pin_cmd: PIN_CMD(cmd:0, ref:135)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card-cardos.c:1507:cardos_pin_cmd: PIN1(max:12, min:6)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card-cardos.c:1510:cardos_pin_cmd: PIN2(max:0, min:0)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.412 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.413 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.413 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:20, P1:0, P2:87, data(10) 0x7ffe2be64e60
P:4509; T:0x140446534069760 14:31:40.413 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.413 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (15 bytes):
00 20 00 87 0A XX XX XX XX XX XX XX XX XX XX . ...XXXXXXXXXX

P:4509; T:0x140446534069760 14:31:40.413 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] card-cardos.c:1522:cardos_pin_cmd: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] sec.c:259:sc_pin_cmd: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] pkcs15-pin.c:455:sc_pkcs15_verify_pin_with_session_pin: PIN cmd result 0
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] pkcs15-pin.c:761:sc_pkcs15_pincache_add: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] pkcs15-pin.c:805:sc_pkcs15_pincache_add: PIN(Signature-PIN) cached
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] pkcs15-pin.c:477:sc_pkcs15_verify_pin_with_session_pin: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] pkcs15-pin.c:855:sc_pkcs15_pincache_revalidate: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] sec.c:108:sc_set_security_env: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] card.c:471:sc_lock: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] apdu.c:367:sc_single_transmit: CLA:0, INS:22, P1:41, P2:B6, data(6) 0x7ffe2be6511f
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Alcor Micro AU9540 00 00'
P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 22 41 B6 06 84 01 02 95 01 40 ."A.......@

P:4509; T:0x140446534069760 14:31:40.439 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
69 82 i.

P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] card-cardos.c:485:cardos_check_sw: required access right not granted
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] card-cardos.c:1030:cardos_set_security_env: Card returned error: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] sec.c:112:sc_set_security_env: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs15-sec.c:169:use_key: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs15-sec.c:771:sc_pkcs15_compute_signature: use_key() failed: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs15-sec.c:784:sc_pkcs15_compute_signature: returning with: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] card.c:523:sc_unlock: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] reader-pcsc.c:742:pcsc_unlock: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] framework-pkcs15.c:4370:pkcs15_prkey_sign: Sign complete. Result -1211.
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: -1211 (Security status not satisfied)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] mechanism.c:607:sc_pkcs11_signature_final: returning with: 257
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] mechanism.c:464:sc_pkcs11_sign_final: returning with: 257
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs11-object.c:809:C_SignFinal: C_SignFinal() = CKR_USER_NOT_LOGGED_IN
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs11-global.c:415:C_Finalize: C_Finalize()
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] ctx.c:966:sc_cancel: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] reader-pcsc.c:792:pcsc_cancel: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] slot.c:191:card_removed: Alcor Micro AU9540 00 00: card removed
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x0)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x0) 1
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] framework-pkcs15.c:1751:pkcs15_release_token: pkcs15_release_token() not implemented
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x1)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x1) 1
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs11-session.c:109:sc_pkcs11_close_session: real C_CloseSession(0x557fb2f87cf0)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] framework-pkcs15.c:1751:pkcs15_release_token: pkcs15_release_token() not implemented
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x2)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x2) 0
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] slot.c:501:slot_token_removed: slot_token_removed(0x3)
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] pkcs11-session.c:145:sc_pkcs11_close_all_sessions: real C_CloseAllSessions(0x3) 0
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] sc.c:340:sc_detect_card_presence: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] reader-pcsc.c:472:pcsc_detect_card_presence: called
P:4509; T:0x140446534069760 14:31:40.446 [opensc-pkcs11] reader-pcsc.c:362:refresh_attributes: Alcor Micro AU9540 00 00 check
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] reader-pcsc.c:387:refresh_attributes: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] reader-pcsc.c:480:pcsc_detect_card_presence: returning with: 1
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] sc.c:351:sc_detect_card_presence: returning with: 1
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] pkcs15.c:1371:sc_pkcs15_unbind: called
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] pkcs15-pin.c:863:sc_pkcs15_pincache_clear: called
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] misc.c:71:sc_to_cryptoki_error_common: libopensc return value: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] card.c:414:sc_disconnect_card: called
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] card-cardos.c:403:cardos_finish: called
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] card-cardos.c:411:cardos_finish: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] reader-pcsc.c:675:pcsc_disconnect: Alcor Micro AU9540 00 00:SCardDisconnect returned: 0x00000000
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] card.c:434:sc_disconnect_card: returning with: 0 (Success)
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] ctx.c:990:sc_release_context: called
P:4509; T:0x140446534069760 14:31:40.448 [opensc-pkcs11] reader-pcsc.c:979:pcsc_finish: called
error: PKCS11 function C_SignFinal failed: rv = CKR_USER_NOT_LOGGED_IN (0x101)
Aborting.

@dengert
Copy link
Member

dengert commented May 28, 2023

Do you have another key on the card that does not require a second pin. Can you try and do the operation with that key.
This newer card might be enforcing a policy on the card that requires no APDUs or only select set of APDUs between the the verify APDU and the 00 22 set command. Any other APDU may be resetting the login state.

As @jurajsarinay suggested using the vendor's PKCS11 module instead of OpenSC and pscd debugging log might show what the vendor does

@hamarituc
Copy link
Contributor Author

Do you have another key on the card that does not require a second pin. Can you try and do the operation with that key.

The card has two certificate. A qualified certificate according to the eIDAS regulation and an advanced certificate. The error is independent of the certificate to use.

This newer card might be enforcing a policy on the card that requires no APDUs or only select set of APDUs between the the verify APDU and the 00 22 set command. Any other APDU may be resetting the login state.

Unfortunately I don't have an older card available.

As @jurajsarinay suggested using the vendor's PKCS11 module instead of OpenSC and pscd debugging log might show what the vendor does

Unfortunately, the reference software crashes with a segmentation violation when used together with pcsc-spy. I need some time to troubleshoot that issue and to get a working APDU sequence. Are there any suggestion what we can try in the meantime?

@hamarituc
Copy link
Contributor Author

As @jurajsarinay suggested using the vendor's PKCS11 module instead of OpenSC and pscd debugging log might show what the vendor does

I didn't got pcsc-spy working. But by starting pcscd in foreground mode I was able to log the relevant APDUs, but without interpretation. The following commands were issued during the signature creation process.

APDU: 00 A4 00 0C
SW: 90 00
APDU: 00 A4 04 0C 06 D2 76 00 00 66 01
SW: 90 00
APDU: 80 CA 00 0B 00
SW: E3 04 90 02 00 00 90 00
APDU: 00 20 00 87
SW: 63 C3
APDU: 00 A4 00 0C
SW: 90 00
APDU: 00 A4 04 0C 06 D2 76 00 00 66 01
SW: 90 00
APDU: 80 CA 00 0B 00
SW: E3 04 90 02 00 00 90 00
APDU: 00 20 00 87
SW: 63 C3
APDU: 00 20 00 87
SW: 63 C3

At this point the software asks to input the PIN. Then the following commands are issued (PIN redacted).

APDU: 00 20 00 87 0A XX XX XX XX XX XX XX XX XX XX
SW: 90 00
APDU: 00 22 F3 19
SW: 90 00  
APDU: 00 2A 9E 9A 00 00 20 1C F7 6E 5B 4E 3D 6B C5 38 DD E4 B9 31 04 23 37 2B CB 9F 45 16 9C CD 73 4D A5 1B 44 76 07 22 20 01 80 
SW: 8D 0E 76 0D 5D 89 44 AF E5 14 28 BE CF 60 9D 8D 0E C5 26 17 BE 19 16 41 D9 CD 91 4B F6 DD 8A 81 3C CE 62 2B 5F 11 F5 ED 3C 7D 81 4E E7 9D 48 48 69 5D 66 6D 78 B1 3D 5E 61 94 1C C1 C4 EB 2C 6C 42 F1 42 79 8F 03 2C 0B BA C1 30 A7 B8 81 81 6B 96 55 8B FE CF 1C 30 B5 51 5B F7 B0 3B 7A 84 ED 9D 54 FC 32 78 E1 2A 2B 14 8F B9 F0 21 69 CC 9F 66 37 13 4D F6 27 C0 41 AD 26 C6 3A 92 A2 CB F7 3A D7 11 5F 1E 7E 91 6E B5 11 1E FE 40 5C 3D CA 8B CE 9E 9D 88 8F 5A EC D4 CE D6 D4 BD 27 CB 99 F8 1C 0A A2 B3 B5 A9 C8 84 26 E6 98 C3 3C 45 70 34 61 49 E2 73 0E 35 E5 31 D5 CB 94 F1 31 2E 13 3B 23 CA 04 58 30 18 E6 9E B9 86 D3 ED 84 29 79 61 2D 24 B3 6D BA 1B 5B 45 CB 05 B3 58 0D 06 FC 37 14 A0 4F 98 CB A0 49 15 55 A0 27 F0 55 20 6A E5 13 0C 03 C2 D7 ED 26 8A D4 7C E9 C5 5D 18 4F 50 78 1E 76 48 D3 34 9D 16 C7 4D C9 B2 13 C9 DC 2F 45 3E 3B 88 B0 4B 8D FB 4C 04 93 BF 98 6A ED 4C 35 52 E5 D1 DF 8A 87 20 B7 B1 ED 9B 68 F2 0C 1B E4 17 8A EB 58 EE 14 2F 4C FE 7E 4B CB E8 51 8A B0 D2 30 B3 C0 F8 1B D5 49 7A 4E FC F5 E9 B8 B9 14 E5 A6 61 BC 8E 14 C0 C9 A8 C3 A9 F0 11 FA 6A BB E7 94 0C A3 18 6F 81 7E 50 37 DD B2 87 38 B4 BF 55 6C 32 F4 02 95 22 11 C0 CC 6E A6 D8 96 90 00

Previously a lot of commands enumerating the certificates of the cards are executed. I skipped that to keep this issue brief. Please tell, if these commands are necessary.

@dengert
Copy link
Member

dengert commented May 29, 2023

This is significant: 00 22 F3 19. I am on vacation any don't have access to ISO docs, but it looks like it may be telling card to use a template that already exists on card, rather then OpenSC sending command to setup a template. @jurajsarinay any ideas?

@jurajsarinay
Copy link
Contributor

This is significant: 00 22 F3 19. I am on vacation any don't have access to ISO docs, but it looks like it may be telling card to use a template that already exists on card

This is indeed MSE RESTORE with a SEID in P2. It is the same pattern as the one followed by skeid (#2672 (comment)), also a CardOS 5.4 card (identical ATR).

I did not feel comfortable adapting card-cardos.c at the time and ended up carving "my" card out (see card-skeid.c).

Given #2296 it appears that D-Trust Card 4.1 and skeid are the only CardOS 5.4 cards one has ever hoped OpenSC to work with. If that were the case, it might make sense to revisit @frankmorgner 's suggestion from #2672 (comment) and dissolve card-skeid.c in a more generic card-cardos.c that also supports D-Trust Card 4.1.

The question is, where the SEID (0x19 for this particular card/key/operation) comes from. In ISO/IEC 7816-15 there is the option to store it within the Private Key CIO (AuthReference.seIdentifier). The fields are indeed present on my skeid card, but as other parts of the CIA appear defective, I hardcoded the SE identifiers within pkcs15-skeid.c.

The Private Key CIO within the log uploaded by @hamarituc appears not to contain any seIdentifier, but it is most likely constant and could simply be hardcoded.

At the moment there is no room for seIdentifier within struct sc_pkcs15_object. The parameter se_num within sc_set_security_env serves a different purpose and appears to always be 0.

@gh47110815
Copy link

Regarding "The question is, where the SEID (0x19 for this particular card/key/operation) comes from."

As far as I understood, "00 22 F3 19" (MSE Restore) is used to select the signing algorithm. For a D-Trust 4.1/4.4 Std. Card "19" is used for Algorithm "RSASSA PSS-MGF1-SHA256".
Another SEIDs could be "1A" (RSASSA PSS-MGF1-SHA384) or "1B" (RSASSA PSS-MGF1-SHA512) and some others for this 4.x Std.
D-Trust is selling a set of cards - using the same ATR - some support RSA others (so called Multi Cards) support ECDSA or ECDH ... My interpretation: To be able to select the signing algorithm for a specific card, MSE RESTORE with different SEIDs is / must be used.

To be honest - I have no clue whether it make sense what I have written above because I am absolute beginner in this area. So be careful with my post - but maybe it helps. If not - just forget :-)

@dengert
Copy link
Member

dengert commented Jun 24, 2023

@gh47110815 It makes a lot of sense. The 19, 1A and 1B tells the card to do the actual PSS padding with what ever info it needs. But card-cardos.c in cardos_init does not set flags = SC_ALGORITHM_PSS to tell OpenSC routines that the card is capable of doing the PSS on the card. But it does set SC_ALGORITHM_RSA. So OpenSC will do the padding in software and tell card to do RAW RSA. The padding.c routine had the logic to do that.

Support to do the PSS on card could be added. It may be needed if this card does not support RSA RAW.

The errors are all Security status not satisfied

@jurajsarinay Your proposed patch may work for your card, but this code is used by many other cards. It must be card specific.

@frankmorgner
Copy link
Member

If anyone would be interested in adding D-Trust Card 4.X to OpenSC, please let me know via mail and I will provide the full the Developer-Handbücher (yes, only available in German).

@tlahn
Copy link

tlahn commented Sep 25, 2023

I also have a D-Trust 4.1 card and cannot get it to work to sign my data and I would really like to see this feature implemented.

I am using Cherry ST-2100 reader and could use Linux and Win10 to do some debugging and / or development. I have a software development background, but all this close to hardware development and smartcard area is completely new to me. So if it helps I could try to support with this matter, but I will surely need quite some time to dig into. German manual is not an issue as I am native German speaker.

@frankmorgner
Copy link
Member

Feel free to contact me via e-mail

@hamarituc
Copy link
Contributor Author

FYI: Based on the documents provided by @frankmorgner I started to work on this issue in the dtrust-branch in my personal repo (https://github.com/hamarituc/OpenSC/tree/dtrust). Currently the driver just implements the card identification procedure. My goal is to get signatures working until end of December 2023 or January 2024.

Comments to the current code are appreciated.

@gh47110815
Copy link

Very, Very cool !!! I think I will not be able to "actively" support your work on "coding" BUT .... I have just cloned your repo, checked out the d-trust branch, did a build and voila ....

./opensc-tool -n
Using reader with a card: REINER SCT cyberJack RFID komfort
D-TRUST Card 4.1 Std. RSA 2ca

./opensc-tool -a
Using reader with a card: REINER SCT cyberJack RFID komfort
3b:d2:18:00:81:31:fe:58:c9:04:11

AND maybe interesting for you: I am using macOS .... so feel free to contact me regarding e.g. testing support and I will try to help.

"Good luck" and thanks in advance !!!

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

Successfully merging a pull request may close this issue.

8 participants
@dengert @frankmorgner @Jakuje @tlahn @hamarituc @gh47110815 @jurajsarinay and others