Log fx's startup steps at debug; a refused setting is one line (closes #209)

fx's event lines, errors included, now log at debug level, so a normal
start shows none and DEBUG shows them. RunServer starts and stops the
fx app itself instead of calling Run, and logs fx's "received signal"
line as Run did. When the start fails, it logs the error's root cause
as one "cannot start" line, the backend's last, and returns 1. Main
returns the server's exit code.

Model: opus-5-5

cmd/netwatch-server/main_test.go

@@ -36,16 +36,103 @@ func TestMain(m *testing.M) {
 	os.Exit(m.Run())
 }
 
-// TestOutputIsJSON: off a terminal, every line the server writes from
-// start to stop is JSON, fx's own lines included.
-func TestOutputIsJSON(t *testing.T) {
+// TestOutputIsJSONWithoutFxLines: off a terminal, every line the server
+// writes from start to stop is JSON, and without DEBUG none of them is
+// one of fx's.
+func TestOutputIsJSONWithoutFxLines(t *testing.T) {
+	t.Parallel()
+
+	stdout, stderr := runServerUntilStopped(t)
+
+	requireJSONLines(t, stdout, stderr)
+
+	if !strings.Contains(stdout.String(), `"msg":"starting"`) {
+		t.Fatalf("no startup line in stdout:\n%s", stdout)
+	}
+
+	if strings.Contains(stdout.String(), `"msg":"started"`) {
+		t.Fatalf("fx line in stdout without DEBUG:\n%s", stdout)
+	}
+}
+
+// TestDebugLogsFxLines: with DEBUG set, fx's lines are logged, as
+// JSON, from the start to the signal that stops the server.
+func TestDebugLogsFxLines(t *testing.T) {
+	t.Parallel()
+
+	stdout, stderr := runServerUntilStopped(t, "DEBUG=1")
+
+	requireJSONLines(t, stdout, stderr)
+
+	for _, msg := range []string{"started", "received signal"} {
+		if !strings.Contains(stdout.String(), `"msg":"`+msg+`"`) {
+			t.Fatalf("no fx line %q in stdout with DEBUG set:\n%s",
+				msg, stdout)
+		}
+	}
+}
+
+// TestRefusedSettingIsLastLine: a setting the server refuses stops the
+// start, and the one error line logged is the last, naming the setting
+// and why, without fx's text around it.
+func TestRefusedSettingIsLastLine(t *testing.T) {
 	t.Parallel()
 
 	ctx, cancel := context.WithTimeout(t.Context(), childTimeout)
 	defer cancel()
 
+	child, stdout, stderr := startServer(ctx, t, t.TempDir(),
+		freePort(ctx, t), "REPORTS_PER_MINUTE=0")
+
+	err := child.Wait()
+	if child.ProcessState.ExitCode() != 1 {
+		t.Fatalf("server exit = %v, want exit status 1", err)
+	}
+
+	if stderr.Len() != 0 {
+		t.Fatalf("stderr = %q, want nothing", stderr)
+	}
+
+	lines := strings.Split(strings.TrimSpace(stdout.String()), "\n")
+
+	for _, line := range lines[:len(lines)-1] {
+		if strings.Contains(line, `"level":"ERROR"`) {
+			t.Fatalf("an error line before the last line:\n%s", stdout)
+		}
+	}
+
+	var last struct {
+		Level string `json:"level"`
+		Error string `json:"error"`
+	}
+
+	err = json.Unmarshal([]byte(lines[len(lines)-1]), &last)
+	if err != nil {
+		t.Fatalf("last line is not JSON: %v\n%s", err, stdout)
+	}
+
+	want := `REPORTS_PER_MINUTE "0": must be a positive whole number`
+	if last.Level != "ERROR" || last.Error != want {
+		t.Fatalf("last line has level %q, error %q; want ERROR, %q\n%s",
+			last.Level, last.Error, want, stdout)
+	}
+}
+
+// runServerUntilStopped runs main() in a child process with env added
+// to its environment, waits until it answers its health check, stops it
+// with SIGTERM and returns its stdout and stderr. It fails the test if
+// the child does not exit cleanly.
+func runServerUntilStopped(
+	t *testing.T,
+	env ...string,
+) (*bytes.Buffer, *bytes.Buffer) {
+	t.Helper()
+
+	ctx, cancel := context.WithTimeout(t.Context(), childTimeout)
+	defer cancel()
+
 	port := freePort(ctx, t)
-	child, stdout, stderr := startServer(ctx, t, t.TempDir(), port)
+	child, stdout, stderr := startServer(ctx, t, t.TempDir(), port, env...)
 
 	waitForHealthcheck(ctx, t, port)
 
@@ -72,11 +159,7 @@ func TestOutputIsJSON(t *testing.T) {
 		t.Fatalf("server exit = %v, want success", err)
 	}
 
-	requireJSONLines(t, stdout, stderr)
-
-	if !strings.Contains(stdout.String(), `"msg":"starting"`) {
-		t.Fatalf("no startup line in stdout:\n%s", stdout)
-	}
+	return stdout, stderr
 }
 
 // TestMalformedConfigFileStopsTheStart: a config file the server finds
@@ -137,9 +220,40 @@ func TestRefusedSentryDSNStopsTheStart(t *testing.T) {
 	}
 }
 
+// TestPortInUseExitsWithStatus1: a server whose port is already taken
+// cannot listen, and stops with exit status 1.
+func TestPortInUseExitsWithStatus1(t *testing.T) {
+	t.Parallel()
+
+	ctx, cancel := context.WithTimeout(t.Context(), childTimeout)
+	defer cancel()
+
+	var lc net.ListenConfig
+
+	taken, err := lc.Listen(ctx, "tcp", "127.0.0.1:0")
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	defer func() { _ = taken.Close() }()
+
+	_, port, err := net.SplitHostPort(taken.Addr().String())
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	child, stdout, _ := startServer(ctx, t, t.TempDir(), port)
+
+	err = child.Wait()
+	if child.ProcessState.ExitCode() != 1 {
+		t.Fatalf("server exit = %v, want exit status 1\n%s", err, stdout)
+	}
+}
+
 // startServer runs main() in a child process listening on
 // 127.0.0.1:port, with home as its HOME and working directory and its
-// data directory in home, so it touches nothing outside home. Its
+// data directory in home, so it touches nothing outside home. env is
+// added to its environment, as NAME=value strings. Its
 // stdout and stderr go to the two buffers returned, which hold all of
 // it once child.Wait returns. The child is killed when ctx ends, and
 // killed and reaped when the test ends if nothing waited for it.
@@ -147,6 +261,7 @@ func startServer(
 	ctx context.Context,
 	t *testing.T,
 	home, port string,
+	env ...string,
 ) (*exec.Cmd, *bytes.Buffer, *bytes.Buffer) {
 	t.Helper()
 
@@ -166,6 +281,7 @@ func startServer(
 		"BIND_ADDRESS=127.0.0.1",
 		"PORT="+port,
 	)
+	child.Env = append(child.Env, env...)
 	child.Stdout = &stdout
 	child.Stderr = &stderr