diff --git a/evals/investigate-functions-002-console-output-behind-200/EVAL.ts b/evals/investigate-functions-002-console-output-behind-200/EVAL.ts new file mode 100644 index 00000000..eaca3a2f --- /dev/null +++ b/evals/investigate-functions-002-console-output-behind-200/EVAL.ts @@ -0,0 +1,39 @@ +import type { CheckResult, ToolScorer } from '@supabase-evals/core'; + +// The function returns 200 on every call while `console.error`-ing the real +// failure. The request envelope (source 'function_edge_logs') therefore shows +// nothing wrong; the answer lives only in the console stream (source +// 'function_logs'), and only in its `event_message` column — `log_attributes` +// carries execution metadata, not the log line. See README.md. +// +// All checks are deterministic: the user asked for the exact error, so the +// report must quote the identifiers that only the seeded console line carries. + +const FAILED_ORDERS = ['ORD-48213', 'ORD-48217', 'ORD-48220']; + +const scorer: ToolScorer = async (ctx) => { + const report = ctx.agentReport ?? ''; + const namedOrders = FAILED_ORDERS.filter((id) => report.includes(id)); + + const checks: CheckResult[] = [ + { + name: 'quoted the SKU from the console error (WH-1002)', + passed: /\bWH-1002\b/.test(report), + }, + { + name: 'attributed the failure to the SKU missing from the warehouse feed', + passed: /warehouse feed/i.test(report), + }, + { + name: 'named at least one of the affected orders', + passed: namedOrders.length > 0, + }, + ]; + + return { + passed: checks.every((check) => check.passed), + checks, + }; +}; + +export default scorer; diff --git a/evals/investigate-functions-002-console-output-behind-200/PROMPT.md b/evals/investigate-functions-002-console-output-behind-200/PROMPT.md new file mode 100644 index 00000000..345a1b16 --- /dev/null +++ b/evals/investigate-functions-002-console-output-behind-200/PROMPT.md @@ -0,0 +1,14 @@ +--- +stage: investigate +suite: regression +interface: mcp +product: + - edge-functions +topic: + - observability +motivation: supabase/mcp#375, supabase/mcp#376 +--- + +Something is off with our `order-sync` edge function. Every call this morning came back 200, but a few of the orders never showed up on the warehouse side. + +Can you check what the function actually logged for those orders? I need the exact error it printed so I can send it to the warehouse vendor. diff --git a/evals/investigate-functions-002-console-output-behind-200/README.md b/evals/investigate-functions-002-console-output-behind-200/README.md new file mode 100644 index 00000000..eb2697fd --- /dev/null +++ b/evals/investigate-functions-002-console-output-behind-200/README.md @@ -0,0 +1,40 @@ +# investigate-functions-002-console-output-behind-200 + +Tracks supabase/mcp#375: on hosted projects `get_logs` is hidden and `query_logs` is the only +logs tool, and its ClickHouse hint names `function_edge_logs` but not `function_logs`, and +`log_attributes['']` but not `event_message`. Agents asked for an edge function's console +output reach the request envelope, find nothing wrong, and report that the output was never +stored. The fix under review is supabase/mcp#376. + +## Setup + +`order-sync` is a deployed function that pushes orders to a warehouse. A line whose SKU is not +in the warehouse feed is logged with `console.error` and skipped, and the function still returns +200 — so the request/response stream cannot show the failure. + +The logs seed both edge-function streams separately (platform-lite keeps them as distinct +`source` values, exactly like hosted): + +| seed `source` | unified-stream `source` | what it holds | +| ---------------------- | ----------------------- | ------------------------------------------------------------------------ | +| `edge-function` | `function_edge_logs` | one `POST \| 200 \| …/order-sync` envelope per invocation — all 200s | +| `edge-function-runtime`| `function_logs` | the console lines: 3 `console.error` lines for orders ORD-48213/48217/48220 (SKU `WH-1002` missing from the feed), `console.log` lines for the rest, and a boot line | + +An unrelated `send-receipt` function and two Postgres checkpoint lines are seeded as noise. + +The console line text is only in `event_message`. `log_attributes` on those rows carries +`level`, `event_type`, `function_id`, `execution_id`, `deployment_id`, `version` — no message +key — matching the hosted `function_logs` shape. + +## What it scores + +The prompt asks for the exact error, so the checks are deterministic on the agent's final +report: it must quote the SKU (`WH-1002`), attribute the failure to the SKU missing from the +warehouse feed, and name at least one of the affected orders. + +Two failure modes both score zero here, and both were observed on hosted projects: + +1. The agent queries `function_edge_logs` (the source the hint names), sees only 200 envelopes, + and reports that the function logs nothing or that console output is not stored. +2. The agent reaches `function_logs` but reads `log_attributes[...]` per the hint, finds no + message key, and reaches the same conclusion. diff --git a/evals/investigate-functions-002-console-output-behind-200/remote/functions/order-sync/index.ts b/evals/investigate-functions-002-console-output-behind-200/remote/functions/order-sync/index.ts new file mode 100644 index 00000000..1844e62f --- /dev/null +++ b/evals/investigate-functions-002-console-output-behind-200/remote/functions/order-sync/index.ts @@ -0,0 +1,56 @@ +// Pushes a paid order to the warehouse. The warehouse feed is fetched once per +// invocation and every order line is matched against it by SKU. +// +// NOTE: a line whose SKU is missing from the feed is logged and skipped so a +// single bad SKU never fails the whole checkout — the caller still gets a 200. + +type OrderLine = { sku: string; qty: number }; +type Order = { id: string; lines: OrderLine[] }; + +const WAREHOUSE_URL = Deno.env.get('WAREHOUSE_URL')!; +const WAREHOUSE_TOKEN = Deno.env.get('WAREHOUSE_TOKEN')!; + +async function loadWarehouseFeed(): Promise> { + const res = await fetch(`${WAREHOUSE_URL}/feed`, { + headers: { authorization: `Bearer ${WAREHOUSE_TOKEN}` }, + }); + const feed: { sku: string }[] = await res.json(); + return new Set(feed.map((item) => item.sku)); +} + +Deno.serve(async (req) => { + const order: Order = await req.json(); + const feed = await loadWarehouseFeed(); + + const shippable = order.lines.filter((line) => feed.has(line.sku)); + const missing = order.lines.filter((line) => !feed.has(line.sku)); + + for (const line of missing) { + console.error( + `[order-sync] warehouse sync failed for order ${order.id}: SKU ${line.sku} is not in the warehouse feed (skipping line)` + ); + } + + if (shippable.length > 0) { + await fetch(`${WAREHOUSE_URL}/orders`, { + method: 'POST', + headers: { + authorization: `Bearer ${WAREHOUSE_TOKEN}`, + 'content-type': 'application/json', + }, + body: JSON.stringify({ id: order.id, lines: shippable }), + }); + console.log( + `[order-sync] synced order ${order.id} (${shippable.length} line(s))` + ); + } + + return new Response( + JSON.stringify({ + ok: true, + synced: shippable.length, + skipped: missing.length, + }), + { status: 200, headers: { 'content-type': 'application/json' } } + ); +}); diff --git a/evals/investigate-functions-002-console-output-behind-200/remote/logs.jsonl b/evals/investigate-functions-002-console-output-behind-200/remote/logs.jsonl new file mode 100644 index 00000000..8b7b75ed --- /dev/null +++ b/evals/investigate-functions-002-console-output-behind-200/remote/logs.jsonl @@ -0,0 +1,39 @@ +{"id":"os-boot","ts":"2026-06-15T07:30:00.000Z","source":"edge-function-runtime","level":"info","message":"booted (time: 41ms)","metadata":{"function_id":"order-sync","event_type":"Boot","execution_id":"exec-boot-14","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-req-1","ts":"2026-06-15T07:34:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":180,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-1-ok","ts":"2026-06-15T07:34:01.200Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48209 (2 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48209","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"sr-req-1","ts":"2026-06-15T07:34:30.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/send-receipt","metadata":{"function_id":"send-receipt","status":200,"duration_ms":95,"method":"POST","pathname":"/functions/v1/send-receipt","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"sr-con-1","ts":"2026-06-15T07:34:30.600Z","source":"edge-function-runtime","level":"info","message":"[send-receipt] receipt email queued for ORD-48209","metadata":{"function_id":"send-receipt","event_type":"Log","execution_id":"exec-receipt-1","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"os-req-2","ts":"2026-06-15T07:38:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":217,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-2-ok","ts":"2026-06-15T07:38:01.200Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48210 (1 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48210","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"sr-req-2","ts":"2026-06-15T07:38:30.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/send-receipt","metadata":{"function_id":"send-receipt","status":200,"duration_ms":106,"method":"POST","pathname":"/functions/v1/send-receipt","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"sr-con-2","ts":"2026-06-15T07:38:30.600Z","source":"edge-function-runtime","level":"info","message":"[send-receipt] receipt email queued for ORD-48210","metadata":{"function_id":"send-receipt","event_type":"Log","execution_id":"exec-receipt-2","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"os-req-3","ts":"2026-06-15T07:42:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":254,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-3-ok","ts":"2026-06-15T07:42:01.200Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48211 (3 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48211","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"sr-req-3","ts":"2026-06-15T07:42:30.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/send-receipt","metadata":{"function_id":"send-receipt","status":200,"duration_ms":117,"method":"POST","pathname":"/functions/v1/send-receipt","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"sr-con-3","ts":"2026-06-15T07:42:30.600Z","source":"edge-function-runtime","level":"info","message":"[send-receipt] receipt email queued for ORD-48211","metadata":{"function_id":"send-receipt","event_type":"Log","execution_id":"exec-receipt-3","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"os-req-4","ts":"2026-06-15T07:46:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":201,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-4-err","ts":"2026-06-15T07:46:00.900Z","source":"edge-function-runtime","level":"error","message":"[order-sync] warehouse sync failed for order ORD-48213: SKU WH-1002 is not in the warehouse feed (skipping line)","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48213","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-4-ok","ts":"2026-06-15T07:46:01.500Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48213 (1 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48213","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"sr-req-4","ts":"2026-06-15T07:46:30.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/send-receipt","metadata":{"function_id":"send-receipt","status":200,"duration_ms":128,"method":"POST","pathname":"/functions/v1/send-receipt","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"sr-con-4","ts":"2026-06-15T07:46:30.600Z","source":"edge-function-runtime","level":"info","message":"[send-receipt] receipt email queued for ORD-48214","metadata":{"function_id":"send-receipt","event_type":"Log","execution_id":"exec-receipt-4","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"os-req-5","ts":"2026-06-15T07:50:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":238,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"pg-1","ts":"2026-06-15T07:50:00.000Z","source":"postgres","level":"info","message":"checkpoint complete: wrote 118 buffers (0.7%)","metadata":{}} +{"id":"os-con-5-ok","ts":"2026-06-15T07:50:01.200Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48214 (1 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48214","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"sr-req-5","ts":"2026-06-15T07:50:30.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/send-receipt","metadata":{"function_id":"send-receipt","status":200,"duration_ms":99,"method":"POST","pathname":"/functions/v1/send-receipt","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"sr-con-5","ts":"2026-06-15T07:50:30.600Z","source":"edge-function-runtime","level":"info","message":"[send-receipt] receipt email queued for ORD-48216","metadata":{"function_id":"send-receipt","event_type":"Log","execution_id":"exec-receipt-5","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"os-req-6","ts":"2026-06-15T07:54:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":185,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-6-ok","ts":"2026-06-15T07:54:01.200Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48216 (4 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48216","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"sr-req-6","ts":"2026-06-15T07:54:30.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/send-receipt","metadata":{"function_id":"send-receipt","status":200,"duration_ms":110,"method":"POST","pathname":"/functions/v1/send-receipt","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"sr-con-6","ts":"2026-06-15T07:54:30.600Z","source":"edge-function-runtime","level":"info","message":"[send-receipt] receipt email queued for ORD-48218","metadata":{"function_id":"send-receipt","event_type":"Log","execution_id":"exec-receipt-6","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"os-req-7","ts":"2026-06-15T07:58:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":222,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-7-err","ts":"2026-06-15T07:58:00.900Z","source":"edge-function-runtime","level":"error","message":"[order-sync] warehouse sync failed for order ORD-48217: SKU WH-1002 is not in the warehouse feed (skipping line)","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48217","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"sr-req-7","ts":"2026-06-15T07:58:30.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/send-receipt","metadata":{"function_id":"send-receipt","status":200,"duration_ms":121,"method":"POST","pathname":"/functions/v1/send-receipt","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"sr-con-7","ts":"2026-06-15T07:58:30.600Z","source":"edge-function-runtime","level":"info","message":"[send-receipt] receipt email queued for ORD-48221","metadata":{"function_id":"send-receipt","event_type":"Log","execution_id":"exec-receipt-7","deployment_id":"send-receipt-deploy-6","version":"6"}} +{"id":"os-req-8","ts":"2026-06-15T08:02:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":259,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-8-ok","ts":"2026-06-15T08:02:01.200Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48218 (2 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48218","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"pg-2","ts":"2026-06-15T08:05:00.000Z","source":"postgres","level":"info","message":"checkpoint complete: wrote 64 buffers (0.4%)","metadata":{}} +{"id":"os-req-9","ts":"2026-06-15T08:06:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":206,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-9-err","ts":"2026-06-15T08:06:00.900Z","source":"edge-function-runtime","level":"error","message":"[order-sync] warehouse sync failed for order ORD-48220: SKU WH-1002 is not in the warehouse feed (skipping line)","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48220","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-9-ok","ts":"2026-06-15T08:06:01.500Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48220 (2 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48220","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-req-10","ts":"2026-06-15T08:10:00.000Z","source":"edge-function","level":"info","message":"POST | 200 | https://example.supabase.co/functions/v1/order-sync","metadata":{"function_id":"order-sync","status":200,"duration_ms":243,"method":"POST","pathname":"/functions/v1/order-sync","deployment_id":"order-sync-deploy-14","version":"14"}} +{"id":"os-con-10-ok","ts":"2026-06-15T08:10:01.200Z","source":"edge-function-runtime","level":"info","message":"[order-sync] synced order ORD-48221 (1 line(s))","metadata":{"function_id":"order-sync","event_type":"Log","execution_id":"exec-ord-48221","deployment_id":"order-sync-deploy-14","version":"14"}}