Improved logging and error reporting (#1349)

* Log unhandled GraphQL errors

We already log GraphQL responses, but some errors (e.g. validating the GraphQL request) happen before a response can be generated, and we weren't seeing those errors.

* Add the trace ID to log messages

* Add additional context to gin logs via logrus

graphql/resolver/handlers.go

@@ -436,6 +436,13 @@ func RequestReporter(schema *ast.Schema, log bool, trace bool) func(ctx context.
 	}
 }
 
+func ErrorLogger(ctx context.Context, e error) *gqlerror.Error {
+	err := gqlgen.DefaultErrorPresenter(ctx, e)
+	logger.For(ctx).WithError(err).Warnf("GraphQL error: %s", err.Error())
+
+	return err
+}
+
 // Sentry will drop events if they contain too much data. It's convenient to attach our GraphQL
 // requests and responses to Sentry events, but we don't want to risk dropping events, so we limit
 // the size to something small (like 8kB). Larger payloads should still be logged and available

middleware/middleware.go

@@ -241,6 +241,12 @@ func Tracing() gin.HandlerFunc {
 			sentry.ContinueFromRequest(c.Request),
 		)
 
+		ctx = logger.NewContextWithFields(ctx, logrus.Fields{
+			// Call it "trace" so GCP logging will recognize it as the trace ID
+			// See: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry
+			"trace": span.TraceID,
+		})
+
 		if c.Request.Method == "OPTIONS" {
 			// Don't sample OPTIONS requests; there's nothing to trace and they eat up our Sentry quota.
 			// Using a sampling decision here (instead of simply omitting the span) ensures that any

server/handler.go

@@ -116,6 +116,7 @@ func graphqlHandler(repos *postgres.Repositories, queries *db.Queries, httpClien
 	h.AroundOperations(graphql.RequestReporter(schema.Schema(), enableLogging, true))
 	h.AroundResponses(graphql.ResponseReporter(enableLogging, true))
 	h.AroundFields(graphql.FieldReporter(true))
+	h.SetErrorPresenter(graphql.ErrorLogger)
 
 	// Should happen after FieldReporter, so Sentry trace context is set up prior to error reporting
 	h.AroundFields(graphql.RemapAndReportErrors)

server/server.go

@@ -116,7 +116,8 @@ func CoreInit(ctx context.Context, c *Clients, provider *multichain.Provider, re
 		logrus.SetLevel(logrus.DebugLevel)
 	}
 
-	router := gin.Default()
+	router := gin.New()
+	router.Use(gin.LoggerWithFormatter(logger.GinFormatter()), gin.Recovery())
 	router.Use(middleware.Sentry(true), middleware.Tracing(), middleware.HandleCORS(), middleware.GinContextToContext(), middleware.ErrLogger())
 
 	if v, ok := binding.Validator.Engine().(*validator.Validate); ok {

service/logger/logger.go

@@ -3,6 +3,7 @@ package logger
 import (
 	"context"
 	"fmt"
+	"net/http"
 	"runtime"
 	"time"
 
@@ -136,3 +137,80 @@ func (e LoggedError) Error() string {
 
 	return msg
 }
+
+// GinFormatter returns a gin.LogFormatter that includes additional context via logrus
+func GinFormatter() gin.LogFormatter {
+	// Wrapping gin logs with logrus is noisy in a local development console, so only do it for
+	// cloud logs (which will handle JSON logs gracefully)
+	wrapWithLogrus := true
+	if viper.GetString("ENV") == "local" {
+		//wrapWithLogrus = false
+	}
+
+	return func(param gin.LogFormatterParams) string {
+		// Gin's default logger, copy/pasted from gin/logger.go
+		defaultLogFormatter := func(param gin.LogFormatterParams) string {
+			var statusColor, methodColor, resetColor string
+			if param.IsOutputColor() {
+				statusColor = param.StatusCodeColor()
+				methodColor = param.MethodColor()
+				resetColor = param.ResetColor()
+			}
+
+			if param.Latency > time.Minute {
+				param.Latency = param.Latency.Truncate(time.Second)
+			}
+			return fmt.Sprintf("[GIN] %v |%s %3d %s| %13v | %15s |%s %-7s %s %#v\n%s",
+				param.TimeStamp.Format("2006/01/02 - 15:04:05"),
+				statusColor, param.StatusCode, resetColor,
+				param.Latency,
+				param.ClientIP,
+				methodColor, param.Method, resetColor,
+				param.Path,
+				param.ErrorMessage,
+			)
+		}
+
+		// Custom handling to output gin's log statements with extra context via logrus
+		str := defaultLogFormatter(param)
+		if wrapWithLogrus && param.Request.Context() != nil {
+			logEntry := For(param.Request.Context())
+
+			// Fill in known httpRequest fields for GCP.
+			// See: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#HttpRequest
+			logEntry = logEntry.WithFields(logrus.Fields{
+				"httpRequest": map[string]interface{}{
+					"requestMethod": param.Method,
+					"requestUrl":    param.Request.URL,
+					"status":        param.StatusCode,
+					"responseSize":  param.BodySize,
+					"latency":       param.Latency,
+					"remoteIp":      param.ClientIP,
+					"userAgent":     param.Request.UserAgent(),
+					"protocol":      param.Request.Proto,
+					"referer":       param.Request.Referer(),
+				},
+			})
+
+			if logEntry.Time.IsZero() {
+				logEntry.Time = time.Now()
+			}
+
+			if param.StatusCode >= http.StatusOK && param.StatusCode < http.StatusMultipleChoices {
+				logEntry.Level = logrus.InfoLevel
+			} else {
+				logEntry.Level = logrus.WarnLevel
+			}
+
+			logEntry.Message = str
+
+			// Use the logrus logEntry to format the output, and then return the string back to gin
+			// so it can write the message
+			if output, err := logEntry.String(); err == nil {
+				return output
+			}
+		}
+
+		return str
+	}
+}