OnionService v3 running as onionbalance backend fails to reload failing with get_subcredential_for_handling_intro2_cell: Non-fatal assertion !(!service->ob_subcreds) failed.
When you do a reload on a Tor process that is running an onion service v3 as an onionbalance backend instance (with HiddenServiceOnionBalanceInstance 1
in torrc), it fails to come up, making the backend onion service unavailable while not exiting the Tor process entirely. The only thing that makes it heal is a restart' of the process.
It can be triggered any time you reload (SIGHUP) a Tor process with an onion service running with HiddenServiceOnionBalanceInstance 1
. This is Tor 0.4.4.0-alpha-dev-20200327T132009Z-1~d10.buster+1 from deb.tpo nightly master.
Here is the full stack trace:
Mar 29 15:59:12.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Mar 29 15:59:12.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Mar 29 15:59:12.000 [notice] Read configuration file "/etc/tor/torrc".
Mar 29 15:59:12.000 [info] config_generic_service(): HiddenServiceDir="/var/lib/tor/ob-hs". Configuring...
Mar 29 15:59:12.000 [info] config_generic_service(): HiddenServicePort=80 127.0.0.1:80 for "/var/lib/tor/ob-hs"
Mar 29 15:59:12.000 [info] tor_getpwnam(): Caching new entry debian-tor for debian-tor
Mar 29 15:59:12.000 [info] helper_parse_uint64(): HiddenServiceOnionBalanceInstance was parsed to 1
Mar 29 15:59:12.000 [info] ob_option_parse(): OnionBalance: MasterOnionAddress *******.onion registered
Mar 29 15:59:12.000 [notice] Tor 0.4.4.0-alpha-dev opening log file.
Mar 29 16:00:42.000 [warn] tor_bug_occurred_(): Bug: ../src/feature/hs/hs_circuit.c:987: get_subcredential_for_handling_intro2_cell: Non-fatal assertion !(!service->ob_subcreds) failed. (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: Tor 0.4.4.0-alpha-dev: Non-fatal assertion !(!service->ob_subcreds) failed in get_subcredential_for_handling_intro2_cell at ../src/feature/hs/hs_circuit.c:987. Stack trace: (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(log_backtrace_impl+0x56) [0x558eb518fee6] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(tor_bug_occurred_+0x16c) [0x558eb518b0ec] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(hs_circ_handle_introduce2+0x5eb) [0x558eb5091e3b] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(hs_service_receive_introduce2+0xc3) [0x558eb50a53d3] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(rend_process_relay_cell+0x1be) [0x558eb50e672e] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(+0xbe368) [0x558eb502e368] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(+0xbf1c5) [0x558eb502f1c5] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(circuit_receive_relay_cell+0x2b4) [0x558eb5030a44] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(command_process_cell+0x2c8) [0x558eb5013788] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(channel_tls_handle_cell+0x4eb) [0x558eb4ff2f0b] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(+0xac5ca) [0x558eb501c5ca] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(connection_handle_read+0xa92) [0x558eb4fe03a2] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(+0x75609) [0x558eb4fe5609] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /lib/x86_64-linux-gnu/libevent-2.1.so.6(+0x229ba) [0x7f34833269ba] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /lib/x86_64-linux-gnu/libevent-2.1.so.6(event_base_loop+0x5a7) [0x7f3483327537] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(do_main_loop+0xff) [0x558eb4fe688f] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(tor_run_main+0x10b5) [0x558eb4fd3bc5] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(tor_main+0x3a) [0x558eb4fd12ca] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(main+0x19) [0x558eb4fd0e89] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb) [0x7f3482c0809b] (on Tor 0.4.4.0-alpha-dev )
Mar 29 16:00:42.000 [warn] Bug: /usr/bin/tor(_start+0x2a) [0x558eb4fd0eda] (on Tor 0.4.4.0-alpha-dev )
One instance has 26 such stack traces across a time period of 6 mins and 54 seconds and the other one 32 such stack traces across a time period of 4 mins and 28 seconds.
While we are at this, config_generic_service()
, tor_getpwnam()
, helper_parse_uint64()
and ob_option_parse()
report [info] level logs in a Log notice file configured Tor instance, is this normal?