rend_cache_store(): We already have a v2 descriptor for service xxxxx
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@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)
Trac:
Username: prof7bit