tests: Print duration of setup steps

Author: adombeck

internal/testutils/cmd.go

@@ -0,0 +1,29 @@
+package testutils
+
+import (
+	"log"
+	"os/exec"
+	"strings"
+	"time"
+)
+
+// RunWithTiming runs the given command while logging its duration with the provided message.
+func RunWithTiming(msg string, cmd *exec.Cmd) error {
+	log.Printf("%s: %s", msg, strings.Join(cmd.Args, " "))
+	start := time.Now()
+	err := cmd.Run()
+	duration := time.Since(start)
+	log.Printf("Finished in %.3fs", duration.Seconds())
+	return err
+}
+
+// CombinedOutputWithTiming runs the given command while logging its duration with the provided message
+// and returns its combined standard output and standard error.
+func CombinedOutputWithTiming(msg string, cmd *exec.Cmd) ([]byte, error) {
+	log.Printf("%s: %s", msg, strings.Join(cmd.Args, " "))
+	start := time.Now()
+	out, err := cmd.CombinedOutput()
+	duration := time.Since(start)
+	log.Printf("Finished in %.3fs", duration.Seconds())
+	return out, err
+}

internal/testutils/daemon.go

@@ -169,13 +169,16 @@ paths:
 	}
 
 	// Start the daemon
+	start := time.Now()
 	stopped = make(chan struct{})
 	processPid := make(chan int)
 	go func() {
 		defer close(stopped)
 		var b bytes.Buffer
 		cmd.Stdout = &b
 		cmd.Stderr = &b
+
+		t.Logf("Setup: Starting daemon: %s", cmd.String())
 		err := cmd.Start()
 		require.NoError(t, err, "Setup: daemon cannot start %v", cmd.Args)
 		if opts.pidFile != "" {
@@ -226,6 +229,8 @@ paths:
 	// Block until the daemon is started and ready to accept connections.
 	err = grpcutils.WaitForConnection(ctx, conn, time.Second*30)
 	require.NoError(t, err, "Setup: wait for daemon to be ready timed out")
+	duration := time.Since(start)
+	t.Logf("Setup: daemon is ready after %.3fs", duration.Seconds())
 
 	if opts.pidFile != "" {
 		err := os.WriteFile(opts.pidFile, []byte(fmt.Sprint(<-processPid)), 0600)

internal/testutils/rust.go

@@ -101,8 +101,7 @@ func BuildRustNSSLib(t *testing.T, disableCoverage bool, features ...string) (li
 		cmd.Env = append(cmd.Env, "RUSTFLAGS=-Zsanitizer=address")
 	}
 
-	t.Log("Building NSS library...", cmd.Args)
-	err = cmd.Run()
+	err = RunWithTiming("Building NSS library", cmd)
 	require.NoError(t, err, "Setup: could not build Rust NSS library")
 
 	// When building the crate with dh-cargo, this env is set to indicate which architecture the code

pam/integration-tests/helpers_test.go

@@ -221,11 +221,9 @@ func buildPAMExecChild(t *testing.T) string {
 	cmd.Env = append(os.Environ(), `CGO_CFLAGS=-O0 -g3`)
 
 	authdPam := filepath.Join(t.TempDir(), "authd-pam")
-	t.Logf("Compiling Exec child at %s", authdPam)
-	t.Log(strings.Join(cmd.Args, " "))
 
 	cmd.Args = append(cmd.Args, "-o", authdPam)
-	out, err := cmd.CombinedOutput()
+	out, err := testutils.CombinedOutputWithTiming("Building PAM exec child", cmd)
 	require.NoError(t, err, "Setup: could not compile PAM exec child: %s", out)
 
 	return authdPam

pam/integration-tests/modulehelpers_test.go

@@ -35,7 +35,6 @@ func buildCModule(t *testing.T, sources []string, pkgConfigDeps []string, cFlags
 
 	require.NoError(t, os.MkdirAll(filepath.Dir(libPath), 0700),
 		"Setup: Can't create loader build path")
-	t.Logf("Compiling C Module library at %s", libPath)
 	cmd.Args = append(cmd.Args, "-o", libPath)
 	cmd.Args = append(cmd.Args, sources...)
 	cmd.Args = append(cmd.Args,
@@ -119,8 +118,7 @@ func buildCModule(t *testing.T, sources []string, pkgConfigDeps []string, cFlags
 		})
 	}
 
-	t.Logf("Running compiler command: %s %s", cmd.Path, strings.Join(cmd.Args[1:], " "))
-	out, err := cmd.CombinedOutput()
+	out, err := testutils.CombinedOutputWithTiming("Building PAM module", cmd)
 	require.NoError(t, err, "Setup: could not compile C module %s: %s", soname, out)
 	if string(out) != "" {
 		t.Log(string(out))

pam/integration-tests/ssh_test.go

@@ -675,6 +675,7 @@ func startSSHd(t *testing.T, hostKey, forcedCommand string, env []string, daemon
 	}
 
 	t.Logf("Launching sshd: cmd: %s\nenv: %s", sshd.String(), sshd.Env)
+	start := time.Now()
 	err = sshd.Start()
 	require.NoError(t, err, "Setup: Impossible to start sshd")
 	sshdPid := sshd.Process.Pid
@@ -795,8 +796,9 @@ func startSSHd(t *testing.T, hostKey, forcedCommand string, env []string, daemon
 	pidFileContent, err := os.ReadFile(sshdPidFile)
 	require.NoError(t, err, "Setup: Reading SSHd pid file failed")
 
-	t.Logf("SSHd started with pid %d (%s) and listening on port %s",
-		sshdPid, strings.TrimSpace(string(pidFileContent)), sshdPort)
+	duration := time.Since(start)
+	t.Logf("SSHd started in %.3fs - pid: %d (%s), listen port: %s",
+		duration.Seconds(), sshdPid, strings.TrimSpace(string(pidFileContent)), sshdPort)
 
 	return sshdPort
 }