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

internal/cli/cli.go

@@ -5,8 +5,11 @@
 package cli
 
 import (
+	"context"
 	"fmt"
 	"io"
+	"log/slog"
+	"os"
 	"os/user"
 
 	"sneak.berlin/go/netwatch/internal/config"
@@ -18,6 +21,7 @@ import (
 	"sneak.berlin/go/netwatch/internal/reportbuf"
 	"sneak.berlin/go/netwatch/internal/server"
 
+	"go.uber.org/dig"
 	"go.uber.org/fx"
 	"go.uber.org/fx/fxevent"
 )
@@ -29,19 +33,17 @@ const usageExitCode = 2
 // Main runs netwatch-server with args, its command line after the
 // program's name, and returns the exit code. With no args, Main runs
 // the server by calling serve with appname and version, the name and
-// version the server logs and reports. With "check-cidr CIDR" or
-// "prepare-data-dir DATA_DIR" it runs that subcommand, which writes its
-// errors to stderr. Any other args get a one-line usage message on
-// stderr and exit code 2. main passes os.Stderr and RunServer; the
-// tests pass a buffer and a function of their own, so that no test
-// starts the server. When serve is RunServer and the server fails to
-// start, to listen or to stop, fx's Run exits the process with status 1
-// and Main never returns.
+// version the server logs and reports, and returns serve's exit code.
+// With "check-cidr CIDR" or "prepare-data-dir DATA_DIR" it runs that
+// subcommand, which writes its errors to stderr. Any other args get a
+// one-line usage message on stderr and exit code 2. main passes
+// os.Stderr and RunServer; the tests pass a buffer and a function of
+// their own, so that no test starts the server.
 func Main(
 	stderr io.Writer,
 	appname, version string,
 	args []string,
-	serve func(appname, version string),
+	serve func(appname, version string) int,
 ) int {
 	// "netwatch-server check-cidr CIDR" exits 1, with the error, if
 	// this server would refuse CIDR in its TRUSTED_PROXIES.
@@ -67,9 +69,7 @@ func Main(
 		return usageExitCode
 	}
 
-	serve(appname, version)
-
-	return 0
+	return serve(appname, version)
 }
 
 // checkCIDR returns 0 if the server would take cidr in its
@@ -109,19 +109,30 @@ func prepareDataDir(stderr io.Writer, volume, dataDir, username string) int {
 }
 
 // RunServer runs the server until it is told to stop, with appname and
-// version as the name and version it logs and reports. If the server
-// fails to start, to listen or to stop, fx's Run exits the process
-// with status 1 itself.
-func RunServer(appname, version string) {
+// version as the name and version it logs and reports, and returns the
+// exit code. If the server fails to start, to listen or to stop, it
+// returns 1. A failed start logs one line with the error's cause, such
+// as the setting refused and why, as the server's last line.
+func RunServer(appname, version string) int {
 	globals.Appname = appname
 	globals.Version = version
 
-	fx.New(
-		// fx logs each step of starting and stopping through the
-		// server's own logger, so off a terminal those lines are
-		// JSON like every other line.
+	var (
+		log   *logger.Logger
+		fxLog *fxevent.SlogLogger
+	)
+
+	app := fx.New(
+		// fx logs each step of starting and stopping, errors included,
+		// at debug level through the server's own logger: they show
+		// only with DEBUG set, and off a terminal they are JSON like
+		// every other line.
 		fx.WithLogger(func(log *logger.Logger) fxevent.Logger {
-			return &fxevent.SlogLogger{Logger: log.Get()}
+			fxLog = &fxevent.SlogLogger{Logger: log.Get()}
+			fxLog.UseLogLevel(slog.LevelDebug)
+			fxLog.UseErrorLevel(slog.LevelDebug)
+
+			return fxLog
 		}),
 		fx.Provide(
 			config.New,
@@ -133,11 +144,51 @@ func RunServer(appname, version string) {
 			reportbuf.New,
 			server.New,
 		),
+		// First, so that log is set for the error below even when a
+		// setting stops the start.
+		fx.Populate(&log),
 		fx.Invoke(
-			// First, so the name and version are logged even when
-			// a setting stops the start.
+			// Before the server, so that the name and version are
+			// logged even when a setting stops the start.
 			func(log *logger.Logger) { log.Identify() },
 			func(*server.Server) {},
 		),
-	).Run()
+	)
+
+	startCtx, cancelStart := context.WithTimeout(
+		context.Background(), app.StartTimeout())
+	defer cancelStart()
+
+	err := app.Start(startCtx)
+	if err != nil {
+		// fx wraps a constructor's error in its own text; the cause
+		// alone names the setting. log is nil only if fx failed
+		// before it built the logger.
+		cause := dig.RootCause(err)
+		if log == nil {
+			_, _ = fmt.Fprintln(os.Stderr, cause)
+		} else {
+			log.Get().Error("cannot start", "error", cause)
+		}
+
+		return 1
+	}
+
+	// A signal, or the server asking to stop after a listen error.
+	// fx's Run logs the signal here, so this does too.
+	shutdown := <-app.Wait()
+	fxLog.LogEvent(&fxevent.Stopping{Signal: shutdown.Signal})
+
+	stopCtx, cancelStop := context.WithTimeout(
+		context.Background(), app.StopTimeout())
+	defer cancelStop()
+
+	err = app.Stop(stopCtx)
+	if err != nil {
+		log.Get().Error("cannot stop cleanly", "error", err)
+
+		return 1
+	}
+
+	return shutdown.ExitCode
 }

internal/cli/cli_test.go

@@ -63,7 +63,7 @@ func TestMainRunsPrepareDataDir(t *testing.T) {
 
 // TestMainRunsServerWithNoArguments: Main given no arguments starts the
 // server with the name and version it was given, writes nothing and
-// returns 0.
+// returns the server's exit code.
 func TestMainRunsServerWithNoArguments(t *testing.T) {
 	t.Parallel()
 
@@ -73,11 +73,13 @@ func TestMainRunsServerWithNoArguments(t *testing.T) {
 	)
 
 	code := cli.Main(&stderr, "netwatch", "test", []string{},
-		func(appname, version string) {
+		func(appname, version string) int {
 			gotAppname, gotVersion = appname, version
+
+			return 3
 		})
-	if code != 0 || stderr.Len() != 0 {
-		t.Errorf("exit %d, stderr %q; want exit 0 and no output",
+	if code != 3 || stderr.Len() != 0 {
+		t.Errorf("exit %d, stderr %q; want exit 3 and no output",
 			code, stderr.String())
 	}
 
@@ -210,10 +212,12 @@ func currentUsername(t *testing.T) string {
 
 // failIfServerStarts is what the tests give Main in place of
 // cli.RunServer: it fails the test instead of starting the server.
-func failIfServerStarts(t *testing.T) func(appname, version string) {
+func failIfServerStarts(t *testing.T) func(appname, version string) int {
 	t.Helper()
 
-	return func(string, string) {
+	return func(string, string) int {
 		t.Error("Main started the server")
+
+		return 0
 	}
 }