[tor-bugs] #25882 [Core Tor/Tor]: clients not detecting stale onion service introduction points
Tor Bug Tracker & Wiki
blackhole at torproject.org
Sat Apr 28 20:53:29 UTC 2018
#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
More information about the tor-bugs
mailing list