dimrngr over tor fails obscurely on IPv6 records when NoIPv6Traffic flag is set
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	dkg
	Jan 5 2017, 10:02 PM

Description

I'm using dirmngr 2.1.17 with use-tor, plus git commit
b200e636ab20d2aa93d9f71f3789db5a04af0a56 with the default keyserver of
hkps://hkps.pool.sks-keyservers.net. over in https://bugs.debian.org/849845 , i
observed:

      The remaining problem for me ws that when i use tor, if i get back AAAA
      records, the connections fail, but the IPv6 records are not marked as
      dead, so they fail repeatedly.

I don't think any version of Tor can currently do IPv6, so when using tor, the
nameserver selection should ignore v6 addresses.

Details

External Link: https://bugs.debian.org/849845
Version: 2.1.17

Related Objects

Mentioned Here: T2928: stop fetching PTR records entirely
rG09aeac41c97b: dirmngr: Fix Tor access for v6 addresses.
rG76fb2febde10: dirmngr: Mark hosts dead on ENETDOWN.

Event Timeline

dkg added projects: dirmngr, gnupg, Bug Report, Debian.Jan 5 2017, 10:02 PM

dkg set Version to 2.1.17.

dkg added a subscriber: dkg.

dkg set External Link to https://bugs.debian.org/849845.Jan 5 2017, 10:47 PM

I was wrong about Tor and IPv6 -- Tor has had IPv6 support for years, so
something else is wrong...

The reason why we see an EINVAL for a v6 address is that
we create the socket for AF_INET6 but then use that very socket with AF_INET to
sonnect to the socks5 proxy. Cleary a socket for v6 can't be used to connect to
a v4 address.

I just pushed two patches:
76fb2fe dirmngr: Mark hosts dead on ENETDOWN.
09aeac4 dirmngr: Fix Tor access for v6 addresses.
which should solve this bug.

They don't solve the bug for me, unfortunately. with those patches applied, i
now get "permission denied" errors:

an 11 15:57:18 alice dirmngr[20203]: DBG: gnutls:L3: ASSERT:
mpi.c[_gnutls_x509_read_uint]:246
Jan 11 15:57:18 alice dirmngr[20203]: DBG: gnutls:L5: REC[0x7f07c0008640]:
Allocating epoch #0
Jan 11 15:57:18 alice dirmngr[20203]: can't connect to
'2a02:898:31:0:48:4558:73:6b73': Permission denied
Jan 11 15:57:18 alice dirmngr[20203]: error connecting to
'https://[2a02:898:31:0:48:4558:73:6b73]:443': Permission denied

which also don't mark the IPv6 address as dead, so they're effectively permanent
until i clear them out.

As a workaround, i've been clearing out all IPv6 addresses with this terrible hack:

0 dkg@alice:~$ cat bin/dirmngr-flush-ipv6
#!/bin/bash

drop all IPv6 keyservers from dirmngr:

gpg-connect-agent --dirmngr 'keyserver --hosttable' /bye |\

awk '/\[.*:.*\]/{ print "keyserver --dead " $5 } ' |\
gpg-connect-agent --dirmngr

0 dkg@alice:~$

Can you run dirmngr with

debug dns,network
verbose

I don't think that gnutls debug is required.

Here's the reproducer script i'm using:

--------

#!/bin/bash

WORKDIR=$(mktemp -d)
export GNUPGHOME="$WORKDIR/gpg"
mkdir -p -m 0700 "$GNUPGHOME"
cat > "$GNUPGHOME/dirmngr.conf" <<EOF
debug dns,network
verbose
use-tor
log-file $WORKDIR/dirmngr.log
EOF

gpg --recv 126C0D24BD8A2942CC7DF8AC7638D0442B90D010

gpg-connect-agent --dirmngr 'keyserver --hosttable' /bye

cat "$WORKDIR/dirmngr.log"

rm -rf "$WORKDIR"

I just ran it three times in a row, and i got three different results, which
i'll paste as separate messages for easier visibility.

gpg: keybox '/home/dkg/tmp/tmp.vOaRFt7s4L/gpg/pubring.kbx' created
gpg: keyserver receive failed: Permission denied
S # hosttable (idx, ipv6, ipv4, dead, name, time):
S # 0 hkps.pool.sks-keyservers.net
S # . hkps.pool.sks-keyservers.net
S # . --> 15 14 13 12 11 10 19 18 17 16 9 8 7 6 5 4 3 2* 1
S # 1 6 [2a02:898:31:0:48:4558:73:6b73]
S # 2 6 [2a01:4a0:59:1000:223:9eff:fe00:100f]
S # 3 6 [2a00:14b0:4200:3000:27::27]
S # 4 6 [2606:9500:201:1::141]
S # 5 6 [2606:1c00:2802::b]
S # 6 6 [2001:bc8:4700:2300::10:f15]
S # 7 6 [2001:bc8:2515::1]
S # 8 6 [2001:720:418:caf1::8]
S # 9 6 [2001:470:1:116::6]
S # 10 4 216.66.15.2
S # 11 4 212.12.48.27
S # 12 4 209.135.211.141
S # 13 4 192.94.109.73
S # 14 4 163.172.29.20
S # 15 4 130.206.1.8
S # 16 4 94.142.242.225
S # 17 4 92.43.111.21
S # 18 4 51.15.53.138
S # 19 4 37.191.238.78
OK
2017-01-12 11:36:23 dirmngr[866] listening on socket
'/home/dkg/tmp/tmp.vOaRFt7s4L/gpg/S.dirmngr'
2017-01-12 11:36:23 dirmngr[867.0] permanently loaded certificates: 0
2017-01-12 11:36:23 dirmngr[867.0] runtime cached certificates: 0
2017-01-12 11:36:23 dirmngr[867.0] failed to open cache dir file
'/home/dkg/tmp/tmp.vOaRFt7s4L/gpg/crls.d/DIR.txt': No such file or directory
2017-01-12 11:36:23 dirmngr[867.0] creating directory
'/home/dkg/tmp/tmp.vOaRFt7s4L/gpg/crls.d'
2017-01-12 11:36:23 dirmngr[867.0] new cache dir file
'/home/dkg/tmp/tmp.vOaRFt7s4L/gpg/crls.d/DIR.txt' created
2017-01-12 11:36:24 dirmngr[867.6] handler for fd 6 started
2017-01-12 11:36:24 dirmngr[867.6] connection from process 864 (1000:1000)
2017-01-12 11:36:24 dirmngr[867.6] DBG: dns: libdns initialized (tor mode)
2017-01-12 11:36:26 dirmngr[867.6] DBG: dns:
getsrv(_pgpkey-https._tcp.hkps.pool.sks-keyservers.net) -> 0 records
2017-01-12 11:36:26 dirmngr[867.6] DBG: dns: libdns initialized (tor mode)
2017-01-12 11:36:27 dirmngr[867.6] DBG: dns:
resolve_dns_name(hkps.pool.sks-keyservers.net): Success
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2a02:898:31:0:48:4558:73:6b73]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2a01:4a0:59:1000:223:9eff:fe00:100f]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2a00:14b0:4200:3000:27::27]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2606:9500:201:1::141]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2606:1c00:2802::b]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:bc8:4700:2300::10:f15]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:bc8:2515::1]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:720:418:caf1::8]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:470:1:116::6]'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '216.66.15.2'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '212.12.48.27'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '209.135.211.141'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '192.94.109.73'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '163.172.29.20'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '130.206.1.8'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '94.142.242.225'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '92.43.111.21'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '51.15.53.138'
2017-01-12 11:36:27 dirmngr[867.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '37.191.238.78'
2017-01-12 11:36:27 dirmngr[867.6] DBG: http.c:connect_server: trying
name='2a01:4a0:59:1000:223:9eff:fe00:100f' port=443
2017-01-12 11:36:27 dirmngr[867.6] DBG: dns:
resolve_dns_name(2a01:4a0:59:1000:223:9eff:fe00:100f): Success
2017-01-12 11:36:27 dirmngr[867.6] can't connect to
'2a01:4a0:59:1000:223:9eff:fe00:100f': Permission denied
2017-01-12 11:36:27 dirmngr[867.6] error connecting to
'https://[2a01:4a0:59:1000:223:9eff:fe00:100f]:443': Permission denied
2017-01-12 11:36:27 dirmngr[867.6] command 'KS_GET' failed: Permission denied
2017-01-12 11:36:27 dirmngr[867.6] handler for fd 6 terminated
2017-01-12 11:36:27 dirmngr[867.6] handler for fd 6 started
2017-01-12 11:36:27 dirmngr[867.6] connection from process 869 (1000:1000)
2017-01-12 11:36:27 dirmngr[867.6] handler for fd 6 terminated

gpg: keybox '/home/dkg/tmp/tmp.swbfPRERsO/gpg/pubring.kbx' created
gpg: keyserver receive failed: Server indicated a failure
S # hosttable (idx, ipv6, ipv4, dead, name, time):
S # 0 hkps.pool.sks-keyservers.net
OK
2017-01-12 11:36:01 dirmngr[851] listening on socket
'/home/dkg/tmp/tmp.swbfPRERsO/gpg/S.dirmngr'
2017-01-12 11:36:01 dirmngr[852.0] permanently loaded certificates: 0
2017-01-12 11:36:01 dirmngr[852.0] runtime cached certificates: 0
2017-01-12 11:36:01 dirmngr[852.0] failed to open cache dir file
'/home/dkg/tmp/tmp.swbfPRERsO/gpg/crls.d/DIR.txt': No such file or directory
2017-01-12 11:36:01 dirmngr[852.0] creating directory
'/home/dkg/tmp/tmp.swbfPRERsO/gpg/crls.d'
2017-01-12 11:36:01 dirmngr[852.0] new cache dir file
'/home/dkg/tmp/tmp.swbfPRERsO/gpg/crls.d/DIR.txt' created
2017-01-12 11:36:02 dirmngr[852.6] handler for fd 6 started
2017-01-12 11:36:02 dirmngr[852.6] connection from process 849 (1000:1000)
2017-01-12 11:36:02 dirmngr[852.6] DBG: dns: libdns initialized (tor mode)
2017-01-12 11:36:12 dirmngr[852.6] DBG: dns:
getsrv(_pgpkey-https._tcp.hkps.pool.sks-keyservers.net): Server indicated a failure
2017-01-12 11:36:12 dirmngr[852.6] command 'KS_GET' failed: Server indicated a
failure <Unspecified source>
2017-01-12 11:36:12 dirmngr[852.6] handler for fd 6 terminated
2017-01-12 11:36:12 dirmngr[852.6] handler for fd 6 started
2017-01-12 11:36:12 dirmngr[852.6] connection from process 854 (1000:1000)
2017-01-12 11:36:12 dirmngr[852.6] handler for fd 6 terminated

gpg: keybox '/home/dkg/tmp/tmp.0Ew9D45cz7/gpg/pubring.kbx' created
gpg: /home/dkg/tmp/tmp.0Ew9D45cz7/gpg/trustdb.gpg: trustdb created
gpg: key 7638D0442B90D010: public key "Debian Archive Automatic Signing Key
(8/jessie) <ftpmaster@debian.org>" imported
gpg: no ultimately trusted keys found
gpg: Total number processed: 1
gpg: imported: 1
S # hosttable (idx, ipv6, ipv4, dead, name, time):
S # 0 hkps.pool.sks-keyservers.net
S # . hkps.pool.sks-keyservers.net
S # . --> 15 14 13 12 11 10 19 18* 17 16 9 8 7 6 5 4 3 2 1
S # 1 6 [2a02:898:31:0:48:4558:73:6b73]
S # 2 6 [2a01:4a0:59:1000:223:9eff:fe00:100f]
S # 3 6 [2a00:14b0:4200:3000:27::27]
S # 4 6 [2606:9500:201:1::141]
S # 5 6 [2606:1c00:2802::b]
S # 6 6 [2001:bc8:4700:2300::10:f15]
S # 7 6 [2001:bc8:2515::1]
S # 8 6 [2001:720:418:caf1::8]
S # 9 6 [2001:470:1:116::6]
S # 10 4 216.66.15.2
S # 11 4 212.12.48.27
S # 12 4 209.135.211.141
S # 13 4 192.94.109.73
S # 14 4 163.172.29.20
S # 15 4 130.206.1.8
S # 16 4 94.142.242.225
S # 17 4 92.43.111.21
S # 18 4 51.15.53.138
S # 19 4 37.191.238.78
OK
2017-01-12 11:35:25 dirmngr[833] listening on socket
'/home/dkg/tmp/tmp.0Ew9D45cz7/gpg/S.dirmngr'
2017-01-12 11:35:25 dirmngr[834.0] permanently loaded certificates: 0
2017-01-12 11:35:25 dirmngr[834.0] runtime cached certificates: 0
2017-01-12 11:35:25 dirmngr[834.0] failed to open cache dir file
'/home/dkg/tmp/tmp.0Ew9D45cz7/gpg/crls.d/DIR.txt': No such file or directory
2017-01-12 11:35:25 dirmngr[834.0] creating directory
'/home/dkg/tmp/tmp.0Ew9D45cz7/gpg/crls.d'
2017-01-12 11:35:25 dirmngr[834.0] new cache dir file
'/home/dkg/tmp/tmp.0Ew9D45cz7/gpg/crls.d/DIR.txt' created
2017-01-12 11:35:26 dirmngr[834.6] handler for fd 6 started
2017-01-12 11:35:26 dirmngr[834.6] connection from process 831 (1000:1000)
2017-01-12 11:35:26 dirmngr[834.6] DBG: dns: libdns initialized (tor mode)
2017-01-12 11:35:27 dirmngr[834.6] DBG: dns:
getsrv(_pgpkey-https._tcp.hkps.pool.sks-keyservers.net) -> 0 records
2017-01-12 11:35:27 dirmngr[834.6] DBG: dns: libdns initialized (tor mode)
2017-01-12 11:35:28 dirmngr[834.6] DBG: dns:
resolve_dns_name(hkps.pool.sks-keyservers.net): Success
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2a02:898:31:0:48:4558:73:6b73]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2a01:4a0:59:1000:223:9eff:fe00:100f]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2a00:14b0:4200:3000:27::27]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2606:9500:201:1::141]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2606:1c00:2802::b]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:bc8:4700:2300::10:f15]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:bc8:2515::1]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:720:418:caf1::8]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '[2001:470:1:116::6]'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '216.66.15.2'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '212.12.48.27'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '209.135.211.141'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '192.94.109.73'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '163.172.29.20'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '130.206.1.8'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '94.142.242.225'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '92.43.111.21'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '51.15.53.138'
2017-01-12 11:35:28 dirmngr[834.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': '37.191.238.78'
2017-01-12 11:35:28 dirmngr[834.6] DBG: http.c:connect_server: trying
name='51.15.53.138' port=443
2017-01-12 11:35:28 dirmngr[834.6] DBG: dns: resolve_dns_name(51.15.53.138): Success
2017-01-12 11:35:31 dirmngr[834.6] DBG: http.c:1706:socket_new: object
0x00007f57e400a5d0 for fd 8 created
2017-01-12 11:35:34 dirmngr[834.6] DBG: http.c:request:
2017-01-12 11:35:34 dirmngr[834.6] DBG: >> GET
/pks/lookup?op=get&options=mr&search=0x126C0D24BD8A2942CC7DF8AC7638D0442B90D010
HTTP/1.0\r\n
2017-01-12 11:35:34 dirmngr[834.6] DBG: >> Host:
hkps.pool.sks-keyservers.net:443\r\n
2017-01-12 11:35:34 dirmngr[834.6] DBG: http.c:request-header:
2017-01-12 11:35:34 dirmngr[834.6] DBG: >> \r\n
2017-01-12 11:35:37 dirmngr[834.6] handler for fd 6 terminated
2017-01-12 11:35:37 dirmngr[834.6] handler for fd 6 started
2017-01-12 11:35:37 dirmngr[834.6] connection from process 841 (1000:1000)
2017-01-12 11:35:37 dirmngr[834.6] handler for fd 6 terminated

Thanks for the dumps. I was not able to get the permission denied errors. The
ENETDOWN errors on my site where due to a IPv6 not being enabled for Tor (during
most of my older tests I used the Torbrowser).

Anyway, With the patches from today, things are working much better now.
Please give it a try.

I've tried with the latest patches and i still see failures :(

gpg: keybox '/home/dkg/tmp/tmp.nchsng7MNY/gpg/pubring.kbx' created
gpg: keyserver receive failed: Permission denied
S # hosttable (idx, ipv6, ipv4, dead, name, time):
S # 0 hkps.pool.sks-keyservers.net
S # . hkps.pool.sks-keyservers.net
S # . --> 9 11 6 4 10 5 7 8 2* 3 1
S # 1 6 4 sks.spodhuis.org v6=[2a02:898:31:0:48:4558:73:6b73] v4=94.142.242.225
S # 2 6 4 oteiza.siccegge.de v6=[2a01:4a0:59:1000:223:9eff:fe00:100f]
v4=92.43.111.21
S # 3 6 prod00.keyserver.dca.witopia.net v6=[2606:9500:201:1::141]
S # 4 6 4 gpg.NebrWesleyan.edu v6=[2606:1c00:2802::b] v4=192.94.109.73
S # 5 6 4 d hufu.ki.iif.hu v6=[2001:738:0:600:216:3eff:fe02:42]
v4=193.224.163.43 (1s)
S # 6 6 4 gozer.rediris.es v6=[2001:720:418:caf1::8] v4=130.206.1.8
S # 7 4 ip-209-135-211-141.ragingwire.net v4=209.135.211.141
S # 8 4 mud.stack.nl v4=131.155.141.70
S # 9 4 ams.sks.heypete.com v4=51.15.53.138
S # 10 4 host-37-191-238-78.lynet.no v4=37.191.238.78
S # 11 4 cryptonomicon.mit.edu v4=18.9.60.141
OK
2017-01-18 02:56:23 dirmngr[9098] listening on socket
'/home/dkg/tmp/tmp.nchsng7MNY/gpg/S.dirmngr'
2017-01-18 02:56:23 dirmngr[9099.0] permanently loaded certificates: 0
2017-01-18 02:56:23 dirmngr[9099.0] runtime cached certificates: 0
2017-01-18 02:56:23 dirmngr[9099.0] failed to open cache dir file
'/home/dkg/tmp/tmp.nchsng7MNY/gpg/crls.d/DIR.txt': No such file or directory
2017-01-18 02:56:23 dirmngr[9099.0] creating directory
'/home/dkg/tmp/tmp.nchsng7MNY/gpg/crls.d'
2017-01-18 02:56:23 dirmngr[9099.0] new cache dir file
'/home/dkg/tmp/tmp.nchsng7MNY/gpg/crls.d/DIR.txt' created
2017-01-18 02:56:24 dirmngr[9099.6] handler for fd 6 started
2017-01-18 02:56:24 dirmngr[9099.6] connection from process 9096 (1000:1000)
2017-01-18 02:56:24 dirmngr[9099.6] DBG: dns: libdns initialized (tor mode)
2017-01-18 02:56:25 dirmngr[9099.6] DBG: dns:
getsrv(_pgpkey-https._tcp.hkps.pool.sks-keyservers.net) -> 0 records
2017-01-18 02:56:25 dirmngr[9099.6] DBG: dns: libdns initialized (tor mode)
2017-01-18 02:56:27 dirmngr[9099.6] DBG: dns:
resolve_dns_name(hkps.pool.sks-keyservers.net): Success
2017-01-18 02:56:28 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:28 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'sks.spodhuis.org'
2017-01-18 02:56:28 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:29 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:29 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'oteiza.siccegge.de'
2017-01-18 02:56:29 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:29 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:29 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'prod00.keyserver.dca.witopia.net'
2017-01-18 02:56:29 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:30 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:30 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'gpg.NebrWesleyan.edu'
2017-01-18 02:56:30 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:31 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): No name
2017-01-18 02:56:31 dirmngr[9099.6] resolve_dns_addr failed while checking
'hkps.pool.sks-keyservers.net': No name
2017-01-18 02:56:32 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:32 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'hufu.ki.iif.hu'
2017-01-18 02:56:32 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:33 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:33 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'gozer.rediris.es'
2017-01-18 02:56:33 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:34 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Connection
closed in DNS
2017-01-18 02:56:34 dirmngr[9099.6] resolve_dns_addr failed while checking
'hkps.pool.sks-keyservers.net': Connection closed in DNS
2017-01-18 02:56:35 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:35 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'ip-209-135-211-141.ragingwire.net'
2017-01-18 02:56:35 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:36 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:36 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'hufu.ki.iif.hu' [already known]
2017-01-18 02:56:36 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:37 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:37 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'gpg.NebrWesleyan.edu' [already known]
2017-01-18 02:56:37 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:38 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:38 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'mud.stack.nl'
2017-01-18 02:56:38 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:38 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:38 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'gozer.rediris.es' [already known]
2017-01-18 02:56:38 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:39 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:39 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'sks.spodhuis.org' [already known]
2017-01-18 02:56:39 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:40 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:40 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'oteiza.siccegge.de' [already known]
2017-01-18 02:56:40 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:41 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:41 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'ams.sks.heypete.com'
2017-01-18 02:56:41 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:41 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:41 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'host-37-191-238-78.lynet.no'
2017-01-18 02:56:41 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:42 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:42 dirmngr[9099.6] resolve_dns_addr for
'hkps.pool.sks-keyservers.net': 'cryptonomicon.mit.edu'
2017-01-18 02:56:42 dirmngr[9099.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 02:56:42 dirmngr[9099.6] DBG: http.c:connect_server: trying
name='hufu.ki.iif.hu' port=443
2017-01-18 02:56:45 dirmngr[9099.6] DBG: dns: resolve_dns_name(hufu.ki.iif.hu):
Connection closed in DNS
2017-01-18 02:56:45 dirmngr[9099.6] resolving 'hufu.ki.iif.hu' failed:
Connection closed in DNS
2017-01-18 02:56:45 dirmngr[9099.6] can't connect to 'hufu.ki.iif.hu': host not
found
2017-01-18 02:56:45 dirmngr[9099.6] error connecting to
'https://hufu.ki.iif.hu:443': Unknown host
2017-01-18 02:56:45 dirmngr[9099.6] marking host 'hufu.ki.iif.hu' as dead
2017-01-18 02:56:45 dirmngr[9099.6] DBG: http.c:connect_server: trying
name='oteiza.siccegge.de' port=443
2017-01-18 02:56:46 dirmngr[9099.6] DBG: dns:
resolve_dns_name(oteiza.siccegge.de): Success
2017-01-18 02:56:46 dirmngr[9099.6] can't connect to 'oteiza.siccegge.de':
Permission denied
2017-01-18 02:56:46 dirmngr[9099.6] error connecting to
'https://oteiza.siccegge.de:443': Permission denied
2017-01-18 02:56:46 dirmngr[9099.6] command 'KS_GET' failed: Permission denied
2017-01-18 02:56:46 dirmngr[9099.6] handler for fd 6 terminated
2017-01-18 02:56:46 dirmngr[9099.6] handler for fd 6 started
2017-01-18 02:56:46 dirmngr[9099.6] connection from process 9101 (1000:1000)
2017-01-18 02:56:46 dirmngr[9099.6] handler for fd 6 terminated

I note here that the "oteiza.siccegge.de" domain name might be supplied by PTR
records for both its v4 and v6 addresses, and it appears to have a AAAA record,
but it doesn't have any *forward* A record.

I'm baffled by the fact that you're not seeing these errors, and not sure what
to do about it. What version of tor are you running? how is it configured?

i'm running the stock debian tor package, version 0.2.9.8-2.

fwiw, i'm seeing fewer errors with this version than i was before, perhaps
because we're addressing servers via tor by name instead of by IP address, which
means that we're not tickling the IPv6 issue quite as often?

The failure with oteiza.siccegge.de might actually just be the IPv6 issue
itself, since there is no IPv4 address for it. I can actually force the issue
if i just add the following line to the dirmngr.conf generated in my reproducer
script:

    keyserver hkp://oteiza.siccegge.de

but of course it's a faster failure, because there isn't a dozen DNS A->PTR
round-trips.

Can you explain why dirmngr does the DNS roundtrip lookup, mapping from the
pool's A and AAAA addresses back to names? It seems like it'd be a lot simpler
(and faster, and less error-prone) to avoid the PTR lookups if we have the IP
addresses already.

here's the example run from my modified reproducer script that focuses on
oteiza.siccegge.de:

gpg: keybox '/home/dkg/tmp/tmp.XgzSpI4Oy0/gpg/pubring.kbx' created
gpg: keyserver receive failed: Permission denied
S # hosttable (idx, ipv6, ipv4, dead, name, time):
S # 0 6 oteiza.siccegge.de v6=[2a01:4a0:59:1000:223:9eff:fe00:100f]
OK
2017-01-18 03:19:00 dirmngr[30881] listening on socket
'/home/dkg/tmp/tmp.XgzSpI4Oy0/gpg/S.dirmngr'
2017-01-18 03:19:00 dirmngr[30882.0] permanently loaded certificates: 0
2017-01-18 03:19:00 dirmngr[30882.0] runtime cached certificates: 0
2017-01-18 03:19:00 dirmngr[30882.0] failed to open cache dir file
'/home/dkg/tmp/tmp.XgzSpI4Oy0/gpg/crls.d/DIR.txt': No such file or directory
2017-01-18 03:19:00 dirmngr[30882.0] creating directory
'/home/dkg/tmp/tmp.XgzSpI4Oy0/gpg/crls.d'
2017-01-18 03:19:00 dirmngr[30882.0] new cache dir file
'/home/dkg/tmp/tmp.XgzSpI4Oy0/gpg/crls.d/DIR.txt' created
2017-01-18 03:19:01 dirmngr[30882.6] handler for fd 6 started
2017-01-18 03:19:01 dirmngr[30882.6] connection from process 30879 (1000:1000)
2017-01-18 03:19:01 dirmngr[30882.6] DBG: dns: libdns initialized (tor mode)
2017-01-18 03:19:02 dirmngr[30882.6] DBG: dns:
getsrv(_pgpkey-http._tcp.oteiza.siccegge.de) -> 0 records
2017-01-18 03:19:02 dirmngr[30882.6] DBG: dns: libdns initialized (tor mode)
2017-01-18 03:19:03 dirmngr[30882.6] DBG: dns:
resolve_dns_name(oteiza.siccegge.de): Success
2017-01-18 03:19:03 dirmngr[30882.6] resolve_dns_addr for 'oteiza.siccegge.de':
'oteiza.siccegge.de' [already known]
2017-01-18 03:19:03 dirmngr[30882.6] DBG: dns: resolve_dns_addr(): Success
2017-01-18 03:19:03 dirmngr[30882.6] number of system provided CAs: 142
2017-01-18 03:19:03 dirmngr[30882.6] DBG: http.c:connect_server: trying
name='oteiza.siccegge.de' port=11371
2017-01-18 03:19:05 dirmngr[30882.6] DBG: dns:
resolve_dns_name(oteiza.siccegge.de): Success
2017-01-18 03:19:05 dirmngr[30882.6] can't connect to 'oteiza.siccegge.de':
Permission denied
2017-01-18 03:19:05 dirmngr[30882.6] error connecting to
'http://oteiza.siccegge.de:11371': Permission denied
2017-01-18 03:19:05 dirmngr[30882.6] command 'KS_GET' failed: Permission denied
2017-01-18 03:19:05 dirmngr[30882.6] handler for fd 6 terminated
2017-01-18 03:19:05 dirmngr[30882.6] handler for fd 6 started
2017-01-18 03:19:05 dirmngr[30882.6] connection from process 30921 (1000:1000)
2017-01-18 03:19:05 dirmngr[30882.6] handler for fd 6 terminated

I did my test with tor 2.5.12-4 (jessie). I will ungrade to testing now and redo.

Using a configuration with only "use-tor" and debug options, and no
keyserver nor certificates defined I used

  gpg-connect-agent --dirmngr 'keyserver --resolve --hosttable' /bye

several times until I got oteiza.siccegge.de as keyserver:

DBG: chan_7 <- keyserver --resolve --hosttable
DBG: chan_7 -> S # https://oteiza.siccegge.de:443
DBG: chan_7 -> S # hosttable (idx, ipv6, ipv4, dead, name, time):
DBG: chan_7 -> S # 0 hkps.pool.sks-keyservers.net
DBG: chan_7 -> S # . hkps.pool.sks-keyservers.net
DBG: chan_7 -> S # . --> 2 10 6 4 9 5 8 7 1* 3
DBG: chan_7 -> S # 1 6 4 oteiza.siccegge.de
v6=[2a01:4a0:59:1000:223:9eff:fe00:100f] v4=92.43.111.21
DBG: chan_7 -> S # 2 6 4 bone.digitalis.org v6=[2a00:14b0:4200:3000:27::27]
v4=212.12.48.27
DBG: chan_7 -> S # 3 6 prod00.keyserver.dca.witopia.net
v6=[2606:9500:201:1::141]
DBG: chan_7 -> S # 4 6 4 gpg.NebrWesleyan.edu v6=[2606:1c00:2802::b]
v4=192.94.109.73
DBG: chan_7 -> S # 5 6 4 hufu.ki.iif.hu v6=[2001:738:0:600:216:3eff:fe02:42]
v4=193.224.163.43
DBG: chan_7 -> S # 6 6 4 gozer.rediris.es v6=[2001:720:418:caf1::8]
v4=130.206.1.8
DBG: chan_7 -> S # 7 6 4 mud.stack.nl v6=[2001:610:1108:5011::70]
v4=131.155.141.70
DBG: chan_7 -> S # 8 4 ip-209-135-211-141.ragingwire.net v4=209.135.211.141
DBG: chan_7 -> S # 9 4 host-37-191-238-78.lynet.no v4=37.191.238.78
DBG: chan_7 -> S # 10 4 cryptonomicon.mit.edu v4=18.9.60.141
DBG: chan_7 -> OK

and then "gpg --recv-key deadbeef":

DBG: chan_7 <- KS_GET -- 0xDEADBEEF
DBG: http.c:connect_server: trying name='oteiza.siccegge.de' port=443
DBG: dns: resolve_dns_name(oteiza.siccegge.de): Success
DBG: http.c:1706:socket_new: object 0x00007f5d5000bea0 for fd 9 created
DBG: http.c:request:
DBG: >> GET /pks/lookup?op=get&options=mr&search=0xDEADBEEF HTTP/1.0\r\n
DBG: >> Host: hkps.pool.sks-keyservers.net:443\r\n
DBG: http.c:request-header:
DBG: >> \r\n
DBG: chan_7 -> S PROGRESS tick ? 0 0
DBG: chan_7 -> S SOURCE https://oteiza.siccegge.de:443
DBG: (27779 bytes sent via D lines not shown)

And here is a log when using

  keyserver hkp://oteiza.siccegge.de

in dirmngr.conf (and also use-tor) of course:

DBG: chan_7 -> OK Dirmngr 2.1.18-beta67 at your service
connection from process 24314 (1000:1000)
DBG: chan_7 <- keyserver --resolve --hosttable
DBG: dns: libdns initialized (tor mode)
DBG: dns: getsrv(_pgpkey-http._tcp.oteiza.siccegge.de) -> 0 records
DBG: dns: libdns initialized (tor mode)
DBG: dns: resolve_dns_name(oteiza.siccegge.de): Success
resolve_dns_addr for 'oteiza.siccegge.de': 'oteiza.siccegge.de' [already known]
DBG: dns: resolve_dns_addr(): Success
DBG: chan_7 -> S # http://oteiza.siccegge.de:11371
DBG: chan_7 -> S # hosttable (idx, ipv6, ipv4, dead, name, time):
DBG: chan_7 -> S # 0 6 oteiza.siccegge.de
v6=[2a01:4a0:59:1000:223:9eff:fe00:100f]
DBG: chan_7 -> OK
DBG: chan_7 <- [eof]
handler for fd 7 terminated
handler for fd 7 started
DBG: chan_7 -> # Home: /home/wk/.gnupg
DBG: chan_7 -> # Config: /home/wk/.gnupg/dirmngr.conf
DBG: chan_7 -> OK Dirmngr 2.1.18-beta67 at your service
connection from process 24325 (1000:1000)
DBG: chan_7 <- GETINFO version
DBG: chan_7 -> D 2.1.18-beta67
DBG: chan_7 -> OK
DBG: chan_7 <- KS_GET -- 0xDEADBEEF
number of system provided CAs: 173
DBG: http.c:connect_server: trying name='oteiza.siccegge.de' port=11371
DBG: dns: resolve_dns_name(oteiza.siccegge.de): Success
DBG: http.c:1706:socket_new: object 0x00007f1420453df0 for fd 8 created
DBG: http.c:request:
DBG: >> GET /pks/lookup?op=get&options=mr&search=0xDEADBEEF HTTP/1.0\r\n
DBG: >> Host: oteiza.siccegge.de:11371\r\n
DBG: http.c:request-header:
DBG: >> \r\n
DBG: chan_7 -> S PROGRESS tick ? 0 0
DBG: chan_7 -> S SOURCE http://oteiza.siccegge.de:11371
DBG: (27779 bytes sent via D lines not shown)
DBG: chan_7 -> OK

I tried this with and without my local v6 interface up; both are
obviously the same. Bote that in both cases my resolver is on the
local network and accessed via v4 - but it should not matter because
due to use-tor 8.8.8.8 is used anyway.

Even with the Tor from testing I am stil having the IPv6Traffic flag
in my torrc - I am not sure whether this is still required.

FWIW, I am using Libassuan 2.4.3 plus one portability fix for BSDs.

• werner removed a project: Restricted Project.Jan 19 2017, 12:03 PM

To answer your question:

  Can you explain why dirmngr does the DNS roundtrip lookup, mapping
  from the pool's A and AAAA addresses back to names?  It seems like
  it'd be a lot simpler (and faster, and less error-prone) to avoid
  the PTR lookups if we have the IP addresses already.

If it is a plain server and not a pool, looking up the PTR is
necessary to get the hostname for SNI and possible also for Host:
header.

For a pool we would not need the name because the already known name
of the pool is used for SNI. However, to find duplicate hosts in the
hosttable it is useful to have the hostname. We also return the
actual used hostname to gpg for information purposes and to eventually
store this with the key as meta info.

Yes, we could the PTR lookup of pools faster or in the background -
but for now a simple appraoch is better for debugging.

I've moved the discussion about the need for PTR over to
T2928

In this ticket, let's focus on what happens when Tor has the NoIPv6Traffic flag
set. How should dirmngr respond in that case?

I think if it gets a "permission denied" from its tor socket (or from any proxy)
when it's trying to connect to a host, it should treat that host as dead and
move to try next one. If dirmngr knows that it is using tor, and it knows that
the address it is trying is also IPv6, it could also log a message about the
IPv6Traffic flag.

does that seem like the right set of changes needed?

if you add NoIPv6Traffic to your torrc, and restart tor, can you replicate the
problem?

I have never seen the no permission message but only a general connection failed
error. I can try your suggestion of setting an explicit NoIPv6Traffic

Okay, I get this error now. I had to implement a new option --disable-ipv4 to
make testing easier.

This has been fixed a while ago my having dirmngr print a hint on the possible problem. gpg will then print a warning about a problem with the Tor configuration and with --verbose print the hint on solving this as well.

dimrngr over tor fails obscurely on IPv6 records when NoIPv6Traffic flag is setClosed, ResolvedPublicActions