refactor(logging): enhance logger configuration and streamline event logging

This commit is contained in:
Richard R 2026-05-22 13:11:51 -06:00
parent ad82aede73
commit 3dcda2b4b7

View file

@ -146,9 +146,16 @@ function parseBoolEnv(name: string, fallback: boolean): boolean {
function buildLoggerConfig(): boolean | Record<string, unknown> { function buildLoggerConfig(): boolean | Record<string, unknown> {
const format = (process.env.COMPUTE_LOG_FORMAT?.trim().toLowerCase() || 'pretty'); const format = (process.env.COMPUTE_LOG_FORMAT?.trim().toLowerCase() || 'pretty');
if (format === 'json') return true; const level = process.env.COMPUTE_LOG_LEVEL?.trim() || 'info';
if (format === 'json') {
return {
level,
base: null,
};
}
return { return {
level: process.env.COMPUTE_LOG_LEVEL?.trim() || 'info', level,
base: null,
transport: { transport: {
target: 'pino-pretty', target: 'pino-pretty',
options: { options: {
@ -705,7 +712,6 @@ async function main(): Promise<void> {
const ageMs = Date.now() - current.updatedAt; const ageMs = Date.now() - current.updatedAt;
if (current.status === 'succeeded') { if (current.status === 'succeeded') {
app.log.info({ app.log.info({
event: 'op.accepted',
kind: req.kind, kind: req.kind,
opId: current.opId, opId: current.opId,
jobId: current.jobId, jobId: current.jobId,
@ -713,12 +719,11 @@ async function main(): Promise<void> {
action: 'reused_terminal', action: 'reused_terminal',
status: current.status, status: current.status,
ageMs, ageMs,
}); }, 'op.accepted');
return current; return current;
} }
if ((current.status === 'queued' || current.status === 'running') && ageMs <= opStaleMs) { if ((current.status === 'queued' || current.status === 'running') && ageMs <= opStaleMs) {
app.log.info({ app.log.info({
event: 'op.accepted',
kind: req.kind, kind: req.kind,
opId: current.opId, opId: current.opId,
jobId: current.jobId, jobId: current.jobId,
@ -726,12 +731,11 @@ async function main(): Promise<void> {
action: 'reused_inflight', action: 'reused_inflight',
status: current.status, status: current.status,
ageMs, ageMs,
}); }, 'op.accepted');
return current; return current;
} }
if ((current.status === 'queued' || current.status === 'running') && ageMs > opStaleMs) { if ((current.status === 'queued' || current.status === 'running') && ageMs > opStaleMs) {
app.log.warn({ app.log.warn({
event: 'op.stuck_detected',
kind: req.kind, kind: req.kind,
opId: current.opId, opId: current.opId,
jobId: current.jobId, jobId: current.jobId,
@ -739,7 +743,7 @@ async function main(): Promise<void> {
status: current.status, status: current.status,
ageMs, ageMs,
opStaleMs, opStaleMs,
}); }, 'op.stuck_detected');
} }
} }
@ -783,16 +787,14 @@ async function main(): Promise<void> {
try { try {
await publishQueuedJob(replacement, req.payload); await publishQueuedJob(replacement, req.payload);
app.log.info({ app.log.info({
event: 'op.replaced',
kind: req.kind, kind: req.kind,
opId: replacement.opId, opId: replacement.opId,
jobId: replacement.jobId, jobId: replacement.jobId,
opKeyHash, opKeyHash,
reason: replacementReason, reason: replacementReason,
status: replacement.status, status: replacement.status,
}); }, 'op.replaced');
app.log.info({ app.log.info({
event: 'op.accepted',
kind: req.kind, kind: req.kind,
opId: replacement.opId, opId: replacement.opId,
jobId: replacement.jobId, jobId: replacement.jobId,
@ -800,7 +802,7 @@ async function main(): Promise<void> {
action: 'replaced', action: 'replaced',
status: replacement.status, status: replacement.status,
reason: replacementReason, reason: replacementReason,
}); }, 'op.accepted');
return replacement; return replacement;
} catch (error) { } catch (error) {
const failed: WorkerOperationState<WhisperAlignJobResult | PdfLayoutJobResult> = { const failed: WorkerOperationState<WhisperAlignJobResult | PdfLayoutJobResult> = {
@ -821,7 +823,6 @@ async function main(): Promise<void> {
error: failed.error, error: failed.error,
}); });
app.log.error({ app.log.error({
event: 'op.accepted',
kind: req.kind, kind: req.kind,
opId: failed.opId, opId: failed.opId,
jobId: failed.jobId, jobId: failed.jobId,
@ -830,7 +831,7 @@ async function main(): Promise<void> {
status: failed.status, status: failed.status,
reason: replacementReason, reason: replacementReason,
error: failed.error?.message ?? null, error: failed.error?.message ?? null,
}); }, 'op.accepted');
return failed; return failed;
} }
} }
@ -867,14 +868,13 @@ async function main(): Promise<void> {
try { try {
await publishQueuedJob(created, req.payload); await publishQueuedJob(created, req.payload);
app.log.info({ app.log.info({
event: 'op.accepted',
kind: req.kind, kind: req.kind,
opId: created.opId, opId: created.opId,
jobId: created.jobId, jobId: created.jobId,
opKeyHash, opKeyHash,
action: 'created', action: 'created',
status: created.status, status: created.status,
}); }, 'op.accepted');
return created; return created;
} catch (error) { } catch (error) {
const failed: WorkerOperationState<WhisperAlignJobResult | PdfLayoutJobResult> = { const failed: WorkerOperationState<WhisperAlignJobResult | PdfLayoutJobResult> = {
@ -895,7 +895,6 @@ async function main(): Promise<void> {
error: failed.error, error: failed.error,
}); });
app.log.error({ app.log.error({
event: 'op.accepted',
kind: req.kind, kind: req.kind,
opId: failed.opId, opId: failed.opId,
jobId: failed.jobId, jobId: failed.jobId,
@ -903,7 +902,7 @@ async function main(): Promise<void> {
action: 'created', action: 'created',
status: failed.status, status: failed.status,
error: failed.error?.message ?? null, error: failed.error?.message ?? null,
}); }, 'op.accepted');
return failed; return failed;
} }
} }
@ -943,7 +942,6 @@ async function main(): Promise<void> {
const startedAt = (request as FastifyRequest & { [REQUEST_STARTED_AT_MS_KEY]?: number })[REQUEST_STARTED_AT_MS_KEY]; const startedAt = (request as FastifyRequest & { [REQUEST_STARTED_AT_MS_KEY]?: number })[REQUEST_STARTED_AT_MS_KEY];
const durationMs = Number.isFinite(startedAt) ? Math.max(0, Date.now() - (startedAt as number)) : -1; const durationMs = Number.isFinite(startedAt) ? Math.max(0, Date.now() - (startedAt as number)) : -1;
app.log.error({ app.log.error({
event: 'http.error',
reqId: request.id, reqId: request.id,
method: request.method, method: request.method,
path, path,
@ -951,7 +949,7 @@ async function main(): Promise<void> {
durationMs, durationMs,
traceId: extractTraceId(request) ?? null, traceId: extractTraceId(request) ?? null,
opId: extractOpId(request, path), opId: extractOpId(request, path),
}); }, 'http.error');
} }
}); });
@ -1194,14 +1192,13 @@ async function main(): Promise<void> {
...(latestProgress ? { progress: latestProgress } : {}), ...(latestProgress ? { progress: latestProgress } : {}),
}); });
app.log.info({ app.log.info({
event: 'job.started',
worker: input.workerLabel, worker: input.workerLabel,
kind: decoded.kind, kind: decoded.kind,
opId: decoded.opId, opId: decoded.opId,
jobId: decoded.jobId, jobId: decoded.jobId,
queueWaitMs: queueWaitMs ?? null, queueWaitMs: queueWaitMs ?? null,
deliveryCount: input.msg.info.deliveryCount, deliveryCount: input.msg.info.deliveryCount,
}); }, 'job.started');
const persistRunningState = async (updatedAt: number): Promise<void> => { const persistRunningState = async (updatedAt: number): Promise<void> => {
const runningOpState: WorkerOperationState<WhisperAlignJobResult | PdfLayoutJobResult> = { const runningOpState: WorkerOperationState<WhisperAlignJobResult | PdfLayoutJobResult> = {
@ -1289,17 +1286,15 @@ async function main(): Promise<void> {
const slowJobLogThresholdMs = SLOW_JOB_LOG_THRESHOLD_MS_BY_KIND[decoded.kind]; const slowJobLogThresholdMs = SLOW_JOB_LOG_THRESHOLD_MS_BY_KIND[decoded.kind];
if ((terminalDurationMs ?? 0) >= slowJobLogThresholdMs) { if ((terminalDurationMs ?? 0) >= slowJobLogThresholdMs) {
app.log.info({ app.log.info({
event: 'job.stage',
worker: input.workerLabel, worker: input.workerLabel,
kind: decoded.kind, kind: decoded.kind,
opId: decoded.opId, opId: decoded.opId,
jobId: decoded.jobId, jobId: decoded.jobId,
durationMs: terminalDurationMs ?? null, durationMs: terminalDurationMs ?? null,
timing: resultTiming ?? null, timing: resultTiming ?? null,
}); }, 'job.stage');
} }
app.log.info({ app.log.info({
event: 'job.terminal',
worker: input.workerLabel, worker: input.workerLabel,
kind: decoded.kind, kind: decoded.kind,
opId: decoded.opId, opId: decoded.opId,
@ -1308,7 +1303,7 @@ async function main(): Promise<void> {
durationMs: terminalDurationMs ?? null, durationMs: terminalDurationMs ?? null,
resultRef: extractResultRef(decoded.kind, result), resultRef: extractResultRef(decoded.kind, result),
timing: resultTiming ?? null, timing: resultTiming ?? null,
}); }, 'job.terminal');
} catch (error) { } catch (error) {
const message = toErrorMessage(error); const message = toErrorMessage(error);
const deliveryCount = input.msg.info.deliveryCount; const deliveryCount = input.msg.info.deliveryCount;
@ -1367,7 +1362,6 @@ async function main(): Promise<void> {
if (hasRetriesLeft) { if (hasRetriesLeft) {
input.msg.nak(); input.msg.nak();
app.log.error({ app.log.error({
event: 'job.terminal',
worker: input.workerLabel, worker: input.workerLabel,
kind: decoded?.kind, kind: decoded?.kind,
opId: decoded?.opId, opId: decoded?.opId,
@ -1377,11 +1371,10 @@ async function main(): Promise<void> {
deliveryCount, deliveryCount,
maxAttempts, maxAttempts,
retryAction: 'nack_retry', retryAction: 'nack_retry',
}); }, 'job.terminal');
} else { } else {
input.msg.term(message); input.msg.term(message);
app.log.error({ app.log.error({
event: 'job.terminal',
worker: input.workerLabel, worker: input.workerLabel,
kind: decoded?.kind, kind: decoded?.kind,
opId: decoded?.opId, opId: decoded?.opId,
@ -1392,7 +1385,7 @@ async function main(): Promise<void> {
maxAttempts, maxAttempts,
retrySuppressed: isWhisperAlign ? 'whisper_align' : undefined, retrySuppressed: isWhisperAlign ? 'whisper_align' : undefined,
retryAction: 'term', retryAction: 'term',
}); }, 'job.terminal');
} }
} finally { } finally {
if (heartbeat) clearInterval(heartbeat); if (heartbeat) clearInterval(heartbeat);