update some logging

go.mod

@@ -3,7 +3,7 @@ module github.com/cactus/go-camo/v2
 go 1.19
 
 require (
-	github.com/cactus/mlog v1.0.6
+	github.com/cactus/mlog v1.0.9
 	github.com/jessevdk/go-flags v1.5.0
 	github.com/prometheus/client_golang v1.16.0
 	github.com/prometheus/common v0.44.0

go.sum

@@ -1,9 +1,7 @@
 github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM=
 github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw=
-github.com/cactus/mlog v1.0.5 h1:TjaBRUD0ToZMTzv30SRfwDJfvz3IxDUxcw1dNk6dKAQ=
-github.com/cactus/mlog v1.0.5/go.mod h1:z0zgmK5rbywKn+lJPzhLEFZOJejzfRBBW1RqC/1i588=
-github.com/cactus/mlog v1.0.6 h1:e119rK5LhOyV/mER2Jx7T0QNT314kyziCSokiiTrq0o=
-github.com/cactus/mlog v1.0.6/go.mod h1:z0zgmK5rbywKn+lJPzhLEFZOJejzfRBBW1RqC/1i588=
+github.com/cactus/mlog v1.0.9 h1:34fiSfH7Ds9N50fXP2/c5xNvp1mZBZZCda9GJ1+fwxE=
+github.com/cactus/mlog v1.0.9/go.mod h1:z0zgmK5rbywKn+lJPzhLEFZOJejzfRBBW1RqC/1i588=
 github.com/cactus/tai64 v1.0.2 h1:c5rm3aQ9z3b6Vva2LXRSICx/Rpu9rj4MHEzRG1g7dK0=
 github.com/cactus/tai64 v1.0.2/go.mod h1:gu5LAXd6eWwrRD/HPw+aTrJF5WkieYswRVLSNslKGg4=
 github.com/cespare/xxhash/v2 v2.2.0 h1:DC2CZ1Ep5Y4k3ZQ899DldepgrayRUGE6BBZ/cd9Cj44=

pkg/camo/proxy.go

@@ -116,13 +116,13 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 	}
 
 	if mlog.HasDebug() {
-		mlog.Debugm("signed client url", mlog.Map{"url": sURL})
+		mlog.Debugx("signed client url", mlog.A("url", sURL))
 	}
 
 	u, err := url.Parse(sURL)
 	if err != nil {
 		if mlog.HasDebug() {
-			mlog.Debugm("url parse error", mlog.Map{"err": err})
+			mlog.Debugx("url parse error", mlog.A("err", err))
 		}
 		http.Error(w, "Bad url", http.StatusBadRequest)
 		return
@@ -137,7 +137,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 	nreq, err := http.NewRequestWithContext(req.Context(), req.Method, sURL, nil)
 	if err != nil {
 		if mlog.HasDebug() {
-			mlog.Debugm("could not create NewRequest", mlog.Map{"err": err})
+			mlog.Debugx("could not create NewRequest", mlog.A("err", err))
 		}
 		http.Error(w, "Error Fetching Resource", http.StatusBadGateway)
 		return
@@ -172,7 +172,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 	nreq.Header.Add("Via", p.config.ServerName)
 
 	if mlog.HasDebug() {
-		mlog.Debugm("built outgoing request", mlog.Map{"req": httpReqToMlogMap(nreq)})
+		mlog.Debugm("built outgoing request", httpReqToMlogMap(nreq))
 	}
 
 	resp, err := p.client.Do(nreq)
@@ -198,36 +198,36 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 		case errors.Is(err, ErrRedirect):
 			// Got a bad redirect
 			if mlog.HasDebug() {
-				mlog.Debugm("bad redirect from server", mlog.Map{"err": err})
+				mlog.Debugx("bad redirect from server", mlog.A("err", err))
 			}
 			http.Error(w, "Error Fetching Resource", http.StatusNotFound)
 			return
 		case errors.Is(err, ErrRejectIP):
 			// Got a deny list failure from Dial.Control
 			if mlog.HasDebug() {
-				mlog.Debugm("ip filter rejection from dial.control", mlog.Map{"err": err})
+				mlog.Debugx("ip filter rejection from dial.control", mlog.A("err", err))
 			}
 			http.Error(w, "Error Fetching Resource", http.StatusNotFound)
 			return
 		case errors.Is(err, ErrInvalidHostPort):
 			// Got a deny list failure from Dial.Control
 			if mlog.HasDebug() {
-				mlog.Debugm("invalid host/port rejection from dial.control", mlog.Map{"err": err})
+				mlog.Debugx("invalid host/port rejection from dial.control", mlog.A("err", err))
 			}
 			http.Error(w, "Error Fetching Resource", http.StatusNotFound)
 			return
 		case errors.Is(err, ErrInvalidNetType):
 			// Got a deny list failure from Dial.Control
 			if mlog.HasDebug() {
-				mlog.Debugm("net type rejection from dial.control", mlog.Map{"err": err})
+				mlog.Debugx("net type rejection from dial.control", mlog.A("err", err))
 			}
 			http.Error(w, "Error Fetching Resource", http.StatusNotFound)
 			return
 		}
 
 		// handle other errors
 		if mlog.HasDebug() {
-			mlog.Debugm("could not connect to endpoint", mlog.Map{"err": err})
+			mlog.Debugx("could not connect to endpoint", mlog.A("err", err))
 		}
 
 		// this is a bit janky, but some of these errors don't support
@@ -254,7 +254,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 			contentLengthExceeded.Inc()
 		}
 		if mlog.HasDebug() {
-			mlog.Debugm("content length exceeded", mlog.Map{"url": sURL})
+			mlog.Debugx("content length exceeded", mlog.A("url", sURL))
 		}
 		http.Error(w, "Content length exceeded", http.StatusNotFound)
 		return
@@ -283,7 +283,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 		mediatype, param, err := mime.ParseMediaType(contentType)
 		if err != nil || !p.acceptTypesFilter.CheckPath(mediatype) {
 			if mlog.HasDebug() {
-				mlog.Debugm("Unsupported content-type returned", mlog.Map{"type": u})
+				mlog.Debugx("Unsupported content-type returned", mlog.A("type", u))
 			}
 			http.Error(w, "Unsupported content-type returned", http.StatusBadRequest)
 			return
@@ -368,29 +368,29 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 		if err == context.Canceled || errors.Is(err, context.Canceled) {
 			// client aborted/closed request, which is why copy failed to finish
 			if mlog.HasDebug() {
-				mlog.Debugm("client aborted request (late)", mlog.Map{"req": req})
+				mlog.Debugx("client aborted request (late)", mlog.A("req", req))
 			}
 			return
 		}
 
 		// got an early EOF from the server side
 		if errors.Is(err, io.ErrUnexpectedEOF) {
 			if mlog.HasDebug() {
-				mlog.Debugm("server sent unexpected EOF", mlog.Map{"req": req})
+				mlog.Debugx("server sent unexpected EOF", mlog.A("req", req))
 			}
 			return
 		}
 
 		// only log broken pipe errors at debug level
 		if isBrokenPipe(err) {
 			if mlog.HasDebug() {
-				mlog.Debugm("error writing response", mlog.Map{"err": err, "req": req})
+				mlog.Debugx("error writing response", mlog.A("err", err), mlog.A("req", req))
 			}
 			return
 		}
 
 		// unknown error (not: a broken pipe; server early EOF; client close)
-		mlog.Printm("error writing response", mlog.Map{"err": err, "req": req})
+		mlog.Printx("error writing response", mlog.A("err", err), mlog.A("req", req))
 		return
 	}
 
@@ -399,13 +399,13 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 			responseTruncated.Inc()
 		}
 		if mlog.HasDebug() {
-			mlog.Debugm("response to client truncated: size > MaxSize", mlog.Map{"req": req})
+			mlog.Debugx("response to client truncated: size > MaxSize", mlog.A("req", req))
 		}
 		return
 	}
 
 	if mlog.HasDebug() {
-		mlog.Debugm("response to client", mlog.Map{"resp": w})
+		mlog.Debugx("response to client", mlog.A("resp", w))
 	}
 }
 
@@ -613,14 +613,14 @@ func New(pc Config) (*Proxy, error) {
 	client.CheckRedirect = func(req *http.Request, via []*http.Request) error {
 		if len(via) >= pc.MaxRedirects {
 			if mlog.HasDebug() {
-				mlog.Debug("Got bad redirect: Too many redirects", mlog.Map{"url": req})
+				mlog.Debugx("Got bad redirect: Too many redirects", mlog.A("url", req))
 			}
 			return fmt.Errorf("Too many redirects: %w", ErrRedirect)
 		}
 		err := p.checkURL(req.URL)
 		if err != nil {
 			if mlog.HasDebug() {
-				mlog.Debugm("Got bad redirect", mlog.Map{"url": req})
+				mlog.Debugx("Got bad redirect", mlog.A("url", req))
 			}
 			return fmt.Errorf("Bad redirect: %w", ErrRedirect)
 		}

pkg/camo/proxy_timeout_test.go

@@ -101,7 +101,7 @@ func TestClientCancelEarly(t *testing.T) {
 				_, err := fmt.Fprintf(w, "Chunk #%d\n", i)
 				// conn closed/broken pipe
 				if err != nil {
-					mlog.Debugm("write error", mlog.Map{"err": err, "i": i})
+					mlog.Debugx("write error", mlog.A("err", err), mlog.A("i", i))
 					break
 				}
 				flusher.Flush() // Trigger "chunked" encoding and send a chunk...
@@ -159,7 +159,7 @@ func TestClientCancelLate(t *testing.T) {
 				_, err := fmt.Fprintf(w, "Chunk #%d\n", i)
 				// conn closed/broken pipe
 				if err != nil {
-					mlog.Debugm("write error", mlog.Map{"err": err, "i": i})
+					mlog.Debugx("write error", mlog.A("err", err), mlog.A("i", i))
 					break
 				}
 				flusher.Flush() // Trigger "chunked" encoding and send a chunk...

pkg/router/httpdate_test.go

@@ -6,6 +6,8 @@ package router
 
 import (
 	"bytes"
+	"flag"
+	"os"
 	"testing"
 	"time"
 
@@ -15,10 +17,6 @@ import (
 
 var logBuffer = &bytes.Buffer{}
 
-func init() {
-	mlog.DefaultLogger = mlog.New(logBuffer, mlog.Lstd)
-}
-
 func TestHTTPDateGoroutineUpdate(t *testing.T) {
 	t.Parallel()
 	d := newiHTTPDate()
@@ -59,3 +57,20 @@ func BenchmarkDataString(b *testing.B) {
 		}
 	})
 }
+
+func TestMain(m *testing.M) {
+	flag.Parse()
+
+	debug := os.Getenv("DEBUG")
+	// now configure a standard logger
+	mlog.SetFlags(mlog.Lstd)
+
+	if debug != "" {
+		mlog.SetFlags(mlog.Flags() | mlog.Ldebug)
+		mlog.Debug("debug logging enabled")
+	}
+
+	mlog.DefaultLogger = mlog.New(logBuffer, mlog.Lstd)
+
+	os.Exit(m.Run())
+}