hook: Fix custom hook errors not propagating correctly

In commit c68213377 (updateref: Generalize `PreReceiveError` according
to its usage, 2021-08-25), we have changed how pre-receive errors get
propagated to callers, where it's now instead using a more generalized
`HookError`. Part of this change was a refactoring of the error message
to be more descriptive: instead of printing hook errors printed to their
stdout/stderr as-is, we prepend the actual error we have been seeing to
pinpoint why hook execution failed.

As it turns out though, Rails requires the messages printed by custom
hooks to be returned as-is. This is to support a feature where hooks can
print messages either with a "GitLab:" or with a "GL-HOOK-ERR:" prefix,
which indicates to Rails that it should present the error message to the
user. Prepending the error message with unrelated metadata obviously
breaks this feature.

We are in the process of fixing the whole architecture to use structured
error messages instead, which contain error information in a more
detailed way and don't rely on parsing and/or prefixing error messages.
This doesn't work easily with custom hooks though: we have no control of
stdin and stderr of the command given that these may be connected to
git-receive-pack(1), which would in turn stream anything printed there
to the user. So we have no easy way of inspecting the error messages and
thus cannot properly bubble them up in a custom error type, either.
While we could introduce e.g. a `io.TeeReader` to enable for this, this
introduces additional complexity that may not be worth the hassle given
we're slowly moving towards a deprecation of custom hooks in the first
place.

So let's mark custom hook errors as such and add some special handling
in our hook updater so that both stderr and stdout are returned as-is.
At a later point, we should likely go the road via the `io.TeeReader`
such that we can properly use structured errors, too.

Changelog: fixed

6 files changed, 67 insertions, 37 deletions

diff --git a/internal/git/updateref/update_with_hooks.go b/internal/git/updateref/update_with_hooks.go
index a1b04aa56..3725965d2 100644
--- a/internal/git/updateref/update_with_hooks.go
+++ b/internal/git/updateref/update_with_hooks.go
@@ -37,12 +37,34 @@ type HookError struct {
 
 // Error returns an error message.
 func (e HookError) Error() string {
-	if len(strings.TrimSpace(e.stderr)) > 0 {
-		return fmt.Sprintf("%v, stderr: %q", e.err.Error(), e.stderr)
-	}
-	if len(strings.TrimSpace(e.stdout)) > 0 {
-		return fmt.Sprintf("%v, stdout: %q", e.err.Error(), e.stdout)
+	// If custom hooks write the "GitLab: " or "GL-HOOK-ERR: " prefix to either their stderr or
+	// their stdout, then this prefix is taken as a hint by Rails to print the error as-is in
+	// the web interface. We must thus make sure to not modify these custom hook error messages
+	// at all. Ideally, this logic would be handled by the hook package, which would return an
+	// error struct containing all necessary information. But the hook package does not manage
+	// neither stderr nor stdout itself, and these may be directly connected to the user on a
+	// clone. Given that we do use byte buffers here though, we do have enough information in
+	// the updateref package to handle these custom hook errors.
+	//
+	// Eventually, we should find a solution which allows us to bubble up the error in hook
+	// package such that we can also make proper use of structured errors for custom hooks.
+	var customHookError hook.CustomHookError
+	if errors.As(e.err, &customHookError) {
+		if len(strings.TrimSpace(e.stderr)) > 0 {
+			return e.stderr
+		}
+		if len(strings.TrimSpace(e.stdout)) > 0 {
+			return e.stdout
+		}
+	} else {
+		if len(strings.TrimSpace(e.stderr)) > 0 {
+			return fmt.Sprintf("%v, stderr: %q", e.err.Error(), e.stderr)
+		}
+		if len(strings.TrimSpace(e.stdout)) > 0 {
+			return fmt.Sprintf("%v, stdout: %q", e.err.Error(), e.stdout)
+		}
 	}
+
 	return e.err.Error()
 }
 
diff --git a/internal/gitaly/hook/custom.go b/internal/gitaly/hook/custom.go
index 04fbc61ce..d6b30566b 100644
--- a/internal/gitaly/hook/custom.go
+++ b/internal/gitaly/hook/custom.go
@@ -19,6 +19,9 @@ import (
 // customHooksExecutor executes all custom hooks for a given repository and hook name
 type customHooksExecutor func(ctx context.Context, args, env []string, stdin io.Reader, stdout, stderr io.Writer) error
 
+// CustomHookError is returned in case custom hooks return an error.
+type CustomHookError error
+
 // newCustomHooksExecutor creates a new hooks executor for custom hooks. Hooks
 // are looked up and executed in the following order:
 //
@@ -69,8 +72,14 @@ func (m *GitLabHookManager) newCustomHooksExecutor(repo *gitalypb.Repository, ho
 			if err != nil {
 				return err
 			}
+
 			if err = c.Wait(); err != nil {
-				return fmt.Errorf("error executing \"%s\": %w", hookFile, err)
+				// Custom hook errors need to be handled specially when we update
+				// refs via updateref.UpdaterWithHooks: their stdout and stderr must
+				// not be modified, but instead used as-is as the hooks' error
+				// message given that they may contain output that should be shown
+				// to the user.
+				return CustomHookError(fmt.Errorf("error executing %q: %w", hookFile, err))
 			}
 		}
 
diff --git a/internal/gitaly/service/conflicts/resolve_conflicts_test.go b/internal/gitaly/service/conflicts/resolve_conflicts_test.go
index ce9a7b84e..f1ba63445 100644
--- a/internal/gitaly/service/conflicts/resolve_conflicts_test.go
+++ b/internal/gitaly/service/conflicts/resolve_conflicts_test.go
@@ -835,7 +835,7 @@ func TestResolveConflictsQuarantine(t *testing.T) {
 	// then exits with an error. Like this, we can both assert that the hook can see the
 	// quarantined tag, and it allows us to fail the RPC before we migrate quarantined objects.
 	script := fmt.Sprintf("#!/bin/sh\nread oldval newval ref && echo $newval && %s cat-file -p $newval^{commit} && exit 1", cfg.Git.BinPath)
-	hookFilename := gittest.WriteCustomHook(t, sourceRepoPath, "pre-receive", []byte(script))
+	gittest.WriteCustomHook(t, sourceRepoPath, "pre-receive", []byte(script))
 
 	targetRepoProto, targetRepoPath := gittest.CloneRepo(t, cfg, cfg.Storages[0])
 	targetBlobOID := gittest.WriteBlob(t, cfg, targetRepoPath, []byte("contents-2\n"))
@@ -884,16 +884,14 @@ func TestResolveConflictsQuarantine(t *testing.T) {
 	}))
 
 	response, err := stream.CloseAndRecv()
-	require.EqualError(t, err, fmt.Sprintf("rpc error: code = Unknown desc = executing custom hooks: error executing \"%s\": exit status 1, stdout: %q",
-		hookFilename,
-		`af339cb882d1e3cf8d6751651e58bbaff0265d6e
+	require.EqualError(t, err, `rpc error: code = Unknown desc = af339cb882d1e3cf8d6751651e58bbaff0265d6e
 tree 89fad81bbfa38070b90ca8f4c404625bf0999013
 parent 29449b1d52cd77fd060a083a1de691bbaf12d8af
 parent 26dac52be85c92742b2c0c19eb7303de9feccb63
 author John Doe <johndoe@gitlab.com> 12345 +0000
 committer John Doe <johndoe@gitlab.com> 12345 +0000
 
-Solve conflicts`))
+Solve conflicts`)
 	require.Empty(t, response.GetResolutionError())
 
 	// The file shouldn't have been updated and is thus expected to still have the same old
diff --git a/internal/gitaly/service/operations/branches_test.go b/internal/gitaly/service/operations/branches_test.go
index a760ddfd6..10dcf2581 100644
--- a/internal/gitaly/service/operations/branches_test.go
+++ b/internal/gitaly/service/operations/branches_test.go
@@ -620,37 +620,39 @@ func TestBranchHookOutput(t *testing.T) {
 	testCases := []struct {
 		desc        string
 		hookContent string
-		output      string
+		output      func(hookPath string) string
 	}{
 		{
 			desc:        "empty stdout and empty stderr",
 			hookContent: "#!/bin/sh\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1",
+			output: func(hookPath string) string {
+				return fmt.Sprintf("executing custom hooks: error executing %q: exit status 1", hookPath)
+			},
 		},
 		{
 			desc:        "empty stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
+			output:      func(string) string { return "stderr\n" },
 		},
 		{
 			desc:        "some stdout and empty stderr",
 			hookContent: "#!/bin/sh\necho stdout\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
+			output:      func(string) string { return "stdout\n" },
 		},
 		{
 			desc:        "some stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
+			output:      func(string) string { return "stderr\n" },
 		},
 		{
 			desc:        "whitespace stdout and some stderr",
 			hookContent: "#!/bin/sh\necho '   '\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
+			output:      func(string) string { return "stderr\n" },
 		},
 		{
 			desc:        "some stdout and whitespace stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho '   ' >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
+			output:      func(string) string { return "stdout\n" },
 		},
 	}
 
@@ -671,7 +673,7 @@ func TestBranchHookOutput(t *testing.T) {
 				}
 
 				hookFilename := gittest.WriteCustomHook(t, repoPath, hookName, []byte(testCase.hookContent))
-				expectedError := fmt.Sprintf(testCase.output, hookFilename)
+				expectedError := testCase.output(hookFilename)
 
 				createResponse, err := client.UserCreateBranch(ctx, createRequest)
 				require.NoError(t, err)
diff --git a/internal/gitaly/service/operations/merge_test.go b/internal/gitaly/service/operations/merge_test.go
index 8d834db9c..9c4af0cce 100644
--- a/internal/gitaly/service/operations/merge_test.go
+++ b/internal/gitaly/service/operations/merge_test.go
@@ -134,7 +134,7 @@ func testUserMergeBranchQuarantine(t *testing.T, ctx context.Context) {
 	// Set up a hook that parses the merge commit and then aborts the update. Like this, we
 	// can assert that the object does not end up in the main repository.
 	hookScript := fmt.Sprintf("#!/bin/sh\nread oldval newval ref && %s rev-parse $newval^{commit} && exit 1", cfg.Git.BinPath)
-	hookFilename := gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(hookScript))
+	gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(hookScript))
 
 	gittest.Exec(t, cfg, "-C", repoPath, "branch", mergeBranchName, mergeBranchHeadBefore)
 
@@ -155,12 +155,12 @@ func testUserMergeBranchQuarantine(t *testing.T, ctx context.Context) {
 	require.NoError(t, stream.Send(&gitalypb.UserMergeBranchRequest{Apply: true}), "apply merge")
 	secondResponse, err := stream.Recv()
 	if featureflag.UserMergeBranchAccessError.IsEnabled(ctx) {
-		testassert.GrpcEqualErr(t, helper.ErrInternalf("executing custom hooks: error executing \"%s\": exit status 1, stdout: \"%s\\n\"", hookFilename, firstResponse.CommitId), err)
+		testassert.GrpcEqualErr(t, helper.ErrInternalf("%s\n", firstResponse.CommitId), err)
 		require.Nil(t, secondResponse)
 	} else {
 		require.NoError(t, err, "receive second response")
 		testassert.ProtoEqual(t, &gitalypb.UserMergeBranchResponse{
-			PreReceiveError: fmt.Sprintf("executing custom hooks: exit status 1, stdout: %q", firstResponse.CommitId+"\n"),
+			PreReceiveError: firstResponse.CommitId + "\n",
 		}, secondResponse)
 	}
 
@@ -457,8 +457,7 @@ func testUserMergeBranchFailingHooks(t *testing.T, ctx context.Context) {
 
 			secondResponse, err := mergeBidi.Recv()
 			if featureflag.UserMergeBranchAccessError.IsEnabled(ctx) {
-				hookFilename := gittest.WriteCustomHook(t, repoPath, hookName, hookContent)
-				testassert.GrpcEqualErr(t, helper.ErrInternalf("executing custom hooks: error executing \"%s\": exit status 1, stdout: \"failure\\n\"", hookFilename), err)
+				testassert.GrpcEqualErr(t, helper.ErrInternalf("failure\n"), err)
 				require.Nil(t, secondResponse)
 			} else {
 				require.NoError(t, err, "receive second response")
diff --git a/internal/gitaly/service/operations/tags_test.go b/internal/gitaly/service/operations/tags_test.go
index 715828e5b..ce8adfa11 100644
--- a/internal/gitaly/service/operations/tags_test.go
+++ b/internal/gitaly/service/operations/tags_test.go
@@ -414,7 +414,7 @@ func TestUserCreateTagQuarantine(t *testing.T) {
 	%s cat-file -p $newval^{commit} >/dev/null &&
 	%s cat-file -p $newval^{tag} &&
 	exit 1`, cfg.Git.BinPath, cfg.Git.BinPath)
-	hookFilename := gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(script))
+	gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(script))
 
 	response, err := client.UserCreateTag(ctx, &gitalypb.UserCreateTagRequest{
 		Repository:     repoProto,
@@ -429,14 +429,12 @@ func TestUserCreateTagQuarantine(t *testing.T) {
 	// Conveniently, the pre-receive error will now contain output from our custom hook and thus
 	// the tag's contents.
 	testassert.ProtoEqual(t, &gitalypb.UserCreateTagResponse{
-		PreReceiveError: fmt.Sprintf("executing custom hooks: error executing \"%s\": exit status 1, stdout: %q",
-			hookFilename,
-			`object c7fbe50c7c7419d9701eebe64b1fdacc3df5b9dd
+		PreReceiveError: `object c7fbe50c7c7419d9701eebe64b1fdacc3df5b9dd
 type commit
 tag quarantined-tag
 tagger Jane Doe <janedoe@gitlab.com> 1600000000 +0800
 
-message`),
+message`,
 	}, response)
 
 	// In case we use an object quarantine directory, the tag should not exist in the target
@@ -1334,37 +1332,39 @@ func TestTagHookOutput(t *testing.T) {
 	testCases := []struct {
 		desc        string
 		hookContent string
-		output      string
+		output      func(hookPath string) string
 	}{
 		{
 			desc:        "empty stdout and empty stderr",
 			hookContent: "#!/bin/sh\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1",
+			output: func(hookPath string) string {
+				return fmt.Sprintf("executing custom hooks: error executing %q: exit status 1", hookPath)
+			},
 		},
 		{
 			desc:        "empty stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
+			output:      func(string) string { return "stderr\n" },
 		},
 		{
 			desc:        "some stdout and empty stderr",
 			hookContent: "#!/bin/sh\necho stdout\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
+			output:      func(string) string { return "stdout\n" },
 		},
 		{
 			desc:        "some stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
+			output:      func(string) string { return "stderr\n" },
 		},
 		{
 			desc:        "whitespace stdout and some stderr",
 			hookContent: "#!/bin/sh\necho '   '\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
+			output:      func(string) string { return "stderr\n" },
 		},
 		{
 			desc:        "some stdout and whitespace stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho '   ' >&2\nexit 1",
-			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
+			output:      func(string) string { return "stdout\n" },
 		},
 	}
 
@@ -1385,7 +1385,7 @@ func TestTagHookOutput(t *testing.T) {
 				}
 
 				hookFilename := gittest.WriteCustomHook(t, repoPath, hookName, []byte(testCase.hookContent))
-				expectedError := fmt.Sprintf(testCase.output, hookFilename)
+				expectedError := testCase.output(hookFilename)
 
 				createResponse, err := client.UserCreateTag(ctx, createRequest)
 				require.NoError(t, err)