fix(code): partition Debug Console log retention by level (#4718)

Debug Console level filters now surface recent `INFO`/`WARNING`/`ERROR`
logs even when `DEBUG` output dominates the window; a `DEBUG` flood no
longer evicts higher-severity records.

---

The in-app Debug Console (`Ctrl+\`) tails an always-on in-memory ring
buffer that kept a **single** `deque` shared across every level. When
`DEBUG` logging is enabled, verbose `DEBUG` output quickly filled that
window and evicted the rarer `INFO`/`WARNING`/`ERROR` records before the
user ever picked a level filter — so selecting "INFO" turned up nothing
even though `INFO` records had been emitted this session. The filter
*matching* was correct; *retention* was discarding the records the
filter needed.

This partitions retention by level: each level keeps its own bounded
`deque`, so a burst at one level can no longer evict another. Each
retained record is tagged with its monotonic emission sequence so
snapshots stay chronologically ordered across levels, preserving the
existing `snapshot_records_since` contract (absolute resume index,
`(records, total)` shape, negative-index behavior). Non-standard level
names share one bounded fallback bucket so nothing is silently dropped.
The console's own retained copy applies the same per-level cap so it
isn't re-flattened.

As intended, the `All`/`min:*` views can now show more than the
per-level capacity in total (up to capacity per level) and interleave
older high-severity records that previously fell off the single window —
which is the point. Memory stays bounded (~capacity × number of levels).

Made by [Open
SWE](https://openswe.vercel.app/agents/da1fb4b1-3886-27df-551a-84c49759fbb6)

## References
- Plan:
https://openswe.vercel.app/agents/da1fb4b1-3886-27df-551a-84c49759fbb6/plan

---------

Co-authored-by: open-swe[bot] <open-swe@users.noreply.github.com>
This commit is contained in:
Mason Daugherty
2026-07-14 11:17:46 -04:00
committed by GitHub
parent 970952550e
commit c6e3b351f1
5 changed files with 301 additions and 28 deletions
+1 -1
View File
@@ -92,7 +92,7 @@ Debug logging is configured **once**, on the `deepagents_code` package logger, b
- Do **not** add per-module `configure_debug_logging(logger)` calls. They are redundant now that the package logger is configured at import, and they reintroduce the duplicate-handler problem the single-config approach solves.
- Every module should create its logger with `logging.getLogger(__name__)` so it stays inside the `deepagents_code.*` hierarchy and inherits the package handler. Don't set `logger.propagate = False` or attach your own handlers.
- The **file** handler only attaches when `DEEPAGENTS_CODE_DEBUG` is truthy; that path is a single env-var read, so it's safe on the startup hot path. See `DEVELOPMENT.md` for the `DEEPAGENTS_CODE_DEBUG` / `DEEPAGENTS_CODE_DEBUG_FILE` / `DEEPAGENTS_CODE_LOG_LEVEL` env vars.
- Separately, an **always-on in-memory ring buffer** (`_debug_buffer.install_log_buffer`, called from `__init__.py` right before `configure_debug_logging`) attaches unconditionally at import so the in-app Debug Console (`Ctrl+\`) can tail recent `deepagents_code.*` records without file logging. It captures `INFO` and above by default (or `DEEPAGENTS_CODE_LOG_LEVEL`), and may lower the package logger to `INFO` for the process lifetime. It never spills to the terminal (a handler is always found, so `lastResort` is skipped) and is bounded (a `deque` of 1000 records), so it's cheap enough to keep on. Because it installs *before* `configure_debug_logging`, warnings that helper emits at startup are captured and visible in the console.
- Separately, an **always-on in-memory ring buffer** (`_debug_buffer.install_log_buffer`, called from `__init__.py` right before `configure_debug_logging`) attaches unconditionally at import so the in-app Debug Console (`Ctrl+\`) can tail recent `deepagents_code.*` records without file logging. It captures `INFO` and above by default (or `DEEPAGENTS_CODE_LOG_LEVEL`), and may lower the package logger to `INFO` for the process lifetime. It never spills to the terminal (a handler is always found, so `lastResort` is skipped) and is bounded (a `deque` of 1000 records *per log level*), so it's cheap enough to keep on. Because it installs *before* `configure_debug_logging`, warnings that helper emits at startup are captured and visible in the console.
## CLI help screen
+68 -22
View File
@@ -1,10 +1,12 @@
r"""In-memory ring buffer of recent log records for the in-app Debug Console.
A lightweight `logging.Handler` keeps the most recent structured log records in a
bounded `deque` so the Debug Console (`Ctrl+\`) can show a live tail without
requiring the opt-in file logging from `_debug.configure_debug_logging`. The
handler is installed once on the `deepagents_code` package logger (see
`__init__.py`); child module loggers reach it via propagation.
A lightweight `logging.Handler` keeps the most recent structured log records in
bounded per-level `deque`s so the Debug Console (`Ctrl+\`) can show a live tail
without requiring the opt-in file logging from `_debug.configure_debug_logging`.
Partitioning retention by level means a burst of `DEBUG` output cannot evict the
rarer `INFO`/`WARNING`/`ERROR` records the level filter needs. The handler is
installed once on the `deepagents_code` package logger (see `__init__.py`); child
module loggers reach it via propagation.
Installation is negligible, and each emitted record only appends a structured
record to a bounded `deque`, so the buffer is cheap enough to keep always on.
@@ -12,21 +14,37 @@ record to a bounded `deque`, so the buffer is cheap enough to keep always on.
from __future__ import annotations
import itertools
import logging
import operator
import os
from collections import deque
from dataclasses import dataclass
from deepagents_code._debug import LOG_LEVELS
from deepagents_code._env_vars import LOG_LEVEL
DEFAULT_CAPACITY = 1000
"""Maximum number of records retained in the ring buffer."""
"""Maximum number of records retained per level in the ring buffer."""
_FALLBACK_LEVEL_BUCKET = "_other"
"""Retention bucket for records whose level name is not in `LOG_LEVELS`.
Non-standard level names are retained here rather than discarded at
classification time, and sharing one bucket keeps the number of per-level deques
bounded no matter how many distinct custom names appear. Like every bucket, this
one is bounded to *capacity* and evicts oldest-first, so — unlike the standard
levels, which each get isolated retention — distinct custom levels compete for a
single budget and can evict one another."""
_DATE_FORMAT = "%H:%M:%S"
_FORMATTER = logging.Formatter(datefmt=_DATE_FORMAT)
def retention_bucket_for_level(level: str) -> str:
"""Return the bounded retention bucket key for a log level name."""
return level if level in LOG_LEVELS else _FALLBACK_LEVEL_BUCKET
@dataclass(frozen=True, slots=True)
class InMemoryLogRecord:
"""Structured log record retained by the in-memory debug buffer."""
@@ -44,13 +62,24 @@ class InMemoryLogRecord:
class InMemoryLogBuffer(logging.Handler):
"""Logging handler retaining the most recent structured records in memory."""
"""Logging handler retaining the most recent structured records in memory.
Retention is partitioned by level: each recognized level name (see
`LOG_LEVELS`) keeps its own bounded `deque` of *capacity* records, while
unrecognized names share the `_FALLBACK_LEVEL_BUCKET` deque. A burst of
high-volume records at one recognized level (typically `DEBUG`) therefore
cannot evict the rarer, higher-severity records at other recognized levels,
so the Debug Console's level filter can still surface them. Each retained
record is tagged with its monotonic emission sequence number so snapshots
stay chronologically ordered across levels.
"""
def __init__(self, capacity: int = DEFAULT_CAPACITY) -> None:
"""Create the handler with a bounded backing `deque`.
"""Create the handler with a bounded backing `deque` per level.
Args:
capacity: Maximum records to retain; oldest are dropped first.
capacity: Maximum records to retain per level; oldest are dropped
first.
Raises:
ValueError: If *capacity* is less than 1. A zero-capacity buffer
@@ -61,20 +90,32 @@ class InMemoryLogBuffer(logging.Handler):
msg = f"capacity must be >= 1, got {capacity}"
raise ValueError(msg)
super().__init__()
self._records: deque[InMemoryLogRecord] = deque(maxlen=capacity)
self._capacity = capacity
self._levels: dict[str, deque[tuple[int, InMemoryLogRecord]]] = {}
self._total = 0
def emit(self, record: logging.LogRecord) -> None:
"""Append the structured *record* to the ring buffer."""
"""Append the structured *record* to its level's ring buffer."""
self.acquire()
try:
self._records.append(self._make_record(record))
structured = self._make_record(record)
bucket = self._level_bucket(structured.level)
bucket.append((self._total, structured))
self._total += 1
except Exception: # noqa: BLE001 # never let logging crash the app
self.handleError(record)
finally:
self.release()
def _level_bucket(self, level: str) -> deque[tuple[int, InMemoryLogRecord]]:
"""Return the retention deque for *level*, creating it on first use."""
key = retention_bucket_for_level(level)
bucket = self._levels.get(key)
if bucket is None:
bucket = deque(maxlen=self._capacity)
self._levels[key] = bucket
return bucket
@property
def total_emitted(self) -> int:
"""Total records ever emitted (monotonic; survives buffer eviction)."""
@@ -107,15 +148,20 @@ class InMemoryLogBuffer(logging.Handler):
self.release()
def _records_since_unlocked(self, index: int) -> list[InMemoryLogRecord]:
"""Return retained records from *index* while the handler lock is held."""
start_abs = self._total - len(self._records)
offset = index - start_abs
if offset <= 0:
return list(self._records)
if offset >= len(self._records):
return []
# islice avoids materializing the full deque just to slice off the tail.
return list(itertools.islice(self._records, offset, None))
"""Return retained records from *index* while the handler lock is held.
Merges the per-level deques and restores chronological order using each
record's emission sequence number, so callers see one ordered tail even
though retention is partitioned by level.
"""
tagged = [
entry
for bucket in self._levels.values()
for entry in bucket
if entry[0] >= index
]
tagged.sort(key=operator.itemgetter(0))
return [record for _seq, record in tagged]
@staticmethod
def _make_record(record: logging.LogRecord) -> InMemoryLogRecord:
@@ -34,6 +34,7 @@ from deepagents_code._debug_buffer import (
DEFAULT_CAPACITY,
InMemoryLogRecord,
get_log_buffer,
retention_bucket_for_level,
)
from deepagents_code.clipboard import copy_text_to_clipboard
from deepagents_code.unicode_security import sanitize_control_chars
@@ -65,7 +66,10 @@ _REFRESH_INTERVAL = 0.5
"""Seconds between log-tail refresh ticks."""
_RECORD_LIMIT = DEFAULT_CAPACITY
"""Maximum records retained by an open debug console view."""
"""Maximum records retained per level by an open debug console view.
Matches the buffer's per-level `deque` bound so the console mirrors the buffer's
level-partitioned retention instead of re-flattening it into a single window."""
_FILTER_SELECT_ID = "debug-level-filter"
FilterValue = Literal[
@@ -786,15 +790,36 @@ class DebugConsoleScreen(ModalScreen[None]):
log.append_records(self._visible_records(records))
def _prune_records(self) -> bool:
"""Trim retained records to the in-memory ring buffer capacity.
"""Trim retained records to the ring buffer capacity, per level.
Mirrors the buffer's level-partitioned retention: each standard level
keeps at most `_RECORD_LIMIT` records, while custom levels share the
buffer's fallback bucket. Only the oldest entries of an over-capacity
bucket are dropped; chronological order is preserved.
Returns:
`True` when records were pruned.
"""
overflow = len(self._records) - _RECORD_LIMIT
if overflow <= 0:
counts: dict[str, int] = {}
for record in self._records:
bucket = retention_bucket_for_level(record.level)
counts[bucket] = counts.get(bucket, 0) + 1
overflow = {
level: count - _RECORD_LIMIT
for level, count in counts.items()
if count > _RECORD_LIMIT
}
if not overflow:
return False
del self._records[:overflow]
kept: list[InMemoryLogRecord] = []
for record in self._records:
bucket = retention_bucket_for_level(record.level)
remaining = overflow.get(bucket, 0)
if remaining > 0:
overflow[bucket] = remaining - 1
continue
kept.append(record)
self._records = kept
return True
def _visible_records(
@@ -155,6 +155,115 @@ class TestInMemoryLogBuffer:
assert len(_lines(buffer, 0)) == 2
assert _lines(buffer, 4) == [_lines(buffer, 0)[-1]]
def test_debug_flood_does_not_evict_other_levels(self) -> None:
buffer = InMemoryLogBuffer(capacity=3)
buffer.emit(_record("deepagents_code", "keep-info", level=logging.INFO))
buffer.emit(_record("deepagents_code", "keep-warning", level=logging.WARNING))
for i in range(10): # flood DEBUG well past the per-level capacity
buffer.emit(_record("deepagents_code", f"debug{i}", level=logging.DEBUG))
records, total = buffer.snapshot_records_since(0)
messages = [record.message for record in records]
# The rarer, higher-severity records survive the DEBUG flood ...
assert "keep-info" in messages
assert "keep-warning" in messages
# ... while DEBUG stays bounded to its own capacity (last 3).
assert [m for m in messages if m.startswith("debug")] == [
"debug7",
"debug8",
"debug9",
]
# Merged output stays chronological via the emission sequence.
assert messages == ["keep-info", "keep-warning", "debug7", "debug8", "debug9"]
assert total == 12
def test_per_level_bound_is_independent(self) -> None:
buffer = InMemoryLogBuffer(capacity=2)
for i in range(5):
buffer.emit(_record("deepagents_code", f"info{i}", level=logging.INFO))
for i in range(5):
buffer.emit(_record("deepagents_code", f"err{i}", level=logging.ERROR))
records, _total = buffer.snapshot_records_since(0)
# Each level keeps only its own last `capacity` records.
assert [record.message for record in records] == [
"info3",
"info4",
"err3",
"err4",
]
def test_unknown_level_names_share_one_bounded_bucket(self) -> None:
buffer = InMemoryLogBuffer(capacity=2)
# Custom numeric levels have level names like "Level 25"; none are in
# LOG_LEVELS, so they must share the fallback bucket rather than each
# getting its own unbounded deque.
for i in range(4):
buffer.emit(_record("deepagents_code", f"custom{i}", level=25 + i))
records, _total = buffer.snapshot_records_since(0)
assert [record.message for record in records] == ["custom2", "custom3"]
def test_merge_restores_chronological_order_when_levels_overflow(self) -> None:
"""Interleaved levels that both overflow still merge in emission order.
Unlike `test_per_level_bound_is_independent`, the two levels are emitted
interleaved, so a merge that concatenated the buckets instead of sorting
by emission sequence would regroup the tail by level and fail here.
"""
buffer = InMemoryLogBuffer(capacity=2)
for i in range(3): # INFO and ERROR alternate; both overflow capacity=2
buffer.emit(_record("deepagents_code", f"info{i}", level=logging.INFO))
buffer.emit(_record("deepagents_code", f"err{i}", level=logging.ERROR))
records, _total = buffer.snapshot_records_since(0)
# Each level keeps only its last 2, but the merged tail is chronological
# (info2 precedes err2 in emission order), not grouped by level.
assert [record.message for record in records] == [
"info1",
"err1",
"info2",
"err2",
]
def test_incremental_snapshot_after_eviction_across_levels(self) -> None:
"""Resuming from a prior index skips consumed records but no retained one.
Reproduces the Debug Console's poll loop: snapshot, then snapshot again
from the returned resume index after further emits have evicted records
from one level's bucket. The second snapshot must return only records
emitted since the resume index, chronologically, with nothing already
consumed reappearing -- even though the first poll's records are still
retained in their (un-flooded) buckets.
"""
buffer = InMemoryLogBuffer(capacity=3)
buffer.emit(_record("deepagents_code", "info0", level=logging.INFO))
buffer.emit(_record("deepagents_code", "warn0", level=logging.WARNING))
first, resume = buffer.snapshot_records_since(0)
assert [record.message for record in first] == ["info0", "warn0"]
assert resume == 2
# Flood DEBUG past its own capacity; the INFO/WARNING buckets are
# untouched, so info0/warn0 remain retained but already consumed.
for i in range(5):
buffer.emit(_record("deepagents_code", f"debug{i}", level=logging.DEBUG))
buffer.emit(_record("deepagents_code", "info1", level=logging.INFO))
second, resume2 = buffer.snapshot_records_since(resume)
messages = [record.message for record in second]
# Only records emitted since `resume`, in chronological order ...
assert messages == ["debug2", "debug3", "debug4", "info1"]
# ... and the still-retained first-poll records are not re-yielded.
assert "info0" not in messages
assert "warn0" not in messages
assert resume2 == 8
def test_snapshot_since_returns_records_and_next_index(self) -> None:
buffer = InMemoryLogBuffer(capacity=10)
for i in range(3):
@@ -176,6 +176,56 @@ class TestDebugConsoleScreen:
]
assert visible_messages == messages
def test_custom_levels_share_fallback_retention_bucket(
self, monkeypatch: pytest.MonkeyPatch
) -> None:
"""Custom levels must collectively obey the buffer's fallback bound."""
monkeypatch.setattr(debug_console_mod, "_RECORD_LIMIT", 3)
screen = DebugConsoleScreen(_snapshot())
screen._records = [
_log_record(
f"custom-{index}",
level=f"Level {25 + index}",
levelno=25 + index,
)
for index in range(5)
]
assert screen._prune_records() is True
assert [record.message for record in screen._records] == [
"custom-2",
"custom-3",
"custom-4",
]
def test_prune_keeps_newest_per_standard_level_in_order(
self, monkeypatch: pytest.MonkeyPatch
) -> None:
"""Only the oldest records of an over-capacity level are dropped.
Interleaves a DEBUG flood with sparse INFO/WARNING: the under-capacity
levels survive untouched, DEBUG is trimmed to its newest `_RECORD_LIMIT`,
and the surviving records stay in chronological order.
"""
monkeypatch.setattr(debug_console_mod, "_RECORD_LIMIT", 2)
screen = DebugConsoleScreen(_snapshot())
info = _log_record("info", level="INFO", levelno=logging.INFO)
warning = _log_record("warning", level="WARNING", levelno=logging.WARNING)
debugs = [
_log_record(f"debug{index}", level="DEBUG", levelno=logging.DEBUG)
for index in range(4)
]
# Chronological: info, debug0, debug1, warning, debug2, debug3.
screen._records = [info, debugs[0], debugs[1], warning, debugs[2], debugs[3]]
assert screen._prune_records() is True
assert [record.message for record in screen._records] == [
"info",
"warning",
"debug2",
"debug3",
]
async def test_poll_degrades_on_buffer_failure_without_crashing(
self, monkeypatch: pytest.MonkeyPatch
) -> None:
@@ -470,6 +520,49 @@ class TestDebugConsoleScreen:
for record in log.records
)
async def test_level_filter_finds_info_after_debug_flood(
self, monkeypatch: pytest.MonkeyPatch
) -> None:
"""A DEBUG flood must not hide earlier INFO records from the filter."""
monkeypatch.setattr(debug_console_mod, "_debug_records_enabled", lambda: True)
# Small per-level cap so a modest flood exercises pruning quickly; a flat
# cap would drop the INFO marker in favor of the newer DEBUG records.
monkeypatch.setattr(debug_console_mod, "_RECORD_LIMIT", 5)
package_logger = logging.getLogger("deepagents_code")
original_level = package_logger.level
package_logger.setLevel(logging.DEBUG)
try:
logger.info("debug-console-flood-info-marker")
for index in range(50): # far more DEBUG than the per-level cap
logger.debug("debug-console-flood-debug-%d", index)
app = _Harness()
async with app.run_test() as pilot:
screen = DebugConsoleScreen(_snapshot())
app.push_screen(screen)
await pilot.pause()
log = screen.query_one("#debug-log", _DebugLogView)
select = screen.query_one("#debug-level-filter", Select)
select.value = "min:INFO"
await pilot.pause()
assert any(
"debug-console-flood-info-marker" in record.message
for record in log.records
)
# The filter hides DEBUG from the view, so assert on the
# retained set that pruning actually bounded DEBUG to its own
# per-level cap (newest kept) rather than dropping nothing or
# evicting the rarer INFO marker.
retained = [record.message for record in screen._records]
debug_retained = [m for m in retained if "flood-debug" in m]
assert debug_retained == [
f"debug-console-flood-debug-{index}" for index in range(45, 50)
]
assert "debug-console-flood-info-marker" in retained
finally:
package_logger.setLevel(original_level)
async def test_level_filter_hides_debug_when_runtime_level_excludes_it(
self, monkeypatch: pytest.MonkeyPatch
) -> None: