[tor-relays] Relay not connecting

Sat Jan 6 18:52:14 UTC 2024

I manage the two following exit relays:

* https://metrics.torproject.org/rs.html#details/25FC41154DCB2CAE3ABD74A8DFCD5B90D2CFFD57
* https://metrics.torproject.org/rs.html#details/3B85067588C3F017D5CCF7D8F65B5881B7D4C97C

They are both on the same IP and servers. A few hours ago they lost contact even though I have both Apache and I2P servers on the same machine that are reachable. The weird log messages seem to go back to Dec 18, after a restart:

```
Dec 18 07:49:47 a-n-o-n-y-m-e Tor-Alberta[904715]: Bootstrapped 100% (done): Done
Dec 18 07:54:18 a-n-o-n-y-m-e Tor-Alberta[904715]: Your computer is too slow to handle this many circuit creation requests! Please consider using the MaxAdvertisedBandwidth config option or choosing a more restricted exit policy.
Dec 18 07:57:11 a-n-o-n-y-m-e Tor-Alberta[904715]: Your computer is too slow to handle this many circuit creation requests! Please consider using the MaxAdvertisedBandwidth config option or choosing a more restricted exit policy. [14254 similar message(s) suppressed in last 180 seconds]
```

There are a few more of these messages appearing afterward (My bandwidth is unlimited). This is the typical Heartbeat that comes afterward:

```
Dec 18 13:49:42 a-n-o-n-y-m-e Tor-Alberta[904715]: Heartbeat: Tor's uptime is 6:00 hours, with 476 circuits open. I've sent 30.87 GB and received 9.04 GB. I've received 13401 connections on IPv4 and 0 on IPv6. I've made 46754 connections with IPv4 and 0 with IPv6.
Dec 18 13:49:42 a-n-o-n-y-m-e Tor-Alberta[904715]: While not bootstrapping, fetched this many bytes: 6412201 (server descriptor fetch); 1424 (server descriptor upload); 376002 (consensus network-status fetch); 57564 (microdescriptor fetch)
Dec 18 13:49:42 a-n-o-n-y-m-e Tor-Alberta[904715]: Circuit handshake stats since last time: 8/8 TAP, 1356688/6457307 NTor.
Dec 18 13:49:42 a-n-o-n-y-m-e Tor-Alberta[904715]: Since startup we initiated 0 and received 0 v1 connections; initiated 0 and received 0 v2 connections; initiated 0 and received 0 v3 connections; initiated 0 and received 429 v4 connections; initiated 285 and received 11137 v5 connections.
Dec 18 13:49:42 a-n-o-n-y-m-e Tor-Alberta[904715]: Heartbeat: DoS mitigation since startup: 0 circuits killed with too many cells, 0 circuits rejected, 0 marked addresses, 0 marked addresses for max queue, 0 same address concurrent connections rejected, 0 connections rejected, 0 single hop clients refused, 0 INTRODUCE2 rejected.
```

Then I have this kind of message appearing:

```
Dec 18 14:13:23 a-n-o-n-y-m-e Tor-Alberta[904715]: No circuits are opened. Relaxed timeout for circuit 4487 (a Measuring circuit timeout 3-hop circuit in state doing handshakes with channel state open) to 60000ms. However, it appears the circuit has timed out anyway. [4 similar message(s) suppressed in last 3300 seconds]
```

Then a few days later, this bug report:

```
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: tor_bug_occurred_(): Bug: ../src/core/or/conflux.c:567: conflux_pick_first_leg: Non-fatal assertion !(smartlist_len(cfx->legs) <= 0) failed. (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug: Tor 0.4.8.10: Non-fatal assertion !(smartlist_len(cfx->legs) <= 0) failed in conflux_pick_first_leg at ../src/core/or/conflux.c:567. Stack trace: (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(log_backtrace_impl+0x5b) [0x55651f95b37b] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(tor_bug_occurred_+0x18a) [0x55651f97294a] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(conflux_decide_next_circ+0x40e) [0x55651fa12afe] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(circuit_get_package_window+0x75) [0x55651fa12ec5] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(+0x9ed63) [0x55651f908d63] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(connection_edge_package_raw_inbuf+0xae) [0x55651f90b80e] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(connection_edge_process_inbuf+0x6f) [0x55651fa2b9df] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(+0x1c2fb4) [0x55651fa2cfb4] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(+0x73ffc) [0x55651f8ddffc] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libevent-2.1.so.7(+0x1ff58) [0x7fcee899bf58] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libevent-2.1.so.7(event_base_loop+0x577) [0x7fcee899d8a7] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(do_main_loop+0x127) [0x55651f8de7c7] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(tor_run_main+0x215) [0x55651f8e2805] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(tor_main+0x4d) [0x55651f8e2c6d] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(main+0x1d) [0x55651f8d4dcd] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7fcee80a8d90] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7fcee80a8e40] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(_start+0x25) [0x55651f8d4e25] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_pick_first_leg(): Bug: Matching client sets: (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_log_set(): Bug: Conflux 566550141B144136: 0 linked, 0 launched. Delivered: 75; teardown: 0; Current: (nil), Previous: (nil) (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_pick_first_leg(): Bug: Matching server sets: (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_log_set(): Bug: Conflux 566550141B144136: 0 linked, 0 launched. Delivered: 75; teardown: 0; Current: (nil), Previous: (nil) (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_pick_first_leg(): Bug: End conflux set dump (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: circuit_get_package_window(): Bug: Conflux has no circuit to send on. Circuit 0x556536e76c20 idx 138 marked at line ../src/core/or/command.c:663 (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: tor_bug_occurred_(): Bug: ../src/core/or/conflux.c:567: conflux_pick_first_leg: Non-fatal assertion !(smartlist_len(cfx->legs) <= 0) failed. (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug: Tor 0.4.8.10: Non-fatal assertion !(smartlist_len(cfx->legs) <= 0) failed in conflux_pick_first_leg at ../src/core/or/conflux.c:567. Stack trace: (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(log_backtrace_impl+0x5b) [0x55651f95b37b] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(tor_bug_occurred_+0x18a) [0x55651f97294a] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(conflux_decide_next_circ+0x40e) [0x55651fa12afe] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(circuit_get_package_window+0x75) [0x55651fa12ec5] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(+0x9ed63) [0x55651f908d63] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(connection_edge_package_raw_inbuf+0xae) [0x55651f90b80e] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(connection_edge_process_inbuf+0x6f) [0x55651fa2b9df] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(+0x1c34dd) [0x55651fa2d4dd] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(+0x73ffc) [0x55651f8ddffc] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libevent-2.1.so.7(+0x1ff58) [0x7fcee899bf58] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libevent-2.1.so.7(event_base_loop+0x577) [0x7fcee899d8a7] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(do_main_loop+0x127) [0x55651f8de7c7] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(tor_run_main+0x215) [0x55651f8e2805] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(tor_main+0x4d) [0x55651f8e2c6d] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(main+0x1d) [0x55651f8d4dcd] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7fcee80a8d90] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7fcee80a8e40] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: Bug:     /usr/bin/tor(_start+0x25) [0x55651f8d4e25] (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_pick_first_leg(): Bug: Matching client sets: (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_log_set(): Bug: Conflux 566550141B144136: 0 linked, 0 launched. Delivered: 75; teardown: 0; Current: (nil), Previous: (nil) (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_pick_first_leg(): Bug: Matching server sets: (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_log_set(): Bug: Conflux 566550141B144136: 0 linked, 0 launched. Delivered: 75; teardown: 0; Current: (nil), Previous: (nil) (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: conflux_pick_first_leg(): Bug: End conflux set dump (on Tor 0.4.8.10 )
Dec 21 15:18:48 a-n-o-n-y-m-e Tor-Alberta[904715]: circuit_get_package_window(): Bug: Conflux has no circuit to send on. Circuit 0x556536e76c20 idx 138 marked at line ../src/core/or/command.c:663 (on Tor 0.4.8.10 )
```

It is then an alternation of these three last messages (Heartbeat + "No circuits are opened" + bug) until yesterday where I get a series of these messages:

```
Jan  5 21:58:59 a-n-o-n-y-m-e Tor-Alberta[904715]: Failed to find node for hop #1 of our path. Discarding this circuit.
Jan  5 21:58:59 a-n-o-n-y-m-e Tor-Alberta[904715]: Our circuit 0 (id: 355722) died due to an invalid selected path, purpose Unlinked conflux circuit. This may be a torrc configuration issue, or a bug.
```

At this point, I learned that my relays were down via Tor Weather.

I restarted the relays - even rebooted the whole server - and both relays seem to be unable to connect to the network. Here's a sample:

```
Jan  6 09:44:46 a-n-o-n-y-m-e Tor-Alberta[5621]: 254 connections have failed:
Jan  6 09:44:46 a-n-o-n-y-m-e Tor-Alberta[5621]:  254 connections died in state connect()ing with SSL state (No SSL object)
Jan  6 09:44:46 a-n-o-n-y-m-e Tor-Alberta[5621]: Problem bootstrapping. Stuck at 5% (conn): Connecting to a relay. (Connection timed out; TIMEOUT; count 256; recommendation warn; host 65369D044C659CD299E35763914FFD0FC9AD4509 at 92.205.161.164:80)
```

I also have a bridge on this server (different IP) and it seems OK ( https://metrics.torproject.org/rs.html#details/7CEB9D16C5218FE1A9BAB8E8A6EA9471D2E1F9B8 ). Last messages after the server reboot are:

```
Jan  6 08:34:17 a-n-o-n-y-m-e Tor-Nestor[998]: Bootstrapped 100% (done): Done
Jan  6 08:35:21 a-n-o-n-y-m-e Tor-Nestor[998]: Performing bandwidth self-test...done.
Jan  6 09:54:22 a-n-o-n-y-m-e Tor-Nestor[998]: No circuits are opened. Relaxed timeout for circuit 527 (a Measuring circuit timeout 3-hop circuit in state doing handshakes with channel state open) to 60000ms. However, it appears the circuit has timed out anyway.
```

I have stopped both relays until I figure out what is going on. Help would be appreciated.