[tor-bugs] #2401 [- Select a component]: rend_cache_store(): We already have a v2 descriptor for service xxxxx

Mon Jan 17 14:29:15 UTC 2011

#2401: rend_cache_store(): We already have a v2 descriptor for service xxxxx
------------------------------+---------------------------------------------
 Reporter:  prof7bit          |        Type:  defect              
   Status:  new               |    Priority:  normal              
Milestone:                    |   Component:  - Select a component
  Version:  Tor: unspecified  |    Keywords:                      
   Parent:                    |  
------------------------------+---------------------------------------------
 This is happening with the current 0.2.1.29 and the current alpha.

 When a hidden service is restarted the old intro points are not valid
 anymore. Tor seems to notice this and will fetch a new descriptor when it
 has run out of intro points but then after doing this expensive operation
 it simply discards it with the excuse that there is already *some*
 descriptor there. The expensive operation of fetching has been done for
 nothing.

 The next time it will again try the old descriptor of which it already
 *knows* that there are no valid intro points and fetch a new one (possibly
 better one) again, but only to discard it without even looking at it,
 again and again and again.

 I have seen this going on for quite a long time sometimes. Sometimes I
 have been unable to connect to a hidden service of which I *knew* that was
 running for many hours and I'm sure if it had not discarded the newly
 downloaded descriptor every time it would have been able to connect
 eventually.

 Something is still wrong with this whole caching logic. I am making heavy
 use of hidden services with TorChat and sometimes it is really painful
 watching the logs and watching it not being able to connect to a service
 that *IS* running for hours and not being able to do anything about it.

 rend_cache_store() should store the descriptor and replace the old one in
 all cases. Either it is the exact same, then it has no effect at all or it
 is different (then it is in all likelihood a better one than the one it
 had before because it was fetched later than the cached one)

 Alternatively there could be made a possibility to manually clear the
 cache via the control protocol, either the complete cache or for an
 individual service.

 below is a log from the current stable version:

 {{{
 bernd at t40:~\ $ tail -f .torchat/Tor/tor.log | grep wa5w
 Jan 17 14:36:10.388 [notice] Tried for 120 seconds to get a connection to
 wa5wauj22un2au6o:11009. Giving up. (waiting for rendezvous desc)
 Jan 17 14:36:16.904 [info] connection_ap_handshake_rewrite_and_attach():
 Got a hidden service request for ID 'wa5wauj22un2au6o'
 Jan 17 14:36:16.904 [info] circuit_get_open_circ_or_launch(): No intro
 points for 'wa5wauj22un2au6o': re-fetching service descriptor.
 Jan 17 14:36:16.904 [info] rend_client_refetch_renddesc(): Fetching
 rendezvous descriptor for service "wa5wauj22un2au6o"
 Jan 17 14:36:18.682 [info] rend_cache_store(): We already have a v2
 descriptor for service wa5wauj22un2au6o.
 Jan 17 14:38:16.832 [notice] Tried for 120 seconds to get a connection to
 wa5wauj22un2au6o:11009. Giving up. (waiting for rendezvous desc)
 Jan 17 14:38:27.712 [info] connection_ap_handshake_rewrite_and_attach():
 Got a hidden service request for ID 'wa5wauj22un2au6o'
 Jan 17 14:38:27.712 [info] circuit_get_open_circ_or_launch(): No intro
 points for 'wa5wauj22un2au6o': re-fetching service descriptor.
 Jan 17 14:38:27.712 [info] rend_client_refetch_renddesc(): Fetching
 rendezvous descriptor for service "wa5wauj22un2au6o"
 Jan 17 14:38:29.226 [info] rend_cache_store(): We already have a v2
 descriptor for service wa5wauj22un2au6o.
 Jan 17 14:40:27.460 [notice] Tried for 120 seconds to get a connection to
 wa5wauj22un2au6o:11009. Giving up. (waiting for rendezvous desc)
 Jan 17 14:40:31.442 [info] connection_ap_handshake_rewrite_and_attach():
 Got a hidden service request for ID 'wa5wauj22un2au6o'
 Jan 17 14:40:31.442 [info] circuit_get_open_circ_or_launch(): No intro
 points for 'wa5wauj22un2au6o': re-fetching service descriptor.
 Jan 17 14:40:31.442 [info] rend_client_refetch_renddesc(): Fetching
 rendezvous descriptor for service "wa5wauj22un2au6o"
 Jan 17 14:40:32.682 [info] rend_cache_store(): We already have a v2
 descriptor for service wa5wauj22un2au6o.
 Jan 17 14:42:31.484 [notice] Tried for 120 seconds to get a connection to
 wa5wauj22un2au6o:11009. Giving up. (waiting for rendezvous desc)
 Jan 17 14:42:41.493 [info] connection_ap_handshake_rewrite_and_attach():
 Got a hidden service request for ID 'wa5wauj22un2au6o'
 Jan 17 14:42:41.493 [info] circuit_get_open_circ_or_launch(): No intro
 points for 'wa5wauj22un2au6o': re-fetching service descriptor.
 Jan 17 14:42:41.493 [info] rend_client_refetch_renddesc(): Fetching
 rendezvous descriptor for service "wa5wauj22un2au6o"
 Jan 17 14:42:42.191 [info] rend_cache_store(): We already have a v2
 descriptor for service wa5wauj22un2au6o.
 Jan 17 14:44:41.605 [notice] Tried for 120 seconds to get a connection to
 wa5wauj22un2au6o:11009. Giving up. (waiting for rendezvous desc)
 Jan 17 14:44:54.441 [info] connection_ap_handshake_rewrite_and_attach():
 Got a hidden service request for ID 'wa5wauj22un2au6o'
 Jan 17 14:44:54.441 [info] circuit_get_open_circ_or_launch(): No intro
 points for 'wa5wauj22un2au6o': re-fetching service descriptor.
 Jan 17 14:44:54.441 [info] rend_client_refetch_renddesc(): Fetching
 rendezvous descriptor for service "wa5wauj22un2au6o"
 Jan 17 14:44:55.229 [info] rend_cache_store(): We already have a v2
 descriptor for service wa5wauj22un2au6o.
 Jan 17 14:46:54.864 [notice] Tried for 120 seconds to get a connection to
 wa5wauj22un2au6o:11009. Giving up. (waiting for rendezvous desc)
 Jan 17 14:47:03.401 [info] connection_ap_handshake_rewrite_and_attach():
 Got a hidden service request for ID 'wa5wauj22un2au6o'
 Jan 17 14:47:03.401 [info] connection_ap_handshake_rewrite_and_attach():
 Stale descriptor wa5wauj22un2au6o. Re-fetching.
 Jan 17 14:47:03.418 [info] directory_get_from_hs_dir(): Sending fetch
 request for v2 descriptor for service 'wa5wauj22un2au6o' with descriptor
 ID 'z3zqz265onwi4jdsvqip5xclgglnjk4g', auth type 0, and descriptor cookie
 '[none]' to hidden service directory 'Slipstream' on port 9030.
 Jan 17 14:47:03.418 [info] rend_client_refetch_renddesc(): Fetching
 rendezvous descriptor for service "wa5wauj22un2au6o"
 Jan 17 14:47:05.364 [info] rend_cache_store(): We already have a v2
 descriptor for service wa5wauj22un2au6o.
 Jan 17 14:47:11.039 [info] circuit_get_open_circ_or_launch(): Chose
 '$714AF90AFF324373D6F6A4393084D781C4219FFD' as intro point for
 'wa5wauj22un2au6o'.
 Jan 17 14:47:43.529 [info] circuit_get_open_circ_or_launch(): Chose
 '$CAC54282E75D1459B6174BE696303035929894CD' as intro point for
 'wa5wauj22un2au6o'.
 Jan 17 14:47:49.841 [info] circuit_get_open_circ_or_launch(): Chose
 '$52AEEA15F22B17F6DC760FB4F0DAC7F89DF7934D' as intro point for
 'wa5wauj22un2au6o'.

 }}}
 (btw 0.2.1.29 is missing from the dropdown list below)

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