OmniRoute/tests/unit/chatcore-attempt-logging.test.ts

// tests/unit/chatcore-attempt-logging.test.ts
// Characterization of persistAttemptLogs — the per-attempt call-log persistence extracted from
// handleChatCore (chatCore god-file decomposition, #3501). Uses a real temp DB and polls the
// persisted row (saveCallLog is async + fire-and-forget). Locks: the field mapping, the
// cacheSource semantic/upstream normalization, final credentials.connectionId attribution,
// credentials fallback, and error persistence.
import { test, before, after } from "node:test";
import assert from "node:assert/strict";
import fs from "node:fs";
import os from "node:os";
import path from "node:path";

const testDataDir = fs.mkdtempSync(path.join(os.tmpdir(), "omni-attempt-logging-test-"));
process.env.DATA_DIR = testDataDir;

const coreDb = await import("../../src/lib/db/core.ts");
const { getCallLogById } = await import("../../src/lib/usage/callLogs.ts");
const { persistAttemptLogs } = await import("../../open-sse/handlers/chatCore/attemptLogging.ts");
const { getAuditLog } = await import("../../src/lib/compliance/index.ts");

type CodexRotationEnvelope = {
  _omniroute?: {
    codexAccountRotation?: {
      initialConnectionId: unknown;
      finalConnectionId: unknown;
    };
  };
};

function baseCtx(overrides: Record<string, unknown> = {}) {
  // #13481: traceId defaults to pendingRequestId so existing tests (which poll
  // by pendingRequestId) continue to work. Combo tests set both explicitly.
  const pendingRequestId = (overrides.pendingRequestId as string) ?? "REPLACE";
  return {
    traceId: overrides.traceId ?? pendingRequestId,
    provider: "openai",
    connectionId: "conn-1",
    model: "gpt-x",
    skillRequestId: "skill-1",
    detailedLoggingEnabled: false,
    reqLogger: null,
    pendingRequestId: "REPLACE",
    clientRawRequest: { endpoint: "/v1/chat/completions" },
    requestedModel: "gpt-x-requested",
    credentials: { connectionId: "cred-conn" },
    startTime: Date.now(),
    body: { messages: [{ role: "user", content: "hi" }] },
    sourceFormat: "openai",
    targetFormat: "openai",
    comboName: null,
    comboStepId: null,
    comboExecutionKey: null,
    tokensCompressed: 0,
    apiKeyInfo: { id: "key-1", name: "Key One" },
    noLogEnabled: false,
    ...overrides,
  } as Parameters<typeof persistAttemptLogs>[1];
}

async function pollForCallLog(id: string, tries = 120) {
  for (let i = 0; i < tries; i++) {
    const row = await getCallLogById(id);
    if (row) return row as Record<string, unknown>;
    await new Promise((r) => setTimeout(r, 20));
  }
  return null;
}

function getCodexAccountRotation(value: unknown) {
  if (!value || typeof value !== "object") return undefined;
  return (value as CodexRotationEnvelope)._omniroute?.codexAccountRotation;
}

before(async () => {
  await coreDb.ensureDbInitialized();
});

after(() => {
  coreDb.resetDbInstance();
  fs.rmSync(testDataDir, { recursive: true, force: true, maxRetries: 5, retryDelay: 100 });
});

test("persists a call log row with the mapped fields (default cacheSource=upstream)", async () => {
  const id = "attempt-basic-1";
  persistAttemptLogs(
    { status: 200, tokens: { input: 1, output: 2 } },
    baseCtx({ pendingRequestId: id, credentials: { connectionId: "conn-1" } })
  );
  const row = await pollForCallLog(id);
  assert.ok(row, "call log row should be persisted");
  assert.equal(row.status, 200);
  assert.equal(row.model, "gpt-x");
  assert.equal(row.provider, "openai");
  assert.equal(row.requestedModel, "gpt-x-requested");
  assert.equal(row.connectionId, "conn-1");
  assert.equal(row.cacheSource, "upstream");
});

test("uses final credentials connectionId when Codex failover rotates the account", async () => {
  const id = "attempt-codex-rotation-1";
  persistAttemptLogs(
    { status: 200, tokens: { input: 1, output: 2 }, responseBody: { id: "response-1" } },
    baseCtx({
      pendingRequestId: id,
      provider: "codex",
      connectionId: "initial-conn",
      credentials: { connectionId: "final-conn" },
    })
  );

  const row = await pollForCallLog(id);
  assert.ok(row);
  assert.equal(row.connectionId, "final-conn");
  assert.deepEqual(getCodexAccountRotation(row.requestBody), {
    initialConnectionId: "initial-conn",
    finalConnectionId: "final-conn",
  });
  assert.deepEqual(getCodexAccountRotation(row.responseBody), {
    initialConnectionId: "initial-conn",
    finalConnectionId: "final-conn",
  });
});

test("cacheSource 'semantic' is preserved", async () => {
  const id = "attempt-semantic-1";
  persistAttemptLogs({ status: 200, cacheSource: "semantic" }, baseCtx({ pendingRequestId: id }));
  const row = await pollForCallLog(id);
  assert.ok(row);
  assert.equal(row.cacheSource, "semantic");
});

test("connectionId falls back to credentials.connectionId when null, and error is persisted", async () => {
  const id = "attempt-fallback-1";
  persistAttemptLogs(
    { status: 502, error: "upstream boom" },
    baseCtx({ pendingRequestId: id, connectionId: null })
  );
  const row = await pollForCallLog(id);
  assert.ok(row);
  assert.equal(row.connectionId, "cred-conn");
  assert.equal(row.status, 502);
  assert.match(String(row.error ?? ""), /upstream boom/);
});

function duplicateHeartbeatBody() {
  return {
    choices: [
      {
        message: {
          tool_calls: [
            { function: { name: "heartbeat_respond", arguments: "{}" } },
            { function: { name: "heartbeat_respond", arguments: "{}" } },
          ],
        },
      },
    ],
  };
}

test("duplicate tool_calls in the assembled body writes provider.spec_violation audit", () => {
  persistAttemptLogs(
    { status: 200, responseBody: duplicateHeartbeatBody() },
    baseCtx({ pendingRequestId: "attempt-spec-violation-1", skillRequestId: "skill-spec-1" })
  );
  // logAuditEvent is synchronous; do not wait on the fire-and-forget saveCallLog.
  const rows = getAuditLog({ action: "provider.spec_violation", requestId: "skill-spec-1" });
  assert.equal(rows.length, 1);
  assert.equal(rows[0]?.resourceType, "provider_spec_violation");
  const details = rows[0]?.details;
  assert.ok(details && typeof details === "object");
  assert.equal(
    (details as { violation?: string }).violation,
    'duplicate tool_calls entry for "heartbeat_respond"'
  );
});

test("unique tool_calls do not write provider.spec_violation audit", () => {
  persistAttemptLogs(
    {
      status: 200,
      responseBody: {
        choices: [
          {
            message: {
              tool_calls: [
                { function: { name: "heartbeat_respond", arguments: "{}" } },
                { function: { name: "other_tool", arguments: "{}" } },
              ],
            },
          },
        ],
      },
    },
    baseCtx({ pendingRequestId: "attempt-spec-clean-1", skillRequestId: "skill-spec-clean-1" })
  );
  const rows = getAuditLog({
    action: "provider.spec_violation",
    requestId: "skill-spec-clean-1",
  });
  assert.equal(rows.length, 0);
});

// #13481: Combo attempts must use traceId as the log id, not pendingRequestId.
// When a combo fails over, each attempt has a unique traceId but shares the
// same pendingRequestId. Using pendingRequestId as the log id caused a UNIQUE
// constraint violation — only the first (failed) attempt was logged.
test("combo attempt uses traceId as the log id, not pendingRequestId", async () => {
  const traceId = "combo-trace-attempt-2";
  const pendingRequestId = "combo-shared-request-id";
  persistAttemptLogs(
    { status: 200, tokens: { input: 10, output: 20 } },
    baseCtx({
      traceId,
      pendingRequestId,
      comboName: "my-combo",
      comboStepId: "my-combo-model-2",
    })
  );
  const row = await pollForCallLog(traceId);
  assert.ok(row, "call log row should be persisted with traceId as id");
  assert.equal(row.status, 200);
  assert.equal(row.comboStepId, "my-combo-model-2");

  // A second attempt with the same pendingRequestId but different traceId
  const traceId2 = "combo-trace-attempt-3";
  persistAttemptLogs(
    { status: 200, tokens: { input: 30, output: 40 } },
    baseCtx({
      traceId: traceId2,
      pendingRequestId,
      comboName: "my-combo",
      comboStepId: "my-combo-model-3",
    })
  );
  const row2 = await pollForCallLog(traceId2);
  assert.ok(row2, "second combo attempt should also be persisted");
  assert.equal(row2.comboStepId, "my-combo-model-3");
});