always use request logging middleware (gomods#1522)

* always use request logging middleware

* reads better

* rm http-url as it is redundant

* gopls being redundant

* add color name

cmd/proxy/actions/app.go

@@ -56,10 +56,8 @@ func App(conf *config.Config) (http.Handler, error) {
 	lggr := log.New(conf.CloudRuntime, logLvl)
 
 	r := mux.NewRouter()
-	if conf.GoEnv == "development" {
-		r.Use(mw.RequestLogger)
-	}
 	r.Use(mw.LogEntryMiddleware(lggr))
+	r.Use(mw.RequestLogger)
 	r.Use(secure.New(secure.Options{
 		SSLRedirect:     conf.ForceSSL,
 		SSLProxyHeaders: map[string]string{"X-Forwarded-Proto": "https"},

go.mod

@@ -30,11 +30,14 @@ require (
 	github.com/hashicorp/go-multierror v1.0.0
 	github.com/hashicorp/hcl2 v0.0.0-20190503213020-640445e16309
 	github.com/kelseyhightower/envconfig v1.3.0
+	github.com/kylelemons/godebug v1.1.0 // indirect
 	github.com/minio/minio-go/v6 v6.0.43
 	github.com/mitchellh/go-homedir v1.1.0
 	github.com/philhofer/fwd v1.0.0 // indirect
+	github.com/pkg/errors v0.8.1 // indirect
 	github.com/sirupsen/logrus v1.4.2
 	github.com/spf13/afero v1.1.2
+	github.com/spf13/pflag v1.0.3 // indirect
 	github.com/stretchr/testify v1.3.0
 	github.com/technosophos/moniker v0.0.0-20180509230615-a5dbd03a2245
 	github.com/tidwall/pretty v0.0.0-20180105212114-65a9db5fad51 // indirect

go.sum

@@ -182,6 +182,8 @@ github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
 github.com/kylelemons/godebug v0.0.0-20170820004349-d65d576e9348 h1:MtvEpTB6LX3vkb4ax0b5D2DHbNAUsen0Gx5wZoq3lV4=
 github.com/kylelemons/godebug v0.0.0-20170820004349-d65d576e9348/go.mod h1:B69LEHPfb2qLo0BaaOLcbitczOKLWTsrBG9LczfCD4k=
+github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc=
+github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw=
 github.com/markbates/hmax v1.0.0 h1:yo2N0gBoCnUMKhV/VRLHomT6Y9wUm+oQQENuWJqCdlM=
 github.com/markbates/hmax v1.0.0/go.mod h1:cOkR9dktiESxIMu+65oc/r/bdY4bE8zZw3OLhLx0X2c=
 github.com/mattn/go-colorable v0.0.9 h1:UVL0vNpWh04HeJXV0KLcaT7r06gOH2l4OW6ddYRUIY4=
@@ -216,6 +218,8 @@ github.com/philhofer/fwd v1.0.0/go.mod h1:gk3iGcWd9+svBvR0sR+KPcfE+RNWozjowpeBVG
 github.com/pierrec/lz4 v2.0.5+incompatible/go.mod h1:pdkljMzZIN41W+lC3N2tnIh5sFi+IEE17M5jbnwPHcY=
 github.com/pkg/errors v0.8.0 h1:WdK/asTD0HN+q6hsWO3/vpuAkAr+tw6aNJNDFFf0+qw=
 github.com/pkg/errors v0.8.0/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
+github.com/pkg/errors v0.8.1 h1:iURUrRGxPUNPdy5/HRSm+Yj6okJ6UtLINN0Q9M4+h3I=
+github.com/pkg/errors v0.8.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/client_golang v0.8.0/go.mod h1:7SWBe2y4D6OKWSNQJUaRYU/AaXPKyh/dDVn+NZz0KFw=
@@ -255,6 +259,8 @@ github.com/spf13/cobra v0.0.3/go.mod h1:1l0Ry5zgKvJasoi3XT1TypsSe7PqH0Sj9dhYf7v3
 github.com/spf13/pflag v1.0.1/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
 github.com/spf13/pflag v1.0.2 h1:Fy0orTDgHdbnzHcsOgfCN4LtHf0ec3wwtiwJqwvf3Gc=
 github.com/spf13/pflag v1.0.2/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
+github.com/spf13/pflag v1.0.3 h1:zPAT6CGy6wXeQ7NtTnaTerfKOsV6V6F8agHXFiazDkg=
+github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=

pkg/log/format.go

@@ -1,6 +1,13 @@
 package log
 
 import (
+	"bytes"
+	"fmt"
+	"sort"
+	"strings"
+	"time"
+
+	"github.com/fatih/color"
 	"github.com/sirupsen/logrus"
 )
 
@@ -15,7 +22,46 @@ func getGCPFormatter() logrus.Formatter {
 }
 
 func getDevFormatter() logrus.Formatter {
-	return &logrus.TextFormatter{}
+	return devFormatter{}
+}
+
+type devFormatter struct{}
+
+const lightGrey = 0xffccc
+
+func (devFormatter) Format(e *logrus.Entry) ([]byte, error) {
+	var buf bytes.Buffer
+	var sprintf func(format string, a ...interface{}) string
+	switch e.Level {
+	case logrus.DebugLevel:
+		sprintf = color.New(lightGrey).Sprintf
+	case logrus.WarnLevel:
+		sprintf = color.YellowString
+	case logrus.ErrorLevel:
+		sprintf = color.RedString
+	default:
+		sprintf = color.CyanString
+	}
+	lvl := strings.ToUpper(e.Level.String())
+	buf.WriteString(sprintf(lvl))
+	buf.WriteString("[" + e.Time.Format(time.Kitchen) + "]")
+	buf.WriteString(": ")
+	buf.WriteString(e.Message)
+	buf.WriteByte('\t')
+	for _, k := range sortFields(e.Data) {
+		fmt.Fprintf(&buf, "%s=%s ", color.MagentaString(k), e.Data[k])
+	}
+	buf.WriteByte('\n')
+	return buf.Bytes(), nil
+}
+
+func sortFields(data logrus.Fields) []string {
+	keys := []string{}
+	for k := range data {
+		keys = append(keys, k)
+	}
+	sort.Strings(keys)
+	return keys
 }
 
 func getDefaultFormatter() logrus.Formatter {

pkg/middleware/log_entry.go

@@ -16,7 +16,6 @@ func LogEntryMiddleware(lggr *log.Logger) mux.MiddlewareFunc {
 			ent := lggr.WithFields(logrus.Fields{
 				"http-method": r.Method,
 				"http-path":   r.URL.Path,
-				"http-url":    r.URL.String(),
 			})
 
 			ctx := log.SetEntryInContext(r.Context(), ent)

pkg/middleware/log_entry_test.go

@@ -34,6 +34,6 @@ func TestLogContext(t *testing.T) {
 	req, _ := http.NewRequest("GET", "/test", nil)
 	r.ServeHTTP(w, req)
 
-	expected := `{"http-method":"GET","http-path":"/test","http-url":"/test","level":"info","msg":"test"}`
+	expected := `{"http-method":"GET","http-path":"/test","level":"info","msg":"test"}`
 	assert.True(t, strings.Contains(buf.String(), expected), fmt.Sprintf("%s should contain: %s", buf.String(), expected))
 }

pkg/middleware/request.go

@@ -5,6 +5,8 @@ import (
 	"net/http"
 
 	"github.com/fatih/color"
+	"github.com/gomods/athens/pkg/log"
+	logrus "github.com/sirupsen/logrus"
 )
 
 type responseWriter struct {
@@ -23,18 +25,14 @@ func RequestLogger(h http.Handler) http.Handler {
 	f := func(w http.ResponseWriter, r *http.Request) {
 		rw := &responseWriter{w, 0}
 		h.ServeHTTP(rw, r)
-		fmt.Println(
-			fmtRequest(
-				r.Method,
-				r.URL.Path,
-				rw.statusCode,
-			),
-		)
+		log.EntryFromContext(r.Context()).WithFields(logrus.Fields{
+			"http-status": fmtResponseCode(rw.statusCode),
+		}).Infof("incoming request")
 	}
 	return http.HandlerFunc(f)
 }
 
-func fmtRequest(method, path string, statusCode int) string {
+func fmtResponseCode(statusCode int) string {
 	if statusCode == 0 {
 		statusCode = 200
 	}
@@ -47,11 +45,5 @@ func fmtRequest(method, path string, statusCode int) string {
 	default:
 		status = color.HiRedString("%v", status)
 	}
-	return fmt.Sprintf(
-		"%v %v %v [%v]",
-		color.CyanString("handler:"),
-		method,
-		path,
-		status,
-	)
+	return status
 }