Make SSH integration tests easier to debug

CONTRIBUTING.md

@@ -183,12 +183,12 @@ The test suite must pass before merging the PR to our main branch. Any new featu
 
 #### Tests with dependencies
 
-Some tests, such as the [PAM CLI tests](https://github.com/ubuntu/authd/blob/5ba54c0a573f34e99782fe624b090ab229798fc3/pam/integration-tests/integration_test.go#L21), use external tools such as [vhs](https://github.com/charmbracelet/vhs)
+Some tests, such as the [PAM CLI tests](https://github.com/ubuntu/authd/blob/5ba54c0a573f34e99782fe624b090ab229798fc3/pam/integration-tests/integration_test.go#L21), use external tools such as [VHS](https://github.com/charmbracelet/vhs)
 to record and run the tape files needed for the tests. Those tools are not included in the project dependencies and must be installed manually.
 
 Information about these tools and their usage will be linked below:
 
-- [vhs](https://github.com/charmbracelet/vhs?tab=readme-ov-file#tutorial): tutorial on using vhs as a CLI-based video recorder
+- [VHS](https://github.com/charmbracelet/vhs?tab=readme-ov-file#tutorial): tutorial on using VHS as a CLI-based video recorder
 
 ### Code style
 

cmd/authd/daemon/config.go

@@ -4,7 +4,6 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log/slog"
 	"os"
 	"path/filepath"
 	"strings"
@@ -94,6 +93,5 @@ func setVerboseMode(level int) {
 		log.SetLevel(log.InfoLevel)
 	default:
 		log.SetLevel(log.DebugLevel)
-		slog.SetLogLoggerLevel(slog.LevelDebug)
 	}
 }

cmd/authd/main.go

@@ -55,13 +55,16 @@ func installSignalHandler(a app) func() {
 		for {
 			switch v, ok := <-c; v {
 			case syscall.SIGINT, syscall.SIGTERM:
+				log.Infof(context.Background(), "Received signal %d (%s), exiting...", v, v.String())
 				a.Quit()
 				return
 			case syscall.SIGHUP:
 				if a.Hup() {
+					log.Info(context.Background(), "Received SIGHUP, exiting...")
 					a.Quit()
 					return
 				}
+				log.Info(context.Background(), "Received SIGHUP, but nothing to do")
 			default:
 				// channel was closed: we exited
 				if !ok {

internal/daemon/daemon.go

@@ -132,13 +132,12 @@ func (d *Daemon) Serve(ctx context.Context) (err error) {
 // Quit gracefully quits listening loop and stops the grpc server.
 // It can drops any existing connexion is force is true.
 func (d Daemon) Quit(ctx context.Context, force bool) {
-	log.Infof(ctx, "Stopping daemon requested for socket %s.", d.lis.Addr())
 	if force {
 		d.grpcServer.Stop()
 		return
 	}
 
-	log.Info(ctx, "Wait for active requests to close.")
+	log.Info(ctx, "Waiting for pending requests to finish")
 	d.grpcServer.GracefulStop()
-	log.Debug(ctx, "All connections have now ended.")
+	log.Info(ctx, "gRPC server gracefully stopped")
 }

internal/daemon/daemon_test.go

@@ -254,10 +254,10 @@ func TestQuit(t *testing.T) {
 				require.True(t, connected, "new connection should be made allowed")
 			}
 
-			// Request quitting.
-			quiteDone := make(chan struct{})
+			// Request server shutdown
+			shutdownRequested := make(chan struct{})
 			go func() {
-				defer close(quiteDone)
+				defer close(shutdownRequested)
 				d.Quit(context.Background(), tc.force)
 			}()
 
@@ -269,8 +269,8 @@ func TestQuit(t *testing.T) {
 
 			serverHasQuit := func() bool {
 				select {
-				case _, running := <-quiteDone:
-					return !running
+				case _, ok := <-shutdownRequested:
+					return !ok
 				default:
 					return false
 				}
@@ -287,7 +287,7 @@ func TestQuit(t *testing.T) {
 			// drop connection
 			disconnectClient()
 
-			require.Eventually(t, serverHasQuit, 100*time.Millisecond, 10*time.Millisecond, "Server should quit with no more active connection")
+			require.Eventually(t, serverHasQuit, 1*time.Second, 10*time.Millisecond, "Server should quit with no more active connection")
 		})
 	}
 }

internal/testlog/testlog.go

@@ -0,0 +1,163 @@
+// Package testlog provides utilities for logging test output.
+package testlog
+
+import (
+	"fmt"
+	"os/exec"
+	"testing"
+	"time"
+)
+
+type runWithTimingOptions struct {
+	doNotSetStdoutAndStderr         bool
+	onlyPrintStdoutAndStderrOnError bool
+}
+
+// RunWithTimingOption is a function that configures the RunWithTiming function.
+type RunWithTimingOption func(options *runWithTimingOptions)
+
+// DoNotSetStdoutAndStderr prevents RunWithTiming from setting the stdout and stderr of the given command.
+// By default, RunWithTiming sets stdout and stderr to the test's output.
+func DoNotSetStdoutAndStderr() RunWithTimingOption {
+	return func(options *runWithTimingOptions) {
+		options.doNotSetStdoutAndStderr = true
+	}
+}
+
+// OnlyPrintStdoutAndStderrOnError makes RunWithTiming only print the stdout and stderr of the given command if it fails.
+func OnlyPrintStdoutAndStderrOnError() RunWithTimingOption {
+	return func(options *runWithTimingOptions) {
+		options.onlyPrintStdoutAndStderrOnError = true
+	}
+}
+
+// RunWithTiming runs the given command while logging its duration with the provided message.
+//
+//nolint:thelper // we do call t.Helper() if t is not nil
+func RunWithTiming(t *testing.T, msg string, cmd *exec.Cmd, options ...RunWithTimingOption) error {
+	if t != nil {
+		t.Helper()
+	}
+
+	w := testWriterOrStderr(t)
+
+	opts := runWithTimingOptions{}
+	for _, f := range options {
+		f(&opts)
+	}
+
+	if opts.doNotSetStdoutAndStderr && opts.onlyPrintStdoutAndStderrOnError {
+		panic("onlyPrintStdoutAndStderrOnError and doNotSetStdoutAndStderr cannot be used together")
+	}
+
+	if !opts.doNotSetStdoutAndStderr && !opts.onlyPrintStdoutAndStderrOnError {
+		cmd.Stdout = w
+		cmd.Stderr = w
+	}
+
+	LogCommand(t, msg, cmd)
+	start := time.Now()
+
+	var err error
+	var out []byte
+	if opts.onlyPrintStdoutAndStderrOnError {
+		out, err = cmd.CombinedOutput()
+		if err != nil {
+			_, _ = w.Write(out)
+		}
+	} else {
+		err = cmd.Run()
+	}
+	duration := time.Since(start)
+
+	if err != nil {
+		fmt.Fprintf(w, redSeparatorf("%s failed in %.3fs with %v", msg, duration.Seconds(), err)+"\n")
+	} else {
+		fmt.Fprintf(w, separatorf("%s finished in %.3fs", msg, duration.Seconds())+"\n")
+	}
+
+	return err
+}
+
+// LogCommand logs the given command to stderr.
+//
+//nolint:thelper // we do call t.Helper() if t is not nil
+func LogCommand(t *testing.T, msg string, cmd *exec.Cmd) {
+	if t != nil {
+		t.Helper()
+	}
+	w := testWriterOrStderr(t)
+
+	sep := "----------------------------------------"
+	fmt.Fprintf(w, "\n"+separator(msg)+"command: %s\n%s\nenvironment: %s\n%s\n", cmd.String(), sep, cmd.Env, sep)
+}
+
+// LogStartSeparatorf logs a separator to stderr with the given formatted message.
+//
+//nolint:thelper // we do call t.Helper() if t is not nil
+func LogStartSeparatorf(t *testing.T, s string, args ...any) {
+	if t != nil {
+		t.Helper()
+	}
+	w := testWriterOrStderr(t)
+
+	fmt.Fprintf(w, "\n"+separatorf(s, args...))
+}
+
+// LogStartSeparator logs a separator to stderr with the given message.
+//
+//nolint:thelper // we do call t.Helper() if t is not nil
+func LogStartSeparator(t *testing.T, args ...any) {
+	if t != nil {
+		t.Helper()
+	}
+
+	LogStartSeparatorf(t, fmt.Sprint(args...))
+}
+
+// LogEndSeparatorf logs a separator to stderr with the given formatted message.
+//
+//nolint:thelper // we do call t.Helper() if t is not nil
+func LogEndSeparatorf(t *testing.T, s string, args ...any) {
+	if t != nil {
+		t.Helper()
+	}
+	w := testWriterOrStderr(t)
+
+	fmt.Fprintf(w, separatorf(s, args...)+"\n")
+}
+
+// LogEndSeparator logs a separator to stderr with the given message.
+//
+//nolint:thelper // we do call t.Helper() if t is not nil
+func LogEndSeparator(t *testing.T, args ...any) {
+	if t != nil {
+		t.Helper()
+	}
+
+	LogEndSeparatorf(t, fmt.Sprint(args...))
+}
+
+// separatorf returns a formatted separator string for logging purposes.
+func separatorf(s string, args ...any) string {
+	return highCyan("===== " + fmt.Sprintf(s, args...) + " =====\n")
+}
+
+// separator returns a separator string for logging purposes.
+func separator(args ...any) string {
+	return separatorf(fmt.Sprint(args...))
+}
+
+func redSeparatorf(s string, args ...any) string {
+	return highRed("===== " + fmt.Sprintf(s, args...) + " =====\n")
+}
+
+// highCyan returns a string with the given text in high-intensity cyan color for terminal output.
+func highCyan(s string) string {
+	return fmt.Sprintf("\033[1;36m%s\033[0m", s)
+}
+
+// highRed returns a string with the given text in high-intensity red color for terminal output.
+func highRed(s string) string {
+	return fmt.Sprintf("\033[1;31m%s\033[0m", s)
+}

internal/testlog/testlog_go125.go

@@ -0,0 +1,24 @@
+//go:build go1.25
+
+package testlog
+
+import (
+	"io"
+	"os"
+	"testing"
+)
+
+// NewTestWriter creates a new TestWriter that logs to t.
+//
+//nolint:thelper // we're not using t in any way that requires the helper annotation
+func NewTestWriter(t *testing.T) io.Writer {
+	return t.Output()
+}
+
+//nolint:thelper // we're not using t in any way that requires the helper annotation
+func testWriterOrStderr(t *testing.T) io.Writer {
+	if t != nil {
+		return t.Output()
+	}
+	return os.Stderr
+}

internal/testlog/testlog_pre125.go

@@ -0,0 +1,64 @@
+//go:build !go1.25
+
+package testlog
+
+import (
+	"bytes"
+	"errors"
+	"io"
+	"os"
+	"strings"
+	"sync"
+	"testing"
+)
+
+// TestWriter is an io.Writer that sends its output to a testing.T via t.Log,
+// ensuring logs are attributed to the correct test.
+// It buffers partial writes until a newline is seen.
+type TestWriter struct {
+	t   *testing.T
+	mu  sync.Mutex
+	buf bytes.Buffer
+}
+
+// NewTestWriter creates a new TestWriter that logs to t.
+//
+//nolint:thelper // we're not using t in any way that requires the helper annotation'
+func NewTestWriter(t *testing.T) *TestWriter {
+	return &TestWriter{t: t}
+}
+
+// Write implements io.Writer. It buffers until a newline is seen,
+// then flushes complete lines to t.Log. Remainders are held until
+// the next Write call.
+func (w *TestWriter) Write(p []byte) (n int, err error) {
+	w.t.Helper()
+
+	w.mu.Lock()
+	defer w.mu.Unlock()
+
+	n, err = w.buf.Write(p)
+	for {
+		line, errLine := w.buf.ReadString('\n')
+		if errors.Is(errLine, io.EOF) {
+			// leftover data without newline — keep it for next Write
+			w.buf.Reset()
+			w.buf.WriteString(line)
+			break
+		}
+		// Trim the newline, let t.Log add its own
+		w.t.Log(strings.TrimSuffix(line, "\n"))
+	}
+
+	return n, err
+}
+
+// testWriterOrStderr returns a TestWriter if t is non-nil, or os.Stderr otherwise.
+//
+//nolint:thelper // we're not using t in any way that requires the helper annotation'
+func testWriterOrStderr(t *testing.T) io.Writer {
+	if t != nil {
+		return NewTestWriter(t)
+	}
+	return os.Stderr
+}

internal/testutils/args.go

@@ -99,3 +99,9 @@ func SleepMultiplier() float64 {
 func MultipliedSleepDuration(in time.Duration) time.Duration {
 	return time.Duration(math.Round(float64(in) * SleepMultiplier()))
 }
+
+// IsCI returns whether the test is running in CI environment.
+var IsCI = sync.OnceValue(func() bool {
+	_, ok := os.LookupEnv("GITHUB_ACTIONS")
+	return ok
+})