[tor-bugs] #23681 [Core Tor/Tor]: prop224: Clients mark intro circs as timed-out within seconds

[Tor Bug Tracker & Wiki]

#23681: prop224: Clients mark intro circs as timed-out within seconds
------------------------------+--------------------------------
     Reporter:  asn           |      Owner:  (none)
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:  Tor: 0.3.2.x-final
    Component:  Core Tor/Tor  |    Version:
     Severity:  Normal        |   Keywords:  prop224, tor-hs
Actual Points:                |  Parent ID:
       Points:                |   Reviewer:
      Sponsor:                |
------------------------------+--------------------------------
 I noticed that my prop224 client had some reconnects and I did some log
 digging. The original disconnect was caused by a truncate cell (probably
 natural causes) but then a whole dance of introduction/rendezvous started
 which ended up marking 3 intro circs as timed out within seconds:
 {{{
 <FIRST TIMED-OUT INTRO CIRC>
 Sep 28 03:55:26.000 [notice] Introduction circuit 2276964442 has opened.
 Attaching streams.
 Sep 28 03:55:26.000 [info] connection_ap_handshake_attach_circuit(): Intro
 (2276964442) and rend (2943321454) circs are not both ready. Stalling
 conn. (2 sec old)
 Sep 28 03:55:29.000 [info] circuit_expire_building(): Marking circ
 2276964442 (state 4:open, purpose 6) as timed-out HS circ
 <SECOND TIMED-OUT INTRO CIRC>
 Sep 28 03:55:29.000 [info] circuit_get_best(): There is an intro circuit
 being created right now, but it has already taken quite a while. Starting
 one in parallel.
 Sep 28 03:55:29.000 [notice] Introduction circuit 4126528467 has opened.
 Attaching streams.
 Sep 28 03:55:29.000 [info] connection_ap_handshake_attach_circuit(): Intro
 (4126528467) and rend (2943321454) circs are not both ready. Stalling
 conn. (5 sec old)
 Sep 28 03:55:34.000 [info] circuit_expire_building(): Marking circ
 4126528467 (state 4:open, purpose 6) as timed-out HS circ
 <THIRD TIMED-OUT INTRO CIRC>
 Sep 28 03:55:29.000 [info] circuit_get_best(): There is an intro circuit
 being created right now, but it has already taken quite a while. Starting
 one in parallel.
 Sep 28 03:55:34.000 [notice] Introduction circuit 4282777781 has opened.
 Attaching streams.
 Sep 28 03:55:34.000 [info] connection_ap_handshake_attach_circuit(): Intro
 (4282777781) and rend (2943321454) circs are not both ready. Stalling
 conn. (10 sec old)
 Sep 28 03:55:39.000 [info] circuit_expire_building(): Marking circ
 4282777781 (state 4:open, purpose 6) as timed-out HS circ
 <CIRCUITS CLOSE>
 Sep 28 03:57:26.000 [info] circuit_expire_building(): Abandoning circ 232
 137.205.124.35:1720:2276964442 (state 1,4:open, purpose 6, len 4)
 Sep 28 03:57:26.000 [info] circuit_mark_for_close_(): Circuit 2276964442
 (id: 232) marked for close at src/or/circuituse.c:820 (orig reason: 10,
 new reason: 0)
 Sep 28 03:57:30.000 [info] circuit_expire_building(): Abandoning circ 231
 137.205.124.35:1720:4126528467 (state 1,4:open, purpose 6, len 4)
 Sep 28 03:57:30.000 [info] circuit_mark_for_close_(): Circuit 4126528467
 (id: 231) marked for close at src/or/circuituse.c:820 (orig reason: 10,
 new reason: 0)
 Sep 28 03:57:35.000 [info] circuit_expire_building(): Abandoning circ 233
 137.205.124.35:1720:4282777781 (state 1,4:open, purpose 6, len 4)
 Sep 28 03:57:35.000 [info] circuit_mark_for_close_(): Circuit 4282777781
 (id: 233) marked for close at src/or/circuituse.c:820 (orig reason: 10,
 new reason: 0)
 }}}

 You can see that we went ahead and marked intro circs as timed-out within
 3 seconds of launching them which makes no sense, and caused a whole lot
 of mess in the prop224 state machine.

 We should try to figure out if there is a bug here.

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