Footer says what a latency figure is (closes #208)

The old line said every check is a GET and that CORS may affect
figures; the S3 targets use HEAD and a no-cors check counts any answer.

Model: opus-5-5

README.md

@@ -57,7 +57,7 @@ The page checks 26 hosts on the internet, the WAN hosts:
 - the Anthropic API and the OpenAI API
 - the AWS Console, the Google Cloud Console and Microsoft Azure
 - Cloudflare, Fastly, Akamai, Google, GitHub and Backblaze B2
-- 8 S3 regional endpoints: Cape Town, London, Bahrain, Tokyo, Singapore, Sydney,
+- 8 S3 regional endpoints: Cape Town, London, Mumbai, Tokyo, Singapore, Sydney,
   Oregon and São Paulo
 - 6 Hetzner speed-test servers: Nuremberg, Falkenstein, Helsinki, Ashburn,
   Hillsboro and Singapore
@@ -113,19 +113,19 @@ half second. As soon as one answers, a new round starts.
 ### Rows, colors and controls
 
 A figure and its line in the graph take the color of the legend in the footer,
-from green under 50 ms to red from 500 ms up; gray is no answer. The graph's
-axis ends at 1000 ms; a higher latency is drawn at the top, and the figure still
-shows its real value.
+from green under 50 ms to red from 500 ms up; gray is no answer. The dot beside
+the host's name takes the same color. The graph's axis ends at 1000 ms; a higher
+latency is drawn at the top, and the figure still shows its real value.
 
 From time to time, the page sorts the WAN rows by their latest latency: fastest
 first, failed last. The pin button at the left of a row keeps the row at the
 top; pinned rows are sorted by name. `datavi.be` is pinned at start.
 
 `Pause` stops the checks: the graphs keep scrolling with a gap for each paused
-round, and the figures turn gray. The `Interval` menu sets the time between
-rounds: 1, 2, 3, 5, 10, 15, 30 or 60 seconds. Changing it clears the history and
-starts a new round at once. The `Debug log` checkbox in the footer opens a panel
-with the page's last 1000 log lines.
+round, and the figures and dots turn gray. The `Interval` menu sets the time
+between rounds: 1, 2, 3, 5, 10, 15, 30 or 60 seconds. Changing it clears the
+history and starts a new round at once. The `Debug log` checkbox in the footer
+opens a panel with the page's last 1000 log lines.
 
 ## Reporting
 
@@ -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:

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
 

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

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

test/unit/main.test.js

@@ -28,8 +28,8 @@ import {
 // a host's row that tick or greyOutUI draws into is a plain object, made
 // the first time a test looks it up and kept in elements under its
 // selector until the next test starts. As on a page, writing its text
-// replaces its markup; the status dot greyOutUI looks for in it is not
-// there. Drawing a sparkline does nothing; it looks for the pixel ratio on
+// replaces its markup; setting a style keeps it in the element's style
+// object. Drawing a sparkline does nothing; it looks for the pixel ratio on
 // window and finds none. The commit the page's footer names, which
 // vite.config.js fills in when it builds the page, is blank. In each test,
 // console.error and console.info print nothing and keep what they are
@@ -63,7 +63,7 @@ globalThis.document = {
     querySelector: (selector) =>
         (elements[selector] ??= {
             getContext: () => canvasContext,
-            querySelector: () => null,
+            style: {},
             set textContent(text) {
                 this.innerHTML = text;
             },
@@ -83,6 +83,12 @@ function statusText(state, host) {
     return elements[`.status-text[data-host="${index}"]`]?.innerHTML;
 }
 
+// The color last given to the dot beside host's name.
+function statusDot(state, host) {
+    const index = state.allHosts.indexOf(host);
+    return elements[`.status-dot[data-host="${index}"]`]?.style.backgroundColor;
+}
+
 // What this test wrote to the browser console with console[method].
 function consoleLines(method) {
     return console[method].mock.calls.map((call) => call.arguments[0]);
@@ -215,8 +221,8 @@ test("a target whose home page redirects is checked at /robots.txt on its own ho
             "https://s3.eu-west-2.amazonaws.com/robots.txt",
         ],
         [
-            "S3 me-south-1 (Bahrain)",
-            "https://s3.me-south-1.amazonaws.com/robots.txt",
+            "S3 ap-south-1 (Mumbai)",
+            "https://s3.ap-south-1.amazonaws.com/robots.txt",
         ],
         [
             "S3 ap-northeast-1 (Tokyo)",
@@ -683,6 +689,37 @@ test("a check that timed out or found its target unreachable has a grey figure a
     assert.equal(latencyHex(null), "#6b7280");
 });
 
+test("a check that answers after 488ms turns the dot beside its target's name orange", async (t) => {
+    const { state, target } = stateWithOneTarget();
+    mockTargets(t, () => 488);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(488);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.equal(statusDot(state, target), "#f97316");
+});
+
+test("a check that fails after one that answered turns the dot beside its target's name gray", async (t) => {
+    const { state, target } = stateWithOneTarget();
+    target.pushSample(Date.now(), { latency: 8, error: null });
+    mockTargets(t, () => 23, target.url);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(23);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.equal(statusDot(state, target), "#6b7280");
+});
+
+test("pausing turns the dot beside a target's name gray", async (t) => {
+    const { state, target } = stateWithOneTarget();
+    mockTargets(t, () => 8);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(8);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.equal(statusDot(state, target), "#22c55e");
+    state.paused = true;
+    greyOutUI(state);
+    assert.equal(statusDot(state, target), "#6b7280");
+});
+
 // buildUI draws the page into #app, here a plain object. Each entry in the
 // footer's color legend is a colored dot and the latencies it stands for,
 // with < and > written as &lt; and &gt;. A latency takes the color of the

web/src/main.js

@@ -30,8 +30,8 @@ export const CONFIG = {
         return [0, 1, 2, 3, 4, 5].map((i) => Math.round((d * i) / 5));
     },
     canvasHeight: 96,
-    // A latency figure and its sparkline take the color of the first entry
-    // whose limit, in ms, the latency is below.
+    // A latency figure, its row's dot and its sparkline take the color of
+    // the first entry whose limit, in ms, the latency is below.
     latencyColors: [
         { below: 50, hex: "#22c55e", className: "text-green-500" },
         { below: 100, hex: "#84cc16", className: "text-lime-500" },
@@ -99,8 +99,8 @@ const WAN_HOSTS = [
         method: "HEAD",
     },
     {
-        name: "S3 me-south-1 (Bahrain)",
-        url: "https://s3.me-south-1.amazonaws.com/robots.txt",
+        name: "S3 ap-south-1 (Mumbai)",
+        url: "https://s3.ap-south-1.amazonaws.com/robots.txt",
         method: "HEAD",
     },
     {
@@ -819,7 +819,7 @@ export function hostRowHTML(host, index, showPin = true) {
         ${pinBtn}
         <div class="w-[420px] flex-shrink-0 grid grid-cols-[minmax(0,1fr)_auto] items-center">
           <div class="flex items-center gap-2 min-w-[200px]">
-            <div class="w-3 h-3 rounded-full flex-shrink-0 bg-[#6b7280]"></div>
+            <div class="status-dot w-3 h-3 rounded-full flex-shrink-0 bg-[#6b7280]" data-host="${index}"></div>
             <span class="font-medium text-white truncate">${escapeHTML(host.name)}</span>
           </div>
           <div class="latency-value text-4xl font-bold tabular-nums text-right mt-3" data-host="${index}">
@@ -982,8 +982,10 @@ function updateHostRow(host, index) {
     const canvas = document.querySelector(
         `.sparkline-canvas[data-host="${index}"]`,
     );
-    if (!latencyEl || !statusEl || !canvas) return;
+    const dot = document.querySelector(`.status-dot[data-host="${index}"]`);
+    if (!latencyEl || !statusEl || !canvas || !dot) return;
 
+    dot.style.backgroundColor = latencyHex(host.lastLatency);
     if (host.lastLatency !== null) {
         const cls = latencyClass(host.lastLatency, host.status);
         latencyEl.innerHTML = `<span class="${cls}">${host.lastLatency}<span class="text-lg">ms</span></span>`;
@@ -1420,12 +1422,8 @@ export function greyOutUI(state) {
             statusEl.textContent = "paused";
             statusEl.className = `${STATUS_TEXT_CLASS} text-gray-500`;
         }
-        // Grey out the status dot
-        const row = document.querySelector(`.host-row[data-index="${i}"]`);
-        if (row) {
-            const dot = row.querySelector(".rounded-full");
-            if (dot) dot.style.backgroundColor = "#6b7280";
-        }
+        const dot = document.querySelector(`.status-dot[data-host="${i}"]`);
+        if (dot) dot.style.backgroundColor = latencyHex(null);
     });
 
     // Grey out summary current stats