refactor: scope runtime log context

This commit is contained in:
Eyejoker
2026-03-31 17:23:43 +09:00
parent c2ef6572fd
commit 141898f764
8 changed files with 167 additions and 253 deletions

View File

@@ -1,4 +1,4 @@
import pino from 'pino'; import pino, { type Logger } from 'pino';
const serviceName = (process.env.ASSISTANT_NAME || 'claude').toLowerCase(); const serviceName = (process.env.ASSISTANT_NAME || 'claude').toLowerCase();
@@ -8,6 +8,27 @@ export const logger = pino({
transport: { target: 'pino-pretty', options: { colorize: true } }, transport: { target: 'pino-pretty', options: { colorize: true } },
}); });
type LogBindings = Record<string, unknown>;
function normalizeBindings(bindings: LogBindings): LogBindings {
const normalized = Object.fromEntries(
Object.entries(bindings).filter(([, value]) => value !== undefined),
);
if (
typeof normalized.groupName === 'string' &&
normalized.group === undefined
) {
normalized.group = normalized.groupName;
}
return normalized;
}
export function createScopedLogger(bindings: LogBindings): Logger {
return logger.child(normalizeBindings(bindings));
}
// Route uncaught errors through pino so they get timestamps in stderr // Route uncaught errors through pino so they get timestamps in stderr
process.on('uncaughtException', (err) => { process.on('uncaughtException', (err) => {
logger.fatal({ err }, 'Uncaught exception'); logger.fatal({ err }, 'Uncaught exception');

View File

@@ -70,14 +70,19 @@ vi.mock('./service-routing.js', () => ({
})), })),
})); }));
vi.mock('./logger.js', () => ({ vi.mock('./logger.js', () => {
logger: { const mockLogger = {
debug: vi.fn(), debug: vi.fn(),
info: vi.fn(), info: vi.fn(),
warn: vi.fn(), warn: vi.fn(),
error: vi.fn(), error: vi.fn(),
}, child: (_bindings?: Record<string, unknown>) => mockLogger,
})); };
return {
logger: mockLogger,
createScopedLogger: (_bindings?: Record<string, unknown>) => mockLogger,
};
});
vi.mock('./agent-error-detection.js', async (importOriginal) => { vi.mock('./agent-error-detection.js', async (importOriginal) => {
const actual = const actual =

View File

@@ -21,7 +21,7 @@ import {
insertPairedTurnOutput, insertPairedTurnOutput,
} from './db.js'; } from './db.js';
import { GroupQueue } from './group-queue.js'; import { GroupQueue } from './group-queue.js';
import { logger } from './logger.js'; import { createScopedLogger } from './logger.js';
import { buildRoomMemoryBriefing } from './memento-client.js'; import { buildRoomMemoryBriefing } from './memento-client.js';
import { import {
completePairedExecutionContext, completePairedExecutionContext,
@@ -193,6 +193,16 @@ export async function runAgentForGroup(
pairedExecutionContext.envOverrides[effortKey] = roleConfig.effort; pairedExecutionContext.envOverrides[effortKey] = roleConfig.effort;
} }
} }
const log = createScopedLogger({
chatJid,
groupName: group.name,
groupFolder: group.folder,
runId,
messageSeqStart: startSeq ?? undefined,
messageSeqEnd: endSeq ?? undefined,
role: activeRole,
serviceId: effectiveServiceId,
});
// ── MoA prompt enrichment ───────────────────────────────────── // ── MoA prompt enrichment ─────────────────────────────────────
// When MoA is enabled and we're in arbiter mode, query external API // When MoA is enabled and we're in arbiter mode, query external API
@@ -202,11 +212,8 @@ export async function runAgentForGroup(
let moaEnrichedPrompt = prompt; let moaEnrichedPrompt = prompt;
const moaConfig = getMoaConfig(); const moaConfig = getMoaConfig();
if (arbiterMode && moaConfig.enabled && pairedExecutionContext) { if (arbiterMode && moaConfig.enabled && pairedExecutionContext) {
logger.info( log.info(
{ {
chatJid,
group: group.name,
runId,
models: moaConfig.referenceModels.map((m) => m.name), models: moaConfig.referenceModels.map((m) => m.name),
}, },
'MoA: collecting reference opinions before arbiter', 'MoA: collecting reference opinions before arbiter',
@@ -224,9 +231,8 @@ export async function runAgentForGroup(
const moaSection = formatMoaReferencesForPrompt(references); const moaSection = formatMoaReferencesForPrompt(references);
if (moaSection) { if (moaSection) {
moaEnrichedPrompt = prompt + '\n' + moaSection; moaEnrichedPrompt = prompt + '\n' + moaSection;
logger.info( log.info(
{ {
chatJid,
successCount: references.filter((r) => !r.error).length, successCount: references.filter((r) => !r.error).length,
totalCount: references.length, totalCount: references.length,
}, },
@@ -271,10 +277,7 @@ export async function runAgentForGroup(
// Per-role fallback toggle // Per-role fallback toggle
const roleConfig = getRoleModelConfig(activeRole); const roleConfig = getRoleModelConfig(activeRole);
if (!roleConfig.fallbackEnabled) { if (!roleConfig.fallbackEnabled) {
logger.info( log.info({ reason }, 'Fallback disabled for role, skipping handoff');
{ chatJid, group: group.name, role: activeRole, reason },
'Fallback disabled for role, skipping handoff',
);
return false; return false;
} }
@@ -291,8 +294,8 @@ export async function runAgentForGroup(
end_seq: endSeq ?? null, end_seq: endSeq ?? null,
reason: `arbiter-claude-${reason}`, reason: `arbiter-claude-${reason}`,
}); });
logger.warn( log.warn(
{ chatJid, group: group.name, runId, reason }, { reason },
'Claude arbiter unavailable, handed off arbiter turn to codex', 'Claude arbiter unavailable, handed off arbiter turn to codex',
); );
return true; return true;
@@ -312,8 +315,8 @@ export async function runAgentForGroup(
end_seq: endSeq ?? null, end_seq: endSeq ?? null,
reason: `reviewer-claude-${reason}`, reason: `reviewer-claude-${reason}`,
}); });
logger.warn( log.warn(
{ chatJid, group: group.name, runId, reason }, { reason },
'Claude reviewer unavailable, handed off review turn to codex-review', 'Claude reviewer unavailable, handed off review turn to codex-review',
); );
return true; return true;
@@ -331,8 +334,8 @@ export async function runAgentForGroup(
end_seq: endSeq ?? null, end_seq: endSeq ?? null,
reason: `claude-${reason}`, reason: `claude-${reason}`,
}); });
logger.warn( log.warn(
{ chatJid, group: group.name, runId, reason }, { reason },
'Claude unavailable, handed off current turn to codex-review', 'Claude unavailable, handed off current turn to codex-review',
); );
return true; return true;
@@ -352,14 +355,10 @@ export async function runAgentForGroup(
if (pairedExecutionContext?.blockMessage) { if (pairedExecutionContext?.blockMessage) {
pairedExecutionSummary = pairedExecutionContext.blockMessage.slice(0, 500); pairedExecutionSummary = pairedExecutionContext.blockMessage.slice(0, 500);
logger.warn( log.warn(
{ {
chatJid, roomRoleServiceId: roomRoleContext?.serviceId,
group: group.name, roomRole: roomRoleContext?.role,
groupFolder: group.folder,
runId,
serviceId: roomRoleContext?.serviceId,
role: roomRoleContext?.role,
}, },
'Blocked reviewer execution before review-ready snapshot was available', 'Blocked reviewer execution before review-ready snapshot was available',
); );
@@ -445,11 +444,8 @@ export async function runAgentForGroup(
typeof outputText === 'string' && typeof outputText === 'string' &&
output.status === 'success' output.status === 'success'
) { ) {
logger.warn( log.warn(
{ {
chatJid,
group: group.name,
runId,
reason: evaluation.newTrigger.reason, reason: evaluation.newTrigger.reason,
resultPreview: outputText.slice(0, 120), resultPreview: outputText.slice(0, 120),
}, },
@@ -459,11 +455,8 @@ export async function runAgentForGroup(
evaluation.newTrigger && evaluation.newTrigger &&
typeof output.error === 'string' typeof output.error === 'string'
) { ) {
logger.warn( log.warn(
{ {
chatJid,
group: group.name,
runId,
reason: evaluation.newTrigger.reason, reason: evaluation.newTrigger.reason,
errorPreview: output.error.slice(0, 120), errorPreview: output.error.slice(0, 120),
}, },
@@ -474,11 +467,8 @@ export async function runAgentForGroup(
} }
if (evaluation.suppressedAuthError) { if (evaluation.suppressedAuthError) {
logger.warn( log.warn(
{ {
chatJid,
group: group.name,
runId,
resultPreview: resultPreview:
typeof outputText === 'string' typeof outputText === 'string'
? outputText.slice(0, 120) ? outputText.slice(0, 120)
@@ -490,11 +480,8 @@ export async function runAgentForGroup(
} }
if (evaluation.suppressedRetryableSessionFailure) { if (evaluation.suppressedRetryableSessionFailure) {
logger.warn( log.warn(
{ {
chatJid,
group: group.name,
runId,
resultPreview: resultPreview:
typeof outputText === 'string' typeof outputText === 'string'
? outputText.slice(0, 160) ? outputText.slice(0, 160)
@@ -518,17 +505,11 @@ export async function runAgentForGroup(
} }
: undefined; : undefined;
logger.info( const providerLog = log.child({
{ provider,
chatJid, agentType: effectiveAgentType,
group: group.name, });
groupFolder: group.folder, providerLog.info('Using provider');
runId,
provider: effectiveAgentType,
role: activeRole,
},
`Using provider: ${effectiveAgentType}`,
);
try { try {
const output = await runAgentProcess( const output = await runAgentProcess(
@@ -547,13 +528,8 @@ export async function runAgentForGroup(
deps.persistSession(sessionFolder, output.newSessionId); deps.persistSession(sessionFolder, output.newSessionId);
} }
logger.info( providerLog.info(
{ {
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
provider,
status: output.status, status: output.status,
sawOutput: streamedState.sawOutput, sawOutput: streamedState.sawOutput,
}, },
@@ -595,8 +571,8 @@ export async function runAgentForGroup(
getCodexAccountCount() > 1 && getCodexAccountCount() > 1 &&
rotateCodexToken(lastRotationMessage) rotateCodexToken(lastRotationMessage)
) { ) {
logger.info( log.info(
{ chatJid, group: group.name, runId, reason: trigger.reason }, { reason: trigger.reason },
'Codex account unhealthy, retrying with rotated account', 'Codex account unhealthy, retrying with rotated account',
); );
@@ -611,15 +587,8 @@ export async function runAgentForGroup(
continue; continue;
} }
logger.error( log.error(
{ { provider: 'codex', err: retryAttempt.error },
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
provider: 'codex',
err: retryAttempt.error,
},
'Rotated Codex account also threw', 'Rotated Codex account also threw',
); );
return 'error'; return 'error';
@@ -627,14 +596,8 @@ export async function runAgentForGroup(
const retryOutput = retryAttempt.output; const retryOutput = retryAttempt.output;
if (!retryOutput) { if (!retryOutput) {
logger.error( log.error(
{ { provider: 'codex' },
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
provider: 'codex',
},
'Rotated Codex account produced no output object', 'Rotated Codex account produced no output object',
); );
return 'error'; return 'error';
@@ -671,11 +634,8 @@ export async function runAgentForGroup(
continue; continue;
} }
logger.error( log.error(
{ {
group: group.name,
chatJid,
runId,
provider: 'codex', provider: 'codex',
error: retryOutput.error, error: retryOutput.error,
}, },
@@ -760,8 +720,7 @@ export async function runAgentForGroup(
if (isRetryableClaudeSessionFailure(primaryAttempt)) { if (isRetryableClaudeSessionFailure(primaryAttempt)) {
deps.clearSession(sessionFolder); deps.clearSession(sessionFolder);
logger.warn( log.warn(
{ group: group.name, chatJid, runId },
'Cleared poisoned Claude session before visible output, retrying fresh session', 'Cleared poisoned Claude session before visible output, retrying fresh session',
); );
@@ -769,13 +728,9 @@ export async function runAgentForGroup(
if (isRetryableClaudeSessionFailure(primaryAttempt)) { if (isRetryableClaudeSessionFailure(primaryAttempt)) {
deps.clearSession(sessionFolder); deps.clearSession(sessionFolder);
logger.warn( log.warn('Fresh Claude retry also hit a retryable session failure');
{ group: group.name, chatJid, runId },
'Fresh Claude retry also hit a retryable session failure',
);
logger.error( log.error(
{ group: group.name, chatJid, runId },
'Retryable Claude session failure persisted after fresh retry', 'Retryable Claude session failure persisted after fresh retry',
); );
return 'error'; return 'error';
@@ -829,12 +784,8 @@ export async function runAgentForGroup(
} }
} }
logger.error( log.error(
{ {
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
provider, provider,
err: primaryAttempt.error, err: primaryAttempt.error,
}, },
@@ -845,16 +796,7 @@ export async function runAgentForGroup(
const output = primaryAttempt.output; const output = primaryAttempt.output;
if (!output) { if (!output) {
logger.error( log.error({ provider }, 'Agent produced no output object');
{
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
provider,
},
'Agent produced no output object',
);
return 'error'; return 'error';
} }
@@ -894,8 +836,8 @@ export async function runAgentForGroup(
(resetSessionRequested || shouldResetSessionOnAgentFailure(output)) (resetSessionRequested || shouldResetSessionOnAgentFailure(output))
) { ) {
deps.clearSession(sessionFolder); deps.clearSession(sessionFolder);
logger.warn( log.warn(
{ group: group.name, chatJid, runId, sessionFolder }, { sessionFolder },
'Cleared poisoned agent session after unrecoverable error', 'Cleared poisoned agent session after unrecoverable error',
); );
} }
@@ -945,11 +887,8 @@ export async function runAgentForGroup(
} }
} }
logger.error( log.error(
{ {
group: group.name,
chatJid,
runId,
provider, provider,
error: output.error, error: output.error,
}, },
@@ -988,11 +927,8 @@ export async function runAgentForGroup(
) { ) {
return 'success'; return 'success';
} }
logger.error( log.error(
{ {
group: group.name,
chatJid,
runId,
reason: primaryAttempt.streamedTriggerReason.reason, reason: primaryAttempt.streamedTriggerReason.reason,
}, },
'Agent trigger detected but could not be resolved', 'Agent trigger detected but could not be resolved',
@@ -1006,8 +942,7 @@ export async function runAgentForGroup(
primaryAttempt.sawSuccessNullResultWithoutOutput && primaryAttempt.sawSuccessNullResultWithoutOutput &&
!primaryAttempt.sawOutput !primaryAttempt.sawOutput
) { ) {
logger.error( log.error(
{ group: group.name, chatJid, runId },
'Agent returned success with null result and no visible output', 'Agent returned success with null result and no visible output',
); );
return 'error'; return 'error';
@@ -1046,8 +981,8 @@ export async function runAgentForGroup(
pairedFullOutput, pairedFullOutput,
); );
} catch (err) { } catch (err) {
logger.warn( log.warn(
{ taskId: pairedExecutionContext.task.id, err }, { pairedTaskId: pairedExecutionContext.task.id, err },
'Failed to store paired turn output', 'Failed to store paired turn output',
); );
} }

View File

@@ -154,14 +154,19 @@ vi.mock('./service-routing.js', () => ({
shouldServiceProcessChat: vi.fn(() => true), shouldServiceProcessChat: vi.fn(() => true),
})); }));
vi.mock('./logger.js', () => ({ vi.mock('./logger.js', () => {
logger: { const mockLogger = {
debug: vi.fn(), debug: vi.fn(),
info: vi.fn(), info: vi.fn(),
warn: vi.fn(), warn: vi.fn(),
error: vi.fn(), error: vi.fn(),
}, child: (_bindings?: Record<string, unknown>) => mockLogger,
})); };
return {
logger: mockLogger,
createScopedLogger: (_bindings?: Record<string, unknown>) => mockLogger,
};
});
vi.mock('./sender-allowlist.js', () => ({ vi.mock('./sender-allowlist.js', () => ({
isTriggerAllowed: vi.fn(() => true), isTriggerAllowed: vi.fn(() => true),

View File

@@ -62,9 +62,12 @@ import {
type PairedTask, type PairedTask,
type PairedTurnOutput, type PairedTurnOutput,
} from './types.js'; } from './types.js';
import { logger } from './logger.js'; import { createScopedLogger, logger } from './logger.js';
import { resolveGroupIpcPath } from './group-folder.js'; import { resolveGroupIpcPath } from './group-folder.js';
import { getEffectiveChannelLease, hasReviewerLease } from './service-routing.js'; import {
getEffectiveChannelLease,
hasReviewerLease,
} from './service-routing.js';
/** /**
* Check if a message is a duplicate of the last bot final message in a paired room. * Check if a message is a duplicate of the last bot final message in a paired room.
@@ -637,10 +640,16 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
const { runId } = context; const { runId } = context;
const group = deps.getRegisteredGroups()[chatJid]; const group = deps.getRegisteredGroups()[chatJid];
if (!group) return true; if (!group) return true;
const log = createScopedLogger({
chatJid,
groupName: group.name,
groupFolder: group.folder,
runId,
});
const channel = findChannel(deps.channels, chatJid); const channel = findChannel(deps.channels, chatJid);
if (!channel) { if (!channel) {
logger.warn({ chatJid }, 'No channel owns JID, skipping messages'); log.warn('No channel owns JID, skipping messages');
return true; return true;
} }
@@ -747,9 +756,8 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
}; };
if (hasReviewerLease(chatJid)) { if (hasReviewerLease(chatJid)) {
logger.info( log.info(
{ {
chatJid,
reviewerChannelName, reviewerChannelName,
foundChannel: foundReviewerChannel?.name ?? null, foundChannel: foundReviewerChannel?.name ?? null,
usingChannel: reviewerChannel.name, usingChannel: reviewerChannel.name,
@@ -833,8 +841,7 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
lastMessage.seq, lastMessage.seq,
); );
} }
logger.info( log.info(
{ chatJid, group: group.name, groupFolder: group.folder, runId },
'Skipping bot-only collaboration because no recent human message exists', 'Skipping bot-only collaboration because no recent human message exists',
); );
return true; return true;
@@ -906,10 +913,7 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
hasImplicitContinuationWindow: continuationTracker.has, hasImplicitContinuationWindow: continuationTracker.has,
}) })
) { ) {
logger.info( log.info('Skipping queued run because no allowed trigger was found');
{ chatJid, group: group.name, groupFolder: group.folder, runId },
'Skipping queued run because no allowed trigger was found',
);
return true; return true;
} }
@@ -957,13 +961,11 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
); );
} }
logger.info( log.info(
{ {
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
messageCount: missedMessages.length, messageCount: missedMessages.length,
messageSeqStart: startSeq,
messageSeqEnd: endSeq,
}, },
'Dispatching queued messages to agent', 'Dispatching queued messages to agent',
); );
@@ -981,20 +983,21 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
}); });
if (!deliverySucceeded) { if (!deliverySucceeded) {
logger.warn( log.warn(
{ chatJid, group: group.name, groupFolder: group.folder, runId }, {
messageSeqStart: startSeq,
messageSeqEnd: endSeq,
},
'Persisted produced output for delivery retry without rerunning agent', 'Persisted produced output for delivery retry without rerunning agent',
); );
return false; return false;
} }
logger.info( log.info(
{ {
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
visiblePhase, visiblePhase,
messageSeqStart: startSeq,
messageSeqEnd: endSeq,
}, },
'Queued run completed successfully', 'Queued run completed successfully',
); );

View File

@@ -1,6 +1,6 @@
import { type AgentOutput } from './agent-runner.js'; import { type AgentOutput } from './agent-runner.js';
import { getAgentOutputText } from './agent-output.js'; import { getAgentOutputText } from './agent-output.js';
import { logger } from './logger.js'; import { createScopedLogger, logger } from './logger.js';
import { formatOutbound } from './router.js'; import { formatOutbound } from './router.js';
import { shouldResetSessionOnAgentFailure } from './session-recovery.js'; import { shouldResetSessionOnAgentFailure } from './session-recovery.js';
import { TASK_STATUS_MESSAGE_PREFIX } from './task-watch-status.js'; import { TASK_STATUS_MESSAGE_PREFIX } from './task-watch-status.js';
@@ -35,6 +35,7 @@ interface MessageTurnControllerOptions {
} }
export class MessageTurnController { export class MessageTurnController {
private readonly log: typeof logger;
private idleTimer: ReturnType<typeof setTimeout> | null = null; private idleTimer: ReturnType<typeof setTimeout> | null = null;
private visiblePhase: VisiblePhase = 'silent'; private visiblePhase: VisiblePhase = 'silent';
private hadError = false; private hadError = false;
@@ -56,21 +57,24 @@ export class MessageTurnController {
private closeRequested = false; private closeRequested = false;
private typingActive = false; private typingActive = false;
constructor(private readonly options: MessageTurnControllerOptions) {} constructor(private readonly options: MessageTurnControllerOptions) {
this.log = createScopedLogger({
chatJid: options.chatJid,
groupName: options.group.name,
groupFolder: options.group.folder,
runId: options.runId,
});
}
private async setTyping( private async setTyping(
isTyping: boolean, isTyping: boolean,
source: string, source: string,
extra?: Record<string, unknown>, extra?: Record<string, unknown>,
): Promise<void> { ): Promise<void> {
logger.debug( this.log.debug(
{ {
transition: isTyping ? 'typing:on' : 'typing:off', transition: isTyping ? 'typing:on' : 'typing:off',
source, source,
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
...extra, ...extra,
}, },
'Typing indicator transition', 'Typing indicator transition',
@@ -85,12 +89,8 @@ export class MessageTurnController {
async handleOutput(result: AgentOutput): Promise<void> { async handleOutput(result: AgentOutput): Promise<void> {
if (this.terminalObserved()) { if (this.terminalObserved()) {
logger.info( this.log.info(
{ {
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
resultStatus: result.status, resultStatus: result.status,
resultPhase: result.phase, resultPhase: result.phase,
}, },
@@ -108,13 +108,7 @@ export class MessageTurnController {
this.hadError = true; this.hadError = true;
this.options.clearSession(); this.options.clearSession();
this.requestAgentClose('poisoned-session-detected'); this.requestAgentClose('poisoned-session-detected');
logger.warn( this.log.warn(
{
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
},
'Detected poisoned Claude session from streamed output, forcing close', 'Detected poisoned Claude session from streamed output, forcing close',
); );
} }
@@ -123,12 +117,8 @@ export class MessageTurnController {
const text = raw ? formatOutbound(raw) : null; const text = raw ? formatOutbound(raw) : null;
if (raw) { if (raw) {
logger.info( this.log.info(
{ {
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
resultStatus: result.status, resultStatus: result.status,
resultPhase: result.phase, resultPhase: result.phase,
progressMessageId: this.progressMessageId, progressMessageId: this.progressMessageId,
@@ -265,12 +255,8 @@ export class MessageTurnController {
await this.finalizeProgressMessage(); await this.finalizeProgressMessage();
await this.deliverFinalText(text); await this.deliverFinalText(text);
} else if (raw) { } else if (raw) {
logger.info( this.log.info(
{ {
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
resultStatus: result.status, resultStatus: result.status,
resultPhase: result.phase, resultPhase: result.phase,
progressMessageId: this.progressMessageId, progressMessageId: this.progressMessageId,
@@ -312,13 +298,7 @@ export class MessageTurnController {
!this.hadError && !this.hadError &&
this.latestProgressTextForFinal this.latestProgressTextForFinal
) { ) {
logger.info( this.log.info(
{
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
},
'Sending a separate final message from the last progress output after agent completion', 'Sending a separate final message from the last progress output after agent completion',
); );
await this.finalizeProgressMessage(); await this.finalizeProgressMessage();
@@ -503,12 +483,8 @@ export class MessageTurnController {
this.progressEditFailCount = 0; this.progressEditFailCount = 0;
} catch (err) { } catch (err) {
this.progressEditFailCount++; this.progressEditFailCount++;
logger.warn( this.log.warn(
{ {
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
progressMessageId: this.progressMessageId, progressMessageId: this.progressMessageId,
progressEditFailCount: this.progressEditFailCount, progressEditFailCount: this.progressEditFailCount,
err, err,
@@ -539,12 +515,8 @@ export class MessageTurnController {
} }
private async finalizeProgressMessage(): Promise<void> { private async finalizeProgressMessage(): Promise<void> {
logger.info( this.log.info(
{ {
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
progressMessageId: this.progressMessageId, progressMessageId: this.progressMessageId,
latestProgressText: this.latestProgressText, latestProgressText: this.latestProgressText,
}, },
@@ -594,12 +566,8 @@ export class MessageTurnController {
const rendered = this.renderProgressMessage(text); const rendered = this.renderProgressMessage(text);
if (this.progressMessageId && this.options.channel.editMessage) { if (this.progressMessageId && this.options.channel.editMessage) {
logger.info( this.log.info(
{ {
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
progressMessageId: this.progressMessageId, progressMessageId: this.progressMessageId,
text, text,
}, },
@@ -623,16 +591,7 @@ export class MessageTurnController {
rendered, rendered,
); );
} catch (err) { } catch (err) {
logger.warn( this.log.warn({ err }, 'Failed to send tracked progress message');
{
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
err,
},
'Failed to send tracked progress message',
);
this.latestProgressRendered = rendered; this.latestProgressRendered = rendered;
await this.options.channel.sendMessage(this.options.chatJid, rendered); await this.options.channel.sendMessage(this.options.chatJid, rendered);
this.visiblePhase = toVisiblePhase('progress'); this.visiblePhase = toVisiblePhase('progress');
@@ -640,12 +599,8 @@ export class MessageTurnController {
} }
if (this.progressMessageId) { if (this.progressMessageId) {
logger.info( this.log.info(
{ {
chatJid: this.options.chatJid,
group: this.options.group.name,
groupFolder: this.options.group.folder,
runId: this.options.runId,
progressMessageId: this.progressMessageId, progressMessageId: this.progressMessageId,
text, text,
}, },
@@ -692,11 +647,9 @@ export class MessageTurnController {
} }
this.idleTimer = setTimeout(() => { this.idleTimer = setTimeout(() => {
logger.debug( this.log.debug(
{ {
group: this.options.group.name, idleTimeoutMs: this.options.idleTimeout,
chatJid: this.options.chatJid,
runId: this.options.runId,
}, },
'Idle timeout, closing agent stdin', 'Idle timeout, closing agent stdin',
); );

View File

@@ -89,14 +89,19 @@ vi.mock('./agent-runner.js', async () => {
}; };
}); });
vi.mock('./logger.js', () => ({ vi.mock('./logger.js', () => {
logger: { const mockLogger = {
debug: loggerDebugMock, debug: loggerDebugMock,
info: vi.fn(), info: vi.fn(),
warn: vi.fn(), warn: vi.fn(),
error: vi.fn(), error: vi.fn(),
}, child: (_bindings?: Record<string, unknown>) => mockLogger,
})); };
return {
logger: mockLogger,
createScopedLogger: (_bindings?: Record<string, unknown>) => mockLogger,
};
});
vi.mock('./github-ci.js', () => ({ vi.mock('./github-ci.js', () => ({
checkGitHubActionsRun: checkGitHubActionsRunMock, checkGitHubActionsRun: checkGitHubActionsRunMock,

View File

@@ -25,7 +25,7 @@ import {
resolveGroupIpcPath, resolveGroupIpcPath,
resolveTaskRuntimeIpcPath, resolveTaskRuntimeIpcPath,
} from './group-folder.js'; } from './group-folder.js';
import { logger } from './logger.js'; import { createScopedLogger, logger } from './logger.js';
import { createTaskStatusTracker } from './task-status-tracker.js'; import { createTaskStatusTracker } from './task-status-tracker.js';
import { runClaudeRotationLoop } from './provider-retry.js'; import { runClaudeRotationLoop } from './provider-retry.js';
import { import {
@@ -274,11 +274,15 @@ async function runTask(
}); });
return; return;
} }
const log = createScopedLogger({
taskId: task.id,
chatJid: task.chat_jid,
groupName: context.group.name,
groupFolder: task.group_folder,
runtimeTaskId: context.runtimeTaskId,
});
logger.info( log.info('Running scheduled task');
{ taskId: task.id, group: task.group_folder },
'Running scheduled task',
);
// Update tasks snapshot for agent to read (filtered by group) // Update tasks snapshot for agent to read (filtered by group)
writeTaskSnapshotForGroup( writeTaskSnapshotForGroup(
@@ -360,12 +364,8 @@ async function runTask(
typeof streamedOutput.result === 'string' && typeof streamedOutput.result === 'string' &&
streamedOutput.status === 'success' streamedOutput.status === 'success'
) { ) {
logger.warn( log.warn(
{ {
taskId: task.id,
taskChatJid: task.chat_jid,
group: context.group.name,
groupFolder: task.group_folder,
reason: evaluation.newTrigger.reason, reason: evaluation.newTrigger.reason,
resultPreview: streamedOutput.result.slice(0, 120), resultPreview: streamedOutput.result.slice(0, 120),
}, },
@@ -375,12 +375,8 @@ async function runTask(
evaluation.newTrigger && evaluation.newTrigger &&
typeof streamedOutput.error === 'string' typeof streamedOutput.error === 'string'
) { ) {
logger.warn( log.warn(
{ {
taskId: task.id,
taskChatJid: task.chat_jid,
group: context.group.name,
groupFolder: task.group_folder,
reason: evaluation.newTrigger.reason, reason: evaluation.newTrigger.reason,
errorPreview: streamedOutput.error.slice(0, 120), errorPreview: streamedOutput.error.slice(0, 120),
}, },
@@ -486,11 +482,8 @@ async function runTask(
getCodexAccountCount() > 1 && getCodexAccountCount() > 1 &&
rotateCodexToken(lastRotationMessage) rotateCodexToken(lastRotationMessage)
) { ) {
logger.info( log.info(
{ {
taskId: task.id,
group: context.group.name,
groupFolder: task.group_folder,
reason: trigger.reason, reason: trigger.reason,
}, },
'Codex account unhealthy, retrying scheduled task with rotated account', 'Codex account unhealthy, retrying scheduled task with rotated account',
@@ -603,9 +596,8 @@ async function runTask(
} }
} // end else (non-exhausted path) } // end else (non-exhausted path)
logger.info( log.info(
{ {
taskId: task.id,
agentType: context.taskAgentType, agentType: context.taskAgentType,
durationMs: Date.now() - startTime, durationMs: Date.now() - startTime,
}, },
@@ -613,7 +605,7 @@ async function runTask(
); );
} catch (err) { } catch (err) {
error = getErrorMessage(err); error = getErrorMessage(err);
logger.error({ taskId: task.id, error }, 'Task failed'); log.error({ error }, 'Task failed');
} }
const durationMs = Date.now() - startTime; const durationMs = Date.now() - startTime;
@@ -622,10 +614,7 @@ async function runTask(
if (!currentTask) { if (!currentTask) {
await statusTracker.update('completed'); await statusTracker.update('completed');
logger.debug( log.debug('Task deleted during execution, skipping persistence');
{ taskId: task.id },
'Task deleted during execution, skipping persistence',
);
return; return;
} }
@@ -643,9 +632,8 @@ async function runTask(
if (trigger.shouldRotate) { if (trigger.shouldRotate) {
const rotated = getCodexAccountCount() > 1 && rotateCodexToken(error); const rotated = getCodexAccountCount() > 1 && rotateCodexToken(error);
if (rotated) { if (rotated) {
logger.info( log.info(
{ {
taskId: task.id,
agent: effectiveAgentType, agent: effectiveAgentType,
reason: trigger.reason, reason: trigger.reason,
}, },
@@ -661,9 +649,8 @@ async function runTask(
if (trigger.shouldRetry) { if (trigger.shouldRetry) {
const rotated = getTokenCount() > 1 && rotateToken(error); const rotated = getTokenCount() > 1 && rotateToken(error);
if (rotated) { if (rotated) {
logger.info( log.info(
{ {
taskId: task.id,
agent: effectiveAgentType, agent: effectiveAgentType,
reason: trigger.reason, reason: trigger.reason,
}, },