Weird interactions between TBB and Hidden Services upon HS kill/restart
For the sake of documentation I thought I would share this here: I have a (test) Hidden Service, running vanilla tor 0.2.6.10 The HS torrc is: ControlPort 9051 DataDirectory /home/alecm/tor-dev/data SafeLogging 0 Log info stdout HiddenServiceDir /home/alecm/tor-dev/hs HiddenServicePort 80 localhost:80 SocksPort 0 RendPostPeriod 0 seconds I also have an OSX version of Tor Browser Bundle - version 5.5a4 (tor 0.2.7.4-rc) I amended /Applications/TorBrowser.app/TorBrowser/Data/Tor/torrc-defaults to include: SafeLogging 0 Log info file /tmp/tor-log.txt ...so that I can see what is going on. I launched the Hidden Service (HS) I accessed the HS from TBB - Successful Page Load! The TBB logfile contains the following sequence, pertinent to the first connection attempt, with manual edits: ---- start ----
Nov 12 17:41:13.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_1 Nov 12 17:45:02.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:45:02.000 [info] connection_ap_handshake_rewrite_and_attach(): Unknown descriptor MY_ONION. Fetching. Nov 12 17:45:02.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_2 Nov 12 17:45:03.000 [info] circuit_get_open_circ_or_launch(): Chose INTROPOINT_1 as intro point for 'MY_ONION'. Nov 12 17:45:03.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:45:03.000 [info] link_apconn_to_circ(): Looks like completed circuit to hidden service does allow optimistic data for connection to MY_ONION ---- end ----
This looks good. I killed the HS - the means of killing appears immaterial, SIGINT, SIGTERM, same thing always happens. I waited about 60 seconds. I re-launched the HS. I accessed the HS from (still running, not restarted) TBB using Shift-Reload to force a page-refresh - Failure! The TBB logfile contains the following sequence, pertinent to the second connection attempt: ---- start ----
Nov 12 17:46:27.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:46:27.000 [info] circuit_get_open_circ_or_launch(): Chose INTROPOINT_3 as intro point for 'MY_ONION'. Nov 12 17:46:27.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_3... Nov 12 17:46:27.000 [info] rend_client_report_intro_point_failure(): 2 options left for "MY_ONION". Nov 12 17:46:28.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_2... Nov 12 17:46:28.000 [info] rend_client_report_intro_point_failure(): 1 options left for "MY_ONION". Nov 12 17:46:28.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_1... Nov 12 17:46:28.000 [info] rend_client_report_intro_point_failure(): No more intro points remain for "MY_ONION". Re-fetching descriptor.
Okay, this makes sense, all the IPs are invalid because I killed the daemon, none of them are reachable...
Nov 12 17:46:28.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_2', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_3
Wait, is it relevant that it has picked descriptor ID 'MY_DESC_2' here, not the prior 'MY_DESC_1'? The latter crops-up further down. Perhaps this is a DHT thing? This is the only reference to MY_DESC_2...
Nov 12 17:46:29.000 [info] rend_cache_store_v2_desc_as_client(): Service descriptor with service ID MY_ONION, every intro points are unusable. Discarding it.
That sounds okay, garbage collection of dead data is good...
Nov 12 17:46:29.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_4
Wait, now we are re-fetching MY_DESC_1 again?...
Nov 12 17:46:30.000 [info] rend_cache_store_v2_desc_as_client(): We already have this service descriptor MY_ONION.
And it thinks we already have it? But didn't we just discard it?...
Nov 12 17:46:30.000 [notice] Closing stream for 'MY_ONION.onion': hidden service is unavailable (try again later).
And there is the connection failure, and it looks like it didn't find a new descriptor, or rejected a new one if it found it - assuming it found it at all...
Nov 12 17:46:30.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:46:30.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state.
Try "reload" again, just for good luck:
Nov 12 17:46:40.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:46:40.000 [info] connection_ap_handshake_rewrite_and_attach(): Unknown descriptor MY_ONION. Fetching. Nov 12 17:46:40.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_2 Nov 12 17:46:41.000 [info] rend_cache_store_v2_desc_as_client(): We already have this service descriptor MY_ONION. Nov 12 17:46:41.000 [notice] Closing stream for 'MY_ONION.onion': hidden service is unavailable (try again later). Nov 12 17:46:41.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:46:41.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. ---- end ----
So, it looks like one of three things: - perhaps TBB is not actually discarding the dead descriptor - or perhaps TBB is re-fetching the old descriptor and failing connections again - or perhaps TBB is fetching the new descriptor and rejecting it in favour of the old one, which it hasn't really discarded. In any case: killing TBB and restarting it seems to fix this situation, so it's something on the client side at fault? - alec
Alec Muffett <alecm@fb.com> writes:
For the sake of documentation I thought I would share this here:
I have a (test) Hidden Service, running vanilla tor 0.2.6.10
<snip>
The TBB logfile contains the following sequence, pertinent to the second connection attempt:
---- start ----
Nov 12 17:46:27.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:46:27.000 [info] circuit_get_open_circ_or_launch(): Chose INTROPOINT_3 as intro point for 'MY_ONION'. Nov 12 17:46:27.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_3... Nov 12 17:46:27.000 [info] rend_client_report_intro_point_failure(): 2 options left for "MY_ONION". Nov 12 17:46:28.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_2... Nov 12 17:46:28.000 [info] rend_client_report_intro_point_failure(): 1 options left for "MY_ONION". Nov 12 17:46:28.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_1... Nov 12 17:46:28.000 [info] rend_client_report_intro_point_failure(): No more intro points remain for "MY_ONION". Re-fetching descriptor.
Okay, this makes sense, all the IPs are invalid because I killed the daemon, none of them are reachable...
Nov 12 17:46:28.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_2', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_3
Wait, is it relevant that it has picked descriptor ID 'MY_DESC_2' here, not the prior 'MY_DESC_1'? The latter crops-up further down. Perhaps this is a DHT thing? This is the only reference to MY_DESC_2...
Maybe MY_DESC_2 is the descriptor ID of the second replica? There are two replicas for an HS descriptor, each served by 3 HSDIrs. The descriptor ID is formed like this: descriptor-id = H(permanent-id | H(time-period | descriptor-cookie | replica)) This might also explain why you get the "we already have this descriptor" message below. Not sure though, for more confidence I would have to look deeper here.
Nov 12 17:46:29.000 [info] rend_cache_store_v2_desc_as_client(): Service descriptor with service ID MY_ONION, every intro points are unusable. Discarding it.
That sounds okay, garbage collection of dead data is good...
Nov 12 17:46:29.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_4
Wait, now we are re-fetching MY_DESC_1 again?...
Nov 12 17:46:30.000 [info] rend_cache_store_v2_desc_as_client(): We already have this service descriptor MY_ONION.
And it thinks we already have it? But didn't we just discard it?...
Nov 12 17:46:30.000 [notice] Closing stream for 'MY_ONION.onion': hidden service is unavailable (try again later).
And there is the connection failure, and it looks like it didn't find a new descriptor, or rejected a new one if it found it - assuming it found it at all...
Nov 12 17:46:30.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:46:30.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state.
Try "reload" again, just for good luck:
Nov 12 17:46:40.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:46:40.000 [info] connection_ap_handshake_rewrite_and_attach(): Unknown descriptor MY_ONION. Fetching. Nov 12 17:46:40.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_2 Nov 12 17:46:41.000 [info] rend_cache_store_v2_desc_as_client(): We already have this service descriptor MY_ONION. Nov 12 17:46:41.000 [notice] Closing stream for 'MY_ONION.onion': hidden service is unavailable (try again later). Nov 12 17:46:41.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:46:41.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. ---- end ----
So, it looks like one of three things:
- perhaps TBB is not actually discarding the dead descriptor - or perhaps TBB is re-fetching the old descriptor and failing connections again - or perhaps TBB is fetching the new descriptor and rejecting it in favour of the old one, which it hasn't really discarded.
In any case: killing TBB and restarting it seems to fix this situation, so it's something on the client side at fault?
- alec
_______________________________________________ tor-dev mailing list tor-dev@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-dev
On 12 Nov (18:35:50), Alec Muffett wrote: Hi Alec, Sorry for the late reply. I see that George replied and you also talked to him on IRC but I can clarify some stuff for you here. Also, epic bug report :).
For the sake of documentation I thought I would share this here:
I have a (test) Hidden Service, running vanilla tor 0.2.6.10
The HS torrc is:
ControlPort 9051 DataDirectory /home/alecm/tor-dev/data SafeLogging 0 Log info stdout HiddenServiceDir /home/alecm/tor-dev/hs HiddenServicePort 80 localhost:80 SocksPort 0 RendPostPeriod 0 seconds
I also have an OSX version of Tor Browser Bundle - version 5.5a4 (tor 0.2.7.4-rc)
I amended /Applications/TorBrowser.app/TorBrowser/Data/Tor/torrc-defaults to include:
SafeLogging 0 Log info file /tmp/tor-log.txt
...so that I can see what is going on.
I launched the Hidden Service (HS)
I accessed the HS from TBB - Successful Page Load!
The TBB logfile contains the following sequence, pertinent to the first connection attempt, with manual edits:
---- start ----
Nov 12 17:41:13.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_1 Nov 12 17:45:02.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:45:02.000 [info] connection_ap_handshake_rewrite_and_attach(): Unknown descriptor MY_ONION. Fetching. Nov 12 17:45:02.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_2 Nov 12 17:45:03.000 [info] circuit_get_open_circ_or_launch(): Chose INTROPOINT_1 as intro point for 'MY_ONION'. Nov 12 17:45:03.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:45:03.000 [info] link_apconn_to_circ(): Looks like completed circuit to hidden service does allow optimistic data for connection to MY_ONION ---- end ----
This looks good.
I killed the HS - the means of killing appears immaterial, SIGINT, SIGTERM, same thing always happens.
I waited about 60 seconds.
I re-launched the HS.
I accessed the HS from (still running, not restarted) TBB using Shift-Reload to force a page-refresh - Failure!
Right away? There is a 30 seconds delay before the service uploads its descriptor. That means your client got the old descriptor thus connection failure. (The following logs clearly show that anyway)
The TBB logfile contains the following sequence, pertinent to the second connection attempt:
---- start ----
Nov 12 17:46:27.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:46:27.000 [info] circuit_get_open_circ_or_launch(): Chose INTROPOINT_3 as intro point for 'MY_ONION'. Nov 12 17:46:27.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_3... Nov 12 17:46:27.000 [info] rend_client_report_intro_point_failure(): 2 options left for "MY_ONION". Nov 12 17:46:28.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_2... Nov 12 17:46:28.000 [info] rend_client_report_intro_point_failure(): 1 options left for "MY_ONION". Nov 12 17:46:28.000 [info] rend_client_introduction_acked(): Got nack for MY_ONION from INTROPOINT_1... Nov 12 17:46:28.000 [info] rend_client_report_intro_point_failure(): No more intro points remain for "MY_ONION". Re-fetching descriptor.
Okay, this makes sense, all the IPs are invalid because I killed the daemon, none of them are reachable...
Nov 12 17:46:28.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_2', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_3
Wait, is it relevant that it has picked descriptor ID 'MY_DESC_2' here, not the prior 'MY_DESC_1'? The latter crops-up further down. Perhaps this is a DHT thing? This is the only reference to MY_DESC_2...
Here, the descriptor ID will still be the same since it only changes over time or if you choose a different replica. George explained it before anyway. "directory_get_from_hs_dir()", if I recall correctly, chooses a replica randomly so we never do "Fetch replica 0 on all three HSDirs then replica 1 on all three HSDirs". Thus you have a chance to get the same again basically half the time.
Nov 12 17:46:29.000 [info] rend_cache_store_v2_desc_as_client(): Service descriptor with service ID MY_ONION, every intro points are unusable. Discarding it.
That sounds okay, garbage collection of dead data is good...
As of 0.2.7, client have an "intro point failure cache" so instead of discarding the descriptor based on the time, we discard it if no intro points are usable that is prior to that we had at least one failure for the intro point that has been noted down. This is cleaned up every 5 minutes. There is a ticket to make it much more nicer.
Nov 12 17:46:29.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_4
Wait, now we are re-fetching MY_DESC_1 again?...
What's important here is that the HSDir is different since we also have a cache that tracks HSDir we tried and failure or not. So this is normal behavior I would say.
Nov 12 17:46:30.000 [info] rend_cache_store_v2_desc_as_client(): We already have this service descriptor MY_ONION.
And it thinks we already have it? But didn't we just discard it?...
Now this one is interesting!!!!... It seems there might be something missing in the failure logic that is a edge case where we already have the descriptor but we re-fetch and we realized that it's not a valid descriptor we just fetched. Any chance you can send us the full client log? I'll start investiguating this since it clearly shows an issue on the client side I would say. Thanks! David
Nov 12 17:46:30.000 [notice] Closing stream for 'MY_ONION.onion': hidden service is unavailable (try again later).
And there is the connection failure, and it looks like it didn't find a new descriptor, or rejected a new one if it found it - assuming it found it at all...
Nov 12 17:46:30.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:46:30.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state.
Try "reload" again, just for good luck:
Nov 12 17:46:40.000 [info] connection_ap_handshake_rewrite_and_attach(): Got a hidden service request for ID 'MY_ONION' Nov 12 17:46:40.000 [info] connection_ap_handshake_rewrite_and_attach(): Unknown descriptor MY_ONION. Fetching. Nov 12 17:46:40.000 [info] directory_get_from_hs_dir(): Sending fetch request for v2 descriptor for service 'MY_ONION' with descriptor ID 'MY_DESC_1', auth type 0, and descriptor cookie '[none]' to hidden service directory HSDIR_2 Nov 12 17:46:41.000 [info] rend_cache_store_v2_desc_as_client(): We already have this service descriptor MY_ONION. Nov 12 17:46:41.000 [notice] Closing stream for 'MY_ONION.onion': hidden service is unavailable (try again later). Nov 12 17:46:41.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. Nov 12 17:46:41.000 [info] rend_client_note_connection_attempt_ended(): Connection attempt for MY_ONION has ended; cleaning up temporary state. ---- end ----
So, it looks like one of three things:
- perhaps TBB is not actually discarding the dead descriptor - or perhaps TBB is re-fetching the old descriptor and failing connections again - or perhaps TBB is fetching the new descriptor and rejecting it in favour of the old one, which it hasn't really discarded.
In any case: killing TBB and restarting it seems to fix this situation, so it's something on the client side at fault?
- alec
_______________________________________________ tor-dev mailing list tor-dev@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-dev
participants (3)
-
Alec Muffett -
David Goulet -
George Kadianakis