diff --git a/src/lib/edgeFunctionTracking.ts b/src/lib/edgeFunctionTracking.ts index 6616e394..77126095 100644 --- a/src/lib/edgeFunctionTracking.ts +++ b/src/lib/edgeFunctionTracking.ts @@ -75,11 +75,31 @@ export async function invokeWithTracking( const controller = new AbortController(); const timeoutId = setTimeout(() => controller.abort(), timeout); + // Generate W3C Trace Context header + const effectiveTraceId = context.traceId || crypto.randomUUID(); + const spanId = crypto.randomUUID(); + const traceparent = `00-${effectiveTraceId}-${spanId}-01`; + + // Add breadcrumb with trace context + breadcrumb.apiCall( + `/functions/${functionName}`, + 'POST', + undefined, + { traceId: effectiveTraceId, spanId } + ); + try { const { data, error } = await supabase.functions.invoke(functionName, { - body: { ...payload, clientRequestId: context.requestId }, + body: { + ...payload, + clientRequestId: context.requestId, + traceId: effectiveTraceId, + }, signal: controller.signal, - headers: customHeaders, + headers: { + ...customHeaders, + 'traceparent': traceparent, + }, }); clearTimeout(timeoutId); @@ -103,7 +123,15 @@ export async function invokeWithTracking( } ); - return { data: result, error: null, requestId, duration, attempts: attemptCount, status: 200 }; + return { + data: result, + error: null, + requestId, + duration, + attempts: attemptCount, + status: 200, + traceId, + }; } catch (error: unknown) { // Handle AbortError specifically if (error instanceof Error && error.name === 'AbortError') { diff --git a/src/lib/spanVisualizer.ts b/src/lib/spanVisualizer.ts new file mode 100644 index 00000000..93eabd30 --- /dev/null +++ b/src/lib/spanVisualizer.ts @@ -0,0 +1,150 @@ +/** + * Span Visualizer + * Reconstructs span trees from logs for debugging distributed traces + */ + +import type { Span } from '@/types/tracing'; + +export interface SpanTree { + span: Span; + children: SpanTree[]; + totalDuration: number; + selfDuration: number; +} + +/** + * Build span tree from flat span logs + */ +export function buildSpanTree(spans: Span[]): SpanTree | null { + const spanMap = new Map(); + const childrenMap = new Map(); + + // Index spans + for (const span of spans) { + spanMap.set(span.spanId, span); + + if (span.parentSpanId) { + if (!childrenMap.has(span.parentSpanId)) { + childrenMap.set(span.parentSpanId, []); + } + childrenMap.get(span.parentSpanId)!.push(span); + } + } + + // Find root span + const rootSpan = spans.find(s => !s.parentSpanId); + if (!rootSpan) return null; + + // Build tree recursively + function buildTree(span: Span): SpanTree { + const children = childrenMap.get(span.spanId) || []; + const childTrees = children.map(buildTree); + + const totalDuration = span.duration || 0; + const childrenDuration = childTrees.reduce((sum, child) => sum + child.totalDuration, 0); + const selfDuration = totalDuration - childrenDuration; + + return { + span, + children: childTrees, + totalDuration, + selfDuration, + }; + } + + return buildTree(rootSpan); +} + +/** + * Format span tree as ASCII art + */ +export function formatSpanTree(tree: SpanTree, indent: number = 0): string { + const prefix = ' '.repeat(indent); + const status = tree.span.status === 'error' ? '❌' : tree.span.status === 'ok' ? '✅' : '⏳'; + const line = `${prefix}${status} ${tree.span.name} (${tree.span.duration}ms / self: ${tree.selfDuration}ms)`; + + const childLines = tree.children.map(child => formatSpanTree(child, indent + 1)); + + return [line, ...childLines].join('\n'); +} + +/** + * Calculate span statistics for a tree + */ +export function calculateSpanStats(tree: SpanTree): { + totalSpans: number; + errorCount: number; + maxDepth: number; + totalDuration: number; + criticalPath: string[]; +} { + let totalSpans = 0; + let errorCount = 0; + let maxDepth = 0; + + function traverse(node: SpanTree, depth: number) { + totalSpans++; + if (node.span.status === 'error') errorCount++; + maxDepth = Math.max(maxDepth, depth); + + node.children.forEach(child => traverse(child, depth + 1)); + } + + traverse(tree, 0); + + // Find critical path (longest duration path) + function findCriticalPath(node: SpanTree): string[] { + if (node.children.length === 0) { + return [node.span.name]; + } + + const longestChild = node.children.reduce((longest, child) => + child.totalDuration > longest.totalDuration ? child : longest + ); + + return [node.span.name, ...findCriticalPath(longestChild)]; + } + + return { + totalSpans, + errorCount, + maxDepth, + totalDuration: tree.totalDuration, + criticalPath: findCriticalPath(tree), + }; +} + +/** + * Extract all events from a span tree + */ +export function extractAllEvents(tree: SpanTree): Array<{ + spanName: string; + eventName: string; + timestamp: number; + attributes?: Record; +}> { + const events: Array<{ + spanName: string; + eventName: string; + timestamp: number; + attributes?: Record; + }> = []; + + function traverse(node: SpanTree) { + node.span.events.forEach(event => { + events.push({ + spanName: node.span.name, + eventName: event.name, + timestamp: event.timestamp, + attributes: event.attributes, + }); + }); + + node.children.forEach(child => traverse(child)); + } + + traverse(tree); + + // Sort by timestamp + return events.sort((a, b) => a.timestamp - b.timestamp); +} diff --git a/src/pages/admin/TraceViewer.tsx b/src/pages/admin/TraceViewer.tsx new file mode 100644 index 00000000..7db4c9b5 --- /dev/null +++ b/src/pages/admin/TraceViewer.tsx @@ -0,0 +1,255 @@ +import { useState } from 'react'; +import { Card, CardContent, CardDescription, CardHeader, CardTitle } from '@/components/ui/card'; +import { Input } from '@/components/ui/input'; +import { Button } from '@/components/ui/button'; +import { Accordion, AccordionContent, AccordionItem, AccordionTrigger } from '@/components/ui/accordion'; +import { Alert, AlertDescription } from '@/components/ui/alert'; +import { Badge } from '@/components/ui/badge'; +import { buildSpanTree, formatSpanTree, calculateSpanStats, extractAllEvents } from '@/lib/spanVisualizer'; +import type { Span } from '@/types/tracing'; +import type { SpanTree } from '@/lib/spanVisualizer'; + +/** + * Admin Trace Viewer + * + * Visual tool for debugging distributed traces across the approval pipeline. + * Reconstructs and displays span hierarchies from edge function logs. + */ +export default function TraceViewer() { + const [traceId, setTraceId] = useState(''); + const [spans, setSpans] = useState([]); + const [tree, setTree] = useState(null); + const [isLoading, setIsLoading] = useState(false); + const [error, setError] = useState(null); + + const loadTrace = async () => { + if (!traceId.trim()) { + setError('Please enter a trace ID'); + return; + } + + setIsLoading(true); + setError(null); + + try { + // TODO: Replace with actual edge function log query + // This would need an edge function that queries Supabase logs + // For now, using mock data structure + const mockSpans: Span[] = [ + { + spanId: 'root-1', + traceId, + name: 'process-selective-approval', + kind: 'SERVER', + startTime: Date.now() - 5000, + endTime: Date.now(), + duration: 5000, + attributes: { + 'http.method': 'POST', + 'user.id': 'user-123', + 'submission.id': 'sub-456', + }, + events: [ + { timestamp: Date.now() - 4900, name: 'authentication_start' }, + { timestamp: Date.now() - 4800, name: 'authentication_success' }, + { timestamp: Date.now() - 4700, name: 'validation_complete' }, + ], + status: 'ok', + }, + { + spanId: 'child-1', + traceId, + parentSpanId: 'root-1', + name: 'process_approval_transaction', + kind: 'DATABASE', + startTime: Date.now() - 4500, + endTime: Date.now() - 500, + duration: 4000, + attributes: { + 'db.operation': 'rpc', + 'submission.id': 'sub-456', + }, + events: [ + { timestamp: Date.now() - 4400, name: 'rpc_call_start' }, + { timestamp: Date.now() - 600, name: 'rpc_call_success' }, + ], + status: 'ok', + }, + ]; + + setSpans(mockSpans); + const builtTree = buildSpanTree(mockSpans); + setTree(builtTree); + + if (!builtTree) { + setError('No root span found for this trace ID'); + } + } catch (err) { + setError(err instanceof Error ? err.message : 'Failed to load trace'); + } finally { + setIsLoading(false); + } + }; + + const stats = tree ? calculateSpanStats(tree) : null; + const events = tree ? extractAllEvents(tree) : []; + + return ( +
+
+

Distributed Trace Viewer

+

+ Debug moderation pipeline execution by visualizing span hierarchies +

+
+ + + + Load Trace + + Enter a trace ID from edge function logs to visualize the execution tree + + + +
+ setTraceId(e.target.value)} + placeholder="Enter trace ID (e.g., abc-123-def-456)" + className="flex-1" + /> + +
+ + {error && ( + + {error} + + )} + + + + {tree && stats && ( + <> + + + Trace Statistics + + +
+
+
Total Duration
+
{stats.totalDuration}ms
+
+
+
Total Spans
+
{stats.totalSpans}
+
+
+
Max Depth
+
{stats.maxDepth}
+
+
+
Errors
+
{stats.errorCount}
+
+
+ +
+
Critical Path (Longest Duration):
+
+ {stats.criticalPath.map((spanName, i) => ( + + {spanName} + + ))} +
+
+ + + + + + Span Tree + + Hierarchical view of span execution with timing breakdown + + + + 
+                {formatSpanTree(tree)}
+
+ + + + + + Events Timeline + + Chronological list of all events across all spans + + + +
+ {events.map((event, i) => ( +
+ {event.spanName} + → + {event.eventName} + + {new Date(event.timestamp).toISOString()} + +
+ ))} +
+ + + + + + Span Details + + Detailed breakdown of each span with attributes and events + + + + + {spans.map((span) => ( + + +
+ + {span.kind} + + {span.name} + + ({span.duration}ms) + +
+ + + 
+                        {JSON.stringify(span, null, 2)}
+
+ + + ))} + + + + + )} + + {!tree && !isLoading && !error && ( + + + Enter a trace ID to visualize the distributed trace. You can find trace IDs in edge function logs + under the "Span completed" messages. + + + )} +
+ ); +} diff --git a/src/types/tracing.ts b/src/types/tracing.ts new file mode 100644 index 00000000..e50130e0 --- /dev/null +++ b/src/types/tracing.ts @@ -0,0 +1,35 @@ +/** + * Distributed Tracing Types + * Mirrors the types defined in edge function logger + */ + +export interface Span { + spanId: string; + traceId: string; + parentSpanId?: string; + name: string; + kind: 'SERVER' | 'CLIENT' | 'INTERNAL' | 'DATABASE'; + startTime: number; + endTime?: number; + duration?: number; + attributes: Record; + events: SpanEvent[]; + status: 'ok' | 'error' | 'unset'; + error?: { + type: string; + message: string; + stack?: string; + }; +} + +export interface SpanEvent { + timestamp: number; + name: string; + attributes?: Record; +} + +export interface SpanContext { + traceId: string; + spanId: string; + traceFlags?: number; +} diff --git a/supabase/functions/_shared/logger.ts b/supabase/functions/_shared/logger.ts index 2f6cd072..3b655c81 100644 --- a/supabase/functions/_shared/logger.ts +++ b/supabase/functions/_shared/logger.ts @@ -14,7 +14,39 @@ interface LogContext { [key: string]: unknown; } -// Request tracking utilities +// Span types for distributed tracing +export interface Span { + spanId: string; + traceId: string; + parentSpanId?: string; + name: string; + kind: 'SERVER' | 'CLIENT' | 'INTERNAL' | 'DATABASE'; + startTime: number; + endTime?: number; + duration?: number; + attributes: Record; + events: SpanEvent[]; + status: 'ok' | 'error' | 'unset'; + error?: { + type: string; + message: string; + stack?: string; + }; +} + +export interface SpanEvent { + timestamp: number; + name: string; + attributes?: Record; +} + +export interface SpanContext { + traceId: string; + spanId: string; + traceFlags?: number; +} + +// Request tracking utilities (legacy - use spans instead) export interface RequestTracking { requestId: string; start: number; @@ -33,6 +65,134 @@ export function endRequest(tracking: RequestTracking): number { return Date.now() - tracking.start; } +// ============================================================================ +// Span Lifecycle Functions +// ============================================================================ + +/** + * Start a new span + */ +export function startSpan( + name: string, + kind: Span['kind'], + parentSpan?: SpanContext, + attributes?: Record +): Span { + const traceId = parentSpan?.traceId || crypto.randomUUID(); + + return { + spanId: crypto.randomUUID(), + traceId, + parentSpanId: parentSpan?.spanId, + name, + kind, + startTime: Date.now(), + attributes: attributes || {}, + events: [], + status: 'unset', + }; +} + +/** + * End a span with final status + */ +export function endSpan(span: Span, status?: 'ok' | 'error', error?: Error): Span { + span.endTime = Date.now(); + span.duration = span.endTime - span.startTime; + span.status = status || 'ok'; + + if (error) { + span.error = { + type: error.name, + message: error.message, + stack: error.stack, + }; + } + + return span; +} + +/** + * Add event to span + */ +export function addSpanEvent( + span: Span, + name: string, + attributes?: Record +): void { + span.events.push({ + timestamp: Date.now(), + name, + attributes, + }); +} + +/** + * Set span attributes + */ +export function setSpanAttributes( + span: Span, + attributes: Record +): void { + span.attributes = { ...span.attributes, ...attributes }; +} + +/** + * Extract span context for propagation + */ +export function getSpanContext(span: Span): SpanContext { + return { + traceId: span.traceId, + spanId: span.spanId, + }; +} + +/** + * Extract span context from HTTP headers (W3C Trace Context) + */ +export function extractSpanContextFromHeaders(headers: Headers): SpanContext | undefined { + const traceparent = headers.get('traceparent'); + if (!traceparent) return undefined; + + // Parse W3C traceparent: version-traceId-spanId-flags + const parts = traceparent.split('-'); + if (parts.length !== 4) return undefined; + + return { + traceId: parts[1], + spanId: parts[2], + traceFlags: parseInt(parts[3], 16), + }; +} + +/** + * Inject span context into headers + */ +export function injectSpanContextIntoHeaders(spanContext: SpanContext): Record { + return { + 'traceparent': `00-${spanContext.traceId}-${spanContext.spanId}-01`, + }; +} + +/** + * Log completed span + */ +export function logSpan(span: Span): void { + const sanitizedAttributes = sanitizeContext(span.attributes); + const sanitizedEvents = span.events.map(e => ({ + ...e, + attributes: e.attributes ? sanitizeContext(e.attributes) : undefined, + })); + + edgeLogger.info('Span completed', { + span: { + ...span, + attributes: sanitizedAttributes, + events: sanitizedEvents, + }, + }); +} + // Fields that should never be logged const SENSITIVE_FIELDS = [ 'password', @@ -52,7 +212,7 @@ const SENSITIVE_FIELDS = [ /** * Sanitize context to remove sensitive data */ -function sanitizeContext(context: LogContext): LogContext { +export function sanitizeContext(context: LogContext): LogContext { const sanitized: LogContext = {}; for (const [key, value] of Object.entries(context)) { diff --git a/supabase/functions/process-selective-approval/index.ts b/supabase/functions/process-selective-approval/index.ts index 7035160e..4d64c1a7 100644 --- a/supabase/functions/process-selective-approval/index.ts +++ b/supabase/functions/process-selective-approval/index.ts @@ -2,7 +2,17 @@ import { serve } from 'https://deno.land/std@0.168.0/http/server.ts'; import { createClient } from 'https://esm.sh/@supabase/supabase-js@2.57.4'; import { corsHeaders } from './cors.ts'; import { rateLimiters, withRateLimit } from '../_shared/rateLimiter.ts'; -import { edgeLogger, startRequest, endRequest, type RequestTracking } from '../_shared/logger.ts'; +import { + edgeLogger, + startSpan, + endSpan, + addSpanEvent, + setSpanAttributes, + getSpanContext, + logSpan, + extractSpanContextFromHeaders, + type Span +} from '../_shared/logger.ts'; const SUPABASE_URL = Deno.env.get('SUPABASE_URL') || 'https://api.thrillwiki.com'; const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!; @@ -23,14 +33,29 @@ const handler = async (req: Request) => { }); } - // Start request tracking - const tracking: RequestTracking = startRequest(); - const requestId = tracking.requestId; + // Extract parent span context from headers (if present) + const parentSpanContext = extractSpanContextFromHeaders(req.headers); + + // Create root span for this edge function invocation + const rootSpan = startSpan( + 'process-selective-approval', + 'SERVER', + parentSpanContext, + { + 'http.method': 'POST', + 'function.name': 'process-selective-approval', + } + ); + const requestId = rootSpan.spanId; try { // STEP 1: Authentication + addSpanEvent(rootSpan, 'authentication_start'); const authHeader = req.headers.get('Authorization'); if (!authHeader) { + addSpanEvent(rootSpan, 'authentication_failed', { reason: 'missing_header' }); + endSpan(rootSpan, 'error'); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Missing Authorization header' }), { @@ -49,11 +74,14 @@ const handler = async (req: Request) => { const { data: { user }, error: authError } = await supabase.auth.getUser(); if (authError || !user) { + addSpanEvent(rootSpan, 'authentication_failed', { error: authError?.message }); edgeLogger.warn('Authentication failed', { requestId, error: authError?.message, action: 'process_approval' }); + endSpan(rootSpan, 'error', authError || new Error('Unauthorized')); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Unauthorized' }), { @@ -66,6 +94,8 @@ const handler = async (req: Request) => { ); } + setSpanAttributes(rootSpan, { 'user.id': user.id }); + addSpanEvent(rootSpan, 'authentication_success'); edgeLogger.info('Approval request received', { requestId, moderatorId: user.id, @@ -73,10 +103,16 @@ const handler = async (req: Request) => { }); // STEP 2: Parse request + addSpanEvent(rootSpan, 'validation_start'); const body: ApprovalRequest = await req.json(); const { submissionId, itemIds, idempotencyKey } = body; if (!submissionId || !itemIds || itemIds.length === 0) { + addSpanEvent(rootSpan, 'validation_failed', { + hasSubmissionId: !!submissionId, + hasItemIds: !!itemIds, + itemCount: itemIds?.length || 0, + }); edgeLogger.warn('Invalid request payload', { requestId, hasSubmissionId: !!submissionId, @@ -84,6 +120,8 @@ const handler = async (req: Request) => { itemCount: itemIds?.length || 0, action: 'process_approval' }); + endSpan(rootSpan, 'error'); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Missing required fields: submissionId, itemIds' }), { @@ -96,6 +134,12 @@ const handler = async (req: Request) => { ); } + setSpanAttributes(rootSpan, { + 'submission.id': submissionId, + 'submission.item_count': itemIds.length, + 'idempotency.key': idempotencyKey, + }); + addSpanEvent(rootSpan, 'validation_complete'); edgeLogger.info('Request validated', { requestId, submissionId, @@ -104,6 +148,7 @@ const handler = async (req: Request) => { }); // STEP 3: Idempotency check + addSpanEvent(rootSpan, 'idempotency_check_start'); const { data: existingKey } = await supabase .from('submission_idempotency_keys') .select('*') @@ -111,12 +156,16 @@ const handler = async (req: Request) => { .single(); if (existingKey?.status === 'completed') { + addSpanEvent(rootSpan, 'idempotency_cache_hit'); + setSpanAttributes(rootSpan, { 'cache.hit': true }); edgeLogger.info('Idempotency cache hit', { requestId, idempotencyKey, cached: true, action: 'process_approval' }); + endSpan(rootSpan, 'ok'); + logSpan(rootSpan); return new Response( JSON.stringify(existingKey.result_data), { @@ -138,12 +187,15 @@ const handler = async (req: Request) => { .single(); if (submissionError || !submission) { + addSpanEvent(rootSpan, 'submission_fetch_failed', { error: submissionError?.message }); edgeLogger.error('Submission not found', { requestId, submissionId, error: submissionError?.message, action: 'process_approval' }); + endSpan(rootSpan, 'error', submissionError || new Error('Submission not found')); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Submission not found' }), { @@ -207,6 +259,20 @@ const handler = async (req: Request) => { }); } + // Create child span for RPC transaction + const rpcSpan = startSpan( + 'process_approval_transaction', + 'DATABASE', + getSpanContext(rootSpan), + { + 'db.operation': 'rpc', + 'db.function': 'process_approval_transaction', + 'submission.id': submissionId, + 'submission.item_count': itemIds.length, + } + ); + + addSpanEvent(rpcSpan, 'rpc_call_start'); edgeLogger.info('Calling approval transaction RPC', { requestId, submissionId, @@ -230,7 +296,9 @@ const handler = async (req: Request) => { p_item_ids: itemIds, p_moderator_id: user.id, p_submitter_id: submission.user_id, - p_request_id: requestId + p_request_id: requestId, + p_trace_id: rootSpan.traceId, + p_parent_span_id: rpcSpan.spanId } ); @@ -239,6 +307,10 @@ const handler = async (req: Request) => { if (!rpcError) { // Success! + addSpanEvent(rpcSpan, 'rpc_call_success', { + 'result.status': data?.status, + 'items.processed': itemIds.length, + }); break; } @@ -246,6 +318,7 @@ const handler = async (req: Request) => { if (rpcError.code === '40P01' || rpcError.code === '40001') { retryCount++; if (retryCount > MAX_DEADLOCK_RETRIES) { + addSpanEvent(rpcSpan, 'max_retries_exceeded', { attempt: retryCount }); edgeLogger.error('Max deadlock retries exceeded', { requestId, submissionId, @@ -256,6 +329,7 @@ const handler = async (req: Request) => { } const backoffMs = 100 * Math.pow(2, retryCount); + addSpanEvent(rpcSpan, 'deadlock_retry', { attempt: retryCount, backoffMs }); edgeLogger.warn('Deadlock detected, retrying', { requestId, attempt: retryCount, @@ -268,15 +342,21 @@ const handler = async (req: Request) => { } // Non-retryable error, break immediately + addSpanEvent(rpcSpan, 'rpc_call_failed', { + error: rpcError.message, + errorCode: rpcError.code + }); break; } if (rpcError) { // Transaction failed - EVERYTHING rolled back automatically by PostgreSQL - const duration = endRequest(tracking); + endSpan(rpcSpan, 'error', rpcError); + logSpan(rpcSpan); + edgeLogger.error('Transaction failed', { requestId, - duration, + duration: rpcSpan.duration, submissionId, error: rpcError.message, errorCode: rpcError.code, @@ -305,6 +385,9 @@ const handler = async (req: Request) => { // Non-blocking - continue with error response even if idempotency update fails } + endSpan(rootSpan, 'error', rpcError); + logSpan(rootSpan); + return new Response( JSON.stringify({ error: 'Approval transaction failed', @@ -322,10 +405,18 @@ const handler = async (req: Request) => { ); } - const duration = endRequest(tracking); + // RPC succeeded + endSpan(rpcSpan, 'ok'); + logSpan(rpcSpan); + + setSpanAttributes(rootSpan, { + 'result.status': result?.status, + 'result.final_status': result?.status, + 'retries': retryCount, + }); edgeLogger.info('Transaction completed successfully', { requestId, - duration, + duration: rpcSpan.duration, submissionId, itemCount: itemIds.length, retries: retryCount, @@ -354,6 +445,9 @@ const handler = async (req: Request) => { // Non-blocking - transaction succeeded, so continue with success response } + endSpan(rootSpan, 'ok'); + logSpan(rootSpan); + return new Response( JSON.stringify(result), { @@ -367,10 +461,12 @@ const handler = async (req: Request) => { ); } catch (error) { - const duration = endRequest(tracking); + endSpan(rootSpan, 'error', error instanceof Error ? error : new Error(String(error))); + logSpan(rootSpan); + edgeLogger.error('Unexpected error', { requestId, - duration, + duration: rootSpan.duration, error: error instanceof Error ? error.message : String(error), stack: error instanceof Error ? error.stack : undefined, action: 'process_approval' diff --git a/supabase/functions/process-selective-rejection/index.ts b/supabase/functions/process-selective-rejection/index.ts index b32d11d5..922a459d 100644 --- a/supabase/functions/process-selective-rejection/index.ts +++ b/supabase/functions/process-selective-rejection/index.ts @@ -2,7 +2,17 @@ import { serve } from 'https://deno.land/std@0.168.0/http/server.ts'; import { createClient } from 'https://esm.sh/@supabase/supabase-js@2.57.4'; import { corsHeaders } from './cors.ts'; import { rateLimiters, withRateLimit } from '../_shared/rateLimiter.ts'; -import { edgeLogger, startRequest, endRequest, type RequestTracking } from '../_shared/logger.ts'; +import { + edgeLogger, + startSpan, + endSpan, + addSpanEvent, + setSpanAttributes, + getSpanContext, + logSpan, + extractSpanContextFromHeaders, + type Span +} from '../_shared/logger.ts'; const SUPABASE_URL = Deno.env.get('SUPABASE_URL') || 'https://api.thrillwiki.com'; const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!; @@ -24,14 +34,29 @@ const handler = async (req: Request) => { }); } - // Start request tracking - const tracking: RequestTracking = startRequest(); - const requestId = tracking.requestId; + // Extract parent span context from headers (if present) + const parentSpanContext = extractSpanContextFromHeaders(req.headers); + + // Create root span for this edge function invocation + const rootSpan = startSpan( + 'process-selective-rejection', + 'SERVER', + parentSpanContext, + { + 'http.method': 'POST', + 'function.name': 'process-selective-rejection', + } + ); + const requestId = rootSpan.spanId; try { // STEP 1: Authentication + addSpanEvent(rootSpan, 'authentication_start'); const authHeader = req.headers.get('Authorization'); if (!authHeader) { + addSpanEvent(rootSpan, 'authentication_failed', { reason: 'missing_header' }); + endSpan(rootSpan, 'error'); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Missing Authorization header' }), { @@ -50,11 +75,14 @@ const handler = async (req: Request) => { const { data: { user }, error: authError } = await supabase.auth.getUser(); if (authError || !user) { + addSpanEvent(rootSpan, 'authentication_failed', { error: authError?.message }); edgeLogger.warn('Authentication failed', { requestId, error: authError?.message, action: 'process_rejection' }); + endSpan(rootSpan, 'error', authError || new Error('Unauthorized')); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Unauthorized' }), { @@ -67,6 +95,8 @@ const handler = async (req: Request) => { ); } + setSpanAttributes(rootSpan, { 'user.id': user.id }); + addSpanEvent(rootSpan, 'authentication_success'); edgeLogger.info('Rejection request received', { requestId, moderatorId: user.id, @@ -74,10 +104,17 @@ const handler = async (req: Request) => { }); // STEP 2: Parse request + addSpanEvent(rootSpan, 'validation_start'); const body: RejectionRequest = await req.json(); const { submissionId, itemIds, rejectionReason, idempotencyKey } = body; if (!submissionId || !itemIds || itemIds.length === 0 || !rejectionReason) { + addSpanEvent(rootSpan, 'validation_failed', { + hasSubmissionId: !!submissionId, + hasItemIds: !!itemIds, + itemCount: itemIds?.length || 0, + hasReason: !!rejectionReason, + }); edgeLogger.warn('Invalid request payload', { requestId, hasSubmissionId: !!submissionId, @@ -86,6 +123,8 @@ const handler = async (req: Request) => { hasReason: !!rejectionReason, action: 'process_rejection' }); + endSpan(rootSpan, 'error'); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Missing required fields: submissionId, itemIds, rejectionReason' }), { @@ -98,6 +137,12 @@ const handler = async (req: Request) => { ); } + setSpanAttributes(rootSpan, { + 'submission.id': submissionId, + 'submission.item_count': itemIds.length, + 'idempotency.key': idempotencyKey, + }); + addSpanEvent(rootSpan, 'validation_complete'); edgeLogger.info('Request validated', { requestId, submissionId, @@ -106,6 +151,7 @@ const handler = async (req: Request) => { }); // STEP 3: Idempotency check + addSpanEvent(rootSpan, 'idempotency_check_start'); const { data: existingKey } = await supabase .from('submission_idempotency_keys') .select('*') @@ -113,12 +159,16 @@ const handler = async (req: Request) => { .single(); if (existingKey?.status === 'completed') { + addSpanEvent(rootSpan, 'idempotency_cache_hit'); + setSpanAttributes(rootSpan, { 'cache.hit': true }); edgeLogger.info('Idempotency cache hit', { requestId, idempotencyKey, cached: true, action: 'process_rejection' }); + endSpan(rootSpan, 'ok'); + logSpan(rootSpan); return new Response( JSON.stringify(existingKey.result_data), { @@ -140,12 +190,15 @@ const handler = async (req: Request) => { .single(); if (submissionError || !submission) { + addSpanEvent(rootSpan, 'submission_fetch_failed', { error: submissionError?.message }); edgeLogger.error('Submission not found', { requestId, submissionId, error: submissionError?.message, action: 'process_rejection' }); + endSpan(rootSpan, 'error', submissionError || new Error('Submission not found')); + logSpan(rootSpan); return new Response( JSON.stringify({ error: 'Submission not found' }), { @@ -209,6 +262,20 @@ const handler = async (req: Request) => { }); } + // Create child span for RPC transaction + const rpcSpan = startSpan( + 'process_rejection_transaction', + 'DATABASE', + getSpanContext(rootSpan), + { + 'db.operation': 'rpc', + 'db.function': 'process_rejection_transaction', + 'submission.id': submissionId, + 'submission.item_count': itemIds.length, + } + ); + + addSpanEvent(rpcSpan, 'rpc_call_start'); edgeLogger.info('Calling rejection transaction RPC', { requestId, submissionId, @@ -232,7 +299,9 @@ const handler = async (req: Request) => { p_item_ids: itemIds, p_moderator_id: user.id, p_rejection_reason: rejectionReason, - p_request_id: requestId + p_request_id: requestId, + p_trace_id: rootSpan.traceId, + p_parent_span_id: rpcSpan.spanId } ); @@ -241,6 +310,10 @@ const handler = async (req: Request) => { if (!rpcError) { // Success! + addSpanEvent(rpcSpan, 'rpc_call_success', { + 'result.status': data?.status, + 'items.processed': itemIds.length, + }); break; } @@ -248,6 +321,7 @@ const handler = async (req: Request) => { if (rpcError.code === '40P01' || rpcError.code === '40001') { retryCount++; if (retryCount > MAX_DEADLOCK_RETRIES) { + addSpanEvent(rpcSpan, 'max_retries_exceeded', { attempt: retryCount }); edgeLogger.error('Max deadlock retries exceeded', { requestId, submissionId, @@ -258,6 +332,7 @@ const handler = async (req: Request) => { } const backoffMs = 100 * Math.pow(2, retryCount); + addSpanEvent(rpcSpan, 'deadlock_retry', { attempt: retryCount, backoffMs }); edgeLogger.warn('Deadlock detected, retrying', { requestId, attempt: retryCount, @@ -270,15 +345,21 @@ const handler = async (req: Request) => { } // Non-retryable error, break immediately + addSpanEvent(rpcSpan, 'rpc_call_failed', { + error: rpcError.message, + errorCode: rpcError.code + }); break; } if (rpcError) { // Transaction failed - EVERYTHING rolled back automatically by PostgreSQL - const duration = endRequest(tracking); + endSpan(rpcSpan, 'error', rpcError); + logSpan(rpcSpan); + edgeLogger.error('Transaction failed', { requestId, - duration, + duration: rpcSpan.duration, submissionId, error: rpcError.message, errorCode: rpcError.code, @@ -307,6 +388,9 @@ const handler = async (req: Request) => { // Non-blocking - continue with error response even if idempotency update fails } + endSpan(rootSpan, 'error', rpcError); + logSpan(rootSpan); + return new Response( JSON.stringify({ error: 'Rejection transaction failed', @@ -324,10 +408,18 @@ const handler = async (req: Request) => { ); } - const duration = endRequest(tracking); + // RPC succeeded + endSpan(rpcSpan, 'ok'); + logSpan(rpcSpan); + + setSpanAttributes(rootSpan, { + 'result.status': result?.status, + 'result.final_status': result?.status, + 'retries': retryCount, + }); edgeLogger.info('Transaction completed successfully', { requestId, - duration, + duration: rpcSpan.duration, submissionId, itemCount: itemIds.length, retries: retryCount, @@ -356,6 +448,9 @@ const handler = async (req: Request) => { // Non-blocking - transaction succeeded, so continue with success response } + endSpan(rootSpan, 'ok'); + logSpan(rootSpan); + return new Response( JSON.stringify(result), { @@ -369,10 +464,12 @@ const handler = async (req: Request) => { ); } catch (error) { - const duration = endRequest(tracking); + endSpan(rootSpan, 'error', error instanceof Error ? error : new Error(String(error))); + logSpan(rootSpan); + edgeLogger.error('Unexpected error', { requestId, - duration, + duration: rootSpan.duration, error: error instanceof Error ? error.message : String(error), stack: error instanceof Error ? error.stack : undefined, action: 'process_rejection'