More Torbutton hangs on New Identity control port access
skruffy is reporting hangs on Torbutton's New Identity. Oddly, the hangs seem to be more common if you are loading a bunch of websites at the time of hitting New Identity, but that is not a full repro case.
The hang actually appears to be happening while attempting to open a control port connection. Perhaps another race introduced by our SOCKS optimistic data hack in nsITransport? Or perhaps our hack for #8642 (closed) is insufficient in some cases, and/or during heavy network activity.
Activity
Trac:
Description: skruffy is reporting hangs on Torbutton's New Identity. Oddly, the hangs seem to be more common if you are loading a bunch of websites at the time of hitting New Identity, but that is not a full repro case.The hang actually appears to be happening while attempting to open a control port connection. Perhaps another race introduced by our SOCKS optimistic data hack in nsITransport? Or perhaps our hack for #8462 (moved) is insufficient in some cases, and/or during heavy network activity.
to
skruffy is reporting hangs on Torbutton's New Identity. Oddly, the hangs seem to be more common if you are loading a bunch of websites at the time of hitting New Identity, but that is not a full repro case.
The hang actually appears to be happening while attempting to open a control port connection. Perhaps another race introduced by our SOCKS optimistic data hack in nsITransport? Or perhaps our hack for #8642 (closed) is insufficient in some cases, and/or during heavy network activity.
Socket is never alive during repro case that leads to hangs. Tested with modified torbutton_send_ctrl_cmd() so it waited alive socket after opening stream, like so:
var input = socket.openInputStream(3, 1, 1); // 3 == OPEN_BLOCKING|OPEN_UNBUFFERED var output = socket.openOutputStream(3, 1, 1); // 3 == OPEN_BLOCKING|OPEN_UNBUFFERED while (!socket.isAlive()) {} torbutton_log(4, "Alive!");If hangs happens then it never reaches "Alive!" and browser ask about unresponsive script later.
I got reproducable hang using modified torbutton_send_ctrl_cmd(), on startup without any pages loaded.
var socketTransportService = Components.classes["@mozilla.org/network/socket-transport-service;1"] .getService(Components.interfaces.nsISocketTransportService); var sockets = new Array(); var max=540; // 550 hangs, 545 bypasses for(var i = 0; i < max; i++) { var s = socketTransportService.createTransport(null, 0, m_tb_control_host, m_tb_control_port, null); var input = s.openInputStream(3, 1, 1); // 3 == OPEN_BLOCKING|OPEN_UNBUFFERED var output = s.openOutputStream(3, 1, 1); // 3 == OPEN_BLOCKING|OPEN_UNBUFFERED sockets.push(s); } for(var i = 0; i < max-1; i++) { sockets[i].close; } var socket = sockets[max-2]; torbutton_log(4, "Browser will hang now!");Those number for tested box, it's depends platform in some way. I was unable to find any correlation with local limits like max descriptors or something. Probably missed something.
Trac:
Cc: N/A to g.koppen@jondos.deThis code helps to avoid conditions that leads to hang if no connection able to create.
--- torbutton.js.original +++ torbutton.js @@ -1385,6 +1385,20 @@ } } +function torbutton_process_even_queue() { + // Get the current thread. + var thread = Components.classes["@mozilla.org/thread-manager;1"]. + getService(Components.interfaces.nsIThreadManager).currentThread; +/* +Warning: Calling nsIThread.processNextEvent allows network +and UI events to run which can modify data structures that +your code isn't expecting to be modified during a synchronous +method call. This can cause random crashes and other bugs that +may be hard to find and fix. Consider use asynchronous callbacks instead. +*/ + while (thread.processNextEvent(false)) {} +} + /* The "New Identity" implementation does the following: * 1. Disables Javascript and plugins on all tabs * 2. Clears state: @@ -1580,7 +1594,8 @@ var prefService = Components.classes["@mozilla.org/preferences-service;1"] .getService(Components.interfaces.nsIPrefService); prefService.savePrefFile(null); - + + torbutton_process_even_queue(); torbutton_log(3, "New Identity: Sending NEWNYM"); // We only support TBB for newnym.Trac:
Status: new to needs_reviewReplying to gk:
Why do you think that warning can be ignored in the current case?
Do you think that warning can't be ignored?
No any modified data should prevent: access control port, open new window, close current window. Before "Sending NEWNYM" it actually assumed everything finished: tabs closed, conns destroyed, prefs synced, etc. With processing all events in queue you can guarantee that.
https://bugzilla.mozilla.org/show_bug.cgi?id=698882 Is it reason of hangs?
-
Here comes some gdb output as a starting point:
#4 0xb628579a in mozilla::ReentrantMonitor::Wait (this=0x9b2814e0, interval=4294967295) at /home/ubuntu/build/tor-browser/obj-i686-pc-linux-gnu/xpcom/build/BlockingResourceBase.cpp:313 #5 0xb4a8f352 in mozilla::ReentrantMonitorAutoEnter::Wait (this=0xbfffb7ac, interval=4294967295) at ../../dist/include/mozilla/ReentrantMonitor.h:192 #6 0xb62caa37 in nsPipeOutputStream::Wait (this=0x9b2814bc) at /home/ubuntu/build/tor-browser/xpcom/io/nsPipe3.cpp:980 #7 0xb62cae45 in nsPipeOutputStream::WriteSegments (this=0x9b2814bc, reader=0xb62cafea <nsReadFromRawBuffer(nsIOutputStream*, void*, char*, uint32_t, uint32_t, uint32_t*)>, closure=0x9b5e0be0, count=46, writeCount=0xbfffb898) at /home/ubuntu/build/tor-browser/xpcom/io/nsPipe3.cpp:1090 #8 0xb62cb077 in nsPipeOutputStream::Write (this=0x9b2814bc, fromBuf=0x9b5e0be0 "AUTHENTICATE 422f587d45483e5b737b2f7863234042\r\n", bufLen=47, writeCount=0xbfffb898) at /home/ubuntu/build/tor-browser/xpcom/io/nsPipe3.cpp:1150 #9 0xb62bc86d in nsBinaryOutputStream::Write (this=0x9b6d1980, aBuf=0x9b5e0be0 "AUTHENTICATE 422f587d45483e5b737b2f7863234042\r\n", aCount=47, aActualBytes=0xbfffb898) at /home/ubuntu/build/tor-browser/xpcom/io/nsBinaryStream.cpp:51 #10 0xb62bd0e7 in nsBinaryOutputStream::WriteBytes (this=0x9b6d1980, aString=0x9b5e0be0 "AUTHENTICATE 422f587d45483e5b737b2f7863234042\r\n", aLength=47) at /home/ubuntu/build/tor-browser/xpcom/io/nsBinaryStream.cpp:216It is pretty reliably reproducible in my debug build if I open a bunch of bookmarks (say 5) simultaneously and choose the "New Identity" option immediately afterwards.
-
Trac:
Cc: g.koppen@jondos.de to gk, mcs, brade -
#10880 (closed) is a duplicate of this one.
Trac:
Cc: gk, mcs, brade to gk, mcs, brade, rex_4539 -
Another user reported similar symptoms (beginning with 3.5.2): https://blog.torproject.org/blog/tor-browser-3521-released#comment-47522
-
Okay, I've filed https://bugzilla.mozilla.org/show_bug.cgi?id=978690 to get things started. Let's see what Mozilla folks are saying.
-
TL;DR: We can't use blocking sockets the way we are doing that right now. They are responsible for the hangs.
If we only have non-TLS connections everything is fine. The picture changes as soon as TLS connections are processed while we click on New Identity or start the browser. Then the following may happen (this is the case when we start-up; hitting New Identity gives a slightly different stacktrace which boils down to the same problem, though):
#1 0xb772cc5b in pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:187 #2 0xb71ec899 in PR_WaitCondVar (cvar=0xa1a07d00, timeout=4294967295) at /home/ubuntu/build/tor-browser/nsprpub/pr/src/pthreads/ptsynch.c:385 #3 0xb5e53402 in Wait (this=<optimized out>, interval=<optimized out>) at ../../../../dist/include/mozilla/CondVar.h:71 #4 Wait (interval=<optimized out>, this=<optimized out>) at ../../../../dist/include/mozilla/Monitor.h:47 #5 Wait (interval=<optimized out>, this=<optimized out>) at ../../../../dist/include/mozilla/Monitor.h:102 #6 mozilla::psm::SyncRunnableBase::DispatchToMainThreadAndWait ( this=0xa1a2f6e0) at /home/ubuntu/build/tor-browser/security/manager/ssl/src/PSMRunnable.cpp:25 #7 0xb5e45b6d in nsNSSSocketInfo::GetPreviousCert (this=0xab3c8580, _result=0xb28feef4) at /home/ubuntu/build/tor-browser/security/manager/ssl/src/nsNSSIOLayer.cpp:427 #8 0xb5e31670 in HandshakeCallback (fd=0xab318280, client_data=0xab3c8580) at /home/ubuntu/build/tor-browser/security/manager/ssl/src/nsNSSCallbacks.cpp:901 #9 0xb709f871 in ssl_FinishHandshake (ss=0xfffffe00) at sslsecur.c:141 #10 0xb708cd65 in ssl3_FinishHandshake (ss=0xaa08a000) at ssl3con.c:10637 #11 0xb708e609 in ssl3_AuthCertificateComplete (ss=0xaa08a000, error=0) at ssl3con.c:10040 #12 0xb709faec in SSL_AuthCertificateComplete (fd=0xaa0760e0, error=0) at sslsecur.c:1566 #13 0xb5e486ea in nsNSSSocketInfo::SetCertVerificationResult (this=0xab3c8580, errorCode=0, errorMessageType=mozilla::psm::PlainErrorMessage) at /home/ubuntu/build/tor-browser/security/manager/ssl/src/nsNSSIOLayer.cpp:456 #14 0xb5e53ecf in mozilla::psm::(anonymous namespace)::SSLServerCertVerificationResult::Run (this=0xa1a2f6a0) at /home/ubuntu/build/tor-browser/security/manager/ssl/src/SSLServerCertVerification.cpp:1357 #15 0xb6366498 in nsThread::ProcessNextEvent (this=0xb2907a60, mayWait=true, result=0xb28ff1ef) at /home/ubuntu/build/tor-browser/xpcom/threads/nsThread.cpp:626 #16 0xb63307a7 in NS_ProcessNextEvent (thread=0xfffffe00, mayWait=true) at /home/ubuntu/build/tor-browser/obj-i686-pc-linux-gnu/xpcom/build/nsThreadUtils.cpp:238 #17 0xb543f43e in nsSocketTransportService::Run (this=0xb29079a0) at /home/ubuntu/build/tor-browser/netwerk/base/src/nsSocketTransportService2.cpp:648A SSLServerCertVerificationResult is dispatched to the socket transport thread (see: https://mxr.mozilla.org/mozilla-esr24/source/security/manager/ssl/src/SSLServerCertVerification.cpp#88 for a reason why this has to happen). Processing this event leads to dispatching PreviousCertRunnable to the main thread. Now, if that is processed on the main thread before our
outputStream.writeBytes(command, command.length);everything is fine. If not we see something like the following in the log:
-1344275648[b722a540]: nsSocketOutputStream::Write [this=9d128794 count=0] -1344275648[b722a540]: calling PR_Write [count=0] -1399850176[acb3b680]: STS dispatch [ab6821f0] -1220368640[b722a300]: STS dispatch [a9dca700] -1220368640[b722a300]: STS dispatch [aa76cce0] -1220368640[b722a300]: STS dispatch [aa76cd00] -1220368640[b722a300]: creating nsSocketTransport @9d128e00 -1220368640[b722a300]: nsSocketTransport::Init [this=9d128e00 host=127.0.0.1:9151 proxy=:0] -1220368640[b722a300]: nsSocketTransport::PostEvent [this=9d128e00 type=3 status=0 param=0] -1220368640[b722a300]: STS dispatch [aa76cde0] -1220368640[b722a300]: nsSocketTransport::OpenInputStream [this=9d128e00 flags=3] -1220368640[b722a300]: STS dispatch [aa46c2e8] -1220368640[b722a300]: nsSocketTransport::PostEvent [this=9d128e00 type=0 status=0 param=0] -1220368640[b722a300]: STS dispatch [aa76ce00] -1220368640[b722a300]: nsSocketTransport::OpenOutputStream [this=9d128e00 flags=3] -1220368640[b722a300]: STS dispatch [aa46c338] -1220368640[b722a300]: nsSocketTransport::PostEvent [this=9d128e00 type=0 status=0 param=0] -1220368640[b722a300]: STS dispatch [aa76ce40] -1220368640[b722a300]: OOO WriteSegments [this=a18ed2ac count=47] -1220368640[b722a300]: OOO appended new segment -1220368640[b722a300]: OOO rolling back write cursor 0 bytes -1220368640[b722a300]: OOO SegmentLen is 1 -1220368640[b722a300]: OOO ReadCount is 1 -1220368640[b722a300]: OOO SegmentLen is now 0 and originalLen is 1 -1220368640[b722a300]: OOO advancing write cursor by 1 -1220368640[b722a300]: OOO pipe output: waiting for space -1690313920[aa456940]: STS dispatch [aa49a3a0] -1673528512[aa456640]: STS dispatch [aa48fac0] -1681921216[aa4567c0]: STS dispatch [aa496ec0]Calling PR_Write actually leads to dispatching the TLS stuff to the socket thread as explained above (note though that this log documents a hang on "New Identity"). While the TLS code is running on that thread Torbutton creates a new socket transport and is opening an input and an output stream which leads to dispatching things to the socket thread, too. But this one is till blocked by the TLS code, thus, the stream setup is not properly done yet. Nevertheless, execution of Torbutton code is proceeding with
outputStream.writeBytes(command, command.length);which results in a blocking main thread with a still blocked socket thread: we have a deadlock.
Great work tracking this down. To some extent this is still a Mozilla problem in that users of the socket transport service need to avoid using it in certain ways.
Does the deadlock still occur if we use buffered sockets? The combination of blocking + unbuffered is unusual. I don't remember why buffering causes problems, but Mike probably does.
-
Replying to mcs:
Does the deadlock still occur if we use buffered sockets? The combination of blocking + unbuffered is unusual. I don't remember why buffering causes problems, but Mike probably does.
https://trac.torproject.org/projects/tor/ticket/8642#comment:1 ? It seems we get buffering for free if we have blocking sockets :) So, the comments in torbuttons.js are wrong. Well, they are not wrong but they just don't match reality.
-
Replying to mikeperry:
What am I supposed to review, test, or investigate here?
Knowing whether you tested (and dismissed) other options than using blocking sockets for communicating with tor back then when you wrote the code might be helpful. And, of course, any ideas on how to solve this bug are appreciated as well. :)
-
We went with blocking sockets because New Identity needed to ensure that it actually got a new circuit before allowing the user to do anything else with the browser.
I am wondering if we should try clearing the event queue as cypherpunks suggested. It may be a good idea for a few reasons. We may be able to use https://developer.mozilla.org/en-US/docs/Mozilla/Tech/XPCOM/Reference/Interface/nsIDOMWindowUtils#suppressEventHandling%28%29 to suppress UI events in the meantime, if need be.
Alternatively, we could attempt to do an async New Identity and also use the event suppressor to suppress UI event handling until the New Identity onOutputStreamReady+onInputStream callbacks come back...
-
Replying to mikeperry:
We went with blocking sockets because New Identity needed to ensure that it actually got a new circuit before allowing the user to do anything else with the browser.
I am wondering if we should try clearing the event queue as cypherpunks suggested. It may be a good idea for a few reasons. We may be able to use https://developer.mozilla.org/en-US/docs/Mozilla/Tech/XPCOM/Reference/Interface/nsIDOMWindowUtils#suppressEventHandling%28%29 to suppress UI events in the meantime, if need be.
Yes, sounds reasonable. Alas, this idea is not working for the hang during start-up. There a blank Tor Launcher window is visible for a short amount of time until the usual messages appear giving a weird user experience. So I wonder whether we should separate the two problems and treat them differently: fixing the hang on New Identity with the processNextEvent/suppressEventHandling idea and trying the other one for the hang during start-up.
-
#12119 (closed) is a duplicate.
-
Replying to gk:
So I wonder whether we should separate the two problems and treat them differently: fixing the hang on New Identity with the processNextEvent/suppressEventHandling idea and trying the other one for the hang during start-up.
I convinced myself that this might be a good approach and have a fix for this bug in my bug_9531_v2 branch in my public Torbutton repo.
Trac:
Keywords: N/A deleted, MikePerry201407R added
Status: new to needs_review I think it's better to place this patch to
torbutton_send_ctrl_cmd. Which is called yet bytorbutton_local_tor_checkon start-up, it's better to exclude any possible hangs could be triggered by Torbutton, and investigate #10804 (moved) from scratch.-
Replying to cypherpunks:
Then the following may happen (this is the case when we start-up; hitting New Identity gives a slightly different stacktrace which boils down to the same problem, though) If not we see something like the following in the log Was it log for start-up case or for hitting New Identity?
start-up case. The issue when hitting New Identity shows basically the same log with minor differences. I'd say it is definitely the same underlying bug we hit here.
-
Replying to cypherpunks:
There a blank Tor Launcher window is visible for a short amount of time until the usual messages appear giving a weird user experience. Blank windows with your patch?
If I apply the patch idea to the Tor Launcher related issue, yes.
There a blank Tor Launcher window is visible for a short amount of time until the usual messages appear giving a weird user experience.
Tor Launcher could to finish every stuff for progress document before starting socket transport operations. This specially crafted workaround reducing negative user experience.
diff --git a/src/components/tl-process.js b/src/components/tl-process.js index cc5d654..31d4e45 100644 --- a/src/components/tl-process.js +++ b/src/components/tl-process.js @@ -91,6 +91,7 @@ TorProcessService.prototype = if ("profile-after-change" == aTopic) { this.mObsSvc.addObserver(this, "quit-application-granted", false); + this.mObsSvc.addObserver(this, "document-shown", false); this.mObsSvc.addObserver(this, kOpenNetworkSettingsTopic, false); this.mObsSvc.addObserver(this, kUserQuitTopic, false); this.mObsSvc.addObserver(this, kBootstrapStatusTopic, false); @@ -169,6 +170,17 @@ TorProcessService.prototype = } } } + else if ("document-shown" == aTopic) + { + if (aSubject.getElementById("progressMeter")) + ++this.mDocumentProgressShown; + else + this.mDocumentProgressShown = 0; + if (!this.mDocumentProgressShown || this.mDocumentProgressShown == 3) { + this._monitorTorProcessStartup(); + this.mObsSvc.removeObserver(this, "document-shown"); + } + } else if ("timer-callback" == aTopic) { if (aSubject == this.mControlConnTimer) @@ -296,6 +308,7 @@ TorProcessService.prototype = mRestartWithQuit: false, mLastTorWarningPhase: null, mLastTorWarningReason: null, + mDocumentProgressShown: 0, // Private Methods ///////////////////////////////////////////////////////// @@ -426,7 +439,6 @@ TorProcessService.prototype = { try { - this._monitorTorProcessStartup(); var bridgeConfigIsBad = (this._defaultBridgesStatus == this.kDefaultBridgesStatus_BadConfig);With more knowledge it could be less kludgy fix.
Torbutton 1.6.12.3 should be free of such hangs, it draining queue for every attempts to access Tor's control port . Next patches and research of Tor Launcher's hangs going to #10804 (moved).
