[tor-bugs] #28962 [Core Tor/Tor]: circuits are not both ready. Stalling conn.

[Tor Bug Tracker & Wiki]

#28962: circuits are not both ready. Stalling conn.
------------------------------+------------------------------
     Reporter:  traumschule   |      Owner:  (none)
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:  Tor: unspecified
    Component:  Core Tor/Tor  |    Version:
     Severity:  Normal        |   Keywords:
Actual Points:                |  Parent ID:
       Points:                |   Reviewer:
      Sponsor:                |
------------------------------+------------------------------
 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)
 }}}

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