[CODE-1287] Improve PR Merge for canceled Request (#963)

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
 }

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

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)

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)
+}

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)
+	}
+}

web/src/pages/PullRequest/Conversation/PullRequestActionsBox/PullRequestActionsBox.tsx

@@ -136,7 +136,8 @@ export const PullRequestActionsBox: React.FC<PullRequestActionsBoxProps> = ({
           } 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 {