test: unit + E2E tests for live sub-agent log streaming

- loop: TestEngine_ToolEventHandler — verifies tool_call + tool_result
  fire in correct order during agent loop
- subagent_tool: TestDelegateTasksTool_OnSubagentLog — verifies
  NDJSON progress lines fire via callback, non-NDJSON output handled,
  exit errors reported correctly
- serve: TestServe_E2E_LiveToolEvents — verifies tool_call and
  tool_result events arrive BEFORE done (proves live streaming)

Author: jkyberneees

cmd/odek/serve_test.go

@@ -1274,3 +1274,103 @@ sessionCheck:
 	t.Log("✅ Token stats verified: turn-level + session-level accumulation")
 }
 
+// TestServe_E2E_LiveToolEvents verifies that tool_call and tool_result
+// events stream LIVE via ToolEventHandler (before the done event).
+// This confirms the live streaming pipeline works.
+func TestServe_E2E_LiveToolEvents(t *testing.T) {
+	// Mock LLM: one tool call, then final answer.
+	callCount := 0
+	llmSrv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		callCount++
+		w.Header().Set("Content-Type", "application/json")
+		if callCount == 1 {
+			fmt.Fprint(w, `{"choices":[{"message":{"content":"Running.","tool_calls":[{"id":"c_1","function":{"name":"shell","arguments":"{\"command\":\"echo ok\"}"}}]}}],"usage":{"prompt_tokens":100,"completion_tokens":20}}`)
+		} else {
+			fmt.Fprint(w, `{"choices":[{"message":{"content":"All done."}}],"usage":{"prompt_tokens":200,"completion_tokens":40}}`)
+		}
+	}))
+	defer llmSrv.Close()
+
+	envCleanup := setTestEnv(t, llmSrv.URL)
+	defer envCleanup()
+
+	store := newTestSessionStore(t)
+	ln, mux := buildServeMux(t, store)
+	defer ln.Close()
+
+	errCh := make(chan error, 1)
+	go func() { errCh <- serveOnListener(ln, mux) }()
+	waitForHTTP(t, ln.Addr().String())
+
+	wsURL := "ws://" + ln.Addr().String() + "/ws"
+	conn, err := golangws.Dial(wsURL, "", "http://localhost")
+	if err != nil {
+		t.Fatalf("Dial(%q): %v", wsURL, err)
+	}
+	defer conn.Close()
+
+	// Send prompt
+	payload, _ := json.Marshal(map[string]string{"type": "prompt", "content": "run a step"})
+	if err := golangws.Message.Send(conn, string(payload)); err != nil {
+		t.Fatalf("Send: %v", err)
+	}
+
+	conn.SetReadDeadline(time.Now().Add(15 * time.Second))
+
+	var toolCallTime, toolResultTime, doneTime int
+	var eventOrder []string
+
+	for i := 0; i < 10; i++ {
+		var raw []byte
+		if err := golangws.Message.Receive(conn, &raw); err != nil {
+			t.Fatalf("Receive event %d: %v", i, err)
+		}
+
+		var evt map[string]any
+		if err := json.Unmarshal(raw, &evt); err != nil {
+			t.Fatalf("unmarshal event %d: %v", i, err)
+		}
+
+		typ, _ := evt["type"].(string)
+		eventOrder = append(eventOrder, typ)
+
+		switch typ {
+		case "tool_call":
+			toolCallTime = i
+		case "tool_result":
+			toolResultTime = i
+			// Verify tool_result data is present (not empty)
+			if data, ok := evt["data"]; !ok || data == "" {
+				t.Errorf("tool_result missing 'data' field, got: %v", evt)
+			}
+		case "done":
+			doneTime = i
+			goto doneCheck
+		case "error":
+			t.Fatalf("unexpected error: %v", evt["message"])
+		}
+	}
+
+doneCheck:
+	t.Logf("Event order: %v", eventOrder)
+
+	if toolCallTime == 0 {
+		t.Fatal("missing tool_call event")
+	}
+	if toolResultTime == 0 {
+		t.Fatal("missing tool_result event")
+	}
+	if doneTime == 0 {
+		t.Fatal("missing done event")
+	}
+
+	// Tool events should arrive BEFORE done (live streaming)
+	if toolCallTime > doneTime {
+		t.Error("tool_call should arrive before done (live streaming)")
+	}
+	if toolResultTime > doneTime {
+		t.Error("tool_result should arrive before done (live streaming)")
+	}
+
+	t.Log("✅ Live tool events verified: tool_call + tool_result arrive before done")
+}

cmd/odek/subagent_tool_test.go

@@ -0,0 +1,139 @@
+package main
+
+import (
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+	"time"
+)
+
+// TestDelegateTasksTool_OnSubagentLog verifies that the OnSubagentLog callback
+// fires for each NDJSON progress line emitted by the subagent subprocess,
+// and that the final result is correctly parsed from the last line.
+func TestDelegateTasksTool_OnSubagentLog(t *testing.T) {
+	// Create a mock subagent script that outputs NDJSON log lines
+	// followed by a final result JSON.
+	mockDir := t.TempDir()
+	mockScript := filepath.Join(mockDir, "mock-subagent.sh")
+
+	ndjsonOutput := `{"type":"tool_call","name":"read_file","data":"test.go"}
+{"type":"tool_result","name":"read_file","data":"file content"}
+{"type":"tool_call","name":"shell","data":"echo hello"}
+{"type":"tool_result","name":"shell","data":"hello world"}
+{"status":"success","summary":"All done.","tokens_used":150,"iterations":2,"files_changed":["test.go"]}`
+
+	// Write a shell script that outputs the NDJSON content line by line
+	script := "#!/bin/sh\n"
+	for _, line := range strings.Split(ndjsonOutput, "\n") {
+		script += "echo '" + line + "'\n"
+	}
+	script += "exit 0\n"
+
+	if err := os.WriteFile(mockScript, []byte(script), 0755); err != nil {
+		t.Fatalf("write mock script: %v", err)
+	}
+
+	// Build the tool pointing at the mock script
+	tool := &delegateTasksTool{
+		maxConcurrency: 1,
+		odekPath:       mockScript,
+		timeout:        10 * time.Second,
+	}
+
+	// Collect log events
+	var logEvents []string
+	tool.OnSubagentLog = func(taskIdx int, line string) {
+		logEvents = append(logEvents, line)
+	}
+
+	// Run a task
+	result := tool.runTask(0, "test goal", "", "")
+
+	// Verify log events: should have 4 NDJSON lines
+	if len(logEvents) != 4 {
+		t.Errorf("expected 4 log events, got %d: %v", len(logEvents), logEvents)
+	}
+
+	// Verify each log event has the right type
+	if len(logEvents) > 0 && !strings.Contains(logEvents[0], `"type":"tool_call"`) {
+		t.Errorf("log[0] should be tool_call, got: %s", logEvents[0])
+	}
+	if len(logEvents) > 1 && !strings.Contains(logEvents[1], `"type":"tool_result"`) {
+		t.Errorf("log[1] should be tool_result, got: %s", logEvents[1])
+	}
+
+	// Verify the final result contains the summary
+	if !strings.Contains(result, "All done") {
+		t.Errorf("final result should contain summary, got: %s", result)
+	}
+	if !strings.Contains(result, `"tokens_used": 150`) {
+		t.Errorf("final result should have tokens_used, got: %s", result)
+	}
+}
+
+// TestDelegateTasksTool_OnSubagentLog_NoLogLines verifies that the tool
+// correctly handles a subagent that outputs only the final result (no NDJSON).
+func TestDelegateTasksTool_OnSubagentLog_NoLogLines(t *testing.T) {
+	mockDir := t.TempDir()
+	mockScript := filepath.Join(mockDir, "mock-subagent2.sh")
+
+	resultJSON := `{"status":"success","summary":"Quick task.","tokens_used":30,"iterations":1,"files_changed":[]}`
+
+	script := "#!/bin/sh\necho '" + resultJSON + "'\nexit 0\n"
+	if err := os.WriteFile(mockScript, []byte(script), 0755); err != nil {
+		t.Fatalf("write mock script: %v", err)
+	}
+
+	var logEvents []string
+	tool := &delegateTasksTool{
+		maxConcurrency: 1,
+		odekPath:       mockScript,
+		timeout:        10 * time.Second,
+		OnSubagentLog: func(taskIdx int, line string) {
+			logEvents = append(logEvents, line)
+		},
+	}
+
+	result := tool.runTask(0, "quick", "", "")
+
+	if len(logEvents) != 0 {
+		t.Errorf("expected 0 log events for no-NDJSON output, got %d", len(logEvents))
+	}
+	if !strings.Contains(result, "Quick task") {
+		t.Errorf("result should contain summary, got: %s", result)
+	}
+}
+
+// TestDelegateTasksTool_OnSubagentLog_ExitError verifies error handling
+// when the subagent exits with non-zero status (timeout-like).
+func TestDelegateTasksTool_OnSubagentLog_ExitError(t *testing.T) {
+	mockDir := t.TempDir()
+	mockScript := filepath.Join(mockDir, "mock-fail.sh")
+
+	// Script that outputs partial NDJSON then fails
+	script := "#!/bin/sh\necho '{\"type\":\"tool_call\",\"name\":\"fail\",\"data\":\"\"}'\nexit 1\n"
+	if err := os.WriteFile(mockScript, []byte(script), 0755); err != nil {
+		t.Fatalf("write mock script: %v", err)
+	}
+
+	var logEvents int
+	tool := &delegateTasksTool{
+		maxConcurrency: 1,
+		odekPath:       mockScript,
+		timeout:        10 * time.Second,
+		OnSubagentLog: func(taskIdx int, line string) {
+			logEvents++
+		},
+	}
+
+	result := tool.runTask(0, "failing task", "", "")
+
+	if logEvents != 1 {
+		t.Errorf("expected 1 log event, got %d", logEvents)
+	}
+	// Should get an error result (but with the partial data from lastLine)
+	if strings.Contains(result, "error") {
+		t.Logf("Got error result as expected: %s", result)
+	}
+}

internal/loop/loop_test.go

@@ -736,3 +736,71 @@ func TestEngine_SkillLoader_CalledOncePerInput(t *testing.T) {
 		t.Errorf("LLM called %d times, want 2", callCount)
 	}
 }
+
+func TestEngine_ToolEventHandler(t *testing.T) {
+	// Verify that ToolEventHandler fires tool_call before and tool_result
+	// after each tool invocation, and does so live (during the loop).
+	var events []string
+	var eventData []string
+	eventHandler := func(event, name, data string) {
+		events = append(events, event)
+		eventData = append(eventData, name)
+	}
+
+	callCount := 0
+	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		callCount++
+		if callCount == 1 {
+			// First iteration: request a tool call
+			fmt.Fprint(w, `{
+				"choices":[{
+					"message":{
+						"content":"Checking.",
+						"tool_calls":[{
+							"id":"call_1",
+							"function":{
+								"name":"echo",
+								"arguments":"{}"
+							}
+						}]
+					}
+				}]
+			}`)
+		} else {
+			// Final answer
+			fmt.Fprint(w, `{"choices":[{"message":{"content":"done"}}]}`)
+		}
+	}))
+	defer server.Close()
+
+	echoTool := &fakeTool{name: "echo", description: "echo", output: "ok"}
+	registry := tool.NewRegistry([]tool.Tool{echoTool})
+	client := llm.New(server.URL, "sk-test", "test-model", "", 0)
+	engine := New(client, registry, 10, "", nil, 0)
+	engine.SetToolEventHandler(eventHandler)
+
+	result, err := engine.Run(context.Background(), "do it")
+	if err != nil {
+		t.Fatalf("Run() error: %v", err)
+	}
+	if result != "done" {
+		t.Errorf("result = %q, want %q", result, "done")
+	}
+
+	// Must have exactly: tool_call → tool_result
+	if len(events) != 2 {
+		t.Fatalf("expected 2 events (tool_call, tool_result), got %d: %v", len(events), events)
+	}
+	if events[0] != "tool_call" {
+		t.Errorf("event[0] = %q, want 'tool_call'", events[0])
+	}
+	if events[1] != "tool_result" {
+		t.Errorf("event[1] = %q, want 'tool_result'", events[1])
+	}
+	if eventData[0] != "echo" {
+		t.Errorf("event[0] name = %q, want 'echo'", eventData[0])
+	}
+	if eventData[1] != "echo" {
+		t.Errorf("event[1] name = %q, want 'echo'", eventData[1])
+	}
+}