gpg --refresh with large keyrings and hkps in 2.1.1

[Daniel Kahn Gillmor]

i'm trying to test "gpg --refresh" with large keyrings in gnupg 2.1.1.
It's better than it was before, but i'm still getting some errors with a
larger keyring.

In particular, i'm seeing an abort when i try to refresh the a large
keyring against an hkps keyserver; only the first 83 keys get refreshed,
and then gpg aborts with:

gpg: keyserver refresh failed: Input/output error



Trying the same thing again only results in the same first 83 keys being
refreshed, which means the rest of the keyring is never refreshed.


This appears to be reproducible on a debian system, using a fresh,
non-privileged user account:

$ mkdir ~/.gnupg
$ cat > ~/.gnupg/gpg.conf  <<EOF
keyserver hkps://keys.mayfirst.org
keyserver-options no-honor-keyserver-url
EOF
$ cat > ~/.gnupg/gpg.conf <<EOF
hkp-ca-cert /home/example/mfpl.pem
EOF
$ gpg2 --import < /usr/share/keyrings/debian-keyring.gpg
$ gpg2 --refresh

(i'm attaching the mfpl.pem for use as hkp-ca-cert to this e-mail if
anyone wants to try to replicate the problem) 

The result of this last --refresh looks like:

0 test at tester:~$ gpg2 --refresh
gpg: refreshing 983 keys from hkps://keys.mayfirst.org
gpg: key DEADBEEF: "example <example at example.net>" not changed
 [...]
gpg: key DECAFBAD: "example 2 <example at example.com>" not changed
gpg: Total number processed: 83
gpg:              unchanged: 83
gpg: keyserver refresh failed: Input/output error
2 test at tester:~$

clearly, the other 900 keys were not properly imported.  I can see from
looking at packet captures that multiple connections were opened and
closed to this keyserver during the refresh, though.  I'm not sure why
one of them ultimately failed.


If i add the following three lines in dirmngr.conf:

log-file /home/example/dirmngr.log
debug-level expert
gnutls-debug 9999

then it creates a 14MiB logfile, which looks fine right up until the
end, but in the middle of the last batch of updates:

2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D qHV+tY0R04hvWVwVKwcLs1xv/W66GgiKrm173QpVzjXCKLucSZWhdkhGZAdEosXFqg2xYRhV%0A
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D cagU/RiPS4ZH4uI16pA9XrQkTWF0dGhldyBQYWxtZXIgP
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L10: READ: Got 0 bytes from 0x7f9168008ba0
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L10: READ: read 0 bytes from 0x7f9168008ba0
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L3: ASSERT: gnutls_buffers.c:551
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L3: ASSERT: gnutls_record.c:1064
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L3: ASSERT: gnutls_record.c:1185
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L3: ASSERT: gnutls_record.c:1437
2014-12-16 18:54:41 dirmngr[7939.0] TLS network read failed: The TLS connection was non-properly terminated.
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L5: REC[0x7f9168013590]: Start of epoch cleanup
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L5: REC[0x7f9168013590]: End of epoch cleanup
2014-12-16 18:54:41 dirmngr[7939.0] DBG: gnutls:L5: REC[0x7f9168013590]: Epoch #1 freed
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D G1wYWxtZXJAaGV6bWF0dC5vcmc+%0A
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D iEYEEBECAAYFAk0u17YACgkQBEnrTWk1E4frMwCfQPUV0U46c+t7/oW8rRfToVox8n4An3Ct%0A
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D x484xfR/UGtxapG3ofBkF7gciEYEEBEIAAYFAk1RccsACgkQKb5dImj9VJ/8xgCgrWse1rUU%0A
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D 08U3gqW27k0l0riZ34kAn3hM7PmRXEMTSc4H5e111gxJgWC8iEYEEBEIAAYFAlQ+8B0ACgkQ%0A
 [...another 100 or so lines of base64-encoded PGP data here...]
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D SnmID0CrTa9jjOxussClKrn9VErdVtP5iaPceUWvYezrtZeIB6l0K0ZwChgUsKt4Gkoj95LJ%0A
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D hC9F9npWhNa3UfBhYQlF3svIQE+WhhG5kp/h4+ZqKKhdkMJEE7dWiMGVCxm5hVeklsoeSEPJ%0A
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> D qjD88Op0y+gvrqQQkrhHEz2eW0agplSBOxDss47NGv6yk9vzfMnkyHLWw13d8pI8TAJKa
2014-12-16 18:54:41 dirmngr[7939.0] command 'KS_GET' failed: Input/output error
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> ERR 167804977 Input/output error <Dirmngr>
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 <- BYE
2014-12-16 18:54:41 dirmngr[7939.0] DBG: chan_0 -> OK closing connection
2014-12-16 18:54:41 dirmngr[7939.0] handler for fd 0 terminated


I don't know if this is a timing issue with the particular TLS backend
of this server (nginx acting as a reverse proxy), a network failure, or
if it's something else entirely, but it seems like an intermittent
network failure shouldn't cause the full keyring refresh to abort.

I've also tried this with the keyserver being
hkps://hkps.sks-keyservers.net and hkp-ca-cert set to the file fetched
From here: https://sks-keyservers.net/sks-keyservers.netCA.pem -- and i
ran into the same 83-key cutoff.


Can anyone else confirm that this is happening?

I'm not sure what the next steps are for diagnosis.

    --dkg

-------------- next part --------------
A non-text attachment was scrubbed...
Name: mfpl.pem
Type: application/x-x509-ca-cert
Size: 1294 bytes
Desc: mfpl CA
URL: </pipermail/attachments/20141216/8c362e7a/attachment.crt>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 948 bytes
Desc: not available
URL: </pipermail/attachments/20141216/8c362e7a/attachment.sig>