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

@@ -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 {

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()))

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

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=

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

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
 }

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)

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
+	}
+}