Opened 5 years ago

Closed 5 years ago

#14918 closed defect (fixed)

Tor 0.2.6.2-alpha complaining about "no exits in consensus" but consensus actually seems fine

Reported by: fk Owned by:
Priority: Medium Milestone: Tor: 0.2.6.x-final
Component: Core Tor/Tor Version: Tor: 0.2.6.2-alpha
Severity: Keywords: tor-relay regression
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Since the upgrade to Tor 0.2.6.2-alpha I frequently get complaints like this on the non-exit relay polizeierziehung ($5CE3AD8AD04ADE66C0037A3CF5F7F7A40D48A20B):

Feb 17 10:19:57.000 [warn] {NET} We need more descriptors: we have 0/6967, and can only build 1% of likely paths. (We have 10% of guards bw, 10% of midpoint bw, and 100% of exit bw (no exits in consensus) = 1% 
of path bw.)
Feb 17 10:20:58.000 [warn] {NET} We need more descriptors: we have 0/6967, and can only build 1% of likely paths. (We have 10% of guards bw, 10% of midpoint bw, and 100% of exit bw (no exits in consensus) = 1% 
of path bw.)
Feb 17 10:21:59.000 [warn] {NET} We need more descriptors: we have 0/6967, and can only build 1% of likely paths. (We have 10% of guards bw, 10% of midpoint bw, and 100% of exit bw (no exits in consensus) = 1% 
of path bw.)

At the moment they occur once per ~61 seconds.

Tor already complained about "no exits in consensus" while bootstrapping but stopped after connecting to the network:

Feb 15 12:41:01.000 [notice] Tor 0.2.6.2-alpha (git-6cb1daf062df5252) opening new log file.
Feb 15 12:41:01.576 [notice] Tor v0.2.6.2-alpha (git-6cb1daf062df5252) running on ElectroBSD with Libevent 2.0.21-stable, OpenSSL 1.0.1j-freebsd and Zlib 1.2.8.
Feb 15 12:41:01.576 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Feb 15 12:41:01.576 [notice] This version is not a stable Tor release. Expect more bugs than usual.
Feb 15 12:41:01.576 [notice] Read configuration file "/usr/local/etc/tor/torrc".
Feb 15 12:41:01.581 [notice] Based on detected system memory, MaxMemInQueues is set to 1102 MB. You can override this by setting MaxMemInQueues by hand.
Feb 15 12:41:01.583 [notice] Opening Control listener on 127.0.0.1:9051
Feb 15 12:41:01.583 [notice] Opening OR listener on 0.0.0.0:9001
Feb 15 12:41:01.000 [warn] Your log may contain sensitive information - you're logging more than "notice". Don't log unless it serves an important reason. Overwrite the log afterwards.
Feb 15 12:41:01.000 [notice] Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
Feb 15 12:41:01.000 [notice] Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
Feb 15 12:41:01.000 [notice] Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Feb 15 12:41:01.000 [notice] We were built to run on a 64-bit CPU, with OpenSSL 1.0.1 or later, but with a version of OpenSSL that apparently lacks accelerated support for the NIST P-224 and P-256 groups. Building openssl with such support (using the enable-ec_nistp_64_gcc_128 option when configuring it) would make ECDH much faster.
Feb 15 12:41:01.000 [notice] Your Tor server's identity key fingerprint is 'polizeierziehung 5CE3AD8AD04ADE66C0037A3CF5F7F7A40D48A20B'
Feb 15 12:41:01.000 [notice] Bootstrapped 0%: Starting
Feb 15 12:41:01.000 [notice] The current consensus has no exit nodes. Tor can only build internal paths, such as paths to hidden services.
Feb 15 12:41:01.000 [warn] We need more descriptors: we have 0/7070, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 100% of exit bw (no exits in consensus) = 0% of path bw.)
Feb 15 12:41:01.000 [notice] Bootstrapped 45%: Asking for relay descriptors for internal paths
Feb 15 12:41:01.000 [notice] Guessed our IP address as 95.211.241.83 (source: 194.109.206.212).
Feb 15 12:41:02.000 [notice] Bootstrapped 50%: Loading relay descriptors
Feb 15 12:41:02.000 [notice] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 0/7070, and can only build 0% of likely paths. (We have 0% of guards 
bw, 0% of midpoint bw, and 100% of exit bw (no exits in consensus) = 0% of path bw.)
Feb 15 12:41:02.000 [notice] We'd like to launch a circuit to handle a connection, but we already have 32 general-purpose client circuits pending. Waiting until some finish.
Feb 15 12:41:02.000 [notice] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 0/7070, and can only build 0% of likely paths. (We have 0% of guards 
bw, 0% of midpoint bw, and 100% of exit bw (no exits in consensus) = 0% of path bw.)
[...]
Feb 15 12:41:07.000 [notice] I learned some more directory information, but not enough to build a circuit: We need more descriptors: we have 0/7070, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 100% of exit bw (no exits in consensus) = 0% of path bw.)
Feb 15 12:41:07.000 [notice] We now have enough directory information to build circuits.
Feb 15 12:41:07.000 [notice] Bootstrapped 80%: Connecting to the Tor network
Feb 15 12:41:07.000 [notice] Bootstrapped 85%: Finishing handshake with first hop
Feb 15 12:41:08.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
Feb 15 12:41:08.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Feb 15 12:41:08.000 [notice] Bootstrapped 100%: Done
Feb 15 12:41:12.000 [notice] Performing bandwidth self-test...done.
Feb 15 12:41:13.000 [notice] New control connection opened from 127.0.1.5.
Feb 15 12:47:54.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Feb 15 12:47:54.000 [notice] Read configuration file "/usr/local/etc/tor/torrc".
Feb 15 12:47:54.000 [notice] Tor 0.2.6.2-alpha (git-6cb1daf062df5252) opening log file.
Feb 15 12:47:54.000 [notice] Your Tor server's identity key fingerprint is 'polizeierziehung 5CE3AD8AD04ADE66C0037A3CF5F7F7A40D48A20B'
Feb 15 12:49:40.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Feb 15 12:49:40.000 [notice] Read configuration file "/usr/local/etc/tor/torrc".
Feb 15 12:49:40.000 [notice] Tor 0.2.6.2-alpha (git-6cb1daf062df5252) opening log file.
Feb 15 12:49:40.000 [notice] {GENERAL} Your Tor server's identity key fingerprint is 'polizeierziehung 5CE3AD8AD04ADE66C0037A3CF5F7F7A40D48A20B'
Feb 15 12:51:50.000 [notice] {GENERAL} Received reload signal (hup). Reloading config and resetting internal state.
Feb 15 12:51:50.000 [notice] {CONFIG} Read configuration file "/usr/local/etc/tor/torrc".
Feb 15 12:51:50.000 [notice] Tor 0.2.6.2-alpha (git-6cb1daf062df5252) opening log file.
Feb 15 12:51:50.000 [notice] {GENERAL} Your Tor server's identity key fingerprint is 'polizeierziehung 5CE3AD8AD04ADE66C0037A3CF5F7F7A40D48A20B'
Feb 15 16:18:48.000 [notice] {CIRC} No circuits are opened. Relaxed timeout for circuit 100 (a General-purpose client 1-hop circuit in state doing handshakes with channel state open) to 60000ms. However, it app
ears the circuit has timed out anyway. 1 guards are live.
Feb 15 18:41:03.000 [notice] {HEARTBEAT} Heartbeat: Tor's uptime is 6:00 hours, with 1024 circuits open. I've sent 11.68 GB and received 11.70 GB.
Feb 15 18:41:03.000 [notice] {HEARTBEAT} Average packaged cell fullness: 86.395%
Feb 15 18:41:03.000 [notice] {HEARTBEAT} TLS write overhead: 3%
Feb 15 18:41:03.000 [notice] {HEARTBEAT} Circuit handshake stats since last time: 29367/29367 TAP, 21000/21000 NTor.
Feb 16 00:41:03.000 [notice] {HEARTBEAT} Heartbeat: Tor's uptime is 12:00 hours, with 946 circuits open. I've sent 25.76 GB and received 25.78 GB.
Feb 16 00:41:03.000 [notice] {HEARTBEAT} Average packaged cell fullness: 84.401%
Feb 16 00:41:03.000 [notice] {HEARTBEAT} TLS write overhead: 3%
Feb 16 00:41:03.000 [notice] {HEARTBEAT} Circuit handshake stats since last time: 21818/21818 TAP, 18671/18671 NTor.
Feb 16 06:41:03.000 [notice] {HEARTBEAT} Heartbeat: Tor's uptime is 18:00 hours, with 884 circuits open. I've sent 36.23 GB and received 36.24 GB.
Feb 16 06:41:03.000 [notice] {HEARTBEAT} Average packaged cell fullness: 82.261%
Feb 16 06:41:03.000 [notice] {HEARTBEAT} TLS write overhead: 3%
Feb 16 06:41:03.000 [notice] {HEARTBEAT} Circuit handshake stats since last time: 20746/20746 TAP, 15523/15523 NTor.
Feb 16 08:31:35.000 [notice] {NET} The current consensus has no exit nodes. Tor can only build internal paths, such as paths to hidden services.
Feb 16 09:15:28.000 [notice] {CIRC} No circuits are opened. Relaxed timeout for circuit 163 (a General-purpose client 1-hop circuit in state doing handshakes with channel state open) to 60000ms. However, it appears the circuit has timed out anyway. 1 guards are live.
Feb 16 12:41:03.000 [notice] {HEARTBEAT} Heartbeat: Tor's uptime is 1 day 0:00 hours, with 926 circuits open. I've sent 47.99 GB and received 47.97 GB.
Feb 16 12:41:03.000 [notice] {HEARTBEAT} Average packaged cell fullness: 80.405%
Feb 16 12:41:03.000 [notice] {HEARTBEAT} TLS write overhead: 3%
Feb 16 12:41:03.000 [notice] {HEARTBEAT} Circuit handshake stats since last time: 26272/26272 TAP, 20201/20201 NTor.
Feb 16 18:41:03.000 [notice] {HEARTBEAT} Heartbeat: Tor's uptime is 1 day 6:00 hours, with 1118 circuits open. I've sent 62.63 GB and received 62.58 GB.
Feb 16 18:41:03.000 [notice] {HEARTBEAT} Average packaged cell fullness: 78.707%
Feb 16 18:41:03.000 [notice] {HEARTBEAT} TLS write overhead: 3%
Feb 16 18:41:03.000 [notice] {HEARTBEAT} Circuit handshake stats since last time: 31213/31213 TAP, 23753/23753 NTor.
Feb 16 22:12:01.000 [warn] {NET} We need more descriptors: we have 0/7082, and can only build 59% of likely paths. (We have 77% of guards bw, 77% of midpoint bw, and 100% of exit bw (no exits in consensus) = 59% of path bw.) [62 similar message(s) suppressed in last 60 seconds]
Feb 16 22:13:02.000 [notice] {NET} The current consensus has no exit nodes. Tor can only build internal paths, such as paths to hidden services.
Feb 16 22:13:02.000 [warn] {NET} We need more descriptors: we have 0/7082, and can only build 59% of likely paths. (We have 77% of guards bw, 77% of midpoint bw, and 100% of exit bw (no exits in consensus) = 59% of path bw.)
Feb 16 22:14:03.000 [warn] {NET} We need more descriptors: we have 0/7082, and can only build 59% of likely paths. (We have 77% of guards bw, 77% of midpoint bw, and 100% of exit bw (no exits in consensus) = 59% of path bw.)

At least the cached consensus seems to be fine:

_tor@onion1:~ % grep -c "s Exit" /var/db/tor/cached-consensus
1154

The debug log also shows:

_tor@onion1:~ % grep mmap /var/log/tor/debug.log 
Feb 15 12:41:01.000 [info] tor_mmap_t *tor_mmap_file(const char *)(): Could not open "/var/db/tor/cached-microdescs" for mmap(): No such file or directory
Feb 15 12:41:01.000 [info] tor_mmap_t *tor_mmap_file(const char *)(): Could not open "/var/db/tor/cached-extrainfo" for mmap(): No such file or directory

These files indeed do not exist but Tor could create them:

_tor@onion1:~ % ls -ld /var/db/tor/
drwx------  4 _tor  _tor  11 Feb 17 11:51 /var/db/tor/
_tor@onion1:~ % ls -l /var/db/tor/
total 1151
-rw-------  1 _tor  _tor    20441 Feb 11 15:10 cached-certs
-rw-------  1 _tor  _tor  1587237 Feb 17 11:51 cached-consensus
-rw-------  1 _tor  _tor    20879 Feb 17 11:50 cached-descriptors
-rw-------  1 _tor  _tor        0 Feb 17 11:50 cached-descriptors.new
-rw-------  1 _tor  _tor       58 Jan  6 16:47 fingerprint
drwx------  2 _tor  _tor        7 Feb 10 16:47 keys
-rw-------  1 _tor  _tor        0 Feb 15 12:41 lock
-rw-------  1 _tor  _tor     5008 Feb 17 01:51 state
drwx------  2 _tor  _tor        3 Feb 16 12:41 stats

The problem seems to be reproducible and I can provide additional log excerpts upon request.

As far as I can tell Tor is relaying traffic as expected.

My impression is that the complaints are a side-effect of 55ad54e014 which fixed #13718, but I haven't really looked into this yet.

Child Tickets

Change History (17)

comment:1 Changed 5 years ago by arma

Milestone: Tor: 0.2.6.x-final

Correct, it does look related to #13718.

The other thing to notice in this case is that it's a non-exit relay with no dirport, so it doesn't do microdescriptors, and it doesn't serve dir info so it stops fetching it after a while.

I wonder if teor tested that configuration.

comment:2 in reply to:  description Changed 5 years ago by arma

Replying to fk:

Feb 15 12:41:02.000 [notice] We'd like to launch a circuit to handle a connection, but we already have 32 general-purpose client circuits pending. Waiting until some finish.

Let me also call out this line as a "gosh it seems that we see that a lot in logs lately, I wonder what's up with that" situation. :(

comment:3 Changed 5 years ago by nickm

Keywords: tor-relay regression added

comment:4 Changed 5 years ago by nickm

If you encoutner this bug regularly, could we turn all the log_debug and log_info calls in the following functions into log_notice(), and tell me what they say? This may generate a huge amount of output.

The functions are:

  • compute_frac_paths_available()
  • count_usable_descriptors()

Both in nodelist.c

I'll keep looking for possible explanations.

comment:5 Changed 5 years ago by nickm

Is there anything interesting in the torrc files for the routers that are seeing this?

comment:6 Changed 5 years ago by nickm

From discussion on #tor-dev, it would appear:

  • That the np in have_consensus_path = ((nu > 0) ? ... should be nu.
  • That we should not warn about not having enough directory info in update_router_have_minimum_dir_info() when we have decided not to fetch directory info because of should_delay_dir_fetches() or directory_too_idle_to_fech_descriptors().

comment:7 Changed 5 years ago by nickm

Status: newneeds_review

I hypothesize that my branch "bug14918" in my public repository will fix this. Please test/review?

comment:8 Changed 5 years ago by fk

Log excerpt with the changes requested in comment 4:

Feb 17 17:02:10.000 [notice] Tor 0.2.6.2-alpha (git-6cb1daf062df5252) opening log file.
Feb 17 17:02:10.559 [notice] Tor v0.2.6.2-alpha (git-6cb1daf062df5252) running on ElectroBSD with Libevent 2.0.21-stable, OpenSSL 1.0.1j-freebsd and Zlib 1.2.8.
Feb 17 17:02:10.559 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Feb 17 17:02:10.559 [notice] This version is not a stable Tor release. Expect more bugs than usual.
Feb 17 17:02:10.559 [notice] Read configuration file "/usr/local/etc/tor/torrc".
Feb 17 17:02:10.565 [notice] Based on detected system memory, MaxMemInQueues is set to 1163 MB. You can override this by setting MaxMemInQueues by hand.
Feb 17 17:02:10.566 [notice] Opening Control listener on 127.0.0.1:9051
Feb 17 17:02:10.566 [notice] Opening OR listener on 0.0.0.0:9001
Feb 17 17:02:10.567 [warn] Fixing permissions on directory /var/db/tor
Feb 17 17:02:10.000 [notice] {GENERAL} Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
Feb 17 17:02:10.000 [notice] {GENERAL} Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
Feb 17 17:02:10.000 [notice] {CONFIG} Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Feb 17 17:02:10.000 [notice] {GENERAL} We were built to run on a 64-bit CPU, with OpenSSL 1.0.1 or later, but with a version of OpenSSL that apparently lacks accelerated support for the NIST P-224 and P-256 gro
ups. Building openssl with such support (using the enable-ec_nistp_64_gcc_128 option when configuring it) would make ECDH much faster.
Feb 17 17:02:10.000 [notice] {GENERAL} Your Tor server's identity key fingerprint is 'polizeierziehung 5CE3AD8AD04ADE66C0037A3CF5F7F7A40D48A20B'
Feb 17 17:02:10.000 [notice] {CONTROL} Bootstrapped 0%: Starting
Feb 17 17:02:10.000 [notice] {DIR} 7027 usable, 0 present (descs).
Feb 17 17:02:10.000 [notice] {DIR} 1149 usable, 0 present (desc exits).
Feb 17 17:02:10.000 [notice] {NET} exits: 0 present, 1149 usable
Feb 17 17:02:10.000 [notice] {NET} The current consensus has no exit nodes. Tor can only build internal paths, such as paths to hidden services.
Feb 17 17:02:10.000 [notice] {DIR} 1149 usable, 0 present (desc exits).
Feb 17 17:02:10.000 [notice] {NET} myexits: 0 present, 1149 usable
Feb 17 17:02:10.000 [notice] {DIR} 7027 usable, 0 present (descs).
Feb 17 17:02:10.000 [notice] {NET} myexits_unflagged (initial): 0 present, 7027 usable
Feb 17 17:02:10.000 [notice] {NET} myexits_unflagged (final): 0 present, 7027 usable
Feb 17 17:02:10.000 [notice] {NET} f_exit: 0.00, f_myexit: 0.00, f_myexit_unflagged: 0.00
Feb 17 17:02:10.000 [warn] {NET} We need more descriptors: we have 0/7027, and can only build 0% of likely paths. (We have 0% of guards bw, 0% of midpoint bw, and 100% of exit bw (no exits in consensus) = 0% of path bw.)
Feb 17 17:02:10.000 [notice] {CONTROL} Bootstrapped 45%: Asking for relay descriptors for internal paths
Feb 17 17:02:10.000 [notice] {GENERAL} Guessed our IP address as 95.211.241.83 (source: 194.109.206.212).
[...]
Feb 17 17:02:16.000 [notice] {CONTROL} Bootstrapped 90%: Establishing a Tor circuit
Feb 17 17:02:16.000 [notice] {GENERAL} Tor has successfully opened a circuit. Looks like client functionality is working.
Feb 17 17:02:16.000 [notice] {CONTROL} Bootstrapped 100%: Done
Feb 17 17:02:20.000 [notice] {DIR} 7027 usable, 6643 present (descs).
Feb 17 17:02:20.000 [notice] {DIR} 1149 usable, 1092 present (desc exits).
Feb 17 17:02:20.000 [notice] {NET} exits: 1092 present, 1149 usable
Feb 17 17:02:20.000 [notice] {DIR} 1149 usable, 1092 present (desc exits).
Feb 17 17:02:20.000 [notice] {NET} myexits: 1092 present, 1149 usable
Feb 17 17:02:20.000 [notice] {DIR} 7027 usable, 6643 present (descs).
Feb 17 17:02:20.000 [notice] {NET} myexits_unflagged (initial): 6643 present, 7027 usable
Feb 17 17:02:20.000 [notice] {NET} myexits_unflagged (final): 1352 present, 1736 usable
Feb 17 17:02:20.000 [notice] {NET} f_exit: 0.96, f_myexit: 0.96, f_myexit_unflagged: 0.87
Feb 17 17:02:20.000 [notice] {DIR} 7027 usable, 6739 present (descs).
Feb 17 17:02:20.000 [notice] {DIR} 1149 usable, 1114 present (desc exits).
Feb 17 17:02:20.000 [notice] {NET} exits: 1114 present, 1149 usable
Feb 17 17:02:20.000 [notice] {DIR} 1149 usable, 1114 present (desc exits).
Feb 17 17:02:20.000 [notice] {NET} myexits: 1114 present, 1149 usable
Feb 17 17:02:20.000 [notice] {DIR} 7027 usable, 6739 present (descs).
Feb 17 17:02:20.000 [notice] {NET} myexits_unflagged (initial): 6739 present, 7027 usable
Feb 17 17:02:20.000 [notice] {NET} myexits_unflagged (final): 1376 present, 1664 usable
Feb 17 17:02:20.000 [notice] {NET} f_exit: 0.97, f_myexit: 0.97, f_myexit_unflagged: 0.91
Feb 17 17:02:20.000 [notice] {DIR} 7027 usable, 6739 present (descs).
Feb 17 17:02:20.000 [notice] {DIR} 1149 usable, 1114 present (desc exits).
Feb 17 17:02:20.000 [notice] {NET} exits: 1114 present, 1149 usable
Feb 17 17:02:20.000 [notice] {DIR} 1149 usable, 1114 present (desc exits).
Feb 17 17:02:20.000 [notice] {NET} myexits: 1114 present, 1149 usable
Feb 17 17:02:20.000 [notice] {DIR} 7027 usable, 6739 present (descs).
Feb 17 17:02:20.000 [notice] {NET} myexits_unflagged (initial): 6739 present, 7027 usable
Feb 17 17:02:20.000 [notice] {NET} myexits_unflagged (final): 1376 present, 1664 usable
Feb 17 17:02:20.000 [notice] {NET} f_exit: 0.97, f_myexit: 0.97, f_myexit_unflagged: 0.91
Feb 17 17:02:23.000 [notice] {OR} Performing bandwidth self-test...done.

The torrc is pretty boring:

SocksPort 0

ORPort 9001

ControlPort 9051
HashedControlPassword [...]

Nickname polizeierziehung

RelayBandwidthRate  15000 KBytes
RelayBandwidthBurst 21000 KBytes

ContactInfo [...]

MyFamily [...]

LogMessageDomains 1
#Log [net]debug file /var/log/tor/debug.log

ExitPolicy reject *:*

I'm not seeing the issue with the same binary acting as an hidden service in a different jail on the same system. It also happens to cache micro descriptors:

_tor@onion2-hs:~ % ls -l /var/db/tor/
total 10664
-rw-------  1 _tor  _tor    20441 Feb 17 12:32 cached-certs
-rw-------  1 _tor  _tor  1380751 Feb 17 16:55 cached-microdesc-consensus
-rw-------  1 _tor  _tor  8467363 Feb 12 01:07 cached-microdescs
-rw-------  1 _tor  _tor  3515238 Feb 17 16:55 cached-microdescs.new
-rw-------  1 _tor  _tor        0 Feb 17 12:32 lock
-rw-------  1 _tor  _tor     2040 Feb 17 16:54 state

I just received comment 7 and will test the bug14918 branch in a couple of minutes.

comment:9 Changed 5 years ago by fk

It looks like the hypothesis was correct and adding 8eb3d81e6e8/bug14918 fixed this:

Feb 17 17:23:19.000 [notice] Tor 0.2.6.2-alpha (git-6cb1daf062df5252) opening log file.
Feb 17 17:23:19.735 [notice] Tor v0.2.6.2-alpha (git-6cb1daf062df5252) running on ElectroBSD with Libevent 2.0.21-stable, OpenSSL 1.0.1j-freebsd and Zlib 1.2.8.
Feb 17 17:23:19.735 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Feb 17 17:23:19.735 [notice] This version is not a stable Tor release. Expect more bugs than usual.
Feb 17 17:23:19.735 [notice] Read configuration file "/usr/local/etc/tor/torrc".
Feb 17 17:23:19.740 [notice] Based on detected system memory, MaxMemInQueues is set to 1146 MB. You can override this by setting MaxMemInQueues by hand.
Feb 17 17:23:19.742 [notice] Opening Control listener on 127.0.0.1:9051
Feb 17 17:23:19.742 [notice] Opening OR listener on 0.0.0.0:9001
Feb 17 17:23:19.742 [warn] Fixing permissions on directory /var/db/tor
Feb 17 17:23:19.000 [notice] {GENERAL} Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
Feb 17 17:23:19.000 [notice] {GENERAL} Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
Feb 17 17:23:19.000 [notice] {CONFIG} Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Feb 17 17:23:19.000 [notice] {GENERAL} We were built to run on a 64-bit CPU, with OpenSSL 1.0.1 or later, but with a version of OpenSSL that apparently lacks accelerated support for the NIST P-224 and P-256 groups. Building openssl with such support (using the enable-ec_nistp_64_gcc_128 option when configuring it) would make ECDH much faster.
Feb 17 17:23:20.000 [notice] {GENERAL} Your Tor server's identity key fingerprint is 'polizeierziehung 5CE3AD8AD04ADE66C0037A3CF5F7F7A40D48A20B'
Feb 17 17:23:20.000 [notice] {CONTROL} Bootstrapped 0%: Starting
Feb 17 17:23:20.000 [notice] {DIR} 7029 usable, 7028 present (descs).
Feb 17 17:23:20.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:20.000 [notice] {NET} exits: 1149 present, 1149 usable
Feb 17 17:23:20.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:20.000 [notice] {NET} myexits: 1149 present, 1149 usable
Feb 17 17:23:21.000 [notice] {DIR} 7029 usable, 7028 present (descs).
Feb 17 17:23:21.000 [notice] {NET} myexits_unflagged (initial): 7028 present, 7029 usable
Feb 17 17:23:21.000 [notice] {NET} myexits_unflagged (final): 1429 present, 1430 usable
Feb 17 17:23:21.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 1.00
Feb 17 17:23:21.000 [notice] {DIR} We now have enough directory information to build circuits.
Feb 17 17:23:21.000 [notice] {CONTROL} Bootstrapped 80%: Connecting to the Tor network
Feb 17 17:23:21.000 [notice] {GENERAL} Guessed our IP address as 95.211.241.83 (source: 193.23.244.244).
Feb 17 17:23:21.000 [notice] {DIR} 7029 usable, 7029 present (descs).
Feb 17 17:23:21.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:21.000 [notice] {NET} exits: 1149 present, 1149 usable
Feb 17 17:23:21.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:21.000 [notice] {NET} myexits: 1149 present, 1149 usable
Feb 17 17:23:21.000 [notice] {DIR} 7029 usable, 7029 present (descs).
Feb 17 17:23:21.000 [notice] {NET} myexits_unflagged (initial): 7029 present, 7029 usable
Feb 17 17:23:21.000 [notice] {NET} myexits_unflagged (final): 1429 present, 1429 usable
Feb 17 17:23:21.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 1.00
Feb 17 17:23:21.000 [notice] {DIR} 7029 usable, 7029 present (descs).
Feb 17 17:23:21.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:21.000 [notice] {NET} exits: 1149 present, 1149 usable
Feb 17 17:23:21.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:21.000 [notice] {NET} myexits: 1149 present, 1149 usable
Feb 17 17:23:21.000 [notice] {DIR} 7029 usable, 7029 present (descs).
Feb 17 17:23:21.000 [notice] {NET} myexits_unflagged (initial): 7029 present, 7029 usable
Feb 17 17:23:21.000 [notice] {NET} myexits_unflagged (final): 1429 present, 1429 usable
Feb 17 17:23:21.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 1.00
Feb 17 17:23:21.000 [notice] {OR} Self-testing indicates your ORPort is reachable from the outside. Excellent. Publishing server descriptor.
Feb 17 17:23:21.000 [notice] {CONTROL} Bootstrapped 85%: Finishing handshake with first hop
Feb 17 17:23:22.000 [notice] {DIR} 7029 usable, 7029 present (descs).
Feb 17 17:23:22.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:22.000 [notice] {NET} exits: 1149 present, 1149 usable
Feb 17 17:23:22.000 [notice] {DIR} 1149 usable, 1149 present (desc exits).
Feb 17 17:23:22.000 [notice] {NET} myexits: 1149 present, 1149 usable
Feb 17 17:23:22.000 [notice] {DIR} 7029 usable, 7029 present (descs).
Feb 17 17:23:22.000 [notice] {NET} myexits_unflagged (initial): 7029 present, 7029 usable
Feb 17 17:23:22.000 [notice] {NET} myexits_unflagged (final): 1429 present, 1429 usable
Feb 17 17:23:22.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 1.00
Feb 17 17:23:22.000 [notice] {CONTROL} Bootstrapped 90%: Establishing a Tor circuit
Feb 17 17:23:22.000 [notice] {GENERAL} Tor has successfully opened a circuit. Looks like client functionality is working.
Feb 17 17:23:22.000 [notice] {CONTROL} Bootstrapped 100%: Done
Feb 17 17:23:22.000 [notice] {DIR} 7078 usable, 6456 present (descs).
Feb 17 17:23:22.000 [notice] {DIR} 1153 usable, 1064 present (desc exits).
Feb 17 17:23:22.000 [notice] {NET} exits: 1064 present, 1153 usable
Feb 17 17:23:22.000 [notice] {DIR} 1153 usable, 1064 present (desc exits).
Feb 17 17:23:22.000 [notice] {NET} myexits: 1064 present, 1153 usable
Feb 17 17:23:22.000 [notice] {DIR} 7078 usable, 6456 present (descs).
Feb 17 17:23:22.000 [notice] {NET} myexits_unflagged (initial): 6456 present, 7078 usable
Feb 17 17:23:22.000 [notice] {NET} myexits_unflagged (final): 907 present, 1529 usable
Feb 17 17:23:22.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 1.00
Feb 17 17:23:26.000 [notice] {OR} Performing bandwidth self-test...done.
Feb 17 17:24:02.000 [notice] {CONTROL} New control connection opened from 127.0.1.5.

Thanks a lot.

comment:10 Changed 5 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

Thanks for reporting this, fk! Any day I can resolve something the same day it's reported, I am a happier guy.

Merging this patch into master.

comment:11 Changed 5 years ago by yawning

As a formality (post-merge), the changes in the branch look good to me.

comment:12 Changed 5 years ago by fk

Looks like there's another (presumably new) problem in compute_frac_paths_available().

The number of final exits present seems to consistently stay the same or go down and does not even stop at zero:

Feb 17 22:23:51.000 [notice] {DIR} 7117 usable, 5619 present (descs).
Feb 17 22:23:51.000 [notice] {DIR} 1152 usable, 911 present (desc exits).
Feb 17 22:23:51.000 [notice] {NET} exits: 911 present, 1152 usable
Feb 17 22:23:51.000 [notice] {DIR} 1152 usable, 911 present (desc exits).
Feb 17 22:23:51.000 [notice] {NET} myexits: 911 present, 1152 usable
Feb 17 22:23:51.000 [notice] {DIR} 7117 usable, 5619 present (descs).
Feb 17 22:23:51.000 [notice] {NET} myexits_unflagged (initial): 5619 present, 7117 usable
Feb 17 22:23:51.000 [notice] {NET} myexits_unflagged (final): 113 present, 1611 usable
Feb 17 22:23:51.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 1.00
Feb 17 22:25:52.000 [notice] {DIR} 7117 usable, 5619 present (descs).
Feb 17 22:25:52.000 [notice] {DIR} 1152 usable, 911 present (desc exits).
Feb 17 22:25:52.000 [notice] {NET} exits: 911 present, 1152 usable
Feb 17 22:25:52.000 [notice] {DIR} 1152 usable, 911 present (desc exits).
Feb 17 22:25:52.000 [notice] {NET} myexits: 911 present, 1152 usable
Feb 17 22:25:52.000 [notice] {DIR} 7117 usable, 5619 present (descs).
Feb 17 22:25:52.000 [notice] {NET} myexits_unflagged (initial): 5619 present, 7117 usable
Feb 17 22:25:52.000 [notice] {NET} myexits_unflagged (final): 113 present, 1611 usable
Feb 17 22:25:52.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 1.00
Feb 17 22:27:23.000 [notice] {DIR} 7020 usable, 4643 present (descs).
Feb 17 22:27:23.000 [notice] {DIR} 1151 usable, 763 present (desc exits).
Feb 17 22:27:23.000 [notice] {NET} exits: 763 present, 1151 usable
Feb 17 22:27:23.000 [notice] {DIR} 1151 usable, 763 present (desc exits).
Feb 17 22:27:23.000 [notice] {NET} myexits: 763 present, 1151 usable
Feb 17 22:27:23.000 [notice] {DIR} 7020 usable, 4643 present (descs).
Feb 17 22:27:23.000 [notice] {NET} myexits_unflagged (initial): 4643 present, 7020 usable
Feb 17 22:27:23.000 [notice] {NET} myexits_unflagged (final): -758 present, 1619 usable
Feb 17 22:27:23.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 0.99
Feb 17 22:27:53.000 [notice] {DIR} 7020 usable, 4643 present (descs).
Feb 17 22:27:53.000 [notice] {DIR} 1151 usable, 763 present (desc exits).
Feb 17 22:27:53.000 [notice] {NET} exits: 763 present, 1151 usable
Feb 17 22:27:53.000 [notice] {DIR} 1151 usable, 763 present (desc exits).
Feb 17 22:27:53.000 [notice] {NET} myexits: 763 present, 1151 usable
Feb 17 22:27:53.000 [notice] {DIR} 7020 usable, 4643 present (descs).
Feb 17 22:27:53.000 [notice] {NET} myexits_unflagged (initial): 4643 present, 7020 usable
Feb 17 22:27:53.000 [notice] {NET} myexits_unflagged (final): -758 present, 1619 usable
[...]
Feb 18 11:14:13.000 [notice] {DIR} 6945 usable, 692 present (descs).
Feb 18 11:14:13.000 [notice] {DIR} 1146 usable, 121 present (desc exits).
Feb 18 11:14:13.000 [notice] {NET} exits: 121 present, 1146 usable
Feb 18 11:14:13.000 [notice] {DIR} 1146 usable, 121 present (desc exits).
Feb 18 11:14:13.000 [notice] {NET} myexits: 121 present, 1146 usable
Feb 18 11:14:13.000 [notice] {DIR} 6945 usable, 692 present (descs).
Feb 18 11:14:13.000 [notice] {NET} myexits_unflagged (initial): 692 present, 6945 usable
Feb 18 11:14:13.000 [notice] {NET} myexits_unflagged (final): -4641 present, 1612 usable
Feb 18 11:14:13.000 [notice] {NET} f_exit: 1.00, f_myexit: 1.00, f_myexit_unflagged: 0.98

comment:13 Changed 5 years ago by yawning

Resolution: fixed
Status: closedreopened

Ugh, at least this is easy I think.

  /* All nodes with exit flag in ExitNodes option */
  count_usable_descriptors(&np, &nu, myexits, consensus, options, now,
                           options->ExitNodes, USABLE_DESCRIPTOR_EXIT_ONLY);
  log_debug(LD_NET,
            "%s: %d present, %d usable",
            "myexits",
            np,
            nu);

  /* Now compute the nodes in the ExitNodes option where which we don't know
   * what their exit policy is, or we know it permits something. */
  count_usable_descriptors(&np, &nu, myexits_unflagged,
                           consensus, options, now,
                           options->ExitNodes, USABLE_DESCRIPTOR_ALL);
  log_debug(LD_NET,
            "%s: %d present, %d usable",
            "myexits_unflagged (initial)",
            np,
            nu);

  SMARTLIST_FOREACH_BEGIN(myexits_unflagged, const node_t *, node) {
    if (node_has_descriptor(node) && node_exit_policy_rejects_all(node)) {
      SMARTLIST_DEL_CURRENT(myexits_unflagged, node);
      /* this node is not actually an exit */
      np--;
      /* this node is unusable as an exit */
      nu--;
    }
  } SMARTLIST_FOREACH_END(node);

  log_debug(LD_NET,
            "%s: %d present, %d usable",
            "myexits_unflagged (final)",
            np,
            nu);

With your torrc (and most torrcs that aren't doing testing or tinfoil hattery), options->ExitNodes is NULL, so the 2nd count_usable_descriptors is returning every single router in the consensus, with hilarious results.

Give me a bit and I'll fix this.

comment:14 Changed 5 years ago by yawning

https://github.com/Yawning/tor/compare/bug14918

There's something broken with logging in update_router_have_minimum_dir_info as well, because of the rate limiter, stale logging information is printed because the snprintf doesn't end up being called. This should probably be fixed because seeing everything set to 0, is misleading and annoying as hell.

comment:15 Changed 5 years ago by fk

Looks good to me so far:

_tor@onion1:~ %  grep exits: /var/log/tor/notices | tail -n 30
Feb 18 13:18:17.000 [notice] {NET} exits: 1033 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1048 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1048 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1048 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1063 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1063 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1078 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1078 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1094 present, 1140 usable
Feb 18 13:18:17.000 [notice] {NET} exits: 1094 present, 1140 usable
Feb 18 13:18:18.000 [notice] {NET} exits: 1094 present, 1140 usable
Feb 18 13:18:18.000 [notice] {NET} exits: 1111 present, 1140 usable
Feb 18 13:18:18.000 [notice] {NET} exits: 1111 present, 1140 usable
Feb 18 13:18:20.000 [notice] {NET} exits: 1111 present, 1140 usable
Feb 18 13:18:20.000 [notice] {NET} exits: 1127 present, 1140 usable
Feb 18 13:18:20.000 [notice] {NET} exits: 1127 present, 1140 usable
Feb 18 13:20:07.000 [notice] {NET} exits: 1127 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1127 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1127 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1130 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1130 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1133 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1133 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1133 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1140 present, 1140 usable
Feb 18 13:20:19.000 [notice] {NET} exits: 1140 present, 1140 usable
Feb 18 13:21:57.000 [notice] {NET} exits: 1140 present, 1140 usable
Feb 18 13:22:08.000 [notice] {NET} exits: 1140 present, 1140 usable
Feb 18 13:24:09.000 [notice] {NET} exits: 1140 present, 1140 usable
Feb 18 13:26:10.000 [notice] {NET} exits: 1140 present, 1140 usable

comment:16 Changed 5 years ago by yawning

Status: reopenedneeds_review

Yay. I added another commit onto the branch that fixes the " I learned some more directory information, but not enough to build a circuit:" log output never getting updated during the course of a normal bootstrap.

Tagging this as needs_review.

comment:17 Changed 5 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

lgtm; merged!

Note: See TracTickets for help on using tickets.