Page MenuHome GnuPG

GPG: Cancel on pinpad hangs decryption process for 20 seconds
Closed, ResolvedPublic

Description

While testing T4561 I noticed a strange behavior.

When I cancel the pinpad pinentry on my SPR-532 pinpad through the "X" button the decryption process hangs for 20 seconds even though a file was also encrypted to a different key that I had available.

Here is the scdaemon log of this:

With GnuPG 2.2.19 I get an immediate result. Although that seems a bit weird:

./run-decrypt /tmp/test.gpg
run-decrypt: decrypt failed: Operation cancelled
Original file name .: [none]
Wrong key usage ....: no
Legacy w/o MDC ... .: no
Compliance de-vs ...: no
MIME flag ..........: no
Unsupported algo ...: [none]
Session key ........: [none]
Symmetric algorithm : ?.?
Recipient ...: 0
  status ....: Success
  keyid .....: E6850883703145C9
  algo ......: RSA

Details

Version
master

Event Timeline

It is canceled:

2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: RDR_to_PC_DataBlock:
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   dwLength ..........: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSlot .............: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSeq ..............: 19
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bStatus ...........: 64
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bError ............: 239
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: CCID command failed: PIN cancelled
2019-07-05 09:36:41 scdaemon[71407] DBG: dismiss pinpad entry prompt
2019-07-05 09:36:41 scdaemon[71407] DBG: chan_7 -> INQUIRE DISMISSPINPADPROMPT
2019-07-05 09:36:41 scdaemon[71407] DBG: chan_7 <- END
2019-07-05 09:36:41 scdaemon[71407] verify CHV2 failed: Invalid response
2019-07-05 09:36:41 scdaemon[71407] operation decipher result: Invalid response
2019-07-05 09:36:41 scdaemon[71407] app_decipher failed: Invalid response
2019-07-05 09:36:41 scdaemon[71407] DBG: chan_7 -> ERR 100663372 Invalid response <SCD>

After the cancellation, the card reader seems being screwed up:

2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: PC_to_RDR_XfrBlock:
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   dwLength ..........: 9
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSlot .............: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSeq ..............: 20
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bBWI ..............: 0x04
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   wLevelParameter ...: 0x0000
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0010]  00 40 05 00 CA 5F
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0016]  50 00 80
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: bulk-in msg too short (8)
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: sending abort sequence for seqno 20
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: status: 00  error: 00  octet[9]: 00
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: sending abort sequence succeeded
2019-07-05 09:36:41 scdaemon[71407] ccid_transceive failed: (0x10002)
2019-07-05 09:36:41 scdaemon[71407] apdu_send_simple(1) failed: invalid value

It responds somehow, but the content has invalid data of (bChainParameter=0x04):

2019-07-05 09:36:41 scdaemon[71407] DBG: chan_17 -> S LOGIN-DATA aheinecke
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: PC_to_RDR_XfrBlock:
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   dwLength ..........: 9
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSlot .............: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSeq ..............: 21
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bBWI ..............: 0x04
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   wLevelParameter ...: 0x0000
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0010]  00 40 05 00 CA 00
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0016]  6E 00 E1
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: RDR_to_PC_DataBlock:
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   dwLength ..........: 4
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSlot .............: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSeq ..............: 21
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bStatus ...........: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bChainParameter ...: 0x04
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0010]  00 82 00 82
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: PC_to_RDR_XfrBlock:
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   dwLength ..........: 9
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSlot .............: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSeq ..............: 22
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bBWI ..............: 0x04
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   wLevelParameter ...: 0x0000
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0010]  00 40 05 00 CA 00
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0016]  6E 00 E1
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: RDR_to_PC_DataBlock:
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   dwLength ..........: 4
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSlot .............: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSeq ..............: 22
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bStatus ...........: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bChainParameter ...: 0x04
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0010]  00 82 00 82
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver: PC_to_RDR_XfrBlock:
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   dwLength ..........: 9
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSlot .............: 0
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bSeq ..............: 23
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   bBWI ..............: 0x04
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   wLevelParameter ...: 0x0000
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0010]  00 40 05 00 CA 00
2019-07-05 09:36:41 scdaemon[71407] DBG: ccid-driver:   [0016]  6E 00 E1
2019-07-05 09:36:46 scdaemon[71407] DBG: ccid-driver: usb_bulk_read error: LIBUSB_ERROR_TIMEOUT
2019-07-05 09:36:46 scdaemon[71407] ccid_transceive failed: (0x1000a)
2019-07-05 09:36:46 scdaemon[71407] apdu_send_simple(1) failed: card I/O error

And eventurally, get into LIBUSB_ERROR_TIMEOUT.

Finally, with the physical device, I figure out what's going on.
The error handling in bulk_in in ccid-driver.c is not good for pinpad input.
It doesn't return an error when it is cancelled or timeout (for the user interaction).
And it calls libusb_clear_hald which causes screwed up situation.

I'm going to fix this.

gniibe changed the task status from Open to Testing.Nov 27 2020, 7:21 AM
gniibe added a project: Restricted Project.