[Sks-devel] Recon stalls for one hour

[Pete Stephenson]

Hi all,

I was perusing my recon.log and db.log files today and noticed odd gaps
in gossip activity that last for an hour and result in error messages.
Logs for the last few days indicate this happens 10-15 times per day.

Normally, my server (ams.sks.heypete.com, running SKS 1.1.5) gossips
regularly with its peers. There are 27 entries in my server's membership
file. It's not uncommon for gossip traffic to occur a few times per
minute, though 1-3 minutes between gossiping is normal. Hour-long breaks
are definitely odd.

It appears that SKS stalls waiting for something to happen and it only
times out after an hour elapses. During this time, no other activity is
logged to the recon.log, though regular HKP queries are answered
normally. After the hour period is up a "Reconciliation failed due to
timeout." message is written to the log and the server syncs updates
over gossip as usual.

The standard recon.log and db.log files don't seem to shed any
information on what might be causing this. I'd be happy to enable
debug-level logging if that'd help.

Any ideas as to what might be causing this and what might be done to
resolve the issue?

I've included a log snippet below with the IP addresses of other servers
obfuscated.

Cheers!
-Pete

2014-09-01 15:11:01 Requesting 3 missing keys from <ADDR_INET
[obfuscated]:11371>, starting with 1170CDC515A395E30B6C736061D4A424
2014-09-01 15:11:01 1 keys received
2014-09-01 15:11:01 Added 1 hash-updates. Caught up to 1409577061.475894
2014-09-01 15:11:48 2 hashes recovered from <ADDR_INET [obfuscated]:11371>
2014-09-01 15:11:48     209AD60E7D12D9DEE4F48640A9FB5515
2014-09-01 15:11:48     803938D4FAB32A2A0966BE6463736375
2014-09-01 15:11:52 Requesting 2 missing keys from <ADDR_INET
[obfuscated]:11371>, starting with 209AD60E7D12D9DEE4F48640A9FB5515
2014-09-01 15:11:52 2 keys received
2014-09-01 15:11:52 Added 1 hash-updates. Caught up to 1409577112.595723
2014-09-01 16:12:57 Reconciliation failed due to timeout.  Returning
elements returned so far
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:12:57 <reconciliation handler> error in callback.: End_of_file
2014-09-01 16:13:55 69 hashes recovered from <ADDR_INET [obfuscated]:11371>
2014-09-01 16:13:56 Requesting 69 missing keys from <ADDR_INET
[obfuscated]:11371>, starting with 01416E8D489773D2264E35F85F99472A
2014-09-01 16:13:56 69 keys received
2014-09-01 16:13:57 Added 94 hash-updates. Caught up to 1409580837.179165
2014-09-01 16:16:37 <recon as client> callback timed out.
2014-09-01 16:18:30 Reconciliation attempt from unauthorized host
<ADDR_INET [obfuscated]:45598>.  Ignoring
2014-09-01 16:18:39 2 hashes recovered from <ADDR_INET [obfuscated]:11371>
2014-09-01 16:18:39     8EE10FC0299C509F80B615F8EF195BF9
2014-09-01 16:18:39     9239024F4F415794BF689F08F56F5823

signature.asc
Description: OpenPGP digital signature