Relay directory failures and logging are too aggressive
As mentioned in #18348 (moved), when a relay exhausts the available directory authorities, it now produces the below warning. It seems there are three points to consider when taken in the context of a relay:
-
The actual log message is not correct, this completely unrelated to the firewall/reachability logic
-
I'm not certain, but I believe this is likely a normal situation on the network
-
Logging this at warn seems overly aggressive for something a user can't control
-
and 2) are actually the same point. See the attached debug log extract (including some additional messages I added). Nearly all the dir auths are marked as down due to 304 responses. Should tor be less aggressive about avoiding a directory authority after a 304? I worry, if this is normal behavior, then the network's load is not be distributed among all the directories. It seems like they're being picked off, one-by-one. Especially when this is in the logs - unless I'm reading it wrong they're identical requests despite the first one succeeding (possibly another bug?):
--
Feb 20 05:26:37.000 [info] directory_send_command: Downloading consensus from 128.31.0.39:9131 using /tor/status-vote/current/consensus-microdesc/0232AF+14C131+23D15D+49015F+805509+D586D1+E8A9C4+ED03BB+EFCBE7.z
Feb 20 05:26:39.000 [debug] connection_dir_client_reached_eof: Received response from directory server '128.31.0.39:9131': 200 "OK" (purpose: 14)
--
Feb 20 05:27:37.000 [info] directory_send_command: Downloading consensus from 131.188.40.189 using /tor/status-vote/current/consensus-microdesc/0232AF+14C131+23D15D+49015F+805509+D586D1+E8A9C4+ED03BB+EFCBE7.z
Feb 20 05:27:38.000 [debug] connection_dir_client_reached_eof: Received response from directory server '131.188.40.189:80': 304 "Not modified" (purpose: 14)
Feb 20 05:29:37.000 [info] directory_send_command: Downloading consensus from 199.254.238.52 using /tor/status-vote/current/consensus-microdesc/0232AF+14C131+23D15D+49015F+805509+D586D1+E8A9C4+ED03BB+EFCBE7.z
Feb 20 05:29:41.000 [debug] connection_dir_client_reached_eof: Received response from directory server '199.254.238.52:80': 304 "Not modified" (purpose: 14)
In the attached log, router_set_status() records when a node is marked down. The preceeding lines should say why. router_pick_trusteddirserver_impl() records which nodes we disqualified when we want to send a new request.
Scary backtrace:
[warn] router_picked_poor_directory_log: Bug: Firewall denied all OR and Dir addresses for all relays when searching for a directory. (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: Node search initiated by. Stack trace: (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x1157e08 <log_backtrace+0x48> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x10af86b <hid_serv_responsible_for_desc_id+0xdeb> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x10a6a86 <router_pick_trusteddirserver+0x76> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x1126183 <directory_get_from_dirserver+0x293> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x10ad45a <launch_descriptor_downloads+0x4ba> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x10ad21a <launch_descriptor_downloads+0x27a> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x10adb6b <update_consensus_router_descriptor_downloads+0x6cb> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x10ac7f6 <update_all_descriptor_downloads+0x66> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x10602c8 <directory_info_has_arrived+0x48> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x1128890 <connection_dir_reached_eof+0x1160> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x1107f5b <connection_handle_read+0xb3b> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x105f044 <connection_add_impl+0x214> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x801aa538e <event_base_loop+0x81e> at /usr/local/lib/libevent-2.0.so.5 (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x1060cc5 <do_main_loop+0x5c5> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x1062fcf <tor_main+0xdf> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x105ed49 <main+0x19> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)
[warn] Bug: 0x105ec41 <_start+0x1a1> at /usr/local/bin/tor (on Tor 0.2.8.1-alpha-dev 1f679d4ae11cd976)