Merge pull request #4 from saucelabs/dans-log-headers

Improving proxy logging

internal/logger/logger.go

@@ -57,19 +57,18 @@ func (o *Options) Default() {
 	}
 }
 
-// Get returns logger. If logger isn't setup, it will exit with fatal.
+// Get returns the logger. If the logger isn't configured, it will exit with fatal.
 func Get() *sypl.Sypl {
 	if proxyLogger == nil {
-		log.Fatalln("Logger needs setup")
+		log.Fatalln("Logger is not configired")
 	}
 
 	return proxyLogger
 }
 
-// Setup logger. If it fails to setup, it will exit with fatal.
+// Setup logger. If it fails to set up, it will exit with fatal.
 func Setup(o *Options) *sypl.Sypl {
-	// Do nothing, if already setup. Otherwise, can trigger race condition in
-	// goroutine cases.
+	// Do nothing, if the logger is already set up.
 	if proxyLogger != nil {
 		return proxyLogger
 	}
@@ -100,7 +99,7 @@ func Setup(o *Options) *sypl.Sypl {
 			"filePath":  o.FilePath,
 			"level":     o.Level,
 		},
-	}, level.Debug, "Logging setup")
+	}, level.Trace, "Logging is configured")
 
 	return proxyLogger
 }

pkg/proxy/proxy.go

@@ -324,7 +324,7 @@ func setupUpstreamProxyConnection(ctx *goproxy.ProxyCtx, uri *url.URL) {
 
 	ctx.Proxy.ConnectDial = ctx.Proxy.NewConnectDialToProxyWithHandler(uri.String(), connectReqHandler)
 
-	logger.Get().Debuglnf("Connection to the upstream proxy %s is set up", uri.Redacted())
+	logger.Get().Tracelnf("Connection to the upstream proxy %s is set up", uri.Redacted())
 }
 
 // setupUpstreamProxyConnection dynamically forwards connections to an upstream
@@ -484,7 +484,7 @@ func (p *Proxy) Run() {
 	// Should not panic, but exit with proper error if method is called without
 	// Proxy is setup.
 	if p == nil {
-		logger.Get().Fatalln(ErrFailedToStartProxy, "Proxy isn't setup")
+		logger.Get().Fatalln(ErrFailedToStartProxy, "Proxy isn't set up")
 	}
 
 	// Do nothing if already running.
@@ -511,7 +511,7 @@ func (p *Proxy) Run() {
 		}
 	}
 
-	logger.Get().Debuglnf("Proxy to start at %s", p.parsedLocalProxyURI.Host)
+	logger.Get().Debuglnf("Listening on %s", p.parsedLocalProxyURI.Host)
 
 	// Updates state.
 	p.mutex.Lock()
@@ -672,25 +672,25 @@ func New(
 		p.pacParser = pacParser
 	}
 
-	// HTTPS handler.
 	p.proxy.OnRequest().HandleConnectFunc(func(host string, ctx *goproxy.ProxyCtx) (*goproxy.ConnectAction, string) {
-		logger.Get().Debugln("Request handled by the HTTPS handler")
+		logger.Get().Infolnf("%s %s -> %s", ctx.Req.Method, ctx.Req.RemoteAddr, ctx.Req.Host)
+		logger.Get().Debuglnf("%q", dumpHeaders(ctx.Req))
 
 		if err := p.setupHandlers(ctx); err != nil {
-			logger.Get().Errorlnf("Failed to setup handler (HTTPS) for request %s. %+v", ctx.Req.URL.String(), err)
+			logger.Get().Errorlnf("Failed to setup handler (HTTPS) for request %s. %+v", ctx.Req.URL.Redacted(), err)
 
 			return goproxy.RejectConnect, host
 		}
 
 		return nil, host
 	})
 
-	// HTTP handler.
 	p.proxy.OnRequest().DoFunc(func(req *http.Request, ctx *goproxy.ProxyCtx) (*http.Request, *http.Response) {
-		logger.Get().Debugln("Request handled by the HTTP handler")
+		logger.Get().Infolnf("%s %s -> %s", req.Method, req.RemoteAddr, req.Host)
+		logger.Get().Debuglnf("%q", dumpHeaders(ctx.Req))
 
 		if err := p.setupHandlers(ctx); err != nil {
-			logger.Get().Errorlnf("Failed to setup handler (HTTP) for request %s. %+v", ctx.Req.URL.String(), err)
+			logger.Get().Errorlnf("Failed to setup handler (HTTP) for request %s. %+v", ctx.Req.URL.Redacted(), err)
 
 			return nil, goproxy.NewResponse(
 				ctx.Req,
@@ -703,6 +703,13 @@ func New(
 		return ctx.Req, nil
 	})
 
+	p.proxy.OnResponse().DoFunc(func(resp *http.Response, ctx *goproxy.ProxyCtx) *http.Response {
+		logger.Get().Infolnf("%s <- %s %v (%v bytes)",
+			resp.Request.RemoteAddr, resp.Request.Host, resp.Status, resp.ContentLength)
+
+		return resp
+	})
+
 	// Local proxy authentication.
 	if parsedLocalProxyURI.User.Username() != "" {
 		if err := p.setupBasicAuth(parsedLocalProxyURI); err != nil {

pkg/proxy/utils.go

@@ -4,6 +4,8 @@ import (
 	"bytes"
 	"encoding/gob"
 	"fmt"
+	"net/http"
+	"net/http/httputil"
 	"net/url"
 	"os"
 	"strings"
@@ -48,3 +50,12 @@ func deepCopy(source, target interface{}) error {
 
 	return nil
 }
+
+func dumpHeaders(req *http.Request) []byte {
+	requestDump, err := httputil.DumpRequest(req, false)
+	if err != nil {
+		return nil
+	}
+
+	return requestDump
+}