Bug #10696: Tor bridge mode fails on Jessie when time is way off

Bug #10696

Tor bridge mode fails on Jessie when time is way off

Added by intrigeri 2015-11-30 13:50:28 . Updated 2015-12-01 06:51:12 .

Status:

Resolved

Priority:

Elevated

Assignee:

Category:

Tor configuration

Target version:

Tails_2.0

Start date:

2015-11-30

Due date:

% Done:

100%

Feature Branch:

Type of work:

Code

Blueprint:

Starter:

Affected tool:

Deliverable for:

269

Description

time_syncing.feature fails all “in bridge mode” scenarios: “Tor is ready” fails.

Reproduced manually, I’ve seen “Failed to synchronize the clock” notification while Tor Launcher was still “Loading network status”. So we have two bugs:

time sync is started before Tor is ready
Tor never finishes its bootstrap

Subtasks

Related issues

Blocks Tails - ~~Feature #7563~~: Update the automated test suite for Jessie ISO images

Resolved

2014-11-26

2016-01-15

History

#1 Updated by intrigeri 2015-11-30 13:50:47

blocks ~~Feature #7563~~: Update the automated test suite for Jessie ISO images added

#2 Updated by intrigeri 2015-11-30 14:00:07

Description updated

Extracts of the Journal:

Aug 30 00:00:25 amnesia tor[2707]: Aug 30 00:00:25.414 [notice] Tor v0.2.7.5 (git-6184c873e90d93b2) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.1k and Zlib 1.2.8.
Aug 30 00:00:25 amnesia tor[2707]: Aug 30 00:00:25.415 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Aug 30 00:00:25 amnesia tor[2707]: Aug 30 00:00:25.415 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Aug 30 00:00:25 amnesia tor[2707]: Aug 30 00:00:25.415 [notice] Read configuration file "/etc/tor/torrc".
Aug 30 00:00:25 amnesia tor[2707]: Aug 30 00:00:25.419 [notice] Opening Control listener on 127.0.0.1:9051
Aug 30 00:00:25 amnesia tor[2707]: Aug 30 00:00:25.420 [notice] Opening Control listener on /var/run/tor/control
Aug 30 00:00:25 amnesia tor[2707]: Aug 30 00:00:25.420 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections.
[...]
Aug 30 00:00:25 amnesia sudo[2758]: root : TTY=unknown ; PWD=/ ; USER=tor-launcher ; COMMAND=/usr/bin/tor-launcher
[...]
Aug 30 00:01:01 amnesia time[3316]: Checking if system clock is way off
[...]
Aug 30 00:01:01 amnesia time[3323]: Waiting for a Tor consensus file to contain a valid time interval
Aug 30 00:01:01 amnesia nm-dispatcher[2515]: 2184
Aug 30 00:01:04 amnesia NetworkManager[2514]: <error> [1440892864.041403] [rdisc/nm-lndp-rdisc.c:241] send_rs(): (eth0): cannot send router solicitation: -1.
Aug 30 00:01:04 amnesia kernel: Dropped outbound packet: IN= OUT=eth0 SRC=fe80:0000:0000:0000:5254:00ff:feef:2bf0 DST=ff02:0000:0000:0000:0000:0000:0000:0002 LEN=48 TC=0 HOPLIMIT=255 FLOWLBL=0 PROTO=ICMPv6 TYPE=133 CODE=0 UID
Aug 30 00:01:04 amnesia nm-dispatcher[2515]: /var/lib/tor/ CLOSE_WRITE,CLOSE unverified-microdesc-consensus.tmp
Aug 30 00:01:04 amnesia time[3338]: A Tor consensus file now contains a valid time interval.
Aug 30 00:01:04 amnesia time[3341]: We do not have a Tor verified consensus, let's use the unverified one.
Aug 30 00:01:04 amnesia time[3342]: Waiting for the chosen Tor consensus file to contain a valid time interval...
Aug 30 00:01:04 amnesia time[3344]: The chosen Tor consensus now contains a valid time interval, let's use it.
Aug 30 00:01:04 amnesia time[3348]: Tor: valid-after=2015-11-30 21:00:00 | valid-until=2015-12-01 00:00:00
Aug 30 00:01:04 amnesia time[3351]: Current time is 2015-08-30 00:01:04
Aug 30 00:01:04 amnesia time[3356]: Current time is not in valid Tor range, setting to middle of this range: [2015-11-30 22:30:00]
Nov 30 22:30:00 amnesia systemd[1989]: Time has been changed
Nov 30 22:30:00 amnesia systemd[1616]: Time has been changed
Nov 30 22:30:00 amnesia tor[3366]: Nov 30 22:30:00.304 [notice] Tor v0.2.7.5 (git-6184c873e90d93b2) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.1k and Zlib 1.2.8.
Nov 30 22:30:00 amnesia tor[3366]: Nov 30 22:30:00.304 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Nov 30 22:30:00 amnesia tor[3366]: Nov 30 22:30:00.304 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Nov 30 22:30:00 amnesia tor[3366]: Nov 30 22:30:00.304 [notice] Read configuration file "/etc/tor/torrc".
Nov 30 22:30:00 amnesia tor[3366]: Configuration was valid
Nov 30 22:30:00 amnesia tor[3368]: Nov 30 22:30:00.535 [notice] Tor v0.2.7.5 (git-6184c873e90d93b2) running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.1k and Zlib 1.2.8.
Nov 30 22:30:00 amnesia tor[3368]: Nov 30 22:30:00.535 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Nov 30 22:30:00 amnesia tor[3368]: Nov 30 22:30:00.535 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Nov 30 22:30:00 amnesia tor[3368]: Nov 30 22:30:00.535 [notice] Read configuration file "/etc/tor/torrc".
Nov 30 22:30:00 amnesia tor[3368]: Nov 30 22:30:00.537 [notice] Opening Control listener on 127.0.0.1:9051
Nov 30 22:30:00 amnesia tor[3368]: Nov 30 22:30:00.537 [notice] Opening Control listener on /var/run/tor/control
Nov 30 22:30:00 amnesia tor[3368]: Nov 30 22:30:00.537 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections.
Nov 30 22:30:00 amnesia time[3372]: Waiting for Tor to be working...
[...]
Nov 30 22:31:00 amnesia time[3593]: Timed out waiting for Tor to be working
Nov 30 22:31:00 amnesia time[3604]: Restarting htpdate
Nov 30 22:31:01 amnesia htpdate[3619]: Aborting as one pool could not be reached at /usr/local/sbin/htpdate line 82.
Nov 30 22:31:01 amnesia htpdate[3619]: main::error("Aborting as one pool could not be reached") called at /usr/local/sbin/htpdate line 307
Nov 30 22:31:01 amnesia htpdate[3619]: Perl exited with active threads:
Nov 30 22:31:01 amnesia htpdate[3619]: 1 running and unjoined
Nov 30 22:31:01 amnesia htpdate[3619]: 1 finished and unjoined
Nov 30 22:31:01 amnesia htpdate[3619]: 0 running and detached
Nov 30 22:31:01 amnesia systemd[1]: htpdate.service: main process exited, code=exited, status=255/n/a
Nov 30 22:31:01 amnesia systemd[1]: Failed to start Setting time using HTP.
Nov 30 22:31:01 amnesia systemd[1]: Unit htpdate.service entered failed state.
Nov 30 22:31:01 amnesia nm-dispatcher[2515]: Job for htpdate.service failed. See 'systemctl status htpdate.service' and 'journalctl -xn' for details.
Nov 30 22:31:01 amnesia time[3642]: htpdate service restarted with return code 1
[...]
Nov 30 22:41:01 amnesia nm-dispatcher[2515]: Script '/etc/NetworkManager/dispatcher.d/60-tor-ready.sh' took too long; killing it.
Nov 30 22:41:01 amnesia ttdnsd[7289]: Starting ttdnsd daemon: ttdnsdWe've loaded 208.67.222.222 as a nameserver.
Nov 30 22:41:01 amnesia ttdnsd[7289]: 1 nameservers loaded
Nov 30 22:41:01 amnesia nm-dispatcher[2515]: vidalia: no process found
Nov 30 22:41:02 amnesia sudo[7311]: root : TTY=unknown ; PWD=/ ; USER=amnesia ; COMMAND=/usr/bin/xhost +SI:localuser:vidalia
Nov 30 22:41:02 amnesia sudo[7311]: pam_unix(sudo:session): session opened for user amnesia by (uid=0)
Nov 30 22:41:02 amnesia nm-dispatcher[2515]: localuser:vidalia being added to access control list
Nov 30 22:41:02 amnesia sudo[7311]: pam_unix(sudo:session): session closed for user amnesia
Nov 30 22:41:02 amnesia sudo[7315]: root : TTY=unknown ; PWD=/ ; USER=vidalia ; COMMAND=/usr/bin/lckdo /var/lock/vidalia vidalia -DISPLAY=:0
Nov 30 22:41:02 amnesia sudo[7315]: pam_unix(sudo:session): session opened for user vidalia by (uid=0)

#3 Updated by intrigeri 2015-11-30 14:13:55

# ls -lh /var/lib/tor/
total 2.6M
-rw------- 1 debian-tor debian-tor    0 Nov 30 22:30 cached-descriptors
-rw------- 1 debian-tor debian-tor    0 Nov 30 22:30 cached-descriptors.new
-rw------- 1 debian-tor debian-tor    0 Nov 30 22:30 lock
-rw------- 1 debian-tor debian-tor  215 Nov 30 22:30 state
-rw------- 2 debian-tor debian-tor 1.3M Aug 30 00:01 unverified-microdesc-consensus
-rw------- 2 debian-tor debian-tor 1.3M Aug 30 00:01 unverified-microdesc-consensus.bak

# . /usr/local/lib/tails-shell-library/tor.sh
# tor_control_getconf DisableNetwork
1

… which contradicts the “Wait until the user has done the Tor Launcher configuration” comment we have in the 10-tor.sh NM hook.

#4 Updated by intrigeri 2015-12-01 04:17:53

More debugging: I set time to 20150830 before logging in in bridge mode. At some point DisableNetwork is set to 0, and then 20-time.sh starts, it shows its notification; so far, so good. tor_is_working returns false, is_clock_way_off starts monitoring the log, tor_bootstrap_progress ends up returning 10 but tor_cert_lifetime_invalid returns true, so we’re in the “The clock is so badly off that Tor cannot download a consensus. Setting system time to the authority’s cert’s valid-after date and trying to fetch a consensus again…” case. The time is set to Nov 24, Tor is reloaded, and we unsuccessfully wait_for_tor_consensus for 10 * 30 seconds = 5 minutes. During that time, tor_control_getconf DisableNetwork returns 1, so perhaps it’s not surprising that Tor doesn’t bootstrap?

The Tor log seems to indicate that reloading indeed reset DisableNetwork to 1:

ov 24 00:00:00.000 [warn] comparing times on millisecond detail too far apart: 7430294 seconds
Nov 24 00:00:00.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Nov 24 00:00:00.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Nov 24 00:00:00.000 [notice] Read configuration file "/etc/tor/torrc".
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:25' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:119' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:135-139' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:445' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:563' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:1214' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:4661-4666' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:6346-6429' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:6699' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:6881-6999' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [info] tor_addr_parse_mask_ports(): '*:*' expands into rules which apply to all IPv4 and IPv6 addresses. (Use accept/reject *4:* for IPv4 or accept[6]/reject[6] *6:* for IPv6.)
Nov 24 00:00:00.000 [notice] Closing no-longer-configured Transparent pf/netfilter listener on 127.0.0.1:9040
Nov 24 00:00:00.000 [notice] Closing no-longer-configured DNS listener on 127.0.0.1:5353
Nov 24 00:00:00.000 [notice] Closing no-longer-configured Socks listener on 127.0.0.1:9050
Nov 24 00:00:00.000 [notice] Closing no-longer-configured Socks listener on 127.0.0.1:9061
Nov 24 00:00:00.000 [notice] Closing no-longer-configured Socks listener on 127.0.0.1:9062
Nov 24 00:00:00.000 [notice] Closing no-longer-configured Socks listener on 127.0.0.1:9150
Nov 24 00:00:00.000 [notice] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections.
Nov 24 00:00:00.000 [info] tor_getpwnam(): Caching new entry debian-tor for debian-tor
Nov 24 00:00:00.000 [notice] Tor 0.2.7.5 (git-6184c873e90d93b2) opening log file.
Nov 24 00:00:00.000 [notice] Closing old Transparent pf/netfilter listener on 127.0.0.1:9040
Nov 24 00:00:00.000 [notice] Closing old DNS listener on 127.0.0.1:5353
Nov 24 00:00:00.000 [notice] Closing old Socks listener on 127.0.0.1:9050
Nov 24 00:00:00.000 [notice] Closing old Socks listener on 127.0.0.1:9061
Nov 24 00:00:00.000 [notice] Closing old Socks listener on 127.0.0.1:9062
Nov 24 00:00:00.000 [notice] Closing old Socks listener on 127.0.0.1:9150
Nov 24 00:00:00.000 [notice] Your system clock just jumped 7430295 seconds forward; assuming established circuits no longer work.
Nov 24 00:00:00.000 [notice] Heartbeat: Tor's uptime is 0:01 hours, with 0 circuits open. I've sent 0 kB and received 2 kB.
Nov 24 00:00:00.000 [notice] Average packaged cell fullness: 100.000%. TLS write overhead: 4356%
Nov 24 00:00:00.000 [notice] New control connection opened from 127.0.0.1.
Nov 24 00:15:02.000 [notice] New control connection opened.
Nov 24 00:15:02.000 [notice] New control connection opened.
Nov 24 00:28:13.000 [notice] New control connection opened from 127.0.0.1.

#5 Updated by intrigeri 2015-12-01 04:40:20

Status changed from Confirmed to In Progress

I confirm that DisableNetwork is briefly set to 0 after I click “Connect” in Tor Launcher, but it’s reset back to 1 pretty quickly. I suspect that the modified torrc can’t be written because of the systemd unit file’s hardening.

#6 Updated by intrigeri 2015-12-01 05:23:29

Even after adding /etc/tor to ReadWriteDirectories:

Aug 30 00:01:34.000 [notice] Renaming old configuration file to "/etc/tor/torrc.orig.1"
Aug 30 00:01:34.000 [warn] Couldn't rename configuration file "/etc/tor/torrc" to "/etc/tor/torrc.orig.1": Read-only file system

#7 Updated by intrigeri 2015-12-01 06:47:11

Status changed from In Progress to Resolved
% Done changed from 0 to 100

Applied in changeset commit:0af421ae2bc7bdf457ebc3601e9f35056f66f77f.

#8 Updated by intrigeri 2015-12-01 06:51:12

Assignee deleted (~~intrigeri~~)