[tor-bugs] #21084 [Core Tor/Tor]: sometimes we call circuit has_opened() more than 2 times on client side

[Tor Bug Tracker & Wiki]

#21084: sometimes we call circuit has_opened() more than 2 times on client side
------------------------------+--------------------------------
     Reporter:  s7r           |      Owner:
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:
    Component:  Core Tor/Tor  |    Version:  Tor: 0.3.0.1-alpha
     Severity:  Normal        |   Keywords:  tor-hs
Actual Points:                |  Parent ID:
       Points:                |   Reviewer:
      Sponsor:                |
------------------------------+--------------------------------
 We have a branch `bug15618_030-testing` at
 https://gitweb.torproject.org/user/dgoulet/tor.git that logs a warning
 when we call more than 2 times `circuit has_opened()` on a circuit. The
 patch was made to confirm the theory on #15618 related to a warning we see
 on relays. While until now I never saw the warning on relay side, I see it
 quite often on client side.

 Based on the log messages, I think this is related to introduction point
 circuits and not rendezvous circuits as we thought. Basically it happens
 when we open a 4 hop circuit with last hop X, and immediately we extend
 that circuit to a 5 hop one with last hop Y, where Y is (I think) the
 introduction point. I got the warning 2 times in a row and the similarity
 between them is that they are 5 hop circuits with the last two hops 4 and
 5 the same, but different hops 2 and 3.

 {{{
 Dec 25 13:15:15.000 [info] internal circ (length 5, last hop
 $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7):
 $A7C411B809D0AA98C4264917BB701ABF17B2181E(open)
 $B5212DB685A2A0FCFBAE425738E478D12361710D(open)
 $123F403DA94A74F959B7FE0E5B27FA57EFA12925(open)
 $1F4105C688E835A56AF3D66C787677B57240FFA2(open)
 $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7(open)
 Dec 25 13:15:15.000 [info] entry_guards_note_guard_success(): Recorded
 success for primary confirmed guard sakujakira
 ($A7C411B809D0AA98C4264917BB701ABF17B2181E)
 Dec 25 13:15:15.000 [info] circuit_send_next_onion_skin(): circuit built!
 Dec 25 13:15:15.000 [warn] BLAM. Circuit has_opened() called 3 times.
 Dec 25 13:15:15.000 [info] rend_client_introcirc_has_opened(): introcirc
 is open
 Dec 25 13:15:15.000 [info] connection_ap_handshake_attach_circuit():
 pending-join circ 3419634369 already here, with intro ack. Stalling.
 (stream 26 sec old)
 Dec 25 13:15:15.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 2404371907 already here (no intro-ack yet on intro 2259155742).
 (stream 26 sec old)
 Dec 25 13:15:15.000 [info] connection_ap_handshake_attach_circuit(): found
 open intro circ 2259155742 (rend 2404371907); sending introduction.
 (stream 26 sec old)
 Dec 25 13:15:15.000 [info] rend_client_send_introduction(): Sending an
 INTRODUCE1 cell
 Dec 25 13:15:15.000 [info] pathbias_count_use_attempt(): Used circuit
 53293 is already in path state use succeeded. Circuit is a Hidden service
 client: Pending rendezvous point currently open.
 }}}

 {{{
 Dec 25 13:15:16.000 [info] internal circ (length 5, last hop
 $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7):
 $A7C411B809D0AA98C4264917BB701ABF17B2181E(open)
 $5C01D5518D1F5A071C6F07D1F4630F577AB5B60A(open)
 $DA9DA02A7B0565DF5F3E961CA911E750072DCBBD(open)
 $1F4105C688E835A56AF3D66C787677B57240FFA2(open)
 $D7316BF7FD633DD7474B18C33E1D5FDEB04D26A7(open)
 Dec 25 13:15:16.000 [info] entry_guards_note_guard_success(): Recorded
 success for primary confirmed guard sakujakira
 ($A7C411B809D0AA98C4264917BB701ABF17B2181E)
 Dec 25 13:15:16.000 [info] circuit_send_next_onion_skin(): circuit built!
 Dec 25 13:15:16.000 [warn] BLAM. Circuit has_opened() called 3 times.
 Dec 25 13:15:16.000 [info] rend_client_introcirc_has_opened(): introcirc
 is open
 Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit():
 pending-join circ 3419634369 already here, with intro ack. Stalling.
 (stream 26 sec old)
 Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): Intro
 circ 2259155742 present and awaiting ack (rend 2404371907). Stalling.
 (stream 26 sec old)
 Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): Intro
 circ 3200472182 present and awaiting ack (rend 4286776399). Stalling.
 (stream 26 sec old)
 Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): ready
 rend circ 2334828448 already here (no intro-ack yet on intro 4002828471).
 (stream 27 sec old)
 Dec 25 13:15:16.000 [info] connection_ap_handshake_attach_circuit(): found
 open intro circ 4002828471 (rend 2334828448); sending introduction.
 (stream 27 sec old)
 Dec 25 13:15:16.000 [info] rend_client_send_introduction(): Sending an
 INTRODUCE1 cell
 Dec 25 13:15:16.000 [info] pathbias_count_use_attempt(): Used circuit
 53301 is already in path state use succeeded. Circuit is a Hidden service
 client: Pending rendezvous point currently open.
 }}}

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