From 467a8db96d95848b0ba1c8c8fc1139ee5361c11b Mon Sep 17 00:00:00 2001 From: Patrick Steinhardt Date: Wed, 3 Feb 2021 09:29:40 +0100 Subject: [PATCH 1/6] log: Add missing newline to fatal hook error messages The gitaly-hooks executable uses a special HookLogger because it typically isn't allowed to write to either its stdout nor its stderr as both are potentially used by git itself. It thus writes into a logfile instead as we do not yet have the infrastructure yet to directly relay log messages to the Gitaly server. The exception for this is when a fatal error occurs though: besides logging to the file, gitaly-hooks also prints a single line "error executing git hook". This is then relayed to the server via git's normal stderr and thus shows up in our log messages. The log message is missing a trailing newline though. As a result, generated error messages look for example like: error executing git hookfatal: ref updates aborted by hook This is obviously wrong, so let's fix it by using `fmt.Println()` instead of `fmt.Printf()`. --- internal/log/hook.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/log/hook.go b/internal/log/hook.go index ec4987b541..278049a74e 100644 --- a/internal/log/hook.go +++ b/internal/log/hook.go @@ -41,7 +41,7 @@ func (h *HookLogger) Fatal(err error) { // Fatalf logs a formatted error at the Fatal level func (h *HookLogger) Fatalf(format string, a ...interface{}) { - fmt.Fprintf(os.Stderr, "error executing git hook") + fmt.Fprintln(os.Stderr, "error executing git hook") h.logger.Fatalf(format, a...) } -- GitLab From ce6df597d114687aae34dce089eae181790ec69e Mon Sep 17 00:00:00 2001 From: Patrick Steinhardt Date: Wed, 3 Feb 2021 09:40:20 +0100 Subject: [PATCH 2/6] hook: Pull out primary-only post-receive hook logic This commit refactors the `PostReceiveHook()` implementation and pulls out any logic which is only executed by the primary. This is in preparation of properly stopping transactions if this logic fails. --- internal/gitaly/hook/postreceive.go | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/internal/gitaly/hook/postreceive.go b/internal/gitaly/hook/postreceive.go index 2d7c1cf0c3..2b4d1e74c3 100644 --- a/internal/gitaly/hook/postreceive.go +++ b/internal/gitaly/hook/postreceive.go @@ -126,11 +126,17 @@ func (m *GitLabHookManager) PostReceiveHook(ctx context.Context, repo *gitalypb. return helper.ErrInternalf("reading stdin from request: %w", err) } - if !isPrimary(payload) { - return nil + if isPrimary(payload) { + if err := m.postReceiveHook(ctx, payload, repo, pushOptions, env, changes, stdout, stderr); err != nil { + return err + } } - if len(changes) == 0 { + return nil +} + +func (m *GitLabHookManager) postReceiveHook(ctx context.Context, payload git.HooksPayload, repo *gitalypb.Repository, pushOptions, env []string, stdin []byte, stdout, stderr io.Writer) error { + if len(stdin) == 0 { return helper.ErrInternalf("hook got no reference updates") } @@ -147,7 +153,7 @@ func (m *GitLabHookManager) PostReceiveHook(ctx context.Context, repo *gitalypb. ok, messages, err := m.gitlabAPI.PostReceive( ctx, repo.GetGlRepository(), payload.ReceiveHooksPayload.UserID, - string(changes), + string(stdin), pushOptions..., ) if err != nil { @@ -176,7 +182,7 @@ func (m *GitLabHookManager) PostReceiveHook(ctx context.Context, repo *gitalypb. ctx, nil, customEnv, - bytes.NewReader(changes), + bytes.NewReader(stdin), stdout, stderr, ); err != nil { -- GitLab From eb36617569ae15038ba5d9a52684405330188832 Mon Sep 17 00:00:00 2001 From: Patrick Steinhardt Date: Wed, 3 Feb 2021 09:45:05 +0100 Subject: [PATCH 3/6] hook: Pull out primary-only update hook logic This commit refactors the `UpdateHook()` implementation and pulls out any logic which is only executed by the primary. This is in preparation of properly stopping transactions if this logic fails. --- internal/gitaly/hook/update.go | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/internal/gitaly/hook/update.go b/internal/gitaly/hook/update.go index ce96c55b5b..9e9705d67b 100644 --- a/internal/gitaly/hook/update.go +++ b/internal/gitaly/hook/update.go @@ -15,10 +15,16 @@ func (m *GitLabHookManager) UpdateHook(ctx context.Context, repo *gitalypb.Repos return helper.ErrInternalf("extracting hooks payload: %w", err) } - if !isPrimary(payload) { - return nil + if isPrimary(payload) { + if err := m.updateHook(ctx, payload, repo, ref, oldValue, newValue, env, stdout, stderr); err != nil { + return err + } } + return nil +} + +func (m *GitLabHookManager) updateHook(ctx context.Context, payload git.HooksPayload, repo *gitalypb.Repository, ref, oldValue, newValue string, env []string, stdout, stderr io.Writer) error { if ref == "" { return helper.ErrInternalf("hook got no reference") } -- GitLab From 02e1b93383796ecd7d83973c379b5f985ab7a175 Mon Sep 17 00:00:00 2001 From: Patrick Steinhardt Date: Wed, 3 Feb 2021 09:42:19 +0100 Subject: [PATCH 4/6] hook: Stop transactions when post-receive or update hooks fail The pre-receive, post-receive and update hooks all have logic which will only run on the primary Gitaly node if transactions are in use. This includes the access checks for the pre-receive hook, but also the custom hooks logic implemented for all hooks. Executing custom hooks multiple times for a single change may break current assumptions about how they work in a single-node setup, so we shouldn't execute them multiple times in a Praefect setup either. As only the primary will execute this logic, secondary nodes in a transaction wouldn't know about any potential failures. We have thus implmented a mechanism to gracefully stop transactions in 0d2ea9ff5 (transactions: Allow graceful stop of transactions, 2020-09-25). But right now, this logic is only executed for the pre-receive hook. Considering that primary-only failures can also happen for the post-receive and update hooks, this doesn't make a lot of sense. Let's fix this by stopping transactions on failure of the primary for the post-receive and update hooks, too. While at it, this also unifies error messages when executing custom hooks. --- .../pks-hooks-stop-transactions.yml | 5 + internal/gitaly/hook/postreceive.go | 5 +- internal/gitaly/hook/transactions_test.go | 123 ++++++++++++++++++ internal/gitaly/hook/update.go | 6 +- 4 files changed, 137 insertions(+), 2 deletions(-) create mode 100644 changelogs/unreleased/pks-hooks-stop-transactions.yml create mode 100644 internal/gitaly/hook/transactions_test.go diff --git a/changelogs/unreleased/pks-hooks-stop-transactions.yml b/changelogs/unreleased/pks-hooks-stop-transactions.yml new file mode 100644 index 0000000000..6cbf5acd6c --- /dev/null +++ b/changelogs/unreleased/pks-hooks-stop-transactions.yml @@ -0,0 +1,5 @@ +--- +title: 'hook: Stop transactions when post-receive and update hooks fail' +merge_request: 3094 +author: +type: fixed diff --git a/internal/gitaly/hook/postreceive.go b/internal/gitaly/hook/postreceive.go index 2b4d1e74c3..f42e1db919 100644 --- a/internal/gitaly/hook/postreceive.go +++ b/internal/gitaly/hook/postreceive.go @@ -128,6 +128,9 @@ func (m *GitLabHookManager) PostReceiveHook(ctx context.Context, repo *gitalypb. if isPrimary(payload) { if err := m.postReceiveHook(ctx, payload, repo, pushOptions, env, changes, stdout, stderr); err != nil { + // If the post-receive hook declines the push, then we need to stop any + // secondaries voting on the transaction. + m.stopTransaction(ctx, payload) return err } } @@ -186,7 +189,7 @@ func (m *GitLabHookManager) postReceiveHook(ctx context.Context, payload git.Hoo stdout, stderr, ); err != nil { - return err + return fmt.Errorf("executing custom hooks: %w", err) } return nil diff --git a/internal/gitaly/hook/transactions_test.go b/internal/gitaly/hook/transactions_test.go new file mode 100644 index 0000000000..256e70a7e8 --- /dev/null +++ b/internal/gitaly/hook/transactions_test.go @@ -0,0 +1,123 @@ +package hook + +import ( + "context" + "errors" + "io/ioutil" + "strings" + "testing" + + "github.com/stretchr/testify/require" + "gitlab.com/gitlab-org/gitaly/internal/git" + "gitlab.com/gitlab-org/gitaly/internal/gitaly/config" + "gitlab.com/gitlab-org/gitaly/internal/praefect/metadata" + "gitlab.com/gitlab-org/gitaly/internal/testhelper" +) + +type mockTransactionManager struct { + stop func(context.Context, metadata.Transaction, metadata.PraefectServer) error +} + +func (m *mockTransactionManager) Vote(context.Context, metadata.Transaction, metadata.PraefectServer, []byte) error { + return nil +} + +func (m *mockTransactionManager) Stop(ctx context.Context, tx metadata.Transaction, praefect metadata.PraefectServer) error { + return m.stop(ctx, tx, praefect) +} + +func TestHookManager_stopCalled(t *testing.T) { + expectedTx := metadata.Transaction{ + ID: 1234, Node: "primary", Primary: true, + } + + expectedPraefect := metadata.PraefectServer{ + SocketPath: "socket", + Token: "foo", + } + + repo, repoPath, cleanup := testhelper.NewTestRepo(t) + defer cleanup() + + var mockTxMgr mockTransactionManager + hookManager := NewManager(config.NewLocator(config.Config), &mockTxMgr, GitlabAPIStub, config.Config) + + hooksPayload, err := git.NewHooksPayload( + config.Config, + repo, + &expectedTx, + &expectedPraefect, + &git.ReceiveHooksPayload{ + UserID: "1234", + Username: "user", + Protocol: "web", + }, + ).Env() + require.NoError(t, err) + + ctx, cleanup := testhelper.Context() + defer cleanup() + + for _, hook := range []string{"pre-receive", "update", "post-receive"} { + cleanup = testhelper.WriteCustomHook(t, repoPath, hook, []byte("#!/bin/sh\nexit 1\n")) + defer cleanup() + } + + preReceiveFunc := func(t *testing.T) error { + return hookManager.PreReceiveHook(ctx, repo, nil, []string{hooksPayload}, strings.NewReader("changes"), ioutil.Discard, ioutil.Discard) + } + updateFunc := func(t *testing.T) error { + return hookManager.UpdateHook(ctx, repo, "ref", git.ZeroOID.String(), git.ZeroOID.String(), []string{hooksPayload}, ioutil.Discard, ioutil.Discard) + } + postReceiveFunc := func(t *testing.T) error { + return hookManager.PostReceiveHook(ctx, repo, nil, []string{hooksPayload}, strings.NewReader("changes"), ioutil.Discard, ioutil.Discard) + } + + for _, tc := range []struct { + desc string + hookFunc func(*testing.T) error + stopErr error + }{ + { + desc: "pre-receive gets successfully stopped", + hookFunc: preReceiveFunc, + }, + { + desc: "pre-receive with stop error does not clobber real error", + hookFunc: preReceiveFunc, + stopErr: errors.New("stop error"), + }, + { + desc: "post-receive gets successfully stopped", + hookFunc: postReceiveFunc, + }, + { + desc: "post-receive with stop error does not clobber real error", + hookFunc: postReceiveFunc, + stopErr: errors.New("stop error"), + }, + { + desc: "update gets successfully stopped", + hookFunc: updateFunc, + }, + { + desc: "update with stop error does not clobber real error", + hookFunc: updateFunc, + stopErr: errors.New("stop error"), + }, + } { + t.Run(tc.desc, func(t *testing.T) { + wasInvoked := false + mockTxMgr.stop = func(ctx context.Context, tx metadata.Transaction, praefect metadata.PraefectServer) error { + require.Equal(t, expectedTx, tx) + require.Equal(t, expectedPraefect, praefect) + wasInvoked = true + return tc.stopErr + } + + err := tc.hookFunc(t) + require.Equal(t, "executing custom hooks: exit status 1", err.Error()) + require.True(t, wasInvoked, "expected stop to have been invoked") + }) + } +} diff --git a/internal/gitaly/hook/update.go b/internal/gitaly/hook/update.go index 9e9705d67b..5005735054 100644 --- a/internal/gitaly/hook/update.go +++ b/internal/gitaly/hook/update.go @@ -2,6 +2,7 @@ package hook import ( "context" + "fmt" "io" "gitlab.com/gitlab-org/gitaly/internal/git" @@ -17,6 +18,9 @@ func (m *GitLabHookManager) UpdateHook(ctx context.Context, repo *gitalypb.Repos if isPrimary(payload) { if err := m.updateHook(ctx, payload, repo, ref, oldValue, newValue, env, stdout, stderr); err != nil { + // If the update hook declines the push, then we need + // to stop any secondaries voting on the transaction. + m.stopTransaction(ctx, payload) return err } } @@ -56,7 +60,7 @@ func (m *GitLabHookManager) updateHook(ctx context.Context, payload git.HooksPay stdout, stderr, ); err != nil { - return err + return fmt.Errorf("executing custom hooks: %w", err) } return nil -- GitLab From 351494103c7cdfa16d87cfe7e9781254acb98e0a Mon Sep 17 00:00:00 2001 From: Patrick Steinhardt Date: Wed, 3 Feb 2021 09:43:15 +0100 Subject: [PATCH 5/6] hook: Log when transactions are about to be stopped It's currently hard to observe why a transaction was stopped as there is not a single log entry which gets generated when we are stopping. This commit fixes this shortcoming by adding log messages to all three cases where we gracefully stop transactions. --- internal/gitaly/hook/postreceive.go | 3 +++ internal/gitaly/hook/prereceive.go | 3 +++ internal/gitaly/hook/update.go | 3 +++ 3 files changed, 9 insertions(+) diff --git a/internal/gitaly/hook/postreceive.go b/internal/gitaly/hook/postreceive.go index f42e1db919..0372dc625f 100644 --- a/internal/gitaly/hook/postreceive.go +++ b/internal/gitaly/hook/postreceive.go @@ -10,6 +10,7 @@ import ( "math" "strings" + "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus" "gitlab.com/gitlab-org/gitaly/internal/git" "gitlab.com/gitlab-org/gitaly/internal/helper" "gitlab.com/gitlab-org/gitaly/proto/go/gitalypb" @@ -128,6 +129,8 @@ func (m *GitLabHookManager) PostReceiveHook(ctx context.Context, repo *gitalypb. if isPrimary(payload) { if err := m.postReceiveHook(ctx, payload, repo, pushOptions, env, changes, stdout, stderr); err != nil { + ctxlogrus.Extract(ctx).WithError(err).Warn("stopping transaction because post-receive hook failed") + // If the post-receive hook declines the push, then we need to stop any // secondaries voting on the transaction. m.stopTransaction(ctx, payload) diff --git a/internal/gitaly/hook/prereceive.go b/internal/gitaly/hook/prereceive.go index 8e5ce6f9c5..2c3cfb4eba 100644 --- a/internal/gitaly/hook/prereceive.go +++ b/internal/gitaly/hook/prereceive.go @@ -10,6 +10,7 @@ import ( "path/filepath" "strings" + "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus" "gitlab.com/gitlab-org/gitaly/internal/git" "gitlab.com/gitlab-org/gitaly/internal/helper" "gitlab.com/gitlab-org/gitaly/proto/go/gitalypb" @@ -67,6 +68,8 @@ func (m *GitLabHookManager) PreReceiveHook(ctx context.Context, repo *gitalypb.R // Only the primary should execute hooks and increment reference counters. if isPrimary(payload) { if err := m.preReceiveHook(ctx, payload, repo, pushOptions, env, changes, stdout, stderr); err != nil { + ctxlogrus.Extract(ctx).WithError(err).Warn("stopping transaction because pre-receive hook failed") + // If the pre-receive hook declines the push, then we need to stop any // secondaries voting on the transaction. m.stopTransaction(ctx, payload) diff --git a/internal/gitaly/hook/update.go b/internal/gitaly/hook/update.go index 5005735054..daa21ecf1a 100644 --- a/internal/gitaly/hook/update.go +++ b/internal/gitaly/hook/update.go @@ -5,6 +5,7 @@ import ( "fmt" "io" + "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus" "gitlab.com/gitlab-org/gitaly/internal/git" "gitlab.com/gitlab-org/gitaly/internal/helper" "gitlab.com/gitlab-org/gitaly/proto/go/gitalypb" @@ -18,6 +19,8 @@ func (m *GitLabHookManager) UpdateHook(ctx context.Context, repo *gitalypb.Repos if isPrimary(payload) { if err := m.updateHook(ctx, payload, repo, ref, oldValue, newValue, env, stdout, stderr); err != nil { + ctxlogrus.Extract(ctx).WithError(err).Warn("stopping transaction because update hook failed") + // If the update hook declines the push, then we need // to stop any secondaries voting on the transaction. m.stopTransaction(ctx, payload) -- GitLab From 9a9ac34fce75a90c3e26485ec49d929ed0390cd4 Mon Sep 17 00:00:00 2001 From: Patrick Steinhardt Date: Wed, 3 Feb 2021 17:05:12 +0100 Subject: [PATCH 6/6] hook: Log errors when stopping transactions fails When we have to stop transactions because some primary-specific logic has failed, then we currently completely ignore any errors which happen when stopping the transaction itself. We can't really help this given that the initial error is the actual root cause and thus the error we want to return. But we can at least improve the code by logging those issues. --- internal/gitaly/hook/postreceive.go | 5 ++++- internal/gitaly/hook/prereceive.go | 5 ++++- internal/gitaly/hook/update.go | 5 ++++- 3 files changed, 12 insertions(+), 3 deletions(-) diff --git a/internal/gitaly/hook/postreceive.go b/internal/gitaly/hook/postreceive.go index 0372dc625f..6ab89ecddd 100644 --- a/internal/gitaly/hook/postreceive.go +++ b/internal/gitaly/hook/postreceive.go @@ -133,7 +133,10 @@ func (m *GitLabHookManager) PostReceiveHook(ctx context.Context, repo *gitalypb. // If the post-receive hook declines the push, then we need to stop any // secondaries voting on the transaction. - m.stopTransaction(ctx, payload) + if err := m.stopTransaction(ctx, payload); err != nil { + ctxlogrus.Extract(ctx).WithError(err).Error("failed stopping transaction in post-receive hook") + } + return err } } diff --git a/internal/gitaly/hook/prereceive.go b/internal/gitaly/hook/prereceive.go index 2c3cfb4eba..41dc8aca75 100644 --- a/internal/gitaly/hook/prereceive.go +++ b/internal/gitaly/hook/prereceive.go @@ -72,7 +72,10 @@ func (m *GitLabHookManager) PreReceiveHook(ctx context.Context, repo *gitalypb.R // If the pre-receive hook declines the push, then we need to stop any // secondaries voting on the transaction. - m.stopTransaction(ctx, payload) + if err := m.stopTransaction(ctx, payload); err != nil { + ctxlogrus.Extract(ctx).WithError(err).Error("failed stopping transaction in pre-receive hook") + } + return err } } diff --git a/internal/gitaly/hook/update.go b/internal/gitaly/hook/update.go index daa21ecf1a..d8910b0552 100644 --- a/internal/gitaly/hook/update.go +++ b/internal/gitaly/hook/update.go @@ -23,7 +23,10 @@ func (m *GitLabHookManager) UpdateHook(ctx context.Context, repo *gitalypb.Repos // If the update hook declines the push, then we need // to stop any secondaries voting on the transaction. - m.stopTransaction(ctx, payload) + if err := m.stopTransaction(ctx, payload); err != nil { + ctxlogrus.Extract(ctx).WithError(err).Error("failed stopping transaction in update hook") + } + return err } } -- GitLab