fix(gitter): Add more logs and retry for index.lock

go/cmd/gitter/gitter.go

@@ -17,6 +17,7 @@
 	"os/exec"
 	"os/signal"
 	"path"
+	"path/filepath"
 	"regexp"
 	"strings"
 	"syscall"
@@ -26,6 +27,12 @@
 	"golang.org/x/sync/singleflight"
 )
 
+type contextKey string
+
+const (
+	urlKey contextKey = "url"
+)
+
 const getGitEndpoint = "/getgit"
 const defaultGitterWorkDir = "/work/gitter"
 const persistanceFileName = "last-fetch.json"
@@ -43,6 +50,7 @@
 // runCmd executes a command with context cancellation handled by sending SIGINT.
 // It logs cancellation errors separately as requested.
 func runCmd(ctx context.Context, dir string, env []string, name string, args ...string) error {
+	logger.Debug("Running command", slog.String("cmd", name), slog.String("url", ctx.Value(urlKey).(string)), slog.Any("args", args))
 	cmd := exec.CommandContext(ctx, name, args...)
 	if dir != "" {
 		cmd.Dir = dir
@@ -52,6 +60,7 @@
 	}
 	// Use SIGINT instead of SIGKILL for graceful shutdown of subprocesses
 	cmd.Cancel = func() error {
+		logger.Debug("SIGINT sent to command", slog.String("cmd", name), slog.String("url", ctx.Value(urlKey).(string)), slog.Any("args", args))
 		return cmd.Process.Signal(syscall.SIGINT)
 	}
 	// Ensure it eventually dies if it ignores SIGINT
@@ -61,12 +70,13 @@
 	if err != nil {
 		if ctx.Err() != nil {
 			// Log separately if cancelled
-			logger.Warn("Command cancelled", slog.String("cmd", name), slog.Any("err", ctx.Err()))
+			logger.Warn("Command cancelled", slog.String("cmd", name), slog.String("url", ctx.Value(urlKey).(string)), slog.Any("err", ctx.Err()))
 			return fmt.Errorf("command %s cancelled: %w", name, ctx.Err())
 		}
 
 		return fmt.Errorf("command %s failed: %w, output: %s", name, err, out)
 	}
+	logger.Debug("Command completed successfully", slog.String("cmd", name), slog.String("url", ctx.Value(urlKey).(string)), slog.String("out", string(out)))
 
 	return nil
 }
@@ -103,6 +113,11 @@
 		(strings.Contains(strings.ToLower(errString), "repository") && strings.Contains(strings.ToLower(errString), "not found"))
 }
 
+func isIndexLockError(err error) bool {
+	errString := err.Error()
+	return strings.Contains(errString, "index.lock") && strings.Contains(errString, "File exists")
+}
+
 func fetchBlob(ctx context.Context, url string, forceUpdate bool) ([]byte, error) {
 	repoDirName := getRepoDirName(url)
 	repoPath := path.Join(gitStorePath, repoDirName)
@@ -114,7 +129,7 @@
 
 	// Check if we need to fetch
 	if forceUpdate || !ok || time.Since(accessTime) > fetchTimeout {
-		logger.Info("Fetching git blob", slog.String("url", url), slog.Duration("sinceAccessTime", time.Since(accessTime)))
+		logger.Info("Fetching git blob", slog.String("url", ctx.Value(urlKey).(string)), slog.Duration("sinceAccessTime", time.Since(accessTime)))
 		if _, err := os.Stat(path.Join(repoPath, ".git")); os.IsNotExist(err) {
 			// Clone
 			err := runCmd(ctx, "", []string{"GIT_TERMINAL_PROMPT=0"}, "git", "clone", "--", url, repoPath)
@@ -129,13 +144,25 @@
 			if err != nil {
 				return nil, fmt.Errorf("git fetch failed: %w", err)
 			}
 			err = runCmd(ctx, repoPath, nil, "git", "reset", "--hard", "origin/HEAD")
+			if isIndexLockError(err) {
+				// index.lock exists, likely a previous git reset got terminated and wasn't cleaned up properly.
+				// We can remove the file and retry the command
+				logger.Warn("index.lock exists, attempting to remove and retry", slog.String("url", ctx.Value(urlKey).(string)))
+				indexLockPath := filepath.Join(repoPath, ".git", "index.lock")
+				if err := os.Remove(indexLockPath); err != nil {
+					return nil, fmt.Errorf("failed to remove index.lock in %s: %w", repoPath, err)
+				}
+				// One more attempt at git reset
+				err = runCmd(ctx, repoPath, nil, "git", "reset", "--hard", "origin/HEAD")
+			}
+
 			if err != nil {
 				return nil, fmt.Errorf("git reset failed: %w", err)
 			}
 		}
 
-		logger.Info("Archiving git blob", slog.String("url", url))
+		logger.Info("Archiving git blob", slog.String("url", ctx.Value(urlKey).(string)))
 		// Archive
 		// tar --zstd -cf <archivePath> -C "<gitStorePath>/<repoDirName>" .
 		// using -C to archive the relative path so it unzips nicely
@@ -242,6 +269,8 @@
 	}
 	forceUpdate := r.URL.Query().Get("force-update") == "true"
 
+	ctx := context.WithValue(r.Context(), urlKey, url)
+
 	logger.Info("Received request", slog.String("url", url), slog.Bool("forceUpdate", forceUpdate), slog.String("remoteAddr", r.RemoteAddr))
 	// If request came from a local ip, don't do the check
 	if !isLocalRequest(r) {
@@ -258,13 +287,12 @@
 	// That is highly unlikely in our use case, as importer only queries
 	// the repo once, and always with force update.
 	// This is a tradeoff for simplicity to avoid having to setup locks per repo.
-	//nolint:contextcheck // I can't change singleflight's interface
 	fileData, err, _ := g.Do(url, func() (any, error) {
-		return fetchBlob(r.Context(), url, forceUpdate)
+		return fetchBlob(ctx, url, forceUpdate)
 	})
 
 	if err != nil {
-		logger.Error("Error fetching/archiving blob", slog.String("url", url), slog.Any("error", err))
+		logger.Error("Error fetching/archiving blob", slog.String("url", ctx.Value(urlKey).(string)), slog.Any("error", err))
 		if isAuthError(err) {
 			http.Error(w, fmt.Sprintf("Error fetching blob: %v", err), http.StatusForbidden)
 			return
@@ -284,5 +312,5 @@
 		return
 	}
 
-	logger.Info("Request completed successfully", slog.String("url", url))
+	logger.Info("Request completed successfully", slog.String("url", ctx.Value(urlKey).(string)))
 }