Re: [Tails-dev] Please review and test feature/tordate

01/21/2012 04:16 PM, anonym:
> 01/20/2012 07:15 PM, intrigeri:
>> Hi,
>>
>> I've pushed some robustness improvements to feature/tordate (forked
>> from stable branch, targetted at 0.10.1).

I have now tested the additional commits, i.e.:

35a88c3 Only HUP Tor after setting the system time to the release date.
3bd28e1 Better deal with very badly off clocks.
cf679d5 Minor code simplification.
fec3f37 Set time from Tor unverified-consensus if needed.
deac77c Tiny optimization.
243b1c7 Make has_consensus take an optional file argument.

Even though I suspect our new shiny tordate to work a lot, I did
experience a tordate freeze: it got in a state where
wait_for_tor_consensus() timeouts indefinitely, and I suspect it is due
to a Tor bug. See logs below for the full pictore.

I was running with a system time that was just slightly out of the
consensus validity range (1-2 hours), and Tor got stuck after bootstrap
25%, before it writes the consensus to a file. Manually restarting Tor
at this point start things up again, so maybe we should consider
restarting Tor on timeouts? That has to be thought through thoroughly
though. Thoughts?

Thoughouthrouthothoughoth :)

Cheers!


Here's the 20-time.sh/tordate log:
==================================

Jan 26 10:00:01 localhost time: Waiting for a Tor consensus file to
contain a valid time interval
Jan 26 10:01:01 localhost time: timeout
Jan 26 10:02:01 localhost time: timeout
Jan 26 10:03:01 localhost time: timeout
Jan 26 10:04:01 localhost time: timeout
Jan 26 10:04:10 localhost time: A Tor consensus file now contains a
valid time interval.
Jan 26 10:04:10 localhost time: Waiting for the chosen Tor consensus
file to contain a valid time interval...
Jan 26 10:04:10 localhost time: The chosen Tor consensus now contains a
valid time interval, let's use it.
Jan 26 10:04:10 localhost time: Tor: valid-after=2012-01-26 11:00:00 |
valid-until=2012-01-26 14:00:00
Jan 26 10:04:10 localhost time: Current time is 2012-01-26 10:04:10
Jan 26 10:04:10 localhost time: Current time is not in valid Tor range,
setting to middle of this range: [2012-01-26 12:30:00]
Jan 26 12:30:00 localhost time: Restarting Tor service
Jan 26 12:30:02 localhost time: Waiting for Tor to be working (i.e.
cached descriptors exist)...
Jan 26 12:30:02 localhost time: Tor is now working.


And here's the Tor log (with some comments):
============================================

Jan 26 10:00:01.029 [notice] Tor 0.2.2.35 (git-73ff13ab3cc9570d) opening
new log file.
Jan 26 10:00:01.030 [notice] Parsing GEOIP file /usr/share/tor/geoip.
Jan 26 10:00:01.174 [notice] OpenSSL OpenSSL 0.9.8o 01 Jun 2010 looks
like version 0.9.8m or later; I will try SSL_OP to enable renegotiation
Jan 26 10:00:01.278 [notice] Bootstrapped 5%: Connecting to directory
server.
Jan 26 10:00:01.278 [notice] I learned some more directory information,
but not enough to build a circuit: We have no network-status consensus.
Jan 26 10:00:01.312 [notice] Bootstrapped 10%: Finishing handshake with
directory server.
Jan 26 10:00:01.517 [notice] Bootstrapped 15%: Establishing an encrypted
directory connection.
Jan 26 10:00:01.623 [notice] Bootstrapped 20%: Asking for networkstatus
consensus.
Jan 26 10:00:01.758 [warn] Received directory with skewed time (server
'194.109.206.212:443'): It seems that our clock is behind by 1 hours, 50
minutes, or that theirs is ahead. Tor requires an accurate clock to
work: please check your time, timezone, and date settings.
Jan 26 10:00:01.762 [notice] I learned some more directory information,
but not enough to build a circuit: We have no network-status consensus.
Jan 26 10:00:02.745 [notice] Bootstrapped 25%: Loading networkstatus
consensus.

# This is where Tor locks up and, consequentially,
wait_for_tor_consensus() timeouts 4 times. I manually send a HUP...

Jan 26 10:03:50.955 [notice] Received reload signal (hup). Reloading
config and resetting internal state.
Jan 26 10:03:50.956 [notice] Tor 0.2.2.35 (git-73ff13ab3cc9570d) opening
log file.

# ...but it seems to do nothing. So I manually restart Tor:

Jan 26 10:04:06.887 [notice] Interrupt: exiting cleanly.
Jan 26 10:04:08.900 [notice] Tor 0.2.2.35 (git-73ff13ab3cc9570d) opening
log file.
Jan 26 10:04:08.901 [notice] Parsing GEOIP file /usr/share/tor/geoip.
Jan 26 10:04:09.039 [notice] OpenSSL OpenSSL 0.9.8o 01 Jun 2010 looks
like version 0.9.8m or later; I will try SSL_OP to enable renegotiation
Jan 26 10:04:09.088 [notice] I learned some more directory information,
but not enough to build a circuit: We have no network-status consensus.
Jan 26 10:04:10.090 [notice] Bootstrapped 5%: Connecting to directory
server.
Jan 26 10:04:10.093 [notice] Bootstrapped 10%: Finishing handshake with
directory server.
Jan 26 10:04:10.168 [notice] Bootstrapped 15%: Establishing an encrypted
directory connection.
Jan 26 10:04:10.275 [notice] Bootstrapped 20%: Asking for networkstatus
consensus.
Jan 26 10:04:10.281 [notice] Bootstrapped 25%: Loading networkstatus
consensus.
Jan 26 10:04:10.496 [warn] Received directory with skewed time (server
'213.115.239.118:80'): It seems that our clock is behind by 1 hours, 50
minutes, or that theirs is ahead. Tor requires an accurate clock to
work: please check your time, timezone, and date settings.
Jan 26 10:04:10.529 [warn] Our clock is 55 minutes, 50 seconds behind
the time published in the consensus network status document (2012-01-26
11:00:00 GMT). Tor needs an accurate clock to work correctly. Please
check your time and date settings!

# I think it's here the consensus is actually written to disk.

Jan 26 10:04:10.529 [notice] I learned some more directory information,
but not enough to build a circuit: We have no recent network-status
consensus.
Jan 26 12:30:00.028 [notice] Interrupt: exiting cleanly.

# maybe_set_time_from_tor_consensus() restarts Tor since the system time
was changed.

Jan 26 12:30:02.043 [notice] Tor 0.2.2.35 (git-73ff13ab3cc9570d) opening
log file.
Jan 26 12:30:02.044 [notice] Parsing GEOIP file /usr/share/tor/geoip.
Jan 26 12:30:02.198 [notice] OpenSSL OpenSSL 0.9.8o 01 Jun 2010 looks
like version 0.9.8m or later; I will try SSL_OP to enable renegotiation
Jan 26 12:30:02.276 [notice] Bootstrapped 45%: Asking for relay descriptors.
Jan 26 12:30:02.276 [notice] I learned some more directory information,
but not enough to build a circuit: We have only 0/2569 usable descriptors.
Jan 26 12:30:02.632 [notice] Bootstrapped 50%: Loading relay descriptors.
Jan 26 12:30:02.765 [notice] Bootstrapped 54%: Loading relay descriptors.
Jan 26 12:30:02.765 [notice] I learned some more directory information,
but not enough to build a circuit: We have only 96/2569 usable descriptors.
Jan 26 12:30:02.833 [notice] Bootstrapped 58%: Loading relay descriptors.
Jan 26 12:30:02.833 [notice] I learned some more directory information,
but not enough to build a circuit: We have only 192/2569 usable descriptors.
Jan 26 12:30:03.025 [notice] Bootstrapped 63%: Loading relay descriptors.
Jan 26 12:30:03.025 [notice] I learned some more directory information,
but not enough to build a circuit: We have only 288/2569 usable descriptors.
Jan 26 12:30:03.109 [notice] Bootstrapped 67%: Loading relay descriptors.
Jan 26 12:30:03.109 [notice] I learned some more directory information,
but not enough to build a circuit: We have only 384/2569 usable descriptors.
Jan 26 12:30:03.158 [notice] Bootstrapped 71%: Loading relay descriptors.
Jan 26 12:30:03.159 [notice] I learned some more directory information,
but not enough to build a circuit: We have only 480/2569 usable descriptors.
Jan 26 12:30:03.160 [notice] New control connection opened.
Jan 26 12:30:03.161 [notice] New control connection opened.
Jan 26 12:30:03.270 [notice] Bootstrapped 76%: Loading relay descriptors.
Jan 26 12:30:03.270 [notice] I learned some more directory information,
but not enough to build a circuit: We have only 576/2569 usable descriptors.
Jan 26 12:30:03.317 [notice] We now have enough directory information to
build circuits.
Jan 26 12:30:03.317 [notice] Bootstrapped 80%: Connecting to the Tor
network.
Jan 26 12:30:03.351 [notice] Bootstrapped 85%: Finishing handshake with
first hop.
Jan 26 12:30:04.313 [notice] Bootstrapped 90%: Establishing a Tor circuit.
Jan 26 12:30:05.369 [notice] Tor has successfully opened a circuit.
Looks like client functionality is working.
Jan 26 12:30:05.369 [notice] Bootstrapped 100%: Done.

# Finally Tor works.