[pkg-gnupg-maint] Bug#840680: dirmngr: Dirmngr not always responding

Dhole dhole at openmailbox.org
Wed Oct 26 08:15:21 UTC 2016


Hi,

I'm also experiencing this bug.  I first noticed it while trying to
receive some keys with `gpg --recv-keys`.  It just hangs.  The same
happens with `caff`.

I managed to capture an strace with the following line:
`for i in `seq 0 1000`; do strace -o dirmngr.strace -f -tt -T -p $(pgrep dirmngr); done`

I'm attaching the strace capture as well as the dirmngr.log

Notice that I killed dirmngr at the end, so both the trace and the log
show a SIGTERM.

Funnily enough, while running strace the probability of `gpg` and `caff`
succeeding increases: while capturing the traces I managed to finally
sign a key with `caff`.

Just to give more info, this is the strace of gpg hanging:

    stat("/run/user/1000/gnupg/S.dirmngr", 0x7ffdcd5bf3a0) = -1 ENOENT (No such file or directory)
    socket(AF_UNIX, SOCK_STREAM, 0)         = 3
    stat("/run/user/1000/gnupg/S.dirmngr", 0x7ffdcd5bf3a0) = -1 ENOENT (No such file or directory)
    connect(3, {sa_family=AF_UNIX, sun_path="/run/user/1000/gnupg/S.dirmngr"}, 32) = -1 ENOENT (No such file or directory)
    close(3)                                = 0
    getuid()                                = 1000
    geteuid()                               = 1000
    access("/usr/bin/dirmngr", X_OK)        = 0
    clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f740051f9d0) = 9988
    wait4(9988, NULL, 0, NULL)              = 9988
    --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=9988, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
    nanosleep({1, 0}, 0x7ffdcd5bf550)       = 0
    stat("/run/user/1000/gnupg/S.dirmngr", {st_mode=S_IFSOCK|0700, st_size=0, ...}) = 0
    socket(AF_UNIX, SOCK_STREAM, 0)         = 3
    stat("/run/user/1000/gnupg/S.dirmngr", {st_mode=S_IFSOCK|0700, st_size=0, ...}) = 0
    connect(3, {sa_family=AF_UNIX, sun_path="/run/user/1000/gnupg/S.dirmngr"}, 32) = 0
    read(3, 

Thanks for the great job you're doing maintaining GnuPG :)

Cheers,
-- 
Dhole
-------------- next part --------------
7740  00:53:42.279421 futex(0x7f67b9f3b200, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ffffffff <unfinished ...>
7739  00:53:42.279472 pselect6(5, [0 4], NULL, NULL, {1, 985389545}, {[], 8} <unfinished ...>
7740  00:53:42.279496 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000027>
7740  00:53:42.279521 futex(0x7f67b9f3b200, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000007>
7740  00:53:42.279546 pselect6(1, [], NULL, NULL, {1, 999999919}, {NULL, 8} <unfinished ...>
7739  00:53:43.260796 <... pselect6 resumed> ) = 1 (in [4], left {1, 4173282}) <0.981294>
7739  00:53:43.261047 futex(0x7f67b9f3b200, FUTEX_WAKE_PRIVATE, 1) = 0 <0.000079>
7739  00:53:43.261289 accept(4, {sa_family=AF_UNIX}, [110->2]) = 1 <0.000073>
7739  00:53:43.261546 mmap(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f67b69d9000 <0.000025>
7739  00:53:43.261656 mprotect(0x7f67b69d9000, 4096, PROT_NONE) = 0 <0.000019>
7739  00:53:43.261729 clone(child_stack=0x7f67b71d8ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f67b71d99d0, tls=0x7f67b71d9700, child_tidptr=0x7f67b71d99d0) = 7745 <0.000059>
7739  00:53:43.261863 open("/proc/self/task/7745/comm", O_RDWR <unfinished ...>
7745  00:53:43.261905 set_robust_list(0x7f67b71d99e0, 24) = 0 <0.000019>
7739  00:53:43.261952 <... open resumed> ) = 2 <0.000055>
7745  00:53:43.261973 futex(0x7f67b9f3b200, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, ffffffff <unfinished ...>
7739  00:53:43.261997 write(2, "conn fd=1", 9) = 9 <0.000034>
7739  00:53:43.262079 close(2)          = 0 <0.000014>
7739  00:53:43.262121 pselect6(5, [0 4], NULL, NULL, {1, 2653195}, {[], 8}) = 0 (Timeout) <1.003769>
7739  00:53:44.266071 pselect6(5, [0 4], NULL, NULL, {2, 1047}, {[], 8} <unfinished ...>
7740  00:53:44.281660 <... pselect6 resumed> ) = 0 (Timeout) <2.002084>
7740  00:53:44.281816 pselect6(1, [], NULL, NULL, {2, 456}, {NULL, 8} <unfinished ...>
7739  00:53:46.268272 <... pselect6 resumed> ) = 0 (Timeout) <2.002118>
7739  00:53:46.268442 pselect6(5, [0 4], NULL, NULL, {2, 807}, {[], 8} <unfinished ...>
7740  00:53:46.283965 <... pselect6 resumed> ) = 0 (Timeout) <2.002092>
7740  00:53:46.284137 pselect6(1, [], NULL, NULL, {2, 393}, {NULL, 8} <unfinished ...>
7739  00:53:48.270655 <... pselect6 resumed> ) = 0 (Timeout) <2.002154>
7739  00:53:48.270849 pselect6(5, [0 4], NULL, NULL, {2, 1153}, {[], 8} <unfinished ...>
7740  00:53:48.286356 <... pselect6 resumed> ) = 0 (Timeout) <2.002156>
7740  00:53:48.286567 pselect6(1, [], NULL, NULL, {2, 578}, {NULL, 8} <unfinished ...>
7739  00:53:50.273123 <... pselect6 resumed> ) = 0 (Timeout) <2.002189>
7739  00:53:50.273349 pselect6(5, [0 4], NULL, NULL, {2, 1229}, {[], 8} <unfinished ...>
7740  00:53:50.288830 <... pselect6 resumed> ) = 0 (Timeout) <2.002181>
7740  00:53:50.289037 pselect6(1, [], NULL, NULL, {2, 554}, {NULL, 8} <unfinished ...>
7739  00:53:52.275644 <... pselect6 resumed> ) = 0 (Timeout) <2.002206>
7739  00:53:52.275819 pselect6(5, [0 4], NULL, NULL, {2, 1029}, {[], 8} <unfinished ...>
7740  00:53:52.291312 <... pselect6 resumed> ) = 0 (Timeout) <2.002194>
7740  00:53:52.291509 pselect6(1, [], NULL, NULL, {2, 481}, {NULL, 8} <unfinished ...>
7739  00:53:54.278091 <... pselect6 resumed> ) = 0 (Timeout) <2.002192>
7739  00:53:54.278306 pselect6(5, [0 4], NULL, NULL, {2, 1206}, {[], 8} <unfinished ...>
7740  00:53:54.293779 <... pselect6 resumed> ) = 0 (Timeout) <2.002193>
7740  00:53:54.293988 pselect6(1, [], NULL, NULL, {2, 598}, {NULL, 8} <unfinished ...>
7739  00:53:56.280591 <... pselect6 resumed> ) = 0 (Timeout) <2.002196>
7739  00:53:56.280794 pselect6(5, [0 4], NULL, NULL, {2, 1283}, {[], 8} <unfinished ...>
7740  00:53:56.296238 <... pselect6 resumed> ) = 0 (Timeout) <2.002167>
7740  00:53:56.296439 pselect6(1, [], NULL, NULL, {2, 10336}, {NULL, 8} <unfinished ...>
7739  00:53:58.283064 <... pselect6 resumed> ) = 0 (Timeout) <2.002186>
7739  00:53:58.283274 pselect6(5, [0 4], NULL, NULL, {2, 1303}, {[], 8} <unfinished ...>
7740  00:53:58.297672 <... pselect6 resumed> ) = 0 (Timeout) <2.001157>
7740  00:53:58.297809 pselect6(1, [], NULL, NULL, {2, 782}, {NULL, 8} <unfinished ...>
7739  00:54:00.285586 <... pselect6 resumed> ) = 0 (Timeout) <2.002199>
7739  00:54:00.285774 pselect6(5, [0 4], NULL, NULL, {2, 1153}, {[], 8} <unfinished ...>
7740  00:54:00.299992 <... pselect6 resumed> ) = 0 (Timeout) <2.002114>
7740  00:54:00.300106 pselect6(1, [], NULL, NULL, {2, 453}, {NULL, 8} <unfinished ...>
7739  00:54:01.821714 <... pselect6 resumed> ) = ? ERESTARTNOHAND (To be restarted if no handler) <1.535848>
7739  00:54:01.821799 --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=7764, si_uid=1000} ---
7739  00:54:01.821853 rt_sigreturn({mask=[HUP INT USR1 USR2 TERM]}) = -1 EINTR (Interrupted system call) <0.000024>
7739  00:54:01.821997 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2845, ...}) = 0 <0.000058>
7739  00:54:01.822205 write(3, "2016-10-26 00:54:01 dirmngr[7739"..., 36) = 36 <0.000042>
7739  00:54:01.822306 write(3, "SIGTERM received - shutting down"..., 37) = 37 <0.000017>
7739  00:54:01.822374 close(0)          = 0 <0.000026>
7739  00:54:01.822459 unlink("/run/user/1000/gnupg/S.dirmngr") = 0 <0.000032>
7739  00:54:01.822561 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2845, ...}) = 0 <0.000019>
7739  00:54:01.822649 write(3, "2016-10-26 00:54:01 dirmngr[7739"..., 58) = 58 <0.000020>
7739  00:54:01.822718 write(3, " stopped\n", 9) = 9 <0.000016>
7739  00:54:01.822792 close(4)          = 0 <0.000023>
7739  00:54:01.823081 exit_group(0)     = ?
7745  00:54:01.823209 +++ exited with 0 +++
7740  00:54:01.823602 +++ exited with 0 +++
7739  00:54:01.823638 +++ exited with 0 +++
-------------- next part --------------
2016-10-26 00:53:42 dirmngr[7736] listening on socket '/run/user/1000/gnupg/S.dirmngr'
2016-10-26 00:53:42 dirmngr[7739.0] permanently loaded certificates: 0
2016-10-26 00:53:42 dirmngr[7739.0]     runtime cached certificates: 0
2016-10-26 00:54:01 dirmngr[7739.0] SIGTERM received - shutting down ...
2016-10-26 00:54:01 dirmngr[7739.0] dirmngr (GnuPG) 2.1.15 stopped
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 801 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-gnupg-maint/attachments/20161026/de712492/attachment.sig>


More information about the pkg-gnupg-maint mailing list