From 18788f7f91f5db1e0d411a85388f8686a2648e64 Mon Sep 17 00:00:00 2001 From: Eyejoker Date: Wed, 25 Mar 2026 12:16:09 +0900 Subject: [PATCH] chore: add state transition logging --- src/codex-token-rotation.ts | 43 ++++++++++++++++++++--- src/group-queue.ts | 25 ++++++++++++-- src/ipc.ts | 19 +++++++++-- src/message-runtime.ts | 24 ++++++++++++- src/message-turn-controller.ts | 29 ++++++++++++++-- src/provider-fallback.ts | 62 +++++++++++++++++++++++++++++----- src/token-rotation.ts | 30 ++++++++++++++-- 7 files changed, 207 insertions(+), 25 deletions(-) diff --git a/src/codex-token-rotation.ts b/src/codex-token-rotation.ts index 49ed617..71fad44 100644 --- a/src/codex-token-rotation.ts +++ b/src/codex-token-rotation.ts @@ -261,8 +261,10 @@ export function rotateCodexToken( ): boolean { if (accounts.length <= 1) return false; + const previousIndex = currentIndex; const acct = accounts[currentIndex]; - acct.rateLimitedUntil = computeCooldownUntil(errorMessage); + const cooldownUntil = computeCooldownUntil(errorMessage); + acct.rateLimitedUntil = cooldownUntil; acct.lastUsagePct = 100; // Extract reset time string from error for display const retryAt = parseRetryAfterFromError(errorMessage); @@ -276,9 +278,15 @@ export function rotateCodexToken( currentIndex = nextIdx; logger.info( { - accountIndex: currentIndex, + transition: 'rotation:execute', + fromIndex: previousIndex, + toIndex: currentIndex, totalAccounts: accounts.length, accountId: accounts[nextIdx].accountId, + ignoreRL: opts?.ignoreRateLimits ?? false, + cooldownUntil: + cooldownUntil != null ? new Date(cooldownUntil).toISOString() : null, + reason: errorMessage ?? null, }, `Codex rotated to account #${currentIndex + 1}/${accounts.length}`, ); @@ -286,7 +294,18 @@ export function rotateCodexToken( return true; } - logger.warn('All Codex accounts are rate-limited'); + logger.warn( + { + transition: 'rotation:skip', + fromIndex: previousIndex, + totalAccounts: accounts.length, + ignoreRL: opts?.ignoreRateLimits ?? false, + cooldownUntil: + cooldownUntil != null ? new Date(cooldownUntil).toISOString() : null, + reason: errorMessage ?? null, + }, + 'All Codex accounts are rate-limited', + ); return false; } @@ -353,7 +372,13 @@ export function updateCodexAccountUsage( const nextIdx = findNextCodexAvailable(idx); if (nextIdx !== null && nextIdx !== idx) { logger.info( - { from: idx + 1, to: nextIdx + 1, d7Pct }, + { + transition: 'rotation:auto', + fromIndex: idx, + toIndex: nextIdx, + d7Pct, + accountId: acct.accountId, + }, `Codex auto-rotating: account #${idx + 1} at ${d7Pct}% 7d → #${nextIdx + 1}`, ); currentIndex = nextIdx; @@ -367,7 +392,17 @@ export function markCodexTokenHealthy(): void { if (accounts.length === 0) return; const acct = accounts[currentIndex]; if (acct?.rateLimitedUntil) { + const previousCooldownUntil = acct.rateLimitedUntil; acct.rateLimitedUntil = null; + logger.info( + { + transition: 'rotation:clear-rate-limit', + accountIndex: currentIndex, + accountId: acct.accountId, + cooldownUntil: new Date(previousCooldownUntil).toISOString(), + }, + 'Cleared Codex account rate-limit state after successful response', + ); saveCodexState(); } } diff --git a/src/group-queue.ts b/src/group-queue.ts index a9823cb..f6c80d6 100644 --- a/src/group-queue.ts +++ b/src/group-queue.ts @@ -507,17 +507,38 @@ export class GroupQueue { this.activeCount++; this.activeTaskCount++; - logger.debug( - { groupJid, taskId: task.id, activeCount: this.activeCount }, + logger.info( + { + transition: 'queue:task:start', + groupJid, + taskId: task.id, + activeCount: this.activeCount, + activeTaskCount: this.activeTaskCount, + }, 'Running queued task', ); + let outcome: 'success' | 'error' = 'success'; try { await task.fn(); } catch (err) { + outcome = 'error'; logger.error({ groupJid, taskId: task.id, err }, 'Error running task'); } finally { this.clearPostCloseTimers(state); + const durationMs = state.startedAt ? Date.now() - state.startedAt : null; + logger.info( + { + transition: 'queue:task:finish', + groupJid, + taskId: task.id, + outcome, + durationMs, + pendingMessages: state.pendingMessages, + pendingTasks: state.pendingTasks.length, + }, + 'Finished queued task', + ); state.active = false; state.isTaskProcess = false; state.runningTaskId = null; diff --git a/src/ipc.ts b/src/ipc.ts index 44ef581..8454ca3 100644 --- a/src/ipc.ts +++ b/src/ipc.ts @@ -90,18 +90,31 @@ export function startIpcWatcher(deps: IpcDeps): void { if (msg.type === 'message' && msg.chatJid && msg.text) { // Authorization: verify this group can send to this chatJid const targetGroup = registeredGroups[msg.chatJid]; + const isMainOverride = isMain === true; if ( - isMain || + isMainOverride || (targetGroup && targetGroup.folder === sourceGroup) ) { await deps.sendMessage(msg.chatJid, msg.text); logger.info( - { chatJid: msg.chatJid, sourceGroup }, + { + transition: 'ipc:auth:allow', + chatJid: msg.chatJid, + sourceGroup, + targetGroup: targetGroup?.folder ?? null, + isMainOverride, + }, 'IPC message sent', ); } else { logger.warn( - { chatJid: msg.chatJid, sourceGroup }, + { + transition: 'ipc:auth:deny', + chatJid: msg.chatJid, + sourceGroup, + targetGroup: targetGroup?.folder ?? null, + isMainOverride, + }, 'Unauthorized IPC message attempt blocked', ); } diff --git a/src/message-runtime.ts b/src/message-runtime.ts index a487bec..edc1040 100644 --- a/src/message-runtime.ts +++ b/src/message-runtime.ts @@ -376,7 +376,18 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): { } finally { // Safety net: always clear typing even if runAgent() or finish() throws. // Prevents stuck typing indicators when exceptions bypass the normal - // turnController.finish() → setTyping(false) path. + // turnController.finish() -> setTyping(false) path. + logger.debug( + { + transition: 'typing:off', + source: 'message-runtime:safety-net', + chatJid, + group: group.name, + groupFolder: group.folder, + runId, + }, + 'Typing indicator transition', + ); await channel.setTyping?.(chatJid, false); } } @@ -530,6 +541,17 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): { endSeq, ); } + logger.debug( + { + transition: 'typing:on', + source: 'follow-up-queued', + chatJid, + group: group.name, + groupFolder: group.folder, + endSeq: endSeq ?? null, + }, + 'Typing indicator transition', + ); await channel .setTyping?.(chatJid, true) ?.catch((err) => diff --git a/src/message-turn-controller.ts b/src/message-turn-controller.ts index b492fdc..8d6e67c 100644 --- a/src/message-turn-controller.ts +++ b/src/message-turn-controller.ts @@ -56,9 +56,29 @@ export class MessageTurnController { constructor(private readonly options: MessageTurnControllerOptions) {} + private async setTyping( + isTyping: boolean, + source: string, + extra?: Record, + ): Promise { + logger.debug( + { + transition: isTyping ? 'typing:on' : 'typing:off', + source, + chatJid: this.options.chatJid, + group: this.options.group.name, + groupFolder: this.options.group.folder, + runId: this.options.runId, + ...extra, + }, + 'Typing indicator transition', + ); + await this.options.channel.setTyping?.(this.options.chatJid, isTyping); + } + async start(): Promise { this.resetIdleTimer(); - await this.options.channel.setTyping?.(this.options.chatJid, true); + await this.setTyping(true, 'turn:start'); } async handleOutput(result: AgentOutput): Promise { @@ -274,7 +294,10 @@ export class MessageTurnController { await this.finalizeProgressMessage(); } - await this.options.channel.setTyping?.(this.options.chatJid, false); + await this.setTyping(false, 'turn:handle-output', { + outputStatus: result.status, + phase, + }); if (result.status === 'success' && !this.poisonedSessionDetected) { this.requestAgentClose('output-delivered-close'); } @@ -288,7 +311,7 @@ export class MessageTurnController { deliverySucceeded: boolean; visiblePhase: VisiblePhase; }> { - await this.options.channel.setTyping?.(this.options.chatJid, false); + await this.setTyping(false, 'turn:finish', { outputStatus }); if (outputStatus === 'error') { this.hadError = true; diff --git a/src/provider-fallback.ts b/src/provider-fallback.ts index 0505256..902ad33 100644 --- a/src/provider-fallback.ts +++ b/src/provider-fallback.ts @@ -142,6 +142,22 @@ function clearUsageAvailabilityCache(): void { usageAvailabilityCheckPromise = null; } +function logCooldownTransition( + level: 'debug' | 'info' | 'warn', + transition: string, + fields: Record, + message: string, +): void { + logger[level]( + { + transition, + provider: 'claude', + ...fields, + }, + message, + ); +} + async function getClaudeUsageAvailability(): Promise< 'available' | 'exhausted' | 'unknown' > { @@ -187,10 +203,12 @@ export async function getActiveProvider(): Promise { if (cooldown.reason === 'usage-exhausted') { const usageAvailability = await getClaudeUsageAvailability(); if (usageAvailability === 'available') { - logger.info( + logCooldownTransition( + 'info', + 'cooldown:recover', { - provider: 'claude', reason: cooldown.reason, + fallbackProvider: config.providerName, }, 'Claude usage recovered, retrying primary provider', ); @@ -204,17 +222,27 @@ export async function getActiveProvider(): Promise { getTokenCount() > 1 && rotateToken(undefined, { ignoreRateLimits: true }) ) { - logger.info( + logCooldownTransition( + 'info', + 'cooldown:recover', + { + reason: cooldown.reason, + fallbackProvider: config.providerName, + recovery: 'token-rotation', + }, 'Claude current token exhausted, rotated to next token — retrying', ); cooldown = null; clearUsageAvailabilityCache(); return 'claude'; } - logger.debug( + logCooldownTransition( + 'debug', + 'cooldown:stay', { - provider: config.providerName, reason: cooldown.reason, + fallbackProvider: config.providerName, + usageAvailability, }, 'All Claude tokens exhausted, keeping cooldown active', ); @@ -223,14 +251,26 @@ export async function getActiveProvider(): Promise { } if (Date.now() < cooldown.expiresAt) { + logCooldownTransition( + 'debug', + 'cooldown:stay', + { + reason: cooldown.reason, + fallbackProvider: config.providerName, + remainingMs: cooldown.expiresAt - Date.now(), + }, + 'Claude cooldown still active, routing to fallback provider', + ); return config.providerName; } // Cooldown expired — try Claude again - logger.info( + logCooldownTransition( + 'info', + 'cooldown:expire', { - provider: 'claude', cooldownDurationMs: cooldown.expiresAt - cooldown.startedAt, reason: cooldown.reason, + fallbackProvider: config.providerName, }, 'Claude cooldown expired, retrying primary provider', ); @@ -259,7 +299,9 @@ export function markPrimaryCooldown( }; clearUsageAvailabilityCache(); - logger.info( + logCooldownTransition( + 'info', + 'cooldown:enter', { reason, cooldownMs: durationMs, @@ -274,7 +316,9 @@ export function markPrimaryCooldown( export function clearPrimaryCooldown(): void { clearUsageAvailabilityCache(); if (cooldown) { - logger.info( + logCooldownTransition( + 'info', + 'cooldown:clear', { reason: cooldown.reason }, 'Claude cooldown cleared manually', ); diff --git a/src/token-rotation.ts b/src/token-rotation.ts index fb8123e..0c7515d 100644 --- a/src/token-rotation.ts +++ b/src/token-rotation.ts @@ -118,7 +118,9 @@ export function rotateToken( ): boolean { if (tokens.length <= 1) return false; - tokens[currentIndex].rateLimitedUntil = computeCooldownUntil(errorMessage); + const previousIndex = currentIndex; + const cooldownUntil = computeCooldownUntil(errorMessage); + tokens[currentIndex].rateLimitedUntil = cooldownUntil; const nextIdx = findNextAvailable(tokens, currentIndex, opts); if (nextIdx !== null) { @@ -126,9 +128,14 @@ export function rotateToken( currentIndex = nextIdx; logger.info( { - tokenIndex: currentIndex, + transition: 'rotation:execute', + fromIndex: previousIndex, + toIndex: currentIndex, totalTokens: tokens.length, ignoreRL: opts?.ignoreRateLimits ?? false, + cooldownUntil: + cooldownUntil != null ? new Date(cooldownUntil).toISOString() : null, + reason: errorMessage ?? null, }, `Rotated to token #${currentIndex + 1}/${tokens.length}`, ); @@ -137,7 +144,15 @@ export function rotateToken( } logger.warn( - { totalTokens: tokens.length }, + { + transition: 'rotation:skip', + fromIndex: previousIndex, + totalTokens: tokens.length, + ignoreRL: opts?.ignoreRateLimits ?? false, + cooldownUntil: + cooldownUntil != null ? new Date(cooldownUntil).toISOString() : null, + reason: errorMessage ?? null, + }, 'All tokens are rate-limited, falling through to provider fallback', ); return false; @@ -148,7 +163,16 @@ export function markTokenHealthy(): void { if (tokens.length === 0) return; const state = tokens[currentIndex]; if (state?.rateLimitedUntil) { + const previousCooldownUntil = state.rateLimitedUntil; state.rateLimitedUntil = null; + logger.info( + { + transition: 'rotation:clear-rate-limit', + tokenIndex: currentIndex, + cooldownUntil: new Date(previousCooldownUntil).toISOString(), + }, + 'Cleared Claude token rate-limit state after successful response', + ); saveState(); } }