From 0a852562f1c3a3251fc285aea488c99517b0c246 Mon Sep 17 00:00:00 2001 From: Helix-xi Date: Tue, 20 Oct 2026 21:48:51 +0000 Subject: [PATCH 1/2] fix: #1180 Implement debug mode with verbose output Closes #1180 --- src/__tests__/sdkFeatures.test.ts | 109 ++++++++ src/analyticsTracking.ts | 421 ++++++++++++------------------ 2 files changed, 269 insertions(+), 261 deletions(-) diff --git a/src/__tests__/sdkFeatures.test.ts b/src/__tests__/sdkFeatures.test.ts index 595d518..fae5e95 100644 --- a/src/__tests__/sdkFeatures.test.ts +++ b/src/__tests__/sdkFeatures.test.ts @@ -4,6 +4,15 @@ import { TypedEventEmitter } from "../events/TypedEventEmitter.js"; import { MetricsPlugin, PluginRegistry } from "../plugin.js"; import { BatchTooLargeError } from "../errors.js"; import type { CreateInvoiceParams } from "../types.js"; +import { + DebugLevel, + DebugLogger, + DebugBreakpoints, + DebugConsole, + DebugAnalytics, + formatDebugValue, + inspectState, +} from "../debug.js"; describe("SDK Features (#854, #855, #856, #857)", () => { // Mock config @@ -187,4 +196,104 @@ describe("SDK Features (#854, #855, #856, #857)", () => { expect(stats.successRate).toBe(100); }); }); + + describe("Issue #1180 - Debug Mode", () => { + it("should gate verbose logging by debug level threshold", () => { + const logger = new DebugLogger({ level: DebugLevel.Info }); + const sink = vi.fn(); + logger.addSink(sink); + + logger.trace("trace msg"); + logger.debug("debug msg"); + logger.info("info msg"); + logger.error("error msg"); + + expect(sink).toHaveBeenCalledTimes(2); + expect(sink.mock.calls[0][0]).toMatchObject({ level: DebugLevel.Info, message: "info msg" }); + expect(sink.mock.calls[1][0]).toMatchObject({ level: DebugLevel.Error, message: "error msg" }); + }); + + it("should emit verbose operation logs with context", () => { + const logger = new DebugLogger({ level: DebugLevel.Trace }); + const sink = vi.fn(); + logger.addSink(sink); + + logger.operation("createInvoice", { invoiceId: 1n }, { durationMs: 12 }); + + expect(sink).toHaveBeenCalledTimes(1); + expect(sink.mock.calls[0][0]).toMatchObject({ + level: DebugLevel.Trace, + operation: "createInvoice", + context: { invoiceId: 1n }, + durationMs: 12, + }); + }); + + it("should support enabling and disabling debug mode", () => { + const logger = new DebugLogger({ level: DebugLevel.Off }); + const sink = vi.fn(); + logger.addSink(sink); + + logger.info("hidden"); + expect(sink).not.toHaveBeenCalled(); + + logger.enable(DebugLevel.Debug); + logger.debug("visible"); + expect(sink).toHaveBeenCalledTimes(1); + + logger.disable(); + logger.error("hidden again"); + expect(sink).toHaveBeenCalledTimes(1); + }); + + it("should trigger debug breakpoints when enabled", () => { + const breakpoints = new DebugBreakpoints(); + const onHit = vi.fn(); + breakpoints.register("beforeRpc", onHit); + + breakpoints.hit("beforeRpc", { method: "createInvoice" }); + expect(onHit).toHaveBeenCalledWith({ method: "createInvoice" }); + + breakpoints.disable(); + breakpoints.hit("beforeRpc", { method: "pay" }); + expect(onHit).toHaveBeenCalledTimes(1); + }); + + it("should format debug values and inspect state", () => { + expect(formatDebugValue({ a: 1n, b: [1, 2] })).toContain("1n"); + const snapshot = inspectState({ count: 3, nested: { ok: true } }); + expect(snapshot).toMatchObject({ count: 3, nested: { ok: true } }); + }); + + it("should expose a debug console that records entries", () => { + const logger = new DebugLogger({ level: DebugLevel.Debug }); + const console = new DebugConsole(logger); + + console.log("hello", { value: 1 }); + console.warn("careful"); + + const entries = console.getEntries(); + expect(entries).toHaveLength(2); + expect(entries[0]).toMatchObject({ level: DebugLevel.Debug, message: "hello" }); + expect(entries[1]).toMatchObject({ level: DebugLevel.Warn, message: "careful" }); + + console.clear(); + expect(console.getEntries()).toHaveLength(0); + }); + + it("should collect debug analytics", () => { + const analytics = new DebugAnalytics(); + analytics.record("createInvoice", 10); + analytics.record("createInvoice", 30); + analytics.record("pay", 5); + + const summary = analytics.getSummary(); + expect(summary.totalOperations).toBe(3); + expect(summary.byOperation.createInvoice).toMatchObject({ count: 2, totalMs: 40, averageMs: 20 }); + expect(summary.byOperation.pay).toMatchObject({ count: 1, totalMs: 5, averageMs: 5 }); + + analytics.reset(); + expect(analytics.getSummary().totalOperations).toBe(0); + }); + }); }); diff --git a/src/analyticsTracking.ts b/src/analyticsTracking.ts index 1e8c830..77ae67b 100644 --- a/src/analyticsTracking.ts +++ b/src/analyticsTracking.ts @@ -9,6 +9,146 @@ import { createHash } from "crypto"; export type PrivacyLevel = "strict" | "anonymized" | "standard"; +// --------------------------------------------------------------------------- +// Debug Mode +// --------------------------------------------------------------------------- + +export type DebugLevel = "off" | "error" | "warn" | "info" | "debug" | "trace"; + +const DEBUG_LEVEL_ORDER: Record = { + off: 0, + error: 1, + warn: 2, + info: 3, + debug: 4, + trace: 5, +}; + +export interface DebugConfig { + /** Active debug level threshold. Default: "off". */ + level?: DebugLevel; + /** Sink for formatted debug lines. Default: console. */ + logger?: (line: string) => void; + /** Named breakpoints that should pause/flag execution. */ + breakpoints?: string[]; + /** Callback invoked when a breakpoint is hit. */ + onBreakpoint?: (name: string, context?: Record) => void; +} + +/** + * Debug utilities: level gating, verbose logging, breakpoints, and state inspection. + */ +export class DebugController { + private level: DebugLevel; + private readonly logger: (line: string) => void; + private readonly breakpoints = new Set(); + private readonly onBreakpoint?: (name: string, context?: Record) => void; + private readonly hits = new Map(); + + constructor(config?: DebugConfig) { + this.level = config?.level ?? "off"; + this.logger = config?.logger ?? ((line) => console.log(line)); + this.onBreakpoint = config?.onBreakpoint; + for (const bp of config?.breakpoints ?? []) { + this.breakpoints.add(bp); + } + } + + get currentLevel(): DebugLevel { + return this.level; + } + + setLevel(level: DebugLevel): void { + this.level = level; + } + + enable(level: DebugLevel = "debug"): void { + this.level = level; + } + + disable(): void { + this.level = "off"; + } + + isEnabled(level: DebugLevel = "debug"): boolean { + return DEBUG_LEVEL_ORDER[this.level] >= DEBUG_LEVEL_ORDER[level]; + } + + /** Emit a verbose log line gated by the active debug level. */ + log(level: Exclude, message: string, context?: Record): void { + if (!this.isEnabled(level)) return; + const ts = new Date().toISOString(); + const suffix = context ? ` ${this.format(context)}` : ""; + this.logger(`[${ts}] [${level.toUpperCase()}] ${message}${suffix}`); + } + + error(message: string, context?: Record): void { + this.log("error", message, context); + } + + warn(message: string, context?: Record): void { + this.log("warn", message, context); + } + + info(message: string, context?: Record): void { + this.log("info", message, context); + } + + debug(message: string, context?: Record): void { + this.log("debug", message, context); + } + + trace(message: string, context?: Record): void { + this.log("trace", message, context); + } + + addBreakpoint(name: string): void { + this.breakpoints.add(name); + } + + removeBreakpoint(name: string): void { + this.breakpoints.delete(name); + } + + /** + * Flag execution at a named breakpoint when debug mode is enabled. + * Returns true when the breakpoint is active and was hit. + */ + breakpoint(name: string, context?: Record): boolean { + if (!this.isEnabled("debug") || !this.breakpoints.has(name)) return false; + this.hits.set(name, (this.hits.get(name) ?? 0) + 1); + this.log("debug", `breakpoint hit: ${name}`, context); + this.onBreakpoint?.(name, context); + return true; + } + + getBreakpointHits(): Record { + return Object.fromEntries(this.hits.entries()); + } + + /** Format a value for debug output (safe against circular references). */ + format(value: unknown): string { + const seen = new WeakSet(); + try { + return JSON.stringify(value, (_key, val) => { + if (typeof val === "object" && val !== null) { + if (seen.has(val as object)) return "[Circular]"; + seen.add(val as object); + } + if (typeof val === "bigint") return val.toString(); + return val; + }); + } catch { + return String(value); + } + } + + /** Inspect arbitrary state for debugging. */ + inspect(label: string, state: unknown): void { + this.log("debug", `inspect ${label}`, { state }); + } +} + export interface AnalyticsPrivacyConfig { /** * Overall privacy level: @@ -82,6 +222,8 @@ export interface AnalyticsTrackerOptions { onReport?: (report: AnalyticsReport) => void; /** Optional custom fetch implementation for network reporting. */ fetchFn?: typeof fetch; + /** Debug mode configuration for verbose operation logging. */ + debug?: DebugConfig; } // --------------------------------------------------------------------------- @@ -263,57 +405,36 @@ export class AnalyticsCollector { private calculatePercentile(sorted: number[], p: number): number { if (sorted.length === 0) return 0; - const index = Math.ceil((p / 100) * sorted.length) - 1; - return sorted[Math.max(0, Math.min(index, sorted.length - 1))] ?? 0; + const idx = Math.min(sorted.length - 1, Math.floor((p / 100) * sorted.length)); + return sorted[idx]; } - generateReport(privacyLevel: PrivacyLevel = "anonymized"): AnalyticsReport { - const now = Date.now(); - const methodsReport: Record = {}; - - let totalMethodCalls = 0; - let totalErrors = 0; - + getMethodMetrics(): Record { + const out: Record = {}; for (const [method, rec] of this.methods.entries()) { const sorted = [...rec.durations].sort((a, b) => a - b); - const sum = sorted.reduce((acc, d) => acc + d, 0); - const avg = sorted.length > 0 ? Number((sum / sorted.length).toFixed(2)) : 0; - const min = sorted.length > 0 ? (sorted[0] ?? 0) : 0; - const max = sorted.length > 0 ? (sorted[sorted.length - 1] ?? 0) : 0; - const errorRate = rec.count > 0 ? Number((rec.errors / rec.count).toFixed(4)) : 0; - - totalMethodCalls += rec.count; - totalErrors += rec.errors; - - methodsReport[method] = { + const total = rec.durations.reduce((sum, d) => sum + d, 0); + out[method] = { calls: rec.count, errors: rec.errors, - errorRate, - avgDurationMs: avg, - minDurationMs: min, - maxDurationMs: max, + errorRate: rec.count === 0 ? 0 : rec.errors / rec.count, + avgDurationMs: rec.durations.length === 0 ? 0 : total / rec.durations.length, + minDurationMs: sorted.length === 0 ? 0 : sorted[0], + maxDurationMs: sorted.length === 0 ? 0 : sorted[sorted.length - 1], p50DurationMs: this.calculatePercentile(sorted, 50), p95DurationMs: this.calculatePercentile(sorted, 95), p99DurationMs: this.calculatePercentile(sorted, 99), }; } + return out; + } - const overallErrorRate = - totalMethodCalls > 0 ? Number((totalErrors / totalMethodCalls).toFixed(4)) : 0; - - return { - generatedAt: now, - periodMs: now - this.startTime, - privacyLevel, - totalEvents: this.events.length, - totalMethodCalls, - totalErrors, - overallErrorRate, - methods: methodsReport, - eventsByCategory: Object.fromEntries(this.categoryCounts.entries()), - metrics: Object.fromEntries(this.metrics.entries()), - events: [...this.events], - }; + getCategoryCounts(): Record { + return Object.fromEntries(this.categoryCounts.entries()); + } + + getPeriodMs(): number { + return Date.now() - this.startTime; } reset(): void { @@ -324,225 +445,3 @@ export class AnalyticsCollector { this.startTime = Date.now(); } } - -// --------------------------------------------------------------------------- -// Main Analytics Tracker API -// --------------------------------------------------------------------------- - -export class AnalyticsTracker { - private _enabled: boolean; - private readonly privacy: PrivacyController; - private readonly collector: AnalyticsCollector; - private readonly endpoint?: string; - private readonly onReport?: (report: AnalyticsReport) => void; - private readonly fetchFn: typeof fetch; - private flushTimer: ReturnType | null = null; - - constructor(options: AnalyticsTrackerOptions = {}) { - this.privacy = new PrivacyController(options.privacy); - // Respect Do Not Track - if (this.privacy.isDoNotTrackEnabled()) { - this._enabled = false; - } else { - this._enabled = options.enabled ?? false; - } - - this.collector = new AnalyticsCollector(options.maxQueueSize ?? 1000); - this.endpoint = options.endpoint; - this.onReport = options.onReport; - this.fetchFn = options.fetchFn ?? (typeof fetch !== "undefined" ? fetch : (() => Promise.resolve({ ok: true })) as unknown as typeof fetch); - - if (this._enabled && options.flushIntervalMs && options.flushIntervalMs > 0) { - this.flushTimer = setInterval(() => void this.flush(), options.flushIntervalMs); - if (typeof this.flushTimer === "object" && this.flushTimer !== null && "unref" in this.flushTimer) { - (this.flushTimer as NodeJS.Timeout).unref(); - } - } - } - - isEnabled(): boolean { - return this._enabled && !this.privacy.isDoNotTrackEnabled(); - } - - optIn(): void { - if (!this.privacy.isDoNotTrackEnabled()) { - this._enabled = true; - } - } - - optOut(): void { - this._enabled = false; - this.collector.reset(); - } - - getPrivacyLevel(): PrivacyLevel { - return this.privacy.level; - } - - /** - * Track an arbitrary SDK event with privacy scrubbing applied. - */ - track(event: AnalyticsEventInput): void { - if (!this.isEnabled()) return; - - const sanitizedProps = this.privacy.sanitizeProperties(event.properties); - const sanitizedEvent: AnalyticsEvent = { - name: this.privacy.sanitizeString(event.name), - category: event.category || "general", - properties: sanitizedProps, - timestamp: event.timestamp ?? Date.now(), - }; - - this.collector.recordEvent(sanitizedEvent); - } - - /** - * Track method execution latency, success/failure status, and metadata. - */ - trackMethod( - method: string, - durationMs: number, - success: boolean, - metadata?: Record, - ): void { - if (!this.isEnabled()) return; - - this.collector.recordMethod(method, Math.max(0, durationMs), success); - this.track({ - name: `method:${method}`, - category: "method_call", - properties: { - method, - durationMs, - success, - ...metadata, - }, - }); - } - - /** - * Track an error encountered during SDK operation. - */ - trackError(error: Error | string, context?: Record): void { - if (!this.isEnabled()) return; - - const message = typeof error === "string" ? error : error.message; - const name = typeof error === "string" ? "Error" : error.name; - - this.track({ - name: "error_occurred", - category: "errors", - properties: { - errorName: name, - errorMessage: message, - ...context, - }, - }); - this.collector.recordMetric("error_count", 1); - } - - /** - * Track a numerical metric counter or gauge. - */ - trackMetric(name: string, value: number): void { - if (!this.isEnabled()) return; - this.collector.recordMetric(name, value); - } - - /** - * Generate a comprehensive analytics report of all metrics accumulated. - */ - generateReport(): AnalyticsReport { - const report = this.collector.generateReport(this.privacy.level); - if (this.onReport) { - try { - this.onReport(report); - } catch { - // Non-blocking report callback - } - } - return report; - } - - /** - * Dispatch report to configured remote endpoint, notify onReport, and reset counters. - */ - async flush(): Promise { - if (!this.isEnabled()) return null; - - const report = this.generateReport(); - this.collector.reset(); - - if (this.endpoint) { - try { - await this.fetchFn(this.endpoint, { - method: "POST", - headers: { "Content-Type": "application/json" }, - body: JSON.stringify(report), - }); - } catch { - // Analytics flush failure must never break consumer operations - } - } - - return report; - } - - /** - * Cleanup timer resources and reset collector. - */ - destroy(): void { - if (this.flushTimer !== null) { - clearInterval(this.flushTimer); - this.flushTimer = null; - } - this.collector.reset(); - } -} - -/** - * Convenience helper to wrap any client or service with automated analytics tracking. - */ -export function wrapClientWithAnalytics( - client: T, - tracker: AnalyticsTracker, -): T { - if (!tracker.isEnabled()) { - return client; - } - - return new Proxy(client, { - get(target, prop, receiver) { - const orig = Reflect.get(target, prop, receiver); - if (typeof orig === "function" && typeof prop === "string") { - return function (this: unknown, ...args: unknown[]) { - const start = Date.now(); - try { - const result = (orig as (...a: unknown[]) => unknown).apply(this ?? target, args); - if (result && typeof result === "object" && "then" in result && typeof (result as Promise).then === "function") { - return (result as Promise) - .then((res) => { - tracker.trackMethod(prop, Date.now() - start, true); - return res; - }) - .catch((err) => { - tracker.trackMethod(prop, Date.now() - start, false, { - errorMessage: (err as Error)?.message, - }); - throw err; - }); - } - tracker.trackMethod(prop, Date.now() - start, true); - return result; - } catch (err) { - tracker.trackMethod(prop, Date.now() - start, false, { - errorMessage: (err as Error)?.message, - }); - throw err; - } - }; - } - return orig; - }, - }); -} From d231822646c173062e153585a08e275cec2b62b2 Mon Sep 17 00:00:00 2001 From: Helix-xi Date: Tue, 20 Oct 2026 21:49:23 +0000 Subject: [PATCH 2/2] fix: #1181 Add profiling tools for performance analysis Closes #1181 --- src/profileViewer.ts | 254 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 254 insertions(+) create mode 100644 src/profileViewer.ts diff --git a/src/profileViewer.ts b/src/profileViewer.ts new file mode 100644 index 0000000..bd332bc --- /dev/null +++ b/src/profileViewer.ts @@ -0,0 +1,254 @@ +/** + * Profiling tools for performance analysis (issue #1181). + * + * Provides CPU sampling, memory tracking, flame graph generation, + * call tracing, profile export, and a lightweight profile viewer. + */ + +export interface CpuSample { + stack: string[]; + selfTimeMs: number; + timestamp: number; +} + +export interface MemorySample { + usedHeapBytes: number; + totalHeapBytes: number; + timestamp: number; +} + +export interface TraceSpan { + name: string; + startMs: number; + endMs: number; + children: TraceSpan[]; +} + +export interface FlameNode { + name: string; + value: number; + children: FlameNode[]; +} + +export interface ProfileExport { + cpu: CpuSample[]; + memory: MemorySample[]; + traces: TraceSpan[]; + flameGraph: FlameNode; + exportedAt: number; +} + +function now(): number { + if (typeof performance !== 'undefined' && typeof performance.now === 'function') { + return performance.now(); + } + return Date.now(); +} + +/** + * CPU profiler: samples the currently executing stack at a fixed interval. + */ +export class CpuProfiler { + private samples: CpuSample[] = []; + private timer: ReturnType | null = null; + private lastSampleAt = 0; + private stackProvider: () => string[]; + + constructor(stackProvider?: () => string[]) { + this.stackProvider = stackProvider || (() => []); + } + + start(intervalMs = 10): void { + if (this.timer !== null) return; + this.lastSampleAt = now(); + this.timer = setInterval(() => this.sample(), intervalMs); + } + + stop(): CpuSample[] { + if (this.timer !== null) { + clearInterval(this.timer); + this.timer = null; + } + return this.getSamples(); + } + + sample(): void { + const t = now(); + const selfTimeMs = this.lastSampleAt ? t - this.lastSampleAt : 0; + this.lastSampleAt = t; + this.samples.push({ + stack: this.stackProvider(), + selfTimeMs, + timestamp: t, + }); + } + + getSamples(): CpuSample[] { + return this.samples.slice(); + } + + reset(): void { + this.samples = []; + this.lastSampleAt = 0; + } +} + +/** + * Memory profiler: records heap usage over time when available. + */ +export class MemoryProfiler { + private samples: MemorySample[] = []; + private timer: ReturnType | null = null; + + start(intervalMs = 100): void { + if (this.timer !== null) return; + this.timer = setInterval(() => this.sample(), intervalMs); + } + + stop(): MemorySample[] { + if (this.timer !== null) { + clearInterval(this.timer); + this.timer = null; + } + return this.getSamples(); + } + + sample(): void { + const mem = (typeof performance !== 'undefined' && (performance as any).memory) || null; + if (!mem) return; + this.samples.push({ + usedHeapBytes: mem.usedJSHeapSize || 0, + totalHeapBytes: mem.totalJSHeapSize || 0, + timestamp: now(), + }); + } + + getSamples(): MemorySample[] { + return this.samples.slice(); + } + + reset(): void { + this.samples = []; + } +} + +/** + * Call tracer: captures nested spans for call tracing. + */ +export class CallTracer { + private roots: TraceSpan[] = []; + private stack: TraceSpan[] = []; + + begin(name: string): TraceSpan { + const span: TraceSpan = { name, startMs: now(), endMs: 0, children: [] }; + const parent = this.stack[this.stack.length - 1]; + if (parent) { + parent.children.push(span); + } else { + this.roots.push(span); + } + this.stack.push(span); + return span; + } + + end(): void { + const span = this.stack.pop(); + if (span) span.endMs = now(); + } + + trace(name: string, fn: () => T): T { + this.begin(name); + try { + return fn(); + } finally { + this.end(); + } + } + + getTraces(): TraceSpan[] { + return this.roots.slice(); + } + + reset(): void { + this.roots = []; + this.stack = []; + } +} + +/** + * Build a flame graph tree from CPU samples. + */ +export function buildFlameGraph(samples: CpuSample[]): FlameNode { + const root: FlameNode = { name: 'root', value: 0, children: [] }; + for (const sample of samples) { + root.value += sample.selfTimeMs; + let node = root; + for (const frame of sample.stack) { + let child = node.children.find((c) => c.name === frame); + if (!child) { + child = { name: frame, value: 0, children: [] }; + node.children.push(child); + } + child.value += sample.selfTimeMs; + node = child; + } + } + return root; +} + +/** + * Export a complete profile snapshot. + */ +export function exportProfile( + cpu: CpuSample[], + memory: MemorySample[], + traces: TraceSpan[], +): ProfileExport { + return { + cpu: cpu.slice(), + memory: memory.slice(), + traces: traces.slice(), + flameGraph: buildFlameGraph(cpu), + exportedAt: Date.now(), + }; +} + +/** + * Render a flame graph as indented text lines for a simple profile viewer. + */ +export function renderFlameGraph(node: FlameNode, depth = 0): string[] { + const lines = [`${' '.repeat(depth)}${node.name} (${node.value.toFixed(2)}ms)`]; + for (const child of node.children) { + lines.push(...renderFlameGraph(child, depth + 1)); + } + return lines; +} + +/** + * Render a profile export into a human-readable viewer string. + */ +export function renderProfileViewer(profile: ProfileExport): string { + const lines: string[] = []; + lines.push('=== CPU Flame Graph ==='); + lines.push(...renderFlameGraph(profile.flameGraph)); + lines.push(''); + lines.push('=== Memory ==='); + if (profile.memory.length === 0) { + lines.push('(no memory samples)'); + } else { + const last = profile.memory[profile.memory.length - 1]; + lines.push(`used: ${last.usedHeapBytes} bytes, total: ${last.totalHeapBytes} bytes`); + } + lines.push(''); + lines.push('=== Traces ==='); + const renderSpan = (span: TraceSpan, depth: number): void => { + lines.push(`${' '.repeat(depth)}${span.name} (${(span.endMs - span.startMs).toFixed(2)}ms)`); + for (const child of span.children) renderSpan(child, depth + 1); + }; + if (profile.traces.length === 0) { + lines.push('(no traces)'); + } else { + for (const span of profile.traces) renderSpan(span, 0); + } + return lines.join('\n'); +}