Maniphest T8491

Mac Kleopatra: Update of smime certificate via ldap does not finish
Open, NormalPublic
Actions

Assigned To
None
Authored By
timegrid
Fri, Oct 9, 3:34 PM
Tags
Subscribers
• ikloecker
tfry
timegrid

Description

To reproduce:

  1. Add an LDAP server
  2. Search and import a certificate
  3. Update the certificate (via context menu in the certificate list) => Update Certificate progress is shown, but in does not finish

Notes:

  • nothing logged for gpgsm on "Update"
  • gpgme seems not be able to log to a file. the log level is adjusted with the envvar though, but the log is printed on stderr: export GPGME_DEBUG="9;/Users/arnold/tests/log/gpgme.log"
  • gpgme seems to be in a loop (already after displaying the main certificate list, update was on 14:35:29, nothing logged on "Update"). the same log level does not contain anything similar on windows (no "poll" found):
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: enter: fd=35 msg=0x000000016d3344d8 flags=0
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: check: about to receive 3 bytes
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: check: BYE
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: leave: result=3
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: enter: fd=35 msg=0x000000016d3344d8 flags=0
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: check: about to receive 1 bytes
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: check: <LF>
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_sendmsg: leave: result=1
2026-10-09 14:35:04 gpgme[9967] _assuan_close (ctx=0x0000000bccaf7000): call: fd=0x23\n
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_close: enter: fd=35
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_close: leave: result=0
2026-10-09 14:35:04 gpgme[9967] gpgme_data_release: call: dh=0x0000000bcfd8e800 
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll OK [ r=27 (11) r=31 (11) r=33 (11) ]
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: leave: result=3
2026-10-09 14:35:04 gpgme[9967]   _gpgme_run_io_cb: call: item=0x0000000bcfd944c0 need to check
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: enter: nfds=1, nonblock=1
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll on [ r=27 ]
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll OK [ r=27 (11) ]
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: leave: result=1
2026-10-09 14:35:04 gpgme[9967]   _gpgme_run_io_cb: call: item=0x0000000bcfd944c0 handler (0x0000000bcc7d5680, 27)
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_read: enter: fd=27 buffer=0x0000000bcef30000 count=1024
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_read: leave: result=0
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_close: enter: fd=27
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_close: check: invoking close handler 0x0000000103b4cf80/0x0000000bcc7d5680
2026-10-09 14:35:04 gpgme[9967]     _gpgme_remove_io_cb: call: data=0x0000000bcc7df260 setting fd 0x1b (item=0x0000000bcfd944c0) done
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_close: leave: result=0
2026-10-09 14:35:04 gpgme[9967]   _gpgme_run_io_cb: call: item=0x0000000bcfd941c0 need to check
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: enter: nfds=1, nonblock=1
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll on [ r=31 ]
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll OK [ r=31 (11) ]
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: leave: result=1
2026-10-09 14:35:04 gpgme[9967]   _gpgme_run_io_cb: call: item=0x0000000bcfd941c0 handler (0x0000000bcc7d5680, 31)
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_read: enter: fd=31 buffer=0x0000000bced1b800 count=1024
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_read: leave: result=0
2026-10-09 14:35:04 gpgme[9967]   gpgme:keylist_colon_handler: call: ctx=0x0000000bcc120000 key = 0x0000000bcc18b480, line = (null)
2026-10-09 14:35:04 gpgme[9967]   gpgme:gpg_io_event: call: gpg=0x0000000bcc7d5680 event 0x0000000103b27f10, type 2, type_data 0x0000000bcc18b480
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_close: enter: fd=31
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_close: check: invoking close handler 0x0000000103b4cf80/0x0000000bcc7d5680
2026-10-09 14:35:04 gpgme[9967]     _gpgme_remove_io_cb: call: data=0x0000000bcc7df280 setting fd 0x1f (item=0x0000000bcfd941c0) done
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_close: leave: result=0
2026-10-09 14:35:04 gpgme[9967]   _gpgme_run_io_cb: call: item=0x0000000bcfd94400 need to check
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: enter: nfds=1, nonblock=1
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll on [ r=33 ]
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll OK [ r=33 (11) ]
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: leave: result=1
2026-10-09 14:35:04 gpgme[9967]   _gpgme_run_io_cb: call: item=0x0000000bcfd94400 handler (0x0000000bcfd8e580, 33)
2026-10-09 14:35:04 gpgme[9967]   _gpgme_data_inbound_handler: enter: dh=0x0000000bcfd8e580 fd=33
2026-10-09 14:35:04 gpgme[9967]     _gpgme_io_read: enter: fd=33 buffer=0x000000016dada4c8 count=512
2026-10-09 14:35:04 gpgme[9967]     _gpgme_io_read: leave: result=0
2026-10-09 14:35:04 gpgme[9967]     _gpgme_io_close: enter: fd=33
2026-10-09 14:35:04 gpgme[9967]     _gpgme_io_close: check: invoking close handler 0x0000000103b4cf80/0x0000000bcc7d5680
2026-10-09 14:35:04 gpgme[9967]       _gpgme_remove_io_cb: call: data=0x0000000bcc7df2a0 setting fd 0x21 (item=0x0000000bcfd94400) done
2026-10-09 14:35:04 gpgme[9967]     _gpgme_io_close: leave: result=0
2026-10-09 14:35:04 gpgme[9967]   _gpgme_data_inbound_handler: leave: 
2026-10-09 14:35:04 gpgme[9967]   gpgme:gpg_io_event: call: gpg=0x0000000bcc7d5680 event 0x0000000103b27f10, type 1, type_data 0x000000016dada774
2026-10-09 14:35:04 gpgme[9967] gpgme_op_keylist_next: leave: key=0x0000000bcc18b480 (1493269DE61F124AA69A316E3ADF34EBDBB200A4)
2026-10-09 14:35:04 gpgme[9967] gpgme_get_keylist_mode: call: ctx=0x0000000bcc120000 ctx->keylist_mode=0x11d
2026-10-09 14:35:04 gpgme[9967] gpgme_op_keylist_next: enter: ctx=0x0000000bcc120000 
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: enter: nfds=10, nonblock=0
2026-10-09 14:35:04 gpgme[9967] _gpgme_io_select: check: poll on [ ]
2026-10-09 14:35:04 gpgme[9967]   _gpgme_io_select: leave: result=0
2026-10-09 14:35:04 gpgme[9967]   gpgme:gpg_io_event: call: gpg=0x0000000bcc7d5680 event 0x0000000103b27f10, type 1, type_data 0x000000016dada774
2026-10-09 14:35:04 gpgme[9967] gpgme_op_keylist_next:1457: error: End of file <GPGME>\n
2026-10-09 14:35:04 gpgme[9967] gpgme_op_keylist_end: call: ctx=0x0000000bcc120000 
2026-10-09 14:35:04 gpgme[9967] gpgme_op_keylist_result: enter: ctx=0x0000000bcc120000 
2026-10-09 14:35:04 gpgme[9967] gpgme_op_keylist_result: check: ctx=0x0000000bcc120000 truncated = 0
2026-10-09 14:35:04 gpgme[9967] gpgme_op_keylist_result: leave: result=0x0000000bcfd3ec60
2026-10-09 14:35:04 gpgme[9967] gpgme_set_keylist_mode: call: ctx=0x0000000bcc120000 keylist_mode=0x10d
2026-10-09 14:35:04 gpgme[9967] gpgme_cancel_async: enter: ctx=0x0000000bcc120000 
2026-10-09 14:35:04 gpgme[9967] gpgme_cancel_async: leave: 
2026-10-09 14:35:04 gpgme[9967] gpgme_release: call: ctx=0x0000000bcc120000 
2026-10-09 14:35:04 gpgme[9967] gpgme_data_release: call: dh=0x0000000000000000 
2026-10-09 14:35:04 gpgme[9967] gpgme_data_release: call: dh=0x0000000bcfd8e580 
2026-10-09 14:35:05 gpgme[9967] _gpgme_io_select: check: poll OK [ ]
2026-10-09 14:35:05 gpgme[9967] _gpgme_io_select: leave: result=0

2026-10-09 14:35:05 gpgme[9967] _gpgme_io_select: enter: nfds=10, nonblock=0
2026-10-09 14:35:05 gpgme[9967] _gpgme_io_select: check: poll on [ r=23 ]
2026-10-09 14:35:06 gpgme[9967] _gpgme_io_select: check: poll OK [ ]
2026-10-09 14:35:06 gpgme[9967] _gpgme_io_select: leave: result=0

2026-10-09 14:35:06 gpgme[9967] _gpgme_io_select: enter: nfds=10, nonblock=0
2026-10-09 14:35:06 gpgme[9967] _gpgme_io_select: check: poll on [ r=23 ]
2026-10-09 14:35:07 gpgme[9967] _gpgme_io_select: check: poll OK [ ]
2026-10-09 14:35:07 gpgme[9967] _gpgme_io_select: leave: result=0

2026-10-09 14:35:07 gpgme[9967] _gpgme_io_select: enter: nfds=10, nonblock=0
2026-10-09 14:35:07 gpgme[9967] _gpgme_io_select: check: poll on [ r=23 ]
2026-10-09 14:35:08 gpgme[9967] _gpgme_io_select: check: poll OK [ ]
2026-10-09 14:35:08 gpgme[9967] _gpgme_io_select: leave: result=0
[...]

Details

Version
gpg4win-5.2.0-beta783 @ mac26.6

Revisions and Commits

rGPGMEQT Gpgme for Qt
rGPGMEQT50e3888dc59f Properly look up gpgsm binary when refreshing keys

Event Timeline

timegrid triaged this task as Normal priority.Fri, Oct 9, 3:34 PM
timegrid created this task.
timegrid created this object with edit policy "Contributor (Project)".
tfry added a comment.EditedWed, Oct 28, 4:18 PM

I do not think the polling in the logs is related to this issue, but it may be something to look at, separately(?).

The main here while is caused be two subproblems:

  • qgpgme tries to call gpgsm (yes, the standalone binary), but that isn't found -> qgpgme should be made smarter about where to look for the binary: -> Should use the same logic as in libkleo's Kleo::gpgSmPath() ; other places in qgpgme should be reviewed for similar issues.
  • the failed-to-start error is never signalled to kleopatra, and so it looks like the job never finishes (definitely a qgpgme bug; QGpgMERefreshSMIMEKeysJob::startAProcess()).
tfry added a subscriber: • ikloecker.Thu, Oct 29, 12:51 PM

@ikloecker

Fixed in qgpgme work/tfry/gpgsm_lookup. Three other job types invoke gpgXY binaries via QProcess, but those are already doing lookup via GpgME::binDir().

tfry added a commit: rGPGMEQT50e3888dc59f: Properly look up gpgsm binary when refreshing keys.Thu, Oct 29, 5:17 PM