From ccc6217014d059213673884d27353342a53c759e Mon Sep 17 00:00:00 2001 From: Evan Buss Date: Sat, 10 Aug 2024 20:03:34 +0000 Subject: [PATCH] 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 | 2 +- convert/convert.go | 4 +++- convert/kepub.go | 3 ++- convert/mobi.go | 6 +++--- go.mod | 1 + go.sum | 2 ++ main.go | 11 +++++++--- server.go | 54 ++++++++++++++++++++++++++++++++++++++++------ 8 files changed, 68 insertions(+), 15 deletions(-) diff --git a/.air.toml b/.air.toml index 609e4a4..def35eb 100644 --- a/.air.toml +++ b/.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 diff --git a/convert/convert.go b/convert/convert.go index 041f584..e62b805 100644 --- a/convert/convert.go +++ b/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) } diff --git a/convert/kepub.go b/convert/kepub.go index 6ca63ae..1b3c89e 100644 --- a/convert/kepub.go +++ b/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() diff --git a/convert/mobi.go b/convert/mobi.go index 511a4f1..cc2cc24 100644 --- a/convert/mobi.go +++ b/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()), diff --git a/go.mod b/go.mod index 0a78054..e49c126 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 4929c44..3245bbf 100644 --- a/go.sum +++ b/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= diff --git a/main.go b/main.go index d282013..fbe6a30 100644 --- a/main.go +++ b/main.go @@ -16,9 +16,10 @@ import ( ) type ProxyConfig struct { - Port string `koanf:"port"` - Auth AuthConfig `koanf:"auth"` - Feeds []FeedConfig `koanf:"feeds" ` + 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) diff --git a/server.go b/server.go index 7171011..fa06565 100644 --- a/server.go +++ b/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) }