From 96db9b6c7ff206e2702ea1166d08d35c527bf1ae Mon Sep 17 00:00:00 2001 From: agent_coder Date: Tue, 7 Jul 2026 02:10:54 +0300 Subject: [PATCH 1/3] =?UTF-8?q?feat(metrics):=20#402=20pass=201=20?= =?UTF-8?q?=E2=80=94=20collab-cycle=20observability=20(load/lifecycle/conn?= =?UTF-8?q?ect/auth)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Extends the #355 perf-metrics registry (all behind the METRICS_PORT hard gate — nullable instruments, no-op helpers when unset). New families: - collab_doc_load_duration_seconds{size_bucket} — onLoadDocument timed on the real DB-load paths only (the already-loaded early-return is skipped). - size_bucket added to collab_store_duration_seconds; storeDocument returns the ydoc byte length (reusing its single Y.encodeStateAsUpdate, no second encode) so onStoreDocument observes size without extra cost. - collab_docs_open (gauge, read-on-scrape via collect() from hocuspocus.getDocumentsCount() — never inc/dec'd, so it can't drift) + collab_doc_loads_total / collab_doc_unloads_total (afterLoad/afterUnload). - collab_connect_duration_seconds — onConnect->connected, correlated by a WeakMap keyed on the shared request (leak-free; the current client uses one socket per document). - collab_auth_duration_seconds — wraps onAuthenticate (success and failure). - sizeBucket() shared helper (lt64k|lt256k|lt1m|ge1m, 4 bounded values). The mcp_tool_duration_seconds histogram + collab_connect_timeouts_total counter helpers are registered here but wired in pass 2 (MCP callback). Co-Authored-By: Claude Opus 4.8 (1M context) --- .../collaboration/collaboration.gateway.ts | 66 ++++++++- .../extensions/authentication.extension.ts | 13 ++ .../extensions/persistence.extension.ts | 41 +++++- .../integrations/metrics/metrics.constants.ts | 46 ++++++ .../integrations/metrics/metrics.registry.ts | 137 +++++++++++++++++- .../src/integrations/metrics/metrics.spec.ts | 83 ++++++++++- 6 files changed, 374 insertions(+), 12 deletions(-) diff --git a/apps/server/src/collaboration/collaboration.gateway.ts b/apps/server/src/collaboration/collaboration.gateway.ts index ced36083..75d05c22 100644 --- a/apps/server/src/collaboration/collaboration.gateway.ts +++ b/apps/server/src/collaboration/collaboration.gateway.ts @@ -1,4 +1,9 @@ -import { Hocuspocus } from '@hocuspocus/server'; +import { + connectedPayload, + Extension, + Hocuspocus, + onConnectPayload, +} from '@hocuspocus/server'; import { IncomingMessage } from 'http'; import WebSocket from 'ws'; import { AuthenticationExtension } from './extensions/authentication.extension'; @@ -25,6 +30,56 @@ import { CollaborationHandler, CollabEventHandlers, } from './collaboration.handler'; +import { + incDocLoad, + incDocUnload, + isMetricsEnabled, + observeCollabConnect, + registerDocsOpenSource, +} from '../integrations/metrics/metrics.registry'; + +/** + * #402 — collab lifecycle metrics as a lightweight hocuspocus extension. + * + * - afterLoadDocument / afterUnloadDocument (fire once PER DOCUMENT) drive the + * doc load/unload counters. + * - collab_connect_duration_seconds: I time the onConnect→connected hook pair, + * i.e. connection ACCEPTANCE (which includes the auth handshake). This is the + * cleanest per-connection correlation hocuspocus exposes: both payloads carry + * the SAME `request` IncomingMessage object, so a WeakMap keyed on it gives a + * per-connection start with NO leak (the entry is GC'd with the request if a + * connection is rejected in onAuthenticate and `connected` never fires). + * I deliberately do NOT observe at afterLoadDocument: that hook fires per + * DOCUMENT, not per connection, so a second client joining an already-open + * doc would be missed. auth/load latencies are their own separate metrics. + * + * All helpers are no-ops when METRICS_PORT is unset; these hooks are per + * connect/load/unload (never per message), so there is no hot-path cost. + */ +class CollabMetricsExtension implements Extension { + // Keyed by the per-connection request object → connect start time (ms). + private readonly connectStarts = new WeakMap(); + + async onConnect(data: onConnectPayload) { + this.connectStarts.set(data.request, performance.now()); + } + + async connected(data: connectedPayload) { + const start = this.connectStarts.get(data.request); + if (start !== undefined) { + observeCollabConnect((performance.now() - start) / 1000); + this.connectStarts.delete(data.request); + } + } + + async afterLoadDocument() { + incDocLoad(); + } + + async afterUnloadDocument() { + incDocUnload(); + } +} @Injectable() export class CollaborationGateway { @@ -58,9 +113,18 @@ export class CollaborationGateway { this.authenticationExtension, this.persistenceExtension, this.loggerExtension, + // #402 collab lifecycle + connect-duration metrics (no-op when off). + new CollabMetricsExtension(), ], }); + // #402 — read-on-scrape source for collab_docs_open. Wire ONCE, gated, so + // nothing runs when metrics are disabled. The gauge's collect() pulls the + // live count from the hocuspocus instance on each scrape (no inc/dec drift). + if (isMetricsEnabled()) { + registerDocsOpenSource(() => this.hocuspocus.getDocumentsCount()); + } + if (this.withRedis) { this.redisClient = new RedisClient({ host: this.redisConfig.host, diff --git a/apps/server/src/collaboration/extensions/authentication.extension.ts b/apps/server/src/collaboration/extensions/authentication.extension.ts index addce7af..79b4246c 100644 --- a/apps/server/src/collaboration/extensions/authentication.extension.ts +++ b/apps/server/src/collaboration/extensions/authentication.extension.ts @@ -16,6 +16,7 @@ import { isUserDisabled } from '../../common/helpers'; import { getPageId } from '../collaboration.util'; import { JwtCollabPayload, JwtType } from '../../core/auth/dto/jwt-payload'; import { resolveProvenance } from '../../common/decorators/auth-provenance.decorator'; +import { observeCollabAuth } from '../../integrations/metrics/metrics.registry'; @Injectable() export class AuthenticationExtension implements Extension { @@ -30,6 +31,18 @@ export class AuthenticationExtension implements Extension { ) {} async onAuthenticate(data: onAuthenticatePayload) { + // #402 — time the whole auth (verify + user/page/permission lookups) into + // collab_auth_duration_seconds. finally so failed auths are timed too. + // No-op when METRICS_PORT is unset. Behavior unchanged. + const start = performance.now(); + try { + return await this.doAuthenticate(data); + } finally { + observeCollabAuth((performance.now() - start) / 1000); + } + } + + private async doAuthenticate(data: onAuthenticatePayload) { const { documentName, token } = data; const pageId = getPageId(documentName); diff --git a/apps/server/src/collaboration/extensions/persistence.extension.ts b/apps/server/src/collaboration/extensions/persistence.extension.ts index 35310cf4..10afc82e 100644 --- a/apps/server/src/collaboration/extensions/persistence.extension.ts +++ b/apps/server/src/collaboration/extensions/persistence.extension.ts @@ -41,7 +41,10 @@ import { HISTORY_INTERVAL, } from '../constants'; import { TransclusionService } from '../../core/page/transclusion/transclusion.service'; -import { observeCollabStore } from '../../integrations/metrics/metrics.registry'; +import { + observeCollabLoad, + observeCollabStore, +} from '../../integrations/metrics/metrics.registry'; /** * #251 — wire format of the client→server stateless message that signals a @@ -150,10 +153,14 @@ export class PersistenceExtension implements Extension { const { documentName, document } = data; const pageId = getPageId(documentName); + // #402 — the early return below (live doc already non-empty) does NOT touch + // the DB, so it is deliberately NOT timed. We only observe the real DB-load + // work, and only on each real-load return, tagged by the loaded doc size. if (!document.isEmpty('default')) { return; } + const startedAt = performance.now(); const page = await this.pageRepo.findById(pageId, { includeContent: true, includeYdoc: true, @@ -171,6 +178,7 @@ export class PersistenceExtension implements Extension { const dbState = new Uint8Array(page.ydoc); Y.applyUpdate(doc, dbState); + observeCollabLoad(dbState.length, (performance.now() - startedAt) / 1000); return doc; } @@ -184,26 +192,42 @@ export class PersistenceExtension implements Extension { tiptapExtensions, ); - Y.encodeStateAsUpdate(ydoc); + // Reuse this single encode for the size label (do NOT add a second one). + const encoded = Y.encodeStateAsUpdate(ydoc); + observeCollabLoad( + encoded.byteLength, + (performance.now() - startedAt) / 1000, + ); return ydoc; } this.logger.debug(`creating fresh ydoc: ${pageId}`); + observeCollabLoad(0, (performance.now() - startedAt) / 1000); return new Y.Doc(); } async onStoreDocument(data: onStoreDocumentPayload) { // #355 — time the full store (persist + post-store side effects) into - // collab_store_duration_seconds. No-op when METRICS_PORT is unset. + // collab_store_duration_seconds. #402 — also tag by document size bucket. + // No-op when METRICS_PORT is unset. const startedAt = performance.now(); + // Default 0 so a throw before storeDocument returns still records a + // (smallest-bucket) observation rather than dropping the timing entirely. + let bytes = 0; try { - await this.storeDocument(data); + bytes = await this.storeDocument(data); } finally { - observeCollabStore((performance.now() - startedAt) / 1000); + observeCollabStore(bytes, (performance.now() - startedAt) / 1000); } } - private async storeDocument(data: onStoreDocumentPayload) { + /** + * Persist the document. Returns the serialized ydoc byte size (used as the + * store histogram's size_bucket). The single Y.encodeStateAsUpdate below is + * the ONLY serialization — its byteLength is reused for the label (no second + * encode). + */ + private async storeDocument(data: onStoreDocumentPayload): Promise { const { documentName, document, context } = data; const pageId = getPageId(documentName); @@ -455,6 +479,11 @@ export class PersistenceExtension implements Extension { await this.enqueuePageHistory(page, lastUpdatedSource); } + + // #402 — report the serialized size for the store histogram's size_bucket. + // ydocState is always computed above (there is no earlier no-write return in + // this method), so this reflects the doc that was serialized this store. + return ydocState.byteLength; } /** diff --git a/apps/server/src/integrations/metrics/metrics.constants.ts b/apps/server/src/integrations/metrics/metrics.constants.ts index b802e2f0..f829d58a 100644 --- a/apps/server/src/integrations/metrics/metrics.constants.ts +++ b/apps/server/src/integrations/metrics/metrics.constants.ts @@ -2,6 +2,11 @@ * Perf-metrics contract (#355). These names/labels are FIXED by the already * deployed scrape+dashboard infra (VictoriaMetrics scraping docmost:9464, * Grafana dashboards, alerts). Do NOT rename them. + * + * #402 extends the #355 table with the collab-lifecycle + MCP-tool families + * (grouped below). These are the fixed contract from #402; same "do not rename" + * rule applies. Server-side families land in Pass 1; the MCP-tool histogram is + * fed by the MCP callback in a later pass but its NAME is fixed here now. */ export const METRIC_HTTP_REQUEST_DURATION = 'http_request_duration_seconds'; export const METRIC_DB_QUERY_DURATION = 'db_query_duration_seconds'; @@ -9,6 +14,17 @@ export const METRIC_BULLMQ_QUEUE_DEPTH = 'bullmq_queue_depth'; export const METRIC_BULLMQ_JOB_DURATION = 'bullmq_job_duration_seconds'; export const METRIC_COLLAB_STORE_DURATION = 'collab_store_duration_seconds'; +// #402 additions — collaboration lifecycle + MCP tool timing. +export const METRIC_COLLAB_LOAD_DURATION = 'collab_doc_load_duration_seconds'; +export const METRIC_COLLAB_DOCS_OPEN = 'collab_docs_open'; +export const METRIC_COLLAB_DOC_LOADS_TOTAL = 'collab_doc_loads_total'; +export const METRIC_COLLAB_DOC_UNLOADS_TOTAL = 'collab_doc_unloads_total'; +export const METRIC_COLLAB_CONNECT_DURATION = 'collab_connect_duration_seconds'; +export const METRIC_COLLAB_CONNECT_TIMEOUTS_TOTAL = + 'collab_connect_timeouts_total'; +export const METRIC_COLLAB_AUTH_DURATION = 'collab_auth_duration_seconds'; +export const METRIC_MCP_TOOL_DURATION = 'mcp_tool_duration_seconds'; + // Histogram buckets (seconds). Chosen to give useful p50/p95/p99 resolution // for typical web/DB latencies without exploding series cardinality. export const HTTP_BUCKETS = [ @@ -23,6 +39,12 @@ export const COLLAB_BUCKETS = [ export const JOB_BUCKETS = [ 0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 120, ]; +// #402 — MCP tool-call latency. Same shape as COLLAB_BUCKETS but stretched to +// 10s at the top: an MCP tool round-trip (LLM-driven doc ops) can be slower +// than a single collab store, so keep resolution out to 10s. +export const MCP_TOOL_BUCKETS = [ + 0.005, 0.025, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, +]; /** * Extract the first SQL token (select/insert/update/delete/...) from a query, @@ -58,6 +80,30 @@ export function firstSqlToken(sql: string | undefined): string { return KNOWN_SQL_TOKENS.has(token) ? token : 'other'; } +/** + * #402 — bucket a document byte size into ONE of four fixed labels for the + * collab load/store histograms' `size_bucket` label. Using the raw byte count + * would be a continuous, unbounded label; four coarse buckets keep series + * cardinality bounded (each of collab_doc_load / collab_store gets ×4 series). + * + * The SAME function is shared by both the load and store paths so their buckets + * can never drift apart. Non-finite / negative sizes collapse to the smallest + * bucket ('lt64k') as a safe default (they can't be legitimately huge and we + * must never throw here — this runs on every store/load when metrics are on). + */ +// Module-const thresholds, built once (not per observe). +const SIZE_THRESHOLDS = { lt64k: 65536, lt256k: 262144, lt1m: 1048576 } as const; + +export function sizeBucket( + bytes: number | undefined | null, +): 'lt64k' | 'lt256k' | 'lt1m' | 'ge1m' { + if (bytes == null || !Number.isFinite(bytes) || bytes < 0) return 'lt64k'; + if (bytes < SIZE_THRESHOLDS.lt64k) return 'lt64k'; + if (bytes < SIZE_THRESHOLDS.lt256k) return 'lt256k'; + if (bytes < SIZE_THRESHOLDS.lt1m) return 'lt1m'; + return 'ge1m'; +} + /** * Whether an HTTP response must be EXCLUDED from http_request_duration_seconds. * diff --git a/apps/server/src/integrations/metrics/metrics.registry.ts b/apps/server/src/integrations/metrics/metrics.registry.ts index d62be165..37991254 100644 --- a/apps/server/src/integrations/metrics/metrics.registry.ts +++ b/apps/server/src/integrations/metrics/metrics.registry.ts @@ -1,5 +1,6 @@ import { collectDefaultMetrics, + Counter, Histogram, Gauge, Registry, @@ -9,11 +10,21 @@ import { DB_BUCKETS, HTTP_BUCKETS, JOB_BUCKETS, + MCP_TOOL_BUCKETS, METRIC_BULLMQ_JOB_DURATION, METRIC_BULLMQ_QUEUE_DEPTH, + METRIC_COLLAB_AUTH_DURATION, + METRIC_COLLAB_CONNECT_DURATION, + METRIC_COLLAB_CONNECT_TIMEOUTS_TOTAL, + METRIC_COLLAB_DOC_LOADS_TOTAL, + METRIC_COLLAB_DOC_UNLOADS_TOTAL, + METRIC_COLLAB_DOCS_OPEN, + METRIC_COLLAB_LOAD_DURATION, METRIC_COLLAB_STORE_DURATION, METRIC_DB_QUERY_DURATION, METRIC_HTTP_REQUEST_DURATION, + METRIC_MCP_TOOL_DURATION, + sizeBucket, } from './metrics.constants'; /** @@ -39,7 +50,24 @@ let httpHist: Histogram<'method' | 'route' | 'status'> | null = null; let dbHist: Histogram<'op'> | null = null; let queueDepthGauge: Gauge<'queue'> | null = null; let jobHist: Histogram<'queue'> | null = null; -let collabHist: Histogram | null = null; +// #402 — collab store now carries a size_bucket label (see sizeBucket()). +let collabHist: Histogram<'size_bucket'> | null = null; +// #402 collab-lifecycle + MCP instruments. +let collabLoadHist: Histogram<'size_bucket'> | null = null; +let docsOpenGauge: Gauge | null = null; +let docLoadsCounter: Counter | null = null; +let docUnloadsCounter: Counter | null = null; +let connectTimeoutsCounter: Counter | null = null; +let collabConnectHist: Histogram | null = null; +let collabAuthHist: Histogram | null = null; +let mcpToolHist: Histogram<'tool'> | null = null; + +// #402 — read-on-scrape source for collab_docs_open. The gauge is NEVER +// inc/dec'd (that drifts under crashes/handoffs); instead its collect() callback +// pulls the authoritative live count from here on every scrape. Registered once, +// gated, by the collaboration gateway via registerDocsOpenSource(). Null until +// then → the collect() is a no-op. +let docsOpenSource: (() => number) | null = null; function init(): void { if (registry || !enabled) return; @@ -82,10 +110,71 @@ function init(): void { collabHist = new Histogram({ name: METRIC_COLLAB_STORE_DURATION, - help: 'Collaboration onStoreDocument duration in seconds', + help: 'Collaboration onStoreDocument duration in seconds, by document size bucket', + labelNames: ['size_bucket'], buckets: COLLAB_BUCKETS, registers: [registry], }); + + collabLoadHist = new Histogram({ + name: METRIC_COLLAB_LOAD_DURATION, + help: 'Collaboration onLoadDocument DB-load duration in seconds, by document size bucket', + labelNames: ['size_bucket'], + buckets: COLLAB_BUCKETS, + registers: [registry], + }); + + docsOpenGauge = new Gauge({ + name: METRIC_COLLAB_DOCS_OPEN, + help: 'Number of collaboration documents currently open in memory', + registers: [registry], + // Read-on-scrape: pull the live count from the registered source (the + // hocuspocus instance) so the value can never drift. No-op until a source + // is registered. + collect() { + if (docsOpenSource) this.set(docsOpenSource()); + }, + }); + + docLoadsCounter = new Counter({ + name: METRIC_COLLAB_DOC_LOADS_TOTAL, + help: 'Total collaboration documents loaded into memory', + registers: [registry], + }); + + docUnloadsCounter = new Counter({ + name: METRIC_COLLAB_DOC_UNLOADS_TOTAL, + help: 'Total collaboration documents unloaded from memory', + registers: [registry], + }); + + connectTimeoutsCounter = new Counter({ + name: METRIC_COLLAB_CONNECT_TIMEOUTS_TOTAL, + help: 'Total collaboration connection setup timeouts', + registers: [registry], + }); + + collabConnectHist = new Histogram({ + name: METRIC_COLLAB_CONNECT_DURATION, + help: 'Collaboration connection acceptance duration in seconds (onConnect→connected)', + buckets: COLLAB_BUCKETS, + registers: [registry], + }); + + collabAuthHist = new Histogram({ + name: METRIC_COLLAB_AUTH_DURATION, + help: 'Collaboration onAuthenticate duration in seconds', + buckets: COLLAB_BUCKETS, + registers: [registry], + }); + + mcpToolHist = new Histogram({ + name: METRIC_MCP_TOOL_DURATION, + help: 'MCP tool-call duration in seconds, by tool name', + labelNames: ['tool'], + buckets: MCP_TOOL_BUCKETS, + registers: [registry], + }); } // Runs once when this module is first imported. Safe to call again (idempotent). @@ -121,6 +210,46 @@ export function observeJobDuration(queue: string, seconds: number): void { jobHist?.observe({ queue }, seconds); } -export function observeCollabStore(seconds: number): void { - collabHist?.observe(seconds); +export function observeCollabStore(bytes: number, seconds: number): void { + collabHist?.observe({ size_bucket: sizeBucket(bytes) }, seconds); +} + +export function observeCollabLoad(bytes: number, seconds: number): void { + collabLoadHist?.observe({ size_bucket: sizeBucket(bytes) }, seconds); +} + +/** + * Register the live open-document count source for the collab_docs_open gauge. + * Called ONCE, gated by isMetricsEnabled(), by the collaboration gateway. The + * gauge reads this on every scrape (collect()); nothing inc/dec's it. + */ +export function registerDocsOpenSource(fn: () => number): void { + docsOpenSource = fn; +} + +export function incDocLoad(): void { + docLoadsCounter?.inc(); +} + +export function incDocUnload(): void { + docUnloadsCounter?.inc(); +} + +export function incConnectTimeout(): void { + connectTimeoutsCounter?.inc(); +} + +export function observeCollabConnect(seconds: number): void { + collabConnectHist?.observe(seconds); +} + +export function observeCollabAuth(seconds: number): void { + collabAuthHist?.observe(seconds); +} + +export function observeMcpTool(tool: string, seconds: number): void { + // `tool` MUST be a bounded, registration-derived MCP tool name (the caller + // guarantees it comes from the registered-tool set) — never free-form input — + // so this label stays low-cardinality with no 'other' bucketing needed. + mcpToolHist?.observe({ tool }, seconds); } diff --git a/apps/server/src/integrations/metrics/metrics.spec.ts b/apps/server/src/integrations/metrics/metrics.spec.ts index 311ad43d..cd88134d 100644 --- a/apps/server/src/integrations/metrics/metrics.spec.ts +++ b/apps/server/src/integrations/metrics/metrics.spec.ts @@ -1,6 +1,23 @@ import { FastifyRequest } from 'fastify'; import { resolveRouteLabel } from './http-metrics.hook'; -import { firstSqlToken, isStreamingResponse } from './metrics.constants'; +import { + firstSqlToken, + isStreamingResponse, + sizeBucket, +} from './metrics.constants'; +import { + getMetricsRegistry, + incConnectTimeout, + incDocLoad, + incDocUnload, + isMetricsEnabled, + observeCollabAuth, + observeCollabConnect, + observeCollabLoad, + observeCollabStore, + observeMcpTool, + registerDocsOpenSource, +} from './metrics.registry'; describe('resolveRouteLabel (histogram route label)', () => { it('uses the ROUTE TEMPLATE, never the raw URL', () => { @@ -123,3 +140,67 @@ describe('firstSqlToken (bounded db label)', () => { expect(firstSqlToken('vacuum analyze')).toBe('other'); }); }); + +describe('sizeBucket (#402 bounded size label)', () => { + it('maps sizes to the four fixed buckets at their boundaries', () => { + // Boundaries are exclusive-upper: <65536 → lt64k, etc. + expect(sizeBucket(0)).toBe('lt64k'); + expect(sizeBucket(65535)).toBe('lt64k'); + expect(sizeBucket(65536)).toBe('lt256k'); + expect(sizeBucket(262143)).toBe('lt256k'); + expect(sizeBucket(262144)).toBe('lt1m'); + expect(sizeBucket(1048575)).toBe('lt1m'); + expect(sizeBucket(1048576)).toBe('ge1m'); + expect(sizeBucket(5_000_000)).toBe('ge1m'); + }); + + it('falls back to the smallest bucket for invalid sizes', () => { + // Non-finite / negative / nullish collapse to the smallest, safe default. + expect(sizeBucket(-1)).toBe('lt64k'); + expect(sizeBucket(NaN)).toBe('lt64k'); + expect(sizeBucket(Infinity)).toBe('lt64k'); + expect(sizeBucket(undefined)).toBe('lt64k'); + expect(sizeBucket(null)).toBe('lt64k'); + }); + + it('only ever returns one of the four fixed labels (bounded cardinality)', () => { + const labels = new Set( + [0, 65536, 262144, 1048576, -5, NaN].map((b) => sizeBucket(b)), + ); + for (const l of labels) { + expect(['lt64k', 'lt256k', 'lt1m', 'ge1m']).toContain(l); + } + }); +}); + +describe('metrics helpers are safe no-ops when METRICS_PORT is unset', () => { + // These specs run without METRICS_PORT, so the registry is never created and + // every observe/inc/set helper must be a cheap `?.` no-op that never throws. + beforeAll(() => { + // Guard the contract this suite depends on: if a CI env set METRICS_PORT, + // the assertions below would be meaningless, so fail loudly instead. + expect(process.env.METRICS_PORT).toBeUndefined(); + }); + + it('reports metrics disabled and a null registry', () => { + expect(isMetricsEnabled()).toBe(false); + expect(getMetricsRegistry()).toBeNull(); + }); + + it('does not throw from any #402 collab/MCP helper', () => { + expect(() => { + observeCollabLoad(123456, 0.01); + observeCollabStore(123456, 0.02); + observeCollabConnect(0.03); + observeCollabAuth(0.04); + observeMcpTool('some-tool', 0.05); + incDocLoad(); + incDocUnload(); + incConnectTimeout(); + // Registering a source must not create the gauge or invoke the fn. + registerDocsOpenSource(() => { + throw new Error('docsOpenSource must NOT be called when disabled'); + }); + }).not.toThrow(); + }); +}); -- 2.52.0 From 7a9d719877cd34bd863059dde7793c0558c62d63 Mon Sep 17 00:00:00 2001 From: agent_coder Date: Tue, 7 Jul 2026 02:20:46 +0300 Subject: [PATCH 2/3] =?UTF-8?q?feat(metrics):=20#402=20pass=202=20?= =?UTF-8?q?=E2=80=94=20MCP=20tool=20+=20connect-timeout=20via=20dependency?= =?UTF-8?q?-neutral=20callback?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit packages/mcp stays free of prom-client/server: it only calls an optional DocmostMcpConfig.onMetric(name, value, labels?) sink the host provides. - client.ts: onMetric on the config; fires collab_connect_timeouts_total once, only inside the 25s connect-timeout callback (the connect-vs-unload signal). cleanup() clears the timer on every other finish path, so no double-count. - index.ts: createDocmostMcpServer monkeypatches server.registerTool (before registerShared + inline tools are registered) to wrap every handler with timeToolHandler — times in a finally on success AND throw, re-throws unchanged, emits mcp_tool_duration_seconds{tool=} (bounded cardinality). Single choke point catches all tools. - mcp.service.ts: the per-request config resolver injects onMetric ONLY when isMetricsEnabled(), routing mcp_tool_duration_seconds -> observeMcpTool and collab_connect_timeouts_total -> incConnectTimeout. Disabled / standalone (stdio, no onMetric) -> undefined -> zero-overhead no-op. New node:test unit (tool-timing.test.mjs) covers the wrapper's value/throw preservation and the standalone no-op. packages/mcp/build/ is gitignored, not committed (CI rebuilds it). Co-Authored-By: Claude Opus 4.8 (1M context) --- .../src/integrations/mcp/mcp-auth.helpers.ts | 9 +++ .../src/integrations/mcp/mcp.service.ts | 28 +++++++- packages/mcp/src/client.ts | 20 ++++++ packages/mcp/src/index.ts | 47 +++++++++++++ packages/mcp/test/unit/tool-timing.test.mjs | 67 +++++++++++++++++++ 5 files changed, 170 insertions(+), 1 deletion(-) create mode 100644 packages/mcp/test/unit/tool-timing.test.mjs diff --git a/apps/server/src/integrations/mcp/mcp-auth.helpers.ts b/apps/server/src/integrations/mcp/mcp-auth.helpers.ts index 80e34d4f..e1709666 100644 --- a/apps/server/src/integrations/mcp/mcp-auth.helpers.ts +++ b/apps/server/src/integrations/mcp/mcp-auth.helpers.ts @@ -149,6 +149,15 @@ export type DocmostMcpConfig = ( has?: (uri: string) => boolean; evict?: (uri: string) => void; }; + // Dependency-neutral metrics sink injected by McpService (mirror of the + // package's onMetric). The package emits generic (name, value, labels) + // samples; McpService maps them onto the prom-client registry. Undefined + // when metrics are disabled → the package no-ops. + onMetric?: ( + name: string, + value: number, + labels?: Record, + ) => void; }; export interface ResolvedMcpAuth { diff --git a/apps/server/src/integrations/mcp/mcp.service.ts b/apps/server/src/integrations/mcp/mcp.service.ts index d6942963..11ae9d64 100644 --- a/apps/server/src/integrations/mcp/mcp.service.ts +++ b/apps/server/src/integrations/mcp/mcp.service.ts @@ -30,6 +30,11 @@ import { ResolvedMcpAuth, } from './mcp-auth.helpers'; import { SandboxStore } from '../sandbox/sandbox.store'; +import { + isMetricsEnabled, + observeMcpTool, + incConnectTimeout, +} from '../metrics/metrics.registry'; // Minimal shape of the embedded MCP HTTP handler exported by @docmost/mcp/http. interface McpHttpHandler { @@ -331,7 +336,28 @@ export class McpService implements OnModuleDestroy { // can store blobs in the shared in-RAM store regardless of which // credential variant resolved. The sink (put/has/evict + uri↔id // mapping) is owned by SandboxStore.asSink(). - return { ...resolved.config, sandbox: this.sandboxStore.asSink() }; + // Route the package's dependency-neutral metric samples onto the + // prom-client registry. When metrics are disabled, onMetric is + // undefined → the package's tool-timer/timeout hooks no-op with + // zero overhead. labels?.tool is guarded defensively (the tool + // wrapper always sets it). + return { + ...resolved.config, + sandbox: this.sandboxStore.asSink(), + onMetric: isMetricsEnabled() + ? ( + name: string, + value: number, + labels?: Record, + ) => { + if (name === 'mcp_tool_duration_seconds') { + observeMcpTool(labels?.tool ?? 'other', value); + } else if (name === 'collab_connect_timeouts_total') { + incConnectTimeout(); + } + } + : undefined, + }; }, { identify: (req: IncomingMessage) => { diff --git a/packages/mcp/src/client.ts b/packages/mcp/src/client.ts index 1ddc3432..d370a2b6 100644 --- a/packages/mcp/src/client.ts +++ b/packages/mcp/src/client.ts @@ -137,6 +137,15 @@ export type DocmostMcpConfig = { apiUrl: string } & ( has?: (uri: string) => boolean; evict?: (uri: string) => void; }; + // Dependency-neutral metrics sink. When present, the client emits generic + // (name, value, labels) samples; the HOST maps those names onto its own + // metrics registry (the package never depends on prom-client or the server). + // Absent in standalone/stdio mode → the client is a complete no-op here. + onMetric?: ( + name: string, + value: number, + labels?: Record, + ) => void; }; // Canonical UUID shape (versions 1–8, matching the `uuid` package's `validate` @@ -173,6 +182,11 @@ export class DocmostClient { // op's image blobs if the final doc put throws. Null when the sink omits them. private sandboxHas: ((uri: string) => boolean) | null = null; private sandboxEvict: ((uri: string) => void) | null = null; + // Optional dependency-neutral metrics sink (see DocmostMcpConfig.onMetric). + // Null on the legacy positional form and whenever the host omits it → no-op. + private onMetricFn: + | ((name: string, value: number, labels?: Record) => void) + | null = null; // In-flight login dedup: when the token expires, the 401 interceptor, // ensureAuthenticated, getCollabTokenWithReauth and the two multipart retries // can all call login() at once. Memoizing a single promise collapses that @@ -222,6 +236,8 @@ export class DocmostClient { this.sandboxHas = config.sandbox.has ?? null; this.sandboxEvict = config.sandbox.evict ?? null; } + // Legacy positional form carries no onMetric → null (complete no-op). + this.onMetricFn = config.onMetric ?? null; this.client = axios.create({ baseURL: this.apiUrl, // Default request timeout so a hung connection cannot wedge a per-page @@ -447,6 +463,10 @@ export class DocmostClient { }; connectTimer = setTimeout(() => { + // Only the actual 25s collab connect timeout fires here — the agent's + // collab connection to the server never became ready. This is the + // connect-vs-unload signal; the other finish() paths must NOT emit it. + this.onMetricFn?.("collab_connect_timeouts_total", 1); finish(new Error("Connection timeout to collaboration server")); }, CONNECT_TIMEOUT_MS); diff --git a/packages/mcp/src/index.ts b/packages/mcp/src/index.ts index 771c3e6f..de2cbcb3 100644 --- a/packages/mcp/src/index.ts +++ b/packages/mcp/src/index.ts @@ -64,6 +64,33 @@ const jsonContent = (data: any) => ({ * REST + the collaboration WebSocket using the provided service-account * credentials and auto-re-authenticates. */ +/** + * Wrap a tool handler so its wall-clock duration is reported through the host's + * dependency-neutral sink as `mcp_tool_duration_seconds` (labelled by tool + * name). Pure and side-effect-free apart from the optional `onMetric` call: + * - preserves the handler's exact return value (awaited); + * - observes in a `finally`, so it records on BOTH success and throw, then + * rethrows the original error unchanged (never swallowed); + * - with no `onMetric` (standalone/stdio) it is a transparent pass-through. + * Exported so the timing contract can be unit-tested without a live transport. + */ +export function timeToolHandler( + name: string, + handler: (...args: any[]) => any, + onMetric?: (name: string, value: number, labels?: Record) => void, +): (...args: any[]) => Promise { + return async (...handlerArgs: any[]) => { + const start = performance.now(); + try { + return await handler(...handlerArgs); + } finally { + onMetric?.("mcp_tool_duration_seconds", (performance.now() - start) / 1000, { + tool: name, + }); + } + }; +} + export function createDocmostMcpServer(config: DocmostMcpConfig): McpServer { // Pass the whole config union through: the client branches internally on // credentials vs. getToken, so both the external /mcp (creds) and the @@ -78,6 +105,26 @@ export function createDocmostMcpServer(config: DocmostMcpConfig): McpServer { { instructions: SERVER_INSTRUCTIONS }, ); + // Single choke point for MCP tool timing. Both `registerShared` (below) and + // the inline `server.registerTool(...)` calls funnel through this one method, + // so monkeypatching it HERE — before any tool is registered and before + // `registerShared` captures a reference to it — times every tool with no + // per-tool boilerplate. The wrapped handler records wall-clock duration and, + // in a `finally`, feeds the host's dependency-neutral sink + // `config.onMetric("mcp_tool_duration_seconds", seconds, { tool })`. The tool + // name is the registration name (bounded cardinality). When no onMetric is + // provided (standalone/stdio) the wrapper is a pure pass-through: it still + // returns the original result and rethrows the original error unchanged. + const originalRegisterTool = server.registerTool.bind(server) as ( + ...args: any[] + ) => any; + (server as any).registerTool = (...args: any[]) => { + const name = args[0] as string; + const handler = args[args.length - 1]; + const timedHandler = timeToolHandler(name, handler, config.onMetric); + return originalRegisterTool(...args.slice(0, -1), timedHandler); + }; + // Register a tool from the shared, zod-agnostic spec registry. The spec owns // the canonical name + model-facing description + (optional) schema builder; // only the execute body is supplied per call. buildShape is invoked with THIS diff --git a/packages/mcp/test/unit/tool-timing.test.mjs b/packages/mcp/test/unit/tool-timing.test.mjs new file mode 100644 index 00000000..543bb04f --- /dev/null +++ b/packages/mcp/test/unit/tool-timing.test.mjs @@ -0,0 +1,67 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; + +import { timeToolHandler } from "../../build/index.js"; + +// #402 — the registerTool wrapper times every tool through a single choke point +// and feeds the host's dependency-neutral onMetric sink. These assert the +// timing contract without a live transport (the factory monkeypatches +// server.registerTool with exactly this helper). + +test("times a tool and preserves the handler's return value", async () => { + const calls = []; + const onMetric = (name, value, labels) => calls.push({ name, value, labels }); + + const handler = async (arg) => ({ ok: true, echo: arg }); + const wrapped = timeToolHandler("get_page", handler, onMetric); + + const result = await wrapped("hello"); + // Return value passes through untouched. + assert.deepEqual(result, { ok: true, echo: "hello" }); + + // Exactly one sample, correct name/labels, numeric non-negative duration. + assert.equal(calls.length, 1); + assert.equal(calls[0].name, "mcp_tool_duration_seconds"); + assert.deepEqual(calls[0].labels, { tool: "get_page" }); + assert.equal(typeof calls[0].value, "number"); + assert.ok(calls[0].value >= 0, "duration must be non-negative seconds"); +}); + +test("standalone (no onMetric) is a transparent pass-through", async () => { + const handler = async (a, b) => a + b; + const wrapped = timeToolHandler("noop_tool", handler, undefined); + + // No throw, result unchanged, and nothing to observe. + const result = await wrapped(2, 3); + assert.equal(result, 5); +}); + +test("still observes on throw, then rethrows the original error", async () => { + const calls = []; + const onMetric = (name, value, labels) => calls.push({ name, value, labels }); + + const boom = new Error("handler failed"); + const handler = async () => { + throw boom; + }; + const wrapped = timeToolHandler("boom_tool", handler, onMetric); + + await assert.rejects(() => wrapped(), (err) => err === boom); + + // Observed exactly once despite the throw. + assert.equal(calls.length, 1); + assert.equal(calls[0].name, "mcp_tool_duration_seconds"); + assert.deepEqual(calls[0].labels, { tool: "boom_tool" }); +}); + +test("standalone still rethrows the original error (no swallow, no observe)", async () => { + const boom = new Error("standalone failure"); + const wrapped = timeToolHandler( + "boom_standalone", + async () => { + throw boom; + }, + undefined, + ); + await assert.rejects(() => wrapped(), (err) => err === boom); +}); -- 2.52.0 From 8f5f5877b31a0caab88a4a42946b4f80b10440f5 Mon Sep 17 00:00:00 2001 From: agent_coder Date: Tue, 7 Jul 2026 02:38:11 +0300 Subject: [PATCH 3/3] =?UTF-8?q?test(metrics):=20#403=20review=20=E2=80=94?= =?UTF-8?q?=20lock=20the=20registerTool=20monkeypatch=20+=20reword=20overh?= =?UTF-8?q?ead=20note=20(#402)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit DO-1: add an integration test (test/mock/tool-timing-server.test.mjs) that constructs a real createDocmostMcpServer with a spy onMetric, links a Client over InMemoryTransport, invokes get_workspace (no input schema, so the wrapped handler always runs) and asserts onMetric fired with ("mcp_tool_duration_seconds", , { tool: "get_workspace" }). This locks that the monkeypatch wraps every tool AND labels with the registration name — which the isolated timeToolHandler unit test does not. Mutation-verified (mislabel -> test fails). The tool's expected backend failure (ECONNREFUSED) is tolerated: the wrapper times in a finally on throw too, so the metric fires. DO-2: reword the mcp.service.ts "zero overhead when disabled" comment to "negligible overhead" — the registerTool wrapper still runs performance.now() + an async try/finally per tool call when onMetric is undefined (the `onMetric?.()` short-circuits the label build; cost is immaterial at tool-call rate), so "zero" was literally inaccurate. Co-Authored-By: Claude Opus 4.8 (1M context) --- .../src/integrations/mcp/mcp.service.ts | 9 +- .../mcp/test/mock/tool-timing-server.test.mjs | 87 +++++++++++++++++++ 2 files changed, 93 insertions(+), 3 deletions(-) create mode 100644 packages/mcp/test/mock/tool-timing-server.test.mjs diff --git a/apps/server/src/integrations/mcp/mcp.service.ts b/apps/server/src/integrations/mcp/mcp.service.ts index 11ae9d64..26349d56 100644 --- a/apps/server/src/integrations/mcp/mcp.service.ts +++ b/apps/server/src/integrations/mcp/mcp.service.ts @@ -338,9 +338,12 @@ export class McpService implements OnModuleDestroy { // mapping) is owned by SandboxStore.asSink(). // Route the package's dependency-neutral metric samples onto the // prom-client registry. When metrics are disabled, onMetric is - // undefined → the package's tool-timer/timeout hooks no-op with - // zero overhead. labels?.tool is guarded defensively (the tool - // wrapper always sets it). + // undefined → the package's tool-timer/timeout hooks are a + // negligible-overhead no-op: the registerTool wrapper still runs a + // performance.now() + async try/finally per tool call, but the + // `onMetric?.()` short-circuits so no label/object is built. (Cost + // is immaterial at LLM tool-call rate.) labels?.tool is guarded + // defensively (the tool wrapper always sets it). return { ...resolved.config, sandbox: this.sandboxStore.asSink(), diff --git a/packages/mcp/test/mock/tool-timing-server.test.mjs b/packages/mcp/test/mock/tool-timing-server.test.mjs new file mode 100644 index 00000000..6e93842f --- /dev/null +++ b/packages/mcp/test/mock/tool-timing-server.test.mjs @@ -0,0 +1,87 @@ +// #402 — INTEGRATION test that locks the registerTool monkeypatch installed by +// createDocmostMcpServer (src/index.ts). The sibling unit test +// (test/unit/tool-timing.test.mjs) only exercises the timeToolHandler helper in +// ISOLATION; it never constructs the server, so nothing there proves the factory +// actually (a) wraps every registered tool through that helper and (b) labels +// each sample with the tool's REGISTRATION name. +// +// Here we stand up a real McpServer via the factory, connect a real MCP Client +// over the SDK's in-memory transport, invoke one registered tool, and assert the +// host's onMetric sink received `("mcp_tool_duration_seconds", , { tool +// })` with tool === the exact registration name. This locks both the "monkeypatch +// wraps tools" and "label = registration name" halves of the contract, so a +// mutation to args.slice(0, -1) / the handler-arg detection / the capture order +// is caught. +import { test } from "node:test"; +import assert from "node:assert/strict"; + +import { Client } from "@modelcontextprotocol/sdk/client/index.js"; +import { InMemoryTransport } from "@modelcontextprotocol/sdk/inMemory.js"; + +import { createDocmostMcpServer } from "../../build/index.js"; + +// The tool we drive. get_workspace has NO input schema, so protocol-level input +// validation cannot short-circuit before the handler runs — the wrapped handler +// is guaranteed to execute (and then fail on the unreachable backend, which is +// exactly what we want: the wrapper times in a finally on throw too). +const TOOL_NAME = "get_workspace"; + +test("the factory's registerTool monkeypatch times a live tool call and labels it with the registration name", async () => { + const calls = []; + const onMetric = (name, value, labels) => calls.push({ name, value, labels }); + + // Minimal valid credentials config. apiUrl points at a port that refuses + // connections immediately so the tool's backend call fails FAST (ECONNREFUSED) + // rather than hanging — the wrapper still emits the metric from its finally. + const server = createDocmostMcpServer({ + apiUrl: "http://127.0.0.1:1", + email: "x@example.com", + password: "pw", + onMetric, + }); + + const [clientTransport, serverTransport] = + InMemoryTransport.createLinkedPair(); + + const client = new Client( + { name: "test-client", version: "0.0.0" }, + { capabilities: {} }, + ); + + await Promise.all([ + server.connect(serverTransport), + client.connect(clientTransport), + ]); + + try { + // Invoke the tool. The backend is unreachable, so this either resolves with + // an error result (isError) or rejects — both are fine. What matters is that + // the handler ran through the timing wrapper, which fires onMetric either way. + try { + await client.callTool({ name: TOOL_NAME, arguments: {} }); + } catch { + // Tolerate the expected backend failure surfacing as a thrown protocol error. + } + + // The wrapper must have fed exactly the timing sample for THIS tool. + const timing = calls.filter( + (c) => c.name === "mcp_tool_duration_seconds", + ); + assert.ok( + timing.length >= 1, + "onMetric must receive a mcp_tool_duration_seconds sample from the wrapped handler", + ); + + const sample = timing.find((c) => c.labels && c.labels.tool === TOOL_NAME); + assert.ok( + sample, + `a timing sample must be labelled with the registration name "${TOOL_NAME}"; ` + + `got labels: ${JSON.stringify(timing.map((c) => c.labels))}`, + ); + assert.equal(typeof sample.value, "number"); + assert.ok(sample.value >= 0, "duration must be non-negative seconds"); + } finally { + await client.close(); + await server.close(); + } +}); -- 2.52.0