[tor-bugs] #16585 [Tor]: relay stops forwarding all traffic when client function cannot establish circuits -- scheduler_run() starvation
Tor Bug Tracker & Wiki
blackhole at torproject.org
Sat Aug 15 17:16:27 UTC 2015
#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: |
---------------------------+---------------------------
Comment (by starlight):
Examining the debug log turned up what appears to be
the specific issue. Appears the scheduler event
loop is still able to accept incoming cells while
performing heavy computation for new circuit
onion-skins, but that no outbound cell are
written. The most interesting section of the
log (edited for relevance and attached to ticket)
shows extreme delays between bulk calls to
`channel_write_packed_cell()`. The most
interesting of the interesting follows inline:
{{{
22:11:15 [info] choose_good_exit_server_general(): Found 894 servers that
might support 0/0 pending connections.
22:11:15 [info] compute_weighted_bandwidths(): Empty routerlist passed in
to consensus weight node selection for rule weight as exit
22:11:15 [info] choose_good_exit_server_general(): Chose exit server
'$F1BE15429B3CE696D6807F4D4A58B1BFEC45C822~zwiebeltoralf at 5.9.158.75'
22:11:15 [info] circuit_send_next_onion_skin(): First hop: finished
sending CREATE cell to '${scrubbed1}~{scrubbed1} at {scrubbed1}'
22:11:15 [info] connection_edge_process_inbuf(): data from edge while in
'waiting for circuit' state. Leaving it on buffer.
22:11:15 [debug] scheduler_evt_callback(): Scheduler event callback called
22:11:15 [debug] scheduler_run(): We have a chance to run the scheduler
22:11:15 [debug] channel_write_packed_cell() { COUNT 119 }
22:11:15 [debug] scheduler_run(): Scheduler handled 23 of 23 pending
channels, queue size from 102906952 to 102969213, queue heuristic from
32559 to 94820
22:11:15 [debug] channel_write_packed_cell(): Writing packed_cell_t
0x7fa2b5089150 to channel 0x7fa2b1fb6590 with global ID 2574011
22:11:16 [info] choose_good_exit_server_general(): Found 894 servers that
might support 0/0 pending connections.
22:11:16 [info] compute_weighted_bandwidths(): Empty routerlist passed in
to consensus weight node selection for rule weight as exit
22:11:16 [info] choose_good_exit_server_general(): Chose exit server
'$21ABB9584677EEB54514265F24756AD0B04E0EFA~spfTOR1e1 at 77.109.141.138'
22:11:16 [info] circuit_send_next_onion_skin(): First hop: finished
sending CREATE cell to '${scrubbed1}~{scrubbed1} at {scrubbed1}'
22:11:16 [info] connection_edge_process_inbuf(): data from edge while in
'waiting for circuit' state. Leaving it on buffer.
22:11:16 [debug] channel_write_packed_cell(): Writing packed_cell_t
0x7fa2ae01be50 to channel 0x7fa2b06218c0 with global ID 2619137
22:11:16 [debug] channel_write_packed_cell(): Writing packed_cell_t
0x7fa2b146a180 to channel 0x7fa2b60546f0 with global ID 2632321
22:11:16 [debug] channel_write_packed_cell(): Writing packed_cell_t
0x7fa2ab1ec0c0 to channel 0x7fa2b77e85e0 with global ID 2517382
22:11:16 [debug] channel_write_packed_cell(): Writing packed_cell_t
0x7fa2b658ac10 to channel 0x7fa2ace699e0 with global ID 2538923
22:11:16 [info] connection_exit_connect_dir(): Opening local connection
for anonymized directory exit
22:11:16 [info] connection_exit_connect_dir(): Opening local connection
for anonymized directory exit
22:11:16 [info] connection_exit_connect_dir(): Opening local connection
for anonymized directory exit
22:11:16 [info] choose_good_exit_server_general(): Found 894 servers that
might support 0/0 pending connections.
22:11:16 [info] compute_weighted_bandwidths(): Empty routerlist passed in
to consensus weight node selection for rule weight as exit
22:11:16 [info] choose_good_exit_server_general(): Chose exit server
'$E1E922A20AF608728824A620BADC6EFC8CB8C2B8~TorLand1 at 37.130.227.133'
22:11:16 [info] circuit_send_next_onion_skin(): First hop: finished
sending CREATE cell to '${scrubbed1}~{scrubbed1} at {scrubbed1}'
22:11:17 [info] choose_good_exit_server_general(): Found 894 servers that
might support 0/0 pending connections.
22:11:17 [info] compute_weighted_bandwidths(): Empty routerlist passed in
to consensus weight node selection for rule weight as exit
22:11:17 [info] choose_good_exit_server_general(): Chose exit server
'$22F9FB518CE880081B3101B70B9D85D5BD4D7967~BabylonNetwork06 at
185.62.188.14'
22:11:17 [info] circuit_send_next_onion_skin(): First hop: finished
sending CREATE cell to '${scrubbed1}~{scrubbed1} at {scrubbed1}'
22:11:17 [info] run_connection_housekeeping(): Expiring non-used OR
connection to fd 427 (23.239.18.57:9001) [no circuits for 1090; timeout
1089; canonical].
22:11:17 [debug] scheduler_evt_callback(): Scheduler event callback called
22:11:17 [debug] scheduler_run(): We have a chance to run the scheduler
22:11:17 [debug] channel_write_packed_cell() { COUNT 261 }
22:11:17 [debug] scheduler_run(): Scheduler handled 80 of 80 pending
channels, queue size from 102876843 to 103013928, queue heuristic from 0
to 137085
22:11:17 [info] rep_hist_note_or_conn_bytes(): 1793602 below threshold,
128897 mostly read, 116725 mostly written, 223398 both read and written.
22:11:17 [debug] channel_write_packed_cell() { COUNT 2 }
22:11:17 [info] circuit_finish_handshake(): Finished building circuit hop:
22:11:17 [info] exit circ (length 3, last hop zwiebeltoralf):
${scrubbed1}(open) $A6F64642F6D4C15E62BC421589E013433193055D(closed)
$F1BE15429B3CE696D6807F4D4A58B1BFEC45C822(closed)
22:11:17 [info] circuit_send_next_onion_skin(): Sending extend relay cell.
22:11:17 [debug] channel_write_packed_cell() { COUNT 1 }
22:11:17 [info] connection_edge_process_relay_cell(): sendme cell dropped,
unknown stream (streamid 304).
22:11:17 [debug] channel_write_packed_cell() { COUNT 1 }
22:11:17 [info] connection_handle_listener_read(): New SOCKS connection
opened from {scrubbed}.
22:11:17 [debug] channel_write_packed_cell() { COUNT 6 }
22:11:17 [info] channel_register(): Channel 0x7fa2b3494de0 (global ID
2657985) in state opening (1) registered with no identity digest
22:11:17 [debug] channel_write_packed_cell() { COUNT 1 }
22:11:18 [info] choose_good_exit_server_general(): Found 894 servers that
might support 0/0 pending connections.
22:11:18 [info] compute_weighted_bandwidths(): Empty routerlist passed in
to consensus weight node selection for rule weight as exit
22:11:18 [info] choose_good_exit_server_general(): Chose exit server
'$7DD29A65C370B86B5BE706EA3B1417745714C8AF~dreamatorium at 89.31.57.5'
22:11:18 [info] circuit_send_next_onion_skin(): First hop: finished
sending CREATE cell to '${scrubbed1}~{scrubbed1} at {scrubbed1}'
22:11:18 [debug] scheduler_evt_callback(): Scheduler event callback called
22:11:18 [debug] scheduler_run(): We have a chance to run the scheduler
22:11:18 [debug] channel_write_packed_cell() { COUNT 318 }
22:11:18 [debug] scheduler_run(): Scheduler handled 87 of 87 pending
channels, queue size from 102864432 to 103031360, queue heuristic from 0
to 166928
22:11:18 [info] directory_handle_command_get(): Got a v2 rendezvous
descriptor request for ID '[scrubbed]'
22:11:18 [info] directory_handle_command_get(): Got a v2 rendezvous
descriptor request for ID '[scrubbed]'
22:11:18 [info] directory_handle_command_get(): Got a v2 rendezvous
descriptor request for ID '[scrubbed]'
22:11:18 [info] circuit_finish_handshake(): Finished building circuit hop:
22:11:18 [info] exit circ (length 3, last hop TorLand1):
${scrubbed1}(open) $3B2757383632D8C20B5E02DB55FEFF6198C8FEF5(closed)
$E1E922A20AF608728824A620BADC6EFC8CB8C2B8(closed)
22:11:18 [info] circuit_send_next_onion_skin(): Sending extend relay cell.
22:11:18 [info] circuit_finish_handshake(): Finished building circuit hop:
22:11:18 [info] exit circ (length 3, last hop spfTOR1e1):
${scrubbed1}(open) $28F5601709FDCAA51C60E1D7004F40EFA0C99DE4(closed)
$21ABB9584677EEB54514265F24756AD0B04E0EFA(closed)
22:11:18 [info] circuit_send_next_onion_skin(): Sending extend relay cell.
22:11:18 [info] connection_edge_process_relay_cell(): sendme cell dropped,
unknown stream (streamid 304).
22:11:18 [debug] channel_write_packed_cell() { COUNT 1 }
22:11:18 [info] connection_handle_listener_read(): New SOCKS connection
opened from {scrubbed}.
22:11:18 [debug] channel_write_packed_cell() { COUNT 1 }
22:11:18 [info] channel_register(): Channel 0x7fa2af81b840 (global ID
2657986) in state opening (1) registered with no identity digest
22:11:18 [debug] channel_write_packed_cell() { COUNT 4 }
22:11:18 [debug] scheduler_evt_callback(): Scheduler event callback called
22:11:18 [debug] scheduler_run(): We have a chance to run the scheduler
22:11:18 [debug] channel_write_packed_cell() { COUNT 1 }
22:11:18 [debug] scheduler_run(): Scheduler handled 97 of 97 pending
channels, queue size from 102895271 to 103041195, queue heuristic from 0
to 145924
}}}
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/16585#comment:6>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list