diff --git a/pkg/osquery/runtime/runtime_posix_test.go b/pkg/osquery/runtime/runtime_posix_test.go index e2ee780f0a..3feb46ce7d 100644 --- a/pkg/osquery/runtime/runtime_posix_test.go +++ b/pkg/osquery/runtime/runtime_posix_test.go @@ -78,7 +78,7 @@ func TestOsquerySlowStart(t *testing.T) { }), ) go runner.Run() - waitHealthy(t, runner) + waitHealthy(t, runner, &logBytes) // ensure that we actually had to wait on the socket require.Contains(t, logBytes.String(), "osquery extension socket not created yet") @@ -94,11 +94,17 @@ func TestExtensionSocketPath(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) @@ -113,7 +119,7 @@ func TestExtensionSocketPath(t *testing.T) { ) go runner.Run() - waitHealthy(t, runner) + waitHealthy(t, runner, &logBytes) // wait for the launcher-provided extension to register time.Sleep(2 * time.Second) @@ -135,13 +141,13 @@ func TestExtensionSocketPath(t *testing.T) { // Should investigate why this is the case. func TestRestart(t *testing.T) { t.Parallel() - runner, teardown := setupOsqueryInstanceForTests(t) + runner, logBytes, teardown := setupOsqueryInstanceForTests(t) defer teardown() previousStats := runner.instance.stats require.NoError(t, runner.Restart()) - waitHealthy(t, runner) + waitHealthy(t, runner, logBytes) require.NotEmpty(t, runner.instance.stats.StartTime, "start time should be set on latest instance stats after restart") require.NotEmpty(t, runner.instance.stats.ConnectTime, "connect time should be set on latest instance stats after restart") @@ -152,7 +158,7 @@ func TestRestart(t *testing.T) { previousStats = runner.instance.stats require.NoError(t, runner.Restart()) - waitHealthy(t, runner) + waitHealthy(t, runner, logBytes) require.NotEmpty(t, runner.instance.stats.StartTime, "start time should be added to latest instance stats after restart") require.NotEmpty(t, runner.instance.stats.ConnectTime, "connect time should be added to latest instance stats after restart") diff --git a/pkg/osquery/runtime/runtime_test.go b/pkg/osquery/runtime/runtime_test.go index 1aa958e74e..6578c7cc4c 100644 --- a/pkg/osquery/runtime/runtime_test.go +++ b/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,17 @@ 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 +355,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 +368,12 @@ 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 +383,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 +400,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 +418,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 +460,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 +476,17 @@ 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 +499,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 +513,17 @@ 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 +536,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 +549,17 @@ 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 +573,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 +583,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 +621,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,17 +638,22 @@ 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) @@ -624,7 +661,7 @@ func setupOsqueryInstanceForTests(t *testing.T) (runner *Runner, teardown func() 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,7 +673,7 @@ 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) @@ -644,5 +681,5 @@ func setupOsqueryInstanceForTests(t *testing.T) (runner *Runner, teardown func() defer rmRootDirectory() require.NoError(t, runner.Shutdown()) } - return runner, teardown + return runner, logBytes, teardown }