Add JSON log output support via logrus

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, ",")

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 {

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

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=

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)

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
 		}