[tor-bugs] #14224 [Tor]: Two minutes after a failed hidserv connection, we do a bonus hsdesc fetch

[Tor Bug Tracker & Wiki]

#14224: Two minutes after a failed hidserv connection, we do a bonus hsdesc fetch
------------------------------+------------------------------
 Reporter:  arma              |          Owner:
     Type:  defect            |         Status:  new
 Priority:  normal            |      Milestone:  Tor: 0.2.???
Component:  Tor               |        Version:
 Keywords:  SponsorR, tor-hs  |  Actual Points:
Parent ID:                    |         Points:
------------------------------+------------------------------
 If you do the steps to reproduce #14219, you end up eventually hanging up
 on the hidden service stream attempt: your controller events include
 {{{
 1421356924.815634 [torctl-log] localhost:9051 650 HS_DESC REQUESTED
 yjiqkj6p7drpiwyq NO_AUTH
 $0B5E5E70FFEA9C7F9FFD13B8E16916A608F3E9EB~CalyxInstitute08
 blwd4dzs2mnncf4wtc3bpv6pljwx5awb
 1421356925.596473 [torctl-log] localhost:9051 650 HS_DESC RECEIVED
 yjiqkj6p7drpiwyq NO_AUTH
 $0B5E5E70FFEA9C7F9FFD13B8E16916A608F3E9EB~CalyxInstitute08
 }}}
 and your Tor debug log says
 {{{
 Jan 15 16:22:05.595 [info] connection_dir_client_reached_eof(): Received
 rendezvous descriptor (size 3254, status 200 ("OK"))
 Jan 15 16:22:05.596 [info] rend_cache_store_v2_desc_as_client(): We
 already have a new enough service descriptor for service ID
 yjiqkj6p7drpiwyq with the same desc ID and version.
 Jan 15 16:22:05.596 [info] connection_dir_client_reached_eof():
 Successfully fetched v2 rendezvous descriptor.
 Jan 15 16:22:05.596 [notice] Closing stream for 'yjiqkj6p7drpiwyq.onion':
 hidden service is unavailable (try again later).
 Jan 15 16:22:05.596 [info] rend_client_note_connection_attempt_ended():
 Connection attempt for yjiqkj6p7drpiwyq has ended; cleaning up temporary
 state.
 Jan 15 16:22:05.596 [info] rend_client_note_connection_attempt_ended():
 Connection attempt for yjiqkj6p7drpiwyq has ended; cleaning up temporary
 state.
 }}}
 and then your application stream gets closed.

 Then two minutes later (!), you see these controller events:
 {{{
 1421357045.919921 [torctl-log] localhost:9051 650 HS_DESC REQUESTED
 yjiqkj6p7drpiwyq NO_AUTH $0B569B9F3999ACA1E7F52EA2C41841F9DDA89C3D~Unnamed
 blwd4dzs2mnncf4wtc3bpv6pljwx5awb
 1421357047.114483 [torctl-log] localhost:9051 650 HS_DESC RECEIVED
 yjiqkj6p7drpiwyq NO_AUTH $0B569B9F3999ACA1E7F52EA2C41841F9DDA89C3D~Unnamed
 }}}

 It turns out that happens because the intro circuit finally closes:
 {{{
 Jan 15 16:24:05.918 [info] circuit_expire_building(): Abandoning circ 5
 195.154.127.246:9001:2375802890 (state 1,3:open, purpose 6, len 6)
 Jan 15 16:24:05.918 [info] internal circ (length 6):
 $4FEE77AFFD157BBCF2D896AE417FBF647860466C(open)
 $F4F605AA21C4633CCB5B8DBBC1CEEE5C590C6DCE(open)
 $B6D30CEC9F8FAB676CCD0634DC86412F1BA8F4D2(open)
 $5B3B9A0EA1DC16F6348C57FCC83BBB43D1013F4A(open)
 $10B6A20E3F1D0C0742053A19242AB61586A5B9B4(open)
 $D51C1F3A39FB0BCA12D2795F67B1FA93A750218D(open)
 }}}

 which is reasonable, except, then:
 {{{
 Jan 15 16:24:05.918 [info] circuit_mark_for_close_(): Failed intro circ
 yjiqkj6p7drpiwyq to $D51C1F3A39FB0BCA12D2795F67B1FA93A750218D (building
 circuit to intro point). Marking intro point as possibly unreachable.
 Jan 15 16:24:05.918 [info] rend_client_report_intro_point_failure():
 Unknown service "yjiqkj6p7drpiwyq". Re-fetching descriptor.
 Jan 15 16:24:05.918 [debug] rend_client_refetch_v2_renddesc(): Fetching v2
 rendezvous descriptor for service yjiqkj6p7drpiwyq
 }}}

 It looks like the closing of the intro circuit, 2 minutes later, triggers
 another fetching of a descriptor!

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