Include runner logs in test failure message

pkg/osquery/runtime/runtime_test.go

@@ -6,6 +6,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log/slog"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -24,6 +25,7 @@ import (
 	"github.com/kolide/launcher/pkg/log/multislogger"
 	"github.com/kolide/launcher/pkg/osquery/runtime/history"
 	"github.com/kolide/launcher/pkg/packaging"
+	"github.com/kolide/launcher/pkg/threadsafebuffer"
 
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/mock"
@@ -330,11 +332,18 @@ func TestWithOsqueryFlags(t *testing.T) {
 	require.NoError(t, err)
 	defer rmRootDirectory()
 
+	var logBytes threadsafebuffer.ThreadSafeBuffer
+
+	slogger := slog.New(slog.NewTextHandler(&logBytes, &slog.HandlerOptions{
+		AddSource: true,
+		Level:     slog.LevelDebug,
+	}))
+
 	k := typesMocks.NewKnapsack(t)
 	k.On("OsqueryHealthcheckStartupDelay").Return(0 * time.Second).Maybe()
 	k.On("WatchdogEnabled").Return(false)
 	k.On("RegisterChangeObserver", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything)
-	k.On("Slogger").Return(multislogger.NewNopLogger())
+	k.On("Slogger").Return(slogger)
 	k.On("LatestOsquerydPath", mock.Anything).Return(testOsqueryBinaryDirectory)
 	store, err := storageci.NewStore(t, multislogger.NewNopLogger(), storage.KatcConfigStore.String())
 	require.NoError(t, err)
@@ -347,7 +356,7 @@ func TestWithOsqueryFlags(t *testing.T) {
 		WithOsqueryFlags([]string{"verbose=false"}),
 	)
 	go runner.Run()
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, &logBytes)
 	assert.Equal(t, []string{"verbose=false"}, runner.instance.opts.osqueryFlags)
 
 	runner.Interrupt(errors.New("test error"))
@@ -360,6 +369,13 @@ func TestFlagsChanged(t *testing.T) {
 	require.NoError(t, err)
 	defer rmRootDirectory()
 
+	var logBytes threadsafebuffer.ThreadSafeBuffer
+
+	slogger := slog.New(slog.NewTextHandler(&logBytes, &slog.HandlerOptions{
+		AddSource: true,
+		Level:     slog.LevelDebug,
+	}))
+
 	k := typesMocks.NewKnapsack(t)
 	k.On("OsqueryHealthcheckStartupDelay").Return(0 * time.Second).Maybe()
 	// First, it should return false, then on the next call, it should return true
@@ -369,7 +385,7 @@ func TestFlagsChanged(t *testing.T) {
 	k.On("WatchdogUtilizationLimitPercent").Return(20)
 	k.On("WatchdogDelaySec").Return(120)
 	k.On("RegisterChangeObserver", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything)
-	k.On("Slogger").Return(multislogger.NewNopLogger())
+	k.On("Slogger").Return(slogger)
 	k.On("LatestOsquerydPath", mock.Anything).Return(testOsqueryBinaryDirectory)
 	store, err := storageci.NewStore(t, multislogger.NewNopLogger(), storage.KatcConfigStore.String())
 	require.NoError(t, err)
@@ -386,7 +402,7 @@ func TestFlagsChanged(t *testing.T) {
 
 	// Wait for the instance to start
 	time.Sleep(2 * time.Second)
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, &logBytes)
 
 	// Confirm watchdog is disabled
 	watchdogDisabled := false
@@ -404,7 +420,7 @@ func TestFlagsChanged(t *testing.T) {
 
 	// Wait for the instance to restart
 	time.Sleep(2 * time.Second)
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, &logBytes)
 
 	// Now confirm that the instance is new
 	require.NotEqual(t, startingInstance, runner.instance, "instance not replaced")
@@ -446,14 +462,14 @@ func TestFlagsChanged(t *testing.T) {
 
 // waitHealthy expects the instance to be healthy within 30 seconds, or else
 // fatals the test
-func waitHealthy(t *testing.T, runner *Runner) {
+func waitHealthy(t *testing.T, runner *Runner, logBytes *threadsafebuffer.ThreadSafeBuffer) {
 	require.NoError(t, backoff.WaitFor(func() error {
 		err := runner.Healthy()
 		if err != nil {
 			return fmt.Errorf("instance not healthy: %w", err)
 		}
 		return nil
-	}, 30*time.Second, 1*time.Second))
+	}, 30*time.Second, 1*time.Second), fmt.Sprintf("runner logs: %s", logBytes.String()))
 }
 
 func TestSimplePath(t *testing.T) {
@@ -462,11 +478,18 @@ func TestSimplePath(t *testing.T) {
 	require.NoError(t, err)
 	defer rmRootDirectory()
 
+	var logBytes threadsafebuffer.ThreadSafeBuffer
+
+	slogger := slog.New(slog.NewTextHandler(&logBytes, &slog.HandlerOptions{
+		AddSource: true,
+		Level:     slog.LevelDebug,
+	}))
+
 	k := typesMocks.NewKnapsack(t)
 	k.On("OsqueryHealthcheckStartupDelay").Return(0 * time.Second).Maybe()
 	k.On("WatchdogEnabled").Return(false)
 	k.On("RegisterChangeObserver", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything)
-	k.On("Slogger").Return(multislogger.NewNopLogger())
+	k.On("Slogger").Return(slogger)
 	k.On("LatestOsquerydPath", mock.Anything).Return(testOsqueryBinaryDirectory)
 	store, err := storageci.NewStore(t, multislogger.NewNopLogger(), storage.KatcConfigStore.String())
 	require.NoError(t, err)
@@ -479,7 +502,7 @@ func TestSimplePath(t *testing.T) {
 	)
 	go runner.Run()
 
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, &logBytes)
 
 	require.NotEmpty(t, runner.instance.stats.StartTime, "start time should be added to instance stats on start up")
 	require.NotEmpty(t, runner.instance.stats.ConnectTime, "connect time should be added to instance stats on start up")
@@ -493,11 +516,18 @@ func TestMultipleShutdowns(t *testing.T) {
 	require.NoError(t, err)
 	defer rmRootDirectory()
 
+	var logBytes threadsafebuffer.ThreadSafeBuffer
+
+	slogger := slog.New(slog.NewTextHandler(&logBytes, &slog.HandlerOptions{
+		AddSource: true,
+		Level:     slog.LevelDebug,
+	}))
+
 	k := typesMocks.NewKnapsack(t)
 	k.On("OsqueryHealthcheckStartupDelay").Return(0 * time.Second).Maybe()
 	k.On("WatchdogEnabled").Return(false)
 	k.On("RegisterChangeObserver", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything)
-	k.On("Slogger").Return(multislogger.NewNopLogger())
+	k.On("Slogger").Return(slogger)
 	k.On("LatestOsquerydPath", mock.Anything).Return(testOsqueryBinaryDirectory)
 	store, err := storageci.NewStore(t, multislogger.NewNopLogger(), storage.KatcConfigStore.String())
 	require.NoError(t, err)
@@ -510,7 +540,7 @@ func TestMultipleShutdowns(t *testing.T) {
 	)
 	go runner.Run()
 
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, &logBytes)
 
 	for i := 0; i < 3; i += 1 {
 		require.NoError(t, runner.Shutdown(), "expected no error on calling shutdown but received error on attempt: ", i)
@@ -523,11 +553,18 @@ func TestOsqueryDies(t *testing.T) {
 	require.NoError(t, err)
 	defer rmRootDirectory()
 
+	var logBytes threadsafebuffer.ThreadSafeBuffer
+
+	slogger := slog.New(slog.NewTextHandler(&logBytes, &slog.HandlerOptions{
+		AddSource: true,
+		Level:     slog.LevelDebug,
+	}))
+
 	k := typesMocks.NewKnapsack(t)
 	k.On("OsqueryHealthcheckStartupDelay").Return(0 * time.Second).Maybe()
 	k.On("WatchdogEnabled").Return(false)
 	k.On("RegisterChangeObserver", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything)
-	k.On("Slogger").Return(multislogger.NewNopLogger())
+	k.On("Slogger").Return(slogger)
 	k.On("LatestOsquerydPath", mock.Anything).Return(testOsqueryBinaryDirectory)
 	store, err := storageci.NewStore(t, multislogger.NewNopLogger(), storage.KatcConfigStore.String())
 	require.NoError(t, err)
@@ -541,7 +578,7 @@ func TestOsqueryDies(t *testing.T) {
 	go runner.Run()
 	require.NoError(t, err)
 
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, &logBytes)
 
 	previousStats := runner.instance.stats
 
@@ -551,7 +588,7 @@ func TestOsqueryDies(t *testing.T) {
 	runner.instance.errgroup.Wait()
 	runner.instanceLock.Unlock()
 
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, &logBytes)
 	require.NotEmpty(t, previousStats.Error, "error should be added to stats when unexpected shutdown")
 	require.NotEmpty(t, previousStats.ExitTime, "exit time should be added to instance when unexpected shutdown")
 
@@ -589,7 +626,7 @@ func TestExtensionIsCleanedUp(t *testing.T) {
 	t.Skip("https://github.com/kolide/launcher/issues/478")
 	t.Parallel()
 
-	runner, teardown := setupOsqueryInstanceForTests(t)
+	runner, logBytes, teardown := setupOsqueryInstanceForTests(t)
 	defer teardown()
 
 	requirePgidMatch(t, runner.instance.cmd.Process.Pid)
@@ -606,25 +643,30 @@ func TestExtensionIsCleanedUp(t *testing.T) {
 	timer1 := time.NewTimer(35 * time.Second)
 
 	// Wait for osquery to respawn
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, logBytes)
 
 	// Ensure we've waited at least 32s
 	<-timer1.C
 }
 
 // sets up an osquery instance with a running extension to be used in tests.
-func setupOsqueryInstanceForTests(t *testing.T) (runner *Runner, teardown func()) {
+func setupOsqueryInstanceForTests(t *testing.T) (runner *Runner, logBytes *threadsafebuffer.ThreadSafeBuffer, teardown func()) {
 	rootDirectory, rmRootDirectory, err := osqueryTempDir()
 	require.NoError(t, err)
 
+	slogger := slog.New(slog.NewTextHandler(logBytes, &slog.HandlerOptions{
+		AddSource: true,
+		Level:     slog.LevelDebug,
+	}))
+
 	k := typesMocks.NewKnapsack(t)
 	k.On("OsqueryHealthcheckStartupDelay").Return(0 * time.Second).Maybe()
 	k.On("WatchdogEnabled").Return(true)
 	k.On("WatchdogMemoryLimitMB").Return(150)
 	k.On("WatchdogUtilizationLimitPercent").Return(20)
 	k.On("WatchdogDelaySec").Return(120)
 	k.On("RegisterChangeObserver", mock.Anything, mock.Anything, mock.Anything, mock.Anything, mock.Anything).Maybe()
-	k.On("Slogger").Return(multislogger.NewNopLogger())
+	k.On("Slogger").Return(slogger)
 	k.On("LatestOsquerydPath", mock.Anything).Return(testOsqueryBinaryDirectory)
 	store, err := storageci.NewStore(t, multislogger.NewNopLogger(), storage.KatcConfigStore.String())
 	require.NoError(t, err)
@@ -636,13 +678,13 @@ func setupOsqueryInstanceForTests(t *testing.T) (runner *Runner, teardown func()
 		WithRootDirectory(rootDirectory),
 	)
 	go runner.Run()
-	waitHealthy(t, runner)
+	waitHealthy(t, runner, logBytes)
 
 	requirePgidMatch(t, runner.instance.cmd.Process.Pid)
 
 	teardown = func() {
 		defer rmRootDirectory()
 		require.NoError(t, runner.Shutdown())
 	}
-	return runner, teardown
+	return runner, logBytes, teardown
 }