internal/nix: log all command starts and exits (#2135)

Write logs whenever a Nix command is about to start and after it exits.
Make `cmd` a `slog.LogValuer` so that it writes structured log
attributes grouped under a `cmd` prefix.

Example logs and attributes (line breaks added for readability):

	msg="nix command starting"
cmd.args="nix --extra-experimental-features ca-derivations --option
experimental-features 'nix-command flakes fetch-closure' eval --impure
--raw --expr builtins.currentSystem"
		cmd.path=/nix/var/nix/profiles/default/bin/nix

	msg="nix command exited"
cmd.args="nix --extra-experimental-features ca-derivations --option
experimental-features 'nix-command flakes fetch-closure' eval --impure
--raw --expr builtins.currentSystem"
		cmd.path=/nix/var/nix/profiles/default/bin/nix
		cmd.pid=68672
		cmd.code=0
		cmd.dur=34.296041ms

Command exits are always logged at the debug level, even if the command
exits with a non-zero exit code. This is because some commands might be
expected to fail (for example, when checking if a path exists in the
store).

Author: gcurtis

internal/nix/build.go

@@ -44,7 +44,5 @@ func Build(ctx context.Context, args *BuildArgs, installables ...string) error {
 	cmd.Stdin = os.Stdin
 	cmd.Stdout = args.Writer
 	cmd.Stderr = args.Writer
-
-	slog.Debug("running cmd", "cmd", cmd)
 	return cmd.Run(ctx)
 }

internal/nix/command.go

@@ -6,12 +6,12 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log/slog"
 	"os"
 	"os/exec"
 	"slices"
 	"strconv"
 	"strings"
-	"sync"
 	"syscall"
 	"time"
 )
@@ -24,8 +24,10 @@ type cmd struct {
 	Stdout io.Writer
 	Stderr io.Writer
 
-	execCmd     *exec.Cmd
-	execCmdOnce sync.Once
+	execCmd *exec.Cmd
+	err     error
+	dur     time.Duration
+	logger  *slog.Logger
 }
 
 func command(args ...any) *cmd {
@@ -35,69 +37,141 @@ func command(args ...any) *cmd {
 			"--extra-experimental-features", "ca-derivations",
 			"--option", "experimental-features", "nix-command flakes fetch-closure",
 		}, args...),
+		logger: slog.Default(),
 	}
 	return cmd
 }
 
 func (c *cmd) CombinedOutput(ctx context.Context) ([]byte, error) {
-	out, err := c.initExecCommand(ctx).CombinedOutput()
-	return out, c.error(ctx, err)
+	cmd := c.initExecCommand(ctx)
+	c.logger.DebugContext(ctx, "nix command starting", "cmd", c)
+
+	start := time.Now()
+	out, err := cmd.CombinedOutput()
+	c.dur = time.Since(start)
+
+	c.err = c.error(ctx, err)
+	c.logger.DebugContext(ctx, "nix command exited", "cmd", c)
+	return out, c.err
 }
 
 func (c *cmd) Output(ctx context.Context) ([]byte, error) {
-	out, err := c.initExecCommand(ctx).Output()
-	return out, c.error(ctx, err)
+	cmd := c.initExecCommand(ctx)
+	c.logger.DebugContext(ctx, "nix command starting", "cmd", c)
+
+	start := time.Now()
+	out, err := cmd.Output()
+	c.dur = time.Since(start)
+
+	c.err = c.error(ctx, err)
+	c.logger.DebugContext(ctx, "nix command exited", "cmd", c)
+	return out, c.err
 }
 
 func (c *cmd) Run(ctx context.Context) error {
-	return c.error(ctx, c.initExecCommand(ctx).Run())
+	cmd := c.initExecCommand(ctx)
+	c.logger.DebugContext(ctx, "nix command starting", "cmd", c)
+
+	start := time.Now()
+	err := cmd.Run()
+	c.dur = time.Since(start)
+
+	c.err = c.error(ctx, err)
+	c.logger.DebugContext(ctx, "nix command exited", "cmd", c)
+	return c.err
+}
+
+func (c *cmd) LogValue() slog.Value {
+	attrs := []slog.Attr{
+		slog.Any("args", c.Args),
+	}
+	if c.execCmd == nil {
+		return slog.GroupValue(attrs...)
+	}
+	attrs = append(attrs, slog.String("path", c.execCmd.Path))
+
+	var exitErr *exec.ExitError
+	if errors.As(c.err, &exitErr) {
+		stderr := c.stderrExcerpt(exitErr.Stderr)
+		if len(stderr) != 0 {
+			attrs = append(attrs, slog.String("stderr", stderr))
+		}
+	}
+	if proc := c.execCmd.Process; proc != nil {
+		attrs = append(attrs, slog.Int("pid", proc.Pid))
+	}
+	if procState := c.execCmd.ProcessState; procState != nil {
+		if procState.Exited() {
+			attrs = append(attrs, slog.Int("code", procState.ExitCode()))
+		}
+		if status, ok := procState.Sys().(syscall.WaitStatus); ok && status.Signaled() {
+			if status.Signaled() {
+				attrs = append(attrs, slog.String("signal", status.Signal().String()))
+			}
+		}
+	}
+	if c.dur != 0 {
+		attrs = append(attrs, slog.Duration("dur", c.dur))
+	}
+	return slog.GroupValue(attrs...)
 }
 
 func (c *cmd) String() string {
 	return c.Args.String()
 }
 
 func (c *cmd) initExecCommand(ctx context.Context) *exec.Cmd {
-	c.execCmdOnce.Do(func() {
-		args := c.Args.StringSlice()
-		c.execCmd = exec.CommandContext(ctx, args[0], args[1:]...)
-		c.execCmd.Env = c.Env
-		c.execCmd.Stdin = c.Stdin
-		c.execCmd.Stdout = c.Stdout
-		c.execCmd.Stderr = c.Stderr
-
-		c.execCmd.Cancel = func() error {
-			// Try to let Nix exit gracefully by sending an
-			// interrupt instead of the default behavior of killing
-			// it.
-			err := c.execCmd.Process.Signal(os.Interrupt)
-			if errors.Is(err, os.ErrProcessDone) {
-				// Nix already exited; execCmd.Wait will use the
-				// exit code.
-				return err
-			}
-			if err != nil {
-				// We failed to send SIGINT, so kill the process
-				// instead.
-				//
-				// - If Nix already exited, Kill will return
-				//   os.ErrProcessDone and execCmd.Wait will use
-				//   the exit code.
-				// - Otherwise, execCmd.Wait will always return
-				//   an error.
-				return c.execCmd.Process.Kill()
-			}
+	if c.execCmd != nil {
+		return c.execCmd
+	}
 
-			// We sent the SIGINT successfully. It's still possible
-			// for Nix to exit successfully, so return
-			// os.ErrProcessDone so that execCmd.Wait uses the exit
-			// code instead of ctx.Err.
-			return os.ErrProcessDone
+	args := c.Args.StringSlice()
+	c.execCmd = exec.CommandContext(ctx, args[0], args[1:]...)
+	c.execCmd.Env = c.Env
+	c.execCmd.Stdin = c.Stdin
+	c.execCmd.Stdout = c.Stdout
+	c.execCmd.Stderr = c.Stderr
+
+	c.execCmd.Cancel = func() error {
+		// Try to let Nix exit gracefully by sending an interrupt
+		// instead of the default behavior of killing it.
+		c.logger.DebugContext(ctx, "sending interrupt to nix process", slog.Group("cmd",
+			"args", c.Args,
+			"path", c.execCmd.Path,
+			"pid", c.execCmd.Process.Pid,
+		))
+		err := c.execCmd.Process.Signal(os.Interrupt)
+		if errors.Is(err, os.ErrProcessDone) {
+			// Nix already exited; execCmd.Wait will use the exit
+			// code.
+			return err
 		}
-		// Kill Nix if it doesn't exit within 15 seconds of Devbox
-		// sending an interrupt.
-		c.execCmd.WaitDelay = 15 * time.Second
-	})
+		if err != nil {
+			// We failed to send SIGINT, so kill the process
+			// instead.
+			//
+			// - If Nix already exited, Kill will return
+			//   os.ErrProcessDone and execCmd.Wait will use
+			//   the exit code.
+			// - Otherwise, execCmd.Wait will always return an
+			//   error.
+			c.logger.ErrorContext(ctx, "error interrupting nix process, attempting to kill",
+				"err", err, slog.Group("cmd",
+					"args", c.Args,
+					"path", c.execCmd.Path,
+					"pid", c.execCmd.Process.Pid,
+				))
+			return c.execCmd.Process.Kill()
+		}
+
+		// We sent the SIGINT successfully. It's still possible for Nix
+		// to exit successfully, so return os.ErrProcessDone so that
+		// execCmd.Wait uses the exit code instead of ctx.Err.
+		return os.ErrProcessDone
+	}
+	// Kill Nix if it doesn't exit within 15 seconds of Devbox sending an
+	// interrupt.
+	c.execCmd.WaitDelay = 15 * time.Second
 	return c.execCmd
 }
 

internal/nix/profiles.go

@@ -10,7 +10,6 @@ import (
 	"fmt"
 	"io"
 	"io/fs"
-	"log/slog"
 	"os"
 	"path/filepath"
 
@@ -60,14 +59,10 @@ func ProfileInstall(ctx context.Context, args *ProfileInstallArgs) error {
 	// However, now we do the building in nix.Build, by the time we install in profile everything
 	// should already be in the store. We need to capture the output so we can decide if a conflict
 	// happened.
-
-	slog.Debug("running command", "cmd", cmd)
 	out, err := cmd.CombinedOutput(ctx)
-
 	if bytes.Contains(out, []byte("error: An existing package already provides the following file")) {
 		return ErrPriorityConflict
 	}
-
 	return err
 }
 

internal/nix/search.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
-	"log/slog"
 	"os"
 	"regexp"
 	"strings"
@@ -103,7 +102,6 @@ func searchSystem(url, system string) (map[string]*Info, error) {
 	if system != "" {
 		cmd.Args = append(cmd.Args, "--system", system)
 	}
-	slog.Debug("running command", "cmd", cmd)
 	out, err := cmd.Output(context.TODO())
 	if err != nil {
 		// for now, assume all errors are invalid packages.

internal/nix/store.go

@@ -35,7 +35,6 @@ func StorePathsFromInstallable(ctx context.Context, installable string, allowIns
 		cmd.Env = allowInsecureEnv(cmd.Env)
 	}
 
-	slog.Debug("running cmd", "cmd", cmd)
 	resultBytes, err := cmd.Output(ctx)
 	if err != nil {
 		return nil, err
@@ -57,7 +56,6 @@ func StorePathsAreInStore(ctx context.Context, storePaths []string) (map[string]
 	}
 	cmd := command("path-info", "--offline", "--json")
 	cmd.Args = appendArgs(cmd.Args, storePaths)
-	slog.Debug("running cmd", "cmd", cmd)
 	output, err := cmd.Output(ctx)
 	if err != nil {
 		return nil, err