[tor-bugs] #23603 [Core Tor/Tor]: hs: Cleanup race between circuit close and free with the HS circuitmap

[Tor Bug Tracker & Wiki]

#23603: hs: Cleanup race between circuit close and free with the HS circuitmap
--------------------------+------------------------------------
 Reporter:  dgoulet       |          Owner:  (none)
     Type:  defect        |         Status:  new
 Priority:  High          |      Milestone:  Tor: 0.3.2.x-final
Component:  Core Tor/Tor  |        Version:
 Severity:  Normal        |     Resolution:
 Keywords:  tor-hs        |  Actual Points:
Parent ID:                |         Points:
 Reviewer:                |        Sponsor:
--------------------------+------------------------------------

Comment (by asn):

 OK I had this happen to me again on my unstable service.

 Here is the creation of the circuit:
 {{{
 Sep 23 02:33:29.000 [info] hs_circ_launch_intro_point(): Launching a
 circuit to intro point $809814F480D046EF977004BD545914BFFA47C06D~uhkakw at
 185.148.145.74 for service
 4acth47i6kxnvkewtm6q7ib2s3ufpo5sqbsnzjpbi7utijcltosqemad.
 Sep 23 02:33:29.000 [info] origin_circuit_new(): Circuit 697 chose an idle
 timeout of 681 based on 652 seconds of predictive building remaining.
 Sep 23 02:33:29.000 [info] onion_pick_cpath_exit(): Using requested exit
 node '$809814F480D046EF977004BD545914BFFA47C06D~uhkakw at 185.148.145.74'
 Sep 23 02:33:29.000 [info] select_entry_guard_for_circuit(): Selected
 primary guard Unnamed ($3E53D3979DB07EFD736661C934A1DED14127B684) for
 circuit.
 ...
 }}}

 and then after a second:
 {{{
 Sep 23 02:33:30.000 [warn] Unknown introduction point auth key on circuit
 3571433146 for service
 4acth47i6kxnvkewtm6q7ib2s3ufpo5sqbsnzjpbi7utijcltosqemad
 Sep 23 02:33:30.000 [info] circuit_mark_for_close_(): Circuit 3571433146
 (id: 697) marked for close at src/or/hs_service.c:2711 (orig reason: 12,
 new reason: 0)
 ...
 Sep 23 02:33:30.000 [info] circuit_free(): Circuit 0 (id: 697) has been
 freed.
 }}}

 Note the `697` id which is the only identifier. There are no other
 references to `3571433146` or `697` in the logs.

 There are no `cleanup_intro_points()` logs between creation and
 destruction (it only took a second). I'm not sure where the circuit went,
 or maybe the circuitmap was never updated? :/

 ----

 BTW note that this is an unstable hidden service where internet goes up
 and down a few times a day. I have 200 intro circuit creations in 3 days.

 My cleanup intro point logs always have maxed out retries:
 {{{
 Sep 23 01:46:41.000 [info] cleanup_intro_points(): Intro point
 $9C900A7F6F5DD034CFFD192DAEC9CCAA813DB022 (retried: 4 times). Removing it.
 Sep 23 01:46:41.000 [info] cleanup_intro_points(): Intro point
 $CC865174BE13444B251CCB2F82B3F0F9A614DC53 (retried: 4 times). Removing it.
 Sep 23 01:46:41.000 [info] cleanup_intro_points(): Intro point
 $60AEEBDC21E6D5411853BDA03478604FFBA00B20 (retried: 4 times). Removing it.
 Sep 23 02:09:19.000 [info] cleanup_intro_points(): Intro point
 $F1D71314781D23800C3C62CB720BBCF449B27399 (retried: 4 times). Removing it.
 }}}
 also i got this once
 {{{
 Sep 23 02:33:30.000 [info] circuit_free(): Circuit 0 (id: 697) has been
 freed.
 }}}

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