Page MenuHome GnuPG
Create Task
Maniphest T7066

Communication with Yubikey hangs in scdaemon
Closed, ResolvedPublic
Actions

Description

gpg 2.4.5
Arch Linux uptodate

Since some recent change (hard to say what it was), I experience consistent hangs in scdaemon.
My gpg key is on a Yubikey (4C, authentic).

I have activated logging from gpg-agent and scdaemon at log-level guru, Any action (gpg --edit-card, ssh-add -L, ...) hangs at the same state:

log of gpg-agent:
2024-03-28 20:01:20 gpg-agent[4884] no running /usr/lib/gnupg/scdaemon daemon - starting it
2024-03-28 20:01:20 gpg-agent[4884] DBG: agent_flush_cache (pincache only)
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 <- OK GNU Privacy Guard's Smartcard server ready
2024-03-28 20:01:20 gpg-agent[4884] first connection to daemon /usr/lib/gnupg/scdaemon established
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 -> GETINFO socket_name
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 <- D /run/user/1000/gnupg/S.scdaemon
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 <- OK
2024-03-28 20:01:20 gpg-agent[4884] DBG: additional connections at '/run/user/1000/gnupg/S.scdaemon'
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 -> OPTION event-signal=12
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 <- OK
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 -> GETINFO version
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 <- D 2.4.5
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 <- OK
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_10 -> D 2.4.5
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_10 -> OK
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_10 <- SCD SERIALNO
2024-03-28 20:01:20 gpg-agent[4884] DBG: chan_11 -> SERIALNO

log of scdaemon:
2024-03-28 20:01:20 scdaemon[4886] listening on socket '/run/user/1000/gnupg/S.scdaemon'
2024-03-28 20:01:20 scdaemon[4886] handler for fd -1 started
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 -> OK GNU Privacy Guard's Smartcard server ready
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 <- GETINFO socket_name
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 -> D /run/user/1000/gnupg/S.scdaemon
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 -> OK
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 <- OPTION event-signal=12
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 -> OK
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 <- GETINFO version
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 -> D 2.4.5
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 -> OK
2024-03-28 20:01:20 scdaemon[4886] DBG: chan_7 <- SERIALNO

Nothing works at this state.

When I do things unrelated to the yubikey, like ssh-add -L, I can get an answer by *killing* scdaemon, in this case I get an immediate response.

Configurations:

gpg-agent.conf
enable-ssh-support
allow-loopback-pinentry
log-file /home/norbert/.gnupg/gpg-agent.log
debug-level guru

scdaemon.conf:
debug-level guru
log-file /home/norbert/.gnupg/scdaemon.log

Details

Version
2.4.5

Event Timeline

npreining created this task.Mar 28 2024, 12:16 PM
• werner added a subscriber: • werner.Mar 28 2024, 1:22 PM

Please use

debug ipc,card,cardio,reader,app
log-file /home/norbert/.gnupg/scdaemon.log

for full debugging.

npreining added a comment.Mar 29 2024, 1:14 AM

I rebooted, edited the scdaemon.conf to match the above, and tried gpg --edit-card with the yubikey plugged in. It resulted in the same output:

scdaemong.log

2024-03-29 09:10:52 scdaemon[5236] listening on socket '/run/user/1000/gnupg/S.scdaemon'
2024-03-29 09:10:52 scdaemon[5236] handler for fd -1 started
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 -> OK GNU Privacy Guard's Smartcard server ready
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 <- GETINFO socket_name
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 -> D /run/user/1000/gnupg/S.scdaemon
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 -> OK
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 <- OPTION event-signal=12
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 -> OK
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 <- GETINFO version
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 -> D 2.4.5
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 -> OK
2024-03-29 09:10:52 scdaemon[5236] DBG: chan_7 <- SERIALNO

and gpg-agent.log

2024-03-29 09:10:52 gpg-agent[5234] gpg-agent (GnuPG) 2.4.5 starting in supervised mode.
2024-03-29 09:10:52 gpg-agent[5234] using fd 3 for extra socket (/run/user/1000/gnupg/S.gpg-agent.extra)
2024-03-29 09:10:52 gpg-agent[5234] using fd 4 for browser socket (/run/user/1000/gnupg/S.gpg-agent.browser)
2024-03-29 09:10:52 gpg-agent[5234] using fd 5 for ssh socket (/run/user/1000/gnupg/S.gpg-agent.ssh)
2024-03-29 09:10:52 gpg-agent[5234] using fd 6 for std socket (/run/user/1000/gnupg/S.gpg-agent)
2024-03-29 09:10:52 gpg-agent[5234] listening on: std=6 extra=3 browser=4 ssh=5
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK Pleased to meet you, process 5233
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- RESET
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION ttyname=/dev/pts/1
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION ttytype=xterm-256color
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION display=:1
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION xauthority=/run/user/1000/xauth_RgXOlu
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION putenv=XMODIFIERS=@im=fcitx
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION putenv=WAYLAND_DISPLAY=wayland-0
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION putenv=XDG_SESSION_TYPE=wayland
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION putenv=DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION lc-ctype=en_US.UTF-8
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION lc-messages=en_US.UTF-8
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- GETINFO version
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> D 2.4.5
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION allow-pinentry-notify
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- OPTION agent-awareness=2.1.0
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- SCD GETINFO version
2024-03-29 09:10:52 gpg-agent[5234] no running /usr/lib/gnupg/scdaemon daemon - starting it
2024-03-29 09:10:52 gpg-agent[5234] DBG: agent_flush_cache (pincache only)
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 <- OK GNU Privacy Guard's Smartcard server ready
2024-03-29 09:10:52 gpg-agent[5234] first connection to daemon /usr/lib/gnupg/scdaemon established
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 -> GETINFO socket_name
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 <- D /run/user/1000/gnupg/S.scdaemon
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 <- OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: additional connections at '/run/user/1000/gnupg/S.scdaemon'
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 -> OPTION event-signal=12
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 <- OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 -> GETINFO version
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 <- D 2.4.5
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 <- OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> D 2.4.5
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 -> OK
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_10 <- SCD SERIALNO
2024-03-29 09:10:52 gpg-agent[5234] DBG: chan_11 -> SERIALNO
npreining added a comment.Mar 29 2024, 10:09 AM

Please wait investigating it, a downgrade of the *kernel* from 6.8.2 to 6.8.1 helped. It seemed the USB communication got broken with 6.8.2. I am investigating

• werner added projects: yubikey, Arch.Apr 9 2024, 1:44 PM
• werner closed this task as Resolved.May 1 2024, 7:55 PM
• werner claimed this task.

Seems it was a kernel / USB bug