[pkg-gnupg-maint] Bug#914395: Bug#914395: Bug#914395: dirmngr log

[Daniel Kahn Gillmor]

On Mon 2018-11-26 08:42:20 +0100, Werner Koch wrote:
> On Sun, 25 Nov 2018 22:22, csmall at debian.org said:
>> It seems it needs the SRV record and fails wrong without it.
>> Checking on the same system looking up that SRV record I get the
>> expected NXDOMAIN error.
>
> That seems to be a Debian specific problem; with a dirmngr started by
> the gpg command, I get this with master (and pretty sure also with 2.2.11):

I don't see the problem on my local network when using 2.2.11-1 (that
is, including the debian-specific patches, and using dirmngr as launched
by the local user's systemd instance). 

I wouldn't be surprised if the problems about the specific network are
the cause here.

~/.gnupg/dirmngr.conf contains only:

    debug ipc,dns,network

And I ran the following two commands:

    systemctl --user stop dirmngr
    gpg-connect-agent --dirmngr 'KEYSERVER --clear hkp://keyring.debian.org' 'KS_GET -- 0xDF50FEA5' /bye

To get the logs, i ran:

    journalctl --since -10min --user-unit dirmngr.service

Nov 26 16:24:04 testhost systemd[1509]: Started GnuPG network certificate management daemon.
Nov 26 16:24:04 testhost dirmngr[32374]: dirmngr[32374]: enabled debug flags: ipc dns network
Nov 26 16:24:04 testhost dirmngr[32374]: permanently loaded certificates: 129
Nov 26 16:24:04 testhost dirmngr[32374]:     runtime cached certificates: 0
Nov 26 16:24:04 testhost dirmngr[32374]:            trusted certificates: 129 (128,0,0,1)
Nov 26 16:24:04 testhost dirmngr[32374]: handler for fd 5 started
Nov 26 16:24:04 testhost dirmngr[32374]: DBG: chan_5 -> # Home: /home/dkg/.gnupg
Nov 26 16:24:04 testhost dirmngr[32374]: DBG: chan_5 -> # Config: /home/dkg/.gnupg/dirmngr.conf
Nov 26 16:24:04 testhost dirmngr[32374]: DBG: chan_5 -> OK Dirmngr 2.2.11 at your service
Nov 26 16:24:04 testhost dirmngr[32374]: connection from process 32373 (1000:1000)
Nov 26 16:24:04 testhost dirmngr[32374]: DBG: chan_5 <- KEYSERVER --clear hkp://keyring.debian.org
Nov 26 16:24:04 testhost dirmngr[32374]: DBG: chan_5 -> OK
Nov 26 16:24:04 testhost dirmngr[32374]: DBG: chan_5 <- KS_GET -- 0xDF50FEA5
Nov 26 16:24:04 testhost dirmngr[32374]: DBG: dns: libdns initialized (tor mode)
Nov 26 16:24:05 testhost dirmngr[32374]: DBG: dns: getsrv(_pgpkey-http._tcp.keyring.debian.org) -> 0 records
Nov 26 16:24:05 testhost dirmngr[32374]: DBG: dns: libdns initialized (tor mode)
Nov 26 16:24:06 testhost dirmngr[32374]: DBG: dns: resolve_dns_name(keyring.debian.org): Success
Nov 26 16:24:06 testhost dirmngr[32374]: resolve_dns_addr for 'keyring.debian.org': 'keyring.debian.org' [already known]
Nov 26 16:24:06 testhost dirmngr[32374]: number of system provided CAs: 128
Nov 26 16:24:06 testhost dirmngr[32374]: DBG: Using TLS library: GNUTLS 3.5.19
Nov 26 16:24:06 testhost dirmngr[32374]: DBG: http.c:connect_server: trying name='keyring.debian.org' port=11371
Nov 26 16:24:07 testhost dirmngr[32374]: DBG: dns: resolve_dns_name(keyring.debian.org): Success
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: http.c:1877:socket_new: object 0x00007f2b0c3490a0 for fd 6 created
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: http.c:request:
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: >> GET /pks/lookup?op=get&options=mr&search=0xDF50FEA5 HTTP/1.0\r\n
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: >> Host: keyring.debian.org:11371\r\n
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: http.c:request-header:
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: >> \r\n
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: chan_5 -> S PROGRESS tick ? 0 0
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: http.c:response:
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: >> HTTP/1.1 200 OK\r\n
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'Date: Mon, 26 Nov 2018 21:24:08 GMT'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'Server: Apache'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'X-Content-Type-Options: nosniff'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'X-Frame-Options: sameorigin'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'Referrer-Policy: no-referrer'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'X-Xss-Protection: 1'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'Vary: Accept-Encoding'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'X-Clacks-Overhead: GNU Terry Pratchett'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'Connection: close'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: 'Content-Type: text/html; charset=ISO-8859-1'
Nov 26 16:24:08 testhost dirmngr[32374]: http.c:RESP: ''
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: chan_5 -> S SOURCE http://keyring.debian.org:11371
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: (20847 bytes sent via D lines not shown)
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: chan_5 -> OK
Nov 26 16:24:08 testhost dirmngr[32374]: DBG: chan_5 <- [eof]
Nov 26 16:24:08 testhost dirmngr[32374]: handler for fd 5 terminated

So i think this shows that it doesn't appear to be the debian packaging.
It looks to me like it has to do with the GnuPG-specific DNS client
code.  Can you suggest further debugging steps for the original
reporter, Werner?

        --dkg

PS I don't actually think of debian's dirmngr being "heavily-patched".
   The 3 patches that we carry in debian unstable are only related to
   the scheduler/wakeup events, which keep an idle dirmngr from
   consuming unnecesary battery.  They were deferred by Werner upstream
   a couple years ago in the thread starting with
   id:20161101003306.12261-1-dkg at fifthhorseman.net on gnupg-devel.

   I haven't seen any effect from those patches on DNS resolution, but
   if they do have some effect, i'd like to know about it!
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 227 bytes
Desc: not available
URL: <http://alioth-lists.debian.net/pipermail/pkg-gnupg-maint/attachments/20181126/6306bd7d/attachment.sig>