[tor-bugs] #33762 [Core Tor/Tor]: OnionService v3 running as onionbalance backend fails to reload failing with get_subcredential_for_handling_intro2_cell: Non-fatal assertion !(!service->ob_subcreds) failed.

[Tor Bug Tracker & Wiki]

#33762: OnionService v3 running as onionbalance backend fails to reload failing
with get_subcredential_for_handling_intro2_cell: Non-fatal assertion
!(!service->ob_subcreds) failed.
------------------------------+------------------------------------
     Reporter:  s7r           |      Owner:  (none)
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:
    Component:  Core Tor/Tor  |    Version:  Tor: 0.4.4.0-alpha-dev
     Severity:  Normal        |   Keywords:  tor-hs, onionbalance
Actual Points:                |  Parent ID:
       Points:                |   Reviewer:
      Sponsor:                |
------------------------------+------------------------------------
 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?

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/33762>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online