Merge branch 'qmnguyen0711/handle-pack-objects-limit-error' into 'master'

Let gitaly-hook propagate limit error back to clients

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

Merged-by: Justin Tobler <jtobler@gitlab.com>
Approved-by: Justin Tobler <jtobler@gitlab.com>
Approved-by: Will Chandler <wchandler@gitlab.com>
Reviewed-by: Quang-Minh Nguyen <qmnguyen@gitlab.com>
Reviewed-by: Justin Tobler <jtobler@gitlab.com>
Co-authored-by: Quang-Minh Nguyen <qmnguyen@gitlab.com>

4 files changed, 426 insertions, 178 deletions

diff --git a/cmd/gitaly-hooks/hooks.go b/cmd/gitaly-hooks/hooks.go
index 52bba0490..0852cb08c 100644
--- a/cmd/gitaly-hooks/hooks.go
+++ b/cmd/gitaly-hooks/hooks.go
@@ -25,12 +25,15 @@ import (
 	labkitcorrelation "gitlab.com/gitlab-org/labkit/correlation/grpc"
 	labkittracing "gitlab.com/gitlab-org/labkit/tracing"
 	"google.golang.org/grpc"
+	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/metadata"
+	"google.golang.org/grpc/status"
 )
 
 type hookError struct {
 	returnCode int
 	err        error
+	clientMsg  string
 }
 
 func (e hookError) Error() string {
@@ -62,23 +65,43 @@ var hooksBySubcommand = map[string]hookCommand{
 }
 
 func main() {
-	logger := gitalylog.NewHookLogger()
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
 
-	if err := run(os.Args); err != nil {
+	// Since the environment is sanitized at the moment, we're only
+	// using this to extract the correlation ID. The finished() call
+	// to clean up the tracing will be a NOP here.
+	ctx, finished := labkittracing.ExtractFromEnv(ctx)
+	defer finished()
+
+	logger := gitalylog.NewHookLogger(ctx)
+	if err := run(ctx, os.Args); err != nil {
 		var hookError hookError
 		if errors.As(err, &hookError) {
 			if hookError.err != nil {
-				logger.Fatalf("%s", err)
+				notifyError("error executing git hook")
+				logger.WithError(hookError.err).Error("error executing git hook")
+			}
+			if hookError.clientMsg != "" {
+				notifyError(hookError.clientMsg)
 			}
 			os.Exit(hookError.returnCode)
 		}
 
-		logger.Fatalf("%s", err)
+		notifyError("error executing git hook")
+		logger.WithError(err).Error("error executing git hook")
 		os.Exit(1)
 	}
 }
 
-func run(args []string) error {
+// Both stderr and stdout of gitaly-hooks are streamed back to clients. stdout is processed by client
+// git process transparently. stderr is dumped directly to client's stdout. Thus, we must be cautious
+// what to write into stderr.
+func notifyError(msg string) {
+	fmt.Fprintln(os.Stderr, msg)
+}
+
+func run(ctx context.Context, args []string) error {
 	switch filepath.Base(args[0]) {
 	case "gitaly-hooks":
 		if len(args) < 2 {
@@ -89,7 +112,7 @@ func run(args []string) error {
 
 		switch subCmd {
 		case "git":
-			return executeHook(hookCommand{
+			return executeHook(ctx, hookCommand{
 				exec:     packObjectsHook,
 				hookType: git.PackObjectsHook,
 			}, args[2:])
@@ -103,20 +126,11 @@ func run(args []string) error {
 			return fmt.Errorf("subcommand name invalid: %q", hookName)
 		}
 
-		return executeHook(hookCommand, args[1:])
+		return executeHook(ctx, hookCommand, args[1:])
 	}
 }
 
-func executeHook(cmd hookCommand, args []string) error {
-	ctx, cancel := context.WithCancel(context.Background())
-	defer cancel()
-
-	// Since the environment is sanitized at the moment, we're only
-	// using this to extract the correlation ID. The finished() call
-	// to clean up the tracing will be a NOP here.
-	ctx, finished := labkittracing.ExtractFromEnv(ctx)
-	defer finished()
-
+func executeHook(ctx context.Context, cmd hookCommand, args []string) error {
 	payload, err := git.HooksPayloadFromEnv(os.Environ())
 	if err != nil {
 		return fmt.Errorf("error when getting hooks payload: %w", err)
@@ -138,11 +152,7 @@ func executeHook(cmd hookCommand, args []string) error {
 
 	hookClient := gitalypb.NewHookServiceClient(conn)
 
-	if err := cmd.exec(ctx, payload, hookClient, args); err != nil {
-		return err
-	}
-
-	return nil
+	return cmd.exec(ctx, payload, hookClient, args)
 }
 
 func injectMetadataIntoOutgoingCtx(ctx context.Context, payload git.HooksPayload) context.Context {
@@ -379,19 +389,11 @@ func referenceTransactionHook(ctx context.Context, payload git.HooksPayload, hoo
 }
 
 func packObjectsHook(ctx context.Context, payload git.HooksPayload, hookClient gitalypb.HookServiceClient, args []string) error {
-	if err := handlePackObjectsWithSidechannel(ctx, payload, hookClient, args); err != nil {
-		return hookError{returnCode: 1, err: fmt.Errorf("RPC failed: %w", err)}
-	}
-
-	return nil
-}
-
-func handlePackObjectsWithSidechannel(ctx context.Context, payload git.HooksPayload, hookClient gitalypb.HookServiceClient, args []string) error {
 	ctx, wt, err := hook.SetupSidechannel(ctx, payload, func(c *net.UnixConn) error {
 		return stream.ProxyPktLine(c, os.Stdin, os.Stdout, os.Stderr)
 	})
 	if err != nil {
-		return fmt.Errorf("SetupSidechannel: %w", err)
+		return hookError{returnCode: 1, err: fmt.Errorf("RPC failed: SetupSidechannel: %w", err)}
 	}
 	defer func() {
 		// We aleady check the error further down.
@@ -418,16 +420,30 @@ func handlePackObjectsWithSidechannel(ctx context.Context, payload git.HooksPayl
 			RemoteIp:    remoteIP,
 		},
 	); err != nil {
-		return fmt.Errorf("call PackObjectsHookWithSidechannel: %w", err)
+		return wrapGRPCError(err)
 	}
 
 	if err := wt.Wait(); err != nil {
-		return err
+		return hookError{returnCode: 1, err: fmt.Errorf("RPC failed: %w", err)}
 	}
 
 	if err := wt.Close(); err != nil {
-		return fmt.Errorf("closing sidechannel: %w", err)
+		return hookError{returnCode: 1, err: fmt.Errorf("RPC failed: closing sidechannel: %w", err)}
 	}
 
 	return nil
 }
+
+func wrapGRPCError(err error) error {
+	wrappedErr := hookError{
+		returnCode: 1,
+		err:        fmt.Errorf("RPC failed: %w", err),
+	}
+	if e, ok := status.FromError(err); ok {
+		switch e.Code() {
+		case codes.ResourceExhausted:
+			wrappedErr.clientMsg = "error resource exhausted, please try again later"
+		}
+	}
+	return wrappedErr
+}
diff --git a/cmd/gitaly-hooks/hooks_test.go b/cmd/gitaly-hooks/hooks_test.go
index b807b2c0c..614d6fe5a 100644
--- a/cmd/gitaly-hooks/hooks_test.go
+++ b/cmd/gitaly-hooks/hooks_test.go
@@ -30,6 +30,8 @@ import (
 	gitalylog "gitlab.com/gitlab-org/gitaly/v15/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/metadata"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/metadata/featureflag"
+	"gitlab.com/gitlab-org/gitaly/v15/internal/middleware/limithandler"
+	"gitlab.com/gitlab-org/gitaly/v15/internal/structerr"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/testhelper"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/testhelper/testcfg"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/testhelper/testserver"
@@ -40,10 +42,12 @@ import (
 	labkittracing "gitlab.com/gitlab-org/labkit/tracing"
 	"google.golang.org/grpc"
 	grpcmetadata "google.golang.org/grpc/metadata"
+	"google.golang.org/protobuf/types/known/durationpb"
 )
 
 type glHookValues struct {
 	GLID, GLUsername, GLProtocol, GitObjectDir, RemoteIP string
+	GitalyLogDir                                         string
 	GitAlternateObjectDirs                               []string
 }
 
@@ -111,6 +115,9 @@ func envForHooks(tb testing.TB, ctx context.Context, cfg config.Cfg, repo *gital
 	if len(glHookValues.GitAlternateObjectDirs) > 0 {
 		env = append(env, fmt.Sprintf("GIT_ALTERNATE_OBJECT_DIRECTORIES=%s", strings.Join(glHookValues.GitAlternateObjectDirs, ":")))
 	}
+	if glHookValues.GitalyLogDir != "" {
+		env = append(env, fmt.Sprintf("GITALY_LOG_DIR=%s", glHookValues.GitalyLogDir))
+	}
 
 	return env
 }
@@ -529,74 +536,65 @@ func TestHooksNotAllowed(t *testing.T) {
 	require.NoFileExists(t, customHookOutputPath)
 }
 
-func runHookServiceServer(t *testing.T, cfg config.Cfg, assertUserDetails bool, serverOpts ...testserver.GitalyServerOpt) {
-	runHookServiceWithGitlabClient(t, cfg, assertUserDetails, gitlab.NewMockClient(
-		t, gitlab.MockAllowed, gitlab.MockPreReceive, gitlab.MockPostReceive,
-	), serverOpts...)
-}
-
-type baggageAsserter struct {
-	gitalypb.UnimplementedHookServiceServer
-	t                 testing.TB
-	wrapped           gitalypb.HookServiceServer
-	assertUserDetails bool
-}
-
-func (svc baggageAsserter) assert(ctx context.Context) {
-	assert.True(svc.t, enabledFeatureFlag.IsEnabled(ctx))
-	assert.True(svc.t, disabledFeatureFlag.IsDisabled(ctx))
-
-	md, ok := grpcmetadata.FromIncomingContext(ctx)
-	assert.True(svc.t, ok)
-	correlationID := labkitcorrelation.CorrelationIDFromMetadata(md)
-	assert.NotEmpty(svc.t, correlationID)
-
-	if svc.assertUserDetails {
-		assert.Equal(svc.t, glID, metadata.GetValue(ctx, "user_id"))
-		assert.Equal(svc.t, glUsername, metadata.GetValue(ctx, "username"))
-		assert.Equal(svc.t, remoteIP, metadata.GetValue(ctx, "remote_ip"))
-	}
-}
+func TestRequestedHooks(t *testing.T) {
+	for hook, hookArgs := range map[git.Hook][]string{
+		git.ReferenceTransactionHook: {"reference-transaction"},
+		git.UpdateHook:               {"update"},
+		git.PreReceiveHook:           {"pre-receive"},
+		git.PostReceiveHook:          {"post-receive"},
+		git.PackObjectsHook:          {"gitaly-hooks", "git"},
+	} {
+		t.Run(hookArgs[0], func(t *testing.T) {
+			t.Run("unrequested hook is ignored", func(t *testing.T) {
+				cfg := testcfg.Build(t)
+				testcfg.BuildGitalyHooks(t, cfg)
+				testcfg.BuildGitalySSH(t, cfg)
 
-func (svc baggageAsserter) PreReceiveHook(stream gitalypb.HookService_PreReceiveHookServer) error {
-	svc.assert(stream.Context())
-	return svc.wrapped.PreReceiveHook(stream)
-}
+				payload, err := git.NewHooksPayload(
+					cfg,
+					&gitalypb.Repository{},
+					gittest.DefaultObjectHash,
+					nil,
+					nil,
+					git.AllHooks&^hook,
+					nil,
+				).Env()
+				require.NoError(t, err)
 
-func (svc baggageAsserter) PostReceiveHook(stream gitalypb.HookService_PostReceiveHookServer) error {
-	svc.assert(stream.Context())
-	return svc.wrapped.PostReceiveHook(stream)
-}
+				cmd := exec.Command(cfg.BinaryPath("gitaly-hooks"))
+				cmd.Args = hookArgs
+				cmd.Env = []string{payload}
+				require.NoError(t, cmd.Run())
+			})
 
-func (svc baggageAsserter) UpdateHook(request *gitalypb.UpdateHookRequest, stream gitalypb.HookService_UpdateHookServer) error {
-	svc.assert(stream.Context())
-	return svc.wrapped.UpdateHook(request, stream)
-}
+			t.Run("requested hook runs", func(t *testing.T) {
+				cfg := testcfg.Build(t)
+				testcfg.BuildGitalyHooks(t, cfg)
+				testcfg.BuildGitalySSH(t, cfg)
 
-func (svc baggageAsserter) ReferenceTransactionHook(stream gitalypb.HookService_ReferenceTransactionHookServer) error {
-	svc.assert(stream.Context())
-	return svc.wrapped.ReferenceTransactionHook(stream)
-}
+				payload, err := git.NewHooksPayload(
+					cfg,
+					&gitalypb.Repository{},
+					gittest.DefaultObjectHash,
+					nil,
+					nil,
+					hook,
+					nil,
+				).Env()
+				require.NoError(t, err)
 
-func (svc baggageAsserter) PackObjectsHookWithSidechannel(ctx context.Context, req *gitalypb.PackObjectsHookWithSidechannelRequest) (*gitalypb.PackObjectsHookWithSidechannelResponse, error) {
-	svc.assert(ctx)
-	return svc.wrapped.PackObjectsHookWithSidechannel(ctx, req)
-}
+				cmd := exec.Command(cfg.BinaryPath("gitaly-hooks"))
+				cmd.Args = hookArgs
+				cmd.Env = []string{payload}
 
-func runHookServiceWithGitlabClient(t *testing.T, cfg config.Cfg, assertUserDetails bool, gitlabClient gitlab.Client, serverOpts ...testserver.GitalyServerOpt) {
-	testserver.RunGitalyServer(t, cfg, func(srv *grpc.Server, deps *service.Dependencies) {
-		gitalypb.RegisterHookServiceServer(srv, baggageAsserter{
-			t:                 t,
-			assertUserDetails: assertUserDetails,
-			wrapped:           hook.NewServer(deps.GetHookManager(), deps.GetGitCmdFactory(), deps.GetPackObjectsCache(), deps.GetPackObjectsConcurrencyTracker(), deps.GetPackObjectsLimiter()),
+				// We simply check that there is an error here as an indicator that
+				// the hook logic ran. We don't care for the actual error because we
+				// know that in the previous testcase without the hook being
+				// requested, there was no error.
+				require.Error(t, cmd.Run(), "hook should have run and failed due to incomplete setup")
+			})
 		})
-	}, append(serverOpts, testserver.WithGitLabClient(gitlabClient))...)
-}
-
-func requireContainsOnce(t *testing.T, s string, contains string) {
-	r := regexp.MustCompile(contains)
-	matches := r.FindAllStringIndex(s, -1)
-	require.Equal(t, 1, len(matches))
+	}
 }
 
 func TestGitalyHooksPackObjects(t *testing.T) {
@@ -652,63 +650,308 @@ func TestGitalyHooksPackObjects(t *testing.T) {
 	}
 }
 
-func TestRequestedHooks(t *testing.T) {
-	for hook, hookArgs := range map[git.Hook][]string{
-		git.ReferenceTransactionHook: {"reference-transaction"},
-		git.UpdateHook:               {"update"},
-		git.PreReceiveHook:           {"pre-receive"},
-		git.PostReceiveHook:          {"post-receive"},
-		git.PackObjectsHook:          {"gitaly-hooks", "git"},
-	} {
-		t.Run(hookArgs[0], func(t *testing.T) {
-			t.Run("unrequested hook is ignored", func(t *testing.T) {
-				cfg := testcfg.Build(t)
-				testcfg.BuildGitalyHooks(t, cfg)
-				testcfg.BuildGitalySSH(t, cfg)
+func TestGitalyServerReturnsError(t *testing.T) {
+	resourceExhaustedErr := structerr.NewResourceExhausted("%w", limithandler.ErrMaxQueueTime).WithDetail(&gitalypb.LimitError{
+		ErrorMessage: limithandler.ErrMaxQueueTime.Error(),
+		RetryAfter:   durationpb.New(0),
+	})
 
-				payload, err := git.NewHooksPayload(
-					cfg,
-					&gitalypb.Repository{},
-					gittest.DefaultObjectHash,
-					nil,
-					nil,
-					git.AllHooks&^hook,
-					nil,
-				).Env()
-				require.NoError(t, err)
+	for _, tc := range []struct {
+		hook           string
+		args           []string
+		stdin          string
+		expectedStderr string
+	}{
+		{
+			hook:           "pre-receive",
+			stdin:          "abc",
+			expectedStderr: "error executing git hook\n",
+		},
+		{
+			hook:           "post-receive",
+			stdin:          "abc",
+			expectedStderr: "error executing git hook\n",
+		},
+		{
+			hook:           "update",
+			args:           []string{"ref", "oldValue", "newValue"},
+			stdin:          "abc",
+			expectedStderr: "error executing git hook\n",
+		},
+		{
+			hook:           "reference-transaction",
+			args:           []string{"prepared"},
+			stdin:          "abc",
+			expectedStderr: "error executing git hook\n",
+		},
+	} {
+		t.Run(tc.hook, func(t *testing.T) {
+			logDir := testhelper.TempDir(t)
+
+			ctx := testhelper.Context(t)
+			cfg := testcfg.Build(t, testcfg.WithBase(config.Cfg{
+				Auth:  auth.Config{Token: "abc123"},
+				Hooks: config.Hooks{CustomHooksDir: testhelper.TempDir(t)},
+			}))
+
+			repo, repoPath := gittest.CreateRepository(t, ctx, cfg, gittest.CreateRepositoryConfig{
+				SkipCreationViaService: true,
+				Seed:                   gittest.SeedGitLabTest,
+			})
 
-				cmd := exec.Command(cfg.BinaryPath("gitaly-hooks"))
-				cmd.Args = hookArgs
-				cmd.Env = []string{payload}
-				require.NoError(t, cmd.Run())
+			runHookServiceWithMockServer(t, cfg, &hookMockServer{
+				preReceiveHook: func(server gitalypb.HookService_PreReceiveHookServer) error {
+					return resourceExhaustedErr
+				},
+				postReceiveHook: func(server gitalypb.HookService_PostReceiveHookServer) error {
+					return resourceExhaustedErr
+				},
+				updateHook: func(request *gitalypb.UpdateHookRequest, server gitalypb.HookService_UpdateHookServer) error {
+					return resourceExhaustedErr
+				},
+				referenceTransactionHook: func(server gitalypb.HookService_ReferenceTransactionHookServer) error {
+					return resourceExhaustedErr
+				},
 			})
 
-			t.Run("requested hook runs", func(t *testing.T) {
-				cfg := testcfg.Build(t)
-				testcfg.BuildGitalyHooks(t, cfg)
-				testcfg.BuildGitalySSH(t, cfg)
+			gitalyHooksPath := testcfg.BuildGitalyHooks(t, cfg)
+			testcfg.BuildGitalySSH(t, cfg)
 
-				payload, err := git.NewHooksPayload(
-					cfg,
-					&gitalypb.Repository{},
-					gittest.DefaultObjectHash,
-					nil,
-					nil,
-					hook,
-					nil,
-				).Env()
-				require.NoError(t, err)
+			var stderr, stdout bytes.Buffer
 
-				cmd := exec.Command(cfg.BinaryPath("gitaly-hooks"))
-				cmd.Args = hookArgs
-				cmd.Env = []string{payload}
+			cmd := exec.Command(gitalyHooksPath)
+			cmd.Args = append([]string{tc.hook}, tc.args...)
+			cmd.Stderr = &stderr
+			cmd.Stdout = &stdout
+			cmd.Stdin = strings.NewReader(tc.stdin)
+			cmd.Env = envForHooks(t, ctx, cfg, repo,
+				glHookValues{
+					GLID:         glID,
+					GLUsername:   glUsername,
+					GLProtocol:   "ssh",
+					RemoteIP:     remoteIP,
+					GitalyLogDir: logDir,
+				},
+				proxyValues{})
+			cmd.Dir = repoPath
 
-				// We simply check that there is an error here as an indicator that
-				// the hook logic ran. We don't care for the actual error because we
-				// know that in the previous testcase without the hook being
-				// requested, there was no error.
-				require.Error(t, cmd.Run(), "hook should have run and failed due to incomplete setup")
+			require.Error(t, cmd.Run())
+			require.Equal(t, tc.expectedStderr, stderr.String())
+			require.Equal(t, "", stdout.String())
+			hookLogs := string(testhelper.MustReadFile(t, filepath.Join(logDir, "gitaly_hooks.log")))
+
+			require.NotEmpty(t, hookLogs)
+			require.Contains(t, hookLogs, "error executing git hook")
+			require.Contains(t, hookLogs, fmt.Sprintf("correlation_id=%s", correlationID))
+		})
+	}
+}
+
+func TestGitalyServerReturnsError_packObjects(t *testing.T) {
+	for _, tc := range []struct {
+		name           string
+		err            error
+		expectedStderr string
+		expectedLogs   string
+	}{
+		{
+			name: "resource exhausted with LimitError detail",
+			err: structerr.NewResourceExhausted("%w", limithandler.ErrMaxQueueTime).WithDetail(&gitalypb.LimitError{
+				ErrorMessage: limithandler.ErrMaxQueueTime.Error(),
+				RetryAfter:   durationpb.New(0),
+			}),
+			expectedStderr: `
+remote: error executing git hook
+remote: error resource exhausted, please try again later
+`,
+			expectedLogs: `RPC failed: rpc error: code = ResourceExhausted desc = maximum time in concurrency queue reached`,
+		},
+		{
+			name: "resource exhausted without LimitError detail",
+			err:  structerr.NewResourceExhausted("not enough resource"),
+			expectedStderr: `
+remote: error executing git hook
+remote: error resource exhausted, please try again later
+`,
+			expectedLogs: `RPC failed: rpc error: code = ResourceExhausted desc = not enough resource`,
+		},
+		{
+			name: "other error - status code is hidden",
+			err:  structerr.NewUnavailable("server is not available"),
+			expectedStderr: `
+remote: error executing git hook
+`,
+			expectedLogs: `RPC failed: rpc error: code = Unavailable desc = server is not available`,
+		},
+	} {
+		t.Run(tc.name, func(t *testing.T) {
+			logDir := testhelper.TempDir(t)
+
+			ctx := testhelper.Context(t)
+			cfg := testcfg.Build(t, testcfg.WithBase(config.Cfg{
+				Auth:  auth.Config{Token: "abc123"},
+				Hooks: config.Hooks{CustomHooksDir: testhelper.TempDir(t)},
+			}))
+
+			repo, repoPath := gittest.CreateRepository(t, ctx, cfg, gittest.CreateRepositoryConfig{
+				SkipCreationViaService: true,
+				Seed:                   gittest.SeedGitLabTest,
 			})
+
+			testcfg.BuildGitalyHooks(t, cfg)
+			testcfg.BuildGitalySSH(t, cfg)
+
+			runHookServiceWithMockServer(t, cfg, &hookMockServer{
+				packObjectsHookWithSidechannel: func(ctx context.Context, request *gitalypb.PackObjectsHookWithSidechannelRequest) (*gitalypb.PackObjectsHookWithSidechannelResponse, error) {
+					return nil, tc.err
+				},
+			})
+
+			args := []string{
+				"clone",
+				"-u",
+				"git -c uploadpack.allowFilter -c uploadpack.packObjectsHook=" + cfg.BinaryPath("gitaly-hooks") + " upload-pack",
+				"--quiet",
+				"--no-local",
+				"--bare",
+				repoPath,
+				testhelper.TempDir(t),
+			}
+
+			var stderr, stdout bytes.Buffer
+
+			gittest.ExecOpts(t, cfg, gittest.ExecConfig{
+				Env:    envForHooks(t, ctx, cfg, repo, glHookValues{GitalyLogDir: logDir}, proxyValues{}),
+				Stdout: &stdout,
+				Stderr: &stderr,
+			}, args...)
+
+			require.Equal(t, "", stdout.String())
+
+			var actualStderr []string
+			for _, line := range strings.Split(stderr.String(), "\n") {
+				actualStderr = append(actualStderr, strings.TrimSpace(line))
+			}
+
+			require.Contains(t, strings.Join(actualStderr, "\n"), strings.TrimSpace(tc.expectedStderr))
+			hookLogs := string(testhelper.MustReadFile(t, filepath.Join(logDir, "gitaly_hooks.log")))
+			require.NotEmpty(t, hookLogs)
+			require.Contains(t, hookLogs, tc.expectedLogs)
+			require.Contains(t, hookLogs, fmt.Sprintf("correlation_id=%s", correlationID))
+		})
+	}
+}
+
+func runHookServiceServer(t *testing.T, cfg config.Cfg, assertUserDetails bool, serverOpts ...testserver.GitalyServerOpt) {
+	t.Helper()
+
+	runHookServiceWithGitlabClient(t, cfg, assertUserDetails, gitlab.NewMockClient(
+		t, gitlab.MockAllowed, gitlab.MockPreReceive, gitlab.MockPostReceive,
+	), serverOpts...)
+}
+
+func runHookServiceWithGitlabClient(t *testing.T, cfg config.Cfg, assertUserDetails bool, gitlabClient gitlab.Client, serverOpts ...testserver.GitalyServerOpt) {
+	t.Helper()
+
+	testserver.RunGitalyServer(t, cfg, func(srv *grpc.Server, deps *service.Dependencies) {
+		gitalypb.RegisterHookServiceServer(srv, baggageAsserter{
+			t:                 t,
+			assertUserDetails: assertUserDetails,
+			wrapped:           hook.NewServer(deps.GetHookManager(), deps.GetGitCmdFactory(), deps.GetPackObjectsCache(), deps.GetPackObjectsConcurrencyTracker(), deps.GetPackObjectsLimiter()),
+		})
+	}, append(serverOpts, testserver.WithGitLabClient(gitlabClient))...)
+}
+
+func runHookServiceWithMockServer(t *testing.T, cfg config.Cfg, mockServer gitalypb.HookServiceServer) {
+	t.Helper()
+
+	testserver.RunGitalyServer(t, cfg, func(srv *grpc.Server, deps *service.Dependencies) {
+		gitalypb.RegisterHookServiceServer(srv, baggageAsserter{
+			t:       t,
+			wrapped: mockServer,
 		})
+	}, testserver.WithDisablePraefect())
+}
+
+type hookMockServer struct {
+	gitalypb.UnimplementedHookServiceServer
+	preReceiveHook                 func(gitalypb.HookService_PreReceiveHookServer) error
+	postReceiveHook                func(gitalypb.HookService_PostReceiveHookServer) error
+	updateHook                     func(*gitalypb.UpdateHookRequest, gitalypb.HookService_UpdateHookServer) error
+	referenceTransactionHook       func(gitalypb.HookService_ReferenceTransactionHookServer) error
+	packObjectsHookWithSidechannel func(context.Context, *gitalypb.PackObjectsHookWithSidechannelRequest) (*gitalypb.PackObjectsHookWithSidechannelResponse, error)
+}
+
+func (s *hookMockServer) PreReceiveHook(server gitalypb.HookService_PreReceiveHookServer) error {
+	return s.preReceiveHook(server)
+}
+
+func (s *hookMockServer) PostReceiveHook(server gitalypb.HookService_PostReceiveHookServer) error {
+	return s.postReceiveHook(server)
+}
+
+func (s *hookMockServer) UpdateHook(request *gitalypb.UpdateHookRequest, server gitalypb.HookService_UpdateHookServer) error {
+	return s.updateHook(request, server)
+}
+
+func (s *hookMockServer) ReferenceTransactionHook(server gitalypb.HookService_ReferenceTransactionHookServer) error {
+	return s.referenceTransactionHook(server)
+}
+
+func (s *hookMockServer) PackObjectsHookWithSidechannel(ctx context.Context, request *gitalypb.PackObjectsHookWithSidechannelRequest) (*gitalypb.PackObjectsHookWithSidechannelResponse, error) {
+	return s.packObjectsHookWithSidechannel(ctx, request)
+}
+
+type baggageAsserter struct {
+	gitalypb.UnimplementedHookServiceServer
+	t                 testing.TB
+	wrapped           gitalypb.HookServiceServer
+	assertUserDetails bool
+}
+
+func (svc baggageAsserter) assert(ctx context.Context) {
+	assert.True(svc.t, enabledFeatureFlag.IsEnabled(ctx))
+	assert.True(svc.t, disabledFeatureFlag.IsDisabled(ctx))
+
+	md, ok := grpcmetadata.FromIncomingContext(ctx)
+	assert.True(svc.t, ok)
+	correlationID := labkitcorrelation.CorrelationIDFromMetadata(md)
+	assert.NotEmpty(svc.t, correlationID)
+
+	if svc.assertUserDetails {
+		assert.Equal(svc.t, glID, metadata.GetValue(ctx, "user_id"))
+		assert.Equal(svc.t, glUsername, metadata.GetValue(ctx, "username"))
+		assert.Equal(svc.t, remoteIP, metadata.GetValue(ctx, "remote_ip"))
 	}
 }
+
+func (svc baggageAsserter) PreReceiveHook(stream gitalypb.HookService_PreReceiveHookServer) error {
+	svc.assert(stream.Context())
+	return svc.wrapped.PreReceiveHook(stream)
+}
+
+func (svc baggageAsserter) PostReceiveHook(stream gitalypb.HookService_PostReceiveHookServer) error {
+	svc.assert(stream.Context())
+	return svc.wrapped.PostReceiveHook(stream)
+}
+
+func (svc baggageAsserter) UpdateHook(request *gitalypb.UpdateHookRequest, stream gitalypb.HookService_UpdateHookServer) error {
+	svc.assert(stream.Context())
+	return svc.wrapped.UpdateHook(request, stream)
+}
+
+func (svc baggageAsserter) ReferenceTransactionHook(stream gitalypb.HookService_ReferenceTransactionHookServer) error {
+	svc.assert(stream.Context())
+	return svc.wrapped.ReferenceTransactionHook(stream)
+}
+
+func (svc baggageAsserter) PackObjectsHookWithSidechannel(ctx context.Context, req *gitalypb.PackObjectsHookWithSidechannelRequest) (*gitalypb.PackObjectsHookWithSidechannelResponse, error) {
+	svc.assert(ctx)
+	return svc.wrapped.PackObjectsHookWithSidechannel(ctx, req)
+}
+
+func requireContainsOnce(t *testing.T, s string, contains string) {
+	r := regexp.MustCompile(contains)
+	matches := r.FindAllStringIndex(s, -1)
+	require.Equal(t, 1, len(matches))
+}
diff --git a/internal/git/gittest/command.go b/internal/git/gittest/command.go
index e26878ee4..9e81bac6e 100644
--- a/internal/git/gittest/command.go
+++ b/internal/git/gittest/command.go
@@ -20,6 +20,9 @@ type ExecConfig struct {
 	// Stdout sets up stdout of the spawned command. Note that `ExecOpts()` will not return any
 	// output anymore if this field is set.
 	Stdout io.Writer
+	// Stderr sets up stderr of the spawned command. If this field is not set, the error is
+	// dumped to test logs.
+	Stderr io.Writer
 	// Env contains environment variables that should be appended to the spawned command's
 	// environment.
 	Env []string
@@ -41,11 +44,7 @@ func ExecOpts(tb testing.TB, cfg config.Cfg, execCfg ExecConfig, args ...string)
 	// we detect this case and call `cmd.Run()` instead.
 	if execCfg.Stdout != nil {
 		if err := cmd.Run(); err != nil {
-			tb.Log(cfg.Git.BinPath, args)
-			if ee, ok := err.(*exec.ExitError); ok {
-				tb.Logf("%s\n", ee.Stderr)
-			}
-			tb.Fatal(err)
+			handleExecErr(tb, cfg, execCfg, args, err)
 		}
 
 		return nil
@@ -53,14 +52,20 @@ func ExecOpts(tb testing.TB, cfg config.Cfg, execCfg ExecConfig, args ...string)
 
 	output, err := cmd.Output()
 	if err != nil {
+		handleExecErr(tb, cfg, execCfg, args, err)
+	}
+
+	return output
+}
+
+func handleExecErr(tb testing.TB, cfg config.Cfg, execCfg ExecConfig, args []string, err error) {
+	if execCfg.Stderr == nil {
 		tb.Log(cfg.Git.BinPath, args)
 		if ee, ok := err.(*exec.ExitError); ok {
-			tb.Logf("%s: %s\n", ee.Stderr, output)
+			tb.Logf("%s\n", ee.Stderr)
 		}
 		tb.Fatal(err)
 	}
-
-	return output
 }
 
 // NewCommand creates a new Git command ready for execution.
@@ -95,6 +100,7 @@ func createCommand(tb testing.TB, cfg config.Cfg, execCfg ExecConfig, args ...st
 
 	cmd.Stdout = execCfg.Stdout
 	cmd.Stdin = execCfg.Stdin
+	cmd.Stderr = execCfg.Stderr
 
 	return cmd
 }
diff --git a/internal/log/hook.go b/internal/log/hook.go
index 96e348b42..589c772f2 100644
--- a/internal/log/hook.go
+++ b/internal/log/hook.go
@@ -1,28 +1,24 @@
 package log
 
 import (
-	"fmt"
+	"context"
 	"io"
 	"os"
 	"path/filepath"
 
 	"github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/helper/perm"
+	"gitlab.com/gitlab-org/labkit/correlation"
 )
 
-// HookLogger is a wrapper around *logrus.Logger
-type HookLogger struct {
-	logger *logrus.Logger
-}
-
 // NewHookLogger creates a file logger, since both stderr and stdout will be displayed in git output
-func NewHookLogger() *HookLogger {
+func NewHookLogger(ctx context.Context) *logrus.Entry {
 	logger := logrus.New()
 
 	logDir := os.Getenv(GitalyLogDirEnvKey)
 	if logDir == "" {
 		logger.SetOutput(io.Discard)
-		return &HookLogger{logger: logger}
+		return logrus.NewEntry(logger)
 	}
 
 	logFile, err := os.OpenFile(filepath.Join(logDir, "gitaly_hooks.log"), os.O_CREATE|os.O_APPEND|os.O_WRONLY, perm.SharedFile)
@@ -34,24 +30,11 @@ func NewHookLogger() *HookLogger {
 
 	logger.SetFormatter(UTCTextFormatter())
 
-	return &HookLogger{logger: logger}
-}
-
-// Fatal logs an error at the Fatal level and writes a generic message to stderr
-func (h *HookLogger) Fatal(err error) {
-	h.Fatalf("%v", err)
+	return logger.WithFields(logFieldsFromContext(ctx))
 }
 
-// Fatalf logs a formatted error at the Fatal level
-func (h *HookLogger) Fatalf(format string, a ...interface{}) {
-	fmt.Fprintln(os.Stderr, "error executing git hook")
-	h.logger.Fatalf(format, a...)
-}
-
-// Errorf logs a formatted error at the Fatal level
-func (h *HookLogger) Errorf(format string, a ...interface{}) {
-	h.logger.Errorf(format, a...)
+func logFieldsFromContext(ctx context.Context) logrus.Fields {
+	return logrus.Fields{
+		correlation.FieldName: correlation.ExtractFromContext(ctx),
+	}
 }
-
-// Logger returns the underlying logrus logger
-func (h *HookLogger) Logger() *logrus.Logger { return h.logger }