diff --git a/README.md b/README.md index 04ba350..4bfbe0b 100644 --- a/README.md +++ b/README.md @@ -336,6 +336,10 @@ The backend logs JSON to stdout, or plain text when stdout is a terminal. Each request is logged with its method, URL, status, client address and duration. Every value taken from a request is cut to 128 bytes before it is logged. +The steps `fx` takes to start and stop the backend are logged at debug level, so +they show only with `DEBUG` set. When the backend refuses a setting, its last +log line is one error that names the setting and the reason. + ## Design The repository holds the page, the backend and the image: diff --git a/cmd/netwatch-server/main_test.go b/cmd/netwatch-server/main_test.go index 5d9eee5..9495179 100644 --- a/cmd/netwatch-server/main_test.go +++ b/cmd/netwatch-server/main_test.go @@ -36,16 +36,94 @@ 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. +func TestDebugLogsFxLines(t *testing.T) { + t.Parallel() + + stdout, stderr := runServerUntilStopped(t, "DEBUG=1") + + requireJSONLines(t, stdout, stderr) + + if !strings.Contains(stdout.String(), `"msg":"started"`) { + t.Fatalf("no fx line in stdout with DEBUG set:\n%s", stdout) + } +} + +// TestRefusedSettingIsLastLine: a setting the server refuses stops the +// start, and the last line logged is one error 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") + + 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 +150,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 @@ -139,7 +213,8 @@ func TestRefusedSentryDSNStopsTheStart(t *testing.T) { // 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 +222,7 @@ func startServer( ctx context.Context, t *testing.T, home, port string, + env ...string, ) (*exec.Cmd, *bytes.Buffer, *bytes.Buffer) { t.Helper() @@ -166,6 +242,7 @@ func startServer( "BIND_ADDRESS=127.0.0.1", "PORT="+port, ) + child.Env = append(child.Env, env...) child.Stdout = &stdout child.Stderr = &stderr diff --git a/go.mod b/go.mod index 20cca2a..161afd5 100644 --- a/go.mod +++ b/go.mod @@ -16,6 +16,7 @@ require ( github.com/prometheus/client_golang v1.24.1 github.com/slok/go-http-metrics v0.13.0 github.com/spf13/viper v1.21.0 + go.uber.org/dig v1.19.0 go.uber.org/fx v1.24.0 golang.org/x/sys v0.47.0 ) @@ -38,7 +39,6 @@ require ( github.com/spf13/pflag v1.0.10 // indirect github.com/subosito/gotenv v1.6.0 // indirect github.com/zeebo/xxh3 v1.0.2 // indirect - go.uber.org/dig v1.19.0 // indirect go.uber.org/multierr v1.10.0 // indirect go.uber.org/zap v1.26.0 // indirect go.yaml.in/yaml/v3 v3.0.4 // indirect diff --git a/internal/cli/cli.go b/internal/cli/cli.go index 0b618c4..3d61892 100644 --- a/internal/cli/cli.go +++ b/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 } diff --git a/internal/cli/cli_test.go b/internal/cli/cli_test.go index b76428e..5da2972 100644 --- a/internal/cli/cli_test.go +++ b/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 } }