debug statements

Signed-off-by: reggie-k <regina.voloshin@codefresh.io>

Author: reggie-k

util/exec/exec.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"os"
 	"os/exec"
+	"path/filepath"
 	"strconv"
 	"strings"
 	"syscall"
@@ -183,13 +184,29 @@ func RunCommandExt(cmd *exec.Cmd, opts CmdOpts) (string, error) {
 	args := strings.Join(cmd.Args, " ")
 	logCtx.WithFields(logrus.Fields{"dir": cmd.Dir}).Info(redactor(args))
 
+	// Helper: debug whether HEAD.lock exists under the current working directory
+	logHeadLockStatus := func(where string) {
+		if cmd.Dir == "" {
+			return
+		}
+		lockPath := filepath.Join(cmd.Dir, ".git", "HEAD.lock")
+		_, statErr := os.Stat(lockPath)
+		exists := statErr == nil
+		logCtx.WithFields(logrus.Fields{
+			"headLockPath":   lockPath,
+			"headLockExists": exists,
+			"where":          where,
+		}).Info("HEAD.lock status " + execId)
+	}
+
 	var stdout bytes.Buffer
 	var stderr bytes.Buffer
 	cmd.Stdout = &stdout
 	cmd.Stderr = &stderr
 
 	start := time.Now()
 	err = cmd.Start()
+	logCtx.Info("*************************************** EXEC COMMAND STARTED *************************************** " + execId)
 	if err != nil {
 		return "", err
 	}
@@ -228,13 +245,16 @@ func RunCommandExt(cmd *exec.Cmd, opts CmdOpts) (string, error) {
 	select {
 	// noinspection ALL
 	case <-timoutCh:
+		logCtx.Info("*************************************** EXEC TIMEOUT HAPPENED *************************************** " + execId)
 		// send timeout signal
 		_ = cmd.Process.Signal(timeoutBehavior.Signal)
 		// wait on timeout signal and fallback to fatal timeout signal
 		if timeoutBehavior.ShouldWait {
+			logCtx.Info("*************************************** EXEC WAIT HAPPENED *************************************** " + execId)
 			select {
 			case <-done:
 			case <-fatalTimeoutCh:
+				logCtx.Info("*************************************** EXEC FATAL TIMEOUT HAPPENED *************************************** " + execId)
 				// upgrades to SIGKILL if cmd does not respect SIGTERM
 				_ = cmd.Process.Signal(fatalTimeoutBehaviour)
 				// now original cmd should exit immediately after SIGKILL
@@ -245,6 +265,7 @@ func RunCommandExt(cmd *exec.Cmd, opts CmdOpts) (string, error) {
 					output += stderr.String()
 				}
 				logCtx.WithFields(logrus.Fields{"duration": time.Since(start)}).Debug(redactor(output))
+				logHeadLockStatus("fatal-timeout")
 				err = newCmdError(redactor(args), fmt.Errorf("fatal timeout after %v", timeout+fatalTimeout), "")
 				logCtx.Error(err.Error())
 				return strings.TrimSuffix(output, "\n"), err
@@ -256,11 +277,14 @@ func RunCommandExt(cmd *exec.Cmd, opts CmdOpts) (string, error) {
 			output += stderr.String()
 		}
 		logCtx.WithFields(logrus.Fields{"duration": time.Since(start)}).Debug(redactor(output))
+		logHeadLockStatus("timeout")
 		err = newCmdError(redactor(args), fmt.Errorf("timeout after %v", timeout), "")
 		logCtx.Error(err.Error())
 		return strings.TrimSuffix(output, "\n"), err
 	case err := <-done:
+		logCtx.Info("*************************************** FINISHED ON TIME *************************************** " + execId)
 		if err != nil {
+			logCtx.Error("*************************************** FINISHED ON TIME EXEC FAILED *************************************** " + execId)
 			output := stdout.String()
 			if opts.CaptureStderr {
 				output += stderr.String()
@@ -270,6 +294,7 @@ func RunCommandExt(cmd *exec.Cmd, opts CmdOpts) (string, error) {
 			if !opts.SkipErrorLogging {
 				logCtx.Error(err.Error())
 			}
+			logHeadLockStatus("done-error")
 			return strings.TrimSuffix(output, "\n"), err
 		}
 	}
@@ -278,6 +303,7 @@ func RunCommandExt(cmd *exec.Cmd, opts CmdOpts) (string, error) {
 		output += stderr.String()
 	}
 	logCtx.WithFields(logrus.Fields{"duration": time.Since(start)}).Debug(redactor(output))
+	logHeadLockStatus("done-success")
 
 	return strings.TrimSuffix(output, "\n"), nil
 }