[ci_runner] Add more debug logs (#7379)

enterprise/server/cmd/ci_runner/main.go

@@ -550,6 +550,11 @@ func (r *buildEventReporter) startBackgroundProgressFlush() func() {
 }
 
 func main() {
+	if os.Getenv("CI_RUNNER_DEBUG") == "1" {
+		*backendLog.LogLevel = "debug"
+		backendLog.Configure()
+	}
+	backendLog.Debugf("Top of main")
 	if err := run(); err != nil {
 		if result, ok := err.(*actionResult); ok {
 			os.Exit(result.exitCode)
@@ -570,10 +575,13 @@ func run() error {
 			return err
 		}
 	}
+	backendLog.Debugf("Finished parsing flags")
 	if *credentialHelper {
+		backendLog.Debugf("Running credential helper")
 		return runCredentialHelper()
 	}
 	if isBazelWrapper {
+		backendLog.Debugf("Running bazel wrapper")
 		return runBazelWrapper()
 	}
 
@@ -605,6 +613,7 @@ func run() error {
 
 	// Use a context without a timeout for the build event reporter, so that even
 	// if the `timeout` is reached, any events will finish getting published
+	backendLog.Debugf("Initializing build event reporter")
 	buildEventReporter, err := newBuildEventReporter(contextWithoutTimeout, *besBackend, ws.buildbuddyAPIKey, *invocationID, *workflowID != "" /*=isWorkflow*/)
 	if err != nil {
 		return err
@@ -630,6 +639,7 @@ func run() error {
 	}
 	// Change the current working directory to respect WORKDIR_OVERRIDE, if set.
 	if wd := os.Getenv("WORKDIR_OVERRIDE"); wd != "" {
+		backendLog.Debugf("Initializing working directory %s", wd)
 		if err := os.MkdirAll(wd, 0755); err != nil {
 			return status.WrapError(err, "create WORKDIR_OVERRIDE directory")
 		}
@@ -663,10 +673,13 @@ func run() error {
 		return status.WrapError(err, "disable interactivity")
 	}
 
+	backendLog.Debugf("Completed checking configuration requirements")
+
 	// Write default bazelrc
 	if err := writeBazelrc(buildbuddyBazelrcPath, buildEventReporter.invocationID, runID, rootDir); err != nil {
 		return status.WrapError(err, "write "+buildbuddyBazelrcPath)
 	}
+	backendLog.Debugf("Completed writing bazelrc")
 	// Delete bazelrc before exiting. Use abs path since we might cd after this
 	// point.
 	absBazelrcPath, err := filepath.Abs(buildbuddyBazelrcPath)
@@ -687,18 +700,22 @@ func run() error {
 	// Make sure we have a bazel / bazelisk binary available.
 	if *bazelCommand == "" {
 		bazeliskPath := filepath.Join(rootDir, bazeliskBinaryName)
+		backendLog.Debugf("Preparing to extract bazelisk")
 		if err := extractBazelisk(bazeliskPath); err != nil {
 			return status.WrapError(err, "failed to extract bazelisk")
 		}
+		backendLog.Debugf("Finished extracting bazelisk")
 		*bazelCommand = bazeliskPath
 
 	}
 
 	// Use the bazel wrapper script, which adds some common flags to all
 	// Bazel builds.
+	backendLog.Debugf("Preparing to write bazel wrapper script")
 	if err := ws.writeBazelWrapperScript(); err != nil {
 		return status.WrapError(err, "write bazel wrapper script")
 	}
+	backendLog.Debugf("Finished write bazel wrapper script")
 
 	if *shutdownAndExit {
 		ws.log.Println("--shutdown_and_exit requested; will run bazel shutdown then exit.")
@@ -727,6 +744,7 @@ func run() error {
 		return nil
 	}
 
+	backendLog.Debugf("Starting build event reporter")
 	if err := buildEventReporter.Start(ws.startTime); err != nil {
 		return status.WrapError(err, "could not publish started event")
 	}

enterprise/server/remote_execution/commandutil/commandutil.go

@@ -46,6 +46,8 @@ var (
 )
 
 func constructExecCommand(command *repb.Command, workDir string, stdio *interfaces.Stdio) (*exec.Cmd, *bytes.Buffer, *bytes.Buffer, error) {
+	log.Debugf("Top of constructExecCommand")
+	defer log.Debugf("Finished constructExecCommand")
 	if stdio == nil {
 		stdio = &interfaces.Stdio{}
 	}
@@ -72,6 +74,7 @@ func constructExecCommand(command *repb.Command, workDir string, stdio *interfac
 	// the process doesn't consume its stdin. See
 	// https://go.dev/play/p/DpKaVrx8d8G
 	if stdio.Stdin != nil {
+		log.Debugf("Get stdin pipe")
 		inp, err := cmd.StdinPipe()
 		if err != nil {
 			return nil, nil, nil, status.InternalErrorf("failed to get stdin pipe: %s", err)
@@ -86,6 +89,7 @@ func constructExecCommand(command *repb.Command, workDir string, stdio *interfac
 		cmd.Stdout = io.MultiWriter(cmd.Stdout, logWriter)
 		cmd.Stderr = io.MultiWriter(cmd.Stderr, logWriter)
 	}
+	log.Debugf("Preparing to get default sys proc attr")
 	cmd.SysProcAttr = getDefaultSysProcAttr()
 	for _, envVar := range command.GetEnvironmentVariables() {
 		cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", envVar.GetName(), envVar.GetValue()))
@@ -189,9 +193,11 @@ func startNewProcess(ctx context.Context, cmd *exec.Cmd) (*process, error) {
 		cmd:        cmd,
 		terminated: make(chan struct{}),
 	}
+	log.Debugf("Preparing to run process prestart")
 	if err := p.preStart(); err != nil {
 		return nil, fmt.Errorf("fail to setup preStart: %w", err)
 	}
+	log.Debugf("Preparing to run command start")
 	if err := p.cmd.Start(); err != nil {
 		return nil, err
 	}
@@ -244,6 +250,7 @@ func RunWithProcessTreeCleanup(ctx context.Context, cmd *exec.Cmd, opts *RunOpts
 		opts = &RunOpts{}
 	}
 
+	log.CtxDebugf(ctx, "Preparing to start new process")
 	p, err := startNewProcess(ctx, cmd)
 	if err != nil {
 		return nil, err