scdaemon does not survive suspend/resume with Yubikey4
Open, NormalPublic

Description

I am not using pcscd.

When I perform some card actions (I have mostly tested with 'gpg --card-status' and with signing git commits), and then suspend/resume, the card becomes unusable.

In the logging I see "DBG: raw apdu: 00ca00c400" and "apdu_send_simple(0) failed: unknown status error". Closer examination reveals that send_apdu_ccid returned '0', but also reported '0' for the response length, which cannot be right (since a successful response always has at least 2 status bytes).

Looking with wireshark, I indeed see the "00ca00c400" apdu wrapped in CCID packets, and while normally I see it returning with status 0, error 0, after suspend/resume it returns status 64, error 252.

So it seems somewhere in send_apdu_ccid the fact that this call was unsuccessful is lost.

Resetting the connection with "gpg-connect-agent 'scd reset' /bye" is not sufficient to restore the yubikey to working order, but "gpgconf --kill scdaemon" is.

I have a wireshark file with the monitored CCID exchanges if that is useful.

I encountered this issue with gnupg 2.2.12-1 from Debian, but also saw it when I replaced scdaemon with the one from git master at 3d766924b412b36fc9481803447b93f7fa68b8f6.

This sounds similar to https://dev.gnupg.org/T3825 but I'm not sure if it is the same thing - if so then at least the workaround does not appear to work for me.

raboof created this task.Thu, Jan 3, 9:30 AM
gniibe claimed this task.Fri, Jan 4, 6:16 AM
gniibe triaged this task as Normal priority.
gniibe added a subscriber: gniibe.

The workaround in T3825 is for PC/SC driver. So, it is not the case for internal stock CCID driver.
'scd reset /bye' does not let the scdaemon do reset process of the card itself. It resets the transaction of scdaemon.

Please upload your debug log and wireshark file.

raboof added a comment.EditedFri, Jan 4, 10:53 AM

Attached the wireshark log

Logs inserting card, doing gpg --card-status (succeeds), suspend/resume, gpg --card-status again (seems to succeed shows invalid data, for example '0' for 'Signature counter').

Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00a4000c023f00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00a4040006d27600012401
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca004f00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca5f5200
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00c400
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca006e00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca006e00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca005e00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca006e00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca006e00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca006e00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: sending signal 12 to client 27195
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca006500
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca5f5000
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00c400
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca007a00
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00d600
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00d700
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00d800
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca010100
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca010200
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 0047810002b60000
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00c00000ff
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00c0000011
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 0047810002b80000
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00c00000ff
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00c0000011
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 0047810002a40000
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00c00000ff
Jan  2 22:18:37 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00c0000011
Jan  2 22:18:37 yinka gpg-agent[27195]: card has S/N: D2760001240102010006074066590000
Jan  2 22:20:14 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00c400
Jan  2 22:20:14 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca007a00
Jan  2 22:20:14 yinka gpg-agent[27195]: card has S/N: D2760001240102010006074066590000
Jan  2 22:20:44 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00c400
Jan  2 22:20:44 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca007a00
Jan  2 22:20:44 yinka gpg-agent[27195]: card has S/N: D2760001240102010006074066590000

suspend/resume

Jan  2 22:21:08 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00c400
Jan  2 22:21:08 yinka gpg-agent[27195]: scdaemon[11411]: apdu_send_simple(0) failed: unknown status error
Jan  2 22:21:08 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca007a00
Jan  2 22:21:08 yinka gpg-agent[27195]: scdaemon[11411]: apdu_send_simple(0) failed: unknown status error
Jan  2 22:21:08 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca009300
Jan  2 22:21:08 yinka gpg-agent[27195]: scdaemon[11411]: apdu_send_simple(0) failed: unknown status error
Jan  2 22:21:08 yinka gpg-agent[27195]: card has S/N: D2760001240102010006074066590000
Jan  2 22:21:12 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca00c400
Jan  2 22:21:12 yinka gpg-agent[27195]: scdaemon[11411]: apdu_send_simple(0) failed: unknown status error
Jan  2 22:21:12 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca007a00
Jan  2 22:21:12 yinka gpg-agent[27195]: scdaemon[11411]: apdu_send_simple(0) failed: unknown status error
Jan  2 22:21:12 yinka gpg-agent[27195]: scdaemon[11411]: DBG:  raw apdu: 00ca009300
gniibe added a comment.Mon, Jan 7, 6:06 AM

Thanks a lot for your logs. I see what's going on here.
For some reason, Yubikey keeps running after failure by suspend/resume (perhaps, because it serves for multiple functionalities of USB HID for OTP, as well as CCID for OpenPGPcard).
This failure mode is not expected by the current implementation of scdaemon, under in-stock CCID driver.

There are two ways fixing this problem:
(1) Fix scdaemon code (possibly all code), for failures to reset smart card
(2) Fix the detection of suspend/resume

Ideally, (1) is needed, but impact would be bigger. So, if possible, I'd like to take the way of (2).
According to your wireshark log, I found USB INTERRUPT packet returns -ESHUTDOWN. I think that we can use this event to detect suspend/resume problem.
Currently, in ccid-driver.c, when intr_cb function is called (for -ESHUTDOWN, thus LIBUSB_TRANSFER_NO_DEVICE), it expects further request should fail.
But for Yubikey, it seems it accepts the request of USB INTERRUPT. I'm going to change this code now (for experiment now) to see if it's OK for other cases.
Let's see. Please wait.