Use control port to determine if bridge works.

Parsing Tor's log file is ugly and error-prone.  It's cleaner to use
Tor's control port to figure out if a bridge bootstrapped correctly or
not.  The library bulb helps us accomplish this.

tor.go

 package main
 
 import (
-	"bufio"
 	"context"
 	"fmt"
 	"io"
@@ -11,29 +10,84 @@ import (
 	"os/exec"
 	"regexp"
 	"time"
+
+	"github.com/yawning/bulb"
 )
 
 const (
 	// Sixty seconds is a reasonable timeout according to:
 	// <https://bugs.torproject.org/32126#comment:1>
 	TorBootstrapTimeout = 60 * time.Second
+	CacheValidity       = 24 * time.Hour
 )
 
-// torHasBootstrapped returns true if the given log line indicates that tor has
-// successfully bootstrapped and false otherwise.
-func torHasBootstrapped(line string) bool {
+// CacheEntry represents an entry in our cache of bridges that we recently
+// tested.  Error is nil if a bridge works, and otherwise holds an error
+// string.  Time determines when we tested the bridge.
+type CacheEntry struct {
+	Error error
+	Time  time.Time
+}
+
+type TestCache map[string]*CacheEntry
+
+var cache TestCache = make(TestCache)
+
+// Regular expressions that match tor's bootstrap status events.
+var success = regexp.MustCompile(`PROGRESS=100`)
+var warning = regexp.MustCompile(`STATUS_CLIENT WARN BOOTSTRAP`)
+
+// BridgeLineToAddrPort takes a bridge line as input and returns a string
+// consisting of the bridge's addr:port.
+func BridgeLineToAddrPort(bridgeLine string) (string, error) {
+
+	// Represents an addr:port tuple.
+	re := regexp.MustCompile(`(?:[0-9]{1,3}\.){3}[0-9]{1,3}:[0-9]{1,5}`)
+	result := string(re.Find([]byte(bridgeLine)))
 
-	re := regexp.MustCompile(`Bootstrapped 100%`)
-	return re.Match([]byte(line))
+	if result == "" {
+		return result, fmt.Errorf("could not extract addr:port from bridge line")
+	} else {
+		return result, nil
+	}
 }
 
-// torEncounteredError returns true if the given log line indicates that tor
-// encountered an error while bootstrapping and false otherwise.
-func torEncounteredError(line string) bool {
+// IsCached returns a cache entry if the given bridge line has been tested
+// recently (as determined by CacheValidity), and nil otherwise.
+func (tc *TestCache) IsCached(bridgeLine string) *CacheEntry {
+
+	// First, prune expired cache entries.
+	now := time.Now()
+	for index, entry := range *tc {
+		if entry.Time.Before(now.Add(-CacheValidity)) {
+			delete(*tc, index)
+		}
+	}
 
-	// FIXME: Find a better way to handle this.
-	re := regexp.MustCompile(`(Problem bootstrapping|Bridge line|unable to connect)`)
-	return re.Match([]byte(line))
+	addrPort, err := BridgeLineToAddrPort(bridgeLine)
+	if err != nil {
+		return nil
+	}
+
+	return (*tc)[addrPort]
+}
+
+// AddEntry adds an entry for the given bridge and test result to our cache.
+func (tc *TestCache) AddEntry(bridgeLine string, result error) {
+
+	addrPort, err := BridgeLineToAddrPort(bridgeLine)
+	if err != nil {
+		return
+	}
+
+	log.Printf("Caching %q: %q", addrPort, result)
+	(*tc)[addrPort] = &CacheEntry{result, time.Now()}
+}
+
+// getDomainSocketPath takes as input the path to our data directory and
+// returns the path to the domain socket for tor's control port.
+func getDomainSocketPath(dataDir string) string {
+	return fmt.Sprintf("%s/control-socket", dataDir)
 }
 
 // writeConfigToTorrc writes the content of a Tor config file (including the
@@ -41,23 +95,60 @@ func torEncounteredError(line string) bool {
 func writeConfigToTorrc(tmpFh io.Writer, dataDir, bridgeLine string) error {
 
 	_, err := fmt.Fprintf(tmpFh, "UseBridges 1\n"+
+		"ControlPort unix:%s\n"+
 		"SocksPort auto\n"+
 		"SafeLogging 0\n"+
 		"__DisablePredictedCircuits\n"+
 		"DataDirectory %s\n"+
 		"ClientTransportPlugin obfs4 exec /usr/bin/obfs4proxy\n"+
 		"PathsNeededToBuildCircuits 0.25\n"+
-		"Bridge %s", dataDir, bridgeLine)
+		"Bridge %s", getDomainSocketPath(dataDir), dataDir, bridgeLine)
 
 	return err
 }
 
-// bootstrapTorOverBridge attempts to bootstrap a Tor connection over the given
-// bridge line.  This function returns nil if the bootstrap succeeds and an
-// error otherwise.
+// makeControlConnection attempts to establish a control connection with Tor's
+// given domain socket.  If successful, it returns the connection.  Otherwise,
+// it returns an error.
+func makeControlConnection(domainSocket string) (*bulb.Conn, error) {
+
+	var torCtrl *bulb.Conn
+	var err error
+
+	// Try connecting to tor's control socket.  It may take a second or two for
+	// it to be ready.
+	for attempts := 0; attempts < 10; attempts++ {
+		torCtrl, err = bulb.Dial("unix", domainSocket)
+		if err == nil {
+			if err := torCtrl.Authenticate(""); err != nil {
+				return nil, fmt.Errorf("authentication with tor's control port failed: %v", err)
+			}
+			return torCtrl, nil
+		} else {
+			time.Sleep(1 * time.Second)
+		}
+	}
+
+	return nil, fmt.Errorf("unable to connect to domain socket")
+}
+
+// bootstrapTorOverBridge implements a cache around
+// bootstrapTorOverBridgeWrapped.
 func bootstrapTorOverBridge(bridgeLine string) error {
+	if cacheEntry := cache.IsCached(bridgeLine); cacheEntry != nil {
+		return cacheEntry.Error
+	}
 
-	log.Printf("Creating temporary torrc file.")
+	err := bootstrapTorOverBridgeWrapped(bridgeLine)
+	cache.AddEntry(bridgeLine, err)
+
+	return err
+}
+
+// bootstrapTorOverBridgeWrapped attempts to bootstrap a Tor connection over
+// the given bridge line.  This function returns nil if the bootstrap succeeds
+// and an error otherwise.
+func bootstrapTorOverBridgeWrapped(bridgeLine string) error {
 
 	// Create our torrc.
 	tmpFh, err := ioutil.TempFile(os.TempDir(), "torrc-")
@@ -81,59 +172,52 @@ func bootstrapTorOverBridge(bridgeLine string) error {
 	ctx, cancel := context.WithTimeout(context.Background(), TorBootstrapTimeout)
 	defer cancel()
 
-	cmd := exec.CommandContext(ctx, "tor", "-f", tmpFh.Name())
-	stdout, err := cmd.StdoutPipe()
-	if err != nil {
-		return err
-	}
-
 	log.Printf("Using bridge line %q.", bridgeLine)
 	// Start tor but don't wait for the process to complete, so our call
 	// returns right away.
+	cmd := exec.CommandContext(ctx, "tor", "-f", tmpFh.Name())
 	if err = cmd.Start(); err != nil {
 		return err
 	}
 
-	// Read tor's log messages from stdout and try to figure out when/if tor
-	// bootstrapped successfully.
-	c := make(chan error)
-	go func() {
-		stdoutReader := bufio.NewReader(stdout)
-		for {
-			// If we hit our timeout, the tor process is terminated and we'll
-			// end up with an error here.
-			line, _, err := stdoutReader.ReadLine()
-			if err != nil {
-				log.Printf("Failed to read line from tor's stdout: %s", err)
-				c <- err
-				close(c)
-				return
-			}
-			log.Printf("tor says: %q", line)
-
-			if torEncounteredError(string(line)) {
-				if err := cmd.Process.Kill(); err != nil {
-					log.Printf("Failed to kill process: %s", err)
-				}
-				// FIXME: Is %v correct here?
-				c <- fmt.Errorf("%v", string(line))
-				close(c)
-				return
-			}
+	torCtrl, err := makeControlConnection(getDomainSocketPath(tmpDir))
+	if err != nil {
+		return err
+	}
+	defer torCtrl.Close()
+
+	// Start our async reader and listen for STATUS_CLIENT events, which
+	// include bootstrap messages:
+	// <https://gitweb.torproject.org/torspec.git/tree/control-spec.txt?id=b7cfa8619947be4a377366365f5ddee8e0733330#n2499>
+	torCtrl.StartAsyncReader()
+	if _, err := torCtrl.Request("SETEVENTS STATUS_CLIENT"); err != nil {
+		return fmt.Errorf("command SETEVENTS STATUS_CLIENT failed: %v", err)
+	}
 
-			if torHasBootstrapped(string(line)) {
-				log.Printf("Bootstrapping worked!")
-				if err := cmd.Process.Kill(); err != nil {
-					log.Printf("Failed to kill process: %s", err)
+	// Keep reading events until one of the following happens:
+	// 1) tor bootstrapped to 100%
+	// 2) tor encountered a warning while bootstrapping
+	// 3) we hit our timeout, which interrupts our call to NextEvent()
+	for {
+		ev, err := torCtrl.NextEvent()
+		if err != nil {
+			return err
+		}
+		log.Printf("Controller: %s", ev.RawLines)
+		for _, line := range ev.RawLines {
+			if success.MatchString(line) {
+				return nil
+			} else if warning.MatchString(line) {
+				re := regexp.MustCompile(`WARNING="([^"]*)"`)
+				matches := re.FindStringSubmatch(line)
+				if len(matches) != 2 {
+					log.Printf("Unexpected number of substring matches: %q", matches)
+					return fmt.Errorf("could not bootstrap")
 				}
-				c <- nil
-				close(c)
-				return
+				return fmt.Errorf(matches[1])
 			}
 		}
-	}()
-
-	// FIXME: Use context to figure out if tor died on us.
+	}
 
-	return <-c
+	return fmt.Errorf("could not bootstrap")
 }

tor_test.go

@@ -2,46 +2,18 @@ package main
 
 import (
 	"bytes"
+	"fmt"
 	"testing"
+	"time"
 )
 
-func TestTorHasBootstrapped(t *testing.T) {
-
-	r := torHasBootstrapped(`Oct 29 10:08:31.000 [notice] Bootstrapped 100%: Done`)
-	if !r {
-		t.Errorf("torHasBootstrapped failed to realise that Tor has bootstrapped.")
-	}
-
-	r = torHasBootstrapped(`Oct 29 10:08:30.000 [notice] Bootstrapped 90%: Establishing a Tor circuit`)
-	if r {
-		t.Errorf("torHasBootstrapped failed to realise that Tor has not bootstrapped.")
-	}
-}
-
-func TestTorEncounteredError(t *testing.T) {
-
-	r := torEncounteredError(`Oct 29 10:15:33.000 [warn] Proxy Client: unable to connect to 3.135.154.16:41609 ("general SOCKS server failure")`)
-	if !r {
-		t.Errorf("torEncounteredError failed to recognise bootstrapping error.")
-	}
-
-	r = torEncounteredError(`Oct 29 10:08:31.000 [notice] Bootstrapped 100%: Done`)
-	if r {
-		t.Errorf("torEncounteredError incorrectly detected a bootstrapping error.")
-	}
-
-	r = torEncounteredError(`Oct 29 10:17:49.000 [warn] Problem bootstrapping. Stuck at 5%: Connecting to directory server. (Can't connect to bridge; PT_MISSING; count 4; recommendation warn; host 0000000000000000000000000000000000000000 at 1.2.3.4:1234)`)
-	if !r {
-		t.Errorf("torEncounteredError failed to recognise bootstrapping error.")
-	}
-}
-
 func TestWriteConfigToTorrc(t *testing.T) {
 
 	bridgeLine := "1.2.3.4:1234"
 	dataDir := "/foo"
 	fileBuf := new(bytes.Buffer)
 	torrc := `UseBridges 1
+ControlPort unix:/foo/control-socket
 SocksPort auto
 SafeLogging 0
 __DisablePredictedCircuits
@@ -82,3 +54,88 @@ func TestBootstrapTorOverBridge(t *testing.T) {
 		t.Errorf("Failed to label default bridge as broken.")
 	}
 }
+
+func TestCacheFunctions(t *testing.T) {
+
+	cache := make(TestCache)
+	bridgeLine := "obfs4 127.0.0.1:1 cert=foo iat-mode=0"
+
+	e := cache.IsCached(bridgeLine)
+	if e != nil {
+		t.Errorf("Cache is empty but marks bridge line as existing.")
+	}
+
+	cache.AddEntry(bridgeLine, nil)
+	e = cache.IsCached(bridgeLine)
+	if e == nil {
+		t.Errorf("Could not retrieve existing element from cache.")
+	}
+
+	testError := fmt.Errorf("bridge is on fire")
+	cache.AddEntry(bridgeLine, testError)
+	e = cache.IsCached(bridgeLine)
+	if e.Error != testError {
+		t.Errorf("Got test result %q but expected %q.", e.Error, testError)
+	}
+}
+
+func TestCacheExpiration(t *testing.T) {
+
+	cache := make(TestCache)
+
+	const shortForm = "2006-Jan-02"
+	expiry, _ := time.Parse(shortForm, "2000-Jan-01")
+	bridgeLine1 := "1.1.1.1:1111"
+	addrPort, _ := BridgeLineToAddrPort(bridgeLine1)
+	cache[addrPort] = &CacheEntry{nil, expiry}
+
+	bridgeLine2 := "2.2.2.2:2222"
+	addrPort, _ = BridgeLineToAddrPort(bridgeLine2)
+	cache[addrPort] = &CacheEntry{nil, time.Now()}
+
+	e := cache.IsCached(bridgeLine1)
+	if e != nil {
+		t.Errorf("Expired cache entry was not successfully pruned.")
+	}
+
+	e = cache.IsCached(bridgeLine2)
+	if e == nil {
+		t.Errorf("Valid cache entry was incorrectly pruned.")
+	}
+}
+
+func TestBridgeLineToAddrPort(t *testing.T) {
+
+	_, err := BridgeLineToAddrPort("foo")
+	if err == nil {
+		t.Errorf("Failed to return error for invalid bridge line.")
+	}
+
+	_, err = BridgeLineToAddrPort("obfs4 1.1.1.1 FINGERPRINT")
+	if err == nil {
+		t.Errorf("Failed to return error for invalid bridge line.")
+	}
+
+	addrPort, err := BridgeLineToAddrPort("1.1.1.1:1")
+	if err != nil {
+		t.Errorf("Failed to accept valid bridge line.")
+	}
+	if addrPort != "1.1.1.1:1" {
+		t.Errorf("Returned invalid addr:port tuple.")
+	}
+
+	_, err = BridgeLineToAddrPort("255.255.255.255:12345")
+	if err != nil {
+		t.Errorf("Failed to accept valid bridge line.")
+	}
+
+	_, err = BridgeLineToAddrPort("255.255.255.255:12345 FINGERPRINT")
+	if err != nil {
+		t.Errorf("Failed to accept valid bridge line.")
+	}
+
+	_, err = BridgeLineToAddrPort("obfs4 255.255.255.255:12345 FINGERPRINT")
+	if err != nil {
+		t.Errorf("Failed to accept valid bridge line.")
+	}
+}

[Cecylia Bocovich]

I really like this implementation of a cache to only re-check bridges every week as a way of reducing load on this service. Some thoughts:

• Consider the following use case: an operator does some maintenance on their bridge machine and then uses bridgestrap to determine whether the bridge is still online after the maintenance. Their bridgeline is cached because they last checked less than a week ago. The result they get will have today's date in the response since the Time field in TestResult is assigned after the cached result is returned from bootstrapTorOverBridge. Alternatively, they use this tool to see that their bridge is down, fix the problem and then try another bootstrap only to get the cached error value. My main concern is that the operator has no way of knowing if the result is cached. One way to solve this would be to assign the time field with the time at which the actual bootstrap was conducted.

• At every request (every call to IsCached) is potentially too frequently to be iterating over an entire week's worth of cached contents. Maybe assigning each cache entry a timer is more efficient? I don't know enough about the Go backend details of the timer mechanism to tell if that would hurt or help.

[Philipp Winter]

At every request (every call to IsCached) is potentially too frequently to be iterating over an entire week's worth of cached contents. Maybe assigning each cache entry a timer is more efficient? I don't know enough about the Go backend details of the timer mechanism to tell if that would hurt or help.

That's a good point that had not occurred to me. To learn more, I added benchmark code in 471ab071 and it suggests that it takes 0.3 ms to prune a cache holding 10,000 elements. That should do for now but I filed #1 (closed) to implement your idea.

[Philipp Winter]

My main concern is that the operator has no way of knowing if the result is cached.

Yes, that's indeed an issue. I filed #2 to get that fixed.

[Philipp Winter]

(By the way, bridgestrap's cache validity period is one day and not one week.)