New logging; JSON and structured log formats

errors.go

@@ -19,12 +19,12 @@ func (e *imgproxyError) Error() string {
 	return e.Message
 }
 
-func (e *imgproxyError) ErrorWithStack() string {
+func (e *imgproxyError) FormatStack() string {
 	if e.stack == nil {
-		return e.Message
+		return ""
 	}
 
-	return fmt.Sprintf("%s\n%s", e.Message, formatStack(e.stack))
+	return formatStack(e.stack)
 }
 
 func (e *imgproxyError) StackTrace() []uintptr {

go.mod

@@ -30,12 +30,13 @@ require (
 	github.com/prometheus/common v0.1.0 // indirect
 	github.com/prometheus/procfs v0.0.0-20190104112138-b1a0a9a36d74 // indirect
 	github.com/shirou/gopsutil v2.18.12+incompatible // indirect
+	github.com/sirupsen/logrus v1.4.2
 	github.com/stretchr/testify v1.3.0
 	golang.org/x/image v0.0.0-20181116024801-cd38e8056d9b
 	golang.org/x/net v0.0.0-20190110200230-915654e7eabc
 	golang.org/x/oauth2 v0.0.0-20190110195249-fd3eaa146cbb // indirect
 	golang.org/x/sync v0.0.0-20181221193216-37e7f081c4d4
-	golang.org/x/sys v0.0.0-20190109145017-48ac38b7c8cb
+	golang.org/x/sys v0.0.0-20190422165155-953cdadca894
 	google.golang.org/api v0.1.0
 	google.golang.org/genproto v0.0.0-20190110221437-6909d8a4a91b // indirect
 )

go.sum

@@ -64,6 +64,7 @@ github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7V
 github.com/kardianos/osext v0.0.0-20170510131534-ae77be60afb1 h1:PJPDf8OUfOK1bb/NeTKd4f1QXZItOX389VN3B6qC8ro=
 github.com/kardianos/osext v0.0.0-20170510131534-ae77be60afb1/go.mod h1:1NbS8ALrpOvjt0rHPNLyCIeMtbizbir8U//inJ+zuB8=
 github.com/kisielk/gotool v1.0.0/go.mod h1:XhKaO+MFFWcvkIS/tQcRk01m1F5IRFswLeQ+oQHNcck=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1 h1:mweAR1A6xJ3oS2pRaGiHgQ4OO8tzTaLawm8vnODuwDk=
 github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
@@ -108,7 +109,10 @@ github.com/prometheus/procfs v0.0.0-20190104112138-b1a0a9a36d74 h1:d1Xoc24yp/pXm
 github.com/prometheus/procfs v0.0.0-20190104112138-b1a0a9a36d74/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
 github.com/shirou/gopsutil v2.18.12+incompatible h1:1eaJvGomDnH74/5cF4CTmTbLHAriGFsTZppLXDX93OM=
 github.com/shirou/gopsutil v2.18.12+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=
+github.com/sirupsen/logrus v1.2.0 h1:juTguoYk5qI21pwyTXY3B3Y5cOTH3ZUyZCg1v/mihuo=
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
+github.com/sirupsen/logrus v1.4.2 h1:SPIRibHv4MatM3XXNO2BJeFLZwZ2LvZgfQ5+UNI2im4=
+github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.1.1 h1:2vfRuCMp5sSVIDSqO8oNnWJq7mPa6KVP3iPIwFBuy8A=
 github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
@@ -117,6 +121,7 @@ github.com/stretchr/testify v1.3.0 h1:TivCn/peBQ7UY8ooIcPgZFpTNSz0Q2U6UrFlUfqbe0
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 go.opencensus.io v0.18.0 h1:Mk5rgZcggtbvtAun5aJzAtjKKN/t0R3jJPlWILlv938=
 go.opencensus.io v0.18.0/go.mod h1:vKdFvxhtzZ9onBp9VKHK8z/sRpBMnKAsufL7wlDrCOA=
+golang.org/x/crypto v0.0.0-20180904163835-0709b304e793 h1:u+LnwYTOOW7Ukr/fppxEb1Nwz0AtPflrblfvUudpo+I=
 golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/image v0.0.0-20181116024801-cd38e8056d9b h1:VHyIDlv3XkfCa5/a81uzaoDkHH4rr81Z62g+xlnO8uM=
 golang.org/x/image v0.0.0-20181116024801-cd38e8056d9b/go.mod h1:ux5Hcp/YLpHSI86hEcLt0YII63i6oz57MZXIpbrjZUs=
@@ -145,6 +150,8 @@ golang.org/x/sys v0.0.0-20180909124046-d0be0721c37e/go.mod h1:STP8DvDyc/dI5b8T5h
 golang.org/x/sys v0.0.0-20181116152217-5ac8a444bdc5/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190109145017-48ac38b7c8cb h1:1w588/yEchbPNpa9sEvOcMZYbWHedwJjg4VOAdDHWHk=
 golang.org/x/sys v0.0.0-20190109145017-48ac38b7c8cb/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894 h1:Cz4ceDQGXuKRnVBDTS23GTn/pU5OE2C0WrNTOYK1Uuc=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/tools v0.0.0-20180828015842-6cd1fcedba52/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=

log.go

@@ -1,92 +1,97 @@
 package main
 
 import (
-	"fmt"
-	"log"
-	"log/syslog"
 	"net/http"
-)
 
-const (
-	logRequestFmt        = "[%s] %s: %s"
-	logRequestSyslogFmt  = "REQUEST [%s] %s: %s"
-	logResponseFmt       = "[%s] |\033[7;%dm %d \033[0m| %s"
-	logResponseSyslogFmt = "RESPONSE [%s] | %d | %s"
-	logWarningFmt        = "\033[1;33m[WARNING]\033[0m %s"
-	logWarningSyslogFmt  = "WARNING %s"
-	logFatalSyslogFmt    = "FATAL %s"
+	logrus "github.com/sirupsen/logrus"
 )
 
-func logRequest(reqID string, r *http.Request) {
-	path := r.URL.RequestURI()
+func initLog() {
+	logFormat := "pretty"
+	strEnvConfig(&logFormat, "IMGPROXY_LOG_FORMAT")
+
+	switch logFormat {
+	case "structured":
+		logrus.SetFormatter(&logStructuredFormatter{})
+	case "json":
+		logrus.SetFormatter(&logrus.JSONFormatter{})
+	default:
+		logrus.SetFormatter(newLogPrettyFormatter())
+	}
 
-	log.Printf(logRequestFmt, reqID, r.Method, path)
+	logrus.SetLevel(logrus.DebugLevel)
+
+	if isSyslogEnabled() {
+		slHook, err := newSyslogHook()
+		if err != nil {
+			logFatal("Unable to connect to local syslog daemon")
+		}
 
-	if syslogWriter != nil {
-		syslogWriter.Notice(fmt.Sprintf(logRequestSyslogFmt, reqID, r.Method, path))
+		logrus.AddHook(slHook)
 	}
 }
 
-func logResponse(reqID string, status int, msg string) {
-	var color int
+func logRequest(reqID string, r *http.Request) {
+	path := r.URL.RequestURI()
+
+	logrus.WithFields(logrus.Fields{
+		"request_id": reqID,
+		"method":     r.Method,
+	}).Infof("Started %s", path)
+}
+
+func logResponse(reqID string, r *http.Request, status int, err *imgproxyError, imageURL *string, po *processingOptions) {
+	var level logrus.Level
 
 	switch {
 	case status >= 500:
-		color = 31
+		level = logrus.ErrorLevel
 	case status >= 400:
-		color = 33
+		level = logrus.WarnLevel
 	default:
-		color = 32
+		level = logrus.InfoLevel
 	}
 
-	log.Printf(logResponseFmt, reqID, color, status, msg)
-
-	if syslogWriter != nil {
-		syslogMsg := fmt.Sprintf(logResponseSyslogFmt, reqID, status, msg)
-
-		switch {
-		case status >= 500:
-			if syslogLevel >= syslog.LOG_ERR {
-				syslogWriter.Err(syslogMsg)
-			}
-		case status >= 400:
-			if syslogLevel >= syslog.LOG_WARNING {
-				syslogWriter.Warning(syslogMsg)
-			}
-		default:
-			if syslogLevel >= syslog.LOG_NOTICE {
-				syslogWriter.Notice(syslogMsg)
-			}
-		}
+	fields := logrus.Fields{
+		"request_id": reqID,
+		"method":     r.Method,
+		"status":     status,
 	}
-}
 
-func logNotice(f string, args ...interface{}) {
-	msg := fmt.Sprintf(f, args...)
+	if err != nil {
+		fields["error"] = err
 
-	log.Print(msg)
+		if stack := err.FormatStack(); len(stack) > 0 {
+			fields["stack"] = stack
+		}
+	}
 
-	if syslogWriter != nil && syslogLevel >= syslog.LOG_NOTICE {
-		syslogWriter.Notice(msg)
+	if imageURL != nil {
+		fields["image_url"] = *imageURL
 	}
-}
 
-func logWarning(f string, args ...interface{}) {
-	msg := fmt.Sprintf(f, args...)
+	if po != nil {
+		fields["processing_options"] = po
+	}
 
-	log.Printf(logWarningFmt, msg)
+	logrus.WithFields(fields).Logf(
+		level,
+		"Completed in %s %s", getTimerSince(r.Context()), r.URL.RequestURI(),
+	)
+}
 
-	if syslogWriter != nil && syslogLevel >= syslog.LOG_WARNING {
-		syslogWriter.Warning(fmt.Sprintf(logWarningSyslogFmt, msg))
-	}
+func logNotice(f string, args ...interface{}) {
+	logrus.Infof(f, args...)
 }
 
-func logFatal(f string, args ...interface{}) {
-	msg := fmt.Sprintf(f, args...)
+func logWarning(f string, args ...interface{}) {
+	logrus.Warnf(f, args...)
+}
 
-	if syslogWriter != nil {
-		syslogWriter.Crit(fmt.Sprintf(logFatalSyslogFmt, msg))
-	}
+func logFatal(f string, args ...interface{}) {
+	logrus.Fatalf(f, args...)
+}
 
-	log.Fatal(msg)
+func logDebug(f string, args ...interface{}) {
+	logrus.Debugf(f, args...)
 }

log_formatter.go

@@ -0,0 +1,155 @@
+package main
+
+import (
+	"bytes"
+	"fmt"
+	"regexp"
+	"sort"
+	"strings"
+	"time"
+	"unicode/utf8"
+
+	logrus "github.com/sirupsen/logrus"
+)
+
+var (
+	logKeysPriorities = map[string]int{
+		"request_id": 3,
+		"method":     2,
+		"status":     1,
+		"error":      -1,
+		"stack":      -2,
+	}
+
+	logQuotingRe = regexp.MustCompile(`^[a-zA-Z0-9\-._/@^+]+$`)
+)
+
+type logKeys []string
+
+func (p logKeys) Len() int           { return len(p) }
+func (p logKeys) Less(i, j int) bool { return logKeysPriorities[p[i]] > logKeysPriorities[p[j]] }
+func (p logKeys) Swap(i, j int)      { p[i], p[j] = p[j], p[i] }
+
+type logPrettyFormatter struct {
+	levelFormat string
+}
+
+func newLogPrettyFormatter() *logPrettyFormatter {
+	f := new(logPrettyFormatter)
+
+	levelLenMax := 0
+	for _, level := range logrus.AllLevels {
+		levelLen := utf8.RuneCount([]byte(level.String()))
+		if levelLen > levelLenMax {
+			levelLenMax = levelLen
+		}
+	}
+
+	f.levelFormat = fmt.Sprintf("%%-%ds", levelLenMax)
+
+	return f
+}
+
+func (f *logPrettyFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	keys := make([]string, 0, len(entry.Data))
+	for k := range entry.Data {
+		if k != "stack" {
+			keys = append(keys, k)
+		}
+	}
+
+	sort.Sort(logKeys(keys))
+
+	levelColor := 36
+	switch entry.Level {
+	case logrus.DebugLevel, logrus.TraceLevel:
+		levelColor = 37
+	case logrus.WarnLevel:
+		levelColor = 33
+	case logrus.ErrorLevel, logrus.FatalLevel, logrus.PanicLevel:
+		levelColor = 31
+	}
+
+	levelText := fmt.Sprintf(f.levelFormat, strings.ToUpper(entry.Level.String()))
+	msg := strings.TrimSuffix(entry.Message, "\n")
+
+	var b *bytes.Buffer
+	if entry.Buffer != nil {
+		b = entry.Buffer
+	} else {
+		b = new(bytes.Buffer)
+	}
+
+	fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m [%s] %s ", levelColor, levelText, entry.Time.Format(time.RFC3339), msg)
+
+	for _, k := range keys {
+		v := entry.Data[k]
+		fmt.Fprintf(b, " \x1b[1m%s\x1b[0m=", k)
+		f.appendValue(b, v)
+	}
+
+	b.WriteByte('\n')
+
+	if stack, ok := entry.Data["stack"]; ok {
+		fmt.Fprintln(b, stack)
+	}
+
+	return b.Bytes(), nil
+}
+
+func (f *logPrettyFormatter) appendValue(b *bytes.Buffer, value interface{}) {
+	strValue, ok := value.(string)
+	if !ok {
+		strValue = fmt.Sprint(value)
+	}
+
+	if logQuotingRe.MatchString(strValue) {
+		b.WriteString(strValue)
+	} else {
+		fmt.Fprintf(b, "%q", strValue)
+	}
+}
+
+type logStructuredFormatter struct{}
+
+func (f *logStructuredFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	keys := make([]string, 0, len(entry.Data))
+	for k := range entry.Data {
+		keys = append(keys, k)
+	}
+
+	sort.Sort(logKeys(keys))
+
+	msg := strings.TrimSuffix(entry.Message, "\n")
+
+	var b *bytes.Buffer
+	if entry.Buffer != nil {
+		b = entry.Buffer
+	} else {
+		b = new(bytes.Buffer)
+	}
+
+	f.appendKeyValue(b, "time", entry.Time.Format(time.RFC3339))
+	f.appendKeyValue(b, "level", entry.Level.String())
+	f.appendKeyValue(b, "message", msg)
+
+	for _, k := range keys {
+		f.appendKeyValue(b, k, entry.Data[k])
+	}
+
+	b.WriteByte('\n')
+	return b.Bytes(), nil
+}
+
+func (f *logStructuredFormatter) appendKeyValue(b *bytes.Buffer, key string, value interface{}) {
+	if b.Len() != 0 {
+		b.WriteByte(' ')
+	}
+
+	strValue, ok := value.(string)
+	if !ok {
+		strValue = fmt.Sprint(value)
+	}
+
+	fmt.Fprintf(b, "%s=%q", key, strValue)
+}

main.go

@@ -17,7 +17,7 @@ type ctxKey string
 func initialize() {
 	log.SetOutput(os.Stdout)
 
-	initSyslog()
+	initLog()
 	configure()
 	initNewrelic()
 	initPrometheus()
@@ -38,7 +38,7 @@ func main() {
 			if logMemStats {
 				var m runtime.MemStats
 				runtime.ReadMemStats(&m)
-				logNotice("[MEMORY USAGE] Sys: %d; HeapIdle: %d; HeapInuse: %d", m.Sys/1024/1024, m.HeapIdle/1024/1024, m.HeapInuse/1024/1024)
+				logDebug("MEMORY USAGE: Sys=%d HeapIdle=%d HeapInuse=%d", m.Sys/1024/1024, m.HeapIdle/1024/1024, m.HeapInuse/1024/1024)
 			}
 		}
 	}()

processing_handler.go

@@ -83,11 +83,22 @@ func respondWithImage(ctx context.Context, reqID string, r *http.Request, rw htt
 		rw.Write(data)
 	}
 
-	logResponse(reqID, 200, fmt.Sprintf("Processed in %s: %s; %+v", getTimerSince(ctx), getImageURL(ctx), po))
+	imageURL := getImageURL(ctx)
+
+	logResponse(reqID, r, 200, nil, &imageURL, po)
+	// logResponse(reqID, r, 200, getTimerSince(ctx), getImageURL(ctx), po))
+}
+
+func respondWithNotModified(ctx context.Context, reqID string, r *http.Request, rw http.ResponseWriter) {
+	rw.WriteHeader(304)
+
+	imageURL := getImageURL(ctx)
+
+	logResponse(reqID, r, 304, nil, &imageURL, getProcessingOptions(ctx))
 }
 
 func handleProcessing(reqID string, rw http.ResponseWriter, r *http.Request) {
-	ctx := context.Background()
+	ctx := r.Context()
 
 	if newRelicEnabled {
 		var newRelicCancel context.CancelFunc
@@ -103,7 +114,7 @@ func handleProcessing(reqID string, rw http.ResponseWriter, r *http.Request) {
 	processingSem <- struct{}{}
 	defer func() { <-processingSem }()
 
-	ctx, timeoutCancel := startTimer(ctx, time.Duration(conf.WriteTimeout)*time.Second)
+	ctx, timeoutCancel := context.WithTimeout(ctx, time.Duration(conf.WriteTimeout)*time.Second)
 	defer timeoutCancel()
 
 	ctx, err := parsePath(ctx, r)
@@ -130,8 +141,7 @@ func handleProcessing(reqID string, rw http.ResponseWriter, r *http.Request) {
 		rw.Header().Set("ETag", eTag)
 
 		if eTag == r.Header.Get("If-None-Match") {
-			logResponse(reqID, 304, "Not modified")
-			rw.WriteHeader(304)
+			respondWithNotModified(ctx, reqID, r, rw)
 			return
 		}
 	}

processing_options.go

@@ -189,6 +189,10 @@ func (po *processingOptions) presetUsed(name string) {
 	po.UsedPresets = append(po.UsedPresets, name)
 }
 
+func (po *processingOptions) String() string {
+	return fmt.Sprintf("%+v", *po)
+}
+
 func colorFromHex(hexcolor string) (rgbColor, error) {
 	c := rgbColor{}
 

prometheus.go

@@ -108,7 +108,7 @@ func initPrometheus() {
 			logFatal(err.Error())
 		}
 
-		logNotice("Starting Prometheus server at %s\n", conf.PrometheusBind)
+		logNotice("Starting Prometheus server at %s", conf.PrometheusBind)
 		if err := s.Serve(l); err != nil && err != http.ErrServerClosed {
 			logFatal(err.Error())
 		}

router.go

@@ -65,6 +65,8 @@ func (r *router) OPTIONS(prefix string, handler routeHandler, exact bool) {
 }
 
 func (r *router) ServeHTTP(rw http.ResponseWriter, req *http.Request) {
+	req = req.WithContext(setTimerSince(req.Context()))
+
 	reqID := req.Header.Get(xRequestIDHeader)
 
 	if len(reqID) == 0 || !requestIDRe.MatchString(reqID) {

server.go

@@ -111,7 +111,7 @@ func handlePanic(reqID string, rw http.ResponseWriter, r *http.Request, err erro
 		reportError(err, r)
 	}
 
-	logResponse(reqID, ierr.StatusCode, ierr.ErrorWithStack())
+	logResponse(reqID, r, ierr.StatusCode, ierr, nil, nil)
 
 	rw.WriteHeader(ierr.StatusCode)
 
@@ -123,17 +123,18 @@ func handlePanic(reqID string, rw http.ResponseWriter, r *http.Request, err erro
 }
 
 func handleHealth(reqID string, rw http.ResponseWriter, r *http.Request) {
-	logResponse(reqID, 200, string(imgproxyIsRunningMsg))
+	logResponse(reqID, r, 200, nil, nil, nil)
 	rw.WriteHeader(200)
 	rw.Write(imgproxyIsRunningMsg)
 }
 
 func handleOptions(reqID string, rw http.ResponseWriter, r *http.Request) {
-	logResponse(reqID, 200, "Respond with options")
+	logResponse(reqID, r, 200, nil, nil, nil)
 	rw.WriteHeader(200)
 }
 
 func handleFavicon(reqID string, rw http.ResponseWriter, r *http.Request) {
+	logResponse(reqID, r, 200, nil, nil, nil)
 	// TODO: Add a real favicon maybe?
 	rw.WriteHeader(200)
 }

syslog.go

@@ -1,55 +1,84 @@
 package main
 
 import (
-	"log"
+	"fmt"
 	"log/syslog"
+	"os"
+
+	"github.com/sirupsen/logrus"
 )
 
 var (
-	syslogWriter *syslog.Writer
-	syslogLevel  syslog.Priority
+	syslogLevels = map[string]logrus.Level{
+		"crit":    logrus.FatalLevel,
+		"error":   logrus.ErrorLevel,
+		"warning": logrus.WarnLevel,
+		"info":    logrus.InfoLevel,
+	}
 )
 
-var syslogLevels = map[string]syslog.Priority{
-	"crit":    syslog.LOG_CRIT,
-	"error":   syslog.LOG_ERR,
-	"warning": syslog.LOG_WARNING,
-	"notice":  syslog.LOG_NOTICE,
+type syslogHook struct {
+	writer    *syslog.Writer
+	levels    []logrus.Level
+	formatter logrus.Formatter
 }
 
-func initSyslog() {
-	var (
-		err error
+func isSyslogEnabled() (enabled bool) {
+	boolEnvConfig(&enabled, "IMGPROXY_SYSLOG_ENABLE")
+	return
+}
 
-		enabled       bool
+func newSyslogHook() (*syslogHook, error) {
+	var (
 		network, addr string
-	)
+		level         logrus.Level
 
-	boolEnvConfig(&enabled, "IMGPROXY_SYSLOG_ENABLE")
-
-	if !enabled {
-		return
-	}
+		tag      = "imgproxy"
+		levelStr = "notice"
+	)
 
 	strEnvConfig(&network, "IMGPROXY_SYSLOG_NETWORK")
 	strEnvConfig(&addr, "IMGPROXY_SYSLOG_ADDRESS")
-
-	tag := "imgproxy"
 	strEnvConfig(&tag, "IMGPROXY_SYSLOG_TAG")
+	strEnvConfig(&levelStr, "IMGPROXY_SYSLOG_LEVEL")
 
-	syslogWriter, err = syslog.Dial(network, addr, syslog.LOG_NOTICE, tag)
+	if l, ok := syslogLevels[levelStr]; ok {
+		level = l
+	} else {
+		level = logrus.InfoLevel
+		logWarning("Syslog level '%s' is invalid, 'info' is used", levelStr)
+	}
+
+	w, err := syslog.Dial(network, addr, syslog.LOG_NOTICE, tag)
+
+	return &syslogHook{
+		writer:    w,
+		levels:    logrus.AllLevels[:int(level)+1],
+		formatter: &logStructuredFormatter{},
+	}, err
+}
 
+func (hook *syslogHook) Fire(entry *logrus.Entry) error {
+	line, err := hook.formatter.Format(entry)
 	if err != nil {
-		log.Fatalf("Can't connect to syslog: %s", err)
+		fmt.Fprintf(os.Stderr, "Unable to read entry, %v\n", err)
+		return err
 	}
 
-	levelStr := "notice"
-	strEnvConfig(&levelStr, "IMGPROXY_SYSLOG_LEVEL")
-
-	if l, ok := syslogLevels[levelStr]; ok {
-		syslogLevel = l
-	} else {
-		syslogLevel = syslog.LOG_NOTICE
-		logWarning("Syslog level '%s' is invalid, 'notice' is used", levelStr)
+	switch entry.Level {
+	case logrus.PanicLevel, logrus.FatalLevel:
+		return hook.writer.Crit(string(line))
+	case logrus.ErrorLevel:
+		return hook.writer.Err(string(line))
+	case logrus.WarnLevel:
+		return hook.writer.Warning(string(line))
+	case logrus.InfoLevel:
+		return hook.writer.Info(string(line))
+	default:
+		return nil
 	}
 }
+
+func (hook *syslogHook) Levels() []logrus.Level {
+	return hook.levels
+}

timer.go

@@ -8,11 +8,8 @@ import (
 
 var timerSinceCtxKey = ctxKey("timerSince")
 
-func startTimer(ctx context.Context, d time.Duration) (context.Context, context.CancelFunc) {
-	return context.WithTimeout(
-		context.WithValue(ctx, timerSinceCtxKey, time.Now()),
-		d,
-	)
+func setTimerSince(ctx context.Context) context.Context {
+	return context.WithValue(ctx, timerSinceCtxKey, time.Now())
 }
 
 func getTimerSince(ctx context.Context) time.Duration {