[tor-bugs] #16585 [Tor]: relay stops forwarding all traffic when client function cannot establish circuits -- scheduler_run() starvation (was: relay stops forwarding all traffic when client function cannot establish circuits)

[Tor Bug Tracker & Wiki]

#16585: relay stops forwarding all traffic when client function cannot establish
circuits -- scheduler_run() starvation
---------------------------+---------------------------
     Reporter:  starlight  |      Owner:
         Type:  defect     |     Status:  new
     Priority:  major      |  Milestone:
    Component:  Tor        |    Version:  Tor: 0.2.6.10
   Resolution:             |   Keywords:
Actual Points:             |  Parent ID:
       Points:             |
---------------------------+---------------------------
Changes (by starlight):

 * priority:  normal => major


Comment:

 Nailed it down.

 Problem starts at

 {{{
 Aug 14 22:11:15.000 [debug] new_route_len(): Chosen route length 3
 (6239/7105 routers suitable).
 .
 .
 .
 Aug 14 22:11:16.000 [debug] circuit_increment_failure_count():
 n_circuit_failures now 1.
 }}}

 at which time

 {{{
 scheduler_run(): We have a chance to run the scheduler
 }}}

 goes into starvation, and `scheduler_run()` is not
 invoked again for 2000 milliseconds

 here's a histogram where the left column is total
 logged events and the right column is `scheduler_run()`

 {{{
 22:11:12  67873 363
 22:11:13  78595 658
 22:11:14  93149 242
 22:11:15  14383   5
 22:11:16   1812   0
 22:11:17   1200   0
 22:11:18   5547   0
 22:11:19  18219   4
 22:11:20   3729   0
 22:11:21   5063   0
 22:11:22   1445   0
 22:11:23   6735   0
 22:11:24     28   0
 22:11:25  63976  17
 22:11:26  67298  28
 22:11:27  77377  38
 22:11:28 100585  80
 22:11:29  99899  71
 22:11:30  77994  72
 22:11:31 101059  99
 22:11:32 100829  94
 22:11:33  79472  84
 22:11:34  99978  98
 22:11:35  98906  89
 22:11:36  81795  77
 22:11:37 100629 170
 22:11:38  98391 213
 22:11:39  79961 223
 22:11:40  81213 659
 22:11:41  93819 566
 22:11:42  82917 744
 22:11:43  85495 538
 22:11:44  29038 271
 22:11:45  71416 259
 22:11:46  58348 656
 22:11:47  65918 686
 22:11:48  78183 568
 22:11:49  70243 651
 22:11:50  86030 608
 22:11:51  67953 744
 22:11:52  74292 662
 22:11:53  91937 562
 }}}

 so it's fairly obvious `scheduler_run()`
 starvation and whatever is causing it is
 the problem

 FULL [DEBUG] LEVEL LOG IS ATTACHED TO TICKET IN TWO .XZ PARTS

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