diff --git a/changelogs/unreleased/48132-display-output-from-pre-receive-scripts.yml b/changelogs/unreleased/48132-display-output-from-pre-receive-scripts.yml new file mode 100644 index 0000000000000000000000000000000000000000..04b1f270203125913f8fc6cade54d4ab7c3eb32f --- /dev/null +++ b/changelogs/unreleased/48132-display-output-from-pre-receive-scripts.yml @@ -0,0 +1,5 @@ +--- +title: Only return sanitized errors for Custom Hooks +merge_request: 1101 +author: +type: changed diff --git a/internal/service/operations/branches_test.go b/internal/service/operations/branches_test.go index 7b6597afd93d5219055cc8b52c235545bfb9a5a8..325cdcddabfabf64ab8880e8630e594cccee0b8d 100644 --- a/internal/service/operations/branches_test.go +++ b/internal/service/operations/branches_test.go @@ -131,7 +131,7 @@ func TestFailedUserCreateBranchDueToHooks(t *testing.T) { } // Write a hook that will fail with the environment as the error message // so we can check that string for our env variables. - hookContent := []byte("#!/bin/sh\nprintenv | paste -sd ' ' -\nexit 1") + hookContent := []byte("#!/bin/sh\nprintenv | sed -e 's/^/GitLab: /' | paste -sd ' ' -\nexit 1") for _, hookName := range gitlabPreHooks { remove, err := OverrideHooks(hookName, hookContent) @@ -386,7 +386,7 @@ func TestFailedUserDeleteBranchDueToHooks(t *testing.T) { User: user, } - hookContent := []byte("#!/bin/sh\necho GL_ID=$GL_ID\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range gitlabPreHooks { t.Run(hookName, func(t *testing.T) { @@ -397,9 +397,8 @@ func TestFailedUserDeleteBranchDueToHooks(t *testing.T) { ctx, cancel := testhelper.Context() defer cancel() - response, err := client.UserDeleteBranch(ctx, request) + _, err = client.UserDeleteBranch(ctx, request) require.Nil(t, err) - require.Contains(t, response.PreReceiveError, "GL_ID="+user.GlId) branches := testhelper.MustRunCommand(t, nil, "git", "-C", testRepoPath, "branch") require.Contains(t, string(branches), branchNameInput, "branch name does not exist in branches list") diff --git a/internal/service/operations/cherry_pick_test.go b/internal/service/operations/cherry_pick_test.go index bc3609c725992ae7a8bf231102aa836f5362fd86..e96a4851c295addb2074f0d59a88a9b9fa81c447 100644 --- a/internal/service/operations/cherry_pick_test.go +++ b/internal/service/operations/cherry_pick_test.go @@ -294,7 +294,7 @@ func TestFailedUserCherryPickRequestDueToPreReceiveError(t *testing.T) { Message: []byte("Cherry-picking " + cherryPickedCommit.Id), } - hookContent := []byte("#!/bin/sh\necho GL_ID=$GL_ID\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range operations.GitlabPreHooks { t.Run(hookName, func(t *testing.T) { @@ -305,9 +305,8 @@ func TestFailedUserCherryPickRequestDueToPreReceiveError(t *testing.T) { md := testhelper.GitalyServersMetadata(t, serverSocketPath) ctx := metadata.NewOutgoingContext(ctxOuter, md) - response, err := client.UserCherryPick(ctx, request) + _, err = client.UserCherryPick(ctx, request) require.NoError(t, err) - require.Contains(t, response.PreReceiveError, "GL_ID="+user.GlId) }) } } diff --git a/internal/service/operations/commit_files_test.go b/internal/service/operations/commit_files_test.go index 3026c431d56ea1b0d8dd37b2474ff3fd7d2a7e2b..27583a0247488999517e078c1d53c28fd096eec7 100644 --- a/internal/service/operations/commit_files_test.go +++ b/internal/service/operations/commit_files_test.go @@ -219,7 +219,7 @@ func TestFailedUserCommitFilesRequestDueToHooks(t *testing.T) { headerRequest := headerRequest(testRepo, user, branchName, commitFilesMessage) actionsRequest1 := createFileHeaderRequest(filePath) actionsRequest2 := actionContentRequest("My content") - hookContent := []byte("#!/bin/sh\nprintenv | paste -sd ' ' -\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range operations.GitlabPreHooks { t.Run(hookName, func(t *testing.T) { @@ -235,11 +235,8 @@ func TestFailedUserCommitFilesRequestDueToHooks(t *testing.T) { require.NoError(t, stream.Send(actionsRequest1)) require.NoError(t, stream.Send(actionsRequest2)) - r, err := stream.CloseAndRecv() + _, err = stream.CloseAndRecv() require.NoError(t, err) - - require.Contains(t, r.PreReceiveError, "GL_ID="+user.GlId) - require.Contains(t, r.PreReceiveError, "GL_USERNAME="+user.GlUsername) }) } } diff --git a/internal/service/operations/custom_hook_integration_test.go b/internal/service/operations/custom_hook_integration_test.go new file mode 100644 index 0000000000000000000000000000000000000000..15f28e8ea066255cd25b42035f9e16ebae1a46c1 --- /dev/null +++ b/internal/service/operations/custom_hook_integration_test.go @@ -0,0 +1,144 @@ +package operations + +import ( + "context" + "os/exec" + "testing" + + "github.com/stretchr/testify/require" + "gitlab.com/gitlab-org/gitaly-proto/go/gitalypb" + "gitlab.com/gitlab-org/gitaly/internal/testhelper" +) + +var testCases = []struct { + scriptContent string + responseContains []string // strings we expect to be contained + responseNotContains []string // strings we should not see in PreReceiveError +}{ + { + "echo \"msg to STDOUT\";", + []string{}, + []string{"msg to STDOUT"}, + }, + { + "echo \"GitLab: msg to STDOUT\";", + []string{"msg to STDOUT"}, + []string{}, + }, + { + "echo \"gitlab: msg to STDOUT\";", // case-insensitive match on prefix + []string{"msg to STDOUT"}, + []string{}, + }, + { + "echo \"GitLab: msg to STDOUT\na second line\";", + []string{"msg to STDOUT"}, + []string{"a second line"}, + }, + { + "echo \"GitLab:msg to STDOUT\";", // no whitespace separation from prefix + []string{"msg to STDOUT"}, + []string{}, + }, + { + "echo \"msg to STDOUT, not prefixed by GitLab:, but containing it\";", + []string{}, + []string{"msg to STDOUT, not prefixed by GitLab:, but containing it"}, + }, + { + "1>&2 echo \"GitLab: msg to STDERR\";", + []string{"msg to STDERR"}, + []string{}, + }, + { + "1>&2 echo \"msg to STDERR, not prefixed by GitLab, but containing it\";", + []string{}, + []string{"msg to STDERR, not prefixed by GitLab:, but containing it"}, + }, +} + +func TestCustomHookResponseWhenHooksFail(t *testing.T) { + testRepo, _, cleanupFn := testhelper.NewTestRepo(t) + defer cleanupFn() + + server, serverSocketPath := runOperationServiceServer(t) + defer server.Stop() + + client, conn := newOperationClient(t, serverSocketPath) + defer conn.Close() + + request := &gitalypb.UserCreateBranchRequest{ + Repository: testRepo, + BranchName: []byte("new-branch"), + StartPoint: []byte("c7fbe50c7c7419d9701eebe64b1fdacc3df5b9dd"), + User: user, + } + + for _, testCase := range testCases { + script := testhelper.FailingHookScript(testCase.scriptContent) + + for _, hookName := range gitlabPreHooks { + remove, err := OverrideHooks(hookName, []byte(script)) + + require.NoError(t, err) + defer remove() + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + response, err := client.UserCreateBranch(ctx, request) + require.NoError(t, err) + + for _, msg := range testCase.responseContains { + require.Contains(t, response.PreReceiveError, msg) + } + + for _, msg := range testCase.responseNotContains { + require.NotContains(t, response.PreReceiveError, msg) + } + } + } +} + +func TestCustomHookResponseWhenHooksSucceed(t *testing.T) { + testRepo, testRepoPath, cleanupFn := testhelper.NewTestRepo(t) + defer cleanupFn() + + server, serverSocketPath := runOperationServiceServer(t) + defer server.Stop() + + client, conn := newOperationClient(t, serverSocketPath) + defer conn.Close() + + branchName := "new-branch" + + request := &gitalypb.UserCreateBranchRequest{ + Repository: testRepo, + BranchName: []byte(branchName), + StartPoint: []byte("c7fbe50c7c7419d9701eebe64b1fdacc3df5b9dd"), + User: user, + } + + for _, testCase := range testCases { + script := testhelper.SuccessfulHookScript(testCase.scriptContent) + + for _, hookName := range gitlabPreHooks { + t.Run(hookName, func(t *testing.T) { + defer exec.Command("git", "-C", testRepoPath, "branch", "-D", branchName).Run() + + remove, err := OverrideHooks(hookName, []byte(script)) + require.NoError(t, err) + defer remove() + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + response, err := client.UserCreateBranch(ctx, request) + require.NoError(t, err) + + // response.PreReceiveError is always empty when script exits with success + require.Empty(t, response.PreReceiveError) + }) + } + } +} diff --git a/internal/service/operations/merge_test.go b/internal/service/operations/merge_test.go index aab11c5d97ae04bdaa29324c7f2ed10c6e74a3ae..b242cf18ce7f3306b58a35075c2fb9aff99218f0 100644 --- a/internal/service/operations/merge_test.go +++ b/internal/service/operations/merge_test.go @@ -231,7 +231,7 @@ func TestFailedMergeDueToHooks(t *testing.T) { prepareMergeBranch(t, testRepoPath) - hookContent := []byte("#!/bin/sh\necho 'failure'\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range gitlabPreHooks { t.Run(hookName, func(t *testing.T) { @@ -262,9 +262,8 @@ func TestFailedMergeDueToHooks(t *testing.T) { require.NoError(t, mergeBidi.Send(&gitalypb.UserMergeBranchRequest{Apply: true}), "apply merge") require.NoError(t, mergeBidi.CloseSend(), "close send") - secondResponse, err := mergeBidi.Recv() + _, err = mergeBidi.Recv() require.NoError(t, err, "receive second response") - require.Contains(t, secondResponse.PreReceiveError, "failure") err = consumeEOF(func() error { _, err = mergeBidi.Recv() @@ -435,7 +434,7 @@ func TestFailedUserFFBranchDueToHooks(t *testing.T) { testhelper.MustRunCommand(t, nil, "git", "-C", testRepoPath, "branch", "-f", branchName, "6d394385cf567f80a8fd85055db1ab4c5295806f") defer exec.Command("git", "-C", testRepoPath, "branch", "-d", branchName).Run() - hookContent := []byte("#!/bin/sh\necho 'failure'\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range gitlabPreHooks { t.Run(hookName, func(t *testing.T) { @@ -446,9 +445,8 @@ func TestFailedUserFFBranchDueToHooks(t *testing.T) { ctx, cancel := testhelper.Context() defer cancel() - resp, err := client.UserFFBranch(ctx, request) + _, err = client.UserFFBranch(ctx, request) require.Nil(t, err) - require.Contains(t, resp.PreReceiveError, "failure") }) } } @@ -668,7 +666,7 @@ func TestUserMergeToRefFailedDueToHooksRequest(t *testing.T) { Message: []byte(mergeCommitMessage), } - hookContent := []byte("#!/bin/sh\necho 'failure'\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range gitlabPreHooks { t.Run(hookName, func(t *testing.T) { @@ -679,9 +677,8 @@ func TestUserMergeToRefFailedDueToHooksRequest(t *testing.T) { ctx, cancel := testhelper.Context() defer cancel() - resp, err := client.UserMergeToRef(ctx, request) + _, err = client.UserMergeToRef(ctx, request) require.Nil(t, err) - require.Contains(t, resp.PreReceiveError, "failure") }) } } diff --git a/internal/service/operations/rebase_test.go b/internal/service/operations/rebase_test.go index 0ac8eb44f4b98199bf789e71ce4c477cfeb60bb6..984873d96a3aeb28cae88a0795cd1eab4e8a1dae 100644 --- a/internal/service/operations/rebase_test.go +++ b/internal/service/operations/rebase_test.go @@ -97,7 +97,7 @@ func TestFailedUserRebaseRequestDueToPreReceiveError(t *testing.T) { RemoteBranch: []byte("master"), } - hookContent := []byte("#!/bin/sh\necho GL_ID=$GL_ID\nexit 1\n") + hookContent := []byte("#!/bin/sh\nexit 1\n") for i, hookName := range operations.GitlabPreHooks { t.Run(hookName, func(t *testing.T) { remove, err := operations.OverrideHooks(hookName, hookContent) @@ -108,9 +108,8 @@ func TestFailedUserRebaseRequestDueToPreReceiveError(t *testing.T) { ctx := metadata.NewOutgoingContext(ctxOuter, md) request.RebaseId = fmt.Sprintf("%d", i+1) - response, err := client.UserRebase(ctx, request) + _, err = client.UserRebase(ctx, request) require.NoError(t, err) - require.Contains(t, response.PreReceiveError, "GL_ID="+user.GlId) }) } } diff --git a/internal/service/operations/revert_test.go b/internal/service/operations/revert_test.go index 621b858dec1fec8817455cc12734454fa70d3096..e78106befcf57a6a82dfdec5c6960a0a41fa3b8e 100644 --- a/internal/service/operations/revert_test.go +++ b/internal/service/operations/revert_test.go @@ -291,7 +291,7 @@ func TestFailedUserRevertRequestDueToPreReceiveError(t *testing.T) { Message: []byte("Reverting " + revertedCommit.Id), } - hookContent := []byte("#!/bin/sh\necho GL_ID=$GL_ID\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range operations.GitlabPreHooks { t.Run(hookName, func(t *testing.T) { @@ -302,9 +302,8 @@ func TestFailedUserRevertRequestDueToPreReceiveError(t *testing.T) { md := testhelper.GitalyServersMetadata(t, serverSocketPath) ctx := metadata.NewOutgoingContext(ctxOuter, md) - response, err := client.UserRevert(ctx, request) + _, err = client.UserRevert(ctx, request) require.NoError(t, err) - require.Contains(t, response.PreReceiveError, "GL_ID="+user.GlId) }) } } diff --git a/internal/service/operations/tags_test.go b/internal/service/operations/tags_test.go index b458fb00096ebe8e3d0e2904c7ebc182ec780907..e74f805f3cc3f05872d00c2141c5ac2682128f7c 100644 --- a/internal/service/operations/tags_test.go +++ b/internal/service/operations/tags_test.go @@ -321,9 +321,8 @@ func TestFailedUserDeleteTagDueToHooks(t *testing.T) { ctx, cancel := testhelper.Context() defer cancel() - response, err := client.UserDeleteTag(ctx, request) + _, err = client.UserDeleteTag(ctx, request) require.Nil(t, err) - require.Contains(t, response.PreReceiveError, "GL_ID="+user.GlId) tags := testhelper.MustRunCommand(t, nil, "git", "-C", testRepoPath, "tag") require.Contains(t, string(tags), tagNameInput, "tag name does not exist in tags list") @@ -354,7 +353,7 @@ func TestFailedUserCreateTagDueToHooks(t *testing.T) { User: user, } - hookContent := []byte("#!/bin/sh\necho GL_ID=$GL_ID\nexit 1") + hookContent := []byte("#!/bin/sh\nexit 1") for _, hookName := range gitlabPreHooks { remove, err := OverrideHooks(hookName, hookContent) @@ -364,9 +363,8 @@ func TestFailedUserCreateTagDueToHooks(t *testing.T) { ctx, cancel := testhelper.Context() defer cancel() - response, err := client.UserCreateTag(ctx, request) + _, err = client.UserCreateTag(ctx, request) require.Nil(t, err) - require.Contains(t, response.PreReceiveError, "GL_ID="+user.GlId) } } diff --git a/internal/service/operations/update_branches_test.go b/internal/service/operations/update_branches_test.go index 8dd910dc9785cac95544bc2a3d460d98a8e704e2..5d17065eba2deeead1217ace8acf138c881bfa20 100644 --- a/internal/service/operations/update_branches_test.go +++ b/internal/service/operations/update_branches_test.go @@ -106,7 +106,7 @@ func TestFailedUserUpdateBranchDueToHooks(t *testing.T) { } // Write a hook that will fail with the environment as the error message // so we can check that string for our env variables. - hookContent := []byte("#!/bin/sh\nprintenv | paste -sd ' ' -\nexit 1") + hookContent := []byte("#!/bin/sh\nprintenv | sed -e 's/^/GitLab: /' | paste -sd ' ' -\nexit 1") for _, hookName := range gitlabPreHooks { remove, err := OverrideHooks(hookName, hookContent) diff --git a/internal/testhelper/hook_script.go b/internal/testhelper/hook_script.go new file mode 100644 index 0000000000000000000000000000000000000000..86b1ea60c50bcae0b2ba42805108fb4b1356f442 --- /dev/null +++ b/internal/testhelper/hook_script.go @@ -0,0 +1,22 @@ +package testhelper + +import "fmt" + +const scriptWrapper = ` +#!/bin/sh\ +%s +exit %d` + +// SuccessfulHookScript creates a bash script that will exit with a success code +func SuccessfulHookScript(scriptContent string) string { + return script(scriptContent, 0) +} + +// FailingHookScript creates a bash script that will exit with a failure code +func FailingHookScript(scriptContent string) string { + return script(scriptContent, 1) +} + +func script(scriptContent string, exitCode int8) string { + return fmt.Sprintf(scriptWrapper, scriptContent, exitCode) +} diff --git a/ruby/lib/gitlab/git/hook.rb b/ruby/lib/gitlab/git/hook.rb index 1b2979cc276af7a38ce9ee5210b89b3a3704cbcd..48126dc6075d37d373809e3254977f0c4b761315 100644 --- a/ruby/lib/gitlab/git/hook.rb +++ b/ruby/lib/gitlab/git/hook.rb @@ -8,6 +8,12 @@ module Gitlab end GL_PROTOCOL = 'web' + + SAFE_MESSAGE_PREFIX = 'GitLab:' + SAFE_MESSAGE_REGEX = Regexp.new("^#{SAFE_MESSAGE_PREFIX}\s*(?.+)", Regexp::IGNORECASE) + + ERROR_LOG_FORMAT = '%s hook error in repository %s: %s' + attr_reader :name, :path, :repository def initialize(name, repository) @@ -68,9 +74,18 @@ module Gitlab stdin.close + # Reading from pipes needs to be non-blocking to avoid deadlocks + out_reader = Thread.new { stdout.read } + err_reader = Thread.new { stderr.read } + + stdout_messages = out_reader.value + stderr_messages = err_reader.value + + log_error(stderr_messages) + unless wait_thr.value == 0 exit_status = false - exit_message = retrieve_error_message(stderr, stdout) + exit_message = retrieve_safe_messages(stdout_messages + stderr_messages) end end @@ -87,13 +102,41 @@ module Gitlab vars = env_base_vars(gl_id, gl_username) stdout, stderr, status = Open3.capture3(vars, path, *args, options) - [status.success?, stderr.presence || stdout] + + log_error(stderr) + + exit_message = if status.success? + nil + else + retrieve_safe_messages(stdout + stderr) + end + + [status.success?, exit_message] + end + + def retrieve_safe_messages(messages) + lines = messages.split("\n").map do |msg| + if (match = msg.match(SAFE_MESSAGE_REGEX)) + match[:safe_message] + end + end.compact + + lines.join("\n") end - def retrieve_error_message(stderr, stdout) - err_message = stderr.read - err_message = err_message.blank? ? stdout.read : err_message - err_message + def log_error(errors) + return unless errors.present? + + errors.split("\n").each do |error| + message = format( + ERROR_LOG_FORMAT, + @name, + @repository.relative_path, + error + ) + + Gitlab::GitLogger.error(message) + end end def env_base_vars(gl_id, gl_username) diff --git a/ruby/spec/lib/gitlab/git/hook_spec.rb b/ruby/spec/lib/gitlab/git/hook_spec.rb index 2e1551ba106285571ff4f72dc67d81c5e71d5f15..c437bab6c39dc49366b8a3aa9d606e66f7b59f6a 100644 --- a/ruby/spec/lib/gitlab/git/hook_spec.rb +++ b/ruby/spec/lib/gitlab/git/hook_spec.rb @@ -92,5 +92,94 @@ describe Gitlab::Git::Hook do end end end + + describe 'sanitizing hook output' do + let(:trigger_hook) do + lambda do |hook| + described_class.new(hook, repo).trigger('user-456', 'admin', '0' * 40, 'a' * 40, 'master') + end + end + + context 'when the hooks are successful' do + let(:script) { stdout_stderr_script(exit_code: 0) } + + it 'does not return a message' do + hook_names.each do |hook| + silence_error_log + + trigger_result = trigger_hook[hook] + + expect(trigger_result.last).to be_nil + end + end + + it 'logs all stderr to the error log' do + hook_names.each do |hook| + error_message = format( + Gitlab::Git::Hook::ERROR_LOG_FORMAT, + hook, + repo.relative_path, + 'GitLab: prefixed msg to STDERR' + ) + + expect(Gitlab::GitLogger).to receive(:error).with(error_message) + + trigger_hook[hook] + end + end + end + + context 'when the hooks fail' do + let(:script) { stdout_stderr_script(exit_code: 1) } + + it 'only returns messages that were marked as safe' do + hook_names.each do |hook| + silence_error_log + + trigger_result = trigger_hook[hook] + + expect(trigger_result.last).to eq( + "prefixed msg to STDOUT\na second safe message with no whitespace separation\nprefixed msg to STDERR" + ) + end + end + + it 'logs all stderr to the error log' do + hook_names.each do |hook| + error_message = format( + Gitlab::Git::Hook::ERROR_LOG_FORMAT, + hook, + repo.relative_path, + 'GitLab: prefixed msg to STDERR' + ) + + expect(Gitlab::GitLogger).to receive(:error).with(error_message) + + trigger_hook[hook] + end + end + end + end + + private + + def stdout_stderr_script(exit_code:) + <<-SCRIPT + #!/bin/sh + echo "msg to STDOUT"; + 1>&2 echo "#{Gitlab::Git::Hook::SAFE_MESSAGE_PREFIX} prefixed msg to STDERR"; + echo "#{Gitlab::Git::Hook::SAFE_MESSAGE_PREFIX} prefixed msg to STDOUT\nwith a second line"; + echo "#{Gitlab::Git::Hook::SAFE_MESSAGE_PREFIX}a second safe message with no whitespace separation"; + echo "not prefixed by, but containing, #{Gitlab::Git::Hook::SAFE_MESSAGE_PREFIX}"; + exit #{exit_code} + SCRIPT + end + + # Call before tests of scripts that write to stderr, when stderr is + # not a subject of a test. This prevents the error from appearing in + # rspec's output when rspec is running + def silence_error_log + expect(Gitlab::GitLogger).to receive(:error) + end end end