Merge branch 'sh-improve-custom-hook-logging' into 'master'

Improve custom hook error logging

See merge request gitlab-org/gitaly!4111

8 files changed, 51 insertions, 31 deletions

diff --git a/internal/git/gittest/hooks.go b/internal/git/gittest/hooks.go
index e2867648a..6f0504c96 100644
--- a/internal/git/gittest/hooks.go
+++ b/internal/git/gittest/hooks.go
@@ -40,9 +40,11 @@ end
 }
 
 // WriteCustomHook writes a hook in the repo/path.git/custom_hooks directory
-func WriteCustomHook(t testing.TB, repoPath, name string, content []byte) {
+func WriteCustomHook(t testing.TB, repoPath, name string, content []byte) string {
 	fullPath := filepath.Join(repoPath, "custom_hooks", name)
 	testhelper.WriteExecutable(t, fullPath, content)
+
+	return fullPath
 }
 
 // CaptureHookEnv creates a bogus 'update' Git hook to sniff out what
diff --git a/internal/gitaly/hook/custom.go b/internal/gitaly/hook/custom.go
index cbbf10c1b..04fbc61ce 100644
--- a/internal/gitaly/hook/custom.go
+++ b/internal/gitaly/hook/custom.go
@@ -70,7 +70,7 @@ func (m *GitLabHookManager) newCustomHooksExecutor(repo *gitalypb.Repository, ho
 				return err
 			}
 			if err = c.Wait(); err != nil {
-				return err
+				return fmt.Errorf("error executing \"%s\": %w", hookFile, err)
 			}
 		}
 
diff --git a/internal/gitaly/hook/custom_test.go b/internal/gitaly/hook/custom_test.go
index 9f99fa6b7..4cc9e9249 100644
--- a/internal/gitaly/hook/custom_test.go
+++ b/internal/gitaly/hook/custom_test.go
@@ -158,7 +158,12 @@ func TestCustomHookPartialFailure(t *testing.T) {
 			require.NoError(t, err)
 
 			var stdout, stderr bytes.Buffer
-			require.Error(t, caller(ctx, nil, nil, &bytes.Buffer{}, &stdout, &stderr))
+			result := caller(ctx, nil, nil, &bytes.Buffer{}, &stdout, &stderr)
+			failedHookPath := filepath.Join(projectHookPath, tc.hook)
+			if !tc.globalHookSucceeds {
+				failedHookPath = filepath.Join(globalHookPath, tc.hook)
+			}
+			require.EqualError(t, result, fmt.Sprintf("error executing \"%s\": exit status 1", failedHookPath))
 
 			if tc.projectHookSucceeds && tc.globalHookSucceeds {
 				require.Equal(t, filepath.Join(projectHookPath, tc.hook), text.ChompBytes(stdout.Bytes()))
diff --git a/internal/gitaly/hook/transactions_test.go b/internal/gitaly/hook/transactions_test.go
index b9ee01858..f5c832a23 100644
--- a/internal/gitaly/hook/transactions_test.go
+++ b/internal/gitaly/hook/transactions_test.go
@@ -51,8 +51,9 @@ func TestHookManager_stopCalled(t *testing.T) {
 	).Env()
 	require.NoError(t, err)
 
-	for _, hook := range []string{"pre-receive", "update", "post-receive"} {
-		gittest.WriteCustomHook(t, repoPath, hook, []byte("#!/bin/sh\nexit 1\n"))
+	hookPaths := make([]string, 3)
+	for i, hook := range []string{"pre-receive", "update", "post-receive"} {
+		hookPaths[i] = gittest.WriteCustomHook(t, repoPath, hook, []byte("#!/bin/sh\nexit 1\n"))
 	}
 
 	preReceiveFunc := func(t *testing.T) error {
@@ -68,34 +69,41 @@ func TestHookManager_stopCalled(t *testing.T) {
 	for _, tc := range []struct {
 		desc     string
 		hookFunc func(*testing.T) error
+		hookPath string
 		stopErr  error
 	}{
 		{
 			desc:     "pre-receive gets successfully stopped",
 			hookFunc: preReceiveFunc,
+			hookPath: hookPaths[0],
 		},
 		{
 			desc:     "pre-receive with stop error does not clobber real error",
 			hookFunc: preReceiveFunc,
 			stopErr:  errors.New("stop error"),
+			hookPath: hookPaths[0],
 		},
 		{
 			desc:     "post-receive gets successfully stopped",
 			hookFunc: postReceiveFunc,
+			hookPath: hookPaths[2],
 		},
 		{
 			desc:     "post-receive with stop error does not clobber real error",
 			hookFunc: postReceiveFunc,
 			stopErr:  errors.New("stop error"),
+			hookPath: hookPaths[2],
 		},
 		{
 			desc:     "update gets successfully stopped",
 			hookFunc: updateFunc,
+			hookPath: hookPaths[1],
 		},
 		{
 			desc:     "update with stop error does not clobber real error",
 			hookFunc: updateFunc,
 			stopErr:  errors.New("stop error"),
+			hookPath: hookPaths[1],
 		},
 	} {
 		t.Run(tc.desc, func(t *testing.T) {
@@ -107,7 +115,7 @@ func TestHookManager_stopCalled(t *testing.T) {
 			}
 
 			err := tc.hookFunc(t)
-			require.Equal(t, "executing custom hooks: exit status 1", err.Error())
+			require.Equal(t, fmt.Sprintf("executing custom hooks: error executing \"%s\": exit status 1", tc.hookPath), err.Error())
 			require.True(t, wasInvoked, "expected stop to have been invoked")
 		})
 	}
diff --git a/internal/gitaly/service/conflicts/resolve_conflicts_test.go b/internal/gitaly/service/conflicts/resolve_conflicts_test.go
index bc752eed4..ce9a7b84e 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)
-	gittest.WriteCustomHook(t, sourceRepoPath, "pre-receive", []byte(script))
+	hookFilename := 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,7 +884,8 @@ func TestResolveConflictsQuarantine(t *testing.T) {
 	}))
 
 	response, err := stream.CloseAndRecv()
-	require.EqualError(t, err, fmt.Sprintf("rpc error: code = Unknown desc = executing custom hooks: exit status 1, stdout: %q",
+	require.EqualError(t, err, fmt.Sprintf("rpc error: code = Unknown desc = executing custom hooks: error executing \"%s\": exit status 1, stdout: %q",
+		hookFilename,
 		`af339cb882d1e3cf8d6751651e58bbaff0265d6e
 tree 89fad81bbfa38070b90ca8f4c404625bf0999013
 parent 29449b1d52cd77fd060a083a1de691bbaf12d8af
diff --git a/internal/gitaly/service/operations/branches_test.go b/internal/gitaly/service/operations/branches_test.go
index 129c066a3..a760ddfd6 100644
--- a/internal/gitaly/service/operations/branches_test.go
+++ b/internal/gitaly/service/operations/branches_test.go
@@ -625,32 +625,32 @@ func TestBranchHookOutput(t *testing.T) {
 		{
 			desc:        "empty stdout and empty stderr",
 			hookContent: "#!/bin/sh\nexit 1",
-			output:      "executing custom hooks: exit status 1",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1",
 		},
 		{
 			desc:        "empty stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stderr: \"stderr\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
 		},
 		{
 			desc:        "some stdout and empty stderr",
 			hookContent: "#!/bin/sh\necho stdout\nexit 1",
-			output:      "executing custom hooks: exit status 1, stdout: \"stdout\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
 		},
 		{
 			desc:        "some stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stderr: \"stderr\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
 		},
 		{
 			desc:        "whitespace stdout and some stderr",
 			hookContent: "#!/bin/sh\necho '   '\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stderr: \"stderr\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
 		},
 		{
 			desc:        "some stdout and whitespace stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho '   ' >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stdout: \"stdout\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
 		},
 	}
 
@@ -670,18 +670,19 @@ func TestBranchHookOutput(t *testing.T) {
 					User:       gittest.TestUser,
 				}
 
-				gittest.WriteCustomHook(t, repoPath, hookName, []byte(testCase.hookContent))
+				hookFilename := gittest.WriteCustomHook(t, repoPath, hookName, []byte(testCase.hookContent))
+				expectedError := fmt.Sprintf(testCase.output, hookFilename)
 
 				createResponse, err := client.UserCreateBranch(ctx, createRequest)
 				require.NoError(t, err)
-				require.Equal(t, testCase.output, createResponse.PreReceiveError)
+				require.Equal(t, expectedError, createResponse.PreReceiveError)
 
 				gittest.Exec(t, cfg, "-C", repoPath, "branch", branchNameInput)
 				defer gittest.Exec(t, cfg, "-C", repoPath, "branch", "-d", branchNameInput)
 
 				deleteResponse, err := client.UserDeleteBranch(ctx, deleteRequest)
 				require.NoError(t, err)
-				require.Equal(t, testCase.output, deleteResponse.PreReceiveError)
+				require.Equal(t, expectedError, deleteResponse.PreReceiveError)
 			})
 		}
 	}
diff --git a/internal/gitaly/service/operations/merge_test.go b/internal/gitaly/service/operations/merge_test.go
index 1d5704725..a8a99332c 100644
--- a/internal/gitaly/service/operations/merge_test.go
+++ b/internal/gitaly/service/operations/merge_test.go
@@ -134,7 +134,7 @@ func TestUserMergeBranch_quarantine(t *testing.T) {
 	// 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)
-	gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(hookScript))
+	hookFilename := gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(hookScript))
 
 	gittest.Exec(t, cfg, "-C", repoPath, "branch", mergeBranchName, mergeBranchHeadBefore)
 
@@ -155,7 +155,7 @@ func TestUserMergeBranch_quarantine(t *testing.T) {
 	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: exit status 1, stdout: \"%s\\n\"", firstResponse.CommitId), err)
+		testassert.GrpcEqualErr(t, helper.ErrInternalf("executing custom hooks: error executing \"%s\": exit status 1, stdout: \"%s\\n\"", hookFilename, firstResponse.CommitId), err)
 		require.Nil(t, secondResponse)
 	} else {
 		require.NoError(t, err, "receive second response")
@@ -457,7 +457,8 @@ func TestUserMergeBranch_failingHooks(t *testing.T) {
 
 			secondResponse, err := mergeBidi.Recv()
 			if featureflag.UserMergeBranchAccessError.IsEnabled(ctx) {
-				testassert.GrpcEqualErr(t, helper.ErrInternalf("executing custom hooks: exit status 1, stdout: \"failure\\n\""), err)
+				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)
 				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 1bf43e6f3..715828e5b 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)
-	gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(script))
+	hookFilename := gittest.WriteCustomHook(t, repoPath, "pre-receive", []byte(script))
 
 	response, err := client.UserCreateTag(ctx, &gitalypb.UserCreateTagRequest{
 		Repository:     repoProto,
@@ -429,7 +429,8 @@ 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: exit status 1, stdout: %q",
+		PreReceiveError: fmt.Sprintf("executing custom hooks: error executing \"%s\": exit status 1, stdout: %q",
+			hookFilename,
 			`object c7fbe50c7c7419d9701eebe64b1fdacc3df5b9dd
 type commit
 tag quarantined-tag
@@ -1338,32 +1339,32 @@ func TestTagHookOutput(t *testing.T) {
 		{
 			desc:        "empty stdout and empty stderr",
 			hookContent: "#!/bin/sh\nexit 1",
-			output:      "executing custom hooks: exit status 1",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1",
 		},
 		{
 			desc:        "empty stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stderr: \"stderr\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
 		},
 		{
 			desc:        "some stdout and empty stderr",
 			hookContent: "#!/bin/sh\necho stdout\nexit 1",
-			output:      "executing custom hooks: exit status 1, stdout: \"stdout\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
 		},
 		{
 			desc:        "some stdout and some stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stderr: \"stderr\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
 		},
 		{
 			desc:        "whitespace stdout and some stderr",
 			hookContent: "#!/bin/sh\necho '   '\necho stderr >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stderr: \"stderr\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stderr: \"stderr\\n\"",
 		},
 		{
 			desc:        "some stdout and whitespace stderr",
 			hookContent: "#!/bin/sh\necho stdout\necho '   ' >&2\nexit 1",
-			output:      "executing custom hooks: exit status 1, stdout: \"stdout\\n\"",
+			output:      "executing custom hooks: error executing \"%s\": exit status 1, stdout: \"stdout\\n\"",
 		},
 	}
 
@@ -1383,7 +1384,8 @@ func TestTagHookOutput(t *testing.T) {
 					User:       gittest.TestUser,
 				}
 
-				gittest.WriteCustomHook(t, repoPath, hookName, []byte(testCase.hookContent))
+				hookFilename := gittest.WriteCustomHook(t, repoPath, hookName, []byte(testCase.hookContent))
+				expectedError := fmt.Sprintf(testCase.output, hookFilename)
 
 				createResponse, err := client.UserCreateTag(ctx, createRequest)
 				require.NoError(t, err)
@@ -1391,7 +1393,7 @@ func TestTagHookOutput(t *testing.T) {
 				createResponseOk := &gitalypb.UserCreateTagResponse{
 					Tag:             createResponse.Tag,
 					Exists:          false,
-					PreReceiveError: testCase.output,
+					PreReceiveError: expectedError,
 				}
 				testassert.ProtoEqual(t, createResponseOk, createResponse)
 
@@ -1401,7 +1403,7 @@ func TestTagHookOutput(t *testing.T) {
 				deleteResponse, err := client.UserDeleteTag(ctx, deleteRequest)
 				require.NoError(t, err)
 				deleteResponseOk := &gitalypb.UserDeleteTagResponse{
-					PreReceiveError: testCase.output,
+					PreReceiveError: expectedError,
 				}
 				testassert.ProtoEqual(t, deleteResponseOk, deleteResponse)
 			})