diff --git a/src/routes/clinicalAssistant.js b/src/routes/clinicalAssistant.js index 38f6ede9..b41186f2 100644 --- a/src/routes/clinicalAssistant.js +++ b/src/routes/clinicalAssistant.js @@ -453,7 +453,7 @@ router.post('/clinical-assistant/chat/stream', async function(req, res) { }); res.end(); } catch (e) { - console.error('[clinical-assistant stream]', e.message, e.stack || ''); + logger.error('[clinical-assistant stream] ' + e.message, { code: e.code, stack: String(e.stack || '').slice(0, 800) }); if (!streamOpen) return res.status(e.statusCode || 500).json({ error: assistantErrorMessage(e), code: e.code, budget: e.budget }); sendEvent('error', { error: assistantErrorMessage(e), code: e.code, budget: e.budget }); res.end(); @@ -500,9 +500,9 @@ async function dispatchImageRequestFallback(ai, prepared, req) { prepared.imageModel); ai.imageJobs = [job]; ai.imageToolHandled = true; - console.log('[clinical-assistant] image requested via text; queued image job', { jobId: job.jobId, model: job.model }); + logger.info('[clinical-assistant] image requested via text; queued image job', { jobId: job.jobId, model: job.model }); } catch (e) { - console.warn('[clinical-assistant] image fallback enqueue failed', e && e.message); + logger.warn('[clinical-assistant] image fallback enqueue failed', { error: e && e.message }); } return ai; } diff --git a/src/utils/clinicalAnswer.js b/src/utils/clinicalAnswer.js index 82a092b0..5726c808 100644 --- a/src/utils/clinicalAnswer.js +++ b/src/utils/clinicalAnswer.js @@ -45,7 +45,7 @@ async function finalizeAssistantAnswer(ai, options) { // transient. If it comes back empty again, that is said out loud rather than // presented as an answer. if (!answer && typeof options.callAI === 'function') { - console.warn('[clinical-assistant] the model returned an empty answer; asking once more', { + require('./fileLog').write('warn', '[clinical-assistant] the model returned an empty answer; asking once more', { finishReason: ai && ai.finishReason, streamed: Boolean(options.streamed) }); if (typeof options.onRegenerating === 'function') options.onRegenerating(); var retried = await options.callAI(options.messages, Object.assign({}, options.generationOptions || {}, { @@ -67,7 +67,7 @@ async function finalizeAssistantAnswer(ai, options) { } if (shouldRegenerateTruncatedAnswer(answer, ai && ai.finishReason) && typeof options.callAI === 'function') { - console.warn('[clinical-assistant] answer looked truncated; regenerating final answer', { finishReason: ai && ai.finishReason, chars: answer.length, streamed: Boolean(options.streamed) }); + require('./fileLog').write('warn', '[clinical-assistant] answer looked truncated; regenerating final answer', { finishReason: ai && ai.finishReason, chars: answer.length, streamed: Boolean(options.streamed) }); if (typeof options.onRegenerating === 'function') options.onRegenerating(); var completed = await options.callAI(options.messages, Object.assign({}, options.generationOptions || {}, { model: options.chatModel || undefined, diff --git a/src/utils/deckBuild.js b/src/utils/deckBuild.js index 8379301c..abaa0175 100644 --- a/src/utils/deckBuild.js +++ b/src/utils/deckBuild.js @@ -82,8 +82,23 @@ async function drawFigures(deck, opts) { if (!holder) continue; try { var context = images.imageContext(opts.subject + ' — ' + (slide.heading || ''), []); - var key = ('deck:' + images.requestKey(opts.body) + ':' + request.index + - (request.shape === undefined ? '' : '.' + request.shape)).slice(0, 160); + // Keyed on what is being drawn, not on where it sits. + // + // This used to be requestKey(body) + slide index. Two generations from the + // same form produced the same body hash, so slide 4 of one deck and slide + // 4 of another collided on (owner, workflow, key) — the unique constraint + // handed back the first job, and the second deck showed the first deck's + // picture. The decks are not even the same length, so the reused image + // could land on a slide about something else entirely. + // + // The body hash stays, so submitting the identical request twice still + // dedupes rather than billing twice; the prompt hash is what makes two + // different pictures two different jobs. + var drawing = require('crypto').createHash('sha256') + .update(JSON.stringify({ p: request.prompt, s: request.shape, + l: slide.type === 'figure' ? 'portrait' : 'landscape' })) + .digest('hex').slice(0, 24); + var key = ('deck:' + images.requestKey(opts.body) + ':' + drawing).slice(0, 160); var job = await queue.enqueue(opts.owner, 'my_resources', { prompt: request.prompt, layout: slide.type === 'figure' ? 'portrait' : 'landscape' }, key, true, context, opts.imageModel); diff --git a/src/utils/fileLog.js b/src/utils/fileLog.js new file mode 100644 index 00000000..f5885663 --- /dev/null +++ b/src/utils/fileLog.js @@ -0,0 +1,38 @@ +// ============================================================ +// FILE LOG +// ============================================================ +// Appending a line to the dated log file, and nothing else. +// +// Split out of logger.js because logger requires the database at module load, +// so importing it just to record a diagnostic pulls in a connection pool. That +// is wrong on its own terms — a note about what happened should not need a +// database — and it hung the test suite: a unit test that exercised a code path +// containing a log call inherited an open pool handle and never exited. +// +// fs and the redactor only. logger.file delegates here, so there is one +// implementation of where a line goes and how it is redacted. +var fs = require('fs'); +var path = require('path'); +var { redact } = require('./redact'); + +var LOG_DIR = path.join(__dirname, '../../data/logs'); + +function write(level, message, data) { + try { + if (!fs.existsSync(LOG_DIR)) fs.mkdirSync(LOG_DIR, { recursive: true }); + var now = new Date(); + var file = path.join(LOG_DIR, now.toISOString().split('T')[0] + '.log'); + // Defensive redaction: both message and data go through redact() so PHI + // patterns cannot reach the file if a caller passes a request body, a + // clinical string, or a stack trace containing transcript text. + var line = '[' + now.toISOString() + '] [' + level.toUpperCase() + '] ' + + redact(String(message == null ? '' : message)); + if (data != null) { + line += ' | ' + redact(typeof data === 'string' ? data : JSON.stringify(data)); + } + fs.appendFileSync(file, line + '\n'); + if (level === 'error') console.error(line); + } catch (e) { /* a diagnostic is never worth failing the caller for */ } +} + +module.exports = { write, LOG_DIR }; diff --git a/src/utils/imageTool.js b/src/utils/imageTool.js index c59472c0..ffd69e5e 100644 --- a/src/utils/imageTool.js +++ b/src/utils/imageTool.js @@ -1,4 +1,22 @@ const { service, args, requestKey, failure } = require('./generatedImages'); +// Every refusal below ends the turn with no picture and, until now, no record of +// which refusal it was. There are five of them and they want five different +// fixes; console output dies with the container, so by the time anyone asks +// "why was there no image" the answer has already been deleted. +// fileLog, not logger: logger requires the database at module load, so importing +// it here just to record a refusal would pull a connection pool into every test +// that touches this module. +const fileLog = require('./fileLog'); + +function note(level, message, detail) { + fileLog.write(level, '[image-tool] ' + message, detail || {}); +} + +// Refuse loudly. The message the caller sees stays exactly as it was. +function refuse(status, message, detail) { + note('warn', message, detail); + return failure(status, message); +} const tools = [{ type: 'function', function: { name: 'generate_image', description: 'Generate one medical educational image. Use it when the user\'s latest message asks for a picture, or for a change to one you just made, and not otherwise. Supply a self-contained prompt grounded in the current clinical content. The server selects model, credentials and workflow. Return the educational answer separately; never put image markup or invented asset URLs in it.', parameters: { type: 'object', additionalProperties: false, properties: { @@ -7,16 +25,21 @@ const tools = [{ type: 'function', function: { name: 'generate_image', }, required: ['prompt'] } } }]; async function dispatch(ai, { owner, workflow, body, messages, options, callAI, images, imageContext, imageModel }) { if (!ai.toolCalls || !ai.toolCalls.length) return ai; - if (ai.toolCalls.length !== 1) throw failure(400, 'Only one image tool invocation is permitted per request'); + if (ai.toolCalls.length !== 1) throw refuse(400, 'Only one image tool invocation is permitted per request', { calls: ai.toolCalls.length }); const call = ai.toolCalls[0]; if (!call || call.type !== 'function' || call.function?.name !== 'generate_image' || typeof call.id !== 'string' || call.id.length > 200 || - typeof call.function.arguments !== 'string' || call.function.arguments.length > 40000) throw failure(400, 'Invalid image tool call'); + typeof call.function.arguments !== 'string' || call.function.arguments.length > 40000) throw refuse(400, 'Invalid image tool call', { + type: call && call.type, name: call && call.function && call.function.name, + argType: typeof (call && call.function && call.function.arguments) }); let input; - try { input = JSON.parse(call.function.arguments); } catch (_) { throw failure(400, 'Image tool arguments must be valid JSON'); } - args(input); - if (!imageContext) throw failure(400, 'Validated original image request and context are required for image tools'); + try { input = JSON.parse(call.function.arguments); } catch (_) { throw refuse(400, 'Image tool arguments must be valid JSON', { chars: call.function.arguments.length }); } + try { args(input); } + catch (e) { throw refuse(400, 'Image tool arguments were rejected', { reason: e && e.message }); } + if (!imageContext) throw refuse(400, 'Validated original image request and context are required for image tools', { workflow: workflow }); images = images || service(); const job = await images.enqueue(owner, workflow, input, 'tool:' + requestKey(body), true, imageContext, imageModel); + note('info', 'queued', { jobId: job.jobId, workflow: workflow, model: job.model, + hadText: Boolean(String(ai.content || '').trim()) }); let completed = ai; if (!String(ai.content || '').trim()) { // One FIRST-body continuation only. Existing body/citations are never sent for rewriting. @@ -24,7 +47,12 @@ async function dispatch(ai, { owner, workflow, body, messages, options, callAI, { role: 'assistant', content: null, tool_calls: [call] }, { role: 'tool', tool_call_id: call.id, content: JSON.stringify({ jobId: job.jobId, status: job.status, instruction: 'Image job queued. Now return the first educational body in the originally requested format. Do not claim the image is complete or insert image URLs.' }) } ]), { ...options, tools, toolChoice: 'none', maxTokens: Math.min(options.maxTokens || 4000, 8000) }); - if (completed.toolCalls?.length || !String(completed.content || '').trim()) throw failure(502, 'Image job queued but the model did not return educational content. The job is available in image history.'); + if (completed.toolCalls?.length || !String(completed.content || '').trim()) { + // The job exists; only the words are missing. Recorded with the job id so + // the picture can be found rather than paid for and lost. + throw refuse(502, 'Image job queued but the model did not return educational content. The job is available in image history.', + { jobId: job.jobId, toolCalls: (completed.toolCalls || []).length, chars: String(completed.content || '').length }); + } } return { ...completed, imageJobs: [job], imageToolHandled: true }; } diff --git a/src/utils/logger.js b/src/utils/logger.js index 0710e31c..bc2c29b1 100644 --- a/src/utils/logger.js +++ b/src/utils/logger.js @@ -122,27 +122,9 @@ var logger = { pushToLoki(accessLabels, accessMsg); }, - file: function(level, message, data) { - try { - var now = new Date(); - var date = now.toISOString().split('T')[0]; - var logFile = path.join(LOG_DIR, date + '.log'); - // Defensive redaction: route both message and optional data through - // redact() so PHI patterns (SSN, phone, email, DoB) and note-body - // heuristics can't leak to the daily log file if a caller accidentally - // passes a request body, clinical string, or stack trace containing - // transcript text. - var safeMessage = redact(String(message == null ? '' : message)); - var line = '[' + now.toISOString() + '] [' + level.toUpperCase() + '] ' + safeMessage; - if (data != null) { - var raw = typeof data === 'string' ? data : JSON.stringify(data); - line += ' | ' + redact(raw); - } - line += '\n'; - fs.appendFileSync(logFile, line); - if (level === 'error') console.error(line.trim()); - } catch (e) {} - }, + // Delegated, so there is one implementation of where a line goes and how it + // is redacted. See fileLog.js for why it is not defined here. + file: function(level, message, data) { require('./fileLog').write(level, message, data); }, info: function(msg, data) { this.file('info', msg, data); }, warn: function(msg, data) { this.file('warn', msg, data); }, diff --git a/src/utils/resourceImages.js b/src/utils/resourceImages.js index 29794fd3..f98d3a2a 100644 --- a/src/utils/resourceImages.js +++ b/src/utils/resourceImages.js @@ -109,8 +109,14 @@ async function dispatch(ai, opts) { if (!input) { failures.push('an illustration request could not be read'); continue; } try { // A key per figure, so two figures in one reply are two jobs rather than - // the second being returned as a replay of the first. - var key = ('res:' + images.requestKey(opts.body) + ':' + i).slice(0, 160); + // the second being returned as a replay of the first — and keyed on the + // figure itself, not on its position in the reply. Position collided + // across two generations from the same form: identical body hash plus + // identical index returned the earlier job, so the second document showed + // the first one's artwork. Same reason as deckBuild. + var drawing = require('crypto').createHash('sha256') + .update(JSON.stringify(input)).digest('hex').slice(0, 24); + var key = ('res:' + images.requestKey(opts.body) + ':' + drawing).slice(0, 160); jobs.push(await queue.enqueue(opts.owner, 'my_resources', input, key, true, context, opts.imageModel)); } catch (err) { failures.push(err && err.message ? err.message : 'an illustration could not be queued'); diff --git a/test/image-key-collision.test.js b/test/image-key-collision.test.js new file mode 100644 index 00000000..46a52d03 --- /dev/null +++ b/test/image-key-collision.test.js @@ -0,0 +1,71 @@ +// Two generations from the same form used to collide: the image key was the +// request-body hash plus the figure's *position*, and the unique constraint on +// (owner, workflow, key) then handed back the first generation's job. The second +// deck showed the first deck's picture — and since the decks are not the same +// length, on a slide about something else. +const test = require('node:test'); +const assert = require('node:assert/strict'); + +const deckBuild = require('../src/utils/deckBuild'); +const resourceImages = require('../src/utils/resourceImages'); + +const deckSchema = require('../src/utils/deckSchema'); + +// opts.images is the job queue, not the generatedImages module. +function recorder() { + const keys = []; + return { + keys, + images: { enqueue: async (owner, workflow, input, key) => { keys.push(key); return { jobId: 'job-' + keys.length, status: 'pending' }; } } + }; +} + +function deckOf(prompts) { + return deckSchema.normalise({ + slides: prompts.map((p, i) => ({ type: 'figure', heading: 'Slide ' + i, bullets: ['a'], image_prompt: p })) + }); +} + +test('the same form twice, with different figures, makes different jobs', async () => { + const a = recorder(); + await deckBuild.drawFigures(deckOf(['a neuron diagram', 'a rash photograph']), + { owner: 1, body: { topic: 'x' }, subject: 'x', imageModel: 'm', images: a.images }); + + const b = recorder(); + await deckBuild.drawFigures(deckOf(['a completely different airway diagram', 'a bilirubin chart']), + { owner: 1, body: { topic: 'x' }, subject: 'x', imageModel: 'm', images: b.images }); + + assert.equal(a.keys.length, 2); + assert.equal(b.keys.length, 2); + for (const key of b.keys) { + assert.ok(!a.keys.includes(key), + 'a second generation must not reuse the first generation\'s key: ' + key); + } +}); + +test('the identical figure requested again does dedupe, so a resubmit is not billed twice', async () => { + const a = recorder(); + const opts = { owner: 1, body: { topic: 'x' }, subject: 'x', imageModel: 'm', images: a.images }; + await deckBuild.drawFigures(deckOf(['a neuron diagram']), opts); + + const b = recorder(); + await deckBuild.drawFigures(deckOf(['a neuron diagram']), + { ...opts, images: b.images }); + + assert.deepEqual(a.keys, b.keys, 'same request, same drawing, same key'); +}); + +test('two figures in one deck are still two jobs', async () => { + const a = recorder(); + await deckBuild.drawFigures(deckOf(['diagram one', 'diagram two']), + { owner: 1, body: { topic: 'x' }, subject: 'x', imageModel: 'm', images: a.images }); + + assert.equal(a.keys.length, 2); + assert.notEqual(a.keys[0], a.keys[1]); +}); + +test('the key no longer contains the slide index, which is what collided', async () => { + const src = require('fs').readFileSync(require('path').join(__dirname, '..', 'src/utils/deckBuild.js'), 'utf8'); + assert.doesNotMatch(src, /requestKey\(opts\.body\) \+ ':' \+ request\.index/); + assert.match(src, /Keyed on what is being drawn, not on where it sits/); +}); diff --git a/test/my-resources.test.js b/test/my-resources.test.js index c18610e6..2f9f0994 100644 --- a/test/my-resources.test.js +++ b/test/my-resources.test.js @@ -203,8 +203,11 @@ test('the author can ask for the illustration, not only leave it to the model', assert.match(lib, /function requestedCount\(text\)/); assert.match(lib, /var MAX_IMAGES = 6;/, 'bounded, because each figure is a paid request'); assert.match(lib, /jobs\.length < MAX_IMAGES/); - assert.match(lib, /'res:' \+ images\.requestKey\(opts\.body\) \+ ':' \+ i/, - 'a key per figure, or the second is returned as a replay of the first'); + // A key per figure, or the second is returned as a replay of the first — and + // keyed on the figure rather than on its index, or two generations from the + // same form collide with each other. See image-key-collision.test.js. + assert.match(lib, /'res:' \+ images\.requestKey\(opts\.body\) \+ ':' \+ drawing/); + assert.match(lib, /createHash\('sha256'\)\s*\n?\s*\.update\(JSON\.stringify\(input\)\)/); assert.match(route, /resourceImages\.guidance\(opts\.refinement\)/, 'generate'); assert.match(route, /resourceImages\.guidance\(instructions\)/, 'and modify'); // A figure that cannot be queued is said out loud; fewer pictures than asked