[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

Re: [tor-bugs] #25882 [Core Tor/Tor]: clients not detecting stale onion service introduction points



#25882: clients not detecting stale onion service introduction points
--------------------------+------------------------------------
 Reporter:  cypherpunks   |          Owner:  (none)
     Type:  defect        |         Status:  assigned
 Priority:  Medium        |      Milestone:  Tor: 0.3.4.x-final
Component:  Core Tor/Tor  |        Version:
 Severity:  Normal        |     Resolution:
 Keywords:  tor-hs        |  Actual Points:
Parent ID:  #22455        |         Points:
 Reviewer:                |        Sponsor:
--------------------------+------------------------------------

Comment (by cypherpunks):

 Digging a bit deeper into {{{debug.A.log}}}, we find that Tor tries some
 random descriptors but ultimately keeps choosing 185.2.172.237 as an intro
 point.  After 06:30:17, it is the only one remaining that has not been·

 {{{
 $ grep "\(as intro point\)\|\(Failed to reach\)" debug.A.log | head -40
 Apr 27 06:30:01.000 [info] circuit_get_open_circ_or_launch(): Chose
 $DC161F3B2FF30446A14B69A1E6493FD6300A45D2~$DC161F3B2FF30446A1 at
 185.50.191.250 as intro point for '[scrubbed]'.
 Apr 27 06:30:01.000 [info] circuit_get_open_circ_or_launch(): Chose
 $35E8B344F661F4F2E68B17648F35798B44672D7E~$35E8B344F661F4F2E6 at
 146.0.32.144 as intro point for '[scrubbed]'.
 Apr 27 06:30:01.000 [info] circuit_get_open_circ_or_launch(): Chose
 $813BD9A5FF580C9BDDD9767E85D4CF6FC868B20D~$813BD9A5FF580C9BDD at
 82.118.17.235 as intro point for '[scrubbed]'.
 Apr 27 06:30:04.000 [info] circuit_get_open_circ_or_launch(): Chose
 $8FA6BBB26DDD237A22DD11866D196357F29BC19E~$8FA6BBB26DDD237A22 at
 134.119.217.250 as intro point for '[scrubbed]'.
 Apr 27 06:30:05.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:06.000 [info] circuit_get_open_circ_or_launch(): Chose
 $73A9297A6741DF33F4D1B7BB935B30B6A1D25B52~$73A9297A6741DF33F4 at
 46.101.100.94 as intro point for '[scrubbed]'.
 Apr 27 06:30:06.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:07.000 [info] circuit_get_open_circ_or_launch(): Chose
 $E1D0BA78D83BC0A5E7F1A791973022AE15C3548E~$E1D0BA78D83BC0A5E7 at
 185.100.86.249 as intro point for '[scrubbed]'.
 Apr 27 06:30:07.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 2 times.
 Apr 27 06:30:07.000 [info] circuit_get_open_circ_or_launch(): Chose
 $500FD47E7503B0C51EAD9E250A0119EBEE56EC5C~$500FD47E7503B0C51E at
 173.212.248.165 as intro point for '[scrubbed]'.
 Apr 27 06:30:09.000 [info] circuit_get_open_circ_or_launch(): Chose
 $FAA935B0BC3B4348CCBD3EBA95681AB51730977D~$FAA935B0BC3B4348CC at
 89.163.225.7 as intro point for '[scrubbed]'.
 Apr 27 06:30:10.000 [info] circuit_get_open_circ_or_launch(): Chose
 $FDAC8BA3ABFCC107D1B1EAC953F195BEEBA7FF54~$FDAC8BA3ABFCC107D1 at
 62.210.84.34 as intro point for '[scrubbed]'.
 Apr 27 06:30:11.000 [info] circuit_get_open_circ_or_launch(): Chose
 $3E515AB55BCFDD1E9ED1515B60223A08EE7710F0~$3E515AB55BCFDD1E9E at
 144.76.61.48 as intro point for '[scrubbed]'.
 Apr 27 06:30:11.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 3 times.
 Apr 27 06:30:12.000 [info] circuit_get_open_circ_or_launch(): Chose
 $3E515AB55BCFDD1E9ED1515B60223A08EE7710F0~$3E515AB55BCFDD1E9E at
 144.76.61.48 as intro point for '[scrubbed]'.
 Apr 27 06:30:12.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 4 times.
 Apr 27 06:30:12.000 [info] circuit_get_open_circ_or_launch(): Chose
 $B493C692A62D8D24E93DD50113653A4D0152B7C5~$B493C692A62D8D24E9 at
 176.24.237.138 as intro point for '[scrubbed]'.
 Apr 27 06:30:13.000 [info] circuit_get_open_circ_or_launch(): Chose
 $3E515AB55BCFDD1E9ED1515B60223A08EE7710F0~$3E515AB55BCFDD1E9E at
 144.76.61.48 as intro point for '[scrubbed]'.
 Apr 27 06:30:13.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0F85E6DB0E4A3B6FDDF7C9452C9B5D089B11979D~$0F85E6DB0E4A3B6FDD at
 31.31.73.222 as intro point for '[scrubbed]'.
 Apr 27 06:30:13.000 [info] circuit_get_open_circ_or_launch(): Chose
 $E0EAA536856FBD3C3AB46C2BAA398E7CDFDAFF5D~$E0EAA536856FBD3C3A at
 77.87.50.6 as intro point for '[scrubbed]'.
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 5 times. Removing from descriptor.
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:15.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:15.000 [info] circuit_get_open_circ_or_launch(): Chose
 $99B6BE15B92A8746D14308F6C7FD84C28034335C~$99B6BE15B92A8746D1 at
 188.230.183.231 as intro point for '[scrubbed]'.
 Apr 27 06:30:17.000 [info] circuit_get_open_circ_or_launch(): Chose
 $D64366987CB39F61AD21DBCF8142FA0577B92811~$D64366987CB39F61AD at
 37.221.162.226 as intro point for '[scrubbed]'.
 Apr 27 06:30:20.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:22.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:25.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:27.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:29.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:31.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:34.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:36.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:38.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:40.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:42.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:45.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:48.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:51.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:53.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 }}}

 Notice that once we reach the intro point 185.22.172.237, Tor gets stuck.
 (Note that the log message about choosing 185.22.172.237 occurs 75 more
 times between 06:30:53 and 06:33:59.)  Note that we are not noticing that
 it is unreachable, as we do for some other intro points:

 {{{
 $ grep "Failed" debug.A.log | more
 Apr 27 06:30:05.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:05.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:06.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:06.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:07.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:07.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 2 times.
 Apr 27 06:30:08.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:09.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:10.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:11.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:11.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 3 times.
 Apr 27 06:30:12.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:12.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 4 times.
 Apr 27 06:30:13.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 5 times. Removing from descriptor.
 Apr 27 06:30:13.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:15.000 [info] circuit_about_to_free(): Failed intro circ
 [scrubbed] to [scrubbed] (building circuit to intro point). Marking intro
 point as possibly unreachable.
 }}}

 One of the problems with these logs is that my Tor is trying to connect to
 several different onion services around the same time.  As you can see
 here, the descriptors for three of the hidden services in question are
 actually re-fetched, as they ought to be, although after 06:30:18, there
 is "1 options left" for the service that is stuck with 185.22.172.237
 (note: it might be nice to have some kind of unique identifier, perhaps
 the stream ID, for each of these hidden services, so that we can correlate
 them with each other in the log, rather than just see the same
 "[scrubbed]" for each):

 {{{
 $ grep -i "rend_client_report_intro_point_failure" debug.A.log | more
 Apr 27 06:30:04.000 [info] rend_client_report_intro_point_failure(): 5
 options left for [scrubbed].
 Apr 27 06:30:04.000 [info] rend_client_report_intro_point_failure(): 9
 options left for [scrubbed].
 Apr 27 06:30:05.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:05.000 [info] rend_client_report_intro_point_failure(): 5
 options left for [scrubbed].
 Apr 27 06:30:05.000 [info] rend_client_report_intro_point_failure(): 8
 options left for [scrubbed].
 Apr 27 06:30:05.000 [info] rend_client_report_intro_point_failure(): 4
 options left for [scrubbed].
 Apr 27 06:30:06.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:06.000 [info] rend_client_report_intro_point_failure(): 6
 options left for [scrubbed].
 Apr 27 06:30:06.000 [info] rend_client_report_intro_point_failure(): 3
 options left for [scrubbed].
 Apr 27 06:30:06.000 [info] rend_client_report_intro_point_failure(): 5
 options left for [scrubbed].
 Apr 27 06:30:07.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 2 times.
 Apr 27 06:30:07.000 [info] rend_client_report_intro_point_failure(): 3
 options left for [scrubbed].
 Apr 27 06:30:07.000 [info] rend_client_report_intro_point_failure(): 7
 options left for [scrubbed].
 Apr 27 06:30:07.000 [info] rend_client_report_intro_point_failure(): 4
 options left for [scrubbed].
 Apr 27 06:30:08.000 [info] rend_client_report_intro_point_failure(): 6
 options left for [scrubbed].
 Apr 27 06:30:08.000 [info] rend_client_report_intro_point_failure(): 6
 options left for [scrubbed].
 Apr 27 06:30:08.000 [info] rend_client_report_intro_point_failure(): 2
 options left for [scrubbed].
 Apr 27 06:30:08.000 [info] rend_client_report_intro_point_failure(): 3
 options left for [scrubbed].
 Apr 27 06:30:08.000 [info] rend_client_report_intro_point_failure(): 5
 options left for [scrubbed].
 Apr 27 06:30:09.000 [info] rend_client_report_intro_point_failure(): 3
 options left for [scrubbed].
 Apr 27 06:30:09.000 [info] rend_client_report_intro_point_failure(): 1
 options left for [scrubbed].
 Apr 27 06:30:09.000 [info] rend_client_report_intro_point_failure(): 4
 options left for [scrubbed].
 Apr 27 06:30:09.000 [info] rend_client_report_intro_point_failure(): 2
 options left for [scrubbed].
 Apr 27 06:30:10.000 [info] rend_client_report_intro_point_failure(): 4
 options left for [scrubbed].
 Apr 27 06:30:10.000 [info] rend_client_report_intro_point_failure(): 1
 options left for [scrubbed].
 Apr 27 06:30:10.000 [info] rend_client_report_intro_point_failure(): 3
 options left for [scrubbed].
 Apr 27 06:30:11.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 3 times.
 Apr 27 06:30:11.000 [info] rend_client_report_intro_point_failure(): 1
 options left for [scrubbed].
 Apr 27 06:30:11.000 [info] rend_client_report_intro_point_failure(): No
 more intro points remain for [scrubbed]. Re-fetching descriptor.
 Apr 27 06:30:12.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 4 times.
 Apr 27 06:30:12.000 [info] rend_client_report_intro_point_failure(): 1
 options left for [scrubbed].
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 5 times. Removing from descriptor.
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure(): No
 more intro points remain for [scrubbed]. Re-fetching descriptor.
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure():
 Failed to reach this intro point 1 times.
 Apr 27 06:30:13.000 [info] rend_client_report_intro_point_failure(): 6
 options left for [scrubbed].
 Apr 27 06:30:15.000 [info] rend_client_report_intro_point_failure(): No
 more intro points remain for [scrubbed]. Re-fetching descriptor.
 Apr 27 06:30:15.000 [info] rend_client_report_intro_point_failure(): 2
 options left for [scrubbed].
 Apr 27 06:30:18.000 [info] rend_client_report_intro_point_failure(): 1
 options left for [scrubbed].
 }}}

 Note also that in {{{circuit_about_to_free}}} in {{{circuitlist.c}}}, we
 never seem to record any timeouts for the bad intro point, despite the
 fact that we are deciding that it is too old (see description of ticket
 and comment:6 above:

 {{{
     if (orig_reason != END_CIRC_REASON_IP_NOW_REDUNDANT &&
         ocirc->rend_data) {
       /* treat this like getting a nack from it */
       log_info(LD_REND, "Failed intro circ %s to %s (awaiting ack). %s",
           safe_str_client(rend_data_get_address(ocirc->rend_data)),
 safe_str_client(build_state_get_exit_nickname(ocirc->build_state)),
           timed_out ? "Recording timeout." : "Removing from descriptor.");
 rend_client_report_intro_point_failure(ocirc->build_state->chosen_exit,
                                              ocirc->rend_data,
                                              timed_out ?
                                              INTRO_POINT_FAILURE_TIMEOUT :
                                              INTRO_POINT_FAILURE_GENERIC);
     }
 }}}

 The circuits are indeed reaped.  For example, circuit 878 is freed about
 one second after its purpose is reassigned:

 {{{
 Apr 27 06:30:20.000 [info] circuit_get_open_circ_or_launch(): Chose
 $0074ECA82BD58B8BB1909C9C4F237FD9779B23FC~$0074ECA82BD58B8BB1 at
 185.22.172.237 as intro point for '[scrubbed]'.
 Apr 27 06:30:20.000 [debug] circuit_find_to_cannibalize(): Hunting for a
 circ to cannibalize: purpose 6, uptime 0, capacity 1, internal 1
 Apr 27 06:30:20.000 [info] circuit_launch_by_extend_info(): Cannibalizing
 circ 3959015402 (id: 878) for purpose 6 (Hidden service client: Connecting
 to intro point)
 Apr 27 06:30:20.000 [debug] circuit_change_purpose(): changing purpose of
 origin circ 878 from "General-purpose client" (5) to "Hidden service
 client: Connecting to intro point" (6)

 [...]

 Apr 27 06:30:21.000 [debug] circuit_get_by_circid_channel_impl():
 circuit_get_by_circid_channel_impl() returning circuit 0x125e268 for
 circ_id 3959015402, channel ID 174 (0x1afb648)
 Apr 27 06:30:21.000 [debug] circuitmux_append_destroy_cell(): Cmux at
 0x14fd5a0 queued a destroy for circ 3959015402, cmux counter is now 1,
 global counter is now 1
 Apr 27 06:30:21.000 [debug] circuitmux_append_destroy_cell(): Primed a
 buffer.
 Apr 27 06:30:21.000 [debug] channel_write_cell_generic_(): Writing p
 0x14838f0 to channel 0x1afb648 with global ID 174
 Apr 27 06:30:21.000 [debug] circuit_get_by_circid_channel_impl():
 circuit_get_by_circid_channel_impl() returning circuit 0x125e268 for
 circ_id 3959015402, channel ID 174 (0x1afb648)
 Apr 27 06:30:21.000 [debug] channel_tls_get_overhead_estimate_method():
 Estimated overhead ratio for TLS chan 174 is 1.040139
 Apr 27 06:30:21.000 [debug] channel_update_xmit_queue_size(): Increasing
 queue size for channel 174 by 534 from 0 to 534
 Apr 27 06:30:21.000 [debug] channel_update_xmit_queue_size(): Increasing
 global queue size by 534 for channel 174, new size is 534
 Apr 27 06:30:21.000 [debug] circuitmux_notify_xmit_destroy(): Cmux at
 0x14fd5a0 sent a destroy, cmux counter is now 0, global counter is now 0
 Apr 27 06:30:21.000 [debug] channel_send_destroy(): Sending destroy
 (circID 3959015402) on channel 0x1afb648 (global ID 174)
 Apr 27 06:30:21.000 [info] circuit_free(): Circuit 0 (id: 878) has been
 freed.
 }}}

 But why is the timeout not recorded?  Looking in
 {{{circuit_about_to_free}}} in {{{circuitlist.c}}}, have we not set
 {{{ocirc->rend_data}}}?  Or have we failed to set the purpose
 to{{{CIRCUIT_PURPOSE_C_INTRODUCE_ACK_WAIT}}} (I would have guessed that we
 do this in {{{send_introduce1}}} in {{{circuituse.c}}}.)  More
 investigation would be useful, although I would surmise that adding
 debugging statements to {{{circuit_about_to_free}}} would be the next
 step.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/25882#comment:11>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs