diff --git a/CHANGELOG.md b/CHANGELOG.md index cc38c2d36..464d93728 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -36,6 +36,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 * **ccr:** make retrieval store TTL configurable with `HEADROOM_CCR_TTL_SECONDS`, expose the effective TTL in `/v1/retrieve/stats`, and distinguish expired retrievals from missing hashes. * **proxy:** add native Bedrock `/model/{id}/converse-stream` route and forward it through the existing streaming EventStream/SSE pipeline. * **wrap (codex):** fix `headroom wrap codex` producing a `config.toml` with duplicate top-level `model_provider` / `openai_base_url` keys (TOML-spec error) when the user had already configured their own provider. The injector now rewrites pre-existing top-level `model_provider` and `openai_base_url` lines in place — the previous value is kept in a `# was: …` trailing comment — instead of unconditionally prepending a duplicate, so `codex` can start against the proxy. The pre-wrap snapshot mechanism continues to byte-for-byte restore the original file on `headroom unwrap codex`. +* **wrap:** isolate wrapped proxy subprocess stdout/stderr into `proxy-stdio.log`, so `proxy.log` remains the canonical rotating runtime log and Windows rollover failures from `RotatingFileHandler` are no longer blocked by wrapper stdio handles ([#1184](https://github.com/chopratejas/headroom/issues/1184)). ## [0.27.0](https://github.com/chopratejas/headroom/compare/v0.26.0...v0.27.0) (2026-06-22) diff --git a/headroom/cli/wrap.py b/headroom/cli/wrap.py index 718362fa9..86756a592 100644 --- a/headroom/cli/wrap.py +++ b/headroom/cli/wrap.py @@ -328,6 +328,11 @@ def _get_log_path() -> Path: return log_dir / "proxy.log" +def _get_proxy_stdio_log_path() -> Path: + """Get path for dedicated proxy stdio capture.""" + return _get_log_path().with_name("proxy-stdio.log") + + def _start_proxy( port: int, *, @@ -344,9 +349,9 @@ def _start_proxy( ) -> subprocess.Popen: """Start Headroom proxy as a background subprocess. - Logs are written to ~/.headroom/logs/proxy.log to avoid pipe buffer - deadlocks (macOS pipe buffer is ~64KB — a busy proxy fills it quickly, - blocking the process). + Stdout and stderr are written to a dedicated sibling file, usually + `~/.headroom/logs/proxy-stdio.log`, to avoid pipe deadlock risk without + competing with the rotating `proxy.log` runtime log. """ cmd = [sys.executable, "-m", "headroom.cli", "proxy", "--port", str(port)] @@ -388,7 +393,8 @@ def _start_proxy( timeout_seconds = _resolve_wrap_proxy_timeout_seconds() log_path = _get_log_path() - log_file = open(log_path, "a") # noqa: SIM115 + stdio_log_path = _get_proxy_stdio_log_path() + stdio_log_file = open(stdio_log_path, "a") # noqa: SIM115 # Ensure proxy subprocess uses UTF-8 (Windows defaults to cp1252) proxy_env = os.environ.copy() @@ -418,8 +424,8 @@ def _start_proxy( proc = subprocess.Popen( cmd, - stdout=log_file, - stderr=log_file, + stdout=stdio_log_file, + stderr=stdio_log_file, env=proxy_env, start_new_session=os.name == "posix", ) @@ -431,19 +437,20 @@ def _start_proxy( time.sleep(1) if _check_proxy(port): click.echo(f" Logs: {log_path}") + stdio_log_file.close() return proc # Check if process died if proc.poll() is not None: - log_file.close() + stdio_log_file.close() # Read last few lines of log for error context try: - tail = log_path.read_text()[-500:] + tail = stdio_log_path.read_text()[-500:] except Exception: tail = "(no log output)" raise RuntimeError(f"Proxy exited with code {proc.returncode}: {tail}") proc.kill() - log_file.close() + stdio_log_file.close() raise RuntimeError( f"Proxy failed to start on port {port} within {timeout_seconds} seconds. " f"Set {_WRAP_PROXY_TIMEOUT_ENV} to a larger number of seconds for slow startup." diff --git a/tests/test_cli_proxy_env.py b/tests/test_cli_proxy_env.py index c7e53e843..1ae78b5aa 100644 --- a/tests/test_cli_proxy_env.py +++ b/tests/test_cli_proxy_env.py @@ -106,6 +106,32 @@ class TestCLIWrapProxyTimeout: assert env["GITHUB_COPILOT_API_URL"] == "https://copilot-api.acme.ghe.com" assert env["GITHUB_COPILOT_API_TOKEN"] == "copilot-api-token" + def test_start_proxy_redirects_subprocess_stdio_to_standalone_log(self, monkeypatch, tmp_path): + fake_proc = _FakeProxyProcess() + captured: dict[str, object] = {} + logs: list[str] = [] + + monkeypatch.delenv(wrap_mod._WRAP_PROXY_TIMEOUT_ENV, raising=False) + monkeypatch.setattr(wrap_mod, "_get_log_path", lambda: tmp_path / "proxy.log") + monkeypatch.setattr(wrap_mod, "_check_proxy", lambda _port: True) + monkeypatch.setattr(wrap_mod.time, "sleep", lambda _seconds: None) + monkeypatch.setattr(wrap_mod, "_ml_wrap_extras_detected", lambda: False) + monkeypatch.setattr(wrap_mod.click, "echo", lambda message: logs.append(str(message))) + + def fake_popen(*args, **kwargs): # noqa: ANN002, ANN003 + captured["kwargs"] = kwargs + return fake_proc + + monkeypatch.setattr(wrap_mod.subprocess, "Popen", fake_popen) + + proc = wrap_mod._start_proxy(8787, agent_type="codex") + + assert proc is fake_proc + assert captured["kwargs"]["stdout"] is captured["kwargs"]["stderr"] + assert captured["kwargs"]["stdout"].name == str(tmp_path / "proxy-stdio.log") + assert captured["kwargs"]["stdout"].name != str(tmp_path / "proxy.log") + assert f" Logs: {tmp_path / 'proxy.log'}" in logs + def test_env_timeout_allows_slow_start_proxy_to_succeed(self, monkeypatch, tmp_path): fake_proc = _FakeProxyProcess() sleeps = [] @@ -129,6 +155,30 @@ class TestCLIWrapProxyTimeout: assert sleeps == [1, 1, 1, 1] assert fake_proc.killed is False + def test_start_proxy_tail_reads_standalone_stdio_log_on_process_exit( + self, monkeypatch, tmp_path + ): + fake_proc = _FakeProxyProcess() + fake_proc.returncode = 1 + fake_proc.poll = lambda: fake_proc.returncode + + monkeypatch.setenv(wrap_mod._WRAP_PROXY_TIMEOUT_ENV, "2") + monkeypatch.setattr(wrap_mod, "_get_log_path", lambda: tmp_path / "proxy.log") + monkeypatch.setattr(wrap_mod, "_check_proxy", lambda _port: False) + monkeypatch.setattr(wrap_mod.time, "sleep", lambda _seconds: None) + monkeypatch.setattr(wrap_mod.subprocess, "Popen", lambda *args, **kwargs: fake_proc) + + (tmp_path / "proxy.log").write_text("canonical runtime log output") + (tmp_path / "proxy-stdio.log").write_text("proxy stdio startup output") + + with pytest.raises(RuntimeError) as excinfo: + wrap_mod._start_proxy(8787, agent_type="codex") + + message = str(excinfo.value) + assert "Proxy exited with code 1" in message + assert "proxy stdio startup output" in message + assert "canonical runtime log output" not in message + def test_timeout_error_names_configured_timeout_and_env_var(self, monkeypatch, tmp_path): fake_proc = _FakeProxyProcess()