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: 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,27 @@ 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
+
+	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 +141,49 @@ 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.
+	shutdown := <-app.Wait()
+
+	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
 	}
 }