Opened 6 weeks ago

Last modified 4 weeks ago

#27410 merge_ready defect

Bug: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed in retry_all_socks_conn_waiting_for_desc at ../src/or/hs_client.c:268

Reported by: cstest Owned by:
Priority: Medium Milestone: Tor: 0.3.4.x-final
Component: Core Tor/Tor Version: Tor: 0.3.3.9
Severity: Normal Keywords: tor-hs, hs-v3, 032-backport, 033-backport, 034-backport
Cc: Actual Points:
Parent ID: Points:
Reviewer: asn Sponsor:

Description

Sever running one v3 and one v2 hidden service and there is a bash script that test availability of those domains from time to time through curl. Bug warning is repeating.

v3 domain is not working at all but v2 is working fine.

Sep 02 06:26:05.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening new log file.
Sep 02 06:28:26.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:28:26.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:28:26.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:28:36.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:30:05.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:30:05.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:30:05.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:30:21.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:32:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:34:10.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:36:04.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:36:04.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:36:04.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:36:21.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:38:05.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:38:05.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:38:05.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:40:05.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:40:05.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:40:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:40:06.000 [warn] tor_bug_occurred_(): Bug: ../src/or/hs_client.c:268: retry_all_socks_conn_waiting_for_desc: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed. (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed in retry_all_socks_conn_waiting_for_desc at ../src/or/hs_client.c:268. Stack trace: (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(log_backtrace+0x43) [0x55c6f6515873] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(tor_bug_occurred_+0xb9) [0x55c6f6531109] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(hs_client_dir_info_changed+0x106) [0x55c6f64f44f6] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(+0x5208a) [0x55c6f63de08a] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(+0x1f75c) [0x7f861da1175c] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(event_base_loop+0x5a7) [0x7f861da12227] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(do_main_loop+0x2b4) [0x55c6f63e1624] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(tor_run_main+0x1025) [0x55c6f63e3b05] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(tor_main+0x3a) [0x55c6f63dc0ba] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(main+0x19) [0x55c6f63dbe49] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7f861c2191c1] (on Tor 0.3.3.9 )
Sep 02 06:40:06.000 [warn] Bug:     /usr/sbin/tor(_start+0x2a) [0x55c6f63dbe9a] (on Tor 0.3.3.9 )
Sep 02 06:40:09.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 06:40:15.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:42:09.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:44:26.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:44:26.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:44:26.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:44:40.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:46:08.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:48:26.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:48:26.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:48:26.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:48:40.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:50:11.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:52:12.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:54:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:54:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:54:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:54:41.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:56:10.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 06:58:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 06:58:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 06:58:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 06:58:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:00:28.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:00:28.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:00:28.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:00:43.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:02:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:02:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:02:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:02:15.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:04:16.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:06:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:06:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:06:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:08:10.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 07:08:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:08:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:08:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:08:36.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:10:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:10:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:10:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:10:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:12:15.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:14:28.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:14:28.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:14:28.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:14:45.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:16:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:16:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:16:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:16:17.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:18:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:18:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:18:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:18:20.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:20:28.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:20:28.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:20:28.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:20:38.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:22:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:22:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:22:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:22:21.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:24:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:24:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:24:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:26:11.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 07:26:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:26:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:26:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:26:39.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:28:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:28:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:28:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:28:16.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:30:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:30:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:30:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:31:01.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:32:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:32:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:32:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:34:10.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 07:34:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:34:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:34:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:34:38.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:36:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:36:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:36:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:36:17.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:38:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:38:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:38:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:38:20.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:40:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:40:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:40:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:42:11.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 07:42:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:42:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:42:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:42:35.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:44:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:44:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:44:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:44:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:46:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:46:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:46:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:46:21.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:48:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:48:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:48:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:48:43.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:50:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:50:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:50:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:50:16.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:52:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:52:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:52:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:52:22.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:54:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:54:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:54:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:56:11.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 07:56:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:56:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:56:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:56:36.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 07:58:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 07:58:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 07:58:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 07:58:16.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:00:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:00:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:00:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:00:23.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:02:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:02:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:02:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:02:37.000 [notice] Heartbeat: Tor's uptime is 23:59 hours, with 19 circuits open. I've sent 126.53 MB and received 77.24 MB.
Sep 02 08:02:37.000 [notice] Our hidden service received 2574 v2 and 4187 v3 INTRODUCE2 cells and attempted to launch 6776 rendezvous circuits.
Sep 02 08:04:11.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 08:04:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:04:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:04:28.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:04:38.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:06:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:06:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:06:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:06:17.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:08:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:08:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:08:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:08:21.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:10:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:10:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:10:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:12:12.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 08:12:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:12:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:12:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:12:38.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:14:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:14:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:14:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:14:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:16:14.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:18:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:18:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:18:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:18:42.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:20:11.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:22:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:22:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:22:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:22:22.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:24:28.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:24:28.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:24:28.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:24:43.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:26:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:26:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:26:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:26:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:28:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:28:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:28:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:28:28.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:30:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:30:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:30:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:32:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:32:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:32:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:32:06.000 [warn] tor_bug_occurred_(): Bug: ../src/or/hs_client.c:268: retry_all_socks_conn_waiting_for_desc: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed. (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed in retry_all_socks_conn_waiting_for_desc at ../src/or/hs_client.c:268. Stack trace: (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(log_backtrace+0x43) [0x55c6f6515873] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(tor_bug_occurred_+0xb9) [0x55c6f6531109] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(hs_client_dir_info_changed+0x106) [0x55c6f64f44f6] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(+0x5208a) [0x55c6f63de08a] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(+0x1f75c) [0x7f861da1175c] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(event_base_loop+0x5a7) [0x7f861da12227] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(do_main_loop+0x2b4) [0x55c6f63e1624] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(tor_run_main+0x1025) [0x55c6f63e3b05] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(tor_main+0x3a) [0x55c6f63dc0ba] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(main+0x19) [0x55c6f63dbe49] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7f861c2191c1] (on Tor 0.3.3.9 )
Sep 02 08:32:06.000 [warn] Bug:     /usr/sbin/tor(_start+0x2a) [0x55c6f63dbe9a] (on Tor 0.3.3.9 )
Sep 02 08:32:12.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 08:32:20.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:34:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:34:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:34:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:36:11.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 08:36:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:36:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:36:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:36:42.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:38:10.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:40:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:40:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:40:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:40:23.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:42:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:42:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:42:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:42:39.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:44:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:44:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:44:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:44:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:46:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:46:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:46:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:47:02.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:48:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:48:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:48:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:48:50.000 [warn] tor_bug_occurred_(): Bug: ../src/or/hs_client.c:268: retry_all_socks_conn_waiting_for_desc: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed. (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed in retry_all_socks_conn_waiting_for_desc at ../src/or/hs_client.c:268. Stack trace: (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(log_backtrace+0x43) [0x55c6f6515873] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(tor_bug_occurred_+0xb9) [0x55c6f6531109] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(hs_client_dir_info_changed+0x106) [0x55c6f64f44f6] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(microdescs_add_list_to_cache+0x185) [0x55c6f63e5f35] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(microdescs_add_to_cache+0x292) [0x55c6f63e6402] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(connection_dir_reached_eof+0x19db) [0x55c6f64c293b] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(+0x10d249) [0x55c6f6499249] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(+0x5456e) [0x55c6f63e056e] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(+0x1f6aa) [0x7f861da116aa] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(event_base_loop+0x5a7) [0x7f861da12227] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(do_main_loop+0x2b4) [0x55c6f63e1624] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(tor_run_main+0x1025) [0x55c6f63e3b05] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(tor_main+0x3a) [0x55c6f63dc0ba] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(main+0x19) [0x55c6f63dbe49] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7f861c2191c1] (on Tor 0.3.3.9 )
Sep 02 08:48:50.000 [warn] Bug:     /usr/sbin/tor(_start+0x2a) [0x55c6f63dbe9a] (on Tor 0.3.3.9 )
Sep 02 08:50:11.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 08:50:28.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:50:28.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:50:28.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:50:40.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:52:09.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:54:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:54:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:54:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:54:22.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:56:28.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:56:28.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:56:28.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:56:42.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 08:58:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 08:58:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 08:58:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 08:58:18.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 09:00:07.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 09:00:07.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 09:00:07.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 09:00:23.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 09:02:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 09:02:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 09:02:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 09:04:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 09:04:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 09:04:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 09:04:06.000 [warn] tor_bug_occurred_(): Bug: ../src/or/hs_client.c:268: retry_all_socks_conn_waiting_for_desc: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed. (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug: Non-fatal assertion !(status == HS_CLIENT_FETCH_HAVE_DESC) failed in retry_all_socks_conn_waiting_for_desc at ../src/or/hs_client.c:268. Stack trace: (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(log_backtrace+0x43) [0x55c6f6515873] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(tor_bug_occurred_+0xb9) [0x55c6f6531109] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(hs_client_dir_info_changed+0x106) [0x55c6f64f44f6] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(+0x5208a) [0x55c6f63de08a] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(+0x1f75c) [0x7f861da1175c] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/lib/x86_64-linux-gnu/libevent-2.1.so.6(event_base_loop+0x5a7) [0x7f861da12227] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(do_main_loop+0x2b4) [0x55c6f63e1624] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(tor_run_main+0x1025) [0x55c6f63e3b05] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(tor_main+0x3a) [0x55c6f63dc0ba] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(main+0x19) [0x55c6f63dbe49] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7f861c2191c1] (on Tor 0.3.3.9 )
Sep 02 09:04:06.000 [warn] Bug:     /usr/sbin/tor(_start+0x2a) [0x55c6f63dbe9a] (on Tor 0.3.3.9 )
Sep 02 09:04:11.000 [notice] Tried for 120 seconds to get a connection to v3onion....................onion:80. Giving up. (waiting for rendezvous desc)
Sep 02 09:04:17.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 09:06:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 09:06:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 09:06:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 09:06:40.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 09:08:06.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 09:08:06.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 09:08:06.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 09:08:17.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 09:10:27.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 02 09:10:27.000 [notice] Read configuration file "/etc/tor/tor1.cfg".
Sep 02 09:10:27.000 [notice] Tor 0.3.3.9 (git-ca1a436fa8e53a32) opening log file.
Sep 02 09:10:42.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.
Sep 02 09:12:10.000 [notice] Closed 1 streams for service v3onion....................onion for reason resolve failed. Fetch status: No more HSDir available to query.

Child Tickets

Change History (9)

comment:1 Changed 6 weeks ago by cstest

This is probably client issue so v3 hidden service not working is probably not related to this bug report.

comment:2 Changed 4 weeks ago by dgoulet

Keywords: tor-hs hs-v3 added
Milestone: Tor: 0.3.5.x-final

comment:3 Changed 4 weeks ago by dgoulet

I have a long theory about what can cause this problem:

It all starts with hs_client_desc_has_arrived() which is called when a descriptor is cached (client side). That function goes over all pending SOCKS request that are waiting for that descriptor. It changes the state of the connection to "wait for circuits".

However, there is one code path that can make it exit early which is when no intro points in the descriptor are usable. In that case, we'll unattached a SOCKS connection and exit the function. But, here comes the problem, there could be more SOCKS connection for that same .onion, they won't be unattached and ultimately wait until they timeout.

This creates the problem that when our directory information changes, the HS client will go retry all SOCKS connection and see if we should refetch the descriptor:

    /* Order a refetch in case it works this time. */
    status = hs_client_refetch_hsdesc(&edge_conn->hs_ident->identity_pk);
    if (BUG(status == HS_CLIENT_FETCH_HAVE_DESC)) {
      /* This case is unique because it can NOT happen in theory. Once we get
       * a new descriptor, the HS client subsystem is notified immediately and
       * the connections waiting for it are handled which means the state will
       * change from renddesc wait state. Log this and continue to next
       * connection. */
      continue;
    }

The comment explaining the BUG() is actually wrong for one edge case. In reality, we change the state of *one* single SOCKS connection, not all of them. So yes, we can end up looking at a SOCKS connection for which we have a descriptor where the IPs in the descriptor (that were originally flagged has unusable) might now be usable now (intro point failure cache cleanup for instance) and so the SOCKS connection state is still in RENDDESC_WAIT, we now have a usable descriptor (HS_CLIENT_FETCH_HAVE_DESC) and boom.

I think the solution needs those two elements:

  1. In hs_client_desc_has_arrived(), do not exit if the descriptor is not usable but rather continue to loop on all SOCKS connections so we can detach them all.
  1. Once a descriptor arrives and stored in our cache, if it is unusable, get rid of it.

For (1), it is super important that we end up with no SOCKS connection in RENDDESC_WAIT state if we know that the descriptor is unusable and there are no inflight directory requests for it.

About (2), there is this issue where we'll create a way to continuously re-request the descriptor on the HSDirs at each SOCKS request adding considerable loads on the network. In theory, we shouldn't because we have the last_hid_serv_requests_ cache for this meaning we can't query the same HSDir for the same .onion more than once in a 15 minutes time frame. HOWEVER, in hs_client_desc_has_arrived(), if the descriptor is unusable, we purge that cache for the .onion so we can attempt again to fetch the descriptor that might have changed on the HSDir (note_connection_attempt_succeeded()).

I still think (2) worth doing but then we might want to remove that purge if the IPs aren't usable and bring down that retry time period to something more acceptable like 60 secs instead of 15 minutes which is crazy high for the user experience.

comment:4 Changed 4 weeks ago by asn

Theory here looks plausible.

Since this bug seems reproducible, can we try to repro and see if the early-exit behavior of hs_client_desc_has_arrived() is the issue here? If that's the case, I think the above solutions make sense.

comment:5 Changed 4 weeks ago by dgoulet

Reviewer: asn
Status: newneeds_review

One liner fix. I'm not doing a PR for this.

See branch ticket27410_035_01.

comment:6 Changed 4 weeks ago by asn

Status: needs_reviewmerge_ready

Great stuff. LGTM!

FWIW, I made PR about this because it's easy and I wanted CI and coveralls to run:
https://github.com/torproject/tor/pull/360

comment:7 Changed 4 weeks ago by nickm

The changes file says it's a bugfix on 0.3.2. Does this need a backport, or is it okay to fix it in 0.3.5 only and leave it broken for earlier releases?

comment:8 in reply to:  7 Changed 4 weeks ago by dgoulet

Keywords: 032-backport 033-backport 034-backport added

Replying to nickm:

The changes file says it's a bugfix on 0.3.2. Does this need a backport, or is it okay to fix it in 0.3.5 only and leave it broken for earlier releases?

Oh good point! ...

Here is the 032 branch: ticket27410_032_01. I haven't backported the unit test as that was a complicated thing to do! Many helper function went in since 032 and would take me a while to figure it out in 032.

comment:9 Changed 4 weeks ago by nickm

Milestone: Tor: 0.3.5.x-finalTor: 0.3.4.x-final

Okay -- i've merged both branches to master; marking the 0.3.2 one for possible backport.

Note: See TracTickets for help on using tickets.