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

[Craig Small]

Hi Daniel,
  I'm not sure if this helps, but using the connect manager gave an odd
result.

If I start connect manager, then gpg --send-key works immediately, it looks
just like your gpg-connect-agent output.
On another screen, I use gpg --send-key and that works. The key gets sent
and all is good.

However if I hit enter on the connect manager it exits but dirmngr keeps
running. gpg --send-key then is like before where it hangs.

This happened in both 2.1.15-4 and 2.1.15-5
However! I downloaded 2.1.15-6 and it sends the key fine, so it looks like
that was the fix for me.

 - Craig

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

[Daniel Kahn Gillmor]

Hi Dhole and Craig--

Thanks for your reports of dirmngr not responding.  I've tried to
reproduce this bug, and actually found it easiest to reproduce with:

 GNUPGHOME=$(mktemp -d) gpg-connect-agent --dirmngr

This should produce the following debugging info, followed by a "> "
prompt:

gpg-connect-agent: no running Dirmngr - starting '/usr/bin/dirmngr'
gpg-connect-agent: waiting for the dirmngr to come up ... (5s)
gpg-connect-agent: connection to the dirmngr established
> 

Instead, it was hanging.

I've just imported an upstream fix for hanging instances of dirmngr and
included it in an upload to unstable as 2.1.15-6, which i've marked as
fixing this bug.  Please try it out in the environments that were
hanging for you, and reopen this bug report if the problems are still
happening.

Many thanks for the reporting, testing, and followup!

Regards,

 --dkg


signature.asc
Description: PGP signature

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

[Francesco Poli]

Control: severity -1 grave


On Thu, 13 Oct 2016 19:16:56 -0400 Daniel Kahn Gillmor wrote:

> Control: tags 840680 + unreproducible moreinfo
> Control: severity 840680 important

Hello Daniel,
I am another user who's been bitten by this bug.

When the bug report severity was downgraded below the RC threshold,
apt-listbugs removed the pin on my boxes and I upgraded dirmngr.

  [UPGRADE] dirmngr:amd64 2.1.15-3 -> 2.1.15-4
  [UPGRADE] gnupg:amd64 2.1.15-3 -> 2.1.15-4
  [UPGRADE] gnupg-agent:amd64 2.1.15-3 -> 2.1.15-4

Immediately after, I was no longer able to refresh keys from the key
servers:

  $ gpg --keyserver-options no-honor-keyserver-url \
--import-options repair-pks-subkey-bug \
--refresh-keys 0x3E1C27E11F69BFFE
  ^C
  gpg: signal Interrupt caught ... exiting

I had to press [Ctrl+C] after a long wait with no output at all.

As soon as I downgraded dirmngr, everything was back to normal:

  # dpkg -i /var/cache/apt/archives/dirmngr_2.1.15-3_amd64.deb \
/var/cache/apt/archives/gnupg_2.1.15-3_amd64.deb \
/var/cache/apt/archives/gnupg-agent_2.1.15-3_amd64.deb
  [...]
  # checkrestart 
  Found 1 processes using old versions of upgraded files
  (1 distinct program)
  (1 distinct packages)
  These processes (1) do not seem to have an associated init script to restart 
them:
  dirmngr:
  5074/usr/bin/dirmngr
  # kill -TERM 5074
  # checkrestart 
  Found 0 processes using old versions of upgraded files
  $ gpg --keyserver-options no-honor-keyserver-url \
--import-options repair-pks-subkey-bug \
--refresh-keys 0x3E1C27E11F69BFFE
  gpg: removing stale lockfile (created by 5071)
  gpg: refreshing 1 key from hkp://pool.sks-keyservers.net
  gpg: key 0x3E1C27E11F69BFFE: "Francesco Poli (wintermute) 
" not changed
  gpg: Total number processed: 1
  gpg:  unchanged: 1


Please do not downgrade the severity of this bug report, until the bug
is fixed (this way apt-listbugs users will be warned about this issue
and will have an opportunity to pin the package, while waiting for a
fix).

Thanks for your time and for the great job in maintaining GnuPG in
Debian!



-- 
 http://www.inventati.org/frx/
 There's not a second to spare! To the laboratory!
. Francesco Poli .
 GnuPG key fpr == CA01 1147 9CD2 EFDF FB82  3925 3E1C 27E1 1F69 BFFE


pgp08vZMVOIV8.pgp
Description: PGP signature

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

[SJ Zhu]

> Thanks for this report.  it sounds frustrating!  I hope we can debug it:
> 
> is this "always not responding" or "sometimes not responding"?  I
> haven't observed the same behavior with dirmngr myself, so i'm not sure
> how to best proceed...
> 

I find it is 'sometimes'. To describe it, I use vlc to record a video of
my desktop, see https://www.youtube.com/watch?v=cOLuUKh-_nA
The video describes the problem, but the timestamp is not the same with
the log files I attached.

> this is definitely strange behavior!  have you tried attaching strace to
> the dirmngr process to see what it's doing while it's not answering you?
> or have you tried increasing the logging of dirmngr to see what it's
> doing while it's not responding?
> 
> if the process id of dirmngr is $DIRMNGR_PID, you can use:
> 
> strace -o dirmngr.strace -f -tt -T -p $DIRMNGR_PID
>

I have attach a dirmngr.strace.


> to get an strace dump.
> 
> You can increase the logging by adding these lines to
> ~/.gnupg/dirmngr.conf and then restarting dirmngr:
> 
> log-file /tmp/dirmngr.log
> debug-level advanced
> 

I have attach a dirmngr.log

In the dirmngr.log:
11:36:50 I launch dirmngr by `gpg-connect-agent --dirmngr /bye`
 But this `gpg-connect-agent` is stuch.
11:38:20 I attach strace to dirmngr, and the `gpg-connect-agent`
 returns.
11:39:52 I start second `gpg-connect-agent`, and stuck too
(In strace log, it seems dirmngr already writed to S.dirmngr)
11:40:15 I start third `gpg-connect-agent`, and the second returns.
Then I send `ctrl-c`

It seems no sensitive log, so I publish it to the BTS.

I don't know whether the config file is needed:

dirmngr.conf

keyserver hkp://sks.ustclug.org
hkp-cacert /usr/share/gnupg2/sks-keyservers.netCA.pem
hkp-cacert ~/.gnupg/trusted-certs/DST_Root_CA_X3.pem

log-file /tmp/dirmngr.log
debug-level advanced

gpg-agent.conf

enable-ssh-support

gpg.conf

default-key 7DFBB2F2
2016-10-14 11:36:50 dirmngr[20597] listening on socket 
'/run/user/1000/gnupg/S.dirmngr'
2016-10-14 11:36:50 dirmngr[20598.0] permanently loaded certificates: 0
2016-10-14 11:36:50 dirmngr[20598.0] runtime cached certificates: 0
2016-10-14 11:38:20 dirmngr[20598.1] handler for fd 1 started
2016-10-14 11:38:20 dirmngr[20598.1] DBG: chan_1 -> # Home: /home/zsj/.gnupg
2016-10-14 11:38:20 dirmngr[20598.1] DBG: chan_1 -> # Config: 
/home/zsj/.gnupg/dirmngr.conf
2016-10-14 11:38:20 dirmngr[20598.1] DBG: chan_1 -> OK Dirmngr 2.1.15 at your 
service
2016-10-14 11:38:20 dirmngr[20598.1] connection from process 20595 (1000:1000)
2016-10-14 11:38:20 dirmngr[20598.1] DBG: chan_1 <- [eof]
2016-10-14 11:38:20 dirmngr[20598.1] handler for fd 1 terminated
2016-10-14 11:39:52 dirmngr[20598.1] handler for fd 1 started
2016-10-14 11:39:52 dirmngr[20598.1] DBG: chan_1 -> # Home: /home/zsj/.gnupg
2016-10-14 11:39:52 dirmngr[20598.1] DBG: chan_1 -> # Config: 
/home/zsj/.gnupg/dirmngr.conf
2016-10-14 11:39:52 dirmngr[20598.1] DBG: chan_1 -> OK Dirmngr 2.1.15 at your 
service
2016-10-14 11:39:52 dirmngr[20598.1] connection from process 20745 (1000:1000)
2016-10-14 11:39:52 dirmngr[20598.1] DBG: chan_1 <- [eof]
2016-10-14 11:39:52 dirmngr[20598.1] handler for fd 1 terminated
2016-10-14 11:40:15 dirmngr[20598.2] handler for fd 2 started
2016-10-14 11:40:15 dirmngr[20598.2] DBG: chan_2 -> # Home: /home/zsj/.gnupg
2016-10-14 11:40:15 dirmngr[20598.2] Assuan accept problem: Broken pipe
2016-10-14 11:40:15 dirmngr[20598.2] handler for fd 2 terminated
20600 11:38:20.134818 futex(0x7fa74998d200, 
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL,  
20599 11:38:20.134970 pselect6(1, [], NULL, NULL, {1, 56253895}, {NULL, 8} 

20600 11:38:20.135039 <... futex resumed> ) = -1 EAGAIN (Resource temporarily 
unavailable) <0.89>
20600 11:38:20.135122 mmap(NULL, 134217728, PROT_NONE, 
MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0 
20598 11:38:20.135189 pselect6(5, [0 4], NULL, NULL, {0, 91526580}, {[], 8} 

20600 11:38:20.135265 <... mmap resumed> ) = 0x7fa73e0e2000 <0.92>
20600 11:38:20.135524 munmap(0x7fa73e0e2000, 32628736) = 0 <0.000110>
20600 11:38:20.135737 munmap(0x7fa74400, 34480128) = 0 <0.35>
20600 11:38:20.135833 mprotect(0x7fa74000, 135168, PROT_READ|PROT_WRITE) = 
0 <0.33>
20600 11:38:20.136019 stat("/etc/localtime", {st_mode=S_IFREG|0644, 
st_size=414, ...}) = 0 <0.48>
20600 11:38:20.136247 write(3, "2016-10-14 11:38:20 dirmngr[2059"..., 53) = 53 
<0.42>
20600 11:38:20.136359 write(3, " started\n", 9) = 9 <0.35>
20600 11:38:20.136576 getsockopt(1, SOL_SOCKET, SO_PEERCRED, {pid=20595, 
uid=1000, gid=1000}, [12]) = 0 <0.32>
20600 11:38:20.136702 stat("/etc/localtime", {st_mode=S_IFREG|0644, 
st_size=414, ...}) = 0 <0.39>
20600 11:38:20.136834 write(3, "2016-10-14 11:38:20 dirmngr[2059"..., 42) = 42 
<0.29>
20600 11:38:20.136920 write(3, "chan_1 -> # Home: /home/zsj/.gnu"..., 35) = 35 
<0.29>
20600 11:38:20.137018 futex(0x7fa74998d200, FUTEX_WAKE_PRIVATE, 1) = 0 

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

[Daniel Kahn Gillmor]

Control: tags 840680 + unreproducible moreinfo
Control: severity 840680 important

hi Shengjing--

Thanks for this report.  it sounds frustrating!  I hope we can debug it:

On Thu 2016-10-13 15:12:44 -0400, Shengjing Zhu wrote:
> After upgrade to 2.1.15-4, I find dirmngr is not always responding
> which makes command like `gpg --refresh-keys` stuck.

is this "always not responding" or "sometimes not responding"?  I
haven't observed the same behavior with dirmngr myself, so i'm not sure
how to best proceed...

> I test dirmngr with the following steps:
>
> First run `gpg-connect-agent --dirmngr /bye`
> It should immediately return but it's stuck.
>
> But I open another shell to run `gpg-connect-agent --dirmngr /bye`
> again. The first gpg-connect-agent returns and the second still is
> stuck.
>
> And I run again `gpg-connect-agent` and the previous one returns.

this is definitely strange behavior!  have you tried attaching strace to
the dirmngr process to see what it's doing while it's not answering you?
or have you tried increasing the logging of dirmngr to see what it's
doing while it's not responding?

if the process id of dirmngr is $DIRMNGR_PID, you can use:

strace -o dirmngr.strace -f -tt -T -p $DIRMNGR_PID

to get an strace dump.

You can increase the logging by adding these lines to
~/.gnupg/dirmngr.conf and then restarting dirmngr:

log-file /tmp/dirmngr.log
debug-level advanced

If you've got dirmgnr logs or strace output that you think might be
worth sharing, but are maybe too sensitive to post to this public bug
report, feel free to send them privately to me (you can encrypt to
0EE5BE979282D80B9F7540F1CCD2ED94D21739E9 if you like).

> So I guess only another process access to the dirmngr socket, the
> previous connect will be got processed.

I'm not sure what you mean by this.  can you explain?

  --dkg


signature.asc
Description: PGP signature