Merge branch 'kkloss-workhorse-expose-correlation-id-overload' into 'master'

Expose correlation ID in overloaded message

See merge request https://gitlab.com/gitlab-org/gitlab/-/merge_requests/182908



Merged-by: Ash McKenzie <amckenzie@gitlab.com>
Approved-by: Jaime Martinez <jmartinez@gitlab.com>
Approved-by: Igor <iwiedler@gitlab.com>
Approved-by: Mustafa Bayar <mbayar@gitlab.com>
Approved-by: Ash McKenzie <amckenzie@gitlab.com>
Reviewed-by: Ash McKenzie <amckenzie@gitlab.com>
Reviewed-by: Jaime Martinez <jmartinez@gitlab.com>
Co-authored-by: Kev Kloss <kkloss@gitlab.com>

workhorse/_support/lint_last_known_acceptable.txt

@@ -13,9 +13,8 @@ internal/git/archive.go:67: Function 'Inject' has too many statements (55 > 40)
 internal/git/blob.go:21:5: exported: exported var SendBlob should have comment or be unexported (revive)
 internal/git/diff.go:1: 1-47 lines are duplicate of `internal/git/format-patch.go:1-48` (dupl)
 internal/git/diff.go:22:5: exported: exported var SendDiff should have comment or be unexported (revive)
-internal/git/error.go:36:4: singleCaseSwitch: should rewrite switch statement to if statement (gocritic)
-internal/git/error_test.go:28: File is not `gofmt`-ed with `-s` (gofmt)
-internal/git/error_test.go:66:2: unnecessary trailing newline (whitespace)
+internal/git/error.go:29:45: context-as-argument: context.Context should be the first parameter of a function (revive)
+internal/git/error.go:38:4: singleCaseSwitch: should rewrite switch statement to if statement (gocritic)
 internal/git/format-patch.go:1: 1-48 lines are duplicate of `internal/git/diff.go:1-47` (dupl)
 internal/git/format-patch.go:22:5: exported: exported var SendPatch should have comment or be unexported (revive)
 internal/git/git-http.go:21:2: exported: comment on exported const GitConfigShowAllRefs should be of the form "GitConfigShowAllRefs ..." (revive)

workhorse/internal/git/error.go

 package git
 
 import (
+	"context"
 	"errors"
 	"fmt"
 	"io"
 
 	"gitlab.com/gitlab-org/gitaly/v16/proto/go/gitalypb"
+	"gitlab.com/gitlab-org/labkit/correlation"
 	"google.golang.org/grpc/status"
 
 	"gitlab.com/gitlab-org/gitlab/workhorse/internal/log"
@@ -24,7 +26,7 @@ type copyError struct{ error }
 // LimitError. A LimitError is returned by Gitaly when it is at its limit in
 // handling requests. Since this is a known error, we should print a sensible
 // error message to the end user.
-func handleLimitErr(err error, w io.Writer, f func(w io.Writer) error) {
+func handleLimitErr(err error, w io.Writer, c context.Context, f func(w io.Writer, correlationID string) error) {
 	var statusErr grpcErr
 	if !errors.As(err, &statusErr) {
 		return
@@ -35,7 +37,7 @@ func handleLimitErr(err error, w io.Writer, f func(w io.Writer) error) {
 		for _, detail := range details {
 			switch detail.(type) {
 			case *gitalypb.LimitError:
-				if err := f(w); err != nil {
+				if err := f(w, correlation.ExtractFromContext(c)); err != nil {
 					log.WithError(fmt.Errorf("handling limit error: %w", err))
 				}
 			}
@@ -54,7 +56,7 @@ func handleLimitErr(err error, w io.Writer, f func(w io.Writer) error) {
 // information through the side-band 2 channel.
 // See https://gitlab.com/gitlab-org/gitaly/-/tree/jc-return-structured-error-limits
 // for more details.
-func writeReceivePackError(w io.Writer) error {
+func writeReceivePackError(w io.Writer, correlationID string) error {
 	if _, err := fmt.Fprintf(w, "%04x", 35); err != nil {
 		return err
 	}
@@ -71,15 +73,10 @@ func writeReceivePackError(w io.Writer) error {
 		return err
 	}
 
-	if _, err := fmt.Fprintf(w, "%04x", 68); err != nil {
-		return err
-	}
-
-	if _, err := w.Write([]byte{0x2}); err != nil {
-		return err
-	}
+	correlationID = truncateCorrelationID(correlationID)
+	msg := fmt.Sprintf("\x02GitLab is currently unable to handle this request due to load (ID %s).\n", correlationID)
 
-	if _, err := fmt.Fprint(w, "GitLab is currently unable to handle this request due to load.\n"); err != nil {
+	if err := writeMessage(w, msg); err != nil {
 		return err
 	}
 
@@ -94,7 +91,27 @@ func writeReceivePackError(w io.Writer) error {
 // understands and prints to stdout. UploadPack expects to receive pack data in
 // PKT-LINE format. An error-line can be passed that begins with ERR.
 // See https://git-scm.com/docs/pack-protocol/2.29.0#_pkt_line_format.
-func writeUploadPackError(w io.Writer) error {
-	_, err := fmt.Fprintf(w, "%04xERR GitLab is currently unable to handle this request due to load.\n", 71)
+func writeUploadPackError(w io.Writer, correlationID string) error {
+	correlationID = truncateCorrelationID(correlationID)
+	msg := fmt.Sprintf("ERR GitLab is currently unable to handle this request due to load (ID %s).\n", correlationID)
+	return writeMessage(w, msg)
+}
+
+func truncateCorrelationID(correlationID string) string {
+	// We often use ULIDs (Universally Unique Lexicographically Sortable Identifiers,
+	// see https://github.com/oklog/ulid) that are encoded to 26 chars but some
+	// correlation IDs may be 32 characters. To be future proof, we’re limiting this
+	// to more than that because e.g. a UUID is 36 characters already.
+	const maxCorrelationIDLen = 48
+
+	if len(correlationID) > maxCorrelationIDLen {
+		correlationID = correlationID[:maxCorrelationIDLen] + " (truncated)"
+	}
+
+	return correlationID
+}
+
+func writeMessage(w io.Writer, msg string) error {
+	_, err := fmt.Fprintf(w, "%04x%s", len(msg)+4, msg)
 	return err
 }

workhorse/internal/git/error_test.go

@@ -2,12 +2,14 @@ package git
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"io"
 	"testing"
 
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v16/proto/go/gitalypb"
+	"gitlab.com/gitlab-org/labkit/correlation"
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/status"
 	"google.golang.org/protobuf/proto"
@@ -16,17 +18,19 @@ import (
 )
 
 func TestHandleLimitErr(t *testing.T) {
+	const expectedCorrelationID = "abcdef01234"
+
 	testCases := []struct {
 		desc          string
-		errWriter     func(io.Writer) error
+		errWriter     func(io.Writer, string) error
 		expectedBytes []byte
 	}{
 		{
 			desc:      "upload pack",
 			errWriter: writeUploadPackError,
 			expectedBytes: bytes.Join([][]byte{
-				[]byte{'0', '0', '4', '7'},
-				[]byte("ERR GitLab is currently unable to handle this request due to load.\n"),
+				{'0', '0', '5', '8'},
+				[]byte("ERR GitLab is currently unable to handle this request due to load (ID abcdef01234).\n"),
 			}, []byte{}),
 		},
 		{
@@ -35,13 +39,15 @@ func TestHandleLimitErr(t *testing.T) {
 			expectedBytes: bytes.Join([][]byte{
 				{'0', '0', '2', '3', 1, '0', '0', '1', 'a'},
 				[]byte("unpack server is busy\n"),
-				{'0', '0', '0', '0', '0', '0', '4', '4', 2},
-				[]byte("GitLab is currently unable to handle this request due to load.\n"),
+				{'0', '0', '0', '0', '0', '0', '5', '5', 2},
+				[]byte("GitLab is currently unable to handle this request due to load (ID abcdef01234).\n"),
 				{'0', '0', '0', '0'},
 			}, []byte{}),
 		},
 	}
 
+	ctx := correlation.ContextWithCorrelation(context.Background(), expectedCorrelationID)
+
 	for _, tc := range testCases {
 		t.Run(tc.desc, func(t *testing.T) {
 			var body bytes.Buffer
@@ -49,7 +55,7 @@ func TestHandleLimitErr(t *testing.T) {
 				ErrorMessage: "concurrency queue wait time reached",
 				RetryAfter:   durationpb.New(0)})
 
-			handleLimitErr(fmt.Errorf("wrapped error: %w", err), &body, tc.errWriter)
+			handleLimitErr(fmt.Errorf("wrapped error: %w", err), &body, ctx, tc.errWriter)
 			require.Equal(t, tc.expectedBytes, body.Bytes())
 		})
 	}
@@ -57,12 +63,11 @@ func TestHandleLimitErr(t *testing.T) {
 	t.Run("non LimitError", func(t *testing.T) {
 		var body bytes.Buffer
 		err := status.Error(codes.Internal, "some internal error")
-		handleLimitErr(fmt.Errorf("wrapped error: %w", err), &body, writeUploadPackError)
-		require.Equal(t, []byte(nil), body.Bytes())
-
-		handleLimitErr(fmt.Errorf("wrapped error: %w", err), &body, writeReceivePackError)
-		require.Equal(t, []byte(nil), body.Bytes())
+		handleLimitErr(fmt.Errorf("wrapped error: %w", err), &body, ctx, writeUploadPackError)
+		require.Equal(t, []byte(nil), body.Bytes(), expectedCorrelationID)
 
+		handleLimitErr(fmt.Errorf("wrapped error: %w", err), &body, ctx, writeReceivePackError)
+		require.Equal(t, []byte(nil), body.Bytes(), expectedCorrelationID)
 	})
 }
 

workhorse/internal/git/git-http.go

@@ -46,7 +46,7 @@ func postRPCHandler(
 	name string,
 	handler func(*HTTPResponseWriter, *http.Request, *api.Response) (*gitalypb.PackfileNegotiationStatistics, error),
 	postFunc func(*api.API, *http.Request, *api.Response, *gitalypb.PackfileNegotiationStatistics),
-	errWriter func(io.Writer) error,
+	errWriter func(io.Writer, string) error,
 ) http.Handler {
 	return repoPreAuthorizeHandler(a, func(rw http.ResponseWriter, r *http.Request, ar *api.Response) {
 		cr := &countReadCloser{ReadCloser: r.Body}
@@ -60,7 +60,7 @@ func postRPCHandler(
 
 		stats, err := handler(w, r, ar)
 		if err != nil {
-			handleLimitErr(err, w, errWriter)
+			handleLimitErr(err, w, r.Context(), errWriter)
 			// If the handler, or handleLimitErr already wrote a response this WriteHeader call is a
 			// no-op. It never reaches net/http because GitHttpResponseWriter calls
 			// WriteHeader on its underlying ResponseWriter at most once.