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

@@ -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
 	}

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)

cmd/micromdm/swap_signal.go

@@ -0,0 +1,7 @@
+// +build !windows test
+
+package main
+
+import "syscall"
+
+var defaultSwapSignal = syscall.SIGUSR2

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)

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)