Move request logger to pkg/middleware and add tests

cmd/milmove/main.go

@@ -592,7 +592,7 @@ func serveFunction(cmd *cobra.Command, args []string) error {
 	root := goji.NewMux()
 	root.Use(middleware.Recovery(logger))
 	root.Use(sessionCookieMiddleware)
-	root.Use(logging.LogRequestMiddleware(logger))
+	root.Use(middleware.RequestLogger(logger))
 
 	// CSRF path is set specifically at the root to avoid duplicate tokens from different paths
 	csrfAuthKey, err := hex.DecodeString(v.GetString(cli.CSRFAuthKeyFlag))

pkg/logging/log.go

@@ -1,16 +1,8 @@
 package logging
 
 import (
-	"net/http"
-	"strings"
-
-	"github.com/felixge/httpsnoop"
-	"github.com/gofrs/uuid"
-
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
-
-	"github.com/transcom/mymove/pkg/auth"
 )
 
 // Config configures a Zap logger based on the environment string and debugLevel
@@ -33,69 +25,3 @@ func Config(env string, debugLogging bool) (*zap.Logger, error) {
 
 	return loggerConfig.Build()
 }
-
-// LogRequestMiddleware generates an HTTP/HTTPS request logs using Zap
-func LogRequestMiddleware(logger Logger) func(inner http.Handler) http.Handler {
-	return func(inner http.Handler) http.Handler {
-		mw := func(w http.ResponseWriter, r *http.Request) {
-			var protocol, tspUserID, officeUserID, serviceMemberID, userID string
-
-			if r.TLS == nil {
-				protocol = "http"
-			} else {
-				protocol = "https"
-			}
-
-			session := auth.SessionFromRequestContext(r)
-			if session.UserID != uuid.Nil {
-				userID = session.UserID.String()
-			}
-			if session.IsServiceMember() {
-				serviceMemberID = session.ServiceMemberID.String()
-			}
-
-			if session.IsOfficeUser() {
-				officeUserID = session.OfficeUserID.String()
-			}
-
-			if session.IsTspUser() {
-				tspUserID = session.TspUserID.String()
-			}
-
-			metrics := httpsnoop.CaptureMetrics(inner, w, r)
-
-			fields := []zap.Field{
-				zap.String("accepted-language", r.Header.Get("accepted-language")),
-				zap.Int64("content-length", r.ContentLength),
-				zap.Duration("duration", metrics.Duration),
-				zap.String("host", r.Host),
-				zap.String("method", r.Method),
-				zap.String("office-user-id", officeUserID),
-				zap.String("tsp-user-id", tspUserID),
-				zap.String("protocol", protocol),
-				zap.String("protocol-version", r.Proto),
-				zap.String("referer", r.Header.Get("referer")),
-				zap.Int64("resp-size-bytes", metrics.Written),
-				zap.Int("resp-status", metrics.Code),
-				zap.String("service-member-id", serviceMemberID),
-				zap.String("source", r.RemoteAddr),
-				zap.String("url", r.URL.String()),
-				zap.String("user-agent", r.UserAgent()),
-				zap.String("user-id", userID),
-			}
-
-			// Append x- headers, e.g., x-forwarded-for.
-			for name, values := range r.Header {
-				if nameLowerCase := strings.ToLower(name); strings.HasPrefix(nameLowerCase, "x-") {
-					if len(values) > 0 {
-						fields = append(fields, zap.String(nameLowerCase, values[0]))
-					}
-				}
-			}
-
-			logger.Info("Request", fields...)
-
-		}
-		return http.HandlerFunc(mw)
-	}
-}

pkg/middleware/logger.go

@@ -11,4 +11,5 @@ type Logger interface {
 	Error(msg string, fields ...zap.Field)
 	Warn(msg string, fields ...zap.Field)
 	Fatal(msg string, fields ...zap.Field)
+	WithOptions(options ...zap.Option) *zap.Logger
 }

pkg/middleware/request_logger.go

@@ -0,0 +1,76 @@
+package middleware
+
+import (
+	"net/http"
+	"strings"
+
+	"github.com/felixge/httpsnoop"
+	"github.com/gofrs/uuid"
+
+	"go.uber.org/zap"
+
+	"github.com/transcom/mymove/pkg/auth"
+)
+
+// RequestLogger returns a middleware that logs requests.
+// The middleware trys to use the logger from the context.
+// If the request context has no handler, then falls back to the server logger.
+func RequestLogger(logger Logger) func(inner http.Handler) http.Handler {
+	return func(inner http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+
+			fields := []zap.Field{
+				zap.String("accepted-language", r.Header.Get("accepted-language")),
+				zap.Int64("content-length", r.ContentLength),
+				zap.String("host", r.Host),
+				zap.String("method", r.Method),
+				zap.String("protocol-version", r.Proto),
+				zap.String("referer", r.Header.Get("referer")),
+				zap.String("source", r.RemoteAddr),
+				zap.String("url", r.URL.String()),
+				zap.String("user-agent", r.UserAgent()),
+			}
+
+			if r.TLS == nil {
+				fields = append(fields, zap.String("protocol", "http"))
+			} else {
+				fields = append(fields, zap.String("protocol", "https"))
+			}
+
+			// Append x- headers, e.g., x-forwarded-for.
+			for name, values := range r.Header {
+				if nameLowerCase := strings.ToLower(name); strings.HasPrefix(nameLowerCase, "x-") {
+					if len(values) > 0 {
+						fields = append(fields, zap.String(nameLowerCase, values[0]))
+					}
+				}
+			}
+
+			if session := auth.SessionFromRequestContext(r); session != nil {
+				if session.UserID != uuid.Nil {
+					fields = append(fields, zap.String("user-id", session.UserID.String()))
+				}
+				if session.IsServiceMember() {
+					fields = append(fields, zap.String("service-member-id", session.ServiceMemberID.String()))
+				}
+				if session.IsOfficeUser() {
+					fields = append(fields, zap.String("office-user-id", session.OfficeUserID.String()))
+				}
+				if session.IsTspUser() {
+					fields = append(fields, zap.String("tsp-user-id", session.TspUserID.String()))
+				}
+			}
+
+			metrics := httpsnoop.CaptureMetrics(inner, w, r)
+
+			fields = append(fields, []zap.Field{
+				zap.Duration("duration", metrics.Duration),
+				zap.Int64("resp-size-bytes", metrics.Written),
+				zap.Int("resp-status", metrics.Code),
+			}...)
+
+			logger.Info("Request", fields...)
+
+		})
+	}
+}

pkg/middleware/request_logger_test.go

@@ -0,0 +1,44 @@
+package middleware
+
+import (
+	"bytes"
+	"encoding/json"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+func (suite *testSuite) TestRequestLogger() {
+	buf := bytes.NewBuffer(make([]byte, 0))
+	// Create logger that writes to the buffer instead of stdout/stderr
+	logger := suite.logger.WithOptions(zap.WrapCore(func(c zapcore.Core) zapcore.Core {
+		return zapcore.NewTee(c, zapcore.NewCore(
+			zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()),
+			zapcore.AddSync(buf),
+			zapcore.DebugLevel,
+		))
+	}))
+	requestLogger := RequestLogger(logger)
+	rr := httptest.NewRecorder()
+	suite.do(requestLogger, suite.ok, rr, httptest.NewRequest("GET", testURL, nil))
+	suite.Equal(http.StatusOK, rr.Code, errStatusCode) // check status code
+	out := strings.TrimSpace(string(buf.Bytes()))      // remove trailing new line
+	suite.NotEmpty(out, "log was empty")
+	lines := strings.Split(out, "\n")
+	suite.Len(lines, 1) // there is 1 INFO log line
+	parts := strings.Split(lines[0], "\t")
+	suite.Len(parts, 4)
+	//suite.Equal(parts[0], "") // The Date Time
+	suite.Equal(parts[1], "INFO", "log level is invalid")
+	suite.Equal(parts[2], "Request", "log message is invalid")
+	m := map[string]interface{}{}
+	err := json.Unmarshal([]byte(parts[3]), &m)
+	suite.Nil(err, "log fields are not valid json")
+	suite.Contains(m, "method")
+	suite.Equal("GET", m["method"])
+	suite.Contains(m, "resp-status")
+	suite.EqualValues(200, m["resp-status"])
+}