Add debug logging to runner (#7324)

enterprise/server/remote_execution/container/container.go

@@ -437,11 +437,15 @@ type VM interface {
 // PullImageIfNecessary pulls the image configured for the container if it
 // is not cached locally.
 func PullImageIfNecessary(ctx context.Context, env environment.Env, ctr CommandContainer, creds oci.Credentials, imageRef string) error {
-	ctx, span := tracing.StartSpan(ctx)
-	defer span.End()
-	if *debugUseLocalImagesOnly {
+	if *debugUseLocalImagesOnly || imageRef == "" {
 		return nil
 	}
+
+	ctx, span := tracing.StartSpan(ctx)
+	defer span.End()
+	log.CtxDebugf(ctx, "Preparing to pull image")
+	defer log.CtxDebugf(ctx, "Finished pulling image")
+
 	cacheAuth := env.GetImageCacheAuthenticator()
 	if cacheAuth == nil || env.GetAuthenticator() == nil {
 		// If we don't have an authenticator available, fall back to

enterprise/server/remote_execution/containers/bare/BUILD

@@ -13,6 +13,7 @@ go_library(
         "//enterprise/server/util/procstats",
         "//proto:remote_execution_go_proto",
         "//server/interfaces",
+        "//server/util/log",
         "//server/util/status",
     ],
 )

enterprise/server/remote_execution/containers/bare/bare.go

@@ -13,6 +13,7 @@ import (
 	"github.com/buildbuddy-io/buildbuddy/enterprise/server/util/oci"
 	"github.com/buildbuddy-io/buildbuddy/enterprise/server/util/procstats"
 	"github.com/buildbuddy-io/buildbuddy/server/interfaces"
+	"github.com/buildbuddy-io/buildbuddy/server/util/log"
 	"github.com/buildbuddy-io/buildbuddy/server/util/status"
 
 	repb "github.com/buildbuddy-io/buildbuddy/proto/remote_execution"
@@ -81,6 +82,7 @@ func (c *bareCommandContainer) Signal(ctx context.Context, sig syscall.Signal) e
 }
 
 func (c *bareCommandContainer) exec(ctx context.Context, cmd *repb.Command, workDir string, stdio *interfaces.Stdio) (result *interfaces.CommandResult) {
+	log.CtxDebugf(ctx, "Beginning exec in container")
 	var statsListener procstats.Listener
 	if c.opts.EnableStats {
 		defer container.Metrics.Unregister(c)
@@ -90,6 +92,7 @@ func (c *bareCommandContainer) exec(ctx context.Context, cmd *repb.Command, work
 	}
 
 	if *enableLogFiles {
+		log.CtxDebugf(ctx, "Creating log files")
 		stdoutPath := workDir + ".stdout"
 		stdoutFile, err := os.Create(stdoutPath)
 		if err != nil {
@@ -127,6 +130,7 @@ func (c *bareCommandContainer) exec(ctx context.Context, cmd *repb.Command, work
 		stdio.Stderr = io.MultiWriter(stdio.Stderr, stderrFile)
 	}
 
+	log.CtxDebugf(ctx, "Preparing to run command")
 	return commandutil.RunWithOpts(ctx, cmd, &commandutil.RunOpts{
 		Dir:           workDir,
 		StatsListener: statsListener,

enterprise/server/remote_execution/runner/runner.go

@@ -212,7 +212,8 @@ func (r *taskRunner) String() string {
 		truncate(r.key.InstanceName, 8, "..."), truncate(ph, 8, ""))
 }
 
-func (r *taskRunner) pullCredentials() (oci.Credentials, error) {
+func (r *taskRunner) pullCredentials(ctx context.Context) (oci.Credentials, error) {
+	log.CtxDebugf(ctx, "Pulling credentials")
 	return oci.CredentialsFromProperties(r.PlatformProperties)
 }
 
@@ -232,7 +233,7 @@ func (r *taskRunner) PrepareForTask(ctx context.Context) error {
 
 	// Pull the container image before Run() is called, so that we don't
 	// use up the whole exec ctx timeout with a slow container pull.
-	creds, err := r.pullCredentials()
+	creds, err := r.pullCredentials(ctx)
 	if err != nil {
 		return err
 	}
@@ -298,6 +299,7 @@ func (r *taskRunner) DownloadInputs(ctx context.Context, ioStats *repb.IOStats)
 
 // Run runs the task that is currently bound to the command runner.
 func (r *taskRunner) Run(ctx context.Context) (res *interfaces.CommandResult) {
+	log.CtxDebugf(ctx, "Starting run")
 	start := time.Now()
 	defer func() {
 		// Discard nonsensical PSI full-stall durations which are greater
@@ -346,10 +348,11 @@ func (r *taskRunner) Run(ctx context.Context) (res *interfaces.CommandResult) {
 	command := r.task.GetCommand()
 
 	if !r.PlatformProperties.RecycleRunner {
+		log.CtxDebugf(ctx, "Runner is not recyclable - running full container lifecycle")
 		// If the container is not recyclable, then use `Run` to walk through
 		// the entire container lifecycle in a single step.
 		// TODO: Remove this `Run` method and call lifecycle methods directly.
-		creds, err := r.pullCredentials()
+		creds, err := r.pullCredentials(ctx)
 		if err != nil {
 			return commandutil.ErrorResult(err)
 		}
@@ -367,7 +370,7 @@ func (r *taskRunner) Run(ctx context.Context) (res *interfaces.CommandResult) {
 	r.p.mu.RUnlock()
 	switch s {
 	case initial:
-		creds, err := r.pullCredentials()
+		creds, err := r.pullCredentials(ctx)
 		if err != nil {
 			return commandutil.ErrorResult(err)
 		}
@@ -392,6 +395,7 @@ func (r *taskRunner) Run(ctx context.Context) (res *interfaces.CommandResult) {
 	}
 
 	if _, ok := persistentworker.Key(r.PlatformProperties, command.GetArguments()); ok {
+		log.CtxDebugf(ctx, "Sending persistent work request")
 		return r.sendPersistentWorkRequest(ctx, command)
 	}