[tor-dev] Weird interactions between TBB and Hidden Services upon HS kill/restart

Tue Nov 17 15:23:24 UTC 2015

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 at lists.torproject.org
> https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-dev

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 603 bytes
Desc: Digital signature
URL: <http://lists.torproject.org/pipermail/tor-dev/attachments/20151117/fdaa6738/attachment.sig>