http refactor.

internal/http/logger.go

@@ -1,86 +1,129 @@
 package http
 
 import (
+	"context"
 	"fmt"
 	"net/http"
 	"time"
 
 	"github.com/go-chi/chi/middleware"
 	"github.com/rs/zerolog/log"
+
+	"demodesk/neko/internal/http/auth"
+	"demodesk/neko/internal/types"
+	"demodesk/neko/internal/utils"
 )
 
-func Logger(next http.Handler) http.Handler {
-	fn := func(w http.ResponseWriter, r *http.Request) {
-		req := map[string]interface{}{}
+type logEntryKey int
 
-		// exclude healthcheck from logs
-		if r.RequestURI == "/api/health" {
-			next.ServeHTTP(w, r)
+const logEntryKeyCtx logEntryKey = iota
+
+func setLogEntry(r *http.Request, data logEntry) *http.Request {
+	ctx := context.WithValue(r.Context(), logEntryKeyCtx, data)
+	return r.WithContext(ctx)
+}
+
+func getLogEntry(r *http.Request) logEntry {
+	return r.Context().Value(logEntryKeyCtx).(logEntry)
+}
+
+func LoggerMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		next.ServeHTTP(w, setLogEntry(r, newLogEntry(w, r)))
+	})
+}
+
+type logEntry struct {
+	req struct {
+		time   time.Time
+		id     string
+		scheme string
+		proto  string
+		method string
+		remote string
+		agent  string
+		uri    string
+	}
+	res struct {
+		time  time.Time
+		code  int
+		bytes int
+	}
+	err        error
+	elapsed    time.Duration
+	hasSession bool
+	session    types.Session
+}
+
+func newLogEntry(w http.ResponseWriter, r *http.Request) logEntry {
+	e := logEntry{}
+	e.req.time = time.Now()
+
+	if reqID := middleware.GetReqID(r.Context()); reqID != "" {
+		e.req.id = reqID
+	}
+
+	scheme := "http"
+	if r.TLS != nil {
+		scheme = "https"
+	}
+
+	e.req.scheme = scheme
+	e.req.proto = r.Proto
+	e.req.method = r.Method
+	e.req.remote = r.RemoteAddr
+	e.req.agent = r.UserAgent()
+	e.req.uri = fmt.Sprintf("%s://%s%s", scheme, r.Host, r.RequestURI)
+	return e
+}
+
+func (e *logEntry) SetResponse(w http.ResponseWriter, r *http.Request) {
+	ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+	e.res.time = time.Now()
+	e.res.code = ww.Status()
+	e.res.bytes = ww.BytesWritten()
+
+	e.elapsed = e.res.time.Sub(e.req.time)
+	e.session, e.hasSession = auth.GetSession(r)
+}
+
+func (e *logEntry) SetError(err error) {
+	e.err = err
+}
+
+func (e *logEntry) Write() {
+	logger := log.With().
+		Str("module", "http").
+		Float64("elapsed", float64(e.elapsed.Nanoseconds())/1000000.0).
+		Interface("req", e.req).
+		Interface("res", e.res).
+		Logger()
+
+	if e.hasSession {
+		logger = logger.With().Str("session_id", e.session.ID()).Logger()
+	}
+
+	if e.err != nil {
+		httpErr, ok := e.err.(*utils.HTTPError)
+		if !ok {
+			logger.Err(e.err).Msgf("request failed (%d)", e.res.code)
 			return
 		}
 
-		if reqID := middleware.GetReqID(r.Context()); reqID != "" {
-			req["id"] = reqID
+		if httpErr.Message == "" {
+			httpErr.Message = http.StatusText(httpErr.Code)
 		}
 
-		scheme := "http"
-		if r.TLS != nil {
-			scheme = "https"
+		logger := logger.Error().Err(httpErr.InternalErr)
+
+		message := httpErr.Message
+		if httpErr.InternalMsg != "" {
+			message = httpErr.InternalMsg
 		}
 
-		req["scheme"] = scheme
-		req["proto"] = r.Proto
-		req["method"] = r.Method
-		req["remote"] = r.RemoteAddr
-		req["agent"] = r.UserAgent()
-		req["uri"] = fmt.Sprintf("%s://%s%s", scheme, r.Host, r.RequestURI)
-
-		fields := map[string]interface{}{}
-		fields["req"] = req
-
-		entry := &entry{
-			fields: fields,
-		}
-
-		ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
-		t1 := time.Now()
-
-		defer func() {
-			entry.Write(ww.Status(), ww.BytesWritten(), time.Since(t1))
-		}()
-
-		next.ServeHTTP(ww, r)
+		logger.Msgf("request failed (%d): %s", e.res.code, message)
+		return
 	}
-	return http.HandlerFunc(fn)
-}
-
-type entry struct {
-	fields map[string]interface{}
-	errors []map[string]interface{}
-}
-
-func (e *entry) Write(status, bytes int, elapsed time.Duration) {
-	res := map[string]interface{}{}
-	res["time"] = time.Now().UTC().Format(time.RFC1123)
-	res["status"] = status
-	res["bytes"] = bytes
-	res["elapsed"] = float64(elapsed.Nanoseconds()) / 1000000.0
-
-	e.fields["res"] = res
-	e.fields["module"] = "http"
-
-	if len(e.errors) > 0 {
-		e.fields["errors"] = e.errors
-		log.Error().Fields(e.fields).Msgf("request failed (%d)", status)
-	} else {
-		log.Debug().Fields(e.fields).Msgf("request complete (%d)", status)
-	}
-}
-
-func (e *entry) Panic(v interface{}, stack []byte) {
-	err := map[string]interface{}{}
-	err["message"] = fmt.Sprintf("%+v", v)
-	err["stack"] = string(stack)
-
-	e.errors = append(e.errors, err)
+
+	logger.Debug().Msgf("request complete (%d)", e.res.code)
 }