Merge pull request #200 from pace/improved-logging

Improved logging

go.mod

@@ -31,6 +31,7 @@ require (
 	github.com/prometheus/client_model v0.0.0-20180712105110-5c3871d89910 // indirect
 	github.com/prometheus/common v0.0.0-20180801064454-c7de2306084e // indirect
 	github.com/prometheus/procfs v0.0.0-20180725123919-05ee40e3a273 // indirect
+	github.com/rs/xid v1.2.1
 	github.com/rs/zerolog v1.17.2
 	github.com/shopspring/decimal v0.0.0-20200105231215-408a2507e114
 	github.com/sony/gobreaker v0.4.1

http/jsonapi/runtime/error.go

@@ -100,7 +100,7 @@ func WriteError(w http.ResponseWriter, code int, err error) {
 
 	// update the http status code of the error
 	errList.List.setHTTPStatus(code)
-	reqID := w.Header().Get("Request-ID")
+	reqID := w.Header().Get("Request-Id")
 	errList.List.setID(reqID)
 
 	// render the error to the client

http/transport/default_transport.go

@@ -6,5 +6,11 @@ package transport
 // NewDefaultTransportChain returns a transport chain with retry, jaeger and logging support.
 // If not explicitly finalized via `Final` it uses `http.DefaultTransport` as finalizer.
 func NewDefaultTransportChain() *RoundTripperChain {
-	return Chain(NewDefaultRetryRoundTripper(), &JaegerRoundTripper{}, &LoggingRoundTripper{}, &LocaleRoundTripper{})
+	return Chain(
+		NewDefaultRetryRoundTripper(),
+		&JaegerRoundTripper{},
+		&LoggingRoundTripper{},
+		&LocaleRoundTripper{},
+		&RequestIDRoundTripper{},
+	)
 }

http/transport/logging_round_tripper_test.go

@@ -6,7 +6,6 @@ package transport
 import (
 	"bytes"
 	"context"
-	"net/http"
 	"net/http/httptest"
 	"net/url"
 	"strings"
@@ -72,13 +71,3 @@ func TestLoggingRoundTripper(t *testing.T) {
 		}
 	})
 }
-
-type transportWithResponse struct {
-	statusCode int
-}
-
-func (t *transportWithResponse) RoundTrip(req *http.Request) (*http.Response, error) {
-	resp := &http.Response{StatusCode: t.statusCode}
-
-	return resp, nil
-}

http/transport/request_id.go

@@ -0,0 +1,35 @@
+// Copyright © 2020 by PACE Telematics GmbH. All rights reserved.
+// Created at 2020/05/18 by Vincent Landgraf
+
+package transport
+
+import (
+	"net/http"
+
+	"github.com/pace/bricks/maintenance/log"
+)
+
+// RequestIDRoundTripper implements a chainable round tripper for setting the Request-Source header
+type RequestIDRoundTripper struct {
+	transport  http.RoundTripper
+	SourceName string
+}
+
+// Transport returns the RoundTripper to make HTTP requests
+func (l *RequestIDRoundTripper) Transport() http.RoundTripper {
+	return l.transport
+}
+
+// SetTransport sets the RoundTripper to make HTTP requests
+func (l *RequestIDRoundTripper) SetTransport(rt http.RoundTripper) {
+	l.transport = rt
+}
+
+// RoundTrip executes a single HTTP transaction via Transport()
+func (l *RequestIDRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
+	ctx := req.Context()
+	if reqID := log.RequestIDFromContext(ctx); reqID != "" {
+		req.Header.Set("Request-Id", reqID)
+	}
+	return l.Transport().RoundTrip(req)
+}

http/transport/request_id_test.go

@@ -0,0 +1,53 @@
+// Copyright © 2020 by PACE Telematics GmbH. All rights reserved.
+// Created at 2020/05/18 by Vincent Landgraf
+
+package transport
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/gorilla/mux"
+	"github.com/pace/bricks/maintenance/log"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestRequestIDRoundTripper(t *testing.T) {
+	rt := RequestIDRoundTripper{}
+	rt.SetTransport(&transportWithResponse{})
+
+	t.Run("without req_id", func(t *testing.T) {
+		req := httptest.NewRequest("GET", "/foo", nil)
+		_, err := rt.RoundTrip(req)
+		assert.NoError(t, err)
+		assert.Empty(t, req.Header["Request-Id"])
+	})
+
+	t.Run("with req_id", func(t *testing.T) {
+		ID := "bqprir5mp1o6vaipufsg"
+
+		r := mux.NewRouter()
+		r.Use(log.Handler())
+		r.HandleFunc("/foo", func(w http.ResponseWriter, r *http.Request) {
+			require.Equal(t, []string{ID}, r.Header["Request-Id"])
+			require.Equal(t, ID, log.RequestID(r))
+			require.Equal(t, ID, log.RequestIDFromContext(r.Context()))
+
+			r1 := httptest.NewRequest("GET", "/foo", nil)
+			r1 = r1.WithContext(r.Context())
+
+			_, err := rt.RoundTrip(r1)
+			assert.NoError(t, err)
+			assert.Equal(t, []string{ID}, r1.Header["Request-Id"])
+			w.WriteHeader(http.StatusNoContent)
+		})
+
+		rec := httptest.NewRecorder()
+		req := httptest.NewRequest("GET", "/foo", nil)
+		req.Header.Set("Request-Id", ID)
+		r.ServeHTTP(rec, req)
+		assert.Equal(t, http.StatusNoContent, rec.Code)
+	})
+}

http/transport/transport_helper_test.go

@@ -0,0 +1,16 @@
+// Copyright © 2020 by PACE Telematics GmbH. All rights reserved.
+// Created at 2020/05/18 by Vincent Landgraf
+
+package transport
+
+import "net/http"
+
+type transportWithResponse struct {
+	statusCode int
+}
+
+func (t *transportWithResponse) RoundTrip(req *http.Request) (*http.Response, error) {
+	resp := &http.Response{StatusCode: t.statusCode}
+
+	return resp, nil
+}

maintenance/log/handler.go

@@ -4,16 +4,22 @@
 package log
 
 import (
+	"errors"
 	"net"
 	"net/http"
 	"strings"
 	"time"
 
+	"github.com/pace/bricks/maintenance/log/hlog"
 	"github.com/pace/bricks/maintenance/tracing/wire"
-	"github.com/rs/zerolog/hlog"
+	"github.com/rs/xid"
+	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 )
 
+// RequestIDHeader name of the header that can contain a request ID
+const RequestIDHeader = "Request-Id"
+
 // Handler returns a middleware that handles all of the logging aspects of
 // any incoming http request. Optionally several path prefixes like "/health"
 // can be provided to decrease log spamming. All url paths with these
@@ -24,7 +30,7 @@ func Handler(silentPrefixes ...string) func(http.Handler) http.Handler {
 		return hlog.NewHandler(log.Logger)(
 			handlerWithSink(silentPrefixes...)(
 				hlog.AccessHandler(requestCompleted)(
-					hlog.RequestIDHandler("req_id", "Request-Id")(next))))
+					RequestIDHandler("req_id", RequestIDHeader)(next))))
 	}
 }
 
@@ -78,3 +84,46 @@ func ProxyAwareRemote(r *http.Request) string {
 	}
 	return host
 }
+
+var noXid = errors.New("no xid")
+
+func RequestIDHandler(fieldKey, headerName string) func(next http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			ctx := r.Context()
+			var id xid.ID
+			var err error
+
+			// try extract of xid from header
+			reqID := r.Header.Get(headerName)
+			if reqID != "" {
+				id, err = xid.FromString(reqID)
+			} else {
+				err = noXid
+			}
+
+			// try extract of xid context
+			if err != nil {
+				nid, ok := hlog.IDFromCtx(ctx)
+				if !ok {
+					// give up, generate a new xid
+					id = xid.New()
+				}
+				id = nid
+			}
+
+			ctx = hlog.WithValue(ctx, id)
+			r = r.WithContext(ctx)
+
+			// log requests with request id
+			log := zerolog.Ctx(ctx)
+			log.UpdateContext(func(c zerolog.Context) zerolog.Context {
+				return c.Str(fieldKey, id.String())
+			})
+
+			// return the request id as a header to the client
+			w.Header().Set(headerName, id.String())
+			next.ServeHTTP(w, r)
+		})
+	}
+}

vendor/github.com/rs/zerolog/hlog/hlog.go → maintenance/log/hlog/hlog.go

@@ -1,4 +1,5 @@
 // Package hlog provides a set of http.Handler helpers for zerolog.
+// ## COPY of zero log helpers to get access to context values ##
 package hlog
 
 import (
@@ -198,3 +199,7 @@ func AccessHandler(f func(r *http.Request, status, size int, duration time.Durat
 		})
 	}
 }
+
+func WithValue(ctx context.Context, reqID xid.ID) context.Context {
+	return context.WithValue(ctx, idKey{}, reqID)
+}

maintenance/log/log.go

@@ -13,7 +13,7 @@ import (
 	"time"
 
 	"github.com/caarlos0/env"
-	"github.com/rs/zerolog/hlog"
+	"github.com/pace/bricks/maintenance/log/hlog"
 
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
@@ -91,13 +91,12 @@ func RequestID(r *http.Request) string {
 
 // RequestIDFromContext returns a unique request id or an empty string if there is none
 func RequestIDFromContext(ctx context.Context) string {
-	// create dummy request to get the request id
-	r, err := http.NewRequest("GET", "", nil)
-	if err != nil {
-		panic(err)
+	id, ok := hlog.IDFromCtx(ctx)
+	if ok {
+		return id.String()
 	}
 
-	return RequestID(r.WithContext(ctx))
+	return ""
 }
 
 // Req returns the logger for the passed request

maintenance/tracing/tracing.go

@@ -64,7 +64,7 @@ func (h *traceHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	}
 	ww := mutil.WrapWriter(w)
 	h.next.ServeHTTP(ww, r.WithContext(ctx))
-	handlerSpan.LogFields(olog.Int("bytes", ww.BytesWritten()), olog.Int("status", ww.Status()))
+	handlerSpan.LogFields(olog.Int("bytes", ww.BytesWritten()), olog.Int("status_code", ww.Status()))
 	handlerSpan.Finish()
 }
 

vendor/modules.txt

@@ -116,11 +116,11 @@ github.com/prometheus/procfs/internal/util
 github.com/prometheus/procfs/nfs
 github.com/prometheus/procfs/xfs
 # github.com/rs/xid v1.2.1
+## explicit
 github.com/rs/xid
 # github.com/rs/zerolog v1.17.2
 ## explicit
 github.com/rs/zerolog
-github.com/rs/zerolog/hlog
 github.com/rs/zerolog/internal/cbor
 github.com/rs/zerolog/internal/json
 github.com/rs/zerolog/log