Opened 9 years ago

Closed 2 years ago

#1890 closed defect (worksforme)

Tor failed to make a consensus 2010/08/29 17:00

Reported by: Sebastian Owned by:
Priority: High Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-auth
Cc: arma Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Karsten found this in his log (note that gabelmoo is running on utc+2):

Aug 29 18:55:09.585 [warn] Could not add queued signature to new consensus: Mismatched digest.
Aug 29 19:00:01.727 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 19:00:01.727 [warn] Not enough good signatures on networkstatus consensus
Aug 29 19:00:01.727 [warn] Error publishing ns consensus
Aug 29 19:00:01.759 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 19:00:01.759 [warn] Not enough good signatures on networkstatus consensus
Aug 29 19:00:01.759 [warn] Error publishing microdesc consensus

and sure enough, the authorities couldn't make a consensus. An hour later, they succeeded.

Karsten made the status votes available at http://freehaven.net/~karsten/volatile/v3-status-votes but I failed to find anything obvious.

Child Tickets

Attachments (3)

deviant-consensus-times-2011.txt (2.9 KB) - added by rransom 7 years ago.
list of deviant consensus times in 2011 tarballs
deviant-consensus-times.png (24.1 KB) - added by karsten 7 years ago.
Graph of deviant consensus times in 2011 and 2012
deviant-consensus-times.R (788 bytes) - added by karsten 7 years ago.
Graphing code

Download all attachments as: .zip

Change History (32)

comment:1 Changed 9 years ago by mikeperry

There are no such warns on ides during this time period. It looks like ides thinks it produced a consensus? All of our logs are UTC right? Mine are.

Aug 29 18:52:31.996 [notice] Time to fetch any votes that we're missing.
Aug 29 18:55:01.257 [notice] Time to compute a consensus.
Aug 29 18:55:01.732 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=995739 M=602846 E=242701 D=805246 T=2646532
Aug 29 18:55:01.790 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 18:55:01.993 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=995739 M=602846 E=242701 D=805246 T=2646532
Aug 29 18:55:02.040 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 18:55:02.072 [notice] Consensus computed; uploading signature(s)
Aug 29 18:55:02.072 [notice] Signature(s) posted.
Aug 29 18:55:02.114 [notice] Got a signature from 194.109.206.212. Adding it to the pending consensus.
Aug 29 18:55:02.196 [notice] Got a signature from 86.59.21.38. Adding it to the pending consensus.
Aug 29 18:55:02.271 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 18:55:02.288 [notice] Uploaded signature(s) to dirserver 216.224.124.114:9030
Aug 29 18:55:02.303 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 18:55:02.503 [notice] Uploaded signature(s) to dirserver 86.59.21.38:80
Aug 29 18:55:02.531 [notice] Uploaded signature(s) to dirserver 208.83.223.34:443
Aug 29 18:55:02.533 [notice] Uploaded signature(s) to dirserver 194.109.206.212:80
Aug 29 18:55:02.709 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 18:55:03.146 [notice] Uploaded signature(s) to dirserver 213.115.239.118:443
Aug 29 18:55:05.228 [notice] Got a signature from 128.31.0.34. Adding it to the pending consensus.
Aug 29 18:55:05.506 [notice] Uploaded signature(s) to dirserver 128.31.0.34:9131
Aug 29 18:55:05.937 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 18:55:06.520 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 18:55:06.597 [notice] Uploaded signature(s) to dirserver 80.190.246.100:8180
Aug 29 18:55:06.996 [notice] Uploaded signature(s) to dirserver 193.23.244.244:80
Aug 29 18:57:31.583 [notice] Time to fetch any signatures that we're missing.
Aug 29 18:57:31.598 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 18:57:31.738 [notice] Got a signature from 128.31.0.34. Adding it to the pending consensus.
Aug 29 18:57:31.903 [notice] Got a signature from 194.109.206.212. Adding it to the pending consensus.
Aug 29 18:57:31.935 [notice] Got a signature from 86.59.21.38. Adding it to the pending consensus.
Aug 29 18:57:31.990 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 18:57:32.021 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 18:57:32.287 [notice] Got a signature from 193.23.244.244. Adding it to t
he pending consensus.
Aug 29 19:00:01.888 [notice] Time to publish the consensus and discard old votes
Aug 29 19:00:01.967 [notice] Choosing expected valid-after time as 2010-08-29 20
:00:00: consensus_set=1, interval=3600
Aug 29 19:00:01.974 [notice] Published ns consensus
Aug 29 19:00:02.055 [notice] Published microdesc consensus
Aug 29 19:00:02.118 [notice] Choosing expected valid-after time as 2010-08-29 20
:00:00: consensus_set=1, interval=3600

comment:2 Changed 9 years ago by Sebastian

Look at 17:00, not 19:00. Karsten's logs are in CEST (UTC+2)

comment:3 Changed 9 years ago by arma

moria1 failed to make a consensus then too:

Aug 29 12:50:01.860 [notice] Time to vote.
Aug 29 12:50:02.329 [notice] Choosing valid-after time in vote as 2010-08-29 17:00:00: consensus_set=1, last_interval=3600
Aug 29 12:50:02.800 [notice] Vote posted.
Aug 29 12:50:02.940 [notice] Uploaded a vote to dirserver 128.31.0.34:9131
Aug 29 12:50:04.278 [notice] Uploaded a vote to dirserver 216.224.124.114:9030
Aug 29 12:50:04.793 [notice] Uploaded a vote to dirserver 194.109.206.212:80
Aug 29 12:50:04.899 [notice] Uploaded a vote to dirserver 208.83.223.34:443
Aug 29 12:50:05.623 [notice] Uploaded a vote to dirserver 86.59.21.38:80
Aug 29 12:50:07.738 [notice] Uploaded a vote to dirserver 213.115.239.118:443
Aug 29 12:50:14.630 [notice] Uploaded a vote to dirserver 193.23.244.244:80
Aug 29 12:51:47.089 [notice] Uploaded a vote to dirserver 80.190.246.100:8180
Aug 29 12:52:31.186 [notice] Time to fetch any votes that we're missing.
Aug 29 12:52:31.186 [notice] We're missing votes from 1 authorities. Asking every other authority for a copy.
Aug 29 12:52:31.374 [warn] Received http status code 404 ("Not found") from server '216.224.124.114:9030' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 12:52:31.377 [warn] Received http status code 404 ("Not found") from server '208.83.223.34:443' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 12:52:31.384 [warn] Received http status code 404 ("Not found") from server '194.109.206.212:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 12:52:31.443 [warn] Received http status code 404 ("Not found") from server '86.59.21.38:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 12:52:31.451 [warn] Received http status code 404 ("Not found") from server '213.115.239.118:443' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 12:52:31.835 [warn] Received http status code 404 ("Not found") from server '193.23.244.244:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 12:55:01.668 [notice] Got a signature from 194.109.206.212. Queuing it for the next consensus.
Aug 29 12:55:01.913 [notice] Time to compute a consensus.
Aug 29 12:55:02.054 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=988101 M=592235 E=248355 D=815597 T=2644288
Aug 29 12:55:02.108 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 12:55:02.277 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=988101 M=592235 E=248355 D=815597 T=2644288
Aug 29 12:55:02.332 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 12:55:02.459 [notice] Added 2 pending signatures while building consensus.
Aug 29 12:55:02.459 [notice] Consensus computed; uploading signature(s)
Aug 29 12:55:02.459 [notice] Signature(s) posted.
Aug 29 12:55:02.522 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 12:55:02.523 [warn] Unable to store signatures posted by 208.83.223.34: Mismatched digest.
Aug 29 12:55:02.526 [notice] Got a signature from 86.59.21.38. Adding it to the pending consensus.
Aug 29 12:55:02.615 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 12:55:02.616 [warn] Unable to store signatures posted by 213.115.239.118: Mismatched digest.
Aug 29 12:55:02.620 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 12:55:02.620 [warn] Unable to store signatures posted by 216.224.124.114: Mismatched digest.
Aug 29 12:55:02.623 [notice] Got a signature from 128.31.0.39. Adding it to the pending consensus.
Aug 29 12:55:02.713 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '216.224.124.114:9030'. Please correct.
Aug 29 12:55:02.715 [notice] Uploaded signature(s) to dirserver 128.31.0.34:9131
Aug 29 12:55:02.718 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '208.83.223.34:443'. Please correct.
Aug 29 12:55:02.803 [notice] Uploaded signature(s) to dirserver 80.190.246.100:8180
Aug 29 12:55:02.803 [notice] Uploaded signature(s) to dirserver 86.59.21.38:80
Aug 29 12:55:02.814 [notice] Uploaded signature(s) to dirserver 194.109.206.212:80
Aug 29 12:55:03.003 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '213.115.239.118:443'. Please correct.
Aug 29 12:55:04.846 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 12:55:04.854 [warn] Unable to store signatures posted by 193.23.244.244: Mismatched digest.
Aug 29 12:55:06.282 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '193.23.244.244:80'. Please correct.
Aug 29 12:57:10.853 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 12:57:31.360 [notice] Time to fetch any signatures that we're missing.
Aug 29 12:57:31.517 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 12:57:31.517 [warn] Problem adding detached signatures from 216.224.124.114:9030: Mismatched digest.
Aug 29 12:57:31.548 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 12:57:31.548 [warn] Problem adding detached signatures from 208.83.223.34:443: Mismatched digest.
Aug 29 12:57:31.586 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 12:57:31.608 [notice] Got a signature from 86.59.21.38. Adding it to the pending consensus.
Aug 29 12:57:31.625 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 12:57:31.625 [warn] Problem adding detached signatures from 213.115.239.118:443: Mismatched digest.
Aug 29 12:57:32.042 [notice] Got a signature from 194.109.206.212. Adding it to the pending consensus.
Aug 29 12:57:32.256 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 12:57:32.256 [warn] Problem adding detached signatures from 193.23.244.244:80: Mismatched digest.
Aug 29 13:00:01.814 [notice] Time to publish the consensus and discard old votes
Aug 29 13:00:01.857 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 13:00:01.857 [warn] Not enough good signatures on networkstatus consensus
Aug 29 13:00:01.858 [warn] Error publishing ns consensus
Aug 29 13:00:01.901 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 13:00:01.901 [warn] Not enough good signatures on networkstatus consensus
Aug 29 13:00:01.902 [warn] Error publishing microdesc consensus
Aug 29 13:00:02.233 [notice] Choosing expected valid-after time as 2010-08-29 18:00:00: consensus_set=1, interval=3600

comment:4 Changed 9 years ago by arma

It looks like moria1 never got a vote from gabelmoo, and it asked six other authorities and they never got a vote from gabelmoo either.

Karsten, what does your log say from the :50:00 mark on?

comment:5 Changed 9 years ago by karsten

These are gabelmoo's logs from 16:50:00 to 17:10:00 UTC.

Aug 29 18:50:01.226 [notice] Time to vote.
Aug 29 18:50:56.939 [notice] Choosing valid-after time in vote as 2010-08-29 17:00:00: consensus_set=1, last_interval=3600
Aug 29 18:52:20.775 [notice] Vote posted.
Aug 29 18:52:21.454 [warn] Your system clock just jumped 140 seconds forward; assuming established circuits no longer work.
Aug 29 18:52:38.929 [notice] Time to fetch any votes that we're missing.
Aug 29 18:52:39.440 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Aug 29 18:52:58.013 [notice] Uploaded a vote to dirserver 86.59.21.38:80
Aug 29 18:53:00.594 [notice] Got a signature from 194.109.206.212. Queuing it for the next consensus.
Aug 29 18:53:00.733 [notice] Uploaded a vote to dirserver 194.109.206.212:80
Aug 29 18:53:01.135 [notice] Got a signature from 86.59.21.38. Queuing it for the next consensus.
Aug 29 18:53:01.151 [notice] Got a signature from 208.83.223.34. Queuing it for the next consensus.
Aug 29 18:53:01.304 [notice] Got a signature from 213.115.239.118. Queuing it for the next consensus.
Aug 29 18:53:01.623 [notice] Got a signature from 216.224.124.114. Queuing it for the next consensus.
Aug 29 18:53:01.757 [notice] Got a signature from 128.31.0.34. Queuing it for the next consensus.
Aug 29 18:53:01.925 [notice] Uploaded a vote to dirserver 128.31.0.34:9131
Aug 29 18:53:02.300 [notice] Uploaded a vote to dirserver 216.224.124.114:9030
Aug 29 18:53:02.517 [notice] Uploaded a vote to dirserver 213.115.239.118:443
Aug 29 18:53:02.916 [notice] Uploaded a vote to dirserver 208.83.223.34:443
Aug 29 18:53:03.685 [notice] Got a signature from 193.23.244.244. Queuing it for the next consensus.
Aug 29 18:53:27.133 [notice] Uploaded a vote to dirserver 193.23.244.244:80
Aug 29 18:53:27.150 [notice] Uploaded a vote to dirserver 80.190.246.100:8180
Aug 29 18:55:01.990 [notice] Time to compute a consensus.
Aug 29 18:55:03.201 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=988101 M=592235 E=248355 D=815597 T=2644288
Aug 29 18:55:04.614 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 18:55:04.768 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=988101 M=592235 E=248355 D=815597 T=2644288
Aug 29 18:55:09.292 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 18:55:09.518 [warn] Could not add queued signature to new consensus: Mismatched digest.
Aug 29 18:55:09.518 [warn] Could not add queued signature to new consensus: Mismatched digest.
Aug 29 18:55:09.518 [warn] Could not add queued signature to new consensus: Mismatched digest.
Aug 29 18:55:09.585 [warn] Could not add queued signature to new consensus: Mismatched digest.
Aug 29 18:55:09.585 [notice] Added 8 pending signatures while building consensus.
Aug 29 18:55:09.585 [notice] Consensus computed; uploading signature(s)
Aug 29 18:55:09.585 [notice] Signature(s) posted.
Aug 29 18:55:09.693 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 18:55:09.766 [notice] Uploaded signature(s) to dirserver 86.59.21.38:80
Aug 29 18:55:09.768 [notice] Uploaded signature(s) to dirserver 80.190.246.100:8180
Aug 29 18:55:09.770 [notice] Uploaded signature(s) to dirserver 194.109.206.212:80
Aug 29 18:55:09.887 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '213.115.239.118:443'. Please correct.
Aug 29 18:55:10.077 [notice] Uploaded signature(s) to dirserver 128.31.0.34:9131
Aug 29 18:55:10.104 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '208.83.223.34:443'. Please correct.
Aug 29 18:55:10.109 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '216.224.124.114:9030'. Please correct.
Aug 29 18:55:10.129 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '193.23.244.244:80'. Please correct.
Aug 29 18:57:46.665 [notice] Time to fetch any signatures that we're missing.
Aug 29 18:57:47.367 [notice] Got a signature from 86.59.21.38. Adding it to the pending consensus.
Aug 29 18:57:47.372 [notice] Got a signature from 194.109.206.212. Adding it to the pending consensus.
Aug 29 18:57:47.372 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 18:57:47.372 [warn] Problem adding detached signatures from 193.23.244.244:80: Mismatched digest.
Aug 29 18:57:47.482 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 18:57:47.482 [warn] Problem adding detached signatures from 213.115.239.118:443: Mismatched digest.
Aug 29 18:57:47.485 [notice] Got a signature from 128.31.0.34. Adding it to the pending consensus.
Aug 29 18:57:47.532 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 18:57:47.532 [warn] Problem adding detached signatures from 208.83.223.34:443: Mismatched digest.
Aug 29 18:57:47.532 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 18:57:47.532 [warn] Problem adding detached signatures from 216.224.124.114:9030: Mismatched digest.
Aug 29 19:00:01.252 [notice] Time to publish the consensus and discard old votes
Aug 29 19:00:01.727 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 19:00:01.727 [warn] Not enough good signatures on networkstatus consensus
Aug 29 19:00:01.727 [warn] Error publishing ns consensus
Aug 29 19:00:01.759 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 19:00:01.759 [warn] Not enough good signatures on networkstatus consensus
Aug 29 19:00:01.759 [warn] Error publishing microdesc consensus
Aug 29 19:00:02.840 [notice] Choosing expected valid-after time as 2010-08-29 18:00:00: consensus_set=1, interval=3600

comment:6 Changed 9 years ago by arma

All the authorities started their voting process at :50:00. They started uploading their votes to various places.

While gabelmoo was computing its vote, it moved its clock forward by 2 minutes and 20 seconds.

moria1 finished uploading its vote to gabelmoo at:
Aug 29 12:51:47.089 [notice] Uploaded a vote to dirserver 80.190.246.100:8180
but I don't see this vote appearing in gabelmoo's logs. If it did, we could use it to figure out gabelmoo's clock offset.

So question 1: How come it doesn't appear?

What happened to gabelmoo during this time? It wasn't just fixing its clock, because it took 1 minute 43 seconds longer to upload moria1's vote to it than it took to upload moria1's vote to the other authorities. It looks like it was having some serious load or network issues.

Then a little while later gabelmoo says
Aug 29 18:53:01.925 [notice] Uploaded a vote to dirserver 128.31.0.34:9131

which corresponds to this line in moria1's log:
Aug 29 12:55:01.424 [info] connection_dir_client_reached_eof(): Got votes (size 827573) from server 80.190.246.100:8180
Aug 29 12:55:01.496 [info] update_consensus_router_descriptor_downloads(): Learned about Unnamed (2010-08-29 16:48:15 vs 2010-08-29 16:53:28) from gabelmoo's vote (known)
Aug 29 12:55:01.596 [info] connection_dir_client_reached_eof(): Added vote(s) successfully [msg: ok]

Except my theory might be wrong, because moria1 seems to think it *downloaded* the vote, and gabelmoo seems to think it *uploaded* the vote. These cannot both be true. I didn't find any hints in moria1's logs of receiving an uploaded vote from gabelmoo, but I don't know where to look because I think gabelmoo's time is wrong.

It would be good to get (at least notice-level) logs from all the other authorities so we can see if we can match up timings and figure out what time gabelmoo actually did various things.

comment:7 Changed 9 years ago by arma

Priority: majorminor

My intuition is that if an authority withholds its votes and then uploads them to 3 authorities at just the right time, it can throw a wrench in building the consensus that hour.

Triage: no need for this to block 0.2.2.x's release.

But we should keep investigating it in the near term, to make sure we understand better what the issues are.

comment:8 Changed 9 years ago by ln5

maatuska was logging level 'notice' at the time. Still is.
These are the logs between 16:50 and 17:10 UTC:

Aug 29 18:50:01.987 [notice] Time to vote.
Aug 29 18:50:02.516 [notice] Choosing valid-after time in vote as 2010-08-29 17:00:00: consensus_set=1, last_interval=3600
Aug 29 18:50:03.079 [notice] Vote posted.
Aug 29 18:50:03.861 [notice] Uploaded a vote to dirserver 213.115.239.118:443
Aug 29 18:50:04.698 [notice] Uploaded a vote to dirserver 194.109.206.212:80
Aug 29 18:50:06.033 [notice] Uploaded a vote to dirserver 86.59.21.38:80
Aug 29 18:50:08.043 [notice] Uploaded a vote to dirserver 128.31.0.34:9131
Aug 29 18:50:08.738 [notice] Uploaded a vote to dirserver 208.83.223.34:443
Aug 29 18:50:09.831 [notice] Uploaded a vote to dirserver 216.224.124.114:9030
Aug 29 18:50:13.152 [notice] Uploaded a vote to dirserver 193.23.244.244:80
Aug 29 18:51:32.068 [notice] Uploaded a vote to dirserver 80.190.246.100:8180
Aug 29 18:52:31.848 [notice] Time to fetch any votes that we're missing.
Aug 29 18:52:31.848 [notice] We're missing votes from 1 authorities. Asking every other authority for a copy.
Aug 29 18:52:31.895 [warn] Received http status code 404 ("Not found") from server '194.109.206.212:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 18:52:31.974 [warn] Received http status code 404 ("Not found") from server '86.59.21.38:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 18:52:32.114 [warn] Received http status code 404 ("Not found") from server '128.31.0.34:9131' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 18:52:32.192 [warn] Received http status code 404 ("Not found") from server '208.83.223.34:443' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 18:52:32.260 [warn] Received http status code 404 ("Not found") from server '216.224.124.114:9030' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 18:52:32.426 [warn] Received http status code 404 ("Not found") from server '193.23.244.244:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 18:55:01.638 [notice] Time to compute a consensus.
Aug 29 18:55:01.949 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=1278478 M=755042 E=309410 D=913270 T=3256200
Aug 29 18:55:02.019 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 18:55:02.215 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=1278478 M=755042 E=309410 D=913270 T=3256200
Aug 29 18:55:02.285 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 18:55:02.338 [notice] Consensus computed; uploading signature(s)
Aug 29 18:55:02.339 [notice] Signature(s) posted.
Aug 29 18:55:02.493 [notice] Got a signature from 194.109.206.212. Adding it to the pending consensus.
Aug 29 18:55:02.493 [warn] Unable to store signatures posted by 194.109.206.212: Mismatched digest.
Aug 29 18:55:02.503 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '194.109.206.212:80'. Please correct.
Aug 29 18:55:02.503 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 18:55:02.510 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 18:55:02.636 [notice] Got a signature from 86.59.21.38. Adding it to the pending consensus.
Aug 29 18:55:02.636 [warn] Unable to store signatures posted by 86.59.21.38: Mismatched digest.
Aug 29 18:55:02.643 [notice] Uploaded signature(s) to dirserver 80.190.246.100:8180
Aug 29 18:55:02.643 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '86.59.21.38:80'. Please correct.
Aug 29 18:55:02.644 [notice] Uploaded signature(s) to dirserver 213.115.239.118:443
Aug 29 18:55:02.919 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 18:55:03.044 [notice] Uploaded signature(s) to dirserver 208.83.223.34:443
Aug 29 18:55:03.058 [notice] Uploaded signature(s) to dirserver 216.224.124.114:9030
Aug 29 18:55:03.058 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '128.31.0.34:9131'. Please correct.
Aug 29 18:55:03.185 [notice] Got a signature from 128.31.0.34. Adding it to the pending consensus.
Aug 29 18:55:03.185 [warn] Unable to store signatures posted by 128.31.0.34: Mismatched digest.
Aug 29 18:55:04.903 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 18:55:06.003 [notice] Uploaded signature(s) to dirserver 193.23.244.244:80
Aug 29 18:57:10.991 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 18:57:10.991 [warn] Unable to store signatures posted by 80.190.246.100: Mismatched digest.
Aug 29 18:57:31.744 [notice] Time to fetch any signatures that we're missing.
Aug 29 18:57:31.813 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 18:57:31.813 [warn] Problem adding detached signatures from 80.190.246.100:8180: Mismatched digest.
Aug 29 18:57:31.863 [notice] Got a signature from 86.59.21.38. Adding it to the pending consensus.
Aug 29 18:57:31.863 [warn] Problem adding detached signatures from 86.59.21.38:80: Mismatched digest.
Aug 29 18:57:32.013 [notice] Got a signature from 128.31.0.34. Adding it to the pending consensus.
Aug 29 18:57:32.013 [warn] Problem adding detached signatures from 128.31.0.34:9131: Mismatched digest.
Aug 29 18:57:32.091 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 18:57:32.156 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 18:57:32.303 [notice] Got a signature from 194.109.206.212. Adding it to the pending consensus.
Aug 29 18:57:32.303 [warn] Problem adding detached signatures from 194.109.206.212:80: Mismatched digest.
Aug 29 18:57:32.726 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 19:00:01.964 [notice] Time to publish the consensus and discard old votes
Aug 29 19:00:01.964 [warn] 0 unknown, 0 missing key, 4 good, 0 bad, 4 no signature, 5 required
Aug 29 19:00:01.964 [warn] Not enough info to publish pending ns consensus
Aug 29 19:00:01.965 [warn] 0 unknown, 0 missing key, 4 good, 0 bad, 4 no signature, 5 required
Aug 29 19:00:01.965 [warn] Not enough info to publish pending microdesc consensus
Aug 29 19:00:01.983 [notice] Choosing expected valid-after time as 2010-08-29 18:00:00: consensus_set=1, interval=3600

comment:9 Changed 9 years ago by weasel

tor26, as requested by sebastian:

Aug 29 16:23:36.024 [notice] Tor 0.2.2.15-alpha (git-8ea1c7b8c5dd2314) opening log file.
Aug 29 16:50:01.433 [notice] Time to vote.
Aug 29 16:50:01.701 [notice] Choosing valid-after time in vote as 2010-08-29 17:00:00: consensus_set=1, last_interval=3600
Aug 29 16:50:01.990 [notice] Vote posted.
Aug 29 16:50:02.070 [notice] Uploaded a vote to dirserver 86.59.21.38:80
Aug 29 16:50:03.905 [notice] Uploaded a vote to dirserver 194.109.206.212:80
Aug 29 16:50:04.566 [notice] Uploaded a vote to dirserver 128.31.0.34:9131
Aug 29 16:50:04.924 [notice] Uploaded a vote to dirserver 216.224.124.114:9030
Aug 29 16:50:04.939 [notice] Uploaded a vote to dirserver 208.83.223.34:443
Aug 29 16:50:06.359 [notice] Uploaded a vote to dirserver 213.115.239.118:443
Aug 29 16:50:12.505 [notice] Uploaded a vote to dirserver 193.23.244.244:80
Aug 29 16:50:55.098 [notice] Uploaded a vote to dirserver 80.190.246.100:8180
Aug 29 16:52:31.697 [notice] Time to fetch any votes that we're missing.
Aug 29 16:52:31.697 [notice] We're missing votes from 1 authorities. Asking every other authority for a copy.
Aug 29 16:52:31.807 [warn] Received http status code 404 ("Not found") from server '194.109.206.212:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 16:52:31.818 [warn] Received http status code 404 ("Not found") from server '213.115.239.118:443' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 16:52:31.945 [warn] Received http status code 404 ("Not found") from server '128.31.0.34:9131' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 16:52:32.039 [warn] Received http status code 404 ("Not found") from server '208.83.223.34:443' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 16:52:32.053 [warn] Received http status code 404 ("Not found") from server '216.224.124.114:9030' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 16:52:32.249 [warn] Received http status code 404 ("Not found") from server '193.23.244.244:80' while fetching "/tor/status-vote/next/ED03BB616EB2F60BEC80151114BB25CEF515B226.z".
Aug 29 16:55:01.821 [notice] Got a signature from 194.109.206.212. Queuing it for the next consensus.
Aug 29 16:55:01.961 [notice] Time to compute a consensus.
Aug 29 16:55:02.050 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=988101 M=592235 E=248355 D=815597 T=2644288
Aug 29 16:55:02.081 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 16:55:02.186 [notice] Computed bandwidth weights for Case 3b (E scarce, Wme*E == Wmd*D): G=988101 M=592235 E=248355 D=815597 T=2644288
Aug 29 16:55:02.219 [notice] Bandwidth-weight Case 3b is verified and valid.
Aug 29 16:55:02.296 [notice] Added 2 pending signatures while building consensus.
Aug 29 16:55:02.296 [notice] Consensus computed; uploading signature(s)
Aug 29 16:55:02.296 [notice] Signature(s) posted.
Aug 29 16:55:02.307 [notice] Got a signature from 172.22.121.11. Adding it to the pending consensus.
Aug 29 16:55:02.307 [notice] Uploaded signature(s) to dirserver 86.59.21.38:80
Aug 29 16:55:02.352 [notice] Uploaded signature(s) to dirserver 80.190.246.100:8180
Aug 29 16:55:02.370 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 16:55:02.370 [warn] Unable to store signatures posted by 208.83.223.34: Mismatched digest.
Aug 29 16:55:02.463 [notice] Uploaded signature(s) to dirserver 194.109.206.212:80
Aug 29 16:55:02.513 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 16:55:02.513 [warn] Unable to store signatures posted by 213.115.239.118: Mismatched digest.
Aug 29 16:55:02.677 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '213.115.239.118:443'. Please correct.
Aug 29 16:55:02.833 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 16:55:02.833 [warn] Unable to store signatures posted by 216.224.124.114: Mismatched digest.
Aug 29 16:55:02.849 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '216.224.124.114:9030'. Please correct.
Aug 29 16:55:02.902 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '208.83.223.34:443'. Please correct.
Aug 29 16:55:02.962 [notice] Uploaded signature(s) to dirserver 128.31.0.34:9131
Aug 29 16:55:02.963 [notice] Got a signature from 128.31.0.34. Adding it to the pending consensus.
Aug 29 16:55:04.901 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 16:55:04.901 [warn] Unable to store signatures posted by 193.23.244.244: Mismatched digest.
Aug 29 16:55:05.846 [warn] http status 400 ("Mismatched digest.") response after uploading signatures to dirserver '193.23.244.244:80'. Please correct.
Aug 29 16:57:10.871 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 16:57:31.389 [notice] Time to fetch any signatures that we're missing.
Aug 29 16:57:31.412 [notice] Got a signature from 80.190.246.100. Adding it to the pending consensus.
Aug 29 16:57:31.512 [notice] Got a signature from 213.115.239.118. Adding it to the pending consensus.
Aug 29 16:57:31.512 [warn] Problem adding detached signatures from 213.115.239.118:443: Mismatched digest.
Aug 29 16:57:31.640 [notice] Got a signature from 128.31.0.34. Adding it to the pending consensus.
Aug 29 16:57:31.736 [notice] Got a signature from 208.83.223.34. Adding it to the pending consensus.
Aug 29 16:57:31.736 [warn] Problem adding detached signatures from 208.83.223.34:443: Mismatched digest.
Aug 29 16:57:31.743 [notice] Got a signature from 216.224.124.114. Adding it to the pending consensus.
Aug 29 16:57:31.743 [warn] Problem adding detached signatures from 216.224.124.114:9030: Mismatched digest.
Aug 29 16:57:32.183 [notice] Got a signature from 193.23.244.244. Adding it to the pending consensus.
Aug 29 16:57:32.183 [warn] Problem adding detached signatures from 193.23.244.244:80: Mismatched digest.
Aug 29 16:57:32.295 [notice] Got a signature from 194.109.206.212. Adding it to the pending consensus.
Aug 29 17:00:01.644 [notice] Time to publish the consensus and discard old votes
Aug 29 17:00:01.670 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 17:00:01.670 [warn] Not enough good signatures on networkstatus consensus
Aug 29 17:00:01.670 [warn] Error publishing ns consensus
Aug 29 17:00:01.695 [warn] 2 unknown, 0 missing key, 4 good, 0 bad, 6 no signature, 5 required
Aug 29 17:00:01.695 [warn] Not enough good signatures on networkstatus consensus
Aug 29 17:00:01.695 [warn] Error publishing microdesc consensus
Aug 29 17:00:01.712 [notice] Choosing expected valid-after time as 2010-08-29 18:00:00: consensus_set=1, interval=3600
Aug 29 17:50:01.888 [notice] Time to vote.

comment:10 Changed 8 years ago by Sebastian

Milestone: Tor: 0.2.2.x-finalTor: 0.2.3.1-alpha
Priority: minornormal

Bumping the priority and moving it out of 0.2.2.x, since authority-specific issues shouldn't affect the stable release.

comment:11 Changed 8 years ago by arma

Component: Tor RelayTor Directory Authority

comment:12 Changed 8 years ago by nickm

Milestone: Tor: 0.2.3.1-alphaTor: 0.2.3.x-final
Priority: normalmajor

Roger says:

This is because authorities take just long enough to publish that not everybody gets the same view of who voted, so multiple consensuses with not enough signatures occur.

He says that this bug occurs several times a week, at least.

Roger also notes that the original report here seems to have happened when gabelmoo's clock jumped during voting. I hope that isn't the reason this is happening often.

I say that the stuff to investigate here to make good progress is:

  • Are authorities' times really synchronized? Are authorities starting to vote at _actually_ the same time?
  • Does it really take long enough to publish a vote that we hit race conditions? If so, why?

If our start times are desynchonized, we should fix that. If publication takes too long, we should see if we can get it down.

Otherwise, if these are the issues and they can't be easily fixed, we should examine whether we can allow more time for votes to arrive.

comment:13 Changed 7 years ago by nickm

Status: newneeds_information

Bridge authority ops -- is it possible to investigate the above questions?

comment:14 Changed 7 years ago by arma

*bridge*?

I think the consensus process will be in better shape if we put in the proposal sebastian was working on, to have intervals after which we don't accept votes because getting a vote at the wrong time is screwing us up. I wonder if that has a ticket or a proposal number.

comment:15 Changed 7 years ago by nickm

oops. Not bridge.

"Authority ops, is it possible to investigate the above questions?" :)

The idea you describe has some promise; I'll wait and see what it turns out to be. Still, if the analysis is right, I think it would be good to know _why_ the votes are arriving at the wrong time and screwing stuff up. Desynchronized authorities? Publishing at the wrong time? Taking too long to publish? Some bug in the "start uploading your vote now" code?

comment:16 Changed 7 years ago by arma

Sometimes directory authorities have clocks that are wrong by several minutes. This happened on gabelmoo for a while.

I would say this is not an isolated event, but it also doesn't happen often enough to be a real problem. We should do some of the steps we know will improve the situation, and then see if there's a reduction in frequency.

Speaking of which! How about getting Karsten or somebody to make us a visual on how often we fail to achieve a consensus?

comment:17 Changed 7 years ago by rransom

Deviant consensus times in 2012 so far:

        2012-01-07-21-00-00-consensus
        2012-01-07-22-00-00-consensus
        2012-01-07-23-00-00-consensus
        2012-01-08-00-00-00-consensus
        2012-01-08-01-00-00-consensus
        2012-01-08-02-00-00-consensus
        2012-01-08-03-00-00-consensus
        2012-01-08-04-00-00-consensus
        2012-01-08-05-00-00-consensus
        2012-01-08-06-00-00-consensus
        2012-01-08-07-00-00-consensus
        2012-01-08-08-00-00-consensus
        2012-01-08-09-00-00-consensus
        2012-01-08-10-00-00-consensus
        2012-01-08-11-00-00-consensus
        2012-01-08-12-00-00-consensus
        2012-01-08-13-00-00-consensus
        2012-01-08-14-00-00-consensus
        2012-01-08-15-00-00-consensus
        2012-01-08-17-00-00-consensus
        2012-01-08-19-00-00-consensus
        2012-01-09-00-00-00-consensus
        2012-01-09-14-00-00-consensus
        2012-01-09-15-00-00-consensus
        2012-01-09-18-00-00-consensus
        2012-01-09-19-00-00-consensus
        2012-01-09-20-00-00-consensus
        2012-01-09-21-00-00-consensus
        2012-01-09-22-00-00-consensus
        2012-01-09-23-00-00-consensus
        2012-01-10-00-00-00-consensus
        2012-01-10-01-00-00-consensus
        2012-01-10-02-00-00-consensus
        2012-01-10-03-00-00-consensus
        2012-01-10-04-00-00-consensus
        2012-01-10-05-00-00-consensus
        2012-01-10-06-00-00-consensus
        2012-01-10-07-00-00-consensus
        2012-01-10-13-00-00-consensus
        2012-01-10-20-00-00-consensus
        2012-01-13-12-00-00-consensus
        2012-01-13-21-00-00-consensus
        2012-01-15-11-00-00-consensus
        2012-01-15-23-00-00-consensus
        2012-01-16-03-00-00-consensus
        2012-01-16-07-00-00-consensus
        2012-01-16-11-00-00-consensus
        2012-01-23-22-00-00-consensus
        2012-01-24-15-00-00-consensus
        2012-01-26-16-00-00-consensus
        2012-02-02-23-00-00-consensus
        2012-02-07-23-00-00-consensus
        2012-02-24-19-00-00-consensus
        2012-02-25-01-00-00-consensus
        2012-02-25-10-00-00-consensus
        2012-02-27-12-00-00-consensus
        2012-02-29-18-00-00-consensus
        2012-03-08-04-00-00-consensus
        2012-03-21-20-00-00-consensus

Changed 7 years ago by rransom

list of deviant consensus times in 2011 tarballs

comment:18 Changed 7 years ago by rransom

I've attached a list of ‘deviant consensus times’ from 2011. Most of the failures happened in bursts of contiguous missing consensuses; we will need a visualization.

Oddly, my scripts didn't find any consensuses in the metrics-archive tarballs generated at a half hour. I suspect that the consensus archive system doesn't catch those.

Changed 7 years ago by karsten

Attachment: deviant-consensus-times.png added

Graph of deviant consensus times in 2011 and 2012

Changed 7 years ago by karsten

Attachment: deviant-consensus-times.R added

Graphing code

comment:19 in reply to:  18 Changed 7 years ago by karsten

Replying to rransom:

I've attached a list of ‘deviant consensus times’ from 2011. Most of the failures happened in bursts of contiguous missing consensuses; we will need a visualization.

I attached a graph and the graphing code.

Oddly, my scripts didn't find any consensuses in the metrics-archive tarballs generated at a half hour. I suspect that the consensus archive system doesn't catch those.

That's correct.

comment:20 Changed 7 years ago by nickm

Does any of this info help answer my questions about what was going on here? (synchonization issues, delays transmitting, bugs in timing, other?)

comment:21 Changed 7 years ago by Sebastian

I think it's clear there's some kind of correlation here, where having one failed consensus means it's more likely the next will also be missing. My theory for what's happening is still the same, it's network issues at one authority meaning it can't get through to all others in a sane timeframe, but eventually gets there for some of them.

comment:22 in reply to:  20 ; Changed 7 years ago by arma

Replying to nickm:

Does any of this info help answer my questions about what was going on here? (synchonization issues, delays transmitting, bugs in timing, other?)

For the original report, it looks like gabelmoo was somehow wedged such that it took between 75 and 105 seconds for people to publish their vote to it. See comment 5 for when it noticed that it was napping for 2-3 minutes. This still-unexplained wedging triggered synchronization problems in agreeing about the consensus.

If I had to guess about the wedging, I would guess some sort of VM/VPS bug. Distant second guess might be a libevent bug.

comment:23 in reply to:  22 ; Changed 7 years ago by Sebastian

Replying to arma:

If I had to guess about the wedging, I would guess some sort of VM/VPS bug. Distant second guess might be a libevent bug.

Gabelmoo didn't run in a VM at that time.

comment:24 in reply to:  23 Changed 7 years ago by arma

Replying to Sebastian:

Replying to arma:

If I had to guess about the wedging, I would guess some sort of VM/VPS bug. Distant second guess might be a libevent bug.

Gabelmoo didn't run in a VM at that time.

Ok. The "why did your Tor claim it jumped forward in time" bug has been around since the dawn of time, without many good explanations for it. It happens less often on better maintained computers, but that's about the only hint we've got, and that's anecdotal at best.

comment:25 Changed 7 years ago by Sebastian

Right. I don't think this bug is about tracking down why a clock might've jumped. maatuska's clock wasn't jumping, yet it caused the recent problems, and gabelmoo's clock is still jumping sometimes, but doesn't cause an issue.

comment:26 Changed 7 years ago by nickm

Keywords: tor-auth added

comment:27 Changed 7 years ago by nickm

Component: Tor Directory AuthorityTor

comment:28 Changed 6 years ago by nickm

Milestone: Tor: 0.2.3.x-finalTor: unspecified

comment:29 Changed 2 years ago by nickm

Resolution: worksforme
Severity: Normal
Status: needs_informationclosed

No reports of this for a while; optimistically closing.

Note: See TracTickets for help on using tickets.