diff --git a/src/features/session/sessionChatAi.ts b/src/features/session/sessionChatAi.ts index 042ef13..99a82c9 100644 --- a/src/features/session/sessionChatAi.ts +++ b/src/features/session/sessionChatAi.ts @@ -4,8 +4,11 @@ import { getAiAgentRuntime, waitForSidecarReady, } from '@/features/ai/aiAgent' +import { logger } from '@/lib/log' import { strings } from '@/strings' +const log = logger.child('ai.session-chat') + export type SessionAiMessage = { role: 'user' | 'assistant' content: string @@ -18,6 +21,26 @@ export const SESSION_CHAT_MAX_TOPIC_LENGTH = 120 export const SESSION_CHAT_MAX_AUDIT_CONTEXT = 8 export const SESSION_CHAT_MAX_AUDIT_KIND_LENGTH = 64 +// llama-server's `json_object` response format constrains only JSON syntax +// unless a schema is supplied. Keep the grammar aligned with the parser so a +// small local model cannot satisfy the server while missing `reply_text`. +// This is the schema shape supported by our pinned llama.cpp b9095 build. +export const SESSION_CHAT_RESPONSE_FORMAT = { + type: 'json_object', + schema: { + type: 'object', + properties: { + reply_text: { + type: 'string', + minLength: 1, + maxLength: SESSION_CHAT_MAX_REPLY_LENGTH, + }, + }, + required: ['reply_text'], + additionalProperties: false, + }, +} as const + export const SESSION_CHAT_SYSTEM_PROMPT = `You are StudyVis AI, a concise conversational study assistant running entirely on the user's device. Answer the current user message, using the prior conversation and session context when it is helpful. Return ONLY one JSON object with exactly this shape: @@ -81,29 +104,36 @@ function buildHistory( .filter((message) => message.content.length > 0) } -function parseSessionChatReply(raw: string): string { - const candidates: string[] = [] +function parseSessionChatReply(raw: string, modelId: string): string { + const candidates = new Set() const trimmed = raw.trim() - if (trimmed) candidates.push(trimmed) + if (trimmed) candidates.add(trimmed) const fenceMatch = raw.match(/```(?:json)?\s*([\s\S]*?)\s*```/) - if (fenceMatch?.[1]) candidates.push(fenceMatch[1].trim()) + if (fenceMatch?.[1]) candidates.add(fenceMatch[1].trim()) const firstBrace = raw.indexOf('{') const lastBrace = raw.lastIndexOf('}') if (firstBrace >= 0 && lastBrace > firstBrace) { - candidates.push(raw.slice(firstBrace, lastBrace + 1)) + candidates.add(raw.slice(firstBrace, lastBrace + 1)) } + let parsedObjectCount = 0 + let replyTextPresent = false + let replyTextString = false for (const candidate of candidates) { try { const parsed: unknown = JSON.parse(candidate) if (!parsed || typeof parsed !== 'object' || Array.isArray(parsed)) continue - const keys = Object.keys(parsed) - if (keys.length !== 1 || keys[0] !== 'reply_text') continue + parsedObjectCount += 1 + replyTextPresent ||= Object.prototype.hasOwnProperty.call( + parsed, + 'reply_text' + ) const replyText = (parsed as { reply_text?: unknown }).reply_text if (typeof replyText !== 'string') continue + replyTextString = true const bounded = boundedText(replyText, SESSION_CHAT_MAX_REPLY_LENGTH) if (bounded) return bounded } catch { @@ -112,6 +142,16 @@ function parseSessionChatReply(raw: string): string { } } + // Shape only: prompts, session context, candidate keys, and generated text + // must never enter the diagnostic bundle. + log.warn('reply.parse_failed', { + modelId, + rawLength: raw.length, + candidateCount: candidates.size, + parsedObjectCount, + replyTextPresent, + replyTextString, + }) throw new AiAgentError('parse_error', strings.session.chat.aiFailed) } @@ -128,6 +168,32 @@ function isAbortError(error: unknown): boolean { return error instanceof Error && error.name === 'AbortError' } +function abortablePromise( + promise: Promise, + signal: AbortSignal +): Promise { + if (signal.aborted) return Promise.reject(abortReason(signal)) + + return new Promise((resolve, reject) => { + const onAbort = () => { + cleanup() + reject(abortReason(signal)) + } + const cleanup = () => signal.removeEventListener('abort', onAbort) + signal.addEventListener('abort', onAbort, { once: true }) + promise.then( + (value) => { + cleanup() + resolve(value) + }, + (error) => { + cleanup() + reject(error) + } + ) + }) +} + export async function handleSessionChatText( input: SessionChatInput ): Promise { @@ -150,16 +216,23 @@ export async function handleSessionChatText( controller.abort(input.signal?.reason) } input.signal?.addEventListener('abort', abortFromInput, { once: true }) + // AbortSignal does not replay an abort event to a listener added after the + // transition. Close the narrow race between the post-readiness check above + // and listener registration before starting any local-model work. + if (input.signal?.aborted) abortFromInput() const timer = setTimeout(() => { if (abortSource) return abortSource = 'timeout' controller.abort() }, AGENT_REQUEST_TIMEOUT_MS) + const requestStartedAt = runtime.now() + let stage: 'request' | 'response_body' | 'reply_parse' = 'request' + let responseStatus: number | null = null + let contentLength: number | null = null try { - const response = await runtime.fetch( - `http://127.0.0.1:${port}/v1/chat/completions`, - { + const response = await abortablePromise( + runtime.fetch(`http://127.0.0.1:${port}/v1/chat/completions`, { method: 'POST', headers: { 'Content-Type': 'application/json' }, body: JSON.stringify({ @@ -171,11 +244,13 @@ export async function handleSessionChatText( ], temperature: 0, max_tokens: 300, - response_format: { type: 'json_object' }, + response_format: SESSION_CHAT_RESPONSE_FORMAT, }), signal: controller.signal, - } + }), + controller.signal ) + responseStatus = response.status if (!response.ok) { throw new AiAgentError( 'http_error', @@ -183,22 +258,56 @@ export async function handleSessionChatText( ) } - const json = (await response.json()) as { + stage = 'response_body' + const json = (await abortablePromise( + response.json(), + controller.signal + )) as { choices?: Array<{ message?: { content?: unknown } }> } const content = json?.choices?.[0]?.message?.content - return parseSessionChatReply(typeof content === 'string' ? content : '') + const rawContent = typeof content === 'string' ? content : '' + contentLength = rawContent.length + stage = 'reply_parse' + const reply = parseSessionChatReply(rawContent, input.modelId) + log.info('request.succeeded', { + modelId: input.modelId, + elapsedMs: Math.max(0, runtime.now() - requestStartedAt), + status: responseStatus, + contentLength, + }) + return reply } catch (error) { if (abortSource === 'external') throw abortReason(input.signal) + let mappedError: unknown = error if (abortSource === 'timeout') { - throw new AiAgentError('timeout', strings.session.chat.aiTimedOut) - } - if (error instanceof AiAgentError) throw error - if (error instanceof SyntaxError) { - throw new AiAgentError('parse_error', strings.session.chat.aiFailed) + mappedError = new AiAgentError('timeout', strings.session.chat.aiTimedOut) + } else if (error instanceof SyntaxError) { + mappedError = new AiAgentError( + 'parse_error', + strings.session.chat.aiFailed + ) + } else if (!(error instanceof AiAgentError) && !isAbortError(error)) { + mappedError = new AiAgentError( + 'http_error', + strings.session.chat.aiFailed + ) } - if (isAbortError(error)) throw error - throw new AiAgentError('http_error', strings.session.chat.aiFailed) + + log.warn('request.failed', { + modelId: input.modelId, + elapsedMs: Math.max(0, runtime.now() - requestStartedAt), + stage, + code: + mappedError instanceof AiAgentError + ? mappedError.code + : isAbortError(mappedError) + ? 'aborted' + : 'unknown', + status: responseStatus, + contentLength, + }) + throw mappedError } finally { clearTimeout(timer) input.signal?.removeEventListener('abort', abortFromInput) diff --git a/tests/unit/session-chat-ai.test.ts b/tests/unit/session-chat-ai.test.ts index 789851b..0514595 100644 --- a/tests/unit/session-chat-ai.test.ts +++ b/tests/unit/session-chat-ai.test.ts @@ -23,6 +23,7 @@ import { SESSION_CHAT_SYSTEM_PROMPT, type SessionAiMessage, } from '@/features/session/sessionChatAi' +import { __resetLog, __setLogRecordSink, type LogRecord } from '@/lib/log' import { strings } from '@/strings' const BASE_INPUT = { @@ -100,6 +101,7 @@ function pendingFetch(): typeof fetch { afterEach(() => { __resetAiAgentRuntime() + __resetLog() vi.useRealTimers() vi.restoreAllMocks() }) @@ -137,7 +139,21 @@ describe('handleSessionChatText request contract', () => { const body = requestBody(fetchMock) expect(body.model).toBe(BASE_INPUT.modelId) - expect(body.response_format).toEqual({ type: 'json_object' }) + expect(body.response_format).toEqual({ + type: 'json_object', + schema: { + type: 'object', + properties: { + reply_text: { + type: 'string', + minLength: 1, + maxLength: SESSION_CHAT_MAX_REPLY_LENGTH, + }, + }, + required: ['reply_text'], + additionalProperties: false, + }, + }) expect(body.messages).toHaveLength(SESSION_CHAT_MAX_HISTORY_MESSAGES + 2) expect(body.messages[0].role).toBe('system') expect(body.messages[0].content).toContain(SESSION_CHAT_SYSTEM_PROMPT) @@ -216,9 +232,16 @@ describe('handleSessionChatText request contract', () => { ]) }) - test('trims and caps a valid reply without exposing command fields', async () => { + test('trims and caps reply_text while ignoring extra command-shaped fields', async () => { const fetchMock = vi.fn(async () => - completion(JSON.stringify({ reply_text: ` ${'r'.repeat(700)} ` })) + completion( + JSON.stringify({ + intent: 'topic_change', + payload: { new_topic: 'A model-supplied topic must not be applied' }, + metadata: { confidence: 0.9 }, + reply_text: ` ${'r'.repeat(700)} `, + }) + ) ) useRuntime({ fetch: fetchMock as unknown as typeof fetch }) @@ -251,6 +274,42 @@ describe('handleSessionChatText request contract', () => { expect(fetchMock).toHaveBeenCalledOnce() expect(vi.getTimerCount()).toBe(0) }) + + test('records bounded outcome metadata without prompts or replies', async () => { + const records: LogRecord[] = [] + __resetLog() + __setLogRecordSink((record) => records.push(record)) + const privatePrompt = 'private prompt 9kJw2R' + const privateTopic = 'private topic 4xPq7S' + const privateReply = 'private reply 6mNv3T' + const fetchMock = vi.fn(async () => + completion(JSON.stringify({ reply_text: privateReply })) + ) + useRuntime({ fetch: fetchMock as unknown as typeof fetch }) + + await expect( + handleSessionChatText({ + ...BASE_INPUT, + text: privatePrompt, + declaredTopic: privateTopic, + }) + ).resolves.toBe(privateReply) + + const succeeded = records.find( + (record) => + record.scope === 'ai.session-chat' && record.msg === 'request.succeeded' + ) + expect(succeeded?.data).toEqual({ + modelId: BASE_INPUT.modelId, + elapsedMs: 0, + status: 200, + contentLength: JSON.stringify({ reply_text: privateReply }).length, + }) + const serialized = JSON.stringify(records) + expect(serialized).not.toContain(privatePrompt) + expect(serialized).not.toContain(privateTopic) + expect(serialized).not.toContain(privateReply) + }) }) describe('handleSessionChatText failures and cancellation', () => { @@ -313,11 +372,13 @@ describe('handleSessionChatText failures and cancellation', () => { test.each([ 'not JSON', + JSON.stringify({}), + JSON.stringify({ answer: 'Wrong key.' }), JSON.stringify({ reply_text: '' }), + JSON.stringify({ reply_text: ' ' }), JSON.stringify({ reply_text: 42 }), - JSON.stringify({ intent: 'topic_change', reply_text: 'Changed it.' }), ])( - 'rejects malformed or command-shaped model output: %s', + 'rejects malformed, missing, empty, or non-string reply output: %s', async (content) => { const fetchMock = vi.fn(async () => completion(content)) useRuntime({ fetch: fetchMock as unknown as typeof fetch }) @@ -329,6 +390,66 @@ describe('handleSessionChatText failures and cancellation', () => { } ) + test('rejects a successful completion envelope with no reply content', async () => { + const fetchMock = vi.fn( + async () => + new Response(JSON.stringify({ choices: [{ message: {} }] }), { + status: 200, + }) + ) + useRuntime({ fetch: fetchMock as unknown as typeof fetch }) + + await expect(handleSessionChatText(BASE_INPUT)).rejects.toMatchObject({ + code: 'parse_error', + message: strings.session.chat.aiFailed, + }) + }) + + test('deduplicates failed reply candidates and logs only shape/error metadata', async () => { + const records: LogRecord[] = [] + __resetLog() + __setLogRecordSink((record) => records.push(record)) + const privatePrompt = 'private failure prompt 2qLm8D' + const privateOutput = JSON.stringify({ answer: 'private output 7vRs5C' }) + const fetchMock = vi.fn(async () => completion(privateOutput)) + useRuntime({ fetch: fetchMock as unknown as typeof fetch }) + + await expect( + handleSessionChatText({ ...BASE_INPUT, text: privatePrompt }) + ).rejects.toMatchObject({ code: 'parse_error' }) + + const parseFailed = records.find( + (record) => + record.scope === 'ai.session-chat' && + record.msg === 'reply.parse_failed' + ) + expect(parseFailed?.data).toEqual({ + modelId: BASE_INPUT.modelId, + rawLength: privateOutput.length, + candidateCount: 1, + parsedObjectCount: 1, + replyTextPresent: false, + replyTextString: false, + }) + expect( + records.find( + (record) => + record.scope === 'ai.session-chat' && record.msg === 'request.failed' + )?.data + ).toEqual({ + modelId: BASE_INPUT.modelId, + elapsedMs: 0, + stage: 'reply_parse', + code: 'parse_error', + status: 200, + contentLength: privateOutput.length, + }) + const serialized = JSON.stringify(records) + expect(serialized).not.toContain(privatePrompt) + expect(serialized).not.toContain(privateOutput) + expect(serialized).not.toContain('private output 7vRs5C') + }) + test('classifies an invalid completion response body as a parse error', async () => { const fetchMock = vi.fn( async () => new Response('{broken', { status: 200 }) @@ -342,8 +463,8 @@ describe('handleSessionChatText failures and cancellation', () => { test('aborts a stalled request at the agent timeout', async () => { vi.useFakeTimers() - const fetchMock = pendingFetch() - useRuntime({ fetch: fetchMock }) + const fetchMock = vi.fn(() => new Promise(() => {})) + useRuntime({ fetch: fetchMock as unknown as typeof fetch }) const request = handleSessionChatText(BASE_INPUT) const rejection = expect(request).rejects.toMatchObject({ code: 'timeout' }) @@ -353,6 +474,45 @@ describe('handleSessionChatText failures and cancellation', () => { await rejection }) + test('times out a stalled response body even when it ignores AbortSignal', async () => { + vi.useFakeTimers() + let bodyReadStarted = false + const fetchMock = vi.fn( + async () => + ({ + ok: true, + status: 200, + json: () => { + bodyReadStarted = true + return new Promise(() => {}) + }, + }) as unknown as Response + ) + useRuntime({ fetch: fetchMock as unknown as typeof fetch }) + + const request = handleSessionChatText(BASE_INPUT) + let settled = false + void request.then( + () => { + settled = true + }, + () => { + settled = true + } + ) + const rejection = expect(request).rejects.toMatchObject({ code: 'timeout' }) + + await vi.advanceTimersByTimeAsync(0) + expect(fetchMock).toHaveBeenCalledOnce() + expect(bodyReadStarted).toBe(true) + await vi.advanceTimersByTimeAsync(AGENT_REQUEST_TIMEOUT_MS - 1) + expect(settled).toBe(false) + await vi.advanceTimersByTimeAsync(1) + await rejection + expect(settled).toBe(true) + expect(vi.getTimerCount()).toBe(0) + }) + test('forwards caller cancellation independently of the timeout', async () => { vi.useFakeTimers() const fetchMock = pendingFetch() @@ -372,6 +532,37 @@ describe('handleSessionChatText failures and cancellation', () => { expect(vi.getTimerCount()).toBe(0) }) + test('forwards caller cancellation while a response body ignores AbortSignal', async () => { + vi.useFakeTimers() + let bodyReadStarted = false + const fetchMock = vi.fn( + async () => + ({ + ok: true, + status: 200, + json: () => { + bodyReadStarted = true + return new Promise(() => {}) + }, + }) as unknown as Response + ) + useRuntime({ fetch: fetchMock as unknown as typeof fetch }) + const controller = new AbortController() + const reason = new DOMException('panel closed', 'AbortError') + + const request = handleSessionChatText({ + ...BASE_INPUT, + signal: controller.signal, + }) + const rejection = expect(request).rejects.toBe(reason) + await vi.advanceTimersByTimeAsync(0) + expect(bodyReadStarted).toBe(true) + + controller.abort(reason) + await rejection + expect(vi.getTimerCount()).toBe(0) + }) + test('forwards caller cancellation while waiting for readiness', async () => { vi.useFakeTimers() const fetchHealth = pendingFetch()