Skip to content
Permalink
Browse files

New logging; JSON and structured log formats

  • Loading branch information...
DarthSim committed Sep 16, 2019
1 parent 83c00a9 commit 16784fb1e2f482b4b7dcfe1009515f0b8b8ba599
Showing with 321 additions and 110 deletions.
  1. +3 −3 errors.go
  2. +2 −1 go.mod
  3. +7 −0 go.sum
  4. +65 −60 log.go
  5. +155 −0 log_formatter.go
  6. +2 −2 main.go
  7. +15 −5 processing_handler.go
  8. +4 −0 processing_options.go
  9. +1 −1 prometheus.go
  10. +2 −0 router.go
  11. +4 −3 server.go
  12. +59 −30 syslog.go
  13. +2 −5 timer.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 {
3 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
)
7 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=
125 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...)
}
@@ -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)
}
@@ -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)
}
}
}()

0 comments on commit 16784fb

Please sign in to comment.
You can’t perform that action at this time.