From 81262d706ad3f63df5ea14464678d54c9121a64e Mon Sep 17 00:00:00 2001 From: Alejandro Rosales Date: Wed, 14 Jan 2026 15:25:14 -0600 Subject: [PATCH] Refactor input normalization and enhance logging for OpenAI function --- supabase/functions/ai-structured/index.ts | 412 +++++++++++++++++++--- 1 file changed, 366 insertions(+), 46 deletions(-) diff --git a/supabase/functions/ai-structured/index.ts b/supabase/functions/ai-structured/index.ts index 096c36d..4ccd566 100644 --- a/supabase/functions/ai-structured/index.ts +++ b/supabase/functions/ai-structured/index.ts @@ -47,7 +47,6 @@ function sanitizeTools(tools: any[]): any[] { function normalizeInputWithOpenAIFileIds(input: any, fileIds: string[]) { if (!fileIds?.length) return input; - // Responses API acepta input como string o array. let items = Array.isArray(input) ? [...input] : [{ role: "user", content: [ @@ -55,7 +54,6 @@ function normalizeInputWithOpenAIFileIds(input: any, fileIds: string[]) { ], }]; - // Busca último mensaje "user" let idx = -1; for (let i = items.length - 1; i >= 0; i--) { if (items[i]?.role === "user") { @@ -71,13 +69,11 @@ function normalizeInputWithOpenAIFileIds(input: any, fileIds: string[]) { const msg = items[idx]; const fileParts = fileIds.map((id) => ({ type: "input_file", file_id: id })); - // Normalize content to array format if (typeof msg.content === "string") { msg.content = [{ type: "input_text", text: msg.content }, ...fileParts]; } else if (Array.isArray(msg.content)) { msg.content = [...msg.content, ...fileParts]; } else { - // fallback raro msg.content = [ { type: "input_text", text: String(msg.content) }, ...fileParts, @@ -110,100 +106,294 @@ function normalizeInputUser(input: any) { } } +/** ----------------- LOGGING HELPERS (diagnóstico) ----------------- */ + +function nowIso() { + return new Date().toISOString(); +} + +function redactAuthHeader(v: string | null) { + if (!v) return null; + // "Bearer xxx" => "Bearer [REDACTED]" + const parts = v.split(" "); + if (parts.length >= 2) return `${parts[0]} [REDACTED]`; + return "[REDACTED]"; +} + +function safePreview(val: unknown, maxLen = 1200) { + try { + const jsonStr = JSON.stringify(val, (k, v) => { + if (typeof v === "string") { + if (v.length > 500) return v.slice(0, 500) + "…[TRUNCATED]"; + // evita imprimir base64/data URLs + if (v.startsWith("data:") && v.includes(";base64,")) return "[DATA_URL_REDACTED]"; + } + return v; + }); + if (!jsonStr) return String(val); + return jsonStr.length > maxLen ? jsonStr.slice(0, maxLen) + "…[TRUNCATED]" : jsonStr; + } catch { + return String(val); + } +} + +function headersSnapshot(req: Request) { + const h: Record = {}; + for (const [k, v] of req.headers.entries()) { + if (k.toLowerCase() === "authorization") h[k] = redactAuthHeader(v) ?? ""; + else h[k] = v; + } + return h; +} + +function summarizeInputShape(input: any) { + const out: any = { type: typeof input }; + if (Array.isArray(input)) { + out.kind = "array"; + out.length = input.length; + out.lastRole = input?.[input.length - 1]?.role ?? null; + out.roles = input.map((m: any) => m?.role).filter(Boolean); + // intenta contar parts (sin imprimir textos) + try { + let parts = 0; + for (const m of input) { + if (Array.isArray(m?.content)) parts += m.content.length; + } + out.totalParts = parts; + } catch { + // ignore + } + } + return out; +} + +function summarizeFormat(format: any) { + if (!format) return null; + const t = format.type ?? null; + const name = format.name ?? null; + const strict = format.strict ?? null; + const schemaKeys = format.schema ? Object.keys(format.schema) : []; + return { + type: t, + name, + strict, + hasSchema: Boolean(format.schema), + schemaTopKeys: schemaKeys.slice(0, 20), + }; +} + +function toolsSummary(tools: any[]) { + const arr = Array.isArray(tools) ? tools : []; + return arr.map((t) => { + if (!t) return t; + const base: any = { type: t.type }; + if (t.type === "file_search") base.vector_store_ids_count = (t.vector_store_ids ?? []).length; + if (t.type === "mcp") { + base.server_label = t.server_label ?? null; + base.server_url = t.server_url ? "[SET]" : null; + base.require_approval = t.require_approval ?? null; + base.authorization = t.authorization ? "[REDACTED]" : null; + base.allowed_tools_count = Array.isArray(t.allowed_tools) ? t.allowed_tools.length : null; + } + return base; + }); +} + +/** ----------------------------------------------------------------- */ + Deno.serve(async (req) => { + const cid = crypto.randomUUID(); + const t0 = performance.now(); + + const log = (msg: string, extra?: unknown) => { + if (extra !== undefined) { + console.log(`[${nowIso()}][ai-structured][${cid}] ${msg}`, safePreview(extra)); + } else { + console.log(`[${nowIso()}][ai-structured][${cid}] ${msg}`); + } + }; + + const warn = (msg: string, extra?: unknown) => { + if (extra !== undefined) { + console.warn(`[${nowIso()}][ai-structured][${cid}] ⚠️ ${msg}`, safePreview(extra)); + } else { + console.warn(`[${nowIso()}][ai-structured][${cid}] ⚠️ ${msg}`); + } + }; + + const errlog = (msg: string, extra?: unknown) => { + if (extra !== undefined) { + console.error(`[${nowIso()}][ai-structured][${cid}] ❌ ${msg}`, safePreview(extra)); + } else { + console.error(`[${nowIso()}][ai-structured][${cid}] ❌ ${msg}`); + } + }; + if (req.method === "OPTIONS") { + log("OPTIONS preflight ✅", { + method: req.method, + url: req.url, + headers: headersSnapshot(req), + }); return new Response(null, { status: 204, headers: corsHeaders }); } + log("START 🚀", { method: req.method, url: req.url }); + log("Headers snapshot 🧾", headersSnapshot(req)); + try { // 1) Auth requerido ✅ - console.log('Función EDGE'); - - const authHeader = req.headers.get("Authorization") ?? + log("Step 1: Auth check 🔐"); + + const authHeaderRaw = req.headers.get("Authorization") ?? req.headers.get("authorization"); - if (!authHeader) { - return json({ ok: false, error: "Missing Authorization header" }, 401); + log("Authorization header present?", { present: Boolean(authHeaderRaw), value: redactAuthHeader(authHeaderRaw) }); + + if (!authHeaderRaw) { + warn("Missing Authorization header"); + return json({ ok: false, error: "Missing Authorization header", cid }, 401); } const SUPABASE_URL = Deno.env.get("SUPABASE_URL"); const SUPABASE_ANON_KEY = Deno.env.get("SUPABASE_ANON_KEY"); + log("Env presence (Supabase) 🌍", { + hasSUPABASE_URL: Boolean(SUPABASE_URL), + hasSUPABASE_ANON_KEY: Boolean(SUPABASE_ANON_KEY), + }); + if (!SUPABASE_URL || !SUPABASE_ANON_KEY) { + errlog("Missing SUPABASE_URL / SUPABASE_ANON_KEY"); return json({ ok: false, error: "Missing SUPABASE_URL / SUPABASE_ANON_KEY", + cid, }, 500); } - // Cliente con el JWT del usuario (para validar quién llama) const supabaseUser = createClient(SUPABASE_URL, SUPABASE_ANON_KEY, { - global: { headers: { Authorization: authHeader } }, + global: { headers: { Authorization: authHeaderRaw } }, }); - const { data: userData, error: userErr } = await supabaseUser.auth - .getUser(); - if (userErr || !userData?.user) { - return json({ ok: false, error: "Invalid token" }, 401); - } - const user = userData.user; + const tAuth = performance.now(); + const { data: userData, error: userErr } = await supabaseUser.auth.getUser(); + log("Supabase auth.getUser() done ⏱️", { ms: Math.round(performance.now() - tAuth) }); + + if (userErr || !userData?.user) { + warn("Invalid token", { userErr: userErr?.message ?? userErr ?? null }); + return json({ ok: false, error: "Invalid token", cid }, 401); + } + + const user = userData.user; + log("Authenticated user ✅", { userId: user.id, email: user.email ?? null }); - // (Opcional) service role para uploads server-side (más confiable) const SERVICE_ROLE = Deno.env.get("SUPABASE_SERVICE_ROLE_KEY"); + log("Env presence (service role) 🗝️", { hasSERVICE_ROLE: Boolean(SERVICE_ROLE) }); + const supabaseAdmin = SERVICE_ROLE ? createClient(SUPABASE_URL, SERVICE_ROLE) : supabaseUser; + log("Supabase client selected 🧩", { adminMode: Boolean(SERVICE_ROLE) }); + // 2) Parse body (JSON o multipart) 📦 + log("Step 2: Parse body 📦"); const contentType = req.headers.get("content-type") ?? ""; + log("Content-Type", { contentType }); + let payload: any = {}; let tempFiles: File[] = []; + const tParse = performance.now(); if (contentType.includes("multipart/form-data")) { + log("Parsing multipart/form-data 🧷"); let form; try { form = await req.formData(); } catch (error) { + errlog("Invalid multipart/form-data body", { + message: (error as Error)?.message ?? String(error), + stack: (error as Error)?.stack ?? null, + }); return json({ ok: false, error: "Invalid multipart/form-data body", - details: error, + details: (error as Error)?.message ?? String(error), + cid, }, 400); } - const raw = form.get("payload") ?? "{}"; - payload = JSON.parse(raw); - // Soporta nombres comunes - for ( - const key of ["files", "files[]", "archivos", "archivosTemporales"] - ) { - for (const v of form.getAll(key)) { + // keys overview + const keys = Array.from(form.keys()); + log("Multipart keys", { keys, keysCount: keys.length }); + + const raw = form.get("payload") ?? "{}"; + log("Multipart payload field type", { type: typeof raw }); + + try { + payload = JSON.parse(String(raw)); + } catch (e) { + errlog("Multipart `payload` is not valid JSON", { + rawPreview: String(raw).slice(0, 400), + error: (e as Error)?.message ?? String(e), + }); + return json({ + ok: false, + error: "Invalid JSON in multipart `payload` field", + cid, + }, 400); + } + + for (const key of ["files", "files[]", "archivos", "archivosTemporales"]) { + const vals = form.getAll(key); + if (vals?.length) log(`Found multipart field "${key}"`, { count: vals.length }); + for (const v of vals) { if (v instanceof File) tempFiles.push(v); } } - // Fallback: toma cualquier File en el form + if (tempFiles.length === 0) { - for (const [, v] of form.entries()) { + for (const [k, v] of form.entries()) { if (v instanceof File) tempFiles.push(v); + // opcional: log campos no-file si necesitas + // else log("Form entry", { key: k, type: typeof v }); } } + + log("Multipart files detected 📎", { + count: tempFiles.length, + files: tempFiles.map((f) => ({ name: f.name, type: f.type, size: f.size })), + }); } else { - payload = await req.json(); + log("Parsing JSON body 🧾"); + try { + payload = await req.json(); + } catch (e) { + errlog("Invalid JSON body", { error: (e as Error)?.message ?? String(e) }); + return json({ ok: false, error: "Invalid JSON body", cid }, 400); + } } + log("Body parsed ⏱️", { ms: Math.round(performance.now() - tParse) }); + log("Payload top-level keys", { keys: Object.keys(payload ?? {}), hasOpenAI: Boolean(payload?.openai), hasResponse: Boolean(payload?.response) }); // 3) Construye config final para OpenAI (passthrough + overrides) 🧠 - // Puedes mandar "response" o "openai" (ambos se mezclan) + log("Step 3: Build responseCfg 🧠"); const responseCfg: any = { ...(payload.openai ?? {}), ...(payload.response ?? {}), }; - // Conveniencia top-level if (payload.input !== undefined && responseCfg.input === undefined) { responseCfg.input = payload.input; + log("responseCfg.input set from payload.input"); } - // Normaliza input a array de mensajes + if (responseCfg.input !== undefined) { responseCfg.input = normalizeInputUser(responseCfg.input); + log("responseCfg.input normalized ✅", summarizeInputShape(responseCfg.input)); + } else { + warn("responseCfg.input is undefined (is that expected?)"); } + if (payload.model && !responseCfg.model) responseCfg.model = payload.model; if (payload.conversationId && responseCfg.conversation === undefined) { responseCfg.conversation = payload.conversationId; @@ -216,73 +406,98 @@ Deno.serve(async (req) => { responseCfg.reasoning = payload.reasoning; } - // Defaults responseCfg.model = responseCfg.model ?? "gpt-5"; + log("OpenAI config summary 🤖", { + model: responseCfg.model, + hasConversation: Boolean(responseCfg.conversation), + hasPreviousResponseId: Boolean(responseCfg.previous_response_id), + hasReasoning: Boolean(responseCfg.reasoning), + include: Array.isArray(responseCfg.include) ? responseCfg.include : null, + }); - // Regla API: no mezclar conversation + previous_response_id if (responseCfg.conversation && responseCfg.previous_response_id) { + warn("Invalid: conversation + previous_response_id together"); return json( { ok: false, error: "Do not send both `conversation` and `previous_response_id`.", + cid, }, 400, ); } // 4) Structured Outputs (JSON Schema) ✅ - // Espera payload.structured (o payload.outputSchema) como objeto o string JSON + log("Step 4: Structured output setup ✅"); let structured = payload.structured ?? payload.outputSchema; + log("Structured presence", { + hasStructured: Boolean(structured), + structuredType: typeof structured, + }); + if (!structured) { + warn("Missing structured schema"); return json({ ok: false, error: "Missing `structured` (JSON schema format).", + cid, }, 400); } if (typeof structured === "string") { + log("Parsing structured from string 🧩", { preview: structured.slice(0, 200) }); try { structured = JSON.parse(structured); - } catch { + } catch (e) { + errlog("`structured` string is not valid JSON", { error: (e as Error)?.message ?? String(e) }); return json({ ok: false, error: "`structured` is a string but not valid JSON.", + cid, }, 400); } } - // Permite que te manden { format: {...} } const format = structured.format ? structured.format : structured; - if (!format.type) format.type = "json_schema"; if (format.type === "json_schema") { format.name = format.name ?? "structured_output"; format.strict = format.strict ?? true; if (!format.schema) { + warn("structured.schema missing"); return json( - { ok: false, error: "structured.schema is required." }, + { ok: false, error: "structured.schema is required.", cid }, 400, ); } } responseCfg.text = { ...(responseCfg.text ?? {}), format }; + log("Structured format summary 🧾", summarizeFormat(format)); // 5) Referencias (3 tipos) 📎 + log("Step 5: References & tools 📎"); const references = payload.references ?? {}; const openaiFileIds: string[] = references.openaiFileIds ?? payload.openaiFileIds ?? []; const vectorStoreIds: string[] = references.vectorStoreIds ?? payload.vectorStoreIds ?? []; + log("References summary", { + openaiFileIdsCount: openaiFileIds.length, + vectorStoreIdsCount: vectorStoreIds.length, + usarMCP: Boolean(payload.usarMCP ?? references.usarMCP ?? payload.mcp?.enabled), + }); + // 5a) Vector stores => file_search tool const tools: any[] = Array.isArray(responseCfg.tools) ? [...responseCfg.tools] : []; + log("Initial tools (from client)", toolsSummary(tools)); + if (vectorStoreIds.length) { tools.push({ type: "file_search", vector_store_ids: vectorStoreIds }); - // Si quieres ver resultados de búsqueda en la respuesta const include = Array.isArray(responseCfg.include) ? responseCfg.include : []; @@ -290,6 +505,8 @@ Deno.serve(async (req) => { include.push("file_search_call.results"); } responseCfg.include = include; + + log("Added file_search tool 🗂️", { vectorStoreIdsCount: vectorStoreIds.length, include: responseCfg.include }); } // 5b) MCP opcional @@ -299,15 +516,24 @@ Deno.serve(async (req) => { if (usarMCP) { const mcp = payload.mcp ?? {}; const server_url = mcp.server_url ?? Deno.env.get("MCP_SERVER_URL"); + log("MCP config presence", { + hasServerUrl: Boolean(server_url), + hasAuthorization: Boolean(mcp.authorization ?? Deno.env.get("MCP_AUTHORIZATION")), + server_label: mcp.server_label ?? Deno.env.get("MCP_SERVER_LABEL") ?? "supabase", + }); + if (!server_url) { + warn("usarMCP=true but missing server_url"); return json( { ok: false, error: "usarMCP=true pero falta MCP_SERVER_URL o mcp.server_url", + cid, }, 400, ); } + tools.push({ type: "mcp", server_label: mcp.server_label ?? Deno.env.get("MCP_SERVER_LABEL") ?? @@ -316,21 +542,27 @@ Deno.serve(async (req) => { server_url, require_approval: mcp.require_approval ?? "never", authorization: mcp.authorization ?? Deno.env.get("MCP_AUTHORIZATION"), - allowed_tools: mcp.allowed_tools, // opcional + allowed_tools: mcp.allowed_tools, }); + + log("Added MCP tool 🔌", toolsSummary([tools[tools.length - 1]])); } responseCfg.tools = tools; + log("Final tools summary 🧰", toolsSummary(responseCfg.tools)); // 5c) OpenAI file IDs => se insertan al input como input_file if (openaiFileIds.length) { + log("Injecting OpenAI file_ids into input 🧷", { count: openaiFileIds.length }); responseCfg.input = normalizeInputWithOpenAIFileIds( responseCfg.input, openaiFileIds, ); + log("Input after OpenAI file_ids injection", summarizeInputShape(responseCfg.input)); } // 6) Archivos temporales => subir a Supabase Storage (NO a OpenAI) ☁️ + log("Step 6: Temp files -> Storage ☁️"); const uploadedToStorage: Array<{ bucket: string; path: string; @@ -345,24 +577,47 @@ Deno.serve(async (req) => { const prefix = payload.storage?.prefix ?? Deno.env.get("AI_FILES_PREFIX") ?? "tmp"; + log("Storage target", { bucket, prefix, filesCount: tempFiles.length }); + for (const f of tempFiles) { const safeName = (f.name ?? "file").replaceAll(/[^a-zA-Z0-9._-]/g, "_"); const path = `${prefix}/${user.id}/${crypto.randomUUID()}-${safeName}`; + log("Uploading file to storage ⬆️", { name: f.name, type: f.type, size: f.size, path }); + + const tUp = performance.now(); const bytes = new Uint8Array(await f.arrayBuffer()); + + // warning útil: btoa + spread puede tronarse con archivos grandes + if (bytes.length > 2 * MB) { + warn("Large file detected: base64 building might be heavy (btoa + spread) 🧨", { + name: f.name, + bytes: bytes.length, + approxBase64Chars: Math.ceil(bytes.length * 4 / 3), + }); + } + const { data, error } = await supabaseAdmin.storage .from(bucket) .upload(path, bytes, { contentType: f.type, upsert: false }); + log("Storage upload done ⏱️", { ms: Math.round(performance.now() - tUp) }); + if (error) { + errlog("Storage upload failed", { message: error.message, file: f.name, bucket, path }); return json({ ok: false, error: `Storage upload failed: ${error.message}`, file: f.name, + cid, }, 500); } + // Add as an input_file base64 reference to the last user message content - const fileBase64 = btoa(String.fromCharCode(...bytes)); + const tB64 = performance.now(); + const fileBase64 = btoa(String.fromCharCode(...bytes)); // ⚠️ potencialmente pesado + log("Base64 built ⏱️", { ms: Math.round(performance.now() - tB64), base64Chars: fileBase64.length }); + if (Array.isArray(responseCfg.input) && responseCfg.input.length > 0) { const lastMsg = responseCfg.input[responseCfg.input.length - 1]; if (lastMsg?.role === "user" && Array.isArray(lastMsg.content)) { @@ -371,7 +626,20 @@ Deno.serve(async (req) => { filename: f.name, file_data: `data:${f.type};base64,${fileBase64}`, }); + log("Appended input_file to last user message 🧷", { + lastRole: lastMsg.role, + partsCount: lastMsg.content.length, + filename: f.name, + // no imprimimos file_data + }); + } else { + warn("Could not append input_file: last message is not user/content array", { + lastRole: lastMsg?.role ?? null, + lastContentType: typeof lastMsg?.content, + }); } + } else { + warn("responseCfg.input not array or empty; cannot append file_data", summarizeInputShape(responseCfg.input)); } uploadedToStorage.push({ @@ -382,33 +650,73 @@ Deno.serve(async (req) => { size: f.size, }); } + } else { + log("No temp files to upload 🧼"); } // 7) Llamada a OpenAI Responses API 🚀 + log("Step 7: OpenAI call 🚀"); const OPENAI_API_KEY = Deno.env.get("OPENAI_API_KEY"); + log("Env presence (OpenAI) 🔑", { hasOPENAI_API_KEY: Boolean(OPENAI_API_KEY) }); + if (!OPENAI_API_KEY) { - return json({ ok: false, error: "Missing OPENAI_API_KEY" }, 500); + errlog("Missing OPENAI_API_KEY"); + return json({ ok: false, error: "Missing OPENAI_API_KEY", cid }, 500); } + // snapshot del request hacia OpenAI (sin secretos y sin megadata) + log("OpenAI request snapshot (sanitized) 🧪", { + model: responseCfg.model, + input: summarizeInputShape(responseCfg.input), + tools: toolsSummary(responseCfg.tools), + include: Array.isArray(responseCfg.include) ? responseCfg.include : null, + hasTextFormat: Boolean(responseCfg.text?.format), + textFormat: summarizeFormat(responseCfg.text?.format), + hasConversation: Boolean(responseCfg.conversation), + hasPreviousResponseId: Boolean(responseCfg.previous_response_id), + }); + const openai = new OpenAI({ apiKey: OPENAI_API_KEY }); - let resp = null; + let resp: any = null; + + const tOpenAI = performance.now(); try { resp = await openai.responses.create(responseCfg); } catch (error) { + errlog("OpenAI API error", { + message: (error as Error)?.message ?? String(error), + stack: (error as Error)?.stack ?? null, + }); return json({ ok: false, error: "OpenAI API error", details: (error as Error)?.message ?? String(error), + cid, }, 500); } + log("OpenAI call done ⏱️", { ms: Math.round(performance.now() - tOpenAI) }); const outputText = extractOutputText(resp); + log("OpenAI response basics ✅", { + responseId: resp?.id ?? null, + model: resp?.model ?? responseCfg.model, + hasConversationObj: Boolean(resp?.conversation), + usage: resp?.usage ?? null, + outputTextChars: outputText?.length ?? 0, + }); + let output: unknown = null; let outputParseError: string | null = null; + const tParseOut = performance.now(); try { output = JSON.parse(outputText); + log("Output JSON parsed ✅", { ms: Math.round(performance.now() - tParseOut) }); } catch (e) { outputParseError = (e as Error)?.message ?? String(e); + warn("Output JSON parse FAILED 🧯", { + error: outputParseError, + outputTextPreview: (outputText ?? "").slice(0, 600), + }); } const conv = resp?.conversation?.id ?? @@ -416,8 +724,16 @@ Deno.serve(async (req) => { ? resp.conversation : responseCfg.conversation ?? null); + log("RETURN ✅", { + ok: !outputParseError, + conversationId: conv, + responseId: resp?.id ?? null, + totalMs: Math.round(performance.now() - t0), + }); + return json({ ok: outputParseError ? false : true, + cid, // 👈 útil para correlacionar logs responseId: resp.id, conversationId: conv, model: resp.model ?? responseCfg.model, @@ -431,7 +747,6 @@ Deno.serve(async (req) => { uploadedToStorage, openaiFileIds, vectorStoreIds, - // Si quieres mandar tus UUID internos de archivos, aquí van (solo eco) archivosReferenciaIds: references.archivosReferenciaIds ?? payload.archivosReferenciaIds ?? payload.archivosReferencia ?? [], }, @@ -439,6 +754,11 @@ Deno.serve(async (req) => { tools: sanitizeTools(responseCfg.tools), }); } catch (e) { - return json({ ok: false, error: (e as Error)?.message ?? String(e) }, 500); + errlog("Unhandled error 💥", { + message: (e as Error)?.message ?? String(e), + stack: (e as Error)?.stack ?? null, + totalMs: Math.round(performance.now() - t0), + }); + return json({ ok: false, error: (e as Error)?.message ?? String(e), cid }, 500); } });