From 3bb8748c8c10a3ab4b31bb4e230c0b58b4612df0 Mon Sep 17 00:00:00 2001 From: SandObserver <260779319+SandObserver@users.noreply.github.com> Date: Mon, 10 Aug 2026 17:27:03 -0400 Subject: [PATCH] Improve: reduce the container boot log to six lines Replace the boxed banner with aligned label rows and drop the guessed http://localhost: URL, which named the internal API port while nginx serves on 80 and the shipped compose maps 8700:80. Add one logfmt readiness record, since the banner bypasses both level filtering and the logfmt shape and left nothing greppable to prove the app came up. Demote the widget registry inventory to debug, collapse the two TRUST_PROXY warnings into a single branch, quiet supervisord to warn, keep the event listener protocol out of the container log, and silence the entrypoint's nginx config check on success. --- api/src/server.js | 53 ++++---- api/src/widgets.js | 4 +- api/test/boot-output.test.js | 150 +++++++++++++++++++++++ api/test/entrypoint-config-check.test.js | 9 ++ api/test/supervisord-fatal.test.js | 28 +++++ docker-entrypoint.sh | 4 +- supervisord.conf | 18 ++- 7 files changed, 239 insertions(+), 27 deletions(-) create mode 100644 api/test/boot-output.test.js diff --git a/api/src/server.js b/api/src/server.js index 49d8e439..65fa0b99 100644 --- a/api/src/server.js +++ b/api/src/server.js @@ -33,22 +33,17 @@ http.createServer(dispatch).listen(PORT, () => { const pkg = require('../package.json'); const version = process.env.APP_VERSION || pkg.version; const widgets = Object.keys(getRegistry()); - const W = 47; - const bar = c => c + '─'.repeat(W) + (c === '┌' ? '┐' : '┘'); - const mid = t => '│ ' + t.padEnd(W - 2) + ' │'; - const wlist = widgets.slice(0, 4).join(', ') + (widgets.length > 4 ? ', ...' : ''); + /* The port the container listens on, not PORT: nginx fronts the API, so PORT + is internal and naming it here sends operators to an address that answers + for nobody. */ + const row = (label, value) => ' ' + label.padEnd(11) + value; const lines = [ '', - ' ' + bar('┌'), - ' ' + mid('STACKYARD'), - ' ' + mid('self-hosted dashboard · v' + version), - ' ' + bar('└'), - ` ➜ Web UI: http://localhost:${PORT}`, - ` ➜ Config: ${CONFIG_PATH}`, - ` ➜ Icons: ${ICONS_PATH}`, - ` ➜ Widgets: ${widgets.length} loaded (${wlist})`, - ` ➜ Node: ${process.version}`, - '', + ` Stackyard ${version} · Node ${process.version}`, + row('Dashboard', ':80 in the container'), + row('Config', CONFIG_PATH), + row('Icons', ICONS_PATH), + row('Widgets', `${widgets.length} loaded`), ]; try { const ll = require('./config').loadConfig().settings.logLevel; @@ -56,14 +51,26 @@ http.createServer(dispatch).listen(PORT, () => { } catch {} log.print(lines.join('\n')); + /* The banner bypasses level filtering and the logfmt shape, so this is the + only greppable record that the app came up. */ + log.info('server ready', { + version, + port: PORT, + widgets: widgets.length, + node: process.version, + }); + /* With this on, clients can spoof X-Forwarded-* unless there really is a proxy - in front. Flagged at boot so the misconfiguration is visible. */ - if (process.env.TRUST_PROXY === 'true') - log.warn( - 'TRUST_PROXY is enabled: X-Forwarded-Proto is trusted, so a request claiming https gets a Secure session cookie. Only safe behind a reverse proxy you control.', - ); - if (process.env.TRUST_PROXY === 'true' && !process.env.TRUSTED_PROXY) - log.warn( - 'TRUST_PROXY is set but TRUSTED_PROXY is not: rate limiting counts every request through the front proxy as one client. Set TRUSTED_PROXY to the proxy address.', - ); + in front. Flagged at boot so the misconfiguration is visible. The unset case + covers the trust exposure too, so only ever one line. */ + if (process.env.TRUST_PROXY === 'true') { + if (process.env.TRUSTED_PROXY) + log.warn( + 'TRUST_PROXY is on, so forwarded headers are trusted; this is only safe behind a reverse proxy you control.', + ); + else + log.warn( + 'TRUST_PROXY without TRUSTED_PROXY trusts forwarded headers from any client and rate-limits all traffic as one; set TRUSTED_PROXY to the proxy address.', + ); + } }); diff --git a/api/src/widgets.js b/api/src/widgets.js index 27992409..8e6ef8d2 100644 --- a/api/src/widgets.js +++ b/api/src/widgets.js @@ -258,7 +258,9 @@ function loadRegistry() { }; } - log.info('widget registry loaded', { count: Object.keys(reg).length, widgets: Object.keys(reg) }); + /* debug, not info: the banner and the readiness record both carry the count, + so the names are the only extra here. Refusals stay at warn above. */ + log.debug('widget registry loaded', { count: Object.keys(reg).length, widgets: Object.keys(reg) }); _registry = reg; _rejected = rejected; return reg; diff --git a/api/test/boot-output.test.js b/api/test/boot-output.test.js new file mode 100644 index 00000000..79aa47b7 --- /dev/null +++ b/api/test/boot-output.test.js @@ -0,0 +1,150 @@ +/* What the container prints at boot. + + Spawned as a real child process rather than by requiring server.js. The + banner goes out through log.print, which bypasses level filtering and the + logfmt shape; the server starts listening on require; and both TRUST_PROXY + branches are decided once inside the listen callback. Reading the real + process output is the only way to assert on any of that. */ + +const { test } = require('node:test'); +const assert = require('node:assert/strict'); +const path = require('node:path'); +const fs = require('node:fs'); +const net = require('node:net'); +const { spawn } = require('node:child_process'); +const { tmpDir } = require('../test-support/tmp'); + +const SERVER = path.join(__dirname, '../src/server.js'); + +/* Two widgets, so the count the banner prints is one this test controls rather + than however many ship in the image. */ +function widgetsDir() { + const dir = tmpDir('boot-widgets'); + for (const name of ['alpha', 'beta']) { + const d = path.join(dir, name); + fs.mkdirSync(d, { recursive: true }); + fs.writeFileSync( + path.join(d, 'widget.json'), + JSON.stringify({ + name, + label: name, + sizes: ['medium'], + views: { main: { src: 'index.html' } }, + }), + ); + fs.writeFileSync(path.join(d, 'index.html'), ''); + } + return dir; +} + +async function freePort() { + const srv = net.createServer(); + await new Promise(r => srv.listen(0, '127.0.0.1', r)); + const { port } = srv.address(); + await new Promise(r => srv.close(r)); + return port; +} + +/* Runs the server until it reports readiness, gives the warnings that follow in + the same callback a moment to flush, then stops it. */ +async function boot(env = {}) { + const child = spawn(process.execPath, [SERVER], { + env: { + ...process.env, + PORT: String(await freePort()), + CONFIG_PATH: path.join(tmpDir('boot-config'), 'apps.json'), + WIDGETS_PATH: widgetsDir(), + APP_VERSION: '9.9.9', + LOG_LEVEL: 'info', + TRUST_PROXY: '', + TRUSTED_PROXY: '', + ...env, + }, + stdio: ['ignore', 'pipe', 'pipe'], + }); + + let out = ''; + child.stdout.on('data', d => (out += d)); + child.stderr.on('data', d => (out += d)); + + try { + await new Promise((resolve, reject) => { + const timer = setTimeout(() => reject(new Error(`never reported ready:\n${out}`)), 15000); + child.stdout.on('data', () => { + if (!out.includes('server ready')) return; + clearTimeout(timer); + setTimeout(resolve, 100); + }); + child.on('exit', code => { + clearTimeout(timer); + reject(new Error(`exited with ${code}:\n${out}`)); + }); + }); + } finally { + child.kill('SIGKILL'); + } + return out; +} + +const trustWarnings = out => out.split('\n').filter(l => l.includes('WRN') && l.includes('TRUST_PROXY')); + +test('the banner names the port the container listens on, not the API port', async () => { + const out = await boot(); + assert.ok(!out.includes('http://localhost'), 'the guessed URL reached nobody and must be gone'); + assert.match(out, /Dashboard {2}:80 in the container/); +}); + +test('the banner prints the version without a v prefix and without box drawing', async () => { + const out = await boot(); + assert.match(out, /Stackyard 9\.9\.9 · Node v/); + assert.ok(!out.includes('v9.9.9'), 'APP_VERSION defaults to "dev", so a v prefix renders "vdev"'); + for (const ch of ['┌', '┐', '└', '┘', '│', '─', '➜']) { + assert.ok(!out.includes(ch), `box drawing misaligns in narrow terminals: found ${ch}`); + } +}); + +test('the banner lines up its labels and drops the truncated widget sample', async () => { + const out = await boot(); + assert.match(out, /^ {2}Config {5}\S/m); + assert.match(out, /^ {2}Icons {6}\S/m); + assert.match(out, /^ {2}Widgets {4}2 loaded$/m); +}); + +test('one structured readiness record follows the banner', async () => { + const out = await boot(); + const ready = out.split('\n').filter(l => l.includes('msg="server ready"')); + assert.equal(ready.length, 1, 'exactly one readiness record'); + assert.match(ready[0], /INF msg="server ready" version=9\.9\.9 port=\d+ widgets=2 node=v/); +}); + +test('the widget registry inventory is not printed at the default level', async () => { + const out = await boot(); + assert.ok(!out.includes('widget registry loaded'), 'the count is already in the banner'); +}); + +test('the widget registry inventory is still available at debug', async () => { + const out = await boot({ LOG_LEVEL: 'debug' }); + assert.match(out, /DBG msg="widget registry loaded"/); + assert.ok(out.includes('alpha'), 'the names are the reason to turn debug on'); +}); + +test('TRUST_PROXY with TRUSTED_PROXY set warns exactly once', async () => { + const out = await boot({ TRUST_PROXY: 'true', TRUSTED_PROXY: '10.0.0.0/8' }); + const w = trustWarnings(out); + assert.equal(w.length, 1, `one warning, got ${w.length}: ${w.join(' | ')}`); + assert.match(w[0], /forwarded headers are trusted/); +}); + +/* The second condition implies the first, so this case used to print two long + warnings about one problem. */ +test('TRUST_PROXY without TRUSTED_PROXY warns exactly once, naming the fix', async () => { + const out = await boot({ TRUST_PROXY: 'true' }); + const w = trustWarnings(out); + assert.equal(w.length, 1, `one warning, got ${w.length}: ${w.join(' | ')}`); + assert.match(w[0], /set TRUSTED_PROXY to the proxy address/); +}); + +test('a correctly configured boot warns about neither', async () => { + const out = await boot(); + assert.deepEqual(trustWarnings(out), []); +}); diff --git a/api/test/entrypoint-config-check.test.js b/api/test/entrypoint-config-check.test.js index 82370daa..219ba843 100644 --- a/api/test/entrypoint-config-check.test.js +++ b/api/test/entrypoint-config-check.test.js @@ -82,6 +82,15 @@ test('a config nginx accepts starts normally', () => { assert.ok(r.started, 'the handoff command should have run'); }); +/* -q prints nothing on success, which is two fewer lines on every boot. The + check itself is unchanged: set -eu still stops here, and nginx still prints + what it rejected. */ +test('the config check is quiet when it passes', () => { + const fs = require('node:fs'); + const entrypoint = fs.readFileSync(require('node:path').join(__dirname, '../../docker-entrypoint.sh'), 'utf8'); + assert.match(entrypoint, /^nginx -t -q$/m); +}); + test('a config nginx rejects stops the container from starting', () => { const r = run({ nginxExit: 1 }); assert.notEqual(r.status, 0, 'the entrypoint must exit non-zero'); diff --git a/api/test/supervisord-fatal.test.js b/api/test/supervisord-fatal.test.js index f80e63bb..bd3d411a 100644 --- a/api/test/supervisord-fatal.test.js +++ b/api/test/supervisord-fatal.test.js @@ -131,6 +131,34 @@ test('the listener only acts on FATAL', () => { assert.match(listener, /RESULT 2\\nOK/); }); +/* ── the boot log stays quiet without losing the safety net ───────────────── */ + +const listenerBlock = () => supervisord.slice(supervisord.indexOf('[eventlistener:exit-on-fatal]')); + +/* This program's stdout is the event listener protocol channel. Pointing it at + /dev/stdout makes supervisord copy READY, RESULT and OK into `docker logs`, + where they read as noise nobody can act on. */ +test('the listener protocol does not reach the container log', () => { + const m = /^stdout_logfile=(\S+)$/m.exec(listenerBlock()); + assert.ok(m, 'the listener has no stdout_logfile'); + assert.notEqual(m[1], '/dev/stdout', 'this puts READY, RESULT and OK in docker logs'); +}); + +/* The other half, and the one that must never be traded away: the "could not be + started" message goes to stderr, and it is the plainest explanation an + operator gets once supervisord stops narrating at info. */ +test('the listener still reports failure on stderr', () => { + assert.match(listenerBlock(), /^stderr_logfile=\/dev\/stderr$/m); +}); + +/* At info, supervisord narrates its own startup in eight lines that say nothing + an operator acts on. At warn the crash-loop line (`exited: ... not expected`) + and configuration failures both survive. `gave up: ... entered FATAL state` is + logged at info and is lost, which is why the two messages above exist. */ +test('supervisord logs at warn, not info', () => { + assert.match(supervisord, /^loglevel=warn$/m); +}); + /* ── the script reaches the build context ──────────────────────────────────── The first attempt at this failed CI: .dockerignore excluded `scripts`, so the file was never in the build context and COPY could not find it. A bare diff --git a/docker-entrypoint.sh b/docker-entrypoint.sh index a6469cf9..322998a0 100644 --- a/docker-entrypoint.sh +++ b/docker-entrypoint.sh @@ -36,7 +36,9 @@ REALIP_CONF="${REALIP_CONF:-/etc/nginx/http.d/realip.conf}" } > "$REALIP_CONF" # Fail fast and loudly rather than starting with a config nginx will reject. -nginx -t +# -q keeps the two success lines out of every boot; set -eu still stops here on +# failure, and nginx still prints what it rejected. +nginx -t -q # supervisord always exits 0 on SIGTERM, including the SIGTERM that # scripts/exit-on-fatal.py sends when a program can no longer be started. The diff --git a/supervisord.conf b/supervisord.conf index 36e0f39e..d4b5166f 100644 --- a/supervisord.conf +++ b/supervisord.conf @@ -4,7 +4,17 @@ user=root logfile=/var/log/supervisor/supervisord.log logfile_maxbytes=10MB logfile_backups=3 -loglevel=info +; warn, not info: at info supervisord narrates its own startup in eight lines +; (Set uid, started with pid, spawned, entered RUNNING) that say nothing an +; operator acts on. What matters survives at warn: `exited: ... not expected`, +; the line that repeats while a program crash-loops, is logged at warn, and +; configuration failures are logged at critical. +; +; The one loss is `gave up: ... entered FATAL state`, which supervisor logs at +; info. That case is already covered in plainer language by the two messages +; this repo prints itself, from scripts/exit-on-fatal.py and +; docker-entrypoint.sh. Do not restore info without re-reading that trade. +loglevel=warn pidfile=/tmp/supervisord.pid [program:nginx] @@ -49,7 +59,11 @@ events=PROCESS_STATE_FATAL autostart=true autorestart=true priority=1 -stdout_logfile=/dev/stdout +; Not /dev/stdout: this program's stdout is the event listener protocol channel, +; so supervisord copying it to the child log puts READY, RESULT and OK in +; `docker logs`. supervisord still reads the protocol over its own pipe. +; stderr must stay on /dev/stderr; the "could not be started" message goes there. +stdout_logfile=/dev/null stdout_logfile_maxbytes=0 stderr_logfile=/dev/stderr stderr_logfile_maxbytes=0