fix: separate finals from tracked progress

This commit is contained in:
Eyejoker
2026-03-23 03:54:04 +09:00
parent 78145c1d46
commit 290cd95e51
4 changed files with 940 additions and 849 deletions

View File

@@ -409,6 +409,41 @@ describe('GroupQueue', () => {
await vi.advanceTimersByTimeAsync(10); await vi.advanceTimersByTimeAsync(10);
}); });
it('keeps a post-final follow-up queued instead of preempting the idle run', async () => {
const fs = await import('fs');
let resolveProcess: () => void;
const processMessages = vi.fn(async () => {
await new Promise<void>((resolve) => {
resolveProcess = resolve;
});
return true;
});
queue.setProcessMessagesFn(processMessages);
queue.enqueueMessageCheck('group1@g.us');
await vi.advanceTimersByTimeAsync(10);
queue.registerProcess('group1@g.us', {} as any, 'agent-1', 'test-group');
queue.setFollowUpPipeAllowed('group1@g.us', () => false);
queue.notifyIdle('group1@g.us');
const writeFileSync = vi.mocked(fs.default.writeFileSync);
writeFileSync.mockClear();
queue.enqueueMessageCheck('group1@g.us', 'test-group');
const closeWrites = writeFileSync.mock.calls.filter(
(call) => typeof call[0] === 'string' && call[0].endsWith('_close'),
);
expect(closeWrites).toHaveLength(0);
resolveProcess!();
await vi.advanceTimersByTimeAsync(10);
expect(processMessages).toHaveBeenCalledTimes(2);
});
it('sendMessage resets idleWaiting so a subsequent task enqueue does not preempt', async () => { it('sendMessage resets idleWaiting so a subsequent task enqueue does not preempt', async () => {
const fs = await import('fs'); const fs = await import('fs');
let resolveProcess: () => void; let resolveProcess: () => void;

View File

@@ -111,6 +111,18 @@ export class GroupQueue {
state.followUpPipeAllowed = allowed; state.followUpPipeAllowed = allowed;
} }
private canPreemptIdleActiveRun(state: GroupState): boolean {
if (!state.idleWaiting) {
return false;
}
if (!state.followUpPipeAllowed) {
return true;
}
return state.followUpPipeAllowed();
}
private createRunId(): string { private createRunId(): string {
return `run-${Date.now().toString(36)}-${Math.random().toString(36).slice(2, 8)}`; return `run-${Date.now().toString(36)}-${Math.random().toString(36).slice(2, 8)}`;
} }
@@ -127,7 +139,7 @@ export class GroupQueue {
if (state.active) { if (state.active) {
state.pendingMessages = true; state.pendingMessages = true;
if (state.idleWaiting) { if (this.canPreemptIdleActiveRun(state)) {
this.closeStdin(groupJid, { this.closeStdin(groupJid, {
runId: state.currentRunId ?? undefined, runId: state.currentRunId ?? undefined,
reason: 'pending-message-preemption', reason: 'pending-message-preemption',
@@ -187,7 +199,7 @@ export class GroupQueue {
if (state.active) { if (state.active) {
state.pendingTasks.push({ id: taskId, groupJid, fn }); state.pendingTasks.push({ id: taskId, groupJid, fn });
if (state.idleWaiting) { if (this.canPreemptIdleActiveRun(state)) {
this.closeStdin(groupJid); this.closeStdin(groupJid);
} }
logger.debug({ groupJid, taskId }, 'Agent active, task queued'); logger.debug({ groupJid, taskId }, 'Agent active, task queued');

View File

@@ -425,9 +425,13 @@ describe('createMessageRuntime', () => {
expect(channel.editMessage).toHaveBeenCalledWith( expect(channel.editMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'progress-1', 'progress-1',
'CI 상태 확인 중입니다.\n\n10초',
);
expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid,
'CI 상태 확인 중입니다.', 'CI 상태 확인 중입니다.',
); );
expect(channel.sendMessage).not.toHaveBeenCalled();
expect(notifyIdle).toHaveBeenCalledTimes(1); expect(notifyIdle).toHaveBeenCalledTimes(1);
expect(notifyIdle).toHaveBeenCalledWith(chatJid, 'run-progress'); expect(notifyIdle).toHaveBeenCalledWith(chatJid, 'run-progress');
expect(persistSession).toHaveBeenCalledWith( expect(persistSession).toHaveBeenCalledWith(
@@ -585,7 +589,7 @@ describe('createMessageRuntime', () => {
); );
}); });
it('resets the idle timeout when follow-up Codex progress keeps arriving', async () => { it('discards late progress and duplicate final after a terminal final', async () => {
vi.useFakeTimers(); vi.useFakeTimers();
const chatJid = 'group@test'; const chatJid = 'group@test';
const group = makeGroup('codex'); const group = makeGroup('codex');
@@ -607,36 +611,34 @@ describe('createMessageRuntime', () => {
async (_group, _input, _onProcess, onOutput) => { async (_group, _input, _onProcess, onOutput) => {
await onOutput?.({ await onOutput?.({
status: 'success', status: 'success',
result: '초기 응답입니다.', phase: 'progress',
newSessionId: 'session-follow-up', result: '첫 번째 진행상황입니다.',
newSessionId: 'session-terminal',
});
await vi.advanceTimersByTimeAsync(10_000);
await onOutput?.({
status: 'success',
phase: 'final',
result: '최종 답변입니다.',
newSessionId: 'session-terminal',
}); });
await vi.advanceTimersByTimeAsync(800);
await onOutput?.({ await onOutput?.({
status: 'success', status: 'success',
phase: 'progress', phase: 'progress',
result: '후속 작업 진행입니다.', result: '늦게 도착한 진행상황입니다.',
newSessionId: 'session-follow-up', newSessionId: 'session-terminal',
}); });
await vi.advanceTimersByTimeAsync(800);
await onOutput?.({ await onOutput?.({
status: 'success', status: 'success',
phase: 'progress', phase: 'final',
result: '후속 작업 계속 진행 중입니다.', result: '중복 최종 답변입니다.',
newSessionId: 'session-follow-up', newSessionId: 'session-terminal',
});
await vi.advanceTimersByTimeAsync(800);
await onOutput?.({
status: 'success',
result: null,
newSessionId: 'session-follow-up',
}); });
return { return {
status: 'success', status: 'success',
result: null, result: null,
newSessionId: 'session-follow-up', newSessionId: 'session-terminal',
}; };
}, },
); );
@@ -665,28 +667,37 @@ describe('createMessageRuntime', () => {
try { try {
const result = await runtime.processGroupMessages(chatJid, { const result = await runtime.processGroupMessages(chatJid, {
runId: 'run-follow-up-progress', runId: 'run-terminal-final',
reason: 'messages', reason: 'messages',
}); });
expect(result).toBe(true); expect(result).toBe(true);
expect(closeStdin).toHaveBeenCalledWith(chatJid, { expect(closeStdin).toHaveBeenCalledWith(chatJid, {
runId: 'run-follow-up-progress', runId: 'run-terminal-final',
reason: 'output-delivered-close', reason: 'output-delivered-close',
}); });
expect(channel.sendMessage).toHaveBeenCalledWith( expect(channel.sendAndTrack).toHaveBeenCalledTimes(1);
chatJid,
'초기 응답입니다.',
);
expect(channel.sendAndTrack).toHaveBeenCalledWith( expect(channel.sendAndTrack).toHaveBeenCalledWith(
chatJid, chatJid,
'후속 작업 진행입니다.\n\n0초', '첫 번째 진행상황입니다.\n\n0초',
); );
expect(channel.editMessage).toHaveBeenCalledWith( expect(channel.editMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'progress-1', 'progress-1',
'후속 작업 계속 진행입니다.\n\n0초', '첫 번째 진행상황입니다.\n\n10초',
); );
expect(channel.editMessage).not.toHaveBeenCalledWith(
chatJid,
'progress-1',
'늦게 도착한 진행상황입니다.\n\n0초',
);
expect(channel.editMessage).not.toHaveBeenCalledWith(
chatJid,
'progress-1',
'중복 최종 답변입니다.',
);
expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendMessage).toHaveBeenCalledWith(chatJid, '최종 답변입니다.');
} finally { } finally {
vi.useRealTimers(); vi.useRealTimers();
} }
@@ -718,23 +729,8 @@ describe('createMessageRuntime', () => {
newSessionId: 'session-long-progress', newSessionId: 'session-long-progress',
}); });
await vi.advanceTimersByTimeAsync(70_000); await vi.advanceTimersByTimeAsync(70_000);
expect(channel.editMessage).toHaveBeenLastCalledWith(
chatJid,
'progress-1',
'오래 걸리는 작업입니다.\n\n1분 10초',
);
await vi.advanceTimersByTimeAsync(50_000); await vi.advanceTimersByTimeAsync(50_000);
expect(channel.editMessage).toHaveBeenLastCalledWith(
chatJid,
'progress-1',
'오래 걸리는 작업입니다.\n\n2분 0초',
);
await vi.advanceTimersByTimeAsync(3_480_000); await vi.advanceTimersByTimeAsync(3_480_000);
expect(channel.editMessage).toHaveBeenLastCalledWith(
chatJid,
'progress-1',
'오래 걸리는 작업입니다.\n\n1시간 0분 0초',
);
await vi.advanceTimersByTimeAsync(70_000); await vi.advanceTimersByTimeAsync(70_000);
await onOutput?.({ await onOutput?.({
status: 'success', status: 'success',
@@ -782,11 +778,20 @@ describe('createMessageRuntime', () => {
chatJid, chatJid,
'오래 걸리는 작업입니다.\n\n0초', '오래 걸리는 작업입니다.\n\n0초',
); );
expect(channel.editMessage).toHaveBeenLastCalledWith( expect(channel.editMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'progress-1', 'progress-1',
'오래 걸리는 작업입니다.\n\n1시간 0초', '오래 걸리는 작업입니다.\n\n1시간 0초',
); );
expect(channel.editMessage).toHaveBeenCalledWith(
chatJid,
'progress-1',
'오래 걸리는 작업입니다.\n\n1시간 10초',
);
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid,
'오래 걸리는 작업입니다.',
);
} finally { } finally {
vi.useRealTimers(); vi.useRealTimers();
} }
@@ -874,9 +879,13 @@ describe('createMessageRuntime', () => {
expect(channel.editMessage).toHaveBeenCalledWith( expect(channel.editMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'progress-1', 'progress-1',
'테스트를 돌리는 중입니다.\n\n10초',
);
expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid,
'테스트가 끝났습니다.', '테스트가 끝났습니다.',
); );
expect(channel.sendMessage).not.toHaveBeenCalled();
expect(notifyIdle).toHaveBeenCalledTimes(1); expect(notifyIdle).toHaveBeenCalledTimes(1);
expect(notifyIdle).toHaveBeenCalledWith(chatJid, 'run-final'); expect(notifyIdle).toHaveBeenCalledWith(chatJid, 'run-final');
} finally { } finally {
@@ -884,11 +893,12 @@ describe('createMessageRuntime', () => {
} }
}); });
it('starts a fresh tracked progress message for each Codex turn in one runner session', async () => { it('retries a silent run internally before any visible output and succeeds in the same queue item', async () => {
vi.useFakeTimers();
const chatJid = 'group@test'; const chatJid = 'group@test';
const group = makeGroup('codex'); const group = makeGroup('codex');
const channel = makeChannel(chatJid); const channel = makeChannel(chatJid);
const lastAgentTimestamps: Record<string, string> = {};
const saveState = vi.fn();
vi.mocked(db.getMessagesSince).mockReturnValue([ vi.mocked(db.getMessagesSince).mockReturnValue([
{ {
@@ -898,48 +908,29 @@ describe('createMessageRuntime', () => {
sender_name: 'User', sender_name: 'User',
content: 'hello', content: 'hello',
timestamp: '2026-03-19T00:00:00.000Z', timestamp: '2026-03-19T00:00:00.000Z',
seq: 1,
}, },
]); ]);
vi.mocked(channel.sendAndTrack!) vi.mocked(agentRunner.runAgentProcess)
.mockResolvedValueOnce('progress-1') .mockResolvedValueOnce({
.mockResolvedValueOnce('progress-2');
vi.mocked(agentRunner.runAgentProcess).mockImplementation(
async (_group, _input, _onProcess, onOutput) => {
await onOutput?.({
status: 'success', status: 'success',
phase: 'progress', result: null,
result: '첫 번째 진행상황입니다.', newSessionId: 'session-silent-rollover',
newSessionId: 'session-multi-turn', })
}); .mockImplementationOnce(async (_group, _input, _onProcess, onOutput) => {
await vi.advanceTimersByTimeAsync(10_000);
await onOutput?.({ await onOutput?.({
status: 'success', status: 'success',
phase: 'final', phase: 'final',
result: ' 번째 결과입니다.', result: ' 번째 시도에서 성공했습니다.',
newSessionId: 'session-multi-turn', newSessionId: 'session-silent-rollover',
});
await onOutput?.({
status: 'success',
phase: 'progress',
result: '두 번째 진행상황입니다.',
newSessionId: 'session-multi-turn',
});
await vi.advanceTimersByTimeAsync(10_000);
await onOutput?.({
status: 'success',
phase: 'final',
result: '두 번째 결과입니다.',
newSessionId: 'session-multi-turn',
}); });
return { return {
status: 'success', status: 'success',
result: null, result: null,
newSessionId: 'session-multi-turn', newSessionId: 'session-silent-rollover',
}; };
}, });
);
const runtime = createMessageRuntime({ const runtime = createMessageRuntime({
assistantName: 'Andy', assistantName: 'Andy',
@@ -957,57 +948,168 @@ describe('createMessageRuntime', () => {
getSessions: () => ({}), getSessions: () => ({}),
getLastTimestamp: () => '', getLastTimestamp: () => '',
setLastTimestamp: vi.fn(), setLastTimestamp: vi.fn(),
getLastAgentTimestamps: () => ({}), getLastAgentTimestamps: () => lastAgentTimestamps,
saveState: vi.fn(), saveState,
persistSession: vi.fn(), persistSession: vi.fn(),
clearSession: vi.fn(), clearSession: vi.fn(),
}); });
try {
const result = await runtime.processGroupMessages(chatJid, { const result = await runtime.processGroupMessages(chatJid, {
runId: 'run-multi-turn', runId: 'run-silent-rollover',
reason: 'messages', reason: 'messages',
}); });
expect(result).toBe(true); expect(result).toBe(true);
expect(channel.sendAndTrack).toHaveBeenNthCalledWith( expect(agentRunner.runAgentProcess).toHaveBeenCalledTimes(2);
1, expect(saveState).toHaveBeenCalled();
expect(lastAgentTimestamps[chatJid]).toBe('1');
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid, chatJid,
' 번째 진행상황입니다.\n\n0초', ' 번째 시도에서 성공했습니다.',
); );
expect(channel.sendAndTrack).toHaveBeenNthCalledWith( expect(channel.sendAndTrack).not.toHaveBeenCalled();
2, });
chatJid,
'두 번째 진행상황입니다.\n\n0초', it('retries a silent run with the original prompt still included after a queued follow-up arrives', async () => {
); const chatJid = 'group@test';
expect(channel.editMessage).toHaveBeenNthCalledWith( const group = makeGroup('codex');
1, const channel = makeChannel(chatJid);
chatJid, const lastAgentTimestamps: Record<string, string> = {};
'progress-1', const saveState = vi.fn();
'첫 번째 진행상황입니다.\n\n10초', let activityTouch:
); | ((meta?: {
expect(channel.editMessage).toHaveBeenNthCalledWith( source: 'follow-up';
2, textLength: number;
chatJid, filename: string;
'progress-1', }) => void)
'첫 번째 결과입니다.', | null = null;
); let followUpPersisted = false;
expect(channel.editMessage).toHaveBeenNthCalledWith(
3, vi.mocked(db.getMessagesSince).mockImplementation(
chatJid, (_chatJid, sinceSeqCursor) => {
'progress-2', if (String(sinceSeqCursor || '0') === '0') {
'두 번째 진행상황입니다.\n\n10초', return followUpPersisted
); ? [
expect(channel.editMessage).toHaveBeenNthCalledWith( {
4, id: 'msg-1',
chatJid, chat_jid: chatJid,
'progress-2', sender: 'user@test',
'두 번째 결과입니다.', sender_name: 'User',
); content: 'hello',
expect(channel.sendMessage).not.toHaveBeenCalled(); timestamp: '2026-03-19T00:00:00.000Z',
} finally { seq: 1,
vi.useRealTimers(); },
{
id: 'msg-2',
chat_jid: chatJid,
sender: 'codex@test',
sender_name: 'Codex',
content: 'follow-up',
timestamp: '2026-03-19T00:00:05.000Z',
seq: 2,
},
]
: [
{
id: 'msg-1',
chat_jid: chatJid,
sender: 'user@test',
sender_name: 'User',
content: 'hello',
timestamp: '2026-03-19T00:00:00.000Z',
seq: 1,
},
];
} }
if (String(sinceSeqCursor || '0') === '1' && followUpPersisted) {
return [
{
id: 'msg-2',
chat_jid: chatJid,
sender: 'codex@test',
sender_name: 'Codex',
content: 'follow-up',
timestamp: '2026-03-19T00:00:05.000Z',
seq: 2,
},
];
}
return [];
},
);
vi.mocked(agentRunner.runAgentProcess)
.mockImplementationOnce(async () => {
lastAgentTimestamps[chatJid] = '2';
followUpPersisted = true;
activityTouch?.({
source: 'follow-up',
textLength: 9,
filename: 'follow-up.json',
});
return {
status: 'success',
result: null,
newSessionId: 'session-silent-follow-up',
};
})
.mockImplementationOnce(async (_group, input, _onProcess, onOutput) => {
expect(input.prompt).toContain('hello');
expect(input.prompt).toContain('follow-up');
await onOutput?.({
status: 'success',
phase: 'final',
result: '원래 요청과 follow-up을 같이 처리했습니다.',
newSessionId: 'session-silent-follow-up',
});
return {
status: 'success',
result: null,
newSessionId: 'session-silent-follow-up',
};
});
const runtime = createMessageRuntime({
assistantName: 'Andy',
idleTimeout: 1_000,
pollInterval: 1_000,
timezone: 'UTC',
triggerPattern: /^@Andy\b/i,
channels: [channel],
queue: {
registerProcess: vi.fn(),
closeStdin: vi.fn(),
notifyIdle: vi.fn(),
setActivityTouch: vi.fn(
(_jid, touch) => (activityTouch = touch as typeof activityTouch),
),
setFollowUpPipeAllowed: vi.fn(),
} as any,
getRegisteredGroups: () => ({ [chatJid]: group }),
getSessions: () => ({}),
getLastTimestamp: () => '',
setLastTimestamp: vi.fn(),
getLastAgentTimestamps: () => lastAgentTimestamps,
saveState,
persistSession: vi.fn(),
clearSession: vi.fn(),
});
const result = await runtime.processGroupMessages(chatJid, {
runId: 'run-silent-follow-up',
reason: 'messages',
});
expect(result).toBe(true);
expect(agentRunner.runAgentProcess).toHaveBeenCalledTimes(2);
expect(saveState).toHaveBeenCalled();
expect(lastAgentTimestamps[chatJid]).toBe('2');
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid,
'원래 요청과 follow-up을 같이 처리했습니다.',
);
}); });
it('resets tracked progress after a final output that becomes empty after formatting', async () => { it('resets tracked progress after a final output that becomes empty after formatting', async () => {
@@ -1120,9 +1222,13 @@ describe('createMessageRuntime', () => {
expect(channel.editMessage).toHaveBeenCalledWith( expect(channel.editMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'progress-2', 'progress-2',
'두 번째 진행상황입니다.\n\n10초',
);
expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid,
'두 번째 진행상황입니다.', '두 번째 진행상황입니다.',
); );
expect(channel.sendMessage).not.toHaveBeenCalled();
} finally { } finally {
vi.useRealTimers(); vi.useRealTimers();
} }
@@ -1216,19 +1322,33 @@ describe('createMessageRuntime', () => {
expect(channel.editMessage).toHaveBeenCalledWith( expect(channel.editMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'progress-1', 'progress-1',
'커밋은 정상 들어갔고 pre-commit도 통과했습니다.\n\n10초',
);
expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid,
'커밋은 정상 들어갔고 pre-commit도 통과했습니다.', '커밋은 정상 들어갔고 pre-commit도 통과했습니다.',
); );
expect(channel.sendMessage).not.toHaveBeenCalled();
} finally { } finally {
vi.useRealTimers(); vi.useRealTimers();
} }
}); });
it('promotes progress-only output for a follow-up turn after a prior final in the same run', async () => { it('ignores follow-up activity after a final was already observed in the same run', async () => {
vi.useFakeTimers(); vi.useFakeTimers();
const chatJid = 'group@test'; const chatJid = 'group@test';
const group = makeGroup('codex'); const group = makeGroup('codex');
const channel = makeChannel(chatJid); const channel = makeChannel(chatJid);
const closeStdin = vi.fn();
const enqueueMessageCheck = vi.fn();
const lastAgentTimestamps: Record<string, string> = { [chatJid]: '1' };
let activityTouch:
| ((meta?: {
source: 'follow-up';
textLength: number;
filename: string;
}) => void)
| null = null;
vi.mocked(db.getMessagesSince).mockReturnValue([ vi.mocked(db.getMessagesSince).mockReturnValue([
{ {
@@ -1238,37 +1358,33 @@ describe('createMessageRuntime', () => {
sender_name: 'User', sender_name: 'User',
content: 'hello', content: 'hello',
timestamp: '2026-03-19T00:00:00.000Z', timestamp: '2026-03-19T00:00:00.000Z',
seq: 2,
}, },
]); ]);
vi.mocked(channel.sendAndTrack!).mockResolvedValueOnce(
'progress-follow-up',
);
vi.mocked(agentRunner.runAgentProcess).mockImplementation( vi.mocked(agentRunner.runAgentProcess).mockImplementation(
async (_group, _input, _onProcess, onOutput) => { async (_group, _input, _onProcess, onOutput) => {
await onOutput?.({ await onOutput?.({
status: 'success', status: 'success',
phase: 'final', phase: 'final',
result: '첫 번째 턴 최종 답변', result: '첫 번째 턴 최종 답변',
newSessionId: 'session-follow-up', newSessionId: 'session-final-boundary',
}); });
await onOutput?.({ activityTouch?.({
status: 'success', source: 'follow-up',
phase: 'progress', textLength: 32,
result: '두 번째 턴 진행상황입니다.', filename: 'late-follow-up.json',
newSessionId: 'session-follow-up',
}); });
await vi.advanceTimersByTimeAsync(10_000); lastAgentTimestamps[chatJid] = '3';
await onOutput?.({ await onOutput?.({
status: 'success', status: 'success',
result: null, result: null,
newSessionId: 'session-follow-up', newSessionId: 'session-final-boundary',
}); });
return { return {
status: 'success', status: 'success',
result: null, result: null,
newSessionId: 'session-follow-up', newSessionId: 'session-final-boundary',
}; };
}, },
); );
@@ -1282,14 +1398,18 @@ describe('createMessageRuntime', () => {
channels: [channel], channels: [channel],
queue: { queue: {
registerProcess: vi.fn(), registerProcess: vi.fn(),
closeStdin: vi.fn(), closeStdin,
notifyIdle: vi.fn(), notifyIdle: vi.fn(),
enqueueMessageCheck,
setActivityTouch: vi.fn(
(_jid, touch) => (activityTouch = touch as typeof activityTouch),
),
} as any, } as any,
getRegisteredGroups: () => ({ [chatJid]: group }), getRegisteredGroups: () => ({ [chatJid]: group }),
getSessions: () => ({}), getSessions: () => ({}),
getLastTimestamp: () => '', getLastTimestamp: () => '',
setLastTimestamp: vi.fn(), setLastTimestamp: vi.fn(),
getLastAgentTimestamps: () => ({}), getLastAgentTimestamps: () => lastAgentTimestamps,
saveState: vi.fn(), saveState: vi.fn(),
persistSession: vi.fn(), persistSession: vi.fn(),
clearSession: vi.fn(), clearSession: vi.fn(),
@@ -1297,31 +1417,23 @@ describe('createMessageRuntime', () => {
try { try {
const result = await runtime.processGroupMessages(chatJid, { const result = await runtime.processGroupMessages(chatJid, {
runId: 'run-follow-up-progress-only', runId: 'run-final-boundary',
reason: 'messages', reason: 'messages',
}); });
expect(result).toBe(true); expect(result).toBe(true);
expect(channel.sendMessage).toHaveBeenNthCalledWith( expect(closeStdin).toHaveBeenCalledWith(chatJid, {
1, runId: 'run-final-boundary',
reason: 'output-delivered-close',
});
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'첫 번째 턴 최종 답변', '첫 번째 턴 최종 답변',
); );
expect(channel.sendAndTrack).toHaveBeenCalledWith(
chatJid,
'두 번째 턴 진행상황입니다.\n\n0초',
);
expect(channel.editMessage).toHaveBeenCalledWith(
chatJid,
'progress-follow-up',
'두 번째 턴 진행상황입니다.\n\n10초',
);
expect(channel.editMessage).toHaveBeenCalledWith(
chatJid,
'progress-follow-up',
'두 번째 턴 진행상황입니다.',
);
expect(channel.sendMessage).toHaveBeenCalledTimes(1); expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendAndTrack).not.toHaveBeenCalled();
expect(enqueueMessageCheck).not.toHaveBeenCalled();
expect(lastAgentTimestamps[chatJid]).toBe('3');
} finally { } finally {
vi.useRealTimers(); vi.useRealTimers();
} }
@@ -1413,7 +1525,7 @@ describe('createMessageRuntime', () => {
chatJid, chatJid,
'진행 중입니다.\n\n0초', '진행 중입니다.\n\n0초',
); );
// 같은 메시지를 계속 편집하고, 마지막엔 final로 승격한다. // 같은 progress 메시지는 유지하고, final은 별도 메시지로 보낸다.
expect(channel.editMessage).toHaveBeenCalledWith( expect(channel.editMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'progress-1', 'progress-1',
@@ -1422,29 +1534,22 @@ describe('createMessageRuntime', () => {
expect(channel.editMessage).toHaveBeenLastCalledWith( expect(channel.editMessage).toHaveBeenLastCalledWith(
chatJid, chatJid,
'progress-1', 'progress-1',
'아직 진행 중.', '아직 진행 중.\n\n10초',
); );
expect(channel.sendMessage).not.toHaveBeenCalled(); expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendMessage).toHaveBeenCalledWith(chatJid, '아직 진행 중.');
} finally { } finally {
vi.useRealTimers(); vi.useRealTimers();
} }
}); });
it('requeues a queued follow-up as a fresh run when the active agent ends without follow-up output', async () => { it('emits one visible failure final after silent rollovers exhaust the quiet budget', async () => {
vi.useFakeTimers(); vi.useFakeTimers();
const chatJid = 'group@test'; const chatJid = 'group@test';
const group = makeGroup('codex'); const group = makeGroup('codex');
const channel = makeChannel(chatJid); const channel = makeChannel(chatJid);
const closeStdin = vi.fn(); const closeStdin = vi.fn();
const enqueueMessageCheck = vi.fn(); const lastAgentTimestamps: Record<string, string> = {};
let activityTouch:
| ((meta?: {
source: 'follow-up';
textLength: number;
filename: string;
}) => void)
| null = null;
const lastAgentTimestamps: Record<string, string> = { [chatJid]: '1' };
const saveState = vi.fn(); const saveState = vi.fn();
vi.mocked(db.getMessagesSince).mockReturnValue([ vi.mocked(db.getMessagesSince).mockReturnValue([
@@ -1455,34 +1560,17 @@ describe('createMessageRuntime', () => {
sender_name: 'User', sender_name: 'User',
content: 'hello', content: 'hello',
timestamp: '2026-03-19T00:00:00.000Z', timestamp: '2026-03-19T00:00:00.000Z',
seq: 2, seq: 1,
}, },
]); ]);
vi.mocked(agentRunner.runAgentProcess).mockImplementation( vi.mocked(agentRunner.runAgentProcess).mockImplementation(
async (_group, _input, _onProcess, onOutput) => { async () => {
await onOutput?.({ await vi.advanceTimersByTimeAsync(1_100);
status: 'success',
phase: 'final',
result: '초기 턴 응답입니다.',
newSessionId: 'session-follow-up-rerun',
});
activityTouch?.({
source: 'follow-up',
textLength: 48,
filename: 'follow-up.json',
});
lastAgentTimestamps[chatJid] = '3';
await vi.advanceTimersByTimeAsync(10_000);
await onOutput?.({
status: 'success',
result: null,
newSessionId: 'session-follow-up-rerun',
});
return { return {
status: 'success', status: 'success',
result: null, result: null,
newSessionId: 'session-follow-up-rerun', newSessionId: 'session-quiet-budget',
}; };
}, },
); );
@@ -1498,10 +1586,6 @@ describe('createMessageRuntime', () => {
registerProcess: vi.fn(), registerProcess: vi.fn(),
closeStdin, closeStdin,
notifyIdle: vi.fn(), notifyIdle: vi.fn(),
enqueueMessageCheck,
setActivityTouch: vi.fn(
(_jid, touch) => (activityTouch = touch as typeof activityTouch),
),
} as any, } as any,
getRegisteredGroups: () => ({ [chatJid]: group }), getRegisteredGroups: () => ({ [chatJid]: group }),
getSessions: () => ({}), getSessions: () => ({}),
@@ -1515,22 +1599,19 @@ describe('createMessageRuntime', () => {
try { try {
const result = await runtime.processGroupMessages(chatJid, { const result = await runtime.processGroupMessages(chatJid, {
runId: 'run-follow-up-rerun', runId: 'run-quiet-budget',
reason: 'messages', reason: 'messages',
}); });
expect(result).toBe(true); expect(result).toBe(true);
expect(closeStdin).toHaveBeenCalledWith(chatJid, { expect(agentRunner.runAgentProcess).toHaveBeenCalledTimes(3);
runId: 'run-follow-up-rerun', expect(channel.sendMessage).toHaveBeenCalledTimes(1);
reason: 'follow-up-no-output-preemption',
});
expect(lastAgentTimestamps[chatJid]).toBe('2');
expect(saveState).toHaveBeenCalled();
expect(enqueueMessageCheck).toHaveBeenCalledWith(chatJid, group.folder);
expect(channel.sendMessage).toHaveBeenCalledWith( expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid, chatJid,
'초기 턴 응답입니다.', '요청을 완료하지 못했습니다. 다시 시도해 주세요.',
); );
expect(lastAgentTimestamps[chatJid]).toBe('1');
expect(saveState).toHaveBeenCalled();
} finally { } finally {
vi.useRealTimers(); vi.useRealTimers();
} }
@@ -1608,7 +1689,7 @@ describe('createMessageRuntime', () => {
}); });
}); });
it('does not roll back when a streamed progress message was already posted before an error', async () => { it('publishes exactly one final after a visible progress when the run errors', async () => {
const chatJid = 'group@test'; const chatJid = 'group@test';
const group = makeGroup('codex'); const group = makeGroup('codex');
const channel = makeChannel(chatJid); const channel = makeChannel(chatJid);
@@ -1681,6 +1762,11 @@ describe('createMessageRuntime', () => {
chatJid, chatJid,
'중간 진행상황입니다.\n\n0초', '중간 진행상황입니다.\n\n0초',
); );
expect(channel.sendMessage).toHaveBeenCalledTimes(1);
expect(channel.sendMessage).toHaveBeenCalledWith(
chatJid,
'요청을 완료하지 못했습니다. 다시 시도해 주세요.',
);
expect(lastAgentTimestamps[chatJid]).toBe('1'); expect(lastAgentTimestamps[chatJid]).toBe('1');
expect(saveState).toHaveBeenCalled(); expect(saveState).toHaveBeenCalled();
}); });

View File

@@ -563,6 +563,21 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
} }
const isMainGroup = group.isMain === true; const isMainGroup = group.isMain === true;
const isClaudeCodeAgent =
(group.agentType || 'claude-code') === 'claude-code';
const QUIET_RUN_ROLLOVER_MS = Math.min(deps.idleTimeout, 10_000);
const MAX_SILENT_ROLLOVERS = 2;
const MAX_TOTAL_SILENT_WAIT_MS =
QUIET_RUN_ROLLOVER_MS * (MAX_SILENT_ROLLOVERS + 1);
const FAILURE_FINAL_TEXT = '요청을 완료하지 못했습니다. 다시 시도해 주세요.';
const queueItemBaseCursor = normalizeStoredSeqCursor(
deps.getLastAgentTimestamps()[chatJid] || '0',
chatJid,
);
let silentRolloverCount = 0;
let totalSilentWaitMs = 0;
while (true) {
const sinceSeqCursor = deps.getLastAgentTimestamps()[chatJid] || '0'; const sinceSeqCursor = deps.getLastAgentTimestamps()[chatJid] || '0';
const rawMissedMessages = getMessagesSinceSeq( const rawMissedMessages = getMessagesSinceSeq(
chatJid, chatJid,
@@ -615,7 +630,11 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
!requiresTrigger || !requiresTrigger ||
(hasTrigger && (hasTrigger &&
(msg.is_from_me || (msg.is_from_me ||
isTriggerAllowed(chatJid, msg.sender, loadSenderAllowlist()))) isTriggerAllowed(
chatJid,
msg.sender,
loadSenderAllowlist(),
)))
); );
}, },
}, },
@@ -654,194 +673,39 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
groupFolder: group.folder, groupFolder: group.folder,
runId, runId,
messageCount: missedMessages.length, messageCount: missedMessages.length,
silentRolloverCount,
totalSilentWaitMs,
}, },
'Dispatching queued messages to agent', 'Dispatching queued messages to agent',
); );
type VisiblePhase = 'silent' | 'progress' | 'final';
type PendingFollowUp =
| {
queuedAt: number;
textLength: number;
filename: string;
}
| null;
let idleTimer: ReturnType<typeof setTimeout> | null = null; let idleTimer: ReturnType<typeof setTimeout> | null = null;
let producedFinalText: string | null = null;
let followUpQueuedAt: number | null = null;
let followUpQueuedTextLength: number | null = null;
let followUpQueuedFilename: string | null = null;
let followUpRollbackCursor: string | null = null;
let followUpRestartRequested = false;
let followUpEndedWithoutOutputReason: string | null = null;
let followUpNoOutputWarnTimer: ReturnType<typeof setTimeout> | null = null;
let hadError = false; let hadError = false;
let producedDeliverySucceeded = true;
let quietStopReason: string | null = null;
let visiblePhase: VisiblePhase = 'silent';
let latestProgressText: string | null = null; let latestProgressText: string | null = null;
let latestProgressRendered: string | null = null; let latestProgressRendered: string | null = null;
let progressMessageId: string | null = null; let progressMessageId: string | null = null;
let progressStartedAt: number | null = null; let progressStartedAt: number | null = null;
let progressTicker: ReturnType<typeof setInterval> | null = null; let progressTicker: ReturnType<typeof setInterval> | null = null;
let progressEditFailCount = 0; let progressEditFailCount = 0;
let promotableTrackedProgressMessageId: string | null = null; let latestProgressTextForFinal: string | null = null;
let finalOutputSentToUser = false;
let progressOutputSentToUser = false;
let latestModelProgressTextForFinalFallback: string | null = null;
let sawNonProgressOutput = false;
let producedDeliverySucceeded = true;
let isFirstLogicalTurn = true;
let poisonedSessionDetected = false; let poisonedSessionDetected = false;
// Visible output 이후에는 같은 프로세스에 follow-up을 더 밀어넣지 않고 fresh run으로 넘긴다.
let canPipeFollowUps = true; let canPipeFollowUps = true;
const isClaudeCodeAgent = let pendingFollowUp: PendingFollowUp = null;
(group.agentType || 'claude-code') === 'claude-code'; const attemptStartedAt = Date.now();
const FOLLOW_UP_NO_OUTPUT_WARN_MS = 10_000;
const resetIdleTimer = () => { const hasVisibleOutput = () => visiblePhase !== 'silent';
if (idleTimer) clearTimeout(idleTimer); const terminalObserved = () => visiblePhase === 'final';
idleTimer = setTimeout(() => {
logger.debug(
{ group: group.name, chatJid, runId },
'Idle timeout, closing agent stdin',
);
if (followUpQueuedAt !== null) {
logger.warn(
{
group: group.name,
chatJid,
runId,
followUpQueuedAt: new Date(followUpQueuedAt).toISOString(),
followUpQueuedTextLength,
followUpQueuedFilename,
followUpWaitMs: Date.now() - followUpQueuedAt,
},
'Idle timeout reached while a queued follow-up still had no agent output',
);
followUpRestartRequested = true;
}
deps.queue.closeStdin(chatJid, { reason: 'idle-timeout' });
}, deps.idleTimeout);
};
const clearFollowUpNoOutputWarnTimer = () => {
if (followUpNoOutputWarnTimer) {
clearTimeout(followUpNoOutputWarnTimer);
followUpNoOutputWarnTimer = null;
}
};
const clearPendingFollowUpDiagnostics = () => {
clearFollowUpNoOutputWarnTimer();
followUpQueuedAt = null;
followUpQueuedTextLength = null;
followUpQueuedFilename = null;
followUpRollbackCursor = null;
followUpRestartRequested = false;
followUpEndedWithoutOutputReason = null;
};
const scheduleFollowUpNoOutputWarning = () => {
clearFollowUpNoOutputWarnTimer();
followUpNoOutputWarnTimer = setTimeout(() => {
if (followUpQueuedAt === null) return;
logger.warn(
{
group: group.name,
chatJid,
runId,
followUpQueuedAt: new Date(followUpQueuedAt).toISOString(),
followUpQueuedTextLength,
followUpQueuedFilename,
elapsedMs: Date.now() - followUpQueuedAt,
},
'No agent output observed within 10s of queuing a follow-up message',
);
followUpRestartRequested = true;
deps.queue.closeStdin(chatJid, {
runId,
reason: 'follow-up-no-output-preemption',
});
}, FOLLOW_UP_NO_OUTPUT_WARN_MS);
};
const noteFollowUpQueued = (meta?: {
source: 'follow-up';
textLength: number;
filename: string;
}) => {
if (meta?.source !== 'follow-up') return;
if (followUpRollbackCursor === null) {
followUpRollbackCursor = deps.getLastAgentTimestamps()[chatJid] || '0';
}
followUpQueuedAt = Date.now();
followUpQueuedTextLength = meta.textLength;
followUpQueuedFilename = meta.filename;
scheduleFollowUpNoOutputWarning();
logger.info(
{
group: group.name,
chatJid,
runId,
followUpQueuedTextLength,
followUpQueuedFilename,
},
'Registered follow-up activity for active agent',
);
};
const noteAgentOutputObserved = (phase?: string) => {
if (followUpQueuedAt === null) return;
logger.info(
{
group: group.name,
chatJid,
runId,
followUpQueuedAt: new Date(followUpQueuedAt).toISOString(),
followUpQueuedTextLength,
followUpQueuedFilename,
followUpWaitMs: Date.now() - followUpQueuedAt,
resultPhase: phase,
},
'Agent produced output after a queued follow-up',
);
clearPendingFollowUpDiagnostics();
};
const warnFollowUpEndedWithoutOutput = (reasonText: string) => {
if (followUpQueuedAt === null) return;
followUpEndedWithoutOutputReason = reasonText;
};
const requeuePendingFollowUp = (reasonText: string): boolean => {
if (followUpQueuedAt === null || followUpRollbackCursor === null) {
return false;
}
const lastAgentTimestamps = deps.getLastAgentTimestamps();
const currentCursor = lastAgentTimestamps[chatJid] || '0';
lastAgentTimestamps[chatJid] = normalizeStoredSeqCursor(
followUpRollbackCursor,
chatJid,
);
deps.saveState();
logger.warn(
{
group: group.name,
chatJid,
runId,
followUpQueuedAt: new Date(followUpQueuedAt).toISOString(),
followUpQueuedTextLength,
followUpQueuedFilename,
followUpWaitMs: Date.now() - followUpQueuedAt,
reason: reasonText,
rollbackCursor: followUpRollbackCursor,
currentCursor,
},
'Re-queueing queued follow-up after active agent ended without output',
);
clearPendingFollowUpDiagnostics();
deps.queue.enqueueMessageCheck(chatJid, group.folder);
return true;
};
deps.queue.setActivityTouch?.(chatJid, (meta) => {
noteFollowUpQueued(meta);
resetIdleTimer();
});
deps.queue.setFollowUpPipeAllowed?.(chatJid, () => canPipeFollowUps);
const clearProgressTicker = () => { const clearProgressTicker = () => {
if (progressTicker) { if (progressTicker) {
@@ -850,50 +714,6 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
} }
}; };
const resetTurnOutputState = () => {
finalOutputSentToUser = false;
progressOutputSentToUser = false;
latestModelProgressTextForFinalFallback = null;
sawNonProgressOutput = false;
producedFinalText = null;
};
const flushProducedFinalText = async (replaceMessageId?: string | null) => {
if (!producedFinalText) {
return;
}
try {
const workItem = createProducedWorkItem({
group_folder: group.folder,
chat_jid: chatJid,
agent_type: group.agentType || 'claude-code',
start_seq: isFirstLogicalTurn ? startSeq : null,
end_seq: isFirstLogicalTurn ? endSeq : null,
result_payload: producedFinalText,
});
const delivered = await deliverOpenWorkItem(channel, workItem, {
replaceMessageId,
});
if (delivered) {
finalOutputSentToUser = true;
} else {
producedDeliverySucceeded = false;
}
} catch (err) {
producedDeliverySucceeded = false;
logger.warn(
{ group: group.name, chatJid, runId, err },
'Failed to persist produced output for delivery',
);
} finally {
producedFinalText = null;
latestModelProgressTextForFinalFallback = null;
promotableTrackedProgressMessageId = null;
isFirstLogicalTurn = false;
}
};
const resetProgressState = () => { const resetProgressState = () => {
clearProgressTicker(); clearProgressTicker();
latestProgressText = null; latestProgressText = null;
@@ -903,6 +723,10 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
progressEditFailCount = 0; progressEditFailCount = 0;
}; };
const clearPendingFollowUp = () => {
pendingFollowUp = null;
};
const renderProgressMessage = (text: string) => { const renderProgressMessage = (text: string) => {
const elapsedSeconds = const elapsedSeconds =
progressStartedAt === null progressStartedAt === null
@@ -987,16 +811,54 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
return trackedMessageId; return trackedMessageId;
}; };
const deliverFinalText = async (
text: string,
replaceMessageId?: string | null,
) => {
visiblePhase = 'final';
try {
const workItem = createProducedWorkItem({
group_folder: group.folder,
chat_jid: chatJid,
agent_type: group.agentType || 'claude-code',
start_seq: startSeq,
end_seq: endSeq,
result_payload: text,
});
const delivered = await deliverOpenWorkItem(channel, workItem, {
replaceMessageId,
});
if (!delivered) {
producedDeliverySucceeded = false;
}
} catch (err) {
producedDeliverySucceeded = false;
logger.warn(
{ group: group.name, chatJid, runId, err },
'Failed to persist produced output for delivery',
);
} finally {
latestProgressTextForFinal = null;
}
};
const publishFailureFinal = async () => {
if (terminalObserved()) {
return;
}
await finalizeProgressMessage();
await deliverFinalText(FAILURE_FINAL_TEXT);
};
const sendProgressMessage = async (text: string) => { const sendProgressMessage = async (text: string) => {
if (!text || (text === latestProgressText && progressMessageId)) { if (!text || (text === latestProgressText && progressMessageId)) {
return; return;
} }
if (progressStartedAt === null) { if (progressStartedAt === null) {
resetTurnOutputState();
progressStartedAt = Date.now(); progressStartedAt = Date.now();
} }
latestModelProgressTextForFinalFallback = text; latestProgressTextForFinal = text;
latestProgressText = text; latestProgressText = text;
const rendered = renderProgressMessage(text); const rendered = renderProgressMessage(text);
@@ -1013,14 +875,14 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
'Updating tracked progress message', 'Updating tracked progress message',
); );
await syncTrackedProgressMessage(); await syncTrackedProgressMessage();
progressOutputSentToUser = true; visiblePhase = 'progress';
return; return;
} }
if (!channel.sendAndTrack) { if (!channel.sendAndTrack) {
latestProgressRendered = rendered; latestProgressRendered = rendered;
await channel.sendMessage(chatJid, rendered); await channel.sendMessage(chatJid, rendered);
progressOutputSentToUser = true; visiblePhase = 'progress';
return; return;
} }
@@ -1039,7 +901,7 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
); );
latestProgressRendered = rendered; latestProgressRendered = rendered;
await channel.sendMessage(chatJid, rendered); await channel.sendMessage(chatJid, rendered);
progressOutputSentToUser = true; visiblePhase = 'progress';
return; return;
} }
@@ -1057,15 +919,101 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
); );
latestProgressRendered = rendered; latestProgressRendered = rendered;
ensureProgressTicker(); ensureProgressTicker();
progressOutputSentToUser = true; visiblePhase = 'progress';
return; return;
} }
latestProgressRendered = rendered; latestProgressRendered = rendered;
await channel.sendMessage(chatJid, rendered); await channel.sendMessage(chatJid, rendered);
progressOutputSentToUser = true; visiblePhase = 'progress';
}; };
const resetIdleTimer = () => {
if (idleTimer) clearTimeout(idleTimer);
if (hasVisibleOutput()) {
idleTimer = null;
return;
}
idleTimer = setTimeout(() => {
const closeReason =
!hasVisibleOutput() && pendingFollowUp
? 'follow-up-no-output-preemption'
: 'idle-timeout';
quietStopReason ??=
!hasVisibleOutput() && pendingFollowUp
? 'follow-up-no-output-timeout'
: 'idle-timeout';
if (!hasVisibleOutput() && pendingFollowUp) {
logger.warn(
{
group: group.name,
chatJid,
runId,
followUpQueuedAt: new Date(
pendingFollowUp.queuedAt,
).toISOString(),
followUpQueuedTextLength: pendingFollowUp.textLength,
followUpQueuedFilename: pendingFollowUp.filename,
followUpWaitMs: Date.now() - pendingFollowUp.queuedAt,
},
'Idle timeout reached while a queued follow-up still had no visible output',
);
} else {
logger.debug(
{ group: group.name, chatJid, runId, closeReason },
'Idle timeout, closing agent stdin',
);
}
deps.queue.closeStdin(chatJid, { runId, reason: closeReason });
}, hasVisibleOutput() ? deps.idleTimeout : QUIET_RUN_ROLLOVER_MS);
};
const noteFollowUpQueued = (meta?: {
source: 'follow-up';
textLength: number;
filename: string;
}) => {
if (meta?.source !== 'follow-up' || terminalObserved()) return;
pendingFollowUp = {
queuedAt: Date.now(),
textLength: meta.textLength,
filename: meta.filename,
};
logger.info(
{
group: group.name,
chatJid,
runId,
followUpQueuedTextLength: pendingFollowUp.textLength,
followUpQueuedFilename: pendingFollowUp.filename,
},
'Registered follow-up activity for active agent',
);
resetIdleTimer();
};
const noteVisibleOutputObserved = (phase?: string) => {
if (!pendingFollowUp) return;
logger.info(
{
group: group.name,
chatJid,
runId,
followUpQueuedAt: new Date(pendingFollowUp.queuedAt).toISOString(),
followUpQueuedTextLength: pendingFollowUp.textLength,
followUpQueuedFilename: pendingFollowUp.filename,
followUpWaitMs: Date.now() - pendingFollowUp.queuedAt,
resultPhase: phase,
},
'Agent produced visible output after a queued follow-up',
);
clearPendingFollowUp();
};
deps.queue.setActivityTouch?.(chatJid, noteFollowUpQueued);
deps.queue.setFollowUpPipeAllowed?.(chatJid, () => canPipeFollowUps);
resetIdleTimer();
await channel.setTyping?.(chatJid, true); await channel.setTyping?.(chatJid, true);
const output = await runAgent( const output = await runAgent(
@@ -1074,6 +1022,21 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
chatJid, chatJid,
runId, runId,
async (result) => { async (result) => {
if (terminalObserved()) {
logger.info(
{
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
resultStatus: result.status,
resultPhase: result.phase,
},
'Discarding late agent output after terminal final',
);
return;
}
if ( if (
isClaudeCodeAgent && isClaudeCodeAgent &&
shouldResetSessionOnAgentFailure(result) && shouldResetSessionOnAgentFailure(result) &&
@@ -1092,15 +1055,15 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
); );
} }
if (result.result) {
const raw = const raw =
typeof result.result === 'string' result.result === null || result.result === undefined
? null
: typeof result.result === 'string'
? result.result ? result.result
: JSON.stringify(result.result); : JSON.stringify(result.result);
const text = formatOutbound(raw); const text = raw ? formatOutbound(raw) : null;
if (text) {
canPipeFollowUps = false; if (raw) {
}
logger.info( logger.info(
{ {
chatJid, chatJid,
@@ -1113,43 +1076,29 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
}, },
`Agent output: ${raw.slice(0, 200)}`, `Agent output: ${raw.slice(0, 200)}`,
); );
noteAgentOutputObserved(result.phase);
if (result.phase === 'progress') {
if (finalOutputSentToUser || sawNonProgressOutput) {
logger.info(
{
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
},
'New logical turn detected (follow-up), resetting turn state',
);
resetTurnOutputState();
resetProgressState();
isFirstLogicalTurn = false;
await channel.setTyping?.(chatJid, true);
} }
if (result.phase === 'progress') {
if (text) { if (text) {
canPipeFollowUps = false;
noteVisibleOutputObserved(result.phase);
await sendProgressMessage(text); await sendProgressMessage(text);
} }
if (!poisonedSessionDetected) { if (!poisonedSessionDetected) {
resetIdleTimer(); resetIdleTimer();
} }
if (result.status === 'error') {
hadError = true;
}
return; return;
} }
sawNonProgressOutput = true;
if (text) { if (text) {
const trackedProgressMessageId = await finalizeProgressMessage({ canPipeFollowUps = false;
preserveTrackedMessage: !!( noteVisibleOutputObserved(result.phase);
progressMessageId && channel.editMessage await finalizeProgressMessage();
), await deliverFinalText(text);
}); } else if (raw) {
producedFinalText = text;
await flushProducedFinalText(trackedProgressMessageId);
} else {
logger.info( logger.info(
{ {
chatJid, chatJid,
@@ -1163,20 +1112,11 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
'Agent output became empty after formatting; resetting tracked progress state', 'Agent output became empty after formatting; resetting tracked progress state',
); );
await finalizeProgressMessage(); await finalizeProgressMessage();
latestModelProgressTextForFinalFallback = null; latestProgressTextForFinal = null;
}
} else { } else {
if (result.status === 'success') { quietStopReason ??=
warnFollowUpEndedWithoutOutput('success-null-result'); result.status === 'success' ? 'success-null-result' : 'error';
} await finalizeProgressMessage();
promotableTrackedProgressMessageId = await finalizeProgressMessage({
preserveTrackedMessage: !!(
!sawNonProgressOutput &&
latestModelProgressTextForFinalFallback &&
progressMessageId &&
channel.editMessage
),
});
} }
await channel.setTyping?.(chatJid, false); await channel.setTyping?.(chatJid, false);
@@ -1186,10 +1126,7 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
if (result.status === 'success' && !poisonedSessionDetected) { if (result.status === 'success' && !poisonedSessionDetected) {
deps.queue.notifyIdle(chatJid, runId); deps.queue.notifyIdle(chatJid, runId);
// After producing visible output, close stdin so the process exits if (hasVisibleOutput()) {
// promptly instead of lingering in idle wait. New messages will
// always start a fresh run.
if (finalOutputSentToUser || progressOutputSentToUser) {
deps.queue.closeStdin(chatJid, { deps.queue.closeStdin(chatJid, {
runId, runId,
reason: 'output-delivered-close', reason: 'output-delivered-close',
@@ -1207,14 +1144,18 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
if (output === 'error') { if (output === 'error') {
hadError = true; hadError = true;
quietStopReason ??= 'error';
} else if (visiblePhase === 'silent') {
quietStopReason ??= 'success-null-result';
} }
const settledVisiblePhase = visiblePhase as VisiblePhase;
if ( if (
output === 'success' && output === 'success' &&
settledVisiblePhase === 'progress' &&
!hadError && !hadError &&
!producedFinalText && latestProgressTextForFinal
!sawNonProgressOutput &&
latestModelProgressTextForFinalFallback
) { ) {
logger.info( logger.info(
{ {
@@ -1223,54 +1164,69 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
groupFolder: group.folder, groupFolder: group.folder,
runId, runId,
}, },
'Promoting last progress output to final message after agent completion', 'Sending a separate final message from the last progress output after agent completion',
);
const trackedProgressMessageId = await finalizeProgressMessage({
preserveTrackedMessage: !!(progressMessageId && channel.editMessage),
});
producedFinalText = latestModelProgressTextForFinalFallback;
await flushProducedFinalText(
trackedProgressMessageId || promotableTrackedProgressMessageId,
); );
await finalizeProgressMessage();
await deliverFinalText(latestProgressTextForFinal);
} else if (
settledVisiblePhase === 'progress' &&
!terminalObserved() &&
(hadError || quietStopReason === 'idle-timeout')
) {
await publishFailureFinal();
} }
clearProgressTicker(); const pendingFollowUpSnapshot = pendingFollowUp as PendingFollowUp;
const quietWaitStartedAt =
pendingFollowUpSnapshot?.queuedAt ?? attemptStartedAt;
const quietWaitMs = Date.now() - quietWaitStartedAt;
clearProgressTicker();
if (idleTimer) clearTimeout(idleTimer); if (idleTimer) clearTimeout(idleTimer);
deps.queue.setActivityTouch?.(chatJid, null); deps.queue.setActivityTouch?.(chatJid, null);
deps.queue.setFollowUpPipeAllowed?.(chatJid, null); deps.queue.setFollowUpPipeAllowed?.(chatJid, null);
clearPendingFollowUp();
const finalFollowUpRequeueReason = if (settledVisiblePhase === 'silent') {
followUpEndedWithoutOutputReason || const nextTotalSilentWaitMs = totalSilentWaitMs + quietWaitMs;
(followUpRestartRequested ? 'follow-up-no-output-timeout' : null); const canRolloverAgain =
if ( silentRolloverCount < MAX_SILENT_ROLLOVERS &&
finalFollowUpRequeueReason && nextTotalSilentWaitMs <= MAX_TOTAL_SILENT_WAIT_MS;
requeuePendingFollowUp(finalFollowUpRequeueReason)
) {
return true;
}
clearPendingFollowUpDiagnostics(); if (canRolloverAgain) {
deps.getLastAgentTimestamps()[chatJid] = queueItemBaseCursor;
if (hadError) {
if (
finalOutputSentToUser ||
progressOutputSentToUser ||
producedFinalText
) {
logger.warn(
{ chatJid, group: group.name, groupFolder: group.folder, runId },
'Agent error after output was produced, skipping cursor rollback to prevent duplicates',
);
return producedFinalText ? producedDeliverySucceeded : true;
}
deps.getLastAgentTimestamps()[chatJid] = previousCursor;
deps.saveState(); deps.saveState();
silentRolloverCount++;
totalSilentWaitMs = nextTotalSilentWaitMs;
logger.warn( logger.warn(
{ chatJid, group: group.name, groupFolder: group.folder, runId }, {
'Agent error, rolled back message cursor for retry', chatJid,
group: group.name,
groupFolder: group.folder,
runId,
quietStopReason,
rollbackCursor: queueItemBaseCursor,
silentRolloverCount,
totalSilentWaitMs,
},
'Retrying silent run within the same queue item',
); );
return false; continue;
}
logger.warn(
{
chatJid,
group: group.name,
groupFolder: group.folder,
runId,
quietStopReason,
silentRolloverCount,
totalSilentWaitMs: nextTotalSilentWaitMs,
},
'Silent run budget exhausted, emitting failure final',
);
await publishFailureFinal();
} }
if (!producedDeliverySucceeded) { if (!producedDeliverySucceeded) {
@@ -1287,13 +1243,15 @@ export function createMessageRuntime(deps: MessageRuntimeDeps): {
group: group.name, group: group.name,
groupFolder: group.folder, groupFolder: group.folder,
runId, runId,
outputSentToUser: finalOutputSentToUser, visiblePhase: settledVisiblePhase,
progressOutputSentToUser, silentRolloverCount,
totalSilentWaitMs,
}, },
'Queued run completed successfully', 'Queued run completed successfully',
); );
return true; return true;
}
}; };
const startMessageLoop = async (): Promise<void> => { const startMessageLoop = async (): Promise<void> => {