Skip to content

Commit 0b7607e

Browse files
jkyberneeesclaude
andauthored
fix(concurrency): stop /new orphaning per-chat mutex; raise sub-agent stdout scan cap (#29)
Two concurrency/correctness bugs from the audit (FIX_PLAN.md item 5): 1. Telegram /new deleted the per-chat mutex (chatMu.Delete) while an in-flight handleChatMessage goroutine still held it. The next message LoadOrStored a fresh mutex and TryLocked it successfully, so two agent runs executed concurrently for the same chat — corrupting interleaved sessionManager.Save writes and clobbering each other's approver. The /new reset is extracted into resetChatForNew, which archives the session and resets approver trust but retains the mutex (naturally bounded, one per chat ID, so not a meaningful leak). 2. delegate_tasks read sub-agent stdout with a default bufio.Scanner (64KB token cap). A streamed tool_call event embedding large tool args (e.g. a big write_file) exceeded the cap -> ErrTooLong -> reader stopped -> child blocked on a full pipe -> cmd.Wait hung until the 120s timeout killed a task that had actually succeeded. The scan loop is extracted into scanSubagentStream with the buffer cap raised to 10 MiB. Both paths now have regression tests (verified to fail without the fix): TestResetChatForNew_KeepsMutex and TestScanSubagentStream_LargeLineNotTruncated. https://claude.ai/code/session_01PGZHe9fYB8p7eb6Rs8VLHt Co-authored-by: Claude <noreply@anthropic.com>
1 parent 2d63470 commit 0b7607e

4 files changed

Lines changed: 233 additions & 34 deletions

File tree

cmd/odek/subagent_scan_test.go

Lines changed: 75 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,75 @@
1+
package main
2+
3+
import (
4+
"strings"
5+
"testing"
6+
)
7+
8+
// TestScanSubagentStream_LargeLineNotTruncated is the regression test for the
9+
// >64KB NDJSON line bug. A streamed tool_call event embedding large tool
10+
// arguments exceeds bufio.Scanner's default 64KB token cap. With the default
11+
// cap the scanner returns ErrTooLong, the result that follows is never read,
12+
// and (in production) the child blocks on a full pipe until the timeout. This
13+
// test feeds an oversized progress line followed by the real result and asserts
14+
// the result is still parsed and no scanner error occurs.
15+
func TestScanSubagentStream_LargeLineNotTruncated(t *testing.T) {
16+
// A tool_call progress line whose embedded args are ~256KB — well past the
17+
// 64KB default scanner cap, but under maxSubagentLine.
18+
bigArg := strings.Repeat("a", 256*1024)
19+
progress := `{"type":"tool_call","name":"write_file","args":{"content":"` + bigArg + `"}}`
20+
result := `{"status":"success","summary":"wrote the file"}`
21+
input := progress + "\n" + result + "\n"
22+
23+
var logged int
24+
res, lastLine, err := scanSubagentStream(strings.NewReader(input), func(string) { logged++ })
25+
if err != nil {
26+
t.Fatalf("scanSubagentStream returned error on large line: %v", err)
27+
}
28+
if res == nil {
29+
t.Fatal("result is nil — the final result line was lost after the oversized progress line")
30+
}
31+
if res["status"] != "success" {
32+
t.Errorf("result status = %v, want success", res["status"])
33+
}
34+
if logged != 1 {
35+
t.Errorf("onLog called %d times, want 1 (the big progress line)", logged)
36+
}
37+
if lastLine != result {
38+
t.Errorf("lastLine = %q, want the result line", lastLine)
39+
}
40+
}
41+
42+
// TestScanSubagentStream_NormalFlow verifies ordinary progress + result parsing
43+
// and that progress lines are forwarded to onLog while the result is returned.
44+
func TestScanSubagentStream_NormalFlow(t *testing.T) {
45+
input := strings.Join([]string{
46+
`{"type":"tool_call","name":"shell"}`,
47+
`{"type":"tool_result","name":"shell"}`,
48+
`{"status":"success","summary":"done"}`,
49+
}, "\n") + "\n"
50+
51+
var logs []string
52+
res, _, err := scanSubagentStream(strings.NewReader(input), func(l string) { logs = append(logs, l) })
53+
if err != nil {
54+
t.Fatalf("unexpected error: %v", err)
55+
}
56+
if res == nil || res["summary"] != "done" {
57+
t.Fatalf("result = %v, want summary=done", res)
58+
}
59+
if len(logs) != 2 {
60+
t.Errorf("onLog called %d times, want 2 progress lines", len(logs))
61+
}
62+
}
63+
64+
// TestScanSubagentStream_NilOnLog ensures a nil onLog callback is tolerated
65+
// (the production path passes nil when no streaming sink is attached).
66+
func TestScanSubagentStream_NilOnLog(t *testing.T) {
67+
input := `{"type":"tool_call"}` + "\n" + `{"status":"ok"}` + "\n"
68+
res, _, err := scanSubagentStream(strings.NewReader(input), nil)
69+
if err != nil {
70+
t.Fatalf("unexpected error: %v", err)
71+
}
72+
if res == nil || res["status"] != "ok" {
73+
t.Fatalf("result = %v, want status=ok", res)
74+
}
75+
}

cmd/odek/subagent_tool.go

Lines changed: 53 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import (
55
"context"
66
"encoding/json"
77
"fmt"
8+
"io"
89
"os"
910
"os/exec"
1011
"strings"
@@ -241,34 +242,15 @@ func (t *delegateTasksTool) runTask(taskIdx int, goal, taskContext, guidance, tr
241242
return fmt.Sprintf(`{"error":"start: %v"}`, err)
242243
}
243244

244-
// Read stdout line-by-line — NDJSON progress lines followed by final JSON result
245-
var result map[string]any
246-
var lastLine string
247-
scanner := bufio.NewScanner(stdout)
248-
for scanner.Scan() {
249-
line := scanner.Text()
250-
lastLine = line
251-
252-
// Check if this is a progress line (NDJSON with "type":"tool_call" or "type":"tool_result")
253-
var event struct {
254-
Type string `json:"type"`
255-
}
256-
if err := json.Unmarshal([]byte(line), &event); err == nil {
257-
if event.Type == "tool_call" || event.Type == "tool_result" {
258-
if t.OnSubagentLog != nil {
259-
t.OnSubagentLog(taskIdx, line)
260-
}
261-
continue
262-
}
263-
}
264-
265-
// Not a progress line — parse as result JSON
266-
var r map[string]any
267-
if err := json.Unmarshal([]byte(line), &r); err == nil {
268-
result = r
269-
}
245+
// Read stdout line-by-line — NDJSON progress lines followed by final JSON
246+
// result. A streamed tool_call event can embed full tool arguments (e.g. a
247+
// large write_file), so lines routinely exceed bufio.Scanner's default 64KB
248+
// token cap; scanSubagentStream raises the cap to avoid losing the result.
249+
var onLog func(line string)
250+
if t.OnSubagentLog != nil {
251+
onLog = func(line string) { t.OnSubagentLog(taskIdx, line) }
270252
}
271-
scannerErr := scanner.Err()
253+
result, lastLine, scannerErr := scanSubagentStream(stdout, onLog)
272254

273255
if err := cmd.Wait(); err != nil {
274256
// Process exited with error — result may still be valid
@@ -302,5 +284,49 @@ func (t *delegateTasksTool) runTask(taskIdx int, goal, taskContext, guidance, tr
302284
return `{"error":"no result from sub-agent"}`
303285
}
304286

287+
// maxSubagentLine caps a single NDJSON line read from a sub-agent's stdout.
288+
// Streamed tool_call events embed full tool arguments (e.g. a large write_file
289+
// or patch), which routinely exceed bufio.Scanner's default 64KB token cap.
290+
// Without a raised cap the scanner returns bufio.ErrTooLong, the reader stops,
291+
// the child blocks writing to a full stdout pipe, and cmd.Wait hangs until the
292+
// timeout kills a task that actually completed successfully.
293+
const maxSubagentLine = 10 << 20 // 10 MiB
294+
295+
// scanSubagentStream reads a sub-agent's NDJSON stdout: zero or more progress
296+
// lines (objects with "type":"tool_call" or "type":"tool_result") followed by
297+
// the final JSON result object. Progress lines are forwarded to onLog (when
298+
// non-nil); the last line that parses as a JSON object is returned as result.
299+
// It returns the result map (nil if none parsed), the last raw line seen, and
300+
// any scanner error. The scan buffer is sized to maxSubagentLine so large
301+
// streamed events do not truncate the stream.
302+
func scanSubagentStream(r io.Reader, onLog func(line string)) (result map[string]any, lastLine string, err error) {
303+
scanner := bufio.NewScanner(r)
304+
scanner.Buffer(make([]byte, 0, 64*1024), maxSubagentLine)
305+
for scanner.Scan() {
306+
line := scanner.Text()
307+
lastLine = line
308+
309+
// Check if this is a progress line (NDJSON with "type":"tool_call" or "type":"tool_result")
310+
var event struct {
311+
Type string `json:"type"`
312+
}
313+
if uerr := json.Unmarshal([]byte(line), &event); uerr == nil {
314+
if event.Type == "tool_call" || event.Type == "tool_result" {
315+
if onLog != nil {
316+
onLog(line)
317+
}
318+
continue
319+
}
320+
}
321+
322+
// Not a progress line — parse as result JSON
323+
var rmap map[string]any
324+
if uerr := json.Unmarshal([]byte(line), &rmap); uerr == nil {
325+
result = rmap
326+
}
327+
}
328+
return result, lastLine, scanner.Err()
329+
}
330+
305331
// Ensure delegateTasksTool implements odek.Tool
306332
var _ odek.Tool = (*delegateTasksTool)(nil)

cmd/odek/telegram.go

Lines changed: 20 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -82,6 +82,25 @@ func getChatMutex(chatID int64) *sync.Mutex {
8282
return v.(*sync.Mutex)
8383
}
8484

85+
// resetChatForNew implements the /new command's session reset: it archives the
86+
// current session and clears the approver's trust state for a fresh start.
87+
//
88+
// It deliberately does NOT remove the per-chat mutex from chatMu. Deleting the
89+
// mutex while an in-flight handleChatMessage goroutine still holds it lets the
90+
// next message LoadOrStore a *fresh* mutex and TryLock it successfully, so two
91+
// agent runs execute concurrently for the same chat — corrupting interleaved
92+
// sessionManager.Save writes and clobbering each other's approver. The per-chat
93+
// mutex is naturally bounded (one entry per chat ID ever seen), so retaining it
94+
// is not a meaningful leak.
95+
func resetChatForNew(chatID int64, sessionManager *telegram.SessionManager, handler *telegram.Handler, log telegram.Logger) {
96+
if err := sessionManager.ArchiveAndDelete(chatID); err != nil {
97+
log.Warn("archive session", "chat_id", chatID, "error", err)
98+
}
99+
if a := handler.GetApprover(chatID); a != nil {
100+
a.ResetTrust()
101+
}
102+
}
103+
85104
// telegramCmd is the entry point for "odek telegram".
86105
func telegramCmd(args []string) error {
87106
// 0. Acquire singleton lock — kill any stale previous instance.
@@ -266,13 +285,7 @@ func telegramCmd(args []string) error {
266285
// The current session is preserved as a timestamped archive file
267286
// so it can be revisited via `odek session list`.
268287
if cmdName == "new" {
269-
if err := sessionManager.ArchiveAndDelete(chatID); err != nil {
270-
handlerLog.Warn("archive session", "chat_id", chatID, "error", err)
271-
}
272-
chatMu.Delete(chatID) // prevent mutex leak on session reset
273-
if a := handler.GetApprover(chatID); a != nil {
274-
a.ResetTrust()
275-
}
288+
resetChatForNew(chatID, sessionManager, handler, handlerLog)
276289
var b strings.Builder
277290
b.WriteString("🔄 *Session archived, starting fresh*\n\n")
278291
fmt.Fprintf(&b, "• Model: `%s`\n", resolved.Model)
Lines changed: 85 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,85 @@
1+
package main
2+
3+
import (
4+
"sync"
5+
"testing"
6+
"time"
7+
8+
"github.com/BackendStack21/odek/internal/session"
9+
"github.com/BackendStack21/odek/internal/telegram"
10+
)
11+
12+
// TestResetChatForNew_KeepsMutex is the regression test for the "/new deletes
13+
// the per-chat mutex while a run holds it" bug. The scenario:
14+
//
15+
// 1. An in-flight handleChatMessage goroutine holds the per-chat mutex (run A).
16+
// 2. The user sends /new, which calls resetChatForNew.
17+
// 3. The next message calls getChatMutex again (run B).
18+
//
19+
// If resetChatForNew removes the mutex from chatMu (the old behavior), run B's
20+
// getChatMutex LoadOrStores a *fresh* mutex and TryLocks it successfully — two
21+
// runs execute concurrently for the same chat. This test asserts the mutex is
22+
// preserved across the reset so run B still blocks on run A.
23+
func TestResetChatForNew_KeepsMutex(t *testing.T) {
24+
withTempHome(t) // session.NewStore writes under a sandbox HOME
25+
26+
chatID := int64(770001)
27+
chatMu = sync.Map{} // isolate from other tests
28+
29+
store, err := session.NewStore()
30+
if err != nil {
31+
t.Fatalf("session.NewStore: %v", err)
32+
}
33+
sm := telegram.NewSessionManager(store, time.Hour)
34+
bot := telegram.NewBot("test:token")
35+
handler := telegram.NewHandler(bot)
36+
37+
// Run A acquires the per-chat mutex and holds it for the duration.
38+
muA := getChatMutex(chatID)
39+
if !muA.TryLock() {
40+
t.Fatal("run A could not acquire a fresh mutex")
41+
}
42+
defer muA.Unlock()
43+
44+
// User sends /new while run A is still in flight.
45+
resetChatForNew(chatID, sm, handler, telegram.NewNopLogger())
46+
47+
// Run B fetches the per-chat mutex. It MUST be the same instance run A
48+
// holds, so B cannot lock it — serialization is preserved.
49+
muB := getChatMutex(chatID)
50+
if muB != muA {
51+
t.Fatal("resetChatForNew orphaned the per-chat mutex: run B got a different mutex and would run concurrently with run A")
52+
}
53+
if muB.TryLock() {
54+
muB.Unlock()
55+
t.Fatal("run B was able to lock the per-chat mutex while run A holds it — concurrent same-chat runs possible")
56+
}
57+
}
58+
59+
// TestResetChatForNew_ResetsApproverTrust verifies the reset still clears the
60+
// approver's trust state (the legitimate purpose of /new's reset), so removing
61+
// the mutex delete did not drop the approver reset.
62+
func TestResetChatForNew_ResetsApproverTrust(t *testing.T) {
63+
withTempHome(t)
64+
65+
chatID := int64(770002)
66+
chatMu = sync.Map{}
67+
68+
store, err := session.NewStore()
69+
if err != nil {
70+
t.Fatalf("session.NewStore: %v", err)
71+
}
72+
sm := telegram.NewSessionManager(store, time.Hour)
73+
bot := telegram.NewBot("test:token")
74+
handler := telegram.NewHandler(bot)
75+
76+
approver := telegram.NewTelegramApprover(bot, chatID)
77+
handler.SetApprover(chatID, approver)
78+
79+
// Should not panic and should reach the approver reset path.
80+
resetChatForNew(chatID, sm, handler, telegram.NewNopLogger())
81+
82+
if handler.GetApprover(chatID) != approver {
83+
t.Fatal("approver unexpectedly replaced by resetChatForNew")
84+
}
85+
}

0 commit comments

Comments
 (0)