Page MenuHome GnuPG
Create Task
Maniphest T5971

Yubikey: Removal of device is not detected by PC/SC
Open, NormalPublic
Actions

Description

Since 2022-02 or so, second time insertion of Yubikey doesn't work.

Looking the debug log, it seems that PC/SC doesn't detect the USB device removal and scdaemon cannot know the removal.

Related Objects
Search...

Event Timeline

• gniibe triaged this task as Normal priority.May 10 2022, 2:51 AM
• gniibe created this task.
• gniibe mentioned this in T5963: Yubikey: scdaemon causes libc segfault and clashes with ECC keys.May 10 2022, 3:48 AM
• gniibe removed a project: gnupg.May 10 2022, 7:00 AM
oddlama added a comment.EditedMay 10 2022, 10:17 PM

I've uploaded the requested information with triple verbose and debug-all setting in the scdaemon.conf as scdaemon.log:

scdaemon.log32 KBDownload

It seems my laptop destroys the whole host controller when the yubikey is removed from the only usb-c thunderbolt slot.
The related pcscd issue that I created and linked to in my original post has also had trouble with it. My system is not special,
just a freshly installed gentoo with official distribution kernel for reproducibility.

When I remove my yubikey:

[141704.902634] usb 3-1: USB disconnect, device number 2
[141704.974096] xhci_hcd 0000:3d:00.0: xHCI host controller not responding, assume dead
[141704.974104] xhci_hcd 0000:3d:00.0: HC died; cleaning up
[141704.974407] pcieport 0000:00:1d.0: pciehp: Slot(16): Link Down
[141704.974409] pcieport 0000:00:1d.0: pciehp: Slot(16): Card not present
[141704.974428] xhci_hcd 0000:3d:00.0: remove, state 4
[141704.974430] usb usb4: USB disconnect, device number 1
[141704.974854] xhci_hcd 0000:3d:00.0: USB bus 4 deregistered
[141704.974961] xhci_hcd 0000:3d:00.0: remove, state 1
[141704.974962] usb usb3: USB disconnect, device number 1
[141705.138746] xhci_hcd 0000:3d:00.0: Host halt failed, -19
[141705.138751] xhci_hcd 0000:3d:00.0: Host not accessible, reset failed.
[141705.138846] xhci_hcd 0000:3d:00.0: USB bus 3 deregistered
[141705.139110] pcieport 0000:06:01.0: can't change power state from D3cold to D0 (config space inaccessible)
[141705.139211] pcieport 0000:06:00.0: can't change power state from D3cold to D0 (config space inaccessible)
[141705.139370] pci_bus 0000:07: busn_res: [bus 07] is released
[141705.139597] pci_bus 0000:08: busn_res: [bus 08-3c] is released
[141705.141356] pci_bus 0000:3d: busn_res: [bus 3d] is released
[141705.141467] pci_bus 0000:06: busn_res: [bus 06-3d] is released

When I re-insert it:

[141680.254240] pcieport 0000:00:1d.0: pciehp: Slot(16): Card present
[141680.254244] pcieport 0000:00:1d.0: pciehp: Slot(16): Link Up
[141680.386780] pci 0000:05:00.0: [8086:15da] type 01 class 0x060400
[141680.386914] pci 0000:05:00.0: enabling Extended Tags
[141680.387177] pci 0000:05:00.0: supports D1 D2
[141680.387183] pci 0000:05:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[141680.387730] pci 0000:05:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[141680.387998] pci 0000:06:00.0: [8086:15da] type 01 class 0x060400
[141680.388123] pci 0000:06:00.0: enabling Extended Tags
[141680.388367] pci 0000:06:00.0: supports D1 D2
[141680.388371] pci 0000:06:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[141680.388752] pci 0000:06:01.0: [8086:15da] type 01 class 0x060400
[141680.388879] pci 0000:06:01.0: enabling Extended Tags
[141680.389117] pci 0000:06:01.0: supports D1 D2
[141680.389121] pci 0000:06:01.0: PME# supported from D0 D1 D2 D3hot D3cold
[141680.389439] pci 0000:06:02.0: [8086:15da] type 01 class 0x060400
[141680.389558] pci 0000:06:02.0: enabling Extended Tags
[141680.389783] pci 0000:06:02.0: supports D1 D2
[141680.389786] pci 0000:06:02.0: PME# supported from D0 D1 D2 D3hot D3cold
[141680.391537] pci 0000:05:00.0: PCI bridge to [bus 06-3d]
[141680.391567] pci 0000:05:00.0:   bridge window [io  0x0000-0x0fff]
[141680.391585] pci 0000:05:00.0:   bridge window [mem 0x00000000-0x000fffff]
[141680.391603] pci 0000:05:00.0:   bridge window [mem 0x00000000-0x000fffff 64bit pref]
[141680.391612] pci 0000:06:00.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[141680.391634] pci 0000:06:01.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[141680.391653] pci 0000:06:02.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[141680.391857] pci 0000:06:00.0: PCI bridge to [bus 07-3d]
[141680.391882] pci 0000:06:00.0:   bridge window [io  0x0000-0x0fff]
[141680.391893] pci 0000:06:00.0:   bridge window [mem 0x00000000-0x000fffff]
[141680.391909] pci 0000:06:00.0:   bridge window [mem 0x00000000-0x000fffff 64bit pref]
[141680.391915] pci_bus 0000:07: busn_res: [bus 07-3d] end is updated to 07
[141680.392062] pci 0000:06:01.0: PCI bridge to [bus 08-3d]
[141680.392079] pci 0000:06:01.0:   bridge window [io  0x0000-0x0fff]
[141680.392089] pci 0000:06:01.0:   bridge window [mem 0x00000000-0x000fffff]
[141680.392105] pci 0000:06:01.0:   bridge window [mem 0x00000000-0x000fffff 64bit pref]
[141680.392110] pci_bus 0000:08: busn_res: [bus 08-3d] end is updated to 3c
[141680.392345] pci 0000:3d:00.0: [8086:15db] type 00 class 0x0c0330
[141680.392391] pci 0000:3d:00.0: reg 0x10: [mem 0x00000000-0x0000ffff]
[141680.392744] pci 0000:3d:00.0: supports D1 D2
[141680.392749] pci 0000:3d:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[141680.392919] pci 0000:3d:00.0: 8.000 Gb/s available PCIe bandwidth, limited by 2.5 GT/s PCIe x4 link at 0000:06:02.0 (capable of 31.504 Gb/s with 8.0 GT/s PCIe x4 link)
[141680.394783] pci 0000:06:02.0: PCI bridge to [bus 3d]
[141680.394808] pci 0000:06:02.0:   bridge window [io  0x0000-0x0fff]
[141680.394819] pci 0000:06:02.0:   bridge window [mem 0x00000000-0x000fffff]
[141680.394834] pci 0000:06:02.0:   bridge window [mem 0x00000000-0x000fffff 64bit pref]
[141680.394840] pci_bus 0000:3d: busn_res: [bus 3d] end is updated to 3d
[141680.394855] pci_bus 0000:06: busn_res: [bus 06-3d] end is updated to 3d
[141680.394871] pci 0000:06:01.0: bridge window [mem 0x00100000-0x001fffff 64bit pref] to [bus 08-3c] add_size 100000 add_align 100000
[141680.394879] pci 0000:06:01.0: bridge window [mem 0x00100000-0x001fffff] to [bus 08-3c] add_size 100000 add_align 100000
[141680.394889] pci 0000:05:00.0: bridge window [mem 0x00100000-0x003fffff 64bit pref] to [bus 06-3d] add_size 100000 add_align 100000
[141680.394896] pci 0000:05:00.0: bridge window [mem 0x00100000-0x003fffff] to [bus 06-3d] add_size 100000 add_align 100000
[141680.394910] pci 0000:05:00.0: BAR 14: assigned [mem 0x94000000-0xaa0fffff]
[141680.394918] pci 0000:05:00.0: BAR 15: assigned [mem 0x50000000-0x71ffffff 64bit pref]
[141680.394924] pci 0000:05:00.0: BAR 13: assigned [io  0x6000-0x7fff]
[141680.394935] pci 0000:06:00.0: BAR 14: assigned [mem 0x94000000-0x940fffff]
[141680.394941] pci 0000:06:00.0: BAR 15: assigned [mem 0x50000000-0x500fffff 64bit pref]
[141680.394946] pci 0000:06:01.0: BAR 14: assigned [mem 0x94100000-0xa9ffffff]
[141680.394952] pci 0000:06:01.0: BAR 15: assigned [mem 0x50100000-0x71efffff 64bit pref]
[141680.394957] pci 0000:06:02.0: BAR 14: assigned [mem 0xaa000000-0xaa0fffff]
[141680.394962] pci 0000:06:02.0: BAR 15: assigned [mem 0x71f00000-0x71ffffff 64bit pref]
[141680.394967] pci 0000:06:00.0: BAR 13: assigned [io  0x6000-0x6fff]
[141680.394972] pci 0000:06:01.0: BAR 13: assigned [io  0x7000-0x7fff]
[141680.394976] pci 0000:06:02.0: BAR 13: no space for [io  size 0x1000]
[141680.394981] pci 0000:06:02.0: BAR 13: failed to assign [io  size 0x1000]
[141680.394989] pci 0000:06:00.0: PCI bridge to [bus 07]
[141680.395000] pci 0000:06:00.0:   bridge window [io  0x6000-0x6fff]
[141680.395013] pci 0000:06:00.0:   bridge window [mem 0x94000000-0x940fffff]
[141680.395023] pci 0000:06:00.0:   bridge window [mem 0x50000000-0x500fffff 64bit pref]
[141680.395039] pci 0000:06:01.0: PCI bridge to [bus 08-3c]
[141680.395045] pci 0000:06:01.0:   bridge window [io  0x7000-0x7fff]
[141680.395058] pci 0000:06:01.0:   bridge window [mem 0x94100000-0xa9ffffff]
[141680.395068] pci 0000:06:01.0:   bridge window [mem 0x50100000-0x71efffff 64bit pref]
[141680.395085] pci 0000:3d:00.0: BAR 0: assigned [mem 0xaa000000-0xaa00ffff]
[141680.395103] pci 0000:06:02.0: PCI bridge to [bus 3d]
[141680.395116] pci 0000:06:02.0:   bridge window [mem 0xaa000000-0xaa0fffff]
[141680.395126] pci 0000:06:02.0:   bridge window [mem 0x71f00000-0x71ffffff 64bit pref]
[141680.395141] pci 0000:05:00.0: PCI bridge to [bus 06-3d]
[141680.395147] pci 0000:05:00.0:   bridge window [io  0x6000-0x7fff]
[141680.395159] pci 0000:05:00.0:   bridge window [mem 0x94000000-0xaa0fffff]
[141680.395169] pci 0000:05:00.0:   bridge window [mem 0x50000000-0x71ffffff 64bit pref]
[141680.395185] pcieport 0000:00:1d.0: PCI bridge to [bus 05-3d]
[141680.395192] pcieport 0000:00:1d.0:   bridge window [io  0x6000-0x7fff]
[141680.395204] pcieport 0000:00:1d.0:   bridge window [mem 0x94000000-0xaa0fffff]
[141680.395214] pcieport 0000:00:1d.0:   bridge window [mem 0x50000000-0x71ffffff 64bit pref]
[141680.395230] PCI: No. 2 try to assign unassigned res
[141680.395233] pci 0000:06:00.0: resource 13 [io  0x6000-0x6fff] released
[141680.395238] pci 0000:06:00.0: PCI bridge to [bus 07]
[141680.395257] pci 0000:06:01.0: resource 13 [io  0x7000-0x7fff] released
[141680.395262] pci 0000:06:01.0: PCI bridge to [bus 08-3c]
[141680.395282] pci 0000:05:00.0: resource 13 [io  0x6000-0x7fff] released
[141680.395286] pci 0000:05:00.0: PCI bridge to [bus 06-3d]
[141680.395313] pci 0000:05:00.0: BAR 13: assigned [io  0x6000-0x7fff]
[141680.395320] pci 0000:06:00.0: BAR 13: assigned [io  0x6000-0x6fff]
[141680.395324] pci 0000:06:01.0: BAR 13: assigned [io  0x7000-0x7fff]
[141680.395329] pci 0000:06:02.0: BAR 13: no space for [io  size 0x1000]
[141680.395333] pci 0000:06:02.0: BAR 13: failed to assign [io  size 0x1000]
[141680.395341] pci 0000:06:00.0: PCI bridge to [bus 07]
[141680.395352] pci 0000:06:00.0:   bridge window [io  0x6000-0x6fff]
[141680.395364] pci 0000:06:00.0:   bridge window [mem 0x94000000-0x940fffff]
[141680.395374] pci 0000:06:00.0:   bridge window [mem 0x50000000-0x500fffff 64bit pref]
[141680.395390] pci 0000:06:01.0: PCI bridge to [bus 08-3c]
[141680.395396] pci 0000:06:01.0:   bridge window [io  0x7000-0x7fff]
[141680.395408] pci 0000:06:01.0:   bridge window [mem 0x94100000-0xa9ffffff]
[141680.395417] pci 0000:06:01.0:   bridge window [mem 0x50100000-0x71efffff 64bit pref]
[141680.395433] pci 0000:06:02.0: PCI bridge to [bus 3d]
[141680.395445] pci 0000:06:02.0:   bridge window [mem 0xaa000000-0xaa0fffff]
[141680.395455] pci 0000:06:02.0:   bridge window [mem 0x71f00000-0x71ffffff 64bit pref]
[141680.395470] pci 0000:05:00.0: PCI bridge to [bus 06-3d]
[141680.395477] pci 0000:05:00.0:   bridge window [io  0x6000-0x7fff]
[141680.395489] pci 0000:05:00.0:   bridge window [mem 0x94000000-0xaa0fffff]
[141680.395499] pci 0000:05:00.0:   bridge window [mem 0x50000000-0x71ffffff 64bit pref]
[141680.395514] pcieport 0000:00:1d.0: PCI bridge to [bus 05-3d]
[141680.395520] pcieport 0000:00:1d.0:   bridge window [io  0x6000-0x7fff]
[141680.395532] pcieport 0000:00:1d.0:   bridge window [mem 0x94000000-0xaa0fffff]
[141680.395542] pcieport 0000:00:1d.0:   bridge window [mem 0x50000000-0x71ffffff 64bit pref]
[141680.395640] pcieport 0000:05:00.0: enabling device (0000 -> 0003)
[141680.396109] pcieport 0000:06:00.0: enabling device (0000 -> 0003)
[141680.398729] pcieport 0000:06:01.0: enabling device (0000 -> 0003)
[141680.399871] pcieport 0000:06:01.0: pciehp: Slot #1 AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug+ Surprise+ Interlock- NoCompl+ IbPresDis- LLActRep+
[141680.400826] pcieport 0000:06:02.0: enabling device (0000 -> 0002)
[141680.401659] pci 0000:3d:00.0: enabling device (0000 -> 0002)
[141680.402225] xhci_hcd 0000:3d:00.0: xHCI Host Controller
[141680.402369] xhci_hcd 0000:3d:00.0: new USB bus registered, assigned bus number 3
[141680.403676] xhci_hcd 0000:3d:00.0: hcc params 0x200077c1 hci version 0x110 quirks 0x0000000200009810
[141680.404131] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.17
[141680.404141] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[141680.404147] usb usb3: Product: xHCI Host Controller
[141680.404152] usb usb3: Manufacturer: Linux 5.17.4-gentoo-dist xhci-hcd
[141680.404156] usb usb3: SerialNumber: 0000:3d:00.0
[141680.405751] hub 3-0:1.0: USB hub found
[141680.405779] hub 3-0:1.0: 2 ports detected
[141680.406350] xhci_hcd 0000:3d:00.0: xHCI Host Controller
[141680.406460] xhci_hcd 0000:3d:00.0: new USB bus registered, assigned bus number 4
[141680.406468] xhci_hcd 0000:3d:00.0: Host supports USB 3.1 Enhanced SuperSpeed
[141680.406563] usb usb4: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.17
[141680.406589] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[141680.406594] usb usb4: Product: xHCI Host Controller
[141680.406598] usb usb4: Manufacturer: Linux 5.17.4-gentoo-dist xhci-hcd
[141680.406602] usb usb4: SerialNumber: 0000:3d:00.0
[141680.409205] hub 4-0:1.0: USB hub found
[141680.409234] hub 4-0:1.0: 2 ports detected
[141680.653349] usb 3-1: new full-speed USB device number 2 using xhci_hcd
[141680.795723] usb 3-1: New USB device found, idVendor=1050, idProduct=0407, bcdDevice= 5.27
[141680.795739] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[141680.795746] usb 3-1: Product: YubiKey OTP+FIDO+CCID
[141680.795751] usb 3-1: Manufacturer: Yubico
[141680.800388] input: Yubico YubiKey OTP+FIDO+CCID as /devices/pci0000:00/0000:00:1d.0/0000:05:00.0/0000:06:02.0/0000:3d:00.0/usb3/3-1/3-1:1.0/0003:1050:0407.003D/input/input61
[141680.857342] hid-generic 0003:1050:0407.003D: input,hidraw4: USB HID v1.10 Keyboard [Yubico YubiKey OTP+FIDO+CCID] on usb-0000:3d:00.0-1/input0
[141680.858671] hid-generic 0003:1050:0407.003E: hiddev99,hidraw5: USB HID v1.10 Device [Yubico YubiKey OTP+FIDO+CCID] on usb-0000:3d:00.0-1/input1
• gniibe added a comment.EditedMay 11 2022, 1:50 AM

Thank you for the logs. It seems that scdaemon didn't detect the removal correctly.

Examining the logs in detail, IIUC, I think that you only applied the patch: rG385f4841330e: scd:openpgp: Fix a segv for cards supporting unknown curves.
The patch of mine which workaround the initial failure of Yubikey is: rG054d14887ef8: scd: Add workaround for ECC attribute on Yubikey.

Although those patches cannot fix the fundamental problem of detecting the removal of USB device, it may improve the situation around the failure.

So, if it is the case, please try the second patch (which is in master already), to see if it changes the situation, hopefully better side.

oddlama added a comment.EditedMay 11 2022, 12:49 PM

I'm certain I've applied the patches correctly. This is my current patchset:

diff --git a/common/openpgp-oid.c b/common/openpgp-oid.c
index 0189407f8..f0460b068 100644
--- a/common/openpgp-oid.c
+++ b/common/openpgp-oid.c
@@ 656,24 +658,24 @@
       for (i=0; i < keyalgo_strings_used; i++)
         {
           if (keyalgo_strings[i].algo == algo
-              && keyalgo_strings[i].curve
+              && keyalgo_strings[i].curve && curve
               && !strcmp (keyalgo_strings[i].curve, curve))
             return keyalgo_strings[i].name;
         }

       /* Not yet in the table - add it.  */
       curvename = openpgp_oid_or_name_to_curve (curve, 0);
       if (curvename)
         name = xasprintf ("%s", curvename);
       else if (curve)
         name = xasprintf ("E_%s", curve);
       else
         name = xasprintf ("E_error");
       nbits = 0;
-      curvebuf = xstrdup (curve);
+      curvebuf = curve? xstrdup (curve) : NULL;
     }
   else
     {
       for (i=0; i < keyalgo_strings_used; i++)
         {
           if (keyalgo_strings[i].algo == algo
diff --git a/scd/app-openpgp.c b/scd/app-openpgp.c
index d4439e7c3..7dc98aa75 100644
--- a/scd/app-openpgp.c
+++ b/scd/app-openpgp.c
@@ 6219,13 +6221,14 @@
   else if (*buffer == PUBKEY_ALGO_ECDH || *buffer == PUBKEY_ALGO_ECDSA
            || *buffer == PUBKEY_ALGO_EDDSA)
     {
       int oidlen = buflen - 1;

       app->app_local->keyattr[keyno].ecc.algo = *buffer;
       app->app_local->keyattr[keyno].ecc.flags = 0;

-      if (buffer[buflen-1] == 0x00 || buffer[buflen-1] == 0xff)
+      if (APP_CARD(app)->cardtype == CARDTYPE_YUBIKEY
+         || buffer[buflen-1] == 0x00 || buffer[buflen-1] == 0xff)
         { /* Found "pubkey required"-byte for private key template.  */
           oidlen--;
           if (buffer[buflen-1] == 0xff)
             app->app_local->keyattr[keyno].ecc.flags |= ECC_FLAG_PUBKEY;
• gniibe added a comment.May 12 2022, 1:43 AM

Umm... The problem is the last bogus octet from Yubikey. In the log, we see:

2022-05-10 22:09:58 scdaemon[961424] DBG: Curve with OID not supported:  2b06010401da470f01f9
2022-05-10 22:09:58 scdaemon[961424] Key-Algo-sign ..: E_error
2022-05-10 22:09:58 scdaemon[961424] Key-Attr-encr ..:
2022-05-10 22:09:58 scdaemon[961424] DBG: Curve with OID not supported:  2b060104019755010501c8
2022-05-10 22:09:58 scdaemon[961424] Key-Algo-encr ..: E_error
2022-05-10 22:09:58 scdaemon[961424] Key-Attr-auth ..:
2022-05-10 22:09:58 scdaemon[961424] DBG: Curve with OID not supported:  2b06010401da470f0159
2022-05-10 22:09:58 scdaemon[961424] Key-Algo-auth ..: E_error

The patch of mine is to ignore (when it's Yubikey) such octets like f9, c8, and 59 in the log. But it seems that it is not ignored (as my expected).

In the log, we see:

2022-05-10 22:09:58 scdaemon[961424] DBG: send apdu: c=00 i=A4 p1=04 p2=00 lc=8 le=-1 em=0
2022-05-10 22:09:58 scdaemon[961424] DBG:   PCSC_data: 00a4040008a000000527471117
2022-05-10 22:09:58 scdaemon[961424] DBG:  response: sw=9000  datalen=30
2022-05-10 22:09:58 scdaemon[961424] DBG:      dump: 5669727475616c206d6772202d2046572076657273696f6e20352e322e37
2022-05-10 22:09:58 scdaemon[961424] DBG:   PCSC_data: 001d000000
2022-05-10 22:09:58 scdaemon[961424] DBG:  response: sw=9000  datalen=47
2022-05-10 22:09:58 scdaemon[961424] DBG:       dump:  2e0102023f0302023f020400e812d604010305030502070602000007010f0801 \
2022-05-10 22:09:58 scdaemon[961424] DBG:  000d02023f0e02023b0a01000f01009000
2022-05-10 22:09:58 scdaemon[961424] Yubico: config=2e0102023f0302023f020400e812d604010305030502070602000007010f0801000d02023f0e02023b0a01000f0100

So, I think that the condition CARDTYPE_YUBIKEY meets.

Something (other) is going wrong...

oddlama added a comment.EditedMay 12 2022, 12:36 PM

In case you need any information, be sure to let me know. Maybe we can add some manual loggers to the patches, to confirm that everything is working as you imagine it to?

• gniibe added a comment.May 12 2022, 5:19 PM

Please do experiment again and give us the whole log of scdaemon.log for:

  • insert Yubikey initially
  • run gpg --card-status (success is expected)
  • remove Yubikey
  • insert Yubikey second time
  • run gpg --card-status (failure is expected)

What I need is the log of the particular case of: initial success and second failure.

oddlama added a comment.May 12 2022, 7:48 PM

Contrary to your expectations, all gpg --card-status fail after yubikey insertion:

  • [no gpg-agent running]
  • insert yubikey
  • gpg --card-status (fails)
  • remove yubikey
  • insert yubikey
  • gpg --card-status (fails)
  • [fails always after fresh insertion]

scdaemon_triple_fail.log93 KBDownload

The only way to get it working reliably is the following:

  • [no gpg-agent running]
  • insert yubikey
  • gpg --card-status (fails)
  • killall gpg-agent
  • gpg --card-status (success, any further attempt is also successful until the yubikey is reinserted)

scdaemon_works_after_kill.log59 KBDownload

It seems to always work, when gpg-agent is killed AFTER the yubikey was inserted, suggesting an error triggered by the usb insertion event.

• gniibe added a comment.May 13 2022, 3:15 AM

Thanks a lot for your cooperation.

My analysis before seemed wrong. According to your logs, device removal is correctly detected.

But for some reason, the workaround rG054d14887ef8 doesn't work.

Could you please try apply this patch over those two:

diff --git a/scd/app-openpgp.c b/scd/app-openpgp.c
index 08c9d71ac..bd9fbffbc 100644
--- a/scd/app-openpgp.c
+++ b/scd/app-openpgp.c
@@ -6172,6 +6172,10 @@ parse_algorithm_attribute (app_t app, int keyno)
 
   log_assert (keyno >=0 && keyno <= 2);
 
+  if (opt.verbose)
+    log_debug ("is-cardtype-yubikey: %d\n",
+               APP_CARD(app)->cardtype == CARDTYPE_YUBIKEY);
+
   app->app_local->keyattr[keyno].key_type = KEY_TYPE_RSA;
   app->app_local->keyattr[keyno].rsa.n_bits = 0;

Here, it works well like:

2022-05-13 10:12:17 scdaemon[10196] Yubico: config=2e0102023f03020239020400a1fcf104010105030502040602000007010f0801000d02023f0e02023b0a01000f0100
2022-05-13 10:12:17 scdaemon[10196] DBG: send apdu: c=00 i=A4 p1=04 p2=00 lc=6 le=-1 em=0
2022-05-13 10:12:17 scdaemon[10196] DBG:   PCSC_data: 00a4040006d27600012401
2022-05-13 10:12:17 scdaemon[10196] DBG:  response: sw=9000  datalen=0
2022-05-13 10:12:17 scdaemon[10196] DBG:      dump: [all zero]
2022-05-13 10:12:17 scdaemon[10196] DBG: send apdu: c=00 i=CA p1=00 p2=4F lc=-1 le=256 em=0
2022-05-13 10:12:17 scdaemon[10196] DBG:   PCSC_data: 00ca004f00
2022-05-13 10:12:17 scdaemon[10196] DBG:  response: sw=9000  datalen=16
2022-05-13 10:12:17 scdaemon[10196] DBG:      dump: d2760001240103040006106160490000
2022-05-13 10:12:17 scdaemon[10196] AID: d2760001240103040006106160490000
2022-05-13 10:12:17 scdaemon[10196] DBG: send apdu: c=00 i=CA p1=5F p2=52 lc=-1 le=256 em=0
2022-05-13 10:12:17 scdaemon[10196] DBG:   PCSC_data: 00ca5f5200
2022-05-13 10:12:17 scdaemon[10196] DBG:  response: sw=9000  datalen=8
2022-05-13 10:12:17 scdaemon[10196] DBG:      dump: 00730000e0059000
2022-05-13 10:12:17 scdaemon[10196] Historical Bytes: 00730000e0059000
2022-05-13 10:12:17 scdaemon[10196] DBG: send apdu: c=00 i=CA p1=00 p2=C4 lc=-1 le=256 em=0
2022-05-13 10:12:17 scdaemon[10196] DBG:   PCSC_data: 00ca00c400
2022-05-13 10:12:17 scdaemon[10196] DBG:  response: sw=9000  datalen=7
2022-05-13 10:12:17 scdaemon[10196] DBG:      dump: 007f7f7f030003
2022-05-13 10:12:17 scdaemon[10196] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2022-05-13 10:12:17 scdaemon[10196] DBG:   PCSC_data: 00ca006e00
2022-05-13 10:12:17 scdaemon[10196] DBG:  response: sw=614B  datalen=256
2022-05-13 10:12:17 scdaemon[10196] DBG: apdu_send_simple(0): 75 more bytes available
2022-05-13 10:12:17 scdaemon[10196] DBG:   PCSC_data: 00c000004b
2022-05-13 10:12:17 scdaemon[10196] DBG:      more: sw=9000  datalen=75
2022-05-13 10:12:17 scdaemon[10196] DBG:      dump: 6e8201474f10d27600012401030400061061604900005f520800730000e00590 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  007f740381012073820120c00a7d000bfe080000ff0000c10b162b06010401da \
2022-05-13 10:12:17 scdaemon[10196] DBG:  470f01d2c20c122b060104019755010501c3c30b162b06010401da470f019ada \
2022-05-13 10:12:17 scdaemon[10196] DBG:  06010800001100c407007f7f7f030003c550365f11680f07535a370e32eb2517 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  f8fb6f6c0dd4f90416b2f51ae846585b7d6ed088fd501f5649150c4014e2f978 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  bd0ab6b059537a8c84104a79a00a000000000000000000000000000000000000 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  0000c65000000000000000000000000000000000000000000000000000000000 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  0000000000000000000000000000000000000000000000000000000000000000 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  0000000000000000000000000000000000000000cd1062787026627870266278 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  702600000000de0801010201030181027f660802020bfe02020bfed6020020d7 \
2022-05-13 10:12:17 scdaemon[10196] DBG:  020020d8020020d9020020
2022-05-13 10:12:17 scdaemon[10196] DBG: send apdu: c=00 i=CA p1=00 p2=5E lc=-1 le=65534 em=255
2022-05-13 10:12:17 scdaemon[10196] DBG:   PCSC_data: 00ca005e00fffe
2022-05-13 10:12:17 scdaemon[10196] DBG:  response: sw=9000  datalen=0
2022-05-13 10:12:17 scdaemon[10196] DBG:      dump: [all zero]
2022-05-13 10:12:17 scdaemon[10196] Version-2+ .....: yes
2022-05-13 10:12:17 scdaemon[10196] Version-3+ .....: yes
2022-05-13 10:12:17 scdaemon[10196] Button .........: yes
2022-05-13 10:12:17 scdaemon[10196] SM-Support .....: no
2022-05-13 10:12:17 scdaemon[10196] Get-Challenge ..: yes (3070 bytes max)
2022-05-13 10:12:17 scdaemon[10196] Key-Import .....: yes
2022-05-13 10:12:17 scdaemon[10196] Change-Force-PW1: yes
2022-05-13 10:12:17 scdaemon[10196] Private-DOs ....: yes
2022-05-13 10:12:17 scdaemon[10196] Algo-Attr-Change: yes
2022-05-13 10:12:17 scdaemon[10196] Symmetric Crypto: no
2022-05-13 10:12:17 scdaemon[10196] KDF-Support ....: yes
2022-05-13 10:12:17 scdaemon[10196] Max-Cert-Len ...: 2048
2022-05-13 10:12:17 scdaemon[10196] PIN-Block-2 ....: no
2022-05-13 10:12:17 scdaemon[10196] MSE-Support ....: no
2022-05-13 10:12:17 scdaemon[10196] Max-Special-DOs : 255
2022-05-13 10:12:17 scdaemon[10196] Cmd-Chaining ...: yes
2022-05-13 10:12:17 scdaemon[10196] Ext-Lc-Le ......: yes
2022-05-13 10:12:17 scdaemon[10196] Status-Indicator: 05
2022-05-13 10:12:17 scdaemon[10196] GnuPG-No-Sync ..: no
2022-05-13 10:12:17 scdaemon[10196] GnuPG-Def-PW2 ..: no
2022-05-13 10:12:17 scdaemon[10196] DBG: is-cardtype-yubikey: 1
2022-05-13 10:12:17 scdaemon[10196] Key-Attr-sign ..: ECC, curve=Ed25519 (eddsa)
2022-05-13 10:12:17 scdaemon[10196] Key-Algo-sign ..: ed25519
2022-05-13 10:12:17 scdaemon[10196] DBG: is-cardtype-yubikey: 1
2022-05-13 10:12:17 scdaemon[10196] Key-Attr-encr ..: ECC, curve=Curve25519 (djb-tweak)
2022-05-13 10:12:17 scdaemon[10196] Key-Algo-encr ..: cv25519
2022-05-13 10:12:17 scdaemon[10196] DBG: is-cardtype-yubikey: 1
2022-05-13 10:12:17 scdaemon[10196] Key-Attr-auth ..: ECC, curve=Ed25519 (eddsa)
2022-05-13 10:12:17 scdaemon[10196] Key-Algo-auth ..: ed25519

In this case, the bogus octet is correctly ignored, as expected.

• gniibe added a comment.May 13 2022, 3:21 AM

I put more fix for error handling of key algorithm attribute.
The change: rG53eddf9b9ea0: scd: Fail when no good algorithm attribute.

It correctly reports failure, and it allows a user to try second initialization.
Even if the first, gpg --card-status may fail, it may work next time (with no need of killing gpg-agent).

(Before this change, the failure was just ignored, so second time access assumed it works well. Thus, it kept not-working.)

oddlama added a comment.May 13 2022, 2:28 PM

Thanks a lot for your cooperation.

I thank you for trying to fix this issue!

Your newest patch rG53eddf9b9ea0 made the situation better, like you said. No more Card Errors, and no need to restart the agent.
Just the first gpg --card-status fails with gpg: selecting card failed: End of file, after that everything works as expected.

Here is the relevant scdaemon log file for the following actions:

  • [No agent running]
  • Insert yubikey
  • gpg --card-status (fails)
  • gpg --card-status (works from here on)

scdaemon_works_better.log42 KBDownload

• gniibe added a comment.May 16 2022, 3:08 AM

Thanks again for your update.

I think that in your scdaemon_works_better.log, the scdaemon got segv by the initial --card-status.
I think that it means that you only applied the last two patches.

What we need to test is four patches. That is, please apply following four patches to test:
(1) rG385f4841330e
(2) rG054d14887ef8
(3) The patch to see if (2) is working well

diff --git a/scd/app-openpgp.c b/scd/app-openpgp.c
index 08c9d71ac..bd9fbffbc 100644
--- a/scd/app-openpgp.c
+++ b/scd/app-openpgp.c
@@ -6172,6 +6172,10 @@ parse_algorithm_attribute (app_t app, int keyno)
 
   log_assert (keyno >=0 && keyno <= 2);
 
+  if (opt.verbose)
+    log_debug ("is-cardtype-yubikey: %d\n",
+               APP_CARD(app)->cardtype == CARDTYPE_YUBIKEY);
+
   app->app_local->keyattr[keyno].key_type = KEY_TYPE_RSA;
   app->app_local->keyattr[keyno].rsa.n_bits = 0;

(4) rG53eddf9b9ea0

oddlama added a comment.May 16 2022, 4:14 PM

I think that it means that you only applied the last two patches.

I have to disagree. I'm using gentoo's automatic patch system, and I have put all four patches including the one you mentioned in the patch directory.
When compiling the package, I can see that all 4 are applied. I also have compiled it using debug symbols and portage automatically saves the sources of the package for later inspection.
The log_debug line is present there.

I'm 100% confident that my patching is correct. To show you that this is actually the case I've made sure the newly introduced debug string is part of the executable:

strings -tx /usr/libexec/scdaemon | grep is-cardtype
  74d5d is-cardtype-yubikey: %d

You are correct that the first invocation segfaults. So I guess the previous bug is not completely resolved?
Using killall gpg-agent; valgrind /usr/libexec/scdaemon --server --disable-ccid --debug cardio I get the following output when writing SERIALNO:

==3337711== Memcheck, a memory error detector
==3337711== Copyright (C) 2002-2022, and GNU GPL'd, by Julian Seward et al.
==3337711== Using Valgrind-3.19.0 and LibVEX; rerun with -h for copyright info
==3337711== Command: /usr/libexec/scdaemon --server --disable-ccid --debug cardio
==3337711==
scdaemon[3337711]: reading options from '/home/myuser/.gnupg/scdaemon.conf'
scdaemon[3337711]: reading options from '[cmdline]'
scdaemon[3337711]: enabled debug flags: mpi crypto memory cache memstat hashing ipc cardio reader app
OK GNU Privacy Guard's Smartcard server ready
SERIALNO
==3337711== Thread 2:
==3337711== Conditional jump or move depends on uninitialised value(s)
==3337711==    at 0x591FFAE: SCardListReaders (in /usr/lib64/libpcsclite.so.1.0.0)
==3337711==    by 0x11E178: apdu_dev_list_start (apdu.c:2031)
==3337711==    by 0x12B4AF: select_application (app.c:817)
==3337711==    by 0x117C8F: open_card_with_request (command.c:281)
==3337711==    by 0x117C8F: cmd_serialno (command.c:358)
==3337711==    by 0x4A20839: ??? (in /usr/lib64/libassuan.so.0.8.5)
==3337711==    by 0x4A20C28: assuan_process (in /usr/lib64/libassuan.so.0.8.5)
==3337711==    by 0x1186DC: scd_command_handler (command.c:2521)
==3337711==    by 0x114D93: start_connection_thread (scdaemon.c:1202)
==3337711==    by 0x4A2F49D: ??? (in /usr/lib64/libnpth.so.0.1.2)
==3337711==    by 0x4ADC3E9: start_thread (pthread_create.c:442)
==3337711==    by 0x4B5E0DF: clone (clone.S:100)
==3337711==
==3337711== Invalid read of size 1
==3337711==    at 0x484A7C2: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==3337711==    by 0x48794E2: ??? (in /usr/lib64/libgcrypt.so.20.4.1)
==3337711==    by 0x487AEC0: ??? (in /usr/lib64/libgcrypt.so.20.4.1)
==3337711==    by 0x16C5CF: get_keyalgo_string (openpgp-oid.c:675)
==3337711==    by 0x1300FF: parse_algorithm_attribute (app-openpgp.c:6270)
==3337711==    by 0x13AD13: app_select_openpgp (app-openpgp.c:6505)
==3337711==    by 0x12B78E: app_new_register (app.c:766)
==3337711==    by 0x12B78E: select_application (app.c:841)
==3337711==    by 0x117C8F: open_card_with_request (command.c:281)
==3337711==    by 0x117C8F: cmd_serialno (command.c:358)
==3337711==    by 0x4A20839: ??? (in /usr/lib64/libassuan.so.0.8.5)
==3337711==    by 0x4A20C28: assuan_process (in /usr/lib64/libassuan.so.0.8.5)
==3337711==    by 0x1186DC: scd_command_handler (command.c:2521)
==3337711==    by 0x114D93: start_connection_thread (scdaemon.c:1202)
==3337711==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==3337711==
==3337711==
==3337711== Process terminating with default action of signal 11 (SIGSEGV)
==3337711==  Access not within mapped region at address 0x0
==3337711==    at 0x484A7C2: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==3337711==    by 0x48794E2: ??? (in /usr/lib64/libgcrypt.so.20.4.1)
==3337711==    by 0x487AEC0: ??? (in /usr/lib64/libgcrypt.so.20.4.1)
==3337711==    by 0x16C5CF: get_keyalgo_string (openpgp-oid.c:675)
==3337711==    by 0x1300FF: parse_algorithm_attribute (app-openpgp.c:6270)
==3337711==    by 0x13AD13: app_select_openpgp (app-openpgp.c:6505)
==3337711==    by 0x12B78E: app_new_register (app.c:766)
==3337711==    by 0x12B78E: select_application (app.c:841)
==3337711==    by 0x117C8F: open_card_with_request (command.c:281)
==3337711==    by 0x117C8F: cmd_serialno (command.c:358)
==3337711==    by 0x4A20839: ??? (in /usr/lib64/libassuan.so.0.8.5)
==3337711==    by 0x4A20C28: assuan_process (in /usr/lib64/libassuan.so.0.8.5)
==3337711==    by 0x1186DC: scd_command_handler (command.c:2521)
==3337711==    by 0x114D93: start_connection_thread (scdaemon.c:1202)
==3337711==  If you believe this happened as a result of a stack
==3337711==  overflow in your program's main thread (unlikely but
==3337711==  possible), you can try to increase the size of the
==3337711==  main thread stack using the --main-stacksize= flag.
==3337711==  The main thread stack size used in this run was 8388608.
==3337711==
==3337711== HEAP SUMMARY:
==3337711==     in use at exit: 76,205 bytes in 122 blocks
==3337711==   total heap usage: 376 allocs, 254 frees, 260,595 bytes allocated
==3337711==
==3337711== LEAK SUMMARY:
==3337711==    definitely lost: 33 bytes in 1 blocks
==3337711==    indirectly lost: 0 bytes in 0 blocks
==3337711==      possibly lost: 2,939 bytes in 3 blocks
==3337711==    still reachable: 73,233 bytes in 118 blocks
==3337711==         suppressed: 0 bytes in 0 blocks
==3337711== Rerun with --leak-check=full to see details of leaked memory
==3337711==
==3337711== Use --track-origins=yes to see where uninitialised values come from
==3337711== For lists of detected and suppressed errors, rerun with: -s
==3337711== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 0 from 0)
[1]    3337711 segmentation fault (core dumped)  valgrind /usr/libexec/scdaemon --server --disable-ccid --debug cardio
• gniibe added a comment.EditedMay 17 2022, 2:41 AM

When compiling the package, I can see that all 4 are applied.

Please show us your four patch files and the log of your compilation.

Please show us the patched files (after patches applied): scd/app-openpgp.c and common/openpgp-oid.c.

I think that natural interpretation of your valgrind output is that the second part of the patch (1) is not applied correctly, at least; With NULL, it fails in the function gcry_xstrdup, which is in libgcrypt. And it is highly likely that the patch (2) is not applied correctly, too.

Or, if it's difficult, try the next release, 2.3.7, which will include all patches except (3).

oddlama added a comment.May 17 2022, 1:34 PM

I apologize, you seem to be right. Even though the package build log shows that all patches were applied, it seems there are some hunks missing in the generated sources.
I've attached my patches, but those are most likely correct. There seems to be an issue with my distribution's package manager. I will investigate this and report back afterwards. Maybe I'll just build it manually.

>>> Emerging (1 of 1) app-crypt/gnupg-2.3.6::gentoo
 * gnupg-2.3.6.tar.bz2 BLAKE2B SHA512 size ;-) ... [ ok ]
>>> Unpacking source...
>>> Unpacking gnupg-2.3.6.tar.bz2 to /var/tmp/portage/app-crypt/gnupg-2.3.6/work
>>> Source unpacked in /var/tmp/portage/app-crypt/gnupg-2.3.6/work
>>> Preparing source in /var/tmp/portage/app-crypt/gnupg-2.3.6/work/gnupg-2.3.6 ...
 * Applying gnupg-2.1.20-gpgscm-Use-shorter-socket-path-lengts-to-improve-tes.patch ... [ ok ]
* =======================================================================================================================================================
 * Applying user patches from /etc/portage/patches ...
 * Applying 00-werner.patch ...  [ ok ]
 * Applying 01-gniibe.patch ...  [ ok ]
 * Applying 02-gniibe.patch ...  [ ok ]
 * Applying 03-gniibe.patch ...  [ ok ]
 * User patches applied.
* =======================================================================================================================================================
>>> Source prepared.
>>> Configuring source in /var/tmp/portage/app-crypt/gnupg-2.3.6/work/gnupg-2.3.6 ...
 * econf: updating gnupg-2.3.6/build-aux/config.guess with /usr/share/gnuconfig/config.guess
 * econf: updating gnupg-2.3.6/build-aux/config.sub with /usr/share/gnuconfig/config.sub
./configure --prefix=/usr --build=x86_64-pc-linux-gnu --host=x86_64-pc-linux-gnu --mandir=/usr/share/man --infodir=/usr/share/info --datadir=/usr/share --sysconfdir=/etc --localstatedir=/var/lib --disable-dependency-tracking --disable-silen
t-rules --docdir=/usr/share/doc/gnupg-2.3.6 --htmldir=/usr/share/doc/gnupg-2.3.6/html --libdir=/usr/lib64 --enable-bzip2 --enable-nls --enable-scdaemon --enable-gnutls --enable-tofu --enable-keyboxd --enable-sqlite --disable-tpm2d --disable
-ccid-driver --disable-wks-tools --without-ldap --with-readline --with-mailprog=/usr/libexec/sendmail --disable-ntbtls --enable-all-tests --enable-gpgsm --enable-large-secmem CC_FOR_BUILD=x86_64-pc-linux-gnu-gcc GPG_ERROR_CONFIG=/usr/bin/x8
6_64-pc-linux-gnu-gpg-error-config KSBA_CONFIG=/usr/bin/ksba-config LIBASSUAN_CONFIG=/usr/bin/libassuan-config LIBGCRYPT_CONFIG=/usr/bin/x86_64-pc-linux-gnu-libgcrypt-config NPTH_CONFIG=/usr/bin/npth-config --without-libiconv-prefix --witho
ut-libintl-prefix
checking for a BSD-compatible install... /usr/lib/portage/python3.9/ebuild-helpers/xattr/install -c
checking whether build environment is sane... yes
checking for a thread-safe mkdir -p... /bin/mkdir -p

01-gniibe.patch817 BDownload

02-gniibe.patch488 BDownload

03-gniibe.patch5 KBDownload

00-werner.patch1005 BDownload

• gniibe added a comment.May 18 2022, 1:37 AM

No, no apologize needed. You did your best for the bug report, and it helped us a lot to identify the issue, and it certainly helped resulting the fixes. Moreover, your report kicked another fix of T5979 (thanks to the valgrind output).
Thank you.

Our common goal is to fix the bug. I hope it's done. At least, we now see a bit of progress.

oddlama added a comment.May 18 2022, 2:10 AM

Glad to hear. I've also now had time to manually apply the patches and have not seen any issues so far! Thank you! If anything does turn up later down the road I'll let you know.

saper added a subscriber: saper.Mar 18 2023, 12:49 AM