diff --git a/.gitignore b/.gitignore index db2b8a28..1b6be523 100644 --- a/.gitignore +++ b/.gitignore @@ -8,6 +8,9 @@ node_modules /service-logs/**/* /tool-call-server-logs/**/* /.build-lambda-microvm/ +/api/.build/ +/trees/ +/docs/project/_local/ # Helm artifacts helm/*/charts/*.tgz diff --git a/api/openapi.yaml b/api/openapi.yaml index e4c04c14..765ed452 100644 --- a/api/openapi.yaml +++ b/api/openapi.yaml @@ -1,12 +1,17 @@ -openapi: 3.0.0 +openapi: 3.0.3 info: - title: Code Execution API - version: 1.0.0 + title: CodeAPI Internal Sandbox Runner API + version: 2.0.0 + description: >- + Internal service-to-sandbox contract. This API is not a public client + surface. The public authenticated contract is service/openapi.yml. +x-internal: true paths: - /execute: + /api/v2/execute: post: - summary: Execute code + summary: Execute a prepared sandbox job + operationId: executeSandboxJob requestBody: required: true content: @@ -15,80 +20,192 @@ paths: $ref: '#/components/schemas/ExecuteRequest' responses: '200': - description: Successful execution + description: Sandbox execution result content: application/json: schema: $ref: '#/components/schemas/ExecuteResponse' '400': - description: Bad request + description: Invalid execution request + content: + application/json: + schema: + $ref: '#/components/schemas/Error' + '409': + description: Runtime session workspace conflict + content: + application/json: + schema: + $ref: '#/components/schemas/Error' + '413': + description: Request body exceeds the configured limit + content: + application/json: + schema: + $ref: '#/components/schemas/Error' '500': - description: Internal server error + description: Sandbox execution failed + content: + application/json: + schema: + $ref: '#/components/schemas/Error' components: schemas: + Error: + type: object + required: [message] + properties: + message: + type: string + code: + type: string + ExecuteRequest: type: object - required: - - language - - version - - files + required: [language, version, files] properties: session_id: type: string + description: Top-level execution session identifier. + output_session_id: + type: string + description: Storage session for generated files. language: type: string version: type: string - files: + args: type: array items: - $ref: '#/components/schemas/File' + type: string stdin: type: string - args: + files: type: array items: - type: string - compileTimeout: + $ref: '#/components/schemas/InputFile' + compile_memory_limit: + type: integer + run_memory_limit: type: integer - runTimeout: + run_timeout: type: integer - compileMemoryLimit: + compile_timeout: type: integer - runMemoryLimit: + run_cpu_time: type: integer - - File: + compile_cpu_time: + type: integer + env_vars: + type: object + additionalProperties: + type: string + egress_grant: + type: string + description: Opaque internal egress capability. + execution_manifest: + type: string + description: Signed internal execution scope. + tool_call_socket: + type: boolean + + InputFile: type: object - required: - - name - - content + required: [name] properties: - name: - type: string id: type: string + description: Storage object identifier for a by-reference input. + storage_session_id: + type: string + description: Storage session for a by-reference input. + input_cache_key: + type: string + description: Stable opaque runner-local cache identity. + name: + type: string content: type: string + description: Inline file content. encoding: type: string enum: [base64, hex, utf8] - - ExecuteResponse: + entity_id: + type: string + description: Caller authorization scope echoed on inherited outputs. + + FileRef: type: object + required: [id, name, storage_session_id] properties: - compile: - $ref: '#/components/schemas/ExecutionStage' - run: - $ref: '#/components/schemas/ExecutionStage' - + id: + type: string + name: + type: string + storage_session_id: + type: string + modified_from: + type: object + required: [id, storage_session_id] + properties: + id: + type: string + storage_session_id: + type: string + inherited: + type: boolean + enum: [true] + entity_id: + type: string + ExecutionStage: type: object + required: [stdout, stderr, output] properties: stdout: type: string stderr: type: string - exitCode: + code: type: integer + nullable: true + signal: + type: string + nullable: true + output: + type: string + memory: + type: integer + nullable: true + message: + type: string + nullable: true + status: + type: string + nullable: true + cpu_time: + type: number + nullable: true + wall_time: + type: number + nullable: true + + ExecuteResponse: + type: object + required: [language, version, session_id, files] + properties: + compile: + $ref: '#/components/schemas/ExecutionStage' + run: + $ref: '#/components/schemas/ExecutionStage' + language: + type: string + version: + type: string + session_id: + type: string + files: + type: array + items: + $ref: '#/components/schemas/FileRef' diff --git a/api/src/api/lifecycle.ts b/api/src/api/lifecycle.ts index 28977eda..00489710 100644 --- a/api/src/api/lifecycle.ts +++ b/api/src/api/lifecycle.ts @@ -1,6 +1,7 @@ import express, { Router, type Request, type Response } from 'express'; import { logger } from '../logger'; import { bindSessionWorkspace, parseSessionBinding, unbindSessionWorkspace } from '../session-workspace'; +import { operationalErrorMeta } from '../operational-log'; /** * AWS Lambda MicroVM hook endpoints. The platform POSTs to @@ -60,11 +61,11 @@ export function applyRunHook(body: unknown): MicrovmRunContext { const binding = parseSessionBinding(runHookPayload); if (binding) { bindSessionWorkspace(binding); - logger.info({ runtimeSessionId: binding.runtimeSessionId }, 'Bound persistent session workspace'); + logger.info('Bound persistent session workspace'); } } else if (runContext.microvmId != null && microvmId != null && runContext.microvmId !== microvmId) { logger.warn( - { existing: runContext.microvmId, incoming: microvmId }, + { identityConflict: true }, 'Ignoring /run hook for a different microvmId', ); } @@ -86,7 +87,7 @@ lifecycleRouter.post('/validate', ackHook('validate')); lifecycleRouter.post('/run', express.json({ limit: '32kb' }), (req: Request, res: Response) => { const context = applyRunHook(req.body); logger.info( - { hook: 'run', microvmId: context.microvmId, hasPayload: context.runHookPayload != null }, + { hook: 'run', hasIdentity: context.microvmId != null, hasPayload: context.runHookPayload != null }, 'MicroVM lifecycle hook invoked', ); return res.status(200).json({ hook: 'run', status: 'ok' }); @@ -97,7 +98,9 @@ lifecycleRouter.post('/suspend', ackHook('suspend')); lifecycleRouter.post('/terminate', (_req: Request, res: Response) => { logger.info({ hook: 'terminate' }, 'MicroVM lifecycle hook invoked'); - void unbindSessionWorkspace().catch((err) => logger.error({ err }, 'Failed to unbind session workspace on terminate')); + void unbindSessionWorkspace().catch((err) => { + logger.error(operationalErrorMeta(err), 'Failed to unbind session workspace on terminate'); + }); return res.status(200).json({ hook: 'terminate', status: 'ok' }); }); diff --git a/api/src/api/v2.ts b/api/src/api/v2.ts index b4895735..9aafce30 100644 --- a/api/src/api/v2.ts +++ b/api/src/api/v2.ts @@ -3,6 +3,7 @@ import type { Runtime } from '../runtime'; import type { TFile } from '../job'; import { getLatestRuntimeMatchingLanguageVersion, getRuntimes } from '../runtime'; import { logger } from '../logger'; +import { operationalErrorMeta } from '../operational-log'; import { config } from '../config'; import { Job, @@ -441,7 +442,7 @@ router.post('/execute', express.json({ limit: config.execute_body_limit }), asyn logger.warn({ reason: error.reason, status }, 'Rejected sandbox request by execution manifest'); return res.status(status).json({ message: error.message }); } - logger.error({ err: error }, 'Execution manifest validation failed unexpectedly'); + logger.error(operationalErrorMeta(error), 'Execution manifest validation failed unexpectedly'); return res.status(500).json({ message: 'Execution manifest validation failed' }); } } @@ -526,7 +527,7 @@ router.post('/execute', express.json({ limit: config.execute_body_limit }), asyn 'codeapi.language': job.runtime.language, }, () => job!.uploadGeneratedFiles()) .catch((err) => { - logger.error({ job: job!.uuid, err }, 'File upload failed'); + logger.error(operationalErrorMeta(err), 'File upload failed'); return new Set(); }); @@ -538,7 +539,7 @@ router.post('/execute', express.json({ limit: config.execute_body_limit }), asyn const dropped = before - result.files.length; if (dropped > 0) { logger.warn( - { job: job.uuid, dropped, kept: result.files.length }, + { dropped, kept: result.files.length }, 'Pruned files from response because upload did not reach file_server', ); } @@ -555,7 +556,10 @@ router.post('/execute', express.json({ limit: config.execute_body_limit }), asyn * means files really were primed and dirty is the honest answer. */ if (primeCompleted && job?.markSessionDirty('execution failed after input priming')) { metricsOutcome = 'execution_error'; - logger.error({ job: job.uuid, err: error }, 'Session execution left workspace state unknown'); + logger.error( + operationalErrorMeta(error), + 'Session execution left workspace state unknown', + ); return res.status(409).json({ error: 'session_workspace_dirty', message: 'Session workspace must be restored before another execute', @@ -563,7 +567,10 @@ router.post('/execute', express.json({ limit: config.execute_body_limit }), asyn } if (error instanceof SessionWorkspaceDirtyError) { metricsOutcome = 'execution_error'; - logger.error({ job: job?.uuid, err: error }, 'Session input priming left a partial workspace'); + logger.error( + operationalErrorMeta(error), + 'Session input priming left a partial workspace', + ); return res.status(409).json({ error: error.code, message: error.message, @@ -576,11 +583,14 @@ router.post('/execute', express.json({ limit: config.execute_body_limit }), asyn const safeError = classifySandboxSafeError(error); if (safeError) { metricsOutcome = 'execution_error'; - logger.error({ job: job?.uuid, err: error, safeError: safeError.body.error }, 'Sandbox setup failed'); + logger.error( + { status: safeError.status, ...operationalErrorMeta(error) }, + 'Sandbox setup failed', + ); return res.status(safeError.status).json(safeError.body); } metricsOutcome = 'execution_error'; - logger.error({ job: job?.uuid, err: error }, 'Error executing job'); + logger.error(operationalErrorMeta(error), 'Error executing job'); return res.status(500).json({ error: 'sandbox_execution_failed', message: 'Sandbox execution failed', @@ -604,7 +614,7 @@ router.get('/health', async (_req: Request, res: Response) => { try { return res.status(200).json(await checkSandboxWorkspaceHealth()); } catch (error) { - logger.error({ err: error }, 'Sandbox workspace health check failed'); + logger.error(operationalErrorMeta(error), 'Sandbox workspace health check failed'); return res.status(503).json({ status: 'unhealthy', error: 'workspace_unavailable', @@ -771,11 +781,11 @@ router.post( expectedBytes, ); await pruneInputCache(config.input_cache_max_bytes).catch((err) => { - logger.warn({ err }, 'Failed to prune session input cache'); + logger.warn(operationalErrorMeta(err), 'Failed to prune session input cache'); }); return res.status(200).json({ stored }); } catch (error) { - logger.error({ err: error }, 'Failed to store session inputs'); + logger.error(operationalErrorMeta(error), 'Failed to store session inputs'); return res.status(500).json({ message: 'session input delivery failed' }); } }, diff --git a/api/src/index.ts b/api/src/index.ts index 629436e2..4e487aa7 100644 --- a/api/src/index.ts +++ b/api/src/index.ts @@ -10,6 +10,7 @@ import { startWarmupCommand } from './warmup'; import { stopToolCallSocketProxy } from './tool-call-socket-process'; import v2Router from './api/v2'; import lifecycleRouter, { LIFECYCLE_HOOK_BASE_PATH } from './api/lifecycle'; +import { operationalErrorMeta } from './operational-log'; const app = express(); @@ -60,7 +61,7 @@ interface HttpError extends Error { statusCode?: number; } app.use((err: HttpError, _req: express.Request, res: express.Response, _next: express.NextFunction) => { - logger.error({ err }, 'Unhandled error'); + logger.error(operationalErrorMeta(err), 'Unhandled error'); const status = err.status ?? err.statusCode ?? 400; return res.status(status).json({ message: err.message || 'Bad request' }); }); @@ -73,7 +74,7 @@ async function main(): Promise { const [address, port] = config.bind_address.split(':'); const stopWorkspaceReaper = startWorkspaceReaper(); const server = app.listen(Number(port), address, () => { - logger.info({ address: config.bind_address }, 'Sandbox API started'); + logger.info('Sandbox API started'); }); let shuttingDown = false; const closeHttpServer = (): Promise => new Promise((resolve, reject) => { @@ -89,7 +90,7 @@ async function main(): Promise { ): Promise => { let timeout: ReturnType | undefined; const closePromise = closeHttpServer().catch((err) => { - logger.warn({ err }, 'Sandbox HTTP server close failed'); + logger.warn(operationalErrorMeta(err), 'Sandbox HTTP server close failed'); }); const timeoutPromise = new Promise((resolve) => { timeout = setTimeout(() => { @@ -112,12 +113,12 @@ async function main(): Promise { stopWorkspaceReaper(); await closeHttpServerWithTimeout(); await stopToolCallSocketProxy().catch((err) => { - logger.warn({ err }, 'Tool-call socket proxy shutdown failed'); + logger.warn(operationalErrorMeta(err), 'Tool-call socket proxy shutdown failed'); }); try { await shutdownTelemetry(); } catch (err) { - logger.warn({ err }, 'OpenTelemetry shutdown failed'); + logger.warn(operationalErrorMeta(err), 'OpenTelemetry shutdown failed'); } process.exit(0); }; @@ -127,6 +128,6 @@ async function main(): Promise { } main().catch((err) => { - logger.error({ err }, 'Sandbox API startup failed'); + logger.error(operationalErrorMeta(err), 'Sandbox API startup failed'); process.exit(1); }); diff --git a/api/src/job.ts b/api/src/job.ts index eceffdfd..64636401 100644 --- a/api/src/job.ts +++ b/api/src/job.ts @@ -42,6 +42,7 @@ import { isValidFilePath, } from './validation'; import { cachedInputResponse, inputCacheKey, openCachedInput } from './session-inputs'; +import { operationalErrorMeta } from './operational-log'; export { DIRKEEP, @@ -740,7 +741,7 @@ export class Job { this.session = opts.session ?? undefined; this.uuid = opts.session_id ?? nanoid(); this.outputSessionId = opts.output_session_id ?? this.uuid; - this.log = rootLogger.child({ job: this.uuid }); + this.log = rootLogger; this.runtime = opts.runtime; this.files = opts.files.map((file, i) => ({ id: file.id, @@ -952,11 +953,9 @@ export class Job { if (!this.isSynthetic) { this.log.info( { - submissionDir: this.submissionDir, - workspaceId: this.workspaceLease.workspaceId, - uid: this.jobIdentity.uid, - gid: this.jobIdentity.gid, - session: this.session ? this.session.runtimeSessionId : undefined, + fileCount: this.files.length, + persistentSession: this.session != null, + perJobUid: this.jobIdentity.perJobUid, }, 'Priming job', ); @@ -1177,7 +1176,7 @@ export class Job { if (!Array.isArray(data)) return []; return data.filter(isNormalizedObjectForSession(sid)); } catch (err) { - this.log.warn({ sessionId: sid, err }, 'Failed to auto-load .dirkeep markers'); + this.log.warn(operationalErrorMeta(err), 'Failed to auto-load .dirkeep markers'); return []; } finally { clearTimeout(timeout); @@ -1199,14 +1198,14 @@ export class Job { if (existingNames.has(obj.name)) return false; if (!isValidFilePath(obj.name, this.submissionDir)) { this.log.warn( - { sessionId: obj.storage_session_id, name: obj.name }, + { invalidPath: true }, 'autoLoadDirkeep: rejected marker with invalid or traversing path', ); return false; } if (markerConflictsWithExplicitFile(obj.name, explicitFilePaths)) { this.log.debug( - { sessionId: obj.storage_session_id, name: obj.name }, + { destinationConflict: true }, 'autoLoadDirkeep: skipping marker that conflicts with explicit request file', ); return false; @@ -1250,7 +1249,7 @@ export class Job { if (response.status === 404 && attempt < maxRetries) { await response.body?.cancel().catch(() => {}); const delay = retryDelay * Math.pow(2, attempt - 1); - this.log.info({ fileId: file.id, attempt, maxRetries, delay }, 'File not found, retrying'); + this.log.info({ attempt, maxRetries, delay }, 'File not found, retrying'); await sleep(delay, operation.signal); continue; } @@ -1311,7 +1310,7 @@ export class Job { * the file lives under originalName on disk. */ if (originalName !== file.name) file.name = originalName; - this.log.info({ file: originalName, hash: hash.substring(0, 8) }, 'Downloaded file'); + this.log.info('Downloaded file'); return originalName; } catch (error: unknown) { if (response?.body && !response.bodyUsed) { @@ -1332,13 +1331,19 @@ export class Job { lastError = error instanceof Error ? error : new Error(String(error)); if (attempt < maxRetries) { const delay = retryDelay * Math.pow(2, attempt - 1); - this.log.warn({ fileId: file.id, attempt, maxRetries, delay, err: lastError }, 'Download failed, retrying'); + this.log.warn( + { attempt, maxRetries, delay, ...operationalErrorMeta(lastError) }, + 'Download failed, retrying', + ); await sleep(delay, operation.signal); } } } - this.log.error({ fileId: file.id, maxRetries, err: lastError }, 'Failed to download file'); + this.log.error( + { maxRetries, ...operationalErrorMeta(lastError) }, + 'Failed to download file', + ); try { await fsp.unlink(tempPath); } catch { /* may not exist */ } throw lastError ?? new Error(`Failed to download input ${file.id}`); } @@ -1363,7 +1368,7 @@ export class Job { throwIfAborted(signal); } if (cached) { - this.log.debug({ fileId: file.id }, 'Priming input from pushed cache'); + this.log.debug('Priming input from pushed cache'); return cachedInputResponse(cached); } if (!this.fileEgressBaseUrl()) { @@ -1529,7 +1534,10 @@ export class Job { async execute(): Promise { if (!this.isSynthetic) { - this.log.info({ runtime: this.runtime.language, version: this.runtime.version.raw }, 'Executing'); + this.log.info( + { runtimeClass: this.runtime.language === 'python' ? 'python' : 'other' }, + 'Executing', + ); } const codeFiles = this.files.filter( @@ -1596,7 +1604,7 @@ export class Job { try { await this.walkDir(this.submissionDir, 0, inputByName); } catch (error) { - this.log.error({ err: error }, 'Error scanning submission directory'); + this.log.error(operationalErrorMeta(error), 'Error scanning submission directory'); } /* Generated files get priority in sessionFiles; fill remaining slots up @@ -1630,7 +1638,7 @@ export class Job { isDir = st.isDirectory(); isRegularFile = st.isFile(); } catch (err) { - this.log.debug({ path: relativePath, err }, 'walkDir: failed to lstat entry'); + this.log.debug(operationalErrorMeta(err), 'walkDir: failed to lstat entry'); return 'skip'; } } @@ -1703,7 +1711,10 @@ export class Job { await fsp.access(keepFullPath); return false; } catch (err) { - this.log.debug({ keepPath, err }, 'walkDir: user .dirkeep no longer accessible'); + this.log.debug( + operationalErrorMeta(err), + 'walkDir: user .dirkeep no longer accessible', + ); return true; } } @@ -1759,7 +1770,10 @@ export class Job { const currentHash = await this.computeFileHash(keepFullPath, true); return currentHash !== keepInfo.hash; } catch (err) { - this.log.debug({ keepPath, err }, 'walkDir: failed to hash inherited .dirkeep'); + this.log.debug( + operationalErrorMeta(err), + 'walkDir: failed to hash inherited .dirkeep', + ); return false; } } @@ -1801,7 +1815,10 @@ export class Job { await fsp.writeFile(keepFullPath, '', { flag: 'wx' }); await this.applySandboxFilePermissions(keepFullPath, true); } catch (err) { - this.log.debug({ keepPath, err }, 'walkDir: failed to write .dirkeep marker'); + this.log.debug( + operationalErrorMeta(err), + 'walkDir: failed to write .dirkeep marker', + ); return { collected: false, truncated: false }; } const id = nanoid(); @@ -1911,7 +1928,7 @@ export class Job { const st = await fsp.lstat(fullPath); size = st.size; } catch (err) { - this.log.debug({ path: relativePath, err }, 'walkDir: unable to stat file'); + this.log.debug(operationalErrorMeta(err), 'walkDir: unable to stat file'); return { collected: false, truncated: false, stopLoop: false }; } if (size > this.runtime.max_file_size) { @@ -1931,7 +1948,7 @@ export class Job { try { contentHash = await this.computeFileHash(fullPath, true); } catch (err) { - this.log.debug({ path: relativePath, err }, 'walkDir: failed to hash file'); + this.log.debug(operationalErrorMeta(err), 'walkDir: failed to hash file'); } } @@ -1964,7 +1981,7 @@ export class Job { let wasModified = false; if (inputFileInfo && contentHash != null) { wasModified = contentHash !== inputFileInfo.hash; - if (wasModified) this.log.info({ file: relativePath }, 'Input file was modified'); + if (wasModified) this.log.info('Input file was modified'); } const echoed = this.tryEchoUnchangedInput({ @@ -2036,7 +2053,7 @@ export class Job { try { entries = await fsp.readdir(dir, { withFileTypes: true }); } catch (err) { - this.log.debug({ dir, err }, 'walkDir: unable to read directory'); + this.log.debug(operationalErrorMeta(err), 'walkDir: unable to read directory'); return 'skipped'; } @@ -2094,7 +2111,7 @@ export class Job { * "Generated files" pollutes the chip list and the next prime(). * `.dirkeep` is a file, not a directory, so it's unaffected. */ if (isHiddenDirectory(entry.name) && !inputsLiveUnder(inputByName, relativePath)) { - this.log.debug({ path: relativePath }, 'walkDir: skipping hidden directory'); + this.log.debug('walkDir: skipping hidden directory'); skippedHiddenDirs++; continue; } @@ -2205,19 +2222,19 @@ export class Job { try { const lstat = await fsp.lstat(file.path); if (lstat.isSymbolicLink()) { - this.log.error({ file: file.name }, 'Refusing to upload a symlink'); + this.log.error('Refusing to upload a symlink'); return null; } if (!lstat.isFile()) { - this.log.error( - { file: file.name }, - 'Refusing to upload a non-regular file', - ); + this.log.error('Refusing to upload a non-regular file'); return null; } size = lstat.size; } catch (error) { - this.log.error({ file: file.name, err: error }, 'Error stat-ing file before upload'); + this.log.error( + operationalErrorMeta(error), + 'Error stat-ing file before upload', + ); return null; } @@ -2245,7 +2262,7 @@ export class Job { uploadHandle = await fsp.open(file.path, fs.constants.O_RDONLY | fs.constants.O_NOFOLLOW); stream = uploadHandle.createReadStream(); stream.on('error', (error) => { - this.log.warn({ file: file.name, err: error }, 'Upload file stream error'); + this.log.warn(operationalErrorMeta(error), 'Upload file stream error'); }); const controller = new AbortController(); timeout = setTimeout(() => controller.abort(), 30000); @@ -2265,10 +2282,10 @@ export class Job { if (!response.ok) { throw new Error(`Upload HTTP error: ${response.status}`); } - this.log.debug({ file: file.name, id: file.id, size }, 'Uploaded file'); + this.log.debug({ bytes: size }, 'Uploaded file'); return file.id; } catch (error) { - this.log.error({ file: file.name, err: error }, 'Error uploading file'); + this.log.error(operationalErrorMeta(error), 'Error uploading file'); return null; } finally { if (timeout) clearTimeout(timeout); @@ -2312,7 +2329,7 @@ export class Job { workspaceRemoved = await cleanupSandboxWorkspace(workspaceLease); } catch (error) { workspaceRemoved = false; - this.log.error({ submissionDir: this.submissionDir, err: error }, 'Failed to clean up'); + this.log.error(operationalErrorMeta(error), 'Failed to clean up'); } finally { this.workspaceLease = undefined; this.submissionDir = ''; @@ -2325,15 +2342,9 @@ export class Job { } else { retainWorkspaceCleanupUntilRemoved(workspaceLease, () => { releaseJobIdentity(jobIdentity); - this.log.info( - { uid: jobIdentity.uid, gid: jobIdentity.gid, slot: jobIdentity.slot }, - 'Released retained sandbox job UID slot after workspace cleanup', - ); + this.log.info('Released retained sandbox job UID slot after workspace cleanup'); }); - this.log.error( - { uid: jobIdentity.uid, gid: jobIdentity.gid, slot: jobIdentity.slot }, - 'Retaining sandbox job UID slot after failed workspace cleanup', - ); + this.log.error('Retaining sandbox job UID slot after failed workspace cleanup'); } this.jobIdentity = undefined; } diff --git a/api/src/nsjail.ts b/api/src/nsjail.ts index 87a2b791..91ca4076 100644 --- a/api/src/nsjail.ts +++ b/api/src/nsjail.ts @@ -4,6 +4,7 @@ import { spawn, type ChildProcessWithoutNullStreams } from 'node:child_process'; import { nanoid } from 'nanoid'; import { config } from './config'; import { logger } from './logger'; +import { operationalErrorClass, operationalErrorMeta } from './operational-log'; import { defaultNsJailSetupGate, type NsJailSetupGate } from './nsjail-setup-gate'; import { nsjailSetupGateWatchdogFires } from './metrics'; import { SANDBOX_INSIDE_GID, SANDBOX_INSIDE_UID, type SandboxJobIdentity } from './workspace-isolation'; @@ -400,7 +401,7 @@ export async function execute(opts: ExecuteOptions, setupGate: NsJailSetupGate = const errno = err as NodeJS.ErrnoException; if (spawnError === null) spawnError = errno; logger.warn( - { logId, err: { code: errno.code, message: errno.message } }, + operationalErrorMeta(errno), 'nsjail child process error', ); childDiedSignal.abort(); @@ -420,7 +421,7 @@ export async function execute(opts: ExecuteOptions, setupGate: NsJailSetupGate = child.stdin.on('error', err => { const errno = err as NodeJS.ErrnoException; logger.warn( - { logId, err: { code: errno.code, message: errno.message } }, + operationalErrorMeta(errno), 'nsjail stdin pipe error (child likely exited mid-write)', ); }); @@ -450,7 +451,10 @@ export async function execute(opts: ExecuteOptions, setupGate: NsJailSetupGate = * log was unreadable (EACCES on a chmod race, EISDIR if the path got * replaced, EIO, ...) which is far more diagnostic than a bare timeout. */ logger.warn( - { logId, pollError: pollError && { code: pollError.code, message: pollError.message } }, + { + setupMarkerSeen: false, + pollErrorClass: pollError == null ? 'none' : operationalErrorClass(pollError), + }, 'nsjail setup gate watchdog fired before "Executing" marker', ); nsjailSetupGateWatchdogFires.inc(); @@ -558,7 +562,7 @@ export async function execute(opts: ExecuteOptions, setupGate: NsJailSetupGate = const logContent = fs.readFileSync(logPath, 'utf8'); if (exitCode === 255) { - logger.error({ logContent }, 'nsjail exit 255'); + logger.error({ exitCode, logBytes: Buffer.byteLength(logContent) }, 'nsjail exit 255'); } for (const line of logContent.split('\n')) { @@ -577,7 +581,7 @@ export async function execute(opts: ExecuteOptions, setupGate: NsJailSetupGate = } } } else if (exitCode === 255) { - logger.error({ logPath }, 'nsjail exit 255 - no log file found'); + logger.error({ exitCode, logAvailable: false }, 'nsjail exit 255 - no log file found'); } } catch { /* log file may not exist */ } finally { try { fs.unlinkSync(logPath); } catch { /* ignore */ } diff --git a/api/src/operational-log-capture.test.ts b/api/src/operational-log-capture.test.ts new file mode 100644 index 00000000..0fbd7c2e --- /dev/null +++ b/api/src/operational-log-capture.test.ts @@ -0,0 +1,60 @@ +import { createHash } from 'node:crypto'; +import { Writable } from 'node:stream'; +import { describe, expect, test } from 'bun:test'; +import pino from 'pino'; +import { operationalErrorMeta } from './operational-log'; + +const SENTINEL = 'PRIVATE_sandbox_capture_6Rw9mQ2p'; + +describe('Pino operational log capture', () => { + test('does not serialize runtime identifiers, content, or nested errors', () => { + const chunks: string[] = []; + const stream = new Writable({ + write(chunk, _encoding, callback) { + chunks.push(chunk.toString()); + callback(); + }, + }); + const captureLogger = pino({ level: 'debug' }, stream); + const error = { + name: 'Error', + message: `failed for ${SENTINEL}`, + stack: `Error: ${SENTINEL}`, + code: SENTINEL, + filename: `${SENTINEL}.csv`, + output: SENTINEL, + response: { data: SENTINEL }, + }; + + captureLogger.error( + { + status: 500, + durationMs: 12, + fileCount: 1, + bytes: 128, + ...operationalErrorMeta(error), + }, + 'Synthetic sandbox failure', + ); + captureLogger.info( + { outputBytes: SENTINEL.length, removed: 2 }, + 'Synthetic runtime cleanup', + ); + captureLogger.flush(); + + const captured = chunks.join(''); + expect(captured).toContain('Synthetic sandbox failure'); + expect(captured).toContain('durationMs'); + expect(captured).toContain('fileCount'); + expect(captured).toContain('outputBytes'); + expect(captured).toContain('unexpected'); + for (const variant of [ + SENTINEL, + encodeURIComponent(SENTINEL), + Buffer.from(SENTINEL).toString('base64'), + createHash('sha256').update(SENTINEL).digest('hex'), + ]) { + expect(captured).not.toContain(variant); + } + }); +}); diff --git a/api/src/operational-log.ts b/api/src/operational-log.ts new file mode 100644 index 00000000..01c125d4 --- /dev/null +++ b/api/src/operational-log.ts @@ -0,0 +1,46 @@ +export function operationalErrorClass(error: unknown): string { + const value = error as { name?: unknown; code?: unknown; message?: unknown } | null; + const name = typeof value?.name === 'string' ? value.name : ''; + switch (name) { + case 'AbortError': + return 'aborted'; + case 'ExecutionManifestError': + return 'manifest'; + case 'SessionCheckpointError': + return 'checkpoint'; + case 'SessionWorkspaceBindingError': + case 'SessionWorkspaceDirtyError': + return 'session_workspace'; + case 'SyntaxError': + case 'TypeError': + case 'ValidationError': + return 'invalid_state'; + } + + switch (value?.code) { + case 'ABORT_ERR': + return 'aborted'; + case 'EACCES': + case 'EPERM': + return 'permission'; + case 'ECONNREFUSED': + case 'ECONNRESET': + case 'ENETUNREACH': + case 'ENOTFOUND': + case 'EPIPE': + return 'dependency'; + case 'ENOSPC': + return 'capacity'; + case 'ETIMEDOUT': + return 'timeout'; + } + + const message = typeof value?.message === 'string' ? value.message.toLowerCase() : ''; + if (message.includes('timed out') || message.includes('timeout')) return 'timeout'; + if (message.includes('abort')) return 'aborted'; + return 'unexpected'; +} + +export function operationalErrorMeta(error: unknown): { errorClass: string } { + return { errorClass: operationalErrorClass(error) }; +} diff --git a/api/src/runtime.ts b/api/src/runtime.ts index ff790380..cfef9ff6 100644 --- a/api/src/runtime.ts +++ b/api/src/runtime.ts @@ -3,6 +3,7 @@ import * as path from 'path'; import * as semver from 'semver'; import { config } from './config'; import { logger } from './logger'; +import { operationalErrorMeta } from './operational-log'; interface RuntimeLimits { timeouts: { compile: number; run: number }; @@ -82,7 +83,7 @@ function loadEnvVars(packageDir: string): Record { export function loadPackage(packageDir: string): void { const infoPath = path.join(packageDir, 'pkg-info.json'); if (!fs.existsSync(infoPath)) { - logger.warn({ packageDir }, 'Missing pkg-info.json'); + logger.warn('Missing pkg-info.json'); return; } @@ -91,13 +92,13 @@ export function loadPackage(packageDir: string): void { try { info = JSON.parse(fs.readFileSync(infoPath, 'utf8')); } catch (err) { - logger.warn({ packageDir, err }, 'Failed to parse pkg-info.json'); + logger.warn(operationalErrorMeta(err), 'Failed to parse pkg-info.json'); return; } const { language, version, aliases, provides, limit_overrides } = info; const parsedVersion = semver.parse(version); if (!parsedVersion) { - logger.warn({ version, packageDir }, 'Failed to parse version'); + logger.warn('Failed to parse package version'); return; } @@ -154,7 +155,7 @@ const INSTALLED_MARKER = '.package-installed'; export function loadPackages(packagesDirectory: string): void { const pkgdir = packagesDirectory; if (!fs.existsSync(pkgdir)) { - logger.warn({ pkgdir }, 'Package directory does not exist'); + logger.warn('Package directory does not exist'); return; } diff --git a/api/src/session-checkpoint.ts b/api/src/session-checkpoint.ts index 8ddd7390..3ec7e703 100644 --- a/api/src/session-checkpoint.ts +++ b/api/src/session-checkpoint.ts @@ -8,6 +8,7 @@ import { pipeline } from 'stream/promises'; import { createGunzip, createGzip } from 'zlib'; import { config } from './config'; import { logger } from './logger'; +import { operationalErrorClass, operationalErrorMeta } from './operational-log'; import { SANDBOX_WORKSPACE_ROOT, SESSION_WORKSPACE_ID } from './workspace-isolation'; import type { SessionMetaSnapshot, SessionWorkspace } from './session-workspace'; import { SESSION_META_FILE, SESSION_META_MARKER, getBoundSessionWorkspace } from './session-workspace'; @@ -133,7 +134,9 @@ export async function streamSessionCheckpoint( stdio: ['ignore', 'pipe', 'pipe'], env: { ...process.env, COPYFILE_DISABLE: '1' }, }); - tar.stderr.on('data', (chunk: Buffer) => logger.debug({ tar: chunk.toString() }, 'checkpoint tar')); + tar.stderr.on('data', (chunk: Buffer) => { + logger.debug({ outputBytes: chunk.length }, 'Checkpoint archive process emitted error output'); + }); /* Register the 'close' listener BEFORE awaiting the pipeline: for a small * workspace tar can exit and emit 'close' before pipeline resolves, and a * listener attached only afterward would miss it and hang here forever. @@ -175,7 +178,7 @@ export async function streamSessionCheckpoint( throw error; } } catch (error) { - logger.error({ err: error }, 'Failed to stream session checkpoint'); + logger.error(operationalErrorMeta(error), 'Failed to stream session checkpoint'); if (!res.headersSent) res.status(500).json({ message: 'checkpoint failed' }); else res.destroy(); } finally { @@ -265,7 +268,9 @@ export async function restoreSessionCheckpoint( stdio: ['pipe', 'ignore', 'pipe'], env: { ...process.env, COPYFILE_DISABLE: '1' }, }); - tar.stderr.on('data', (chunk: Buffer) => logger.debug({ tar: chunk.toString() }, 'restore tar')); + tar.stderr.on('data', (chunk: Buffer) => { + logger.debug({ outputBytes: chunk.length }, 'Checkpoint restore process emitted error output'); + }); const closed: Promise = new Promise((resolve, reject) => { tar.on('close', resolve); tar.on('error', reject); @@ -345,12 +350,18 @@ export async function restoreSessionCheckpoint( * A socket/serialization error now causes the control plane to recycle this * VM, but must never roll the successfully restored workspace backward. */ await fsp.rm(liveBackup, { recursive: true, force: true }).catch(error => { - logger.warn({ err: error, liveBackup }, 'Failed to remove replaced checkpoint workspace'); + logger.warn( + operationalErrorMeta(error), + 'Failed to remove replaced checkpoint workspace', + ); }); res.status(200).json({ status: 'restored', dir: path.basename(dir) }); } catch (error) { if (committed) { - logger.error({ err: error }, 'Checkpoint restored but response delivery failed'); + logger.error( + operationalErrorMeta(error), + 'Checkpoint restored but response delivery failed', + ); throw error; } @@ -362,12 +373,15 @@ export async function restoreSessionCheckpoint( retainStageForRecovery = true; session.markDirty('checkpoint restore rollback failed'); logger.error( - { err: error, rollbackErr: rollbackError, recoveryPath: liveBackup }, + { + errorClass: operationalErrorClass(error), + rollbackErrorClass: operationalErrorClass(rollbackError), + }, 'Failed to roll back checkpoint workspace replacement', ); } } - logger.error({ err: error }, 'Failed to restore session checkpoint'); + logger.error(operationalErrorMeta(error), 'Failed to restore session checkpoint'); /* Extraction, validation, and ownership happen only in restoreStage. * Ordinary pre-commit failures therefore leave both the live workspace and * its matching metadata/dirty state untouched. Only an unsuccessful @@ -463,13 +477,13 @@ async function readRestoredMeta( * it in the workspace to be surfaced as a generated artifact. Rollouts * that change this marker must drain/recycle old development sessions. */ logger.warn( - { marker: (parsed as { marker: string }).marker, expected: SESSION_META_MARKER }, + { metadataVersion: 'incompatible' }, 'Ignoring incompatible session checkpoint metadata', ); await fsp.rm(metaPath, { force: true }).catch(() => {}); } } catch (error) { - logger.debug({ err: error }, 'No session meta sidecar to restore'); + logger.debug(operationalErrorMeta(error), 'No session meta sidecar to restore'); } return empty; } diff --git a/api/src/session-inputs.ts b/api/src/session-inputs.ts index 0f1b7f3a..ee796c0a 100644 --- a/api/src/session-inputs.ts +++ b/api/src/session-inputs.ts @@ -230,7 +230,7 @@ export async function openCachedInput( } const meta = raw === null ? null : parseCachedInputMeta(raw); if (!meta) { - logger.warn({ key }, 'Ignoring session input with missing or invalid metadata'); + logger.warn('Ignoring session input with missing or invalid metadata'); await handle.close(); return null; } diff --git a/api/src/session-workspace.ts b/api/src/session-workspace.ts index 3f2105bc..d8a79113 100644 --- a/api/src/session-workspace.ts +++ b/api/src/session-workspace.ts @@ -205,7 +205,7 @@ export class SessionWorkspace { markDirty(reason: string): void { this.dirty = reason; logger.error( - { runtimeSessionId: this.runtimeSessionId, reason }, + { reasonClass: operationalWorkspaceDirtyReason(reason) }, 'Session workspace marked dirty', ); } @@ -258,10 +258,7 @@ export class SessionWorkspace { this.dirty = undefined; this.lease = undefined; if (!wiped) { - logger.error( - { runtimeSessionId: this.runtimeSessionId }, - 'Session workspace wipe failed; retaining pinned UID for the quarantined directory', - ); + logger.error('Session workspace wipe failed; retaining pinned UID for the quarantined directory'); return; } if (this.identity) { @@ -288,7 +285,7 @@ export function bindSessionWorkspace(binding: SessionBinding | undefined): Sessi } if (boundSession) { logger.error( - { bound: boundSession.runtimeSessionId, requested: binding.runtimeSessionId }, + { identityConflict: true }, 'Refusing to rebind runner to a different runtime session', ); return undefined; @@ -311,3 +308,14 @@ export async function unbindSessionWorkspace(): Promise { export function resetSessionWorkspaceStateForTests(): void { boundSession = undefined; } + +function operationalWorkspaceDirtyReason(reason: string): string { + switch (reason) { + case 'checkpoint restore rollback failed': + return 'checkpoint_rollback'; + case 'execution failed after input priming': + return 'execution_after_priming'; + default: + return 'other'; + } +} diff --git a/api/src/tool-call-socket-process.ts b/api/src/tool-call-socket-process.ts index 4694c07f..b68f846f 100644 --- a/api/src/tool-call-socket-process.ts +++ b/api/src/tool-call-socket-process.ts @@ -3,6 +3,7 @@ import * as net from 'net'; import * as path from 'path'; import { logger } from './logger'; import { config } from './config'; +import { operationalErrorMeta } from './operational-log'; const START_TIMEOUT_MS = 10_000; const STOP_TIMEOUT_MS = 3_000; @@ -94,14 +95,14 @@ async function launch(): Promise { `tool-call socket proxy failed to spawn: ${error.message}`, { cause: error }, ); - logger.error({ error }, 'tool-call socket proxy spawn failed'); + logger.error(operationalErrorMeta(error), 'tool-call socket proxy spawn failed'); rejectSpawnFailure(launchError); }); started.stdout?.on('data', (chunk: Buffer) => { - logger.debug({ proxy: chunk.toString().trim() }, 'tool-call socket proxy'); + logger.debug({ outputBytes: chunk.length }, 'tool-call socket proxy emitted output'); }); started.stderr?.on('data', (chunk: Buffer) => { - logger.warn({ proxy: chunk.toString().trim() }, 'tool-call socket proxy stderr'); + logger.warn({ outputBytes: chunk.length }, 'tool-call socket proxy emitted error output'); }); started.once('exit', (code, signal) => { if (child === started) { @@ -117,10 +118,7 @@ async function launch(): Promise { waitUntilReady(started, socketPath, START_TIMEOUT_MS), spawnFailure, ]); - logger.info( - { socketPath, target: rawTarget }, - 'Tool-call socket proxy started after MicroVM restore', - ); + logger.info('Tool-call socket proxy started after MicroVM restore'); } catch (error) { started.kill('SIGKILL'); if (child === started) child = undefined; diff --git a/api/src/tool-call-socket-proxy.ts b/api/src/tool-call-socket-proxy.ts index 78e689b7..02bf7c91 100644 --- a/api/src/tool-call-socket-proxy.ts +++ b/api/src/tool-call-socket-proxy.ts @@ -501,9 +501,9 @@ export async function startToolCallSocketProxy( upstream?.destroy(new Error('tool-call upstream timeout')); }); - upstream.on('error', error => { + upstream.on('error', () => { if (rejected) return; - log.error('tool-call socket proxy upstream error', error); + log.error('tool-call socket proxy upstream error'); if (!res.headersSent) { res.writeHead(502, { 'Content-Type': 'text/plain', Connection: 'close' }); } @@ -585,7 +585,7 @@ export async function startToolCallSocketProxy( fs.chownSync(socketPath, opts.socketUid, opts.socketGid); } fs.chmodSync(socketPath, socketMode); - log.log(`tool-call socket proxy listening on ${socketPath}`); + log.log('tool-call socket proxy started'); resolve(); }; server.once('error', onError); @@ -662,8 +662,8 @@ if (require.main === module) { .then(started => { handle = started; }) - .catch(error => { - console.error('tool-call socket proxy failed to start', error); + .catch(() => { + console.error('tool-call socket proxy failed to start'); process.exit(1); }); } diff --git a/api/src/warmup.ts b/api/src/warmup.ts index 6e275cfb..4348c92c 100644 --- a/api/src/warmup.ts +++ b/api/src/warmup.ts @@ -1,5 +1,6 @@ import { spawn } from 'child_process'; import { logger } from './logger'; +import { operationalErrorMeta } from './operational-log'; export type WarmupOutcome = 'skipped' | 'completed' | 'failed' | 'timed_out'; @@ -85,9 +86,14 @@ export async function startWarmupCommand( if (settled) return; settled = true; clearTimers(); - const details = { command, code, elapsedMs: Date.now() - startedAt, err }; + const details = { + outcome, + code, + elapsedMs: Date.now() - startedAt, + ...(err == null ? {} : operationalErrorMeta(err)), + }; if (outcome === 'completed') logger.info(details, 'Sandbox warmup command finished'); - else logger.warn(details, `Sandbox warmup command ${outcome.replace('_', ' ')}`); + else logger.warn(details, 'Sandbox warmup command did not complete'); resolve(outcome); }; const failStartup = (err: unknown): void => { @@ -95,7 +101,7 @@ export async function startWarmupCommand( settled = true; clearTimers(); logger.error( - { command, elapsedMs: Date.now() - startedAt, err }, + { elapsedMs: Date.now() - startedAt, ...operationalErrorMeta(err) }, 'Sandbox warmup process group could not be reaped', ); reject(err); @@ -154,6 +160,6 @@ export async function startWarmupCommand( failStartup, ); }, boundedTimeoutMs); - logger.info({ command, timeoutMs: boundedTimeoutMs }, 'Sandbox warmup command started'); + logger.info({ timeoutMs: boundedTimeoutMs }, 'Sandbox warmup command started'); }); } diff --git a/api/src/workspace-isolation.ts b/api/src/workspace-isolation.ts index d5a0aa22..52078036 100644 --- a/api/src/workspace-isolation.ts +++ b/api/src/workspace-isolation.ts @@ -5,6 +5,7 @@ import * as path from 'path'; import type { Dirent } from 'fs'; import { config } from './config'; import { logger } from './logger'; +import { operationalErrorMeta } from './operational-log'; import { SANDBOX_DIR_MODE } from './validation'; export const SANDBOX_WORKSPACE_ROOT = '/tmp/sandbox'; @@ -404,7 +405,7 @@ export async function resetSessionWorkspace(root = SANDBOX_WORKSPACE_ROOT): Prom await fsp.rm(dir, { recursive: true, force: true }); return true; } catch (error) { - logger.error({ dir, err: error }, 'Failed to reset session workspace'); + logger.error(operationalErrorMeta(error), 'Failed to reset session workspace'); await quarantineWorkspace(dir); return false; } finally { @@ -431,7 +432,7 @@ export async function cleanupSandboxWorkspace(lease: SandboxWorkspaceLease): Pro await fsp.rm(lease.dir, { recursive: true, force: true }); return true; } catch (error) { - logger.error({ workspaceId: lease.workspaceId, dir: lease.dir, err: error }, 'Failed to remove sandbox workspace'); + logger.error(operationalErrorMeta(error), 'Failed to remove sandbox workspace'); await quarantineWorkspace(lease.dir); return false; } finally { @@ -444,7 +445,7 @@ function scheduleRetainedWorkspaceRetry(): void { retainedWorkspaceRetryTimer = setTimeout(() => { retainedWorkspaceRetryTimer = undefined; retryRetainedWorkspaceCleanups().catch(err => { - logger.error({ err }, 'Retained sandbox workspace cleanup retry failed'); + logger.error(operationalErrorMeta(err), 'Retained sandbox workspace cleanup retry failed'); }); }, RETAINED_WORKSPACE_RETRY_MS); retainedWorkspaceRetryTimer.unref?.(); @@ -480,7 +481,7 @@ export async function retryRetainedWorkspaceCleanups( removed = await cleanup(retained.lease); } catch (error) { logger.error( - { workspaceId, attempts: retained.attempts, err: error }, + { attempts: retained.attempts, ...operationalErrorMeta(error) }, 'Retained sandbox workspace cleanup failed', ); } @@ -555,7 +556,7 @@ export async function initializeSandboxWorkspaceIsolation(): Promise { await assertNsJailConfigHasNoStaticUidMaps(config.nsjail_config); await prepareWorkspaceRoot(); const removed = await reapStaleWorkspaces({ removeAll: true }); - logger.info({ root: SANDBOX_WORKSPACE_ROOT, removed }, 'Sandbox workspace isolation initialized'); + logger.info({ removed }, 'Sandbox workspace isolation initialized'); } export function startWorkspaceReaper(): () => void { @@ -568,7 +569,9 @@ export function startWorkspaceReaper(): () => void { .then(removed => { if (removed > 0) logger.info({ removed }, 'Removed stale sandbox workspaces'); }) - .catch(err => logger.error({ err }, 'Sandbox workspace reaper failed')); + .catch(err => { + logger.error(operationalErrorMeta(err), 'Sandbox workspace reaper failed'); + }); }, 300_000); interval.unref?.(); return () => clearInterval(interval); diff --git a/docker-compose.yaml b/docker-compose.yaml index ac98d917..a3a637a8 100644 --- a/docker-compose.yaml +++ b/docker-compose.yaml @@ -12,6 +12,7 @@ services: - CODEAPI_HARDENED_SANDBOX_MODE=${CODEAPI_HARDENED_SANDBOX_MODE:-true} - CODEAPI_AUTH_PROVIDER=${CODEAPI_AUTH_PROVIDER:-} - CODEAPI_ALLOW_AUTH_PROVIDER_NONE=${CODEAPI_ALLOW_AUTH_PROVIDER_NONE:-} + - CODEAPI_JWT_TRUST_ENTRIES_JSON - CODEAPI_JWT_ISSUER=${CODEAPI_JWT_ISSUER:-} - CODEAPI_JWT_AUDIENCE=${CODEAPI_JWT_AUDIENCE:-} - CODEAPI_JWT_ALLOWED_ALGS=${CODEAPI_JWT_ALLOWED_ALGS:-} diff --git a/docs/adr/0001-issuer-bound-jwt-trust.md b/docs/adr/0001-issuer-bound-jwt-trust.md new file mode 100644 index 00000000..6d741548 --- /dev/null +++ b/docs/adr/0001-issuer-bound-jwt-trust.md @@ -0,0 +1,55 @@ +# ADR 0001: Bind JWT trust policy to issuers + +Status: accepted + +Date: 2026-08-30 + +## Context + +CodeAPI previously applied one global issuer, audience, algorithm, and key set +to every accepted JWT. Adding another caller to that verifier would allow a key +or principal source intended for one issuer to be combined with another +issuer's claims unless every trust dimension moves together. + +The verifier already supports several local key-material sources and bounded +global safety settings. Replacing those mechanisms would add operational risk +without improving the trust boundary. + +## Decision + +CodeAPI accepts an optional strict `CODEAPI_JWT_TRUST_ENTRIES_JSON` table. Each +entry binds one exact issuer to non-empty accepted audiences, globally unique +key IDs, allowed algorithms, and accepted principal sources. + +The verifier uses the unverified issuer only to select a policy. It then checks +the selected policy's algorithm and key ID, verifies the signature, and enforces +the selected audience and principal source before creating a principal. + +Existing key-material loaders remain global. In modern mode, every loaded key +belongs to exactly one trust entry. Duplicate, missing, multiply assigned, and +orphan key IDs fail configuration. Clock skew, token lifetime, key-cache +lifetime, and tenant-isolation settings remain global safety controls. + +Modern and legacy policy variables are mutually exclusive. When the trust table +is absent, CodeAPI normalizes the existing issuer, audience, algorithms, and +loaded keys into one LibreChat entry accepting `librechat_jwt` and +`openid_reuse`. This preserves the current migration path and key rotation. + +## Consequences + +- Cross-issuer key, algorithm, audience, and principal-source combinations fail + closed. +- A future Klicker entry can accept only `klicker_jwt` without changing + downstream principal semantics. +- Operators must use globally unique key IDs and remove stale legacy policy + variables before enabling modern mode. +- Existing deployments continue in legacy mode until they opt into the trust + table. + +## Rejected alternatives + +- One global policy cannot express separate caller trust boundaries safely. +- Embedding key material in each trust entry duplicates existing secret and + rotation mechanisms. +- Allowing duplicate key IDs under issuer namespaces makes key selection and + operational rotation ambiguous across the global loaders. diff --git a/docs/project/2026-08-30-pr-18-codeapi-trust-contract-logging-plan.md b/docs/project/2026-08-30-pr-18-codeapi-trust-contract-logging-plan.md new file mode 100644 index 00000000..8a82ddf5 --- /dev/null +++ b/docs/project/2026-08-30-pr-18-codeapi-trust-contract-logging-plan.md @@ -0,0 +1,308 @@ +# PR 18: CodeAPI issuer trust, public contract, and values-free logging + +Status: draft pull request open + +## Goal + +Prepare the public CodeAPI repository for a future Klicker tutor integration by +binding JWT trust to issuers, publishing a truthful v1 execution and file API +contract, and removing linkable client values from operational logs. + +This package stops at a pushed, verified, review-complete draft pull request. +Image publication, deployment, cluster access, live proof, and merge remain +separate decisions. + +## Baseline and authority + +- Repository: `uzh-bf/code-interpreter` +- Worktree: `trees/codeapi-trust-contract-logging` +- Branch: `rs/codeapi-trust-contract-logging` +- Base: `origin/main` +- Pull request: [#18](https://github.com/uzh-bf/code-interpreter/pull/18) +- Planning SHA: `83c4f7b105b6b3e69eda12701ad4ec437acba08f` +- Required delivery layer: `pr_ready` +- Authorized terminal layer: `pr_ready` +- Boundary owner: current execution orchestrator +- Pause conditions: a material contract change, secret or personal-data + exposure, upstream integration requirement, or any withheld external action + +The user approved the roadmap and local execution as a goal, then separately +authorized pushing the reviewed branch and opening draft pull request +[#18](https://github.com/uzh-bf/code-interpreter/pull/18). Integration, merge, +image publication, deployment, cluster access, live proof, branch deletion, +and worktree cleanup remain withheld. + +## Research and planning review + +Source inspection used the exact planning SHA and the repository's existing +tests, OpenAPI files, runtime routes, exported types, loggers, CI workflow, and +deployment configuration checks. + +The configured Claude Opus advisor could not review this package because its +OAuth token had expired. The terminal error was `401 OAuth access token has +expired`; no fallback is represented as an Opus review. + +The required native planning review completed with `DONE`. It accepted the +issuer-bound design with these corrections: + +- trust entries use a strict, closed JSON schema; +- modern and legacy policy modes are mutually exclusive; +- loaded key IDs are unique and map bijectively to modern trust entries; +- issuer selection may inspect unverified `iss`, but every other field is + checked only under the selected policy before a principal is accepted; +- the migration helper emits an explicit LibreChat entry and does not print a + key ID. + +No unresolved product or technical decision requires another user ruling. + +## Product primitives and architectural decision + +This package extends three existing primitives: + +1. JWT trust policy changes from one global verifier policy to explicit + issuer-bound entries owned by the CodeAPI operator and consumed by + LibreChat and Klicker. +2. The CodeAPI v1 execution and file contract is corrected to describe existing + runtime behavior. This package does not add a new execution feature. +3. Operational evidence remains useful through bounded classes, statuses, + durations, counts, and byte totals while linkable client values leave logs. + +The JWT choice passes the ADR gate because it changes an external security +contract and has meaningful alternatives. Slice 1 creates +`docs/adr/0001-issuer-bound-jwt-trust.md`. No domain glossary is needed. + +## Frozen trust contract + +`CODEAPI_JWT_TRUST_ENTRIES_JSON` is a strict JSON array. Every entry contains +exactly: + +- `issuer`: one non-empty exact issuer; +- `audiences`: a non-empty unique list; +- `keyIds`: a non-empty unique list; +- `allowedAlgorithms`: a non-empty unique subset of `EdDSA`, `RS256`, and + `HS256`; +- `principalSources`: a non-empty unique subset of `librechat_jwt`, + `openid_reuse`, and `klicker_jwt`. + +Unknown fields, unknown values, duplicate values, empty values, duplicate +issuers, duplicate loaded key IDs, keys assigned to multiple entries, missing +configured keys, and orphan loaded keys fail configuration. Declared or +inferred key types must be compatible with the entry's algorithms. + +If the variable is present, even if empty, modern mode applies. Modern mode +rejects simultaneous `CODEAPI_JWT_ISSUER`, `CODEAPI_JWT_AUDIENCE`, or +`CODEAPI_JWT_ALLOWED_ALGS`. Existing key-material inputs and global clock skew, +maximum token lifetime, cache lifetime, and tenant-isolation settings remain. + +If the variable is absent, CodeAPI normalizes the current legacy issuer, +audience, allowed algorithms, and all loaded keys into one LibreChat entry that +accepts `librechat_jwt` and `openid_reuse`. Existing claims, fallback aliases, +tenant behavior, key rotation, and error taxonomy remain compatible. + +Verification decodes unverified payload data only to select an entry by exact +issuer. It then constrains algorithm and key ID, verifies the signature, and +enforces that entry's audience, principal source, and global time rules. +Unknown issuers report `wrong_issuer`; known issuers with unassigned keys report +`unknown_kid` where compatible with the current taxonomy. + +Documentation and tests may contain synthetic Klicker examples that accept +only `klicker_jwt`. No live issuer, key, credential, or production value enters +the repository. + +## Test portfolio + +| Consequential behavior | Stable evidence seam | Slice | +| --- | --- | --- | +| Cross-entry combinations fail closed | Table-driven verifier tests swap issuer, key, algorithm, audience, and source one field at a time | S1 | +| LibreChat migration remains equivalent | Existing JWT, startup, principal, session, rate-limit, and setup-script tests cover legacy and explicit modes | S1 | +| Configuration and rotation are deterministic | Malformed, coexistence, duplicate, orphan, missing-key, fingerprint, and cache-expiry tests | S1 | +| Public contract matches runtime | Parsed OpenAPI assertions plus TypeScript compile/build evidence | S2 | +| Public errors stay generic | Timeout, rate-limit, download, authorization, and upstream-failure tests | S2 | +| Logs contain no linkable values | Winston and Pino sentinel captures reject raw, hashed, encoded, nested, message, and stack representations | S3-S4 | +| Metrics and traces remain useful | Existing telemetry privacy checks and low-cardinality metric assertions | S3-S4 | +| Exact package is buildable | Full API/service tests and builds plus deployment configuration checks | S5 | + +No dependency is added solely for tests. Each new test protects an observable +security, privacy, or public-contract behavior. + +## Delegation map + +| Workstream | Owner | Dependency | Acceptance boundary | +| --- | --- | --- | --- | +| S1 issuer trust | Main session | Plan commit | Security and migration tests pass; slice reviews resolved | +| S2 public contract | One trusted executor | S1 decisions frozen; one writer at a time | Main session inspects the diff and reruns contract, type, and build checks | +| S3 service-edge logging | Main session | S2 integrated | Service sentinel captures and safe evidence assertions pass | +| S4 runtime logging | Main session | S3 safe logging seam | Remaining log inventory and dual-logger captures pass | +| S5 integration proof | Main session | S1-S4 reviewed | Exact-head full verification and final review pass | + +S1 remains in the main session because it sets the security boundary. S3 and S4 +remain there because they set the privacy boundary. S5 is critical-path +integration. S2 is bounded and decision-frozen enough for a trusted executor. + +## Slices + +### S1: Bind JWT trust by issuer + +Implement the frozen trust contract in the existing verifier and startup path. +Preserve downstream `CodeApiPrincipal` semantics. Update configuration examples, +the local setup helper, focused tests, and ADR 0001. + +Acceptance: + +- strict modern configuration and legacy normalization are both covered; +- every cross-entry issuer, key, algorithm, audience, and source mismatch fails; +- LibreChat `librechat_jwt` and `openid_reuse` behavior remains; +- key rotation and configuration fingerprint behavior remain deterministic; +- the setup helper emits an explicit LibreChat entry without printing key IDs; +- service-focused tests and build pass. + +Commit: `fix(auth): bind JWT trust by issuer` + +After commit, run one simplifier and one security/architecture slice reviewer on +the immutable plan-to-S1 range. Apply only verified findings and rerun affected +checks. + +### S2: Make the public contract truthful + +Keep the flat v1 execution result as the public exported contract. Rename or +move the wrapped execution type so it is clearly an internal sandbox transport. +Correct `service/openapi.yml` for actual v1 execution, upload, batch upload, +file-reference, listing, metadata, deletion, download, rate-limit, timeout, and +safe-error behavior. Keep `api/openapi.yaml` explicitly internal and aligned +with `/api/v2/execute`. Replace the download route's raw internal error detail +with a generic response. + +Acceptance: + +- parsed OpenAPI assertions cover the listed public operations and responses; +- the public execution response is flat and the legacy wrapper is not exported + as the public response; +- the internal sandbox route is not advertised as public v1; +- 429 headers and body, 504 timeout, and generic errors match runtime behavior; +- focused tests and API/service builds pass. + +Commit: `fix(api): align the public CodeAPI contract` + +After commit, run one simplifier and one public-contract slice reviewer. + +### S3: Remove client values from service-edge logs + +Use the smallest shared safe-classification helpers needed by auth, +request-error, rate-limit, public router, file authorization, programmatic +router, and replay paths. Emit static event names, normalized route classes, +stable reason/status, durations, counts, and bytes. Remove raw paths, client +request IDs, identities, sessions and keys, filenames and object names, code and +outputs, response bodies, hashes, and arbitrary errors. + +Acceptance: + +- synthetic auth, execution, upload, download, rate-limit, request-error, and + programmatic sentinels do not appear raw, encoded, hashed, nested, or in error + messages and stacks; +- useful low-cardinality reason, status, count, duration, and byte fields remain; +- existing service behavior, metrics, and telemetry privacy tests pass. + +Commit: `fix(logging): remove client values from service logs` + +After commit, run one simplifier and one privacy/security slice reviewer. + +### S4: Sanitize internal and sandbox logs + +Audit remaining operational logger and console calls in `service/src/**` and +`api/src/**`, including file server, workers, tool-call server, egress, runtime +sessions, checkpoints, workspace/input handling, sandbox routes, and jobs. Keep +returned stdout, stderr, files, and execution behavior unchanged. + +Acceptance: + +- Winston and Pino captures reject identifier, filename, code/output, + response-body, and error-stack sentinels in every remaining path; +- bounded class, status, duration, count, and byte evidence remains; +- telemetry and metrics stay low-cardinality; +- full focused logging tests and package builds pass. + +Commit: `fix(logging): sanitize runtime and sandbox logs` + +After commit, run one simplifier and one privacy/security slice reviewer. + +### S5: Prove the exact local head + +Run the repository's complete API and service installs, tests, and builds on the +same exact commit. Run the existing deployment configuration shell checks. +Update this Progress section with command outcomes and the exact SHA, then run a +final reviewer over the complete base-to-head range. + +No repository mutation follows a clean final review. One bounded correction +pass may address verified material findings, followed by affected verification +and review. + +## Scope exclusions + +- Klicker implementation, token minting, production configuration, and live + issuer or key values; +- remote JWKS retrieval, a new key provider, per-entry tenant or TTL policy, or + a new dependency; +- relabelling internal `/api/v2/execute` as public v1; +- telemetry redesign, execution-output redaction, storage redesign, or a + rate-limit behavior change; +- upstream merge or rebase, image publication, deployment, cluster access, live + proof, merge, branch deletion, or worktree cleanup. + +## Progress + +- 2026-08-30: Roadmap W1 selected and exact public CodeAPI baseline pinned at + `83c4f7b105b6b3e69eda12701ad4ec437acba08f`. +- 2026-08-30: Source inventory completed for auth, API contracts, logging, and + CI verification seams. +- 2026-08-30: Claude Opus advisor unavailable because its OAuth token expired; + no Opus review claimed. +- 2026-08-30: Mandatory native planner returned `DONE` and its fail-closed + corrections were incorporated. +- 2026-08-30: User approval is recorded for local execution through + `local_review_complete`; external delivery remains withheld. +- 2026-08-30: S1 committed at `d5f1ea0` with a follow-up test simplification at + `e860e58`; focused trust, migration, startup, and build checks passed, and + the required simplifier and security/architecture review were resolved. +- 2026-08-30: S2 committed at `ce11d7f` with a follow-up contract-test + simplification at `8eba719`; parsed OpenAPI, type, focused behavior, and + package build checks passed, and the required simplifier and public-contract + review were resolved. +- 2026-08-30: S3 committed at `7d0546f`; service-edge Winston captures and + focused auth, request, router, programmatic, rate-limit, and telemetry checks + passed. The privacy/security reviewer found no issue. Two simplifier ideas + targeted unrelated pre-existing CI and router structure and were rejected as + outside the logging slice. +- 2026-08-30: S4 completed a source-wide operational-log and telemetry audit. + Pino and Winston sentinel captures, the complete API suite, the + repository-defined service suite (`569` tests), and both package builds + passed. Existing Rollup export, circular-dependency, and two TS2352 warnings + remain unchanged. +- 2026-08-30: S4 committed at + `0be1654b052bcceaea9e4b585a502dbdbd50ec9e`. Its required simplifier and + privacy/security reviewer both returned `DONE`; neither found a material + correction. +- 2026-08-30: S5 exact-source verification used `0be1654`. `bun ci` reported + no dependency changes in either package. API tests and build passed; the + repository-defined service tests passed `569/569`, and the service build + passed with the unchanged warnings above. Both + `tests/block_root_package_delivery.sh` and + `tests/sandbox_runner_healthcheck.sh` passed. +- 2026-08-30: A diagnostic bare `bun test` in `service/` is not the + repository-defined suite: it also discovers the k6 stress script and fails + because Bun cannot resolve `k6/http`. This result is not represented as a + service-suite pass or failure; `bun run test` is the configured CI command. +- 2026-08-30: The integrated final reviewer covered correctness, plan + compliance, maintainability, security, and architecture across + `83c4f7b..0be1654` and returned `DONE` with no findings. +- 2026-08-30: Draft pull request + [#18](https://github.com/uzh-bf/code-interpreter/pull/18) opened for the + reviewed package; this metadata-only rename records its identifier. +- Current slice: delivery complete through the draft PR boundary. +- Required delivery layer: `pr_ready`. +- Achieved delivery layer: `pr_ready` through draft pull request + [#18](https://github.com/uzh-bf/code-interpreter/pull/18); source review and + verification remain anchored at `0be1654`, with later commits limited to + plan metadata. +- Delivery status: exact-head GitHub checks remain the merge blocker. + Integration, merge, image publication, deployment, cluster access, and live + proof remain withheld. diff --git a/helm/codeapi/README.md b/helm/codeapi/README.md index 9c9d0f1d..1773bac1 100644 --- a/helm/codeapi/README.md +++ b/helm/codeapi/README.md @@ -109,17 +109,29 @@ api: extraEnv: - name: CODEAPI_AUTH_PROVIDER value: librechat-jwt + - name: CODEAPI_JWT_TRUST_ENTRIES_JSON + value: '[{"issuer":"librechat","audiences":["codeapi"],"keyIds":["librechat-2026"],"allowedAlgorithms":["EdDSA"],"principalSources":["librechat_jwt","openid_reuse"]}]' - name: CODEAPI_JWT_PUBLIC_KEY # single PEM/base64-DER verifier key valueFrom: secretKeyRef: name: codeapi-jwt-verifier key: public-key - name: CODEAPI_JWT_KID - value: my-key-id + value: librechat-2026 ``` `CODEAPI_JWT_PUBLIC_KEYS_DIR` (a mounted directory of PEM files) and `CODEAPI_JWT_JWKS_JSON` (inline JWKS) are also supported for key rotation. +Each modern trust entry binds one exact issuer to accepted audiences, key IDs, +algorithms, and principal sources. Key IDs must be globally unique across +entries, and every loaded key must belong to exactly one entry. A Klicker entry +uses only `klicker_jwt` as its principal source. + +When `CODEAPI_JWT_TRUST_ENTRIES_JSON` is absent, the verifier preserves the +legacy single-LibreChat behavior from `CODEAPI_JWT_ISSUER`, +`CODEAPI_JWT_AUDIENCE`, and `CODEAPI_JWT_ALLOWED_ALGS`. Do not set those three +legacy variables together with the modern trust table. An empty or malformed +trust table fails startup. For development only, `LOCAL_MODE=true` bypasses authentication — see `values-local.yaml`. diff --git a/scripts/setup-local-auth-env.js b/scripts/setup-local-auth-env.js index 5459a4ed..46f8ccca 100644 --- a/scripts/setup-local-auth-env.js +++ b/scripts/setup-local-auth-env.js @@ -110,6 +110,17 @@ function updateEnvText(text, updates) { return next; } +function removeEnvKeys(text, keys) { + const removals = new Set(keys); + return text + .split(/\r?\n/) + .filter((line) => { + const match = /^\s*(?:export\s+)?([A-Za-z_][A-Za-z0-9_]*)=/.exec(line); + return !match || !removals.has(match[1]); + }) + .join('\n'); +} + function writeEnvFile(filePath, text) { fs.mkdirSync(path.dirname(filePath), { recursive: true }); fs.writeFileSync(filePath, text); @@ -267,9 +278,15 @@ function main() { const codeApiUpdates = { LOCAL_MODE: 'false', CODEAPI_AUTH_PROVIDER: args.provider, - CODEAPI_JWT_ISSUER: issuer, - CODEAPI_JWT_AUDIENCE: audience, - CODEAPI_JWT_ALLOWED_ALGS: signing.alg, + CODEAPI_JWT_TRUST_ENTRIES_JSON: JSON.stringify([ + { + issuer, + audiences: [audience], + keyIds: [signing.kid], + allowedAlgorithms: [signing.alg], + principalSources: ['librechat_jwt', 'openid_reuse'], + }, + ]), CODEAPI_JWT_CLOCK_SKEW_SECONDS: '30', CODEAPI_JWT_MAX_TTL_SECONDS: '300', CODEAPI_JWT_KEY_CACHE_TTL_SECONDS: '30', @@ -285,13 +302,19 @@ function main() { ); writeEnvFile( codeApiEnvPath, - updateEnvText(codeApiFile.text, codeApiUpdates), + updateEnvText( + removeEnvKeys(codeApiFile.text, [ + 'CODEAPI_JWT_ISSUER', + 'CODEAPI_JWT_AUDIENCE', + 'CODEAPI_JWT_ALLOWED_ALGS', + ]), + codeApiUpdates, + ), ); console.log(`Updated LibreChat env: ${librechatEnvPath}`); console.log(`Updated CodeAPI env: ${codeApiEnvPath}`); console.log(`Provider: ${args.provider}`); - console.log(`kid: ${signing.kid}`); if (signing.generated) { console.log('Generated a new local Ed25519 signing key for LibreChat.'); } diff --git a/service/openapi.yml b/service/openapi.yml index 913e7809..60f2a18b 100644 --- a/service/openapi.yml +++ b/service/openapi.yml @@ -1,14 +1,14 @@ -openapi: '3.0.0' +openapi: 3.0.3 info: - title: LibreChat Code Interpreter API - version: '1.0.0' + title: CodeAPI Public Service API + version: 1.0.0 description: >- - API for sandbox code execution and file management. Trusted callers should - assert the intended deployment with X-CodeAPI-Expected-Profile on every - request; responses advertise the actual profile. + Public authenticated API for sandboxed code execution and file management. + This contract describes the service gateway mounted at /v1. It does not + describe the internal sandbox-runner API. servers: - url: https://api.librechat.ai/v1 - description: LibreChat API server + description: Public CodeAPI service security: - BearerAuth: [] @@ -27,10 +27,22 @@ components: required: false description: >- Trusted routing assertion. A mismatched endpoint returns HTTP 409 - before any work is enqueued. Optional only for backwards compatibility. + before work is enqueued. Optional for backwards compatibility. schema: type: string enum: [default, stateful] + SessionId: + name: session_id + in: path + required: true + schema: + type: string + FileId: + name: fileId + in: path + required: true + schema: + type: string headers: ExecutionProfile: @@ -38,19 +50,45 @@ components: schema: type: string enum: [default, stateful] + RetryAfter: + description: Seconds until the caller should retry. + schema: + type: integer + minimum: 1 + RateLimitLimit: + description: Request limit for the current window. + schema: + type: integer + minimum: 1 + RateLimitRemaining: + description: Requests remaining in the current window. + schema: + type: integer + minimum: 0 + RateLimitReset: + description: Seconds until the current rate-limit window resets. + schema: + type: integer + minimum: 1 responses: BadRequest: - description: Invalid request or invalid expected execution profile + description: Invalid request or expected execution profile headers: X-CodeAPI-Execution-Profile: $ref: '#/components/headers/ExecutionProfile' content: application/json: schema: - anyOf: + oneOf: - $ref: '#/components/schemas/Error' - $ref: '#/components/schemas/ExecutionProfileError' + Unauthorized: + description: Missing or invalid authentication + content: + application/json: + schema: + $ref: '#/components/schemas/Error' Conflict: description: Request conflict or execution-profile mismatch headers: @@ -59,84 +97,119 @@ components: content: application/json: schema: - anyOf: + oneOf: - $ref: '#/components/schemas/Error' - $ref: '#/components/schemas/ExecutionProfileError' + GenericRateLimited: + description: Request rate limit exceeded + headers: + Retry-After: + $ref: '#/components/headers/RetryAfter' + RateLimit-Limit: + $ref: '#/components/headers/RateLimitLimit' + RateLimit-Remaining: + $ref: '#/components/headers/RateLimitRemaining' + RateLimit-Reset: + $ref: '#/components/headers/RateLimitReset' + content: + application/json: + schema: + $ref: '#/components/schemas/Error' + ExecutionRateLimited: + description: Execution request rate limit exceeded + headers: + Retry-After: + $ref: '#/components/headers/RetryAfter' + RateLimit-Limit: + $ref: '#/components/headers/RateLimitLimit' + RateLimit-Remaining: + $ref: '#/components/headers/RateLimitRemaining' + RateLimit-Reset: + $ref: '#/components/headers/RateLimitReset' + content: + application/json: + schema: + $ref: '#/components/schemas/RateLimitError' + InternalError: + description: Internal server error without backend details + content: + application/json: + schema: + $ref: '#/components/schemas/Error' schemas: - FileRef: + Error: type: object + required: [error] properties: - id: + error: type: string - name: + message: type: string - path: + details: type: string - - RequestFile: + description: Optional fixed public guidance, never an internal error payload. + PublicExecutionError: type: object + required: [error, message] properties: - id: + error: type: string - session_id: + message: type: string - name: + RateLimitError: + type: object + required: [error, message, retry_after_seconds] + properties: + error: type: string - required: - - id - - session_id - - name - - ExecuteResponse: + enum: [rate_limited] + message: + type: string + retry_after_seconds: + type: integer + minimum: 1 + ExecutionProfileError: type: object + required: [error, message, actual_profile] properties: - run: - type: object - properties: - stdout: - type: string - stderr: - type: string - code: - type: integer - nullable: true - signal: - type: string - nullable: true - output: - type: string - memory: - type: integer - nullable: true - message: - type: string - nullable: true - status: - type: string - nullable: true - cpu_time: - type: number - nullable: true - wall_time: - type: number - nullable: true - language: + error: type: string - version: + enum: [invalid_execution_profile, execution_profile_mismatch] + message: type: string - session_id: + expected_profile: type: string - files: - type: array - items: - $ref: '#/components/schemas/FileRef' + actual_profile: + type: string + enum: [default, stateful] - RequestBody: + RequestFile: type: object - required: - - code - - lang + additionalProperties: false + required: [id, resource_id, storage_session_id, name, kind] + properties: + id: + type: string + description: Storage object identifier. + resource_id: + type: string + description: Owner resource identifier used for authorization. + storage_session_id: + type: string + description: Storage session containing the object. + name: + type: string + kind: + type: string + enum: [skill, agent, user] + version: + type: integer + description: Required for skill resources and forbidden for other kinds. + ExecuteRequest: + type: object + additionalProperties: false + required: [code, lang] properties: code: type: string @@ -148,8 +221,8 @@ components: type: string user_id: type: string - entity_id: - type: string + deprecated: true + description: Legacy caller metadata. Authentication determines identity. files: type: array items: @@ -160,78 +233,233 @@ components: pattern: '^[A-Za-z0-9._:-]+$' description: >- Stable opaque hint for stateful runtime reuse. The server binds it - to the authenticated tenant and user. Required in strict runtime - session mode and ignored by the default stateless profile. + to authenticated identity. It is ignored by the stateless profile. - FileObject: + FileRef: type: object + required: [id, name] properties: - name: - type: string id: type: string - session_id: + name: type: string - content: + storage_session_id: type: string - size: - type: number - lastModified: - type: string - etag: + path: type: string - metadata: + modified_from: type: object + required: [id, storage_session_id] properties: - content-type: + id: type: string - original-filename: + storage_session_id: type: string - contentType: + inherited: + type: boolean + enum: [true] + ExecuteResponse: + type: object + required: [session_id, stdout, stderr, files] + properties: + session_id: + type: string + stdout: + type: string + stderr: + type: string + files: + type: array + items: + $ref: '#/components/schemas/FileRef' + code: + type: integer + nullable: true + signal: type: string + nullable: true + message: + type: string + nullable: true + status: + type: string + nullable: true + wall_time: + type: number + nullable: true + UploadRequest: + type: object + required: [kind, id, files] + properties: + kind: + type: string + enum: [skill, agent, user] + id: + type: string + version: + type: integer + read_only: + type: boolean + files: + type: array + items: + type: string + format: binary + UploadResult: + type: object + required: [filename, fileId] + properties: + filename: + type: string + fileId: + type: string UploadResponse: type: object + required: [message, storage_session_id, files] properties: message: type: string - session_id: + enum: [success] + storage_session_id: type: string files: type: array items: - $ref: '#/components/schemas/FileObject' - - Error: + $ref: '#/components/schemas/UploadResult' + BatchUploadFileSuccess: type: object + required: [status, filename, fileId] properties: - error: + status: type: string - details: + enum: [success] + filename: + type: string + fileId: + type: string + BatchUploadFileError: + type: object + required: [status, filename, error] + properties: + status: + type: string + enum: [error] + filename: type: string + error: + type: string + BatchUploadResponse: + type: object + required: [message, storage_session_id, files, succeeded, failed] + properties: message: type: string + enum: [success, partial_success, error] + storage_session_id: + type: string + files: + type: array + items: + oneOf: + - $ref: '#/components/schemas/BatchUploadFileSuccess' + - $ref: '#/components/schemas/BatchUploadFileError' + succeeded: + type: integer + minimum: 0 + failed: + type: integer + minimum: 0 + filesLimitReached: + type: boolean + maxFiles: + type: integer + minimum: 1 - ExecutionProfileError: + SummaryFileObject: type: object - required: [error, message, actual_profile] properties: - error: + name: type: string - enum: [invalid_execution_profile, execution_profile_mismatch] + size: + type: number + lastModified: + type: string + format: date-time + etag: + type: string + FullFileObject: + allOf: + - $ref: '#/components/schemas/SummaryFileObject' + - type: object + properties: + metadata: + type: object + additionalProperties: true + versionId: + type: string + nullable: true + contentType: + type: string + NormalizedFileObject: + type: object + required: [id, name, storage_session_id, size, contentType, lastModified] + properties: + id: + type: string + name: + type: string + storage_session_id: + type: string + size: + type: number + contentType: + type: string + lastModified: + type: string + format: date-time + read_only: + type: boolean + FileListItem: + oneOf: + - type: string + - $ref: '#/components/schemas/SummaryFileObject' + - $ref: '#/components/schemas/FullFileObject' + - $ref: '#/components/schemas/NormalizedFileObject' + ObjectMetadata: + type: object + required: [name, originalFilename, size, lastModified, etag, contentType, readOnly] + properties: + name: + type: string + originalFilename: + type: string + size: + type: number + lastModified: + type: string + format: date-time + etag: + type: string + contentType: + type: string + readOnly: + type: boolean + DeleteResponse: + type: object + required: [message, session_id, fileId] + properties: message: type: string - expected_profile: + session_id: type: string - actual_profile: + fileId: type: string - enum: [default, stateful] paths: /exec: post: summary: Execute code - description: Execute code with specified language and parameters operationId: executeCode parameters: - $ref: '#/components/parameters/ExpectedExecutionProfile' @@ -240,7 +468,7 @@ paths: content: application/json: schema: - $ref: '#/components/schemas/RequestBody' + $ref: '#/components/schemas/ExecuteRequest' responses: '200': description: Successful execution @@ -251,38 +479,57 @@ paths: application/json: schema: $ref: '#/components/schemas/ExecuteResponse' - '401': - description: Unauthorized - content: - application/json: - schema: - $ref: '#/components/schemas/Error' '400': $ref: '#/components/responses/BadRequest' + '401': + $ref: '#/components/responses/Unauthorized' '409': $ref: '#/components/responses/Conflict' + '413': + description: Input files exceed the delivery limit + content: + application/json: + schema: + $ref: '#/components/schemas/PublicExecutionError' + '422': + description: One or more input files are unavailable + content: + application/json: + schema: + $ref: '#/components/schemas/PublicExecutionError' + '429': + $ref: '#/components/responses/ExecutionRateLimited' + '500': + $ref: '#/components/responses/InternalError' + '502': + description: Sandbox or input-file service failed + content: + application/json: + schema: + $ref: '#/components/schemas/PublicExecutionError' '503': - description: Service unavailable + description: Service or sandbox unavailable content: application/json: schema: - $ref: '#/components/schemas/Error' + oneOf: + - $ref: '#/components/schemas/Error' + - $ref: '#/components/schemas/PublicExecutionError' + '504': + description: Execution or input delivery timed out + content: + application/json: + schema: + $ref: '#/components/schemas/PublicExecutionError' /download/{session_id}/{fileId}: get: summary: Download a file + operationId: downloadFile parameters: - $ref: '#/components/parameters/ExpectedExecutionProfile' - - name: session_id - in: path - required: true - schema: - type: string - - name: fileId - in: path - required: true - schema: - type: string + - $ref: '#/components/parameters/SessionId' + - $ref: '#/components/parameters/FileId' responses: '200': description: File content @@ -294,20 +541,27 @@ paths: schema: type: string format: binary + '400': + $ref: '#/components/responses/BadRequest' + '401': + $ref: '#/components/responses/Unauthorized' '404': description: File not found content: application/json: schema: $ref: '#/components/schemas/Error' - '400': - $ref: '#/components/responses/BadRequest' '409': $ref: '#/components/responses/Conflict' + '429': + $ref: '#/components/responses/GenericRateLimited' + '500': + $ref: '#/components/responses/InternalError' /upload: post: summary: Upload files + operationId: uploadFiles parameters: - $ref: '#/components/parameters/ExpectedExecutionProfile' requestBody: @@ -315,15 +569,7 @@ paths: content: multipart/form-data: schema: - type: object - properties: - entity_id: - type: string - files: - type: array - items: - type: string - format: binary + $ref: '#/components/schemas/UploadRequest' responses: '200': description: Successful upload @@ -334,35 +580,85 @@ paths: application/json: schema: $ref: '#/components/schemas/UploadResponse' + '400': + $ref: '#/components/responses/BadRequest' + '401': + $ref: '#/components/responses/Unauthorized' + '409': + $ref: '#/components/responses/Conflict' '413': description: File size limit exceeded content: application/json: schema: $ref: '#/components/schemas/Error' + '429': + $ref: '#/components/responses/GenericRateLimited' + '500': + $ref: '#/components/responses/InternalError' + '504': + description: Upload timed out + content: + application/json: + schema: + $ref: '#/components/schemas/Error' + + /upload/batch: + post: + summary: Upload a bounded batch of files + operationId: uploadFilesBatch + parameters: + - $ref: '#/components/parameters/ExpectedExecutionProfile' + requestBody: + required: true + content: + multipart/form-data: + schema: + $ref: '#/components/schemas/UploadRequest' + responses: + '200': + description: Complete or partial upload success + headers: + X-CodeAPI-Execution-Profile: + $ref: '#/components/headers/ExecutionProfile' + content: + application/json: + schema: + $ref: '#/components/schemas/BatchUploadResponse' '400': - $ref: '#/components/responses/BadRequest' + description: All files failed or the request contained no files + content: + application/json: + schema: + oneOf: + - $ref: '#/components/schemas/Error' + - $ref: '#/components/schemas/BatchUploadResponse' + '401': + $ref: '#/components/responses/Unauthorized' '409': $ref: '#/components/responses/Conflict' + '429': + $ref: '#/components/responses/GenericRateLimited' + '500': + $ref: '#/components/responses/InternalError' /files/{session_id}: get: - summary: Get files information + summary: List files in a storage session + operationId: listFiles parameters: - $ref: '#/components/parameters/ExpectedExecutionProfile' - - name: session_id - in: path - required: true - schema: - type: string + - $ref: '#/components/parameters/SessionId' - name: detail in: query + required: false schema: type: string + enum: [simple, summary, full, normalized] default: simple responses: '200': - description: Files information + description: Files at the requested detail level headers: X-CodeAPI-Execution-Profile: $ref: '#/components/headers/ExecutionProfile' @@ -371,40 +667,78 @@ paths: schema: type: array items: - $ref: '#/components/schemas/FileObject' + $ref: '#/components/schemas/FileListItem' '400': $ref: '#/components/responses/BadRequest' + '401': + $ref: '#/components/responses/Unauthorized' '409': $ref: '#/components/responses/Conflict' + '429': + $ref: '#/components/responses/GenericRateLimited' + '500': + $ref: '#/components/responses/InternalError' + + /sessions/{session_id}/objects/{fileId}: + get: + summary: Read file metadata + operationId: getFileMetadata + parameters: + - $ref: '#/components/parameters/ExpectedExecutionProfile' + - $ref: '#/components/parameters/SessionId' + - $ref: '#/components/parameters/FileId' + responses: + '200': + description: File metadata + headers: + X-CodeAPI-Execution-Profile: + $ref: '#/components/headers/ExecutionProfile' + content: + application/json: + schema: + $ref: '#/components/schemas/ObjectMetadata' + '400': + $ref: '#/components/responses/BadRequest' + '401': + $ref: '#/components/responses/Unauthorized' + '404': + description: File not found + content: + application/json: + schema: + $ref: '#/components/schemas/Error' + '409': + $ref: '#/components/responses/Conflict' + '429': + $ref: '#/components/responses/GenericRateLimited' + '500': + $ref: '#/components/responses/InternalError' /files/{session_id}/{fileId}: delete: summary: Delete a file + operationId: deleteFile parameters: - $ref: '#/components/parameters/ExpectedExecutionProfile' - - name: session_id - in: path - required: true - schema: - type: string - - name: fileId - in: path - required: true - schema: - type: string + - $ref: '#/components/parameters/SessionId' + - $ref: '#/components/parameters/FileId' responses: '200': - description: File deleted successfully + description: File deleted headers: X-CodeAPI-Execution-Profile: $ref: '#/components/headers/ExecutionProfile' - '500': - description: Error deleting file content: application/json: schema: - $ref: '#/components/schemas/Error' + $ref: '#/components/schemas/DeleteResponse' '400': $ref: '#/components/responses/BadRequest' + '401': + $ref: '#/components/responses/Unauthorized' '409': $ref: '#/components/responses/Conflict' + '429': + $ref: '#/components/responses/GenericRateLimited' + '500': + $ref: '#/components/responses/InternalError' diff --git a/service/src/api-server.ts b/service/src/api-server.ts index 78689826..ffec024d 100644 --- a/service/src/api-server.ts +++ b/service/src/api-server.ts @@ -25,6 +25,7 @@ import { executionProfileMiddleware } from './middleware/execution-profile'; import { traceHttpRequest } from './telemetry'; import { env } from './config'; import logger from './logger'; +import { operationalErrorMeta } from './operational-log'; const { LOCAL_MODE: isLocalMode } = env; @@ -46,7 +47,7 @@ app.get('/v1/health', async (_, res) => { await connection.ping(); res.sendStatus(200); } catch (error) { - logger.error('Health check failed:', error); + logger.error('Health check failed', operationalErrorMeta(error)); res.sendStatus(503); } }); @@ -69,10 +70,10 @@ process.on('SIGINT', gracefulShutdown); process.on('SIGUSR2', gracefulShutdown); process.on('uncaughtException', async (error) => { - logger.error('Uncaught Exception', error); + logger.error('Uncaught exception', operationalErrorMeta(error)); await gracefulShutdown(); }); process.on('unhandledRejection', (reason) => { - logger.error('Unhandled Rejection', reason); + logger.error('Unhandled rejection', operationalErrorMeta(reason)); }); diff --git a/service/src/auth/librechat-jwt.test.ts b/service/src/auth/librechat-jwt.test.ts index 2030b2e7..024d0919 100644 --- a/service/src/auth/librechat-jwt.test.ts +++ b/service/src/auth/librechat-jwt.test.ts @@ -3,13 +3,14 @@ import { generateKeyPairSync, sign as cryptoSign } from 'crypto'; import { mkdtempSync, rmSync, symlinkSync, writeFileSync } from 'fs'; import { tmpdir } from 'os'; import { join } from 'path'; -import type { KeyObject } from 'crypto'; +import type { JsonWebKey, KeyObject } from 'crypto'; import { CodeApiJwtAuthError, verifyLibreChatJwt } from './librechat-jwt'; const ENV_KEYS = [ 'CODEAPI_JWT_ISSUER', 'CODEAPI_JWT_AUDIENCE', 'CODEAPI_JWT_ALLOWED_ALGS', + 'CODEAPI_JWT_TRUST_ENTRIES_JSON', 'CODEAPI_JWT_CLOCK_SKEW_SECONDS', 'CODEAPI_JWT_MAX_TTL_SECONDS', 'CODEAPI_JWT_KEY_CACHE_TTL_SECONDS', @@ -52,6 +53,7 @@ type JwtClaims = { const originalEnv = new Map(); let privateKey: KeyObject; +let publicJwk: JsonWebKey; function base64Url(value: Buffer | string): string { return Buffer.from(value).toString('base64url'); @@ -111,6 +113,24 @@ function expectJwtReason(token: string, reason: string): void { } } +function setModernTrustEntries(entries: unknown[]): void { + delete process.env.CODEAPI_JWT_ISSUER; + delete process.env.CODEAPI_JWT_AUDIENCE; + delete process.env.CODEAPI_JWT_ALLOWED_ALGS; + process.env.CODEAPI_JWT_TRUST_ENTRIES_JSON = JSON.stringify(entries); +} + +function trustEntry(overrides: Record = {}): Record { + return { + issuer: 'librechat', + audiences: ['codeapi'], + keyIds: ['test-kid'], + allowedAlgorithms: ['EdDSA'], + principalSources: ['librechat_jwt', 'openid_reuse'], + ...overrides, + }; +} + beforeEach(() => { if (originalEnv.size === 0) { for (const key of ENV_KEYS) { @@ -120,7 +140,7 @@ beforeEach(() => { const { publicKey, privateKey: generatedPrivateKey } = generateKeyPairSync('ed25519'); privateKey = generatedPrivateKey; - const jwk = publicKey.export({ format: 'jwk' }); + publicJwk = publicKey.export({ format: 'jwk' }); process.env.CODEAPI_JWT_ISSUER = 'librechat'; process.env.CODEAPI_JWT_AUDIENCE = 'codeapi'; @@ -129,8 +149,9 @@ beforeEach(() => { process.env.CODEAPI_JWT_MAX_TTL_SECONDS = '300'; process.env.CODEAPI_JWT_KEY_CACHE_TTL_SECONDS = '30'; process.env.CODEAPI_JWT_JWKS_JSON = JSON.stringify({ - keys: [{ ...jwk, kid: 'test-kid', alg: 'EdDSA' }], + keys: [{ ...publicJwk, kid: 'test-kid', alg: 'EdDSA' }], }); + delete process.env.CODEAPI_JWT_TRUST_ENTRIES_JSON; delete process.env.CODEAPI_JWT_PUBLIC_KEYS_DIR; delete process.env.CODEAPI_JWT_PUBLIC_KEY; delete process.env.CODEAPI_JWT_KID; @@ -217,6 +238,109 @@ describe('LibreChat JWT auth provider', () => { expect(principal.tenantId).toBe('tenant_abc'); }); + test('binds issuer, key, audience, algorithm, and principal source in modern mode', () => { + const klicker = generateKeyPairSync('ed25519'); + const klickerJwk = klicker.publicKey.export({ format: 'jwk' }); + process.env.CODEAPI_JWT_JWKS_JSON = JSON.stringify({ + keys: [ + { ...publicJwk, kid: 'test-kid', alg: 'EdDSA' }, + { ...klickerJwk, kid: 'klicker-kid', alg: 'EdDSA' }, + ], + }); + setModernTrustEntries([ + trustEntry(), + trustEntry({ + issuer: 'klicker', + audiences: ['klicker-codeapi'], + keyIds: ['klicker-kid'], + principalSources: ['klicker_jwt'], + }), + ]); + + expect(verifyLibreChatJwt(signJwt(baseClaims())).principalSource).toBe('openid_reuse'); + const klickerClaims = baseClaims({ + iss: 'klicker', + aud: 'klicker-codeapi', + principal_source: 'klicker_jwt', + }); + expect( + verifyLibreChatJwt( + signJwt(klickerClaims, { kid: 'klicker-kid' }, klicker.privateKey), + ).principalSource, + ).toBe('klicker_jwt'); + + expectJwtReason(signJwt(klickerClaims), 'unknown_kid'); + expectJwtReason( + signJwt({ ...klickerClaims, principal_source: 'openid_reuse' }, { kid: 'klicker-kid' }, klicker.privateKey), + 'malformed_claims', + ); + expectJwtReason( + signJwt({ ...klickerClaims, aud: 'codeapi' }, { kid: 'klicker-kid' }, klicker.privateKey), + 'wrong_audience', + ); + expectJwtReason( + signJwt(baseClaims(), { kid: 'klicker-kid' }, klicker.privateKey), + 'unknown_kid', + ); + }); + + test('rejects malformed, ambiguous, and incomplete modern trust configuration', () => { + const valid = trustEntry(); + const invalidEntries: unknown[][] = [ + [], + [{ ...valid, unknown: true }], + [{ ...valid, audiences: ['codeapi', 'codeapi'] }], + [{ ...valid, allowedAlgorithms: ['ES256'] }], + [{ ...valid, principalSources: ['api_key'] }], + [valid, { ...valid }], + [{ ...valid, keyIds: ['missing-kid'] }], + [{ ...valid, allowedAlgorithms: ['RS256'] }], + ]; + + for (const entries of invalidEntries) { + setModernTrustEntries(entries); + expectJwtReason(signJwt(baseClaims()), 'config'); + } + + setModernTrustEntries([valid]); + process.env.CODEAPI_JWT_ISSUER = 'stale-issuer'; + expectJwtReason(signJwt(baseClaims()), 'config'); + + delete process.env.CODEAPI_JWT_ISSUER; + process.env.CODEAPI_JWT_PUBLIC_KEY = JSON.stringify(publicJwk); + process.env.CODEAPI_JWT_KID = 'test-kid'; + expectJwtReason(signJwt(baseClaims()), 'config'); + }); + + test('rejects orphan and cross-entry key assignments in modern mode', () => { + const second = generateKeyPairSync('ed25519'); + const secondJwk = second.publicKey.export({ format: 'jwk' }); + process.env.CODEAPI_JWT_JWKS_JSON = JSON.stringify({ + keys: [ + { ...publicJwk, kid: 'test-kid', alg: 'EdDSA' }, + { ...secondJwk, kid: 'second-kid', alg: 'EdDSA' }, + ], + }); + + setModernTrustEntries([trustEntry()]); + expectJwtReason(signJwt(baseClaims()), 'config'); + + setModernTrustEntries([ + trustEntry(), + trustEntry({ issuer: 'second', keyIds: ['test-kid'] }), + ]); + expectJwtReason(signJwt(baseClaims()), 'config'); + }); + + test('reloads modern trust metadata immediately when its fingerprint changes', () => { + setModernTrustEntries([trustEntry()]); + const token = signJwt(baseClaims()); + expect(verifyLibreChatJwt(token).principalSource).toBe('openid_reuse'); + + setModernTrustEntries([trustEntry({ principalSources: ['librechat_jwt'] })]); + expectJwtReason(token, 'malformed_claims'); + }); + test('defaults missing tenant_id to the single-tenant namespace outside strict mode', () => { const principal = verifyLibreChatJwt(signJwt(baseClaims({ tenant_id: undefined }))); diff --git a/service/src/auth/librechat-jwt.ts b/service/src/auth/librechat-jwt.ts index 1e7e8079..f07add48 100644 --- a/service/src/auth/librechat-jwt.ts +++ b/service/src/auth/librechat-jwt.ts @@ -12,7 +12,7 @@ import type { AuthProvider } from './provider'; import type { CodeApiPrincipal } from './principal'; type JwtAlg = 'EdDSA' | 'RS256' | 'HS256'; -type LibreChatPrincipalSource = 'librechat_jwt' | 'openid_reuse'; +type JwtPrincipalSource = 'librechat_jwt' | 'openid_reuse' | 'klicker_jwt'; interface JwtHeader { alg?: string; @@ -46,10 +46,16 @@ interface PublicKeyEntry { key: KeyObject | Buffer; } -interface VerificationConfig { +interface JwtTrustEntry { issuer: string; - audience: string; + audiences: Set; + keyIds: Set; allowedAlgs: Set; + principalSources: Set; +} + +interface VerificationConfig { + trustEntries: Map; clockSkewSeconds: number; maxTokenLifetimeSeconds: number; keys: Map; @@ -72,9 +78,18 @@ const MAX_KEY_CACHE_TTL_SECONDS = 300; const DEFAULT_MAX_TOKEN_LIFETIME_SECONDS = 300; const MAX_TOKEN_LIFETIME_SECONDS = 300; const DEFAULT_SINGLE_TENANT_ID = 'legacy'; -const TRUSTED_PRINCIPAL_SOURCES = new Set([ +const SUPPORTED_ALGORITHMS = new Set(['EdDSA', 'RS256', 'HS256']); +const SUPPORTED_PRINCIPAL_SOURCES = new Set([ 'librechat_jwt', 'openid_reuse', + 'klicker_jwt', +]); +const TRUST_ENTRY_FIELDS = new Set([ + 'issuer', + 'audiences', + 'keyIds', + 'allowedAlgorithms', + 'principalSources', ]); function base64UrlDecode(value: string): Buffer { @@ -120,6 +135,36 @@ function parseAllowedAlgs(): Set { return allowed; } +function assertUniqueStrings(value: unknown, name: string): string[] { + if (!Array.isArray(value) || value.length === 0) { + throw new CodeApiJwtAuthError('config', `${name} must be a non-empty array`); + } + const result: string[] = []; + const seen = new Set(); + for (const item of value) { + if (typeof item !== 'string' || item.trim() === '') { + throw new CodeApiJwtAuthError('config', `${name} must contain non-empty strings`); + } + if (item !== item.trim()) { + throw new CodeApiJwtAuthError('config', `${name} values must not contain surrounding whitespace`); + } + if (seen.has(item)) { + throw new CodeApiJwtAuthError('config', `${name} must not contain duplicate values`); + } + seen.add(item); + result.push(item); + } + return result; +} + +function assertNoUnknownFields(value: Record, name: string): void { + for (const field of Object.keys(value)) { + if (!TRUST_ENTRY_FIELDS.has(field)) { + throw new CodeApiJwtAuthError('config', `${name} contains unknown field ${field}`); + } + } +} + function parseClockSkew(): number { const parsed = Number(process.env.CODEAPI_JWT_CLOCK_SKEW_SECONDS); if (!Number.isFinite(parsed) || parsed < 0) { @@ -148,6 +193,17 @@ function publicKeyFromValue(value: string): KeyObject { } } +function addKey( + keys: Map, + kid: string, + entry: PublicKeyEntry, +): void { + if (keys.has(kid)) { + throw new CodeApiJwtAuthError('config', `Duplicate CodeAPI JWT key ID: ${kid}`); + } + keys.set(kid, entry); +} + function loadJwks(keys: Map, raw: string): void { let parsed: { keys?: Array }; try { @@ -163,7 +219,7 @@ function loadJwks(keys: Map, raw: string): void { continue; } try { - keys.set(jwk.kid, { + addKey(keys, jwk.kid, { alg: jwk.alg === 'EdDSA' || jwk.alg === 'RS256' ? jwk.alg : undefined, key: createPublicKey({ key: jwk, format: 'jwk' }), }); @@ -187,7 +243,7 @@ function loadPublicKeyDir(keys: Map, dir: string): void if (!kid) { continue; } - keys.set(kid, { key: publicKeyFromValue(readFileSync(fullPath, 'utf8')) }); + addKey(keys, kid, { key: publicKeyFromValue(readFileSync(fullPath, 'utf8')) }); } } catch (error) { if (error instanceof CodeApiJwtAuthError) { @@ -215,13 +271,13 @@ function loadKeys(): Map { if (!kid) { throw new CodeApiJwtAuthError('config', 'CODEAPI_JWT_KID is required with CODEAPI_JWT_PUBLIC_KEY'); } - keys.set(kid, { key: publicKeyFromValue(publicKey) }); + addKey(keys, kid, { key: publicKeyFromValue(publicKey) }); } const hsSecret = process.env.CODEAPI_JWT_HS256_SECRET; if (hsSecret != null && hsSecret !== '') { const kid = process.env.CODEAPI_JWT_HS256_KID ?? process.env.CODEAPI_JWT_KID ?? 'hs256-dev'; - keys.set(kid, { alg: 'HS256', key: Buffer.from(hsSecret) }); + addKey(keys, kid, { alg: 'HS256', key: Buffer.from(hsSecret) }); } if (keys.size === 0) { @@ -230,11 +286,141 @@ function loadKeys(): Map { return keys; } +function keyAlgorithm(key: PublicKeyEntry): JwtAlg | undefined { + if (key.alg) { + return key.alg; + } + if (Buffer.isBuffer(key.key)) { + return 'HS256'; + } + if (key.key.asymmetricKeyType === 'ed25519') { + return 'EdDSA'; + } + if (key.key.asymmetricKeyType === 'rsa') { + return 'RS256'; + } + return undefined; +} + +function parseModernTrustEntries(keys: Map, raw: string): Map { + let parsed: unknown; + try { + parsed = JSON.parse(raw); + } catch { + throw new CodeApiJwtAuthError('config', 'CODEAPI_JWT_TRUST_ENTRIES_JSON is not valid JSON'); + } + if (!Array.isArray(parsed) || parsed.length === 0) { + throw new CodeApiJwtAuthError( + 'config', + 'CODEAPI_JWT_TRUST_ENTRIES_JSON must be a non-empty array', + ); + } + + for (const legacyName of [ + 'CODEAPI_JWT_ISSUER', + 'CODEAPI_JWT_AUDIENCE', + 'CODEAPI_JWT_ALLOWED_ALGS', + ]) { + if ((process.env[legacyName] ?? '').trim() !== '') { + throw new CodeApiJwtAuthError( + 'config', + `${legacyName} cannot be combined with CODEAPI_JWT_TRUST_ENTRIES_JSON`, + ); + } + } + + const entries = new Map(); + const assignedKeyIds = new Set(); + for (const [index, value] of parsed.entries()) { + if (value === null || typeof value !== 'object' || Array.isArray(value)) { + throw new CodeApiJwtAuthError('config', `JWT trust entry ${index} must be an object`); + } + const record = value as Record; + assertNoUnknownFields(record, `JWT trust entry ${index}`); + const issuer = typeof record.issuer === 'string' ? record.issuer : ''; + if (issuer === '' || issuer !== issuer.trim()) { + throw new CodeApiJwtAuthError('config', `JWT trust entry ${index} issuer is invalid`); + } + if (entries.has(issuer)) { + throw new CodeApiJwtAuthError('config', `Duplicate JWT trust issuer: ${issuer}`); + } + + const audiences = assertUniqueStrings(record.audiences, `JWT trust entry ${index} audiences`); + const keyIds = assertUniqueStrings(record.keyIds, `JWT trust entry ${index} keyIds`); + const algorithmValues = assertUniqueStrings( + record.allowedAlgorithms, + `JWT trust entry ${index} allowedAlgorithms`, + ); + const sourceValues = assertUniqueStrings( + record.principalSources, + `JWT trust entry ${index} principalSources`, + ); + if (!algorithmValues.every((value): value is JwtAlg => SUPPORTED_ALGORITHMS.has(value as JwtAlg))) { + throw new CodeApiJwtAuthError('config', `JWT trust entry ${index} has an unsupported algorithm`); + } + if (!sourceValues.every((value): value is JwtPrincipalSource => + SUPPORTED_PRINCIPAL_SOURCES.has(value as JwtPrincipalSource))) { + throw new CodeApiJwtAuthError('config', `JWT trust entry ${index} has an unsupported principal source`); + } + const allowedAlgs = new Set(algorithmValues); + for (const keyId of keyIds) { + if (assignedKeyIds.has(keyId)) { + throw new CodeApiJwtAuthError('config', `JWT key ID is assigned to multiple trust entries: ${keyId}`); + } + const key = keys.get(keyId); + if (!key) { + throw new CodeApiJwtAuthError('config', `JWT trust entry references unknown key ID: ${keyId}`); + } + const algorithm = keyAlgorithm(key); + if (!algorithm || !allowedAlgs.has(algorithm)) { + throw new CodeApiJwtAuthError( + 'config', + `JWT key ID ${keyId} is incompatible with its trust entry algorithms`, + ); + } + assignedKeyIds.add(keyId); + } + entries.set(issuer, { + issuer, + audiences: new Set(audiences), + keyIds: new Set(keyIds), + allowedAlgs, + principalSources: new Set(sourceValues), + }); + } + + for (const keyId of keys.keys()) { + if (!assignedKeyIds.has(keyId)) { + throw new CodeApiJwtAuthError('config', `CodeAPI JWT key ID is not assigned to a trust entry: ${keyId}`); + } + } + return entries; +} + +function buildTrustEntries(keys: Map): Map { + const modern = process.env.CODEAPI_JWT_TRUST_ENTRIES_JSON; + if (modern !== undefined) { + return parseModernTrustEntries(keys, modern); + } + const issuer = process.env.CODEAPI_JWT_ISSUER ?? 'librechat'; + const audience = process.env.CODEAPI_JWT_AUDIENCE ?? 'codeapi'; + return new Map([ + [issuer, { + issuer, + audiences: new Set([audience]), + keyIds: new Set(keys.keys()), + allowedAlgs: parseAllowedAlgs(), + principalSources: new Set(['librechat_jwt', 'openid_reuse']), + }], + ]); +} + function rawConfigFingerprint(): string { return JSON.stringify({ issuer: process.env.CODEAPI_JWT_ISSUER, audience: process.env.CODEAPI_JWT_AUDIENCE, allowedAlgs: process.env.CODEAPI_JWT_ALLOWED_ALGS, + trustEntries: process.env.CODEAPI_JWT_TRUST_ENTRIES_JSON, skew: process.env.CODEAPI_JWT_CLOCK_SKEW_SECONDS, maxTokenLifetime: process.env.CODEAPI_JWT_MAX_TTL_SECONDS, keyCacheTtl: process.env.CODEAPI_JWT_KEY_CACHE_TTL_SECONDS, @@ -259,19 +445,18 @@ function getConfig(): VerificationConfig { DEFAULT_KEY_CACHE_TTL_SECONDS, MAX_KEY_CACHE_TTL_SECONDS, ); + const keys = loadKeys(); configCache = { rawConfig, reloadAt: now + keyCacheTtlSeconds * 1000, - issuer: process.env.CODEAPI_JWT_ISSUER ?? 'librechat', - audience: process.env.CODEAPI_JWT_AUDIENCE ?? 'codeapi', - allowedAlgs: parseAllowedAlgs(), + trustEntries: buildTrustEntries(keys), clockSkewSeconds: parseClockSkew(), maxTokenLifetimeSeconds: parseCappedSeconds( process.env.CODEAPI_JWT_MAX_TTL_SECONDS, DEFAULT_MAX_TOKEN_LIFETIME_SECONDS, MAX_TOKEN_LIFETIME_SECONDS, ), - keys: loadKeys(), + keys, }; return configCache; } @@ -311,9 +496,9 @@ function assertString(value: unknown, name: string): string { return value; } -function assertAudience(value: unknown, expected: string): void { +function assertAudience(value: unknown, accepted: Set): void { if (typeof value === 'string' && value.trim() !== '') { - if (value !== expected) { + if (!accepted.has(value)) { throw new CodeApiJwtAuthError('wrong_audience', 'JWT audience is not accepted'); } return; @@ -323,7 +508,7 @@ function assertAudience(value: unknown, expected: string): void { if (!value.every((audience) => typeof audience === 'string')) { throw new CodeApiJwtAuthError('malformed_claims', 'aud must contain only strings'); } - if (value.includes(expected)) { + if (value.some((audience) => accepted.has(audience))) { return; } throw new CodeApiJwtAuthError('wrong_audience', 'JWT audience is not accepted'); @@ -372,19 +557,19 @@ function resolveTenantIdClaim(value: unknown): string { return resolveSingleTenantId(); } -function isTrustedPrincipalSource(value: string): value is LibreChatPrincipalSource { - return TRUSTED_PRINCIPAL_SOURCES.has(value as LibreChatPrincipalSource); -} - -function assertPrincipalSource(value: unknown): LibreChatPrincipalSource { +function assertPrincipalSource(value: unknown, accepted: Set): JwtPrincipalSource { const principalSource = assertString(value, 'principal_source'); - if (isTrustedPrincipalSource(principalSource)) { - return principalSource; + if (accepted.has(principalSource as JwtPrincipalSource)) { + return principalSource as JwtPrincipalSource; } throw new CodeApiJwtAuthError('malformed_claims', 'principal_source is not accepted'); } -function validateClaims(claims: LibreChatJwtClaims, config: VerificationConfig): CodeApiPrincipal { +function validateClaims( + claims: LibreChatJwtClaims, + config: VerificationConfig, + trustEntry: JwtTrustEntry, +): CodeApiPrincipal { const now = Math.floor(Date.now() / 1000); const issuer = assertString(claims.iss, 'iss'); const userId = assertString(claims.sub, 'sub'); @@ -394,16 +579,16 @@ function validateClaims(claims: LibreChatJwtClaims, config: VerificationConfig): const nbf = assertNumericDate(claims.nbf, 'nbf'); const exp = assertNumericDate(claims.exp, 'exp'); const planId = optionalString(claims.plan_id, 'plan_id'); - const principalSource = assertPrincipalSource(claims.principal_source); + const principalSource = assertPrincipalSource(claims.principal_source, trustEntry.principalSources); const authContextHash = assertString(claims.auth_context_hash, 'auth_context_hash'); if (jti.length > 256) { throw new CodeApiJwtAuthError('malformed_claims', 'jti is too long'); } - if (issuer !== config.issuer) { + if (issuer !== trustEntry.issuer) { throw new CodeApiJwtAuthError('wrong_issuer', 'JWT issuer is not trusted'); } - assertAudience(claims.aud, config.audience); + assertAudience(claims.aud, trustEntry.audiences); if (exp <= now - config.clockSkewSeconds) { throw new CodeApiJwtAuthError('expired', 'JWT is expired'); } @@ -449,17 +634,25 @@ export function verifyLibreChatJwt(token: string): CodeApiPrincipal { const [encodedHeader, encodedPayload, encodedSignature] = parts; const header = parseJsonSegment(encodedHeader, 'JWT header'); const claims = parseJsonSegment(encodedPayload, 'JWT payload'); + const issuer = assertString(claims.iss, 'iss'); + const trustEntry = config.trustEntries.get(issuer); + if (!trustEntry) { + throw new CodeApiJwtAuthError('wrong_issuer', 'JWT issuer is not trusted'); + } const alg = header.alg; if (alg !== 'EdDSA' && alg !== 'RS256' && alg !== 'HS256') { throw new CodeApiJwtAuthError('wrong_alg', 'JWT alg is not supported'); } - if (!config.allowedAlgs.has(alg)) { + if (!trustEntry.allowedAlgs.has(alg)) { throw new CodeApiJwtAuthError('wrong_alg', 'JWT alg is not allowed'); } if (header.typ !== undefined && header.typ !== 'JWT') { throw new CodeApiJwtAuthError('malformed', 'JWT typ must be JWT'); } const kid = assertString(header.kid, 'kid'); + if (!trustEntry.keyIds.has(kid)) { + throw new CodeApiJwtAuthError('unknown_kid', 'JWT kid is not configured for issuer'); + } const key = config.keys.get(kid); if (!key) { throw new CodeApiJwtAuthError('unknown_kid', 'JWT kid is not configured'); @@ -472,7 +665,7 @@ export function verifyLibreChatJwt(token: string): CodeApiPrincipal { if (!verifySignature(alg, key, signingInput, signature)) { throw new CodeApiJwtAuthError('bad_signature', 'JWT signature is invalid'); } - return validateClaims(claims, config); + return validateClaims(claims, config, trustEntry); } export class LibreChatJwtAuthProvider implements AuthProvider { diff --git a/service/src/auth/setup-local-auth-env.test.ts b/service/src/auth/setup-local-auth-env.test.ts new file mode 100644 index 00000000..f3bed9b7 --- /dev/null +++ b/service/src/auth/setup-local-auth-env.test.ts @@ -0,0 +1,63 @@ +import { afterEach, describe, expect, test } from 'bun:test'; +import { spawnSync } from 'child_process'; +import { mkdtempSync, readFileSync, rmSync, writeFileSync } from 'fs'; +import { tmpdir } from 'os'; +import { join, resolve } from 'path'; + +const tempDirs: string[] = []; + +afterEach(() => { + for (const dir of tempDirs.splice(0)) { + rmSync(dir, { force: true, recursive: true }); + } +}); + +function envValue(text: string, name: string): string | undefined { + const line = text.split(/\r?\n/).find((candidate) => candidate.startsWith(`${name}=`)); + return line?.slice(name.length + 1); +} + +describe('setup-local-auth-env', () => { + test('writes an explicit LibreChat trust entry and removes legacy verifier policy', () => { + const dir = mkdtempSync(join(tmpdir(), 'codeapi-auth-setup-')); + tempDirs.push(dir); + const librechatEnv = join(dir, 'librechat.env'); + const codeApiEnv = join(dir, 'codeapi.env'); + writeFileSync( + librechatEnv, + 'CODEAPI_JWT_ISSUER=librechat-local\nCODEAPI_JWT_AUDIENCE=codeapi-local\n', + ); + writeFileSync( + codeApiEnv, + 'CODEAPI_JWT_ISSUER=stale\nCODEAPI_JWT_AUDIENCE=stale\nCODEAPI_JWT_ALLOWED_ALGS=HS256\n', + ); + + const script = resolve(process.cwd(), '../scripts/setup-local-auth-env.js'); + const result = spawnSync( + process.execPath, + [script, '--librechat-env', librechatEnv, '--codeapi-env', codeApiEnv], + { encoding: 'utf8' }, + ); + + expect(result.status).toBe(0); + expect(result.stderr).toBe(''); + expect(result.stdout).not.toContain('kid:'); + + const codeApiText = readFileSync(codeApiEnv, 'utf8'); + expect(envValue(codeApiText, 'CODEAPI_JWT_ISSUER')).toBeUndefined(); + expect(envValue(codeApiText, 'CODEAPI_JWT_AUDIENCE')).toBeUndefined(); + expect(envValue(codeApiText, 'CODEAPI_JWT_ALLOWED_ALGS')).toBeUndefined(); + const entries = JSON.parse( + envValue(codeApiText, 'CODEAPI_JWT_TRUST_ENTRIES_JSON') ?? 'null', + ); + expect(entries).toEqual([ + { + issuer: 'librechat-local', + audiences: ['codeapi-local'], + keyIds: ['lc-codeapi-local-2026-05'], + allowedAlgorithms: ['EdDSA'], + principalSources: ['librechat_jwt', 'openid_reuse'], + }, + ]); + }); +}); diff --git a/service/src/egress-gateway.ts b/service/src/egress-gateway.ts index 3499de80..1b006a7a 100644 --- a/service/src/egress-gateway.ts +++ b/service/src/egress-gateway.ts @@ -42,6 +42,11 @@ import { isValidId } from './utils'; import logger from './logger'; import { parseBoundedContentLength } from './http-limits'; import { validateEgressGatewayHardenedConfig } from './secure-startup'; +import { + operationalErrorMeta, + operationalMethod, + operationalPrincipalSource, +} from './operational-log'; export const app: Express = express(); app.disable('x-powered-by'); @@ -73,11 +78,6 @@ const SUPPORTED_OUTPUT_EXTENSIONS = new Set([ ]); type EgressAuditFields = { - execHash?: string; - requestExecHash?: string; - tenantHash?: string; - userHash?: string; - authContextHash?: string; principalSource?: string; }; @@ -94,15 +94,6 @@ function routeFamily(req: Request): string { return 'unknown'; } -function requestId(res: Response): string | undefined { - return res.locals.egressRequestId as string | undefined; -} - -function hashLabel(value: string | undefined): string | undefined { - if (!value) return undefined; - return crypto.createHash('sha256').update(value, 'utf8').digest('base64url').slice(0, 16); -} - function auditFields(res: Response): EgressAuditFields { return (res.locals.egressAuditFields as EgressAuditFields | undefined) ?? {}; } @@ -114,18 +105,9 @@ function isSyntheticEgressRequest(res: Response): boolean { function setGrantAudit(res: Response, grant: EgressGrantClaims): void { res.locals.egressAuditFields = { - execHash: hashLabel(grant.exec_id), - tenantHash: hashLabel(grant.tenant_id), - userHash: hashLabel(grant.user_id), - authContextHash: hashLabel(grant.auth_context_hash), - ...(grant.principal_source ? { principalSource: grant.principal_source } : {}), - }; -} - -function setPtcAudit(res: Response, args: { callbackExecId: string; requestExecId: string }): void { - res.locals.egressAuditFields = { - execHash: hashLabel(args.callbackExecId), - requestExecHash: hashLabel(args.requestExecId), + ...(grant.principal_source + ? { principalSource: operationalPrincipalSource(grant.principal_source) } + : {}), }; } @@ -134,19 +116,17 @@ app.use((req: Request, res: Response, next: NextFunction) => { const id = req.header('x-request-id') ?? crypto.randomUUID(); res.locals.syntheticInternalRequest = req.path.startsWith('/internal/') && isSyntheticInternalRequestHeader(req.header(CODEAPI_SYNTHETIC_INTERNAL_REQUEST_HEADER)); - res.locals.egressRequestId = id; res.setHeader('X-Request-ID', id); res.on('finish', () => { if (req.path === '/live' || req.path === '/health' || req.path === '/ready' || req.path === '/metrics') return; if (res.statusCode < 400 && isSyntheticEgressRequest(res)) return; logger.info('Egress gateway request completed', { - requestId: id, - method: req.method, + method: operationalMethod(req.method), route: routeFamily(req), statusCode: res.statusCode, durationMs: Date.now() - started, - contentLength: req.header('content-length'), + contentLengthPresent: req.header('content-length') != null, ...auditFields(res), }); }); @@ -165,9 +145,8 @@ function sendEgressError(req: Request, res: Response, error: unknown): Response if (error instanceof EgressGrantError) { const statusCode = errorStatus(error); logger.warn('Rejected egress gateway request', { - requestId: requestId(res), reason: error.reason, - method: req.method, + method: operationalMethod(req.method), route: routeFamily(req), statusCode, ...auditFields(res), @@ -175,10 +154,9 @@ function sendEgressError(req: Request, res: Response, error: unknown): Response return res.status(statusCode).json({ error: error.message }); } logger.error('Egress gateway request failed', { - requestId: requestId(res), - method: req.method, + method: operationalMethod(req.method), route: routeFamily(req), - error, + ...operationalErrorMeta(error), ...auditFields(res), }); return res.status(500).json({ error: 'Internal server error' }); @@ -374,7 +352,7 @@ async function readiness(_req: Request, res: Response): Promise { await pingEgressLedger(); res.sendStatus(200); } catch (error) { - logger.error('Egress gateway readiness failed', { error }); + logger.error('Egress gateway readiness failed', operationalErrorMeta(error)); res.sendStatus(503); } } @@ -403,10 +381,7 @@ app.post('/internal/egress-grants', express.json({ limit: env.HTTP_JSON_LIMIT }) await createEgressLedger(grant); if (!isSyntheticPrincipalSource(grant.principal_source)) { logger.info('Egress grant created', { - grantHash: hashLabel(grant.grant_id), - execHash: hashLabel(grant.exec_id), - tenantHash: hashLabel(grant.tenant_id), - userHash: hashLabel(grant.user_id), + principalSource: operationalPrincipalSource(grant.principal_source), }); } return res.status(201).json({ grant_id: grantId, ...prepared }); @@ -695,9 +670,7 @@ app.put('/sessions/:sessionHandle/objects/:fileId', async (req, res) => { if (reservedUpload) { await releaseEgressUpload(reservedUpload).catch(releaseError => { logger.error('Failed to release egress upload reservation after upstream failure', { - error: releaseError, - grantHash: hashLabel(reservedUpload?.grant.grant_id), - fileId: reservedUpload?.fileId, + ...operationalErrorMeta(releaseError), }); }); } @@ -723,7 +696,6 @@ app.post('/tool-call', async (req, res) => { executionIdPresent: !!executionId, callIdPresent: !!callId, callbackTokenPresent: !!opaqueCallbackToken, - remoteAddress: req.socket.remoteAddress, }, ); res.setHeader('Connection', 'close'); @@ -739,7 +711,6 @@ app.post('/tool-call', async (req, res) => { } const length = parsedLength.length; const callback = openPtcCallbackToken(opaqueCallbackToken, env.EGRESS_GRANT_SECRET); - setPtcAudit(res, { callbackExecId: callback.exec_id, requestExecId: executionId }); if (callback.exec_id !== executionId) { throw new EgressGrantError('scope_mismatch', 'PTC callback token execution does not match request'); } @@ -818,15 +789,15 @@ async function shutdown(): Promise { try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn('OpenTelemetry shutdown failed', { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } process.exit(0); } catch (error) { - logger.error('Egress gateway shutdown failed', { error }); + logger.error('Egress gateway shutdown failed', operationalErrorMeta(error)); try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn('OpenTelemetry shutdown failed', { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } process.exit(1); } @@ -834,7 +805,7 @@ async function shutdown(): Promise { if (process.env.CODEAPI_EGRESS_GATEWAY_AUTOSTART !== 'false') { server = app.listen(env.EGRESS_GATEWAY_PORT, () => { - logger.info(`Egress gateway listening on port ${env.EGRESS_GATEWAY_PORT}`); + logger.info('Egress gateway started'); }); process.on('SIGTERM', () => void shutdown()); diff --git a/service/src/egress-ledger.ts b/service/src/egress-ledger.ts index c190897a..cccb01b5 100644 --- a/service/src/egress-ledger.ts +++ b/service/src/egress-ledger.ts @@ -6,6 +6,7 @@ import type { EgressGrantClaims } from './egress-grant'; import { EgressGrantError } from './egress-grant'; import logger from './logger'; import { redisKeepAliveOptions } from './redis-options'; +import { operationalErrorMeta } from './operational-log'; type LedgerStatus = 'active' | 'revoked'; @@ -81,7 +82,9 @@ function redisConnection(): IORedis { ? { dnsLookup: (address: string, callback: (err: Error | null, addr: string) => void): void => callback(null, address) } : {}), }); - redis.on('error', error => logger.error('Egress ledger Redis error', { error })); + redis.on('error', error => { + logger.error('Egress ledger Redis error', operationalErrorMeta(error)); + }); return redis; } @@ -119,7 +122,9 @@ async function dedicatedMutationConnection(): Promise { function createMutationConnection(): IORedis { const client = redisConnection().duplicate(); mutationConnections.add(client); - client.on('error', error => logger.error('Egress ledger mutation Redis error', { error })); + client.on('error', error => { + logger.error('Egress ledger mutation Redis error', operationalErrorMeta(error)); + }); return client; } @@ -249,7 +254,10 @@ async function mutateRecord( } } catch (error) { await client.unwatch().catch(unwatchError => { - logger.warn('Failed to clear egress ledger WATCH after rejected mutation', { error: unwatchError }); + logger.warn( + 'Failed to clear egress ledger WATCH after rejected mutation', + operationalErrorMeta(unwatchError), + ); }); throw error; } @@ -263,7 +271,10 @@ async function mutateRecord( } } finally { await client.unwatch().catch(error => { - logger.warn('Failed to clear egress ledger WATCH before returning mutation connection', { error }); + logger.warn( + 'Failed to clear egress ledger WATCH before returning mutation connection', + operationalErrorMeta(error), + ); }); releaseMutationConnection(client); } diff --git a/service/src/execution-log.test.ts b/service/src/execution-log.test.ts index d78fafc4..748fd165 100644 --- a/service/src/execution-log.test.ts +++ b/service/src/execution-log.test.ts @@ -33,8 +33,10 @@ describe('execution log summaries', () => { expect(JSON.stringify(summary)).not.toContain('top secret stdout'); expect(JSON.stringify(summary)).not.toContain('sensitive stderr'); expect(JSON.stringify(summary)).not.toContain('combined output'); + expect(JSON.stringify(summary)).not.toContain('sess_123'); + expect(JSON.stringify(summary)).not.toContain('5.2.0'); expect(summary).toMatchObject({ - session_id: 'sess_123', + languageClass: 'other', files: { count: 2, inheritedCount: 1, modifiedCount: 1 }, run: { stdout: { length: 17, present: true }, @@ -56,4 +58,3 @@ describe('execution log summaries', () => { expect(summary).toEqual({ count: 3, skillCount: 1, agentCount: 1, userCount: 1 }); }); }); - diff --git a/service/src/execution-log.ts b/service/src/execution-log.ts index 311169e8..f3659928 100644 --- a/service/src/execution-log.ts +++ b/service/src/execution-log.ts @@ -63,9 +63,7 @@ export function summarizeRequestedFiles(files: unknown): { export function summarizeSandboxResponse(data: SandboxResponseLike): Record { const run = data.run; return { - session_id: data.session_id, - language: data.language, - version: data.version, + languageClass: data.language === 'python' ? 'python' : 'other', files: summarizeFiles(data.files), run: run == null ? undefined @@ -83,4 +81,3 @@ export function summarizeSandboxResponse(data: SandboxResponseLike): Record { }; if (useIrsa) { - logger.info('Using IRSA (IamAwsProvider) for S3 authentication', { - tokenFile: process.env.AWS_WEB_IDENTITY_TOKEN_FILE, - roleArn: process.env.AWS_ROLE_ARN, - region: baseConfig.region, - }); + logger.info('Using IRSA for S3 authentication'); /** IamAwsProvider exists in minio 8.0.6+ but isn't exported from main module * Try multiple import paths for compatibility with different runtimes (bun, ts-node, node) @@ -68,7 +63,10 @@ async function createMinioClient(): Promise { const mod = await import(`${resolvePath}dist/main/IamAwsProvider.js`) as IamProviderModule; IamAwsProviderClass = (mod.IamAwsProvider ?? mod.default)!; } catch (fallbackError) { - logger.error('Failed to load IamAwsProvider', { primaryError, fallbackError }); + logger.error('Failed to load IamAwsProvider', { + primaryErrorClass: operationalErrorClass(primaryError), + fallbackErrorClass: operationalErrorClass(fallbackError), + }); throw new Error('Could not load IamAwsProvider for IRSA authentication. Ensure minio >= 8.0.6 is installed.'); } } @@ -125,14 +123,11 @@ const redisClient = new IORedis({ }); redisClient.on('error', (err) => { - logger.error('Redis Client Error', { error: err }); + logger.error('Redis client error', operationalErrorMeta(err)); }); redisClient.on('connect', () => { - logger.info('Redis Client Connected', { - host: process.env.REDIS_HOST, - port: process.env.REDIS_PORT - }); + logger.info('Redis client connected'); }); redisClient.on('ready', () => { @@ -161,10 +156,18 @@ async function ensureBucketExists(retries = 10, delay = 1000): Promise { if (attempt < retries) { const backoff = delay * Math.pow(2, attempt - 1); - logger.warn(`MinIO not ready, retrying in ${backoff}ms (attempt ${attempt}/${retries})`, { error: error.message }); + logger.warn('Object storage is not ready; retrying', { + attempt, + maxAttempts: retries, + retryAfterMs: backoff, + ...operationalErrorMeta(err), + }); await new Promise(resolve => setTimeout(resolve, backoff)); } else { - logger.error('Failed to ensure bucket exists after all retries', { error }); + logger.error( + 'Failed to ensure object storage bucket exists after all retries', + { attempts: retries, ...operationalErrorMeta(err) }, + ); throw err; } } @@ -262,7 +265,7 @@ async function uploadFile( } else { await minioClient.putObject(bucketName, objectName, peeked.body, undefined, metaData); } - logger.info(`[${INSTANCE_ID}] File ID: ${fileId} | Filename: ${filename} | Session key: ${sessionKey}`); + logger.info('File stored', { empty: peeked.empty, readOnly }); await redisClient.set(`upload:${sessionKey}${session_id}${fileId}`, 'true', 'EX', env.SESSION_CACHE_TTL); fileUploads.inc(); @@ -291,7 +294,7 @@ app.get('/ready', async (_req: express.Request, res: express.Response) => { await redisClient.ping(); checks.redis = 'ok'; } catch (error) { - logger.error('Readiness check failed - Redis:', { error }); + logger.error('Readiness check failed for Redis', operationalErrorMeta(error)); checks.redis = 'error'; healthy = false; } @@ -301,7 +304,7 @@ app.get('/ready', async (_req: express.Request, res: express.Response) => { await minioClient.bucketExists(bucketName); checks.s3 = 'ok'; } catch (error) { - logger.error('Readiness check failed - S3:', { error }); + logger.error('Readiness check failed for object storage', operationalErrorMeta(error)); checks.s3 = 'error'; healthy = false; } @@ -348,17 +351,17 @@ app.post('/sessions/:session_id/objects', async (req: express.Request, res: expr decodedFilename = decodeURIComponent(combinedFilename); } catch (err) { // If decoding fails, use the original filename - logger.warn(`Failed to decode filename, using original: ${combinedFilename}`, { error: err }); + logger.warn('Failed to decode filename; using original', operationalErrorMeta(err)); decodedFilename = combinedFilename; } const [fileId, ...filenameParts] = decodedFilename.split('___'); const filename = filenameParts.join('___'); - logger.info(`[${INSTANCE_ID}] Processing file: ${filename} with ID: ${fileId}`); + logger.info('Processing uploaded file'); const uploadPromise = uploadFile(session_id, file, filename, mimeType, fileId, readOnly).catch(err => { - logger.error(`[${INSTANCE_ID}] Error uploading file ${filename}:`, { error: err }); + logger.error('Error uploading file', operationalErrorMeta(err)); return null; }); uploadPromises.push(uploadPromise); @@ -369,7 +372,7 @@ app.post('/sessions/:session_id/objects', async (req: express.Request, res: expr const results = await Promise.all(uploadPromises); const successfulUploads = results.filter((result): result is t.UploadResult => result !== null); - logger.info(`[${INSTANCE_ID}] Successfully uploaded ${successfulUploads.length} files for session ${session_id}`); + logger.info('Upload batch completed', { uploadedFiles: successfulUploads.length }); return res.status(200).json({ message: 'success', @@ -377,13 +380,13 @@ app.post('/sessions/:session_id/objects', async (req: express.Request, res: expr files: successfulUploads }); } catch (err) { - logger.error('Error processing uploads:', { error: err }); + logger.error('Error processing uploads', operationalErrorMeta(err)); return res.status(500).send('Error uploading files.'); } }); busboy.on('error', (error) => { - logger.error(`[${INSTANCE_ID}] Busboy error for session_id ${session_id}:`, error); + logger.error('Multipart upload parser failed', operationalErrorMeta(error)); res.status(500).json({ error: 'Error processing upload' }); }); @@ -401,7 +404,7 @@ app.put('/sessions/:session_id/objects/:fileId', async (req: express.Request, re decodedFilename = decodeURIComponent(originalFilename); } catch (err) { // If decoding fails, use the original filename - logger.warn(`Failed to decode filename header, using original: ${originalFilename}`, { error: err }); + logger.warn('Failed to decode filename header; using original', operationalErrorMeta(err)); decodedFilename = originalFilename; } } @@ -416,10 +419,10 @@ app.put('/sessions/:session_id/objects/:fileId', async (req: express.Request, re try { const result = await uploadFile(session_id, req, decodedFilename, mimeType, fileId, readOnly); - logger.info(`[${INSTANCE_ID}] File uploaded successfully: ${result.filename}`); + logger.info('File upload completed'); return res.status(200).json(result); } catch (err) { - logger.error(`[${INSTANCE_ID}] Error uploading file ${decodedFilename}:`, { error: err }); + logger.error('Error uploading file', operationalErrorMeta(err)); return res.status(500).json({ error: 'Error uploading file.' }); } }); @@ -470,7 +473,7 @@ app.get('/sessions/:session_id/objects/:objectId/metadata', async (req, res) => readOnly: stat.metaData?.['read-only'] === 'true', }); } catch (err) { - logger.error('Error fetching object metadata:', { error: err, session_id, objectId, bucketName }); + logger.error('Error fetching object metadata', operationalErrorMeta(err)); return res.status(500).json({ error: 'Error fetching object metadata', details: (err as Error | undefined)?.message, @@ -494,7 +497,7 @@ app.get('/sessions/:session_id/objects/:objectId', async (req, res) => { } if (!objectName) { - logger.warn('File not found', { session_id, objectId, bucketName }); + logger.warn('File not found'); return res.status(404).json({ error: 'File not found', details: 'No matching file found', @@ -504,7 +507,7 @@ app.get('/sessions/:session_id/objects/:objectId', async (req, res) => { }); } - logger.info(`[${INSTANCE_ID}] Attempting to download: ${objectName}`); + logger.info('File download started'); const stat: Partial = await minioClient.statObject(bucketName, objectName); @@ -513,14 +516,17 @@ app.get('/sessions/:session_id/objects/:objectId', async (req, res) => { try { originalFilename = Buffer.from(stat.metaData['original-filename'], 'base64').toString('utf8'); } catch (err) { - logger.warn('Failed to decode filename from metadata, using fallback', { error: err }); + logger.warn( + 'Failed to decode filename from metadata; using fallback', + operationalErrorMeta(err), + ); originalFilename = stat.metaData['original-filename'] ?? path.basename(objectName); } } else if (stat.metaData?.['original-filename'] != null) { originalFilename = stat.metaData['original-filename']; } - logger.info(`[${INSTANCE_ID}] File found: ${objectName}`); + logger.info('File download source found'); // Explicitly remove problematic headers that might be duplicated res.removeHeader('Transfer-Encoding'); @@ -550,7 +556,7 @@ app.get('/sessions/:session_id/objects/:objectId', async (req, res) => { }); dataStream.on('error', (err) => { - logger.error('Error streaming file:', { error: err, session_id, objectId, bucketName }); + logger.error('Error streaming file', operationalErrorMeta(err)); // Only send error if headers haven't been sent yet if (!res.headersSent) { res.status(500).json({ @@ -562,7 +568,7 @@ app.get('/sessions/:session_id/objects/:objectId', async (req, res) => { } }); } catch (err) { - logger.error('Error downloading file:', { error: err, session_id, objectId, bucketName }); + logger.error('Error downloading file', operationalErrorMeta(err)); return res.status(500).json({ error: 'Error downloading file', details: (err as Error | undefined)?.message, @@ -673,7 +679,7 @@ app.get('/sessions/:session_id/objects', async (req, res) => { res.json(objects); } catch (err) { - logger.error('Error listing objects:', { error: err, session_id }); + logger.error('Error listing objects', operationalErrorMeta(err)); return res.status(500).send('Error listing objects'); } }); @@ -693,7 +699,7 @@ app.delete('/sessions/:session_id/objects/:fileId', async (req, res) => { } if (!objectName) { - logger.warn('File not found for deletion', { session_id, fileId, bucketName }); + logger.warn('File not found for deletion'); return res.status(404).json({ error: 'File not found', details: 'No matching file found for deletion', @@ -704,7 +710,7 @@ app.delete('/sessions/:session_id/objects/:fileId', async (req, res) => { } await minioClient.removeObject(bucketName, objectName); - logger.info(`[${INSTANCE_ID}] File deleted successfully: ${objectName}`); + logger.info('File deleted successfully'); return res.status(200).json({ message: 'File deleted successfully', session_id, @@ -712,7 +718,7 @@ app.delete('/sessions/:session_id/objects/:fileId', async (req, res) => { }); } catch (err) { - logger.error('Error deleting file:', err); + logger.error('Error deleting file', operationalErrorMeta(err)); return res.status(500).json({ error: 'Error deleting file', }); @@ -732,11 +738,11 @@ async function startServer(): Promise { try { await initializeStorage(); const onListen = () => { - logger.info(`[${INSTANCE_ID}] Server running on ${host ?? '*'}:${port}`); + logger.info('File server started'); }; server = host ? app.listen(port, host, onListen) : app.listen(port, onListen); } catch (err) { - logger.error('Critical: Could not initialize storage', { error: err }); + logger.error('Could not initialize storage', operationalErrorMeta(err)); process.exit(1); } } @@ -754,22 +760,22 @@ function closeHttpServer(): Promise { async function shutdown(): Promise { if (shuttingDown) return; shuttingDown = true; - logger.info(`[${INSTANCE_ID}] Shutting down file server...`); + logger.info('Shutting down file server'); try { await closeHttpServer(); await redisClient.quit(); try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn(`[${INSTANCE_ID}] OpenTelemetry shutdown failed`, { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } process.exit(0); } catch (error) { - logger.error(`[${INSTANCE_ID}] File server shutdown failed`, { error }); + logger.error('File server shutdown failed', operationalErrorMeta(error)); try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn(`[${INSTANCE_ID}] OpenTelemetry shutdown failed`, { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } process.exit(1); } @@ -781,9 +787,9 @@ process.on('SIGTERM', () => void shutdown()); process.on('SIGINT', () => void shutdown()); process.on('uncaughtException', (error) => { - logger.error('Uncaught Exception', { error }); + logger.error('Uncaught exception', operationalErrorMeta(error)); }); -process.on('unhandledRejection', (reason, promise) => { - logger.error('Unhandled Rejection', { reason, promise }); +process.on('unhandledRejection', (reason) => { + logger.error('Unhandled rejection', operationalErrorMeta(reason)); }); diff --git a/service/src/lifecycle.ts b/service/src/lifecycle.ts index 8fc0adc2..58329a3c 100644 --- a/service/src/lifecycle.ts +++ b/service/src/lifecycle.ts @@ -12,8 +12,8 @@ import { import logger from './logger'; import { shutdownTelemetry } from './telemetry'; import { configureExecutionProfileMetrics } from './metrics'; +import { operationalErrorMeta } from './operational-log'; -const { INSTANCE_ID } = env; let isShuttingDown = false; let isStartingUp = true; @@ -30,7 +30,7 @@ async function shutdownTracing(): Promise { await shutdownTelemetry(); logger.info('OpenTelemetry shutdown completed'); } catch (error) { - logger.warn('OpenTelemetry shutdown failed', { error }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(error)); } } @@ -52,33 +52,33 @@ export function registerWorkers(): void { /** * Set up queue event listeners for monitoring */ -function setupQueueListeners(queue: Queue, name: string): void { +function setupQueueListeners(queue: Queue, queueClass: 'python' | 'other'): void { queue.on('error', (error: Error) => { - logger.error(`${name} queue error:`, error); + logger.error('Queue error', { queueClass, ...operationalErrorMeta(error) }); }); - queue.on('waiting', (job) => { - logger.debug(`${name} job ${job.id} waiting`); + queue.on('waiting', () => { + logger.debug('Queue job waiting', { queueClass }); }); - queue.on('progress', (job, progress) => { - logger.debug(`${name} job progress:`, { job, progress }); + queue.on('progress', () => { + logger.debug('Queue job progressed', { queueClass }); }); queue.on('paused', () => { - logger.info(`${name} queue paused`); + logger.info('Queue paused', { queueClass }); }); queue.on('resumed', () => { - logger.info(`${name} queue resumed`); + logger.info('Queue resumed', { queueClass }); }); - queue.on('removed', (jobId) => { - logger.debug(`${name} job ${jobId} removed`); + queue.on('removed', () => { + logger.debug('Queue job removed', { queueClass }); }); - queue.on('cleaned', (jobs, type) => { - logger.info(`${name} queue cleaned ${jobs.length} ${type} jobs`); + queue.on('cleaned', (jobs) => { + logger.info('Queue jobs cleaned', { queueClass, jobCount: jobs.length }); }); } @@ -99,8 +99,8 @@ export async function startupApiOnly(): Promise { configureProfileMetrics(); // Set up queue listeners for monitoring (optional, for observability) - setupQueueListeners(pyQueue, 'Python'); - setupQueueListeners(otherQueue, 'Other'); + setupQueueListeners(pyQueue, 'python'); + setupQueueListeners(otherQueue, 'other'); isStartingUp = false; logger.info('API service startup complete'); @@ -163,8 +163,8 @@ async function gracefulStartup(): Promise { registerWorkers(); // Set up queue event listeners - setupQueueListeners(pyQueue, 'Python'); - setupQueueListeners(otherQueue, 'Other'); + setupQueueListeners(pyQueue, 'python'); + setupQueueListeners(otherQueue, 'other'); // Verify workers are running const checkWorkers = (): void => { @@ -191,7 +191,7 @@ async function gracefulStartup(): Promise { isStartingUp = false; logger.info('Service startup complete'); } catch (error) { - logger.error('Error during startup:', error); + logger.error('Error during startup', operationalErrorMeta(error)); throw error; } } @@ -224,20 +224,26 @@ export async function gracefulShutdown(): Promise { // Note: We pause workers, NOT queues (queues are shared) // pause(false) = wait for active jobs to finish before resolving (doNotWaitActive=false) // pause(true) = return immediately without waiting for active jobs - const pauseAndDrain = async (worker: typeof pyWorker, name: string): Promise => { - logger.info(`Pausing ${name} worker and waiting for active jobs to drain...`); + const pauseAndDrain = async ( + worker: typeof pyWorker, + workerClass: 'python' | 'other', + ): Promise => { + logger.info('Pausing worker and waiting for active jobs to drain', { workerClass }); try { // doNotWaitActive=false means wait for active jobs to complete await worker.pause(false); - logger.info(`${name} worker drained successfully`); + logger.info('Worker drained successfully', { workerClass }); } catch (error) { - logger.warn(`${name} worker pause failed`, { error }); + logger.warn('Worker pause failed', { + workerClass, + ...operationalErrorMeta(error), + }); } }; await Promise.all([ - pauseAndDrain(pyWorker, 'Python'), - pauseAndDrain(otherWorker, 'Other') + pauseAndDrain(pyWorker, 'python'), + pauseAndDrain(otherWorker, 'other') ]); // Close workers @@ -269,7 +275,7 @@ export async function gracefulShutdown(): Promise { logger.info('Graceful shutdown completed'); process.exit(0); } catch (error) { - logger.error('Error during shutdown:', error); + logger.error('Error during shutdown', operationalErrorMeta(error)); await shutdownTracing(); clearTimeout(shutdownTimeout); process.exit(1); @@ -295,15 +301,14 @@ export async function startServer(app: Express, callback?: () => Promise): try { await gracefulStartup(); app.listen(env.PORT, () => { - logger.info(`[${INSTANCE_ID}] Server is running on port ${env.PORT}`); - logger.info(`[${INSTANCE_ID}] PYTHON_CONCURRENCY: ${env.PYTHON_CONCURRENCY} | OTHER_CONCURRENCY: ${env.OTHER_CONCURRENCY} | JOB_WINDOW: ${env.JOB_WINDOW}`); + logger.info('Combined API and worker service started'); }); if (callback != null) { await callback(); } } catch (error) { - logger.error('Failed to start server:', error); + logger.error('Failed to start server', operationalErrorMeta(error)); process.exit(1); } } @@ -315,15 +320,14 @@ export async function startApiServer(app: Express, callback?: () => Promise { - logger.info(`[${INSTANCE_ID}] API Server is running on port ${env.PORT}`); - logger.info(`[${INSTANCE_ID}] Mode: API-only (no workers)`); + logger.info('API service started'); }); if (callback != null) { await callback(); } } catch (error) { - logger.error('Failed to start API server:', error); + logger.error('Failed to start API server', operationalErrorMeta(error)); process.exit(1); } } @@ -334,14 +338,13 @@ export async function startApiServer(app: Express, callback?: () => Promise Promise): Promise { try { await startupWorkerOnly(); - logger.info(`[${INSTANCE_ID}] Worker Server started`); - logger.info(`[${INSTANCE_ID}] PYTHON_CONCURRENCY: ${env.PYTHON_CONCURRENCY} | OTHER_CONCURRENCY: ${env.OTHER_CONCURRENCY} | JOB_WINDOW: ${env.JOB_WINDOW}`); + logger.info('Worker service started'); if (callback != null) { await callback(); } } catch (error) { - logger.error('Failed to start worker server:', error); + logger.error('Failed to start worker server', operationalErrorMeta(error)); process.exit(1); } } diff --git a/service/src/local-api.ts b/service/src/local-api.ts index 701270d7..afb4aedd 100644 --- a/service/src/local-api.ts +++ b/service/src/local-api.ts @@ -22,6 +22,7 @@ import logger from './logger'; import { shutdownTelemetry, traceHttpRequest } from './telemetry'; import { validateExecutionProfilePolicy } from './secure-startup'; import { configureExecutionProfileMetrics } from './metrics'; +import { operationalErrorMeta } from './operational-log'; const app = express(); app.disable('x-powered-by'); @@ -40,7 +41,7 @@ app.get('/v1/health', async (_, res) => { await connection.ping(); res.sendStatus(200); } catch (error) { - logger.error('Health check failed:', error); + logger.error('Health check failed', operationalErrorMeta(error)); res.sendStatus(503); } }); @@ -80,7 +81,7 @@ async function localStartup(): Promise { setStartupComplete(); logger.info('Local startup complete'); } catch (error) { - logger.error('Error during local startup:', error); + logger.error('Error during local startup', operationalErrorMeta(error)); throw error; } } @@ -99,16 +100,16 @@ async function localShutdown(): Promise { try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn('OpenTelemetry shutdown failed', { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } logger.info('Local shutdown complete'); process.exit(0); } catch (error) { - logger.error('Error during shutdown:', error); + logger.error('Error during shutdown', operationalErrorMeta(error)); try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn('OpenTelemetry shutdown failed', { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } process.exit(1); } @@ -117,11 +118,10 @@ async function localShutdown(): Promise { // Start server localStartup().then(() => { app.listen(env.PORT, () => { - logger.info(`[LOCAL] Server running on port ${env.PORT}`); - logger.info(`[LOCAL] PYTHON_CONCURRENCY: ${env.PYTHON_CONCURRENCY} | OTHER_CONCURRENCY: ${env.OTHER_CONCURRENCY}`); + logger.info('Local server started'); }); }).catch((error) => { - logger.error('Failed to start local server:', error); + logger.error('Failed to start local server', operationalErrorMeta(error)); process.exit(1); }); @@ -130,10 +130,10 @@ process.on('SIGINT', localShutdown); process.on('SIGUSR2', localShutdown); process.on('uncaughtException', async (error) => { - logger.error('Uncaught Exception', error); + logger.error('Uncaught exception', operationalErrorMeta(error)); await localShutdown(); }); process.on('unhandledRejection', (reason) => { - logger.error('Unhandled Rejection', reason); + logger.error('Unhandled rejection', operationalErrorMeta(reason)); }); diff --git a/service/src/middleware/auth-log.test.ts b/service/src/middleware/auth-log.test.ts new file mode 100644 index 00000000..81486845 --- /dev/null +++ b/service/src/middleware/auth-log.test.ts @@ -0,0 +1,75 @@ +import { createHash } from 'node:crypto'; +import { afterEach, describe, expect, test } from 'bun:test'; +import type { AuthenticatedRequest } from '../types'; +import { buildAuthLogMeta } from './auth-log'; + +const SENTINEL = 'PRIVATE_auth_9dQm2V7x'; +const originalProvider = process.env.CODEAPI_AUTH_PROVIDER; + +afterEach(() => { + if (originalProvider == null) { + delete process.env.CODEAPI_AUTH_PROVIDER; + } else { + process.env.CODEAPI_AUTH_PROVIDER = originalProvider; + } +}); + +describe('buildAuthLogMeta', () => { + test('keeps auth classes without retaining client values', () => { + process.env.CODEAPI_AUTH_PROVIDER = 'librechat-jwt'; + const req = { + method: `CUSTOM-${SENTINEL}`, + originalUrl: `/private/${SENTINEL}`, + path: `/private/${SENTINEL}`, + url: `/private/${SENTINEL}`, + ip: SENTINEL, + header: (name: string) => { + const headers: Record = { + authorization: `Bearer ${SENTINEL}`, + 'x-api-key': SENTINEL, + }; + return headers[name.toLowerCase()]; + }, + codeApiAuthContext: { + userId: SENTINEL, + tenantId: SENTINEL, + authContextHash: SENTINEL, + }, + codeApiPrincipal: { + userId: SENTINEL, + tenantId: SENTINEL, + principalSource: SENTINEL, + authContextHash: SENTINEL, + }, + } as unknown as AuthenticatedRequest; + + const serialized = JSON.stringify( + buildAuthLogMeta(req, { + error: new Error(SENTINEL), + mode: SENTINEL, + reason: SENTINEL, + reasonSource: 'jwt', + }), + ); + + expect(JSON.parse(serialized)).toMatchObject({ + method: 'OTHER', + route: 'unmatched', + authProvider: 'librechat-jwt', + hasBearerToken: true, + hasApiKeyHeader: true, + principalSource: 'other', + mode: 'invalid', + reason: 'other', + errorClass: 'unexpected', + }); + for (const variant of [ + SENTINEL, + encodeURIComponent(SENTINEL), + Buffer.from(SENTINEL).toString('base64'), + createHash('sha256').update(SENTINEL).digest('hex'), + ]) { + expect(serialized).not.toContain(variant); + } + }); +}); diff --git a/service/src/middleware/auth-log.ts b/service/src/middleware/auth-log.ts new file mode 100644 index 00000000..cc0a2edf --- /dev/null +++ b/service/src/middleware/auth-log.ts @@ -0,0 +1,52 @@ +import type { AuthenticatedRequest } from '../types'; +import { hasSyntheticAccessToken } from '../auth/synthetic'; +import { + operationalAuthProvider, + operationalAuthReason, + operationalErrorClass, + operationalMethod, + operationalPrincipalSource, + operationalRoute, +} from '../operational-log'; + +type AuthLogExtra = { + error?: unknown; + mode?: unknown; + reason?: unknown; + reasonSource?: 'jwt' | 'synthetic'; +}; + +export function buildAuthLogMeta( + req: AuthenticatedRequest, + extra: AuthLogExtra = {}, +): Record { + const mode = extra.mode; + const safeMode = + mode === 'local' || mode === 'synthetic' + ? mode + : operationalAuthProvider( + mode ?? process.env.CODEAPI_AUTH_PROVIDER ?? 'librechat-jwt', + ); + return { + method: operationalMethod(req.method), + route: operationalRoute(req), + authProvider: operationalAuthProvider( + process.env.CODEAPI_AUTH_PROVIDER || 'librechat-jwt', + ), + hasBearerToken: Boolean( + req.header('Authorization')?.match(/^Bearer\s+(.+)$/i)?.[1]?.trim(), + ), + hasApiKeyHeader: Boolean(req.header('X-API-Key')), + hasSyntheticToken: hasSyntheticAccessToken(req), + principalSource: operationalPrincipalSource( + req.codeApiPrincipal?.principalSource, + ), + mode: safeMode, + reason: + extra.reasonSource == null + ? undefined + : operationalAuthReason(extra.reason, extra.reasonSource), + errorClass: + extra.error == null ? undefined : operationalErrorClass(extra.error), + }; +} diff --git a/service/src/middleware/auth.ts b/service/src/middleware/auth.ts index b402e346..6b3d0762 100644 --- a/service/src/middleware/auth.ts +++ b/service/src/middleware/auth.ts @@ -11,8 +11,13 @@ import { AuthProviderConfigError, getAuthProviderMode } from '../auth/provider'; import { authenticateSyntheticRequest, CODEAPI_SYNTHETIC_AUTH_HEADER, - hasSyntheticAccessToken, } from '../auth/synthetic'; +import { + operationalErrorClass, + operationalMethod, + operationalRoute, +} from '../operational-log'; +import { buildAuthLogMeta } from './auth-log'; import logger from '../logger'; /** @@ -30,14 +35,14 @@ const logSessionKeyResolutionError = ( context: string, ): boolean => { if (err instanceof SessionKeyResolutionError) { - logger.error(`sessionKey resolution failed (${context})`, { + logger.error('Session key resolution failed', { status: err.status, - message: err.message, - method: req.method, - path: req.path, - requestUserId: req.codeApiAuthContext?.userId, - authContextUserId: req.codeApiAuthContext?.userId, - tenantId: req.codeApiAuthContext?.tenantId, + stage: context.includes('parseUploadSessionKeyInput') + ? 'parse_upload_identity' + : 'resolve_session_key', + method: operationalMethod(req.method), + route: operationalRoute(req), + errorClass: operationalErrorClass(err), }); res.status(err.status).json({ error: err.message }); return true; @@ -47,23 +52,6 @@ const logSessionKeyResolutionError = ( const jwtProvider = new LibreChatJwtAuthProvider(); -function authLogMeta(req: AuthenticatedRequest, extra: Record = {}): Record { - return { - method: req.method, - path: req.originalUrl || req.path, - ip: req.ip, - authProvider: process.env.CODEAPI_AUTH_PROVIDER || 'librechat-jwt', - hasBearerToken: Boolean(req.header('Authorization')?.match(/^Bearer\s+(.+)$/i)?.[1]?.trim()), - hasApiKeyHeader: Boolean(req.header('X-API-Key')), - hasSyntheticToken: hasSyntheticAccessToken(req), - principalSource: req.codeApiPrincipal?.principalSource, - userId: req.codeApiAuthContext?.userId, - tenantId: req.codeApiAuthContext?.tenantId, - authContextHash: req.codeApiAuthContext?.authContextHash, - ...extra, - }; -} - export const apiKeyAuth = async ( req: AuthenticatedRequest, res: Response, @@ -71,7 +59,7 @@ export const apiKeyAuth = async ( ): Promise => { if (env.LOCAL_MODE === true) { applyLocalPrincipal(req); - logger.debug('CodeAPI local request authenticated', authLogMeta(req, { mode: 'local' })); + logger.debug('CodeAPI local request authenticated', buildAuthLogMeta(req, { mode: 'local' })); next(); return; } @@ -81,7 +69,7 @@ export const apiKeyAuth = async ( const syntheticToken = req.header(CODEAPI_SYNTHETIC_AUTH_HEADER)?.trim(); const authHeaderCount = [legacyApiKeyHeader, bearerToken, syntheticToken].filter(Boolean).length; if (authHeaderCount > 1) { - logger.warn('Rejecting ambiguous CodeAPI auth headers', authLogMeta(req)); + logger.warn('Rejecting ambiguous CodeAPI auth headers', buildAuthLogMeta(req)); return res.status(400).json({ error: 'Ambiguous authentication headers' }); } @@ -89,7 +77,11 @@ export const apiKeyAuth = async ( const syntheticAuthResult = authenticateSyntheticRequest(req); if (syntheticAuthResult !== null) { if (!syntheticAuthResult.ok) { - const logMeta = authLogMeta(req, { mode: 'synthetic', reason: syntheticAuthResult.reason }); + const logMeta = buildAuthLogMeta(req, { + mode: 'synthetic', + reason: syntheticAuthResult.reason, + reasonSource: 'synthetic', + }); if (syntheticAuthResult.status >= 500) { logger.error('Rejecting synthetic CodeAPI request', logMeta); } else { @@ -99,7 +91,7 @@ export const apiKeyAuth = async ( } applyPrincipal(req, syntheticAuthResult.principal); - logger.debug('CodeAPI synthetic request authenticated', authLogMeta(req, { mode: 'synthetic' })); + logger.debug('CodeAPI synthetic request authenticated', buildAuthLogMeta(req, { mode: 'synthetic' })); next(); return; } @@ -108,7 +100,7 @@ export const apiKeyAuth = async ( let principal: CodeApiPrincipal | null = null; if (legacyApiKeyHeader) { - logger.warn('Rejecting legacy CodeAPI API key header', authLogMeta(req, { mode })); + logger.warn('Rejecting legacy CodeAPI API key header', buildAuthLogMeta(req, { mode })); return res.status(401).json({ error: 'Bearer token is required' }); } @@ -116,7 +108,7 @@ export const apiKeyAuth = async ( if (process.env.CODEAPI_ALLOW_AUTH_PROVIDER_NONE !== 'true') { logger.error( 'Rejecting CODEAPI_AUTH_PROVIDER=none outside local mode', - authLogMeta(req, { mode }), + buildAuthLogMeta(req, { mode }), ); return res .status(500) @@ -131,42 +123,50 @@ export const apiKeyAuth = async ( }; } else { if (!bearerToken) { - logger.warn('Rejecting CodeAPI request without bearer token', authLogMeta(req, { mode })); + logger.warn('Rejecting CodeAPI request without bearer token', buildAuthLogMeta(req, { mode })); return res.status(401).json({ error: 'Bearer token is required' }); } principal = await jwtProvider.verify(req); } if (!principal) { - logger.warn('CodeAPI auth provider returned no principal', authLogMeta(req, { mode })); + logger.warn('CodeAPI auth provider returned no principal', buildAuthLogMeta(req, { mode })); return res.status(401).json({ error: 'Authentication is required' }); } applyPrincipal(req, principal); - logger.debug('CodeAPI request authenticated', authLogMeta(req, { mode })); + logger.debug('CodeAPI request authenticated', buildAuthLogMeta(req, { mode })); next(); } catch (error) { if (error instanceof CodeApiJwtAuthError) { if (error.reason === 'config') { logger.error( - `JWT auth configuration failure request from ${req.ip}: ${error.message}`, - authLogMeta(req, { reason: error.reason, error }), + 'JWT auth configuration failure', + buildAuthLogMeta(req, { + reason: error.reason, + reasonSource: 'jwt', + error, + }), ); return res.status(500).json({ error: 'CodeAPI JWT auth is misconfigured' }); } logger.warn( - `JWT auth failure request from ${req.ip}: ${error.reason}`, - authLogMeta(req, { reason: error.reason }), + 'JWT authentication failed', + buildAuthLogMeta(req, { + reason: error.reason, + reasonSource: 'jwt', + error, + }), ); return res.status(401).json({ error: 'Invalid bearer token' }); } if (error instanceof AuthProviderConfigError) { logger.error( - `Auth provider configuration failure request from ${req.ip}: ${error.message}`, - authLogMeta(req, { error }), + 'Auth provider configuration failure', + buildAuthLogMeta(req, { error }), ); return res.status(500).json({ error: 'CodeAPI auth provider is misconfigured' }); } - logger.error(`CodeAPI authentication error request from ${req.ip}:`, authLogMeta(req, { error })); + logger.error('CodeAPI authentication error', buildAuthLogMeta(req, { error })); return res.status(401).json({ error: 'Authentication is required' }); } }; @@ -187,30 +187,38 @@ export const sessionAuth = async (req: AuthenticatedRequest, res: Response, next const { session_id, fileId } = req.params as { session_id?: string; fileId?: string }; if (!isValidId(session_id)) { - logger.error(`Invalid session ID: ${session_id}`); + logger.warn('Session authorization rejected', { + status: 400, + reason: 'invalid_session_id', + route: operationalRoute(req), + }); return res.status(400).json({ error: 'Bad request' }); } else if (fileId != null && fileId.length > 0 && !isValidId(fileId)) { - logger.error(`Invalid file ID: ${fileId}`); + logger.warn('Session authorization rejected', { + status: 400, + reason: 'invalid_file_id', + route: operationalRoute(req), + }); return res.status(400).json({ error: 'Bad request' }); } const userId = req.codeApiAuthContext?.userId ?? ''; if (!userId) { - logger.warn('Rejecting session auth without authContext.userId', authLogMeta(req)); + logger.warn('Rejecting session auth without authenticated user', buildAuthLogMeta(req)); return res.status(401).json({ error: 'User not found' }); } const { kind, id, version } = req.query; if (kind !== undefined && typeof kind !== 'string') { - logger.warn('Rejecting session auth with malformed kind query', authLogMeta(req)); + logger.warn('Rejecting session auth with malformed kind query', buildAuthLogMeta(req)); return res.status(400).json({ error: 'Bad request' }); } if (id !== undefined && typeof id !== 'string') { - logger.warn('Rejecting session auth with malformed id query', authLogMeta(req)); + logger.warn('Rejecting session auth with malformed id query', buildAuthLogMeta(req)); return res.status(400).json({ error: 'Bad request' }); } if (version !== undefined && typeof version !== 'string') { - logger.warn('Rejecting session auth with malformed version query', authLogMeta(req)); + logger.warn('Rejecting session auth with malformed version query', buildAuthLogMeta(req)); return res.status(400).json({ error: 'Bad request' }); } @@ -240,7 +248,11 @@ export const sessionAuth = async (req: AuthenticatedRequest, res: Response, next } const cachedSessionKey = await connection.get(`session:${session_id}`); if (cachedSessionKey !== sessionKey) { - logger.error(`Unauthorized download: Cached session key: ${cachedSessionKey} | Expected session key: ${sessionKey} | Session ID: ${session_id} | File ID: ${fileId}`); + logger.warn('Session authorization rejected', { + status: 403, + reason: 'session_key_mismatch', + route: operationalRoute(req), + }); return res.status(403).json({ error: 'Unauthorized' }); } diff --git a/service/src/middleware/limits.ts b/service/src/middleware/limits.ts index b16ed196..27cc3d83 100644 --- a/service/src/middleware/limits.ts +++ b/service/src/middleware/limits.ts @@ -1,5 +1,4 @@ // src/middleware/limits.ts -import { createHash } from 'crypto'; import rateLimitFactory from 'express-rate-limit'; import RateLimitRedisStore from 'rate-limit-redis'; import type { RateLimitRequestHandler } from 'express-rate-limit'; @@ -8,6 +7,7 @@ import type { NextFunction, Request, Response } from 'express'; import type { AuthenticatedRequest } from '../types'; import { env } from '../config'; import { getExecutionIdentity } from '../execution-identity'; +import { operationalPrincipalSource, operationalRoute } from '../operational-log'; import logger from '../logger'; type RedisCommandTarget = { @@ -58,12 +58,6 @@ const keySegment = (value: string | undefined, fallback = unknownPrincipal): str return trimmed ? trimmed.replace(/:/g, '_') : fallback; }; -const hashLabel = (value: string | undefined): string | undefined => { - const trimmed = value?.trim(); - if (!trimmed) return undefined; - return createHash('sha256').update(trimmed).digest('hex').slice(0, 12); -}; - export function setRateLimitRedisForTests(client?: RedisCommandTarget): void { redisCommands = client; } @@ -124,19 +118,17 @@ const buildRateLimiter = ( if (options.logRejections) { const authReq = req as AuthenticatedRequest; - const principal = authReq.codeApiPrincipal; const identity = getExecutionIdentity(authReq); const hasIdentity = Boolean(identity.canonicalUserId); logger.warn('CodeAPI rate limit rejected', { limiter: prefix, - path: req.originalUrl || req.path, + route: operationalRoute(req), retryAfterSeconds: retryAfter, limit: rateLimit?.limit ?? max, windowMs, - principalSource: hasIdentity ? identity.principalSource : undefined, - tenantHash: hasIdentity ? hashLabel(identity.storageNamespace) : undefined, - userHash: hasIdentity ? hashLabel(identity.canonicalUserId) : undefined, - credentialHash: hashLabel(principal?.credentialId), + principalSource: hasIdentity + ? operationalPrincipalSource(identity.principalSource) + : undefined, }); } diff --git a/service/src/middleware/request-error-logger.test.ts b/service/src/middleware/request-error-logger.test.ts index 9e473464..b0754594 100644 --- a/service/src/middleware/request-error-logger.test.ts +++ b/service/src/middleware/request-error-logger.test.ts @@ -44,7 +44,7 @@ afterEach(() => { }); describe('buildRequestErrorLogMeta', () => { - test('includes request path and auth context for session-key failures', () => { + test('keeps only values-free request classes for session-key failures', () => { process.env.CODEAPI_AUTH_PROVIDER = 'librechat-jwt'; const meta = buildRequestErrorLogMeta( @@ -55,46 +55,36 @@ describe('buildRequestErrorLogMeta', () => { expect(meta).toMatchObject({ status: 500, method: 'POST', - path: '/v1/exec', - requestId: 'req_123', - userAgent: 'unit-test', + route: 'v1.exec', authProvider: 'librechat-jwt', principalSource: 'librechat_jwt', - userId: 'user_123', - tenantId: 'tenant_abc', - authContextHash: 'hash_123', - }); - expect(meta.error).toMatchObject({ - name: 'SessionKeyResolutionError', - message: 'tenantId missing from auth context', + errorClass: 'session_key', }); + expect(JSON.stringify(meta)).not.toContain('user_123'); + expect(JSON.stringify(meta)).not.toContain('tenant_abc'); + expect(JSON.stringify(meta)).not.toContain('hash_123'); }); - test('keeps JWT auth failure reason observable', () => { + test('classifies JWT failures without retaining their messages', () => { const meta = buildRequestErrorLogMeta( new CodeApiJwtAuthError('malformed_claims', 'tenant_id is required'), request() as AuthenticatedRequest, ); expect(meta.status).toBe(401); - expect(meta.error).toMatchObject({ - name: 'CodeApiJwtAuthError', - message: 'tenant_id is required', - reason: 'malformed_claims', - }); + expect(meta.errorClass).toBe('authentication'); + expect(JSON.stringify(meta)).not.toContain('tenant_id is required'); }); }); describe('buildRequestNotFoundLogMeta', () => { - test('includes unmatched path and auth-header presence', () => { + test('classifies routes and keeps only auth-header presence', () => { const meta = buildRequestNotFoundLogMeta(request()); expect(meta).toMatchObject({ status: 404, method: 'POST', - path: '/v1/exec', - requestId: 'req_123', - userAgent: 'unit-test', + route: 'v1.exec', hasBearerToken: false, hasApiKeyHeader: false, hasSyntheticToken: false, diff --git a/service/src/middleware/request-error-logger.ts b/service/src/middleware/request-error-logger.ts index 304e6062..d4eaff9e 100644 --- a/service/src/middleware/request-error-logger.ts +++ b/service/src/middleware/request-error-logger.ts @@ -5,18 +5,13 @@ import { CodeApiJwtAuthError } from '../auth/librechat-jwt'; import { AuthProviderConfigError } from '../auth/provider'; import { hasSyntheticAccessToken } from '../auth/synthetic'; import logger from '../logger'; - -function serializeError(error: unknown): unknown { - if (error instanceof Error) { - return { - name: error.name, - message: error.message, - stack: error.stack, - ...(error instanceof CodeApiJwtAuthError ? { reason: error.reason } : {}), - }; - } - return error; -} +import { + operationalAuthProvider, + operationalErrorClass, + operationalMethod, + operationalPrincipalSource, + operationalRoute, +} from '../operational-log'; function statusFromError(error: unknown): number { if (error instanceof SessionKeyResolutionError) { @@ -39,37 +34,30 @@ function statusFromError(error: unknown): number { return 500; } -function requestPath(req: Request): string { - return req.originalUrl || req.path || req.url; -} - export function buildRequestErrorLogMeta(error: unknown, req: Request): Record { const authReq = req as AuthenticatedRequest; return { status: statusFromError(error), - method: req.method, - path: requestPath(req), - requestId: req.header('x-request-id') || req.header('x-correlation-id'), - userAgent: req.header('user-agent'), - ip: req.ip, - authProvider: process.env.CODEAPI_AUTH_PROVIDER || 'librechat-jwt', - principalSource: authReq.codeApiPrincipal?.principalSource, - userId: authReq.codeApiAuthContext?.userId, - tenantId: authReq.codeApiAuthContext?.tenantId, - authContextHash: authReq.codeApiAuthContext?.authContextHash, - error: serializeError(error), + method: operationalMethod(req.method), + route: operationalRoute(req), + authProvider: operationalAuthProvider( + process.env.CODEAPI_AUTH_PROVIDER || 'librechat-jwt', + ), + principalSource: operationalPrincipalSource( + authReq.codeApiPrincipal?.principalSource, + ), + errorClass: operationalErrorClass(error), }; } export function buildRequestNotFoundLogMeta(req: Request): Record { return { status: 404, - method: req.method, - path: requestPath(req), - requestId: req.header('x-request-id') || req.header('x-correlation-id'), - userAgent: req.header('user-agent'), - ip: req.ip, - authProvider: process.env.CODEAPI_AUTH_PROVIDER || 'librechat-jwt', + method: operationalMethod(req.method), + route: operationalRoute(req), + authProvider: operationalAuthProvider( + process.env.CODEAPI_AUTH_PROVIDER || 'librechat-jwt', + ), hasBearerToken: Boolean(req.header('Authorization')?.match(/^Bearer\s+(.+)$/i)?.[1]?.trim()), hasApiKeyHeader: Boolean(req.header('X-API-Key')), hasSyntheticToken: hasSyntheticAccessToken(req), diff --git a/service/src/openapi-contract.test.ts b/service/src/openapi-contract.test.ts new file mode 100644 index 00000000..b6c26557 --- /dev/null +++ b/service/src/openapi-contract.test.ts @@ -0,0 +1,192 @@ +import { YAML } from 'bun'; +import { readFileSync } from 'node:fs'; +import { resolve } from 'node:path'; +import { describe, expect, test } from 'bun:test'; +import type { ExecuteResponse, ExecuteResult } from './types/service'; + +type Schema = { + properties?: Record; + required?: string[]; +}; + +type Operation = { + responses: Record; +}; + +type OpenApiDocument = { + info: { title: string; description?: string }; + servers?: Array<{ url: string }>; + paths: Record>; + components: { + responses: Record< + string, + { + headers?: Record; + content?: { + 'application/json'?: { schema?: { $ref?: string } }; + }; + } + >; + schemas: Record; + }; + 'x-internal'?: boolean; +}; + +type IsExact = + (() => Value extends Left ? 1 : 2) extends + (() => Value extends Right ? 1 : 2) + ? true + : false; + +const publicResponseMatchesFlatResult: IsExact< + ExecuteResponse, + ExecuteResult +> = true; + +function loadSpec(path: string): OpenApiDocument { + return YAML.parse(readFileSync(path, 'utf8')) as OpenApiDocument; +} + +const publicSpecPath = resolve(import.meta.dir, '../openapi.yml'); +const internalSpecPath = resolve(import.meta.dir, '../../api/openapi.yaml'); + +describe('OpenAPI contract boundaries', () => { + test('the public execution type is the flat service result', () => { + expect(publicResponseMatchesFlatResult).toBe(true); + }); + + test('the public spec exposes the supported v1 routes', () => { + const spec = loadSpec(publicSpecPath); + + expect(spec.info.title).toContain('Public'); + expect(spec.servers?.[0]?.url.endsWith('/v1')).toBe(true); + expect(Object.keys(spec.paths).sort()).toEqual([ + '/download/{session_id}/{fileId}', + '/exec', + '/files/{session_id}', + '/files/{session_id}/{fileId}', + '/sessions/{session_id}/objects/{fileId}', + '/upload', + '/upload/batch', + ]); + expect(spec.paths).not.toHaveProperty('/api/v2/execute'); + expect(spec.paths).not.toHaveProperty('/execute'); + }); + + test('the public request and response schemas match the service types', () => { + const schemas = loadSpec(publicSpecPath).components.schemas; + const requestFile = schemas.RequestFile; + const executeResponse = schemas.ExecuteResponse; + const fileRef = schemas.FileRef; + const uploadResponse = schemas.UploadResponse; + + expect(requestFile.required?.sort()).toEqual([ + 'id', + 'kind', + 'name', + 'resource_id', + 'storage_session_id', + ]); + expect(Object.keys(requestFile.properties ?? {}).sort()).toEqual([ + 'id', + 'kind', + 'name', + 'resource_id', + 'storage_session_id', + 'version', + ]); + expect(executeResponse.required?.sort()).toEqual([ + 'files', + 'session_id', + 'stderr', + 'stdout', + ]); + expect(executeResponse.properties).not.toHaveProperty('run'); + expect(executeResponse.properties).not.toHaveProperty('compile'); + expect(executeResponse.properties).not.toHaveProperty('language'); + expect(executeResponse.properties).not.toHaveProperty('version'); + expect(fileRef.required?.sort()).toEqual(['id', 'name']); + expect(Object.keys(fileRef.properties ?? {}).sort()).toEqual([ + 'id', + 'inherited', + 'modified_from', + 'name', + 'path', + 'storage_session_id', + ]); + expect(uploadResponse.required?.sort()).toEqual([ + 'files', + 'message', + 'storage_session_id', + ]); + expect(uploadResponse.properties).not.toHaveProperty('session_id'); + }); + + test('the public spec documents rate limits and timeout responses', () => { + const spec = loadSpec(publicSpecPath); + const rateLimitHeaders = Object.keys( + spec.components.responses.GenericRateLimited.headers ?? {}, + ).sort(); + + expect(rateLimitHeaders).toEqual([ + 'RateLimit-Limit', + 'RateLimit-Remaining', + 'RateLimit-Reset', + 'Retry-After', + ]); + expect( + spec.components.responses.ExecutionRateLimited.content?.[ + 'application/json' + ]?.schema?.$ref, + ).toBe('#/components/schemas/RateLimitError'); + + for (const path of Object.values(spec.paths)) { + for (const operation of Object.values(path)) { + expect(operation.responses).toHaveProperty('429'); + } + } + expect(spec.paths['/exec'].post.responses).toHaveProperty('504'); + expect(spec.paths['/upload'].post.responses).toHaveProperty('504'); + }); + + test('the internal spec describes only the sandbox v2 execute contract', () => { + const spec = loadSpec(internalSpecPath); + const schemas = spec.components.schemas; + + expect(spec['x-internal']).toBe(true); + expect(spec.info.title).toContain('Internal'); + expect(Object.keys(spec.paths)).toEqual(['/api/v2/execute']); + expect(Object.keys(schemas.ExecuteRequest.properties ?? {}).sort()).toEqual([ + 'args', + 'compile_cpu_time', + 'compile_memory_limit', + 'compile_timeout', + 'egress_grant', + 'env_vars', + 'execution_manifest', + 'files', + 'language', + 'output_session_id', + 'run_cpu_time', + 'run_memory_limit', + 'run_timeout', + 'session_id', + 'stdin', + 'tool_call_socket', + 'version', + ]); + expect(schemas.ExecuteRequest.required?.sort()).toEqual([ + 'files', + 'language', + 'version', + ]); + expect(Object.keys(schemas.ExecuteResponse.properties ?? {}).sort()).toEqual([ + 'compile', + 'files', + 'language', + 'run', + 'session_id', + 'version', + ]); + }); +}); diff --git a/service/src/operational-log-capture.test.ts b/service/src/operational-log-capture.test.ts new file mode 100644 index 00000000..d4ffe8ec --- /dev/null +++ b/service/src/operational-log-capture.test.ts @@ -0,0 +1,138 @@ +import { createHash } from 'node:crypto'; +import { Writable } from 'node:stream'; +import { afterEach, describe, expect, test } from 'bun:test'; +import type { AuthenticatedRequest } from './types'; +import { createLogger, format, transports } from 'winston'; +import { buildAuthLogMeta } from './middleware/auth-log'; +import { buildRequestErrorLogMeta } from './middleware/request-error-logger'; +import { operationalErrorMeta } from './operational-log'; +import { summarizeSandboxResponse } from './execution-log'; + +const SENTINEL = 'PRIVATE_capture_9dQm2V7x'; +const originalProvider = process.env.CODEAPI_AUTH_PROVIDER; + +afterEach(() => { + if (originalProvider == null) { + delete process.env.CODEAPI_AUTH_PROVIDER; + } else { + process.env.CODEAPI_AUTH_PROVIDER = originalProvider; + } +}); + +function sentinelRequest(): AuthenticatedRequest { + return { + method: `CUSTOM-${SENTINEL}`, + originalUrl: `/private/${SENTINEL}`, + path: `/private/${SENTINEL}`, + url: `/private/${SENTINEL}`, + ip: SENTINEL, + header: (name: string) => { + const headers: Record = { + authorization: `Bearer ${SENTINEL}`, + 'user-agent': SENTINEL, + 'x-api-key': SENTINEL, + 'x-request-id': SENTINEL, + }; + return headers[name.toLowerCase()]; + }, + codeApiAuthContext: { + userId: SENTINEL, + tenantId: SENTINEL, + authContextHash: SENTINEL, + }, + codeApiPrincipal: { + userId: SENTINEL, + tenantId: SENTINEL, + principalSource: SENTINEL, + authContextHash: SENTINEL, + }, + } as unknown as AuthenticatedRequest; +} + +describe('Winston operational log capture', () => { + test('does not serialize client values or nested error details', async () => { + process.env.CODEAPI_AUTH_PROVIDER = 'librechat-jwt'; + const chunks: string[] = []; + const stream = new Writable({ + write(chunk, _encoding, callback) { + chunks.push(chunk.toString()); + callback(); + }, + }); + const captureLogger = createLogger({ + format: format.combine( + format.timestamp(), + format.errors({ stack: true }), + format.json(), + ), + transports: [new transports.Stream({ stream })], + }); + const error = { + name: 'AxiosError', + message: `failed for ${SENTINEL}`, + stack: `Error: ${SENTINEL}`, + code: SENTINEL, + filename: `${SENTINEL}.csv`, + output: SENTINEL, + nested: { response: { data: SENTINEL } }, + }; + const req = sentinelRequest(); + + captureLogger.warn( + 'Synthetic auth rejection', + buildAuthLogMeta(req, { + error, + mode: SENTINEL, + reason: SENTINEL, + reasonSource: 'jwt', + }), + ); + captureLogger.error( + 'Synthetic request failure', + buildRequestErrorLogMeta(error, req), + ); + captureLogger.error('Synthetic execution failure', { + route: 'v1.exec.programmatic', + status: 500, + durationMs: 12, + fileCount: 1, + bytes: 128, + ...operationalErrorMeta(error), + }); + captureLogger.info( + 'Synthetic sandbox response', + summarizeSandboxResponse({ + session_id: SENTINEL, + language: SENTINEL, + version: SENTINEL, + files: [{ id: SENTINEL, name: `${SENTINEL}.csv` }], + run: { + code: 0, + message: SENTINEL, + stdout: SENTINEL, + stderr: SENTINEL, + output: SENTINEL, + wall_time: 12, + }, + }), + ); + captureLogger.end(); + await new Promise(resolve => captureLogger.on('finish', resolve)); + + const captured = chunks.join(''); + expect(captured).toContain('v1.exec.programmatic'); + expect(captured).toContain('durationMs'); + expect(captured).toContain('fileCount'); + expect(captured).toContain('languageClass'); + expect(captured).toContain('stdout'); + expect(captured).toContain('upstream_http'); + for (const variant of [ + SENTINEL, + encodeURIComponent(SENTINEL), + Buffer.from(SENTINEL).toString('base64'), + createHash('sha256').update(SENTINEL).digest('hex'), + ]) { + expect(captured).not.toContain(variant); + } + }); +}); diff --git a/service/src/operational-log.test.ts b/service/src/operational-log.test.ts new file mode 100644 index 00000000..b3271629 --- /dev/null +++ b/service/src/operational-log.test.ts @@ -0,0 +1,59 @@ +import { createHash } from 'node:crypto'; +import { describe, expect, test } from 'bun:test'; +import type { Request } from 'express'; +import { + operationalAuthReason, + operationalErrorMeta, + operationalMethod, + operationalPrincipalSource, + operationalRoute, +} from './operational-log'; + +const SENTINEL = 'PRIVATE_user-file_9dQm2V7x'; + +function request(path: string, method = 'GET'): Request { + return { + method, + originalUrl: path, + path, + url: path, + } as Request; +} + +describe('operational log classification', () => { + test('maps dynamic and unknown paths to fixed route classes', () => { + expect( + operationalRoute(request(`/v1/download/${SENTINEL}/${SENTINEL}`)), + ).toBe('v1.download'); + expect(operationalRoute(request(`/unmatched/${SENTINEL}`))).toBe('unmatched'); + expect(operationalMethod(`CUSTOM-${SENTINEL}`)).toBe('OTHER'); + }); + + test('does not retain raw, encoded, hashed, nested, or stack sentinels', () => { + const error = { + name: 'AxiosError', + message: `failed for ${SENTINEL}`, + stack: `Error: ${SENTINEL}`, + nested: { response: { data: SENTINEL } }, + }; + const serialized = JSON.stringify(operationalErrorMeta(error)); + const variants = [ + SENTINEL, + encodeURIComponent(SENTINEL), + Buffer.from(SENTINEL).toString('base64'), + createHash('sha256').update(SENTINEL).digest('hex'), + ]; + + expect(serialized).toBe('{"errorClass":"upstream_http"}'); + for (const variant of variants) { + expect(serialized).not.toContain(variant); + } + }); + + test('keeps only allowlisted auth reasons and principal sources', () => { + expect(operationalAuthReason('wrong_issuer', 'jwt')).toBe('wrong_issuer'); + expect(operationalAuthReason(SENTINEL, 'jwt')).toBe('other'); + expect(operationalPrincipalSource('klicker_jwt')).toBe('klicker_jwt'); + expect(operationalPrincipalSource(SENTINEL)).toBe('other'); + }); +}); diff --git a/service/src/operational-log.ts b/service/src/operational-log.ts new file mode 100644 index 00000000..785b8d2b --- /dev/null +++ b/service/src/operational-log.ts @@ -0,0 +1,134 @@ +import type { Request } from 'express'; + +const JWT_REASONS = new Set([ + 'bad_signature', + 'config', + 'expired', + 'future_iat', + 'malformed', + 'malformed_claims', + 'not_yet_valid', + 'ttl_too_long', + 'unknown_kid', + 'wrong_alg', + 'wrong_audience', + 'wrong_issuer', +]); + +const SYNTHETIC_REASONS = new Set([ + 'invalid_token', + 'missing_config', + 'not_allowed', + 'weak_config', +]); + +function requestPath(req: Request): string { + return (req.originalUrl || req.path || req.url || '').split('?')[0] ?? ''; +} + +export function operationalRoute(req: Request): string { + const path = requestPath(req); + if (/^(?:\/v1)?\/exec\/?$/.test(path)) return 'v1.exec'; + if (/^(?:\/v1)?\/exec\/programmatic\/?$/.test(path)) { + return 'v1.exec.programmatic'; + } + if (/^(?:\/v1)?\/upload\/batch\/?$/.test(path)) return 'v1.upload.batch'; + if (/^(?:\/v1)?\/upload\/?$/.test(path)) return 'v1.upload'; + if (/^(?:\/v1)?\/download\/[^/]+\/[^/]+\/?$/.test(path)) { + return 'v1.download'; + } + if (/^(?:\/v1)?\/files\/[^/]+\/[^/]+\/?$/.test(path)) { + return req.method.toUpperCase() === 'DELETE' ? 'v1.files.delete' : 'v1.files.object'; + } + if (/^(?:\/v1)?\/files\/[^/]+\/?$/.test(path)) return 'v1.files.list'; + if (/^(?:\/v1)?\/sessions\/[^/]+\/objects\/[^/]+\/?$/.test(path)) { + return 'v1.files.metadata'; + } + if (/^\/v1\/health\/?$/.test(path)) return 'v1.health'; + return 'unmatched'; +} + +export function operationalMethod(method: string | undefined): string { + switch (method?.toUpperCase()) { + case 'DELETE': + case 'GET': + case 'HEAD': + case 'OPTIONS': + case 'PATCH': + case 'POST': + case 'PUT': + return method.toUpperCase(); + default: + return 'OTHER'; + } +} + +export function operationalAuthProvider(value: unknown): string { + return value === 'none' || value === 'librechat-jwt' ? value : 'invalid'; +} + +export function operationalPrincipalSource(value: unknown): string | undefined { + switch (value) { + case 'klicker_jwt': + case 'librechat_jwt': + case 'none': + case 'openid_reuse': + case 'synthetic_test': + return value; + default: + return value == null ? undefined : 'other'; + } +} + +export function operationalAuthReason( + value: unknown, + source: 'jwt' | 'synthetic', +): string { + const allowed = source === 'jwt' ? JWT_REASONS : SYNTHETIC_REASONS; + return typeof value === 'string' && allowed.has(value) ? value : 'other'; +} + +export function operationalErrorClass(error: unknown): string { + const value = error as { name?: unknown; code?: unknown; message?: unknown } | null; + const name = typeof value?.name === 'string' ? value.name : ''; + switch (name) { + case 'AbortError': + return 'aborted'; + case 'AuthProviderConfigError': + case 'CodeApiJwtAuthError': + return 'authentication'; + case 'AxiosError': + return 'upstream_http'; + case 'ExecutionStateTooLargeError': + return 'capacity'; + case 'FileRefAuthorizationError': + return 'authorization'; + case 'SessionKeyResolutionError': + return 'session_key'; + case 'SyntaxError': + case 'TypeError': + return 'invalid_state'; + } + + switch (value?.code) { + case 'ABORT_ERR': + return 'aborted'; + case 'ECONNREFUSED': + case 'ECONNRESET': + case 'ENETUNREACH': + case 'ENOTFOUND': + case 'EPIPE': + return 'dependency'; + case 'ETIMEDOUT': + return 'timeout'; + } + + const message = typeof value?.message === 'string' ? value.message.toLowerCase() : ''; + if (message.includes('timed out') || message.includes('timeout')) return 'timeout'; + if (message.includes('abort')) return 'aborted'; + return 'unexpected'; +} + +export function operationalErrorMeta(error: unknown): { errorClass: string } { + return { errorClass: operationalErrorClass(error) }; +} diff --git a/service/src/queue.ts b/service/src/queue.ts index dfc91680..6aada413 100644 --- a/service/src/queue.ts +++ b/service/src/queue.ts @@ -12,21 +12,22 @@ import logger from './logger'; import { redisKeepAliveOptions } from './redis-options'; import { bullmqQueueJobs, registerBullmqQueueMetricsCollector } from './metrics'; import { waitForJobFinished } from './queue-wait'; +import { operationalErrorMeta } from './operational-log'; const MAX_RECONNECT_ATTEMPTS = 5; const RECONNECT_DELAY = 2000; const retryStrategy: CommonRedisOptions['retryStrategy'] = (times) => { if (times > MAX_RECONNECT_ATTEMPTS) { - logger.error(`Failed to connect to Redis after ${times} attempts`); + logger.error('Failed to connect to Redis', { attempts: times }); return null; } - logger.warn(`Retrying Redis connection attempt ${times}`); + logger.warn('Retrying Redis connection', { attempt: times }); return RECONNECT_DELAY; }; const reconnectOnError: CommonRedisOptions['reconnectOnError'] = (err) => { - logger.error('Redis connection error:', err); + logger.error('Redis connection error', operationalErrorMeta(err)); const targetError = 'READONLY'; if (err.message.includes(targetError)) { return true; @@ -70,8 +71,8 @@ const otherQueueEvents = new QueueEvents(queueNames.other, { connection }); const queueMetricStates = ['waiting', 'active', 'delayed'] as const; const queueMetricSources = [ - { name: queueNames.python, queue: pyQueue }, - { name: queueNames.other, queue: otherQueue }, + { name: queueNames.python, queue: pyQueue, queueClass: 'python' }, + { name: queueNames.other, queue: otherQueue, queueClass: 'other' }, ] as const; const QUEUE_METRICS_TIMEOUT_MS = 1000; @@ -91,7 +92,7 @@ async function withTimeout(promise: Promise, timeoutMs: number, message: s } registerBullmqQueueMetricsCollector(async () => { - await Promise.all(queueMetricSources.map(async ({ name, queue }) => { + await Promise.all(queueMetricSources.map(async ({ name, queue, queueClass }) => { try { const counts = await withTimeout( queue.getJobCounts(...queueMetricStates), @@ -102,7 +103,10 @@ registerBullmqQueueMetricsCollector(async () => { bullmqQueueJobs.set({ queue: name, state }, counts[state] ?? 0); } } catch (error) { - logger.warn('Failed to collect BullMQ queue metrics', { queue: name, error }); + logger.warn('Failed to collect BullMQ queue metrics', { + queueClass, + ...operationalErrorMeta(error), + }); for (const state of queueMetricStates) { bullmqQueueJobs.remove({ queue: name, state }); } diff --git a/service/src/runtime-session/checkpoint.ts b/service/src/runtime-session/checkpoint.ts index 3562cd17..1d044457 100644 --- a/service/src/runtime-session/checkpoint.ts +++ b/service/src/runtime-session/checkpoint.ts @@ -20,6 +20,7 @@ import { checkpointObjectKey } from './checkpoint-store'; import { microvmCheckpoints, microvmRestores, microvmCheckpointBytes } from '../metrics'; import { CHECKPOINT_METADATA_TIMEOUT_CAP_MS } from '../config'; import logger from '../logger'; +import { operationalErrorMeta } from '../operational-log'; /** Reject if `promise` doesn't settle within `ms`, so a stalled metadata leg * cannot hold the session lock. The production S3-compatible store separately @@ -301,8 +302,7 @@ export async function checkpointSession(args: { markerCommitted = true; }).catch(error => { logger.warn('Checkpoint commit marker failed; Redis pointer remains authoritative', { - runtimeSessionId: args.runtimeSessionId, - error: error instanceof Error ? error.message : String(error), + ...operationalErrorMeta(error), }); }); /* Never prune the previous durable recovery point unless the new marker @@ -311,8 +311,7 @@ export async function checkpointSession(args: { if (markerCommitted) { void args.store.pruneOlderThan(args.runtimeSessionId, sequence).catch(error => { logger.warn('Checkpoint garbage collection failed', { - runtimeSessionId: args.runtimeSessionId, - error: error instanceof Error ? error.message : String(error), + ...operationalErrorMeta(error), }); }); } @@ -322,8 +321,7 @@ export async function checkpointSession(args: { } catch (error) { microvmCheckpoints.inc({ outcome: 'failed' }); logger.warn('Session checkpoint failed', { - runtimeSessionId: args.runtimeSessionId, - error: error instanceof Error ? error.message : String(error), + ...operationalErrorMeta(error), }); return 'failed'; } finally { @@ -363,8 +361,7 @@ export async function restoreSession(args: { * this VM. */ microvmRestores.inc({ outcome: 'failed' }); logger.warn('Checkpoint fetch failed; refusing to run with an empty workspace', { - runtimeSessionId: args.runtimeSessionId, - error: error instanceof Error ? error.message : String(error), + ...operationalErrorMeta(error), }); return 'fetch_failed'; } @@ -381,7 +378,6 @@ export async function restoreSession(args: { }, data, args.config); microvmRestores.inc({ outcome: 'restored' }); logger.info('Session workspace restored from checkpoint', { - runtimeSessionId: args.runtimeSessionId, bytes: data.size, }); return 'restored'; @@ -392,8 +388,7 @@ export async function restoreSession(args: { * execute against it. */ microvmRestores.inc({ outcome: 'failed' }); logger.warn('Checkpoint push-restore failed; the VM workspace may be partial', { - runtimeSessionId: args.runtimeSessionId, - error: error instanceof Error ? error.message : String(error), + ...operationalErrorMeta(error), }); return 'push_failed'; } finally { diff --git a/service/src/runtime-session/files.ts b/service/src/runtime-session/files.ts index f17998dd..5ff7aedb 100644 --- a/service/src/runtime-session/files.ts +++ b/service/src/runtime-session/files.ts @@ -9,7 +9,7 @@ import { Readable, Transform } from 'stream'; import { pipeline } from 'stream/promises'; import type * as t from '../types'; import { internalServiceHeaders } from '../internal-service-auth'; -import { getAxiosErrorDetails } from '../utils'; +import { operationalErrorMeta } from '../operational-log'; import { env } from '../config'; import logger from '../logger'; @@ -180,7 +180,7 @@ export async function buildInputBatch( ); } if (error instanceof SessionFilesError) throw error; - logger.error('Failed to prepare session input batch:', getAxiosErrorDetails(error)); + logger.error('Failed to prepare session input batch', operationalErrorMeta(error)); throw new SessionFilesError( 'SESSION_INPUT_PREPARATION_FAILED', 'Failed to prepare session input batch', @@ -242,9 +242,9 @@ async function fetchFileObjectToPath( 'Session input delivery aborted', ); } - /* Sanitized details only: a raw axios error carries the request config — - * including the internal service token header — straight into the logs. */ - logger.error(`Failed to fetch session input ${ref.id}:`, getAxiosErrorDetails(error)); + /* Keep the raw axios error out of logs: its request config includes the + * internal service token header and the file reference is linkable. */ + logger.error('Failed to fetch session input', operationalErrorMeta(error)); const status = axios.isAxiosError(error) ? error.response?.status : undefined; throw new SessionFilesError( status != null && status >= 400 && status < 500 diff --git a/service/src/runtime-session/registry.ts b/service/src/runtime-session/registry.ts index f8d66507..a29b309d 100644 --- a/service/src/runtime-session/registry.ts +++ b/service/src/runtime-session/registry.ts @@ -6,6 +6,7 @@ import { RUNTIME_SESSION_REDIS_COMMAND_TIMEOUT_MS, } from '../config'; import logger from '../logger'; +import { operationalErrorMeta } from '../operational-log'; export { RUNTIME_SESSION_REDIS_COMMAND_TIMEOUT_MS } from '../config'; @@ -421,8 +422,7 @@ export async function releaseRuntimeSessionLock( * the token-guarded lease must age out. The Lua release is idempotent, so a * retry is safe even if Redis deleted the key but lost the first response. */ logger.warn('Failed to release runtime session lock after retries', { - runtimeSessionId, - err: lastError, + ...operationalErrorMeta(lastError), }); } @@ -459,7 +459,7 @@ export async function renewRuntimeSessionLock( ); return result === 1 ? 'held' : 'lost'; } catch (err) { - logger.warn('Failed to renew runtime session lock', { runtimeSessionId, err }); + logger.warn('Failed to renew runtime session lock', operationalErrorMeta(err)); return 'error'; } } @@ -479,7 +479,7 @@ export async function readRuntimeSessionRecord( try { return JSON.parse(data) as RuntimeSessionRecord; } catch (err) { - logger.warn('Discarding malformed runtime session record', { runtimeSessionId, err }); + logger.warn('Discarding malformed runtime session record', operationalErrorMeta(err)); return null; } } diff --git a/service/src/sandbox-backend/lambda-microvm.ts b/service/src/sandbox-backend/lambda-microvm.ts index 1cb8a4dd..4677387a 100644 --- a/service/src/sandbox-backend/lambda-microvm.ts +++ b/service/src/sandbox-backend/lambda-microvm.ts @@ -40,6 +40,23 @@ import { SandboxBackendError } from './types'; import { Jobs } from '../enum'; import { checkpointPipelineBudgetMs } from '../config'; import logger from '../logger'; +import { operationalErrorMeta } from '../operational-log'; + +function operationalMicrovmReason(reason: string): string { + switch (reason) { + case 'error': + case 'fenced': + case 'result_finalization_failed': + case 'session_binding_conflict': + case 'stateless': + case 'superseded': + case 'timeout': + case 'workspace_dirty': + return reason; + default: + return 'other'; + } +} /** Header that opts a proxied /execute into the runner's persistent session * workspace (see api/src/session-workspace.ts). Session mode is delivered @@ -612,9 +629,7 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { ); if (!quarantined) { logger.warn('Lost session lock while quarantining a mutated MicroVM', { - runtimeSessionId, - microvmId: vm.microvmId, - reason, + reason: operationalMicrovmReason(reason), }); } } @@ -625,10 +640,8 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { * fenced write skip teardown of a VM whose uncommitted workspace was * already mutated. */ logger.error('Failed to quarantine a mutated MicroVM in the session registry', { - runtimeSessionId, - microvmId: vm.microvmId, - reason, - error, + reason: operationalMicrovmReason(reason), + ...operationalErrorMeta(error), }); } @@ -651,9 +664,7 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { ); if (!terminal) { logger.warn('Lost session lock after recycling a mutated MicroVM', { - runtimeSessionId, - microvmId: vm.microvmId, - reason, + reason: operationalMicrovmReason(reason), }); } } catch (error) { @@ -661,10 +672,8 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { * record remains non-reusable with its prior checkpoint pointer intact. * Preserve the primary execution/finalization error. */ logger.error('Failed to mark a recycled MicroVM terminal in the session registry', { - runtimeSessionId, - microvmId: vm.microvmId, - reason, - error, + reason: operationalMicrovmReason(reason), + ...operationalErrorMeta(error), }); } } @@ -707,14 +716,11 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { timeoutMs: RUNTIME_SESSION_REDIS_CLEANUP_TIMEOUT_MS, }); if (!retired) { - logger.warn('Lost session lock while retiring an exhausted launch intent', { - runtimeSessionId: launchIntent.runtime_session_id, - }); + logger.warn('Lost session lock while retiring an exhausted launch intent'); } } catch (cleanupError) { logger.warn('Failed to retire an exhausted launch intent', { - runtimeSessionId: launchIntent.runtime_session_id, - error: cleanupError, + ...operationalErrorMeta(cleanupError), }); } } @@ -1205,7 +1211,6 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { ); } logger.info('Session input delivery', { - microvmId: vm.microvmId, refs: refs.length, missing: missing.length, }); @@ -1438,7 +1443,8 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { * original would hand back the same dead VM. The retry consumes only the * first attempt's remaining launch budget. */ logger.warn( - `[${ctx.executionId}] MicroVM died during boot (${retryableError.message}); retrying launch once`, + 'MicroVM died during boot; retrying launch once', + operationalErrorMeta(retryableError), ); microvmLaunches.inc({ outcome: 'retried' }); try { @@ -1630,7 +1636,10 @@ export class LambdaMicrovmSandboxBackend implements SandboxBackend { microvmTerminations.inc({ reason }); return true; } - logger.error('Failed to terminate MicroVM', { microvmId, reason, error }); + logger.error('Failed to terminate MicroVM', { + reason: operationalMicrovmReason(reason), + ...operationalErrorMeta(error), + }); return false; } } diff --git a/service/src/sandbox-backend/types.ts b/service/src/sandbox-backend/types.ts index 75d7f1af..2aa1988f 100644 --- a/service/src/sandbox-backend/types.ts +++ b/service/src/sandbox-backend/types.ts @@ -49,10 +49,10 @@ export interface SandboxExecuteContext { } /** Raw sandbox response, pre-gateway-restore. */ -export type SandboxRawResponse = t.ExecuteResponse & { +export type SandboxRawResponse = t.SandboxExecuteResponse & { session_id: string; files?: t.FileRefs; - run?: t.ExecuteResponse['run']; + run?: t.SandboxExecuteResponse['run']; }; export interface SandboxBackend { diff --git a/service/src/service-api.ts b/service/src/service-api.ts index ec15b1ac..63af984a 100644 --- a/service/src/service-api.ts +++ b/service/src/service-api.ts @@ -8,6 +8,7 @@ import programmaticRouter from './service/programmatic-router'; import { connection } from './queue'; import { env } from './config'; import logger from './logger'; +import { operationalErrorMeta } from './operational-log'; const app = express(); app.disable('x-powered-by'); @@ -23,7 +24,7 @@ app.get('/v1/health', async (_, res) => { await connection.ping(); res.sendStatus(200); } catch (error) { - logger.error('Health check failed:', error); + logger.error('Health check failed', operationalErrorMeta(error)); res.sendStatus(503); } }); @@ -46,10 +47,10 @@ process.on('SIGUSR2', gracefulShutdown); // For nodemon restarts // Improve your existing handlers process.on('uncaughtException', async (error) => { - logger.error('Uncaught Exception', error); + logger.error('Uncaught exception', operationalErrorMeta(error)); await gracefulShutdown(); }); process.on('unhandledRejection', (reason) => { - logger.error('Unhandled Rejection', reason); + logger.error('Unhandled rejection', operationalErrorMeta(reason)); }); diff --git a/service/src/service/file-authorization.test.ts b/service/src/service/file-authorization.test.ts index 4d98c59f..713b832b 100644 --- a/service/src/service/file-authorization.test.ts +++ b/service/src/service/file-authorization.test.ts @@ -176,11 +176,7 @@ describe('validateRequestedFiles', () => { expect(() => validateRequestedFiles([broken])).toThrow(/version is only valid/); }); - /* Diagnostic context — the warn log lives or dies by `error.context`. - * Pre-fix the validator threw context-free 400s, so log lines like - * "files[0].resource_id is invalid" gave operators no offending value - * to act on. These lock the contract. */ - test('attaches index, field, type, length, value to the rejection context', () => { + test('keeps only type and size evidence in rejection context', () => { const broken = validFile({ resource_id: 'has space' }); try { validateRequestedFiles([broken]); @@ -193,8 +189,9 @@ describe('validateRequestedFiles', () => { field: 'resource_id', type: 'string', length: 9, - value: 'has space', }); + expect(e.context).not.toHaveProperty('value'); + expect(e.context).not.toHaveProperty('sample'); } }); @@ -212,7 +209,7 @@ describe('validateRequestedFiles', () => { } }); - test('overlong string is sampled head…tail rather than dumped whole', () => { + test('overlong string reports length without a sample', () => { const longBad = `${'a'.repeat(100)} ${'b'.repeat(100)}`; // space → fails regex const broken = validFile({ resource_id: longBad }); try { @@ -222,8 +219,7 @@ describe('validateRequestedFiles', () => { const e = err as FileRefAuthorizationError; expect(e.context).not.toHaveProperty('value'); expect(e.context.length).toBe(longBad.length); - expect(typeof e.context.sample).toBe('string'); - expect((e.context.sample as string).length).toBeLessThan(longBad.length); + expect(e.context).not.toHaveProperty('sample'); } }); }); diff --git a/service/src/service/file-authorization.ts b/service/src/service/file-authorization.ts index 4afa2c85..765bbd76 100644 --- a/service/src/service/file-authorization.ts +++ b/service/src/service/file-authorization.ts @@ -8,14 +8,6 @@ const MAX_FILE_REF_NAME_LENGTH = 256; const MAX_FILE_REF_NESTING_DEPTH = 10; const KNOWN_KINDS = new Set(CODE_ENV_KINDS); -/* Diagnostic redaction bounds for `describeValue`. Short strings - * (≤64 chars — typical id/slug shapes) inline whole; longer ones - * become a head…tail sample so logs can distinguish "wrong shape" - * from "wrong char" without dumping unbounded user input. */ -const REDACT_INLINE_THRESHOLD = 64; -const REDACT_PREFIX_LEN = 32; -const REDACT_SUFFIX_LEN = 16; - type FileRefStore = { get(key: string): Promise; exists(key: string): Promise; @@ -55,14 +47,7 @@ function describeValue(value: unknown): Record { return { type }; } const s = value as string; - if (s.length <= REDACT_INLINE_THRESHOLD) { - return { type, length: s.length, value: s }; - } - return { - type, - length: s.length, - sample: `${s.slice(0, REDACT_PREFIX_LEN)}…${s.slice(-REDACT_SUFFIX_LEN)}`, - }; + return { type, length: s.length }; } function failValidation(message: string, context: Record): never { @@ -226,18 +211,6 @@ export async function authorizeRequestedFiles(args: { 403, 'Unauthorized file reference', 'session_key_mismatch', - { - file: { - id: file.id, - resource_id: file.resource_id, - storage_session_id: file.storage_session_id, - name: file.name, - kind: file.kind, - version: file.version, - }, - resolvedSessionKey: sessionKey, - cachedSessionKey, - }, ); } @@ -253,18 +226,6 @@ export async function authorizeRequestedFiles(args: { 403, 'Unauthorized file reference', 'upload_missing', - { - file: { - id: file.id, - resource_id: file.resource_id, - storage_session_id: file.storage_session_id, - name: file.name, - kind: file.kind, - version: file.version, - }, - resolvedSessionKey: sessionKey, - uploadKey, - }, ); } } diff --git a/service/src/service/programmatic-router.ts b/service/src/service/programmatic-router.ts index dd0d72f3..5b33632b 100644 --- a/service/src/service/programmatic-router.ts +++ b/service/src/service/programmatic-router.ts @@ -36,6 +36,11 @@ import { findUnregisteredToolCall } from '../tool-scope'; import { summarizeRequestedFiles } from '../execution-log'; import { FileRefAuthorizationError, authorizeRequestedFiles } from './file-authorization'; import { buildReplayExecutionState } from './programmatic-state'; +import { + operationalErrorMeta, + operationalMethod, + operationalRoute, +} from '../operational-log'; import logger from '../logger'; import { type ExecutionState, @@ -59,7 +64,6 @@ import { validateContinuationBatch, } from './replay-state'; -const { INSTANCE_ID } = env; const POLL_INTERVAL = 100; // ms (blocking mode only) const MAX_POLL_TIME = 300000; // 5 minutes (blocking mode only) const TOOL_CALL_SERVER_RETRY_ATTEMPTS = 3; @@ -84,11 +88,7 @@ function sendFileRefAuthorizationError( logger.warn('File reference authorization rejected', { status: error.status, reason: error.reason, - message: error.message, - requestUserId: req?.codeApiAuthContext?.userId, - requestApiKeyId: req ? getCredentialId(req) : undefined, - tenantId: req?.codeApiAuthContext?.tenantId, - ...error.context, + route: req == null ? 'v1.exec.programmatic' : operationalRoute(req), }); res.status(error.status).json({ error: error.message }); return true; @@ -108,14 +108,14 @@ function sendSessionKeyResolutionError( context: string, ): boolean { if (error instanceof SessionKeyResolutionError) { - logger.error(`sessionKey resolution failed (${context})`, { + logger.error('Session key resolution failed', { status: error.status, - message: error.message, - method: req.method, - path: req.path, - requestUserId: req.codeApiAuthContext?.userId, - authContextUserId: req.codeApiAuthContext?.userId, - tenantId: req.codeApiAuthContext?.tenantId, + stage: context.includes('blocking') + ? 'resolve_blocking_output_bucket' + : 'resolve_replay_output_bucket', + method: operationalMethod(req.method), + route: operationalRoute(req), + ...operationalErrorMeta(error), }); res.status(error.status).json({ error: error.message }); return true; @@ -128,6 +128,15 @@ async function retryToolCallServerRequest( context: string, ): Promise { let lastError: Error | undefined; + const operation = context === 'Get pending tool calls' + ? 'get_pending_calls' + : context === 'Get execution status' + ? 'get_execution_status' + : context === 'Submit tool results' + ? 'submit_results' + : context === 'Create Tool Call Server session' + ? 'create_session' + : 'other'; for (let attempt = 1; attempt <= TOOL_CALL_SERVER_RETRY_ATTEMPTS; attempt++) { try { @@ -140,15 +149,24 @@ async function retryToolCallServerRequest( } } if (attempt < TOOL_CALL_SERVER_RETRY_ATTEMPTS) { - logger.warn(`${context} failed (attempt ${attempt}/${TOOL_CALL_SERVER_RETRY_ATTEMPTS}), retrying...`, { - error: lastError.message, + logger.warn('Tool Call Server request failed; retrying', { + route: 'v1.exec.programmatic', + operation, + attempt, + maxAttempts: TOOL_CALL_SERVER_RETRY_ATTEMPTS, + ...operationalErrorMeta(error), }); await new Promise(resolve => setTimeout(resolve, TOOL_CALL_SERVER_RETRY_DELAY * attempt)); } } } - logger.error(`${context} failed after ${TOOL_CALL_SERVER_RETRY_ATTEMPTS} attempts`); + logger.error('Tool Call Server request failed after retries', { + route: 'v1.exec.programmatic', + operation, + attempts: TOOL_CALL_SERVER_RETRY_ATTEMPTS, + ...operationalErrorMeta(lastError), + }); throw lastError; } @@ -158,7 +176,10 @@ async function retryToolCallServerRequest( * timer the test process would have to clean up. */ setInterval(() => { cleanupStaleExecutions().catch(err => { - logger.error('Cleanup interval error:', err); + logger.error('Programmatic cleanup interval failed', { + route: 'v1.exec.programmatic', + ...operationalErrorMeta(err), + }); }); }, STALE_CLEANUP_INTERVAL_MS); @@ -388,7 +409,7 @@ async function runReplayIteration( if (DEBUG_MODE) { const firstFile = rawPayload.files[0] as { content?: string } | undefined; logger.debug('Replay enqueue details', { - execution_id: state.execution_id, + route: 'v1.exec.programmatic', historySize: Object.keys(history).length, callCount: state.callCount ?? 0, toolCount: (state.tools ?? []).length, @@ -442,12 +463,7 @@ async function handleReplayInitial( }, ): Promise { const { apiKeyId, userId } = params; - const { - code, - tools, - user_id, - files, - } = req.body as t.ProgrammaticRequestBody; + const { code, tools, files } = req.body as t.ProgrammaticRequestBody; let timeout: number; try { timeout = normalizeProgrammaticTimeoutMs((req.body as t.ProgrammaticRequestBody).timeout); @@ -519,7 +535,10 @@ async function handleReplayInitial( (req.body as t.ProgrammaticRequestBody).files = authorizedFiles.length > 0 ? authorizedFiles : undefined; } catch (error) { if (sendFileRefAuthorizationError(error, res, req)) return; - logger.error('Error authorizing replay file refs:', error); + logger.error('Replay file reference authorization failed', { + route: 'v1.exec.programmatic', + ...operationalErrorMeta(error), + }); res.status(500).json({ error: 'Internal server error' }); return; } @@ -572,9 +591,7 @@ async function handleReplayInitial( } catch (err) { if (err instanceof ExecutionStateTooLargeError) { logger.warn('Rejecting replay request: ExecutionState exceeds Redis cap', { - execution_id, - userId, - apiKeyId, + route: 'v1.exec.programmatic', bytes: err.bytes, cap: err.cap, }); @@ -589,16 +606,12 @@ async function handleReplayInitial( } logger.info('Programmatic execution request received (replay)', { - userId, - apiKeyId, - user: user_id, - session_id, - execution_id, + route: 'v1.exec.programmatic', + mode: 'replay', language, toolCount: tools.length, codeLength: code.length, files: summarizeRequestedFiles(authorizedFiles), - sessionKey, timeout, }); @@ -708,13 +721,9 @@ async function handleReplayContinuation( if (!pre.ok) { if (pre.status === 403) { logger.warn('Unauthorized replay continuation request rejected', { - execution_id: state.execution_id, - requestUserId: userId, - requestApiKeyId: apiKeyId, - requestTenantId: identity.storageNamespace, - executionUserId: state.userId, - executionApiKeyId: state.apiKeyId, - executionTenantId: state.tenantId, + route: 'v1.exec.programmatic', + mode: 'replay', + status: 403, }); } if (pre.cleanupOnReject === true) { @@ -725,7 +734,8 @@ async function handleReplayContinuation( } logger.info('Replay continuation received', { - execution_id: state.execution_id, + route: 'v1.exec.programmatic', + mode: 'replay', resultCount: validatedResults.length, newCallCount: delta.newCallIds.length, prevCallCount: state.callCount ?? 0, @@ -753,7 +763,8 @@ async function handleReplayContinuation( * old execution to free the lock and Redis keys, then return * an actionable 413 instead of a generic 500. */ logger.warn('Replay continuation rejected: ExecutionState exceeds Redis cap', { - execution_id: state.execution_id, + route: 'v1.exec.programmatic', + mode: 'replay', bytes: err.bytes, cap: err.cap, callCount: state.callCount, @@ -781,8 +792,9 @@ async function handleReplayContinuation( * 500 — clients (and load balancers) treat 5xx classes very * differently for retry policy. */ logger.error('Failed to commit replay continuation; returning retryable 503', { - execution_id: state.execution_id, - err: (err as Error).message, + route: 'v1.exec.programmatic', + mode: 'replay', + ...operationalErrorMeta(err), }); res.status(503).json({ status: 'error', @@ -793,7 +805,8 @@ async function handleReplayContinuation( } if (delta.newCallIds.length !== validatedResults.length) { logger.info('Idempotent continuation retry detected', { - execution_id: state.execution_id, + route: 'v1.exec.programmatic', + mode: 'replay', total: validatedResults.length, new: delta.newCallIds.length, bytesDelta: delta.bytesDelta, @@ -829,7 +842,11 @@ async function runAndRespond( try { result = await runReplayIteration(req, state, apiKeyId, userId); } catch (err) { - logger.error('Replay iteration failed', { execution_id: state.execution_id, err }); + logger.error('Replay iteration failed', { + route: 'v1.exec.programmatic', + mode: 'replay', + ...operationalErrorMeta(err), + }); await cleanupExecution(state.execution_id, 'replay'); if (!isDisconnected()) { const message = (err as Error).message; @@ -844,7 +861,8 @@ async function runAndRespond( if (isDisconnected()) { logger.info('Client disconnected during replay; cleaning up', { - execution_id: state.execution_id, + route: 'v1.exec.programmatic', + mode: 'replay', }); await cleanupExecution(state.execution_id, 'replay'); return; @@ -858,7 +876,8 @@ async function runAndRespond( if (pending != null) { if (pending.length === 0) { logger.error('Sentinel emitted with empty pending array', { - execution_id: state.execution_id, + route: 'v1.exec.programmatic', + mode: 'replay', }); await cleanupExecution(state.execution_id, 'replay'); res.status(200).json({ @@ -873,9 +892,9 @@ async function runAndRespond( const unregisteredToolCall = findUnregisteredToolCall(pending, state.tools); if (unregisteredToolCall != null) { logger.warn('Sandbox requested unregistered replay tool call', { - execution_id: state.execution_id, - call_id: unregisteredToolCall.call_id, - tool_name: unregisteredToolCall.tool_name, + route: 'v1.exec.programmatic', + mode: 'replay', + status: 400, }); await cleanupExecution(state.execution_id, 'replay'); res.status(200).json({ @@ -931,8 +950,9 @@ async function runAndRespond( await refreshExecutionTtl(state.execution_id); } catch (err) { logger.error('Failed to persist execution state before continuation; aborting', { - execution_id: state.execution_id, - err: (err as Error).message, + route: 'v1.exec.programmatic', + mode: 'replay', + ...operationalErrorMeta(err), }); await cleanupExecution(state.execution_id, 'replay').catch(() => {}); if (!isDisconnected()) { @@ -1083,7 +1103,10 @@ router.post('/exec/programmatic', executionLimiter, async (req: t.AuthenticatedR } return await handleBlocking(req, res, { apiKeyId, userId }); } catch (err) { - logger.error(`[${INSTANCE_ID}] Programmatic routing error:`, err); + logger.error('Programmatic routing failed', { + route: 'v1.exec.programmatic', + ...operationalErrorMeta(err), + }); if (!res.headersSent) { return res.status(500).json({ error: 'Internal server error' }); } @@ -1105,7 +1128,6 @@ async function handleBlocking( const { code, tools, - user_id, files, continuation_token, tool_results, @@ -1144,19 +1166,16 @@ async function handleBlocking( ) ) { logger.warn('Unauthorized blocking continuation request rejected', { - execution_id, - requestUserId: userId, - requestApiKeyId: apiKeyId, - requestTenantId: identity.storageNamespace, - executionUserId: execution.userId, - executionApiKeyId: execution.apiKeyId, - executionTenantId: execution.tenantId, + route: 'v1.exec.programmatic', + mode: 'blocking', + status: 403, }); return res.status(403).json({ error: 'Forbidden' }); } logger.info('Continuation request received', { - execution_id, + route: 'v1.exec.programmatic', + mode: 'blocking', resultCount: tool_results.length, }); @@ -1205,7 +1224,11 @@ async function handleBlocking( session_id: execution.session_id, }); } catch (error) { - logger.error('Error processing continuation:', error); + logger.error('Blocking continuation failed', { + route: 'v1.exec.programmatic', + mode: 'blocking', + ...operationalErrorMeta(error), + }); await cleanupExecution(execution_id, 'blocking'); return res.status(500).json({ error: 'Internal server error' }); } @@ -1219,10 +1242,10 @@ async function handleBlocking( return res.status(400).json({ error: 'Missing required field: tools (must be a non-empty array)' }); } if (tools.length > MAX_TOOLS_PER_REQUEST) { - logger.warn(`Too many tools provided: ${tools.length}, limit is ${MAX_TOOLS_PER_REQUEST}`, { - execution_id: 'pre-creation', - userId, + logger.warn('Programmatic tool count limit reached', { + route: 'v1.exec.programmatic', toolCount: tools.length, + maxTools: MAX_TOOLS_PER_REQUEST, }); return res.status(400).json({ error: `Too many tools provided (${tools.length}). Maximum is ${MAX_TOOLS_PER_REQUEST}.`, @@ -1247,7 +1270,10 @@ async function handleBlocking( (req.body as t.ProgrammaticRequestBody).files = authorizedFiles.length > 0 ? authorizedFiles : undefined; } catch (error) { if (sendFileRefAuthorizationError(error, res, req)) return; - logger.error('Error authorizing programmatic file refs:', error); + logger.error('Programmatic file reference authorization failed', { + route: 'v1.exec.programmatic', + ...operationalErrorMeta(error), + }); return res.status(500).json({ error: 'Internal server error' }); } @@ -1290,15 +1316,11 @@ async function handleBlocking( try { logger.info('Programmatic execution request received', { - userId, - apiKeyId, - user: user_id, - session_id, - execution_id, + route: 'v1.exec.programmatic', + mode: 'blocking', toolCount: tools.length, codeLength: code.length, files: summarizeRequestedFiles(authorizedFiles), - sessionKey, timeout, }); @@ -1306,7 +1328,11 @@ async function handleBlocking( try { callbackUrl = normalizeEgressGatewayUrl(env.EGRESS_GATEWAY_URL); } catch (error) { - logger.error('Blocking PTC requires egress gateway callback URL:', error); + logger.error('Blocking programmatic callback URL is unavailable', { + route: 'v1.exec.programmatic', + mode: 'blocking', + ...operationalErrorMeta(error), + }); await cleanupExecution(execution_id, 'blocking'); return res.status(503).json({ error: 'Egress gateway unavailable' }); } @@ -1335,7 +1361,11 @@ async function handleBlocking( allowedToolNames: tools.map(tool => tool.name), }); } catch (error) { - logger.error('Failed to create Tool Call Server session or callback token:', error); + logger.error('Blocking programmatic callback setup failed', { + route: 'v1.exec.programmatic', + mode: 'blocking', + ...operationalErrorMeta(error), + }); await cleanupExecution(execution_id, 'blocking'); return res.status(503).json({ error: 'Tool Call Server unavailable' }); } @@ -1352,7 +1382,11 @@ async function handleBlocking( timeout, }); } catch (error) { - logger.error('Failed to create payload', { execution_id, error: (error as Error).message }); + logger.error('Blocking programmatic payload creation failed', { + route: 'v1.exec.programmatic', + mode: 'blocking', + ...operationalErrorMeta(error), + }); await cleanupExecution(execution_id, 'blocking'); return res.status(400).json({ error: (error as Error).message || 'Failed to generate code payload', @@ -1391,18 +1425,28 @@ async function handleBlocking( }); jobsSubmitted.inc({ language: 'python' }); - logger.info('Job queued, polling for tool calls', { execution_id, session_id }); + logger.info('Programmatic execution job queued', { + route: 'v1.exec.programmatic', + mode: 'blocking', + }); let clientDisconnected = false; req.on('close', async () => { if (clientDisconnected) return; clientDisconnected = true; - logger.warn(`Client disconnected for execution ${execution_id}`); + logger.warn('Client disconnected during programmatic execution', { + route: 'v1.exec.programmatic', + mode: 'blocking', + }); try { await job.remove(); await cleanupExecution(execution_id, 'blocking'); } catch (error) { - logger.error('Error cleaning up after client disconnect:', error); + logger.error('Programmatic disconnect cleanup failed', { + route: 'v1.exec.programmatic', + mode: 'blocking', + ...operationalErrorMeta(error), + }); } }); @@ -1445,7 +1489,11 @@ async function handleBlocking( session_id, }); } catch (error) { - logger.error(`[${INSTANCE_ID}] Session ID: ${session_id} | Execution ID: ${execution_id} | Error:`, error); + logger.error('Blocking programmatic execution failed', { + route: 'v1.exec.programmatic', + mode: 'blocking', + ...operationalErrorMeta(error), + }); await cleanupExecution(execution_id, 'blocking'); return res.status(500).json({ error: 'Internal server error' }); } diff --git a/service/src/service/replay-state.ts b/service/src/service/replay-state.ts index 562e06dd..5e499bfd 100644 --- a/service/src/service/replay-state.ts +++ b/service/src/service/replay-state.ts @@ -27,6 +27,7 @@ import type { LCTool } from '../preamble'; import { connection } from '../queue'; import { env } from '../config'; import { internalServiceHeaders } from '../internal-service-auth'; +import { operationalErrorMeta } from '../operational-log'; import logger from '../logger'; import { ptcReplayHistorySize, @@ -358,7 +359,10 @@ export async function releaseExecutionLock(execution_id: string, token: string): try { await redis.releaseExecutionLockScript(`exec_lock:${execution_id}`, token); } catch (err) { - logger.warn('Failed to release exec lock', { execution_id, err }); + logger.warn('Failed to release execution lock', { + mode: 'replay', + ...operationalErrorMeta(err), + }); } } @@ -382,7 +386,10 @@ export async function scanKeys( if (out.length >= limit) { stream.destroy(); logger.warn('scanKeys hit limit; remaining keys deferred to next pass', { - match, limit, + keyClass: match.startsWith('exec_state:') + ? 'execution_state' + : 'other', + limit, }); return out; } @@ -565,8 +572,7 @@ export async function computeToolHistoryDelta( }); } catch { logger.warn('Malformed existing tool_history entry; treating as absent', { - execution_id, - call_id: callIds[i], + mode: 'replay', }); } } @@ -693,7 +699,7 @@ export async function loadToolHistory(execution_id: string): Promise { * and structured logs, instead of silently disappearing. */ const orphanId = batchKeys[i].slice('exec_state:'.length); logger.warn('Reaping malformed exec_state and sibling keys', { - execution_id: orphanId, + mode: 'replay', }); await Promise.all([ redis.del(batchKeys[i]), @@ -761,8 +767,8 @@ export async function cleanupStaleExecutions(): Promise { deleteBlockingResult(orphanId), ]).catch(err => { logger.warn('Sibling delete failed during malformed-key cleanup', { - execution_id: orphanId, - error: err instanceof Error ? err.message : String(err), + mode: 'replay', + ...operationalErrorMeta(err), }); }); cleaned++; @@ -773,7 +779,6 @@ export async function cleanupStaleExecutions(): Promise { if (idle > EXECUTION_STATE_TTL * 1000 && state.jobCompleted !== true) { logger.warn('Cleaning up stale execution', { - execution_id: state.execution_id, idleSeconds: idle / 1000, totalAgeSeconds: (now - state.startTime) / 1000, mode: state.mode, @@ -796,12 +801,14 @@ export async function cleanupStaleExecutions(): Promise { } if (cleaned > 0) { - logger.info(`Cleaned up ${cleaned} stale executions`); + logger.info('Cleaned up stale executions', { count: cleaned }); ptcReplayStaleCleanups.inc(cleaned); } return cleaned; } catch (error) { - logger.error('Error cleaning up stale executions:', error); + logger.error('Failed to clean up stale executions', { + ...operationalErrorMeta(error), + }); return 0; } } @@ -821,9 +828,12 @@ export async function cleanupExecution(execution_id: string, mode: 'blocking' | ); } await Promise.all(ops); - logger.info('Execution cleanup completed', { execution_id, mode }); + logger.info('Execution cleanup completed', { mode }); } catch (error) { - logger.error('Error during execution cleanup:', { execution_id, error }); + logger.error('Execution cleanup failed', { + mode, + ...operationalErrorMeta(error), + }); } } diff --git a/service/src/service/router.ts b/service/src/service/router.ts index 7854b958..3e666259 100644 --- a/service/src/service/router.ts +++ b/service/src/service/router.ts @@ -11,7 +11,7 @@ import { executionLimiter, uploadLimiter, downloadLimiter, fetchLimiter } from ' import { internalServiceHeaders } from '../internal-service-auth'; import { resolveSessionKey, resolveOutputBucketSessionKey, SessionKeyResolutionError, parseUploadSessionKeyInput, type SessionKeyInput } from '../session-key'; import { pyQueue, otherQueue, pyQueueEvents, otherQueueEvents, queueNames, connection, waitForJobFinished } from '../queue'; -import { sleep, getAxiosErrorDetails, publicExecutionFailure } from '../utils'; +import { sleep, publicExecutionFailure } from '../utils'; import { env, jobCompletionWaitTimeoutMs, planLimits, resolveLanguage } from '../config'; import { createPayload } from '../payload'; import { summarizeRequestedFiles } from '../execution-log'; @@ -25,9 +25,9 @@ import { Jobs, Languages } from '../enum'; import { FileRefAuthorizationError, authorizeRequestedFiles } from './file-authorization'; import { createUploadSessionRegistrar } from './upload-session'; import { prepareSandboxJobSecurity } from '../sandbox-egress'; +import { operationalErrorMeta, operationalRoute } from '../operational-log'; import logger from '../logger'; -const { INSTANCE_ID } = env; const JOB_COMPLETION_WAIT_TIMEOUT_MS = jobCompletionWaitTimeoutMs( env.JOB_TIMEOUT, env.LAMBDA_MICROVM_LAUNCH_TIMEOUT_MS, @@ -66,16 +66,10 @@ function sendFileRefAuthorizationError( req?: t.AuthenticatedRequest, ): boolean { if (error instanceof FileRefAuthorizationError) { - const queryEntityId = typeof req?.query?.entity_id === 'string' ? req.query.entity_id : undefined; logger.warn('File reference authorization rejected', { status: error.status, reason: error.reason, - message: error.message, - requestUserId: req?.codeApiAuthContext?.userId, - requestApiKeyId: req ? getCredentialId(req) : undefined, - requestEntityId: queryEntityId, - tenantId: req?.codeApiAuthContext?.tenantId, - ...error.context, + route: req == null ? 'v1.exec' : operationalRoute(req), }); res.status(error.status).json({ error: error.message }); return true; @@ -90,8 +84,7 @@ function sendFileRefAuthorizationError( * `codeApiAuthContext`, malformed kind/version on uploads) would * surface as 500/400s in the response body with zero server-side * trail — silent in production logs and easy to miss until a user - * reports it. Includes auth/request context so the failure mode is - * traceable without correlating HTTP captures. + * reports it. The log keeps only the fixed stage and status. */ function sendSessionKeyResolutionError( error: unknown, @@ -100,14 +93,13 @@ function sendSessionKeyResolutionError( context: string, ): boolean { if (error instanceof SessionKeyResolutionError) { - logger.error(`[${INSTANCE_ID}] sessionKey resolution failed (${context})`, { + logger.error('Session key resolution failed', { status: error.status, - message: error.message, - method: req.method, - path: req.path, - requestUserId: req.codeApiAuthContext?.userId, - authContextUserId: req.codeApiAuthContext?.userId, - tenantId: req.codeApiAuthContext?.tenantId, + stage: context === 'resolveOutputBucketSessionKey' + ? 'resolve_output_bucket' + : 'resolve_upload_identity', + route: operationalRoute(req), + ...operationalErrorMeta(error), }); res.status(error.status).json({ error: error.message }); return true; @@ -134,7 +126,7 @@ router.post('/exec', executionLimiter, async (req: t.AuthenticatedRequest, res) } const body = req.body as t.RequestBody; - const { user_id, lang: rawLang, code, files } = body; + const { lang: rawLang, code, files } = body; const language = resolveLanguage(rawLang); if (language == null) { return res.status(400).json({ error: `Unsupported language: ${rawLang}` }); @@ -169,7 +161,10 @@ router.post('/exec', executionLimiter, async (req: t.AuthenticatedRequest, res) body.files = authorizedFiles.length > 0 ? authorizedFiles : undefined; } catch (error) { if (sendFileRefAuthorizationError(error, res, req)) return; - logger.error(`[${INSTANCE_ID}] Error authorizing file refs:`, error); + logger.error('File reference authorization failed', { + route: 'v1.exec', + ...operationalErrorMeta(error), + }); return res.status(500).json({ error: 'Internal server error' }); } @@ -199,13 +194,10 @@ router.post('/exec', executionLimiter, async (req: t.AuthenticatedRequest, res) try { if (!isSyntheticRequest) { logger.info('Request received', { - userId, - apiKeyId, - user: user_id, - session_id, + route: 'v1.exec', language, files: summarizeRequestedFiles(authorizedFiles), - sessionKey, + codeLength: code.length, }); } @@ -271,9 +263,14 @@ router.post('/exec', executionLimiter, async (req: t.AuthenticatedRequest, res) req.on('close', async () => { try { await job.remove(); - logger.info(`[${INSTANCE_ID}] Job ${job.id} removed due to client disconnect`); + logger.info('Execution job removed after client disconnect', { + route: 'v1.exec', + }); } catch (error) { - logger.error(`[${INSTANCE_ID}] Error removing job ${job.id} on client disconnect:`, error); + logger.error('Execution job cleanup failed after client disconnect', { + route: 'v1.exec', + ...operationalErrorMeta(error), + }); } }); @@ -285,12 +282,16 @@ router.post('/exec', executionLimiter, async (req: t.AuthenticatedRequest, res) }, () => waitForJobFinished(job, queue, queueEvents, JOB_COMPLETION_WAIT_TIMEOUT_MS), 'CONSUMER'); if (!isSyntheticRequest) { - logger.info('Execution completed', { session_id, user_id }); + logger.info('Execution completed', { route: 'v1.exec', language }); } return res.status(200).json(result); } catch (error) { - logger.error(`[${INSTANCE_ID}] Session ID: ${session_id} | User ID: ${user_id} | Error during execution:`, error); const publicFailure = publicExecutionFailure(error); + logger.error('Execution failed', { + route: 'v1.exec', + status: publicFailure?.status ?? 500, + ...operationalErrorMeta(error), + }); if (publicFailure) { return res.status(publicFailure.status).json(publicFailure.body); } @@ -312,7 +313,11 @@ router.get('/download/:session_id/:fileId', downloadLimiter, sessionAuth, async } if (exists === 0) { - logger.error(`[${INSTANCE_ID}] Session ID: ${session_id} | File ID: ${fileId} | File not found in cache`); + logger.warn('File download rejected', { + route: 'v1.download', + status: 404, + reason: 'upload_marker_missing', + }); return res.status(404).json({ error: 'File not found', details: 'The file may have expired or does not exist' @@ -330,12 +335,13 @@ router.get('/download/:session_id/:fileId', downloadLimiter, sessionAuth, async res.set(response.headers); response.data.pipe(res); } catch (error) { - const errorDetails = getAxiosErrorDetails(error); - logger.error(`[${INSTANCE_ID}] Session ID: ${session_id} | File ID: ${fileId} | Error downloading file:`, errorDetails); + logger.error('File download failed', { + route: 'v1.download', + ...operationalErrorMeta(error), + }); return res.status(500).json({ error: 'Error downloading file', - details: (error as Error).message }); } }); @@ -394,11 +400,17 @@ router.post('/upload', uploadLimiter, async (req: t.AuthenticatedRequest, res: R file.on('limit', () => { if (hasResponded) { - logger.warn(`[${INSTANCE_ID}] Post-process file size limit exceeded: ${filename} | Session: ${session_id}`); + logger.warn('Upload file size limit reached after response', { + route: 'v1.upload', + limitBytes: planFileSize, + }); return; } hasResponded = true; - logger.warn(`[${INSTANCE_ID}] File size limit exceeded: ${filename} | Session: ${session_id}`); + logger.warn('Upload file size limit reached', { + route: 'v1.upload', + limitBytes: planFileSize, + }); abortController.abort(); file.resume(); res.status(413).json({ error: 'File size limit exceeded' }); @@ -447,7 +459,7 @@ router.post('/upload', uploadLimiter, async (req: t.AuthenticatedRequest, res: R } connection.set(`session:${session_id}`, sessionKey, 'EX', env.SESSION_CACHE_TTL) .then(() => { - logger.info(`[${INSTANCE_ID}] Upload: Session ID: ${session_id} | User ID: ${userId} | Session key: ${sessionKey}`); + logger.info('Upload session registered', { route: 'v1.upload' }); return axios.put( `${env.FILE_SERVER_URL}/sessions/${session_id}/objects/${fileId}`, file, @@ -479,17 +491,25 @@ router.post('/upload', uploadLimiter, async (req: t.AuthenticatedRequest, res: R bb.on('error', (error) => { if (hasResponded) { - logger.warn(`[${INSTANCE_ID}] Post-process busboy error for session ${session_id}:`, error); + logger.warn('Upload parser failed after response', { + route: 'v1.upload', + ...operationalErrorMeta(error), + }); return; } hasResponded = true; - logger.error(`[${INSTANCE_ID}] Busboy error for session ${session_id}:`, error); + logger.error('Upload parser failed', { + route: 'v1.upload', + ...operationalErrorMeta(error), + }); res.status(500).json({ error: 'Error processing upload' }); }); bb.on('finish', async () => { if (hasResponded) { - logger.warn(`[${INSTANCE_ID}] Post-process upload already responded for session ${session_id}`); + logger.warn('Upload completion ignored after response', { + route: 'v1.upload', + }); void Promise.allSettled(uploadPromises); return; } @@ -503,7 +523,10 @@ router.post('/upload', uploadLimiter, async (req: t.AuthenticatedRequest, res: R }; res.status(200).json(response); } catch (error) { - logger.error(`[${INSTANCE_ID}] Error uploading files for session ${session_id}:`, error); + logger.error('Upload failed', { + route: 'v1.upload', + ...operationalErrorMeta(error), + }); if (!res.headersSent) { if (error instanceof Error) { if (error.message === 'Upload timeout') { @@ -522,16 +545,25 @@ router.post('/upload', uploadLimiter, async (req: t.AuthenticatedRequest, res: R req.on('error', (error) => { if (hasResponded) { - logger.warn(`[${INSTANCE_ID}] Post-process request error for session ${session_id}:`, error); + logger.warn('Upload request failed after response', { + route: 'v1.upload', + ...operationalErrorMeta(error), + }); return; } hasResponded = true; - logger.error(`[${INSTANCE_ID}] Request error for session ${session_id}:`, error); + logger.error('Upload request failed', { + route: 'v1.upload', + ...operationalErrorMeta(error), + }); res.status(500).json({ error: 'Error processing request' }); }); } catch (error) { - logger.error(`[${INSTANCE_ID}] Unexpected upload error:`, error); + logger.error('Unexpected upload failure', { + route: 'v1.upload', + ...operationalErrorMeta(error), + }); if (!res.headersSent) { res.status(500).json({ error: 'An unexpected error occurred' }); } @@ -566,7 +598,9 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, let sessionRegistrationError: Error | undefined; const ensureSessionRegistered = createUploadSessionRegistrar((sessionKey) => { - logger.info(`[${INSTANCE_ID}] Batch upload: Session ID: ${session_id} | User ID: ${userId} | Session key: ${sessionKey}`); + logger.info('Batch upload session registered', { + route: 'v1.upload.batch', + }); return connection.set(`session:${session_id}`, sessionKey, 'EX', env.SESSION_CACHE_TTL); }); @@ -597,7 +631,10 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, bb.on('filesLimit', () => { filesLimitReached = true; - logger.warn(`[${INSTANCE_ID}] Batch upload files limit reached (${MAX_BATCH_FILES}) for session ${session_id}`); + logger.warn('Batch upload file count limit reached', { + route: 'v1.upload.batch', + maxFiles: MAX_BATCH_FILES, + }); }); bb.on('file', (_fieldname: string, file: Readable, info: busboy.FileInfo) => { @@ -606,7 +643,10 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, const abortController = new AbortController(); file.on('limit', () => { - logger.warn(`[${INSTANCE_ID}] Batch upload file size limit exceeded: ${filename} | Session: ${session_id}`); + logger.warn('Batch upload file size limit reached', { + route: 'v1.upload.batch', + limitBytes: planFileSize, + }); abortController.abort('size_limit'); file.resume(); }); @@ -685,7 +725,10 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, } file.resume(); const message = error instanceof Error ? error.message : 'Unknown upload error'; - logger.error(`[${INSTANCE_ID}] Batch upload file failed: ${filename} | Session: ${session_id}`, { error: message }); + logger.error('Batch upload file failed', { + route: 'v1.upload.batch', + ...operationalErrorMeta(error), + }); resolve({ status: 'error', filename, error: message }); }; const forwardFile = (): Promise => axios.put( @@ -712,17 +755,25 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, bb.on('error', (error) => { if (hasResponded) { - logger.warn(`[${INSTANCE_ID}] Post-process busboy error for batch session ${session_id}:`, error); + logger.warn('Batch upload parser failed after response', { + route: 'v1.upload.batch', + ...operationalErrorMeta(error), + }); return; } hasResponded = true; - logger.error(`[${INSTANCE_ID}] Busboy error for batch session ${session_id}:`, error); + logger.error('Batch upload parser failed', { + route: 'v1.upload.batch', + ...operationalErrorMeta(error), + }); res.status(500).json({ error: 'Error processing upload' }); }); bb.on('finish', async () => { if (hasResponded) { - logger.warn(`[${INSTANCE_ID}] Post-process batch upload already responded for session ${session_id}`); + logger.warn('Batch upload completion ignored after response', { + route: 'v1.upload.batch', + }); return; } hasResponded = true; @@ -731,10 +782,10 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, const results = await Promise.all(uploadPromises); if (sessionRegistrationError) { - logger.error( - `[${INSTANCE_ID}] Batch upload session registration failed for session ${session_id}:`, - sessionRegistrationError, - ); + logger.error('Batch upload session registration failed', { + route: 'v1.upload.batch', + ...operationalErrorMeta(sessionRegistrationError), + }); res.status(500).json({ error: 'Error registering upload session' }); return; } @@ -746,10 +797,12 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, * `partial_success` when a tenantId gap or similar makes * EVERY upload structurally impossible. */ if (serverError) { - logger.error( - `[${INSTANCE_ID}] Batch upload faulted on sessionKey resolution: ${serverError.message}`, - { session_id, files: results.length }, - ); + logger.error('Batch upload session key resolution failed', { + route: 'v1.upload.batch', + fileCount: results.length, + status: serverError.status, + ...operationalErrorMeta(serverError), + }); res.status(500).json({ error: serverError.message }); return; } @@ -786,7 +839,10 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, }; res.status(statusCode).json(response); } catch (error) { - logger.error(`[${INSTANCE_ID}] Error in batch upload finish for session ${session_id}:`, error); + logger.error('Batch upload completion failed', { + route: 'v1.upload.batch', + ...operationalErrorMeta(error), + }); if (!res.headersSent) { res.status(500).json({ error: 'Error processing batch upload' }); } @@ -797,16 +853,25 @@ router.post('/upload/batch', uploadLimiter, async (req: t.AuthenticatedRequest, req.on('error', (error) => { if (hasResponded) { - logger.warn(`[${INSTANCE_ID}] Post-process request error for batch session ${session_id}:`, error); + logger.warn('Batch upload request failed after response', { + route: 'v1.upload.batch', + ...operationalErrorMeta(error), + }); return; } hasResponded = true; - logger.error(`[${INSTANCE_ID}] Request error for batch session ${session_id}:`, error); + logger.error('Batch upload request failed', { + route: 'v1.upload.batch', + ...operationalErrorMeta(error), + }); res.status(500).json({ error: 'Error processing request' }); }); } catch (error) { - logger.error(`[${INSTANCE_ID}] Unexpected batch upload error:`, error); + logger.error('Unexpected batch upload failure', { + route: 'v1.upload.batch', + ...operationalErrorMeta(error), + }); if (!res.headersSent) { res.status(500).json({ error: 'An unexpected error occurred' }); } @@ -825,8 +890,10 @@ router.get('/files/:session_id', fetchLimiter, sessionAuth, async (req: t.Authen return res.status(200).json(response.data); } catch (error) { - const errorDetails = getAxiosErrorDetails(error); - logger.error(`[${INSTANCE_ID}] Error fetching file info for session ${session_id}:`, errorDetails); + logger.error('File listing failed', { + route: 'v1.files.list', + ...operationalErrorMeta(error), + }); return res.status(500).json({ error: 'Error fetching file information', }); @@ -860,11 +927,10 @@ router.get('/sessions/:session_id/objects/:fileId', fetchLimiter, sessionAuth, a if (axios.isAxiosError(error) && error.response?.status === 404) { return res.status(404).json({ error: 'File not found' }); } - const errorDetails = getAxiosErrorDetails(error); - logger.error( - `[${INSTANCE_ID}] Error fetching object metadata - Session ID: ${session_id} | File ID: ${fileId}:`, - errorDetails, - ); + logger.error('File metadata lookup failed', { + route: 'v1.files.metadata', + ...operationalErrorMeta(error), + }); return res.status(500).json({ error: 'Error fetching object metadata' }); } }); @@ -879,11 +945,13 @@ router.delete('/files/:session_id/:fileId', fetchLimiter, sessionAuth, async (re ); await connection.del(`upload:${req.sessionKey}${session_id}${fileId}`); - logger.info(`[${INSTANCE_ID}] File deleted: Session ID: ${session_id} | File ID: ${fileId}`); + logger.info('File deleted', { route: 'v1.files.delete' }); return res.status(200).json(response.data); } catch (error) { - const errorDetails = getAxiosErrorDetails(error); - logger.error(`[${INSTANCE_ID}] Error deleting file - Session ID: ${session_id} | File ID: ${fileId}:`, errorDetails); + logger.error('File deletion failed', { + route: 'v1.files.delete', + ...operationalErrorMeta(error), + }); return res.status(500).json({ error: 'Error deleting file', }); diff --git a/service/src/tool-call-server.ts b/service/src/tool-call-server.ts index 866de623..694be486 100644 --- a/service/src/tool-call-server.ts +++ b/service/src/tool-call-server.ts @@ -15,6 +15,7 @@ import { isRegisteredToolName } from './tool-scope'; import { normalizeTracePath, shutdownTelemetry, withSpan, withTraceContext } from './telemetry'; import logger from './toolCallServerLogger'; import { redisKeepAliveOptions } from './redis-options'; +import { operationalErrorMeta } from './operational-log'; const INSTANCE_ID = process.env.INSTANCE_ID ?? nanoid(); const PORT = Number(process.env.TOOL_CALL_SERVER_PORT) || 3033; @@ -57,14 +58,11 @@ const redis = new IORedis({ }); redis.on('error', (err) => { - logger.error('Redis Client Error', { error: err }); + logger.error('Redis client error', operationalErrorMeta(err)); }); redis.on('connect', () => { - logger.info('Redis Client Connected', { - host: process.env.REDIS_HOST, - port: process.env.REDIS_PORT - }); + logger.info('Redis client connected'); }); redis.on('ready', () => { @@ -156,7 +154,7 @@ async function handleCreateSession(req: Request): Promise { await setSession(session); toolCallActiveSessions.inc(); - logger.info(`[${INSTANCE_ID}] Session created: ${execution_id}`); + logger.info('Tool-call session created', { toolCount: tools.length }); return jsonResponse({ success: true, @@ -165,7 +163,7 @@ async function handleCreateSession(req: Request): Promise { callback_token }); } catch (error) { - logger.error('Error creating session:', { error }); + logger.error('Error creating tool-call session', operationalErrorMeta(error)); return errorResponse('Internal server error', 500); } } @@ -188,7 +186,7 @@ async function handleGetPending(executionId: string): Promise { partial_stderr: '' }); } catch (error) { - logger.error('Error getting pending calls:', { error }); + logger.error('Error getting pending tool calls', operationalErrorMeta(error)); return errorResponse('Internal server error', 500); } } @@ -246,7 +244,7 @@ async function handleSubmitResults(executionId: string, req: Request): Promise { updated_at: session.updated_at }); } catch (error) { - logger.error('Error getting status:', { error }); + logger.error('Error getting tool-call status', operationalErrorMeta(error)); return errorResponse('Internal server error', 500); } } @@ -321,11 +319,11 @@ async function handleComplete(executionId: string, req: Request): Promise SESSION_EXPIRY ); - logger.info(`[${INSTANCE_ID}] Execution error: ${executionId}`); + logger.info('Tool-call execution marked failed'); return jsonResponse({ success: true }); } catch (error) { - logger.error('Error marking error:', { error }); + logger.error('Error marking tool-call execution failed', operationalErrorMeta(error)); return errorResponse('Internal server error', 500); } } @@ -385,11 +383,11 @@ async function handleDeleteSession(executionId: string): Promise { if (wasActive) { toolCallActiveSessions.dec(); } - logger.info(`[${INSTANCE_ID}] Session deleted: ${executionId}, cleaned ${keys.length} keys`); + logger.info('Tool-call session deleted', { cleanedKeys: keys.length }); return jsonResponse({ success: true, cleaned_keys: keys.length }); } catch (error) { - logger.error('Error deleting session:', { error }); + logger.error('Error deleting tool-call session', operationalErrorMeta(error)); return errorResponse('Internal server error', 500); } } @@ -423,7 +421,7 @@ async function handleToolCall(req: Request): Promise { return errorResponse('Invalid tool name', 400); } if (!isRegisteredToolName(tool_name, session.tools)) { - logger.warn(`[${INSTANCE_ID}] Rejected unregistered tool call: ${executionId}/${callId} - ${tool_name}`); + logger.warn('Rejected unregistered tool call'); return errorResponse('Tool is not registered for this execution', 403); } @@ -444,7 +442,7 @@ async function handleToolCall(req: Request): Promise { await setSession(session); toolCalls.inc(); - logger.info(`[${INSTANCE_ID}] Tool call received: ${executionId}/${callId} - ${tool_name}`); + logger.info('Tool call received'); // Wait for result (blocking) const result = await waitForResult(executionId, callId, session.timeout); @@ -465,7 +463,7 @@ async function handleToolCall(req: Request): Promise { error_message: result.error_message }); } catch (error) { - logger.error('Error handling tool call:', { error }); + logger.error('Error handling tool call', operationalErrorMeta(error)); return errorResponse('Internal server error', 500); } } @@ -622,7 +620,7 @@ const server = Bun.serve({ fetch: handleRequest, }); -logger.info(`[${INSTANCE_ID}] Tool Call Server running on port ${PORT}`); +logger.info('Tool-call server started'); // Graceful shutdown let shuttingDown = false; @@ -630,22 +628,22 @@ let shuttingDown = false; async function shutdown(): Promise { if (shuttingDown) return; shuttingDown = true; - logger.info(`[${INSTANCE_ID}] Shutting down...`); + logger.info('Shutting down tool-call server'); try { server.stop(); await redis.quit(); try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn(`[${INSTANCE_ID}] OpenTelemetry shutdown failed`, { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } process.exit(0); } catch (error) { - logger.error(`[${INSTANCE_ID}] Shutdown failed`, { error }); + logger.error('Tool-call server shutdown failed', operationalErrorMeta(error)); try { await shutdownTelemetry(); } catch (telemetryError) { - logger.warn(`[${INSTANCE_ID}] OpenTelemetry shutdown failed`, { error: telemetryError }); + logger.warn('OpenTelemetry shutdown failed', operationalErrorMeta(telemetryError)); } process.exit(1); } @@ -655,11 +653,11 @@ process.on('SIGTERM', () => void shutdown()); process.on('SIGINT', () => void shutdown()); process.on('uncaughtException', (error) => { - logger.error('Uncaught Exception', { error }); + logger.error('Uncaught exception', operationalErrorMeta(error)); }); -process.on('unhandledRejection', (reason, promise) => { - logger.error('Unhandled Rejection', { reason, promise }); +process.on('unhandledRejection', (reason) => { + logger.error('Unhandled rejection', operationalErrorMeta(reason)); }); export { server }; diff --git a/service/src/types/service.ts b/service/src/types/service.ts index a642dda3..9de34d2b 100644 --- a/service/src/types/service.ts +++ b/service/src/types/service.ts @@ -103,7 +103,7 @@ export type RequestFile = { export type FileRefs = FileRef[]; -export type ExecuteResponse = { +export type SandboxExecuteResponse = { run?: { stdout: string; stderr: string; @@ -228,6 +228,10 @@ export type ExecuteResult = { wall_time?: number | null; }; +/** Public `/v1/exec` response. The sandbox transport uses + * `SandboxExecuteResponse` and is not part of the public API. */ +export type ExecuteResponse = ExecuteResult; + export interface LanguageConfig { language: string; version: string; diff --git a/service/src/worker-server.ts b/service/src/worker-server.ts index 89049049..b9c34d1f 100644 --- a/service/src/worker-server.ts +++ b/service/src/worker-server.ts @@ -26,6 +26,7 @@ import { startWorkerServer, gracefulShutdown } from './lifecycle'; import { httpLatencyElapsedSeconds, httpLatencyStartMs, metricsResponse, recordHttpRequest } from './metrics'; import { env } from './config'; import logger from './logger'; +import { operationalErrorMeta } from './operational-log'; // Health check endpoint (optional, for K8s liveness probes) import http from 'http'; @@ -162,7 +163,7 @@ const healthServer = http.createServer(async (req, res) => { startWorkerServer(async () => { // Start health check server healthServer.listen(HEALTH_PORT, () => { - logger.info(`Worker health check server running on port ${HEALTH_PORT}`); + logger.info('Worker health check server started'); }); }); @@ -186,11 +187,11 @@ process.on('SIGUSR2', async () => { }); process.on('uncaughtException', async (error) => { - logger.error('Uncaught Exception', error); + logger.error('Uncaught exception', operationalErrorMeta(error)); healthServer.close(); await gracefulShutdown(); }); process.on('unhandledRejection', (reason) => { - logger.error('Unhandled Rejection', reason); + logger.error('Unhandled rejection', operationalErrorMeta(reason)); }); diff --git a/service/src/workers.ts b/service/src/workers.ts index ed2a46dd..5074381b 100644 --- a/service/src/workers.ts +++ b/service/src/workers.ts @@ -1,7 +1,7 @@ import axios from 'axios'; import { Worker } from 'bullmq'; import type * as t from './types'; -import { filterSystemLogs, applySystemReplacements, getAxiosErrorDetails, sandboxErrorMessageFromAxios } from './utils'; +import { filterSystemLogs, applySystemReplacements, sandboxErrorMessageFromAxios } from './utils'; import { jobProcessingDuration, jobsCompleted, jobsFailed, activeJobs, workerRunning } from './metrics'; import { connection, queueNames } from './queue'; import { env, jobDeadlineAtMs } from './config'; @@ -18,9 +18,7 @@ import { withSpan, withTraceContext } from './telemetry'; import { workerDeadlineFailure } from './worker-error'; import logger from './logger'; import { validateQueuedExecutionProfile } from './execution-profile'; - -const { INSTANCE_ID } = env; -const WORKER_ID = `${INSTANCE_ID}-${process.pid}`; +import { operationalErrorMeta } from './operational-log'; function isAbortError(error: unknown): boolean { return axios.isAxiosError(error) && (error.name === 'AbortError' || error.code === 'ERR_CANCELED'); @@ -30,8 +28,7 @@ async function processJob(job: t.ExecuteJob): Promise { return withTraceContext(job.data._otel, () => withSpan('codeapi.job.process', { 'messaging.system': 'bullmq', 'messaging.operation.name': 'process', - 'messaging.message.id': typeof job.id === 'string' ? job.id : String(job.id ?? ''), - 'codeapi.language': job.data.payload?.language ?? 'unknown', + 'codeapi.language': job.data.payload?.language === 'python' ? 'python' : 'other', 'codeapi.execution_profile': job.data.executionProfile ?? 'legacy', 'codeapi.worker_execution_profile': env.EXECUTION_PROFILE, }, () => processJobInner(job), 'CONSUMER')); @@ -183,7 +180,6 @@ async function processJobInner(job: t.ExecuteJob): Promise { if (result.message || result.signal) { logger.warn('Sandbox execution error metadata', { - session_id: responseData.session_id, code: result.code, signal: result.signal, message: summarizeText(result.message), @@ -195,8 +191,7 @@ async function processJobInner(job: t.ExecuteJob): Promise { return result; } catch (error) { revokeReason = controller.signal.aborted || isAbortError(error) ? 'timeout' : 'failed'; - const errorDetails = getAxiosErrorDetails(error); - logger.error('Error processing job', errorDetails); + logger.error('Error processing job', operationalErrorMeta(error)); const deadlineFailure = workerDeadlineFailure( error, @@ -229,7 +224,7 @@ async function processJobInner(job: t.ExecuteJob): Promise { reason: revokeReason, timeoutMs: env.EGRESS_GATEWAY_REVOKE_TIMEOUT_MS, }).catch(error => { - logger.error('Failed to revoke egress grant', { grantId: egressGrantId, error: getAxiosErrorDetails(error) }); + logger.error('Failed to revoke egress grant', operationalErrorMeta(error)); }); } if (timer) clearTimeout(timer); @@ -264,35 +259,47 @@ workerRunning.set({ worker_type: 'other' }, 1); pyWorker.on('completed', job => { if (job.data.isSynthetic !== true) { - logger.info(`[${WORKER_ID}] Python job completed ${job.id}`); + logger.info('Worker job completed', { workerClass: 'python' }); } jobsCompleted.inc({ language: 'python' }); }); otherWorker.on('completed', job => { if (job.data.isSynthetic !== true) { - logger.info(`[${WORKER_ID}] Other job completed ${job.id}`); + logger.info('Worker job completed', { workerClass: 'other' }); } jobsCompleted.inc({ language: 'other' }); }); -pyWorker.on('failed', (job, err) => { - logger.error(`[${WORKER_ID}] Python job ${job?.id} failed`, err); +pyWorker.on('failed', (_job, err) => { + logger.error('Worker job failed', { + workerClass: 'python', + ...operationalErrorMeta(err), + }); jobsFailed.inc({ language: 'python' }); }); -otherWorker.on('failed', (job, err) => { - logger.error(`[${WORKER_ID}] Other job ${job?.id} failed`, err); +otherWorker.on('failed', (_job, err) => { + logger.error('Worker job failed', { + workerClass: 'other', + ...operationalErrorMeta(err), + }); jobsFailed.inc({ language: 'other' }); }); pyWorker.on('error', (err) => { - logger.error(`[${WORKER_ID}] Python worker error`, err); + logger.error('Worker error', { + workerClass: 'python', + ...operationalErrorMeta(err), + }); workerRunning.set({ worker_type: 'python' }, 0); }); otherWorker.on('error', (err) => { - logger.error(`[${WORKER_ID}] Other worker error`, err); + logger.error('Worker error', { + workerClass: 'other', + ...operationalErrorMeta(err), + }); workerRunning.set({ worker_type: 'other' }, 0); });