Page MenuHome GnuPG
Create Task
Maniphest T4116

Kleopatra: Hang on posix with GPGME_DEBUG=9
Closed, ResolvedPublic
Actions

Description

Noticed while testing Kleopatra does repeatedly not start for me. This is the first time I'm seeing this.

Sometimes it starts but often times it hangs. Strace shows a read while it is hanging.
Version gpgme-1.11.2-beta247 gpg 2.2.9-beta11

Strangely enough t-gpgconf works without a problem even if I run it 1000 times. Maybe something with gpgme++? Looking into it.

Attaching GDB resulted in the following backtrace:

(gdb) bt full
#0  0x00007f1bd6fcb20d in read () at ../sysdeps/unix/syscall-template.S:84
No locals.
#1  0x00007f1bd6da6bb5 in _gpgme_ath_read (fd=<optimized out>, buf=<optimized out>, nbytes=<optimized out>)
    at ../../../src/gpgme/src/ath.c:84
No locals.
#2  0x00007f1bd6da0d08 in _gpgme_io_read (fd=22, buffer=buffer@entry=0x55d2d45f1300, count=count@entry=1023)
    at ../../../src/gpgme/src/posix-io.c:116
        nread = <optimized out>
        _gpgme_trace_func = 0x7f1bd6dabd7f "_gpgme_io_read"
        _gpgme_trace_tagname = 0x7f1bd6daa625 "fd"
        _gpgme_trace_tag = 0x16
#3  0x00007f1bd6d9ab97 in gpgconf_read (engine=engine@entry=0x55d2d45f08c0, 
    arg1=arg1@entry=0x7f1bd6daa491 "--list-options", arg2=<optimized out>, 
    cb=cb@entry=0x7f1bd6d9be40 <gpgconf_config_load_cb2>, hook=hook@entry=0x55d2d45ea350)
    at ../../../src/gpgme/src/engine-gpgconf.c:275
        gpgconf = 0x55d2d45f08c0
        err = 0
        linebuf = 0x55d2d45f1300 "X\v<\324\033\177"
        linebufsize = <optimized out>
        linelen = 0
        argv = {0x55d2d45f08e0 "/opt/gnupg/bin/gpgconf", 0x7f1bd6daa491 "--list-options", 0x55d2d45f1710 "gpg", 
          0x0, 0x20 <error: Cannot access memory at address 0x20>, 0x0}
        argc = <optimized out>
        rp = {22, 23}
        cfd = {{fd = 23, dup_to = 1, peer_name = 23, arg_loc = 0}, {fd = -1, dup_to = -1, peer_name = 0, 
            arg_loc = 0}}
        status = <optimized out>
        nread = <optimized out>
        mark = <optimized out>
#4  0x00007f1bd6d9ae3e in gpgconf_conf_load (engine=0x55d2d45f08c0, comp_p=0x7fff9ce82c58)
    at ../../../src/gpgme/src/engine-gpgconf.c:582
        err = 0
        comp = 0x55d2d45ea350
        cur_comp = 0x55d2d45ea350
#5  0x00007f1bd6da03f4 in gpgme_op_conf_load (ctx=0x55d2d45f0610, conf_p=conf_p@entry=0x7fff9ce82c58)
    at ../../../src/gpgme/src/gpgconf.c:85
        err = <optimized out>
        proto = GPGME_PROTOCOL_OpenPGP
#6  0x00007f1bd724e46a in GpgME::Configuration::Component::load (returnedError=...)
    at ../../../../../src/gpgme/lang/cpp/src/configuration.cpp:78
        err = <optimized out>
        ctx_native = 0x55d2d45f0610
        ctx = std::shared_ptr (count 1, weak 0) 0x0
        conf_list_native = 0x0
        head = <optimized out>

Event Timeline

aheinecke created this task.Aug 30 2018, 10:23 AM
aheinecke renamed this task from Kleopatra: Hang in gpgconf_read on posix to Kleopatra: Hang in gpgconf_read on posix with GPGME_DEBUG=9.Aug 30 2018, 10:50 AM
aheinecke lowered the priority of this task from High to Normal.

This happens only if GPGME_DEBUG is set to 9 which was accidentally set in my environment. So I've lowered the priority.

Buit even with that set I can't reproduce it without Kleopatra.

aheinecke added a comment.Dec 17 2018, 8:29 AM

Even with the logging changes this still happens. I just retested it. Can't run Kleopatra on Linux with GPGME_DEBUG=9.

aheinecke renamed this task from Kleopatra: Hang in gpgconf_read on posix with GPGME_DEBUG=9 to Kleopatra: Hang on posix with GPGME_DEBUG=9.Jun 5 2019, 11:05 AM
aheinecke added a subscriber: wk.

I have a hang now when keylisting in Kleo with GPGME_DEBUG=9:

(gdb) bt full
#0 lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
No locals.
#1 0x00007fda16882714 in GI___pthread_mutex_lock (mutex=mutex@entry=0x7fda16877908 <debug_lock+8>)

at ../nptl/pthread_mutex_lock.c:80
    ignore1 = <optimized out>
    ignore2 = <optimized out>
    ignore3 = <optimized out>
    type = <optimized out>
    __PRETTY_FUNCTION__ = "__pthread_mutex_lock"
    id = <optimized out>

#2 0x00007fda16c747d9 in _gpgrt_lock_lock (lockhd=lockhd@entry=0x7fda16877900 <debug_lock>)

at ../../../src/libgpg-error/src/posix-lock.c:174
    lock = 0x7fda16877900 <debug_lock>
    rc = <optimized out>

#3 0x00007fda16c7e8d5 in gpgrt_lock_lock (lockhd=lockhd@entry=0x7fda16877900 <debug_lock>)

at ../../../src/libgpg-error/src/visibility.c:135

No locals.
#4 0x00007fda1685d851 in _gpgme_debug (level=level@entry=7, mode=mode@entry=0,

func=func@entry=0x7fda16866ab2 "gpgme:max_fds", tagname=tagname@entry=0x7fda16864532 "0", 
tagvalue=tagvalue@entry=0x0, format=format@entry=0x7fda16866aa1 "max fds=%ld (%s)")
at /home/aheinecke/dev/main/src/gpgme/src/debug.c:266
    arg_ptr = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7fd9f3ffe100, 
        reg_save_area = 0x7fd9f3ffe010}}
    saved_errno = 0
    need_lf = <optimized out>
    output = 0x1 <error: Cannot access memory at address 0x1>
    out_len = <optimized out>

#5 0x00007fda1685ad04 in get_max_fds () at /home/aheinecke/dev/main/src/gpgme/src/posix-io.c:431

source = 0x7fda16866a6e "/proc"
fds = 35
rc = <optimized out>

#6 0x00007fda1685ba58 in _gpgme_io_spawn (path=path@entry=0x55b7f9088a40 "/opt/gnupg/bin/gpgsm",

argv=argv@entry=0x7fd9f3ffe790, flags=flags@entry=5, fd_list=fd_list@entry=0x7fd9ec007d10, atfork=atfork@entry=
0x7fda16c9b930 <at_socketpair_fork_cb>, atforkvalue=atforkvalue@entry=0x7fd9f3ffe6b0, r_pid=0x7fd9f3ffe6a4)
at /home/aheinecke/dev/main/src/gpgme/src/posix-io.c:535
    fd = <optimized out>
    seen_stdin = 0
    seen_stdout = 0
    max_fds = -1
    seen_stderr = 0
    pid = 0
    i = <optimized out>
    status = 103168
    signo = 0
    _gpgme_trace_func = 0x7fda16866baf "_gpgme_io_spawn"
    _gpgme_trace_tagname = 0x7fda168655f8 "path"
    _gpgme_trace_tag = 0x55b7f9088a40

#7 0x00007fda16849707 in my_spawn (ctx=<optimized out>, r_pid=0x7fd9f3ffe6a4,

name=0x55b7f9088a40 "/opt/gnupg/bin/gpgsm", argv=0x7fd9f3ffe790, fd_in=-1, fd_out=-1, 
fd_child_list=0x7fd9ec007600, atfork=0x7fda16c9b930 <at_socketpair_fork_cb>, atforkvalue=0x7fd9f3ffe6b0, flags=0)
at /home/aheinecke/dev/main/src/gpgme/src/assuan-support.c:259
    err = 0
    fd_items = 0x7fd9ec007d10

--Type <RET> for more, q to quit, c to continue without paging--

i = <optimized out>
__PRETTY_FUNCTION__ = "my_spawn"

#8 0x00007fda16c96713 in _assuan_spawn (ctx=ctx@entry=0x7fd9ec006450, r_pid=r_pid@entry=0x7fd9f3ffe6a4,

name=name@entry=0x55b7f9088a40 "/opt/gnupg/bin/gpgsm", argv=argv@entry=0x7fd9f3ffe790, fd_in=fd_in@entry=-1, 
fd_out=fd_out@entry=-1, fd_child_list=0x7fd9ec007600, atfork=0x7fda16c9b930 <at_socketpair_fork_cb>, 
atforkvalue=0x7fd9f3ffe6b0, flags=0) at ../../../src/libassuan/src/system.c:337
    res = <optimized out>
    i = <optimized out>
    _assuan_trace_context = 0x7fd9ec006450
    _assuan_trace_func = 0x7fda16ca042f "_assuan_spawn"
    _assuan_trace_tagname = 0x7fda16c9ed82 "ctx"
    _assuan_trace_tag = 0x7fd9ec006450

#9 0x00007fda16c9bed8 in socketpair_connect (atforkvalue=0x0, atfork=0x0, fd_child_list=0x7fd9f3ffe7d0,

argv=0x7fd9f3ffe790, name=0x55b7f9088a40 "/opt/gnupg/bin/gpgsm", ctx=0x7fd9ec006450)
at ../../../src/libassuan/src/assuan-pipe-connect.c:327
    err = <optimized out>
    fds = {33, 34}
    pid = 0
    _assuan_trace_tagname = 0x7fda16c9ed82 "ctx"
    _assuan_trace_tag = 0x7fd9ec006450
    _assuan_trace_context = 0x7fd9ec006450
    _assuan_trace_level = 2
    idx = <optimized out>
    mypidstr = "20508", '\000' <repeats 44 times>
    child_fds = 0x7fd9ec007600
    child_fds_cnt = <optimized out>
    atp = {peer_fd = 34, user_atfork = 0x0, user_atforkvalue = 0x0, parent_pid = 20508}
    rc = <optimized out>
    _assuan_trace_func = 0x7fda16c9ff75 "socketpair_connect"
    err = <optimized out>
    idx = <optimized out>
    fds = <optimized out>
    mypidstr = <optimized out>
    pid = <optimized out>
    child_fds = <optimized out>
    child_fds_cnt = <optimized out>
    atp = <optimized out>
    rc = <optimized out>
    _assuan_trace_context = <optimized out>
    _assuan_trace_level = <optimized out>
    _assuan_trace_func = <optimized out>
    _assuan_trace_tagname = <optimized out>
    _assuan_trace_tag = <optimized out>

#10 assuan_pipe_connect (ctx=0x7fd9ec006450, name=name@entry=0x55b7f9088a40 "/opt/gnupg/bin/gpgsm",

aheinecke added a comment.Jun 5 2019, 11:06 AM

Log loops with:

GPGME 2019-06-05 11:05:22 <0x5043> _gpgme_io_select: check: fds=0x00007fd9f8007200, select on [ r0x16 r0x1a r0x1c ]
GPGME 2019-06-05 11:05:23 <0x5043> _gpgme_io_select: check: fds=0x00007fd9f8007200, select OK [ ]
GPGME 2019-06-05 11:05:23 <0x5043> _gpgme_io_select: leave: result=0
GPGME 2019-06-05 11:05:23 <0x5043> _gpgme_io_select: enter: fds=0x7fd9f8007200 nfds=10, nonblock=0
GPGME 2019-06-05 11:05:23 <0x5043> _gpgme_io_select: check: fds=0x00007fd9f8007200, select on [ r0x16 r0x1a r0x1c ]
GPGME 2019-06-05 11:05:24 <0x5043> _gpgme_io_select: check: fds=0x00007fd9f8007200, select OK [ ]
GPGME 2019-06-05 11:05:24 <0x5043> _gpgme_io_select: leave: result=0
GPGME 2019-06-05 11:05:24 <0x5043> _gpgme_io_select: enter: fds=0x7fd9f8007200 nfds=10, nonblock=0
GPGME 2019-06-05 11:05:24 <0x5043> _gpgme_io_select: check: fds=0x00007fd9f8007200, select on [ r0x16 r0x1a r0x1c ]
GPGME 2019-06-05 11:05:25 <0x5043> _gpgme_io_select: check: fds=0x00007fd9f8007200, select OK [ ]
GPGME 2019-06-05 11:05:25 <0x5043> _gpgme_io_select: leave: result=0

aheinecke closed this task as Resolved.Jan 12 2021, 12:13 PM

Long since resolved