search

github-af / SmartPGP

SmartPGP is a JavaCard implementation of the OpenPGP card specifications
GNU General Public License v2.0
227 stars 47 forks source link

Default user PIN not accepted #4

Closed sowbug closed 6 years ago

sowbug commented 6 years ago

gpg (GnuPG) 2.2.4 libgcrypt 1.8.2

Ordinary Debian system.

Build tip of tree with jc304. Install on a card supporting 3.0.4.

gpg --card-edit
> verify
[enter 123456]

see following:

Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 2 0 3
Signature counter : 0

I checked Constants.java and confirmed it's as follows:

    protected static final byte[] USER_PIN_DEFAULT = {
        0x31, 0x32, 0x33,0x34, 0x35, 0x36
    };
sowbug commented 6 years ago

I tried rebuilding with the FORMAT_2 versions enabled, and it seemed to get farther, as the verify command works without decrementing the retry counter. However, if I try setting the Admin PIN to something else, it fails with Error changing the PIN: Invalid value.

Same problem with keytocard and the default PIN:

gpg> keytocard
Please select where to store the key:
   (2) Encryption key
Your selection? 2
gpg: KEYTOCARD failed: Invalid value
af-anssi commented 6 years ago

I don't have this problem with the following software configuration: original debian + gnupg 2.2.1 + libgcrypt 1.8.1

I tested the applet on several cards (from several manufacturers) and several readers (in contact and contactless), and I have no such problem. Could you give me some more information:

The "format 2" is intented to be used with a pinpad card reader, but very few are supported by gnupg so I recommend you test with "normal" PIN at first and with a card reader without pinpad (to avoid any problem in case the pinpad is recognized by gnupg).

To check if the good VERIFY command (including the correct PIN value) is sent, you can try the following:

  1. set the following values in ~/.gnupg/scdaemon.conf

    debug-all log-file /tmp/scd.log

  2. kill all instances of gpg-agent and scdaemon; this is needed to ensure the new configuration is applied
  3. retry the verify operation from gpg2 --card-edit
  4. look at the generated /tmp/scd.log to see raw APDU commands and responses

BE CAREFUL: remove ~/.gnupg/scdaemon.conf and /tmp/scd.log files and kill manually all instances of gpg-agent and scdaemon after...

As an alternative, you can launch pcsc daemon manually(pcscd -a -f -d), which will also dump all APDU commands and responses.

Just in case, I will update the code to force the byte cast which is missing in Constants class for PIN values, but this should not be the cause of your issue.

sowbug commented 6 years ago

Thanks for the comprehensive reply. I'll go through the exact steps again tonight and document them. I hope it's a misconfiguration on my side rather than a real bug.

sowbug commented 6 years ago

This is what I found so far:

  1. check out https://github.com/ANSSI-FR/SmartPGP to c2ab8edbe085d52a8676d4ec98da778f2cc93ea5

  2. Also get https://github.com/martinpaljak/oracle_javacard_sdks

  3. edit javacard.properties JAVACARD_HOME=/home/miket/src/oracle_javacard_sdks/jc304_kit

  4. in root of SmartPGP: ant, see BUILD SUCCESSFUL Total time: 1 second

  5. stick in an ACOSJ 40K

$ pcsc_scan
PC/SC device scanner
V 1.4.25 (c) 2001-2011, Ludovic Rousseau <ludovic.rousseau@free.fr>
Compiled with PC/SC lite version: 1.8.14
Using reader plug'n play mechanism
Scanning present readers...
0: Alcor Micro AU9540 00 00

Mon Feb  5 19:21:08 2018
Reader 0: Alcor Micro AU9540 00 00
  Card state: Card inserted, Exclusive Mode, 
  ATR: 3B 69 00 02 41 43 4F 53 4A 76 31 30 31

ATR: 3B 69 00 02 41 43 4F 53 4A 76 31 30 31
+ TS = 3B --> Direct Convention
+ T0 = 69, Y(1): 0110, K: 9 (historical bytes)
  TB(1) = 00 --> VPP is not electrically connected
  TC(1) = 02 --> Extra guard time: 2
+ Historical bytes: 41 43 4F 53 4A 76 31 30 31
  Category indicator byte: 41 (proprietary format)

Possibly identified card (using /home/miket/.cache/smartcard_list.txt):
3B 69 00 02 41 43 4F 53 4A 76 31 30 31
    ACOSJ 40K Dual Interface (JavaCard)

$ gp -info
GlobalPlatformPro v0.3.10rc5-12-gac0b7cc
Running on Linux 4.13.0-32-generic amd64, Java 1.8.0_151 by Oracle Corporation
Reader: Alcor Micro AU9540 00 00
ATR: 3B69000241434F534A76313031
More information about your card:
    http://smartcard-atr.appspot.com/parse?ATR=3B69000241434F534A76313031

Warning: no keys given, using default test key 404142434445464748494A4B4C4D4E4F
***** Card info:
[WARN] GlobalPlatform - GET DATA(CPLC) failed: 0x6A88 (Referenced data not found)
NO CPLC
VER:32 ID:1 TYPE:DES3 LEN:16
VER:32 ID:2 TYPE:DES3 LEN:16
VER:32 ID:3 TYPE:DES3 LEN:16
***** GET DATA:
GET DATA(IIN) not supported0x6A88 (Referenced data not found)
GET DATA(CIN) not supported: 0x6A88 (Referenced data not found)
SSC 0003
*****
***** CARD DATA
Tag 6: 1.2.840.114283.1
-> Global Platform card
Tag 60: 1.2.840.114283.2.2.2.1
-> GP Version: 2.2.1
Tag 63: 1.2.840.114283.3
Tag 64: 1.2.840.114283.4.2.85
-> GP SCP02 i=55
Tag 65: 1.2.840.114283.2.1.3
-> GP Version: 1.3
Tag 66: 1.3.6.1.4.1.42.2.110.1.3
***** KEY INFO
VER:32 ID:1 TYPE:DES3 LEN:16
VER:32 ID:2 TYPE:DES3 LEN:16
VER:32 ID:3 TYPE:DES3 LEN:16

$ gp -list
Warning: no keys given, using default test key 404142434445464748494A4B4C4D4E4F
ISD: A000000151000000 (OP_READY)
     Privs:   SecurityDomain, CardLock, CardTerminate, CardReset, CVMManagement, TrustedPath, AuthorizedManagement, GlobalDelete, GlobalLock, GlobalRegistry, FinalApplication

PKG: A0000001515350 (LOADED)
     Applet:  A000000151535041

$ gp -install /home/miket/src/SmartPGP/build/fr/anssi/smartpgp/javacard/smartpgp.cap -default
Warning: no keys given, using default test key 404142434445464748494A4B4C4D4E4F
CAP loaded

$ gpg --version
gpg (GnuPG) 2.2.4
libgcrypt 1.8.2

$ gpg --card-edit

Reader ...........: Alcor Micro AU9540 00 00
Application ID ...: D276000124010302AFAF000000000000
Version ..........: 3.2
Manufacturer .....: unknown
Serial number ....: 00000000
Name of cardholder: [not set]
Language prefs ...: en
Sex ..............: unspecified
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 0 3
Signature counter : 0
Signature key ....: [none]
Encryption key....: [none]
Authentication key: [none]
General key info..: [none]

gpg/card> verify [enter 123456 on pinentry]

Reader ...........: Alcor Micro AU9540 00 00
Application ID ...: D276000124010302AFAF000000000000
Version ..........: 3.2
Manufacturer .....: unknown
Serial number ....: 00000000
Name of cardholder: [not set]
Language prefs ...: en
Sex ..............: unspecified
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 2 0 3
Signature counter : 0
Signature key ....: [none]
Encryption key....: [none]
Authentication key: [none]
General key info..: [none]

gpg/card> verify [enter 12345678 on pinentry]

Reader ...........: Alcor Micro AU9540 00 00
Application ID ...: D276000124010302AFAF000000000000
Version ..........: 3.2
Manufacturer .....: unknown
Serial number ....: 00000000
Name of cardholder: [not set]
Language prefs ...: en
Sex ..............: unspecified
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 1 0 3
Signature counter : 0
Signature key ....: [none]
Encryption key....: [none]
Authentication key: [none]
General key info..: [none]

$ nano ~/.gnupg/scdaemon.conf [add suggested debug/log commands]
$ killall gpg-agent
$ killall scdaemon
scdaemon: no process found
$ gp -delete D27600012401Warning: no keys given, using default test key 404142434445464748494A4B4C4D4E4F
$ gp -install /home/miket/src/SmartPGP/build/fr/anssi/smartpgp/javacard/smartpgp.cap -default
Warning: no keys given, using default test key 404142434445464748494A4B4C4D4E4F

$ gpg --card-edit
Reader ...........: Alcor Micro AU9540 00 00
Application ID ...: D276000124010302AFAF000000000000
Version ..........: 3.2
Manufacturer .....: unknown
Serial number ....: 00000000
Name of cardholder: [not set]
Language prefs ...: en
Sex ..............: unspecified
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 0 3
Signature counter : 0
Signature key ....: [none]
Encryption key....: [none]
Authentication key: [none]
General key info..: [none]

                ┌──────────────────────────────────────────────┐
                │ Please unlock the card                       │
                │                                              │
                │ Number: AFAF 00000000                        │
                │ Holder:                                      │
                │                                              │
                │ PIN ******__________________________________ │
                │                                              │
                │      <OK>                        <Cancel>    │
                └──────────────────────────────────────────────┘

Fails the same way again. Then cat /tmp/scd.log:

2018-02-05 19:24:23 scdaemon[28802] listening on socket '/run/user/1000/gnupg/S.scdaemon'
2018-02-05 19:24:23 scdaemon[28802] handler for fd -1 started
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 -> OK GNU Privacy Guard's Smartcard server ready
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 <- GETINFO socket_name
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 -> D /run/user/1000/gnupg/S.scdaemon
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 <- OPTION event-signal=12
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 <- GETINFO version
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 -> D 2.2.4
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:24:23 scdaemon[28802] DBG: chan_5 <- SERIALNO openpgp
2018-02-05 19:24:23 scdaemon[28802] DBG: apdu_open_reader: BAI=10f00
2018-02-05 19:24:23 scdaemon[28802] DBG: apdu_open_reader: new device=10f00
2018-02-05 19:24:23 scdaemon[28802] ccid open error: skip
2018-02-05 19:24:23 scdaemon[28802] DBG: enter: apdu_open_reader: portstr=(null)
2018-02-05 19:24:23 scdaemon[28802] detected reader 'Alcor Micro AU9540 00 00'
2018-02-05 19:24:23 scdaemon[28802] reader slot 0: not connected
2018-02-05 19:24:23 scdaemon[28802] DBG: leave: apdu_open_reader => slot=0 [pc/sc]
2018-02-05 19:24:23 scdaemon[28802] DBG: enter: apdu_connect: slot=0
2018-02-05 19:24:23 scdaemon[28802] DBG: feature: code=12, len=4, v=42330012
2018-02-05 19:24:23 scdaemon[28802] DBG: TLV properties: tag=01, len=2, v=00000000
2018-02-05 19:24:23 scdaemon[28802] DBG: TLV properties: tag=03, len=1, v=00000000
2018-02-05 19:24:23 scdaemon[28802] DBG: TLV properties: tag=09, len=1, v=00000000
2018-02-05 19:24:23 scdaemon[28802] DBG: TLV properties: tag=0B, len=2, v=0000058F
2018-02-05 19:24:23 scdaemon[28802] DBG: TLV properties: tag=0C, len=2, v=00009540
2018-02-05 19:24:23 scdaemon[28802] DBG: TLV properties: tag=0A, len=4, v=00010000
2018-02-05 19:24:23 scdaemon[28802] reader slot 0: active protocol: T0
2018-02-05 19:24:23 scdaemon[28802] slot 0: ATR=3B 69 00 02 41 43 4F 53 4A 76 31 30 31
2018-02-05 19:24:23 scdaemon[28802] DBG: leave: apdu_connect => sw=0x0
2018-02-05 19:24:23 scdaemon[28802] DBG: send apdu: c=00 i=A4 p1=00 p2=0C lc=2 le=-1 em=0
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 A4 00 0C 02 3F 00
2018-02-05 19:24:23 scdaemon[28802] DBG:  response: sw=6D00  datalen=0
2018-02-05 19:24:23 scdaemon[28802] DBG: send apdu: c=00 i=A4 p1=04 p2=00 lc=6 le=-1 em=0
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 A4 04 00 06 D2 76 00 01 24 01
2018-02-05 19:24:23 scdaemon[28802] DBG:  response: sw=9000  datalen=0
2018-02-05 19:24:23 scdaemon[28802] DBG:     dump:  
2018-02-05 19:24:23 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=4F lc=-1 le=256 em=0
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 4F 00
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 4F 10
2018-02-05 19:24:23 scdaemon[28802] DBG:  response: sw=9000  datalen=16
2018-02-05 19:24:23 scdaemon[28802] DBG:       dump:  D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00
2018-02-05 19:24:23 scdaemon[28802] AID: D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00
2018-02-05 19:24:23 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=5F p2=52 lc=-1 le=256 em=0
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 5F 52 00
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 5F 52 0A
2018-02-05 19:24:23 scdaemon[28802] DBG:  response: sw=9000  datalen=10
2018-02-05 19:24:23 scdaemon[28802] DBG:       dump:  00 C1 C5 73 C0 01 80 05 90 00
2018-02-05 19:24:23 scdaemon[28802] Historical Bytes: 00 C1 C5 73 C0 01 80 05 90 00
2018-02-05 19:24:23 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=C4 lc=-1 le=256 em=0
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 00
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 07
2018-02-05 19:24:23 scdaemon[28802] DBG:  response: sw=9000  datalen=7
2018-02-05 19:24:23 scdaemon[28802] DBG:       dump:  00 7F 7F 7F 03 00 03
2018-02-05 19:24:23 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E 00
2018-02-05 19:24:23 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E DC
2018-02-05 19:24:24 scdaemon[28802] DBG:  response: sw=9000  datalen=220
2018-02-05 19:24:24 scdaemon[28802] DBG:       dump:  6E 81 D9 4F 10 D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00 5F 52 0A 00 C1 C5 73 C0 01 80 05 90 00 73 81 B7 C0 0A FF 03 00 20 04 80 00 FF 01 00 C1 06 01 08 00 00 11 03 C2 06 01 08 00 00 11 03 C3 06 01 08 00 00 11 03 C4 07 00 7F 7F 7F 03 00 03 C5 3C 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 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 00 00 00 00 00 00 C6 3C 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 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 00 00 00 00 00 00 CD 0C 00 00 00 00 00 00 00 00 00 00 00 00
2018-02-05 19:24:24 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=7F p2=74 lc=-1 le=256 em=0
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 7F 74 00
2018-02-05 19:24:24 scdaemon[28802] DBG:  response: sw=6A88  datalen=0
2018-02-05 19:24:24 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=5E lc=-1 le=256 em=0
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 5E 00
2018-02-05 19:24:24 scdaemon[28802] DBG:  response: sw=9000  datalen=0
2018-02-05 19:24:24 scdaemon[28802] DBG:       dump:  
2018-02-05 19:24:24 scdaemon[28802] Version-2+ .....: yes
2018-02-05 19:24:24 scdaemon[28802] Extcap-v3 ......: yes
2018-02-05 19:24:24 scdaemon[28802] Button .........: no
2018-02-05 19:24:24 scdaemon[28802] SM-Support .....: yes (AES-256)
2018-02-05 19:24:24 scdaemon[28802] Get-Challenge ..: yes (32 bytes max)
2018-02-05 19:24:24 scdaemon[28802] Key-Import .....: yes
2018-02-05 19:24:24 scdaemon[28802] Change-Force-PW1: yes
2018-02-05 19:24:24 scdaemon[28802] Private-DOs ....: yes
2018-02-05 19:24:24 scdaemon[28802] Algo-Attr-Change: yes
2018-02-05 19:24:24 scdaemon[28802] Symmetric Crypto: yes
2018-02-05 19:24:24 scdaemon[28802] KDF-Support ....: yes
2018-02-05 19:24:24 scdaemon[28802] Max-Cert3-Len ..: 1152
2018-02-05 19:24:24 scdaemon[28802] PIN-Block-2 ....: yes
2018-02-05 19:24:24 scdaemon[28802] MSE-Support ....: no
2018-02-05 19:24:24 scdaemon[28802] Max-Special-DOs : 255
2018-02-05 19:24:24 scdaemon[28802] Cmd-Chaining ...: yes
2018-02-05 19:24:24 scdaemon[28802] Ext-Lc-Le ......: no
2018-02-05 19:24:24 scdaemon[28802] Status-Indicator: 05
2018-02-05 19:24:24 scdaemon[28802] GnuPG-No-Sync ..: no
2018-02-05 19:24:24 scdaemon[28802] GnuPG-Def-PW2 ..: no
2018-02-05 19:24:24 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E 00
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E DC
2018-02-05 19:24:24 scdaemon[28802] DBG:  response: sw=9000  datalen=220
2018-02-05 19:24:24 scdaemon[28802] DBG:       dump:  6E 81 D9 4F 10 D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00 5F 52 0A 00 C1 C5 73 C0 01 80 05 90 00 73 81 B7 C0 0A FF 03 00 20 04 80 00 FF 01 00 C1 06 01 08 00 00 11 03 C2 06 01 08 00 00 11 03 C3 06 01 08 00 00 11 03 C4 07 00 7F 7F 7F 03 00 03 C5 3C 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 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 00 00 00 00 00 00 C6 3C 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 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 00 00 00 00 00 00 CD 0C 00 00 00 00 00 00 00 00 00 00 00 00
2018-02-05 19:24:24 scdaemon[28802] Key-Attr-sign ..: RSA, n=2048, e=17, fmt=crt+n
2018-02-05 19:24:24 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E 00
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E DC
2018-02-05 19:24:24 scdaemon[28802] DBG:  response: sw=9000  datalen=220
2018-02-05 19:24:24 scdaemon[28802] DBG:       dump:  6E 81 D9 4F 10 D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00 5F 52 0A 00 C1 C5 73 C0 01 80 05 90 00 73 81 B7 C0 0A FF 03 00 20 04 80 00 FF 01 00 C1 06 01 08 00 00 11 03 C2 06 01 08 00 00 11 03 C3 06 01 08 00 00 11 03 C4 07 00 7F 7F 7F 03 00 03 C5 3C 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 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 00 00 00 00 00 00 C6 3C 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 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 00 00 00 00 00 00 CD 0C 00 00 00 00 00 00 00 00 00 00 00 00
2018-02-05 19:24:24 scdaemon[28802] Key-Attr-encr ..: RSA, n=2048, e=17, fmt=crt+n
2018-02-05 19:24:24 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E 00
2018-02-05 19:24:24 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E DC
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=220
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  6E 81 D9 4F 10 D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00 5F 52 0A 00 C1 C5 73 C0 01 80 05 90 00 73 81 B7 C0 0A FF 03 00 20 04 80 00 FF 01 00 C1 06 01 08 00 00 11 03 C2 06 01 08 00 00 11 03 C3 06 01 08 00 00 11 03 C4 07 00 7F 7F 7F 03 00 03 C5 3C 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 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 00 00 00 00 00 00 C6 3C 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 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 00 00 00 00 00 00 CD 0C 00 00 00 00 00 00 00 00 00 00 00 00
2018-02-05 19:24:25 scdaemon[28802] Key-Attr-auth ..: RSA, n=2048, e=17, fmt=crt+n
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S SERIALNO D276000124010302AFAF000000000000
2018-02-05 19:24:25 scdaemon[28802] DBG: SIGCONT received - breaking select
2018-02-05 19:24:25 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:25 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:25 scdaemon[28802] sending signal 12 to client 28800
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 <- LEARN --force
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S READER Alcor Micro AU9540 00 00
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S SERIALNO D276000124010302AFAF000000000000
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S APPTYPE OPENPGP
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S EXTCAP gc=1+ki=1+fc=1+pd=1+mcl3=1152+aac=1+sm=9+si=5+dec=1+bt=0
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=65 lc=-1 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 65 00
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 65 0B
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=11
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  5B 00 5F 2D 02 65 6E 5F 35 01 39
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S DISP-NAME
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S DISP-LANG en
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S DISP-SEX 9
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=5F p2=50 lc=-1 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 5F 50 00
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=0
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S PUBKEY-URL
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E 00
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E DC
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=220
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  6E 81 D9 4F 10 D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00 5F 52 0A 00 C1 C5 73 C0 01 80 05 90 00 73 81 B7 C0 0A FF 03 00 20 04 80 00 FF 01 00 C1 06 01 08 00 00 11 03 C2 06 01 08 00 00 11 03 C3 06 01 08 00 00 11 03 C4 07 00 7F 7F 7F 03 00 03 C5 3C 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 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 00 00 00 00 00 00 C6 3C 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 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 00 00 00 00 00 00 CD 0C 00 00 00 00 00 00 00 00 00 00 00 00
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=C4 lc=-1 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 00
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 07
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=7
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  00 7F 7F 7F 03 00 03
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S CHV-STATUS +0+127+127+127+3+0+3
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=7A lc=-1 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 7A 00
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 7A 05
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=5
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  93 03 00 00 00
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S SIG-COUNTER 0
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=01 p2=01 lc=-1 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 01 01 00
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=0
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S PRIVATE-DO-1
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=01 p2=02 lc=-1 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 CA 01 02 00
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=9000  datalen=0
2018-02-05 19:24:25 scdaemon[28802] DBG:       dump:  
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S PRIVATE-DO-2
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=47 p1=81 p2=00 lc=2 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 47 81 00 02 B6 00
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=6A80  datalen=0
2018-02-05 19:24:25 scdaemon[28802] reading public key failed: Invalid value
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=47 p1=81 p2=00 lc=2 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 47 81 00 02 B8 00
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=6A80  datalen=0
2018-02-05 19:24:25 scdaemon[28802] reading public key failed: Invalid value
2018-02-05 19:24:25 scdaemon[28802] DBG: send apdu: c=00 i=47 p1=81 p2=00 lc=2 le=256 em=0
2018-02-05 19:24:25 scdaemon[28802] DBG:   PCSC_data: 00 47 81 00 02 A4 00
2018-02-05 19:24:25 scdaemon[28802] DBG:  response: sw=6A80  datalen=0
2018-02-05 19:24:25 scdaemon[28802] reading public key failed: Invalid value
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:24:25 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:25 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 <- GETATTR KEY-ATTR
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S KEY-ATTR 1 1 rsa2048 17 4
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S KEY-ATTR 2 1 rsa2048 17 4
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> S KEY-ATTR 3 1 rsa2048 17 4
2018-02-05 19:24:25 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:24:26 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:26 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:26 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:26 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:27 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:27 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:27 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:27 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:28 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:28 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:28 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:28 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:29 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:29 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:29 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:29 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:30 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:30 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:30 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:30 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:31 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:31 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:31 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:31 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:32 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:32 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:32 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:32 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:33 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:33 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:33 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:33 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:34 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:34 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:34 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:34 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:35 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:35 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:35 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:35 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:36 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:36 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:36 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:36 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:37 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:37 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:37 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:37 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:38 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:38 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:38 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:38 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:39 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:39 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:39 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:39 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:40 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:40 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:40 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:40 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:41 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:41 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:41 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:41 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:42 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:24:42 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:24:42 scdaemon[28802] DBG: chan_5 <- CHECKPIN D276000124010302AFAF000000000000
2018-02-05 19:24:42 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=C4 lc=-1 le=256 em=0
2018-02-05 19:24:42 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 00
2018-02-05 19:24:42 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 07
2018-02-05 19:24:42 scdaemon[28802] DBG:  response: sw=9000  datalen=7
2018-02-05 19:24:42 scdaemon[28802] DBG:       dump:  00 7F 7F 7F 03 00 03
2018-02-05 19:24:42 scdaemon[28802] DBG: check_pcsc_pinpad: command=20, r=27265
2018-02-05 19:24:42 scdaemon[28802] DBG: asking for PIN '||Please unlock the card%0A%0ANumber: AFAF 00000000%0AHolder: '
2018-02-05 19:24:42 scdaemon[28802] DBG: chan_5 -> [ 49 4e 51 55 49 52 45 20 4e 45 45 44 50 49 4e 20 ...(65 byte(s) skipped) ]
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 <- [ 44 20 31 32 33 34 35 36 00 00 00 00 00 00 00 00 ...(76 byte(s) skipped) ]
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 <- END
2018-02-05 19:25:01 scdaemon[28802] DBG: send apdu: c=00 i=20 p1=00 p2=82 lc=6 le=-1 em=0
2018-02-05 19:25:01 scdaemon[28802] DBG:   PCSC_data: 00 20 00 82 06 31 32 33 34 35 36
2018-02-05 19:25:01 scdaemon[28802] DBG:  response: sw=6982  datalen=0
2018-02-05 19:25:01 scdaemon[28802] verify CHV2 failed: Bad PIN
2018-02-05 19:25:01 scdaemon[28802] operation check_pin result: Bad PIN
2018-02-05 19:25:01 scdaemon[28802] app_check_pin failed: Bad PIN
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> ERR 100663383 Bad PIN <SCD>
2018-02-05 19:25:01 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:01 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 <- LEARN --force
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> S READER Alcor Micro AU9540 00 00
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> S SERIALNO D276000124010302AFAF000000000000
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> S APPTYPE OPENPGP
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> S EXTCAP gc=1+ki=1+fc=1+pd=1+mcl3=1152+aac=1+sm=9+si=5+dec=1+bt=0
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> S DISP-NAME
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> S DISP-LANG en
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> S DISP-SEX 9
2018-02-05 19:25:01 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2018-02-05 19:25:01 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E 00
2018-02-05 19:25:01 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 6E DC
2018-02-05 19:25:02 scdaemon[28802] DBG:  response: sw=9000  datalen=220
2018-02-05 19:25:02 scdaemon[28802] DBG:       dump:  6E 81 D9 4F 10 D2 76 00 01 24 01 03 02 AF AF 00 00 00 00 00 00 5F 52 0A 00 C1 C5 73 C0 01 80 05 90 00 73 81 B7 C0 0A FF 03 00 20 04 80 00 FF 01 00 C1 06 01 08 00 00 11 03 C2 06 01 08 00 00 11 03 C3 06 01 08 00 00 11 03 C4 07 00 7F 7F 7F 02 00 03 C5 3C 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 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 00 00 00 00 00 00 C6 3C 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 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 00 00 00 00 00 00 CD 0C 00 00 00 00 00 00 00 00 00 00 00 00
2018-02-05 19:25:02 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=C4 lc=-1 le=256 em=0
2018-02-05 19:25:02 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 00
2018-02-05 19:25:02 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 C4 07
2018-02-05 19:25:02 scdaemon[28802] DBG:  response: sw=9000  datalen=7
2018-02-05 19:25:02 scdaemon[28802] DBG:       dump:  00 7F 7F 7F 02 00 03
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 -> S CHV-STATUS +0+127+127+127+2+0+3
2018-02-05 19:25:02 scdaemon[28802] DBG: send apdu: c=00 i=CA p1=00 p2=7A lc=-1 le=256 em=0
2018-02-05 19:25:02 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 7A 00
2018-02-05 19:25:02 scdaemon[28802] DBG:   PCSC_data: 00 CA 00 7A 05
2018-02-05 19:25:02 scdaemon[28802] DBG:  response: sw=9000  datalen=5
2018-02-05 19:25:02 scdaemon[28802] DBG:       dump:  93 03 00 00 00
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 -> S SIG-COUNTER 0
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 <- GETATTR KEY-ATTR
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 -> S KEY-ATTR 1 1 rsa2048 17 4
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 -> S KEY-ATTR 2 1 rsa2048 17 4
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 -> S KEY-ATTR 3 1 rsa2048 17 4
2018-02-05 19:25:02 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:25:02 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:02 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:02 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:02 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:03 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:03 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:03 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:03 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:04 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:04 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:04 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:04 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:05 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:05 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:05 scdaemon[28802] DBG: chan_5 <- RESTART
2018-02-05 19:25:05 scdaemon[28802] DBG: chan_5 -> OK
2018-02-05 19:25:05 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:05 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
2018-02-05 19:25:06 scdaemon[28802] DBG: enter: apdu_get_status: slot=0 hang=0
2018-02-05 19:25:06 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
[many repetitions removed]
2018-02-05 19:26:36 scdaemon[28802] DBG: leave: apdu_get_status => sw=0x0 status=7
sowbug commented 6 years ago

I think that the 31..36 here means it did send the right PIN:

2018-02-05 19:25:01 scdaemon[28802] DBG: send apdu: c=00 i=20 p1=00 p2=82 lc=6 le=-1 em=0
2018-02-05 19:25:01 scdaemon[28802] DBG:   PCSC_data: 00 20 00 82 06 31 32 33 34 35 36
2018-02-05 19:25:01 scdaemon[28802] DBG:  response: sw=6982  datalen=0
2018-02-05 19:25:01 scdaemon[28802] verify CHV2 failed: Bad PIN
2018-02-05 19:25:01 scdaemon[28802] operation check_pin result: Bad PIN
2018-02-05 19:25:01 scdaemon[28802] app_check_pin failed: Bad PIN
2018-02-05 19:25:01 scdaemon[28802] DBG: chan_5 -> ERR 100663383 Bad PIN <SCD>
af-anssi commented 6 years ago

The verify command is indeed correct.

I suspect a non-standard implementation of the OwnerPIN class on your card. This behaviour should be mentionned in the reference manual of your card. I cannot verify as I cannot access the reference manual in the download section here.

To test this hypothesis, I created a branch named solving-issue-4 where I implemented a fully functional but (very) insecure PIN verification which does not rely on the OwnerPIN class at all.

Could you try this version and tell me if it works ? (I also increased the PIN retry limits to 4 and changed the application ID to clearly identify this version).

sowbug commented 6 years ago

The behavior didn't change:

$ gpg --card-edit
Reader ...........: Alcor Micro AU9540 00 00
Application ID ...: D276000124010302EFEF000000000000
Version ..........: 3.2
Manufacturer .....: unknown
Serial number ....: 00000000
Name of cardholder: [not set]
Language prefs ...: en
Sex ..............: unspecified
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 4 0 4
Signature counter : 0
Signature key ....: [none]
Encryption key....: [none]
Authentication key: [none]
General key info..: [none]

gpg/card> verify

Reader ...........: Alcor Micro AU9540 00 00
Application ID ...: D276000124010302EFEF000000000000
Version ..........: 3.2
Manufacturer .....: unknown
Serial number ....: 00000000
Name of cardholder: [not set]
Language prefs ...: en
Sex ..............: unspecified
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Key attributes ...: rsa2048 rsa2048 rsa2048
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 0 4
Signature counter : 0
Signature key ....: [none]
Encryption key....: [none]
Authentication key: [none]
General key info..: [none]

I'm not sure whether this is intended behavior, but I noticed that if I enter the admin PIN at the verify step (when it's expecting the user PIN), the retry count does not drop. Same behavior if I enter 12345677 (same length as default admin but different). However, I can't change the admin PIN using the default 12345678 -- in that case it decrements the admin retry counter.

Unfortunately I don't have the reference manual, either.

NOTE: I also built https://github.com/Yubico/ykneo-openpgp, and discovered that it has the same problem. It is very unlikely that this is your problem. I'm going to find more GnuPG clients and see if anything works. I also tried with gpg (GnuPG) 2.1.11 and libgcrypt 1.8.2.

If this turns out to be a problem on my side, I apologize for taking up your time!

sowbug commented 6 years ago

Yes, I think this is a problem with my two copies of GnuPG. I was able to load a P-256 (not P-521, which failed) key to your applet using the Android app OpenKeychain. I was also able to load an RSA-2048 using the Yubico applet. I will continue debugging what's wrong with my gpg, but meanwhile I doubt this is a bug on your side.

af-anssi commented 6 years ago

For test/debug purposes, I really suggest you monitor APDU commands and responses at the PCSC level to be as close as possible to what is really sent to the card. Since the card is OK (working with OpenKeychain), and that scdaemon reports that it sends the correct VERIFY, verifying that this is really the command sent to the card reader by PCSC is necessary.

Do you use a contact reader without pinpad ? Because if there is a pinpad, it is possible for the reader to intercept the VERIFY command (which is a standard ISO command) and replace on the fly its data. This is the way pinpad are working actually.

af-anssi commented 6 years ago

For P-521, I have already seen some cards that require to report the EC point size rounded to a multiple of 8 bits, even if this is not compliant with the spec. You thus have to replace 521 by 528 here: https://github.com/ANSSI-FR/SmartPGP/blob/master/src/fr/anssi/smartpgp/ECCurves.java#L54 This is quite simple to test :-)

UPDATE: I added a patch https://github.com/ANSSI-FR/SmartPGP/blob/master/patches/fix_p521_528_bits.patch

sowbug commented 6 years ago

Unfortunately, the patch didn't change the result with OpenKeychain. It seems that these cards are simply a little bit weird. It did work with P-384. Here's what I changed:

$ git diff
diff --git a/src/fr/anssi/smartpgp/ECCurves.java b/src/fr/anssi/smartpgp/ECCurves.java
index b156a3a..0a57b1e 100644
--- a/src/fr/anssi/smartpgp/ECCurves.java
+++ b/src/fr/anssi/smartpgp/ECCurves.java
@@ -51,7 +51,7 @@ public final class ECCurves {
                          (short)1);

         final ECParams ansix9p521r1 =
-            new ECParams((short)521,
+            new ECParams((short)528,
                          ECConstants.ansix9p521r1_oid,
                          ECConstants.ansix9p521r1_field,
                          ECConstants.ansix9p521r1_a,

As for the PIN verification problem, my card reader is a Rocketek RT-SCR1. I also tried a portable reader that I got with my Estonian e-residency card, and it failed the same way. Neither has a pinpad. It seems much more likely that there's something wrong with my copy of GnuPG (note that I built it myself on my Ubuntu machine from tip of tree, so it's possible it's a buggy version).

Thank you very much for your persistence in helping me track down the issues I'm seeing. I will learn more about APDU monitoring, and if I discover anything relevant to your project, I'll update with results.

My goal is simply to program a few OpenPGP cards for my family using P-256 keys (or Curve25519 if the spec is ever implemented to support it). I hadn't intended to become an OpenPGP smart card developer!

af-anssi commented 6 years ago

Be careful with current git master trunk of gnupg, there is an ongoing issue with a feature they did not implemented correctly (KDF for PIN) with could cause the exact problem you have ("Bad PIN value"): https://lists.gnupg.org/pipermail/gnupg-devel/2018-February/033424.html. You can checkout at de3a740c2e1156e58d2f94faa85c051740c8988e, this version is working properly.

For p521, your card does not support it. It supports ECC up to 384 bits https://www.acs.com.hk/en/products/405/acosj-java-card-combi/#features.

sowbug commented 6 years ago

I'm giving up on this for now. I no longer trust anything about my local gnupg installation (even after rebuilding to the commit that you specified, which didn't change the bad PIN behavior). I might install a newer version of Debian or Ubuntu on a test machine that contains a known-good newer version of gnupg than the default 2.1.11 that comes with Ubuntu 16.04. But I don't have an extra machine at the moment.

That's very interesting that the level of support for the NIST curves depends on the card, not just the applet. In most software environments that I've worked in, the hardware is just the architecture, and the software defines the capabilities. I assume that the Java Card environment that is shipped with the smart card is tightly coupled to the hardware because of crypto acceleration, which means that it's more important to pay attention to the "hardware" (the card + its JRE) for questions like P384 vs P521.

breard-r commented 5 years ago

Hi!

I'm having the exact same issue with the same card (ACOSJ 40K Dual) and the latest version of GnuPG. gpg (GnuPG) 2.2.11 libgcrypt 1.8.4

Last week I emailed ACS asking them the reference manual in order to investigate the bug, they didn't answered (yet?). I guess at this point it would be a good idea to have file, wiki entry or anything else listing which cards works and which don't. Anyway, if there's anything I can do to help solve this problem, I would gladly participate.

af-anssi commented 5 years ago

Which reader are you using ? Could you provide the APDU exchanges ? (the easiest way to obtain them is to launch PCSC with the following options pcscd -a -f -d)

af-anssi commented 5 years ago

This problem seems clearly related to the ACOSJ card and/or to the T0 protocol use: https://github.com/jderuiter/javacard-openpgpcard/issues/8. But since the issue is not closed, I don't known if the problem is solved or not.

In SmartPGP the setIncomingAndReceive is already called so it seems not to be enough with the ACOSJ.

breard-r commented 5 years ago

Thank you for your feedback! :) I use a Gemalto IDBridge CT30 reader (a.k.a Gemalto PC Twin Reader) and here is the revelant outout of pcscd:

00000026 winscard_svc.c:832:MSGSendReaderStates() Send reader states: 14
00000158 winscard_svc.c:362:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 14
00000027 winscard_svc.c:440:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 14
12834420 winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 14
00000022 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000005 winscard.c:1601:SCardTransmit() Send Protocol: T=0
00000005 APDU: 00 CA 00 F9 00 
00000011 ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/002/004 (lun: 0)
00033218 SW: 6C 03 
00000027 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000008 winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 14
00000145 winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 14
00000027 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000014 winscard.c:1601:SCardTransmit() Send Protocol: T=0
00000016 APDU: 00 CA 00 F9 03 
00000007 ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/002/004 (lun: 0)
00015173 SW: 81 01 00 90 00 
00000027 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000009 winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 14
00000133 winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 14
00000024 readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000009 winscard.c:1601:SCardTransmit() Send Protocol: T=0
00000010 APDU: 00 24 00 81 0C 31 32 33 34 35 36 36 35 34 33 32 31 
00000007 ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/002/004 (lun: 0)
00044266 SW: 69 82 
00000036 winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000011 winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 14
00000282 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 14

Like it's said in the link you provided, it uses the T=0 protocol. If I grep T= in the whole output, I get this:

00000008 prothandler.c:108:PHSetProtocol() Attempting PTS to T=0
00000008 ifdhandler.c:695:IFDHSetProtocolParameters() protocol T=0, usb:08e6/3437:libudev:0:/dev/bus/usb/002/004 (lun: 0)
00000008 towitoko/atr.c:357:ATR_GetDefaultProtocol() no default protocol found in ATR. Using T=0
00000922 winscard.c:431:SCardConnect() Active Protocol: T=0
00000006 winscard.c:1601:SCardTransmit() Send Protocol: T=0
(last line repeated many times)

I'm quite curious about why the CCID driver doesn't select the T=1 protocol, it's supported by both the card and the reader.

af-anssi commented 5 years ago

I added a test in the test applet to test the PIN. Could you try to install the TestApplet, run the test.py script and post the resutls back ?

breard-r commented 5 years ago

Sure. Here's the results:

[+] Select applet... ok
[+] Test random... ok
[+] Test RSA 1024 static... ok
[+] Test RSA 1024 generate... ok
[+] Test RSA_CRT 1024 static... ok
[+] Test RSA_CRT 1024 generate... ok
[+] Test RSA 2048 static... ok
[+] Test RSA 2048 generate... ok
[+] Test RSA_CRT 2048 static... ok
[+] Test RSA_CRT 2048 generate... ok
[+] Test NIST P-256 static... ok
[+] Test NIST P-256 generate... ok
[-] Test NIST P-521 static... KO 0x6F00
[-] Test NIST P-521 generate... KO 0x6F00
[-] Test NIST P-521 (size = 528) static... KO 0x6F00
[-] Test NIST P-521 (size = 528) generate... KO 0x6F00
[-] Test PIN... KO 0x6504
af-anssi commented 5 years ago

I wrote an alternative version of the PIN test in the TestApplet when T0 protocol is used. Could you try this new version and report the results ? (You can deactivate all other tests in the test.py script)

breard-r commented 5 years ago

Unfortunately, the result is exactly the same :/

breard-r commented 5 years ago

I don't know neither Java nor the JavaCard SDK, however I can extrapolate from what I read. Therefore I started to work on the problem. The first thing I did was to check the correctness of values passed to pin.check() and… bingo! The problem seems to come from apdu.getOffsetCdata() which returns 7 instead of 5. Hard-coding the offset with (short)5 works.

I have no idea why it would return an invalid value only on ACOSJ or if anything else should be taken into consideration. I guess there is a better way to make it works than hard-coding a 5 or -2, but I lack the knowledge to do so.

Anyway, now that I made the TestApplet work on my card, maybe I can manage to get SmartPGP too. I'll try to hack it a little bit.

breard-r commented 5 years ago

Confirmed, I've been able to change the PIN using gpg --change-pin. Here is the diff I used:

diff --git a/src/fr/anssi/smartpgp/SmartPGPApplet.java b/src/fr/anssi/smartpgp/SmartPGPApplet.java
index 98206b1..e84c943 100644
--- a/src/fr/anssi/smartpgp/SmartPGPApplet.java
+++ b/src/fr/anssi/smartpgp/SmartPGPApplet.java
@@ -112,7 +112,9 @@ public final class SmartPGPApplet extends Applet {
         short blen = apdu.setIncomingAndReceive();

         final short lc = apdu.getIncomingLength();
-        final short offcdata = apdu.getOffsetCdata();
+        short offcdata = apdu.getOffsetCdata();
+        offcdata--;
+        offcdata--;

         short off = transients.chainingInputLength();

It still doesn't answer why it behave like this and need more testing to confirm everything works, but still, I'm quite happy. :)

martinpaljak commented 5 years ago

That command should be under all circumstances a short APDU, and getOffsetCdata() seems to return the extended length.

Why not use ISO7816.OFFSET_CDATA instead?

breard-r commented 5 years ago

Yep, it works. Thanx!

diff --git a/src/fr/anssi/smartpgp/SmartPGPApplet.java b/src/fr/anssi/smartpgp/SmartPGPApplet.java
index 98206b1..d67bfbf 100644
--- a/src/fr/anssi/smartpgp/SmartPGPApplet.java
+++ b/src/fr/anssi/smartpgp/SmartPGPApplet.java
@@ -112,7 +112,6 @@ public final class SmartPGPApplet extends Applet {
         short blen = apdu.setIncomingAndReceive();

         final short lc = apdu.getIncomingLength();
-        final short offcdata = apdu.getOffsetCdata();

         short off = transients.chainingInputLength();

@@ -124,10 +123,10 @@ public final class SmartPGPApplet extends Applet {
         }

         while(blen > 0) {
-            off = Util.arrayCopyNonAtomic(apdubuf, offcdata,
+            off = Util.arrayCopyNonAtomic(apdubuf, ISO7816.OFFSET_CDATA,
                                           transients.buffer, off,
                                           blen);
-            blen = apdu.receiveBytes(offcdata);
+            blen = apdu.receiveBytes(ISO7816.OFFSET_CDATA);
         }

         transients.setChainingInputLength(off);
af-anssi commented 5 years ago

It seems actually it is a known bug on this card: https://stackoverflow.com/questions/51295639/acosj-gives-incorrect-result-from-apdu-getoffsetcdata.

Thank you for your work as it is not that easy to find such bug!