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