fix: a second deck reused the first deck's pictures

The image job key was the request-body hash plus the figure's position — slide
index for a deck, reply index for a document. Two generations from the same form
produce the same body hash, so figure 4 of the second generation collided with
figure 4 of the first on the unique (owner, workflow, idempotency_key). The
constraint handed back the existing job, and the new deck displayed the old
deck's artwork. The decks are not even the same length, so the reused picture
could land on a slide about something else entirely.

Keyed on what is being drawn now: the body hash stays, so submitting the
identical request twice still dedupes rather than billing twice, and a hash of
the prompt (plus layout and shape) is what makes two different pictures two
different jobs. Same fix in deckBuild and resourceImages.

Also split fileLog out of logger. logger requires the database at module load,
so importing it to record a diagnostic pulls in a connection pool — wrong on its
own terms, and it hung the whole test suite when imageTool started logging its
refusals: a unit test that never touches a database inherited an open pool
handle and never exited. logger.file now delegates to fileLog, so there is still
one implementation of where a line goes and how it is redacted.

With that in place, every image-tool refusal is recorded durably. There are five
of them, they want five different fixes, and until now none of them left any
trace once the container was replaced.

Verified against a mutation: restoring the index-based key fails two of the four
collision tests.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Dv6sqaY6Vq3ChZHMem3cnU

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;
 }

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,

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);

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 };

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 };
 }

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); },

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');

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/);
+});

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