From 18f88d0be251195be780b1b712c283f9c278eb60 Mon Sep 17 00:00:00 2001 From: Blake Stoddard Date: Fri, 2 Oct 2020 09:55:15 -0400 Subject: [PATCH] Add JSON log output support via logrus and a logFormat flag --- cmd/imageproxy/main.go | 8 +++++- data.go | 3 +++ go.mod | 2 ++ go.sum | 5 ++++ imageproxy.go | 56 ++++++++++++++++++++---------------------- transform.go | 5 ++-- 6 files changed, 47 insertions(+), 32 deletions(-) diff --git a/cmd/imageproxy/main.go b/cmd/imageproxy/main.go index 25e627865..9e0b606bf 100644 --- a/cmd/imageproxy/main.go +++ b/cmd/imageproxy/main.go @@ -19,7 +19,7 @@ import ( "flag" "fmt" "io/ioutil" - "log" + log "github.com/sirupsen/logrus" "net/http" "net/url" "os" @@ -55,6 +55,7 @@ var signatureKeys signatureKeyList var scaleUp = flag.Bool("scaleUp", false, "allow images to scale beyond their original dimensions") var timeout = flag.Duration("timeout", 0, "time limit for requests served by this proxy") var verbose = flag.Bool("verbose", false, "print verbose logging messages") +var logFormat = flag.String("logFormat", "ascii", "format to output logs in, ascii or json") var _ = flag.Bool("version", false, "Deprecated: this flag does nothing") var contentTypes = flag.String("contentTypes", "image/*", "comma separated list of allowed content types") var userAgent = flag.String("userAgent", "willnorris/imageproxy", "specify the user-agent used by imageproxy when fetching images from origin website") @@ -68,6 +69,11 @@ func main() { envy.Parse("IMAGEPROXY") flag.Parse() + if *logFormat == "json" { + // Log as JSON instead of the default ASCII formatter. + log.SetFormatter(&log.JSONFormatter{}) + } + p := imageproxy.NewProxy(nil, cache.Cache) if *allowHosts != "" { p.AllowHosts = strings.Split(*allowHosts, ",") diff --git a/data.go b/data.go index 83c8e5e1a..033116e1b 100644 --- a/data.go +++ b/data.go @@ -91,6 +91,9 @@ type Options struct { // Automatically find good crop points based on image content. SmartCrop bool + + // Generated transaction ID for logging identification + TransactionId string } func (o Options) String() string { diff --git a/go.mod b/go.mod index 89ff68530..9438d0078 100644 --- a/go.mod +++ b/go.mod @@ -13,6 +13,7 @@ require ( github.com/dnaeon/go-vcr v1.0.1 // indirect github.com/fcjr/aia-transport-go v1.2.1 github.com/gomodule/redigo v2.0.0+incompatible + github.com/google/uuid v1.1.2 github.com/gorilla/mux v1.8.0 github.com/gregjones/httpcache v0.0.0-20190611155906-901d90724c79 github.com/jamiealquiza/envy v1.1.0 @@ -23,6 +24,7 @@ require ( github.com/prometheus/common v0.13.0 // indirect github.com/rwcarlsen/goexif v0.0.0-20190401172101-9e8deecbddbd github.com/satori/go.uuid v0.0.0-20180103174451-36e9d2ebbde5 // indirect + github.com/sirupsen/logrus v1.7.0 golang.org/x/crypto v0.0.0-20200820211705-5c72a883971a // indirect golang.org/x/image v0.0.0-20200801110659-972c09e46d76 golang.org/x/net v0.0.0-20200904194848-62affa334b73 // indirect diff --git a/go.sum b/go.sum index a24a4d0cf..901cbf274 100644 --- a/go.sum +++ b/go.sum @@ -213,6 +213,8 @@ github.com/google/pprof v0.0.0-20200430221834-fc25d7d30c6d/go.mod h1:ZgVRPoUq/hf github.com/google/pprof v0.0.0-20200708004538-1a94d8640e99/go.mod h1:ZgVRPoUq/hfqzAqh7sHMqb3I9Rq5C59dIz2SbBwJ4eM= github.com/google/renameio v0.1.0/go.mod h1:KWCgfxg9yswjAJkECMjeO8J8rahYeXnNhOm40UhjYkI= github.com/google/uuid v1.0.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/google/uuid v1.1.2 h1:EVhdT+1Kseyi1/pUmXKaFxYsDNy9RQYkMWRH68J/W7Y= +github.com/google/uuid v1.1.2/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/googleapis/gax-go/v2 v2.0.4 h1:hU4mGcQI4DaAYW+IbTun+2qEZVFxK0ySjQLTbS0VQKc= github.com/googleapis/gax-go/v2 v2.0.4/go.mod h1:0Wqv26UfaUD9n4G6kQubkQ+KchISgw+vpHVxEJEs9eg= github.com/googleapis/gax-go/v2 v2.0.5 h1:sjZBwGj9Jlw33ImPtvFviGYvseOtDM7hkSKB7+Tv3SM= @@ -394,6 +396,8 @@ github.com/shurcooL/sanitized_anchor_name v1.0.0/go.mod h1:1NzhyTcUVG4SuEtjjoZeV github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo= github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE= github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88= +github.com/sirupsen/logrus v1.7.0 h1:ShrD1U9pZB12TX0cVy0DtePoCH97K8EtX+mg7ZARUtM= +github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0= github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc= github.com/smartystreets/goconvey v1.6.4/go.mod h1:syvi0/a8iFYH4r/RixwvyeAJjdLS9QV7WQ/tjFTllLA= github.com/soheilhy/cmux v0.1.4/go.mod h1:IM3LyeVVIOuxMH7sFAkER9+bJ4dT7Ms6E4xg4kGIyLM= @@ -559,6 +563,7 @@ golang.org/x/sys v0.0.0-20190624142023-c5567b49c5d0/go.mod h1:h1NjWce9XRLGQEsW7w golang.org/x/sys v0.0.0-20190726091711-fc99dfbffb4e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20190826190057-c7b8b68b1456/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191001151750-bb3f8db39f24/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= +golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191204072324-ce4227a45e2e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191220142924-d4481acd189f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/sys v0.0.0-20191228213918-04cbcbbfeed8/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= diff --git a/imageproxy.go b/imageproxy.go index b6cb80dcd..b5fea365a 100644 --- a/imageproxy.go +++ b/imageproxy.go @@ -26,7 +26,7 @@ import ( "fmt" "io" "io/ioutil" - "log" + log "github.com/sirupsen/logrus" "mime" "net" "net/http" @@ -35,6 +35,8 @@ import ( "strings" "time" + "github.com/google/uuid" + "github.com/fcjr/aia-transport-go" "github.com/gregjones/httpcache" "github.com/prometheus/client_golang/prometheus" @@ -120,7 +122,7 @@ func NewProxy(transport http.RoundTripper, cache Cache) *Proxy { CachingClient: client, log: func(format string, v ...interface{}) { if proxy.Verbose { - proxy.logf(format, v...) + log.Info(fmt.Sprintf(format, v...)) } }, }, @@ -135,6 +137,11 @@ func NewProxy(transport http.RoundTripper, cache Cache) *Proxy { // ServeHTTP handles incoming requests. func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) { + // Ensure every request has a unique, traceable ID + requestId := uuid.New().String() + r.Header.Set("X-Request-ID", requestId) // write it to the incoming request for use in log messages + w.Header().Set("X-Request-Id", requestId) + if r.URL.Path == "/favicon.ico" { return // ignore favicon requests } @@ -165,13 +172,14 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) { req, err := NewRequest(r, p.DefaultBaseURL) if err != nil { msg := fmt.Sprintf("invalid request URL: %v", err) - p.log(msg) + log.WithField("transactionId", w.Header().Get("X-Request-Id")).Warn(msg) http.Error(w, msg, http.StatusBadRequest) return } if err := p.allowed(req); err != nil { - p.logf("%s: %v", err, req) + log.WithField("transactionId", w.Header().Get("X-Request-Id")).Warn( + fmt.Sprintf("%s: %v", err, req)) http.Error(w, msgNotAllowed, http.StatusForbidden) return } @@ -180,6 +188,7 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) { req.Options.ScaleUp = p.ScaleUp actualReq, _ := http.NewRequest("GET", req.String(), nil) + actualReq.Header.Set("X-Request-Id", w.Header().Get("X-Request-Id")) if p.UserAgent != "" { actualReq.Header.Set("User-Agent", p.UserAgent) } @@ -209,7 +218,7 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) { if err != nil { msg := fmt.Sprintf("error fetching remote image: %v", err) - p.log(msg) + log.WithField("transactionId", w.Header().Get("X-Request-Id")).Warn(msg) http.Error(w, msg, http.StatusInternalServerError) metricRemoteErrors.Inc() return @@ -219,7 +228,8 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) { cached := resp.Header.Get(httpcache.XFromCache) == "1" if p.Verbose { - p.logf("request: %+v (served from cache: %t)", *actualReq, cached) + log.WithField("transactionId", w.Header().Get("X-Request-Id")).Info( + fmt.Sprintf("request: %+v (served from cache: %t)", *actualReq, cached)) } if cached { @@ -241,7 +251,8 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) { contentType = peekContentType(b) } if resp.ContentLength != 0 && !contentTypeMatches(p.ContentTypes, contentType) { - p.logf("content-type not allowed: %q", contentType) + log.WithField("transactionId", w.Header().Get("X-Request-Id")).Warn( + fmt.Sprintf("content-type not allowed: %q", contentType)) http.Error(w, msgNotAllowed, http.StatusForbidden) return } @@ -254,7 +265,8 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) { w.WriteHeader(resp.StatusCode) if _, err := io.Copy(w, resp.Body); err != nil { - p.logf("error copying response: %v", err) + log.WithField("transactionId", w.Header().Get("X-Request-Id")).Warn( + fmt.Sprintf("error copying response: %v", err)) } } @@ -431,22 +443,6 @@ func should304(req *http.Request, resp *http.Response) bool { return false } -func (p *Proxy) log(v ...interface{}) { - if p.Logger != nil { - p.Logger.Print(v...) - } else { - log.Print(v...) - } -} - -func (p *Proxy) logf(format string, v ...interface{}) { - if p.Logger != nil { - p.Logger.Printf(format, v...) - } else { - log.Printf(format, v...) - } -} - // TransformingTransport is an implementation of http.RoundTripper that // optionally transforms images using the options specified in the request URL // fragment. @@ -467,9 +463,8 @@ type TransformingTransport struct { func (t *TransformingTransport) RoundTrip(req *http.Request) (*http.Response, error) { if req.URL.Fragment == "" { // normal requests pass through - if t.log != nil { - t.log("fetching remote URL: %v", req.URL) - } + log.WithField("transactionId", req.Header.Get("X-Request-Id")).Info( + fmt.Sprintf("fetching remote URL: %v", req.URL)) return t.Transport.RoundTrip(req) } @@ -494,10 +489,12 @@ func (t *TransformingTransport) RoundTrip(req *http.Request) (*http.Response, er } opt := ParseOptions(req.URL.Fragment) + opt.TransactionId = req.Header.Get("X-Request-Id") img, err := Transform(b, opt) if err != nil { - log.Printf("error transforming image %s: %v", req.URL.String(), err) + log.WithField("transactionId", req.Header.Get("X-Request-Id")).Info( + fmt.Sprintf("error transforming image %s: %v", req.URL.String(), err)) img = b } @@ -509,7 +506,8 @@ func (t *TransformingTransport) RoundTrip(req *http.Request) (*http.Response, er // exclude Content-Type header if the format may have changed during transformation "Content-Type": opt.Format != "" || resp.Header.Get("Content-Type") == "image/webp" || resp.Header.Get("Content-Type") == "image/tiff", }); err != nil { - t.log("error copying headers: %v", err) + log.WithField("transactionId", req.Header.Get("X-Request-Id")).Info( + fmt.Sprintf("error copying headers: %v", err)) } fmt.Fprintf(buf, "Content-Length: %d\n\n", len(img)) buf.Write(img) diff --git a/transform.go b/transform.go index ed772e041..8a55fa43b 100644 --- a/transform.go +++ b/transform.go @@ -22,7 +22,7 @@ import ( "image/jpeg" "image/png" "io" - "log" + log "github.com/sirupsen/logrus" "math" "github.com/disintegration/imaging" @@ -182,7 +182,8 @@ func cropParams(m image.Image, opt Options) image.Rectangle { h := evaluateFloat(opt.Height, imgH) r, err := smartcropAnalyzer.FindBestCrop(m, w, h) if err != nil { - log.Printf("smartcrop error finding best crop: %v", err) + log.WithField("transactionId", opt.TransactionId).Info( + fmt.Sprintf("smartcrop error finding best crop: %v", err)) } else { return r }