Unreachable relays launch multiple testing circuits per second
When I start a relay behind a NAT with:
tor ORPort 12345 PublishServerDescriptor 0 Log "info stderr"
I see it launch multiple testing circuits every second. This places a lot of load on the network: it should use exponential backoff instead.
We wanted to fix things like this as part of #4580 (moved) or #8625 (moved), but it seems we missed this case. Maybe we need to do exponential backoff at a lower level than directory requests?
Here are the log messages for one second:
Jul 11 19:07:20.000 [info] circuit_finish_handshake: Finished building circuit hop:
Jul 11 19:07:20.000 [info] internal circ (length 3, last hop Unnamed): $3E13E2EB87CCF5690564EE33E9F9F9F80B229FBB(open) $34D2E3C853C6C60A5CCD93E363CD524BA962D3D6(open) $4345CA43B1F4E1C08271F8FA907B4AE890591111(closed)
Jul 11 19:07:20.000 [info] circuit_send_next_onion_skin: Sending extend relay cell.
Jul 11 19:07:20.000 [info] consider_testing_reachability: Testing reachability of my ORPort: 124.171.199.202:12345.
Jul 11 19:07:20.000 [info] onion_pick_cpath_exit: Using requested exit node '$4345CA43B1F4E1C08271F8FA907B4AE890591111~Unnamed at 124.171.199.202'
Jul 11 19:07:20.000 [info] extend_info_from_node: Not including the ed25519 ID for $7202A9449EC084A305EB19A2A2A0E245FA8C111E~jonasBebe2 at 193.200.241.195, since it won't be able to authenticate it.
Jul 11 19:07:20.000 [info] extend_info_from_node: Not including the ed25519 ID for $CA618B8FB8FDF1C670BA7139B1E3EFCE25771551~bentleywashere3 at 198.199.90.205, since it won't be able to authenticate it.
Jul 11 19:07:20.000 [info] circuit_handle_first_hop: Next router is [scrubbed]: Not connected. Connecting.
Jul 11 19:07:20.000 [info] connection_or_set_identity_digest: Set identity digest for 0x7fcefb6f1cd0 ([scrubbed]): 7202A9449EC084A305EB19A2A2A0E245FA8C111E <unset>.
Jul 11 19:07:20.000 [info] connection_or_set_identity_digest: (Previously: 0000000000000000000000000000000000000000 <unset>)
Jul 11 19:07:20.000 [info] channel_tls_process_versions_cell: Negotiated version 4 with [scrubbed]:443; Sending cells: CERTS
Jul 11 19:07:20.000 [info] connection_or_client_learned_peer_id: learned peer id for 0x7fcefaf87090 ([scrubbed]): 650ABAB06345EEC29BB0B5322C27DC6E5E888019, <null>
Jul 11 19:07:20.000 [info] channel_tls_process_certs_cell: Got some good certificates from [scrubbed]:443: Authenticated it with RSA
Jul 11 19:07:20.000 [info] channel_tls_process_auth_challenge_cell: Got an AUTH_CHALLENGE cell from [scrubbed]:443: Sending authentication type 1
Jul 11 19:07:20.000 [info] circuit_send_next_onion_skin: First hop: finished sending CREATE cell to '$650ABAB06345EEC29BB0B5322C27DC6E5E888019~supc0re at 217.160.15.198'
Jul 11 19:07:20.000 [info] channel_tls_process_netinfo_cell: Got good NETINFO cell from [scrubbed]:443; OR connection is now open, using protocol version 4. Its ID digest is 650ABAB06345EEC29BB0B5322C27DC6E5E888019. Our address is apparently 124.171.199.202.
Jul 11 19:07:20.000 [info] circuit_expire_building: Abandoning circ 198 37.187.3.106:443:3622949943 (state 0,0:doing handshakes, purpose 18, len 3)
Jul 11 19:07:20.000 [info] internal circ (length 3, last hop Unnamed): $597422ADDADAF5FB2727369B7EFC7AA76B89D613(open) $E7578F3484C8ABD5FB3130E31F30C167206BCA7E(open) $4345CA43B1F4E1C08271F8FA907B4AE890591111(waiting for keys)
Jul 11 19:07:20.000 [info] circuit_testing_failed: Our testing circuit (to see if your ORPort is reachable) has failed. I'll try again later.
Jul 11 19:07:20.000 [info] circuit_finish_handshake: Finished building circuit hop:
Jul 11 19:07:20.000 [info] internal circ (length 3, last hop Unnamed): $650ABAB06345EEC29BB0B5322C27DC6E5E888019(open) $45D6A70CAEC4A2C2FCE46A127E461FF852A41280(closed) $4345CA43B1F4E1C08271F8FA907B4AE890591111(closed)
Jul 11 19:07:20.000 [info] circuit_send_next_onion_skin: Sending extend relay cell.