Opened 8 years ago

Last modified 2 years ago

#3080 new defect

Bug: The application request to "jabber.org":5222 has launched 10 circuits without finding one it likes.

Reported by: arma Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.2.2.25-alpha
Severity: Normal Keywords: tor-client streams needs-insight
Cc: Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

In Tor 0.2.2.25-alpha we put in a check to detect inconsistencies between our "build a circuit to handle a stream" logic and our "attach a stream to one of the available circuits" logic.

It triggers for me, but I think it's a false positive.

Apr 29 01:04:25.331 [debug] new_route_len(): Chosen route length 3 (2230/2352 routers suitable).
Apr 29 01:04:25.334 [info] choose_good_exit_server_general(): Found 391 servers that might support 1/1 pending connections.
Apr 29 01:04:25.335 [debug] smartlist_choose_by_bandwidth_weights(): Choosing node for rule weight as exit based on weights Wg=0.679100 Wm=1.000000 We=1.000000 Wd=0.679100 with total bw 1359895429.600000
Apr 29 01:04:25.335 [info] choose_good_exit_server_general(): Chose exit server 'chomsky'
Apr 29 01:04:25.335 [debug] onion_extend_cpath(): Path is 0 long; we want 3
Apr 29 01:04:25.336 [debug] onion_extend_cpath(): Chose router kemna for hop 1 (exit is chomsky)
Apr 29 01:04:25.336 [debug] onion_extend_cpath(): Path is 1 long; we want 3
Apr 29 01:04:25.336 [debug] choose_good_middle_server(): Contemplating intermediate hop: random choice.
Apr 29 01:04:25.340 [debug] smartlist_choose_by_bandwidth_weights(): Choosing node for rule weight as middle node based on weights Wg=0.310000 Wm=1.000000 We=0.000000 Wd=0.160400 with total bw 941905438.000000
Apr 29 01:04:25.340 [debug] onion_extend_cpath(): Chose router spmtorrelay for hop 2 (exit is chomsky)
Apr 29 01:04:25.340 [debug] onion_extend_cpath(): Path is 2 long; we want 3
Apr 29 01:04:25.519 [debug] onion_extend_cpath(): Chose router chomsky for hop 3 (exit is chomsky)
Apr 29 01:04:25.519 [debug] onion_extend_cpath(): Path is complete: 3 steps long
Apr 29 01:04:25.520 [debug] circuit_handle_first_hop(): Looking for firsthop '85.25.62.36:9001'
Apr 29 01:04:25.520 [info] circuit_handle_first_hop(): Next router is kemna: Not connected. Connecting. 
Apr 29 01:04:25.520 [debug] connection_connect(): Connecting to "85.25.62.36":9001.
Apr 29 01:04:25.520 [info] connection_connect(): connect() to "85.25.62.36":9001 failed: Network is unreachable
Apr 29 01:04:25.520 [debug] entry_guard_register_connect_status(): Failed to connect to unreachable entry guard 'kemna' (CFF48861E1A2774BF0D483998198CFECEA9FF477).  It has been unreachable since 2011-04-23 21:30:56.
Apr 29 01:04:25.520 [debug] router_set_status(): Marking router 'kemna/85.25.62.36' as down.
Apr 29 01:04:25.520 [info] circuit_handle_first_hop(): connect to firsthop failed. Closing.
Apr 29 01:04:25.520 [info] circuit_build_failed(): Our circuit died before the first hop with no connection
Apr 29 01:04:25.520 [debug] entry_guard_register_connect_status(): Failed to connect to unreachable entry guard 'kemna' (CFF48861E1A2774BF0D483998198CFECEA9FF477).  It has been unreachable since 2011-04-23 21:30:56.
Apr 29 01:04:25.520 [debug] router_set_status(): Marking router 'kemna/85.25.62.36' as down.
Apr 29 01:04:25.520 [debug] circuit_increment_failure_count(): n_circuit_failures now 1.
Apr 29 01:04:25.520 [warn] circuit_get_open_circ_or_launch(): Bug: The application request to "jabber.org":5222 has launched 10 circuits without finding one it likes.
Apr 29 01:04:25.520 [info] circuit_get_open_circ_or_launch(): No safe circuit (purpose 5) ready for edge connection; delaying.

I think we need to change the check so it only increments num_circuits_launched when the circuit it launches makes it to the 'open' state. I fear that's a more complex hack though.

Child Tickets

Change History (15)

comment:1 Changed 8 years ago by nickm

I fear that's a more complex hack though.

Yeah; by the time the circuit makes it to 'open', we no longer remember that we created it in order to make particular streams happy. I wonder if there's a simpler thing we could do.

comment:2 Changed 8 years ago by arma

One simple approach would be to try to guess if we're in the "circuits we're making generally work" state or the "circuits we're making generally don't work" state. Then only count circuits we launch in the former state.

An approximation would be to remember the success/failure of the most recent circuit launch, and only increment num_circuits_launched if the last circuit outcome was an open circuit.

We might also find that we should make this a log_info in 0.2.2 and continue polishing it in 0.2.3.x.

comment:3 in reply to:  1 Changed 8 years ago by arma

Replying to nickm:

Yeah; by the time the circuit makes it to 'open', we no longer remember that we created it in order to make particular streams happy. I wonder if there's a simpler thing we could do.

Another totally different approach would be to examine the overall list of origin circuits and ask ourselves if we have too many open circuits sitting around.

comment:4 Changed 8 years ago by nickm

Milestone: Tor: 0.2.2.x-finalTor: 0.2.3.x-final

Downgraded the message; punting a better fix to 0.2.3.

comment:5 Changed 7 years ago by nickm

Milestone: Tor: 0.2.3.x-finalTor: 0.2.4.x-final

comment:6 Changed 7 years ago by nickm

Keywords: tor-client added

comment:7 Changed 7 years ago by nickm

Component: Tor ClientTor

comment:8 Changed 6 years ago by nickm

Keywords: 024-deferrable added

comment:9 Changed 6 years ago by nickm

Milestone: Tor: 0.2.4.x-finalTor: 0.2.5.x-final

comment:10 Changed 5 years ago by nickm

Milestone: Tor: 0.2.5.x-finalTor: 0.2.???

comment:11 Changed 2 years ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:12 Changed 2 years ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:13 Changed 2 years ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:14 Changed 2 years ago by nickm

Keywords: 024-deferrable removed

comment:15 Changed 2 years ago by nickm

Keywords: streams needs-insight added
Priority: HighMedium
Severity: Normal
Note: See TracTickets for help on using tickets.