diff --git a/apps/clean-app/server.ts b/apps/clean-app/server.ts index a5e78095..e6bf9ad9 100644 --- a/apps/clean-app/server.ts +++ b/apps/clean-app/server.ts @@ -1,5 +1,9 @@ import { createApp, server } from "@databricks/appkit"; createApp({ - plugins: [server()], + plugins: [ + server({ + port: 8001, + }), + ], }); diff --git a/apps/clean-app/vite.config.ts b/apps/clean-app/vite.config.ts index 0e43ae8d..2ea526b2 100644 --- a/apps/clean-app/vite.config.ts +++ b/apps/clean-app/vite.config.ts @@ -1,7 +1,10 @@ -import { defineConfig } from "vite"; import react from "@vitejs/plugin-react"; +import { defineConfig } from "vite"; // https://vite.dev/config/ export default defineConfig({ plugins: [react()], + server: { + port: 8001, + }, }); diff --git a/apps/dev-playground/client/src/routes/telemetry.route.tsx b/apps/dev-playground/client/src/routes/telemetry.route.tsx index 5291da67..49b3daf3 100644 --- a/apps/dev-playground/client/src/routes/telemetry.route.tsx +++ b/apps/dev-playground/client/src/routes/telemetry.route.tsx @@ -1,7 +1,21 @@ +import { + Badge, + Button, + Card, + CardContent, + CardDescription, + CardHeader, + CardTitle, + Tabs, + TabsContent, + TabsList, + TabsTrigger, +} from "@databricks/appkit-ui/react"; import { createFileRoute, retainSearchParams } from "@tanstack/react-router"; -import { Button, Card } from "@databricks/appkit-ui/react"; -import { useState } from "react"; -import { Activity, Loader2 } from "lucide-react"; +import { Activity, ArrowRight, Loader2 } from "lucide-react"; +import { useEffect, useState } from "react"; +import { codeToHtml } from "shiki"; +import { Header } from "@/components/layout/header"; export const Route = createFileRoute("/telemetry")({ component: TelemetryRoute, @@ -27,11 +41,191 @@ type ExampleResult = { logs?: { emitted?: string[]; }; + features?: Record; + layers?: Record; }; +const LAYER_CONFIGS = [ + { + id: "opinionated", + name: "Opinionated API", + badge: "Recommended", + description: "Automatic observability with standard logger methods", + useCases: [ + "Standard application logging", + "Request tracing", + "Error tracking", + "Performance monitoring", + ], + methods: [ + { + name: "logger.debug()", + description: "Terminal only (requires DEBUG=appkit:*)", + outputs: ["Terminal"], + note: "Local development only", + }, + { + name: "logger.trace()", + description: "Verbose debugging with individual OTEL log records", + outputs: ["Terminal", "WideEvent.logs[]", "Individual OTEL Log"], + isNew: true, + note: "Each trace() creates a separate OTEL log record", + }, + { + name: "logger.info()", + description: "Logs accumulated in WideEvent, sent at request end", + outputs: ["Terminal", "WideEvent.logs[]", "Span Events"], + note: "Aggregated in WideEvent → ONE OTEL log per request", + }, + { + name: "logger.warn()", + description: "Warning logs accumulated in WideEvent", + outputs: ["Terminal", "WideEvent.logs[]", "Span Events"], + note: "Aggregated in WideEvent → ONE OTEL log per request", + }, + { + name: "logger.error()", + description: "Error logs with exception recording on span", + outputs: ["Terminal", "WideEvent.logs[]", "Span Events", "Exception"], + note: "Aggregated in WideEvent → ONE OTEL log per request", + }, + { + name: "logger.recordContext()", + description: "Record metadata without creating log entries", + outputs: ["WideEvent.context", "Span Attributes"], + isNew: true, + note: "Enriches context without cluttering logs array", + }, + ], + }, + { + id: "custom", + name: "Custom API", + badge: "Advanced", + description: "Custom spans, metrics, and scoping", + useCases: [ + "Custom trace spans", + "Business metrics", + "Performance histograms", + "Nested scopes", + ], + methods: [ + { + name: "logger.span()", + description: "Create auto-managed traced spans", + outputs: ["OTEL Traces", "Auto status/end"], + }, + { + name: "logger.counter()", + description: "Create scoped counter metrics", + outputs: ["OTEL Metrics"], + }, + { + name: "logger.histogram()", + description: "Create scoped histogram metrics", + outputs: ["OTEL Metrics"], + }, + { + name: "logger.child()", + description: "Create child logger with nested scope", + outputs: ["Scoped Logger"], + }, + { + name: "logger.getEvent()", + description: "Access WideEvent for advanced use", + outputs: ["WideEvent Access"], + }, + ], + }, + { + id: "escape", + name: "Escape Hatch", + badge: "Expert", + description: "Direct OTEL access for advanced features", + useCases: [ + "Observable gauges (active connections)", + "Custom tracer names", + "SpanKind customization", + "Manual span linking", + ], + methods: [ + { + name: "otel.getTracer()", + description: "Raw OTEL tracer for full span control", + outputs: ["Custom Tracers"], + }, + { + name: "otel.getMeter()", + description: "Raw OTEL meter for gauges & observables", + outputs: ["Observable Instruments"], + }, + { + name: "otel.getLogger()", + description: "Raw OTEL logger (rarely needed)", + outputs: ["OTEL Logs"], + }, + ], + }, +]; + +function CodeSnippet({ + code, + language = "typescript", +}: { + code: string; + language?: string; +}) { + const [isVisible, setIsVisible] = useState(false); + const [html, setHtml] = useState(""); + + useEffect(() => { + if (isVisible && !html) { + codeToHtml(code, { + lang: language, + theme: "dark-plus", + }).then(setHtml); + } + }, [isVisible, code, language, html]); + + return ( +
+ + {isVisible && html && ( +
+ )} +
+ ); +} + +function FlowDiagram({ outputs }: { outputs: string[] }) { + return ( +
+ {outputs.map((output, idx) => ( +
+ {idx > 0 && } + + {output} + +
+ ))} +
+ ); +} + function TelemetryRoute() { const [loading, setLoading] = useState(null); const [results, setResults] = useState>({}); + const [activeTab, setActiveTab] = useState("overview"); const runExample = async ( name: string, @@ -52,7 +246,7 @@ function TelemetryRoute() { method === "POST" ? { "Content-Type": "application/json" } : {}, body: method === "POST" - ? JSON.stringify({ items: [1, 2, 3, 4, 5] }) + ? JSON.stringify({ userId: "demo-user" }) : undefined, }); @@ -82,200 +276,980 @@ function TelemetryRoute() { } }; - const examples = [ - { - id: "combined", - title: "Custom plugin example", - description: ( - <> -

- Demonstrates SDK auto-instrumentation for HTTP requests and caching, - combined with custom tracing, metrics, and structured logging. -

-

Run twice to see cache behavior in action.

-

Observe results in Grafana.

- - ), - endpoint: "/api/telemetry-examples/combined", - method: "POST", - icon: Activity, - }, - ]; - return (
-
-

- Telemetry Demo -

-

- Demonstrates how the SDK's auto-instrumentation integrates with - custom application telemetry. This example showcases HTTP and cache - instrumentation from the SDK, alongside custom tracing, metrics, and - structured logs. -

-
- - -

- View Traces, Metrics & Logs in Grafana -

-

- Ensure telemetry is enabled and the grafana/otel-lgtm{" "} - container is running: -

- - docker run -p 3000:3000 -p 4317:4317 -p 4318:4318 --rm -ti - grafana/otel-lgtm - -

- Access Grafana at{" "} - - http://localhost:3000 - {" "} - to view traces, metrics, and logs (use Explore with Tempo for - traces, Prometheus for metrics, and Loki for logs). -

- +
- {examples.map((example) => { - const result = results[example.id]; - const isLoading = loading === example.id; - const Icon = example.icon; + + + Overview + Opinionated API + Custom + Escape Hatch + - return ( - -

{example.title}

+ {/* Overview Tab */} + + {/* Layer Comparison Cards */} +
+ {LAYER_CONFIGS.map((layer) => { + return ( + setActiveTab(layer.id)} + > + +
+ {layer.badge} +
+ {layer.name} + {layer.description} + + +
+

+ Use Cases: +

+
    + {layer.useCases.map((useCase) => ( +
  • + • {useCase} +
    • + ))} +
+
+ + + + ); + })} +
-
-
-
- -
-
-
- {example.description} -
-
+ {/* Setup Instructions */} + + + + + Setup: View Telemetry in Grafana + + + +

+ To see traces, metrics, and logs, run the Grafana OTEL LGTM + stack: +

+ + docker run -p 3000:3000 -p 4317:4317 -p 4318:4318 --rm -ti + grafana/otel-lgtm + +
+ Access Grafana at{" "} + + http://localhost:3000 + {" "} + (Explore → Tempo for traces, Prometheus for metrics, Loki for + logs)
+ + -
- - curl -X POST - http://localhost:8000/api/telemetry-examples/combined \ - {"\n"} - {" "}-H "Content-Type: application/json" \{"\n"} - {" "}-d '{"{"}"userId":"test-user"{"}"}' - - - + {/* Live Demo */} + + + Live Example + + Demonstrates all three layers working together. Run twice to + see cache behavior. + + + +
+

+ What this example does: +

+
    +
  • + • Uses{" "} + + logger.info() + {" "} + for automatic observability +
    • +
  • + • Creates custom spans with{" "} + + logger.span() + +
    • +
  • + • Uses raw OTEL for observable gauges (escape hatch) +
    • +
-
- {result && ( -
+ runExample( + "combined", + "/api/telemetry-examples/combined", + "POST", + ) + } + disabled={loading === "combined"} + className="w-full" + size="lg" > -
-
- {result.error ? "Error" : "Success"}:{" "} + {loading === "combined" ? ( + <> + + Running Example... + + ) : ( + <> + + Run Combined Example + + )} + + + {results.combined && ( +
+
+
+ {results.combined.error ? "Error" : "Success"} +
+ + {results.combined.duration_ms && ( +
+ Duration: {results.combined.duration_ms}ms +
+ )} + + {results.combined.tracing && ( +
+
+ Tracing +
+ {results.combined.tracing.expectedSpans && ( +
+ {results.combined.tracing.expectedSpans.join( + "\n", + )} +
+ )} +
+ )} + + {results.combined.metrics && ( +
+
+ Metrics +
+ {results.combined.metrics.recorded && ( +
    + {results.combined.metrics.recorded.map((m) => ( +
  • + • {m} +
    • + ))} +
+ )} +
+ )} + + {results.combined.logs && ( +
+
+ Logs +
+ {results.combined.logs.emitted && ( +
    + {results.combined.logs.emitted.map((m) => ( +
  • + • {m} +
    • + ))} +
+ )} +
+ )}
+
+ )} + + + - {result.duration_ms && ( -
- Duration: {result.duration_ms}ms + {/* Opinionated API Tab */} + + {(() => { + const layer = LAYER_CONFIGS[0]; + return ( + <> + + +
+
+ {layer.name} + {layer.description} +
+ {layer.badge}
- )} + + - {result.tracing && ( -
-
- Tracing +
+ {layer.methods.map((method) => ( + + +
+ + {method.name} + + {"isNew" in method && method.isNew && ( + NEW + )} +
+ + {method.description} + + + +
+

+ Output Flow: +

+ + {"note" in method && method.note && ( +
+ {method.note} +
+ )} +
+ + + ))} +
+ + {/* WideEvent Explanation */} + + + Understanding WideEvent Aggregation + + +
+

+ How Logs Flow: +

+
+
+
+ 1 +
+
+ + During Request: + {" "} + Each{" "} + + logger.info() + {" "} + accumulates in{" "} + + WideEvent.logs[] + {" "} + (in memory) +
+
+
+
+ 2 +
+
+ + At Request End: + {" "} + Entire WideEvent sent as{" "} + ONE OTEL + log record +
+
+
+
+ 3 +
+
+ In Loki:{" "} + Query for request_id → see the full WideEvent JSON + with all logs inside +
+
- {result.tracing.services && ( -
- Services:{" "} - {result.tracing.services.length} +
+ +
+

+ Why This Design? +

+
    +
  • + • Request correlation: All logs + from one request stay together +
    • +
  • + • Efficient: One network call per + request (not per log) +
    • +
  • + • Rich metadata: WideEvent includes + execution, errors, duration, user context +
    • +
  • + • Production debugging: "Show me + everything for request abc123" +
    • +
+
+ +
+

+ The Three Destinations +

+
+
+ 1. Terminal: Individual logs for + local debugging (DEBUG=appkit:*)
- )} - {result.tracing.expectedSpans && ( -
- {result.tracing.expectedSpans.join("\n")} +
+ 2. Span Events (Tempo): Individual + events attached to trace timeline
- )} +
+ 3. WideEvent → OTEL Logs (Loki):{" "} + ONE aggregated record per request +
+
+ Exception:{" "} + + logger.trace() + {" "} + sends individual OTEL log records (not aggregated) +
+
+
+ + + + {/* Code Examples */} + + + Code Examples + + +
+

+ Basic Logging (Most Common) +

+

+ Just call logger methods - logs accumulate in + WideEvent: +

+ +
+ +
+

+ NEW: Verbose Debugging (logger.trace) +

+

+ Unlike debug(), trace() sends individual OTEL log + records (not aggregated): +

+ +
+ +
+

+ NEW: Record Context Without Logs +

+

+ Enrich traces with metadata without cluttering logs: +

+ +
+ +
+

+ NEW: Expected Errors (Don't Fail Span) +

+

+ Log errors with graceful fallbacks without marking + span as failed: +

+
- )} - {result.metrics && ( -
-
- Metrics +
+

+ What WideEvent Looks Like in OTEL Logs +

+

+ In Loki/OTEL backend, you see ONE record per request: +

+ +
+ + + + ); + })()} + + + {/* Custom API Tab */} + + {(() => { + const layer = LAYER_CONFIGS[1]; + return ( + <> + + +
+
+ {layer.name} + {layer.description}
- {result.metrics.recorded && ( -
- Recorded: -
    - {result.metrics.recorded.map((m) => ( -
  • • {m}
    • - ))} -
+ {layer.badge} +
+ + + +
+ {layer.methods.map((method) => ( + + + + {method.name} + + + {method.description} + + + +
+

+ Provides: +

+
- )} + + + ))} +
+ + {/* Code Examples */} + + + Code Examples + + +
+

+ Custom Traced Spans +

+

+ Create spans that are automatically managed (no need + to call span.end()): +

+ { + span.setAttribute("db.system", "databricks"); + span.setAttribute("user.id", userId); + + const data = await fetchFromDB(userId); + + span.addEvent("data_fetched", { + records: data.length + }); + + return data; + // ✅ Span automatically ends with OK status + // ✅ If error thrown, span ends with ERROR status +});`} + /> +
+ +
+

Business Metrics

+

+ Track counters and histograms scoped to your plugin: +

+
- )} - {result.logs && ( -
-
- Logs +
+

+ Nested Logger Scopes +

+

+ Create child loggers for better log organization: +

+ +
+ +
+

+ Access WideEvent (Advanced) +

+

+ Get direct access to WideEvent for advanced use cases: +

+ +
+ + + + ); + })()} + + + {/* Escape Hatch Tab */} + + {(() => { + const layer = LAYER_CONFIGS[2]; + return ( + <> + + +
+
+ {layer.name} + {layer.description}
- {result.logs.emitted && ( -
- Emitted: -
    - {result.logs.emitted.map((m) => ( -
  • • {m}
    • - ))} -
+ {layer.badge} +
+ + + + + + When to Use the Escape Hatch + + +

+ Use the escape hatch when you need OTEL features not + available in Opinionated or Custom APIs: +

+
    + {layer.useCases.map((useCase) => ( +
  • • {useCase}
    • + ))} +
+

+ Note: The Custom API is sufficient for most use cases. +

+ + + +
+ {layer.methods.map((method) => ( + + + + {method.name} + + + {method.description} + + + +
+

+ Provides: +

+
- )} + + + ))} +
+ + {/* Code Examples */} + + + Code Examples + + +
+

+ Custom Tracer Names +

+

+ When you need tracer names not scoped to your plugin: +

+ { + span.setAttribute("custom.attribute", "value"); + span.setStatus({ code: SpanStatusCode.OK }); + + // You must manually end the span + span.end(); +});`} + />
- )} + +
+

+ Observable Gauges +

+

+ For metrics that need callbacks (not available in + logger.counter/histogram): +

+ { + // Read from your connection pool + const count = connectionPool.getActiveCount(); + result.observe(count); +});`} + /> +
+ +
+

+ SpanKind Customization +

+

+ Set specific span kinds (CLIENT, SERVER, PRODUCER, + CONSUMER): +

+ { + await fetch("https://api.example.com"); + span.end(); + } +);`} + /> +
+ +
+

Combining Layers

+

+ You can use escape hatch alongside Opinionated API: +

+ { + // Use escape hatch for span control + span.setAttribute("custom.id", "123"); + + // Still use Opinionated API inside! + this.logger.info("Processing inside custom span", { + spanId: span.spanContext().spanId + }); + + // Use Opinionated API for metrics + this.requestCounter.add(1); + + span.end(); +});`} + /> +
+ + + + {/* Demo Button */} + + + Try Escape Hatch Example + + This example uses raw OTEL APIs to create observable + gauges + + + + + + {results.escape && ( +
+ 
+                            {JSON.stringify(results.escape, null, 2)}
+
+
+ )} + + + + ); + })()} + + + + {/* Decision Tree */} + + + Which Layer Should I Use? + + +
+
+
+
+ Start with Opinionated API +
+
+ Use logger.info(), logger.warn(), logger.error() for most + logging needs. It automatically flows everywhere.
- )} - - ); - })} +
+ +
+
+
+ Use Custom API when you need: +
+
+ Custom spans (logger.span), business metrics + (logger.counter/histogram), or nested scopes (logger.child). +
+
+
+ +
+
+
+ Use Escape Hatch only when you need: +
+
+ Observable gauges, custom tracer names, SpanKind + customization, or other advanced OTEL features not in other + layers. +
+
+
+
+ +
); diff --git a/apps/dev-playground/server/telemetry-example-plugin.ts b/apps/dev-playground/server/telemetry-example-plugin.ts index a3d7eb5a..20e4f560 100644 --- a/apps/dev-playground/server/telemetry-example-plugin.ts +++ b/apps/dev-playground/server/telemetry-example-plugin.ts @@ -1,17 +1,42 @@ /** - * Minimal plugin to register telemetry example routes + * Telemetry Example Plugin + * + * Demonstrates the THREE LAYERS of observability in AppKit: + * + * LAYER 1: Opinionated API (99% of cases) - Automatic observability + * - logger.debug() - Terminal only (DEBUG=appkit:*) + * - logger.trace() - Terminal + OTEL + WideEvent (NEW!) + * - logger.info() - Terminal + WideEvent + Span + OTEL + * - logger.warn() - Terminal + WideEvent + Span + OTEL + * - logger.error() - Terminal + WideEvent + Span + OTEL + Exception + * - logger.recordContext() - WideEvent + Span attributes only (NEW!) + * + * LAYER 2: Custom API (when you need control) + * - logger.span() - Create auto-managed traced spans + * - logger.counter() - Create scoped counter metrics + * - logger.histogram() - Create scoped histogram metrics + * - logger.child() - Create child logger with nested scope + * - logger.getEvent() - Access WideEvent for advanced use + * + * LAYER 3: Raw (full OTEL power) + * - otel.getTracer() - Raw OTEL tracer (see registerAdvancedOtelRoutes) + * - otel.getMeter() - Raw OTEL meter (gauges, observables) + * - otel.getLogger() - Raw OTEL logger (rarely needed) + * + * Routes: + * - POST /api/telemetry-examples/combined - Shows all three layers + * - POST /api/telemetry-examples/advanced-otel - Shows raw OTEL usage */ import { - Plugin, - toPlugin, type BasePluginConfig, CacheManager, - SpanStatusCode, - type Span, type Counter, type Histogram, - SeverityNumber, + otel, + Plugin, + type Span, + toPlugin, } from "@databricks/appkit"; import type { Request, Response, Router } from "express"; @@ -24,13 +49,13 @@ class TelemetryExamples extends Plugin { constructor(config: BasePluginConfig) { super(config); - this.cache = new CacheManager({ enabled: true, ttl: 60 }, this.telemetry); + this.cache = CacheManager.getInstanceSync(); - const meter = this.telemetry.getMeter({ name: "custom-telemetry-example" }); - this.requestCounter = meter.createCounter("app.requests.total", { + // Use the custom logger API for metrics + this.requestCounter = this.logger.counter("requests.total", { description: "Total number of requests", }); - this.durationHistogram = meter.createHistogram("app.request.duration", { + this.durationHistogram = this.logger.histogram("request.duration", { description: "Request duration in ms", unit: "ms", }); @@ -38,6 +63,7 @@ class TelemetryExamples extends Plugin { injectRoutes(router: Router): void { this.registerTelemetryExampleRoutes(router as any); + this.registerAdvancedOtelRoutes(router as any); } private registerTelemetryExampleRoutes(router: Router) { @@ -48,468 +74,440 @@ class TelemetryExamples extends Plugin { handler: async (req: Request, res: Response) => { const startTime = Date.now(); - return this.telemetry.startActiveSpan( - "combined-example", - { - attributes: { - "example.type": "combined", - "example.version": "v2", - }, - }, - async (span: Span) => { - try { - const userId = - req.body?.userId || req.query.userId || "demo-user-123"; - - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "Processing telemetry example request", - attributes: { - "user.id": userId, - "request.type": "combined-example", - }, - }); - - const result = await this.complexOperation(userId); - - const duration = Date.now() - startTime; - this.requestCounter.add(1, { status: "success" }); - this.durationHistogram.record(duration); - - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "Request completed successfully", - attributes: { - "user.id": userId, - "duration.ms": duration, - "result.fields": Object.keys(result).length, - }, - }); - - span.setStatus({ code: SpanStatusCode.OK }); - - res.json({ - success: true, - result, - duration_ms: duration, - tracing: { - hint: "Open Grafana at http://localhost:3000", - services: [ - "app-template (main service)", - "user-operations (complex operation)", - "auth-validation (user validation)", - "data-access (database operations - with cache!)", - "auth-service (permissions)", - "external-api (external HTTP calls)", - "data-processing (transformation)", - ], - expectedSpans: [ - "HTTP POST (SDK auto-instrumentation)", - "combined-example (custom tracer: custom-telemetry-example)", - " └─ complex-operation (custom tracer: user-operations)", - " ├─ validate-user (100ms, custom tracer: auth-validation)", - " ├─ fetch-user-data (200ms first call / cached on repeat, custom tracer: data-access) [parallel]", - " │ └─ cache.hit attribute set by SDK (false on first call, true on repeat)", - " ├─ fetch-external-resource (custom tracer: external-api) [parallel]", - " │ └─ HTTP GET https://example.com (SDK auto-instrumentation)", - " ├─ fetch-permissions (150ms, custom tracer: auth-service) [parallel]", - " └─ transform-data (80ms, custom tracer: data-processing)", - ], - }, - metrics: { - recorded: ["app.requests.total", "app.request.duration"], - }, - logs: { - emitted: [ - "Starting complex operation workflow", - "Data fetching completed successfully", - "Data transformation completed", - "Permissions retrieved", - "External API call completed", - ], - }, - }); - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - this.requestCounter.add(1, { status: "error" }); - - this.telemetry.emit({ - severityNumber: SeverityNumber.ERROR, - severityText: "ERROR", - body: error instanceof Error ? error.message : "Unknown error", - attributes: { - "error.type": error instanceof Error ? error.name : "Unknown", - "error.stack": - error instanceof Error ? error.stack : undefined, - "request.path": req.path, - }, - }); - - res.status(500).json({ - error: true, - message: - error instanceof Error ? error.message : "Unknown error", - }); - } finally { - span.end(); - } - }, - { name: "custom-telemetry-example" }, - ); - }, - }); - } + return this.logger.span("combined-example", async (span: Span) => { + span.setAttribute("example.type", "combined"); + span.setAttribute("example.version", "v2"); + try { + const userId = + req.body?.userId || req.query.userId || "demo-user-123"; - private async complexOperation(userId: string) { - return this.telemetry.startActiveSpan( - "complex-operation", - { - attributes: { - "user.id": userId, - "operation.type": "user-data-flow", - }, - }, - async (parentSpan: Span) => { - try { - this.telemetry.emit({ - severityNumber: SeverityNumber.DEBUG, - severityText: "DEBUG", - body: "Starting complex operation workflow", - attributes: { + this.logger.info("Processing telemetry example request", { "user.id": userId, - "workflow.step": "start", - }, - }); + "request.type": "combined-example", + }); - await this.validateUser(); + const result = await this.complexOperation(userId); - const [userData, externalData, permissionsData] = await Promise.all([ - this.fetchUserData(userId), - this.fetchExternalResource(), - this.fetchPermissions(), - ]); + const duration = Date.now() - startTime; + this.requestCounter.add(1, { status: "success" }); + this.durationHistogram.record(duration); - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "Data fetching completed successfully", - attributes: { + this.logger.info("Request completed successfully", { "user.id": userId, - "data.sources": 3, - "workflow.step": "data-fetched", - }, - }); - - await this.transformData(); - - parentSpan.setStatus({ code: SpanStatusCode.OK }); - - return { - ...userData, - external: externalData, - permissions: permissionsData, - }; - } catch (error) { - parentSpan.recordException(error as Error); - parentSpan.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { - parentSpan.end(); - } + "duration.ms": duration, + "result.fields": Object.keys(result as object).length, + }); + + res.json({ + success: true, + result, + duration_ms: duration, + tracing: { + hint: "Open Grafana at http://localhost:3000", + services: [ + "app-template (main service)", + "user-operations (complex operation)", + "auth-validation (user validation)", + "data-access (database operations - with cache!)", + "auth-service (permissions)", + "external-api (external HTTP calls)", + "data-processing (transformation)", + ], + expectedSpans: [ + "HTTP POST (SDK auto-instrumentation)", + "combined-example (custom tracer: custom-telemetry-example)", + " └─ complex-operation (custom tracer: user-operations)", + " ├─ validate-user (100ms, custom tracer: auth-validation)", + " ├─ fetch-user-data (200ms first call / cached on repeat, custom tracer: data-access) [parallel]", + " │ └─ cache.hit attribute set by SDK (false on first call, true on repeat)", + " ├─ fetch-external-resource (custom tracer: external-api) [parallel]", + " │ └─ HTTP GET https://example.com (SDK auto-instrumentation)", + " ├─ fetch-permissions (150ms, custom tracer: auth-service) [parallel]", + " └─ transform-data (80ms, custom tracer: data-processing)", + ], + }, + metrics: { + recorded: ["app.requests.total", "app.request.duration"], + }, + logs: { + emitted: [ + "Starting complex operation workflow (via logger.trace)", + "Data fetching completed successfully", + "Data transformation completed", + "Permissions retrieved", + "External API call completed", + ], + }, + features: { + "NEW: logger.trace()": + "Verbose debug logs sent to OTEL + WideEvent (not just terminal)", + "NEW: logger.recordContext()": + "Record metadata without creating log entries", + "NEW: logger.error({ recordOnSpan: false })": + "Log errors without failing the span (for expected errors)", + "logger.span()": + "Auto-managed spans (no need for span.end(), span.setStatus())", + "logger.info/warn/error()": + "Automatic flow to Terminal + WideEvent + Span + OTEL", + }, + }); + } catch (error) { + this.requestCounter.add(1, { status: "error" }); + + this.logger.error("Request failed", error as Error, { + "error.type": error instanceof Error ? error.name : "Unknown", + "error.stack": error instanceof Error ? error.stack : undefined, + "request.path": req.path, + }); + + res.status(500).json({ + error: true, + message: error instanceof Error ? error.message : "Unknown error", + }); + } + }); }, - { name: "user-operations" }, - ); + }); + } + + private async complexOperation(userId: string) { + return this.logger.span("complex-operation", async (parentSpan: Span) => { + parentSpan.setAttribute("user.id", userId); + parentSpan.setAttribute("operation.type", "user-data-flow"); + + // EXAMPLE: logger.trace() - verbose debugging that goes to OTEL + WideEvent + this.logger.trace("Starting complex operation workflow", { + "user.id": userId, + "workflow.step": "start", + "workflow.timestamp": new Date().toISOString(), + }); + + // EXAMPLE: logger.recordContext() - metadata without log entry + this.logger.recordContext({ + "operation.id": crypto.randomUUID(), + "operation.type": "user-data-flow", + "user.id": userId, + }); + + await this.validateUser(); + + const [userData, externalData, permissionsData] = await Promise.all([ + this.fetchUserData(userId), + this.fetchExternalResource(), + this.fetchPermissions(), + ]); + + this.logger.info("Data fetching completed successfully", { + "user.id": userId, + "data.sources": 3, + "workflow.step": "data-fetched", + }); + + await this.transformData(); + + return { + ...userData, + external: externalData, + permissions: permissionsData, + }; + }); } private async validateUser() { - return this.telemetry.startActiveSpan( - "validate-user", - { - attributes: { - "validation.type": "user", - "validation.method": "token", - }, - }, - async (span: Span) => { - try { - this.telemetry.emit({ - severityNumber: SeverityNumber.DEBUG, - severityText: "DEBUG", - body: "Validating user credentials", - attributes: { - "validation.method": "token", - }, - }); + return this.logger.span("validate-user", async (span: Span) => { + span.setAttribute("validation.type", "user"); + span.setAttribute("validation.method", "token"); - await new Promise((resolve) => setTimeout(resolve, 100)); + this.logger.debug("Validating user credentials", { + "validation.method": "token", + }); - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "User validation successful", - attributes: { - "validation.duration_ms": 100, - }, - }); - - span.setStatus({ code: SpanStatusCode.OK }); - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { - span.end(); - } - }, - { name: "auth-validation" }, - ); + await new Promise((resolve) => setTimeout(resolve, 100)); + + this.logger.info("User validation successful", { + "validation.duration_ms": 100, + }); + }); } private async fetchUserData(userId: string) { - return this.telemetry.startActiveSpan( - "fetch-user-data", - { + return this.logger.span("fetch-user-data", async (span: Span) => { + span.setAttribute("data.source", "database"); + span.setAttribute("db.system", "databricks"); + span.setAttribute("db.operation", "SELECT"); + this.logger.debug("Fetching user data from database", { + "user.id": userId, + "cache.enabled": true, attributes: { - "data.source": "database", - "db.system": "databricks", - "db.operation": "SELECT", + "user.id": userId, + "cache.enabled": true, }, - }, - async (span: Span) => { - try { - this.telemetry.emit({ - severityNumber: SeverityNumber.DEBUG, - severityText: "DEBUG", - body: "Fetching user data from database", - attributes: { + }); + + const result = await this.cache.getOrExecute( + ["user-data", userId], + async () => { + this.logger.warn( + "Cache miss - fetching from database (slow operation)", + { "user.id": userId, - "cache.enabled": true, + "operation.expected_duration_ms": 2000, }, - }); - - const result = await this.cache.getOrExecute( - ["user-data", userId], - async () => { - this.telemetry.emit({ - severityNumber: SeverityNumber.WARN, - severityText: "WARN", - body: "Cache miss - fetching from database (slow operation)", - attributes: { - "user.id": userId, - "operation.expected_duration_ms": 2000, - }, - }); - - await new Promise((resolve) => setTimeout(resolve, 2000)); - return { - userId, - data: "sample user data", - preferences: { theme: "dark", language: "en" }, - lastLogin: new Date().toISOString(), - }; - }, - "", - { ttl: 60 }, // 60 seconds TTL ); - span.setAttribute("data.size_bytes", JSON.stringify(result).length); - span.setStatus({ code: SpanStatusCode.OK }); + await new Promise((resolve) => setTimeout(resolve, 2000)); + return { + userId, + data: "sample user data", + preferences: { theme: "dark", language: "en" }, + lastLogin: new Date().toISOString(), + }; + }, + "", + { ttl: 60 }, // 60 seconds TTL + ); + + span.setAttribute("data.size_bytes", JSON.stringify(result).length); + this.logger.info("User data retrieved successfully", { + "user.id": userId, + "data.size_bytes": JSON.stringify(result).length, + }); - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "User data retrieved successfully", - attributes: { - "user.id": userId, - "data.size_bytes": JSON.stringify(result).length, - }, - }); - - return result; - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { - span.end(); - } - }, - { name: "data-access" }, - ); + return result; + }); } private async fetchExternalResource() { - return this.telemetry.startActiveSpan( - "fetch-external-resource", - { - attributes: { - "http.target": "example.com", - "external.api.purpose": "demo", - }, - }, - async (span: Span) => { - try { - this.telemetry.emit({ - severityNumber: SeverityNumber.DEBUG, - severityText: "DEBUG", - body: "Calling external API", - attributes: { - "http.url": "https://example.com", - "http.method": "GET", - }, - }); - - const response = await fetch("https://example.com"); - const text = await response.text(); - - span.setAttribute("http.status_code", response.status); - span.setAttribute("http.response.size_bytes", text.length); - span.addEvent("external_fetch_completed", { - "response.status": response.status, - }); - span.setStatus({ code: SpanStatusCode.OK }); - - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "External API call completed", - attributes: { - "http.url": "https://example.com", - "http.status_code": response.status, - "http.response.size_bytes": text.length, - }, - }); - - return { status: response.status, size: text.length }; - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - - this.telemetry.emit({ - severityNumber: SeverityNumber.ERROR, - severityText: "ERROR", - body: "External API call failed", - attributes: { - "http.url": "https://example.com", - "error.message": - error instanceof Error ? error.message : "Unknown error", - }, - }); + return this.logger.span("fetch-external-resource", async (span: Span) => { + span.setAttribute("http.target", "example.com"); + span.setAttribute("external.api.purpose", "demo"); + + try { + this.logger.debug("Calling external API", { + "http.url": "https://example.com", + "http.method": "GET", + }); + + const response = await fetch("https://example.com"); + const text = await response.text(); + + span.setAttribute("http.status_code", response.status); + span.setAttribute("http.response.size_bytes", text.length); + span.addEvent("external_fetch_completed", { + "response.status": response.status, + }); + + this.logger.info("External API call completed", { + "http.url": "https://example.com", + "http.status_code": response.status, + "http.response.size_bytes": text.length, + }); + + return { status: response.status, size: text.length }; + } catch (error) { + // EXAMPLE: logger.error() with recordOnSpan: false + // This is an expected/graceful error - we return a fallback value + // So we don't want to mark the span as failed + this.logger.error( + "External API call failed (graceful fallback)", + error as Error, + { + "http.url": "https://example.com", + "error.message": + error instanceof Error ? error.message : "Unknown error", + "fallback.returned": true, + }, + { recordOnSpan: false }, // Don't fail the parent span + ); - return { status: 0, size: 0, error: "fetch failed" }; - } finally { - span.end(); - } - }, - { name: "external-api" }, - ); + return { status: 0, size: 0, error: "fetch failed" }; + } + }); } private async fetchPermissions() { - return this.telemetry.startActiveSpan( - "fetch-permissions", - { - attributes: { - "permissions.scope": "user", - "permissions.type": "rbac", - }, - }, - async (span: Span) => { - try { - this.telemetry.emit({ - severityNumber: SeverityNumber.DEBUG, - severityText: "DEBUG", - body: "Fetching user permissions", - attributes: { - "permissions.type": "rbac", - }, - }); + return this.logger.span("fetch-permissions", async (span: Span) => { + span.setAttribute("permissions.scope", "user"); + span.setAttribute("permissions.type", "rbac"); - await new Promise((resolve) => setTimeout(resolve, 150)); + this.logger.debug("Fetching user permissions", { + "permissions.type": "rbac", + }); - const permissions = { - canRead: true, - canWrite: false, - canDelete: false, - }; + await new Promise((resolve) => setTimeout(resolve, 150)); - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "Permissions retrieved", - attributes: { - "permissions.canRead": permissions.canRead, - "permissions.canWrite": permissions.canWrite, - "permissions.canDelete": permissions.canDelete, - }, - }); - - span.setStatus({ code: SpanStatusCode.OK }); - return permissions; - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { - span.end(); - } - }, - { name: "auth-service" }, - ); + const permissions = { + canRead: true, + canWrite: false, + canDelete: false, + }; + + this.logger.info("Permissions retrieved", { + "permissions.canRead": permissions.canRead, + "permissions.canWrite": permissions.canWrite, + "permissions.canDelete": permissions.canDelete, + }); + + return permissions; + }); } private async transformData() { - return this.telemetry.startActiveSpan( - "transform-data", - { - attributes: { - "transform.type": "enrichment", - "transform.steps": "normalize,enrich,validate", - "external.data.included": true, - }, - }, - async (span: Span) => { - try { - this.telemetry.emit({ - severityNumber: SeverityNumber.DEBUG, - severityText: "DEBUG", - body: "Starting data transformation pipeline", - attributes: { - "transform.steps": ["normalize", "enrich", "validate"], + return this.logger.span("transform-data", async (span: Span) => { + span.setAttribute("transform.type", "enrichment"); + span.setAttribute("transform.steps", "normalize,enrich,validate"); + span.setAttribute("external.data.included", true); + + this.logger.debug("Starting data transformation pipeline", { + "transform.steps": ["normalize", "enrich", "validate"], + }); + + await new Promise((resolve) => setTimeout(resolve, 80)); + + span.addEvent("transformation_completed", { + "output.fields": 5, + "processing.success": true, + }); + + this.logger.info("Data transformation completed", { + "transform.duration_ms": 80, + "output.fields": 5, + }); + }); + } + + /** + * ADVANCED: Direct OTEL escape hatch for power users + * + * Use this when you need: + * - Custom tracer names not scoped to the plugin + * - Raw OTEL Meter for gauges, observable instruments + * - Direct access to OTEL APIs for special use cases + * + * For most use cases, prefer the custom logger API: + * - this.logger.span() instead of otel.getTracer() + * - this.logger.counter() instead of otel.getMeter().createCounter() + */ + private registerAdvancedOtelRoutes(router: Router) { + this.route(router, { + name: "advanced-otel", + method: "post", + path: "/advanced-otel", + handler: async (_req: Request, res: Response) => { + // ADVANCED: Get raw OTEL tracer for custom instrumentation + const customTracer = otel.getTracer("custom-advanced-tracer"); + + // ADVANCED: Get raw OTEL meter for gauges and observable instruments + const customMeter = otel.getMeter("custom-advanced-meter"); + + // Create an observable gauge (not available via logger API) + const activeConnections = customMeter.createObservableGauge( + "app.connections.active", + { + description: "Number of active connections", + unit: "connections", + }, + ); + + // Observable instruments need a callback + activeConnections.addCallback((result: any) => { + // In real code, this would read from your connection pool + result.observe(Math.floor(Math.random() * 100)); + }); + + // Create a span using raw tracer + await customTracer.startActiveSpan( + "advanced-custom-operation", + async (span: Span) => { + span.setAttribute("advanced.example", true); + span.setAttribute("custom.tracer.name", "custom-advanced-tracer"); + + // You can still use the opinionated logger inside raw spans + this.logger.info("Inside raw OTEL span", { + "span.kind": "custom", + }); + + await new Promise((resolve) => setTimeout(resolve, 50)); + + span.end(); + }, + ); + + res.json({ + success: true, + message: "Advanced OTEL example completed", + layers: { + "LAYER 1: Opinionated API (99% of use cases)": { + description: + "Automatic observability - just log and it flows everywhere", + methods: [ + "logger.debug() - Terminal only (DEBUG=appkit:*)", + "logger.trace() - Terminal + OTEL + WideEvent [NEW!]", + "logger.info() - Terminal + WideEvent + Span + OTEL", + "logger.warn() - Terminal + WideEvent + Span + OTEL", + "logger.error() - Terminal + WideEvent + Span + OTEL + Exception", + "logger.recordContext() - WideEvent + Span attributes only [NEW!]", + ], + }, + "LAYER 2: Custom API (when you need control)": { + description: "Custom spans, metrics, and scoping", + methods: [ + "logger.span() - Auto-managed traced spans", + "logger.counter() - Scoped counter metrics", + "logger.histogram() - Scoped histogram metrics", + "logger.child() - Nested logger scopes", + "logger.getEvent() - Access WideEvent for advanced use", + ], }, - }); - - await new Promise((resolve) => setTimeout(resolve, 80)); - - span.addEvent("transformation_completed", { - "output.fields": 5, - "processing.success": true, - }); - - this.telemetry.emit({ - severityNumber: SeverityNumber.INFO, - severityText: "INFO", - body: "Data transformation completed", - attributes: { - "transform.duration_ms": 80, - "output.fields": 5, + "LAYER 3: Raw (full OTEL power)": { + description: "Use when you need features not in Layer 1 or 2", + methods: [ + "otel.getTracer() - Custom tracer names, full span control", + "otel.getMeter() - Gauges, observable instruments", + "otel.getLogger() - Raw OTEL logger (rarely needed)", + ], + whenToUse: [ + "Observable gauges (like active connection count)", + "Custom tracer names not scoped to plugin", + "SpanKind customization (CLIENT, SERVER, etc.)", + "Manual span linking across services", + ], }, - }); - - span.setStatus({ code: SpanStatusCode.OK }); - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { - span.end(); - } + }, + recommendation: + "Start with LAYER 1 (Opinionated API). Use LAYER 2 for custom spans. " + + "Only use LAYER 3 (Raw) when you need features not available in layers 1-2.", + newFeatures: { + "logger.trace()": { + description: + "Verbose debugging that goes to OTEL (unlike debug which is terminal-only)", + useCases: [ + "Production debugging with detailed context", + "Tracing request flow through multiple services", + "Recording intermediate state for troubleshooting", + ], + }, + "logger.recordContext()": { + description: + "Record metadata to WideEvent and Span without creating log entries", + useCases: [ + "Enriching request context with IDs (operation ID, correlation ID)", + "Recording computed values (cache key, query hash)", + "Adding metadata that doesn't need to appear in logs", + ], + }, + "logger.error({ recordOnSpan: false })": { + description: "Log errors without marking the span as failed", + useCases: [ + "Expected errors with graceful fallbacks (like failed external API)", + "Validation errors that are handled", + "Cache misses or other recoverable errors", + ], + }, + }, + }); }, - { name: "data-processing" }, - ); + }); } } diff --git a/packages/appkit/package.json b/packages/appkit/package.json index 9cb701d6..dfb8cbcc 100644 --- a/packages/appkit/package.json +++ b/packages/appkit/package.json @@ -60,6 +60,7 @@ "@types/semver": "^7.7.1", "dotenv": "^16.6.1", "express": "^4.22.0", + "obug": "^2.1.1", "pg": "^8.16.3", "semver": "^7.7.3", "shared": "workspace:*", diff --git a/packages/appkit/src/analytics/analytics.ts b/packages/appkit/src/analytics/analytics.ts index 5d960687..47bce059 100644 --- a/packages/appkit/src/analytics/analytics.ts +++ b/packages/appkit/src/analytics/analytics.ts @@ -39,7 +39,7 @@ export class AnalyticsPlugin extends Plugin { this.SQLClient = new SQLWarehouseConnector({ timeout: config.timeout, - telemetry: config.telemetry, + observability: config?.observability, }); } @@ -95,22 +95,28 @@ export class AnalyticsPlugin extends Plugin { const { jobId } = req.params; const workspaceClient = getWorkspaceClient(); - console.log( - `Processing Arrow job request: ${jobId} for plugin: ${this.name}`, - ); + this.logger.info("Fetching arrow data", { + operation: "arrow_fetch", + job_id: jobId, + }); const result = await this.getArrowData(workspaceClient, jobId); + this.logger.info("Arrow data fetched", { + job_id: jobId, + bytes_returned: result.data.length, + }); + res.setHeader("Content-Type", "application/octet-stream"); res.setHeader("Content-Length", result.data.length.toString()); res.setHeader("Cache-Control", "public, max-age=3600"); - console.log( - `Sending Arrow buffer: ${result.data.length} bytes for job ${jobId}`, - ); res.send(Buffer.from(result.data)); } catch (error) { - console.error(`Arrow job error for ${this.name}:`, error); + this.logger.error("Arrow fetch failed", error as Error, { + plugin: this.name, + }); + res.status(404).json({ error: error instanceof Error ? error.message : "Arrow job not found", plugin: this.name, @@ -128,6 +134,7 @@ export class AnalyticsPlugin extends Plugin { ): Promise { const { query_key } = req.params; const { parameters, format = "JSON" } = req.body as IAnalyticsQueryRequest; + const queryParameters = format === "ARROW" ? { @@ -141,7 +148,11 @@ export class AnalyticsPlugin extends Plugin { type: "result", }; - // Get user key from current context (automatically includes user ID when in user context) + this.logger.info("Processing query", { + query_key, + format, + parameter_count: parameters ? Object.keys(parameters).length : 0, + }); const userKey = getCurrentUserId(); if (!query_key) { diff --git a/packages/appkit/src/app/index.ts b/packages/appkit/src/app/index.ts index 9bfadfa6..7f2a7d1c 100644 --- a/packages/appkit/src/app/index.ts +++ b/packages/appkit/src/app/index.ts @@ -1,5 +1,6 @@ import fs from "node:fs/promises"; import path from "node:path"; +import { type ILogger, LoggerManager } from "../observability"; interface RequestLike { query?: Record; @@ -11,6 +12,7 @@ interface DevFileReader { } export class AppManager { + private logger: ILogger = LoggerManager.getLogger("app-manager"); /** * Retrieves a query file by key from the queries directory * In dev mode with a request context, reads from local filesystem via WebSocket @@ -27,9 +29,11 @@ export class AppManager { ): Promise { // Security: Sanitize query key to prevent path traversal if (!queryKey || !/^[a-zA-Z0-9_-]+$/.test(queryKey)) { - console.error( - `Invalid query key format: "${queryKey}". Only alphanumeric characters, underscores, and hyphens are allowed.`, - ); + this.logger.debug("Invalid query key format", { + queryKey, + reason: + "Only alphanumeric characters, underscores, and hyphens are allowed.", + }); return null; } @@ -44,7 +48,9 @@ export class AppManager { const queriesDir = path.resolve(process.cwd(), "config/queries"); if (!resolvedPath.startsWith(queriesDir)) { - console.error(`Invalid query path: path traversal detected`); + this.logger.debug("Invalid query path - traversal detected", { + queryKey, + }); return null; } @@ -57,9 +63,10 @@ export class AppManager { const relativePath = path.relative(process.cwd(), resolvedPath); return await devFileReader.readFile(relativePath, req); } catch (error) { - console.error( - `Failed to read query "${queryKey}" from dev tunnel: ${(error as Error).message}`, - ); + this.logger.debug("Failed to read query from dev tunnel", { + queryKey, + error: error instanceof Error ? error.message : String(error), + }); return null; } } @@ -70,12 +77,14 @@ export class AppManager { return query; } catch (error) { if ((error as NodeJS.ErrnoException).code === "ENOENT") { - console.error(`Query "${queryKey}" not found at path: ${resolvedPath}`); + this.logger.debug("Query not found", { queryKey, path: resolvedPath }); return null; } - console.error( - `Failed to read query "${queryKey}" from server filesystem: ${(error as Error).message}`, - ); + this.logger.debug("Failed to read query from filesystem", { + queryKey, + path: resolvedPath, + error: error instanceof Error ? error.message : String(error), + }); return null; } } diff --git a/packages/appkit/src/cache/index.ts b/packages/appkit/src/cache/index.ts index ec377f92..07c19357 100644 --- a/packages/appkit/src/cache/index.ts +++ b/packages/appkit/src/cache/index.ts @@ -2,8 +2,12 @@ import { createHash } from "node:crypto"; import { WorkspaceClient } from "@databricks/sdk-experimental"; import type { CacheConfig, CacheStorage } from "shared"; import { LakebaseConnector } from "@/connectors"; -import type { Counter, TelemetryProvider } from "../telemetry"; -import { SpanStatusCode, TelemetryManager } from "../telemetry"; +import { + type Counter, + type ILogger, + LoggerManager, + SpanStatusCode, +} from "@/observability"; import { deepMerge } from "../utils"; import { cacheDefaults } from "./defaults"; import { InMemoryStorage, PersistentStorage } from "./storage"; @@ -34,9 +38,8 @@ export class CacheManager { private cleanupInProgress: boolean; private lastCleanupAttempt: number; - // Telemetry - private telemetry: TelemetryProvider; - private telemetryMetrics: { + private logger: ILogger; + private metrics: { cacheHitCount: Counter; cacheMissCount: Counter; }; @@ -48,16 +51,14 @@ export class CacheManager { this.cleanupInProgress = false; this.lastCleanupAttempt = 0; - this.telemetry = TelemetryManager.getProvider( - this.name, - this.config.telemetry, - ); - this.telemetryMetrics = { - cacheHitCount: this.telemetry.getMeter().createCounter("cache.hit", { + this.logger = LoggerManager.getLogger(this.name, config?.observability); + + this.metrics = { + cacheHitCount: this.logger.counter("cache.hit", { description: "Total number of cache hits", unit: "1", }), - cacheMissCount: this.telemetry.getMeter().createCounter("cache.miss", { + cacheMissCount: this.logger.counter("cache.miss", { description: "Total number of cache misses", unit: "1", }), @@ -182,87 +183,90 @@ export class CacheManager { ): Promise { if (!this.config.enabled) return fn(); + const event = this.logger.getEvent(); const cacheKey = this.generateKey(key, userKey); - return this.telemetry.startActiveSpan( - "cache.getOrExecute", - { - attributes: { - "cache.key": cacheKey, - "cache.enabled": this.config.enabled, - "cache.persistent": this.storage.isPersistent(), - }, - }, - async (span) => { - try { - // check if the value is in the cache - const cached = await this.storage.get(cacheKey); - if (cached !== null) { - span.setAttribute("cache.hit", true); - span.setStatus({ code: SpanStatusCode.OK }); - this.telemetryMetrics.cacheHitCount.add(1, { - "cache.key": cacheKey, - }); - return cached.value as T; - } - - // check if the value is being processed by another request - const inFlight = this.inFlightRequests.get(cacheKey); - if (inFlight) { - span.setAttribute("cache.hit", true); - span.setAttribute("cache.deduplication", true); - span.addEvent("cache.deduplication_used", { - "cache.key": cacheKey, - }); - span.setStatus({ code: SpanStatusCode.OK }); - this.telemetryMetrics.cacheHitCount.add(1, { - "cache.key": cacheKey, - "cache.deduplication": "true", - }); - span.end(); - return inFlight as Promise; - } - - // cache miss - execute function - span.setAttribute("cache.hit", false); - span.addEvent("cache.miss", { "cache.key": cacheKey }); - this.telemetryMetrics.cacheMissCount.add(1, { - "cache.key": cacheKey, + return this.logger.span("getOrExecute", async (span) => { + span.setAttribute("cache.key", cacheKey); + span.setAttribute("cache.enabled", this.config.enabled ?? false); + span.setAttribute( + "cache.persistent", + this.storage.isPersistent() ?? false, + ); + + try { + // check if the value is in the cache + const cached = await this.storage.get(cacheKey); + if (cached !== null) { + event?.setExecution({ + cache_hit: true, + cache_key: cacheKey, }); - const promise = fn() - .then(async (result) => { - await this.set(cacheKey, result, options); - span.addEvent("cache.value_stored", { - "cache.key": cacheKey, - "cache.ttl": options?.ttl ?? this.config.ttl ?? 3600, - }); - return result; - }) - .catch((error) => { - span.recordException(error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - }) - .finally(() => { - this.inFlightRequests.delete(cacheKey); - }); + span.setAttribute("cache.hit", true); + span.setStatus({ code: SpanStatusCode.OK }); + this.metrics.cacheHitCount.add(1, { "cache.key": cacheKey }); + return cached.value as T; + } - this.inFlightRequests.set(cacheKey, promise); + // check if the value is being processed by another request + const inFlight = this.inFlightRequests.get(cacheKey); + if (inFlight) { + event?.setExecution({ + cache_hit: true, + cache_key: cacheKey, + }); - const result = await promise; + span.setAttribute("cache.hit", true); + span.setAttribute("cache.deduplication", true); + span.addEvent("cache.deduplication_used", { + "cache.key": cacheKey, + }); span.setStatus({ code: SpanStatusCode.OK }); - return result; - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { - span.end(); + + this.metrics.cacheHitCount.add(1, { "cache.key": cacheKey }); + return inFlight as Promise; } - }, - { name: this.name, includePrefix: true }, - ); + + // cache miss - execute function + event?.setExecution({ + cache_hit: false, + cache_key: cacheKey, + }); + + span.setAttribute("cache.hit", false); + span.addEvent("cache.miss", { "cache.key": cacheKey }); + this.metrics.cacheMissCount.add(1, { "cache.key": cacheKey }); + + const promise = fn() + .then(async (result) => { + await this.set(cacheKey, result, options); + span.addEvent("cache.value_stored", { + "cache.key": cacheKey, + "cache.ttl": options?.ttl ?? this.config.ttl ?? 3600, + }); + return result; + }) + .catch((error) => { + span.recordException(error); + span.setStatus({ code: SpanStatusCode.ERROR }); + throw error; + }) + .finally(() => { + this.inFlightRequests.delete(cacheKey); + }); + + this.inFlightRequests.set(cacheKey, promise); + + const result = await promise; + span.setStatus({ code: SpanStatusCode.OK }); + return result; + } catch (error) { + span.recordException(error as Error); + span.setStatus({ code: SpanStatusCode.ERROR }); + throw error; + } + }); } /** @@ -301,11 +305,10 @@ export class CacheManager { this.lastCleanupAttempt = now; this.cleanupInProgress = true; - (this.storage as PersistentStorage) + void (this.storage as PersistentStorage) .cleanupExpired() - .catch((error) => { - console.debug("Error cleaning up expired entries:", error); - }) + // fire-and-forget: ensure no unhandled rejection escapes + .catch(() => {}) .finally(() => { this.cleanupInProgress = false; }); diff --git a/packages/appkit/src/cache/storage/persistent.ts b/packages/appkit/src/cache/storage/persistent.ts index 9309a8ba..ab2d50d9 100644 --- a/packages/appkit/src/cache/storage/persistent.ts +++ b/packages/appkit/src/cache/storage/persistent.ts @@ -1,5 +1,6 @@ import { createHash } from "node:crypto"; import type { CacheConfig, CacheEntry, CacheStorage } from "shared"; +import { type ILogger, LoggerManager } from "@/observability"; import type { LakebaseConnector } from "../../connectors"; import { lakebaseStorageDefaults } from "./defaults"; @@ -25,6 +26,8 @@ export class PersistentStorage implements CacheStorage { private readonly evictionBatchSize: number; private readonly evictionCheckProbability: number; private initialized: boolean; + private readonly logger: ILogger = + LoggerManager.getLogger("persistent-storage"); constructor(config: CacheConfig, connector: LakebaseConnector) { this.connector = connector; @@ -47,7 +50,10 @@ export class PersistentStorage implements CacheStorage { await this.runMigrations(); this.initialized = true; } catch (error) { - console.error("Error in persistent storage initialization:", error); + this.logger.error( + "Error in persistent storage initialization", + error as Error, + ); throw error; } } @@ -80,7 +86,11 @@ export class PersistentStorage implements CacheStorage { [keyHash], ) .catch(() => { - console.debug("Error updating last_accessed time for key:", key); + this.logger.error( + "Error updating last_accessed time for key", + undefined, + { key }, + ); }); return { @@ -302,9 +312,9 @@ export class PersistentStorage implements CacheStorage { `CREATE INDEX IF NOT EXISTS idx_${this.tableName}_byte_size ON ${this.tableName} (byte_size); `, ); } catch (error) { - console.error( - "Error in running migrations for persistent storage:", - error, + this.logger.error( + "Error in running migrations for persistent storage", + error as Error, ); throw error; } diff --git a/packages/appkit/src/connectors/lakebase/client.ts b/packages/appkit/src/connectors/lakebase/client.ts index e05d2827..a1a4e967 100644 --- a/packages/appkit/src/connectors/lakebase/client.ts +++ b/packages/appkit/src/connectors/lakebase/client.ts @@ -5,10 +5,10 @@ import pg from "pg"; import { type Counter, type Histogram, + type ILogger, + LoggerManager, SpanStatusCode, - TelemetryManager, - type TelemetryProvider, -} from "@/telemetry"; +} from "@/observability"; import { deepMerge } from "../../utils"; import { lakebaseDefaults } from "./defaults"; import type { @@ -41,8 +41,8 @@ export class LakebaseConnector { private credentials: LakebaseCredentials | null = null; // telemetry - private readonly telemetry: TelemetryProvider; - private readonly telemetryMetrics: { + private readonly logger: ILogger; + private readonly metrics: { queryCount: Counter; queryDuration: Histogram; }; @@ -51,29 +51,31 @@ export class LakebaseConnector { this.config = deepMerge(lakebaseDefaults, userConfig); this.connectionConfig = this.parseConnectionConfig(); - this.telemetry = TelemetryManager.getProvider( + this.logger = LoggerManager.getLogger( this.name, - this.config.telemetry, + this.config?.observability, ); - this.telemetryMetrics = { - queryCount: this.telemetry - .getMeter() - .createCounter("lakebase.query.count", { - description: "Total number of queries executed", - unit: "1", - }), - queryDuration: this.telemetry - .getMeter() - .createHistogram("lakebase.query.duration", { - description: "Duration of queries executed", - unit: "ms", - }), + this.metrics = { + queryCount: this.logger.counter("query.count", { + description: "Total number of queries executed", + unit: "1", + }), + queryDuration: this.logger.histogram("query.duration", { + description: "Duration of queries executed", + unit: "ms", + }), }; // validate configuration if (this.config.maxPoolSize < 1) { throw new Error("maxPoolSize must be at least 1"); } + + this.logger.debug("Lakebase connector initialized", { + config: this.config, + database: this.connectionConfig.database, + maxPoolSize: this.config.maxPoolSize, + }); } /** @@ -92,53 +94,84 @@ export class LakebaseConnector { ): Promise> { const startTime = Date.now(); - return this.telemetry.startActiveSpan( - "lakebase.query", - { - attributes: { - "db.system": "lakebase", - "db.statement": sql.substring(0, 500), - "db.retry_count": retryCount, - }, - }, - async (span) => { - try { - const pool = await this.getPool(); - const result = await pool.query(sql, params); - span.setAttribute("db.rows_affected", result.rowCount ?? 0); - span.setStatus({ code: SpanStatusCode.OK }); - return result; - } catch (error) { - // retry on auth failure - if (this.isAuthError(error)) { - span.addEvent("auth_error_retry"); - await this.rotateCredentials(); - const newPool = await this.getPool(); - const result = await newPool.query(sql, params); - span.setAttribute("db.rows_affected", result.rowCount ?? 0); - span.setStatus({ code: SpanStatusCode.OK }); - return result; - } + this.logger.info("Executing query", { + statement: sql.substring(0, 500), + has_params: !!params, + retry_count: retryCount, + }); - // retry on transient errors, but only once - if (this.isTransientError(error) && retryCount < 1) { - span.addEvent("transient_error_retry"); - await new Promise((resolve) => setTimeout(resolve, 100)); - return await this.query(sql, params, retryCount + 1); - } + return this.logger.span("query", async (span) => { + span.setAttribute("db.system", "lakebase"); + span.setAttribute("db.statement", sql.substring(0, 500)); + span.setAttribute("db.retry_count", retryCount); + + try { + const pool = await this.getPool(); + const result = await pool.query(sql, params); + const rowAffected = result.rowCount ?? 0; + const duration = Date.now() - startTime; + + span.setAttribute("db.rows_affected", rowAffected); + span.setStatus({ code: SpanStatusCode.OK }); + + this.logger.info("Query completed", { + rows_affected: rowAffected, + query_duration_ms: duration, + }); + + return result; + } catch (error) { + // retry on auth failure + if (this.isAuthError(error)) { + this.logger.warn("Authentication error, retrying"); + span.addEvent("auth_error_retry"); + + await this.rotateCredentials(); - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); + const newPool = await this.getPool(); + const result = await newPool.query(sql, params); + const rowsAffected = result.rowCount ?? 0; - throw error; - } finally { const duration = Date.now() - startTime; - this.telemetryMetrics.queryCount.add(1); - this.telemetryMetrics.queryDuration.record(duration); - span.end(); + + span.setAttribute("db.rows_affected", rowsAffected); + span.setStatus({ code: SpanStatusCode.OK }); + + this.logger.info( + "Query executed successfully after authentication error", + { + rows_affected: rowsAffected, + query_duration_ms: duration, + }, + ); + + return result; } - }, - ); + + // retry on transient errors, but only once + if (this.isTransientError(error) && retryCount < 1) { + this.logger.warn("Transient error, retrying", { + error_code: (error as any).code, + }); + span.addEvent("transient_error_retry"); + await new Promise((resolve) => setTimeout(resolve, 100)); + return await this.query(sql, params, retryCount + 1); + } + + span.recordException(error as Error); + span.setStatus({ code: SpanStatusCode.ERROR }); + + this.logger.error("Query failed", error as Error); + + throw error; + } finally { + const duration = Date.now() - startTime; + this.metrics.queryCount.add(1); + this.metrics.queryDuration.record(duration); + + span.end(); + } + }); } /** @@ -160,105 +193,128 @@ export class LakebaseConnector { retryCount: number = 0, ): Promise { const startTime = Date.now(); - return this.telemetry.startActiveSpan( - "lakebase.transaction", - { - attributes: { - "db.system": "lakebase", - "db.retry_count": retryCount, - }, - }, - async (span) => { - const pool = await this.getPool(); - const client = await pool.connect(); + this.logger.info("Executing transaction", { + retry_count: retryCount, + }); + + return this.logger.span("transaction", async (span) => { + span.setAttribute("db.system", "lakebase"); + span.setAttribute("db.retry_count", retryCount); + + const pool = await this.getPool(); + const client = await pool.connect(); + + try { + await client.query("BEGIN"); + this.logger.debug("Transaction began"); + const result = await callback(client); + await client.query("COMMIT"); + span.setStatus({ code: SpanStatusCode.OK }); + + const duration = Date.now() - startTime; + + this.logger.info("Transaction committed", { + transaction_duration_ms: duration, + transaction_status: "committed", + }); + + return result; + } catch (error) { try { - await client.query("BEGIN"); - const result = await callback(client); - await client.query("COMMIT"); - span.setStatus({ code: SpanStatusCode.OK }); - return result; - } catch (error) { + await client.query("ROLLBACK"); + this.logger.debug("Transaction ROLLBACK"); + } catch {} + // retry on auth failure + if (this.isAuthError(error)) { + this.logger.warn("Authentication error in transaction, retrying"); + span.addEvent("auth_error_retry"); + client.release(); + await this.rotateCredentials(); + const newPool = await this.getPool(); + const retryClient = await newPool.connect(); try { - await client.query("ROLLBACK"); - } catch {} - // retry on auth failure - if (this.isAuthError(error)) { - span.addEvent("auth_error_retry"); - client.release(); - await this.rotateCredentials(); - const newPool = await this.getPool(); - const retryClient = await newPool.connect(); + await client.query("BEGIN"); + const result = await callback(retryClient); + await client.query("COMMIT"); + span.setStatus({ code: SpanStatusCode.OK }); + + const duration = Date.now() - startTime; + + this.logger.info( + "Transaction committed after authentication error", + { + duration_ms: duration, + }, + ); + + return result; + } catch (retryError) { try { - await client.query("BEGIN"); - const result = await callback(retryClient); - await client.query("COMMIT"); - span.setStatus({ code: SpanStatusCode.OK }); - return result; - } catch (retryError) { - try { - await retryClient.query("ROLLBACK"); - } catch {} - throw retryError; - } finally { - retryClient.release(); - } + await retryClient.query("ROLLBACK"); + } catch {} + throw retryError; + } finally { + retryClient.release(); } + } - // retry on transient errors, but only once - if (this.isTransientError(error) && retryCount < 1) { - span.addEvent("transaction_error_retry"); - client.release(); - await new Promise((resolve) => setTimeout(resolve, 100)); - return await this.transaction(callback, retryCount + 1); - } - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { + // retry on transient errors, but only once + if (this.isTransientError(error) && retryCount < 1) { + this.logger.warn("Transient error in transaction, retrying"); + span.addEvent("transaction_error_retry"); client.release(); - const duration = Date.now() - startTime; - this.telemetryMetrics.queryCount.add(1); - this.telemetryMetrics.queryDuration.record(duration); - span.end(); + await new Promise((resolve) => setTimeout(resolve, 100)); + return await this.transaction(callback, retryCount + 1); } - }, - ); + span.recordException(error as Error); + span.setStatus({ code: SpanStatusCode.ERROR }); + + this.logger.error("Transaction failed", error as Error); + + throw error; + } finally { + client.release(); + const duration = Date.now() - startTime; + this.metrics.queryCount.add(1); + this.metrics.queryDuration.record(duration); + span.end(); + } + }); } /** Check if database connection is healthy */ async healthCheck(): Promise { - return this.telemetry.startActiveSpan( - "lakebase.healthCheck", - {}, - async (span) => { - try { - const result = await this.query<{ result: number }>( - "SELECT 1 as result", - ); - const healthy = result.rows[0]?.result === 1; - span.setAttribute("db.healthy", healthy); - span.setStatus({ code: SpanStatusCode.OK }); - return healthy; - } catch { - span.setAttribute("db.healthy", false); - span.setStatus({ code: SpanStatusCode.ERROR }); - return false; - } finally { - span.end(); - } - }, - ); + return this.logger.span("healthCheck", async (span) => { + try { + const result = await this.query<{ result: number }>( + "SELECT 1 as result", + ); + const healthy = result.rows[0]?.result === 1; + span.setAttribute("db.healthy", healthy); + span.setStatus({ code: SpanStatusCode.OK }); + return healthy; + } catch { + span.setAttribute("db.healthy", false); + span.setStatus({ code: SpanStatusCode.ERROR }); + return false; + } finally { + span.end(); + } + }); } /** Close connection pool (call on shutdown) */ async close(): Promise { if (this.pool) { + this.logger.debug("Closing connection pool"); await this.pool.end().catch((error: unknown) => { - console.error("Error closing connection pool:", error); + this.logger.error("Error closing connection pool:", error as Error); }); this.pool = null; } this.credentials = null; + + this.logger.debug("Connection pool closed"); } /** Setup graceful shutdown to close connection pools */ @@ -298,6 +354,7 @@ export class LakebaseConnector { } if (!this.pool) { + this.logger.debug("Creating new connection pool"); const creds = await this.getCredentials(); this.pool = this.createPool(creds); } @@ -324,10 +381,9 @@ export class LakebaseConnector { }); pool.on("error", (error: Error & { code?: string }) => { - console.error("Connection pool error:", error.message, { - code: error.code, - }); + this.logger.error("Connection pool error:", error as Error); }); + this.logger.debug("Connection pool created"); return pool; } @@ -344,9 +400,12 @@ export class LakebaseConnector { this.credentials && now < this.credentials.expiresAt - this.CACHE_BUFFER_MS ) { + this.logger.debug("Using cached credentials"); return this.credentials; } + this.logger.debug("Fetching new credentials"); + // fetch new credentials const username = await this.fetchUsername(); const { token, expiresAt } = await this.fetchPassword(); @@ -357,11 +416,14 @@ export class LakebaseConnector { expiresAt, }; + this.logger.debug("New credentials fetched"); + return { username, password: token }; } /** Rotate credentials and recreate pool */ private async rotateCredentials(): Promise { + this.logger.debug("Rotating credentials"); // clear cached credentials this.credentials = null; @@ -369,9 +431,9 @@ export class LakebaseConnector { const oldPool = this.pool; this.pool = null; oldPool.end().catch((error: unknown) => { - console.error( + this.logger.error( "Error closing old connection pool during rotation:", - error, + error as Error, ); }); } diff --git a/packages/appkit/src/connectors/lakebase/types.ts b/packages/appkit/src/connectors/lakebase/types.ts index a8591b50..45534330 100644 --- a/packages/appkit/src/connectors/lakebase/types.ts +++ b/packages/appkit/src/connectors/lakebase/types.ts @@ -1,5 +1,5 @@ import type { WorkspaceClient } from "@databricks/sdk-experimental"; -import type { TelemetryOptions } from "shared"; +import type { ObservabilityOptions } from "@/observability"; /** Configuration for LakebaseConnector */ export interface LakebaseConfig { @@ -33,8 +33,8 @@ export interface LakebaseConfig { /** Connection timeout (milliseconds) */ connectionTimeoutMs: number; - /** Telemetry configuration */ - telemetry?: TelemetryOptions; + /** Observability configuration */ + observability?: ObservabilityOptions; /** Additional configuration options */ [key: string]: unknown; diff --git a/packages/appkit/src/connectors/sql-warehouse/client.ts b/packages/appkit/src/connectors/sql-warehouse/client.ts index f1186f1e..941db766 100644 --- a/packages/appkit/src/connectors/sql-warehouse/client.ts +++ b/packages/appkit/src/connectors/sql-warehouse/client.ts @@ -3,22 +3,21 @@ import { type sql, type WorkspaceClient, } from "@databricks/sdk-experimental"; -import { ArrowStreamProcessor } from "../../stream/arrow-stream-processor"; -import type { TelemetryOptions } from "shared"; -import type { TelemetryProvider } from "../../telemetry"; import { type Counter, type Histogram, + type ILogger, + LoggerManager, + type ObservabilityOptions, type Span, - SpanKind, SpanStatusCode, - TelemetryManager, -} from "../../telemetry"; +} from "@/observability"; +import { ArrowStreamProcessor } from "../../stream/arrow-stream-processor"; import { executeStatementDefaults } from "./defaults"; export interface SQLWarehouseConfig { timeout?: number; - telemetry?: TelemetryOptions; + observability?: ObservabilityOptions; } export class SQLWarehouseConnector { @@ -28,9 +27,9 @@ export class SQLWarehouseConnector { // Lazy-initialized: only created when Arrow format is used private _arrowProcessor: ArrowStreamProcessor | null = null; - // telemetry - private readonly telemetry: TelemetryProvider; - private readonly telemetryMetrics: { + + private readonly logger: ILogger; + private readonly metrics: { queryCount: Counter; queryDuration: Histogram; }; @@ -38,22 +37,22 @@ export class SQLWarehouseConnector { constructor(config: SQLWarehouseConfig) { this.config = config; - this.telemetry = TelemetryManager.getProvider( + this.logger = LoggerManager.getLogger( this.name, - this.config.telemetry, + this.config?.observability, ); - this.telemetryMetrics = { - queryCount: this.telemetry.getMeter().createCounter("query.count", { + this.metrics = { + queryCount: this.logger.counter("query.count", { description: "Total number of queries executed", unit: "1", }), - queryDuration: this.telemetry - .getMeter() - .createHistogram("query.duration", { - description: "Duration of queries executed", - unit: "ms", - }), + queryDuration: this.logger.histogram("query.duration", { + description: "Duration of queries executed", + unit: "ms", + }), }; + + this.logger.debug("SQLWarehouseConnector initialized", { config }); } /** @@ -80,93 +79,240 @@ export class SQLWarehouseConnector { const startTime = Date.now(); let success = false; - return this.telemetry.startActiveSpan( - "sql.query", - { - kind: SpanKind.CLIENT, - attributes: { - "db.system": "databricks", - "db.warehouse_id": input.warehouse_id || "", + this.logger.info("Executing statement", { + warehouse_id: input.warehouse_id, + catalog: input.catalog, + schema: input.schema, + has_parameters: !!input.parameters, + }); + + return this.logger.span("query", async (span: Span) => { + span.setAttribute("db.system", "databricks"); + span.setAttribute("db.warehouse_id", input.warehouse_id || ""); + span.setAttribute("db.catalog", input.catalog ?? ""); + span.setAttribute("db.schema", input.schema ?? ""); + span.setAttribute("db.statement_length", input.statement?.length || 0); + span.setAttribute("db.has_parameters", !!input.parameters); + try { + // validate required fields + if (!input.statement) { + throw new Error( + "Statement is required: Please provide a SQL statement to execute", + ); + } + + if (!input.warehouse_id) { + throw new Error( + "Warehouse ID is required: Please provide a warehouse_id to execute the statement", + ); + } + + const body: sql.ExecuteStatementRequest = { + statement: input.statement, + parameters: input.parameters, + warehouse_id: input.warehouse_id, + catalog: input.catalog, + schema: input.schema, + wait_timeout: + input.wait_timeout || executeStatementDefaults.wait_timeout, + disposition: + input.disposition || executeStatementDefaults.disposition, + format: input.format || executeStatementDefaults.format, + byte_limit: input.byte_limit, + row_limit: input.row_limit, + on_wait_timeout: + input.on_wait_timeout || executeStatementDefaults.on_wait_timeout, + }; + + this.logger.debug("Submitting statement to warehouse"); + + span.addEvent("statement.submitting", { + "db.warehouse_id": input.warehouse_id, + }); + + const response = + await workspaceClient.statementExecution.executeStatement( + body, + this._createContext(signal), + ); + + if (!response) { + throw new Error("No response received from SQL Warehouse API"); + } + const status = response.status; + const statementId = response.statement_id as string; + + span.setAttribute("db.statement_id", statementId); + span.addEvent("statement.submitted", { + "db.statement_id": response.statement_id, + "db.status": status?.state, + }); + + this.logger.debug("Statement submitted", { + statement_id: response.statement_id, + status: status?.state, + }); + + let result: + | sql.StatementResponse + | { result: { statement_id: string; status: sql.StatementStatus } }; + + switch (status?.state) { + case "RUNNING": + case "PENDING": + this.logger.debug("Statement polling started", { + statement_id: response.statement_id, + status: status?.state, + }); + span.addEvent("statement.polling_started", { + "db.status": response.status?.state, + }); + result = await this._pollForStatementResult( + workspaceClient, + statementId, + this.config.timeout, + signal, + ); + break; + case "SUCCEEDED": + result = this._transformDataArray(response); + break; + case "FAILED": + throw new Error( + `Statement failed: ${status.error?.message || "Unknown error"}`, + ); + case "CANCELED": + throw new Error("Statement was canceled"); + case "CLOSED": + throw new Error( + "Statement execution completed but results are no longer available (CLOSED state)", + ); + default: + throw new Error(`Unknown statement state: ${status?.state}`); + } + + const resultData = result.result as any; + const rowCount = + resultData?.data?.length || resultData?.data_array?.length; + + if (rowCount > 0) { + span.setAttribute("db.result.row_count", rowCount); + } + + const duration = Date.now() - startTime; + + success = true; + span.setStatus({ code: SpanStatusCode.OK }); + + this.logger.info("Query completed", { + statement_id: response.statement_id, + rows_returned: rowCount, + query_duration_ms: duration, + }); + + return result; + } catch (error) { + span.recordException(error as Error); + span.setStatus({ + code: SpanStatusCode.ERROR, + message: error instanceof Error ? error.message : String(error), + }); + + this.logger.error("Query failed", error as Error, { + warehouse_id: input.warehouse_id, + }); + throw error; + } finally { + const duration = Date.now() - startTime; + + const attributes = { + "db.warehouse_id": input.warehouse_id, "db.catalog": input.catalog ?? "", "db.schema": input.schema ?? "", - "db.statement": input.statement?.substring(0, 500) || "", - "db.has_parameters": !!input.parameters, - }, - }, - async (span: Span) => { - try { - // validate required fields - if (!input.statement) { - throw new Error( - "Statement is required: Please provide a SQL statement to execute", + success: success.toString(), + }; + + this.metrics.queryCount.add(1, attributes); + this.metrics.queryDuration.record(duration, attributes); + } + }); + } + + private async _pollForStatementResult( + workspaceClient: WorkspaceClient, + statementId: string, + timeout = executeStatementDefaults.timeout, + signal?: AbortSignal, + ) { + return this.logger.span("poll", async (span: Span) => { + span.setAttribute("db.statement_id", statementId); + span.setAttribute("db.polling.timeout", timeout); + try { + const startTime = Date.now(); + let delay = 1000; + const maxDelayBetweenPolls = 5000; // max 5 seconds between polls + let pollCount = 0; + + while (true) { + pollCount++; + span.setAttribute("db.polling.current_attempt", pollCount); + + // check if timeout exceeded + const elapsedTime = Date.now() - startTime; + if (elapsedTime > timeout) { + const error = new Error( + `Statement polling timeout exceeded after ${timeout}ms (elapsed: ${elapsedTime}ms)`, ); + span.recordException(error); + span.setStatus({ code: SpanStatusCode.ERROR }); + throw error; } - if (!input.warehouse_id) { - throw new Error( - "Warehouse ID is required: Please provide a warehouse_id to execute the statement", - ); + if (signal?.aborted) { + const error = new Error("Request aborted"); + span.recordException(error); + span.setStatus({ code: SpanStatusCode.ERROR }); + throw error; } - const body: sql.ExecuteStatementRequest = { - statement: input.statement, - parameters: input.parameters, - warehouse_id: input.warehouse_id, - catalog: input.catalog, - schema: input.schema, - wait_timeout: - input.wait_timeout || executeStatementDefaults.wait_timeout, - disposition: - input.disposition || executeStatementDefaults.disposition, - format: input.format || executeStatementDefaults.format, - byte_limit: input.byte_limit, - row_limit: input.row_limit, - on_wait_timeout: - input.on_wait_timeout || executeStatementDefaults.on_wait_timeout, - }; - - span.addEvent("statement.submitting", { - "db.warehouse_id": input.warehouse_id, + span.addEvent("polling.attempt", { + "poll.attempt": pollCount, + "poll.delay_ms": delay, + "poll.elapsed_ms": elapsedTime, }); const response = - await workspaceClient.statementExecution.executeStatement( - body, + await workspaceClient.statementExecution.getStatement( + { + statement_id: statementId, + }, this._createContext(signal), ); - if (!response) { throw new Error("No response received from SQL Warehouse API"); } + const status = response.status; - const statementId = response.statement_id as string; - span.setAttribute("db.statement_id", statementId); - span.addEvent("statement.submitted", { - "db.statement_id": response.statement_id, + span.addEvent("polling.status_check", { "db.status": status?.state, + "poll.attempt": pollCount, }); - let result: - | sql.StatementResponse - | { result: { statement_id: string; status: sql.StatementStatus } }; - switch (status?.state) { - case "RUNNING": case "PENDING": - span.addEvent("statement.polling_started", { - "db.status": response.status?.state, - }); - result = await this._pollForStatementResult( - workspaceClient, - statementId, - this.config.timeout, - signal, - ); + case "RUNNING": + // continue polling break; case "SUCCEEDED": - result = this._transformDataArray(response); - break; + span.setAttribute("db.polling.attempts", pollCount); + span.setAttribute("db.polling.total_duration_ms", elapsedTime); + span.addEvent("polling.completed", { + "poll.attempts": pollCount, + "poll.duration_ms": elapsedTime, + }); + span.setStatus({ code: SpanStatusCode.OK }); + return this._transformDataArray(response); case "FAILED": throw new Error( `Statement failed: ${status.error?.message || "Unknown error"}`, @@ -181,160 +327,21 @@ export class SQLWarehouseConnector { throw new Error(`Unknown statement state: ${status?.state}`); } - const resultData = result.result as any; - if (resultData?.data) { - span.setAttribute("db.result.row_count", resultData.data.length); - } else if (resultData?.data_array) { - span.setAttribute( - "db.result.row_count", - resultData.data_array.length, - ); - } - - success = true; - span.setStatus({ code: SpanStatusCode.OK }); - return result; - } catch (error) { - span.recordException(error as Error); - span.setStatus({ - code: SpanStatusCode.ERROR, - message: error instanceof Error ? error.message : String(error), - }); - throw error; - } finally { - const duration = Date.now() - startTime; - span.end(); - - const attributes = { - "db.warehouse_id": input.warehouse_id, - "db.catalog": input.catalog ?? "", - "db.schema": input.schema ?? "", - "db.statement": input.statement?.substring(0, 500) || "", - success: success.toString(), - }; - - this.telemetryMetrics.queryCount.add(1, attributes); - this.telemetryMetrics.queryDuration.record(duration, attributes); - } - }, - { name: this.name, includePrefix: true }, - ); - } - - private async _pollForStatementResult( - workspaceClient: WorkspaceClient, - statementId: string, - timeout = executeStatementDefaults.timeout, - signal?: AbortSignal, - ) { - return this.telemetry.startActiveSpan( - "sql.poll", - { - attributes: { - "db.statement_id": statementId, - "db.polling.timeout": timeout, - }, - }, - async (span: Span) => { - try { - const startTime = Date.now(); - let delay = 1000; - const maxDelayBetweenPolls = 5000; // max 5 seconds between polls - let pollCount = 0; - - while (true) { - pollCount++; - span.setAttribute("db.polling.current_attempt", pollCount); - - // check if timeout exceeded - const elapsedTime = Date.now() - startTime; - if (elapsedTime > timeout) { - const error = new Error( - `Statement polling timeout exceeded after ${timeout}ms (elapsed: ${elapsedTime}ms)`, - ); - span.recordException(error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } - - if (signal?.aborted) { - const error = new Error("Request aborted"); - span.recordException(error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } - - span.addEvent("polling.attempt", { - "poll.attempt": pollCount, - "poll.delay_ms": delay, - "poll.elapsed_ms": elapsedTime, - }); - - const response = - await workspaceClient.statementExecution.getStatement( - { - statement_id: statementId, - }, - this._createContext(signal), - ); - if (!response) { - throw new Error("No response received from SQL Warehouse API"); - } - - const status = response.status; - - span.addEvent("polling.status_check", { - "db.status": status?.state, - "poll.attempt": pollCount, - }); - - switch (status?.state) { - case "PENDING": - case "RUNNING": - // continue polling - break; - case "SUCCEEDED": - span.setAttribute("db.polling.attempts", pollCount); - span.setAttribute("db.polling.total_duration_ms", elapsedTime); - span.addEvent("polling.completed", { - "poll.attempts": pollCount, - "poll.duration_ms": elapsedTime, - }); - span.setStatus({ code: SpanStatusCode.OK }); - return this._transformDataArray(response); - case "FAILED": - throw new Error( - `Statement failed: ${ - status.error?.message || "Unknown error" - }`, - ); - case "CANCELED": - throw new Error("Statement was canceled"); - case "CLOSED": - throw new Error( - "Statement execution completed but results are no longer available (CLOSED state)", - ); - default: - throw new Error(`Unknown statement state: ${status?.state}`); - } - - // continue polling after delay - await new Promise((resolve) => setTimeout(resolve, delay)); - delay = Math.min(delay * 2, maxDelayBetweenPolls); - } - } catch (error) { - span.recordException(error as Error); - span.setStatus({ - code: SpanStatusCode.ERROR, - message: error instanceof Error ? error.message : String(error), - }); - throw error; - } finally { - span.end(); + // continue polling after delay + await new Promise((resolve) => setTimeout(resolve, delay)); + delay = Math.min(delay * 2, maxDelayBetweenPolls); } - }, - { name: this.name, includePrefix: true }, - ); + } catch (error) { + span.recordException(error as Error); + span.setStatus({ + code: SpanStatusCode.ERROR, + message: error instanceof Error ? error.message : String(error), + }); + throw error; + } finally { + span.end(); + } + }); } private _transformDataArray(response: sql.StatementResponse) { @@ -406,66 +413,57 @@ export class SQLWarehouseConnector { ): Promise> { const startTime = Date.now(); - return this.telemetry.startActiveSpan( - "arrow.getData", - { - kind: SpanKind.CLIENT, - attributes: { - "db.system": "databricks", - "arrow.job_id": jobId, - }, - }, - async (span: Span) => { - try { - const response = - await workspaceClient.statementExecution.getStatement( - { statement_id: jobId }, - this._createContext(signal), - ); - - const chunks = response.result?.external_links; - const schema = response.manifest?.schema; - - if (!chunks || !schema) { - throw new Error("No chunks or schema found in response"); - } - - span.setAttribute("arrow.chunk_count", chunks.length); - - const result = await this.arrowProcessor.processChunks( - chunks, - schema, - signal, - ); - - span.setAttribute("arrow.data_size_bytes", result.data.length); - span.setStatus({ code: SpanStatusCode.OK }); + return this.logger.span("arrow.getData", async (span: Span) => { + span.setAttribute("db.system", "databricks"); + span.setAttribute("arrow.job_id", jobId); + try { + const response = await workspaceClient.statementExecution.getStatement( + { statement_id: jobId }, + this._createContext(signal), + ); - const duration = Date.now() - startTime; - this.telemetryMetrics.queryDuration.record(duration, { - operation: "arrow.getData", - status: "success", - }); - - return result; - } catch (error) { - span.setStatus({ - code: SpanStatusCode.ERROR, - message: error instanceof Error ? error.message : "Unknown error", - }); - span.recordException(error as Error); + const chunks = response.result?.external_links; + const schema = response.manifest?.schema; - const duration = Date.now() - startTime; - this.telemetryMetrics.queryDuration.record(duration, { - operation: "arrow.getData", - status: "error", - }); - - console.error(`Failed Arrow job: ${jobId}`, error); - throw error; + if (!chunks || !schema) { + throw new Error("No chunks or schema found in response"); } - }, - ); + + span.setAttribute("arrow.chunk_count", chunks.length); + + const result = await this.arrowProcessor.processChunks( + chunks, + schema, + signal, + ); + + span.setAttribute("arrow.data_size_bytes", result.data.length); + span.setStatus({ code: SpanStatusCode.OK }); + + const duration = Date.now() - startTime; + this.metrics.queryDuration.record(duration, { + operation: "arrow.getData", + status: "success", + }); + + return result; + } catch (error) { + span.setStatus({ + code: SpanStatusCode.ERROR, + message: error instanceof Error ? error.message : "Unknown error", + }); + span.recordException(error as Error); + + const duration = Date.now() - startTime; + this.metrics.queryDuration.record(duration, { + operation: "arrow.getData", + status: "error", + }); + + console.error(`Failed Arrow job: ${jobId}`, error); + throw error; + } + }); } // create context for cancellation token diff --git a/packages/appkit/src/core/appkit.ts b/packages/appkit/src/core/appkit.ts index 5fad9d00..d7a74ead 100644 --- a/packages/appkit/src/core/appkit.ts +++ b/packages/appkit/src/core/appkit.ts @@ -2,15 +2,33 @@ import type { BasePlugin, CacheConfig, InputPluginMap, + ObservabilityOptions, OptionalConfigPluginDef, PluginConstructor, PluginData, PluginMap, } from "shared"; +import { LoggerManager, type ObservabilityConfig } from "@/observability"; import { CacheManager } from "../cache"; + +function normalizeObservabilityOptions( + options?: ObservabilityOptions, +): ObservabilityConfig { + if (options === undefined) { + return {}; + } + + if (typeof options === "boolean") { + return { enabled: options }; + } + + return { + traces: options.traces, + metrics: options.metrics, + logs: options.logs, + }; +} import { ServiceContext } from "../context"; -import type { TelemetryConfig } from "../telemetry"; -import { TelemetryManager } from "../telemetry"; export class AppKit { private static _instance: AppKit | null = null; @@ -88,12 +106,13 @@ export class AppKit { >( config: { plugins?: T; - telemetry?: TelemetryConfig; + observability?: ObservabilityOptions; cache?: CacheConfig; } = {}, ): Promise> { - // Initialize core services - TelemetryManager.initialize(config?.telemetry); + LoggerManager.initialize( + normalizeObservabilityOptions(config?.observability), + ); await CacheManager.getInstance(config?.cache); // Initialize ServiceContext for Databricks client management @@ -135,7 +154,7 @@ export async function createApp< >( config: { plugins?: T; - telemetry?: TelemetryConfig; + observability?: ObservabilityOptions; cache?: CacheConfig; } = {}, ): Promise> { diff --git a/packages/appkit/src/index.ts b/packages/appkit/src/index.ts index f6923fcf..76aacd00 100644 --- a/packages/appkit/src/index.ts +++ b/packages/appkit/src/index.ts @@ -6,26 +6,22 @@ export type { StreamExecutionSettings, } from "shared"; export { isSQLTypeMarker, sql } from "shared"; - -// Core -export { createApp } from "./core"; export { analytics } from "./analytics"; -export { server } from "./server"; - -// Plugin authoring -export { Plugin, toPlugin } from "./plugin"; export { CacheManager } from "./cache"; - -// Telemetry (for advanced custom telemetry) +// Core +export { createApp } from "./core"; +// Observability export { - SeverityNumber, - SpanStatusCode, - type TelemetryConfig, type Counter, type Histogram, + type ObservabilityConfig, + otel, type Span, - type ITelemetry, -} from "./telemetry"; + SpanStatusCode, +} from "./observability"; +// Plugin authoring +export { Plugin, toPlugin } from "./plugin"; +export { server } from "./server"; // Vite plugin export { appKitTypesPlugin } from "./type-generator/vite-plugin"; diff --git a/packages/appkit/src/observability/context.ts b/packages/appkit/src/observability/context.ts new file mode 100644 index 00000000..47212471 --- /dev/null +++ b/packages/appkit/src/observability/context.ts @@ -0,0 +1,87 @@ +import { AsyncLocalStorage } from "node:async_hooks"; +import { createDebug } from "./debug"; +import { formatJson, formatPretty } from "./formatter"; +import type { WideEvent, WideEventData } from "./wide-event"; + +/** + * AsyncLocalStorage for WideEvent (used by middleware and logger) + * @internal + */ +export const eventStorage = new AsyncLocalStorage(); + +const debug = createDebug("context"); + +const IS_PRODUCTION = process.env.NODE_ENV === "production"; +const SAMPLING_RATE = parseFloat(process.env.APPKIT_LOG_SAMPLING || "1.0"); + +/** + * Get the current wide event if in request context. + * @returns WideEvent if in request context, undefined otherwise + */ +export function getWideEvent(): WideEvent | undefined { + return eventStorage.getStore(); +} + +/** + * Determine if the event should be sampled. + * Takes finalized WideEventData to ensure status_code and duration_ms are available. + * @internal + */ +export function shouldSample(data: WideEventData): boolean { + // skip assets + if (data.path) { + const skipPaths = [ + "/@vite/", + "/@fs/", + "/node_modules/", + "/src/", + "/@react-refresh", + ]; + + if (skipPaths.some((path) => data.path?.startsWith(path))) return false; + + // skip by extension + if ( + /\.(js|css|json|map|svg|png|jpg|jpeg|gif|ico|webp|woff|woff2|ttf|eot|otf)$/.test( + data.path, + ) + ) { + return false; + } + } + + // always keep errors + if (data.status_code && data.status_code >= 400) return true; + if (data.error) return true; + + // always keep slow requests (> 10s) + if (data.duration_ms && data.duration_ms > 10000) return true; + + // always keep retried requests + if (data.execution?.retry_attempts && data.execution.retry_attempts > 0) + return true; + + // random sample the rest + return Math.random() < SAMPLING_RATE; +} + +/** + * Format WideEvent to terminal output. + * @internal - Used by LoggerManager + */ +export function formatAndEmitWideEvent( + event: WideEvent, + statusCode: number, +): WideEventData | null { + // finalize first to set status_code and duration_ms + const data = event.finalize(statusCode); + + // check if the event should be sampled + if (!shouldSample(data)) return null; + + // Format and output to terminal + const output = IS_PRODUCTION ? formatJson(data) : formatPretty(data); + debug(output); + + return data; +} diff --git a/packages/appkit/src/observability/debug.ts b/packages/appkit/src/observability/debug.ts new file mode 100644 index 00000000..8d4937ff --- /dev/null +++ b/packages/appkit/src/observability/debug.ts @@ -0,0 +1,11 @@ +import { createDebug as createObug, type Debugger } from "obug"; + +/** + * Create a debug logger using obug + * RESPECTS DEBUG=appkit:* environment variable + * @param scope - Debug scope name (will be prefixed with "appkit:") + * @returns - Debugger instance + */ +export function createDebug(scope: string): Debugger { + return createObug(`appkit:${scope}`, { useColors: true }); +} diff --git a/packages/appkit/src/observability/formatter.ts b/packages/appkit/src/observability/formatter.ts new file mode 100644 index 00000000..fd45939f --- /dev/null +++ b/packages/appkit/src/observability/formatter.ts @@ -0,0 +1,125 @@ +import type { WideEventData } from "./wide-event"; + +const COLORS = { + reset: "\x1b[0m", + dim: "\x1b[2m", + bold: "\x1b[1m", + green: "\x1b[32m", + magenta: "\x1b[35m", + yellow: "\x1b[33m", + red: "\x1b[31m", + cyan: "\x1b[36m", +}; + +// format JSON - production +export function formatJson(data: WideEventData): string { + return JSON.stringify(data); +} + +// format as human-readable - development +/** + * Format WideEvent as human-readable colored output (for development). + */ +export function formatPretty(data: WideEventData): string { + const { reset, dim, bold, green, yellow, red, cyan, magenta } = COLORS; + + // Status color + const statusColor = + data.status_code && data.status_code >= 500 + ? red + : data.status_code && data.status_code >= 400 + ? yellow + : green; + + // Header line + let output = `${dim}${data.timestamp}${reset} `; + output += `${statusColor}${data.status_code || "---"}${reset} `; + output += `${bold}${data.method || "?"} ${data.path || "/"}${reset} `; + output += `${dim}${data.duration_ms || 0}ms${reset}`; + + if (data.request_id) { + output += ` ${dim}(${data.request_id.slice(0, 8)})${reset}`; + } + + // Component info (plugin, connector, or service) + if (data.component) { + output += `\n ${cyan}component:${reset} ${data.component.name}`; + if (data.component.operation) output += `.${data.component.operation}`; + } + + // User info + if (data.user?.id) { + output += `\n ${cyan}user:${reset} ${data.user.id}`; + } + + // Execution info + if (data.execution) { + const exec = data.execution; + const parts: string[] = []; + if (exec.cache_hit !== undefined) { + parts.push(`cache:${exec.cache_hit ? "HIT" : "MISS"}`); + } + if (exec.cache_key) { + parts.push(`key:${exec.cache_key.substring(0, 16)}...`); + } + if (exec.retry_attempts) parts.push(`retries:${exec.retry_attempts}`); + if (exec.timeout_ms) parts.push(`timeout:${exec.timeout_ms}ms`); + if (parts.length) { + output += `\n ${cyan}execution:${reset} ${parts.join(", ")}`; + } + } + + // Scoped context (plugin, connector, service specific data) + if (data.context) { + for (const [scopeName, context] of Object.entries(data.context)) { + const contextStr = Object.entries(context) + .map(([k, v]) => `${k}:${formatValue(v)}`) + .join(", "); + output += `\n ${magenta}${scopeName}:${reset} ${contextStr}`; + } + } + + // Logs (if any) + if (data.logs && data.logs.length > 0) { + output += `\n ${cyan}logs:${reset}`; + for (const log of data.logs) { + const levelColor = + log.level === "error" ? red : log.level === "warn" ? yellow : dim; + output += `\n ${levelColor}[${log.level}]${reset} ${log.message}`; + if (log.context) { + output += ` ${dim}${JSON.stringify(log.context)}${reset}`; + } + } + } + + // Error info + if (data.error) { + output += `\n ${red}error:${reset} ${data.error.type}: ${data.error.message}`; + if (data.error.code) output += ` [${data.error.code}]`; + if (data.error.cause) + output += `\n ${magenta}cause:${reset} ${data.error.cause}`; + } + + return output; +} + +function formatValue(value: unknown): string { + if (typeof value === "number") { + // format bytes nicely + if (value > 1024 * 1024) { + return `${(value / (1024 * 1024)).toFixed(1)}MB`; + } + + if (value > 1024) { + return `${(value / 1024).toFixed(1)}KB`; + } + + return String(value); + } + + if (typeof value === "string" && value.length > 20) { + return `${value.substring(0, 20)}...`; + } + + return String(value); +} diff --git a/packages/appkit/src/observability/index.ts b/packages/appkit/src/observability/index.ts new file mode 100644 index 00000000..d681188c --- /dev/null +++ b/packages/appkit/src/observability/index.ts @@ -0,0 +1,13 @@ +export type { Counter, Histogram, Span } from "@opentelemetry/api"; +export { SpanKind, SpanStatusCode } from "@opentelemetry/api"; +export { LoggerManager } from "./logger-manager"; +export * as otel from "./otel"; +export type { + ErrorLogOptions, + ILogger, + LogContext, + MetricOptions, + ObservabilityConfig, + ObservabilityOptions, + SpanOptions, +} from "./types"; diff --git a/packages/appkit/src/observability/instrumentations.ts b/packages/appkit/src/observability/instrumentations.ts new file mode 100644 index 00000000..130e83f5 --- /dev/null +++ b/packages/appkit/src/observability/instrumentations.ts @@ -0,0 +1,69 @@ +import { ExpressInstrumentation } from "@opentelemetry/instrumentation-express"; +import { HttpInstrumentation } from "@opentelemetry/instrumentation-http"; + +/** + * Check if request path should be ignored (assets, static files) + */ +function shouldIgnorePath(path: string): boolean { + // Skip Vite dev server paths + const skipPaths = [ + "/@vite/", + "/@fs/", + "/node_modules/", + "/src/", + "/@react-refresh", + ]; + if (skipPaths.some((skipPath) => path.startsWith(skipPath))) { + return true; + } + + // Skip static assets by extension + if ( + /\.(js|css|json|svg|png|jpg|jpeg|gif|ico|webp|woff|woff2|ttf|eot|otf|map)$/.test( + path, + ) + ) { + return true; + } + + return false; +} + +export const httpInstrumentation = new HttpInstrumentation({ + ignoreIncomingRequestHook: (request) => { + const path = request.url || ""; + return shouldIgnorePath(path); + }, + applyCustomAttributesOnSpan: (span: any, request: any) => { + let spanName: string | null = null; + if (request.route) { + const baseURL = request.baseUrl || ""; + const url = request.url?.split("?")[0] || ""; + const fullPath = baseURL + url; + if (fullPath) { + spanName = `${request.method} ${fullPath}`; + } + } else if (request.url) { + const path = request.path.split("?")[0]; + spanName = `${request.method} ${path}`; + } + + if (spanName) { + span.updateName(spanName); + } + }, +}); + +export const expressInstrumentation = new ExpressInstrumentation({ + requestHook: (span: any, info: any) => { + const req = info.request; + if (info.layerType === "request_handler" && req.route) { + const baseURL = req.baseUrl || ""; + const url = req.url?.split("?")[0] || ""; + const fullPath = baseURL + url; + if (fullPath) { + span.updateName(`${req.method} ${fullPath}`); + } + } + }, +}); diff --git a/packages/appkit/src/observability/logger-manager.ts b/packages/appkit/src/observability/logger-manager.ts new file mode 100644 index 00000000..d93b398f --- /dev/null +++ b/packages/appkit/src/observability/logger-manager.ts @@ -0,0 +1,158 @@ +import type { NextFunction, Request, RequestHandler, Response } from "express"; +import { eventStorage, formatAndEmitWideEvent } from "./context"; +import { createDebug } from "./debug"; +import { Logger } from "./logger"; +import { OTELBridge } from "./otel/bridge"; +import type { ObservabilityConfig, ObservabilityOptions } from "./types"; +import { WideEvent, type WideEventData } from "./wide-event"; + +const debug = createDebug("observability"); + +const MAX_REQUEST_ID_LENGTH = 128; +const REQUEST_ID_PATTERN = /^[a-zA-Z0-9_\-:.]+$/; + +/** + * Sanitize request ID to prevent log injection attacks. + * - Validates format (alphanumeric + safe chars only) + * - Clamps length to prevent DoS + * - Falls back to generated UUID if invalid + */ +function sanitizeRequestId(rawId: string | undefined): string { + if (!rawId) return crypto.randomUUID(); + + const trimmed = rawId.slice(0, MAX_REQUEST_ID_LENGTH); + + if (!REQUEST_ID_PATTERN.test(trimmed)) { + return crypto.randomUUID(); + } + + return trimmed; +} + +/** + * Logger Manager + * - Responsible for initializing the OTEL bridge and creating loggers + * - Provides a singleton instance of the LoggerManager + * - Provides a method to get the OTEL bridge + * - Provides a method to get the middleware + * - Provides a method to shutdown the LoggerManager + */ +export class LoggerManager { + private static instance?: LoggerManager; + private otelBridge: OTELBridge; + + private constructor(config: ObservabilityConfig = {}) { + this.otelBridge = new OTELBridge(config); + debug("LoggerManager initialized", { config }); + } + + static initialize(config: ObservabilityConfig = {}): void { + if (LoggerManager.instance) { + debug("LoggerManager already initialized, skipping"); + return; + } + LoggerManager.instance = new LoggerManager(config); + } + + static getInstance(): LoggerManager { + if (!LoggerManager.instance) { + LoggerManager.instance = new LoggerManager(); + } + return LoggerManager.instance; + } + + static getLogger(scope: string, config?: ObservabilityOptions): Logger { + const manager = LoggerManager.getInstance(); + return manager.createLogger(scope, config); + } + + static getOTELBridge(): OTELBridge { + const manager = LoggerManager.getInstance(); + return manager.otelBridge; + } + + /** + * Get the observability middleware. + * Creates WideEvent, formats to terminal, and sends to OTEL. + */ + static getMiddleware(): RequestHandler { + const manager = LoggerManager.getInstance(); + + return (req: Request, res: Response, next: NextFunction) => { + const requestId = sanitizeRequestId( + req.headers["x-request-id"] as string, + ); + res.setHeader("x-request-id", requestId); + + // Create WideEvent and set initial context + const event = new WideEvent(requestId); + event.set("method", req.method); + event.set("path", req.path); + + // Set user context if available (only id for security) + if ((req as any).user?.id) { + event.setUser({ id: (req as any).user.id }); + } + + // On response finish: format to terminal AND send to OTEL + res.on("finish", () => { + const data = formatAndEmitWideEvent(event, res.statusCode); + if (data) { + manager.emitWideEventToOTEL(data); + } + }); + + // Run in AsyncLocalStorage context + eventStorage.run(event, () => next()); + }; + } + + static async shutdown(): Promise { + if (LoggerManager.instance) { + await LoggerManager.instance.otelBridge.shutdown(); + LoggerManager.instance = undefined; + debug("LoggerManager shutdown complete"); + } + } + + /** + * Emit WideEvent to OTEL Logs. + * This is called by the WideEvent middleware at request end. + * @internal + */ + private emitWideEventToOTEL(event: WideEventData): void { + try { + if (!this.otelBridge.isEnabled()) return; + + const logger = this.otelBridge.getLogger("appkit.wide-event"); + + // Determine severity based on status code and errors + let severityNumber = 9; // INFO + if (event.error) { + severityNumber = 17; // ERROR + } else if (event.status_code && event.status_code >= 400) { + severityNumber = 17; // ERROR + } else if (event.status_code && event.status_code >= 300) { + severityNumber = 13; // WARN + } + + logger.emit({ + body: JSON.stringify(event), + severityNumber, + }); + + debug("WideEvent emitted to OTEL", { + request_id: event.request_id, + status_code: event.status_code, + }); + } catch (error) { + // Silently fail - don't break the app if OTEL is down + debug("Failed to emit WideEvent to OTEL", { error }); + } + } + + private createLogger(scope: string, config?: ObservabilityOptions): Logger { + const scopedOtel = this.otelBridge.createScoped(scope, config); + return new Logger(scope, scopedOtel); + } +} diff --git a/packages/appkit/src/observability/logger.ts b/packages/appkit/src/observability/logger.ts new file mode 100644 index 00000000..2819562c --- /dev/null +++ b/packages/appkit/src/observability/logger.ts @@ -0,0 +1,270 @@ +import { + type Attributes, + type Counter, + type Histogram, + type Span, + SpanStatusCode, + trace, +} from "@opentelemetry/api"; +import { getWideEvent } from "./context"; +import { createDebug } from "./debug"; +import type { ScopedOTELBridge } from "./otel/bridge"; +import type { + ErrorLogOptions, + ILogger, + LogContext, + MetricOptions, + SpanOptions, +} from "./types"; + +/** + * Logger + * - Responsible for logging messages to the console and OTEL + */ +export class Logger implements ILogger { + private readonly scope: string; + private readonly obug: ReturnType; + private readonly otel: ScopedOTELBridge; + + constructor(scope: string, otel: ScopedOTELBridge) { + this.scope = scope; + this.obug = createDebug(scope); + this.otel = otel; + } + + /** + * Log a debug message + * @param message - The message to log + * @param context - The context of the message + */ + debug(message: string, context?: LogContext): void { + if (context) { + this.obug("%s %o", message, context); + } else { + this.obug(message); + } + } + + /** + * Log a trace message for detailed debugging + * Goes to: Terminal + OTEL logs + WideEvent + * @param message - The message to log + * @param context - The context of the message + */ + trace(message: string, context?: LogContext): void { + // Terminal output with DEBUG=appkit:* + this.debug(message, context); + + // Add to WideEvent for request correlation + const event = getWideEvent(); + if (event) { + event.addLog("debug", message, context); + if (context) { + event.setContext(this.scope, context); + } + } + + // Send to OTEL logs (unlike debug, this goes to observability backend) + this.otel.emitLog("debug", message, context); + } + + /** + * Log an info message + * @param message - The message to log + * @param context - The context of the message + */ + info(message: string, context?: LogContext): void { + this.debug(message, context); + + // add to wide event if in request context + const event = getWideEvent(); + if (event) { + event.addLog("info", message, context); + // also merge into scoped context for the summary + if (context) { + event.setContext(this.scope, context); + } + } + + // add as span event to current span (if any) + if (context) { + const currentSpan = trace.getActiveSpan(); + currentSpan?.addEvent(message, context as Attributes); + } + } + /** + * Log a warning message + * @param message - The message to log + * @param context - The context of the message + */ + warn(message: string, context?: LogContext): void { + this.debug(`WARN: ${message}`, context); + + const event = getWideEvent(); + if (event) { + event.addLog("warn", message, context); + if (context) { + event.setContext(this.scope, context); + } + } + + if (context) { + const currentSpan = trace.getActiveSpan(); + currentSpan?.addEvent(`WARN: ${message}`, context as Attributes); + } + } + + /** + * Log an error message + * @param message - The message to log + * @param error - The error to log + * @param context - The context of the message + * @param options - Optional error logging configuration + */ + error( + message: string, + error?: Error, + context?: LogContext, + options?: ErrorLogOptions, + ): void { + const fullContext = error + ? { ...context, error: error.message, stack: error.stack } + : context; + + this.debug(`ERROR: ${message}`, fullContext); + + const event = getWideEvent(); + if (event) { + if (error) { + event.setError(error); + } + event.addLog("error", message, context); + if (context) { + event.setContext(this.scope, context); + } + } + + // Record on current span (default: true) + const recordOnSpan = options?.recordOnSpan ?? true; + if (recordOnSpan) { + const currentSpan = trace.getActiveSpan(); + if (currentSpan) { + if (error) { + currentSpan.recordException(error); + } + if (fullContext) { + currentSpan.addEvent(`ERROR: ${message}`, fullContext as Attributes); + } + } + } + } + + /** + * Execute a function within a traced span + * @param name - The name of the span + * @param fn - The function to execute within the span + * @param options - The options for the span + * @returns The result of the function + */ + async span( + name: string, + fn: (span: Span) => Promise, + options?: SpanOptions, + ): Promise { + const spanName = `${this.scope}.${name}`; + + return this.otel.startActiveSpan( + spanName, + options?.attributes || {}, + async (span) => { + const event = getWideEvent(); + event?.setComponent(this.scope, name); + + try { + const result = await fn(span); + span.setStatus({ code: SpanStatusCode.OK }); + return result; + } catch (error) { + span.recordException(error as Error); + span.setStatus({ + code: SpanStatusCode.ERROR, + message: (error as Error).message, + }); + event?.setError(error as Error); + throw error; + } + }, + ); + } + + /** + * Create a counter metric + * @param name - The name of the counter + * @param options - The options for the counter + * @returns The counter + */ + counter(name: string, options?: MetricOptions): Counter { + return this.otel.createCounter(`${this.scope}.${name}`, options); + } + + /** + * Create a histogram metric + * @param name - The name of the histogram + * @param options - The options for the histogram + * @returns The histogram + */ + histogram(name: string, options?: MetricOptions): Histogram { + return this.otel.createHistogram(`${this.scope}.${name}`, options); + } + + /** + * Record context to WideEvent and current span without generating a log entry. + * Use this to enrich the request context with metadata. + * @param context - Context data to record + */ + recordContext(context: LogContext): void { + // Add to WideEvent context (scoped) + const event = getWideEvent(); + if (event) { + event.setContext(this.scope, context); + } + + // Add to current span as attributes (not an event) + const currentSpan = trace.getActiveSpan(); + if (currentSpan) { + for (const [key, value] of Object.entries(context)) { + if ( + typeof value === "string" || + typeof value === "number" || + typeof value === "boolean" + ) { + currentSpan.setAttribute(`${this.scope}.${key}`, value); + } + } + } + } + + /** + * Get the current WideEvent if in request context (advanced usage). + * Returns undefined if called outside of a request context. + * @returns The current WideEvent or undefined + */ + getEvent() { + return getWideEvent(); + } + + /** + * Create a child logger with additional scope. + * The child scope will be appended to the parent scope with a colon separator. + * @param childScope - The additional scope name to append + * @returns A new ILogger instance with the combined scope + * @example + * const parentLogger = LoggerManager.getLogger("analytics"); + * const childLogger = parentLogger.child("query"); + * // childLogger scope: "analytics:query" + */ + child(childScope: string): ILogger { + const newScope = `${this.scope}:${childScope}`; + return new Logger(newScope, this.otel.createScoped(newScope)); + } +} diff --git a/packages/appkit/src/observability/otel/bridge.ts b/packages/appkit/src/observability/otel/bridge.ts new file mode 100644 index 00000000..5dded639 --- /dev/null +++ b/packages/appkit/src/observability/otel/bridge.ts @@ -0,0 +1,398 @@ +import { + type Attributes, + type Counter, + type Histogram, + type Meter, + metrics, + type Span, + type Tracer, + trace, +} from "@opentelemetry/api"; +import { type Logger, logs, SeverityNumber } from "@opentelemetry/api-logs"; +import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-proto"; +import { OTLPMetricExporter } from "@opentelemetry/exporter-metrics-otlp-proto"; +import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-proto"; +import { + detectResources, + envDetector, + hostDetector, + processDetector, + resourceFromAttributes, +} from "@opentelemetry/resources"; +import { BatchLogRecordProcessor } from "@opentelemetry/sdk-logs"; +import { PeriodicExportingMetricReader } from "@opentelemetry/sdk-metrics"; +import { NodeSDK } from "@opentelemetry/sdk-node"; +import { + ATTR_SERVICE_NAME, + ATTR_SERVICE_VERSION, +} from "@opentelemetry/semantic-conventions"; +import { createDebug } from "../debug"; +import { + expressInstrumentation, + httpInstrumentation, +} from "../instrumentations"; +import type { + MetricOptions, + ObservabilityConfig, + ObservabilityOptions, +} from "../types"; +import { NOOP_COUNTER, NOOP_HISTOGRAM, NOOP_SPAN } from "./noop"; + +const debug = createDebug("otel"); + +/** + * OTEL Bridge + * - Responsible for initializing the OpenTelemetry SDK and creating scoped bridges + */ +export class OTELBridge { + private sdk?: NodeSDK; + private enabled: boolean; + private config: ObservabilityConfig; + + constructor(config: ObservabilityConfig = {}) { + this.config = config; + this.enabled = + config.enabled !== false && !!process.env.OTEL_EXPORTER_OTLP_ENDPOINT; + if (this.enabled) { + this.initializeSdk(); + } else { + debug("OTEL disabled (no OTEL_EXPORTER_OTLP_ENDPOINT)"); + } + } + + /** + * Initialize the OpenTelemetry SDK + */ + private initializeSdk(): void { + const endpoint = process.env.OTEL_EXPORTER_OTLP_ENDPOINT; + if (!endpoint) { + this.enabled = false; + debug("OTEL disabled (no OTEL_EXPORTER_OTLP_ENDPOINT)"); + return; + } + const serviceName = + this.config.serviceName || + process.env.OTEL_SERVICE_NAME || + process.env.DATABRICKS_APP_NAME || + "databricks-app"; + + // Respect config flags (default to true if not specified) + const tracesEnabled = this.config.traces !== false; + const metricsEnabled = this.config.metrics !== false; + const logsEnabled = this.config.logs !== false; + + debug("Initializing OTEL SDK", { + endpoint, + serviceName, + traces: tracesEnabled, + metrics: metricsEnabled, + logs: logsEnabled, + }); + + // create resource with service attributes and detected resources + const initialResource = resourceFromAttributes({ + [ATTR_SERVICE_NAME]: serviceName, + [ATTR_SERVICE_VERSION]: this.config.serviceVersion || "unknown", + }); + const detectedResource = detectResources({ + detectors: [envDetector, hostDetector, processDetector], + }); + const resource = initialResource.merge(detectedResource); + + // Build SDK config conditionally based on flags + const sdkConfig: ConstructorParameters[0] = { + resource, + autoDetectResources: false, + instrumentations: tracesEnabled + ? [httpInstrumentation, expressInstrumentation] + : [], + }; + + if (tracesEnabled) { + sdkConfig.traceExporter = new OTLPTraceExporter({ + url: `${endpoint}/v1/traces`, + headers: this.config.headers, + }); + } + + if (metricsEnabled) { + const metricExporter: any = new OTLPMetricExporter({ + url: `${endpoint}/v1/metrics`, + headers: this.config.headers, + }); + + // provide a safe default to avoid runtime errors + if (typeof metricExporter.forceFlush !== "function") { + metricExporter.forceFlush = async () => {}; + } + + const metricReader = new PeriodicExportingMetricReader({ + exporter: metricExporter, + exportIntervalMillis: this.config.exportIntervalMs || 10000, + }); + + sdkConfig.metricReaders = [ + ...(sdkConfig.metricReaders ?? []), + metricReader, + ]; + } + + if (logsEnabled) { + sdkConfig.logRecordProcessor = new BatchLogRecordProcessor( + new OTLPLogExporter({ + url: `${endpoint}/v1/logs`, + headers: this.config.headers, + }), + ); + } + + this.sdk = new NodeSDK(sdkConfig); + + this.sdk.start(); + debug("OTEL SDK started"); + } + + /** + * Create a scoped OTEL bridge + * @param scope - The scope of the bridge + * @param config - The configuration for the bridge + * @returns The scoped OTEL bridge + */ + createScoped(scope: string, config?: ObservabilityOptions): ScopedOTELBridge { + return new ScopedOTELBridge(scope, this, config); + } + + /** + * Get a tracer for the given name + * @param name - The name of the tracer + * @returns The tracer + */ + getTracer(name: string): Tracer { + return trace.getTracer(name); + } + + /** + * Get a meter for the given name + * @param name - The name of the meter + * @returns The meter + */ + getMeter(name: string): Meter { + return metrics.getMeter(name); + } + + /** + * Get a logger for the given name + * @param name - The name of the logger + * @returns The logger + */ + getLogger(name: string): Logger { + return logs.getLogger(name); + } + + /** + * Check if OTEL is enabled + * @returns True if OTEL is enabled, false otherwise + */ + isEnabled(): boolean { + return this.enabled; + } + + /** + * Register OpenTelemetry instrumentations. + * Note: This is currently a no-op as instrumentations are registered during SDK initialization. + * @param instrumentations - Array of OpenTelemetry instrumentations to register + */ + registerInstrumentations(instrumentations: unknown[]): void { + debug("Registering instrumentations", { count: instrumentations.length }); + } + + /** + * Shutdown the OpenTelemetry SDK + */ + async shutdown(): Promise { + if (this.sdk) { + debug("Shutting down OTEL SDK"); + await this.sdk.shutdown(); + } + } +} + +/** + * Scoped OTEL Bridge + */ +export class ScopedOTELBridge { + private scope: string; + private bridge: OTELBridge; + private tracesEnabled: boolean; + private metricsEnabled: boolean; + private logsEnabled: boolean; + + constructor( + scope: string, + bridge: OTELBridge, + config?: ObservabilityOptions, + ) { + this.scope = scope; + this.bridge = bridge; + + // normalize config + if (typeof config === "boolean") { + this.tracesEnabled = config && bridge.isEnabled(); + this.metricsEnabled = config && bridge.isEnabled(); + this.logsEnabled = config && bridge.isEnabled(); + } else { + this.tracesEnabled = (config?.traces ?? true) && bridge.isEnabled(); + this.metricsEnabled = (config?.metrics ?? true) && bridge.isEnabled(); + this.logsEnabled = (config?.logs ?? true) && bridge.isEnabled(); + } + } + + /** + * Start an active span + * @param name - The name of the span + * @param attributes - The attributes for the span + * @param fn - The function to execute within the span + * @returns The result of the function + */ + async startActiveSpan( + name: string, + attributes: Attributes, + fn: (span: Span) => Promise, + ): Promise { + if (!this.tracesEnabled) { + return fn(NOOP_SPAN); + } + + const tracer = this.bridge.getTracer(this.scope); + return tracer.startActiveSpan(name, { attributes }, (span) => { + return fn(span) + .then((result) => { + span.end(); + return result; + }) + .catch((error) => { + span.end(); + throw error; + }); + }); + } + + /** + * Get a meter for the given name + * @param name - The name of the meter + * @returns The meter + */ + getMeter(name: string): Meter { + return this.bridge.getMeter(name); + } + /** + * Get a logger for the given name + * @param name - The name of the logger + * @returns The logger + */ + getLogger(name: string): Logger { + return this.bridge.getLogger(name); + } + + /** + * Emit a log + * @param level - The level of the log + * @param message - The message of the log + * @param context - The context of the log + */ + emitLog( + level: string, + message: string, + context?: Record, + ): void { + if (!this.logsEnabled) return; + + const logger = this.bridge.getLogger(this.scope); + + // Convert context to OTEL Attributes (only primitives allowed) + const attributes: Attributes = {}; + if (context) { + for (const [key, value] of Object.entries(context)) { + if ( + typeof value === "string" || + typeof value === "number" || + typeof value === "boolean" + ) { + attributes[key] = value; + } else if (value !== null && value !== undefined) { + // Stringify complex values + attributes[key] = JSON.stringify(value); + } + } + } + + logger.emit({ + body: message, + severityNumber: this.levelToSeverity(level), + attributes, + }); + } + + /** + * Create a counter + * @param name - The name of the counter + * @param options - The options for the counter + * @returns The counter + */ + createCounter(name: string, options?: MetricOptions): Counter { + if (!this.metricsEnabled) return NOOP_COUNTER; + + return this.bridge.getMeter(this.scope).createCounter(name, { + unit: options?.unit, + description: options?.description, + }); + } + + /** + * Create a histogram + * @param name - The name of the histogram + * @param options - The options for the histogram + * @returns The histogram + */ + createHistogram(name: string, options?: MetricOptions): Histogram { + if (!this.metricsEnabled) return NOOP_HISTOGRAM; + + return this.bridge.getMeter(this.scope).createHistogram(name, { + unit: options?.unit, + description: options?.description, + }); + } + + /** + * Create a scoped OTEL bridge + * @param childScope - The child scope of the bridge + * @returns The scoped OTEL bridge + */ + createScoped(childScope: string): ScopedOTELBridge { + return new ScopedOTELBridge(`${this.scope}.${childScope}`, this.bridge, { + traces: this.tracesEnabled, + metrics: this.metricsEnabled, + logs: this.logsEnabled, + }); + } + + /** + * Convert a log level to a severity number + * @param level - The level of the log + * @returns The severity number + */ + private levelToSeverity(level: string): SeverityNumber { + switch (level) { + case "debug": + return SeverityNumber.DEBUG; + case "info": + return SeverityNumber.INFO; + case "warn": + return SeverityNumber.WARN; + case "error": + return SeverityNumber.ERROR; + default: + return SeverityNumber.INFO; + } + } +} diff --git a/packages/appkit/src/observability/otel/index.ts b/packages/appkit/src/observability/otel/index.ts new file mode 100644 index 00000000..633be8c6 --- /dev/null +++ b/packages/appkit/src/observability/otel/index.ts @@ -0,0 +1,23 @@ +import { metrics, trace } from "@opentelemetry/api"; +import { logs } from "@opentelemetry/api-logs"; + +export const getTracer = trace.getTracer.bind(trace); +export const getMeter = metrics.getMeter.bind(metrics); +export const getLogger = logs.getLogger.bind(logs); + +// Re-export useful OTEL types +export type { + Counter, + Histogram, + Meter, + Tracer, +} from "@opentelemetry/api"; +export { + metrics, + SpanKind, + SpanStatusCode, + trace, +} from "@opentelemetry/api"; +export type { Logger as OTELLogger } from "@opentelemetry/api-logs"; + +export { logs } from "@opentelemetry/api-logs"; diff --git a/packages/appkit/src/observability/otel/noop.ts b/packages/appkit/src/observability/otel/noop.ts new file mode 100644 index 00000000..e1910f36 --- /dev/null +++ b/packages/appkit/src/observability/otel/noop.ts @@ -0,0 +1,35 @@ +import { + type Counter, + type Histogram, + type Span, + type SpanContext, + TraceFlags, +} from "@opentelemetry/api"; + +const NOOP_SPAN_CONTEXT: SpanContext = { + traceId: "00000000000000000000000000000000", + spanId: "0000000000000000", + traceFlags: TraceFlags.NONE, +}; + +export const NOOP_SPAN: Span = { + spanContext: () => NOOP_SPAN_CONTEXT, + setAttribute: () => NOOP_SPAN, + setAttributes: () => NOOP_SPAN, + addEvent: () => NOOP_SPAN, + addLink: () => NOOP_SPAN, + addLinks: () => NOOP_SPAN, + setStatus: () => NOOP_SPAN, + updateName: () => NOOP_SPAN, + end: () => {}, + isRecording: () => false, + recordException: () => {}, +}; + +export const NOOP_COUNTER: Counter = { + add: () => {}, +}; + +export const NOOP_HISTOGRAM: Histogram = { + record: () => {}, +}; diff --git a/packages/appkit/src/observability/otel/tests/bridge.test.ts b/packages/appkit/src/observability/otel/tests/bridge.test.ts new file mode 100644 index 00000000..e234ce9c --- /dev/null +++ b/packages/appkit/src/observability/otel/tests/bridge.test.ts @@ -0,0 +1,269 @@ +import { afterEach, beforeEach, describe, expect, test, vi } from "vitest"; +import { OTELBridge, ScopedOTELBridge } from "../bridge"; + +// Mock OTEL SDK +vi.mock("@opentelemetry/sdk-node", () => ({ + NodeSDK: vi.fn().mockImplementation(() => ({ + start: vi.fn(), + shutdown: vi.fn().mockResolvedValue(undefined), + })), +})); + +vi.mock("@opentelemetry/exporter-trace-otlp-proto"); +vi.mock("@opentelemetry/exporter-metrics-otlp-proto"); +vi.mock("@opentelemetry/exporter-logs-otlp-proto"); + +describe("OTELBridge", () => { + let originalEnv: NodeJS.ProcessEnv; + + beforeEach(() => { + originalEnv = { ...process.env }; + vi.clearAllMocks(); + }); + + afterEach(() => { + process.env = originalEnv; + }); + + describe("Initialization", () => { + test("should initialize when OTEL endpoint is configured", () => { + process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; + + const bridge = new OTELBridge({ serviceName: "test-service" }); + + expect(bridge.isEnabled()).toBe(true); + }); + + test("should not initialize when OTEL endpoint is missing", () => { + delete process.env.OTEL_EXPORTER_OTLP_ENDPOINT; + + const bridge = new OTELBridge(); + + expect(bridge.isEnabled()).toBe(false); + }); + + test("should respect enabled: false config", () => { + process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; + + const bridge = new OTELBridge({ enabled: false }); + + expect(bridge.isEnabled()).toBe(false); + }); + }); + + describe("createScoped()", () => { + test("should create scoped bridge with scope name", () => { + const bridge = new OTELBridge(); + const scoped = bridge.createScoped("test-plugin"); + + expect(scoped).toBeInstanceOf(ScopedOTELBridge); + }); + + test("should pass observability options to scoped bridge", () => { + const bridge = new OTELBridge(); + const scoped = bridge.createScoped("test-plugin", { + traces: false, + metrics: true, + }); + + expect(scoped).toBeDefined(); + }); + }); + + describe("shutdown()", () => { + test("should shutdown SDK", async () => { + process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; + + const bridge = new OTELBridge(); + await bridge.shutdown(); + + // Should not throw + }); + + test("should handle shutdown when SDK not initialized", async () => { + const bridge = new OTELBridge(); + await expect(bridge.shutdown()).resolves.not.toThrow(); + }); + }); +}); + +describe("ScopedOTELBridge", () => { + let mockBridge: OTELBridge; + let mockTracer: any; + let mockMeter: any; + + beforeEach(() => { + mockTracer = { + startActiveSpan: vi.fn(), + }; + + mockMeter = { + createCounter: vi.fn().mockReturnValue({ add: vi.fn() }), + createHistogram: vi.fn().mockReturnValue({ record: vi.fn() }), + }; + + mockBridge = { + isEnabled: vi.fn().mockReturnValue(true), + getTracer: vi.fn().mockReturnValue(mockTracer), + getMeter: vi.fn().mockReturnValue(mockMeter), + getLogger: vi.fn().mockReturnValue({ emit: vi.fn() }), + } as any; + }); + + describe("Observability options", () => { + test("should enable all by default when bridge is enabled", () => { + const scoped = new ScopedOTELBridge("test", mockBridge); + + scoped.createCounter("test"); + scoped.createHistogram("test"); + + expect(mockMeter.createCounter).toHaveBeenCalled(); + expect(mockMeter.createHistogram).toHaveBeenCalled(); + }); + + test("should respect boolean config", () => { + const scoped = new ScopedOTELBridge("test", mockBridge, false); + + const _counter = scoped.createCounter("test"); + const _histogram = scoped.createHistogram("test"); + + // Should return noop instances + expect(mockMeter.createCounter).not.toHaveBeenCalled(); + expect(mockMeter.createHistogram).not.toHaveBeenCalled(); + }); + + test("should respect granular config", () => { + const scoped = new ScopedOTELBridge("test", mockBridge, { + traces: true, + metrics: false, + logs: true, + }); + + scoped.createCounter("test"); + expect(mockMeter.createCounter).not.toHaveBeenCalled(); // metrics disabled + }); + }); + + describe("startActiveSpan()", () => { + test("should create span when traces enabled", async () => { + const scoped = new ScopedOTELBridge("test", mockBridge, { traces: true }); + + mockTracer.startActiveSpan.mockImplementation( + (_name: string, _opts: any, fn: any) => { + const mockSpan = { + end: vi.fn(), + setAttribute: vi.fn(), + setStatus: vi.fn(), + }; + return fn(mockSpan); + }, + ); + + await scoped.startActiveSpan("test-span", {}, async (_span) => { + return "result"; + }); + + expect(mockTracer.startActiveSpan).toHaveBeenCalledWith( + "test-span", + { attributes: {} }, + expect.any(Function), + ); + }); + + test("should return noop span when traces disabled", async () => { + const scoped = new ScopedOTELBridge("test", mockBridge, { + traces: false, + }); + + const result = await scoped.startActiveSpan("test", {}, async (span) => { + expect(span.isRecording()).toBe(false); + return "result"; + }); + + expect(result).toBe("result"); + expect(mockTracer.startActiveSpan).not.toHaveBeenCalled(); + }); + }); + + describe("createCounter()", () => { + test("should create counter with scoped name", () => { + const scoped = new ScopedOTELBridge("test-plugin", mockBridge); + + scoped.createCounter("requests", { description: "Total requests" }); + + expect(mockMeter.createCounter).toHaveBeenCalledWith("requests", { + unit: undefined, + description: "Total requests", + }); + }); + + test("should return noop counter when metrics disabled", () => { + const scoped = new ScopedOTELBridge("test", mockBridge, { + metrics: false, + }); + + const counter = scoped.createCounter("test"); + + expect(mockMeter.createCounter).not.toHaveBeenCalled(); + expect(() => counter.add(1)).not.toThrow(); + }); + }); + + describe("createHistogram()", () => { + test("should create histogram with options", () => { + const scoped = new ScopedOTELBridge("test-plugin", mockBridge); + + scoped.createHistogram("duration", { unit: "ms" }); + + expect(mockMeter.createHistogram).toHaveBeenCalledWith("duration", { + unit: "ms", + description: undefined, + }); + }); + + test("should return noop histogram when metrics disabled", () => { + const scoped = new ScopedOTELBridge("test", mockBridge, { + metrics: false, + }); + + const histogram = scoped.createHistogram("test"); + + expect(mockMeter.createHistogram).not.toHaveBeenCalled(); + expect(() => histogram.record(100)).not.toThrow(); + }); + }); + + describe("createScoped()", () => { + test("should create nested scoped bridge", () => { + const scoped = new ScopedOTELBridge("parent", mockBridge); + const child = scoped.createScoped("child"); + + expect(child).toBeInstanceOf(ScopedOTELBridge); + }); + }); + + describe("emitLog()", () => { + test("should emit log when logs enabled", () => { + const mockLogger = { emit: vi.fn() }; + mockBridge.getLogger = vi.fn().mockReturnValue(mockLogger); + + const scoped = new ScopedOTELBridge("test", mockBridge, { logs: true }); + + scoped.emitLog("info", "Test message", { key: "value" }); + + expect(mockLogger.emit).toHaveBeenCalledWith({ + body: "Test message", + severityNumber: expect.any(Number), + attributes: { key: "value" }, + }); + }); + + test("should not emit log when logs disabled", () => { + const scoped = new ScopedOTELBridge("test", mockBridge, { logs: false }); + + scoped.emitLog("info", "Test message"); + + expect(mockBridge.getLogger).not.toHaveBeenCalled(); + }); + }); +}); diff --git a/packages/appkit/src/observability/tests/context.test.ts b/packages/appkit/src/observability/tests/context.test.ts new file mode 100644 index 00000000..2775ef0b --- /dev/null +++ b/packages/appkit/src/observability/tests/context.test.ts @@ -0,0 +1,133 @@ +import { afterEach, beforeEach, describe, expect, test } from "vitest"; +import { formatAndEmitWideEvent, getWideEvent, shouldSample } from "../context"; +import { WideEvent } from "../wide-event"; + +describe("context", () => { + let originalEnv: NodeJS.ProcessEnv; + + beforeEach(() => { + originalEnv = { ...process.env }; + // Set sampling to 100% to test filtering logic (not random sampling) + process.env.APPKIT_LOG_SAMPLING = "1.0"; + }); + + afterEach(() => { + process.env = originalEnv; + }); + describe("getWideEvent()", () => { + test("should return undefined when not in request context", () => { + const event = getWideEvent(); + expect(event).toBeUndefined(); + }); + }); + + describe("shouldSample()", () => { + test("should filter Vite dev server paths", () => { + const event = new WideEvent("req-1"); + event.set("path", "/@vite/client"); + + expect(shouldSample(event.toJSON())).toBe(false); + }); + + test("should filter @fs paths", () => { + const event = new WideEvent("req-1"); + event.set("path", "/@fs/Users/victor/project/file.js"); + + expect(shouldSample(event.toJSON())).toBe(false); + }); + + test("should filter node_modules paths", () => { + const event = new WideEvent("req-1"); + event.set("path", "/node_modules/package/file.js"); + + expect(shouldSample(event.toJSON())).toBe(false); + }); + + test("should filter static asset extensions", () => { + const extensions = ["js", "css", "png", "svg", "woff", "map"]; + + for (const ext of extensions) { + const event = new WideEvent("req-1"); + event.set("path", `/static/file.${ext}`); + + expect(shouldSample(event.toJSON())).toBe(false); + } + }); + + test("should always keep error responses (4xx)", () => { + const event = new WideEvent("req-1"); + event.set("path", "/api/test"); + event.set("status_code", 404); + + expect(shouldSample(event.toJSON())).toBe(true); + }); + + test("should always keep server errors (5xx)", () => { + const event = new WideEvent("req-1"); + event.set("path", "/api/test"); + event.set("status_code", 500); + + expect(shouldSample(event.toJSON())).toBe(true); + }); + + test("should always keep requests with errors", () => { + const event = new WideEvent("req-1"); + event.set("path", "/api/test"); + event.setError(new Error("Test error")); + + expect(shouldSample(event.toJSON())).toBe(true); + }); + + test("should always keep slow requests (>10s)", () => { + const event = new WideEvent("req-1"); + event.set("path", "/api/test"); + event.set("duration_ms", 15000); + + expect(shouldSample(event.toJSON())).toBe(true); + }); + + test("should always keep retried requests", () => { + const event = new WideEvent("req-1"); + event.set("path", "/api/test"); + event.setExecution({ retry_attempts: 2 }); + + expect(shouldSample(event.toJSON())).toBe(true); + }); + + test("should sample API requests based on APPKIT_LOG_SAMPLING", () => { + const event = new WideEvent("req-1"); + event.set("path", "/api/test"); + event.set("status_code", 200); + + // Should be sampled (default APPKIT_LOG_SAMPLING = 1.0) + const result = shouldSample(event); + expect(typeof result).toBe("boolean"); + }); + }); + + describe("formatAndEmitWideEvent()", () => { + test("should return null for filtered events", () => { + const event = new WideEvent("req-1"); + event.set("path", "/@vite/client"); + + const result = formatAndEmitWideEvent(event, 200); + + expect(result).toBeNull(); + }); + + test("should return finalized data for sampled events", () => { + const event = new WideEvent("req-1"); + event.set("method", "POST"); + event.set("path", "/api/test"); + + const result = formatAndEmitWideEvent(event, 200); + + expect(result).not.toBeNull(); + expect(result?.request_id).toBe("req-1"); + expect(result?.method).toBe("POST"); + expect(result?.path).toBe("/api/test"); + expect(result?.status_code).toBe(200); + expect(result?.duration_ms).toBeGreaterThanOrEqual(0); + }); + }); +}); diff --git a/packages/appkit/src/observability/tests/logger-manager.test.ts b/packages/appkit/src/observability/tests/logger-manager.test.ts new file mode 100644 index 00000000..c7be5c19 --- /dev/null +++ b/packages/appkit/src/observability/tests/logger-manager.test.ts @@ -0,0 +1,167 @@ +import { afterEach, beforeEach, describe, expect, test, vi } from "vitest"; +import { LoggerManager } from "../logger-manager"; + +// Mock OTEL exports to prevent actual SDK initialization +vi.mock("@opentelemetry/exporter-trace-otlp-proto", () => ({ + OTLPTraceExporter: vi.fn(() => ({ + export: vi.fn((_spans, callback) => callback({ code: 0 })), + shutdown: vi.fn().mockResolvedValue(undefined), + })), +})); + +vi.mock("@opentelemetry/exporter-metrics-otlp-proto", () => ({ + OTLPMetricExporter: vi.fn(() => ({ + export: vi.fn((_metrics, callback) => callback({ code: 0 })), + shutdown: vi.fn().mockResolvedValue(undefined), + })), +})); + +vi.mock("@opentelemetry/exporter-logs-otlp-proto", () => ({ + OTLPLogExporter: vi.fn(() => ({ + export: vi.fn((_logs, callback) => callback({ code: 0 })), + shutdown: vi.fn().mockResolvedValue(undefined), + })), +})); + +describe("LoggerManager", () => { + let originalEnv: NodeJS.ProcessEnv; + + beforeEach(() => { + originalEnv = { ...process.env }; + vi.clearAllMocks(); + // @ts-expect-error - accessing private static property for testing + LoggerManager.instance = undefined; + }); + + afterEach(() => { + process.env = originalEnv; + }); + + describe("Singleton behavior", () => { + test("getInstance() should return singleton instance", () => { + const instance1 = LoggerManager.getInstance(); + const instance2 = LoggerManager.getInstance(); + + expect(instance1).toBe(instance2); + }); + + test("initialize() should not reinitialize if already initialized", () => { + LoggerManager.initialize({ serviceName: "test-1" }); + LoggerManager.initialize({ serviceName: "test-2" }); + + // Should only initialize once + const instance = LoggerManager.getInstance(); + expect(instance).toBeDefined(); + }); + }); + + describe("getLogger()", () => { + test("should create logger with scope", () => { + const logger = LoggerManager.getLogger("test-plugin"); + + expect(logger).toBeDefined(); + expect(logger.debug).toBeDefined(); + expect(logger.info).toBeDefined(); + expect(logger.span).toBeDefined(); + }); + + test("should create loggers with different scopes", () => { + const logger1 = LoggerManager.getLogger("plugin-1"); + const logger2 = LoggerManager.getLogger("plugin-2"); + + expect(logger1).not.toBe(logger2); + }); + + test("should respect observability config", () => { + const logger = LoggerManager.getLogger("test-plugin", { + traces: false, + metrics: true, + logs: true, + }); + + expect(logger).toBeDefined(); + }); + }); + + describe("getOTELBridge()", () => { + test("should return OTEL bridge instance", () => { + const bridge = LoggerManager.getOTELBridge(); + + expect(bridge).toBeDefined(); + expect(bridge.isEnabled).toBeDefined(); + }); + }); + + describe("getMiddleware()", () => { + test("should return Express middleware function", () => { + const middleware = LoggerManager.getMiddleware(); + + expect(typeof middleware).toBe("function"); + expect(middleware.length).toBe(3); // (req, res, next) + }); + + test("should create WideEvent and set in AsyncLocalStorage", () => { + const middleware = LoggerManager.getMiddleware(); + + const mockReq: any = { + headers: { "x-request-id": "test-123" }, + method: "POST", + path: "/api/test", + }; + const mockRes: any = { + setHeader: vi.fn(), + on: vi.fn(), + }; + const mockNext = vi.fn(); + + middleware(mockReq, mockRes, mockNext); + + expect(mockRes.setHeader).toHaveBeenCalledWith( + "x-request-id", + "test-123", + ); + expect(mockRes.on).toHaveBeenCalledWith("finish", expect.any(Function)); + expect(mockNext).toHaveBeenCalled(); + }); + }); + + describe("shutdown()", () => { + test("should shutdown OTEL bridge", async () => { + process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; + + LoggerManager.initialize(); + await LoggerManager.shutdown(); + + // @ts-expect-error - accessing private static property + expect(LoggerManager.instance).toBeUndefined(); + }); + + test("should not throw if not initialized", async () => { + await expect(LoggerManager.shutdown()).resolves.not.toThrow(); + }); + }); + + describe("OTEL integration", () => { + test("should initialize with OTEL endpoint", () => { + process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; + + LoggerManager.initialize({ serviceName: "test-service" }); + + const logger = LoggerManager.getLogger("test"); + expect(logger).toBeDefined(); + }); + + test("should work without OTEL endpoint (noop mode)", () => { + delete process.env.OTEL_EXPORTER_OTLP_ENDPOINT; + + LoggerManager.initialize(); + + const logger = LoggerManager.getLogger("test"); + expect(logger).toBeDefined(); + + // Should not throw when creating spans/metrics + expect(() => logger.counter("test")).not.toThrow(); + expect(() => logger.histogram("test")).not.toThrow(); + }); + }); +}); diff --git a/packages/appkit/src/observability/tests/logger.test.ts b/packages/appkit/src/observability/tests/logger.test.ts new file mode 100644 index 00000000..aec282ce --- /dev/null +++ b/packages/appkit/src/observability/tests/logger.test.ts @@ -0,0 +1,205 @@ +import type { Span } from "@opentelemetry/api"; +import { SpanStatusCode } from "@opentelemetry/api"; +import { beforeEach, describe, expect, test, vi } from "vitest"; +import { Logger } from "../logger"; +import type { ScopedOTELBridge } from "../otel/bridge"; + +describe("Logger", () => { + let mockOtelBridge: ScopedOTELBridge; + let mockSpan: Span; + let logger: Logger; + + beforeEach(() => { + mockSpan = { + setAttribute: vi.fn(), + setAttributes: vi.fn(), + setStatus: vi.fn(), + addEvent: vi.fn(), + recordException: vi.fn(), + end: vi.fn(), + spanContext: vi.fn(), + isRecording: vi.fn(() => true), + updateName: vi.fn(), + addLink: vi.fn(), + addLinks: vi.fn(), + } as any; + + mockOtelBridge = { + startActiveSpan: vi.fn().mockImplementation(async (_name, _attrs, fn) => { + return fn(mockSpan); + }), + createCounter: vi.fn().mockReturnValue({ add: vi.fn() }), + createHistogram: vi.fn().mockReturnValue({ record: vi.fn() }), + emitLog: vi.fn(), + createScoped: vi.fn(), + } as any; + + logger = new Logger("test-scope", mockOtelBridge); + }); + + describe("debug()", () => { + test("should output to terminal only", () => { + logger.debug("Test message", { key: "value" }); + // Debug only goes to terminal (obug) - no OTEL, no WideEvent + expect(mockOtelBridge.emitLog).not.toHaveBeenCalled(); + }); + }); + + describe("trace()", () => { + test("should send individual OTEL log records", () => { + logger.trace("Verbose debug", { step: "init" }); + + expect(mockOtelBridge.emitLog).toHaveBeenCalledWith( + "debug", + "Verbose debug", + { step: "init" }, + ); + }); + + test("should add to WideEvent if in request context", () => { + // This would require AsyncLocalStorage setup - tested in context.test.ts + }); + }); + + describe("info()", () => { + test("should not send individual OTEL logs", () => { + logger.info("Info message", { userId: "123" }); + // info() does NOT call emitLog - it accumulates in WideEvent + expect(mockOtelBridge.emitLog).not.toHaveBeenCalled(); + }); + }); + + describe("warn()", () => { + test("should not send individual OTEL logs", () => { + logger.warn("Warning message"); + expect(mockOtelBridge.emitLog).not.toHaveBeenCalled(); + }); + }); + + describe("error()", () => { + test("should record exception on span by default", () => { + const error = new Error("Test error"); + logger.error("Error occurred", error, { context: "value" }); + + // error() does NOT call emitLog directly + expect(mockOtelBridge.emitLog).not.toHaveBeenCalled(); + }); + + test("should not record exception when recordOnSpan is false", () => { + const error = new Error("Expected error"); + logger.error("Expected error", error, {}, { recordOnSpan: false }); + + // Should still not call emitLog (goes to WideEvent) + expect(mockOtelBridge.emitLog).not.toHaveBeenCalled(); + }); + }); + + describe("span()", () => { + test("should create span with scoped name", async () => { + await logger.span("operation", async (_span) => { + return "result"; + }); + + expect(mockOtelBridge.startActiveSpan).toHaveBeenCalledWith( + "test-scope.operation", + {}, + expect.any(Function), + ); + }); + + test("should auto-set span status to OK on success", async () => { + await logger.span("operation", async (_span) => { + return "success"; + }); + + expect(mockSpan.setStatus).toHaveBeenCalledWith({ + code: SpanStatusCode.OK, + }); + }); + + test("should auto-set span status to ERROR on failure", async () => { + const error = new Error("Test error"); + + await expect( + logger.span("operation", async (_span) => { + throw error; + }), + ).rejects.toThrow("Test error"); + + expect(mockSpan.recordException).toHaveBeenCalledWith(error); + expect(mockSpan.setStatus).toHaveBeenCalledWith({ + code: SpanStatusCode.ERROR, + message: "Test error", + }); + }); + + test("should pass span attributes", async () => { + await logger.span( + "operation", + async (_span) => { + return "result"; + }, + { attributes: { key: "value", count: 42 } }, + ); + + expect(mockOtelBridge.startActiveSpan).toHaveBeenCalledWith( + "test-scope.operation", + { key: "value", count: 42 }, + expect.any(Function), + ); + }); + }); + + describe("counter()", () => { + test("should create counter with scoped name", () => { + const _counter = logger.counter("requests", { + description: "Total requests", + }); + + expect(mockOtelBridge.createCounter).toHaveBeenCalledWith( + "test-scope.requests", + { description: "Total requests" }, + ); + }); + }); + + describe("histogram()", () => { + test("should create histogram with scoped name", () => { + const _histogram = logger.histogram("duration", { unit: "ms" }); + + expect(mockOtelBridge.createHistogram).toHaveBeenCalledWith( + "test-scope.duration", + { unit: "ms" }, + ); + }); + }); + + describe("recordContext()", () => { + test("should not throw when no WideEvent exists", () => { + expect(() => { + logger.recordContext({ key: "value" }); + }).not.toThrow(); + }); + + test("should add context to WideEvent if in request context", () => { + // This requires AsyncLocalStorage setup - tested in context.test.ts + }); + }); + + describe("child()", () => { + test("should create child logger with nested scope", () => { + const _childLogger = logger.child("subsystem"); + + expect(mockOtelBridge.createScoped).toHaveBeenCalledWith( + "test-scope:subsystem", + ); + }); + }); + + describe("getEvent()", () => { + test("should return undefined when no WideEvent exists", () => { + const event = logger.getEvent(); + expect(event).toBeUndefined(); + }); + }); +}); diff --git a/packages/appkit/src/observability/tests/wide-event.test.ts b/packages/appkit/src/observability/tests/wide-event.test.ts new file mode 100644 index 00000000..dfb46d38 --- /dev/null +++ b/packages/appkit/src/observability/tests/wide-event.test.ts @@ -0,0 +1,217 @@ +import { describe, expect, test } from "vitest"; +import { WideEvent } from "../wide-event"; + +describe("WideEvent", () => { + test("should initialize with request ID", () => { + const event = new WideEvent("test-request-123"); + const data = event.toJSON(); + + expect(data.request_id).toBe("test-request-123"); + expect(data.timestamp).toBeDefined(); + expect(data.service).toBeDefined(); + expect(data.logs).toEqual([]); + expect(data.context).toEqual({}); + }); + + describe("set()", () => { + test("should set primitive values", () => { + const event = new WideEvent("req-1"); + event.set("method", "POST"); + event.set("path", "/api/test"); + event.set("status_code", 200); + + const data = event.toJSON(); + expect(data.method).toBe("POST"); + expect(data.path).toBe("/api/test"); + expect(data.status_code).toBe(200); + }); + + test("should merge object values", () => { + const event = new WideEvent("req-1"); + event.set("user", { id: "123" }); + event.set("user", { email: "test@example.com" }); + + const data = event.toJSON(); + expect(data.user).toEqual({ id: "123", email: "test@example.com" }); + }); + }); + + describe("setComponent()", () => { + test("should set component name and operation", () => { + const event = new WideEvent("req-1"); + event.setComponent("analytics", "query"); + + const data = event.toJSON(); + expect(data.component).toEqual({ name: "analytics", operation: "query" }); + }); + + test("should set component name without operation", () => { + const event = new WideEvent("req-1"); + event.setComponent("sql-warehouse"); + + const data = event.toJSON(); + expect(data.component).toEqual({ + name: "sql-warehouse", + operation: undefined, + }); + }); + }); + + describe("setUser()", () => { + test("should merge user context", () => { + const event = new WideEvent("req-1"); + event.setUser({ id: "user-123" }); + event.setUser({ email: "user@test.com" }); + + const data = event.toJSON(); + expect(data.user).toEqual({ id: "user-123", email: "user@test.com" }); + }); + }); + + describe("setExecution()", () => { + test("should merge execution context", () => { + const event = new WideEvent("req-1"); + event.setExecution({ cache_hit: true }); + event.setExecution({ retry_attempts: 3 }); + + const data = event.toJSON(); + expect(data.execution).toEqual({ cache_hit: true, retry_attempts: 3 }); + }); + }); + + describe("setStream()", () => { + test("should merge stream context", () => { + const event = new WideEvent("req-1"); + event.setStream({ stream_id: "stream-123" }); + event.setStream({ events_sent: 42 }); + + const data = event.toJSON(); + expect(data.stream).toEqual({ stream_id: "stream-123", events_sent: 42 }); + }); + }); + + describe("setError()", () => { + test("should set error from Error object", () => { + const event = new WideEvent("req-1"); + const error = new Error("Test error"); + error.name = "TestError"; + + event.setError(error); + + const data = event.toJSON(); + expect(data.error).toEqual({ + type: "TestError", + code: "UNKNOWN_ERROR", + message: "Test error", + retriable: false, + cause: undefined, + }); + }); + + test("should detect AppKit errors with code", () => { + const event = new WideEvent("req-1"); + const error: any = new Error("AppKit error"); + error.code = "WAREHOUSE_NOT_FOUND"; + error.statusCode = 404; + error.retriable = true; + + event.setError(error); + + const data = event.toJSON(); + expect(data.error?.code).toBe("WAREHOUSE_NOT_FOUND"); + expect(data.error?.retriable).toBe(true); + }); + }); + + describe("setContext()", () => { + test("should add scoped context", () => { + const event = new WideEvent("req-1"); + event.setContext("analytics", { query_key: "apps_list" }); + event.setContext("sql-warehouse", { warehouse_id: "wh-123" }); + + const data = event.toJSON(); + expect(data.context).toEqual({ + analytics: { query_key: "apps_list" }, + "sql-warehouse": { warehouse_id: "wh-123" }, + }); + }); + + test("should merge context for same scope", () => { + const event = new WideEvent("req-1"); + event.setContext("plugin", { step: 1 }); + event.setContext("plugin", { step: 2, status: "ok" }); + + const data = event.toJSON(); + expect(data.context?.plugin).toEqual({ step: 2, status: "ok" }); + }); + }); + + describe("addLog()", () => { + test("should add log entry", () => { + const event = new WideEvent("req-1"); + event.addLog("info", "Test message", { key: "value" }); + + const data = event.toJSON(); + expect(data.logs).toHaveLength(1); + expect(data.logs?.[0]).toMatchObject({ + level: "info", + message: "Test message", + context: { key: "value" }, + }); + expect(data.logs?.[0].timestamp).toBeDefined(); + }); + + test("should truncate logs after 50 entries", () => { + const event = new WideEvent("req-1"); + + // Add 60 logs + for (let i = 0; i < 60; i++) { + event.addLog("info", `Message ${i}`); + } + + const data = event.toJSON(); + expect(data.logs).toHaveLength(50); + // Should keep the last 50 + expect(data.logs?.[0].message).toBe("Message 10"); + expect(data.logs?.[49].message).toBe("Message 59"); + }); + }); + + describe("finalize()", () => { + test("should set status code and duration", async () => { + const event = new WideEvent("req-1"); + await new Promise((resolve) => setTimeout(resolve, 5)); + const data = event.finalize(200); + + expect(data.status_code).toBe(200); + expect(data.duration_ms).toBeGreaterThanOrEqual(0); + }); + }); + + describe("getDurationMs()", () => { + test("should calculate duration from start time", async () => { + const event = new WideEvent("req-1"); + await new Promise((resolve) => setTimeout(resolve, 10)); + + const duration = event.getDurationMs(); + expect(duration).toBeGreaterThanOrEqual(10); + }); + }); + + describe("toJSON()", () => { + test("should return complete WideEventData", () => { + const event = new WideEvent("req-1"); + event.set("method", "POST"); + event.set("path", "/api/test"); + event.setComponent("analytics", "query"); + event.addLog("info", "Test log"); + + const data = event.toJSON(); + expect(data.request_id).toBe("req-1"); + expect(data.method).toBe("POST"); + expect(data.path).toBe("/api/test"); + expect(data.component).toEqual({ name: "analytics", operation: "query" }); + expect(data.logs).toHaveLength(1); + }); + }); +}); diff --git a/packages/appkit/src/observability/types.ts b/packages/appkit/src/observability/types.ts new file mode 100644 index 00000000..11838346 --- /dev/null +++ b/packages/appkit/src/observability/types.ts @@ -0,0 +1,243 @@ +import type { Counter, Histogram, Span } from "@opentelemetry/api"; +import type { WideEvent } from "./wide-event"; + +export type LogLevel = "debug" | "info" | "warn" | "error"; + +/** * Log context for structured logging */ +export interface LogContext { + [key: string]: unknown; +} + +/** * Span options for tracing */ +export interface SpanOptions { + attributes?: Record; +} + +/** * Metric options for metrics */ +export interface MetricOptions { + unit?: string; + description?: string; + attributes?: Record; +} + +/** + * Options for error logging + */ +export interface ErrorLogOptions { + /** + * Whether to record the error on the current span. + * When true (default), the error is recorded as an exception on the active span. + * Set to false for expected errors that shouldn't mark the span as failed. + * @default true + */ + recordOnSpan?: boolean; +} + +/** + * Main logger interface for observability in AppKit. + * Provides unified access to logging, tracing, and metrics. + * + * THREE LAYERS OF CONTROL: + * + * LAYER 1: Opinionated (99% of cases) - Automatic observability + * - logger.debug() - Terminal only (requires DEBUG=appkit:*) + * - logger.trace() - Terminal + WideEvent + individual OTEL log records + * - logger.info() - Terminal + WideEvent + Span events + * - logger.warn() - Terminal + WideEvent + Span events + * - logger.error() - Terminal + WideEvent + Span events + Exception recording + * + * Note: WideEvent is sent to OTEL Logs as ONE aggregated record at request end + * + * LAYER 2: Custom API (when you need control) + * - logger.span() - Create traced span (auto-managed) + * - logger.counter() - Create counter metric + * - logger.histogram() - Create histogram metric + * - logger.recordContext() - Record context without log entry + * - logger.child() - Create child logger with nested scope + * - logger.getEvent() - Access WideEvent for advanced use + * + * LAYER 3: Raw (full OTEL power) + * - otel.getTracer() - Raw OTEL tracer (custom span names, full control) + * - otel.getMeter() - Raw OTEL meter (gauges, observable instruments) + * - otel.getLogger() - Raw OTEL logger (rarely needed) + * + * OBSERVABILITY FLOW: + * 1. During Request: Logs accumulate in WideEvent (in-memory) + * 2. At Request End: WideEvent sent to OTEL Logs as ONE aggregated record + * 3. Result: One OTEL log per request (not per logger call) + * + * This means: + * - In Loki/OTEL backend: You see ONE log record per request (the WideEvent) + * - In Tempo traces: You see individual log events attached to spans + * - In Terminal: You see individual debug output (requires DEBUG=appkit:*) + * + * @example Opinionated layer - automatic observability + * ```typescript + * logger.info("Processing request", { userId: "123" }); + * // ✅ Goes to: Terminal + WideEvent.logs[] + Current Span Events + * // At request end: WideEvent → OTEL Logs (aggregated) + * ``` + * + * @example Custom layer - custom spans + * ```typescript + * await logger.span("fetch-data", async (span) => { + * span.setAttribute("db.system", "databricks"); + * return await fetchData(); + * }); // ✅ Span auto-ended, status auto-set + * ``` + * + * @example Raw layer - full control + * ```typescript + * const tracer = otel.getTracer("custom-name"); + * await tracer.startActiveSpan("operation", async (span) => { + * span.setStatus({ code: SpanStatusCode.UNSET }); + * span.end(); // ⚠️ You manage everything + * }); + * ``` + */ +export interface ILogger { + /** + * Log a debug message. Only shows when DEBUG=appkit:* is set. + * Output: Terminal only (not sent to OTEL or WideEvent). + * Use this for local development debugging. + * @param message - The message to log + * @param context - Optional structured context data + */ + debug(message: string, context?: LogContext): void; + + /** + * Log a trace message for detailed debugging. + * Output: Terminal + WideEvent + individual OTEL log record. + * Use this for verbose debugging that you want in production observability. + * Unlike info/warn/error, each trace() creates an individual OTEL log record. + * @param message - The message to log + * @param context - Optional structured context data + */ + trace(message: string, context?: LogContext): void; + + /** + * Log an info message. Automatically added to WideEvent and current span. + * Output: Terminal + WideEvent.logs[] + Current Span events. + * Note: Individual logs are aggregated in WideEvent, which is sent to OTEL Logs at request end. + * @param message - The message to log + * @param context - Optional structured context data + */ + info(message: string, context?: LogContext): void; + + /** + * Log a warning message. Automatically added to WideEvent and current span. + * Output: Terminal + WideEvent.logs[] + Current Span events. + * @param message - The message to log + * @param context - Optional structured context data + */ + warn(message: string, context?: LogContext): void; + + /** + * Log an error message. Automatically added to WideEvent and current span. + * Output: Terminal + WideEvent.logs[] + Span events. + * By default, records the exception on the active span. + * @param message - The message to log + * @param error - Optional Error object to record + * @param context - Optional structured context data + * @param options - Optional error logging configuration + * @example Expected error (don't fail span) + * ```typescript + * logger.error("Cache miss", error, context, { recordOnSpan: false }); + * ``` + * @example Unexpected error (default - fails span) + * ```typescript + * logger.error("Database connection failed", error); + * ``` + */ + error( + message: string, + error?: Error, + context?: LogContext, + options?: ErrorLogOptions, + ): void; + + /** + * Execute a function within a traced span. Span is automatically ended. + * @param name - The span name (will be scoped to logger name) + * @param fn - The async function to execute within the span + * @param options - Optional span configuration + * @returns Promise resolving to the function's return value + */ + span( + name: string, + fn: (span: Span) => Promise, + options?: SpanOptions, + ): Promise; + + /** + * Create a counter metric. + * @param name - The metric name (will be scoped to logger name) + * @param options - Optional metric configuration + * @returns A Counter instance for recording values + */ + counter(name: string, options?: MetricOptions): Counter; + + /** + * Create a histogram metric. + * @param name - The metric name (will be scoped to logger name) + * @param options - Optional metric configuration + * @returns A Histogram instance for recording values + */ + histogram(name: string, options?: MetricOptions): Histogram; + + /** + * Record context to WideEvent and current span without generating a log entry. + * Use this to enrich the request context with metadata without cluttering logs. + * @param context - Context data to record + * @example + * ```typescript + * // Record metadata without creating a log entry + * logger.recordContext({ warehouseId: "wh-123", userId: "user-456" }); + * ``` + */ + recordContext(context: LogContext): void; + + /** + * Get the current WideEvent if in request context (advanced usage). + * @returns The current WideEvent or undefined if outside request context + */ + getEvent(): WideEvent | undefined; + + /** + * Create a child logger with additional scope. + * @param scope - The additional scope name to append + * @returns A new ILogger instance with the combined scope + */ + child(scope: string): ILogger; +} + +/** + * App-level observability configuration + */ +export interface ObservabilityConfig { + // enable/disable all observability (default: true) + enabled?: boolean; + + // service name for telemetry (default: DATABRICKS_APP_NAME) + serviceName?: string; + + // service version for telemetry + serviceVersion?: string; + + // enable traces export to OTLP (default: true if endpoint configured) + traces?: boolean; + + // enable metrics export to OTLP (default: true if endpoint configured) + metrics?: boolean; + + // enable logs export to OTLP (default: true if endpoint configured) + logs?: boolean; + + // custom OTLP headers + headers?: Record; + + // metric export interval in ms (default: 10000) + exportIntervalMs?: number; +} + +export type { ObservabilityOptions } from "shared"; diff --git a/packages/appkit/src/observability/wide-event.ts b/packages/appkit/src/observability/wide-event.ts new file mode 100644 index 00000000..a4c6ad80 --- /dev/null +++ b/packages/appkit/src/observability/wide-event.ts @@ -0,0 +1,282 @@ +import { createDebug } from "./debug"; +import type { LogLevel } from "./types"; + +const debug = createDebug("wide-event"); + +export interface QueryData { + key?: string; + warehouse_id?: string; + rows_returned?: number; + query_duration_ms?: number; + bytes_scanned?: number; + [key: string]: unknown; +} + +/** + * WideEvent data interface + * - Represents a single event for a request + * - Fields are camelCase to match OpenTelemetry + */ +export interface WideEventData { + // request metadata + timestamp: string; + request_id: string; + method?: string; + path?: string; + status_code?: number; + duration_ms?: number; + + // service metadata + service?: { + name: string; + version: string; + region?: string; + deployment_id?: string; + node_env?: string; + }; + + // component metadata (plugin, connector, or service) + component?: { + name: string; + operation?: string; + }; + + // user metadata + user?: { + id?: string; + [key: string]: unknown; + }; + + // execution metadata + execution?: { + cache_hit?: boolean; + cache_key?: string; + retry_attempts?: number; + timeout_ms?: number; + [key: string]: unknown; + }; + + // stream metadata + stream?: { + stream_id?: string; + events_sent?: number; + buffer_size?: number; + reconnections?: number; + [key: string]: unknown; + }; + + // error metadata + error?: { + type: string; + code: string; + message: string; + retriable?: boolean; + cause?: string; + }; + + // log metadata + logs?: Array<{ + level: LogLevel; + message: string; + timestamp: string; + context?: Record; + }>; + + /** + * Scoped context data + * Each scope (plugin, connector, service) can add its own namespaced data here. + * Example: { analytics: { query_key: "..."}, "sql-warehouse": { warehouse_id: "..."} } + */ + context?: Record>; + + [key: string]: unknown; +} + +/** + * WideEvent + * - Represents a single event for a request + * - Fields are camelCase to match OpenTelemetry + */ +export class WideEvent { + private data: WideEventData; + private startTime: number; + + constructor(requestId: string) { + this.startTime = Date.now(); + this.data = { + timestamp: new Date().toISOString(), + request_id: requestId, + service: { + name: "appkit", + version: process.env.npm_package_version || "unknown", + region: process.env.REGION, + deployment_id: process.env.DEPLOYMENT_ID, + node_env: process.env.NODE_ENV, + }, + logs: [], + context: {}, + }; + } + + /** + * Set a value in the event + * @param key - The key to set + * @param value - The value to set + * @returns The event + */ + set(key: K, value: WideEventData[K]): this { + if (typeof value === "object" && value !== null && !Array.isArray(value)) { + // merge objects + this.data[key] = { + ...(this.data[key] as object), + ...value, + } as WideEventData[K]; + } else { + this.data[key] = value; + } + return this; + } + + /** + * Set the component name and operation. + * Component can be a plugin, connector, or service. + * @param name - The name of the component (e.g., "analytics", "sql-warehouse", "cache-manager") + * @param operation - The operation being performed (e.g., "query", "getOrExecute") + * @returns The event + */ + setComponent(name: string, operation?: string): this { + this.data.component = { name, operation }; + return this; + } + + /** + * Set the user context + * @param user - The user context + * @returns The event + */ + setUser(user: WideEventData["user"]): this { + this.data.user = { ...this.data.user, ...user }; + return this; + } + + /** + * Set the execution context + * @param execution - The execution context + * @returns The event + */ + setExecution(execution: WideEventData["execution"]): this { + this.data.execution = { ...this.data.execution, ...execution }; + return this; + } + + /** + * Set the stream context + * @param stream - The stream context + * @returns The event + */ + setStream(stream: WideEventData["stream"]): this { + this.data.stream = { ...this.data.stream, ...stream }; + return this; + } + + /** + * Set the error context + * @param error - The error context + * @returns The event + */ + setError(error: Error): this { + const isAppKitError = "code" in error && "statusCode" in error; + const errorCause = (error as any).cause; + + this.data.error = { + type: error.name, + code: isAppKitError ? (error as any).code : "UNKNOWN_ERROR", + message: error.message, + retriable: isAppKitError ? (error as any).retriable : false, + cause: errorCause ? String(errorCause) : undefined, + }; + + return this; + } + + /** + * Add scoped context to the event + * @param scope - The scope name (plugin, connector, or service name) + * @param ctx - Context data to merge + * @example + * event.setContext("analytics", { query_key: "apps_list", rows_returned: 100 }); + * event.setContext("sql-warehouse", { warehouse_id: "1234567890" }); + */ + setContext(scope: string, ctx: Record): this { + if (!this.data.context) { + this.data.context = {}; + } + + this.data.context[scope] = { + ...this.data.context[scope], + ...ctx, + }; + + return this; + } + + /** + * Add a log to the event + * @param level - The level of the log + * @param message - The message of the log + * @param context - The context of the log + * @returns The event + */ + addLog( + level: LogLevel, + message: string, + context?: Record, + ): this { + if (!this.data.logs) { + this.data.logs = []; + } + + this.data.logs.push({ + level, + message, + timestamp: new Date().toISOString(), + context, + }); + + // Keep only last 50 logs to prevent unbounded growth + if (this.data.logs.length > 50) { + const originalLength = this.data.logs.length; + this.data.logs = this.data.logs.slice(-50); + debug("Log limit exceeded, truncated from %d to 50 logs", originalLength); + } + + return this; + } + + /** + * Finalize the event + * @param statusCode - The status code of the response + * @returns The event data + */ + finalize(statusCode: number): WideEventData { + this.data.status_code = statusCode; + this.data.duration_ms = this.getDurationMs(); + return this.data; + } + + /** + * Get the duration of the event in milliseconds + * @returns The duration of the event in milliseconds + */ + getDurationMs(): number { + return this.data.duration_ms || Date.now() - this.startTime; + } + + /** + * Convert the event to a JSON object + * @returns The event data as a JSON object + */ + toJSON(): WideEventData { + return this.data; + } +} diff --git a/packages/appkit/src/plugin/dev-reader.ts b/packages/appkit/src/plugin/dev-reader.ts index f5464753..767182d2 100644 --- a/packages/appkit/src/plugin/dev-reader.ts +++ b/packages/appkit/src/plugin/dev-reader.ts @@ -1,5 +1,6 @@ import { randomUUID } from "node:crypto"; import type { TunnelConnection } from "shared"; +import { type ILogger, LoggerManager } from "@/observability"; import { isRemoteTunnelAllowedByEnv } from "@/server/remote-tunnel/gate"; type TunnelConnectionGetter = ( @@ -13,6 +14,7 @@ type TunnelConnectionGetter = ( export class DevFileReader { private static instance: DevFileReader | null = null; private getTunnelForRequest: TunnelConnectionGetter | null = null; + private logger: ILogger = LoggerManager.getLogger("dev-reader"); private constructor() {} @@ -31,7 +33,10 @@ export class DevFileReader { if (typeof value === "function") { return function noop() { - console.info(`Noop: ${String(prop)} (remote server disabled)`); + DevFileReader.getInstance().logger.debug("Noop", { + prop: String(prop), + reason: "remote server disabled", + }); return Promise.resolve(""); }; } diff --git a/packages/appkit/src/plugin/interceptors/cache.ts b/packages/appkit/src/plugin/interceptors/cache.ts index 7f9f31e6..b8af0ca3 100644 --- a/packages/appkit/src/plugin/interceptors/cache.ts +++ b/packages/appkit/src/plugin/interceptors/cache.ts @@ -1,6 +1,6 @@ -import type { CacheManager } from "../../cache"; import type { CacheConfig } from "shared"; -import type { InterceptorContext, ExecutionInterceptor } from "./types"; +import type { CacheManager } from "../../cache"; +import type { ExecutionInterceptor, InterceptorContext } from "./types"; // interceptor to handle caching logic export class CacheInterceptor implements ExecutionInterceptor { diff --git a/packages/appkit/src/plugin/interceptors/observability.test.ts b/packages/appkit/src/plugin/interceptors/observability.test.ts new file mode 100644 index 00000000..ef49c6bf --- /dev/null +++ b/packages/appkit/src/plugin/interceptors/observability.test.ts @@ -0,0 +1,51 @@ +import { describe, expect, test, vi } from "vitest"; +import { ObservabilityInterceptor } from "./observability"; + +describe("ObservabilityInterceptor", () => { + test("should pass only operation to logger.span (default: execute)", async () => { + const logger = { + span: vi.fn(async (_name: string, fn: any) => await fn()), + } as any; + + const interceptor = new ObservabilityInterceptor(logger); + + await interceptor.intercept(async () => "ok", { + pluginName: "analytics", + userKey: "u1", + }); + + expect(logger.span).toHaveBeenCalledWith("execute", expect.any(Function)); + }); + + test("should pass operation to logger.span when provided", async () => { + const logger = { + span: vi.fn(async (_name: string, fn: any) => await fn()), + } as any; + + const interceptor = new ObservabilityInterceptor(logger); + + await interceptor.intercept(async () => "ok", { + pluginName: "analytics", + operation: "query", + userKey: "u1", + }); + + expect(logger.span).toHaveBeenCalledWith("query", expect.any(Function)); + }); + + test("should strip redundant plugin prefix from operation", async () => { + const logger = { + span: vi.fn(async (_name: string, fn: any) => await fn()), + } as any; + + const interceptor = new ObservabilityInterceptor(logger); + + await interceptor.intercept(async () => "ok", { + pluginName: "analytics", + operation: "analytics.query", + userKey: "u1", + }); + + expect(logger.span).toHaveBeenCalledWith("query", expect.any(Function)); + }); +}); diff --git a/packages/appkit/src/plugin/interceptors/observability.ts b/packages/appkit/src/plugin/interceptors/observability.ts new file mode 100644 index 00000000..dd3fc7bd --- /dev/null +++ b/packages/appkit/src/plugin/interceptors/observability.ts @@ -0,0 +1,36 @@ +import type { ILogger } from "../../observability"; +import { createDebug } from "../../observability/debug"; +import type { ExecutionInterceptor, InterceptorContext } from "./types"; + +const debug = createDebug("observability-interceptor"); + +/** + * Interceptor to automatically instrument plugin executions with observability spans. + * Wraps the execution in a span and handles success/error status. + */ +export class ObservabilityInterceptor implements ExecutionInterceptor { + constructor(private logger: ILogger) {} + + async intercept( + fn: () => Promise, + context: InterceptorContext, + ): Promise { + /** + * Important: `Plugin` already constructs `this.logger` with scope = plugin name. + * `Logger.span(name)` prefixes with `${scope}.${name}`. + * + * So we should pass only the *operation* here (e.g. "query"), not + * `${pluginName}.${operation}`, otherwise we end up with "analytics.analytics.query". + */ + const rawOperation = context.operation ?? "execute"; + const operation = rawOperation.startsWith(`${context.pluginName}.`) + ? rawOperation.slice(context.pluginName.length + 1) + : rawOperation; + + debug("Creating span: %s.%s", context.pluginName, operation); + + return this.logger.span(operation, async () => { + return await fn(); + }); + } +} diff --git a/packages/appkit/src/plugin/interceptors/retry.ts b/packages/appkit/src/plugin/interceptors/retry.ts index 274a0d36..086a723f 100644 --- a/packages/appkit/src/plugin/interceptors/retry.ts +++ b/packages/appkit/src/plugin/interceptors/retry.ts @@ -1,13 +1,16 @@ import type { RetryConfig } from "shared"; -import type { InterceptorContext, ExecutionInterceptor } from "./types"; +import { type ILogger, LoggerManager } from "@/observability"; +import type { ExecutionInterceptor, InterceptorContext } from "./types"; // interceptor to handle retry logic export class RetryInterceptor implements ExecutionInterceptor { + private logger: ILogger; private attempts: number; private initialDelay: number; private maxDelay: number; constructor(config: RetryConfig) { + this.logger = LoggerManager.getLogger("retry-interceptor"); this.attempts = config.attempts ?? 3; this.initialDelay = config.initialDelay ?? 1000; this.maxDelay = config.maxDelay ?? 30000; @@ -17,6 +20,8 @@ export class RetryInterceptor implements ExecutionInterceptor { fn: () => Promise, context: InterceptorContext, ): Promise { + const event = this.logger.getEvent(); + let lastError: Error | unknown; for (let attempt = 1; attempt <= this.attempts; attempt++) { @@ -25,6 +30,8 @@ export class RetryInterceptor implements ExecutionInterceptor { } catch (error) { lastError = error; + event?.setExecution({ retry_attempts: attempt }); + // last attempt, rethrow the error if (attempt === this.attempts) { throw error; diff --git a/packages/appkit/src/plugin/interceptors/telemetry.ts b/packages/appkit/src/plugin/interceptors/telemetry.ts deleted file mode 100644 index 3c0b6594..00000000 --- a/packages/appkit/src/plugin/interceptors/telemetry.ts +++ /dev/null @@ -1,39 +0,0 @@ -import type { ITelemetry, Span } from "../../telemetry"; -import { SpanStatusCode } from "../../telemetry"; -import type { TelemetryConfig } from "shared"; -import type { InterceptorContext, ExecutionInterceptor } from "./types"; - -/** - * Interceptor to automatically instrument plugin executions with telemetry spans. - * Wraps the execution in a span and handles success/error status. - */ -export class TelemetryInterceptor implements ExecutionInterceptor { - constructor( - private telemetry: ITelemetry, - private config?: TelemetryConfig, - ) {} - - async intercept( - fn: () => Promise, - _context: InterceptorContext, - ): Promise { - const spanName = this.config?.spanName || "plugin.execute"; - return this.telemetry.startActiveSpan( - spanName, - { attributes: this.config?.attributes }, - async (span: Span) => { - try { - const result = await fn(); - span.setStatus({ code: SpanStatusCode.OK }); - return result; - } catch (error) { - span.recordException(error as Error); - span.setStatus({ code: SpanStatusCode.ERROR }); - throw error; - } finally { - span.end(); - } - }, - ); - } -} diff --git a/packages/appkit/src/plugin/interceptors/types.ts b/packages/appkit/src/plugin/interceptors/types.ts index 633e38de..af61a3c6 100644 --- a/packages/appkit/src/plugin/interceptors/types.ts +++ b/packages/appkit/src/plugin/interceptors/types.ts @@ -6,6 +6,8 @@ export interface InterceptorContext { signal?: AbortSignal; metadata?: Map; userKey: string; + pluginName: string; + operation?: string; } export interface ExecutionInterceptor { diff --git a/packages/appkit/src/plugin/plugin.ts b/packages/appkit/src/plugin/plugin.ts index a8902810..59604dbc 100644 --- a/packages/appkit/src/plugin/plugin.ts +++ b/packages/appkit/src/plugin/plugin.ts @@ -11,6 +11,7 @@ import type { StreamExecuteHandler, StreamExecutionSettings, } from "shared"; +import { type ILogger, LoggerManager } from "@/observability"; import { AppManager } from "../app"; import { CacheManager } from "../cache"; import { @@ -20,16 +21,11 @@ import { type UserContext, } from "../context"; import { StreamManager } from "../stream"; -import { - type ITelemetry, - normalizeTelemetryOptions, - TelemetryManager, -} from "../telemetry"; import { deepMerge, validateEnv } from "../utils"; import { DevFileReader } from "./dev-reader"; import { CacheInterceptor } from "./interceptors/cache"; +import { ObservabilityInterceptor } from "./interceptors/observability"; import { RetryInterceptor } from "./interceptors/retry"; -import { TelemetryInterceptor } from "./interceptors/telemetry"; import { TimeoutInterceptor } from "./interceptors/timeout"; import type { InterceptorContext, @@ -64,7 +60,7 @@ export abstract class Plugin< protected app: AppManager; protected devFileReader: DevFileReader; protected streamManager: StreamManager; - protected telemetry: ITelemetry; + protected logger: ILogger; protected abstract envVars: string[]; /** Registered endpoints for this plugin */ @@ -75,7 +71,7 @@ export abstract class Plugin< constructor(protected config: TConfig) { this.name = config.name ?? "plugin"; - this.telemetry = TelemetryManager.getProvider(this.name, config.telemetry); + this.logger = LoggerManager.getLogger(this.name, config?.observability); this.streamManager = new StreamManager(); this.cache = CacheManager.getInstanceSync(); this.app = new AppManager(); @@ -217,6 +213,8 @@ export abstract class Plugin< user: userConfig, }); + const interceptors = this._buildInterceptors(executeConfig); + // Get user key from context if not provided const effectiveUserKey = userKey ?? getCurrentUserId(); @@ -229,11 +227,9 @@ export abstract class Plugin< signal: streamSignal, metadata: new Map(), userKey: effectiveUserKey, + pluginName: self.name, }; - // build interceptors - const interceptors = self._buildInterceptors(executeConfig); - // wrap the function to ensure it returns a promise const wrappedFn = async () => { const result = await fn(context.signal); @@ -275,6 +271,7 @@ export abstract class Plugin< const context: InterceptorContext = { metadata: new Map(), userKey: effectiveUserKey, + pluginName: this.name, }; try { @@ -306,9 +303,11 @@ export abstract class Plugin< ): PluginExecuteConfig { const { default: methodDefaults, user: userOverride } = options; - // Merge: method defaults <- plugin config <- user override (highest priority) + const { observability: _, ...pluginConfigWithoutObservability } = + this.config; + return deepMerge( - deepMerge(methodDefaults, this.config), + deepMerge(methodDefaults, pluginConfigWithoutObservability), userOverride ?? {}, ) as PluginExecuteConfig; } @@ -319,17 +318,24 @@ export abstract class Plugin< ): ExecutionInterceptor[] { const interceptors: ExecutionInterceptor[] = []; - // order matters: telemetry → timeout → retry → cache (innermost to outermost) + // order matters: observability → timeout → retry → cache (innermost to outermost) - // Only add telemetry interceptor if traces are enabled - const telemetryConfig = normalizeTelemetryOptions(this.config.telemetry); - if ( - telemetryConfig.traces && - (options.telemetryInterceptor?.enabled ?? true) - ) { - interceptors.push( - new TelemetryInterceptor(this.telemetry, options.telemetryInterceptor), - ); + // Check if traces are enabled (from plugin config OR execution config) + const pluginObservability = this.config?.observability; + const executeObservability = options.observability; + + // Merge: execution config overrides plugin config + const tracesEnabled = + typeof executeObservability === "boolean" + ? executeObservability + : typeof executeObservability === "object" + ? (executeObservability.traces ?? true) + : typeof pluginObservability === "boolean" + ? pluginObservability + : (pluginObservability?.traces ?? true); + + if (tracesEnabled) { + interceptors.push(new ObservabilityInterceptor(this.logger)); } if (options.timeout && options.timeout > 0) { diff --git a/packages/appkit/src/plugin/tests/cache.test.ts b/packages/appkit/src/plugin/tests/cache.test.ts index 7e01e778..99a64e29 100644 --- a/packages/appkit/src/plugin/tests/cache.test.ts +++ b/packages/appkit/src/plugin/tests/cache.test.ts @@ -83,6 +83,7 @@ describe("CacheInterceptor", () => { beforeEach(() => { cacheManager = new MockCacheManager(); context = { + pluginName: "test", metadata: new Map(), userKey: "service", }; @@ -183,6 +184,7 @@ describe("CacheInterceptor", () => { const contextWithToken: InterceptorContext = { metadata: new Map(), userKey: "user1", + pluginName: "test", }; const interceptor = new CacheInterceptor( cacheManager as unknown as ConstructorParameters< @@ -216,6 +218,7 @@ describe("CacheInterceptor", () => { const context1: InterceptorContext = { metadata: new Map(), userKey: "service", + pluginName: "test", }; const fn1 = vi.fn().mockResolvedValue("service-account-data"); await interceptor.intercept(fn1, context1); @@ -224,6 +227,7 @@ describe("CacheInterceptor", () => { const context2: InterceptorContext = { metadata: new Map(), userKey: "user1", + pluginName: "test", }; const fn2 = vi.fn().mockResolvedValue("user-data"); await interceptor.intercept(fn2, context2); diff --git a/packages/appkit/src/plugin/tests/plugin.test.ts b/packages/appkit/src/plugin/tests/plugin.test.ts index 2fedb650..8c06f492 100644 --- a/packages/appkit/src/plugin/tests/plugin.test.ts +++ b/packages/appkit/src/plugin/tests/plugin.test.ts @@ -1,20 +1,18 @@ -import type { ITelemetry, TelemetryProvider } from "../../telemetry"; -import { TelemetryManager } from "../../telemetry"; -import { AppManager } from "../../app"; -import { CacheManager } from "../../cache"; -import { StreamManager } from "../../stream"; +import { mockServiceContext } from "@tools/test-helpers"; +import type express from "express"; import type { BasePluginConfig, - PluginExecuteConfig, IAppResponse, + PluginExecuteConfig, } from "shared"; -import { createMockTelemetry, mockServiceContext } from "@tools/test-helpers"; -import { validateEnv } from "../../utils"; -import type express from "express"; import { afterEach, beforeEach, describe, expect, test, vi } from "vitest"; +import { AppManager } from "../../app"; +import { CacheManager } from "../../cache"; +import { ServiceContext } from "../../context/service-context"; +import { StreamManager } from "../../stream"; +import { validateEnv } from "../../utils"; import type { InterceptorContext } from "../interceptors/types"; import { Plugin } from "../plugin"; -import { ServiceContext } from "../../context/service-context"; // Mock all dependencies vi.mock("../../app"); @@ -83,6 +81,12 @@ vi.mock("../interceptors/telemetry", () => ({ })), })); +vi.mock("../interceptors/observability", () => ({ + ObservabilityInterceptor: vi.fn().mockImplementation((_logger) => ({ + intercept: vi.fn().mockImplementation((fn, _context) => fn()), + })), +})); + // Test plugin implementations class TestPlugin extends Plugin { envVars = ["TEST_ENV_VAR"]; @@ -123,7 +127,6 @@ class PluginWithRoutes extends TestPlugin { } describe("Plugin", () => { - let mockTelemetry: ITelemetry; let mockCache: CacheManager; let mockApp: AppManager; let mockStreamManager: StreamManager; @@ -136,8 +139,6 @@ describe("Plugin", () => { ServiceContext.reset(); serviceContextMock = await mockServiceContext(); - mockTelemetry = createMockTelemetry(); - mockCache = { get: vi.fn(), set: vi.fn(), @@ -164,9 +165,6 @@ describe("Plugin", () => { vi.mocked(CacheManager.getInstanceSync).mockReturnValue(mockCache); vi.mocked(AppManager).mockImplementation(() => mockApp); vi.mocked(StreamManager).mockImplementation(() => mockStreamManager); - vi.mocked(TelemetryManager.getProvider).mockReturnValue( - mockTelemetry as TelemetryProvider, - ); vi.mocked(validateEnv).mockImplementation(() => {}); vi.clearAllMocks(); @@ -283,7 +281,12 @@ describe("Plugin", () => { stream: {}, }; - await (plugin as any).executeStream(mockResponse, mockFn, options, false); + await (plugin as any).executeStream( + mockResponse, + mockFn, + options, + "user-key", + ); expect(mockStreamManager.stream).toHaveBeenCalledTimes(1); expect(mockStreamManager.stream).toHaveBeenCalledWith( @@ -328,7 +331,7 @@ describe("Plugin", () => { user: { timeout: 2000 }, }; - const result = await (plugin as any).execute(mockFn, options, false); + const result = await (plugin as any).execute(mockFn, options, "user-key"); expect(result).toBe("result"); expect(mockFn).toHaveBeenCalledTimes(1); @@ -342,7 +345,7 @@ describe("Plugin", () => { default: {}, }; - const result = await (plugin as any).execute(mockFn, options, false); + const result = await (plugin as any).execute(mockFn, options, "user-key"); expect(result).toBeUndefined(); }); @@ -401,18 +404,14 @@ describe("Plugin", () => { expect(interceptors).toHaveLength(4); // telemetry + timeout + retry + cache - // Import interceptor classes dynamically to avoid module resolution issues - const { TelemetryInterceptor } = await import( - "../interceptors/telemetry" + const { ObservabilityInterceptor } = await import( + "../interceptors/observability" ); const { TimeoutInterceptor } = await import("../interceptors/timeout"); const { RetryInterceptor } = await import("../interceptors/retry"); const { CacheInterceptor } = await import("../interceptors/cache"); - expect(TelemetryInterceptor).toHaveBeenCalledWith( - mockTelemetry, - options.telemetryInterceptor, - ); + expect(ObservabilityInterceptor).toHaveBeenCalledWith(expect.any(Object)); expect(TimeoutInterceptor).toHaveBeenCalledWith(5000); expect(RetryInterceptor).toHaveBeenCalledWith({ enabled: true, @@ -425,11 +424,11 @@ describe("Plugin", () => { }); test("should skip disabled interceptors", () => { - const configWithoutTelemetry = { + const configWithoutObservability = { ...config, - telemetry: { metrics: false, traces: false, logs: false }, + observability: { metrics: false, traces: false, logs: false }, }; - const plugin = new TestPlugin(configWithoutTelemetry); + const plugin = new TestPlugin(configWithoutObservability); const options: PluginExecuteConfig = { timeout: 0, // disabled @@ -446,7 +445,7 @@ describe("Plugin", () => { test("should skip timeout interceptor when timeout is 0 or negative", () => { const configWithoutTelemetry = { ...config, - telemetry: { metrics: false, traces: false, logs: false }, + observability: { metrics: false, traces: false, logs: false }, }; const plugin = new TestPlugin(configWithoutTelemetry); @@ -465,7 +464,7 @@ describe("Plugin", () => { test("should skip retry interceptor when attempts <= 1", () => { const configWithoutTelemetry = { ...config, - telemetry: { metrics: false, traces: false, logs: false }, + observability: { metrics: false, traces: false, logs: false }, }; const plugin = new TestPlugin(configWithoutTelemetry); @@ -482,7 +481,7 @@ describe("Plugin", () => { test("should skip cache interceptor when cacheKey is empty", () => { const configWithoutTelemetry = { ...config, - telemetry: { + observability: { metrics: false, traces: false, logs: false, @@ -508,6 +507,7 @@ describe("Plugin", () => { const context: InterceptorContext = { metadata: new Map(), userKey: "test", + pluginName: plugin.name, }; // @ts-expect-error - _executeWithInterceptors is private @@ -523,6 +523,7 @@ describe("Plugin", () => { const context: InterceptorContext = { metadata: new Map(), userKey: "test", + pluginName: plugin.name, }; const mockInterceptor1 = { @@ -551,6 +552,7 @@ describe("Plugin", () => { metadata: new Map(), signal: new AbortController().signal, userKey: "test", + pluginName: plugin.name, }; const mockInterceptor = { diff --git a/packages/appkit/src/plugin/tests/retry.test.ts b/packages/appkit/src/plugin/tests/retry.test.ts index 913a8262..0de0113c 100644 --- a/packages/appkit/src/plugin/tests/retry.test.ts +++ b/packages/appkit/src/plugin/tests/retry.test.ts @@ -8,6 +8,7 @@ describe("RetryInterceptor", () => { beforeEach(() => { context = { + pluginName: "test", metadata: new Map(), userKey: "test", }; @@ -141,6 +142,7 @@ describe("RetryInterceptor", () => { metadata: new Map(), signal: abortController.signal, userKey: "test", + pluginName: "test", }; const fn = vi.fn().mockImplementation(() => { diff --git a/packages/appkit/src/plugin/tests/timeout.test.ts b/packages/appkit/src/plugin/tests/timeout.test.ts index b065bcb6..325b9a7e 100644 --- a/packages/appkit/src/plugin/tests/timeout.test.ts +++ b/packages/appkit/src/plugin/tests/timeout.test.ts @@ -7,6 +7,7 @@ describe("TimeoutInterceptor", () => { beforeEach(() => { context = { + pluginName: "test", metadata: new Map(), userKey: "test", }; @@ -65,6 +66,7 @@ describe("TimeoutInterceptor", () => { metadata: new Map(), signal: userController.signal, userKey: "test", + pluginName: "test", }; const interceptor = new TimeoutInterceptor(5000); @@ -86,6 +88,7 @@ describe("TimeoutInterceptor", () => { metadata: new Map(), signal: userController.signal, userKey: "test", + pluginName: "test", }; const interceptor = new TimeoutInterceptor(5000); @@ -109,6 +112,7 @@ describe("TimeoutInterceptor", () => { metadata: new Map(), signal: userController.signal, userKey: "test", + pluginName: "test", }; const interceptor = new TimeoutInterceptor(5000); diff --git a/packages/appkit/src/server/index.ts b/packages/appkit/src/server/index.ts index 24810dbd..f490a1c5 100644 --- a/packages/appkit/src/server/index.ts +++ b/packages/appkit/src/server/index.ts @@ -4,12 +4,13 @@ import path from "node:path"; import dotenv from "dotenv"; import express from "express"; import type { PluginPhase } from "shared"; +import { LoggerManager } from "@/observability"; +import { createDebug } from "@/observability/debug"; import { Plugin, toPlugin } from "../plugin"; -import { instrumentations } from "../telemetry"; import { RemoteTunnelController } from "./remote-tunnel/remote-tunnel-controller"; import { StaticServer } from "./static-server"; import type { ServerConfig } from "./types"; -import { type PluginEndpoints, getRoutes } from "./utils"; +import { getRoutes, type PluginEndpoints } from "./utils"; import { ViteDevServer } from "./vite-dev-server"; dotenv.config({ path: path.resolve(process.cwd(), "./.env") }); @@ -44,6 +45,7 @@ export class ServerPlugin extends Plugin { protected declare config: ServerConfig; private serverExtensions: ((app: express.Application) => void)[] = []; static phase: PluginPhase = "deferred"; + static debug = createDebug("server"); constructor(config: ServerConfig) { super(config); @@ -51,10 +53,6 @@ export class ServerPlugin extends Plugin { this.serverApplication = express(); this.server = null; this.serverExtensions = []; - this.telemetry.registerInstrumentations([ - instrumentations.http, - instrumentations.express, - ]); } /** Setup the server plugin. */ @@ -85,6 +83,7 @@ export class ServerPlugin extends Plugin { * @returns The express application. */ async start(): Promise { + this.serverApplication.use(LoggerManager.getMiddleware()); this.serverApplication.use(express.json()); const endpoints = await this.extendRoutes(); @@ -117,7 +116,7 @@ export class ServerPlugin extends Plugin { if (process.env.NODE_ENV === "development") { const allRoutes = getRoutes(this.serverApplication._router.stack); - console.dir(allRoutes, { depth: null }); + ServerPlugin.debug("Registered routes", { routes: allRoutes }); } return this.serverApplication; } @@ -242,7 +241,8 @@ export class ServerPlugin extends Plugin { for (const p of staticPaths) { const fullPath = path.resolve(cwd, p); if (fs.existsSync(path.resolve(fullPath, "index.html"))) { - console.log(`Static files: serving from ${fullPath}`); + const msg = `Static files: serving from ${fullPath}`; + ServerPlugin.debug(msg); return fullPath; } } @@ -255,30 +255,37 @@ export class ServerPlugin extends Plugin { const port = this.config.port ?? ServerPlugin.DEFAULT_CONFIG.port; const host = this.config.host ?? ServerPlugin.DEFAULT_CONFIG.host; - console.log(`Server running on http://${host}:${port}`); - - if (hasExplicitStaticPath) { - console.log(`Mode: static (${this.config.staticPath})`); - } else if (isDev) { - console.log("Mode: development (Vite HMR)"); - } else { - console.log("Mode: production (static)"); - } + ServerPlugin.debug("Server started", { + url: `http://${host}:${port}`, + mode: hasExplicitStaticPath + ? "static" + : isDev + ? "development" + : "production", + staticPath: this.config.staticPath, + remoteTunnel: { + allowed: this.remoteTunnelController?.isAllowedByEnv(), + active: this.remoteTunnelController?.isActive(), + }, + }); - const remoteServerController = this.remoteTunnelController; - if (!remoteServerController) { - console.log("Remote tunnel: disabled (controller not initialized)"); + if (!this.remoteTunnelController) { + ServerPlugin.debug( + "Remote tunnel: disabled (controller not initialized)", + ); } else { - console.log( - `Remote tunnel: ${ - remoteServerController.isAllowedByEnv() ? "allowed" : "blocked" - }; ${remoteServerController.isActive() ? "active" : "inactive"}`, + const allowed = !!this.remoteTunnelController.isAllowedByEnv(); + const active = !!this.remoteTunnelController.isActive(); + ServerPlugin.debug( + `Remote tunnel: ${allowed ? "allowed" : "disallowed"}; ${ + active ? "active" : "inactive" + }`, ); } } private async _gracefulShutdown() { - console.log("Starting graceful shutdown..."); + ServerPlugin.debug("Starting graceful shutdown"); if (this.viteDevServer) { await this.viteDevServer.close(); @@ -307,13 +314,13 @@ export class ServerPlugin extends Plugin { // 2. close the server if (this.server) { this.server.close(() => { - console.log("Server closed gracefully"); + ServerPlugin.debug("Server closed gracefully"); process.exit(0); }); // 3. timeout to force shutdown after 15 seconds setTimeout(() => { - console.log("Force shutdown after timeout"); + ServerPlugin.debug("Force shutdown after timeout"); process.exit(1); }, 15000); } else { diff --git a/packages/appkit/src/server/remote-tunnel/remote-tunnel-controller.ts b/packages/appkit/src/server/remote-tunnel/remote-tunnel-controller.ts index 5c799117..f570d1a1 100644 --- a/packages/appkit/src/server/remote-tunnel/remote-tunnel-controller.ts +++ b/packages/appkit/src/server/remote-tunnel/remote-tunnel-controller.ts @@ -1,5 +1,6 @@ import type { Server as HTTPServer } from "node:http"; import type express from "express"; +import { type ILogger, LoggerManager } from "@/observability"; import type { DevFileReader } from "../../plugin/dev-reader"; import { hasDevQuery, @@ -23,6 +24,7 @@ export class RemoteTunnelController { private manager: RemoteTunnelManager | null; private initPromise: Promise | null; private wsReady: boolean; + private logger: ILogger = LoggerManager.getLogger("remote-tunnel-controller"); constructor(devFileReader: DevFileReader) { this.devFileReader = devFileReader; @@ -124,7 +126,7 @@ export class RemoteTunnelController { // attach server + ws setup this.maybeSetupWebSocket(); - console.log("RemoteTunnel: initialized (on-demand)"); + this.logger.debug("Initialized (on-demand)"); return remoteTunnelManager; })(); @@ -147,6 +149,6 @@ export class RemoteTunnelController { this.manager.setupWebSocket(); this.wsReady = true; - console.log("RemoteTunnel: web socket setup complete"); + this.logger.debug("WebSocket setup complete"); } } diff --git a/packages/appkit/src/server/remote-tunnel/remote-tunnel-manager.ts b/packages/appkit/src/server/remote-tunnel/remote-tunnel-manager.ts index e88ebf01..38c5671c 100644 --- a/packages/appkit/src/server/remote-tunnel/remote-tunnel-manager.ts +++ b/packages/appkit/src/server/remote-tunnel/remote-tunnel-manager.ts @@ -6,6 +6,7 @@ import { fileURLToPath } from "node:url"; import type express from "express"; import type { TunnelConnection } from "shared"; import { WebSocketServer } from "ws"; +import { type ILogger, LoggerManager } from "@/observability"; import { generateTunnelIdFromEmail, getConfigScript, @@ -41,6 +42,7 @@ export class RemoteTunnelManager { private hmrWss: WebSocketServer; private server?: HTTPServer; private devFileReader: DevFileReader; + private logger: ILogger = LoggerManager.getLogger("remote-tunnel"); constructor(devFileReader: DevFileReader) { this.devFileReader = devFileReader; @@ -102,7 +104,7 @@ export class RemoteTunnelManager { ws.send(JSON.stringify(request)); }).catch((err) => { - console.error(`Failed to fetch ${path}:`, err.message); + this.logger.error("Failed to fetch asset", err as Error, { path }); return { status: 504, body: Buffer.from(""), headers: {} }; }); @@ -271,7 +273,7 @@ export class RemoteTunnelManager { if (isBinary) { if (!tunnel.waitingForBinaryBody) { - console.warn( + this.logger.debug( "Received binary message but no requestId is waiting for body", ); return; @@ -281,7 +283,9 @@ export class RemoteTunnelManager { const pending = tunnel.pendingFetches.get(requestId); if (!pending || !pending.metadata) { - console.warn("Received binary message but pending fetch not found"); + this.logger.debug( + "Received binary message but pending fetch not found", + ); tunnel.waitingForBinaryBody = null; return; } @@ -307,12 +311,16 @@ export class RemoteTunnelManager { if (data.approved) { tunnel.approvedViewers.add(data.viewer); - console.log( - `✅ Approved ${data.viewer} for tunnel ${tunnelId}`, - ); + this.logger.debug("Viewer approved", { + viewer: data.viewer, + tunnelId, + }); } else { tunnel.rejectedViewers.add(data.viewer); - console.log(`❌ Denied ${data.viewer} for tunnel ${tunnelId}`); + this.logger.debug("Viewer denied", { + viewer: data.viewer, + tunnelId, + }); } } } else if (data.type === "fetch:response:meta") { @@ -352,7 +360,9 @@ export class RemoteTunnelManager { } } } catch (e) { - console.error("Failed to parse WebSocket message:", e); + this.logger.error("Failed to parse WebSocket message", e as Error, { + error: e instanceof Error ? e.message : String(e), + }); } }); @@ -362,7 +372,7 @@ export class RemoteTunnelManager { const tunnel = this.tunnels.get(tunnelId); if (tunnel) { - for (const [_, pending] of tunnel.pendingFetches) { + for (const [, pending] of Array.from(tunnel.pendingFetches)) { clearTimeout(pending.timeout); pending.reject(new Error("Tunnel closed")); } @@ -393,7 +403,9 @@ export class RemoteTunnelManager { // Browser → CLI browserWs.on("message", (msg) => { const hmrStart = Date.now(); - console.log("browser -> cli browserWS message", msg.toString()); + this.logger.debug("Browser to CLI message", { + size: (msg as Buffer).length, + }); cliWs.send( JSON.stringify({ type: "hmr:message", @@ -415,10 +427,9 @@ export class RemoteTunnelManager { browserWs.send(data.body); } } catch { - console.error( - "Failed to parse CLI message for HMR:", - msg.toString().substring(0, 100), - ); + this.logger.error("Failed to parse CLI message for HMR", undefined, { + message: msg.toString().substring(0, 100), + }); } }; cliWs.on("message", cliHandler); @@ -471,8 +482,8 @@ export class RemoteTunnelManager { } cleanup() { - for (const [, tunnel] of this.tunnels) { - for (const [_, pending] of tunnel.pendingFetches) { + for (const [, tunnel] of Array.from(this.tunnels)) { + for (const [, pending] of Array.from(tunnel.pendingFetches)) { clearTimeout(pending.timeout); pending.reject(new Error("Server shutting down")); } diff --git a/packages/appkit/src/server/tests/server.test.ts b/packages/appkit/src/server/tests/server.test.ts index 6898f627..358b8e91 100644 --- a/packages/appkit/src/server/tests/server.test.ts +++ b/packages/appkit/src/server/tests/server.test.ts @@ -382,20 +382,25 @@ describe("ServerPlugin", () => { describe("logStartupInfo", () => { test("logs remote tunnel controller disabled when missing", () => { - const logSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const originalDebug = (ServerPlugin as any).debug; + const debugSpy = vi.fn(); + (ServerPlugin as any).debug = debugSpy; const plugin = new ServerPlugin({ autoStart: false }); (plugin as any).remoteTunnelController = undefined; (plugin as any).logStartupInfo(); - expect(logSpy).toHaveBeenCalledWith( + expect(debugSpy).toHaveBeenCalledWith( "Remote tunnel: disabled (controller not initialized)", ); - logSpy.mockRestore(); + + (ServerPlugin as any).debug = originalDebug; }); test("logs remote tunnel allowed/active when controller present", () => { - const logSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const originalDebug = (ServerPlugin as any).debug; + const debugSpy = vi.fn(); + (ServerPlugin as any).debug = debugSpy; const plugin = new ServerPlugin({ autoStart: false }); (plugin as any).remoteTunnelController = { isAllowedByEnv: () => true, @@ -405,17 +410,20 @@ describe("ServerPlugin", () => { (plugin as any).logStartupInfo(); expect( - logSpy.mock.calls.some((c) => + debugSpy.mock.calls.some((c) => String(c[0]).includes("Remote tunnel: allowed; active"), ), ).toBe(true); - logSpy.mockRestore(); + + (ServerPlugin as any).debug = originalDebug; }); }); describe("findStaticPath", () => { test("returns first matching static path and logs it", () => { - const logSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const originalDebug = (ServerPlugin as any).debug; + const debugSpy = vi.fn(); + (ServerPlugin as any).debug = debugSpy; vi.mocked(fs.existsSync).mockImplementation((p: any) => { return String(p).endsWith("dist/index.html"); }); @@ -423,11 +431,12 @@ describe("ServerPlugin", () => { const p = (ServerPlugin as any).findStaticPath(); expect(String(p)).toContain("dist"); expect( - logSpy.mock.calls.some((c) => + debugSpy.mock.calls.some((c) => String(c[0]).includes("Static files: serving from"), ), ).toBe(true); - logSpy.mockRestore(); + + (ServerPlugin as any).debug = originalDebug; }); }); diff --git a/packages/appkit/src/server/vite-dev-server.ts b/packages/appkit/src/server/vite-dev-server.ts index 30ad558f..be314b8a 100644 --- a/packages/appkit/src/server/vite-dev-server.ts +++ b/packages/appkit/src/server/vite-dev-server.ts @@ -2,10 +2,11 @@ import fs from "node:fs"; import path from "node:path"; import type express from "express"; import type { ViteDevServer as ViteDevServerType } from "vite"; +import { type ILogger, LoggerManager } from "@/observability"; import { mergeConfigDedup } from "@/utils"; +import { appKitTypesPlugin } from "../type-generator/vite-plugin"; import { BaseServer } from "./base-server"; import type { PluginEndpoints } from "./utils"; -import { appKitTypesPlugin } from "../type-generator/vite-plugin"; /** * Vite dev server for the AppKit. @@ -21,6 +22,7 @@ import { appKitTypesPlugin } from "../type-generator/vite-plugin"; */ export class ViteDevServer extends BaseServer { private vite: ViteDevServerType | null; + private logger: ILogger = LoggerManager.getLogger("vite-dev-server"); constructor(app: express.Application, endpoints: PluginEndpoints = {}) { super(app, endpoints); @@ -114,7 +116,7 @@ export class ViteDevServer extends BaseServer { const hasIndexHtml = fs.existsSync(path.join(fullPath, "index.html")); if (hasViteConfig && hasIndexHtml) { - console.log(`Vite dev server: using client root ${fullPath}`); + this.logger.debug("Using client root", { path: fullPath }); return fullPath; } } diff --git a/packages/appkit/src/stream/stream-manager.ts b/packages/appkit/src/stream/stream-manager.ts index 354b89e1..082b2ced 100644 --- a/packages/appkit/src/stream/stream-manager.ts +++ b/packages/appkit/src/stream/stream-manager.ts @@ -1,5 +1,6 @@ import { randomUUID } from "node:crypto"; import type { IAppResponse, StreamConfig } from "shared"; +import { type ILogger, LoggerManager } from "@/observability"; import { EventRingBuffer } from "./buffers"; import { streamDefaults } from "./defaults"; import { SSEWriter } from "./sse-writer"; @@ -15,6 +16,8 @@ export class StreamManager { private maxEventSize: number; private bufferTTL: number; + private logger: ILogger = LoggerManager.getLogger("stream-manager"); + constructor(options?: StreamConfig) { this.streamRegistry = new StreamRegistry( options?.maxActiveStreams ?? streamDefaults.maxActiveStreams, @@ -33,6 +36,9 @@ export class StreamManager { ): Promise { const { streamId } = options || {}; + const event = this.logger.getEvent(); + event?.setStream({ stream_id: streamId || "new" }); + // setup SSE headers this.sseWriter.setupHeaders(res); @@ -41,6 +47,7 @@ export class StreamManager { const existingStream = this.streamRegistry.get(streamId); // if stream exists, attach to it if (existingStream) { + event?.setStream({ reconnection: true }); return this._attachToExistingStream(res, existingStream, options); } } @@ -190,12 +197,15 @@ export class StreamManager { private async _processGeneratorInBackground( streamEntry: StreamEntry, ): Promise { + const event = this.logger.getEvent(); + let eventCount = 0; + try { // retrieve all events from generator - for await (const event of streamEntry.generator) { + for await (const generatorEvent of streamEntry.generator) { if (streamEntry.abortController.signal.aborted) break; const eventId = randomUUID(); - const eventData = JSON.stringify(event); + const eventData = JSON.stringify(generatorEvent); // validate event size if (eventData.length > this.maxEventSize) { @@ -214,24 +224,31 @@ export class StreamManager { // buffer event for reconnection streamEntry.eventBuffer.add({ id: eventId, - type: event.type, + type: generatorEvent.type, data: eventData, timestamp: Date.now(), }); + eventCount++; + // broadcast to all connected clients - this._broadcastEventsToClients(streamEntry, eventId, event); + this._broadcastEventsToClients(streamEntry, eventId, generatorEvent); streamEntry.lastAccess = Date.now(); } streamEntry.isCompleted = true; + event?.setStream({ events_sent: eventCount }); + // close all clients this._closeAllClients(streamEntry); // cleanup if no clients are connected this._cleanupStream(streamEntry); } catch (error) { + event?.setStream({ events_sent: eventCount }); + event?.setError(error as Error); + const errorMsg = error instanceof Error ? error.message : "Internal server error"; const errorEventId = randomUUID(); @@ -291,7 +308,7 @@ export class StreamManager { eventId: string, event: any, ): void { - for (const client of streamEntry.clients) { + for (const client of Array.from(streamEntry.clients)) { if (!client.writableEnded) { this.sseWriter.writeEvent(client, eventId, event); } @@ -306,7 +323,7 @@ export class StreamManager { errorCode: SSEErrorCode, closeClients: boolean = false, ): void { - for (const client of streamEntry.clients) { + for (const client of Array.from(streamEntry.clients)) { if (!client.writableEnded) { this.sseWriter.writeError(client, eventId, errorMessage, errorCode); if (closeClients) { @@ -318,7 +335,7 @@ export class StreamManager { // close all connected clients private _closeAllClients(streamEntry: StreamEntry): void { - for (const client of streamEntry.clients) { + for (const client of Array.from(streamEntry.clients)) { if (!client.writableEnded) { client.end(); } diff --git a/packages/appkit/src/telemetry/config.ts b/packages/appkit/src/telemetry/config.ts deleted file mode 100644 index 894ffe7a..00000000 --- a/packages/appkit/src/telemetry/config.ts +++ /dev/null @@ -1,26 +0,0 @@ -import type { TelemetryOptions } from "shared"; - -export interface TelemetryProviderConfig { - traces: boolean; - metrics: boolean; - logs: boolean; -} - -export function normalizeTelemetryOptions( - config?: TelemetryOptions, -): TelemetryProviderConfig { - if (typeof config === "undefined" || typeof config === "boolean") { - const value = config ?? true; - return { - traces: value, - metrics: value, - logs: value, - }; - } - - return { - traces: config?.traces ?? true, - metrics: config?.metrics ?? true, - logs: config?.logs ?? true, - }; -} diff --git a/packages/appkit/src/telemetry/index.ts b/packages/appkit/src/telemetry/index.ts deleted file mode 100644 index 52332303..00000000 --- a/packages/appkit/src/telemetry/index.ts +++ /dev/null @@ -1,21 +0,0 @@ -export type { - Attributes, - Counter, - Histogram, - Meter, - Span, - SpanOptions, - Tracer, -} from "@opentelemetry/api"; -export { context, SpanKind, SpanStatusCode } from "@opentelemetry/api"; -export type { LogAttributes, Logger, LogRecord } from "@opentelemetry/api-logs"; -export { SeverityNumber } from "@opentelemetry/api-logs"; -export { normalizeTelemetryOptions } from "./config"; -export { instrumentations } from "./instrumentations"; -export { TelemetryManager } from "./telemetry-manager"; -export { TelemetryProvider } from "./telemetry-provider"; -export type { - InstrumentConfig, - ITelemetry, - TelemetryConfig, -} from "./types"; diff --git a/packages/appkit/src/telemetry/instrumentations.ts b/packages/appkit/src/telemetry/instrumentations.ts deleted file mode 100644 index 6b356f00..00000000 --- a/packages/appkit/src/telemetry/instrumentations.ts +++ /dev/null @@ -1,55 +0,0 @@ -import { ExpressInstrumentation } from "@opentelemetry/instrumentation-express"; -import { HttpInstrumentation } from "@opentelemetry/instrumentation-http"; -import type { Instrumentation } from "@opentelemetry/instrumentation"; - -/** - * Registry of pre-configured instrumentations for common use cases. - * These can be selectively registered by plugins that need them. - * - * While instrumentations are generally safe to re-register, - * the recommended approach is to register them once in a corresponding plugin constructor. - */ -export const instrumentations: Record = { - http: new HttpInstrumentation({ - applyCustomAttributesOnSpan(span: any, request: any) { - let spanName: string | null = null; - - if (request.route) { - const baseUrl = request.baseUrl || ""; - const url = request.url?.split("?")[0] || ""; - const fullPath = baseUrl + url; - if (fullPath) { - spanName = `${request.method} ${fullPath}`; - } - } else if (request.url) { - // No Express route (e.g., static assets) - use the raw URL path - // Remove query string for cleaner trace names - const path = request.url.split("?")[0]; - spanName = `${request.method} ${path}`; - } - - if (spanName) { - span.updateName(spanName); - } - }, - }), - express: new ExpressInstrumentation({ - requestHook: (span: any, info: any) => { - const req = info.request; - - // Only update span name for route handlers (layerType: request_handler) - // This ensures we're not renaming middleware spans - if (info.layerType === "request_handler" && req.route) { - // Combine baseUrl with url to get full path with actual parameter values - // e.g., baseUrl="/api/analytics" + url="/query/spend_data" = "/api/analytics/query/spend_data" - const baseUrl = req.baseUrl || ""; - const url = req.url?.split("?")[0] || ""; - const fullPath = baseUrl + url; - if (fullPath) { - const spanName = `${req.method} ${fullPath}`; - span.updateName(spanName); - } - } - }, - }), -}; diff --git a/packages/appkit/src/telemetry/noop.ts b/packages/appkit/src/telemetry/noop.ts deleted file mode 100644 index 12f48548..00000000 --- a/packages/appkit/src/telemetry/noop.ts +++ /dev/null @@ -1,97 +0,0 @@ -// Our own noop tracer implementation. -// Why? -// Unfortunately, noop tracer is not exported from the api package, unlike noop meter and noop logger. -// Read more: https://github.com/open-telemetry/opentelemetry-js/issues/3455 -// and https://github.com/open-telemetry/opentelemetry-js/issues/4518 -// -// The original implementation is here: https://github.com/open-telemetry/opentelemetry-js/blob/a7acd9355cd0c1da63d285dfb960efeacc3cbc15/api/src/trace/NoopTracer.ts#L32 -// licensed under the Apache License 2.0. -// Our own implementation is much simpler but will do the job for our needs. - -import type { - Context, - Span, - SpanContext, - SpanOptions, - Tracer, -} from "@opentelemetry/api"; -import { - createNoopMeter, - INVALID_SPAN_CONTEXT, - type SpanStatusCode, -} from "@opentelemetry/api"; - -class NonRecordingSpan implements Span { - private readonly _spanContext: SpanContext; - - constructor(spanContext: SpanContext = INVALID_SPAN_CONTEXT) { - this._spanContext = spanContext; - } - - spanContext(): SpanContext { - return this._spanContext; - } - - setAttribute(_key: string, _value: any): this { - return this; - } - - setAttributes(_attributes: any): this { - return this; - } - - addEvent( - _name: string, - _attributesOrStartTime?: any, - _startTime?: any, - ): this { - return this; - } - - addLink(_link: any): this { - return this; - } - - addLinks(_links: any[]): this { - return this; - } - - setStatus(_status: { code: SpanStatusCode; message?: string }): this { - return this; - } - - updateName(_name: string): this { - return this; - } - - end(_endTime?: number): void {} - - isRecording(): boolean { - return false; - } - - recordException(_exception: any, _time?: number): void {} -} - -export class NoopTracer implements Tracer { - startSpan(_name: string, _options?: SpanOptions, _context?: Context): Span { - return new NonRecordingSpan(INVALID_SPAN_CONTEXT); - } - - startActiveSpan any>( - _name: string, - ...args: [F] | [SpanOptions, F] | [SpanOptions, Context, F] - ): ReturnType | undefined { - const fn = args[args.length - 1] as F; - - if (typeof fn !== "function") { - return undefined as ReturnType; - } - - return fn(new NonRecordingSpan(INVALID_SPAN_CONTEXT)); - } -} - -export const NOOP_TRACER = new NoopTracer(); -export const NOOP_METER = createNoopMeter(); -export { NOOP_LOGGER } from "@opentelemetry/api-logs"; diff --git a/packages/appkit/src/telemetry/telemetry-manager.ts b/packages/appkit/src/telemetry/telemetry-manager.ts deleted file mode 100644 index f9b34847..00000000 --- a/packages/appkit/src/telemetry/telemetry-manager.ts +++ /dev/null @@ -1,178 +0,0 @@ -import type { TelemetryOptions } from "shared"; -import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node"; -import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-proto"; -import { OTLPMetricExporter } from "@opentelemetry/exporter-metrics-otlp-proto"; -import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-proto"; -import { - type Instrumentation, - registerInstrumentations as otelRegisterInstrumentations, -} from "@opentelemetry/instrumentation"; -import { - detectResources, - envDetector, - hostDetector, - processDetector, - type Resource, - resourceFromAttributes, -} from "@opentelemetry/resources"; -import { BatchLogRecordProcessor } from "@opentelemetry/sdk-logs"; -import { PeriodicExportingMetricReader } from "@opentelemetry/sdk-metrics"; -import { AlwaysOnSampler } from "@opentelemetry/sdk-trace-base"; -import { - ATTR_SERVICE_NAME, - ATTR_SERVICE_VERSION, -} from "@opentelemetry/semantic-conventions"; -import { TelemetryProvider } from "./telemetry-provider"; -import type { TelemetryConfig } from "./types"; -import { NodeSDK } from "@opentelemetry/sdk-node"; - -export class TelemetryManager { - private static readonly DEFAULT_EXPORT_INTERVAL_MS = 10000; - private static readonly DEFAULT_FALLBACK_APP_NAME = "databricks-app"; - - private static instance?: TelemetryManager; - private sdk?: NodeSDK; - - /** - * Create a scoped telemetry provider for a specific plugin. - * The plugin's name will be used as the default tracer/meter name. - * @param pluginName - The name of the plugin to create scoped telemetry for - * @param telemetryConfig - The telemetry configuration for the plugin - * @returns A scoped telemetry instance for the plugin - */ - static getProvider( - pluginName: string, - telemetryConfig?: TelemetryOptions, - ): TelemetryProvider { - const globalManager = TelemetryManager.getInstance(); - return new TelemetryProvider(pluginName, globalManager, telemetryConfig); - } - - private constructor() {} - - static getInstance(): TelemetryManager { - if (!TelemetryManager.instance) { - TelemetryManager.instance = new TelemetryManager(); - } - return TelemetryManager.instance; - } - - static initialize(config: Partial = {}): void { - const instance = TelemetryManager.getInstance(); - instance._initialize(config); - } - - private _initialize(config: Partial): void { - if (this.sdk) return; - - if (!process.env.OTEL_EXPORTER_OTLP_ENDPOINT) { - return; - } - - try { - this.sdk = new NodeSDK({ - resource: this.createResource(config), - autoDetectResources: false, - sampler: new AlwaysOnSampler(), - traceExporter: new OTLPTraceExporter({ headers: config.headers }), - metricReaders: [ - new PeriodicExportingMetricReader({ - exporter: new OTLPMetricExporter({ headers: config.headers }), - exportIntervalMillis: - config.exportIntervalMs || - TelemetryManager.DEFAULT_EXPORT_INTERVAL_MS, - }), - ], - logRecordProcessors: [ - new BatchLogRecordProcessor( - new OTLPLogExporter({ headers: config.headers }), - ), - ], - instrumentations: this.getDefaultInstrumentations(), - }); - - this.sdk.start(); - this.registerShutdown(); - console.log("[Telemetry] Initialized successfully"); - } catch (error) { - console.error("[Telemetry] Failed to initialize:", error); - } - } - - /** - * Register OpenTelemetry instrumentations. - * Can be called at any time, but recommended to call in plugin constructor. - * @param instrumentations - Array of OpenTelemetry instrumentations to register - */ - registerInstrumentations(instrumentations: Instrumentation[]): void { - otelRegisterInstrumentations({ - // global providers set by NodeSDK.start() - instrumentations, - }); - } - - private createResource(config: Partial): Resource { - const serviceName = - config.serviceName || - process.env.OTEL_SERVICE_NAME || - process.env.DATABRICKS_APP_NAME || - TelemetryManager.DEFAULT_FALLBACK_APP_NAME; - const initialResource = resourceFromAttributes({ - [ATTR_SERVICE_NAME]: serviceName, - [ATTR_SERVICE_VERSION]: config.serviceVersion ?? undefined, - }); - const detectedResource = detectResources({ - detectors: [envDetector, hostDetector, processDetector], - }); - return initialResource.merge(detectedResource); - } - - private getDefaultInstrumentations(): Instrumentation[] { - return [ - ...getNodeAutoInstrumentations({ - // - // enabled as a part of the server plugin - // - "@opentelemetry/instrumentation-http": { - enabled: false, - }, - "@opentelemetry/instrumentation-express": { - enabled: false, - }, - // - // reduce noise - // - "@opentelemetry/instrumentation-fs": { - enabled: false, - }, - "@opentelemetry/instrumentation-dns": { - enabled: false, - }, - "@opentelemetry/instrumentation-net": { - enabled: false, - }, - }), - ]; - } - - private registerShutdown() { - const shutdownFn = async () => { - await TelemetryManager.getInstance().shutdown(); - }; - process.once("SIGTERM", shutdownFn); - process.once("SIGINT", shutdownFn); - } - - private async shutdown(): Promise { - if (!this.sdk) { - return; - } - - try { - await this.sdk.shutdown(); - this.sdk = undefined; - } catch (error) { - console.error("[Telemetry] Error shutting down:", error); - } - } -} diff --git a/packages/appkit/src/telemetry/telemetry-provider.ts b/packages/appkit/src/telemetry/telemetry-provider.ts deleted file mode 100644 index 00fb16a6..00000000 --- a/packages/appkit/src/telemetry/telemetry-provider.ts +++ /dev/null @@ -1,122 +0,0 @@ -import type { TelemetryOptions } from "shared"; -import type { Meter, Span, SpanOptions, Tracer } from "@opentelemetry/api"; -import { metrics, trace } from "@opentelemetry/api"; -import { type Logger, type LogRecord, logs } from "@opentelemetry/api-logs"; -import type { Instrumentation } from "@opentelemetry/instrumentation"; -import { - normalizeTelemetryOptions, - type TelemetryProviderConfig, -} from "./config"; -import { NOOP_LOGGER, NOOP_METER, NOOP_TRACER } from "./noop"; -import type { TelemetryManager } from "./telemetry-manager"; -import type { InstrumentConfig, ITelemetry } from "./types"; - -/** - * Scoped telemetry instance for specific plugins and other classes. - * Automatically uses the plugin name as the default tracer/meter name. - */ -export class TelemetryProvider implements ITelemetry { - private readonly pluginName: string; - private readonly globalManager: TelemetryManager; - private readonly config: TelemetryProviderConfig; - - constructor( - pluginName: string, - globalManager: TelemetryManager, - telemetryConfig?: TelemetryOptions, - ) { - this.pluginName = pluginName; - this.globalManager = globalManager; - this.config = normalizeTelemetryOptions(telemetryConfig); - } - - /** - * Gets a tracer for creating spans. - * @param options - Optional tracer configuration. - */ - getTracer(options?: InstrumentConfig): Tracer { - if (!this.config.traces) { - return NOOP_TRACER; - } - - const tracerName = this.getInstrumentName(options); - return trace.getTracer(tracerName); - } - - /** - * Gets a meter for recording metrics. - * @param config - Optional meter configuration. - */ - getMeter(config?: InstrumentConfig): Meter { - if (!this.config.metrics) { - return NOOP_METER; - } - - const meterName = this.getInstrumentName(config); - return metrics.getMeter(meterName); - } - - /** - * Gets a logger for emitting log records. - * @param config - Optional logger configuration. - */ - getLogger(config?: InstrumentConfig): Logger { - if (!this.config.logs) { - return NOOP_LOGGER; - } - - const loggerName = this.getInstrumentName(config); - return logs.getLogger(loggerName); - } - - /** - * Emits a log record using the default logger. - * Convenience method for logging without explicitly getting a logger. - * @param logRecord - The log record to emit - */ - emit(logRecord: LogRecord): void { - const logger = this.getLogger(); - logger.emit(logRecord); - } - - /** - * Register OpenTelemetry instrumentations. - * Can be called at any time, but recommended to call in plugin constructor. - * @param instrumentations - Array of OpenTelemetry instrumentations to register - */ - registerInstrumentations(instrumentations: Instrumentation[]): void { - if (!this.config.traces) { - return; - } - - this.globalManager.registerInstrumentations(instrumentations); - } - - /** - * Starts an active span and executes a callback function within its context. - * Uses the plugin's default tracer unless custom tracer options are provided. - * @param name - The name of the span - * @param options - Span options including attributes, kind, etc. - * @param fn - Callback function to execute within the span context - * @param tracerOptions - Optional tracer configuration - * @returns Promise resolving to the callback's return value - */ - startActiveSpan( - name: string, - options: SpanOptions, - fn: (span: Span) => Promise, - tracerOptions?: InstrumentConfig, - ): Promise { - const tracer = this.getTracer(tracerOptions); - return tracer.startActiveSpan(name, options, fn); - } - - private getInstrumentName(options?: InstrumentConfig): string { - const prefix = this.pluginName; - if (!options || !options.name) { - return this.pluginName; - } - - return options.includePrefix ? `${prefix}-${options.name}` : options.name; - } -} diff --git a/packages/appkit/src/telemetry/tests/config.test.ts b/packages/appkit/src/telemetry/tests/config.test.ts deleted file mode 100644 index 679a262d..00000000 --- a/packages/appkit/src/telemetry/tests/config.test.ts +++ /dev/null @@ -1,47 +0,0 @@ -import { describe, expect, test } from "vitest"; -import { normalizeTelemetryOptions } from "../config"; - -describe("normalizeTelemetryOptions", () => { - test.each([ - { - description: - "should return all enabled when config is undefined (default)", - input: undefined, - expected: { traces: true, metrics: true, logs: true }, - }, - { - description: "should return all enabled when config is true", - input: true, - expected: { traces: true, metrics: true, logs: true }, - }, - { - description: "should return all disabled when config is false", - input: false, - expected: { traces: false, metrics: false, logs: false }, - }, - { - description: "should return config object as-is when provided", - input: { traces: true, metrics: false, logs: true }, - expected: { traces: true, metrics: false, logs: true }, - }, - { - description: - "should handle mixed configuration (traces and logs enabled)", - input: { traces: true, metrics: false, logs: true }, - expected: { traces: true, metrics: false, logs: true }, - }, - { - description: "should handle mixed configuration (only metrics enabled)", - input: { traces: false, metrics: true, logs: false }, - expected: { traces: false, metrics: true, logs: false }, - }, - { - description: "should handle partial configuration", - input: { traces: false }, - expected: { traces: false, metrics: true, logs: true }, - }, - ])("$description", ({ input, expected }) => { - const result = normalizeTelemetryOptions(input); - expect(result).toEqual(expected); - }); -}); diff --git a/packages/appkit/src/telemetry/tests/plugin-telemetry.test.ts b/packages/appkit/src/telemetry/tests/plugin-telemetry.test.ts deleted file mode 100644 index a6f22e03..00000000 --- a/packages/appkit/src/telemetry/tests/plugin-telemetry.test.ts +++ /dev/null @@ -1,243 +0,0 @@ -import { NOOP_LOGGER } from "@opentelemetry/api-logs"; -import { beforeEach, describe, expect, test, vi } from "vitest"; -import { NOOP_METER, NOOP_TRACER } from "../noop"; -import type { TelemetryManager } from "../telemetry-manager"; -import { TelemetryProvider } from "../telemetry-provider"; - -vi.mock("@opentelemetry/api", () => ({ - trace: { - getTracer: vi.fn(), - }, - metrics: { - getMeter: vi.fn(), - }, - SpanStatusCode: { - OK: 0, - ERROR: 2, - }, - createNoopMeter: vi.fn(() => ({})), -})); - -vi.mock("@opentelemetry/api-logs", () => ({ - NOOP_LOGGER: { - emit: vi.fn(), - }, - logs: { - getLogger: vi.fn(), - }, -})); - -describe("TelemetryProvider", () => { - let mockManager: TelemetryManager; - let mockTracer: any; - let mockMeter: any; - let mockLogger: any; - - beforeEach(async () => { - // Reset mocks - vi.clearAllMocks(); - - mockManager = { - registerInstrumentations: vi.fn(), - } as any; - - mockTracer = { - startActiveSpan: vi.fn(), - startSpan: vi.fn(), - }; - - mockMeter = { - createCounter: vi.fn(), - createHistogram: vi.fn(), - }; - - mockLogger = { - emit: vi.fn(), - }; - - const { trace } = await import("@opentelemetry/api"); - const { logs } = await import("@opentelemetry/api-logs"); - const { metrics } = await import("@opentelemetry/api"); - - vi.mocked(trace.getTracer).mockReturnValue(mockTracer); - vi.mocked(metrics.getMeter).mockReturnValue(mockMeter); - vi.mocked(logs.getLogger).mockReturnValue(mockLogger); - }); - - test("should return NOOP_TRACER when traces disabled", () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager, { - traces: false, - metrics: true, - logs: true, - }); - - const tracer = telemetry.getTracer(); - - expect(tracer).toBe(NOOP_TRACER); - }); - - test("should return NOOP_METER when metrics disabled", () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager, { - traces: true, - metrics: false, - logs: true, - }); - - const meter = telemetry.getMeter(); - - expect(meter).toBe(NOOP_METER); - }); - - test("should return NOOP_LOGGER when logs disabled", () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager, { - traces: true, - metrics: true, - logs: false, - }); - - const logger = telemetry.getLogger(); - - expect(logger).toBe(NOOP_LOGGER); - }); - - test("should return real tracer from OpenTelemetry API when enabled", async () => { - const { trace } = await import("@opentelemetry/api"); - const telemetry = new TelemetryProvider("test-plugin", mockManager); - - const tracer = telemetry.getTracer(); - - expect(trace.getTracer).toHaveBeenCalledWith("test-plugin"); - expect(tracer).toBe(mockTracer); - }); - - test("should return real meter from OpenTelemetry API when enabled", async () => { - const { metrics } = await import("@opentelemetry/api"); - const telemetry = new TelemetryProvider("test-plugin", mockManager); - - const meter = telemetry.getMeter(); - - expect(metrics.getMeter).toHaveBeenCalledWith("test-plugin"); - expect(meter).toBe(mockMeter); - }); - - test("should return real logger from OpenTelemetry API when enabled", async () => { - const { logs } = await import("@opentelemetry/api-logs"); - const telemetry = new TelemetryProvider("test-plugin", mockManager); - - const logger = telemetry.getLogger(); - - expect(logs.getLogger).toHaveBeenCalledWith("test-plugin"); - expect(logger).toBe(mockLogger); - }); - - test("should use plugin name as default instrument name", async () => { - const { trace } = await import("@opentelemetry/api"); - const telemetry = new TelemetryProvider("my-plugin", mockManager); - - telemetry.getTracer(); - - expect(trace.getTracer).toHaveBeenCalledWith("my-plugin"); - }); - - test("should include prefix when includePrefix is true", async () => { - const { trace } = await import("@opentelemetry/api"); - const telemetry = new TelemetryProvider("my-plugin", mockManager); - - telemetry.getTracer({ name: "custom", includePrefix: true }); - - expect(trace.getTracer).toHaveBeenCalledWith("my-plugin-custom"); - }); - - test("should use custom name without prefix when includePrefix is false", async () => { - const { trace } = await import("@opentelemetry/api"); - const telemetry = new TelemetryProvider("my-plugin", mockManager); - - telemetry.getTracer({ name: "custom", includePrefix: false }); - - expect(trace.getTracer).toHaveBeenCalledWith("custom"); - }); - - test("should use custom name without prefix when includePrefix is not specified", async () => { - const { trace } = await import("@opentelemetry/api"); - const telemetry = new TelemetryProvider("my-plugin", mockManager); - - telemetry.getTracer({ name: "custom" }); - - expect(trace.getTracer).toHaveBeenCalledWith("custom"); - }); - - test("should delegate startActiveSpan to tracer", async () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager); - const mockSpan = { end: vi.fn() }; - const callback = vi.fn().mockResolvedValue("result"); - - mockTracer.startActiveSpan.mockImplementation( - async (_name: string, _options: any, fn: any) => { - return fn(mockSpan); - }, - ); - - const result = await telemetry.startActiveSpan( - "test-span", - { attributes: { key: "value" } }, - callback, - ); - - expect(mockTracer.startActiveSpan).toHaveBeenCalledWith( - "test-span", - { attributes: { key: "value" } }, - callback, - ); - expect(result).toBe("result"); - }); - - test("should delegate registerInstrumentations to global manager", () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager); - const instrumentations = [{ name: "test-instrumentation" }] as any; - - telemetry.registerInstrumentations(instrumentations); - - expect(mockManager.registerInstrumentations).toHaveBeenCalledWith( - instrumentations, - ); - }); - - test("should not register instrumentations when traces disabled", () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager, { - traces: false, - metrics: true, - logs: true, - }); - const instrumentations = [{ name: "test-instrumentation" }] as any; - - telemetry.registerInstrumentations(instrumentations); - - expect(mockManager.registerInstrumentations).not.toHaveBeenCalled(); - }); - - test("should call logger.emit() in emit method", () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager); - const logRecord = { - body: "test log message", - severityNumber: 9, - } as any; - - telemetry.emit(logRecord); - - expect(mockLogger.emit).toHaveBeenCalledWith(logRecord); - }); - - test("should handle emit when logs are disabled", () => { - const telemetry = new TelemetryProvider("test-plugin", mockManager, { - traces: true, - metrics: true, - logs: false, - }); - const logRecord = { - body: "test log message", - severityNumber: 9, - } as any; - - expect(() => telemetry.emit(logRecord)).not.toThrow(); - }); -}); diff --git a/packages/appkit/src/telemetry/tests/telemetry-interceptor.test.ts b/packages/appkit/src/telemetry/tests/telemetry-interceptor.test.ts deleted file mode 100644 index f78358ee..00000000 --- a/packages/appkit/src/telemetry/tests/telemetry-interceptor.test.ts +++ /dev/null @@ -1,134 +0,0 @@ -import type { TelemetryConfig } from "shared"; -import { SpanStatusCode, type Span } from "@opentelemetry/api"; -import { beforeEach, describe, expect, test, vi } from "vitest"; -import { TelemetryInterceptor } from "../../plugin/interceptors/telemetry"; -import type { InterceptorContext } from "../../plugin/interceptors/types"; -import type { ITelemetry } from "../types"; - -describe("TelemetryInterceptor", () => { - let mockTelemetry: ITelemetry; - let mockSpan: Span; - let context: InterceptorContext; - - beforeEach(() => { - mockSpan = { - setAttribute: vi.fn(), - setStatus: vi.fn(), - addEvent: vi.fn(), - recordException: vi.fn(), - end: vi.fn(), - } as any; - - mockTelemetry = { - getTracer: vi.fn(), - getMeter: vi.fn(), - getLogger: vi.fn(), - emit: vi.fn(), - startActiveSpan: vi - .fn() - .mockImplementation(async (_name, _options, fn) => { - return fn(mockSpan); - }), - registerInstrumentations: vi.fn(), - } as any; - - context = { - metadata: new Map(), - userKey: "test", - }; - }); - - test("should execute function and set span status to OK on success", async () => { - const interceptor = new TelemetryInterceptor(mockTelemetry); - const fn = vi.fn().mockResolvedValue("success"); - - const result = await interceptor.intercept(fn, context); - - expect(result).toBe("success"); - expect(fn).toHaveBeenCalledTimes(1); - expect(mockSpan.setStatus).toHaveBeenCalledWith({ - code: SpanStatusCode.OK, - }); - expect(mockSpan.end).toHaveBeenCalledTimes(1); - }); - - test("should record exception and set span status to ERROR on failure", async () => { - const interceptor = new TelemetryInterceptor(mockTelemetry); - const error = new Error("test error"); - const fn = vi.fn().mockRejectedValue(error); - - await expect(interceptor.intercept(fn, context)).rejects.toThrow( - "test error", - ); - - expect(mockSpan.recordException).toHaveBeenCalledWith(error); - expect(mockSpan.setStatus).toHaveBeenCalledWith({ - code: SpanStatusCode.ERROR, - }); - expect(mockSpan.end).toHaveBeenCalledTimes(1); - }); - - test("should use custom span name from config", async () => { - const config: TelemetryConfig = { - spanName: "custom.span.name", - }; - const interceptor = new TelemetryInterceptor(mockTelemetry, config); - const fn = vi.fn().mockResolvedValue("result"); - - await interceptor.intercept(fn, context); - - expect(mockTelemetry.startActiveSpan).toHaveBeenCalledWith( - "custom.span.name", - expect.any(Object), - expect.any(Function), - ); - }); - - test("should use default span name when not provided", async () => { - const interceptor = new TelemetryInterceptor(mockTelemetry); - const fn = vi.fn().mockResolvedValue("result"); - - await interceptor.intercept(fn, context); - - expect(mockTelemetry.startActiveSpan).toHaveBeenCalledWith( - "plugin.execute", - expect.any(Object), - expect.any(Function), - ); - }); - - test("should merge custom attributes from config", async () => { - const config: TelemetryConfig = { - attributes: { - "custom.attr1": "value1", - "custom.attr2": "value2", - }, - }; - const interceptor = new TelemetryInterceptor(mockTelemetry, config); - const fn = vi.fn().mockResolvedValue("result"); - - await interceptor.intercept(fn, context); - - expect(mockTelemetry.startActiveSpan).toHaveBeenCalledWith( - "plugin.execute", - { - attributes: { - "custom.attr1": "value1", - "custom.attr2": "value2", - }, - }, - expect.any(Function), - ); - }); - - test("should call span.end() in finally block even on error", async () => { - const interceptor = new TelemetryInterceptor(mockTelemetry); - const error = new Error("test error"); - const fn = vi.fn().mockRejectedValue(error); - - await expect(interceptor.intercept(fn, context)).rejects.toThrow(); - - // Verify end was called despite the error - expect(mockSpan.end).toHaveBeenCalledTimes(1); - }); -}); diff --git a/packages/appkit/src/telemetry/tests/telemetry-manager.test.ts b/packages/appkit/src/telemetry/tests/telemetry-manager.test.ts deleted file mode 100644 index 11b85d9b..00000000 --- a/packages/appkit/src/telemetry/tests/telemetry-manager.test.ts +++ /dev/null @@ -1,227 +0,0 @@ -import { afterEach, beforeEach, describe, expect, test, vi } from "vitest"; -import { TelemetryManager } from "../telemetry-manager"; - -// Mock only exporters to prevent network calls -vi.mock("@opentelemetry/exporter-trace-otlp-proto", () => ({ - OTLPTraceExporter: vi.fn(() => ({ - export: vi.fn((_spans, callback) => callback({ code: 0 })), - shutdown: vi.fn().mockResolvedValue(undefined), - forceFlush: vi.fn().mockResolvedValue(undefined), - })), -})); - -vi.mock("@opentelemetry/exporter-metrics-otlp-proto", () => ({ - OTLPMetricExporter: vi.fn(() => ({ - export: vi.fn((_metrics, callback) => callback({ code: 0 })), - shutdown: vi.fn().mockResolvedValue(undefined), - forceFlush: vi.fn().mockResolvedValue(undefined), - })), -})); - -vi.mock("@opentelemetry/exporter-logs-otlp-proto", () => ({ - OTLPLogExporter: vi.fn(() => ({ - export: vi.fn((_logs, callback) => callback({ code: 0 })), - shutdown: vi.fn().mockResolvedValue(undefined), - forceFlush: vi.fn().mockResolvedValue(undefined), - })), -})); - -// Mock resource detection to avoid env complexity -vi.mock("@opentelemetry/resources", async () => { - const actual = await vi.importActual< - typeof import("@opentelemetry/resources") - >("@opentelemetry/resources"); - return { - ...actual, - detectResources: vi.fn(() => { - return actual.resourceFromAttributes({ - "host.name": "test-host", - }); - }), - }; -}); - -// Mock auto-instrumentations to avoid side effects -vi.mock("@opentelemetry/auto-instrumentations-node", () => ({ - getNodeAutoInstrumentations: vi.fn(() => []), -})); - -describe("TelemetryManager", () => { - let originalEnv: NodeJS.ProcessEnv; - - beforeEach(() => { - originalEnv = { ...process.env }; - vi.clearAllMocks(); - // @ts-expect-error - accessing private static property for testing - TelemetryManager.instance = undefined; - // @ts-expect-error - accessing private static property for testing - TelemetryManager.shutdownRegistered = false; - }); - - afterEach(() => { - process.env = originalEnv; - }); - - test("getInstance() should return singleton instance", () => { - const instance1 = TelemetryManager.getInstance(); - const instance2 = TelemetryManager.getInstance(); - - expect(instance1).toBe(instance2); - }); - - test("should call detectResources when initializing", async () => { - process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; - - const { detectResources } = await import("@opentelemetry/resources"); - vi.clearAllMocks(); - - TelemetryManager.initialize({ - serviceName: "test-service-config", - }); - - expect(detectResources).toHaveBeenCalled(); - }); - - test("should initialize providers and create telemetry instances", async () => { - process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; - - TelemetryManager.initialize({ - serviceName: "integration-test", - serviceVersion: "1.0.0", - }); - - const telemetryProvider = TelemetryManager.getProvider("test-plugin"); - const tracer = telemetryProvider.getTracer(); - const meter = telemetryProvider.getMeter(); - const logger = telemetryProvider.getLogger(); - - expect(tracer).toBeDefined(); - expect(meter).toBeDefined(); - expect(logger).toBeDefined(); - - expect(() => - tracer.startActiveSpan("test.span", {}, async (span) => { - span.setAttribute("test.attribute", "test-value"); - span.setAttribute("test.number", 42); - span.addEvent("test.event", { eventData: "some-data" }); - span.end(); - return "test-result"; - }), - ).not.toThrow(); - expect(() => meter.createCounter("integration.counter")).not.toThrow(); - expect(() => meter.createHistogram("integration.histogram")).not.toThrow(); - expect(() => - logger.emit({ body: "test-log", severityNumber: 9 }), - ).not.toThrow(); - }); - - test("should support disabled telemetry config", async () => { - process.env.OTEL_EXPORTER_OTLP_ENDPOINT = ""; - - TelemetryManager.initialize({ - serviceName: "disabled-test", - serviceVersion: "1.0.0", - }); - - const telemetryProvider = TelemetryManager.getProvider("disabled-plugin", { - traces: false, - metrics: false, - logs: false, - }); - - const tracer = telemetryProvider.getTracer(); - const meter = telemetryProvider.getMeter(); - const logger = telemetryProvider.getLogger(); - - expect(tracer).toBeDefined(); - expect(meter).toBeDefined(); - expect(logger).toBeDefined(); - - expect(() => - tracer.startActiveSpan("test.span", {}, async (span) => { - span.setAttribute("test.attribute", "test-value"); - span.setAttribute("test.number", 42); - span.addEvent("test.event", { eventData: "some-data" }); - span.end(); - return "test-result"; - }), - ).not.toThrow(); - expect(() => meter.createCounter("integration.counter")).not.toThrow(); - expect(() => meter.createHistogram("integration.histogram")).not.toThrow(); - expect(() => - logger.emit({ body: "test-log", severityNumber: 9 }), - ).not.toThrow(); - }); - - test("should pass headers to exporters", async () => { - process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; - - const { OTLPTraceExporter } = await import( - "@opentelemetry/exporter-trace-otlp-proto" - ); - vi.clearAllMocks(); - - TelemetryManager.initialize({ - headers: { - Authorization: "Bearer token", - "Custom-Header": "value", - }, - }); - - expect(OTLPTraceExporter).toHaveBeenCalledWith( - expect.objectContaining({ - headers: { - Authorization: "Bearer token", - "Custom-Header": "value", - }, - }), - ); - }); - - describe("startActiveSpan", () => { - test("should create and execute spans with real tracer", async () => { - process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; - - TelemetryManager.initialize({ - serviceName: "span-test", - serviceVersion: "1.0.0", - }); - - const telemetryProvider = - TelemetryManager.getProvider("span-test-plugin"); - const tracer = telemetryProvider.getTracer(); - - let spanWasExecuted = false; - await tracer.startActiveSpan("test.span", {}, async (span) => { - span.setAttribute("test.attribute", "test-value"); - span.setAttribute("test.number", 42); - span.addEvent("test.event", { eventData: "some-data" }); - span.end(); - spanWasExecuted = true; - return "test-result"; - }); - - expect(spanWasExecuted).toBe(true); - }); - - test("should handle span errors", async () => { - process.env.OTEL_EXPORTER_OTLP_ENDPOINT = "http://localhost:4318"; - - TelemetryManager.initialize({ - serviceName: "error-test", - serviceVersion: "1.0.0", - }); - - const telemetryProvider = - TelemetryManager.getProvider("error-test-plugin"); - const testError = new Error("Test error in span"); - - await expect( - telemetryProvider.startActiveSpan("failing.span", {}, async (span) => { - span.setAttribute("will.fail", true); - throw testError; - }), - ).rejects.toThrow("Test error in span"); - }); - }); -}); diff --git a/packages/appkit/src/telemetry/types.ts b/packages/appkit/src/telemetry/types.ts deleted file mode 100644 index 5814ee55..00000000 --- a/packages/appkit/src/telemetry/types.ts +++ /dev/null @@ -1,82 +0,0 @@ -import type { Meter, Span, SpanOptions, Tracer } from "@opentelemetry/api"; -import type { Logger, LogRecord } from "@opentelemetry/api-logs"; -import type { Instrumentation } from "@opentelemetry/instrumentation"; - -export interface TelemetryConfig { - serviceName?: string; - serviceVersion?: string; - instrumentations?: Instrumentation[]; - exportIntervalMs?: number; - headers?: Record; -} - -/** - * Instrument customization options. - */ -export interface InstrumentConfig { - /** - * The name of the instrument. - */ - name?: string; - /** - * If true, the prefix from the context (e.g. plugin name) will be kept when constructing the final instrument name. - * For example, if the plugin name is "my-plugin" and the instrument name is "my-instrument", the final instrument name will be "my-plugin-my-instrument". - * If false, the final instrument name will be "my-instrument". - */ - includePrefix?: boolean; -} - -/** - * Plugin-facing interface for OpenTelemetry instrumentation. - * Provides a thin abstraction over OpenTelemetry APIs for plugins. - */ -export interface ITelemetry { - /** - * Gets a tracer for creating spans. - * @param options - Instrument customization options. - */ - getTracer(options?: InstrumentConfig): Tracer; - - /** - * Gets a meter for recording metrics. - * @param options - Instrument customization options. - */ - getMeter(options?: InstrumentConfig): Meter; - - /** - * Gets a logger for emitting log records. - * @param options - Instrument customization options. - */ - getLogger(options?: InstrumentConfig): Logger; - - /** - * Emits a log record using the default logger. - * Respects the logs enabled/disabled config. - * @param logRecord - The log record to emit - */ - emit(logRecord: LogRecord): void; - - /** - * Starts an active span and executes a callback function within its context. - * Respects the traces enabled/disabled config. - * When traces are disabled, executes the callback with a no-op span. - * @param name - The name of the span - * @param options - Span options including attributes, kind, etc. - * @param fn - Callback function to execute within the span context - * @param tracerOptions - Optional tracer configuration (custom name, prefix inclusion) - * @returns Promise resolving to the callback's return value - */ - startActiveSpan( - name: string, - options: SpanOptions, - fn: (span: Span) => Promise, - tracerOptions?: InstrumentConfig, - ): Promise; - - /** - * Register OpenTelemetry instrumentations. - * Can be called at any time, but recommended to call in plugin constructor. - * @param instrumentations - Array of OpenTelemetry instrumentations to register - */ - registerInstrumentations(instrumentations: Instrumentation[]): void; -} diff --git a/packages/appkit/src/type-generator/index.ts b/packages/appkit/src/type-generator/index.ts index 085db6de..167249c1 100644 --- a/packages/appkit/src/type-generator/index.ts +++ b/packages/appkit/src/type-generator/index.ts @@ -1,5 +1,6 @@ import fs from "node:fs"; import dotenv from "dotenv"; +import { type ILogger, LoggerManager } from "@/observability"; import { generateQueriesFromDescribe } from "./query-registry"; import type { QuerySchema } from "./types"; @@ -48,9 +49,11 @@ export async function generateFromEntryPoint(options: { warehouseId: string; noCache?: boolean; }) { + const logger: ILogger = LoggerManager.getLogger("type-generator"); + const { outFile, queryFolder, warehouseId, noCache } = options; - console.log("\n[AppKit] Starting type generation...\n"); + logger.debug("Starting type generation"); let queryRegistry: QuerySchema[] = []; if (queryFolder) @@ -66,5 +69,5 @@ export async function generateFromEntryPoint(options: { fs.writeFileSync(outFile, typeDeclarations, "utf-8"); - console.log("\n[AppKit] Type generation complete!\n"); + logger.debug("Type generation complete"); } diff --git a/packages/appkit/src/type-generator/query-registry.ts b/packages/appkit/src/type-generator/query-registry.ts index 4842b810..73d0757f 100644 --- a/packages/appkit/src/type-generator/query-registry.ts +++ b/packages/appkit/src/type-generator/query-registry.ts @@ -1,6 +1,7 @@ import fs from "node:fs"; import path from "node:path"; import { WorkspaceClient } from "@databricks/sdk-experimental"; +import { type ILogger, LoggerManager } from "@/observability"; import { CACHE_VERSION, hashSQL, loadCache, saveCache } from "./cache"; import { Spinner } from "./spinner"; import { @@ -18,7 +19,7 @@ import { export function extractParameters(sql: string): string[] { const matches = sql.matchAll(/:([a-zA-Z_]\w*)/g); const params = new Set(); - for (const match of matches) { + for (const match of Array.from(matches)) { params.add(match[1]); } return Array.from(params); @@ -92,7 +93,7 @@ export function extractParameterTypes(sql: string): Record { const regex = /--\s*@param\s+(\w+)\s+(STRING|NUMERIC|BOOLEAN|DATE|TIMESTAMP|BINARY)/gi; const matches = sql.matchAll(regex); - for (const match of matches) { + for (const match of Array.from(matches)) { const [, paramName, paramType] = match; paramTypes[paramName] = paramType.toUpperCase(); } @@ -116,12 +117,14 @@ export async function generateQueriesFromDescribe( ): Promise { const { noCache = false } = options; + const logger: ILogger = LoggerManager.getLogger("query-registry"); + // read all query files in the folder const queryFiles = fs .readdirSync(queryFolder) .filter((file) => file.endsWith(".sql")); - console.log(` Found ${queryFiles.length} SQL queries\n`); + logger.debug("Found SQL queries", { count: queryFiles.length }); // load cache const cache = noCache ? { version: CACHE_VERSION, queries: {} } : loadCache(); @@ -193,7 +196,10 @@ export async function generateQueriesFromDescribe( // log warning if there are failed queries if (failedQueries.length > 0) { - console.warn(` Warning: ${failedQueries.length} queries failed\n`); + logger.warn("Query validation warnings", { + failed: failedQueries.length, + queries: failedQueries, + }); } return querySchemas; diff --git a/packages/appkit/src/type-generator/vite-plugin.ts b/packages/appkit/src/type-generator/vite-plugin.ts index 67480d79..d0012640 100644 --- a/packages/appkit/src/type-generator/vite-plugin.ts +++ b/packages/appkit/src/type-generator/vite-plugin.ts @@ -1,6 +1,7 @@ +import fs from "node:fs"; import path from "node:path"; import type { Plugin } from "vite"; -import fs from "node:fs"; +import { type ILogger, LoggerManager } from "@/observability"; import { generateFromEntryPoint } from "./index"; /** @@ -24,14 +25,14 @@ export function appKitTypesPlugin(options?: AppKitTypesPluginOptions): Plugin { let outFile: string; let watchFolders: string[]; + const logger: ILogger = LoggerManager.getLogger("type-generator-plugin"); + async function generate() { try { const warehouseId = process.env.DATABRICKS_WAREHOUSE_ID || ""; if (!warehouseId) { - console.warn( - "[AppKit] Warehouse ID not found. Skipping type generation.", - ); + logger.warn("Warehouse ID not found. Skipping type generation."); return; } @@ -46,7 +47,9 @@ export function appKitTypesPlugin(options?: AppKitTypesPluginOptions): Plugin { if (process.env.NODE_ENV === "production") { throw error; } - console.error("[AppKit] Error generating types:", error); + logger.error("Error generating types", error as Error, { + error: error instanceof Error ? error.message : String(error), + }); } } @@ -57,9 +60,7 @@ export function appKitTypesPlugin(options?: AppKitTypesPluginOptions): Plugin { const warehouseId = process.env.DATABRICKS_WAREHOUSE_ID || ""; if (!warehouseId) { - console.warn( - "[AppKit] Warehouse ID not found. Skipping type generation.", - ); + logger.warn("Warehouse ID not found. Skipping type generation."); return false; } diff --git a/packages/shared/src/cache.ts b/packages/shared/src/cache.ts index 485b568b..65e8515e 100644 --- a/packages/shared/src/cache.ts +++ b/packages/shared/src/cache.ts @@ -1,4 +1,4 @@ -import type { TelemetryOptions } from "./plugin"; +import type { ObservabilityOptions } from "./plugin"; /** Cache entry interface */ export interface CacheEntry { @@ -48,8 +48,8 @@ export interface CacheConfig { storage?: CacheStorage; /** Whether to enforce strict persistence */ strictPersistence?: boolean; - /** Telemetry configuration */ - telemetry?: TelemetryOptions; + /** Observability configuration */ + observability?: ObservabilityOptions; /** Probability (0-1) of triggering cleanup on each get operation */ cleanupProbability?: number; diff --git a/packages/shared/src/execute.ts b/packages/shared/src/execute.ts index b748ce5c..be0a9cae 100644 --- a/packages/shared/src/execute.ts +++ b/packages/shared/src/execute.ts @@ -1,4 +1,5 @@ import type { CacheConfig } from "./cache"; +import type { ObservabilityOptions } from "./plugin"; export interface StreamConfig { userSignal?: AbortSignal; @@ -19,17 +20,10 @@ export interface RetryConfig { maxDelay?: number; } -export interface TelemetryConfig { - enabled?: boolean; - spanName?: string; - attributes?: Record; -} - export interface PluginExecuteConfig { cache?: CacheConfig; retry?: RetryConfig; - // to not mix with the 'telemetry' plugin config property - it is a different thing - telemetryInterceptor?: TelemetryConfig; + observability?: ObservabilityOptions; abort?: AbortSignal; timeout?: number; [key: string]: unknown; diff --git a/packages/shared/src/plugin.ts b/packages/shared/src/plugin.ts index b8bb05e8..76548b4c 100644 --- a/packages/shared/src/plugin.ts +++ b/packages/shared/src/plugin.ts @@ -20,14 +20,14 @@ export interface BasePluginConfig { [key: string]: unknown; - /* - * Telemetry configuration - * @default true for all telemetry types + /** + * Observability configuration (replaces telemetry) + * @default true for all observability types */ - telemetry?: TelemetryOptions; + observability?: ObservabilityOptions; } -export type TelemetryOptions = +export type ObservabilityOptions = | boolean | { traces?: boolean; diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index a2e94bf8..86444350 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -269,6 +269,9 @@ importers: express: specifier: ^4.22.0 version: 4.22.0 + obug: + specifier: ^2.1.1 + version: 2.1.1 pg: specifier: ^8.16.3 version: 8.16.3 @@ -8009,6 +8012,9 @@ packages: obuf@1.1.2: resolution: {integrity: sha512-PX1wu0AmAdPqOL1mWhqmlOd8kOIZQwGZw6rh7uby9fTc5lhaOWFLX3I6R1hrF9k3zUY40e6igsLGkDXK92LJNg==} + obug@2.1.1: + resolution: {integrity: sha512-uTqF9MuPraAQ+IsnPf366RG4cP9RtUi7MLO1N3KEc+wb0a6yKpeL0lmk2IB1jY5KHPAlTc6T/JRdC/YqxHNwkQ==} + ohash@2.0.11: resolution: {integrity: sha512-RdR9FQrFwNBNXAr4GixM8YaRZRJ5PUWbKYbE5eOsrwAjJW0q2REGcf79oYPsLyskQCZG1PLN+S/K1V00joZAoQ==} @@ -19727,6 +19733,8 @@ snapshots: obuf@1.1.2: {} + obug@2.1.1: {} + ohash@2.0.11: {} on-finished@2.4.1: diff --git a/tools/test-helpers.ts b/tools/test-helpers.ts index d80072d4..4fb9e427 100644 --- a/tools/test-helpers.ts +++ b/tools/test-helpers.ts @@ -1,17 +1,13 @@ +import type { Span } from "@opentelemetry/api"; import type { IAppRouter } from "shared"; -import type { - InstrumentConfig, - ITelemetry, -} from "../packages/appkit/src/telemetry/types"; import type { ServiceContextState } from "../packages/appkit/src/context/service-context"; import type { UserContext } from "../packages/appkit/src/context/user-context"; import { vi } from "vitest"; -import type { SpanOptions, Span } from "@opentelemetry/api"; /** * Creates a mock telemetry provider for testing */ -export function createMockTelemetry(): ITelemetry { +export function createMockTelemetry(): Span { const mockSpan: Span = { addLink: vi.fn(), addLinks: vi.fn(), @@ -26,38 +22,7 @@ export function createMockTelemetry(): ITelemetry { spanContext: vi.fn(), }; - return { - getTracer: vi.fn().mockReturnValue({ - startActiveSpan: vi.fn().mockImplementation((...args: any[]) => { - const fn = args[args.length - 1]; - if (typeof fn === "function") { - return fn(mockSpan); - } - return undefined; - }), - }), - getMeter: vi.fn().mockReturnValue({ - createCounter: vi.fn().mockReturnValue({ add: vi.fn() }), - createHistogram: vi.fn().mockReturnValue({ record: vi.fn() }), - }), - getLogger: vi.fn().mockReturnValue({ - emit: vi.fn(), - }), - emit: vi.fn(), - startActiveSpan: vi - .fn() - .mockImplementation( - async ( - _name: string, - _options: SpanOptions, - fn: (span: Span) => Promise, - _tracerOptions?: InstrumentConfig, - ) => { - return await fn(mockSpan); - }, - ), - registerInstrumentations: vi.fn(), - }; + return mockSpan; } /**