#28962: circuits are not both ready. Stalling conn.
--------------------------+------------------------------------
 Reporter:  traumschule   |          Owner:  (none)
     Type:  defect        |         Status:  new
 Priority:  Medium        |      Milestone:  Tor: 0.4.0.x-final
Component:  Core Tor/Tor  |        Version:
 Severity:  Normal        |     Resolution:
 Keywords:  tor-hs        |  Actual Points:
Parent ID:                |         Points:
 Reviewer:                |        Sponsor:
--------------------------+------------------------------------

Old description:

> My Tor 0.4.0.0-alpha-dev client shows {{{circuits are not both ready.
> Stalling conn.}}} and most connections hang for some minutes until it
> let‘s through a bunch and hangs again.
>
> It‘s confusing to see netflow padding while waiting for connections,
> looks like an instance of #23681. Maybe it just means that the guard is
> under load?
>
> Relevant code is around src/core/or/circuituse.c:3025.
> Log shows a lot of timeouts like:
> {{{
> Dec 30 10:48:14.000 [info] circuit_build_times_get_xm(): Xm mode #0: 325
> 75
> Dec 30 10:48:14.000 [info] circuit_build_times_get_xm(): Xm mode #1: 375
> 47
> Dec 30 10:48:14.000 [info] circuit_build_times_get_xm(): Xm mode #2: 325
> 75
> Dec 30 10:48:14.000 [info] circuit_build_times_set_timeout_worker():
> Circuit build measurement period of 1337373ms is more than twice the
> maximum build time we have ever observed. Capping it to 1143450ms.
> Dec 30 10:48:14.000 [info] circuit_build_times_set_timeout(): Set circuit
> build timeout to 29s (28864.874645ms, 1143450.000000ms, Xm: 336, a:
> 0.361406, r: 0.282000) based on 1000 circuit times
> Dec 30 10:48:14.000 [info] entry_guards_note_guard_success(): Recorded
> success for primary confirmed guard <scrubbed>
> Dec 30 10:48:14.000 [info] circuit_build_no_more_hops(): circuit built!
> Dec 30 10:48:14.000 [info] pathbias_count_build_success(): Got success
> count 209.532891/219.352138 for guard <scrubbed>
> Dec 30 10:48:14.000 [info] connection_ap_handshake_attach_circuit():
> Intro circ 4177057486 (id: 2028) present and awaiting ACK. Rend circuit
> 3511196698 (id: 2011). Stalling. (stream 41 sec old)
> Dec 30 10:48:14.000 [info] or_state_save(): Saved state to
> "/var/lib/tor/state"
> Dec 30 10:48:14.000 [info] rend_client_introduction_acked(): Got nack for
> [scrubbed] from [scrubbed]...
> Dec 30 10:48:14.000 [info] rend_client_report_intro_point_failure(): 5
> options left for [scrubbed].
> Dec 30 10:48:14.000 [info] hs_client_reextend_intro_circuit(): Re-
> extending circ 4177057486, this time to [scrubbed].
> Dec 30 10:48:14.000 [info] circuit_send_intermediate_onion_skin():
> Sending extend relay cell.
> Dec 30 10:48:14.000 [info] connection_ap_handshake_attach_circuit():
> ready rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on
> intro 4177057486 (id: 2028). (stream 41 sec old)
> Dec 30 10:48:14.000 [info] connection_ap_handshake_attach_circuit():
> Intro 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011)
> circuits are not both ready. Stalling conn. (41 sec old)
> ...
> Dec 30 10:49:01.000 [info] connection_ap_handshake_attach_circuit():
> Intro 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011)
> circuits are not both ready. Stalling conn. (88 sec old)
> Dec 30 10:49:02.000 [info] connection_ap_handshake_attach_circuit():
> ready rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on
> intro 4177057486 (id: 2028). (stream 89 sec old)
> Dec 30 10:49:02.000 [info] connection_ap_handshake_attach_circuit():
> Intro 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011)
> circuits are not both ready. Stalling conn. (89 sec old)
> Dec 30 10:49:03.000 [info] connection_ap_handshake_attach_circuit():
> ready rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on
> intro 4177057486 (id: 2028). (stream 90 sec old)
> Dec 30 10:49:03.000 [info] connection_ap_handshake_attach_circuit():
> Intro 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011)
> circuits are not both ready. Stalling conn. (90 sec old)
> Dec 30 10:49:04.000 [info]
> channelpadding_send_padding_cell_for_callback(): Sending netflow
> keepalive on 608 to [scrubbed] ([scrubbed]) after 8689 ms. Delta 1ms
> Dec 30 10:49:04.000 [info] connection_ap_handshake_attach_circuit():
> ready rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on
> intro 4177057486 (id: 2028). (stream 91 sec old)
> Dec 30 10:49:04.000 [info] connection_ap_handshake_attach_circuit():
> Intro 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011)
> circuits are not both ready. Stalling conn. (91 sec old)
> Dec 30 10:49:05.000 [info] connection_ap_handshake_attach_circuit():
> ready rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on
> intro 4177057486 (id: 2028). (stream 92 sec old)
> Dec 30 10:49:05.000 [info] connection_ap_handshake_attach_circuit():
> Intro 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011)
> circuits are not both ready. Stalling conn. (92 sec old)
> Dec 30 10:49:07.000 [info] connection_ap_handshake_attach_circuit():
> ready rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on
> intro 4177057486 (id: 2028). (stream 93 sec old)
> Dec 30 10:49:07.000 [info] connection_ap_handshake_attach_circuit():
> Intro 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011)
> circuits are not both ready. Stalling conn. (93 sec old)
> }}}

New description:

 Using an unstable (wifi) connection my Tor 0.4.0.0-alpha-dev client shows
 {{{circuits are not both ready. Stalling conn.}}} and most connections
 hang for some minutes until it let‘s through a bunch and hangs again.

 It‘s confusing to see netflow padding while waiting for connections, looks
 like an instance of #23681.

 Relevant code is around src/core/or/circuituse.c:3025.
 Log shows a lot of timeouts like:
 {{{
 Dec 30 10:48:14.000 [info] circuit_build_times_get_xm(): Xm mode #0: 325
 75
 Dec 30 10:48:14.000 [info] circuit_build_times_get_xm(): Xm mode #1: 375
 47
 Dec 30 10:48:14.000 [info] circuit_build_times_get_xm(): Xm mode #2: 325
 75
 Dec 30 10:48:14.000 [info] circuit_build_times_set_timeout_worker():
 Circuit build measurement period of 1337373ms is more than twice the
 maximum build time we have ever observed. Capping it to 1143450ms.
 Dec 30 10:48:14.000 [info] circuit_build_times_set_timeout(): Set circuit
 build timeout to 29s (28864.874645ms, 1143450.000000ms, Xm: 336, a:
 0.361406, r: 0.282000) based on 1000 circuit times
 Dec 30 10:48:14.000 [info] entry_guards_note_guard_success(): Recorded
 success for primary confirmed guard <scrubbed>
 Dec 30 10:48:14.000 [info] circuit_build_no_more_hops(): circuit built!
 Dec 30 10:48:14.000 [info] pathbias_count_build_success(): Got success
 count 209.532891/219.352138 for guard <scrubbed>
 Dec 30 10:48:14.000 [info] connection_ap_handshake_attach_circuit(): Intro
 circ 4177057486 (id: 2028) present and awaiting ACK. Rend circuit
 3511196698 (id: 2011). Stalling. (stream 41 sec old)
 Dec 30 10:48:14.000 [info] or_state_save(): Saved state to
 "/var/lib/tor/state"
 Dec 30 10:48:14.000 [info] rend_client_introduction_acked(): Got nack for
 [scrubbed] from [scrubbed]...
 Dec 30 10:48:14.000 [info] rend_client_report_intro_point_failure(): 5
 options left for [scrubbed].
 Dec 30 10:48:14.000 [info] hs_client_reextend_intro_circuit(): Re-
 extending circ 4177057486, this time to [scrubbed].
 Dec 30 10:48:14.000 [info] circuit_send_intermediate_onion_skin(): Sending
 extend relay cell.
 Dec 30 10:48:14.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on intro
 4177057486 (id: 2028). (stream 41 sec old)
 Dec 30 10:48:14.000 [info] connection_ap_handshake_attach_circuit(): Intro
 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011) circuits are
 not both ready. Stalling conn. (41 sec old)
 ...
 Dec 30 10:49:01.000 [info] connection_ap_handshake_attach_circuit(): Intro
 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011) circuits are
 not both ready. Stalling conn. (88 sec old)
 Dec 30 10:49:02.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on intro
 4177057486 (id: 2028). (stream 89 sec old)
 Dec 30 10:49:02.000 [info] connection_ap_handshake_attach_circuit(): Intro
 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011) circuits are
 not both ready. Stalling conn. (89 sec old)
 Dec 30 10:49:03.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on intro
 4177057486 (id: 2028). (stream 90 sec old)
 Dec 30 10:49:03.000 [info] connection_ap_handshake_attach_circuit(): Intro
 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011) circuits are
 not both ready. Stalling conn. (90 sec old)
 Dec 30 10:49:04.000 [info]
 channelpadding_send_padding_cell_for_callback(): Sending netflow keepalive
 on 608 to [scrubbed] ([scrubbed]) after 8689 ms. Delta 1ms
 Dec 30 10:49:04.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on intro
 4177057486 (id: 2028). (stream 91 sec old)
 Dec 30 10:49:04.000 [info] connection_ap_handshake_attach_circuit(): Intro
 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011) circuits are
 not both ready. Stalling conn. (91 sec old)
 Dec 30 10:49:05.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on intro
 4177057486 (id: 2028). (stream 92 sec old)
 Dec 30 10:49:05.000 [info] connection_ap_handshake_attach_circuit(): Intro
 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011) circuits are
 not both ready. Stalling conn. (92 sec old)
 Dec 30 10:49:07.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 3511196698 (id: 2011) already here. Nointro-ack yet on intro
 4177057486 (id: 2028). (stream 93 sec old)
 Dec 30 10:49:07.000 [info] connection_ap_handshake_attach_circuit(): Intro
 4177057486 (id: 2028) and rend circuit 3511196698 (id: 2011) circuits are
 not both ready. Stalling conn. (93 sec old)
 }}}

--

Comment (by traumschule):

 Removing wrong assumption.

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

Reply via email to