From ba9d2a9601cd7068fbc9b5878dcd8ff4d72c6073 Mon Sep 17 00:00:00 2001 From: Victor Vrantchan Date: Sat, 11 Jul 2020 14:51:31 -0400 Subject: [PATCH] Add signal tests for main (#685) Added tests to validate the process receiving signals: - SIGTERM and SIGINT exit. - SIGUSR2 swaps logs Removed the empty Fprintln in main. Turns out stderr isn't thread safe to write from multiple locations. The logger, which is otherwise the only stderr writing goroutine creates a sync writer. But the stderr in main remains unsafe. This is something to fix later? There are also races happening with the swap log test, but only when the test runs in parallel. I'm not sure what's happening there... added a flag to make this test synchronous for now. Tests that depend on signals don't run on windows. That's a big todo. I moved SIGUSR2 behind build tags, so the binary will at least compile. --- cmd/micromdm/micromdm.go | 3 +- cmd/micromdm/micromdm_test.go | 140 +++++++++++++++++++++++++++- cmd/micromdm/swap_signal.go | 7 ++ cmd/micromdm/swap_signal_windows.go | 8 ++ pkg/log/swap_signal_windows.go | 2 +- 5 files changed, 156 insertions(+), 4 deletions(-) create mode 100644 cmd/micromdm/swap_signal.go create mode 100644 cmd/micromdm/swap_signal_windows.go diff --git a/cmd/micromdm/micromdm.go b/cmd/micromdm/micromdm.go index 351160ca..ee178534 100644 --- a/cmd/micromdm/micromdm.go +++ b/cmd/micromdm/micromdm.go @@ -31,7 +31,7 @@ func writePID(path string) error { func micromdm(args []string, stdin io.Reader, stdout, stderr io.Writer) int { var ( ctx = context.Background() - logger = log.New() + logger = log.New(log.Output(stderr)) ffOptions = []ff.Option{ff.WithConfigFileParser(ff.PlainParser), ff.WithConfigFileFlag("config")} rootfs = flag.NewFlagSet("micromdm", flag.ContinueOnError) pidfile = rootfs.String("pidfile", "/tmp/micromdm.pid", "Path to server pidfile") @@ -126,7 +126,6 @@ func micromdm(args []string, stdin io.Reader, stdout, stderr io.Writer) int { case errors.Is(err, flag.ErrHelp): return 2 default: - fmt.Fprintln(stderr) // when Ctrl+C is used, avoid messing up the logger line log.Info(logger).Log("exit", err) return 1 } diff --git a/cmd/micromdm/micromdm_test.go b/cmd/micromdm/micromdm_test.go index bd24bcb6..26750f2a 100644 --- a/cmd/micromdm/micromdm_test.go +++ b/cmd/micromdm/micromdm_test.go @@ -2,11 +2,19 @@ package main import ( "bytes" + "io/ioutil" + "os" + "path/filepath" + "runtime" + "strconv" "strings" + "syscall" "testing" + "time" ) type mainIOFunc func(t *testing.T, stdin, stdout, stderr *bytes.Buffer) +type signalFunc func(t *testing.T, pidfile string, signal os.Signal, d time.Duration) func mainUsage(t *testing.T, stdin, stdout, stderr *bytes.Buffer) { output := stderr.String() @@ -18,7 +26,86 @@ func mainUsage(t *testing.T, stdin, stdout, stderr *bytes.Buffer) { } } +func checkRestarted(t *testing.T, stdin, stdout, stderr *bytes.Buffer) { + output := stderr.String() + logsub := `level=info msg="restarting process" signal=hangup` + if !strings.Contains(output, logsub) { + t.Errorf("want %q in output, got:\n%s", logsub, output) + } +} + +func checkExitAfterSignal(t *testing.T, stdin, stdout, stderr *bytes.Buffer) { + output := stderr.String() + logsub := `level=info exit="received signal` + if !strings.Contains(output, logsub) { + t.Errorf("want %q in output, got:\n%s", logsub, output) + } +} + +func checkLogSwap(t *testing.T, stdin, stdout, stderr *bytes.Buffer) { + output := stderr.String() + debugsub := `level=debug msg="swapping level" debug=true` + if !strings.Contains(output, debugsub) { + t.Errorf("want %q in output, got:\n%s", debugsub, output) + } +} + +func logswap() signalFunc { + return func(t *testing.T, pidfile string, _ os.Signal, d time.Duration) { + signalAfter(t, pidfile, defaultSwapSignal, 50*time.Millisecond) + signalAfter(t, pidfile, syscall.SIGTERM, 100*time.Millisecond) + } +} + +func sighup() signalFunc { + return func(t *testing.T, pidfile string, _ os.Signal, d time.Duration) { + signalAfter(t, pidfile, syscall.SIGHUP, 50*time.Millisecond) + signalAfter(t, pidfile, syscall.SIGTERM, 100*time.Millisecond) + } +} + +func exitWith(s os.Signal) signalFunc { + return func(t *testing.T, pidfile string, _ os.Signal, d time.Duration) { + signalAfter(t, pidfile, s, 50*time.Millisecond) + } +} + +func signalAfter(t *testing.T, pidfile string, s os.Signal, d time.Duration) { + t.Helper() + + // sleep until pidfile has a chance to exist. + time.Sleep(10 * time.Millisecond) + + pids, err := ioutil.ReadFile(pidfile) + if err != nil { + t.Fatal(err) + } + + pid, err := strconv.Atoi(string(pids)) + if err != nil { + t.Fatal(err) + } + + proc, err := os.FindProcess(pid) + if err != nil { + t.Fatal(err) + } + + select { + case <-time.After(d): + if err := proc.Signal(s); err != nil { + t.Fatal(err) + } + return + } +} + func TestMain(t *testing.T) { + tmpdir, err := ioutil.TempDir("", "micromdm-test-main") + if err != nil { + t.Fatal(err) + } + tests := []struct { name string stdin *bytes.Buffer @@ -27,6 +114,11 @@ func TestMain(t *testing.T) { args []string exit int check mainIOFunc + signal signalFunc + + // run test synchronously + // for cases where parallel test is not possible + synchronous bool }{ { name: "short usage", @@ -55,12 +147,58 @@ func TestMain(t *testing.T) { exit: 2, check: mainUsage, }, + { + name: "exit on signal", + stdin: new(bytes.Buffer), + stdout: new(bytes.Buffer), + stderr: new(bytes.Buffer), + args: []string{"micromdm", "-pidfile", filepath.Join(tmpdir, "sigint.pid")}, + exit: 1, + check: checkExitAfterSignal, + signal: exitWith(syscall.SIGTERM), + }, + { + name: "swap logs", + stdin: new(bytes.Buffer), + stdout: new(bytes.Buffer), + stderr: new(bytes.Buffer), + args: []string{"micromdm", "-pidfile", filepath.Join(tmpdir, "sigusr.pid")}, + exit: 1, + check: checkLogSwap, + signal: logswap(), + + // run this test synchronously to avoid the data race + // bytes.Buffer is not thread safe, or is there an actual bug here? + synchronous: true, + }, + { + name: "restart on hup", + stdin: new(bytes.Buffer), + stdout: new(bytes.Buffer), + stderr: new(bytes.Buffer), + args: []string{"micromdm", "-pidfile", filepath.Join(tmpdir, "sighup.pid")}, + exit: 1, + check: checkRestarted, + signal: sighup(), + synchronous: true, + }, } for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { - t.Parallel() + if !tt.synchronous { + t.Parallel() + } + + if tt.signal != nil { + if runtime.GOOS == "windows" { + t.Skip("TODO(issues/686): signal handling on windows is not done.") + } + + // the signal and timing arguments are defaults, specified by middleware instead. + go tt.signal(t, tt.args[2], syscall.SIGTERM, 50*time.Millisecond) + } if got, want := micromdm(tt.args, tt.stdin, tt.stdout, tt.stderr), tt.exit; got != want { t.Fatalf("exit code: got %d, want %d", got, want) diff --git a/cmd/micromdm/swap_signal.go b/cmd/micromdm/swap_signal.go new file mode 100644 index 00000000..49b42e0f --- /dev/null +++ b/cmd/micromdm/swap_signal.go @@ -0,0 +1,7 @@ +// +build !windows test + +package main + +import "syscall" + +var defaultSwapSignal = syscall.SIGUSR2 diff --git a/cmd/micromdm/swap_signal_windows.go b/cmd/micromdm/swap_signal_windows.go new file mode 100644 index 00000000..cd3000c5 --- /dev/null +++ b/cmd/micromdm/swap_signal_windows.go @@ -0,0 +1,8 @@ +// +build test windows + +package main + +import "os" + +// TODO(issues/686) implement signals for windows +var defaultSwapSignal = os.Signal(nil) diff --git a/pkg/log/swap_signal_windows.go b/pkg/log/swap_signal_windows.go index 4df5112c..bf133c3d 100644 --- a/pkg/log/swap_signal_windows.go +++ b/pkg/log/swap_signal_windows.go @@ -4,5 +4,5 @@ package log import "os" -// TODO(@groob) implement +// TODO(issues/686) implement signals for windows var defaultSwapSignal = os.Signal(nil)