From a892dda8290d387120f728732285a29ba7c6ed4b Mon Sep 17 00:00:00 2001 From: Johannes Batzill Date: Fri, 12 Jan 2024 20:25:16 +0000 Subject: [PATCH] [CODE-1287] Improve PR Merge for canceled Request (#963) --- app/api/controller/pullreq/locks.go | 65 ++++++++++++++++--- app/api/controller/pullreq/merge.go | 35 +++++++--- app/api/middleware/logging/logging.go | 7 +- contextutil/contextutil.go | 36 ++++++++++ logging/logging.go | 61 +++++++++++++++++ .../PullRequestActionsBox.tsx | 3 +- 6 files changed, 183 insertions(+), 24 deletions(-) create mode 100644 contextutil/contextutil.go create mode 100644 logging/logging.go diff --git a/app/api/controller/pullreq/locks.go b/app/api/controller/pullreq/locks.go index ca76816a7..6adceb47e 100644 --- a/app/api/controller/pullreq/locks.go +++ b/app/api/controller/pullreq/locks.go @@ -15,22 +15,69 @@ package pullreq import ( + "context" + "fmt" "strconv" "time" + "github.com/harness/gitness/contextutil" "github.com/harness/gitness/lock" + "github.com/harness/gitness/logging" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" ) -func (c *Controller) newMutexForPR(repoUID string, pr int64, options ...lock.Option) (lock.Mutex, error) { +func (c *Controller) lockPR( + ctx context.Context, + repoUID string, + prNum int64, + expiry time.Duration, +) (func(), error) { key := repoUID + "/pulls" - if pr != 0 { - key += "/" + strconv.FormatInt(pr, 10) + if prNum != 0 { + key += "/" + strconv.FormatInt(prNum, 10) } - return c.mtxManager.NewMutex( + + // annotate logs for easier debugging of lock related merge issues + // TODO: refactor once common logging annotations are added + ctx = logging.NewContext(ctx, func(c zerolog.Context) zerolog.Context { + return c. + Str("pullreq_lock", key). + Str("repo_uid", repoUID) + }) + + mutex, err := c.mtxManager.NewMutex( key, - append(options, - lock.WithNamespace("repo"), - lock.WithExpiry(16*time.Second), - lock.WithTimeoutFactor(0.25), // 4s - )...) + lock.WithNamespace("repo"), + lock.WithExpiry(expiry), + lock.WithTimeoutFactor(4/expiry.Seconds()), // 4s + ) + if err != nil { + return nil, fmt.Errorf("failed to create new mutex for pr %d in repo %q: %w", prNum, repoUID, err) + } + err = mutex.Lock(ctx) + if err != nil { + return nil, fmt.Errorf("failed to lock mutex for pr %d in repo %q: %w", prNum, repoUID, err) + } + + log.Ctx(ctx).Debug().Msgf("successfully locked PR (expiry: %s)", expiry) + + unlockFn := func() { + // always unlock independent of whether source context got canceled or not + ctx, cancel := context.WithTimeout( + contextutil.WithNewValues(context.Background(), ctx), + 30*time.Second, + ) + defer cancel() + + err := mutex.Unlock(ctx) + if err != nil { + log.Ctx(ctx).Warn().Err(err).Msg("failed to unlock PR") + } else { + log.Ctx(ctx).Debug().Msg("successfully unlocked PR") + } + } + + return unlockFn, nil } diff --git a/app/api/controller/pullreq/merge.go b/app/api/controller/pullreq/merge.go index 6137c7ef0..e48877f5c 100644 --- a/app/api/controller/pullreq/merge.go +++ b/app/api/controller/pullreq/merge.go @@ -27,6 +27,7 @@ import ( pullreqevents "github.com/harness/gitness/app/events/pullreq" "github.com/harness/gitness/app/services/codeowners" "github.com/harness/gitness/app/services/protection" + "github.com/harness/gitness/contextutil" "github.com/harness/gitness/errors" "github.com/harness/gitness/git" gitenum "github.com/harness/gitness/git/enum" @@ -96,21 +97,23 @@ func (c *Controller) Merge( return nil, nil, fmt.Errorf("failed to acquire access to target repo: %w", err) } - // if two requests for merging comes at the same time then mutex will lock + // the max time we give a merge to succeed + const timeout = 3 * time.Minute + + // if two requests for merging comes at the same time then unlock will lock // first one and second one will wait, when first one is done then second one // continue with latest data from db with state merged and return error that // pr is already merged. - mutex, err := c.newMutexForPR(targetRepo.GitUID, 0) // 0 means locks all PRs for this repo + unlock, err := c.lockPR( + ctx, + targetRepo.GitUID, + 0, // 0 means locks all PRs for this repo + timeout+30*time.Second, // add 30s to the lock to give enough time for pre + post merge + ) if err != nil { return nil, nil, err } - err = mutex.Lock(ctx) - if err != nil { - return nil, nil, err - } - defer func() { - _ = mutex.Unlock(ctx) - }() + defer unlock() pr, err := c.pullreqStore.FindByNumber(ctx, targetRepo.ID, pullreqNum) if err != nil { @@ -197,6 +200,16 @@ func (c *Controller) Merge( return nil, nil, fmt.Errorf("failed to verify protection rules: %w", err) } + // we want to complete the merge independent of request cancel - start with new, time restricted context. + // TODO: This is a small change to reduce likelihood of dirty state. + // We still require a proper solution to handle an application crash or very slow execution times + // (which could cause an unlocking pre operation completion). + ctx, cancel := context.WithTimeout( + contextutil.WithNewValues(context.Background(), ctx), + timeout, + ) + defer cancel() + //nolint:nestif if in.DryRun { // As the merge API is always executed under a global lock, we use the opportunity of dry-running the merge @@ -273,6 +286,8 @@ func (c *Controller) Merge( mergeTitle = fmt.Sprintf("Merge branch '%s' of %s (#%d)", pr.SourceBranch, sourceRepo.Path, pr.Number) } + log.Ctx(ctx).Debug().Msgf("all pre-check passed, merge PR") + now := time.Now() mergeOutput, err := c.git.Merge(ctx, &git.MergeParams{ WriteParams: targetWriteParams, @@ -324,6 +339,8 @@ func (c *Controller) Merge( }, nil } + log.Ctx(ctx).Debug().Msgf("successfully merged PR") + var activitySeqMerge, activitySeqBranchDeleted int64 pr, err = c.pullreqStore.UpdateOptLock(ctx, pr, func(pr *types.PullReq) error { pr.State = enum.PullReqStateMerged diff --git a/app/api/middleware/logging/logging.go b/app/api/middleware/logging/logging.go index 17be957ba..8ad5e93b8 100644 --- a/app/api/middleware/logging/logging.go +++ b/app/api/middleware/logging/logging.go @@ -20,9 +20,9 @@ import ( "github.com/harness/gitness/app/api/request" "github.com/harness/gitness/git" + "github.com/harness/gitness/logging" "github.com/rs/xid" - "github.com/rs/zerolog" "github.com/rs/zerolog/hlog" ) @@ -51,10 +51,7 @@ func HLogRequestIDHandler() func(http.Handler) http.Handler { ctx = git.WithRequestID(ctx, reqID) // update logging context with request ID - log := zerolog.Ctx(ctx) - log.UpdateContext(func(c zerolog.Context) zerolog.Context { - return c.Str("request_id", reqID) - }) + logging.UpdateContext(ctx, logging.WithRequestID(reqID)) // write request ID to response headers w.Header().Set(requestIDHeader, reqID) diff --git a/contextutil/contextutil.go b/contextutil/contextutil.go new file mode 100644 index 000000000..b5e16ff4e --- /dev/null +++ b/contextutil/contextutil.go @@ -0,0 +1,36 @@ +// Copyright 2023 Harness, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package contextutil + +import ( + "context" +) + +// WithNewValues creates a new context derived from originalCtx with values from valuesCtx. +func WithNewValues(originalCtx context.Context, valuesCtx context.Context) context.Context { + return &combinedContext{ + Context: originalCtx, + valuesCtx: valuesCtx, + } +} + +type combinedContext struct { + context.Context + valuesCtx context.Context +} + +func (c *combinedContext) Value(key any) any { + return c.valuesCtx.Value(key) +} diff --git a/logging/logging.go b/logging/logging.go new file mode 100644 index 000000000..636bdf960 --- /dev/null +++ b/logging/logging.go @@ -0,0 +1,61 @@ +// Copyright 2023 Harness, Inc. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package logging + +import ( + "context" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" +) + +// Option allows to annotate logs with metadata. +type Option func(c zerolog.Context) zerolog.Context + +// UpdateContext updates the existing logging context in the context. +// IMPORTANT: No new context is created, all future logs with provided context will be impacted. +func UpdateContext(ctx context.Context, opts ...Option) { + // updates existing logging context in provided context.Context + zerolog.Ctx(ctx).UpdateContext(func(c zerolog.Context) zerolog.Context { + for _, opt := range opts { + c = opt(c) + } + + return c + }) +} + +// NewContext derives a new LoggingContext from the existing LoggingContext, adds the provided annotations, +// and then returns a clone of the provided context.Context with the new LoggingContext. +// IMPORTANT: The provided context is not modified, logging annotations are only part of the new context. +func NewContext(ctx context.Context, opts ...Option) context.Context { + // create child of current context + childloggingContext := log.Ctx(ctx).With() + + // update child context + for _, opt := range opts { + childloggingContext = opt(childloggingContext) + } + + // return copied context with new logging context + return childloggingContext.Logger().WithContext(ctx) +} + +// WithRequestID can be used to annotate logs with the request id. +func WithRequestID(reqID string) Option { + return func(c zerolog.Context) zerolog.Context { + return c.Str("request_id", reqID) + } +} diff --git a/web/src/pages/PullRequest/Conversation/PullRequestActionsBox/PullRequestActionsBox.tsx b/web/src/pages/PullRequest/Conversation/PullRequestActionsBox/PullRequestActionsBox.tsx index b97928072..c36ae6329 100644 --- a/web/src/pages/PullRequest/Conversation/PullRequestActionsBox/PullRequestActionsBox.tsx +++ b/web/src/pages/PullRequest/Conversation/PullRequestActionsBox/PullRequestActionsBox.tsx @@ -136,7 +136,8 @@ export const PullRequestActionsBox: React.FC = ({ } else if ( getErrorMessage(err) === codeOwnersNotFoundMessage || getErrorMessage(err) === codeOwnersNotFoundMessage2 || - getErrorMessage(err) === codeOwnersNotFoundMessage3 + getErrorMessage(err) === codeOwnersNotFoundMessage3 || + err.status === 423 // resource locked (merge / dry-run already ongoing) ) { return } else {