claude-bot/EJClaw
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

chore: add state transition logging

Browse Source
This commit is contained in:
Eyejoker
2026-03-25 12:16:09 +09:00
parent cc7cfbbc5f
commit 18788f7f91
7 changed files with 207 additions and 25 deletions
Download Patch File Download Diff File Expand all files Collapse all files

43
src/codex-token-rotation.ts
View File

@@ -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();
}
}

25
src/group-queue.ts
View File

@@ -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;

19
src/ipc.ts
View File

@@ -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',
);
}

24
src/message-runtime.ts
View File

@@ -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) =>

29
src/message-turn-controller.ts
View File

@@ -56,9 +56,29 @@ export class MessageTurnController {
constructor(private readonly options: MessageTurnControllerOptions) {}
private async setTyping(
isTyping: boolean,
source: string,
extra?: Record<string, unknown>,
): Promise<void> {
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<void> {
this.resetIdleTimer();
await this.options.channel.setTyping?.(this.options.chatJid, true);
await this.setTyping(true, 'turn:start');
}
async handleOutput(result: AgentOutput): Promise<void> {
@@ -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;

62
src/provider-fallback.ts
View File

@@ -142,6 +142,22 @@ function clearUsageAvailabilityCache(): void {
usageAvailabilityCheckPromise = null;
}
function logCooldownTransition(
level: 'debug' | 'info' | 'warn',
transition: string,
fields: Record<string, unknown>,
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<string> {
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<string> {
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<string> {
}
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',
);

30
src/token-rotation.ts
View File

@@ -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();
}
}