From 89cb7626919d126a51992fc91b97e36aba726d5d Mon Sep 17 00:00:00 2001 From: Derek Reynolds Date: Tue, 11 Aug 2026 12:12:30 -0700 Subject: [PATCH] Add Beerware license and local NDJSON observability MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit License: Beerware, with an explicit as-is warranty note since the repo ships a runnable server. Corrects the vendored Idiomorph attribution — it is 0BSD (no attribution required), not BSD-2-Clause. Logging: structured NDJSON to logs/ with an OTel-shaped field vocabulary, so a Collector filelog receiver can ingest it unchanged, without pulling the OpenTelemetry SDK's dependency tree into a project with one runtime dep. Events cover commands, per-transport patch cost and compress time, broadcast fanout, connection lifetimes, rejections, a 30s runtime snapshot, and a browser-measured submit-to-patch RTT beacon — the one figure no server-side counter can observe. demo/logstat.js summarises it. Message bodies and filter queries are never logged, only their lengths, and session ids are hashed: the sid is a signed bearer cookie and does not belong in a log file. Co-Authored-By: Claude Opus 5 (1M context) --- .gitignore | 2 + LICENSE | 17 +++++ README.md | 6 +- demo/README.md | 33 +++++++++- demo/log.js | 74 ++++++++++++++++++++++ demo/logstat.js | 109 ++++++++++++++++++++++++++++++++ demo/public/pane.js | 2 +- demo/public/shell.js | 15 +++++ demo/server.js | 145 ++++++++++++++++++++++++++++++++++++++++++- 9 files changed, 399 insertions(+), 4 deletions(-) create mode 100644 LICENSE create mode 100644 demo/log.js create mode 100644 demo/logstat.js diff --git a/.gitignore b/.gitignore index d664adf..db149e8 100644 --- a/.gitignore +++ b/.gitignore @@ -9,3 +9,5 @@ tmp/ *.log .DS_Store + +logs/ diff --git a/LICENSE b/LICENSE new file mode 100644 index 0000000..c34a4e4 --- /dev/null +++ b/LICENSE @@ -0,0 +1,17 @@ +---------------------------------------------------------------------------- +"THE BEER-WARE LICENSE" (Revision 42): + wrote this software. As long as you retain +this notice you can do whatever you want with this stuff. If we meet some day, +and you think this stuff is worth it, you can buy me a beer in return. + Derek Reynolds +---------------------------------------------------------------------------- + +Beerware grants no warranty, so to be explicit: this software is provided +as-is, without warranty of any kind, express or implied. `demo/` runs a +network-facing server with no authentication; run it at your own risk. + +Third-party code included in this repository: + + demo/public/idiomorph.js — Idiomorph, https://github.com/bigskysoftware/idiomorph + Licensed 0BSD (Zero-Clause BSD), which requires no attribution. Noted here + for provenance, not obligation. diff --git a/README.md b/README.md index b4e4d13..9c2571a 100644 --- a/README.md +++ b/README.md @@ -22,6 +22,9 @@ WebSocket and just as fast, provided you are on HTTP/2. Chat is not the dividing line. Payload shape is. +Published as a write-up and reference — something to read and take ideas from, +not a library to depend on. See [LICENSE](LICENSE). + ## What's in this repo | | | @@ -30,9 +33,10 @@ Chat is not the dividing line. Payload shape is. | `results/` | captured output from those benchmarks, quoted throughout this file | | `demo/` | a live two-pane demo app you can run and click. See [`demo/README.md`](demo/README.md) | | `report.html` | a standalone write-up page of the findings | +| `LICENSE` | Beerware | `demo/public/idiomorph.js` is vendored [Idiomorph](https://github.com/bigskysoftware/idiomorph) -(BSD-2-Clause), used by both panes so DOM-update cost cannot be mistaken for a +(0BSD), used by both panes so DOM-update cost cannot be mistaken for a transport difference. The harness and the demo each have their own server on purpose: the harness one diff --git a/demo/README.md b/demo/README.md index 628a578..831bb98 100644 --- a/demo/README.md +++ b/demo/README.md @@ -93,6 +93,37 @@ Metrics are per session and per transport, counted server-side: SSE (`Content-Encoding: br`), permessage-deflate with context takeover for WebSocket. There is no brotli option for WebSocket to choose. +## Logs + +The server writes structured NDJSON to `logs/htmlwire.ndjson` (gitignored), one +event per line, so real interaction can be studied after the fact: + +``` +node demo/logstat.js # summarise it +LOG=off node demo/server.js # disable +LOG_ECHO=1 … # also mirror to stdout +LOG_DIR=/var/log/htmlwire … # somewhere else +``` + +Events: `command` (kind, render ms), `patch` (per transport: html bytes, wire +bytes, ratio, compress ms), `broadcast` (fanout, total ms), `conn.open` / +`conn.close` (protocol, compression, lifetime), `reject` (capacity, rate limit, +oversized body, no session), `runtime` (rss, cpu, streams, every 30s), and +`rtt` — submit-to-patch latency measured *in the browser* and beaconed back, +which is the one number no server-side counter can see. + +Two deliberate omissions, because this runs publicly: + +- **Message bodies and filter queries are never written**, only their lengths. + Whatever strangers type into the demo is not ours to keep. +- **Session ids are hashed to 8 hex characters.** The sid is a signed bearer + cookie; writing it to disk would put a live credential in a log file. + +This is plain NDJSON rather than the OpenTelemetry SDK on purpose — the repo +has one runtime dependency and `@opentelemetry/*` would add dozens. The field +names and units follow OTel conventions, so a Collector `filelog` receiver can +ingest the file unchanged if you ever want it off the box. + ## Session scope, and what this demo is not Sessions are keyed by an HMAC-signed cookie minted per browser, so one visitor @@ -123,7 +154,7 @@ many sessions the process is holding. | `public/pane.js` | one pane, one transport; identical below the send/onPatch seam | | `public/shell.js` | the dashboard: chart, bars, readings, controls | | `public/shell.css`, `public/app.css` | dashboard and pane styling | -| `public/idiomorph.js` | vendored [Idiomorph](https://github.com/bigskysoftware/idiomorph), BSD-2-Clause | +| `public/idiomorph.js` | vendored [Idiomorph](https://github.com/bigskysoftware/idiomorph), 0BSD | Metrics are **pushed** to the dashboard over their own SSE stream (`/metrics/stream`), not polled — a 600 ms poll can only observe the last patch, diff --git a/demo/log.js b/demo/log.js new file mode 100644 index 0000000..d4488a1 --- /dev/null +++ b/demo/log.js @@ -0,0 +1,74 @@ +// Structured NDJSON logging, one event per line, to a local file. +// +// Deliberately NOT the OpenTelemetry SDK: this project has one runtime +// dependency (`ws`), and @opentelemetry/* would add dozens of transitive ones +// to a repo whose whole point is that the stack is small enough to read. The +// events below use OTel-shaped naming and units (durations in ms, a `severity`, +// a flat attribute bag), so an OTel Collector `filelog` receiver can ingest +// this file unchanged if you ever want traces off the box. +// +// Two rules that matter because this runs publicly: +// * message bodies and filter queries are NEVER logged, only their lengths. +// Whatever strangers type into the demo is not ours to keep. +// * session ids are hashed. The sid is a signed bearer cookie; writing it to +// a log file would put a live credential on disk. + +import fs from 'node:fs' +import path from 'node:path' +import crypto from 'node:crypto' + +const ENABLED = process.env.LOG !== 'off' +const DIR = process.env.LOG_DIR ?? path.join(process.cwd(), 'logs') +const FILE = path.join(DIR, 'htmlwire.ndjson') +const MAX_BYTES = Number(process.env.LOG_MAX_BYTES ?? 32 * 1024 * 1024) +const ECHO = process.env.LOG_ECHO === '1' // also mirror to stdout + +let stream = null +let written = 0 + +function open() { + fs.mkdirSync(DIR, { recursive: true }) + written = fs.existsSync(FILE) ? fs.statSync(FILE).size : 0 + stream = fs.createWriteStream(FILE, { flags: 'a' }) + stream.on('error', () => { + stream = null + }) +} + +// Single-generation rotation: enough to bound disk on a demo box without +// pulling in a log-rotation dependency. +function rotate() { + try { + stream?.end() + fs.renameSync(FILE, FILE + '.1') + } catch {} + open() +} + +export function log(event, attrs = {}, severity = 'INFO') { + if (!ENABLED) return + if (!stream) open() + const line = + JSON.stringify({ ts: new Date().toISOString(), event, severity, ...attrs }) + '\n' + written += Buffer.byteLength(line) + if (written > MAX_BYTES) rotate() + stream?.write(line) + if (ECHO) process.stdout.write(line) +} + +// Truncated hash: enough to correlate one visitor's events, useless as a token. +const tags = new Map() +export function sessionTag(sid) { + let t = tags.get(sid) + if (!t) { + t = crypto.createHash('sha256').update(sid).digest('hex').slice(0, 8) + if (tags.size > 500) tags.clear() + tags.set(sid, t) + } + return t +} + +export function timer() { + const t0 = performance.now() + return () => +(performance.now() - t0).toFixed(2) +} diff --git a/demo/logstat.js b/demo/logstat.js new file mode 100644 index 0000000..efcf55f --- /dev/null +++ b/demo/logstat.js @@ -0,0 +1,109 @@ +// Summarise the NDJSON log. Collecting numbers is only useful if reading them +// is one command. +// +// node demo/logstat.js [path/to/htmlwire.ndjson] + +import fs from 'node:fs' +import path from 'node:path' +import readline from 'node:readline' + +const FILE = process.argv[2] ?? path.join(process.cwd(), 'logs', 'htmlwire.ndjson') +if (!fs.existsSync(FILE)) { + console.error(`no log at ${FILE} — run the demo first, or pass a path`) + process.exit(1) +} + +const pct = (a, p) => + a.length ? a.slice().sort((x, y) => x - y)[Math.min(a.length - 1, Math.floor((p / 100) * a.length))] : NaN +const fmtB = (n) => (n < 1024 ? `${Math.round(n)} B` : `${(n / 1024).toFixed(1)} KB`) + +const patches = new Map() // "workload/transport" -> {wire[], html[], ms[]} +const rtts = new Map() +const conns = new Map() +const rejects = new Map() +const runtime = [] +const sessions = new Set() +let commands = 0 + +const rl = readline.createInterface({ input: fs.createReadStream(FILE), crlfDelay: Infinity }) +for await (const line of rl) { + let e + try { + e = JSON.parse(line) + } catch { + continue + } + if (e.session) sessions.add(e.session) + if (e.event === 'command') commands++ + if (e.event === 'patch') { + const k = e.transport + if (!patches.has(k)) patches.set(k, { wire: [], html: [], ms: [] }) + const b = patches.get(k) + b.wire.push(e.wireBytes) + b.html.push(e.htmlBytes) + b.ms.push(e.compressMs) + } + if (e.event === 'rtt') { + if (!rtts.has(e.transport)) rtts.set(e.transport, []) + if (e.p50Ms) rtts.get(e.transport).push(e.p50Ms) + } + if (e.event === 'conn.close') { + if (!conns.has(e.transport)) conns.set(e.transport, []) + conns.get(e.transport).push(e.liveMs) + } + if (e.event === 'reject') rejects.set(e.reason, (rejects.get(e.reason) ?? 0) + 1) + if (e.event === 'runtime') runtime.push(e) +} + +console.log(`\n${FILE}`) +console.log(`${sessions.size} sessions · ${commands} commands\n`) + +if (patches.size) { + console.log('patch cost on the wire') + console.log(' transport n html p50 wire p50 wire p95 ratio compress p95') + for (const [k, b] of patches) { + const w = pct(b.wire, 50) + console.log( + ` ${k.padEnd(10)} ${String(b.wire.length).padEnd(6)} ${fmtB(pct(b.html, 50)).padEnd(10)} ` + + `${fmtB(w).padEnd(10)} ${fmtB(pct(b.wire, 95)).padEnd(10)} ` + + `${(pct(b.html, 50) / Math.max(1, w)).toFixed(0)}×`.padEnd(7) + + ` ${pct(b.ms, 95).toFixed(2)} ms`, + ) + } + const ws = patches.get('ws') + const sse = patches.get('sse') + if (ws && sse) { + console.log( + `\n → SSE is ${(pct(ws.wire, 50) / Math.max(1, pct(sse.wire, 50))).toFixed(1)}× leaner at the median patch`, + ) + } +} + +if (rtts.size) { + console.log('\nuser-perceived latency (submit → patch, measured in the browser)') + for (const [k, a] of rtts) { + console.log(` ${k.padEnd(10)} p50 ${pct(a, 50).toFixed(0)} ms · p95 ${pct(a, 95).toFixed(0)} ms · ${a.length} reports`) + } +} + +if (conns.size) { + console.log('\nconnection lifetime') + for (const [k, a] of conns) { + console.log(` ${k.padEnd(10)} p50 ${(pct(a, 50) / 1000).toFixed(1)}s · p95 ${(pct(a, 95) / 1000).toFixed(1)}s · ${a.length} closed`) + } +} + +if (rejects.size) { + console.log('\nrejections') + for (const [k, n] of rejects) console.log(` ${k.padEnd(18)} ${n}`) +} + +if (runtime.length) { + const last = runtime[runtime.length - 1] + console.log( + `\nruntime rss p95 ${pct(runtime.map((r) => r.rssMb), 95).toFixed(0)} MB · ` + + `cpu p95 ${pct(runtime.map((r) => r.cpuPct), 95).toFixed(1)}% · ` + + `peak streams ${Math.max(...runtime.map((r) => r.openStreams))} · ` + + `now ${last.sessions} sessions\n`, + ) +} diff --git a/demo/public/pane.js b/demo/public/pane.js index 746a460..cafc518 100644 --- a/demo/public/pane.js +++ b/demo/public/pane.js @@ -58,7 +58,7 @@ function applyPatch(target, html) { const sorted = [...rtts].sort((a, b) => a - b) const p50 = sorted[Math.floor(sorted.length / 2)] rttEl.textContent = `send → patch: ${dt.toFixed(1)}ms · p50 ${p50.toFixed(1)}ms` - parent.postMessage({ kind: 'rtt', t: T, last: dt, p50 }, '*') + parent.postMessage({ kind: 'rtt', t: T, last: dt, p50, n: rtts.length }, '*') } } diff --git a/demo/public/shell.js b/demo/public/shell.js index 28ab4a2..59baf08 100644 --- a/demo/public/shell.js +++ b/demo/public/shell.js @@ -544,5 +544,20 @@ function watchMetrics() { } } +// Report user-perceived latency back to the server log every 15s. This is the +// one number the server cannot measure for itself: submit -> patch painted. +setInterval(() => { + for (const t of ['ws', 'sse']) { + const r = rtt[t] + if (!r) continue + navigator.sendBeacon?.( + '/telemetry', + new Blob([JSON.stringify({ t, w: workload, p50: r.p50, last: r.last, n: r.n })], { + type: 'application/json', + }), + ) + } +}, 15000) + loadFrames() watchMetrics() diff --git a/demo/server.js b/demo/server.js index 0e9b9a0..4bef11c 100644 --- a/demo/server.js +++ b/demo/server.js @@ -19,6 +19,7 @@ import { fileURLToPath } from 'node:url' import { WebSocketServer } from 'ws' import { getSession, serverStats, ROW_CAP, SESSION_CAP, MAX_SUBS_PER_SESSION } from './db.js' import { renderChat, renderGrid, renderChatRow } from './render.js' +import { log, sessionTag, timer } from './log.js' // The current view for a session, in whichever workload it is running. Both // transports get this exact string. @@ -32,6 +33,27 @@ function renderView(session) { // One command path for both transports and both workloads. Returns the patch // to broadcast, or null if the command was a no-op. function applyCommand(session, cmd, via) { + const done = timer() + const patch = buildPatch(session, cmd, via) + if (patch) { + log('command', { + via, + workload: session.workload, + // What kind of interaction, never what the user typed. + kind: session.workload === 'grid' + ? (cmd.add != null ? 'add' : cmd.sort ? 'sort' : 'filter') + : cmd.mode === 'narrow' ? 'append' : 'morph', + queryLen: typeof cmd.q === 'string' ? cmd.q.length : undefined, + bodyLen: typeof cmd.body === 'string' ? cmd.body.length : undefined, + htmlBytes: Buffer.byteLength(patch.html, 'utf8'), + renderMs: done(), + session: sessionTag(session.id), + }) + } + return patch +} + +function buildPatch(session, cmd, via) { if (session.workload === 'grid') { if (typeof cmd.add === 'string') { const title = cmd.add.trim().slice(0, 120) @@ -165,6 +187,7 @@ const wsMessage = (html, id, target) => JSON.stringify({ t: 'patch', id, target, // ──────────────────────────────────────────────────────────────── broadcast async function broadcast(session, patch) { + const fanoutTimer = timer() const raw = Buffer.byteLength(patch.html, 'utf8') const id = ++session.seq await Promise.all( @@ -176,6 +199,15 @@ async function broadcast(session, patch) { ) // Push after the sends, so lastPatch reflects this patch on both sides. pushMetrics(session) + log('broadcast', { + fanout: session.subs.size, + watchers: session.watchers.size, + htmlBytes: raw, + wsWire: session.metrics.ws.lastPatch || undefined, + sseWire: session.metrics.sse.lastPatch || undefined, + totalMs: fanoutTimer(), + session: sessionTag(session.id), + }) } // ──────────────────────────────────────────────────────────────── SSE route @@ -183,10 +215,12 @@ async function broadcast(session, patch) { function handleEvents(req, res, session, compression, workload) { session.workload = workload if (openStreams >= MAX_STREAMS || !session.canSubscribe()) { + log('reject', { reason: 'capacity', transport: 'sse', openStreams, subs: session.subs.size }, 'WARN') res.writeHead(503, { 'content-type': 'text/plain', 'retry-after': '30' }) return res.end('at capacity') } openStreams++ + const liveSince = timer() const m = session.metrics.sse m.connects++ @@ -219,8 +253,19 @@ function handleEvents(req, res, session, compression, workload) { async send(patch, id, raw) { m.patches++ m.rawDown += raw + const done = timer() m.lastPatch = await comp.write(Buffer.from(sseEvent(patch.html, id, patch.target), 'utf8')) m.lastRaw = raw + log('patch', { + transport: 'sse', + protocol: sub.protocol, + compression, + htmlBytes: raw, + wireBytes: m.lastPatch, + ratio: +(raw / Math.max(1, m.lastPatch)).toFixed(1), + compressMs: done(), + session: sessionTag(session.id), + }) }, close() { try { @@ -240,6 +285,14 @@ function handleEvents(req, res, session, compression, workload) { // Keep-alive comments cost bytes too — count them honestly. const ka = setInterval(() => comp.write(Buffer.from(': ka\n\n', 'utf8')), 25000) + log('conn.open', { + transport: 'sse', + protocol: isH2 ? 'h2' : 'http/1.1', + compression, + workload, + session: sessionTag(session.id), + }) + let closed = false const done = () => { if (closed) return @@ -248,6 +301,13 @@ function handleEvents(req, res, session, compression, workload) { session.subs.delete(sub) comp.end() openStreams = Math.max(0, openStreams - 1) + log('conn.close', { + transport: 'sse', + liveMs: liveSince(), + patches: m.patches, + wireDown: m.wireDown, + session: sessionTag(session.id), + }) m.open = Math.max(0, m.open - 1) m.disconnects++ } @@ -278,6 +338,7 @@ async function handleCommand(req, res, session) { req.on('error', () => !over && resolve(null)) }) if (body === null) { + log('reject', { reason: 'body-too-large', limit: MAX_BODY }, 'WARN') if (!res.headersSent) res.writeHead(413, { 'content-type': 'text/plain' }) res.end('command body too large', () => { try { @@ -288,6 +349,7 @@ async function handleCommand(req, res, session) { } if (!session.takeToken()) { + log('reject', { reason: 'rate-limit', transport: 'sse', session: sessionTag(session.id) }, 'WARN') res.writeHead(429, { 'retry-after': '1' }) return res.end() } @@ -491,6 +553,34 @@ server.on('request', async (req, res) => { } if (p === '/command' && req.method === 'POST') return handleCommand(req, res, session) + // The number no server-side counter can see: submit -> patch painted, as + // measured in the browser. Bounded and rate-limited like any other write. + if (p === '/telemetry' && req.method === 'POST') { + let body = '' + let over = false + req.on('data', (c) => { + if (over) return + body += c + if (body.length > 1024) over = true + }) + await new Promise((r) => req.on('end', r)) + if (!over && session.takeToken()) { + try { + const t = JSON.parse(body || '{}') + log('rtt', { + transport: t.t === 'ws' ? 'ws' : 'sse', + workload: String(t.w ?? '').slice(0, 8), + p50Ms: Number(t.p50) || undefined, + lastMs: Number(t.last) || undefined, + samples: Number(t.n) || undefined, + session: sessionTag(session.id), + }) + } catch {} + } + res.writeHead(204) + return res.end() + } + if (p === '/metrics/stream') return handleMetricsStream(req, res, session) if (p === '/metrics') { @@ -570,12 +660,14 @@ wss.on('connection', (socket, req) => { const session = getSession(parseSid(req.headers.cookie ?? '')) // 1013 = "try again later". Same gates the SSE path enforces. if (!session || openStreams >= MAX_STREAMS || !session.canSubscribe()) { + log('reject', { reason: session ? 'capacity' : 'no-session', transport: 'ws', openStreams }, 'WARN') try { socket.close(1013, 'at capacity') } catch {} return } openStreams++ + const liveSince = timer() const m = session.metrics.ws m.connects++ @@ -589,6 +681,7 @@ wss.on('connection', (socket, req) => { async send(patch, id, raw) { const msg = wsMessage(patch.html, id, patch.target) const bytes = Buffer.byteLength(msg, 'utf8') + const done = timer() const payload = mirror ? await mirror.size(Buffer.from(msg, 'utf8')) : bytes m.patches++ m.rawDown += raw @@ -596,6 +689,16 @@ wss.on('connection', (socket, req) => { m.lastRaw = raw m.wireDown += m.lastPatch socket.send(msg) + log('patch', { + transport: 'ws', + protocol: 'http/1.1', + compression: mirror ? 'deflate' : 'none', + htmlBytes: raw, + wireBytes: m.lastPatch, + ratio: +(raw / Math.max(1, m.lastPatch)).toFixed(1), + compressMs: done(), + session: sessionTag(session.id), + }) }, close() { try { @@ -617,7 +720,10 @@ wss.on('connection', (socket, req) => { return } if (cmd.t !== 'cmd') return - if (!session.takeToken()) return + if (!session.takeToken()) { + log('reject', { reason: 'rate-limit', transport: 'ws', session: sessionTag(session.id) }, 'WARN') + return + } m.commands++ // Client frames are masked: +4 bytes over the server-side overhead. @@ -628,6 +734,14 @@ wss.on('connection', (socket, req) => { if (patch) await broadcast(session, patch) }) + log('conn.open', { + transport: 'ws', + protocol: 'http/1.1', + compression: compress ? 'deflate' : 'none', + workload: session.workload, + session: sessionTag(session.id), + }) + let closed = false const done = () => { if (closed) return @@ -635,6 +749,13 @@ wss.on('connection', (socket, req) => { session.subs.delete(sub) mirror?.end() openStreams = Math.max(0, openStreams - 1) + log('conn.close', { + transport: 'ws', + liveMs: liveSince(), + patches: m.patches, + wireDown: m.wireDown, + session: sessionTag(session.id), + }) m.open = Math.max(0, m.open - 1) m.disconnects++ } @@ -642,6 +763,28 @@ wss.on('connection', (socket, req) => { socket.on('error', done) }) +// A heartbeat of what the box is actually doing, so slow periods can be +// correlated with memory and connection pressure after the fact. +let cpuBase = process.cpuUsage() +let cpuAt = Date.now() +setInterval(() => { + const mem = process.memoryUsage() + const cpu = process.cpuUsage(cpuBase) + const elapsed = Date.now() - cpuAt + cpuBase = process.cpuUsage() + cpuAt = Date.now() + const st = serverStats() + log('runtime', { + rssMb: +(mem.rss / 1048576).toFixed(1), + heapMb: +(mem.heapUsed / 1048576).toFixed(1), + cpuPct: +(((cpu.user + cpu.system) / 1000 / Math.max(1, elapsed)) * 100).toFixed(1), + openStreams, + sessions: st.sessions, + sqliteKb: +(st.bytes / 1024).toFixed(0), + tcpConnections, + }) +}, 30000).unref() + server.listen(PORT, HOST, () => { console.log(`\n transport bake-off demo`) console.log(` ${USE_TLS ? 'https' : 'http'}://${HOST ?? 'localhost'}:${PORT}\n`) -- knotmirror 0.0.1