Trac issueshttps://gitlab.torproject.org/legacy/trac/-/issues2020-06-13T15:46:45Zhttps://gitlab.torproject.org/legacy/trac/-/issues/32108tor can overrun its accountingmax if it enters soft hibernation first2020-06-13T15:46:45ZRoger Dingledinetor can overrun its accountingmax if it enters soft hibernation firstI'll put the punchline first: second_elapsed_callback(), which is where we check if it's time to go dormant for hibernation, is no longer called when we've entered soft hibernation.
I assume this is because of the new "periodic event fl...I'll put the punchline first: second_elapsed_callback(), which is where we check if it's time to go dormant for hibernation, is no longer called when we've entered soft hibernation.
I assume this is because of the new "periodic event flag" feature, where we try to avoid calling callbacks when we're in a state that won't need them. See the "online and active" note here:
```
/* This is a legacy catch-all callback that runs once per second if
* we are online and active. */
CALLBACK(second_elapsed, NET_PARTICIPANT,
FL(NEED_NET)|FL(RUN_ON_DISABLE)),
```
The impact is limited, since we stop accepting new connections and new circuits when we enter soft hibernation, but it can still be bad: existing connections and circuits can last for a long time and use a lot of bandwidth.
A secondary impact is that accounting_run_housekeeping() never gets called, which means that the state file never gets updated after we've entered soft hibernation, which means these bandwidth overspends are never recorded to disk.
I think the bug went in during commit 4bf79fa4f which is part of Tor 0.4.0.1-alpha.
The PERIODIC_EVENT_FLAG_NEED_NET flag (what FL(NEED_NET) expands into) checks net_is_disabled(), but there is another function right after net_is_disabled in netstatus.c called net_is_completely_disabled(), and the only difference is that it checks we_are_fully_hibernating() vs we_are_hibernating().
I confirmed the overall bug happens in practice: there's a relay operator in #tor who hit soft hibernation, and then saw his tor proceed to use more bytes than expected. I had him do a 'gdb attach' to his tor and break on 'second_elapsed_callback' and the function never got called.
It seems like the immediate fix, and best backport plan, would be to resume calling second_elapsed_callback even when net_is_disabled(). The longer term plan can be to audit our calls to net_is_disabled() and net_is_completely_disabled() and we_are_hibernating(), with an eye towards "should we be doing this behavior while soft hibernating", and see what other bugs we find.Tor: 0.4.0.x-finalRoger DingledineRoger Dingledinehttps://gitlab.torproject.org/legacy/trac/-/issues/31810Bug: ../src/lib/process/process_unix.c:265: process_unix_exec: Assertion line...2020-06-13T15:45:51ZTracBug: ../src/lib/process/process_unix.c:265: process_unix_exec: Assertion line should be unreached failed; aborting.I am on Debian Buster, x86_64, trying to run Tor (installed from deb.torproject.org).
```
Sep 20 00:18:33 jennis Tor[1481]: Tor 0.4.1.5 running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1c, Zlib 1.2.11, Liblzma 5.2.4, and Libzst...I am on Debian Buster, x86_64, trying to run Tor (installed from deb.torproject.org).
```
Sep 20 00:18:33 jennis Tor[1481]: Tor 0.4.1.5 running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1c, Zlib 1.2.11, Liblzma 5.2.4, and Libzstd 1.3.8.
Sep 20 00:18:33 jennis Tor[1481]: Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Sep 20 00:18:33 jennis Tor[1481]: Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Sep 20 00:18:33 jennis Tor[1481]: Read configuration file "/etc/tor/torrc".
Sep 20 00:18:33 jennis Tor[1481]: Opening Socks listener on 127.0.0.1:9050
Sep 20 00:18:33 jennis Tor[1481]: Opened Socks listener on 127.0.0.1:9050
Sep 20 00:18:33 jennis Tor[1481]: Opening DNS listener on 127.0.0.1:53
Sep 20 00:18:33 jennis Tor[1481]: Opened DNS listener on 127.0.0.1:53
Sep 20 00:18:33 jennis Tor[1481]: Opening DNS listener on [::1]:53
Sep 20 00:18:33 jennis Tor[1481]: Opened DNS listener on [::1]:53
Sep 20 00:18:33 jennis Tor[1481]: Opening Transparent pf/netfilter listener on 127.0.0.1:9040
Sep 20 00:18:33 jennis Tor[1481]: Opened Transparent pf/netfilter listener on 127.0.0.1:9040
Sep 20 00:18:33 jennis Tor[1481]: Opening Transparent pf/netfilter listener on [::1]:9040
Sep 20 00:18:33 jennis Tor[1481]: Opened Transparent pf/netfilter listener on [::1]:9040
Sep 20 00:18:33 jennis Tor[1481]: Opening Control listener on 127.0.0.1:9051
Sep 20 00:18:33 jennis Tor[1481]: Opened Control listener on 127.0.0.1:9051
Sep 20 00:18:33 jennis Tor[1481]: Parsing GEOIP IPv4 file /usr/share/tor/geoip.
Sep 20 00:18:33 jennis Tor[1482]: tor_assertion_failed_(): Bug: ../src/lib/process/process_unix.c:265: process_unix_exec: Assertion line should be unreached failed; aborting. (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: Assertion line should be unreached failed in process_unix_exec at ../src/lib/process/process_unix.c:265: . Stack trace: (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(log_backtrace_impl+0x46) [0x556988adb106] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(tor_assertion_failed_+0x147) [0x556988ad6297] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(process_unix_exec+0x274) [0x556988ab06c4] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(process_exec+0x5b) [0x556988aaea7b] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(pt_configure_remaining_proxies+0x563) [0x5569889a0093] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(set_options+0x18ba) [0x556988a5405a] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(options_init_from_string+0x382) [0x556988a55292] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(options_init_from_torrc+0x38a) [0x556988a5581a] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(tor_init+0x3c7) [0x556988927567] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(tor_run_main+0xb4) [0x556988927e74] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(tor_main+0x3a) [0x55698892638a] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(main+0x19) [0x556988925f49] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f49509c609b] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1482]: Bug: /usr/bin/tor(_start+0x2a) [0x556988925f9a] (on Tor 0.4.1.5 )
Sep 20 00:18:33 jennis Tor[1481]: Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
Sep 20 00:18:33 jennis Tor[1481]: Bootstrapped 0% (starting): Starting
Sep 20 00:18:33 jennis Tor[1481]: Starting with guard context "default"
Sep 20 00:18:33 jennis Tor[1481]: Signaled readiness to systemd
Sep 20 00:18:34 jennis Tor[1481]: Bootstrapped 5% (conn): Connecting to a relay
Sep 20 00:18:34 jennis Tor[1481]: Opening Control listener on /run/tor/control
Sep 20 00:18:34 jennis Tor[1481]: Opened Control listener on /run/tor/control
Sep 20 00:18:34 jennis Tor[1481]: Bootstrapped 10% (conn_done): Connected to a relay
Sep 20 00:18:34 jennis Tor[1481]: Bootstrapped 14% (handshake): Handshaking with a relay
Sep 20 00:18:34 jennis Tor[1481]: Bootstrapped 15% (handshake_done): Handshake with a relay done
Sep 20 00:18:34 jennis Tor[1481]: Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits
Sep 20 00:18:34 jennis Tor[1481]: Bootstrapped 90% (ap_handshake_done): Handshake finished with a relay to build circuits
Sep 20 00:18:34 jennis Tor[1481]: Bootstrapped 95% (circuit_create): Establishing a Tor circuit
Sep 20 00:18:35 jennis Tor[1481]: Bootstrapped 100% (done): Done
```
**Trac**:
**Username**: ParckwartTor: 0.4.0.x-finalAlexander Færøyahf@torproject.orgAlexander Færøyahf@torproject.org