Merge branch 'correlation-id' into 'master'

Log using correlation-id bound to the incoming request

See merge request gitlab-org/gitlab-workhorse!258

internal/artifacts/entry.go

@@ -12,9 +12,8 @@ import (
 	"strings"
 	"syscall"
 
-	log "github.com/sirupsen/logrus"
-
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/zipartifacts"
 )
@@ -32,7 +31,7 @@ func (e *entry) Inject(w http.ResponseWriter, r *http.Request, sendData string)
 		return
 	}
 
-	log.WithFields(log.Fields{
+	log.WithFields(r.Context(), log.Fields{
 		"entry":   params.Entry,
 		"archive": params.Archive,
 		"path":    r.URL.Path,

internal/git/blob.go

@@ -6,10 +6,9 @@ import (
 	"net/http"
 	"strings"
 
-	log "github.com/sirupsen/logrus"
-
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
@@ -51,7 +50,7 @@ func handleSendBlobWithGitaly(w http.ResponseWriter, r *http.Request, params *bl
 }
 
 func handleSendBlobLocally(w http.ResponseWriter, r *http.Request, params *blobParams) {
-	log.WithFields(log.Fields{
+	log.WithFields(r.Context(), log.Fields{
 		"blobId": params.BlobId,
 		"path":   r.URL.Path,
 	}).Print("SendBlob: sending")

internal/git/diff.go

@@ -5,10 +5,9 @@ import (
 	"io"
 	"net/http"
 
-	log "github.com/sirupsen/logrus"
-
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
@@ -61,7 +60,7 @@ func handleSendDiffWithGitaly(w http.ResponseWriter, r *http.Request, params *di
 }
 
 func handleSendDiffLocally(w http.ResponseWriter, r *http.Request, params *diffParams) {
-	log.WithFields(log.Fields{
+	log.WithFields(r.Context(), log.Fields{
 		"shaFrom": params.ShaFrom,
 		"shaTo":   params.ShaTo,
 		"path":    r.URL.Path,

internal/git/format-patch.go

@@ -5,10 +5,9 @@ import (
 	"io"
 	"net/http"
 
-	log "github.com/sirupsen/logrus"
-
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/gitaly"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 
 	pb "gitlab.com/gitlab-org/gitaly-proto/go"
@@ -60,7 +59,7 @@ func handleSendPatchWithGitaly(w http.ResponseWriter, r *http.Request, params *p
 }
 
 func handleSendPatchLocally(w http.ResponseWriter, r *http.Request, params *patchParams) {
-	log.WithFields(log.Fields{
+	log.WithFields(r.Context(), log.Fields{
 		"shaFrom": params.ShaFrom,
 		"shaTo":   params.ShaTo,
 		"path":    r.URL.Path,

internal/helper/helpers.go

@@ -14,7 +14,7 @@ import (
 	"strings"
 	"syscall"
 
-	log "github.com/sirupsen/logrus"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 )
 
 const NginxResponseBufferHeader = "X-Accel-Buffering"
@@ -46,12 +46,12 @@ func RequestEntityTooLarge(w http.ResponseWriter, r *http.Request, err error) {
 
 func printError(r *http.Request, err error) {
 	if r != nil {
-		log.WithFields(log.Fields{
+		log.WithFields(r.Context(), log.Fields{
 			"method": r.Method,
 			"uri":    ScrubURLParams(r.RequestURI),
 		}).WithError(err).Error("error")
 	} else {
-		log.WithError(err).Error("unknown error")
+		log.NoContext().WithError(err).Error("unknown error")
 	}
 }
 
@@ -94,7 +94,7 @@ func OpenFile(path string) (file *os.File, fi os.FileInfo, err error) {
 func URLMustParse(s string) *url.URL {
 	u, err := url.Parse(s)
 	if err != nil {
-		log.WithField("url", s).WithError(err).Fatal("urlMustParse")
+		log.NoContext().WithField("url", s).WithError(err).Fatal("urlMustParse")
 	}
 	return u
 }

internal/helper/logging.go

@@ -9,6 +9,8 @@ import (
 
 	"github.com/prometheus/client_golang/prometheus"
 	log "github.com/sirupsen/logrus"
+
+	logging "gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 )
 
 var (
@@ -110,7 +112,8 @@ func (l *statsCollectingResponseWriter) writeAccessLog(r *http.Request) {
 		return
 	}
 
-	accessLogEntry.WithFields(l.accessLogFields(r)).Info("access")
+	logEntry := accessLogEntry.WithFields(l.accessLogFields(r))
+	logging.WrapEntry(r.Context(), logEntry).Info("access")
 }
 
 func (l *statsCollectingResponseWriter) accessLogFields(r *http.Request) log.Fields {

internal/log/base62_test.go

+package log
+
+import (
+	"fmt"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+func TestReverseBase62Conversion(t *testing.T) {
+	tests := []struct {
+		n        int64
+		expected string
+	}{
+		{n: 0, expected: "0"},
+		{n: 5, expected: "5"},
+		{n: 10, expected: "a"},
+		{n: 62, expected: "01"},
+		{n: 620, expected: "0a"},
+		{n: 6200, expected: "0C1"},
+	}
+
+	for _, test := range tests {
+		t.Run(fmt.Sprintf("%d_to_%s", test.n, test.expected), func(t *testing.T) {
+			assert.Equal(t, test.expected, encodeReverseBase62(test.n))
+		})
+	}
+}

internal/log/handler.go

+package log
+
+import (
+	"bytes"
+	"context"
+	"crypto/rand"
+	"fmt"
+	"math"
+	"math/big"
+	"net/http"
+	"time"
+)
+
+type ctxKey string
+
+const (
+	// KeyCorrelationID const is the context key for Correlation ID
+	KeyCorrelationID ctxKey = "X-Correlation-ID"
+
+	base62Chars string = "0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ"
+)
+
+var (
+	randMax    = big.NewInt(math.MaxInt64)
+	randSource = rand.Reader
+)
+
+func InjectCorrelationID(h http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		parent := r.Context()
+		correlationID, err := generateRandomCorrelationID()
+		if err != nil {
+			correlationID = fmt.Sprintf("E:%s:%s", r.RemoteAddr, encodeReverseBase62(time.Now().UnixNano()))
+			NoContext().WithError(err).Warning("Can't generate random correlation-id")
+		}
+
+		ctx := context.WithValue(parent, KeyCorrelationID, correlationID)
+		h.ServeHTTP(w, r.WithContext(ctx))
+	})
+}
+
+func generateRandomCorrelationID() (string, error) {
+	id, err := rand.Int(randSource, randMax)
+	if err != nil {
+		return "", err
+	}
+	base62 := encodeReverseBase62(id.Int64())
+
+	return base62, nil
+}
+
+// encodeReverseBase62 encodes num into its Base62 reversed representation.
+// The most significant value is at the end of the string.
+//
+// Appending is faster than prepending and this is enough for the purpose of a random ID
+func encodeReverseBase62(num int64) string {
+	if num == 0 {
+		return "0"
+	}
+
+	encoded := bytes.Buffer{}
+	for q := num; q > 0; q /= 62 {
+		encoded.Write([]byte{base62Chars[q%62]})
+	}
+
+	return encoded.String()
+}

internal/log/handler_test.go

+package log
+
+import (
+	"bytes"
+	"crypto/rand"
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestInjectCorrelationID(t *testing.T) {
+	tests := []struct {
+		name       string
+		randSource io.Reader
+	}{
+		{name: "Entropy Available", randSource: rand.Reader},
+		{name: "No Entropy", randSource: &bytes.Buffer{}},
+	}
+
+	defer func() {
+		randSource = rand.Reader
+	}()
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			invoked := false
+			randSource = test.randSource
+
+			h := InjectCorrelationID(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
+				invoked = true
+
+				ctx := r.Context()
+				correlationID := ctx.Value(KeyCorrelationID)
+				require.NotNil(t, correlationID, "CorrelationID is missing")
+				require.NotEmpty(t, correlationID, "CorrelationID is missing")
+			}))
+
+			r := httptest.NewRequest("GET", "http://example.com", nil)
+			h.ServeHTTP(nil, r)
+
+			assert.True(t, invoked, "handler not executed")
+		})
+	}
+}

internal/log/logrus.go

+package log
+
+import (
+	"context"
+
+	"github.com/sirupsen/logrus"
+)
+
+// Fields type, an helper to avoid importing logrus.Fields
+type Fields map[string]interface{}
+
+func toLogrusFields(f Fields) logrus.Fields {
+	lFields := logrus.Fields{}
+	for k, v := range f {
+		lFields[k] = v
+	}
+
+	return lFields
+}
+
+func getCorrelationID(ctx context.Context) string {
+	noID := "[MISSING]"
+	if ctx == nil {
+		return noID
+	}
+
+	id := ctx.Value(KeyCorrelationID)
+
+	str, ok := id.(string)
+	if !ok {
+		return noID
+	}
+
+	return str
+}
+
+// WithContext provides a *logrus.Entry with the proper "correlation-id" field.
+//
+// "[MISSING]" will be used when ctx has no value for KeyCorrelationID
+func WithContext(ctx context.Context) *logrus.Entry {
+	return logrus.WithField("correlation-id", getCorrelationID(ctx))
+}
+
+// NoContext provides logrus.StandardLogger()
+func NoContext() *logrus.Logger {
+	return logrus.StandardLogger()
+}
+
+// WrapEntry adds the proper "correlation-id" field to the provided *logrus.Entry
+func WrapEntry(ctx context.Context, e *logrus.Entry) *logrus.Entry {
+	return e.WithField("correlation-id", getCorrelationID(ctx))
+}
+
+// WithFields decorates logrus.WithFields with the proper "correlation-id"
+func WithFields(ctx context.Context, f Fields) *logrus.Entry {
+	return WithContext(ctx).WithFields(toLogrusFields(f))
+}
+
+// WithField decorates logrus.WithField with the proper "correlation-id"
+func WithField(ctx context.Context, key string, value interface{}) *logrus.Entry {
+	return WithContext(ctx).WithField(key, value)
+}
+
+// WithError decorates logrus.WithError with the proper "correlation-id"
+func WithError(ctx context.Context, err error) *logrus.Entry {
+	return WithContext(ctx).WithError(err)
+}

internal/log/logrus_test.go

+package log_test
+
+import (
+	"context"
+	"errors"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/require"
+
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
+)
+
+func requireCorrelationID(t *testing.T, getEntry func(ctx context.Context) *logrus.Entry) *logrus.Entry {
+	id := "test-id"
+	ctx := context.WithValue(context.Background(), log.KeyCorrelationID, id)
+
+	e := getEntry(ctx)
+
+	require.NotNil(t, e)
+	require.Contains(t, e.Data, "correlation-id")
+	require.Equal(t, id, e.Data["correlation-id"])
+
+	return e
+}
+
+func TestWithContext(t *testing.T) {
+	e := requireCorrelationID(t, log.WithContext)
+	require.Len(t, e.Data, 1)
+}
+
+func TestWithFields(t *testing.T) {
+	fields := log.Fields{
+		"one": "ok",
+		"two": 2,
+	}
+
+	toTest := func(ctx context.Context) *logrus.Entry {
+		return log.WithFields(ctx, fields)
+	}
+
+	e := requireCorrelationID(t, toTest)
+
+	for key, value := range fields {
+		require.Contains(t, e.Data, key)
+		require.Equal(t, value, e.Data[key])
+	}
+	require.Len(t, e.Data, len(fields)+1)
+}
+
+func TestWithField(t *testing.T) {
+	key := "key"
+	value := struct{ Name string }{"Test"}
+	toTest := func(ctx context.Context) *logrus.Entry {
+		return log.WithField(ctx, key, value)
+	}
+
+	e := requireCorrelationID(t, toTest)
+
+	require.Contains(t, e.Data, key)
+	require.Equal(t, value, e.Data[key])
+	require.Len(t, e.Data, 2)
+}
+
+func TestWithError(t *testing.T) {
+	err := errors.New("An error")
+	toTest := func(ctx context.Context) *logrus.Entry {
+		return log.WithError(ctx, err)
+	}
+
+	e := requireCorrelationID(t, toTest)
+
+	require.Contains(t, e.Data, logrus.ErrorKey)
+	require.Equal(t, err, e.Data[logrus.ErrorKey])
+	require.Len(t, e.Data, 2)
+}
+
+func TestNoContext(t *testing.T) {
+	key := "key"
+	value := struct{ Name string }{"Test"}
+
+	logger := log.NoContext()
+	require.Equal(t, logrus.StandardLogger(), logger)
+
+	e := logger.WithField(key, value)
+	require.NotContains(t, e.Data, "correlation-id")
+
+	require.Contains(t, e.Data, key)
+	require.Equal(t, value, e.Data[key])
+	require.Len(t, e.Data, 1)
+}

internal/sendfile/sendfile.go

@@ -10,11 +10,10 @@ import (
 	"net/http"
 	"regexp"
 
-	log "github.com/sirupsen/logrus"
-
 	"github.com/prometheus/client_golang/prometheus"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 )
 
 const sendFileResponseHeader = "X-Sendfile"
@@ -105,7 +104,7 @@ func (s *sendFileResponseWriter) WriteHeader(status int) {
 }
 
 func sendFileFromDisk(w http.ResponseWriter, r *http.Request, file string) {
-	log.WithFields(log.Fields{
+	log.WithFields(r.Context(), log.Fields{
 		"file":   file,
 		"method": r.Method,
 		"uri":    helper.ScrubURLParams(r.RequestURI),

internal/sendurl/sendurl.go

@@ -7,11 +7,10 @@ import (
 	"net/http"
 	"time"
 
-	log "github.com/sirupsen/logrus"
-
 	"github.com/prometheus/client_golang/prometheus"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/senddata"
 )
 
@@ -98,7 +97,7 @@ func (e *entry) Inject(w http.ResponseWriter, r *http.Request, sendData string)
 		return
 	}
 
-	log.WithFields(log.Fields{
+	log.WithFields(r.Context(), log.Fields{
 		"url":  helper.ScrubURLParams(params.URL),
 		"path": r.URL.Path,
 	}).Print("SendURL: sending")

internal/staticpages/servefile.go

@@ -7,9 +7,8 @@ import (
 	"strings"
 	"time"
 
-	log "github.com/sirupsen/logrus"
-
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/urlprefix"
 )
 
@@ -71,7 +70,7 @@ func (s *Static) ServeExisting(prefix urlprefix.Prefix, cache CacheMode, notFoun
 			w.Header().Set("Expires", cacheUntil)
 		}
 
-		log.WithFields(log.Fields{
+		log.WithFields(r.Context(), log.Fields{
 			"file":     file,
 			"encoding": w.Header().Get("Content-Encoding"),
 			"method":   r.Method,

internal/terminal/terminal.go

@@ -6,12 +6,11 @@ import (
 	"net/http"
 	"time"
 
-	log "github.com/sirupsen/logrus"
-
 	"github.com/gorilla/websocket"
 
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/api"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/helper"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 )
 
 var (
@@ -47,7 +46,7 @@ func ProxyTerminal(w http.ResponseWriter, r *http.Request, terminal *api.Termina
 	server, err := connectToServer(terminal, r)
 	if err != nil {
 		helper.Fail500(w, r, err)
-		log.WithError(err).Print("Terminal: connecting to server failed")
+		log.WithError(r.Context(), err).Print("Terminal: connecting to server failed")
 		return
 	}
 	defer server.UnderlyingConn().Close()
@@ -55,7 +54,7 @@ func ProxyTerminal(w http.ResponseWriter, r *http.Request, terminal *api.Termina
 
 	client, err := upgradeClient(w, r)
 	if err != nil {
-		log.WithError(err).Print("Terminal: upgrading client to websocket failed")
+		log.WithError(r.Context(), err).Print("Terminal: upgrading client to websocket failed")
 		return
 	}
 
@@ -66,7 +65,7 @@ func ProxyTerminal(w http.ResponseWriter, r *http.Request, terminal *api.Termina
 	defer client.UnderlyingConn().Close()
 	clientAddr := getClientAddr(r) // We can't know the port with confidence
 
-	logEntry := log.WithFields(log.Fields{
+	logEntry := log.WithFields(r.Context(), log.Fields{
 		"clientAddr": clientAddr,
 		"serverAddr": serverAddr,
 	})

main.go

@@ -23,9 +23,8 @@ import (
 	"syscall"
 	"time"
 
-	log "github.com/sirupsen/logrus"
-
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/config"
+	"gitlab.com/gitlab-org/gitlab-workhorse/internal/log"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/queueing"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/redis"
 	"gitlab.com/gitlab-org/gitlab-workhorse/internal/secret"
@@ -78,18 +77,19 @@ func main() {
 	}
 
 	startLogging(logConfig)
+	logger := log.NoContext()
 
 	backendURL, err := parseAuthBackend(*authBackend)
 	if err != nil {
-		log.WithError(err).Fatal("invalid authBackend")
+		logger.WithError(err).Fatal("invalid authBackend")
 	}
 
-	log.WithField("version", version).Print("Starting")
+	logger.WithField("version", version).Print("Starting")
 
 	// Good housekeeping for Unix sockets: unlink before binding
 	if *listenNetwork == "unix" {
 		if err := os.Remove(*listenAddr); err != nil && !os.IsNotExist(err) {
-			log.Fatal(err)
+			logger.Fatal(err)
 		}
 	}
 
@@ -98,7 +98,7 @@ func main() {
 	listener, err := net.Listen(*listenNetwork, *listenAddr)
 	syscall.Umask(oldUmask)
 	if err != nil {
-		log.Fatal(err)
+		logger.Fatal(err)
 	}
 
 	// The profiler will only be activated by HTTP requests. HTTP
@@ -107,7 +107,7 @@ func main() {
 	// effectively disabled by default.
 	if *pprofListenAddr != "" {
 		go func() {
-			log.Print(http.ListenAndServe(*pprofListenAddr, nil))
+			logger.Print(http.ListenAndServe(*pprofListenAddr, nil))
 		}()
 	}
 
@@ -115,7 +115,7 @@ func main() {
 		promMux := http.NewServeMux()
 		promMux.Handle("/metrics", promhttp.Handler())
 		go func() {
-			log.Print(http.ListenAndServe(*prometheusListenAddr, promMux))
+			logger.Print(http.ListenAndServe(*prometheusListenAddr, promMux))
 		}()
 	}
 
@@ -136,7 +136,7 @@ func main() {
 	if *configFile != "" {
 		cfgFromFile, err := config.LoadConfig(*configFile)
 		if err != nil {
-			log.WithField("configFile", *configFile).WithError(err).Fatal("Can not load config file")
+			logger.WithField("configFile", *configFile).WithError(err).Fatal("Can not load config file")
 		}
 
 		cfg.Redis = cfgFromFile.Redis
@@ -147,7 +147,7 @@ func main() {
 		}
 	}
 
-	up := wrapRaven(upstream.NewUpstream(cfg))
+	up := wrapRaven(log.InjectCorrelationID(upstream.NewUpstream(cfg)))
 
-	log.Fatal(http.Serve(listener, up))
+	logger.Fatal(http.Serve(listener, up))
 }