engine: stop event-loop freeze from huge --debug dumps; name processes by role

Root cause of "engine 'nvidia' not responding" during generation: in --debug
mode the streaming response generator print()s the ENTIRE generated text (raw
+ repr), and a prompt-echoing/runaway generation makes that multi-MB. The
engine writes stdout to a pipe drained by the front; once the pipe fills, that
synchronous print() — running on the event-loop thread inside the SSE generator
— BLOCKS, freezing the engine so health polls time out and the front flips it
to "not responding" (seen ~3s into each debug flood in debug.log).

- api/text.py: add _clip_for_log() and bound every large debug/dump print
  (generated_text, second_pass/reasoning/final text, formatted_response,
  extracted_tool_calls) to ~4KB head+tail. Shared layer, so both engines covered.
- engine_supervisor: enlarge each engine's stdout pipe to 1 MiB (F_SETPIPE_SZ)
  so bursts can't stall the event loop even if the pump lags briefly.

Also: name processes by role — coderai-front for the front, coderai-<name> for
each engine (CODERAI_ENGINE_NAME passed at spawn), coderai for single-process.
Co-Authored-By: 's avatarClaude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011DDv7BchtZQWsnPG6Jm49m
parent 82aec0f9
...@@ -142,6 +142,27 @@ def _debug_requests_enabled() -> bool: ...@@ -142,6 +142,27 @@ def _debug_requests_enabled() -> bool:
return bool(getattr(global_args, 'debug_requests', False)) if global_args else False return bool(getattr(global_args, 'debug_requests', False)) if global_args else False
def _clip_for_log(s, limit: int = 4000) -> str:
"""Bound a string for debug printing so a huge (e.g. runaway/prompt-echoing)
generation can't be dumped in full.
The engine writes stdout to a PIPE drained by the front; a multi-megabyte
synchronous print fills the pipe and BLOCKS the print() call. These debug
dumps run on the event-loop thread (inside the streaming generator), so a
blocked print freezes the whole engine and the front's health poll flips it
to 'not responding'. Keeping the head and tail bounds the write while still
showing both ends of the output."""
try:
s = s if isinstance(s, str) else str(s)
except Exception:
return "<unprintable>"
if len(s) <= limit:
return s
head = limit * 3 // 4
tail = limit - head
return f"{s[:head]}\n… [clipped {len(s) - limit} chars] …\n{s[-tail:]}"
class _ToolCallStreamGate: class _ToolCallStreamGate:
"""Hold back streamed content once a tool-call marker appears, so a model's """Hold back streamed content once a tool-call marker appears, so a model's
tool call (e.g. gemma's ``<|tool_call>call:NAME{…}``) isn't leaked to the client tool call (e.g. gemma's ``<|tool_call>call:NAME{…}``) isn't leaked to the client
...@@ -1611,15 +1632,15 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request ...@@ -1611,15 +1632,15 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request
print(f"=== RAW STREAM: FULL GENERATED TEXT (DEBUG) ===") print(f"=== RAW STREAM: FULL GENERATED TEXT (DEBUG) ===")
print(f"{'='*80}") print(f"{'='*80}")
print(f"--- SECOND PASS RESULT ---") print(f"--- SECOND PASS RESULT ---")
print(second_pass_result) print(_clip_for_log(second_pass_result))
print(f"--- END SECOND PASS RESULT ---") print(f"--- END SECOND PASS RESULT ---")
print(f"{'='*80}\n") print(f"{'='*80}\n")
# Also dump the reasoning text from first pass # Also dump the reasoning text from first pass
print(f"\n{'='*80}") print(f"\n{'='*80}")
print(f"=== RAW STREAM: REASONING TEXT (DEBUG) ===") print(f"=== RAW STREAM: REASONING TEXT (DEBUG) ===")
print(f"{'='*80}") print(f"{'='*80}")
print(reasoning_text) print(_clip_for_log(reasoning_text))
print(f"{'='*80}\n") print(f"{'='*80}\n")
# Try to extract tool calls from the second pass result ONLY # Try to extract tool calls from the second pass result ONLY
...@@ -1685,7 +1706,7 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request ...@@ -1685,7 +1706,7 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request
print(f"\n{'='*80}") print(f"\n{'='*80}")
print(f"=== RAW STREAM: EXTRACTED TOOL CALLS (DEBUG) ===") print(f"=== RAW STREAM: EXTRACTED TOOL CALLS (DEBUG) ===")
print(f"{'='*80}") print(f"{'='*80}")
print(json.dumps(extracted_tool_calls, indent=2)) print(_clip_for_log(json.dumps(extracted_tool_calls, indent=2)))
print(f"{'='*80}\n") print(f"{'='*80}\n")
elif get_global_debug(): elif get_global_debug():
print(f"DEBUG: No tool calls found in raw stream") print(f"DEBUG: No tool calls found in raw stream")
...@@ -1774,9 +1795,9 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request ...@@ -1774,9 +1795,9 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request
print(f"{'='*80}") print(f"{'='*80}")
print(f"Close tag used: {close_tag}") print(f"Close tag used: {close_tag}")
print(f"\n--- REASONING TEXT ---") print(f"\n--- REASONING TEXT ---")
print(reasoning_text) print(_clip_for_log(reasoning_text))
print(f"\n--- FINAL TEXT (before cleanup) ---") print(f"\n--- FINAL TEXT (before cleanup) ---")
print(final_text) print(_clip_for_log(final_text))
print(f"{'='*80}\n") print(f"{'='*80}\n")
# Clean up control tokens from final text # Clean up control tokens from final text
...@@ -1978,7 +1999,7 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request ...@@ -1978,7 +1999,7 @@ async def chat_completions(request: ChatCompletionRequest, http_request: Request
print(f"\n{'='*80}") print(f"\n{'='*80}")
print(f"=== RAW MODE PARSED OUTPUT (DUMP) ===") print(f"=== RAW MODE PARSED OUTPUT (DUMP) ===")
print(f"{'='*80}") print(f"{'='*80}")
print(json.dumps(formatted_response, indent=2)) print(_clip_for_log(json.dumps(formatted_response, indent=2)))
print(f"{'='*80}\n") print(f"{'='*80}\n")
# Add rate limit headers # Add rate limit headers
...@@ -2618,10 +2639,10 @@ async def stream_chat_response( ...@@ -2618,10 +2639,10 @@ async def stream_chat_response(
print(f"{'='*80}") print(f"{'='*80}")
# Show both raw (actual) content and escaped representation # Show both raw (actual) content and escaped representation
print(f"--- RAW CONTENT (actual newlines shown as lines) ---") print(f"--- RAW CONTENT (actual newlines shown as lines) ---")
print(generated_text) print(_clip_for_log(generated_text))
print(f"--- END RAW CONTENT ---") print(f"--- END RAW CONTENT ---")
print(f"--- ESCAPED CONTENT (repr() - shows \\n for newlines) ---") print(f"--- ESCAPED CONTENT (repr() - shows \\n for newlines) ---")
print(repr(generated_text)) print(_clip_for_log(repr(generated_text)))
print(f"--- END ESCAPED CONTENT ---") print(f"--- END ESCAPED CONTENT ---")
print(f"{'='*80}\n") print(f"{'='*80}\n")
...@@ -2877,7 +2898,7 @@ async def generate_chat_response( ...@@ -2877,7 +2898,7 @@ async def generate_chat_response(
print(f"\n{'='*80}") print(f"\n{'='*80}")
print(f"=== RAW MODEL OUTPUT (DUMP) ===") print(f"=== RAW MODEL OUTPUT (DUMP) ===")
print(f"{'='*80}") print(f"{'='*80}")
print(generated_text) print(_clip_for_log(generated_text))
print(f"{'='*80}\n") print(f"{'='*80}\n")
# Separate the model's thinking from the answer. Surface it as a reasoning # Separate the model's thinking from the answer. Surface it as a reasoning
...@@ -3026,7 +3047,7 @@ async def generate_chat_response( ...@@ -3026,7 +3047,7 @@ async def generate_chat_response(
print(f"\n{'='*80}") print(f"\n{'='*80}")
print(f"=== PARSED OUTPUT (DUMP) ===") print(f"=== PARSED OUTPUT (DUMP) ===")
print(f"{'='*80}") print(f"{'='*80}")
print(json.dumps(formatted_response, indent=2)) print(_clip_for_log(json.dumps(formatted_response, indent=2)))
print(f"{'='*80}\n") print(f"{'='*80}\n")
log_response_payload(formatted_response, streamed=False) log_response_payload(formatted_response, streamed=False)
......
...@@ -332,6 +332,8 @@ class EngineSupervisor: ...@@ -332,6 +332,8 @@ class EngineSupervisor:
# auto-pick CUDA, and vice-versa. # auto-pick CUDA, and vice-versa.
if engine.backend and engine.backend != "auto": if engine.backend and engine.backend != "auto":
env["CODERAI_ENGINE_BACKEND"] = engine.backend env["CODERAI_ENGINE_BACKEND"] = engine.backend
# The engine names its own process (coderai-<name>) from this.
env["CODERAI_ENGINE_NAME"] = str(engine.name)
cmd = self._engine_cmd(engine.port) cmd = self._engine_cmd(engine.port)
tag = engine.name + (f"(gpu{engine.gpu})" if engine.gpu is not None else "") tag = engine.name + (f"(gpu{engine.gpu})" if engine.gpu is not None else "")
print(f"[front] launching {tag} on port {engine.port}: {' '.join(cmd)}", flush=True) print(f"[front] launching {tag} on port {engine.port}: {' '.join(cmd)}", flush=True)
...@@ -341,6 +343,18 @@ class EngineSupervisor: ...@@ -341,6 +343,18 @@ class EngineSupervisor:
preexec_fn=_engine_preexec if os.name == "posix" else None, preexec_fn=_engine_preexec if os.name == "posix" else None,
) )
engine.proc = proc engine.proc = proc
# Enlarge the kernel pipe buffer for this engine's stdout. The engine
# prints (incl. large --debug dumps) synchronously from its event-loop
# thread; if this pipe fills before the pump thread drains it, that
# print() BLOCKS and freezes the engine's event loop — the front then
# sees the health poll stall and flips the engine to 'not responding'.
# A bigger buffer absorbs bursts so a momentary drain lag can't stall it.
try:
import fcntl
F_SETPIPE_SZ = 1031 # not exposed as fcntl.F_SETPIPE_SZ on all builds
fcntl.fcntl(proc.stdout.fileno(), F_SETPIPE_SZ, 1 << 20) # 1 MiB
except Exception:
pass
tail = self._logs.setdefault(engine.id, collections.deque(maxlen=30)) tail = self._logs.setdefault(engine.id, collections.deque(maxlen=30))
threading.Thread(target=self._pump_logs, args=(tag, proc, tail, engine), threading.Thread(target=self._pump_logs, args=(tag, proc, tail, engine),
daemon=True).start() daemon=True).start()
......
...@@ -339,10 +339,22 @@ def main(): ...@@ -339,10 +339,22 @@ def main():
original_unraisablehook(unraisable) original_unraisablehook(unraisable)
sys.unraisablehook = suppress_llama_del_errors sys.unraisablehook = suppress_llama_del_errors
# Optional: set process name if setproctitle is available # Optional: set process name if setproctitle is available. Name by role so
# the front and each engine are distinguishable in ps/top/htop:
# front process → coderai-front
# per-backend engine → coderai-<enginename> (name passed via env at spawn)
# legacy single proc → coderai
try: try:
import setproctitle import setproctitle
setproctitle.setproctitle("codai") _argv = sys.argv[1:]
if "--engine-only" in _argv:
_ename = os.environ.get("CODERAI_ENGINE_NAME") or "engine"
_proc_name = f"coderai-{_ename}"
elif "--single-process" in _argv:
_proc_name = "coderai"
else:
_proc_name = "coderai-front"
setproctitle.setproctitle(_proc_name)
except ImportError: except ImportError:
pass pass
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment