Connect to Lovable Cloud

Implement distributed tracing across edge functions:
- Introduce span types and utilities (logger.ts enhancements)
- Replace request tracking with span-based tracing in approval and rejection flows
- Propagate and manage W3C trace context in edge tracking
- Add span visualization scaffolding (spanVisualizer.ts) and admin TraceViewer UI (TraceViewer.tsx)
- Create tracing-related type definitions and support files
- Prepare RPC call logging with span context and retries
This commit is contained in:
gpt-engineer-app[bot]
2025-11-10 14:40:44 +00:00
parent 1551a2f08d
commit 96adb2b15e
7 changed files with 848 additions and 27 deletions

View File

@@ -75,11 +75,31 @@ export async function invokeWithTracking<T = any>(
const controller = new AbortController(); const controller = new AbortController();
const timeoutId = setTimeout(() => controller.abort(), timeout); 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 { try {
const { data, error } = await supabase.functions.invoke<T>(functionName, { const { data, error } = await supabase.functions.invoke<T>(functionName, {
body: { ...payload, clientRequestId: context.requestId }, body: {
...payload,
clientRequestId: context.requestId,
traceId: effectiveTraceId,
},
signal: controller.signal, signal: controller.signal,
headers: customHeaders, headers: {
...customHeaders,
'traceparent': traceparent,
},
}); });
clearTimeout(timeoutId); clearTimeout(timeoutId);
@@ -103,7 +123,15 @@ export async function invokeWithTracking<T = any>(
} }
); );
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) { } catch (error: unknown) {
// Handle AbortError specifically // Handle AbortError specifically
if (error instanceof Error && error.name === 'AbortError') { if (error instanceof Error && error.name === 'AbortError') {

150
src/lib/spanVisualizer.ts Normal file
View File

@@ -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<string, Span>();
const childrenMap = new Map<string, Span[]>();
// 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<string, unknown>;
}> {
const events: Array<{
spanName: string;
eventName: string;
timestamp: number;
attributes?: Record<string, unknown>;
}> = [];
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);
}

View File

@@ -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<Span[]>([]);
const [tree, setTree] = useState<SpanTree | null>(null);
const [isLoading, setIsLoading] = useState(false);
const [error, setError] = useState<string | null>(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 (
<div className="container mx-auto p-6 space-y-6">
<div>
<h1 className="text-3xl font-bold mb-2">Distributed Trace Viewer</h1>
<p className="text-muted-foreground">
Debug moderation pipeline execution by visualizing span hierarchies
</p>
</div>
<Card>
<CardHeader>
<CardTitle>Load Trace</CardTitle>
<CardDescription>
Enter a trace ID from edge function logs to visualize the execution tree
</CardDescription>
</CardHeader>
<CardContent>
<div className="flex gap-2">
<Input
value={traceId}
onChange={(e) => setTraceId(e.target.value)}
placeholder="Enter trace ID (e.g., abc-123-def-456)"
className="flex-1"
/>
<Button onClick={loadTrace} disabled={isLoading}>
{isLoading ? 'Loading...' : 'Load Trace'}
</Button>
</div>
{error && (
<Alert variant="destructive" className="mt-4">
<AlertDescription>{error}</AlertDescription>
</Alert>
)}
</CardContent>
</Card>
{tree && stats && (
<>
<Card>
<CardHeader>
<CardTitle>Trace Statistics</CardTitle>
</CardHeader>
<CardContent>
<div className="grid grid-cols-2 md:grid-cols-4 gap-4">
<div>
<div className="text-sm text-muted-foreground">Total Duration</div>
<div className="text-2xl font-bold">{stats.totalDuration}ms</div>
</div>
<div>
<div className="text-sm text-muted-foreground">Total Spans</div>
<div className="text-2xl font-bold">{stats.totalSpans}</div>
</div>
<div>
<div className="text-sm text-muted-foreground">Max Depth</div>
<div className="text-2xl font-bold">{stats.maxDepth}</div>
</div>
<div>
<div className="text-sm text-muted-foreground">Errors</div>
<div className="text-2xl font-bold text-destructive">{stats.errorCount}</div>
</div>
</div>
<div className="mt-4">
<div className="text-sm text-muted-foreground mb-2">Critical Path (Longest Duration):</div>
<div className="flex gap-2 flex-wrap">
{stats.criticalPath.map((spanName, i) => (
<Badge key={i} variant="secondary">
{spanName}
</Badge>
))}
</div>
</div>
</CardContent>
</Card>
<Card>
<CardHeader>
<CardTitle>Span Tree</CardTitle>
<CardDescription>
Hierarchical view of span execution with timing breakdown
</CardDescription>
</CardHeader>
<CardContent>
<pre className="bg-muted p-4 rounded-lg overflow-x-auto text-sm">
{formatSpanTree(tree)}
</pre>
</CardContent>
</Card>
<Card>
<CardHeader>
<CardTitle>Events Timeline</CardTitle>
<CardDescription>
Chronological list of all events across all spans
</CardDescription>
</CardHeader>
<CardContent>
<div className="space-y-2">
{events.map((event, i) => (
<div key={i} className="flex gap-2 text-sm border-l-2 border-primary pl-4 py-1">
<Badge variant="outline">{event.spanName}</Badge>
<span className="text-muted-foreground"></span>
<span className="font-medium">{event.eventName}</span>
<span className="text-muted-foreground ml-auto">
{new Date(event.timestamp).toISOString()}
</span>
</div>
))}
</div>
</CardContent>
</Card>
<Card>
<CardHeader>
<CardTitle>Span Details</CardTitle>
<CardDescription>
Detailed breakdown of each span with attributes and events
</CardDescription>
</CardHeader>
<CardContent>
<Accordion type="single" collapsible className="w-full">
{spans.map((span) => (
<AccordionItem key={span.spanId} value={span.spanId}>
<AccordionTrigger>
<div className="flex items-center gap-2">
<Badge variant={span.status === 'error' ? 'destructive' : 'default'}>
{span.kind}
</Badge>
<span>{span.name}</span>
<span className="text-muted-foreground ml-2">
({span.duration}ms)
</span>
</div>
</AccordionTrigger>
<AccordionContent>
<pre className="bg-muted p-4 rounded-lg overflow-x-auto text-xs">
{JSON.stringify(span, null, 2)}
</pre>
</AccordionContent>
</AccordionItem>
))}
</Accordion>
</CardContent>
</Card>
</>
)}
{!tree && !isLoading && !error && (
<Alert>
<AlertDescription>
Enter a trace ID to visualize the distributed trace. You can find trace IDs in edge function logs
under the "Span completed" messages.
</AlertDescription>
</Alert>
)}
</div>
);
}

35
src/types/tracing.ts Normal file
View File

@@ -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<string, unknown>;
events: SpanEvent[];
status: 'ok' | 'error' | 'unset';
error?: {
type: string;
message: string;
stack?: string;
};
}
export interface SpanEvent {
timestamp: number;
name: string;
attributes?: Record<string, unknown>;
}
export interface SpanContext {
traceId: string;
spanId: string;
traceFlags?: number;
}

View File

@@ -14,7 +14,39 @@ interface LogContext {
[key: string]: unknown; [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<string, unknown>;
events: SpanEvent[];
status: 'ok' | 'error' | 'unset';
error?: {
type: string;
message: string;
stack?: string;
};
}
export interface SpanEvent {
timestamp: number;
name: string;
attributes?: Record<string, unknown>;
}
export interface SpanContext {
traceId: string;
spanId: string;
traceFlags?: number;
}
// Request tracking utilities (legacy - use spans instead)
export interface RequestTracking { export interface RequestTracking {
requestId: string; requestId: string;
start: number; start: number;
@@ -33,6 +65,134 @@ export function endRequest(tracking: RequestTracking): number {
return Date.now() - tracking.start; return Date.now() - tracking.start;
} }
// ============================================================================
// Span Lifecycle Functions
// ============================================================================
/**
* Start a new span
*/
export function startSpan(
name: string,
kind: Span['kind'],
parentSpan?: SpanContext,
attributes?: Record<string, unknown>
): 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<string, unknown>
): void {
span.events.push({
timestamp: Date.now(),
name,
attributes,
});
}
/**
* Set span attributes
*/
export function setSpanAttributes(
span: Span,
attributes: Record<string, unknown>
): 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<string, string> {
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 // Fields that should never be logged
const SENSITIVE_FIELDS = [ const SENSITIVE_FIELDS = [
'password', 'password',
@@ -52,7 +212,7 @@ const SENSITIVE_FIELDS = [
/** /**
* Sanitize context to remove sensitive data * Sanitize context to remove sensitive data
*/ */
function sanitizeContext(context: LogContext): LogContext { export function sanitizeContext(context: LogContext): LogContext {
const sanitized: LogContext = {}; const sanitized: LogContext = {};
for (const [key, value] of Object.entries(context)) { for (const [key, value] of Object.entries(context)) {

View File

@@ -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 { createClient } from 'https://esm.sh/@supabase/supabase-js@2.57.4';
import { corsHeaders } from './cors.ts'; import { corsHeaders } from './cors.ts';
import { rateLimiters, withRateLimit } from '../_shared/rateLimiter.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_URL = Deno.env.get('SUPABASE_URL') || 'https://api.thrillwiki.com';
const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!; const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!;
@@ -23,14 +33,29 @@ const handler = async (req: Request) => {
}); });
} }
// Start request tracking // Extract parent span context from headers (if present)
const tracking: RequestTracking = startRequest(); const parentSpanContext = extractSpanContextFromHeaders(req.headers);
const requestId = tracking.requestId;
// 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 { try {
// STEP 1: Authentication // STEP 1: Authentication
addSpanEvent(rootSpan, 'authentication_start');
const authHeader = req.headers.get('Authorization'); const authHeader = req.headers.get('Authorization');
if (!authHeader) { if (!authHeader) {
addSpanEvent(rootSpan, 'authentication_failed', { reason: 'missing_header' });
endSpan(rootSpan, 'error');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Missing Authorization header' }), JSON.stringify({ error: 'Missing Authorization header' }),
{ {
@@ -49,11 +74,14 @@ const handler = async (req: Request) => {
const { data: { user }, error: authError } = await supabase.auth.getUser(); const { data: { user }, error: authError } = await supabase.auth.getUser();
if (authError || !user) { if (authError || !user) {
addSpanEvent(rootSpan, 'authentication_failed', { error: authError?.message });
edgeLogger.warn('Authentication failed', { edgeLogger.warn('Authentication failed', {
requestId, requestId,
error: authError?.message, error: authError?.message,
action: 'process_approval' action: 'process_approval'
}); });
endSpan(rootSpan, 'error', authError || new Error('Unauthorized'));
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Unauthorized' }), 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', { edgeLogger.info('Approval request received', {
requestId, requestId,
moderatorId: user.id, moderatorId: user.id,
@@ -73,10 +103,16 @@ const handler = async (req: Request) => {
}); });
// STEP 2: Parse request // STEP 2: Parse request
addSpanEvent(rootSpan, 'validation_start');
const body: ApprovalRequest = await req.json(); const body: ApprovalRequest = await req.json();
const { submissionId, itemIds, idempotencyKey } = body; const { submissionId, itemIds, idempotencyKey } = body;
if (!submissionId || !itemIds || itemIds.length === 0) { if (!submissionId || !itemIds || itemIds.length === 0) {
addSpanEvent(rootSpan, 'validation_failed', {
hasSubmissionId: !!submissionId,
hasItemIds: !!itemIds,
itemCount: itemIds?.length || 0,
});
edgeLogger.warn('Invalid request payload', { edgeLogger.warn('Invalid request payload', {
requestId, requestId,
hasSubmissionId: !!submissionId, hasSubmissionId: !!submissionId,
@@ -84,6 +120,8 @@ const handler = async (req: Request) => {
itemCount: itemIds?.length || 0, itemCount: itemIds?.length || 0,
action: 'process_approval' action: 'process_approval'
}); });
endSpan(rootSpan, 'error');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Missing required fields: submissionId, itemIds' }), 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', { edgeLogger.info('Request validated', {
requestId, requestId,
submissionId, submissionId,
@@ -104,6 +148,7 @@ const handler = async (req: Request) => {
}); });
// STEP 3: Idempotency check // STEP 3: Idempotency check
addSpanEvent(rootSpan, 'idempotency_check_start');
const { data: existingKey } = await supabase const { data: existingKey } = await supabase
.from('submission_idempotency_keys') .from('submission_idempotency_keys')
.select('*') .select('*')
@@ -111,12 +156,16 @@ const handler = async (req: Request) => {
.single(); .single();
if (existingKey?.status === 'completed') { if (existingKey?.status === 'completed') {
addSpanEvent(rootSpan, 'idempotency_cache_hit');
setSpanAttributes(rootSpan, { 'cache.hit': true });
edgeLogger.info('Idempotency cache hit', { edgeLogger.info('Idempotency cache hit', {
requestId, requestId,
idempotencyKey, idempotencyKey,
cached: true, cached: true,
action: 'process_approval' action: 'process_approval'
}); });
endSpan(rootSpan, 'ok');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify(existingKey.result_data), JSON.stringify(existingKey.result_data),
{ {
@@ -138,12 +187,15 @@ const handler = async (req: Request) => {
.single(); .single();
if (submissionError || !submission) { if (submissionError || !submission) {
addSpanEvent(rootSpan, 'submission_fetch_failed', { error: submissionError?.message });
edgeLogger.error('Submission not found', { edgeLogger.error('Submission not found', {
requestId, requestId,
submissionId, submissionId,
error: submissionError?.message, error: submissionError?.message,
action: 'process_approval' action: 'process_approval'
}); });
endSpan(rootSpan, 'error', submissionError || new Error('Submission not found'));
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Submission not found' }), 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', { edgeLogger.info('Calling approval transaction RPC', {
requestId, requestId,
submissionId, submissionId,
@@ -230,7 +296,9 @@ const handler = async (req: Request) => {
p_item_ids: itemIds, p_item_ids: itemIds,
p_moderator_id: user.id, p_moderator_id: user.id,
p_submitter_id: submission.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) { if (!rpcError) {
// Success! // Success!
addSpanEvent(rpcSpan, 'rpc_call_success', {
'result.status': data?.status,
'items.processed': itemIds.length,
});
break; break;
} }
@@ -246,6 +318,7 @@ const handler = async (req: Request) => {
if (rpcError.code === '40P01' || rpcError.code === '40001') { if (rpcError.code === '40P01' || rpcError.code === '40001') {
retryCount++; retryCount++;
if (retryCount > MAX_DEADLOCK_RETRIES) { if (retryCount > MAX_DEADLOCK_RETRIES) {
addSpanEvent(rpcSpan, 'max_retries_exceeded', { attempt: retryCount });
edgeLogger.error('Max deadlock retries exceeded', { edgeLogger.error('Max deadlock retries exceeded', {
requestId, requestId,
submissionId, submissionId,
@@ -256,6 +329,7 @@ const handler = async (req: Request) => {
} }
const backoffMs = 100 * Math.pow(2, retryCount); const backoffMs = 100 * Math.pow(2, retryCount);
addSpanEvent(rpcSpan, 'deadlock_retry', { attempt: retryCount, backoffMs });
edgeLogger.warn('Deadlock detected, retrying', { edgeLogger.warn('Deadlock detected, retrying', {
requestId, requestId,
attempt: retryCount, attempt: retryCount,
@@ -268,15 +342,21 @@ const handler = async (req: Request) => {
} }
// Non-retryable error, break immediately // Non-retryable error, break immediately
addSpanEvent(rpcSpan, 'rpc_call_failed', {
error: rpcError.message,
errorCode: rpcError.code
});
break; break;
} }
if (rpcError) { if (rpcError) {
// Transaction failed - EVERYTHING rolled back automatically by PostgreSQL // Transaction failed - EVERYTHING rolled back automatically by PostgreSQL
const duration = endRequest(tracking); endSpan(rpcSpan, 'error', rpcError);
logSpan(rpcSpan);
edgeLogger.error('Transaction failed', { edgeLogger.error('Transaction failed', {
requestId, requestId,
duration, duration: rpcSpan.duration,
submissionId, submissionId,
error: rpcError.message, error: rpcError.message,
errorCode: rpcError.code, errorCode: rpcError.code,
@@ -305,6 +385,9 @@ const handler = async (req: Request) => {
// Non-blocking - continue with error response even if idempotency update fails // Non-blocking - continue with error response even if idempotency update fails
} }
endSpan(rootSpan, 'error', rpcError);
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ JSON.stringify({
error: 'Approval transaction failed', 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', { edgeLogger.info('Transaction completed successfully', {
requestId, requestId,
duration, duration: rpcSpan.duration,
submissionId, submissionId,
itemCount: itemIds.length, itemCount: itemIds.length,
retries: retryCount, retries: retryCount,
@@ -354,6 +445,9 @@ const handler = async (req: Request) => {
// Non-blocking - transaction succeeded, so continue with success response // Non-blocking - transaction succeeded, so continue with success response
} }
endSpan(rootSpan, 'ok');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify(result), JSON.stringify(result),
{ {
@@ -367,10 +461,12 @@ const handler = async (req: Request) => {
); );
} catch (error) { } catch (error) {
const duration = endRequest(tracking); endSpan(rootSpan, 'error', error instanceof Error ? error : new Error(String(error)));
logSpan(rootSpan);
edgeLogger.error('Unexpected error', { edgeLogger.error('Unexpected error', {
requestId, requestId,
duration, duration: rootSpan.duration,
error: error instanceof Error ? error.message : String(error), error: error instanceof Error ? error.message : String(error),
stack: error instanceof Error ? error.stack : undefined, stack: error instanceof Error ? error.stack : undefined,
action: 'process_approval' action: 'process_approval'

View File

@@ -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 { createClient } from 'https://esm.sh/@supabase/supabase-js@2.57.4';
import { corsHeaders } from './cors.ts'; import { corsHeaders } from './cors.ts';
import { rateLimiters, withRateLimit } from '../_shared/rateLimiter.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_URL = Deno.env.get('SUPABASE_URL') || 'https://api.thrillwiki.com';
const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!; const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!;
@@ -24,14 +34,29 @@ const handler = async (req: Request) => {
}); });
} }
// Start request tracking // Extract parent span context from headers (if present)
const tracking: RequestTracking = startRequest(); const parentSpanContext = extractSpanContextFromHeaders(req.headers);
const requestId = tracking.requestId;
// 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 { try {
// STEP 1: Authentication // STEP 1: Authentication
addSpanEvent(rootSpan, 'authentication_start');
const authHeader = req.headers.get('Authorization'); const authHeader = req.headers.get('Authorization');
if (!authHeader) { if (!authHeader) {
addSpanEvent(rootSpan, 'authentication_failed', { reason: 'missing_header' });
endSpan(rootSpan, 'error');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Missing Authorization header' }), JSON.stringify({ error: 'Missing Authorization header' }),
{ {
@@ -50,11 +75,14 @@ const handler = async (req: Request) => {
const { data: { user }, error: authError } = await supabase.auth.getUser(); const { data: { user }, error: authError } = await supabase.auth.getUser();
if (authError || !user) { if (authError || !user) {
addSpanEvent(rootSpan, 'authentication_failed', { error: authError?.message });
edgeLogger.warn('Authentication failed', { edgeLogger.warn('Authentication failed', {
requestId, requestId,
error: authError?.message, error: authError?.message,
action: 'process_rejection' action: 'process_rejection'
}); });
endSpan(rootSpan, 'error', authError || new Error('Unauthorized'));
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Unauthorized' }), 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', { edgeLogger.info('Rejection request received', {
requestId, requestId,
moderatorId: user.id, moderatorId: user.id,
@@ -74,10 +104,17 @@ const handler = async (req: Request) => {
}); });
// STEP 2: Parse request // STEP 2: Parse request
addSpanEvent(rootSpan, 'validation_start');
const body: RejectionRequest = await req.json(); const body: RejectionRequest = await req.json();
const { submissionId, itemIds, rejectionReason, idempotencyKey } = body; const { submissionId, itemIds, rejectionReason, idempotencyKey } = body;
if (!submissionId || !itemIds || itemIds.length === 0 || !rejectionReason) { 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', { edgeLogger.warn('Invalid request payload', {
requestId, requestId,
hasSubmissionId: !!submissionId, hasSubmissionId: !!submissionId,
@@ -86,6 +123,8 @@ const handler = async (req: Request) => {
hasReason: !!rejectionReason, hasReason: !!rejectionReason,
action: 'process_rejection' action: 'process_rejection'
}); });
endSpan(rootSpan, 'error');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Missing required fields: submissionId, itemIds, rejectionReason' }), 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', { edgeLogger.info('Request validated', {
requestId, requestId,
submissionId, submissionId,
@@ -106,6 +151,7 @@ const handler = async (req: Request) => {
}); });
// STEP 3: Idempotency check // STEP 3: Idempotency check
addSpanEvent(rootSpan, 'idempotency_check_start');
const { data: existingKey } = await supabase const { data: existingKey } = await supabase
.from('submission_idempotency_keys') .from('submission_idempotency_keys')
.select('*') .select('*')
@@ -113,12 +159,16 @@ const handler = async (req: Request) => {
.single(); .single();
if (existingKey?.status === 'completed') { if (existingKey?.status === 'completed') {
addSpanEvent(rootSpan, 'idempotency_cache_hit');
setSpanAttributes(rootSpan, { 'cache.hit': true });
edgeLogger.info('Idempotency cache hit', { edgeLogger.info('Idempotency cache hit', {
requestId, requestId,
idempotencyKey, idempotencyKey,
cached: true, cached: true,
action: 'process_rejection' action: 'process_rejection'
}); });
endSpan(rootSpan, 'ok');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify(existingKey.result_data), JSON.stringify(existingKey.result_data),
{ {
@@ -140,12 +190,15 @@ const handler = async (req: Request) => {
.single(); .single();
if (submissionError || !submission) { if (submissionError || !submission) {
addSpanEvent(rootSpan, 'submission_fetch_failed', { error: submissionError?.message });
edgeLogger.error('Submission not found', { edgeLogger.error('Submission not found', {
requestId, requestId,
submissionId, submissionId,
error: submissionError?.message, error: submissionError?.message,
action: 'process_rejection' action: 'process_rejection'
}); });
endSpan(rootSpan, 'error', submissionError || new Error('Submission not found'));
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ error: 'Submission not found' }), 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', { edgeLogger.info('Calling rejection transaction RPC', {
requestId, requestId,
submissionId, submissionId,
@@ -232,7 +299,9 @@ const handler = async (req: Request) => {
p_item_ids: itemIds, p_item_ids: itemIds,
p_moderator_id: user.id, p_moderator_id: user.id,
p_rejection_reason: rejectionReason, 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) { if (!rpcError) {
// Success! // Success!
addSpanEvent(rpcSpan, 'rpc_call_success', {
'result.status': data?.status,
'items.processed': itemIds.length,
});
break; break;
} }
@@ -248,6 +321,7 @@ const handler = async (req: Request) => {
if (rpcError.code === '40P01' || rpcError.code === '40001') { if (rpcError.code === '40P01' || rpcError.code === '40001') {
retryCount++; retryCount++;
if (retryCount > MAX_DEADLOCK_RETRIES) { if (retryCount > MAX_DEADLOCK_RETRIES) {
addSpanEvent(rpcSpan, 'max_retries_exceeded', { attempt: retryCount });
edgeLogger.error('Max deadlock retries exceeded', { edgeLogger.error('Max deadlock retries exceeded', {
requestId, requestId,
submissionId, submissionId,
@@ -258,6 +332,7 @@ const handler = async (req: Request) => {
} }
const backoffMs = 100 * Math.pow(2, retryCount); const backoffMs = 100 * Math.pow(2, retryCount);
addSpanEvent(rpcSpan, 'deadlock_retry', { attempt: retryCount, backoffMs });
edgeLogger.warn('Deadlock detected, retrying', { edgeLogger.warn('Deadlock detected, retrying', {
requestId, requestId,
attempt: retryCount, attempt: retryCount,
@@ -270,15 +345,21 @@ const handler = async (req: Request) => {
} }
// Non-retryable error, break immediately // Non-retryable error, break immediately
addSpanEvent(rpcSpan, 'rpc_call_failed', {
error: rpcError.message,
errorCode: rpcError.code
});
break; break;
} }
if (rpcError) { if (rpcError) {
// Transaction failed - EVERYTHING rolled back automatically by PostgreSQL // Transaction failed - EVERYTHING rolled back automatically by PostgreSQL
const duration = endRequest(tracking); endSpan(rpcSpan, 'error', rpcError);
logSpan(rpcSpan);
edgeLogger.error('Transaction failed', { edgeLogger.error('Transaction failed', {
requestId, requestId,
duration, duration: rpcSpan.duration,
submissionId, submissionId,
error: rpcError.message, error: rpcError.message,
errorCode: rpcError.code, errorCode: rpcError.code,
@@ -307,6 +388,9 @@ const handler = async (req: Request) => {
// Non-blocking - continue with error response even if idempotency update fails // Non-blocking - continue with error response even if idempotency update fails
} }
endSpan(rootSpan, 'error', rpcError);
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify({ JSON.stringify({
error: 'Rejection transaction failed', 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', { edgeLogger.info('Transaction completed successfully', {
requestId, requestId,
duration, duration: rpcSpan.duration,
submissionId, submissionId,
itemCount: itemIds.length, itemCount: itemIds.length,
retries: retryCount, retries: retryCount,
@@ -356,6 +448,9 @@ const handler = async (req: Request) => {
// Non-blocking - transaction succeeded, so continue with success response // Non-blocking - transaction succeeded, so continue with success response
} }
endSpan(rootSpan, 'ok');
logSpan(rootSpan);
return new Response( return new Response(
JSON.stringify(result), JSON.stringify(result),
{ {
@@ -369,10 +464,12 @@ const handler = async (req: Request) => {
); );
} catch (error) { } catch (error) {
const duration = endRequest(tracking); endSpan(rootSpan, 'error', error instanceof Error ? error : new Error(String(error)));
logSpan(rootSpan);
edgeLogger.error('Unexpected error', { edgeLogger.error('Unexpected error', {
requestId, requestId,
duration, duration: rootSpan.duration,
error: error instanceof Error ? error.message : String(error), error: error instanceof Error ? error.message : String(error),
stack: error instanceof Error ? error.stack : undefined, stack: error instanceof Error ? error.stack : undefined,
action: 'process_rejection' action: 'process_rejection'