Page MenuHome GnuPG

Kleopatra: Initial keylisting hangs for ~60 seconds (gpg-agent: Socket ...S.gpg-agent cannot be bound)
Open, Needs TriagePublic

Description

I experienced another instance of "initial keylisting hangs". I had just installed a new self-built Gpg4win 4.4.1-beta for testing a bug fix. The installation required a restart (for whatever reason).

After starting Kleopatra the initial keylisting hanged. Task manager showed that 1 instance of gpg-agent, gpgconf (--launch gpg-agent), gpg, and gpgsm were running.

Kleopatra logs:

00000001	0.00000000	[6868] org.kde.pim.kleopatra: Startup timing: 333 ms: Application created	
00000002	0.00045300	[6868] org.kde.pim.kleopatra: Responder handle: 0x0	
00000003	0.00269380	[6868] org.kde.pim.kleopatra: Created responder:  "kleopatraResponder"  with handle:  0x301aa	
00000004	0.00279810	[6868] org.kde.pim.kleopatra: Startup timing: 337 ms: Service created	
00000005	0.00284880	[6868] org.kde.pim.kleopatra: Application created	
00000006	0.00958730	[6868] org.kde.pim.kleopatra: Startup timing: 343 ms: GPGME Initialized	
00000007	0.01121090	[6868] org.kde.pim.kleopatra: Startup timing: 345 ms: Starting version info check	
00000008	0.01220930	[6868] org.kde.pim.libkleo: Verifying "C:/Program Files (x86)/Gpg4win/bin/../VERSION"	
00000009	0.01262480	[6868] org.kde.pim.libkleo: No signature found at "C:/Program Files (x86)/Gpg4win/VERSION.sig"	
00000010	0.01270490	[6868] org.kde.pim.kleopatra: Startup timing: 346 ms: Version info checked	
00000011	0.01335080	[6868] org.kde.pim.kleopatra: Startup timing: 347 ms: Checking backend versions	
00000012	0.01361050	[6868] org.kde.pim.kleopatra: Got ElevationToken  0	
[...]
00000016	0.96211171	[6868] org.kde.pim.libkleo: Parsed 2.4.7 as:  2 . 4 . 7 .	
00000017	0.96222490	[6868] org.kde.pim.libkleo: Running gpgconf --show-versions ...	
00000018	1.17597973	[6868] org.kde.pim.libkleo: gpgconf stdout: "* GnuPG 2.4.7 (7bdaf5647)\nMingW32\nWindows 10.0 build 19045\n\n* Libgcrypt 1.11.0 (9d94d784)\nversion:1.11.0:10b00:1.51:13300:\ncc:100000:gcc:10-win32 20210110:\nciphers:arcfour:blowfish:cast5:des:aes:twofish:serpent:rfc2268:seed:camellia:idea:salsa20:gost28147:chacha20:sm4:aria:\npubkeys:dsa:elgamal:rsa:ecc:\ndigests:crc:gostr3411-94::md4:md5:rmd160:sha1:sha256:sha512:sha3:tiger:whirlpool:stribog:blake2:sm3:\nrnd-mod:w32:\ncpu-arch:x86:i386:\nmpi-asm:i386/mpih-add1.S:i386/mpih-sub1.S:i386/mpih-mul1.S:i386/mpih-mul2.S:i386/mpih-mul3.S:i386/mpih-lshift.S:i386/mpih-rshift.S:\nhwflist:intel-bmi2:intel-ssse3:intel-sse4.1:intel-pclmul:intel-aesni:intel-rdrand:intel-avx:intel-avx2:intel-rdtsc:intel-shaext:\nfips-mode:n:::\nrng-type:standard:1:3030000:1:\ncompliance:::\n\n* GpgRT 1.51 (b0bb9266010d84b30fa2dc6a2127b7e40dc03660)\n\n* nPth 1.8 (64905e765aad9de6054ef70a97fc30bd992ce999)\n\n* Libassuan 3.0.1 (c9e9027)\n\n* KSBA 1.6.7 (b14e68b)\n\n* NTBTLS 0.3.2 (2c38007)\n\n"	
00000019	1.17608500	[6868] org.kde.pim.kleopatra: Startup timing: 1510 ms: backend versions checked	
00000020	3.02422428	[6868] org.kde.pim.libkleo: agentIsRunning : Connecting to the agent failed.	
00000021	3.02437091	[6868] org.kde.pim.libkleo: Starting "C:\\Program Files (x86)\\GnuPG\\bin\\gpgconf.exe" "--launch gpg-agent"  ...	
00000022	3.02911568	[6868] org.kde.pim.libkleo: gpgconf was started successfully

^ here gpgconf --launch gpg-agent is called to start gpg-agent.

00000023	3.02932954	[6868] org.kde.pim.kleopatra: ReaderStatus::Private: Using deprecated FileSystemWatcher	
[...]
00000031	3.21591949	[6868] org.kde.pim.kleopatra: Startup timing: 3535 ms: Application initialized	
00000032	3.21606731	[6868] org.kde.pim.kleopatra: Startup timing: 3538 ms: UiServer created	
00000033	3.25474691	[6868] org.kde.pim.kleopatra: Startup timing: 3588 ms: UiServer started	
00000034	3.25664830	[6868] org.kde.pim.kleopatra: Kleo::Command(0xb3fe94) ~Command	
00000035	3.25675368	[6868] org.kde.pim.kleopatra: Kleo::Command(0xb3fe94) ~Private	
00000036	3.25686312	[6868] org.kde.pim.kleopatra: Startup timing: 3591 ms: SelfCheck completed	
00000037	3.25695992	[6868] org.kde.pim.kleopatra: startMonitoring	
00000038	3.25710511	[6868] org.kde.pim.kleopatra: startMonitoring waiting for key cache ...	
00000039	3.25735807	[6868] org.kde.pim.kleopatra: openOrRaiseMainWindow	
00000040	4.62009048	[6868] org.kde.pim.libkleo: KeyFilterManager:: reload final filter count is 17	
00000042	4.81525135	[6868] org.kde.pim.kleopatra: Hook into the help menu to show the About dialog ourselves	
00000043	4.85487461	[6868] org.kde.pim.kleopatra: open_or_raise showing window	
00000044	5.01271820	[6868] org.kde.pim.kleopatra: you need to register view Kleo::TreeView(0x929cb80, name="m_view") before trying to set it as the current view!	
00000045	5.20467281	[6868] org.kde.pim.kleopatra: No update for: "4.4.1-beta4"	
00000046	5.20546246	[6868] org.kde.pim.kleopatra: Startup timing: 5539 ms: new instance created	
00000047	5.20588255	[6868] org.kde.pim.libkleo: Kleo::KeyCache(0x76dedf0) reload option: 0	
00000048	5.20674086	[6868] org.kde.pim.libkleo: KeyCache::RefreshKeysJob start

^ here the keylisting (with gpg and gpgsm) is started

00000049	5.21036482	[6868] org.kde.pim.libkleo: Kleo::KeyCache(0x76dedf0) reload option: 0	
00000050	5.21046782	[6868] org.kde.pim.libkleo: Kleo::KeyCache(0x76dedf0) reload - refresh already running	
00000051	5.21055984	[6868] org.kde.pim.libkleo: Waiting for keycache.	
00000054	60.66810989	[6868] org.kde.pim.libkleo: Kleo::KeyCache::RefreshKeysJob(0x931a988) RefreshKeysJob::done

^ ~55 seconds later the keylistings are done

00000055	60.68364716	[6868] org.kde.pim.libkleo: readGroups Reading groups	
00000056	60.68596649	[6868] org.kde.pim.kleopatra: startMonitoring	
00000057	60.68605423	[6868] org.kde.pim.kleopatra: startMonitoring key cache is ready	
00000058	60.68667603	[6868] org.kde.pim.kleopatra: ReaderStatusThread[2nd]: new iteration command= "__update__"  ; nullSlot= true	
00000059	60.68676376	[6868] org.kde.pim.kleopatra: update_cardinfo()	
00000060	60.68687439	[6868] org.kde.pim.libkleo: sendCommand "SCD SERIALNO --all"	
00000061	60.68890381	[6868] org.kde.pim.libkleo: Keycache available.	
00000062	60.69105911	[6868] org.kde.pim.libkleo: Reloading keycache with remarks enabled	
00000063	60.69116211	[6868] org.kde.pim.libkleo: Kleo::KeyCache(0x76dedf0) reload option: 0	
00000064	60.69190216	[6868] org.kde.pim.libkleo: KeyCache::RefreshKeysJob start	
00000065	60.69196701	[6868] org.kde.pim.kleopatra: onUpdateCardsStarted	
00000066	60.69257736	[6868] org.kde.pim.kleopatra: Kleo::Command(0x9191750) ~Command	
00000067	60.69270325	[6868] org.kde.pim.kleopatra: Kleo::Command(0x9191750) ~Private	
00000068	60.80812836	[6868] org.kde.pim.libkleo: sendCommand "SCD SERIALNO --all" failed: "No such device" (code: 32848, source: SCD)	
00000069	60.80826187	[6868] org.kde.pim.libkleo: sendStatusLinesCommand "SCD SERIALNO --all" : t == NULL	
00000070	60.80831909	[6868] org.kde.pim.kleopatra: update_cardinfo: No card present	
00000071	60.80894852	[6868] org.kde.pim.kleopatra: ReaderStatusThread[2nd]: waiting for commands	
00000072	62.13568115	[6868] org.kde.pim.kleopatra: onUpdateFinished	
00000073	62.51733017	[6868] org.kde.pim.libkleo: Kleo::KeyCache::RefreshKeysJob(0x92a9030) RefreshKeysJob::done

Event Timeline

gpg-agent.log starts with

2024-12-03 10:11:12 gpg-agent[2816] Der Socket kann nicht an `C:\\Users\\g10code\\AppData\\Local\\gnupg\\S.gpg-agent' gebunden werden: Unknown error
2024-12-03 10:11:12 gpg-agent[2816] secmem usage: 0/32768 bytes in 0 blocks

Looks like gpg-agent tried to bind the socket and immediately exited when this failed. The logs of gpg-agent continue 48 seconds later with

2024-12-03 10:12:00 gpg-agent[6492] Es wird auf Socket `C:\\Users\\g10code\\AppData\\Local\\gnupg\\S.gpg-agent' gehört
2024-12-03 10:12:00 gpg-agent[6492] Es wird auf Socket `C:\\Users\\g10code\\AppData\\Local\\gnupg\\S.gpg-agent.extra' gehört
2024-12-03 10:12:00 gpg-agent[6492] Es wird auf Socket `C:\\Users\\g10code\\AppData\\Local\\gnupg\\S.gpg-agent.browser' gehört
2024-12-03 10:12:00 gpg-agent[6492] Es wird auf Socket `C:\\Users\\g10code\\AppData\\Local\\gnupg\\S.gpg-agent.ssh' gehört
2024-12-03 10:12:00 gpg-agent[6492] gpg-agent (GnuPG) 2.4.7 started
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 <- RESET
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 -> OK
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 <- OPTION ttyname=/dev/tty
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 -> OK
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 <- OPTION putenv=QT_QPA_PLATFORM=windows:darkmode=2
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 -> OK
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 <- GETINFO version
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 -> D 2.4.7
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 -> OK
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 <- OPTION allow-pinentry-notify
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 -> OK
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 <- OPTION agent-awareness=2.1.0
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 -> OK
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x00000084 <- HAVEKEY --list=1000
2024-12-03 10:12:02 gpg-agent[6492] no running C:\\Program Files (x86)\\GnuPG\\bin\\scdaemon.exe daemon - starting it
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x000002a4 <- OK GNU Privacy Guard's Smartcard server ready, process 6272
2024-12-03 10:12:02 gpg-agent[6492] first connection to daemon C:\\Program Files (x86)\\GnuPG\\bin\\scdaemon.exe established
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x000002a4 -> GETINFO socket_name
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x000002a4 <- D C:\Users\g10code\AppData\Local\gnupg\S.scdaemon
2024-12-03 10:12:02 gpg-agent[6492] DBG: chan_0x000002a4 <- OK
2024-12-03 10:12:02 gpg-agent[6492] DBG: additional connections at 'C:\\Users\\g10code\\AppData\\Local\\gnupg\\S.scdaemon'

gpg logged this:

2024-12-03 10:11:08 gpg[3936] enabled debug flags: ipc
2024-12-03 10:11:08 gpg[3936] enabled compatibility flags:
2024-12-03 10:11:08 gpg[3936] verwende Vertrauensmodell pgp
2024-12-03 10:11:10 gpg[3936] Kein aktiver gpg-agent - `C:\\Program Files (x86)\\GnuPG\\bin\\gpg-agent.exe' wird gestartet
2024-12-03 10:11:11 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:13 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:15 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:16 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:19 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:20 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:22 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:23 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:26 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:27 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:30 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:31 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:33 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:34 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:37 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:38 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:41 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:42 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:44 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:45 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:48 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:49 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:52 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:53 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:55 gpg[3936] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:58 gpg[3936] Warte bis der gpg-agent bereit ist ... (8s)
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK Pleased to meet you, process 6492
2024-12-03 10:12:02 gpg[3936] Verbindung zum gpg-agent aufgebaut
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> RESET
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> OPTION ttyname=/dev/tty
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> OPTION putenv=QT_QPA_PLATFORM=windows:darkmode=2
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> GETINFO version
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- D 2.4.7
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> OPTION allow-pinentry-notify
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> OPTION agent-awareness=2.1.0
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> HAVEKEY --list=1000
2024-12-03 10:12:02 gpg[3936] DBG: chan_0000027c <- [ 44 20 07 af f5 9c 99 cf cd 72 e0 c7 a6 af 8f 94 ...(942 byte(s) skipped) ]
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c -> KEYINFO 950A511AA08C9A16C9FA3DD1AA8C1E4BF43E0B0F
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- S KEYINFO 950A511AA08C9A16C9FA3DD1AA8C1E4BF43E0B0F D - - - P - - -
2024-12-03 10:12:02 gpg[3936] DBG: chan_0x0000027c <- OK
[...]
2024-12-03 10:12:03 gpg[3936] DBG: chan_0x0000027c -> KEYINFO 58C8BB90D9D8565156786B1F17C4C6E404237F3A
2024-12-03 10:12:03 gpg[3936] DBG: chan_0x0000027c <- S KEYINFO 58C8BB90D9D8565156786B1F17C4C6E404237F3A D - - - C - - -
2024-12-03 10:12:03 gpg[3936] DBG: chan_0x0000027c <- OK
2024-12-03 10:12:03 gpg[3936] secmem usage: 0/32768 bytes in 0 blocks

gpgsm logged this:

2024-12-03 10:11:08 gpgsm[3940] enabled debug flags: ipc
2024-12-03 10:11:08 gpgsm[3940] enabled compatibility flags:
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> # Home: C:\Users\g10code\AppData\Roaming\gnupg
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> # Config: C:/Users/g10code/AppData/Roaming/gnupg/gpgsm.conf
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> # DirmngrInfo: C:\Users\g10code\AppData\Local\gnupg\S.dirmngr
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK GNU Privacy Guard's S/M server 2.4.7 ready, process 3940
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- OPTION ttyname=/dev/tty
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- OPTION enable-audit-log=1
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- OPTION allow-pinentry-notify
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- OPTION list-mode=1
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- OPTION with-validation=1
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- OPTION with-secret=1
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- OPTION offline=1
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 -> OK
2024-12-03 10:11:08 gpgsm[3940] DBG: chan_0x000001a0 <- LISTKEYS 
2024-12-03 10:11:10 gpgsm[3940] Kein aktiver gpg-agent - `C:\\Program Files (x86)\\GnuPG\\bin\\gpg-agent.exe' wird gestartet
2024-12-03 10:11:10 gpgsm[3940] DBG: chan_0x000001a0 -> S PROGRESS starting_agent ? 0 0
2024-12-03 10:11:11 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:13 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:15 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:16 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:19 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:20 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:22 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:24 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:26 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:27 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:30 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:31 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:33 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:35 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:37 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:38 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:41 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:42 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:44 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:45 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:48 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:49 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:52 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:53 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:55 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:57 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:11:59 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:12:00 gpgsm[3940] waiting for lock C:\\Users\\g10code\\AppData\\Roaming\\gnupg\\gnupg_spawn_agent_sentinel.lock...
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- OK Pleased to meet you, process 6492
2024-12-03 10:12:03 gpgsm[3940] DBG: connection to the gpg-agent established
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> RESET
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- OK
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> OPTION ttyname=/dev/tty
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- OK
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> OPTION putenv=QT_QPA_PLATFORM=windows:darkmode=2
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- OK
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> GETINFO version
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- D 2.4.7
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- OK
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> OPTION allow-pinentry-notify
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- OK
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> HAVEKEY 46B01CFBE21A10B2CFF41ABBD1D6A03E3F364121
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- ERR 67108881 Kein geheimer Schlüssel <GPG Agent>
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> ISTRUSTED 22FF41AB501FD708D10B0931E6F72A5C64DCF10E
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- S TRUSTLISTFLAG relax
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- OK
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 -> KEYINFO 46B01CFBE21A10B2CFF41ABBD1D6A03E3F364121
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x00000294 <- ERR 67108891 Nicht gefunden <GPG Agent>
[...]
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x000001a0 <- BYE
2024-12-03 10:12:03 gpgsm[3940] DBG: chan_0x000001a0 -> OK closing connection
2024-12-03 10:12:03 gpgsm[3940] secmem usage: 0/16384 bytes in 0 blocks

scdaemon logged this:

2024-12-03 10:12:02 scdaemon[6272] Es wird auf Socket `C:\\Users\\g10code\\AppData\\Local\\gnupg\\S.scdaemon' gehört
2024-12-03 10:12:02 scdaemon[6272] Handhabungsroutine für fd -1 gestartet
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 -> OK GNU Privacy Guard's Smartcard server ready, process 6272
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 <- GETINFO socket_name
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 -> D C:\Users\g10code\AppData\Local\gnupg\S.scdaemon
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 -> OK
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 <- OPTION event-signal=28c
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 -> OK
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 <- KEYINFO --list
2024-12-03 10:12:02 scdaemon[6272] DBG: chan_0x000002f8 -> OK
[...]

I'm wondering what happened (or why nothing happened) between the exit of gpg-agent[2816] at 10:11:12 and the start of gpg-agent[6492] at 10:12:00.

In the Windows event log I saw that at 10:12:05 Security-SPP ("software protection service" retranslated from German) is started, but that's probably unrelated because this is 5 seconds after the second gpg-agent instance finally allowed the keylistings to complete.

Let me guess: Kleopatra starts the agent using gpgconf --launch gpg-agent which in turn uses gpg-connect-agent to actually start the agent if needed. Kleopatra does not seem to wait for the launch to succeed and fires up gpg and gpgsm. They both wait for the gpg-agent to be started and both use the same locking strategy. However, this involves a pseudo random wait which should avoid deadlocks. See gnupg/common/dotlock.c:next_wait_interval

Yes, that's what happens. I did an experiment with waiting for gpgconf --launch gpg-agent to succeed, but the timeout of 5 seconds I used was too low and I didn't feel like increasing the timeout. Instead now we run gpgconf --launch gpg-agent detached.

Blocking the startup of Kleopatra waiting for gpg-agent to be running runs counter our wish to speed up the start of Kleopatra. On the other hand, if everything hangs for 50 seconds then we could as well have waited 30 seconds for gpg-agent to start up. gpg-agent should really be started automatically when the user logs in (on Windows).

Kleo needs this only because it wants to directly talk to gpg-agent via Assuan. For example to get smartcard infos. What about delaying this part until you have received some data back from gpg or gpgsm? This makes sure that the agent has been started.

Neither gpg nor gpgsm start gpg-agent if the keyring is empty. That's why Andre made Kleo start gpg-agent explicitly so that people could get going with an empty keyring after inserting their (PKCS#15) smartcard.

Nowadays smartcard access is already delayed until the first keylisting is done. And gpg-agent is started on demand nowadays if an Assuan transaction is used. So we could probably remove the explicit start of gpg-agent again. But that's would just make the hangs less likely because gpg and gpgsm still race for starting gpg-agent when they do the initial keylisting.

We can also serialize listing of the OpenPGP certificates and the S/MIME certificates. For T7332 I experimented with serializing the two key listings and it had a huge negative impact on the run time of the keyresolvercore unit test (which does lots of "initial" keylistings). It will have a lesser negative impact on normal users. Especially, if either OpenPGP or S/MIME is used primarily.

None of those changes would address the race problem of several GnuPG processes trying to start gpg-agent. There seems to be something wrong in gpg-agent or in start_new_service (asshelp.c) if all processes hanged (waiting for the lock to be lifted) for ~48 seconds after the first gpg-agent process exited because it failed to bind the socket. Is there a way to get logs of gpgconf and gpg-connect-agent? It seems that they lack the usual --debug and --log-file options.

I have created two subtasks for the two changes we could make in Kleopatra to avoid the gpg-agent startup race.