diff --git a/README.md b/README.md index d916461..a8ea2ba 100644 --- a/README.md +++ b/README.md @@ -12,8 +12,12 @@ Request tracing and performance visualization library for Node.js. Inspect the f - **Request Tracing** — Full lifecycle tracking with async context propagation via `AsyncLocalStorage` - **Step Tracking** — Manual instrumentation for DB calls, service calls, async operations +- **Automatic Middleware Instrumentation** — Auto-capture middleware timing for Express, Fastify lifecycle phases, and Koa +- **HTTP Client Tracing** — Auto-instrument outgoing `http`, `https`, and `fetch` requests - **Framework Support** — Express.js, Fastify, and Koa -- **UI Dashboard** — Built-in real-time visualization at `/trace/ui` +- **UI Dashboard** — Built-in real-time visualization at `/trace/ui` with Waterfall, Timeline, and Flamegraph views +- **CLI Tool** — Inspect traces from the terminal with `npx node-request-trace` +- **Chrome Trace Export** — Export traces to `chrome://tracing` format for performance engineers - **HTTP API** — JSON endpoints for trace retrieval and statistics - **Slow Request Detection** — Configurable threshold with automatic flagging - **Sampling** — Configurable rate to reduce overhead in production @@ -26,11 +30,10 @@ Request tracing and performance visualization library for Node.js. Inspect the f The library has three core components: -```mermaid -graph LR - A["Trace Engine
AsyncLocalStorage context
+ step tracking"] --> B["Trace Storage
In-memory store
with eviction & retention"] - B --> C["UI Dashboard
Real-time visualization
at /trace/ui"] -``` +| Trace Engine | → | Trace Storage | → | UI Dashboard | +|:---:|:---:|:---:|:---:|:---:| +| AsyncLocalStorage context | | In-memory store | | Real-time visualization | +| + step tracking | | with eviction & retention | | at `/trace/ui` | ## Installation @@ -139,7 +142,8 @@ trace.init({ samplingRate: 1, // 0-1 — fraction of requests to trace (0.1 = 10%) maxTraces: 1000, // max traces kept in memory retentionSeconds: 300, // auto-evict traces older than this (seconds) - autoTrack: false, // auto-track Express middleware execution times + autoTrack: false, // auto-track middleware execution times + traceOutgoing: false, // auto-trace outgoing http/https/fetch requests sensitiveHeaders: null, // custom list of headers to redact (string[]) }); ``` @@ -150,7 +154,8 @@ trace.init({ | `samplingRate` | `1` | Fraction of requests to trace (`1` = 100%, `0.1` = 10%) | | `maxTraces` | `1000` | Maximum traces held in memory; oldest evicted when full | | `retentionSeconds` | `300` | Traces older than this are automatically evicted | -| `autoTrack` | `false` | Automatically track Express middleware execution times | +| `autoTrack` | `false` | Auto-instrument middleware for Express, Fastify lifecycle, Koa | +| `traceOutgoing` | `false` | Auto-trace outgoing `http`, `https`, and `fetch` requests | | `sensitiveHeaders` | `null` | Custom array of header names to redact (overrides defaults) | ## API Reference @@ -201,13 +206,44 @@ Returns the current request trace object, or `null` if called outside a traced r Attach a logger for trace output. Returns `this` for chaining. +### `trace.instrumentKoa(app)` + +Patches `app.use()` on a Koa instance to automatically wrap each middleware with timing. Requires `autoTrack: true`. + +```js +const app = new Koa(); +trace.instrumentKoa(app); // patches app.use() +app.use(authMiddleware); // automatically timed +app.use(validateInput); // automatically timed +``` + +### `trace.enableHttpTracing()` + +Manually enable outgoing HTTP client tracing. Monkey-patches `http.request`, `http.get`, `https.request`, `https.get`, and `globalThis.fetch`. Alternatively, set `traceOutgoing: true` in `init()`. + +### `trace.disableHttpTracing()` + +Restore original HTTP functions and stop tracing outgoing requests. + +### `trace.isHttpTracingEnabled()` + +Returns `true` if outgoing HTTP tracing is currently active. + +### `trace.exportChromeTrace(trace)` + +Convert a trace object to [Chrome Trace Event Format](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU). Returns a `{ traceEvents: [...] }` object. + +### `trace.exportChromeTraceJson(trace)` + +Same as above but returns a JSON string ready for file export. + ### `trace.sanitizeHeaders(headers)` Returns a copy of headers with sensitive values replaced by `[REDACTED]`. ### `trace.destroy()` -Clean up storage intervals and clear all stored traces. +Clean up storage intervals, clear all stored traces, and disable HTTP tracing. ## HTTP Endpoints @@ -220,6 +256,7 @@ Mount with `app.use(trace.routes())` to enable these endpoints: | `GET /trace/slow` | Traces exceeding `slowThreshold` | | `GET /trace/stats` | Aggregate statistics | | `GET /trace/:requestId` | Single trace by request ID | +| `GET /trace/:requestId/chrome` | Chrome Trace Event Format export | ### Example: `/trace/stats` response @@ -263,9 +300,11 @@ Accessible at `/trace/ui`. The dashboard provides: ### Recent Requests Table Sortable table showing request ID, method, path, duration, status, and timestamp. Click any row to view the full trace detail. -### Request Timeline Visualization -Each request displays a waterfall timeline of its steps: +### Request Detail with View Modes + +Click any request to see its full detail with three visualization modes: +**Waterfall** — Bars proportional to step duration (default): ``` authMiddleware |████| 12ms validateInput |██| 5ms @@ -274,6 +313,25 @@ paymentService |██████████| 45ms responseRender |████████| 30ms ``` +**Timeline** — Time-proportional positioning showing when each step started and how long it ran: +``` +|-------------- request 340ms ----------------| +auth |██| +validation |█| +dbQuery |████████████████████████| +payment |████| +render |██| +0ms 340ms +``` + +**Flamegraph** — Compact stacked view showing step durations as proportional blocks: +``` +[auth][val][ dbQuery ][payment][render] +0ms 340ms +``` + +Each detail view also includes a **⬇ Chrome Trace** export button. + ### Slow Requests View Filtered view showing only requests exceeding the configured `slowThreshold`. @@ -386,6 +444,139 @@ app.use(async (ctx) => { app.listen(3000); ``` +## Automatic Middleware Instrumentation + +Enable `autoTrack: true` to automatically capture middleware timing without manual `trace.step()` calls. + +### Express + +Express middleware layers are automatically wrapped to record each middleware's execution time: + +```js +trace.init({ autoTrack: true }); +app.use(trace.middleware()); +``` + +Example trace output: +``` +authMiddleware: 12ms +validateInput: 5ms +handler: 210ms +``` + +### Fastify + +Fastify lifecycle phases are automatically timed: + +```js +trace.init({ autoTrack: true }); +fastify.register(trace.fastifyPlugin()); +``` + +Records: `onRequest`, `preParsing`, `preValidation`, `handler`, `onSend` — each as a step with `type: "lifecycle"`. + +### Koa + +Patch the Koa app to wrap each `app.use()` call with timing: + +```js +trace.init({ autoTrack: true }); +const app = new Koa(); +trace.instrumentKoa(app); + +app.use(authMiddleware); // auto-timed as "authMiddleware" +app.use(validateInput); // auto-timed as "validateInput" +app.use(trace.koaMiddleware()); +``` + +Each middleware is recorded as a step with `type: "middleware"`. + +## HTTP Client Tracing + +Automatically capture outgoing HTTP requests as trace steps: + +```js +trace.init({ traceOutgoing: true }); +``` + +Or enable/disable manually: + +```js +trace.enableHttpTracing(); +// ... make requests ... +trace.disableHttpTracing(); +``` + +Instruments `http.request`, `http.get`, `https.request`, `https.get`, and `globalThis.fetch` (Node 18+). + +Example trace with outgoing calls: +``` +GET /checkout +├─ dbQuery 210ms +├─ HTTP POST stripe.com/v1 180ms [http-outgoing] +├─ redis.get 5ms +└─ HTTP GET cdn.example.com 45ms [http-outgoing] +``` + +Outgoing steps are recorded with `type: "http-outgoing"` and include the method, host, and path. + +## CLI Tool + +Inspect traces from the terminal without the UI dashboard: + +```bash +# Show aggregate statistics +npx node-request-trace stats http://localhost:3000 + +# List recent traces +npx node-request-trace recent http://localhost:3000 + +# List slow traces +npx node-request-trace slow http://localhost:3000 + +# Inspect a single trace with timeline + flamegraph +npx node-request-trace inspect http://localhost:3000 req_a1b2c3d4 + +# Live tail incoming requests +npx node-request-trace tail http://localhost:3000 + +# Export trace as Chrome Trace Event JSON +npx node-request-trace export http://localhost:3000 req_a1b2c3d4 > trace.json +``` + +The CLI uses ANSI colors and renders waterfall bars, flamegraph blocks, and formatted tables directly in the terminal. + +## Chrome Trace Export + +Export any trace in [Chrome Trace Event Format](https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU) for analysis in `chrome://tracing` or other performance tools. + +### Via HTTP endpoint + +```bash +curl http://localhost:3000/trace/req_a1b2c3d4/chrome > trace.json +``` + +### Via API + +```js +const traceData = tracer.storage.get("req_a1b2c3d4"); +const chromeTrace = trace.exportChromeTrace(traceData); +// or as JSON string +const json = trace.exportChromeTraceJson(traceData); +``` + +### Via Dashboard + +Click the **⬇ Chrome Trace** button in any trace detail view to download the file. + +### Via CLI + +```bash +npx node-request-trace export http://localhost:3000 req_a1b2c3d4 > trace.json +``` + +Open the exported file in `chrome://tracing` to see a full timeline visualization with request and step events on separate threads. + ## Logging Integration ```js diff --git a/bin/cli.js b/bin/cli.js new file mode 100644 index 0000000..37ffced --- /dev/null +++ b/bin/cli.js @@ -0,0 +1,317 @@ +#!/usr/bin/env node +'use strict'; + +const http = require('node:http'); +const https = require('node:https'); + +const RESET = '\x1b[0m'; +const BOLD = '\x1b[1m'; +const DIM = '\x1b[2m'; +const RED = '\x1b[31m'; +const GREEN = '\x1b[32m'; +const YELLOW = '\x1b[33m'; +const BLUE = '\x1b[34m'; +const MAGENTA = '\x1b[35m'; +const CYAN = '\x1b[36m'; +const WHITE = '\x1b[37m'; +const GRAY = '\x1b[90m'; + +const BAR_COLORS = [MAGENTA, CYAN, RED, YELLOW, BLUE, GREEN]; + +const USAGE = ` +${BOLD}node-request-trace CLI${RESET} + +${BOLD}Usage:${RESET} + npx node-request-trace [options] + +${BOLD}Commands:${RESET} + ${GREEN}stats${RESET} Show trace statistics + ${GREEN}recent${RESET} Show recent traces + ${GREEN}slow${RESET} Show slow traces + ${GREEN}inspect${RESET} Show single trace detail + ${GREEN}tail${RESET} Live tail of incoming traces + ${GREEN}export${RESET} Export trace as Chrome Trace JSON + +${BOLD}Examples:${RESET} + npx node-request-trace stats http://localhost:3000 + npx node-request-trace recent http://localhost:3000 + npx node-request-trace inspect http://localhost:3000 req_abc123 + npx node-request-trace tail http://localhost:3000 + npx node-request-trace export http://localhost:3000 req_abc123 > trace.json +`; + +function fetchJson(url) { + return new Promise((resolve, reject) => { + const mod = url.startsWith('https') ? https : http; + mod.get(url, (res) => { + let data = ''; + res.on('data', (chunk) => { data += chunk; }); + res.on('end', () => { + if (res.statusCode >= 400) { + return reject(new Error(`HTTP ${res.statusCode}: ${data}`)); + } + try { resolve(JSON.parse(data)); } + catch (e) { reject(new Error('Invalid JSON response')); } + }); + }).on('error', reject); + }); +} + +function methodColor(m) { + switch (m) { + case 'GET': return GREEN; + case 'POST': return MAGENTA; + case 'PUT': return YELLOW; + case 'DELETE': return RED; + default: return WHITE; + } +} + +function statusColor(s) { + if (s < 300) return GREEN; + if (s < 400) return BLUE; + if (s < 500) return YELLOW; + return RED; +} + +function fmtDuration(ms) { + if (ms >= 1000) return (ms / 1000).toFixed(1) + 's'; + return ms + 'ms'; +} + +function fmtTime(ts) { + return new Date(ts).toLocaleTimeString(); +} + +function padRight(str, len) { + return str.length >= len ? str.slice(0, len) : str + ' '.repeat(len - str.length); +} + +function padLeft(str, len) { + return str.length >= len ? str : ' '.repeat(len - str.length) + str; +} + +function renderBar(ratio, width) { + const filled = Math.max(Math.round(ratio * width), 1); + return '█'.repeat(filled) + '░'.repeat(Math.max(width - filled, 0)); +} + +function printStats(stats) { + console.log(`\n${BOLD} Trace Statistics${RESET}\n`); + console.log(` ${CYAN}Total Requests${RESET} ${BOLD}${stats.totalRequests}${RESET}`); + console.log(` ${GREEN}Avg Latency${RESET} ${BOLD}${fmtDuration(stats.avgLatency)}${RESET}`); + console.log(` ${YELLOW}Slow Requests${RESET} ${BOLD}${stats.slowRequests}${RESET}`); + console.log(` ${RED}Error Rate${RESET} ${BOLD}${stats.errorRate}%${RESET}`); + console.log(` ${BLUE}Requests/sec${RESET} ${BOLD}${stats.requestsPerSec}${RESET}`); + console.log(); +} + +function printTraceTable(traces, label) { + if (!traces.length) { + console.log(`\n ${DIM}No ${label} traces found${RESET}\n`); + return; + } + + console.log(`\n${BOLD} ${label} (${traces.length})${RESET}\n`); + console.log(` ${DIM}${padRight('ID', 14)} ${padRight('METHOD', 8)} ${padRight('PATH', 30)} ${padLeft('DURATION', 10)} ${padLeft('STATUS', 8)} TIME${RESET}`); + console.log(` ${DIM}${'─'.repeat(90)}${RESET}`); + + for (const t of traces) { + const mc = methodColor(t.method); + const sc = statusColor(t.status); + const dur = fmtDuration(t.duration); + const isSlow = t._slow ? ` ${RED}●${RESET}` : ''; + console.log( + ` ${GRAY}${padRight(t.requestId.slice(0, 12), 14)}${RESET}` + + ` ${mc}${padRight(t.method, 8)}${RESET}` + + ` ${padRight(t.path, 30)}` + + ` ${padLeft(dur, 10)}${isSlow}` + + ` ${sc}${padLeft(String(t.status), 8)}${RESET}` + + ` ${DIM}${fmtTime(t.startTime)}${RESET}` + ); + } + console.log(); +} + +function printTraceDetail(t) { + console.log(`\n${BOLD} ${t.method} ${t.path}${RESET}\n`); + console.log(` ${DIM}Request ID${RESET} ${t.requestId}`); + console.log(` ${DIM}Status${RESET} ${statusColor(t.status)}${t.status}${RESET}`); + console.log(` ${DIM}Duration${RESET} ${BOLD}${fmtDuration(t.duration)}${RESET}`); + console.log(` ${DIM}Time${RESET} ${fmtTime(t.startTime)}`); + + if (!t.steps || !t.steps.length) { + console.log(`\n ${DIM}No steps recorded${RESET}\n`); + return; + } + + const maxDur = Math.max(...t.steps.map(s => s.duration), 1); + const barWidth = 30; + + console.log(`\n${BOLD} Timeline (${t.steps.length} steps)${RESET}\n`); + + t.steps.forEach((s, i) => { + const ratio = s.duration / maxDur; + const color = BAR_COLORS[i % BAR_COLORS.length]; + const bar = renderBar(ratio, barWidth); + const errTag = s.error ? ` ${RED}✗ ${s.error}${RESET}` : ''; + const typeTag = s.type ? ` ${DIM}[${s.type}]${RESET}` : ''; + + console.log( + ` ${padRight(s.name, 22)} ${color}${bar}${RESET} ${padLeft(fmtDuration(s.duration), 8)}${typeTag}${errTag}` + ); + }); + + // Flamegraph-style compact view + console.log(`\n${BOLD} Flamegraph${RESET}\n`); + const totalWidth = 60; + let flame = ' '; + t.steps.forEach((s, i) => { + const w = Math.max(Math.round((s.duration / t.duration) * totalWidth), 1); + const color = BAR_COLORS[i % BAR_COLORS.length]; + const label = s.name.length <= w - 2 ? s.name : s.name.slice(0, Math.max(w - 2, 1)); + flame += `${color}[${padRight(label, w - 1)}]${RESET}`; + }); + console.log(flame); + console.log(` ${DIM}${'─'.repeat(totalWidth + 2)}${RESET}`); + console.log(` ${DIM}0ms${' '.repeat(totalWidth - 6)}${fmtDuration(t.duration)}${RESET}`); + console.log(); +} + +async function cmdStats(baseUrl) { + const stats = await fetchJson(`${baseUrl}/trace/stats`); + printStats(stats); +} + +async function cmdRecent(baseUrl) { + const traces = await fetchJson(`${baseUrl}/trace/recent`); + printTraceTable(traces, 'Recent Traces'); +} + +async function cmdSlow(baseUrl) { + const traces = await fetchJson(`${baseUrl}/trace/slow`); + printTraceTable(traces, 'Slow Traces'); +} + +async function cmdInspect(baseUrl, requestId) { + if (!requestId) { + console.error(`${RED}Error: request ID required${RESET}`); + console.error('Usage: npx node-request-trace inspect '); + process.exit(1); + } + const trace = await fetchJson(`${baseUrl}/trace/${requestId}`); + printTraceDetail(trace); +} + +async function cmdTail(baseUrl) { + console.log(`${BOLD} Tailing traces from ${baseUrl}${RESET}`); + console.log(` ${DIM}Press Ctrl+C to stop${RESET}\n`); + + let lastSeenId = null; + + const poll = async () => { + try { + const traces = await fetchJson(`${baseUrl}/trace/recent`); + if (traces.length && traces[0].requestId !== lastSeenId) { + const newTraces = []; + for (const t of traces) { + if (t.requestId === lastSeenId) break; + newTraces.push(t); + } + for (const t of newTraces.reverse()) { + const mc = methodColor(t.method); + const sc = statusColor(t.status); + const dur = fmtDuration(t.duration); + const slow = t._slow ? ` ${RED}●${RESET}` : ''; + console.log( + ` ${DIM}${fmtTime(t.startTime)}${RESET}` + + ` ${mc}${t.method}${RESET}` + + ` ${t.path}` + + ` ${BOLD}${dur}${RESET}${slow}` + + ` ${sc}${t.status}${RESET}` + + ` ${GRAY}${t.requestId.slice(0, 12)}${RESET}` + ); + } + lastSeenId = traces[0].requestId; + } + } catch (_) { /* silent */ } + }; + + await poll(); + const interval = setInterval(poll, 2000); + process.on('SIGINT', () => { + clearInterval(interval); + console.log(`\n ${DIM}Stopped.${RESET}\n`); + process.exit(0); + }); +} + +async function cmdExport(baseUrl, requestId) { + if (!requestId) { + console.error(`${RED}Error: request ID required${RESET}`); + console.error('Usage: npx node-request-trace export '); + process.exit(1); + } + const chromeTrace = await fetchJson(`${baseUrl}/trace/${requestId}/chrome`); + console.log(JSON.stringify(chromeTrace, null, 2)); +} + +async function main() { + const args = process.argv.slice(2); + const command = args[0]; + const baseUrl = args[1]; + + if (!command || command === '--help' || command === '-h') { + console.log(USAGE); + return; + } + + if (!baseUrl) { + console.error(`${RED}Error: server URL required${RESET}`); + console.log(USAGE); + process.exit(1); + } + + const cleanUrl = baseUrl.replace(/\/$/, ''); + + try { + switch (command) { + case 'stats': return await cmdStats(cleanUrl); + case 'recent': return await cmdRecent(cleanUrl); + case 'slow': return await cmdSlow(cleanUrl); + case 'inspect': return await cmdInspect(cleanUrl, args[2]); + case 'tail': return await cmdTail(cleanUrl); + case 'export': return await cmdExport(cleanUrl, args[2]); + default: + console.error(`${RED}Unknown command: ${command}${RESET}`); + console.log(USAGE); + process.exit(1); + } + } catch (err) { + console.error(`${RED}Error: ${err.message}${RESET}`); + process.exit(1); + } +} + +main(); + +module.exports = { + fetchJson, + printStats, + printTraceTable, + printTraceDetail, + padRight, + padLeft, + renderBar, + fmtDuration, + fmtTime, + methodColor, + statusColor, + main, + cmdStats, + cmdRecent, + cmdSlow, + cmdInspect, + cmdTail, + cmdExport, +}; diff --git a/index.js b/index.js index f6cd90b..4937d96 100644 --- a/index.js +++ b/index.js @@ -5,9 +5,12 @@ const TraceStorage = require('./lib/trace-storage'); const expressMiddleware = require('./lib/middleware/express'); const fastifyPlugin = require('./lib/middleware/fastify'); const koaMiddleware = require('./lib/middleware/koa'); +const { instrumentKoa } = require('./lib/middleware/koa'); const { createRouter } = require('./lib/routes'); const { createPinoIntegration, createWinstonIntegration, createConsoleIntegration } = require('./lib/logger'); const { sanitizeHeaders } = require('./lib/security'); +const { enableHttpTracing, disableHttpTracing, isEnabled: isHttpTracingEnabled } = require('./lib/http-tracer'); +const { toChromeTraceFormat, toChromeTraceJson } = require('./lib/chrome-trace'); const DEFAULT_CONFIG = { slowThreshold: 200, @@ -15,6 +18,7 @@ const DEFAULT_CONFIG = { maxTraces: 1000, retentionSeconds: 300, autoTrack: false, + traceOutgoing: false, logBody: false, sensitiveHeaders: null, }; @@ -35,6 +39,11 @@ class RequestTracer { }); this.storage.startCleanup(); this._initialized = true; + + if (this.config.traceOutgoing) { + enableHttpTracing(); + } + return this; } @@ -56,6 +65,11 @@ class RequestTracer { return koaMiddleware(this); } + instrumentKoa(app) { + this._ensureInit(); + return instrumentKoa(app, this); + } + routes() { this._ensureInit(); return createRouter(this); @@ -82,6 +96,28 @@ class RequestTracer { return this; } + enableHttpTracing() { + enableHttpTracing(); + return this; + } + + disableHttpTracing() { + disableHttpTracing(); + return this; + } + + isHttpTracingEnabled() { + return isHttpTracingEnabled(); + } + + exportChromeTrace(trace) { + return toChromeTraceFormat(trace); + } + + exportChromeTraceJson(trace) { + return toChromeTraceJson(trace); + } + sanitizeHeaders(headers) { return sanitizeHeaders(headers, this.config.sensitiveHeaders); } @@ -91,6 +127,7 @@ class RequestTracer { this.storage.stopCleanup(); this.storage.clear(); } + disableHttpTracing(); this._initialized = false; } diff --git a/lib/chrome-trace.js b/lib/chrome-trace.js new file mode 100644 index 0000000..f999b8f --- /dev/null +++ b/lib/chrome-trace.js @@ -0,0 +1,51 @@ +'use strict'; + +function toChromeTraceFormat(trace) { + const events = []; + const pid = 1; + const tid = 1; + + events.push({ + cat: 'request', + name: `${trace.method} ${trace.path}`, + ph: 'X', + ts: trace.startTime * 1000, + dur: trace.duration * 1000, + pid, + tid, + args: { + requestId: trace.requestId, + status: trace.status, + }, + }); + + if (trace.steps && trace.steps.length) { + for (const step of trace.steps) { + const event = { + cat: 'step', + name: step.name, + ph: 'X', + ts: step.start * 1000, + dur: step.duration * 1000, + pid, + tid: tid + 1, + args: {}, + }; + if (step.error) { + event.args.error = step.error; + } + if (step.type) { + event.args.type = step.type; + } + events.push(event); + } + } + + return { traceEvents: events }; +} + +function toChromeTraceJson(trace) { + return JSON.stringify(toChromeTraceFormat(trace)); +} + +module.exports = { toChromeTraceFormat, toChromeTraceJson }; diff --git a/lib/dashboard.js b/lib/dashboard.js index b0150ba..b41cf0f 100644 --- a/lib/dashboard.js +++ b/lib/dashboard.js @@ -77,6 +77,7 @@ function getDashboardHtml(config) { .tl-label { width:160px; flex-shrink:0; text-align:right; padding-right:12px; color:var(--text2); overflow:hidden; text-overflow:ellipsis; white-space:nowrap; } .tl-bar-wrap { flex:1; height:22px; background:var(--surface2); border-radius:4px; position:relative; overflow:hidden; } .tl-bar { height:100%; border-radius:4px; display:flex; align-items:center; padding-left:6px; font-size:11px; font-weight:600; color:#fff; min-width:24px; } + .tl-bar.positioned { position:absolute; top:0; } .tl-dur { margin-left:8px; color:var(--text2); font-size:12px; width:60px; flex-shrink:0; } .color-0 { background: linear-gradient(90deg, #6c5ce7, #a29bfe); } .color-1 { background: linear-gradient(90deg, #00cec9, #81ecec); } @@ -85,6 +86,23 @@ function getDashboardHtml(config) { .color-4 { background: linear-gradient(90deg, #74b9ff, #0984e3); } .color-5 { background: linear-gradient(90deg, #55efc4, #00b894); } + /* Flamegraph */ + .flamegraph { margin-top:12px; } + .flame-row { display:flex; height:28px; margin-bottom:2px; border-radius:4px; overflow:hidden; } + .flame-block { display:flex; align-items:center; justify-content:center; font-size:10px; font-weight:600; color:#fff; overflow:hidden; white-space:nowrap; text-overflow:ellipsis; padding:0 4px; border-right:1px solid var(--bg); cursor:default; } + .flame-block:hover { filter:brightness(1.2); } + .flame-axis { display:flex; justify-content:space-between; font-size:11px; color:var(--text2); margin-top:4px; } + + /* View tabs in detail */ + .view-tabs { display:flex; gap:4px; margin:12px 0; background:var(--surface2); border-radius:8px; padding:3px; width:fit-content; } + .view-tab { padding:5px 14px; border-radius:6px; cursor:pointer; font-size:12px; font-weight:500; color:var(--text2); border:none; background:none; } + .view-tab.active { background:var(--accent); color:#fff; } + .view-tab:hover:not(.active) { color:var(--text); } + + /* Chrome export button */ + .export-btn { display:inline-flex; align-items:center; gap:4px; padding:6px 14px; background:var(--surface2); border:1px solid var(--border); border-radius:6px; color:var(--text2); font-size:12px; cursor:pointer; margin-left:8px; } + .export-btn:hover { color:var(--text); border-color:var(--accent); } + .empty { text-align:center; padding:40px; color:var(--text2); } .section-title { font-size:14px; font-weight:600; margin-bottom:12px; } #content-slow, #content-live { display:none; } @@ -157,32 +175,100 @@ function renderRow(t) { + '' + fmtTime(t.startTime) + ''; } -function renderTimeline(steps, totalDur) { +function renderWaterfall(steps) { if (!steps || !steps.length) return '
No steps recorded
'; const maxDur = Math.max(...steps.map(s => s.duration), 1); return steps.map((s, i) => { const pct = Math.max((s.duration / maxDur) * 100, 3); - return '
' + s.name + '
' + const errTag = s.error ? ' \\u2717 ' + s.error + '' : ''; + const typeTag = s.type ? ' [' + s.type + ']' : ''; + return '
' + s.name + typeTag + '
' + '
' - + '
' + s.duration + 'ms
'; + + '
' + s.duration + 'ms' + errTag + '
'; }).join(''); } +function renderTimeline(steps, requestStart, totalDur) { + if (!steps || !steps.length) return '
No steps recorded
'; + const dur = Math.max(totalDur, 1); + let html = ''; + html += steps.map((s, i) => { + const offsetPct = Math.max(((s.start - requestStart) / dur) * 100, 0); + const widthPct = Math.max((s.duration / dur) * 100, 2); + const errTag = s.error ? ' \\u2717' : ''; + return '
' + s.name + '
' + + '
' + + '
' + s.duration + 'ms' + errTag + '
'; + }).join(''); + html += '
0ms' + totalDur + 'ms
'; + return html; +} + +function renderFlamegraph(steps, totalDur) { + if (!steps || !steps.length) return '
No steps recorded
'; + const dur = Math.max(totalDur, 1); + let html = '
'; + steps.forEach((s, i) => { + const pct = Math.max((s.duration / dur) * 100, 2); + const label = s.duration > dur * 0.05 ? s.name : ''; + html += '
' + label + '
'; + }); + html += '
0ms' + totalDur + 'ms
'; + return html; +} + +let _currentTrace = null; +let _currentView = 'waterfall'; + +function switchView(view) { + _currentView = view; + document.querySelectorAll('.view-tab').forEach(b => { + b.classList.toggle('active', b.dataset.view === view); + }); + const container = document.getElementById('viz-container'); + if (!_currentTrace || !container) return; + const t = _currentTrace; + if (view === 'waterfall') container.innerHTML = renderWaterfall(t.steps); + else if (view === 'timeline') container.innerHTML = renderTimeline(t.steps, t.startTime, t.duration); + else if (view === 'flamegraph') container.innerHTML = renderFlamegraph(t.steps, t.duration); +} + +async function exportChrome(id) { + const r = await fetch('/trace/' + id + '/chrome'); + if (!r.ok) return; + const data = await r.text(); + const blob = new Blob([data], { type: 'application/json' }); + const a = document.createElement('a'); + a.href = URL.createObjectURL(blob); + a.download = 'trace-' + id + '.json'; + a.click(); + URL.revokeObjectURL(a.href); +} + async function showDetail(id) { const r = await fetch('/trace/' + id); if (!r.ok) return; const t = await r.json(); + _currentTrace = t; + _currentView = 'waterfall'; const p = document.getElementById('detail-panel'); p.innerHTML = '' - + '

' + t.method + ' ' + t.path + '

' + + '

' + t.method + ' ' + t.path + + '' + + '

' + '
' + '
Request ID
' + t.requestId + '
' + '
Status
' + t.status + '
' + '
Duration
' + t.duration + 'ms
' + '
Time
' + fmtTime(t.startTime) + '
' + '
' - + '
Timeline (' + (t.steps ? t.steps.length : 0) + ' steps)
' - + '
' + renderTimeline(t.steps, t.duration) + '
'; + + '
' + + '' + + '' + + '' + + '
' + + '
Steps (' + (t.steps ? t.steps.length : 0) + ')
' + + '
' + renderWaterfall(t.steps) + '
'; document.getElementById('detail-overlay').classList.add('open'); } diff --git a/lib/http-tracer.js b/lib/http-tracer.js new file mode 100644 index 0000000..043afa1 --- /dev/null +++ b/lib/http-tracer.js @@ -0,0 +1,207 @@ +'use strict'; + +const http = require('node:http'); +const https = require('node:https'); +const { currentTrace } = require('./trace-engine'); + +let _origHttpRequest = null; +let _origHttpGet = null; +let _origHttpsRequest = null; +let _origHttpsGet = null; +let _origFetch = null; +let _enabled = false; + +function enableHttpTracing() { + if (_enabled) return; + _enabled = true; + + _origHttpRequest = http.request; + _origHttpGet = http.get; + _origHttpsRequest = https.request; + _origHttpsGet = https.get; + + http.request = function tracedHttpRequest(...args) { + return _wrapRequest(_origHttpRequest, 'http', args); + }; + http.get = function tracedHttpGet(...args) { + const req = _wrapRequest(_origHttpRequest, 'http', args); + req.end(); + return req; + }; + https.request = function tracedHttpsRequest(...args) { + return _wrapRequest(_origHttpsRequest, 'https', args); + }; + https.get = function tracedHttpsGet(...args) { + const req = _wrapRequest(_origHttpsRequest, 'https', args); + req.end(); + return req; + }; + + if (typeof globalThis.fetch === 'function') { + _origFetch = globalThis.fetch; + globalThis.fetch = function tracedFetch(...args) { + return _wrapFetch(_origFetch, args); + }; + } +} + +function disableHttpTracing() { + if (!_enabled) return; + _enabled = false; + + if (_origHttpRequest) { + http.request = _origHttpRequest; + _origHttpRequest = null; + } + if (_origHttpGet) { + http.get = _origHttpGet; + _origHttpGet = null; + } + if (_origHttpsRequest) { + https.request = _origHttpsRequest; + _origHttpsRequest = null; + } + if (_origHttpsGet) { + https.get = _origHttpsGet; + _origHttpsGet = null; + } + if (_origFetch) { + globalThis.fetch = _origFetch; + _origFetch = null; + } +} + +function isEnabled() { + return _enabled; +} + +function _parseRequestArgs(args) { + let method = 'GET'; + let host = 'unknown'; + let path = '/'; + + const first = args[0]; + if (typeof first === 'string') { + try { + const u = new URL(first); + host = u.host; + path = u.pathname; + } catch (_) { + path = first; + } + } else if (first instanceof URL) { + host = first.host; + path = first.pathname; + } else if (first && typeof first === 'object') { + host = first.hostname || first.host || 'unknown'; + path = first.path || '/'; + method = first.method || 'GET'; + } + + const second = args[1]; + if (second && typeof second === 'object' && typeof second !== 'function') { + if (second.method) method = second.method; + if (second.hostname || second.host) host = second.hostname || second.host; + if (second.path) path = second.path; + } + + return { method: method.toUpperCase(), host, path }; +} + +function _wrapRequest(origFn, protocol, args) { + const trace = currentTrace(); + if (!trace) return origFn.apply(null, args); + + const { method, host, path } = _parseRequestArgs(args); + const stepName = `HTTP ${method} ${host}${path}`; + const start = Date.now(); + + const req = origFn.apply(null, args); + + req.on('response', () => { + trace.steps.push({ + name: stepName, + start, + duration: Date.now() - start, + type: 'http-outgoing', + }); + }); + + req.on('error', (err) => { + trace.steps.push({ + name: stepName, + start, + duration: Date.now() - start, + type: 'http-outgoing', + error: err.message, + }); + }); + + return req; +} + +async function _wrapFetch(origFn, args) { + const trace = currentTrace(); + if (!trace) return origFn.apply(globalThis, args); + + const input = args[0]; + const init = args[1] || {}; + + let method = 'GET'; + let host = 'unknown'; + let path = '/'; + + if (typeof input === 'string') { + try { + const u = new URL(input); + host = u.host; + path = u.pathname; + } catch (_) { + path = input; + } + } else if (input instanceof URL) { + host = input.host; + path = input.pathname; + } else if (input && typeof input === 'object' && input.url) { + try { + const u = new URL(input.url); + host = u.host; + path = u.pathname; + } catch (_) { /* ignore */ } + method = input.method || method; + } + + method = (init.method || method).toUpperCase(); + + const stepName = `HTTP ${method} ${host}${path}`; + const start = Date.now(); + + try { + const response = await origFn.apply(globalThis, args); + trace.steps.push({ + name: stepName, + start, + duration: Date.now() - start, + type: 'http-outgoing', + }); + return response; + } catch (err) { + trace.steps.push({ + name: stepName, + start, + duration: Date.now() - start, + type: 'http-outgoing', + error: err.message, + }); + throw err; + } +} + +module.exports = { + enableHttpTracing, + disableHttpTracing, + isEnabled, + _parseRequestArgs, + _wrapRequest, + _wrapFetch, +}; diff --git a/lib/middleware/fastify.js b/lib/middleware/fastify.js index 8a5e217..9f05b35 100644 --- a/lib/middleware/fastify.js +++ b/lib/middleware/fastify.js @@ -17,15 +17,41 @@ function fastifyPlugin(tracer) { reply.header('X-Request-ID', trace.requestId); request._trace = trace; + request._tracePhaseStart = Date.now(); runWithTrace(trace, () => { hookDone(); }); }); + if (tracer.config.autoTrack) { + fastify.addHook('preParsing', (request, reply, payload, hookDone) => { + _recordPhase(request, 'onRequest'); + hookDone(null, payload); + }); + + fastify.addHook('preValidation', (request, reply, hookDone) => { + _recordPhase(request, 'preParsing'); + hookDone(); + }); + + fastify.addHook('preHandler', (request, reply, hookDone) => { + _recordPhase(request, 'preValidation'); + hookDone(); + }); + + fastify.addHook('onSend', (request, reply, payload, hookDone) => { + _recordPhase(request, 'handler'); + hookDone(null, payload); + }); + } + fastify.addHook('onResponse', (request, reply, hookDone) => { const trace = request._trace; if (trace) { + if (tracer.config.autoTrack) { + _recordPhase(request, 'onSend'); + } finalizeTrace(trace, reply.statusCode); tracer._onTraceComplete(trace); } @@ -36,4 +62,21 @@ function fastifyPlugin(tracer) { }; } +function _recordPhase(request, phaseName) { + const trace = request._trace; + if (!trace || !request._tracePhaseStart) return; + + const now = Date.now(); + const duration = now - request._tracePhaseStart; + if (duration > 0) { + trace.steps.push({ + name: phaseName, + start: request._tracePhaseStart, + duration, + type: 'lifecycle', + }); + } + request._tracePhaseStart = now; +} + module.exports = fastifyPlugin; diff --git a/lib/middleware/koa.js b/lib/middleware/koa.js index 5a6a9c0..3199e9f 100644 --- a/lib/middleware/koa.js +++ b/lib/middleware/koa.js @@ -35,4 +35,43 @@ function koaMiddleware(tracer) { }; } +function instrumentKoa(app, tracer) { + if (!app || typeof app.use !== 'function') return app; + if (app._traceInstrumented) return app; + + const originalUse = app.use.bind(app); + let mwIndex = 0; + + app.use = function instrumentedUse(fn) { + if (!tracer.config.autoTrack) { + return originalUse(fn); + } + + const name = fn.name || fn._name || `middleware_${mwIndex++}`; + + const wrapped = async function (ctx, next) { + const trace = ctx._trace; + const start = Date.now(); + try { + await fn(ctx, next); + } finally { + if (trace) { + trace.steps.push({ + name, + start, + duration: Date.now() - start, + type: 'middleware', + }); + } + } + }; + + return originalUse(wrapped); + }; + + app._traceInstrumented = true; + return app; +} + module.exports = koaMiddleware; +module.exports.instrumentKoa = instrumentKoa; diff --git a/lib/routes.js b/lib/routes.js index 2bb44ef..4121c60 100644 --- a/lib/routes.js +++ b/lib/routes.js @@ -1,6 +1,7 @@ 'use strict'; const { getDashboardHtml } = require('./dashboard'); +const { toChromeTraceFormat } = require('./chrome-trace'); function createRouter(tracer) { return function traceRouter(req, res, next) { @@ -22,6 +23,16 @@ function createRouter(tracer) { return serveJson(res, getStats(tracer)); } + const chromeMatch = url.match(/^\/trace\/([a-zA-Z0-9_]+)\/chrome$/); + if (chromeMatch) { + const trace = tracer.storage.get(chromeMatch[1]); + if (trace) { + return serveJson(res, toChromeTraceFormat(trace)); + } + res.writeHead(404, { 'Content-Type': 'application/json' }); + return res.end(JSON.stringify({ error: 'Trace not found' })); + } + const singleMatch = url.match(/^\/trace\/([a-zA-Z0-9_]+)$/); if (singleMatch) { const trace = tracer.storage.get(singleMatch[1]); diff --git a/package-lock.json b/package-lock.json index 85cd856..9fa74d9 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "node-request-trace", - "version": "1.0.0", + "version": "1.0.2", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "node-request-trace", - "version": "1.0.0", + "version": "1.0.2", "license": "MIT", "devDependencies": { "c8": "^11.0.0" diff --git a/package.json b/package.json index e3c96b3..1002a50 100644 --- a/package.json +++ b/package.json @@ -1,11 +1,15 @@ { "name": "node-request-trace", - "version": "1.0.0", + "version": "1.0.2", "description": "Request tracing and performance visualization library for Node.js", "main": "index.js", + "bin": { + "node-request-trace": "./bin/cli.js" + }, "files": [ "index.js", - "lib/" + "lib/", + "bin/" ], "scripts": { "test": "node test/run.js", @@ -22,7 +26,16 @@ "debugging", "monitoring" ], + "author": "beingmartinbmc", "license": "MIT", + "repository": { + "type": "git", + "url": "git+https://github.com/beingmartinbmc/node-request-trace.git" + }, + "homepage": "https://github.com/beingmartinbmc/node-request-trace#readme", + "bugs": { + "url": "https://github.com/beingmartinbmc/node-request-trace/issues" + }, "engines": { "node": ">=16.0.0" }, diff --git a/test/run.js b/test/run.js index 4e06320..b95586e 100644 --- a/test/run.js +++ b/test/run.js @@ -1502,5 +1502,786 @@ test('api: module exports singleton and RequestTracer class', () => { assert(typeof mod.RequestTracer === 'function'); }); +// ========================================================================= +// lib/chrome-trace.js +// ========================================================================= +const { toChromeTraceFormat, toChromeTraceJson } = require('../lib/chrome-trace'); + +test('chrome-trace: toChromeTraceFormat with steps', () => { + const trace = { + requestId: 'req_abc', + method: 'GET', + path: '/test', + startTime: 1000, + duration: 100, + status: 200, + steps: [ + { name: 'db', start: 1010, duration: 50 }, + { name: 'cache', start: 1060, duration: 20, error: 'miss', type: 'cache' }, + ], + }; + const result = toChromeTraceFormat(trace); + assert(result.traceEvents != null); + assertEqual(result.traceEvents.length, 3); + // Request event + assertEqual(result.traceEvents[0].cat, 'request'); + assertEqual(result.traceEvents[0].name, 'GET /test'); + assertEqual(result.traceEvents[0].ph, 'X'); + assertEqual(result.traceEvents[0].ts, 1000 * 1000); + assertEqual(result.traceEvents[0].dur, 100 * 1000); + assertEqual(result.traceEvents[0].args.requestId, 'req_abc'); + assertEqual(result.traceEvents[0].args.status, 200); + // Step events + assertEqual(result.traceEvents[1].cat, 'step'); + assertEqual(result.traceEvents[1].name, 'db'); + assertEqual(result.traceEvents[1].ts, 1010 * 1000); + assertEqual(result.traceEvents[1].dur, 50 * 1000); + // Step with error and type + assertEqual(result.traceEvents[2].args.error, 'miss'); + assertEqual(result.traceEvents[2].args.type, 'cache'); +}); + +test('chrome-trace: toChromeTraceFormat without steps', () => { + const trace = { + requestId: 'req_no', method: 'POST', path: '/x', + startTime: 500, duration: 10, status: 201, steps: [], + }; + const result = toChromeTraceFormat(trace); + assertEqual(result.traceEvents.length, 1); +}); + +test('chrome-trace: toChromeTraceFormat with null steps', () => { + const trace = { + requestId: 'req_null', method: 'GET', path: '/', + startTime: 500, duration: 10, status: 200, + }; + const result = toChromeTraceFormat(trace); + assertEqual(result.traceEvents.length, 1); +}); + +test('chrome-trace: toChromeTraceFormat step without error or type', () => { + const trace = { + requestId: 'req_plain', method: 'GET', path: '/', + startTime: 500, duration: 10, status: 200, + steps: [{ name: 's1', start: 501, duration: 5 }], + }; + const result = toChromeTraceFormat(trace); + assertEqual(result.traceEvents[1].args.error, undefined); + assertEqual(result.traceEvents[1].args.type, undefined); +}); + +test('chrome-trace: toChromeTraceJson returns valid JSON', () => { + const trace = { + requestId: 'req_json', method: 'GET', path: '/', + startTime: 500, duration: 10, status: 200, steps: [], + }; + const json = toChromeTraceJson(trace); + assert(typeof json === 'string'); + const parsed = JSON.parse(json); + assert(parsed.traceEvents != null); +}); + +// ========================================================================= +// lib/http-tracer.js +// ========================================================================= +const httpTracer = require('../lib/http-tracer'); +const { runWithTrace: rwtForHttp, currentTrace: ctForHttp } = require('../lib/trace-engine'); +const { EventEmitter } = require('node:events'); + +test('http-tracer: _parseRequestArgs with string URL', () => { + const result = httpTracer._parseRequestArgs(['https://api.example.com/users?q=1']); + assertEqual(result.method, 'GET'); + assertEqual(result.host, 'api.example.com'); + assertEqual(result.path, '/users'); +}); + +test('http-tracer: _parseRequestArgs with URL object', () => { + const u = new URL('https://stripe.com/v1/charges'); + const result = httpTracer._parseRequestArgs([u]); + assertEqual(result.host, 'stripe.com'); + assertEqual(result.path, '/v1/charges'); +}); + +test('http-tracer: _parseRequestArgs with options object', () => { + const result = httpTracer._parseRequestArgs([{ hostname: 'db.local', path: '/query', method: 'POST' }]); + assertEqual(result.method, 'POST'); + assertEqual(result.host, 'db.local'); + assertEqual(result.path, '/query'); +}); + +test('http-tracer: _parseRequestArgs with options using host instead of hostname', () => { + const result = httpTracer._parseRequestArgs([{ host: 'myhost:3000', path: '/api' }]); + assertEqual(result.host, 'myhost:3000'); +}); + +test('http-tracer: _parseRequestArgs defaults', () => { + const result = httpTracer._parseRequestArgs([{}]); + assertEqual(result.method, 'GET'); + assertEqual(result.host, 'unknown'); + assertEqual(result.path, '/'); +}); + +test('http-tracer: _parseRequestArgs with second arg overrides', () => { + const result = httpTracer._parseRequestArgs([ + 'http://old.com/old', + { method: 'PUT', hostname: 'new.com', path: '/new' }, + ]); + assertEqual(result.method, 'PUT'); + assertEqual(result.host, 'new.com'); + assertEqual(result.path, '/new'); +}); + +test('http-tracer: _parseRequestArgs with second arg using host', () => { + const result = httpTracer._parseRequestArgs([ + 'http://old.com/old', + { host: 'newhost:8080' }, + ]); + assertEqual(result.host, 'newhost:8080'); +}); + +test('http-tracer: _parseRequestArgs with function as second arg ignores it', () => { + const cb = () => {}; + const result = httpTracer._parseRequestArgs(['http://example.com/path', cb]); + assertEqual(result.host, 'example.com'); + assertEqual(result.path, '/path'); +}); + +test('http-tracer: _parseRequestArgs with invalid string URL', () => { + const result = httpTracer._parseRequestArgs(['/relative/path']); + assertEqual(result.path, '/relative/path'); +}); + +test('http-tracer: enableHttpTracing / disableHttpTracing / isEnabled', () => { + assert(!httpTracer.isEnabled()); + httpTracer.enableHttpTracing(); + assert(httpTracer.isEnabled()); + // Idempotent + httpTracer.enableHttpTracing(); + assert(httpTracer.isEnabled()); + httpTracer.disableHttpTracing(); + assert(!httpTracer.isEnabled()); + // Idempotent + httpTracer.disableHttpTracing(); + assert(!httpTracer.isEnabled()); +}); + +test('http-tracer: _wrapRequest without active trace returns original', () => { + const fakeReq = new EventEmitter(); + const origFn = () => fakeReq; + const result = httpTracer._wrapRequest(origFn, 'http', [{ hostname: 'test.com', path: '/x' }]); + assertEqual(result, fakeReq); +}); + +test('http-tracer: _wrapRequest with trace records step on response', () => { + const fakeReq = new EventEmitter(); + const origFn = () => fakeReq; + const trace = { requestId: 'r1', steps: [] }; + + rwtForHttp(trace, () => { + const req = httpTracer._wrapRequest(origFn, 'http', [{ hostname: 'api.com', path: '/data', method: 'GET' }]); + assertEqual(req, fakeReq); + fakeReq.emit('response', {}); + assertEqual(trace.steps.length, 1); + assert(trace.steps[0].name.includes('api.com')); + assert(trace.steps[0].duration >= 0); + assertEqual(trace.steps[0].type, 'http-outgoing'); + }); +}); + +test('http-tracer: _wrapRequest with trace records step on error', () => { + const fakeReq = new EventEmitter(); + const origFn = () => fakeReq; + const trace = { requestId: 'r2', steps: [] }; + + rwtForHttp(trace, () => { + httpTracer._wrapRequest(origFn, 'https', [{ hostname: 'fail.com', path: '/err' }]); + fakeReq.emit('error', new Error('connect refused')); + assertEqual(trace.steps.length, 1); + assertEqual(trace.steps[0].error, 'connect refused'); + assertEqual(trace.steps[0].type, 'http-outgoing'); + }); +}); + +test('http-tracer: _wrapFetch without active trace calls original', async () => { + let called = false; + const origFn = async () => { called = true; return { status: 200 }; }; + const result = await httpTracer._wrapFetch(origFn, ['http://example.com/api']); + assert(called); + assertEqual(result.status, 200); +}); + +test('http-tracer: _wrapFetch with trace records step on success', async () => { + const origFn = async () => ({ status: 200 }); + const trace = { requestId: 'rf1', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + await httpTracer._wrapFetch(origFn, ['https://api.stripe.com/v1/charges', { method: 'POST' }]); + assertEqual(trace.steps.length, 1); + assert(trace.steps[0].name.includes('api.stripe.com')); + assert(trace.steps[0].name.includes('POST')); + assertEqual(trace.steps[0].type, 'http-outgoing'); + resolve(); + }); + }); +}); + +test('http-tracer: _wrapFetch with trace records step on error', async () => { + const origFn = async () => { throw new Error('network error'); }; + const trace = { requestId: 'rf2', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + try { + await httpTracer._wrapFetch(origFn, ['http://fail.com/x']); + } catch (e) { + assertEqual(e.message, 'network error'); + } + assertEqual(trace.steps.length, 1); + assertEqual(trace.steps[0].error, 'network error'); + resolve(); + }); + }); +}); + +test('http-tracer: _wrapFetch with URL object input', async () => { + const origFn = async () => ({ status: 200 }); + const trace = { requestId: 'rf3', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + const u = new URL('https://cdn.example.com/assets'); + await httpTracer._wrapFetch(origFn, [u]); + assertEqual(trace.steps[0].name, 'HTTP GET cdn.example.com/assets'); + resolve(); + }); + }); +}); + +test('http-tracer: _wrapFetch with Request-like object input', async () => { + const origFn = async () => ({ status: 200 }); + const trace = { requestId: 'rf4', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + await httpTracer._wrapFetch(origFn, [{ url: 'https://api.com/v2/data', method: 'PATCH' }]); + assert(trace.steps[0].name.includes('PATCH')); + assert(trace.steps[0].name.includes('api.com')); + resolve(); + }); + }); +}); + +test('http-tracer: _wrapFetch with Request-like object with invalid url', async () => { + const origFn = async () => ({ status: 200 }); + const trace = { requestId: 'rf5', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + await httpTracer._wrapFetch(origFn, [{ url: 'not-a-url', method: 'GET' }]); + assertEqual(trace.steps.length, 1); + resolve(); + }); + }); +}); + +test('http-tracer: _wrapFetch with Request-like object without method falls back', async () => { + const origFn = async () => ({ status: 200 }); + const trace = { requestId: 'rf_nomethod', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + await httpTracer._wrapFetch(origFn, [{ url: 'https://api.com/data' }]); + assert(trace.steps[0].name.includes('GET')); + resolve(); + }); + }); +}); + +test('http-tracer: _wrapFetch with no init defaults to GET', async () => { + const origFn = async () => ({ status: 200 }); + const trace = { requestId: 'rf6', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + await httpTracer._wrapFetch(origFn, ['http://example.com/']); + assert(trace.steps[0].name.includes('GET')); + resolve(); + }); + }); +}); + +test('http-tracer: patched http.request/get and https.request/get are invoked', () => { + const http = require('node:http'); + const https = require('node:https'); + httpTracer.enableHttpTracing(); + + // Call all four patched functions against a dead port to execute their bodies + const req1 = http.request({ hostname: '127.0.0.1', port: 1, path: '/' }); + req1.on('error', () => {}); + req1.destroy(); + + const req2 = http.get({ hostname: '127.0.0.1', port: 1, path: '/' }); + req2.on('error', () => {}); + req2.destroy(); + + const req3 = https.request({ hostname: '127.0.0.1', port: 1, path: '/' }); + req3.on('error', () => {}); + req3.destroy(); + + const req4 = https.get({ hostname: '127.0.0.1', port: 1, path: '/' }); + req4.on('error', () => {}); + req4.destroy(); + + httpTracer.disableHttpTracing(); +}); + +test('http-tracer: _wrapFetch with invalid string URL in trace context', async () => { + const origFn = async () => ({ status: 200 }); + const trace = { requestId: 'rf_inv', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + await httpTracer._wrapFetch(origFn, ['/relative/no-host']); + assertEqual(trace.steps.length, 1); + assert(trace.steps[0].name.includes('/relative/no-host')); + resolve(); + }); + }); +}); + +test('http-tracer: patched fetch is callable when globalThis.fetch exists', () => { + // Save original + const origFetch = globalThis.fetch; + // Set a dummy fetch + globalThis.fetch = async function dummyFetch() { return { status: 200 }; }; + + httpTracer.enableHttpTracing(); + assert(globalThis.fetch.name === 'tracedFetch'); + httpTracer.disableHttpTracing(); + + // Restore + if (origFetch) { + globalThis.fetch = origFetch; + } else { + delete globalThis.fetch; + } +}); + +test('http-tracer: patched fetch calls _wrapFetch with trace', async () => { + const origFetch = globalThis.fetch; + let fetchCalled = false; + globalThis.fetch = async function dummyFetch() { fetchCalled = true; return { status: 200 }; }; + + httpTracer.enableHttpTracing(); + const trace = { requestId: 'fetch_patched', steps: [] }; + + await new Promise((resolve) => { + rwtForHttp(trace, async () => { + const result = await globalThis.fetch('http://example.com/test'); + assert(fetchCalled); + assertEqual(trace.steps.length, 1); + resolve(); + }); + }); + + httpTracer.disableHttpTracing(); + if (origFetch) { + globalThis.fetch = origFetch; + } else { + delete globalThis.fetch; + } +}); + +// ========================================================================= +// lib/routes.js — chrome trace endpoint +// ========================================================================= +test('routes: /trace/:requestId/chrome returns chrome trace format', () => { + const t = makeTracer(); + const router = createRouter(t); + const trace = { requestId: 'req_chrome1', method: 'GET', path: '/test', startTime: 1000, duration: 50, status: 200, steps: [] }; + t.storage.store(trace); + + let body = ''; + let headers = {}; + const res = { + writeHead(code, h) { headers = h; }, + end(data) { body = data; }, + }; + router({ url: '/trace/req_chrome1/chrome' }, res); + const parsed = JSON.parse(body); + assert(parsed.traceEvents != null); + assertEqual(parsed.traceEvents[0].cat, 'request'); + t.destroy(); +}); + +test('routes: /trace/:requestId/chrome returns 404 when not found', () => { + const t = makeTracer(); + const router = createRouter(t); + + let statusCode = 0; + let body = ''; + const res = { + writeHead(code) { statusCode = code; }, + end(data) { body = data; }, + }; + router({ url: '/trace/req_missing/chrome' }, res); + assertEqual(statusCode, 404); + assert(body.includes('not found')); + t.destroy(); +}); + +// ========================================================================= +// lib/middleware/fastify.js — autoTrack lifecycle +// ========================================================================= +test('fastify-mw: autoTrack registers lifecycle hooks', () => { + const t = makeTracer({ autoTrack: true }); + const pluginFn = fastifyPluginFn(t); + const hooks = {}; + const fakeFastify = { + addHook(name, fn) { + if (!hooks[name]) hooks[name] = []; + hooks[name].push(fn); + }, + }; + let doneCalled = false; + pluginFn(fakeFastify, {}, () => { doneCalled = true; }); + assert(doneCalled); + assert(hooks.onRequest != null); + assert(hooks.preParsing != null); + assert(hooks.preValidation != null); + assert(hooks.preHandler != null); + assert(hooks.onSend != null); + assert(hooks.onResponse != null); + t.destroy(); +}); + +test('fastify-mw: autoTrack lifecycle records phase timings', () => { + const t = makeTracer({ autoTrack: true }); + const pluginFn = fastifyPluginFn(t); + const hooks = {}; + const fakeFastify = { + addHook(name, fn) { + if (!hooks[name]) hooks[name] = []; + hooks[name].push(fn); + }, + }; + pluginFn(fakeFastify, {}, () => {}); + + const fakeRequest = { method: 'GET', url: '/lifecycle', headers: {} }; + const fakeReply = { header() {}, statusCode: 200 }; + + // onRequest + hooks.onRequest[0](fakeRequest, fakeReply, () => {}); + assert(fakeRequest._trace != null); + assert(fakeRequest._tracePhaseStart != null); + + // preParsing + hooks.preParsing[0](fakeRequest, fakeReply, 'payload', (err, payload) => {}); + // preValidation + hooks.preValidation[0](fakeRequest, fakeReply, () => {}); + // preHandler + hooks.preHandler[0](fakeRequest, fakeReply, () => {}); + // onSend + hooks.onSend[0](fakeRequest, fakeReply, 'body', (err, payload) => {}); + // onResponse + hooks.onResponse[0](fakeRequest, fakeReply, () => {}); + + // In synchronous tests, duration between calls is 0ms so _recordPhase skips + // Verify the mechanism worked: trace was finalized and _tracePhaseStart updated + assert(fakeRequest._trace.duration >= 0); + assert(fakeRequest._tracePhaseStart != null); + t.destroy(); +}); + +test('fastify-mw: _recordPhase skips when no trace', () => { + const t = makeTracer({ autoTrack: true }); + const pluginFn = fastifyPluginFn(t); + const hooks = {}; + const fakeFastify = { + addHook(name, fn) { + if (!hooks[name]) hooks[name] = []; + hooks[name].push(fn); + }, + }; + pluginFn(fakeFastify, {}, () => {}); + + // Request with no trace (not sampled) + const fakeRequest = { method: 'GET', url: '/skip', headers: {} }; + const fakeReply = { header() {}, statusCode: 200 }; + + // Skip onRequest (no trace created) + // Directly call preParsing with a request that has no _trace + hooks.preParsing[0](fakeRequest, fakeReply, 'p', (e, p) => {}); + // Should not throw + t.destroy(); +}); + +test('fastify-mw: _recordPhase skips when no _tracePhaseStart', () => { + const t = makeTracer({ autoTrack: true }); + const pluginFn = fastifyPluginFn(t); + const hooks = {}; + const fakeFastify = { + addHook(name, fn) { + if (!hooks[name]) hooks[name] = []; + hooks[name].push(fn); + }, + }; + pluginFn(fakeFastify, {}, () => {}); + + const fakeRequest = { _trace: { steps: [] }, method: 'GET', url: '/no-start', headers: {} }; + const fakeReply = { header() {}, statusCode: 200 }; + hooks.preParsing[0](fakeRequest, fakeReply, 'p', (e, p) => {}); + assertEqual(fakeRequest._trace.steps.length, 0); + t.destroy(); +}); + +test('fastify-mw: _recordPhase records step when duration > 0', () => { + const t = makeTracer({ autoTrack: true }); + const pluginFn = fastifyPluginFn(t); + const hooks = {}; + const fakeFastify = { + addHook(name, fn) { + if (!hooks[name]) hooks[name] = []; + hooks[name].push(fn); + }, + }; + pluginFn(fakeFastify, {}, () => {}); + + const trace = { steps: [], requestId: 'phase_dur', startTime: Date.now(), duration: 0, status: 0 }; + const fakeRequest = { + _trace: trace, + _tracePhaseStart: Date.now() - 50, + method: 'GET', url: '/dur', headers: {}, + }; + const fakeReply = { header() {}, statusCode: 200 }; + // Call preParsing which triggers _recordPhase('onRequest') + hooks.preParsing[0](fakeRequest, fakeReply, 'p', (e, p) => {}); + assertEqual(trace.steps.length, 1); + assertEqual(trace.steps[0].name, 'onRequest'); + assertEqual(trace.steps[0].type, 'lifecycle'); + assert(trace.steps[0].duration > 0); + t.destroy(); +}); + +test('fastify-mw: autoTrack onResponse records onSend phase', () => { + const t = makeTracer({ autoTrack: true }); + const pluginFn = fastifyPluginFn(t); + const hooks = {}; + const fakeFastify = { + addHook(name, fn) { + if (!hooks[name]) hooks[name] = []; + hooks[name].push(fn); + }, + }; + pluginFn(fakeFastify, {}, () => {}); + + const fakeRequest = { method: 'GET', url: '/onsend', headers: {} }; + const fakeReply = { header() {}, statusCode: 200 }; + + hooks.onRequest[0](fakeRequest, fakeReply, () => {}); + hooks.onResponse[0](fakeRequest, fakeReply, () => {}); + + // Should have recorded at least the onSend phase in onResponse + assert(fakeRequest._trace.duration >= 0); + t.destroy(); +}); + +// ========================================================================= +// lib/middleware/koa.js — instrumentKoa +// ========================================================================= +const { instrumentKoa } = require('../lib/middleware/koa'); + +test('koa: instrumentKoa patches app.use', () => { + const t = makeTracer({ autoTrack: true }); + let usedFn = null; + const fakeApp = { + use(fn) { usedFn = fn; return this; }, + }; + const result = instrumentKoa(fakeApp, t); + assertEqual(result, fakeApp); + assert(fakeApp._traceInstrumented); + + // Use a named middleware + async function authMiddleware(ctx, next) { await next(); } + fakeApp.use(authMiddleware); + // usedFn should be a wrapper, not the original + assert(usedFn !== authMiddleware); + assert(typeof usedFn === 'function'); + t.destroy(); +}); + +test('koa: instrumentKoa is idempotent', () => { + const t = makeTracer({ autoTrack: true }); + const fakeApp = { + use(fn) { return this; }, + _traceInstrumented: true, + }; + const result = instrumentKoa(fakeApp, t); + assertEqual(result, fakeApp); + t.destroy(); +}); + +test('koa: instrumentKoa with null app returns it', () => { + const t = makeTracer(); + const result = instrumentKoa(null, t); + assertEqual(result, null); + t.destroy(); +}); + +test('koa: instrumentKoa with app missing use returns it', () => { + const t = makeTracer(); + const app = {}; + const result = instrumentKoa(app, t); + assertEqual(result, app); + t.destroy(); +}); + +test('koa: instrumentKoa wrapped middleware records step with trace', async () => { + const t = makeTracer({ autoTrack: true }); + let wrappedFn = null; + const fakeApp = { + use(fn) { wrappedFn = fn; return this; }, + }; + instrumentKoa(fakeApp, t); + + async function myHandler(ctx, next) { await next(); } + fakeApp.use(myHandler); + + const trace = { requestId: 'koa_auto', steps: [] }; + const ctx = { _trace: trace }; + await wrappedFn(ctx, async () => {}); + assertEqual(trace.steps.length, 1); + assertEqual(trace.steps[0].name, 'myHandler'); + assertEqual(trace.steps[0].type, 'middleware'); + t.destroy(); +}); + +test('koa: instrumentKoa wrapped middleware works without trace', async () => { + const t = makeTracer({ autoTrack: true }); + let wrappedFn = null; + const fakeApp = { + use(fn) { wrappedFn = fn; return this; }, + }; + instrumentKoa(fakeApp, t); + + async function handler(ctx, next) { await next(); } + fakeApp.use(handler); + + const ctx = {}; + await wrappedFn(ctx, async () => {}); + // Should not throw + t.destroy(); +}); + +test('koa: instrumentKoa uses index fallback for unnamed middleware', async () => { + const t = makeTracer({ autoTrack: true }); + let wrappedFn = null; + const fakeApp = { + use(fn) { wrappedFn = fn; return this; }, + }; + instrumentKoa(fakeApp, t); + + const fn = async (ctx, next) => { await next(); }; + Object.defineProperty(fn, 'name', { value: '' }); + fakeApp.use(fn); + + const trace = { requestId: 'koa_idx', steps: [] }; + await wrappedFn({ _trace: trace }, async () => {}); + assert(trace.steps[0].name.startsWith('middleware_')); + t.destroy(); +}); + +test('koa: instrumentKoa with autoTrack false passes through', () => { + const t = makeTracer({ autoTrack: false }); + let directFn = null; + const fakeApp = { + use(fn) { directFn = fn; return this; }, + }; + instrumentKoa(fakeApp, t); + + async function myMw(ctx, next) { await next(); } + fakeApp.use(myMw); + // Should pass the original function through (not wrapped) + assertEqual(directFn, myMw); + t.destroy(); +}); + +test('koa: instrumentKoa records step even when middleware throws', async () => { + const t = makeTracer({ autoTrack: true }); + let wrappedFn = null; + const fakeApp = { + use(fn) { wrappedFn = fn; return this; }, + }; + instrumentKoa(fakeApp, t); + + async function badMw(ctx, next) { throw new Error('boom'); } + fakeApp.use(badMw); + + const trace = { requestId: 'koa_err', steps: [] }; + try { + await wrappedFn({ _trace: trace }, async () => {}); + } catch (e) { + assertEqual(e.message, 'boom'); + } + assertEqual(trace.steps.length, 1); + assertEqual(trace.steps[0].name, 'badMw'); + t.destroy(); +}); + +// ========================================================================= +// index.js — new API methods +// ========================================================================= +test('api: instrumentKoa returns instrumented app', () => { + const t = new RT(); + t.init({ autoTrack: true }); + const fakeApp = { use(fn) { return this; } }; + const result = t.instrumentKoa(fakeApp); + assert(result._traceInstrumented); + t.destroy(); +}); + +test('api: enableHttpTracing / disableHttpTracing / isHttpTracingEnabled', () => { + const t = new RT(); + t.init(); + assert(!t.isHttpTracingEnabled()); + t.enableHttpTracing(); + assert(t.isHttpTracingEnabled()); + t.disableHttpTracing(); + assert(!t.isHttpTracingEnabled()); + t.destroy(); +}); + +test('api: init with traceOutgoing enables http tracing', () => { + const t = new RT(); + t.init({ traceOutgoing: true }); + assert(httpTracer.isEnabled()); + t.destroy(); + assert(!httpTracer.isEnabled()); +}); + +test('api: exportChromeTrace returns chrome format', () => { + const t = new RT(); + const trace = { requestId: 'r', method: 'GET', path: '/', startTime: 1, duration: 1, status: 200, steps: [] }; + const result = t.exportChromeTrace(trace); + assert(result.traceEvents != null); +}); + +test('api: exportChromeTraceJson returns JSON string', () => { + const t = new RT(); + const trace = { requestId: 'r', method: 'GET', path: '/', startTime: 1, duration: 1, status: 200, steps: [] }; + const result = t.exportChromeTraceJson(trace); + assert(typeof result === 'string'); + JSON.parse(result); // should not throw +}); + +test('api: destroy disables http tracing', () => { + const t = new RT(); + t.init({ traceOutgoing: true }); + assert(httpTracer.isEnabled()); + t.destroy(); + assert(!httpTracer.isEnabled()); +}); + // Run all tests run();