diff --git a/docs/config.md b/docs/config.md index da5aeed..4e4b333 100644 --- a/docs/config.md +++ b/docs/config.md @@ -69,6 +69,7 @@ | Variable | Type | Default | Description | |---|---|---|---| | `LLM_COMPLETE_TIMEOUT` | int | `120` | Seconds before a non-streaming `complete()` call times out | +| `PLANNING_LLM_TIMEOUT_SEC` | int | `240` | Seconds before a non-streaming planning phase call times out (`plan` tool / subagent pipeline). Wider than `LLM_COMPLETE_TIMEOUT` — cloud models prefill big planning prompts for up to a couple of minutes, and a timeout here silently kills the plan. | | `LLM_STREAM_FIRST_CHUNK_TIMEOUT` | int | `90` | Seconds to wait for the first token of a streaming call (prefill phase) | | `LLM_STREAM_CHUNK_TIMEOUT` | int | `60` | Max seconds between consecutive tokens in a streaming call | diff --git a/navi/config.py b/navi/config.py index 4c01394..a220cdc 100644 --- a/navi/config.py +++ b/navi/config.py @@ -156,8 +156,12 @@ navi_allowed_origins: str = "" # LLM call timeouts - # complete() is non-streaming (planning, compression) — blocked until full response + # complete() is non-streaming (compression) — blocked until full response llm_complete_timeout: int = 120 + # Non-streaming planning calls (the `plan` tool / subagent pipeline). Wider + # than llm_complete_timeout: cloud models prefill big planning prompts for + # up to a couple of minutes, and a timeout here silently kills the plan. + planning_llm_timeout_sec: int = 240 # stream_complete(): how long to wait for the FIRST token (prefill phase) # Large contexts can take 60-90s to prefill; 90s matches user expectation llm_stream_first_chunk_timeout: int = 90 diff --git a/navi/core/planning.py b/navi/core/planning.py index 05d857d..9f9023a 100644 --- a/navi/core/planning.py +++ b/navi/core/planning.py @@ -35,13 +35,46 @@ _PHASE1_CONTEXT_MAX_CHARS = 20_000 # gemma4 on ollama-cloud leaks its thinking-channel header into content on -# non-streaming calls ("thought\n"); strip the artifact so the -# analysis/plan parse cleanly. +# non-streaming calls ("thought\n"); glm-5.3-flash sometimes wraps +# the whole answer in a structured-response envelope +# ("response:unknown{value:...}"). Both artifacts are unwrapped so +# the analysis/plan parse cleanly. _CHANNEL_ARTIFACT = re.compile(r"^\s*thought\s*\s*", re.IGNORECASE) +_RESPONSE_WRAPPER = re.compile( + r"^\s*response:\S*\{value:\s*(.*)\}\s*(?:)?\s*$", + re.DOTALL | re.IGNORECASE, +) +_RESPONSE_OPEN = re.compile(r"^\s*response:\S*\{value:\s*", re.IGNORECASE) +_TOOL_CALL_TAIL = re.compile(r"\s*\s*$", re.IGNORECASE) def _strip_channel_artifact(text: str) -> str: - return _CHANNEL_ARTIFACT.sub("", text, count=1) + text = _CHANNEL_ARTIFACT.sub("", text, count=1) + m = _RESPONSE_WRAPPER.match(text) + if m: + # Balanced envelope: keep the payload (the greedy group stops at the + # LAST closing brace, so braces inside the payload survive). + return m.group(1) + if _RESPONSE_OPEN.match(text): + # Truncated envelope: strip the opening and a leaked tool-call tail. + text = _RESPONSE_OPEN.sub("", text, count=1) + text = _TOOL_CALL_TAIL.sub("", text, count=1) + return text + + +def _planner_text(response) -> tuple[str, str]: + """Payload of one planning-phase LLM call. + + Content channel first; the thinking channel is the fallback — glm on + ollama-cloud sometimes spends completion tokens with an empty content + field because the whole answer lands in thinking. Returns + ``(text, source)`` where source is ``content`` or ``thinking``. + """ + text = _strip_channel_artifact((response.content or "").strip()) + if text: + return text, "content" + text = _strip_channel_artifact((response.thinking or "").strip()) + return text, ("thinking" if text else "content") def _window_for_planner(msgs: list[Message], max_chars: int) -> list[Message]: @@ -264,11 +297,11 @@ try: r1 = await asyncio.wait_for( llm.complete(phase1_ctx, tools=None, temperature=0.3, model=profile.model, think=False), - timeout=settings.llm_complete_timeout, + timeout=settings.planning_llm_timeout_sec, ) - analysis = _strip_channel_artifact((r1.content or "").strip()) + analysis, _analysis_source = _planner_text(r1) except asyncio.TimeoutError: - log.warning("agent.planning_phase1_timeout", timeout=settings.llm_complete_timeout) + log.warning("agent.planning_phase1_timeout", timeout=settings.planning_llm_timeout_sec) _dbg["result"] = "phase1_timeout" if not is_subagent: yield PlanningDebugData(log=_dbg) @@ -288,6 +321,7 @@ _dbg["phases"]["1"] = { "output": analysis, + "source": _analysis_source, "prompt_tokens": r1.prompt_tokens or 0, "completion_tokens": r1.completion_tokens or 0, } @@ -414,11 +448,11 @@ try: r2 = await asyncio.wait_for( llm.complete(phase3_ctx, tools=None, temperature=0.3, model=profile.model, think=False), - timeout=settings.llm_complete_timeout, + timeout=settings.planning_llm_timeout_sec, ) - plan_text = _strip_channel_artifact((r2.content or "").strip()) + plan_text, _plan_source = _planner_text(r2) except asyncio.TimeoutError: - log.warning("agent.planning_phase3_timeout", timeout=settings.llm_complete_timeout) + log.warning("agent.planning_phase3_timeout", timeout=settings.planning_llm_timeout_sec) _dbg["result"] = "phase3_timeout" if not is_subagent: yield PlanningDebugData(log=_dbg) @@ -438,6 +472,7 @@ _dbg["phases"]["3"] = { "output": plan_text, + "source": _plan_source, "prompt_tokens": r2.prompt_tokens or 0, "completion_tokens": r2.completion_tokens or 0, } diff --git a/tests/unit/core/test_planning.py b/tests/unit/core/test_planning.py index 3945902..fd7cbdf 100644 --- a/tests/unit/core/test_planning.py +++ b/tests/unit/core/test_planning.py @@ -465,4 +465,131 @@ # Sub-agent's KV row received the plan step; parent row is empty. assert await kv.get(None, "sub_run_xyz", "todo", "tasks") is not None - assert await kv.get(None, "parent_sess", "todo", "tasks") is None \ No newline at end of file + assert await kv.get(None, "parent_sess", "todo", "tasks") is None + +class TestResponseEnvelopeUnwrap: + """glm-5.3-flash:cloud sometimes wraps the whole answer in a structured + envelope: "response:unknown{value:...}". The planner unwraps + it so the analysis/plan parse cleanly (production planning_logs showed an + unwrapped envelope killing phase 1 parsing and empty phase 3 output).""" + + async def _engine_run(self, llm, context=None): + profile = make_profile("developer") + engine = PlanningEngine(FakeContextBuilder()) + context = context or [Message(role="user", content="hello")] + events = [] + async for event in engine.run(context, profile, llm, mem=None, tool_schemas=[]): + events.append(event) + return engine, events + + async def test_phase1_envelope_unwrapped(self): + analysis = ( + "TASK: test\nGOAL: done\nUNKNOWNS: NONE\nRESOURCES: NONE\n" + "COMPLEXITY: complex\nSUBTASKS:\n1. Step\nCOMMITMENTS: none" + ) + llm = RecordingLLM([ + f"response:unknown{{value:{analysis}}}\n", + "## Plan\n\n**Steps:**\n1. Step → SELF\n", + ]) + engine, events = await self._engine_run(llm) + + assert engine.last_complexity == "complex" + dbg = [e for e in events if type(e).__name__ == "PlanningDebugData"] + assert dbg and not dbg[-1].log["phases"]["1"]["output"].startswith("response:") + assert dbg[-1].log["phases"]["1"]["source"] == "content" + + async def test_phase3_envelope_unwrapped(self): + llm = RecordingLLM([ + "TASK: test\nGOAL: done\nUNKNOWNS: NONE\nRESOURCES: NONE\n" + "COMPLEXITY: simple\nSUBTASKS:\n1. Step\nCOMMITMENTS: none", + "response:unknown{value:## Plan\n\n**Steps:**\n1. Step → SELF\n}", + ]) + _engine, events = await self._engine_run(llm) + + ready = [e for e in events if isinstance(e, PlanReady)] + assert ready and "1. Step → SELF" in ready[0].plan + + async def test_truncated_envelope_opening_stripped(self): + from navi.core.planning import _strip_channel_artifact + + text = "response:unknown{value:## Plan\n**Steps:**\n1. Step → SELF" + assert _strip_channel_artifact(text) == "## Plan\n**Steps:**\n1. Step → SELF" + + async def test_inner_braces_survive(self): + from navi.core.planning import _strip_channel_artifact + + text = 'response:unknown{value:step {x} done\n2. {y} → TOOL: t}\n' + assert _strip_channel_artifact(text) == "step {x} done\n2. {y} → TOOL: t" + + async def test_plain_text_untouched(self): + from navi.core.planning import _strip_channel_artifact + + assert _strip_channel_artifact("## Plan\n1. Step → SELF") == "## Plan\n1. Step → SELF" + + +class TestThinkingFallback: + """glm on ollama-cloud sometimes spends completion tokens with an empty + content field — the whole answer lands in the thinking channel. The + planner falls back to thinking instead of failing the phase.""" + + class _RespLLM: + def __init__(self, responses): + self.responses = list(responses) + self.kwargs = [] + + async def complete(self, messages, **kwargs): + self.kwargs.append(kwargs) + return self.responses.pop(0) + + async def _run(self, llm): + profile = make_profile("developer") + engine = PlanningEngine(FakeContextBuilder()) + events = [] + async for event in engine.run( + [Message(role="user", content="hello")], profile, llm, mem=None, tool_schemas=[] + ): + events.append(event) + return engine, events + + async def test_phase1_empty_content_uses_thinking(self): + analysis = ( + "TASK: test\nGOAL: done\nUNKNOWNS: NONE\nRESOURCES: NONE\n" + "COMPLEXITY: medium\nSUBTASKS:\n1. Step\nCOMMITMENTS: none" + ) + llm = self._RespLLM([ + LLMResponse(content=None, tool_calls=None, finish_reason="stop", thinking=analysis), + LLMResponse(content="## Plan\n\n**Steps:**\n1. Step → SELF\n", + tool_calls=None, finish_reason="stop"), + ]) + engine, events = await self._run(llm) + + # Phase 1 verdict was recovered from thinking — planning continued. + assert engine.last_complexity == "medium" + assert len(llm.kwargs) == 2 + dbg = [e for e in events if type(e).__name__ == "PlanningDebugData"] + assert dbg and dbg[-1].log["phases"]["1"]["source"] == "thinking" + + async def test_phase3_empty_content_uses_thinking(self): + llm = self._RespLLM([ + LLMResponse(content="TASK: test\nGOAL: done\nUNKNOWNS: NONE\nRESOURCES: NONE\n" + "COMPLEXITY: simple\nSUBTASKS:\n1. Step\nCOMMITMENTS: none", + tool_calls=None, finish_reason="stop"), + LLMResponse(content=None, tool_calls=None, finish_reason="stop", + thinking="## Plan\n\n**Steps:**\n1. Step → SELF\n"), + ]) + _engine, events = await self._run(llm) + + ready = [e for e in events if isinstance(e, PlanReady)] + assert ready and "1. Step → SELF" in ready[0].plan + dbg = [e for e in events if type(e).__name__ == "PlanningDebugData"] + assert dbg and dbg[-1].log["phases"]["3"]["source"] == "thinking" + + async def test_both_channels_empty_still_fails_cleanly(self): + llm = self._RespLLM([ + LLMResponse(content=None, tool_calls=None, finish_reason="stop", thinking=None), + ]) + _engine, events = await self._run(llm) + + assert not any(isinstance(e, PlanReady) for e in events) + dbg = [e for e in events if type(e).__name__ == "PlanningDebugData"] + assert dbg and dbg[-1].log["result"] == "direct"