feat: structured logging improvements

This change adds a child logger with request information to the
http request context. Also improved the log format for clarity.

- Unescaped the query string
- Use JSON log format when not in dev mode.
- Added request ip to the request child logger.
- The child logger is passed to the converter so we can associate
  any errors with a specific request / file.
- Add book file name as a logger attribute
- Add user agent header as a logger attribute
- Log the "X-Forwarded-For" header, falling back to RemoteAddr

.air.toml

@@ -3,7 +3,7 @@ testdata_dir = "testdata"
 tmp_dir = "tmp"
 
 [build]
-  args_bin = []
+  args_bin = ["--dev"]
   bin = "./tmp/main"
   cmd = "go build -o ./tmp/main ."
   delay = 1000

convert/convert.go

@@ -1,9 +1,11 @@
 package convert
 
+import "log/slog"
+
 type Converter interface {
 	// Whether or not the converter is available
 	// Usually based on the availability of the underlying tool
 	Available() bool
 	// Convert the input file to the output file
-	Convert(input string) (string, error)
+	Convert(log *slog.Logger, input string) (string, error)
 }

convert/kepub.go

@@ -1,6 +1,7 @@
 package convert
 
 import (
+	"log/slog"
 	"os/exec"
 	"strings"
 	"sync"
@@ -21,7 +22,7 @@ func (kc *KepubConverter) Available() bool {
 	return kc.available
 }
 
-func (kc *KepubConverter) Convert(input string) (string, error) {
+func (kc *KepubConverter) Convert(_ *slog.Logger, input string) (string, error) {
 	kc.mutex.Lock()
 	defer kc.mutex.Unlock()
 

convert/mobi.go

@@ -23,7 +23,7 @@ func (mc *MobiConverter) Available() bool {
 	return mc.available
 }
 
-func (mc *MobiConverter) Convert(input string) (string, error) {
+func (mc *MobiConverter) Convert(log *slog.Logger, input string) (string, error) {
 	mc.mutex.Lock()
 	defer mc.mutex.Unlock()
 
@@ -49,14 +49,14 @@ func (mc *MobiConverter) Convert(input string) (string, error) {
 		isError := true
 		if exiterr, ok := err.(*exec.ExitError); ok {
 			// Sometimes warnings cause a 1 exit-code, but the file is still created
-			slog.Info("Exit code", slog.Any("code", exiterr.ExitCode()))
+			log.Info("Exit code", slog.Any("code", exiterr.ExitCode()))
 			if exiterr.ExitCode() == 1 {
 				isError = false
 			}
 		}
 
 		if isError {
-			slog.Error("Error converting file",
+			log.Error("Error converting file",
 				slog.Any("error", err),
 				slog.String("stdout", out.String()),
 				slog.String("stderr", stderr.String()),

go.mod

@@ -14,6 +14,7 @@ require (
 	github.com/fsnotify/fsnotify v1.7.0 // indirect
 	github.com/go-task/slim-sprig/v3 v3.0.0
 	github.com/go-viper/mapstructure/v2 v2.0.0 // indirect
+	github.com/google/uuid v1.6.0
 	github.com/knadh/koanf/maps v0.1.1 // indirect
 	github.com/knadh/koanf/providers/confmap v0.1.0
 	github.com/mitchellh/copystructure v1.2.0 // indirect

go.sum

@@ -8,6 +8,8 @@ github.com/go-viper/mapstructure/v2 v2.0.0 h1:dhn8MZ1gZ0mzeodTG3jt5Vj/o87xZKuNAp
 github.com/go-viper/mapstructure/v2 v2.0.0/go.mod h1:oJDH3BJKyqBA2TXFhDsKDGDTlndYOZ6rGS0BRZIxGhM=
 github.com/google/gofuzz v1.2.0 h1:xRy4A+RhZaiKjJ1bPfwQ8sedCA+YS2YcCHW6ec7JMi0=
 github.com/google/gofuzz v1.2.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg=
+github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0=
+github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/gorilla/securecookie v1.1.2 h1:YCIWL56dvtr73r6715mJs5ZvhtnY73hBvEF8kXD8ePA=
 github.com/gorilla/securecookie v1.1.2/go.mod h1:NfCASbcHqRSY+3a8tlWJwsQap2VX5pwzwo4h3eOamfo=
 github.com/knadh/koanf/maps v0.1.1 h1:G5TjmUh2D7G2YWf5SQQqSiHRJEjaicvU0KpypqB3NIs=

main.go

@@ -19,6 +19,7 @@ type ProxyConfig struct {
 	Port      string       `koanf:"port"`
 	Auth      AuthConfig   `koanf:"auth"`
 	Feeds     []FeedConfig `koanf:"feeds" `
+	isDevMode bool
 }
 
 type AuthConfig struct {
@@ -38,6 +39,7 @@ func main() {
 	// These aren't mapped to the config file.
 	configPath := fs.String("config", "config.yml", "config file to load")
 	generateKeys := fs.Bool("generate-keys", false, "generate cookie signing keys and exit")
+	isDevMode := fs.Bool("dev", false, "enable development mode")
 
 	port := fs.String("port", "8080", "port to listen on")
 	if err := fs.Parse(os.Args[1:]); err != nil {
@@ -79,6 +81,9 @@ func main() {
 		config.Auth.BlockKey = blockKey
 	}
 
+	// This should only be set by the command line flag,
+	// so we don't use koanf to set this.
+	config.isDevMode = *isDevMode
 	server, err := NewServer(&config)
 	if err != nil {
 		log.Fatal(err)

server.go

@@ -1,16 +1,17 @@
 package main
 
 import (
+	"context"
 	"encoding/hex"
 	"fmt"
 	"io"
 	"log/slog"
-	"math/rand"
 	"mime"
 	"net/http"
 	"net/url"
 	"os"
 	"path/filepath"
+	"reflect"
 	"strings"
 	"sync"
 	"time"
@@ -18,6 +19,7 @@ import (
 	"github.com/evan-buss/opds-proxy/convert"
 	"github.com/evan-buss/opds-proxy/html"
 	"github.com/evan-buss/opds-proxy/opds"
+	"github.com/google/uuid"
 	"github.com/gorilla/securecookie"
 )
 
@@ -44,6 +46,12 @@ type Credentials struct {
 	Password string
 }
 
+type contextKey string
+
+const (
+	requestLogger = contextKey("log")
+)
+
 func NewServer(config *ProxyConfig) (*Server, error) {
 	hashKey, err := hex.DecodeString(config.Auth.HashKey)
 	if err != nil {
@@ -54,6 +62,10 @@ func NewServer(config *ProxyConfig) (*Server, error) {
 		return nil, err
 	}
 
+	if !config.isDevMode {
+		slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, nil)))
+	}
+
 	s := securecookie.New(hashKey, blockKey)
 
 	router := http.NewServeMux()
@@ -72,9 +84,28 @@ func NewServer(config *ProxyConfig) (*Server, error) {
 func logger(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		start := time.Now()
-		id := rand.Intn(1000)
+		id := uuid.New()
+		requestIP := r.Header.Get("X-Forwarded-For")
+		if requestIP == "" {
+			requestIP = r.RemoteAddr
+		}
+
+		query, _ := url.QueryUnescape(r.URL.RawQuery)
+
+		log := slog.With(
+			slog.Group("request",
+				slog.String("id", id.String()),
+				slog.String("ip", requestIP),
+				slog.String("method", r.Method),
+				slog.String("path", r.URL.Path),
+				slog.String("query", query),
+				slog.String("user-agent", r.UserAgent()),
+			),
+		)
+
+		r = r.WithContext(context.WithValue(r.Context(), requestLogger, log))
 		next.ServeHTTP(w, r)
-		slog.Info("Request", slog.Int("id", id), slog.String("path", r.URL.Path), slog.String("query", r.URL.RawQuery), slog.Duration("duration", time.Since(start)))
+		log.Info("Request Completed", slog.String("duration", time.Since(start).String()))
 	})
 }
 
@@ -168,12 +199,20 @@ func handleFeed(outputDir string, feeds []FeedConfig, s *securecookie.SecureCook
 			converter = mobiConverter
 		}
 
+		log := r.Context().Value(requestLogger).(*slog.Logger)
+		filename, err := parseFileName(resp)
+		if err == nil {
+			log = log.With(slog.String("file", filename))
+		}
+
 		if mimeType != EPUB_MIME || converter == nil {
 			forwardResponse(w, resp)
+			if filename != "" {
+				log.Info("Sent File")
+			}
 			return
 		}
 
-		filename, err := parseFileName(resp)
 		if err != nil {
 			handleError(r, w, "Failed to parse file name", err)
 			return
@@ -183,7 +222,7 @@ func handleFeed(outputDir string, feeds []FeedConfig, s *securecookie.SecureCook
 		downloadFile(epubFile, resp)
 		defer os.Remove(epubFile)
 
-		outputFile, err := converter.Convert(epubFile)
+		outputFile, err := converter.Convert(log, epubFile)
 		if err != nil {
 			handleError(r, w, "Failed to convert epub", err)
 			return
@@ -193,6 +232,8 @@ func handleFeed(outputDir string, feeds []FeedConfig, s *securecookie.SecureCook
 			handleError(r, w, "Failed to send converted file", err)
 			return
 		}
+
+		log.Info("Sent Converted File", slog.String("converter", reflect.TypeOf(converter).String()))
 	}
 }
 
@@ -307,7 +348,8 @@ func fetchFromUrl(url string, credentials *Credentials) (*http.Response, error)
 }
 
 func handleError(r *http.Request, w http.ResponseWriter, message string, err error) {
-	slog.Error(message, slog.String("path", r.URL.Path), slog.String("query", r.URL.RawQuery), slog.Any("error", err))
+	log := r.Context().Value(requestLogger).(*slog.Logger)
+	log.Error(message, slog.Any("error", err))
 	http.Error(w, "An unexpected error occurred", http.StatusInternalServerError)
 }