From 203754726ba02135b0a48bb3e38de5598e8a7313 Mon Sep 17 00:00:00 2001
From: Deluan <deluan@deluan.com>
Date: Sat, 1 Feb 2020 20:07:15 -0500
Subject: [PATCH] refactor: better request logging

---
 server/middlewares.go          | 50 ++++++++++++++++++++++++++++++++++
 server/server.go               |  2 +-
 server/subsonic/api.go         | 10 +++++++
 server/subsonic/middlewares.go |  2 +-
 4 files changed, 62 insertions(+), 2 deletions(-)
 create mode 100644 server/middlewares.go

diff --git a/server/middlewares.go b/server/middlewares.go
new file mode 100644
index 000000000..a70549952
--- /dev/null
+++ b/server/middlewares.go
@@ -0,0 +1,50 @@
+package server
+
+import (
+	"fmt"
+	"net/http"
+	"time"
+
+	"github.com/deluan/navidrome/log"
+	"github.com/go-chi/chi/middleware"
+)
+
+func RequestLogger(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		scheme := "http"
+		if r.TLS != nil {
+			scheme = "https"
+		}
+
+		start := time.Now()
+		ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+		next.ServeHTTP(ww, r)
+		status := ww.Status()
+
+		message := fmt.Sprintf("HTTP: %s %s://%s%s", r.Method, scheme, r.Host, r.RequestURI)
+		logArgs := []interface{}{
+			r.Context(),
+			message,
+			"remoteAddr", r.RemoteAddr,
+			"lapsedTime", time.Since(start),
+			"httpStatus", ww.Status(),
+			"responseSize", ww.BytesWritten(),
+		}
+		if log.CurrentLevel() >= log.LevelDebug {
+			logArgs = append(logArgs, "userAgent", r.UserAgent())
+		}
+
+		switch {
+		case status >= 500:
+			log.Error(logArgs...)
+		case status >= 400:
+			log.Warn(logArgs...)
+		default:
+			if log.CurrentLevel() >= log.LevelDebug {
+				log.Debug(logArgs...)
+			} else {
+				log.Info(logArgs...)
+			}
+		}
+	})
+}
diff --git a/server/server.go b/server/server.go
index f31b99027..61d277362 100644
--- a/server/server.go
+++ b/server/server.go
@@ -33,7 +33,7 @@ func New(scanner *scanner.Scanner, ds model.DataStore) *Server {
 func (a *Server) MountRouter(path string, subRouter http.Handler) {
 	log.Info("Mounting routes", "path", path)
 	a.router.Group(func(r chi.Router) {
-		r.Use(middleware.Logger)
+		r.Use(RequestLogger)
 		r.Mount(path, subRouter)
 	})
 }
diff --git a/server/subsonic/api.go b/server/subsonic/api.go
index ac2075cac..421e9d5b8 100644
--- a/server/subsonic/api.go
+++ b/server/subsonic/api.go
@@ -7,6 +7,7 @@ import (
 	"net/http"
 
 	"github.com/deluan/navidrome/engine"
+	"github.com/deluan/navidrome/log"
 	"github.com/deluan/navidrome/server/subsonic/responses"
 	"github.com/go-chi/chi"
 )
@@ -177,5 +178,14 @@ func SendResponse(w http.ResponseWriter, r *http.Request, payload *responses.Sub
 		w.Header().Set("Content-Type", "application/xml")
 		response, _ = xml.Marshal(payload)
 	}
+	if payload.Status == "ok" {
+		if log.CurrentLevel() >= log.LevelTrace {
+			log.Info(r.Context(), "API: Successful response", "status", "OK", "body", string(response))
+		} else {
+			log.Info(r.Context(), "API: Successful response", "status", "OK")
+		}
+	} else {
+		log.Warn(r.Context(), "API: Failed response", "error", payload.Error.Code, "message", payload.Error.Message)
+	}
 	w.Write(response)
 }
diff --git a/server/subsonic/middlewares.go b/server/subsonic/middlewares.go
index 57c2d131f..f4d38e6bf 100644
--- a/server/subsonic/middlewares.go
+++ b/server/subsonic/middlewares.go
@@ -55,7 +55,7 @@ func checkRequiredParameters(next http.Handler) http.Handler {
 		ctx = context.WithValue(ctx, "username", user)
 		ctx = context.WithValue(ctx, "client", client)
 		ctx = context.WithValue(ctx, "version", version)
-		log.Info(ctx, "New Subsonic API request", "username", user, "client", client, "version", version, "path", r.URL.Path)
+		log.Info(ctx, "API: New request "+r.URL.Path, "username", user, "client", client, "version", version)
 
 		r = r.WithContext(ctx)
 		next.ServeHTTP(w, r)