daily abort in tor 0.4.5.7, 0.4.6.1-alpha, and 0.4.6.2-alpha [Assertion end > start failed in create_voting_schedule]
Summary
I was running 0.4.5.2-alpha with no problems. After I upgraded tor to 0.4.6.1-alpha, tor crashed in under 24 hours. After the third such crash, I switched to 0.4.5.7, naively expecting it to be a "stable" release. That version, too, crashes with the same set of error messages. I have now upgraded to 0.4.6.2-alpha, and the same bug is present. I am running tor on a FreeBSD 11.4-STABLE system.
Steps to reproduce:
- Install one of the afflicted versions of tor onto a FreeBSD 11.4-STABLE system. I do not know whether later versions of FreeBSD would get a different result, but given the abort messages, I suspect not.
- Start tor.
- Wait until 6 p.m. CDT (2300Z). The abort will occur before 7 p.m. CDT (0000Z).
What is the current bug behavior?
During startup and operation everything appears to be normal. However, these versions of tor always abort every day between 6 p.m. and 7 p.m. CDT (2300Z and 0000Z) with the same group of error messages being written to /var/log/notices. The startup messages look as follows.
May 08 19:21:24.633 [notice] Tor 0.4.6.2-alpha opening log file.
May 08 19:21:24.601 [notice] We compiled with OpenSSL 101010bf: OpenSSL 1.1.1k 25 Mar 2021 and we are running with OpenSSL 101010bf: 1.1.1k. These two versions should be binary compatible.
May 08 19:21:24.604 [notice] Tor 0.4.6.2-alpha running on FreeBSD with Libevent 2.1.12-stable, OpenSSL 1.1.1k, Zlib 1.2.11, Liblzma 5.2.5, Libzstd 1.4.9 and Unknown N/A as libc.
May 08 19:21:24.604 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
May 08 19:21:24.604 [notice] This version is not a stable Tor release. Expect more bugs than usual.
May 08 19:21:24.604 [notice] Read configuration file "/usr/local/etc/tor/torrc".
May 08 19:21:24.616 [notice] You configured a non-loopback address '10.1.1.1:9050' for SocksPort. This allows everybody on your local network to use your machine as a proxy. Make sure this is what you wanted.
May 08 19:21:24.616 [notice] Opening Socks listener on 127.0.0.1:9050
May 08 19:21:24.616 [notice] Opened Socks listener connection (ready) on 127.0.0.1:9050
May 08 19:21:24.616 [notice] Opening Socks listener on 10.1.1.1:9050
May 08 19:21:24.616 [notice] Opened Socks listener connection (ready) on 10.1.1.1:9050
May 08 19:21:24.616 [notice] Opening Control listener on 127.0.0.1:9051
May 08 19:21:24.616 [notice] Opened Control listener connection (ready) on 127.0.0.1:9051
May 08 19:21:24.616 [notice] Opening OR listener on 0.0.0.0:32323
May 08 19:21:24.616 [notice] Opened OR listener connection (ready) on 0.0.0.0:32323
May 08 19:21:24.616 [notice] Opening Directory listener on 0.0.0.0:32326
May 08 19:21:24.616 [notice] Opened Directory listener connection (ready) on 0.0.0.0:32326
May 08 19:21:24.640 [notice] Not disabling debugger attaching for unprivileged users.
May 08 19:21:25.419 [notice] Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
May 08 19:21:25.593 [notice] Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
May 08 19:21:25.756 [notice] Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
May 08 19:21:25.907 [notice] Your Tor server's identity key fingerprint is 'MYCROFTsOtherChild 0861F4966E199C0BA9DB1D904DB4BC843508F12C'
May 08 19:21:25.907 [notice] Your Tor server's identity key ed25519 fingerprint is 'MYCROFTsOtherChild hYNLQhYYu0FRDfZGPVW3jFPW27tHY6fZm0GiFP2YkPE'
May 08 19:21:25.907 [notice] Bootstrapped 0% (starting): Starting
May 08 19:21:43.556 [notice] Starting with guard context "default"
May 08 19:21:44.605 [notice] Bootstrapped 5% (conn): Connecting to a relay
May 08 19:21:44.718 [notice] Bootstrapped 10% (conn_done): Connected to a relay
May 08 19:21:44.962 [notice] Bootstrapped 14% (handshake): Handshaking with a relay
May 08 19:21:45.447 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done
May 08 19:21:45.448 [notice] Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits
May 08 19:21:45.448 [notice] Bootstrapped 90% (ap_handshake_done): Handshake finished with a relay to build circuits
May 08 19:21:45.448 [notice] Bootstrapped 95% (circuit_create): Establishing a Tor circuit
May 08 19:21:48.184 [notice] Bootstrapped 100% (done): Done
May 08 19:21:48.185 [notice] Now checking whether IPv4 ORPort 98.193.69.56:32323 is reachable... (this may take up to 20 minutes -- look for log messages indicating success)
May 08 19:21:48.649 [notice] Self-testing indicates your ORPort 98.193.69.56:32323 is reachable from the outside. Excellent. Publishing server descriptor.
May 08 19:39:45.296 [notice] Performing bandwidth self-test...done.
The abort messages follow. It does not appear to matter what time of day tor is started. It always aborts during that hour at the start of the evening, and the exact time seems to be quasi-random and may coincide with some quasi-hourly event, such as downloading directory updates or consensus files.
May 09 18:21:45.586 [notice] Heartbeat: Tor's uptime is 23:00 hours, with 88 circuits open. I've sent 1.18 GB and received 1.46 GB. I've received 12680 connections on IPv4 and 0 on IPv6. I've made 11044 connections with IPv4 and 0 with IPv6.
May 09 18:21:45.620 [notice] While bootstrapping, fetched this many bytes: 35042 (consensus network-status fetch); 500 (microdescriptor fetch)
May 09 18:21:45.620 [notice] While not bootstrapping, fetched this many bytes: 13502874 (server descriptor fetch); 1080 (server descriptor upload); 1780039 (consensus network-status fetch); 89127 (microdescriptor fetch)
May 09 18:21:45.620 [notice] Circuit handshake stats since last time: 11/11 TAP, 1449/1449 NTor.
May 09 18:21:45.620 [notice] 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 511 v4 connections; initiated 10070 and received 11411 v5 connections.
May 09 18:21:45.620 [notice] Heartbeat: DoS mitigation since startup: 0 circuits killed with too many cells, 0 circuits rejected, 0 marked addresses, 0 same address concurrent connections rejected, 0 connections rejected, 0 single hop clients refused, 0 INTRODUCE2 rejected.
May 09 18:23:46.805 [err] tor_assertion_failed_: Bug: src/feature/dirauth/voting_schedule.c:64: create_voting_schedule: Assertion end > start failed; aborting. (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: Tor 0.4.6.2-alpha: Assertion end > start failed in create_voting_schedule at src/feature/dirauth/voting_schedule.c:64: . Stack trace: (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x1107fac <log_backtrace_impl+0x5c> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x11132a2 <tor_assertion_failed_+0x142> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x10e96a6 <dirauth_sched_recalculate_timing+0x1e6> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x109c113 <networkstatus_set_current_consensus+0xed3> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x11d96cc <connection_dir_reached_eof+0x1b6c> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x11acf26 <connection_handle_read+0xbe6> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x1090050 <connection_add_impl+0x240> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x1c1bada8a <event_base_assert_ok_nolock_+0xc3a> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x1c1ba8eec <event_base_loop+0x57c> at /usr/local/lib/libevent-2.1.so.7 (on Tor 0.4.6.2-alpha )
May 09 18:23:46.806 [err] Bug: 0x1092465 <do_main_loop+0x135> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.807 [err] Bug: 0x108d89c <tor_run_main+0x12c> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
May 09 18:23:46.807 [err] Bug: 0x108c22e <tor_main+0x6e> at /usr/local/bin/tor (on Tor 0.4.6.2-alpha )
What is the expected behavior?
I expect tor not to abort and instead to run until either I shut it down or the OS crashes for any reason.
Environment
-
Which version of Tor are you using? Run
tor --version
to get the version if you are unsure.As stated above, the versions I know to be affected are 0.4.5.7, 0.4.6.1-alpha, and 0.4.6.2-alpha.
-
Which operating system are you using? For example: Debian GNU/Linux 10.1, Windows 10, Ubuntu Xenial, FreeBSD 12.2, etc.
As stated above, this problem is occurring on FreeBSD 11.4-STABLE. I have added an entry to /etc/crontab to restart tor every evening at 7:01 p.m. CDT (2301Z), which works, but does not prevent sudden breakage of about 400 to 2000 connections when tor aborts, and means that my relay can never get a Stable flag. (The authorities stopped giving it a HSDir flag months ago for no reason apparent to me, as well, but that appears to be a problem unrelated to the bug reported here.)
-
Which installation method did you use? Distribution package (apt, pkg, homebrew), from source tarball, from Git, etc.
I installed each version using portmaster(8) to install/upgrade from the FreeBSD 11-STABLE ports tree, so portmaster compiled each version locally. Other than the kinds of differences that show up when not using a "reproducible build" procedure, they are the same as if installed by pkg(8).
Relevant logs and/or screenshots
See above.