attempt to open a socket after DisableNetwork=1 transition

Tor Browser 6.0a1 includes a change that was made as part of legacy/trac#11773 (moved) that causes Tor Launcher to immediately issue a SETCONF DisableNetwork=1 command when the user cancels the bootstrapping process. Unfortunately, this causes tor to sometimes emit an error like this one:

650 STATUS_CLIENT WARN BOOTSTRAP PROGRESS=25 TAG=loading_status SUMMARY="Loading networkstatus consensus" WARNING="Network is unreachable" REASON=NOROUTE COUNT=1 RECOMMENDATION=warn HOSTID="0AD3FA884D18F89EEA2D89C019379E0E7FD94417" HOSTADDR="208.83.223.34:80"

And Tor Launcher displays an error alert.

I cannot reproduce this when I enable debug logging in tor, but I can when info logging is enabled. In the tor log I see:

Jan 26 13:40:08.000 [warn] connection_connect_sockaddr(): Bug: Tried to open a socket with DisableNetwork set. (on Tor 0.2.7.6 7a489a6389110120)

I will attach a trace from Tor Launcher as well as the tor info log.

Is this a tor bug? Or is there a better way for Tor Launcher to stop the bootstrapping process?

changed milestone to %Tor: unspecified in legacy/trac

added component::core tor/tor in Legacy / Trac disablenetwork in Legacy / Trac milestone::Tor: unspecified in Legacy / Trac needs-diagnosis in Legacy / Trac points::small/medium in Legacy / Trac priority::low in Legacy / Trac severity::normal in Legacy / Trac status::new in Legacy / Trac tor-client in Legacy / Trac type::defect in Legacy / Trac labels

Trac:
tl-log.txt

Tor Launcher debug log

Trac:
tor-log.txt

tor info log

Trac:
Cc: N/A to gk, brade

This could be due to a race condition where Tor starts a network connection attempt before you issue the SETCONF, then the SETCONF completes, then the socket connection attempt occurs.

I'm not sure what we can do to fix this, but we might be able to make the race harder to trigger.

Are you using 0.2.8.0-alpha-dev in 6.0a1? We refactored periodic events in 0.2.8, which might have made this race easier to trigger.

Replying to teor:

This could be due to a race condition where Tor starts a network connection attempt before you issue the SETCONF, then the SETCONF completes, then the socket connection attempt occurs.

I'm not sure what we can do to fix this, but we might be able to make the race harder to trigger.

I am not very familiar with the tor internals, but I wonder how difficult it would be to gracefully shutdown/cleanup "in progress" connections during a transition to the "network disabled" state? In other words, during some short period of transition tor would not report an error but just close the socket, etc.

Are you using 0.2.8.0-alpha-dev in 6.0a1? We refactored periodic events in 0.2.8, which might have made this race easier to trigger.

TB 6.0a1 still uses 0.2.7.6: Jan 26 13:32:54.055 [notice] Tor v0.2.7.6 (git-7a489a63) running on Darwin with Libevent 2.0.22-stable, OpenSSL 1.0.1q and Zlib 1.2.5.

Trac:
Milestone: N/A to Tor: 0.2.8.x-final

Trac:
Priority: Medium to Low

Throw most 0.2.8 "NEW" tickets into 0.2.9. I expect that many of them will subsequently get triaged out.

Trac:
Milestone: Tor: 0.2.8.x-final to Tor: 0.2.9.x-final

Trac:
Reviewer: N/A to N/A
Points: N/A to small/medium

tickets market to be removed from milestone 029

Trac:
Milestone: Tor: 0.2.9.x-final to Tor: 0.2.???

Milestone renamed

Trac:
Milestone: Tor: 0.2.??? to Tor: 0.3.???

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

Trac:
Milestone: Tor: 0.3.??? to Tor: unspecified
Keywords: N/A deleted, tor-03-unspecified-201612 added

Remove an old triaging keyword.

Trac:
Keywords: tor-03-unspecified-201612 deleted, N/A added

If this comes up again, the tor_fragile_assert() immediately after that log message should make a stack trace get displayed.

Trac:
Keywords: N/A deleted, tor-client disablenetwork needs-diagnosis added

moved from legacy/trac#18154 (moved)

added Bug label and removed 1 deleted label