From c59fde30ebd2c04adb3db0d09f862f0dd7e033d0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Nico=20M=C3=BCrdter?= Date: Fri, 28 Feb 2020 09:28:50 +0100 Subject: [PATCH] Add log sink to be able to send breadcrumbs to sentry (#169) This pr introduces a log sink to be able to store logs inside a context and send them to sentry as breadcrumbs if an error happens. Note: since https://github.com/getsentry/raven-go is no longer supported and does not support breadcrumbs, this pr moves the package to maintenance/errors/raven and adds the missing breadcrumb feature. --- backend/postgres/postgres.go | 3 +- backend/redis/redis.go | 2 +- go.mod | 4 +- go.sum | 2 - http/router.go | 7 +- http/transport/logging_round_tripper.go | 6 +- http/transport/logging_round_tripper_test.go | 4 +- maintenance/errors/error.go | 140 ++++++++++++++- maintenance/errors/error_test.go | 169 ++++++++++++++++++ .../errors/raven}/LICENSE | 0 .../errors/raven}/client.go | 11 ++ .../errors/raven}/errors.go | 0 .../errors/raven}/exception.go | 0 .../errors/raven}/http.go | 0 .../errors/raven}/interfaces.go | 0 .../errors/raven}/stacktrace.go | 0 .../errors/raven}/writer.go | 0 maintenance/log/handler.go | 7 +- maintenance/log/log.go | 11 +- maintenance/log/sink.go | 92 ++++++++++ maintenance/log/sink_test.go | 41 +++++ .../getsentry/raven-go/.dockerignore | 1 - .../github.com/getsentry/raven-go/.gitignore | 2 - .../github.com/getsentry/raven-go/.gitmodules | 0 .../github.com/getsentry/raven-go/.travis.yml | 27 --- .../github.com/getsentry/raven-go/README.md | 13 -- .../github.com/getsentry/raven-go/runtests.sh | 4 - vendor/modules.txt | 2 - 28 files changed, 476 insertions(+), 72 deletions(-) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/LICENSE (100%) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/client.go (98%) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/errors.go (100%) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/exception.go (100%) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/http.go (100%) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/interfaces.go (100%) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/stacktrace.go (100%) rename {vendor/github.com/getsentry/raven-go => maintenance/errors/raven}/writer.go (100%) create mode 100644 maintenance/log/sink.go create mode 100644 maintenance/log/sink_test.go delete mode 100644 vendor/github.com/getsentry/raven-go/.dockerignore delete mode 100644 vendor/github.com/getsentry/raven-go/.gitignore delete mode 100644 vendor/github.com/getsentry/raven-go/.gitmodules delete mode 100644 vendor/github.com/getsentry/raven-go/.travis.yml delete mode 100644 vendor/github.com/getsentry/raven-go/README.md delete mode 100644 vendor/github.com/getsentry/raven-go/runtests.sh diff --git a/backend/postgres/postgres.go b/backend/postgres/postgres.go index aa1c43f6..564b901f 100644 --- a/backend/postgres/postgres.go +++ b/backend/postgres/postgres.go @@ -241,7 +241,8 @@ func queryLogger(event *pg.QueryProcessedEvent) { Int("line", event.Line). Str("func", event.Func). Int("attempt", event.Attempt). - Float64("duration", dur) + Float64("duration", dur). + Str("sentry:category", "postgres") // add error or result set info if event.Error != nil { diff --git a/backend/redis/redis.go b/backend/redis/redis.go index 200ab142..a058b024 100644 --- a/backend/redis/redis.go +++ b/backend/redis/redis.go @@ -168,7 +168,7 @@ func (lt *logtracer) handle(realProcess func(redis.Cmder) error) func(redis.Cmde } // logging prep and tracing - le := logger.Debug().Str("cmd", cmder.Name()) + le := logger.Debug().Str("cmd", cmder.Name()).Str("sentry:category", "redis") startTime := time.Now() span, _ := opentracing.StartSpanFromContext(lt.ctx, fmt.Sprintf("Redis: %s", cmder.Name())) diff --git a/go.mod b/go.mod index f394d73a..29290f7b 100644 --- a/go.mod +++ b/go.mod @@ -6,11 +6,10 @@ require ( github.com/asaskevich/govalidator v0.0.0-20180720115003-f9ffefc3facf github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973 // indirect github.com/caarlos0/env v3.3.0+incompatible - github.com/certifi/gocertifi v0.0.0-20180118203423-deb3ae2ef261 // indirect + github.com/certifi/gocertifi v0.0.0-20180118203423-deb3ae2ef261 github.com/codahale/hdrhistogram v0.0.0-20161010025455-3a0bb77429bd // indirect github.com/dave/jennifer v1.0.2 github.com/getkin/kin-openapi v0.0.0-20180813063848-e1956e8013e5 - github.com/getsentry/raven-go v0.0.0-20180903072508-084a9de9eb03 github.com/ghodss/yaml v1.0.0 // indirect github.com/go-pg/pg v6.14.5+incompatible github.com/go-redis/redis v6.14.1+incompatible @@ -25,6 +24,7 @@ require ( github.com/onsi/ginkgo v1.8.0 // indirect github.com/onsi/gomega v1.4.3 // indirect github.com/opentracing/opentracing-go v1.0.2 + github.com/pkg/errors v0.8.1 github.com/pmezard/go-difflib v1.0.0 github.com/prometheus/client_golang v0.8.0 github.com/prometheus/client_model v0.0.0-20180712105110-5c3871d89910 // indirect diff --git a/go.sum b/go.sum index 07ed1ca8..69e0d41b 100644 --- a/go.sum +++ b/go.sum @@ -20,8 +20,6 @@ github.com/fsnotify/fsnotify v1.4.7 h1:IXs+QLmnXW2CcXuY+8Mzv/fWEsPGWxqefPtCP5CnV github.com/fsnotify/fsnotify v1.4.7/go.mod h1:jwhsz4b93w/PPRr/qN1Yymfu8t87LnFCMoQvtojpjFo= github.com/getkin/kin-openapi v0.0.0-20180813063848-e1956e8013e5 h1:gXUMwj0PndSd+Ub1PptoPX0nAwrrS8/SVFTJwOIzjyk= github.com/getkin/kin-openapi v0.0.0-20180813063848-e1956e8013e5/go.mod h1:+0ZtELZf+SlWH8ZdA/IeFb3L/PKOKJx8eGxAlUZ/sOU= -github.com/getsentry/raven-go v0.0.0-20180903072508-084a9de9eb03 h1:G/9fPivTr5EiyqE9OlW65iMRUxFXMGRHgZFGo50uG8Q= -github.com/getsentry/raven-go v0.0.0-20180903072508-084a9de9eb03/go.mod h1:KungGk8q33+aIAZUIVWZDr2OfAEBsO49PX4NzFV5kcQ= github.com/ghodss/yaml v1.0.0 h1:wQHKEahhL6wmXdzwWG11gIVCkOv05bNOh+Rxn0yngAk= github.com/ghodss/yaml v1.0.0/go.mod h1:4dBDuWmgqj2HViK6kFavaiC9ZROes6MMH2rRYeMEF04= github.com/go-pg/pg v6.14.5+incompatible h1:Tc74MTCCIVd8sAJshYHqutcHhO64/EBHBTydzCGt3Js= diff --git a/http/router.go b/http/router.go index b3542cc0..c012eb61 100644 --- a/http/router.go +++ b/http/router.go @@ -24,12 +24,13 @@ func Router() *mux.Router { r.Use(metricsMiddleware) + // the logging middleware needs to be registered before the error + // middleware to make it possible to send panics to sentry + r.Use(util.NewIgnorePrefixMiddleware(log.Handler(), "/health")) + // last resort error handler r.Use(errors.Handler()) - // for logging - r.Use(util.NewIgnorePrefixMiddleware(log.Handler(), "/health")) - r.Use(tracing.Handler( // no tracing for these prefixes "/metrics", diff --git a/http/transport/logging_round_tripper.go b/http/transport/logging_round_tripper.go index b64fbf47..77990e52 100644 --- a/http/transport/logging_round_tripper.go +++ b/http/transport/logging_round_tripper.go @@ -33,7 +33,9 @@ func (l *LoggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, erro startTime := time.Now() le := log.Ctx(ctx).Debug(). Str("url", req.URL.String()). - Str("method", req.Method) + Str("method", req.Method). + Str("sentry:type", "http"). + Str("sentry:category", "http") resp, err := l.Transport().RoundTrip(req) @@ -49,7 +51,7 @@ func (l *LoggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, erro return nil, err } - le.Int("code", resp.StatusCode).Msg(logEventMsg(req)) + le.Int("status_code", resp.StatusCode).Msg(logEventMsg(req)) return resp, nil } diff --git a/http/transport/logging_round_tripper_test.go b/http/transport/logging_round_tripper_test.go index efc2fe15..992c6109 100644 --- a/http/transport/logging_round_tripper_test.go +++ b/http/transport/logging_round_tripper_test.go @@ -46,7 +46,7 @@ func TestLoggingRoundTripper(t *testing.T) { t.Errorf("Expected retries to not be contained in log output, got %v", got) } - exs := []string{`"level":"debug"`, `"url":"http://example.com/foo"`, `"method":"GET"`, `"code":200`, `"message":"HTTP GET example.com"`} + exs := []string{`"level":"debug"`, `"url":"http://example.com/foo"`, `"method":"GET"`, `"status_code":200`, `"message":"HTTP GET example.com"`} for _, ex := range exs { if !strings.Contains(got, ex) { t.Errorf("Expected %v to be contained in log output, got %v", ex, got) @@ -64,7 +64,7 @@ func TestLoggingRoundTripper(t *testing.T) { } got := out.String() - exs := []string{`"level":"debug"`, `"url":"http://example.com/foo"`, `"method":"GET"`, `"code":200`, `"message":"HTTP GET example.com"`, `"attempt":3`} + exs := []string{`"level":"debug"`, `"url":"http://example.com/foo"`, `"method":"GET"`, `"status_code":200`, `"message":"HTTP GET example.com"`, `"attempt":3`} for _, ex := range exs { if !strings.Contains(got, ex) { t.Errorf("Expected %v to be contained in log output, got %v", ex, got) diff --git a/maintenance/errors/error.go b/maintenance/errors/error.go index 0c3c0810..a0ed66b8 100644 --- a/maintenance/errors/error.go +++ b/maintenance/errors/error.go @@ -5,16 +5,19 @@ package errors import ( "context" + "encoding/json" "errors" "fmt" "net/http" "os" + "time" - raven "github.com/getsentry/raven-go" "github.com/pace/bricks/http/jsonapi/runtime" "github.com/pace/bricks/http/oauth2" + "github.com/pace/bricks/maintenance/errors/raven" "github.com/pace/bricks/maintenance/log" "github.com/prometheus/client_golang/prometheus" + "github.com/rs/zerolog" ) var ( @@ -70,7 +73,7 @@ type contextHandler struct { next http.Handler } -func (h contextHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { +func (h *contextHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // For error handling we want to log information about the request under // which the error happened. But in some cases we only have a context, // because unlike the context the request is not passed down. To make the @@ -81,7 +84,7 @@ func (h contextHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Handler implements a panic recovering middleware func Handler() func(http.Handler) http.Handler { return func(next http.Handler) http.Handler { - next = contextHandler{next: next} + next = &contextHandler{next: next} return &recoveryHandler{next: next} } } @@ -158,7 +161,8 @@ type sentryEvent struct { } func (e sentryEvent) Send() { - raven.Capture(e.build(), nil) + _, errCh := raven.Capture(e.build(), nil) + <-errCh // ensure the message get send even if the main goroutine is about to stop } func (e sentryEvent) build() *raven.Packet { @@ -219,5 +223,133 @@ func (e sentryEvent) build() *raven.Packet { // from env packet.Extra["microservice"] = os.Getenv("JAEGER_SERVICE_NAME") + // add breadcrumbs + packet.Breadcrumbs = getBreadcrumbs(ctx) + return packet } + +// getBreadcrumbs takes a context and tries to extract the logs from it if it +// holds a log.Sink. If that's the case, the logs will all be translated +// to valid sentry breadcrumbs if possible. In case of a failure, the +// breadcrumbs will be dropped and a warning will be logged. +func getBreadcrumbs(ctx context.Context) []*raven.Breadcrumb { + sink, ok := log.SinkFromContext(ctx) + if !ok { + return nil + } + + var data []map[string]interface{} + if err := json.Unmarshal(sink.ToJSON(), &data); err != nil { + log.Ctx(ctx).Warn().Err(err).Msg("failed to prepare sentry message") + return nil + } + + result := make([]*raven.Breadcrumb, len(data)) + for i, d := range data { + crumb, err := createBreadcrumb(d) + if err != nil { + log.Ctx(ctx).Warn().Err(err).Msg("failed to create sentry breadcrumb") + return nil + } + + result[i] = crumb + } + + return result +} + +func createBreadcrumb(data map[string]interface{}) (*raven.Breadcrumb, error) { + // remove the request id if it can still be found in the logs + delete(data, "req_id") + + timeRaw, ok := data["time"].(string) + if !ok { + return nil, errors.New(`cannot parse "time"`) + } + delete(data, "time") + + time, err := time.Parse(time.RFC3339, timeRaw) + if err != nil { + return nil, fmt.Errorf(`cannot parse "time": %w`, err) + } + + levelRaw, ok := data["level"].(string) + if !ok { + return nil, errors.New(`cannot parse "level"`) + } + delete(data, "level") + + level, err := translateZerologLevelToSentryLevel(levelRaw) + if err != nil { + return nil, fmt.Errorf(`cannot parse "level": %w`, err) + } + + message, ok := data["message"].(string) + if !ok { + return nil, errors.New(`cannot parse "message"`) + } + delete(data, "message") + + categoryRaw, ok := data["sentry:category"] + if !ok { + categoryRaw = "" + } + delete(data, "sentry:category") + + category, ok := categoryRaw.(string) + if !ok { + return nil, errors.New(`cannot parse "category"`) + } + + typRaw, ok := data["sentry:type"] + if !ok { + typRaw = "" + } + delete(data, "sentry:type") + + typ, ok := typRaw.(string) + if !ok { + return nil, errors.New(`cannot parse "type"`) + } + + if typ == "" && level == "fatal" { + typ = "error" + } + + return &raven.Breadcrumb{ + Category: category, + Level: level, + Message: message, + Timestamp: time.Unix(), + Type: typ, + Data: data, + }, nil +} + +// translateZerologLevelToSentryLevel takes in a zerolog.Level as string +// and returns the equivalent sentry breadcrumb level. If the given level +// can't be parsed to a valid zerolog.Level an error is returned. +func translateZerologLevelToSentryLevel(l string) (string, error) { + level, err := zerolog.ParseLevel(l) + if err != nil { + return "", err + } + + switch level { + case zerolog.TraceLevel, zerolog.InfoLevel: + return "info", nil + case zerolog.DebugLevel: + return "debug", nil + case zerolog.WarnLevel: + return "warning", nil + case zerolog.ErrorLevel: + return "error", nil + case zerolog.FatalLevel, zerolog.PanicLevel: + return "fatal", nil + case zerolog.NoLevel: + fallthrough + default: + return "", nil + } +} diff --git a/maintenance/errors/error_test.go b/maintenance/errors/error_test.go index 10929f87..7e234993 100644 --- a/maintenance/errors/error_test.go +++ b/maintenance/errors/error_test.go @@ -5,13 +5,18 @@ package errors import ( "context" + "encoding/json" "net/http" "net/http/httptest" "strings" "testing" "github.com/gorilla/mux" + "github.com/pace/bricks/http/transport" + "github.com/pace/bricks/maintenance/errors/raven" + "github.com/pace/bricks/maintenance/log" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) // Note: Tests that there is no panic if there are no @@ -72,3 +77,167 @@ func TestStackTrace(t *testing.T) { assert.NotContains(t, string(d), `"module":"testing"`) assert.NotContains(t, string(d), `"filename":"testing/testing.go"`) } + +func Test_createBreadcrumb(t *testing.T) { + tests := []struct { + name string + data map[string]interface{} + want *raven.Breadcrumb + wantErr bool + }{ + { + name: "standard_error", + data: map[string]interface{}{ + "level": "error", + "message": "this is an error message", + "time": "2020-02-27T10:19:28+01:00", + "req_id": "bpboj6bipt34r4teo7g0", + }, + want: &raven.Breadcrumb{ + Level: "error", + Message: "this is an error message", + Timestamp: 1582795168, + Data: map[string]interface{}{}, + }, + }, + { + name: "http", + data: map[string]interface{}{ + "level": "debug", + "time": "2020-02-27T10:19:28+01:00", + "sentry:category": "http", + "sentry:type": "http", + "message": "HTTPS GET www.pace.car", + "method": "GET", + "attempt": 1, + "status_code": 200, + "duration": 227.717783, + "url": "https://www.pace.car/", + "req_id": "bpboj6bipt34r4teo7g0", + }, + want: &raven.Breadcrumb{ + Category: "http", + Level: "debug", + Message: "HTTPS GET www.pace.car", + Timestamp: 1582795168, + Type: "http", + Data: map[string]interface{}{ + "method": "GET", + "attempt": 1, + "status_code": 200, + "duration": 227.717783, + "url": "https://www.pace.car/", + }, + }, + }, + { + name: "panic_level", + data: map[string]interface{}{ + "level": "panic", + "message": "this is a panic message", + "time": "2020-02-27T10:19:28+01:00", + }, + want: &raven.Breadcrumb{ + Level: "fatal", + Type: "error", + Message: "this is a panic message", + Timestamp: 1582795168, + Data: map[string]interface{}{}, + }, + }, + { + name: "custom_category", + data: map[string]interface{}{ + "level": "info", + "message": "this is an error message", + "sentry:category": "redis", + "sentry:type": "error", + "time": "2020-02-27T10:19:28+01:00", + "req_id": "bpboj6bipt34r4teo7g0", + }, + want: &raven.Breadcrumb{ + Category: "redis", + Level: "info", + Timestamp: 1582795168, + Message: "this is an error message", + Type: "error", + Data: map[string]interface{}{}, + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got, err := createBreadcrumb(tt.data) + if (err != nil) != tt.wantErr { + t.Errorf("createBreadcrumb() error = %v, wantErr %v", err, tt.wantErr) + return + } + + assert.Equal(t, tt.want, got, "createBreadcrumb() = %v, want %v", got, tt.want) + }) + } +} + +// TestHandlerWithLogSink tests whether the panic recover handler +// still works and the corresponding logs reach the integrated log.Sink +// which should be passed to all subsequent requests and handler. +func TestHandlerWithLogSink(t *testing.T) { + rec := httptest.NewRecorder() + req := httptest.NewRequest("GET", "/test", nil) + + var sinkCtx context.Context + + mux := http.NewServeMux() + mux.HandleFunc("/test", func(w http.ResponseWriter, r *http.Request) { + require.NotEqual(t, "", log.RequestID(r), "request should have request id") + sinkCtx = r.Context() + + client := &http.Client{ + Transport: transport.NewDefaultTransportChain(), + } + + r0, err := http.NewRequest("GET", "https://www.pace.car/de", nil) + assert.NoError(t, err, `failed creating request to "/succeed"`) + + r0 = r0.WithContext(r.Context()) + _, err = client.Do(r0) + assert.NoError(t, err, `request to "/succeed" should not error`) + + r1, err := http.NewRequest("GET", "http://localhost/fail", nil) + assert.NoError(t, err, `failed creating request to "/fail"`) + + r1 = r1.WithContext(r.Context()) + _, err = client.Do(r1) + assert.Error(t, err, `request to "/fail" should error`) + + log.Req(r).Info(). + Str("sentry:category", "redis"). + Str("sentry:type", "error"). + Msg("this is a test message for the sink") + + panic("Sink Test Error, IGNORE") + }) + log.Handler()(Handler()(mux)).ServeHTTP(rec, req) + + resp := rec.Result() + defer resp.Body.Close() + + sink, ok := log.SinkFromContext(sinkCtx) + assert.True(t, ok, "failed getting sink") + + var logLines []json.RawMessage + assert.NoError(t, json.Unmarshal(sink.ToJSON(), &logLines), "failed extracting logs from sink") + + assert.Contains(t, string(logLines[0]), "https://www.pace.car/de", "missing log line") + assert.Contains(t, string(logLines[1]), "http://localhost/fail", "missing log line") + + assert.Contains(t, string(logLines[2]), "sentry:category", "missing log line") + assert.Contains(t, string(logLines[2]), "redis", "missing log line") + assert.Contains(t, string(logLines[2]), "sentry:type", "missing log line") + assert.Contains(t, string(logLines[2]), "error", "missing log line") + assert.Contains(t, string(logLines[2]), "this is a test message for the sink", "missing log line") + + assert.Contains(t, string(logLines[3]), "Sink Test Error, IGNORE", "missing log line") + + require.Equal(t, 500, resp.StatusCode, "wrong status code") +} diff --git a/vendor/github.com/getsentry/raven-go/LICENSE b/maintenance/errors/raven/LICENSE similarity index 100% rename from vendor/github.com/getsentry/raven-go/LICENSE rename to maintenance/errors/raven/LICENSE diff --git a/vendor/github.com/getsentry/raven-go/client.go b/maintenance/errors/raven/client.go similarity index 98% rename from vendor/github.com/getsentry/raven-go/client.go rename to maintenance/errors/raven/client.go index e224aa1a..aabcfbd0 100644 --- a/vendor/github.com/getsentry/raven-go/client.go +++ b/maintenance/errors/raven/client.go @@ -166,9 +166,20 @@ type Packet struct { Fingerprint []string `json:"fingerprint,omitempty"` Extra Extra `json:"extra,omitempty"` + Breadcrumbs []*Breadcrumb `json:"breadcrumbs,omitempty"` + Interfaces []Interface `json:"-"` } +type Breadcrumb struct { + Category string `json:"category,omitempty"` + Data map[string]interface{} `json:"data,omitempty"` + Level string `json:"level,omitempty"` + Message string `json:"message,omitempty"` + Timestamp int64 `json:"timestamp,omitempty"` + Type string `json:"type,omitempty"` +} + // NewPacket constructs a packet with the specified message and interfaces. func NewPacket(message string, interfaces ...Interface) *Packet { extra := Extra{} diff --git a/vendor/github.com/getsentry/raven-go/errors.go b/maintenance/errors/raven/errors.go similarity index 100% rename from vendor/github.com/getsentry/raven-go/errors.go rename to maintenance/errors/raven/errors.go diff --git a/vendor/github.com/getsentry/raven-go/exception.go b/maintenance/errors/raven/exception.go similarity index 100% rename from vendor/github.com/getsentry/raven-go/exception.go rename to maintenance/errors/raven/exception.go diff --git a/vendor/github.com/getsentry/raven-go/http.go b/maintenance/errors/raven/http.go similarity index 100% rename from vendor/github.com/getsentry/raven-go/http.go rename to maintenance/errors/raven/http.go diff --git a/vendor/github.com/getsentry/raven-go/interfaces.go b/maintenance/errors/raven/interfaces.go similarity index 100% rename from vendor/github.com/getsentry/raven-go/interfaces.go rename to maintenance/errors/raven/interfaces.go diff --git a/vendor/github.com/getsentry/raven-go/stacktrace.go b/maintenance/errors/raven/stacktrace.go similarity index 100% rename from vendor/github.com/getsentry/raven-go/stacktrace.go rename to maintenance/errors/raven/stacktrace.go diff --git a/vendor/github.com/getsentry/raven-go/writer.go b/maintenance/errors/raven/writer.go similarity index 100% rename from vendor/github.com/getsentry/raven-go/writer.go rename to maintenance/errors/raven/writer.go diff --git a/maintenance/log/handler.go b/maintenance/log/handler.go index d1d82fa2..8d145a11 100644 --- a/maintenance/log/handler.go +++ b/maintenance/log/handler.go @@ -17,11 +17,12 @@ import ( // Handler returns a middleware that handles all of the logging aspects of // any incoming http request func Handler() func(http.Handler) http.Handler { + sink := &Sink{} return func(next http.Handler) http.Handler { - return hlog.NewHandler(log.Logger)( + return hlog.NewHandler(log.Logger.Output(sink))( hlog.AccessHandler(requestCompleted)( - hlog.RequestIDHandler("req_id", "Request-Id")(next))) - + hlog.RequestIDHandler("req_id", "Request-Id")( + handlerWithSink(sink)(next)))) } } diff --git a/maintenance/log/log.go b/maintenance/log/log.go index 7a96f38a..9cec4994 100644 --- a/maintenance/log/log.go +++ b/maintenance/log/log.go @@ -37,7 +37,10 @@ var levelMap = map[string]zerolog.Level{ "disabled": zerolog.Disabled, } -var cfg config +var ( + cfg config + logOutput io.Writer +) func init() { // parse log config @@ -66,13 +69,15 @@ func init() { switch cfg.Format { case "console": - log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: "2006-01-02 15:04:05"}) + logOutput = zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: "2006-01-02 15:04:05"} case "json": // configure json output log // use default timestamp format (RFC3339, subset of iso8601) and UTC for json as defined in https://lab.jamit.de/pace/web/meta/issues/11 - log.Logger = log.Logger.Output(os.Stdout) + logOutput = os.Stdout zerolog.TimestampFunc = func() time.Time { return time.Now().UTC() } } + + log.Logger = log.Output(logOutput) } // RequestID returns a unique request id or an empty string if there is none diff --git a/maintenance/log/sink.go b/maintenance/log/sink.go new file mode 100644 index 00000000..86fe4748 --- /dev/null +++ b/maintenance/log/sink.go @@ -0,0 +1,92 @@ +package log + +import ( + "bytes" + "context" + "net/http" + "strings" + "sync" + + "github.com/gorilla/mux" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +type sinkKey struct{} + +// ContextWithSink wraps the given context in a new context with +// the given Sink stored as value. +func ContextWithSink(ctx context.Context, sink *Sink) context.Context { + return context.WithValue(ctx, sinkKey{}, sink) +} + +// SinkFromContext returns the Sink of the given context if it exists +func SinkFromContext(ctx context.Context) (*Sink, bool) { + sink, ok := ctx.Value(sinkKey{}).(*Sink) + return sink, ok +} + +// Sink respresents a log sink which is used to store +// logs, created with log.Ctx(ctx), inside the context +// and use them at a later point in time +type Sink struct { + jsonLogLines []string + + rwmutex sync.RWMutex +} + +// handlerWithSink returns a mux.MiddlewareFunc which +// adds the Sink to the request context. All logs +// corresponding to the request will be printed and stored +// in the Sink for later use. +func handlerWithSink(sink *Sink) mux.MiddlewareFunc { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + next.ServeHTTP(w, r.WithContext(ContextWithSink(r.Context(), sink))) + }) + } +} + +// ToJSON returns a copy of the currently available +// logs in the Sink as json formatted []byte. +func (s *Sink) ToJSON() []byte { + s.rwmutex.RLock() + defer s.rwmutex.RUnlock() + + return []byte("[" + strings.Join(s.jsonLogLines, ",") + "]") +} + +// Pretty returns the logs as string while using the +// zerolog.ConsoleWriter to format them in a human +// readable way +func (s *Sink) Pretty() string { + buf := &bytes.Buffer{} + writer := &zerolog.ConsoleWriter{ + Out: buf, + NoColor: true, + TimeFormat: "2006-01-02 15:04:05", + } + + for _, str := range s.jsonLogLines { + n, err := strings.NewReader(str).WriteTo(writer) + if err != nil { + log.Warn().Err(err).Msg("log.Sink.Pretty failed") + } else if int(n) != len(str) { + log.Warn().Msg("log.Sink.Pretty failed: could not return all logs") + } + } + + return buf.String() +} + +// Write implements the io.Writer interface. This makes it +// possible to use the Sink as output in the zerolog.Output() +// func. Write stores all incoming logs in its internal store +// and calls Write() on the default output writer. +func (s *Sink) Write(b []byte) (int, error) { + s.rwmutex.Lock() + s.jsonLogLines = append(s.jsonLogLines, string(b)) + s.rwmutex.Unlock() + + return logOutput.Write(b) +} diff --git a/maintenance/log/sink_test.go b/maintenance/log/sink_test.go new file mode 100644 index 00000000..dc091d93 --- /dev/null +++ b/maintenance/log/sink_test.go @@ -0,0 +1,41 @@ +package log + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "testing" + + "github.com/stretchr/testify/require" +) + +func Test_Sink(t *testing.T) { + rec := httptest.NewRecorder() + req := httptest.NewRequest("GET", "/test", nil) + + var sink *Sink + mux := http.NewServeMux() + mux.HandleFunc("/test", func(w http.ResponseWriter, r *http.Request) { + require.NotEqual(t, "", RequestID(r), "request should have request id") + + var ok bool + sink, ok = SinkFromContext(r.Context()) + require.True(t, ok, "SinkFromContext() returned false unexpectedly") + + Req(r).Info().Msg("this is a test message for the sink") + w.WriteHeader(201) + }) + Handler()(mux).ServeHTTP(rec, req) + + resp := rec.Result() + defer resp.Body.Close() + + require.Equal(t, 201, resp.StatusCode, "wrong status code") + + logs := sink.ToJSON() + + var result []interface{} + require.NoError(t, json.Unmarshal(logs, &result), "could not unmarshal logs") + + require.Len(t, result, 2, "expecting exactly two logs, but got: %v", logs) +} diff --git a/vendor/github.com/getsentry/raven-go/.dockerignore b/vendor/github.com/getsentry/raven-go/.dockerignore deleted file mode 100644 index 6b8710a7..00000000 --- a/vendor/github.com/getsentry/raven-go/.dockerignore +++ /dev/null @@ -1 +0,0 @@ -.git diff --git a/vendor/github.com/getsentry/raven-go/.gitignore b/vendor/github.com/getsentry/raven-go/.gitignore deleted file mode 100644 index 815a9756..00000000 --- a/vendor/github.com/getsentry/raven-go/.gitignore +++ /dev/null @@ -1,2 +0,0 @@ -*.test -example/example diff --git a/vendor/github.com/getsentry/raven-go/.gitmodules b/vendor/github.com/getsentry/raven-go/.gitmodules deleted file mode 100644 index e69de29b..00000000 diff --git a/vendor/github.com/getsentry/raven-go/.travis.yml b/vendor/github.com/getsentry/raven-go/.travis.yml deleted file mode 100644 index d771ab68..00000000 --- a/vendor/github.com/getsentry/raven-go/.travis.yml +++ /dev/null @@ -1,27 +0,0 @@ -sudo: false -language: go -go: - - "1.2" - - "1.3" - - 1.4.x - - 1.5.x - - 1.6.x - - 1.7.x - - 1.8.x - - 1.9.x - - 1.10.x - - tip - -before_install: - - go install -race std - - go get golang.org/x/tools/cmd/cover - - go get -v ./... - -script: - - go test -v -race ./... - - go test -v -cover ./... - -matrix: - allow_failures: - - go: "1.2" - - go: tip diff --git a/vendor/github.com/getsentry/raven-go/README.md b/vendor/github.com/getsentry/raven-go/README.md deleted file mode 100644 index 5ea29a0a..00000000 --- a/vendor/github.com/getsentry/raven-go/README.md +++ /dev/null @@ -1,13 +0,0 @@ -# raven [![Build Status](https://travis-ci.org/getsentry/raven-go.png?branch=master)](https://travis-ci.org/getsentry/raven-go) - -raven is a Go client for the [Sentry](https://github.com/getsentry/sentry) -event/error logging system. - -- [**API Documentation**](https://godoc.org/github.com/getsentry/raven-go) -- [**Usage and Examples**](https://docs.sentry.io/clients/go/) - -## Installation - -```text -go get github.com/getsentry/raven-go -``` diff --git a/vendor/github.com/getsentry/raven-go/runtests.sh b/vendor/github.com/getsentry/raven-go/runtests.sh deleted file mode 100644 index 9ed279c9..00000000 --- a/vendor/github.com/getsentry/raven-go/runtests.sh +++ /dev/null @@ -1,4 +0,0 @@ -#!/bin/bash -go test -race ./... -go test -cover ./... -go test -v ./... diff --git a/vendor/modules.txt b/vendor/modules.txt index c13e4d9a..4fcea6a0 100644 --- a/vendor/modules.txt +++ b/vendor/modules.txt @@ -15,8 +15,6 @@ github.com/davecgh/go-spew/spew # github.com/getkin/kin-openapi v0.0.0-20180813063848-e1956e8013e5 github.com/getkin/kin-openapi/jsoninfo github.com/getkin/kin-openapi/openapi3 -# github.com/getsentry/raven-go v0.0.0-20180903072508-084a9de9eb03 -github.com/getsentry/raven-go # github.com/ghodss/yaml v1.0.0 github.com/ghodss/yaml # github.com/go-pg/pg v6.14.5+incompatible