Meek bridges don't work in TB 4.5alpha1

added MikePerry201501R in Legacy / Trac TorBrowserTeam201501R in Legacy / Trac component::applications/tor browser in Legacy / Trac owner::tbb-team in Legacy / Trac priority::medium in Legacy / Trac resolution::fixed in Legacy / Trac status::closed in Legacy / Trac tbb-4.5-alpha-3 in Legacy / Trac type::defect in Legacy / Trac labels

I tried all three built-in meek PT options on a Mac OS 10.9.5 system and each one failed (same tor log as above).

Cc: dcf (You can probably reproduce this problem easily, but let me know if you want me to gather any Tor or meek debug logs)

Trac:
Cc: N/A to dcf, mcs

In the Browser Console (ctrl+J) of the headless helper browser, I see this error:

getFirstPartyURI failed for https://www.torproject.org/dist/torbrowser/update_2/alpha/Linux_x86_64-gcc3/4.5-alpha-1/en-US: 0x80070057
getFirstPartyURI failed for https://ajax.aspnetcdn.com/: 0x80070057
[Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIHttpChannel.responseStatus]"  nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)"  location: "JS frame :: file:///home/david/tor-browser_en-US/Browser/TorBrowser/Data/Browser/profile.meek-http-helper/extensions/meek-http-helper@bamsoftware.com/components/main.js :: MeekHTTPHelper.HttpStreamListener.prototype.onStopRequest :: line 396"  data: no]

The last line refers to main.js:396:

            status: context.responseStatus,

I found the commit that adds getFirstPartyURI, it's one of the patches on top of esr31:

https://gitweb.torproject.org/tor-browser.git/commitdiff/197e8afeef912828e9f9b947a03fe5e907783fdd

I tried setting privacy.thirdparty.isolate=0 in profile.meek-http-helper. It made the getFirstPartyURI errors go away, but the "Component returned failure code: 0x80040111" one remained and it still didn't work.

I am not sure the getFirstPartyURI log messages are relevant; that is probably just "noise."

Regarding the other problem, looking here: http://mxr.mozilla.org/mozilla-esr31/source/netwerk/protocol/http/HttpBaseChannel.cpp#1232 it seems like the request did not complete successfully. I am not sure why that would be the case, but I think the onStopRequest code should execute a test like this:

if (Components.isSuccessCode(status)) {

before trying to access responseStatus.

Replying to mcs:

Regarding the other problem, looking here: http://mxr.mozilla.org/mozilla-esr31/source/netwerk/protocol/http/HttpBaseChannel.cpp#1232 it seems like the request did not complete successfully. I am not sure why that would be the case, but I think the onStopRequest code should execute a test like this: {{{ if (Components.isSuccessCode(status)) { }}} before trying to access responseStatus.

We already do the isSuccessCode(status) check a couple of lines later, at main.js:398. The error is happening at main.js:396 when trying to index context, not when reading status.

There's something internal to Tor Browser that is blocking the request. It's not just a remote server error—those already happen frequently in normal use and the code handles them. Something (something new in 4.5-alpha-1) is preventing the request from even being sent. We can make the code handle this case gracefully, but we'll also have to find out what prevents the requests from being sent in order for the pluggable transport to work.

Trac:
nspr-4.0.log

NSPR_LOG_MODULES for Tor Browser 4.0 with meek-azure.

Trac:
nspr-4.5-alpha-1.log

NSPR_LOG_MODULES for Tor Browser 4.5-alpha-1 with meek-azure.

I attached some NSPR logs for 4.0 (works) and 4.5-alpha-1 (doesn't work).

nspr-4.0.log
nspr-4.5-alpha-1.log I made them with this patch to meek-client-torbrowser:

@@ -79,6 +79,8 @@ func runFirefox() (cmd *exec.Cmd, stdout io.Reader, err error) {
        if err != nil {
                return
        }
+       os.Setenv("NSPR_LOG_MODULES", "nsHttp:5,nsSocketTransport:5,nsStreamPump:5,nsHostResolver:5")
+       os.Setenv("NSPR_LOG_FILE", "nspr.log")
        cmd = exec.Command(firefoxPath, "-no-remote", "-profile", profilePath)
        cmd.Stderr = os.Stderr
        stdout, err = cmd.StdoutPipe()

I don't really know what I'm looking at, but this looks promising. The 4.0 log has this:

nsSocketTransport::ResolveHost [this=7fbe015e6140 ajax.aspnetcdn.com:443]
nsSocketTransport::SendStatus [this=7fbe015e6140 status=804b0003]
Resolving host [ajax.aspnetcdn.com].
  No usable address in cache for [ajax.aspnetcdn.com]
  DNS thread counters: total=1 any-live=0 idle=0 pending=1
  DNS lookup for host [ajax.aspnetcdn.com] blocking pending 'getaddrinfo' query: callback [7fbe00207650] 
  advancing to STATE_RESOLVING

while the 4.5-alpha-1 log has this:

nsSocketTransport::ResolveHost [this=7fc7bcda9c60 :65535] 
nsSocketTransport::SendStatus [this=7fc7bcda9c60 status=804b0003]
  after event [this=7fc7bcda9c60 cond=8000ffff]

Status 804b003 is NS_BINDING_REDIRECTED and 8000ffff is NS_ERROR_UNEXPECTED (https://developer.mozilla.org/en-US/docs/Mozilla/Errors).

The diff between 4.0.1 and 4.5-alpha-1 has a bunch of changes related to name resolution and proxies.

I suspect it's related to the changes made for legacy/trac#3455 (moved), namely either of

08991021207bcc7c982fa5ae5a9984a12ec7bf5f
e0eaf6b471ae3bbc06066232a00f3b27c2bedeee For example comment:39:ticket:3455 says "anyone implementing nsIProtocolProxy is forced to re-examine their code."

Is there an easy way to get at the output of the meek helper extension? Like what it is writing to stdout?

Here are the essential debugging patches.

This one makes the headless browser not headless, so you can Ctrl+J and view the Browser Console. To apply it, you need to first unzip the xpi.

cd Browser/TorBrowser/Data/Browser/profile.meek-http-helper/extensions
mkdir meek-http-helper@bamsoftware.com
cd meek-http-helper@bamsoftware.com
unzip ../meek-http-helper@bamsoftware.com.xpi
rm ../meek-http-helper@bamsoftware.com
# Now edit meek-http-helper@bamsoftware.com/components/main.js.

--- a/components/main.js
+++ b/components/main.js
@@ -83,13 +83,17 @@ MeekHTTPHelper.prototype = {
 
             // Block forever.
             // https://developer.mozilla.org/en-US/Add-ons/Code_snippets/Threads#Waiting_for_a_background_task_to_complete
+            /*
             var thread = Components.classes["@mozilla.org/thread-manager;1"].getService().currentThread;
             while (true)
                 thread.processNextEvent(true);
+            */
         } finally {
+            /*
             var app = Components.classes["@mozilla.org/toolkit/app-startup;1"]
                 .getService(Components.interfaces.nsIAppStartup);
             app.quit(app.eForceQuit);
+            */
         }
     },

Unfortunately I don't know of a way to view the browser dump messages out of the box, but you can do it by patching meek-client-torbrowser to log those messages. You also have to enable logging by adding the --log option to the ClientTransportPlugin line (note meek-client-torbrowser and meek-client have separate logs). The log will be written to Browser/meek-client-torbrowser.log.

ClientTransportPlugin meek exec ./TorBrowser/Tor/PluggableTransports/meek-client-torbrowser --log meek-client-torbrowser.log -- ./TorBrowser/Tor/PluggableTransports/meek-client

--- a/meek-client-torbrowser/meek-client-torbrowser.go
+++ b/meek-client-torbrowser/meek-client-torbrowser.go
@@ -102,6 +102,7 @@ func grepHelperAddr(r io.Reader) (string, error) {
        scanner := bufio.NewScanner(r)
        for scanner.Scan() {
                line := scanner.Text()
+               log.Print(line)
                if m := helperAddrPattern.FindStringSubmatch(line); m != nil {
                        helperAddr = m[1]
                        break
@@ -116,7 +117,12 @@ func grepHelperAddr(r io.Reader) (string, error) {
                return "", io.EOF
        }
        // Keep reading from the browser to avoid its output buffer filling.
-       go io.Copy(ioutil.Discard, r)
+       go func() {
+               for scanner.Scan() {
+                       line := scanner.Text()
+                       log.Print(line)
+               }
+       }()
        return helperAddr, nil
 }

I usually just symlink Browser/TorBrowser/Tor/PluggableTransports/meek-client-torbrowser to my development build of meek-client-torbrowser when I'm testing something like this. To build meek-client-torbrowser,

export GOPATH=~/go
cd meek/meek-client-torbrowser
go build

There are also some commented log.Printf calls in meek-client itself that log when it tries to make a request. However I think the error happening somewhere inside Firefox; none of the meek code changed since 4.0.

Replying to dcf:

Unfortunately I don't know of a way to view the browser dump messages out of the box, but you can do it by patching meek-client-torbrowser to log those messages. You also have to enable logging by adding the --log option to the ClientTransportPlugin line (note meek-client-torbrowser and meek-client have separate logs). The log will be written to Browser/meek-client-torbrowser.log.

When I do this, I just get the same message on stdout that I got in the browser console.

2014/11/24 15:41:04 running firefox command ["./firefox" "-no-remote" "-profile" "/home/david/tor-browser_en-US/Browser/TorBrowser/Data/Browser/profile.meek-http-helper"]
2014/11/24 15:41:04 firefox started with pid 31954
2014/11/24 15:41:04 meek-http-helper: listen 127.0.0.1:51311
2014/11/24 15:41:04 running meek-client command ["./TorBrowser/Tor/PluggableTransports/meek-client" "--helper" "127.0.0.1:51311"]
2014/11/24 15:41:04 meek-client started with pid 31968
2014/11/24 15:41:06 ************************************************************
2014/11/24 15:41:06 * Call to xpconnect wrapped JSObject produced this error:  *
2014/11/24 15:41:06 [Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIHttpChannel.responseStatus]"  nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)"  location: "JS frame :: file:///home/david/tor-browser_en-US/Browser/TorBrowser/Data/Browser/profile.meek-http-helper/extensions/meek-http-helper@bamsoftware.com/components/main.js :: MeekHTTPHelper.HttpStreamListener.prototype.onStopRequest :: line 396"  data: no]
2014/11/24 15:41:06 ************************************************************

The offending patch is: https://gitweb.torproject.org/tor-browser.git/commitdiff/e0eaf6b471ae3bbc06066232a00f3b27c2bedeee

And I think I know what is going on: nsSocketTransport::SocketHost() is using the host of the nsIProxyInfo if there is any. And per default meek is creating an HTTP channel with a nsIProxyInfo which is instructing the browser to make a direct connection (type DIRECT). Thus, the host is empty but is nevertheless selected as the socket host as

if (mProxyInfo && !mProxyTransparent) {

is true. I guess we should just check that we not only have an nsIProxyInfo but a non-empty host as well (nsSocketTransport::SocketPort() is affected, too). Arthur?

(dcf - thanks for the logs they were pretty helpful and saved me some time :) )

Trac:
Cc: dcf, mcs to dcf, mcs, arthuredelstein

Replying to gk:

The offending patch is: https://gitweb.torproject.org/tor-browser.git/commitdiff/e0eaf6b471ae3bbc06066232a00f3b27c2bedeee

And I think I know what is going on: nsSocketTransport::SocketHost() is using the host of the nsIProxyInfo if there is any. And per default meek is creating an HTTP channel with a nsIProxyInfo which is instructing the browser to make a direct connection (type DIRECT). Thus, the host is empty but is nevertheless selected as the socket host as {{{ if (mProxyInfo && !mProxyTransparent) { }}} is true. I guess we should just check that we not only have an nsIProxyInfo but a non-empty host as well (nsSocketTransport::SocketPort() is affected, too). Arthur?

Thanks gk, that's great.

In case anyone is wondering why the code works like that (setting a proxy with a "direct" type instead of simply setting no proxy), it is just a failsafe; see legacy/trac#12674 (moved). Just in case something goes wrong and the extension shows a browser window, the global proxy setting in the extension profile is a non-working "blackhole" proxy. That is, the default proxy setting is blackholed, and the extension has to specifically ask to turn off the proxy for every request that it makes.

I tried this patch (copying the host and port from the URI into the "direct" nsIProxyInfo, rather than using empty values), but it didn't work. It also didnt' work if I hardcoded 443 for the port.

--- a/firefox/components/main.js
+++ b/firefox/components/main.js
@@ -149,3 +149,3 @@ MeekHTTPHelper.lookupStatus = function(status) {
 //   {"type": "socks4a", "host": "example.com", "port": 1080}
-MeekHTTPHelper.buildProxyInfo = function(spec) {
+MeekHTTPHelper.buildProxyInfo = function(spec, uri) {
     // https://developer.mozilla.org/en-US/docs/Mozilla/Tech/XPCOM/Reference/Interface/nsIProxyInfo#Constants
@@ -154,3 +154,3 @@ MeekHTTPHelper.buildProxyInfo = function(spec) {
         // "direct"; i.e., no proxy. This is the default.
-        return MeekHTTPHelper.proxyProtocolService.newProxyInfo("direct", "", 0, flags, 0xffffffff, null);
+        return MeekHTTPHelper.proxyProtocolService.newProxyInfo("direct", uri.host, uri.port, flags, 0xffffffff, null);
     } else if (spec.type === "http") {
@@ -198,5 +198,7 @@ MeekHTTPHelper.LocalConnectionHandler.prototype = {
 
+        var uri = MeekHTTPHelper.ioService.newURI(req.url, null, null);
+
         // Check what proxy to use, if any.
         // dump("using proxy " + JSON.stringify(req.proxy) + "\n");
-        var proxyInfo = MeekHTTPHelper.buildProxyInfo(req.proxy);
+        var proxyInfo = MeekHTTPHelper.buildProxyInfo(req.proxy, uri);
         if (proxyInfo === null) {
@@ -208,3 +210,2 @@ MeekHTTPHelper.LocalConnectionHandler.prototype = {
         // https://developer.mozilla.org/en-US/docs/XPCOM_Interface_Reference/nsIHttpChannel
-        var uri = MeekHTTPHelper.ioService.newURI(req.url, null, null);
         this.channel = MeekHTTPHelper.httpProtocolHandler.newProxiedChannel(uri, proxyInfo, 0, null)

It seems that previously the code used !mProxyHost.IsEmpty() as the signal for a proxy being set, not merely mProxyHost being true. Maybe that old condition should be restored? https://gitweb.torproject.org/tor-browser.git/diff/netwerk/base/src/nsSocketTransport2.h?h=tor-browser-31.2.0esr-4.5-1&id=e0eaf6b471ae3bbc06066232a00f3b27c2bedeee

Trac:
0001-fixup-Bug-3455.2.-Allow-RFC1929-authentication-usern.patch

Replying to dcf: [snip]

It seems that previously the code used !mProxyHost.IsEmpty() as the signal for a proxy being set, not merely mProxyHost being true. Maybe that old condition should be restored? https://gitweb.torproject.org/tor-browser.git/diff/netwerk/base/src/nsSocketTransport2.h?h=tor-browser-31.2.0esr-4.5-1&id=e0eaf6b471ae3bbc06066232a00f3b27c2bedeee

I'm posting a fixup here that simplifies that patch (e0eaf6b4) and restores the use of !mProxyHost.IsEmpty() in nsSocketTransport2.*. I did this work in trying to get the patch to land in mozilla-central (still working on that). The patch works for domain isolation, but I haven't had a chance to test it with meek. If anyone wants to give it a try, let me know if this helps.

Meek bridges don't work in TB 4.5alpha1

Designs

Child items ...

Activity