[chore] improved router logging, recovery and error handling (#705)

* move panic recovery to logging middleware, improve logging + panic recovery logic

Signed-off-by: kim <grufwub@gmail.com>

* remove dead code

Signed-off-by: kim <grufwub@gmail.com>

* remove skip paths code

Signed-off-by: kim <grufwub@gmail.com>

* re-enable log quoting

Signed-off-by: kim <grufwub@gmail.com>

* use human-friendly bytesize in logging body size

Signed-off-by: kim <grufwub@gmail.com>

* only disable quoting in debug builds

Signed-off-by: kim <grufwub@gmail.com>

* use logrus level instead of debug.DEBUG() to enable/disable quoting

Signed-off-by: kim <grufwub@gmail.com>

* shutup linter

Signed-off-by: kim <grufwub@gmail.com>

* fix instance tests

Signed-off-by: kim <grufwub@gmail.com>

* fix gin test contexts created with missing engine HTML renderer

Signed-off-by: kim <grufwub@gmail.com>

* add note regarding not logging query parameters

Signed-off-by: kim <grufwub@gmail.com>

* better explain 'DisableQuoting' logic

Signed-off-by: kim <grufwub@gmail.com>

* add license text

Signed-off-by: kim <grufwub@gmail.com>

internal/router/logger.go

@@ -19,55 +19,78 @@
 package router
 
 import (
+	"fmt"
 	"net/http"
+	"os"
 	"time"
 
+	"codeberg.org/gruf/go-bytesize"
+	"codeberg.org/gruf/go-errors/v2"
 	"github.com/gin-gonic/gin"
 	"github.com/sirupsen/logrus"
 )
 
-var skipPaths = map[string]interface{}{
-	"/api/v1/streaming": nil,
-}
+// loggingMiddleware provides a request logging and panic recovery gin handler.
+func loggingMiddleware(c *gin.Context) {
+	// Initialize the logging fields
+	fields := make(logrus.Fields, 7)
 
-func loggingMiddleware() gin.HandlerFunc {
-	logHandler := func(c *gin.Context) {
-		start := time.Now()
+	// Determine pre-handler time
+	before := time.Now()
+
+	defer func() {
+		code := c.Writer.Status()
 		path := c.Request.URL.Path
-		raw := c.Request.URL.RawQuery
 
-		// Process request
-		c.Next()
-
-		// Log only when path is not being skipped
-		if _, ok := skipPaths[path]; !ok {
-			latency := time.Since(start)
-			clientIP := c.ClientIP()
-			userAgent := c.Request.UserAgent()
-			method := c.Request.Method
-			statusCode := c.Writer.Status()
-			errorMessage := c.Errors.ByType(gin.ErrorTypePrivate).String()
-			bodySize := c.Writer.Size()
-			if raw != "" {
-				path = path + "?" + raw
+		if r := recover(); r != nil {
+			if c.Writer.Status() == 0 {
+				// No response was written, send a generic Internal Error
+				c.Writer.WriteHeader(http.StatusInternalServerError)
 			}
 
-			l := logrus.WithFields(logrus.Fields{
-				"latency":    latency,
-				"clientIP":   clientIP,
-				"userAgent":  userAgent,
-				"method":     method,
-				"statusCode": statusCode,
-				"path":       path,
-			})
+			// Append panic information to the request ctx
+			_ = c.Error(fmt.Errorf("recovered panic: %v", r))
 
-			if errorMessage == "" {
-				l.Infof("[%s] %s: wrote %d bytes", latency, http.StatusText(statusCode), bodySize)
-			} else {
-				l.Errorf("[%s] %s: %s", latency, http.StatusText(statusCode), errorMessage)
+			// Dump a stacktrace to stderr
+			callers := errors.GetCallers(3, 10)
+			fmt.Fprintf(os.Stderr, "recovered panic: %v\n%s", r, callers)
+		}
+
+		// NOTE:
+		// It is very important here that we are ONLY logging
+		// the request path, and none of the query parameters.
+		// Query parameters can contain sensitive information
+		// and could lead to storing plaintext API keys in logs
+
+		// Set request logging fields
+		fields["latency"] = time.Since(before)
+		fields["clientIP"] = c.ClientIP()
+		fields["userAgent"] = c.Request.UserAgent()
+		fields["method"] = c.Request.Method
+		fields["statusCode"] = code
+		fields["path"] = path
+
+		// Create a log entry with fields
+		l := logrus.WithFields(fields)
+		l.Level = logrus.InfoLevel
+
+		if code >= 500 {
+			// This is a server error
+			l.Level = logrus.ErrorLevel
+
+			if len(c.Errors) > 0 {
+				// Add an error string log field
+				fields["error"] = c.Errors.String()
 			}
 		}
-	}
 
-	return logHandler
+		// Generate a nicer looking bytecount
+		size := bytesize.Size(c.Writer.Size())
+
+		// Finally, write log entry with status text body size
+		l.Logf(l.Level, "%s: wrote %s", http.StatusText(code), size)
+	}()
+
+	// Process request
+	c.Next()
 }