Add structured moderation logging

Enhance edge functions process-selective-approval and process-selective-rejection with edgeLogger-based, structured logging. Introduce request tracking (startRequest/endRequest), replace all console logs, add comprehensive logging points (auth, payload validation, idempotency, RPC calls, deadlocks, errors, locks), and register process-selective-rejection in config.toml. Also sanitize sensitive data in logs and ensure duration metrics are captured.
2025-12-20 08:11:13 -05:00 · 2025-11-10 14:32:37 +00:00
parent 94312c8ef0
commit 1551a2f08d
3 changed files with 234 additions and 30 deletions
--- a/supabase/config.toml
+++ b/supabase/config.toml
@@ -47,6 +47,9 @@ verify_jwt = true
 [functions.process-selective-approval]
 verify_jwt = false

+[functions.process-selective-rejection]
+verify_jwt = false
+
 [functions.send-escalation-notification]
 verify_jwt = true

--- a/supabase/functions/process-selective-approval/index.ts
+++ b/supabase/functions/process-selective-approval/index.ts
@@ -2,6 +2,7 @@ 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';

 const SUPABASE_URL = Deno.env.get('SUPABASE_URL') || 'https://api.thrillwiki.com';
 const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!;
@@ -22,8 +23,9 @@ const handler = async (req: Request) => {
    });
  }

-  // Generate request ID for tracking
-  const requestId = crypto.randomUUID();
+  // Start request tracking
+  const tracking: RequestTracking = startRequest();
+  const requestId = tracking.requestId;
  
  try {
    // STEP 1: Authentication
@@ -47,6 +49,11 @@ const handler = async (req: Request) => {

    const { data: { user }, error: authError } = await supabase.auth.getUser();
    if (authError || !user) {
+      edgeLogger.warn('Authentication failed', { 
+        requestId,
+        error: authError?.message,
+        action: 'process_approval'
+      });
      return new Response(
        JSON.stringify({ error: 'Unauthorized' }),
        { 
@@ -59,13 +66,24 @@ const handler = async (req: Request) => {
      );
    }

-    console.log(`[${requestId}] Approval request from moderator ${user.id}`);
+    edgeLogger.info('Approval request received', { 
+      requestId, 
+      moderatorId: user.id,
+      action: 'process_approval'
+    });

    // STEP 2: Parse request
    const body: ApprovalRequest = await req.json();
    const { submissionId, itemIds, idempotencyKey } = body;

    if (!submissionId || !itemIds || itemIds.length === 0) {
+      edgeLogger.warn('Invalid request payload', { 
+        requestId,
+        hasSubmissionId: !!submissionId,
+        hasItemIds: !!itemIds,
+        itemCount: itemIds?.length || 0,
+        action: 'process_approval'
+      });
      return new Response(
        JSON.stringify({ error: 'Missing required fields: submissionId, itemIds' }),
        { 
@@ -78,6 +96,13 @@ const handler = async (req: Request) => {
      );
    }

+    edgeLogger.info('Request validated', {
+      requestId,
+      submissionId,
+      itemCount: itemIds.length,
+      action: 'process_approval'
+    });
+
    // STEP 3: Idempotency check
    const { data: existingKey } = await supabase
      .from('submission_idempotency_keys')
@@ -86,7 +111,12 @@ const handler = async (req: Request) => {
      .single();

    if (existingKey?.status === 'completed') {
-      console.log(`[${requestId}] Idempotency key already processed, returning cached result`);
+      edgeLogger.info('Idempotency cache hit', { 
+        requestId, 
+        idempotencyKey,
+        cached: true,
+        action: 'process_approval'
+      });
      return new Response(
        JSON.stringify(existingKey.result_data),
        {
@@ -108,7 +138,12 @@ const handler = async (req: Request) => {
      .single();

    if (submissionError || !submission) {
-      console.error(`[${requestId}] Submission not found:`, submissionError);
+      edgeLogger.error('Submission not found', { 
+        requestId, 
+        submissionId,
+        error: submissionError?.message,
+        action: 'process_approval'
+      });
      return new Response(
        JSON.stringify({ error: 'Submission not found' }),
        { 
@@ -123,7 +158,13 @@ const handler = async (req: Request) => {

    // STEP 5: Verify moderator can approve this submission
    if (submission.assigned_to && submission.assigned_to !== user.id) {
-      console.error(`[${requestId}] Submission locked by another moderator`);
+      edgeLogger.warn('Lock conflict', { 
+        requestId,
+        submissionId,
+        lockedBy: submission.assigned_to,
+        attemptedBy: user.id,
+        action: 'process_approval'
+      });
      return new Response(
        JSON.stringify({ error: 'Submission is locked by another moderator' }),
        { 
@@ -137,7 +178,13 @@ const handler = async (req: Request) => {
    }

    if (!['pending', 'partially_approved'].includes(submission.status)) {
-      console.error(`[${requestId}] Invalid submission status: ${submission.status}`);
+      edgeLogger.warn('Invalid submission status', { 
+        requestId,
+        submissionId,
+        currentStatus: submission.status,
+        expectedStatuses: ['pending', 'partially_approved'],
+        action: 'process_approval'
+      });
      return new Response(
        JSON.stringify({ error: 'Submission already processed' }),
        { 
@@ -160,7 +207,12 @@ const handler = async (req: Request) => {
      });
    }

-    console.log(`[${requestId}] Calling process_approval_transaction RPC`);
+    edgeLogger.info('Calling approval transaction RPC', { 
+      requestId, 
+      submissionId,
+      itemCount: itemIds.length,
+      action: 'process_approval'
+    });

    // ============================================================================
    // STEP 7: Call RPC function with deadlock retry logic
@@ -194,12 +246,23 @@ const handler = async (req: Request) => {
      if (rpcError.code === '40P01' || rpcError.code === '40001') {
        retryCount++;
        if (retryCount > MAX_DEADLOCK_RETRIES) {
-          console.error(`[${requestId}] Max deadlock retries exceeded`);
+          edgeLogger.error('Max deadlock retries exceeded', { 
+            requestId,
+            submissionId,
+            attempt: retryCount,
+            action: 'process_approval'
+          });
          break;
        }

        const backoffMs = 100 * Math.pow(2, retryCount);
-        console.log(`[${requestId}] Deadlock detected, retrying in ${backoffMs}ms (attempt ${retryCount}/${MAX_DEADLOCK_RETRIES})`);
+        edgeLogger.warn('Deadlock detected, retrying', { 
+          requestId, 
+          attempt: retryCount,
+          maxAttempts: MAX_DEADLOCK_RETRIES,
+          backoffMs,
+          action: 'process_approval'
+        });
        await new Promise(r => setTimeout(r, backoffMs));
        continue;
      }
@@ -210,7 +273,16 @@ const handler = async (req: Request) => {

    if (rpcError) {
      // Transaction failed - EVERYTHING rolled back automatically by PostgreSQL
-      console.error(`[${requestId}] Approval transaction failed:`, rpcError);
+      const duration = endRequest(tracking);
+      edgeLogger.error('Transaction failed', { 
+        requestId, 
+        duration,
+        submissionId,
+        error: rpcError.message,
+        errorCode: rpcError.code,
+        retries: retryCount,
+        action: 'process_approval'
+      });

      // Update idempotency key to failed
      try {
@@ -223,7 +295,13 @@ const handler = async (req: Request) => {
          })
          .eq('idempotency_key', idempotencyKey);
      } catch (updateError) {
-        console.error(`[${requestId}] Failed to update idempotency key to failed:`, updateError);
+        edgeLogger.warn('Failed to update idempotency key', { 
+          requestId, 
+          idempotencyKey,
+          status: 'failed',
+          error: updateError instanceof Error ? updateError.message : String(updateError),
+          action: 'process_approval'
+        });
        // Non-blocking - continue with error response even if idempotency update fails
      }

@@ -244,7 +322,16 @@ const handler = async (req: Request) => {
      );
    }

-    console.log(`[${requestId}] Transaction completed successfully:`, result);
+    const duration = endRequest(tracking);
+    edgeLogger.info('Transaction completed successfully', { 
+      requestId, 
+      duration,
+      submissionId,
+      itemCount: itemIds.length,
+      retries: retryCount,
+      newStatus: result?.status,
+      action: 'process_approval'
+    });

    // STEP 8: Success - update idempotency key
    try {
@@ -257,7 +344,13 @@ const handler = async (req: Request) => {
        })
        .eq('idempotency_key', idempotencyKey);
    } catch (updateError) {
-      console.error(`[${requestId}] Failed to update idempotency key to completed:`, updateError);
+      edgeLogger.warn('Failed to update idempotency key', { 
+        requestId, 
+        idempotencyKey,
+        status: 'completed',
+        error: updateError instanceof Error ? updateError.message : String(updateError),
+        action: 'process_approval'
+      });
      // Non-blocking - transaction succeeded, so continue with success response
    }

@@ -274,7 +367,14 @@ const handler = async (req: Request) => {
    );

  } catch (error) {
-    console.error(`[${requestId}] Unexpected error:`, error);
+    const duration = endRequest(tracking);
+    edgeLogger.error('Unexpected error', { 
+      requestId, 
+      duration,
+      error: error instanceof Error ? error.message : String(error),
+      stack: error instanceof Error ? error.stack : undefined,
+      action: 'process_approval'
+    });
    return new Response(
      JSON.stringify({
        error: 'Internal server error',
--- a/supabase/functions/process-selective-rejection/index.ts
+++ b/supabase/functions/process-selective-rejection/index.ts
@@ -2,6 +2,7 @@ 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';

 const SUPABASE_URL = Deno.env.get('SUPABASE_URL') || 'https://api.thrillwiki.com';
 const SUPABASE_ANON_KEY = Deno.env.get('SUPABASE_ANON_KEY')!;
@@ -23,8 +24,9 @@ const handler = async (req: Request) => {
    });
  }

-  // Generate request ID for tracking
-  const requestId = crypto.randomUUID();
+  // Start request tracking
+  const tracking: RequestTracking = startRequest();
+  const requestId = tracking.requestId;
  
  try {
    // STEP 1: Authentication
@@ -48,6 +50,11 @@ const handler = async (req: Request) => {

    const { data: { user }, error: authError } = await supabase.auth.getUser();
    if (authError || !user) {
+      edgeLogger.warn('Authentication failed', { 
+        requestId,
+        error: authError?.message,
+        action: 'process_rejection'
+      });
      return new Response(
        JSON.stringify({ error: 'Unauthorized' }),
        { 
@@ -60,13 +67,25 @@ const handler = async (req: Request) => {
      );
    }

-    console.log(`[${requestId}] Rejection request from moderator ${user.id}`);
+    edgeLogger.info('Rejection request received', { 
+      requestId, 
+      moderatorId: user.id,
+      action: 'process_rejection'
+    });

    // STEP 2: Parse request
    const body: RejectionRequest = await req.json();
    const { submissionId, itemIds, rejectionReason, idempotencyKey } = body;

    if (!submissionId || !itemIds || itemIds.length === 0 || !rejectionReason) {
+      edgeLogger.warn('Invalid request payload', { 
+        requestId,
+        hasSubmissionId: !!submissionId,
+        hasItemIds: !!itemIds,
+        itemCount: itemIds?.length || 0,
+        hasReason: !!rejectionReason,
+        action: 'process_rejection'
+      });
      return new Response(
        JSON.stringify({ error: 'Missing required fields: submissionId, itemIds, rejectionReason' }),
        { 
@@ -79,6 +98,13 @@ const handler = async (req: Request) => {
      );
    }

+    edgeLogger.info('Request validated', {
+      requestId,
+      submissionId,
+      itemCount: itemIds.length,
+      action: 'process_rejection'
+    });
+
    // STEP 3: Idempotency check
    const { data: existingKey } = await supabase
      .from('submission_idempotency_keys')
@@ -87,7 +113,12 @@ const handler = async (req: Request) => {
      .single();

    if (existingKey?.status === 'completed') {
-      console.log(`[${requestId}] Idempotency key already processed, returning cached result`);
+      edgeLogger.info('Idempotency cache hit', { 
+        requestId, 
+        idempotencyKey,
+        cached: true,
+        action: 'process_rejection'
+      });
      return new Response(
        JSON.stringify(existingKey.result_data),
        {
@@ -109,7 +140,12 @@ const handler = async (req: Request) => {
      .single();

    if (submissionError || !submission) {
-      console.error(`[${requestId}] Submission not found:`, submissionError);
+      edgeLogger.error('Submission not found', { 
+        requestId, 
+        submissionId,
+        error: submissionError?.message,
+        action: 'process_rejection'
+      });
      return new Response(
        JSON.stringify({ error: 'Submission not found' }),
        { 
@@ -124,7 +160,13 @@ const handler = async (req: Request) => {

    // STEP 5: Verify moderator can reject this submission
    if (submission.assigned_to && submission.assigned_to !== user.id) {
-      console.error(`[${requestId}] Submission locked by another moderator`);
+      edgeLogger.warn('Lock conflict', { 
+        requestId,
+        submissionId,
+        lockedBy: submission.assigned_to,
+        attemptedBy: user.id,
+        action: 'process_rejection'
+      });
      return new Response(
        JSON.stringify({ error: 'Submission is locked by another moderator' }),
        { 
@@ -138,7 +180,13 @@ const handler = async (req: Request) => {
    }

    if (!['pending', 'partially_approved'].includes(submission.status)) {
-      console.error(`[${requestId}] Invalid submission status: ${submission.status}`);
+      edgeLogger.warn('Invalid submission status', { 
+        requestId,
+        submissionId,
+        currentStatus: submission.status,
+        expectedStatuses: ['pending', 'partially_approved'],
+        action: 'process_rejection'
+      });
      return new Response(
        JSON.stringify({ error: 'Submission already processed' }),
        { 
@@ -161,7 +209,12 @@ const handler = async (req: Request) => {
      });
    }

-    console.log(`[${requestId}] Calling process_rejection_transaction RPC`);
+    edgeLogger.info('Calling rejection transaction RPC', { 
+      requestId, 
+      submissionId,
+      itemCount: itemIds.length,
+      action: 'process_rejection'
+    });

    // ============================================================================
    // STEP 7: Call RPC function with deadlock retry logic
@@ -195,12 +248,23 @@ const handler = async (req: Request) => {
      if (rpcError.code === '40P01' || rpcError.code === '40001') {
        retryCount++;
        if (retryCount > MAX_DEADLOCK_RETRIES) {
-          console.error(`[${requestId}] Max deadlock retries exceeded`);
+          edgeLogger.error('Max deadlock retries exceeded', { 
+            requestId,
+            submissionId,
+            attempt: retryCount,
+            action: 'process_rejection'
+          });
          break;
        }

        const backoffMs = 100 * Math.pow(2, retryCount);
-        console.log(`[${requestId}] Deadlock detected, retrying in ${backoffMs}ms (attempt ${retryCount}/${MAX_DEADLOCK_RETRIES})`);
+        edgeLogger.warn('Deadlock detected, retrying', { 
+          requestId, 
+          attempt: retryCount,
+          maxAttempts: MAX_DEADLOCK_RETRIES,
+          backoffMs,
+          action: 'process_rejection'
+        });
        await new Promise(r => setTimeout(r, backoffMs));
        continue;
      }
@@ -211,7 +275,16 @@ const handler = async (req: Request) => {

    if (rpcError) {
      // Transaction failed - EVERYTHING rolled back automatically by PostgreSQL
-      console.error(`[${requestId}] Rejection transaction failed:`, rpcError);
+      const duration = endRequest(tracking);
+      edgeLogger.error('Transaction failed', { 
+        requestId, 
+        duration,
+        submissionId,
+        error: rpcError.message,
+        errorCode: rpcError.code,
+        retries: retryCount,
+        action: 'process_rejection'
+      });

      // Update idempotency key to failed
      try {
@@ -224,7 +297,13 @@ const handler = async (req: Request) => {
          })
          .eq('idempotency_key', idempotencyKey);
      } catch (updateError) {
-        console.error(`[${requestId}] Failed to update idempotency key to failed:`, updateError);
+        edgeLogger.warn('Failed to update idempotency key', { 
+          requestId, 
+          idempotencyKey,
+          status: 'failed',
+          error: updateError instanceof Error ? updateError.message : String(updateError),
+          action: 'process_rejection'
+        });
        // Non-blocking - continue with error response even if idempotency update fails
      }

@@ -245,7 +324,16 @@ const handler = async (req: Request) => {
      );
    }

-    console.log(`[${requestId}] Transaction completed successfully:`, result);
+    const duration = endRequest(tracking);
+    edgeLogger.info('Transaction completed successfully', { 
+      requestId, 
+      duration,
+      submissionId,
+      itemCount: itemIds.length,
+      retries: retryCount,
+      newStatus: result?.status,
+      action: 'process_rejection'
+    });

    // STEP 8: Success - update idempotency key
    try {
@@ -258,7 +346,13 @@ const handler = async (req: Request) => {
        })
        .eq('idempotency_key', idempotencyKey);
    } catch (updateError) {
-      console.error(`[${requestId}] Failed to update idempotency key to completed:`, updateError);
+      edgeLogger.warn('Failed to update idempotency key', { 
+        requestId, 
+        idempotencyKey,
+        status: 'completed',
+        error: updateError instanceof Error ? updateError.message : String(updateError),
+        action: 'process_rejection'
+      });
      // Non-blocking - transaction succeeded, so continue with success response
    }

@@ -275,7 +369,14 @@ const handler = async (req: Request) => {
    );

  } catch (error) {
-    console.error(`[${requestId}] Unexpected error:`, error);
+    const duration = endRequest(tracking);
+    edgeLogger.error('Unexpected error', { 
+      requestId, 
+      duration,
+      error: error instanceof Error ? error.message : String(error),
+      stack: error instanceof Error ? error.stack : undefined,
+      action: 'process_rejection'
+    });
    return new Response(
      JSON.stringify({
        error: 'Internal server error',