abord and log

src/api/routes/deliveryParse.js

@@ -212,6 +212,11 @@ async function parseDocumentManifest({ req, res, pages, sourceLabel }) {
             },
         },
         invoke: async (args) => {
+            const basedataKeys = args.basedata && typeof args.basedata === 'object' ? Object.keys(args.basedata) : [];
+            const notesCount = Array.isArray(args.notes) ? args.notes.length : 0;
+            const itemsCount = args.items?.items && Array.isArray(args.items.items) ? args.items.items.length : 0;
+            console.log(`[llmorbiter] Tool invoke output_manifest: basedata=[${basedataKeys.join(', ')}], notes=${notesCount}, items=${itemsCount}`);
+
             // Merge basedata
             if (args.basedata && typeof args.basedata === 'object') {
                 for (const key of ['date', 'kLieferant', 'lieferantName', 'manifestNr', 'manifestType']) {
@@ -259,35 +264,78 @@ async function parseDocumentManifest({ req, res, pages, sourceLabel }) {
     const model = '~openai/gpt-luna-latest:floor';
     const provider = new OpenRouterProvider({ apiKey });
     const orbiter = new LLMOrbiter(provider, {
-        onStatus: (status) => sseWrite(res, 'status', { message: status }),
+        onStatus: (status) => {
-        onLLMCall: (call) =>
+            console.log(`[llmorbiter] Status: ${status}`);
+            sseWrite(res, 'status', { message: status });
+        },
+        onLLMCall: (call) => {
+            console.log(
+                `[llmorbiter] LLM call (iteration ${call.iteration}): model=${call.model}, promptSize=${call.promptSize} chars, messages=${call.messageCount || call.messages}`
+            );
             sseWrite(res, 'llm_call', {
                 model: call.model,
                 promptSize: call.promptSize,
                 messages: call.messages,
-            }),
+            });
-        onToolCall: (call) => sseWrite(res, 'tool_call', { name: call.name }),
+        },
-        onUsage: (usage) =>
+        onToolCall: (call) => {
+            const details = [];
+            if (call.args?.basedata) details.push(`basedata: [${Object.keys(call.args.basedata).join(', ')}]`);
+            if (call.args?.items?.items) details.push(`items: ${call.args.items.items.length}`);
+            if (call.args?.notes) details.push(`notes: ${call.args.notes.length}`);
+            const suffix = details.length ? ` (${details.join(', ')})` : '';
+            console.log(`[llmorbiter] Tool call: ${call.name}${suffix}`);
+            sseWrite(res, 'tool_call', { name: call.name });
+        },
+        onToolResult: (call) => {
+            console.log(`[llmorbiter] Tool result: ${call.name}`);
+        },
+        onToolError: (call) => {
+            console.error(`[llmorbiter] Tool error in ${call.name}:`, call.error);
+        },
+        onUsage: (usage) => {
+            const costStr = usage.cost != null ? `, cost=$${usage.cost.toFixed(4)}` : '';
+            console.log(
+                `[llmorbiter] Usage: input=${usage.input}, cached=${usage.cached}, output=${usage.output}${costStr}`
+            );
             sseWrite(res, 'usage', {
                 input: usage.input,
                 cached: usage.cached,
                 output: usage.output,
                 cost: usage.cost,
-            }),
+            });
+        },
     });
 
+    const abortController = new AbortController();
+    abortController.signal.addEventListener('abort', () => {
+        const reason = abortController.signal.reason;
+        const msg = reason instanceof Error ? reason.message : String(reason || 'aborted');
+        console.log(`[llmorbiter] Abort signal triggered: ${msg}`);
+    });
+
+    const originalAbort = orbiter.abort.bind(orbiter);
+    orbiter.abort = (reason) => {
+        const reasonMsg = reason instanceof Error ? reason.message : String(reason || 'aborted');
+        console.log(`[llmorbiter] orbiter.abort() called (reason: ${reasonMsg})`);
+        return originalAbort(reason);
+    };
+
     const onDisconnect = () => {
-        if (!res.writableEnded) {
+        if (!res.writableEnded && !abortController.signal.aborted) {
-            orbiter.abort();
+            console.log('[llmorbiter] Client connection closed, aborting request');
+            abortController.abort('Client connection closed');
+            orbiter.abort('Client connection closed');
         }
     };
-    req.on('close', onDisconnect);
     res.on('close', onDisconnect);
 
     // ── Process all pages in one batch ───────────────────────────────
     try {
-        if (res.destroyed || req.destroyed) {
+        if (res.destroyed || res.writableEnded) {
-            orbiter.abort();
+            console.log('[llmorbiter] Response already closed or destroyed before run, aborting');
+            abortController.abort('Response closed before run');
+            orbiter.abort('Response closed before run');
             return;
         }
 
@@ -311,22 +359,30 @@ ${JSON.stringify(manifestItems, null, 2)}
 Page content:
 ${pageContent}`;
 
+        console.log(`[llmorbiter] Starting run: model=${model}, pages=${pages.length} (${sourceLabel})`);
         currentPage = 1;
-        await orbiter.run({ prompt, model, tools: [outputManifestTool] });
+        await orbiter.run({ prompt, model, tools: [outputManifestTool], signal: abortController.signal });
+        console.log(`[llmorbiter] Run completed successfully. Extracted ${manifestItems.items.length} item(s), ${manifestNotes.length} note(s)`);
     } catch (err) {
+        if (err.name === 'AbortError' || abortController.signal.aborted) {
+            console.log(`[llmorbiter] Run aborted: ${err.message || abortController.signal.reason?.message || 'AbortError'}`);
+        } else {
+            console.error('[llmorbiter] Run failed with error:', err);
+        }
         if (!res.writableEnded && !res.destroyed) {
             sseWrite(res, 'error', { message: 'LLM processing failed: ' + err.message });
         }
     } finally {
-        req.off('close', onDisconnect);
         res.off('close', onDisconnect);
     }
 
     if (res.writableEnded || res.destroyed) {
+        console.log('[llmorbiter] Response ended or destroyed, skipping final result');
         return;
     }
 
     // ── Final result ─────────────────────────────────────────────────
+    console.log(`[llmorbiter] Emitting final result event and closing stream`);
     sseWrite(res, 'result', {
         basedata: manifestBasedata,
         notes: manifestNotes,
@@ -462,13 +518,18 @@ export function register(app, basePath = '') {
                 return res.status(400).json({ error: 'A document file is required (field name: file)' });
             }
 
+            const sourceLabel = isPdfUpload(req.file) ? 'PDF' : 'Text';
+            console.log(`[deliveryParse] Received file "${req.file.originalname}" (${req.file.size} bytes, type=${sourceLabel})`);
+
             let pages;
             try {
-                pages = isPdfUpload(req.file) ? readPdfPages(req.file.buffer) : readTxtPages(req.file.buffer);
+                pages = sourceLabel === 'PDF' ? readPdfPages(req.file.buffer) : readTxtPages(req.file.buffer);
             } catch (err) {
+                console.error(`[deliveryParse] Failed to parse document: ${err.message}`);
                 return res.status(400).json({ error: 'Failed to parse document: ' + err.message });
             }
             if (pages.length === 0) {
+                console.warn('[deliveryParse] Document content is empty');
                 return res.status(400).json({ error: 'Document content is empty' });
             }
 
@@ -476,7 +537,7 @@ export function register(app, basePath = '') {
                 req,
                 res,
                 pages,
-                sourceLabel: isPdfUpload(req.file) ? 'PDF' : 'Text',
+                sourceLabel,
             });
         },
     );