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

Assigned To

Authored By

	• aheinecke
	Aug 30 2018, 10:23 AM

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

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.

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

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",

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

Long since resolved

Kleopatra: Hang on posix with GPGME_DEBUG=9Closed, ResolvedPublicActions

Description

Event Timeline

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