Make SSH integration tests easier to debug

.github/workflows/qa.yaml

@@ -22,6 +22,7 @@ concurrency:
 env:
   DEBIAN_FRONTEND: noninteractive
   GO_TESTS_TIMEOUT: 20m
+  AUTHD_SSHD_STDERR_LOG_ALL_PAM_MESSAGES: true
   c_build_dependencies: >-
     clang-tools
     clang

CONTRIBUTING.md

@@ -188,12 +188,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/authctl/user/user_test.go

@@ -60,7 +60,7 @@ func TestUserCommand(t *testing.T) {
 func TestUserLockCommand(t *testing.T) {
 	t.Parallel()
 
-	daemonSocket := testutils.StartDaemon(t, daemonPath,
+	daemonSocket := testutils.StartAuthd(t, daemonPath,
 		testutils.WithGroupFile(filepath.Join("testdata", "empty.group")),
 		testutils.WithPreviousDBState("one_user_and_group"),
 		testutils.WithCurrentUserAsRoot,
@@ -112,7 +112,7 @@ func TestMain(m *testing.M) {
 	defer authctlCleanup()
 
 	var daemonCleanup func()
-	daemonPath, daemonCleanup, err = testutils.BuildDaemonWithExampleBroker()
+	daemonPath, daemonCleanup, err = testutils.BuildAuthdWithExampleBroker()
 	if err != nil {
 		fmt.Fprintf(os.Stderr, "Setup: %v\n", err)
 		os.Exit(1)

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

@@ -16,6 +16,7 @@ import (
 	"github.com/ubuntu/authd/internal/daemon/testdata/grpctestservice"
 	"github.com/ubuntu/authd/internal/grpcutils"
 	"github.com/ubuntu/authd/internal/services/errmessages"
+	"github.com/ubuntu/authd/internal/testutils"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/credentials/insecure"
 	"google.golang.org/grpc/health"
@@ -248,7 +249,7 @@ func TestQuit(t *testing.T) {
 			}()
 
 			// make sure Serve() is called. Even std golang grpc has this timeout in tests
-			time.Sleep(100 * time.Millisecond)
+			time.Sleep(testutils.MultipliedSleepDuration(100 * time.Millisecond))
 
 			var disconnectClient func()
 			if tc.activeConnection {
@@ -257,40 +258,50 @@ 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)
 			}()
 
-			time.Sleep(100 * time.Millisecond)
+			time.Sleep(testutils.MultipliedSleepDuration(100 * time.Millisecond))
 
 			// Any new connection is disallowed
 			connected, _ := createClientConnection(t, socketPath)
 			require.False(t, connected, "new connection should be disallowed")
 
 			serverHasQuit := func() bool {
 				select {
-				case _, running := <-quiteDone:
-					return !running
+				case _, ok := <-shutdownRequested:
+					return !ok
 				default:
 					return false
 				}
 			}
 
 			if !tc.activeConnection || tc.force {
-				require.Eventually(t, serverHasQuit, 100*time.Millisecond, 10*time.Millisecond, "Server should quit with no active connection or force")
+				require.Eventually(t,
+					serverHasQuit,
+					testutils.MultipliedSleepDuration(100*time.Millisecond),
+					testutils.MultipliedSleepDuration(10*time.Millisecond),
+					"Server should quit with no active connection or force",
+				)
 				return
 			}
 
-			time.Sleep(100 * time.Millisecond)
+			time.Sleep(testutils.MultipliedSleepDuration(100 * time.Millisecond))
 			require.False(t, serverHasQuit(), "Server should still be running because of active connection and not forced")
 
 			// 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,
+				testutils.MultipliedSleepDuration(200*time.Millisecond),
+				testutils.MultipliedSleepDuration(10*time.Millisecond),
+				"Server should quit with no more active connection",
+			)
 		})
 	}
 }

internal/testlog/testlog.go

@@ -0,0 +1,217 @@
+// Package testlog provides utilities for logging test output.
+package testlog
+
+import (
+	"fmt"
+	"io"
+	"os"
+	"os/exec"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+)
+
+var (
+	isVerboseOnce sync.Once
+	isVerbose     bool
+)
+
+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 := testOutput(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.Fprintln(w, redSeparatorf("%s failed in %.3fs with %v", msg, duration.Seconds(), err)+"\n")
+	} else {
+		fmt.Fprintln(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 := testOutput(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 := testOutput(t)
+
+	fmt.Fprintln(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()
+	}
+	w := testOutput(t)
+
+	fmt.Fprintln(w, "\n"+separator(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 := testOutput(t)
+
+	fmt.Fprintln(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()
+	}
+	w := testOutput(t)
+
+	fmt.Fprintln(w, separator(args...)+"\n")
+}
+
+// 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 highCyan("===== " + fmt.Sprint(args...) + " =====\n")
+}
+
+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)
+}
+
+// testOutput returns the appropriate output writer for the test.
+//
+//nolint:thelper // we're not using t in any way that requires the helper annotation
+func testOutput(t *testing.T) io.Writer {
+	if t != nil {
+		return &syncWriter{w: t.Output()}
+	}
+	if verbose() {
+		return os.Stderr
+	}
+	return io.Discard
+}
+
+// verbose returns whether verbose mode is enabled.
+// testing.Verbose() should be used instead when possible, this function is only
+// needed because testing.Verbose() panics when called in a TestMain function.
+func verbose() bool {
+	isVerboseOnce.Do(func() {
+		for _, arg := range os.Args {
+			value, ok := strings.CutPrefix(arg, "-test.v=")
+			if !ok {
+				continue
+			}
+			isVerbose = value == "true"
+		}
+	})
+	return isVerbose
+}
+
+// syncWriter is a writer that synchronizes writes to its underlying writer.
+type syncWriter struct {
+	w  io.Writer
+	mu sync.Mutex
+}
+
+// Write writes to the underlying writer while synchronizing access.
+func (s *syncWriter) Write(p []byte) (n int, err error) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	return s.w.Write(p)
+}

internal/testutils/args.go

@@ -119,3 +119,15 @@ 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
+})
+
+// IsDebianPackageBuild returns true if the tests are running in a Debian package build environment.
+var IsDebianPackageBuild = sync.OnceValue(func() bool {
+	_, ok := os.LookupEnv("DEB_BUILD_ARCH")
+	return ok
+})