Contextual logging

src/github.com/getlantern/flashlight/client/handler.go

@@ -3,13 +3,16 @@ package client
 import (
 	"fmt"
 	"io"
+	"math/rand"
 	"net"
 	"net/http"
 	"net/http/httputil"
 	"strconv"
 	"sync"
 	"time"
 
+	"github.com/getlantern/golog"
+
 	"github.com/getlantern/flashlight/logging"
 )
 
@@ -21,8 +24,20 @@ const (
 // handler available from getHandler() and latest ReverseProxy available from
 // getReverseProxy().
 func (client *Client) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
-	logging.RegisterUserAgent(req.Header.Get("User-Agent"))
+	userAgent := req.Header.Get("User-Agent")
+	logging.RegisterUserAgent(userAgent)
+
+	golog.WithContext(golog.Map{
+		"op":         "proxy",
+		"user_agent": userAgent,
+		"request_id": rand.Int63(),
+		"origin":     req.Host,
+	}, func() {
+		client.doServeHTTP(resp, req)
+	})
+}
 
+func (client *Client) doServeHTTP(resp http.ResponseWriter, req *http.Request) {
 	if req.Method == httpConnectMethod {
 		// CONNECT requests are often used for HTTPS requests.
 		log.Tracef("Intercepting CONNECT %s", req.URL)
@@ -123,14 +138,14 @@ func (client *Client) intercept(resp http.ResponseWriter, req *http.Request) {
 	}
 
 	success := make(chan bool, 1)
-	go func() {
+	golog.Go(func() {
 		if e := respondOK(clientConn, req); e != nil {
 			log.Errorf("Unable to respond OK: %s", e)
 			success <- false
 			return
 		}
 		success <- true
-	}()
+	})
 
 	if <-success {
 		// Pipe data between the client and the proxy.
@@ -142,12 +157,12 @@ func (client *Client) intercept(resp http.ResponseWriter, req *http.Request) {
 // responsible for responding to the initial CONNECT request with a 200 OK.
 func pipeData(clientConn net.Conn, connOut net.Conn, closeFunc func()) {
 	// Start piping from client to proxy
-	go func() {
+	golog.Go(func() {
 		if _, err := io.Copy(connOut, clientConn); err != nil {
 			log.Tracef("Error piping data from client to proxy: %s", err)
 		}
 		closeFunc()
-	}()
+	})
 
 	// Then start copying from proxy to client.
 	if _, err := io.Copy(clientConn, connOut); err != nil {

src/github.com/getlantern/flashlight/client/pluggable_transports.go

@@ -2,10 +2,10 @@ package client
 
 import (
 	"crypto/tls"
-	"fmt"
 	"net"
 
 	"github.com/Yawning/obfs4/transports/obfs4"
+	"github.com/getlantern/golog"
 	"github.com/getlantern/keyman"
 	"github.com/getlantern/tlsdialer"
 
@@ -33,47 +33,58 @@ func defaultDialFactory(s *ChainedServerInfo, deviceID string) (dialFN, error) {
 
 	if s.Cert == "" && !forceProxy {
 		log.Error("No Cert configured for chained server, will dial with plain tcp")
-		dial = func() (net.Conn, error) {
-			return netd.Dial("tcp", addr)
+		dial = func() (conn net.Conn, err error) {
+			withProxyContext(s.Addr, "http", func() {
+				conn, err = netd.Dial("tcp", addr)
+			})
+			return
 		}
 	} else {
 		log.Trace("Cert configured for chained server, will dial with tls over tcp")
 		cert, err := keyman.LoadCertificateFromPEMBytes([]byte(s.Cert))
 		if err != nil {
-			return nil, fmt.Errorf("Unable to parse certificate: %s", err)
+			return nil, log.Errorf("Unable to parse certificate: %s", err)
 		}
 		x509cert := cert.X509()
 		sessionCache := tls.NewLRUClientSessionCache(1000)
-		dial = func() (net.Conn, error) {
+
+		dialTLS := func() (net.Conn, error) {
 			conn, err := tlsdialer.DialWithDialer(netd, "tcp", addr, false, &tls.Config{
 				ClientSessionCache: sessionCache,
 				InsecureSkipVerify: true,
 			})
 			if err != nil {
-				return nil, err
+				return nil, log.Error(err)
 			}
 			if !forceProxy && !conn.ConnectionState().PeerCertificates[0].Equal(x509cert) {
-				if err := conn.Close(); err != nil {
-					log.Debugf("Error closing chained server connection: %s", err)
+				if err2 := conn.Close(); err2 != nil {
+					log.Debugf("Error closing chained server connection: %s", err2)
 				}
-				return nil, fmt.Errorf("Server's certificate didn't match expected!")
+				return nil, log.Errorf("Server's certificate didn't match expected!")
 			}
 			return conn, err
 		}
+
+		dial = func() (conn net.Conn, err error) {
+			withProxyContext(s.Addr, "https", func() {
+				conn, err = dialTLS()
+			})
+			return
+		}
 	}
 
 	return dial, nil
 }
 
 func obfs4DialFactory(s *ChainedServerInfo, deviceID string) (dialFN, error) {
 	if s.Cert == "" {
-		return nil, fmt.Errorf("No Cert configured for obfs4 server, can't connect")
+		return nil, log.Errorf("No Cert configured for obfs4 server, can't connect")
 	}
 
 	tr := obfs4.Transport{}
 	cf, err := tr.ClientFactory("")
 	if err != nil {
-		return nil, fmt.Errorf("Unable to create obfs4 client factory: %v", err)
+		return nil, log.Errorf("Unable to create obfs4 client factory: %v", err)
 	}
 
 	ptArgs := &pt.Args{}
@@ -82,10 +93,25 @@ func obfs4DialFactory(s *ChainedServerInfo, deviceID string) (dialFN, error) {
 
 	args, err := cf.ParseArgs(ptArgs)
 	if err != nil {
-		return nil, fmt.Errorf("Unable to parse client args: %v", err)
+		return nil, log.Errorf("Unable to parse client args: %v", err)
 	}
 
-	return func() (net.Conn, error) {
-		return cf.Dial("tcp", s.Addr, net.Dial, args)
+	return func() (conn net.Conn, err error) {
+		withProxyContext(s.Addr, "obfs4", func() {
+			conn, err = cf.Dial("tcp", s.Addr, net.Dial, args)
+		})
+		return
 	}, nil
 }
+
+func withProxyContext(addr string, protocol string, fn func()) {
+	m := golog.Map{
+		"proxy_protocol": protocol,
+	}
+	host, port, err := net.SplitHostPort(addr)
+	if err == nil {
+		m["proxy_host"] = host
+		m["proxy_port"] = port
+	}
+	golog.WithContext(m, fn)
+}

src/github.com/getlantern/golog/context.go

@@ -0,0 +1,46 @@
+package golog
+
+import (
+	"bytes"
+	"fmt"
+	"sort"
+
+	"github.com/getlantern/gls"
+)
+
+var (
+	ctx = gls.NewContextManager()
+)
+
+// Map is a map of values
+type Map gls.Values
+
+func WithContext(values Map, fn func()) {
+	ctx.SetValues(gls.Values(values), fn)
+}
+
+func Go(fn func()) {
+	gls.Go(fn)
+}
+
+func printContextTo(buf *bytes.Buffer) {
+	values := ctx.GetAll()
+	if values != nil && len(values) > 0 {
+		buf.WriteString(" [")
+		var keys []string
+		for key := range values {
+			keys = append(keys, key.(string))
+		}
+		sort.Strings(keys)
+		for i, key := range keys {
+			value := values[key]
+			if i > 0 {
+				buf.WriteString(" ")
+			}
+			buf.WriteString(key)
+			buf.WriteString("=")
+			fmt.Fprintf(buf, "%v", value)
+		}
+		buf.WriteByte(']')
+	}
+}

src/github.com/getlantern/golog/golog.go

@@ -18,10 +18,14 @@ import (
 	"strconv"
 	"strings"
 	"sync/atomic"
+
+	"github.com/oxtoacart/bpool"
 )
 
 var (
 	outs atomic.Value
+
+	bufferPool = bpool.NewBufferPool(200)
 )
 
 func init() {
@@ -55,9 +59,9 @@ type Logger interface {
 	Debugf(message string, args ...interface{})
 
 	// Error logs to stderr
-	Error(arg interface{})
+	Error(arg interface{}) error
 	// Errorf logs to stderr
-	Errorf(message string, args ...interface{})
+	Errorf(message string, args ...interface{}) error
 
 	// Fatal logs to stderr and then exits with status 1
 	Fatal(arg interface{})
@@ -134,7 +138,15 @@ func (l *logger) linePrefix(skipFrames int) string {
 }
 
 func (l *logger) print(out io.Writer, skipFrames int, severity string, arg interface{}) {
-	_, err := fmt.Fprintf(out, severity+" "+l.linePrefix(skipFrames)+"%s\n", arg)
+	buf := bufferPool.Get()
+	defer bufferPool.Put(buf)
+	buf.WriteString(severity)
+	buf.WriteString(" ")
+	buf.WriteString(l.linePrefix(skipFrames))
+	fmt.Fprintf(buf, "%v", arg)
+	printContextTo(buf)
+	buf.WriteByte('\n')
+	_, err := out.Write(buf.Bytes())
 	if err != nil {
 		errorOnLogging(err)
 	}
@@ -144,7 +156,15 @@ func (l *logger) print(out io.Writer, skipFrames int, severity string, arg inter
 }
 
 func (l *logger) printf(out io.Writer, skipFrames int, severity string, message string, args ...interface{}) {
-	_, err := fmt.Fprintf(out, severity+" "+l.linePrefix(skipFrames)+message+"\n", args...)
+	buf := bufferPool.Get()
+	defer bufferPool.Put(buf)
+	buf.WriteString(severity)
+	buf.WriteString(" ")
+	buf.WriteString(l.linePrefix(skipFrames))
+	fmt.Fprintf(buf, message, args...)
+	printContextTo(buf)
+	buf.WriteByte('\n')
+	_, err := out.Write(buf.Bytes())
 	if err != nil {
 		errorOnLogging(err)
 	}
@@ -161,12 +181,22 @@ func (l *logger) Debugf(message string, args ...interface{}) {
 	l.printf(GetOutputs().DebugOut, 4, "DEBUG", message, args...)
 }
 
-func (l *logger) Error(arg interface{}) {
-	l.print(GetOutputs().ErrorOut, 4, "ERROR", arg)
+func (l *logger) Error(arg interface{}) error {
+	var err error
+	switch e := arg.(type) {
+	case error:
+		err = e
+	default:
+		err = fmt.Errorf("%v", e)
+	}
+	l.print(GetOutputs().ErrorOut, 4, "ERROR", err)
+	return err
 }
 
-func (l *logger) Errorf(message string, args ...interface{}) {
-	l.printf(GetOutputs().ErrorOut, 4, "ERROR", message, args...)
+func (l *logger) Errorf(message string, args ...interface{}) error {
+	err := fmt.Errorf(message, args...)
+	l.print(GetOutputs().ErrorOut, 4, "ERROR", err)
+	return err
 }
 
 func (l *logger) Fatal(arg interface{}) {

src/github.com/getlantern/golog/golog_test.go

@@ -15,9 +15,9 @@ import (
 )
 
 var (
-	expectedLog      = "myprefix: golog_test.go:([0-9]+) Hello world\nmyprefix: golog_test.go:([0-9]+) Hello 5\n"
+	expectedLog      = "myprefix: golog_test.go:([0-9]+) Hello world\nmyprefix: golog_test.go:([0-9]+) Hello 5 \\[cvar1=a cvar2=2\\]\n"
 	expectedTraceLog = "myprefix: golog_test.go:([0-9]+) Hello world\nmyprefix: golog_test.go:([0-9]+) Hello 5\nmyprefix: golog_test.go:([0-9]+) Gravy\nmyprefix: golog_test.go:([0-9]+) TraceWriter closed due to unexpected error: EOF\n"
-	expectedStdLog   = "myprefix: golog_test.go:([0-9]+) Hello world\nmyprefix: golog_test.go:([0-9]+) Hello 5\n"
+	expectedStdLog   = expectedLog
 )
 
 func expected(severity string, log string) *regexp.Regexp {
@@ -33,7 +33,12 @@ func TestDebug(t *testing.T) {
 	SetOutputs(ioutil.Discard, out)
 	l := LoggerFor("myprefix")
 	l.Debug("Hello world")
-	l.Debugf("Hello %d", 5)
+	WithContext(Map{
+		"cvar1": "a",
+		"cvar2": 2,
+	}, func() {
+		l.Debugf("Hello %d", 5)
+	})
 	assert.Regexp(t, expected("DEBUG", expectedLog), string(out.Bytes()))
 }
 
@@ -42,8 +47,12 @@ func TestError(t *testing.T) {
 	SetOutputs(out, ioutil.Discard)
 	l := LoggerFor("myprefix")
 	l.Error("Hello world")
-	l.Errorf("Hello %d", 5)
-
+	WithContext(Map{
+		"cvar1": "a",
+		"cvar2": 2,
+	}, func() {
+		l.Errorf("Hello %d", 5)
+	})
 	assert.Regexp(t, expected("ERROR", expectedLog), string(out.Bytes()))
 }
 
@@ -110,7 +119,12 @@ func TestAsStdLogger(t *testing.T) {
 	l := LoggerFor("myprefix")
 	stdlog := l.AsStdLogger()
 	stdlog.Print("Hello world")
-	stdlog.Printf("Hello %d", 5)
+	WithContext(Map{
+		"cvar1": "a",
+		"cvar2": 2,
+	}, func() {
+		stdlog.Printf("Hello %d", 5)
+	})
 	assert.Regexp(t, severitize("ERROR", expectedStdLog), string(out.Bytes()))
 }