Skip to content

Commit ccfde97

Browse files
AbirAbbasagentfield-botclaude
authored
Fix get_logger returning agentfield.result_cache for all loggers (#635)
* issue/fix-get-logger-name-bug: fix get_logger to respect name parameter using dictionary cache * chore: finalize repo for handoff * fix(logger): guard logger cache with a lock for thread-safe access The per-name logger cache introduced in this PR is shared mutable module state. `get_logger()` could insert into `_logger_cache` while `set_log_level()`/`set_cp_client()` iterate `.values()`, raising `RuntimeError: dictionary changed size during iteration`. Add a reentrant lock around all cache access. set_log_level/set_cp_client snapshot the values under the lock and apply outside it, so we never hold the lock during the loggers' own work. Addresses the thread-safety findings from the PR review. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * test(logger): fix lint, isolate global logging state, cover concurrency Three issues in the new logger test: - Removed unused imports (`AgentFieldLogger`, `_global_log_level`) that failed `ruff check` (F401) and broke CI lint on 3.10/3.11/3.12. - The fixture's `global _global_log_level = None` only rebound this module's copy, never the real `agentfield.logger` global, so the level reset silently did nothing. Reference the module so the reset bites. - `AgentFieldLogger` mutates the stdlib logging registry (adds a handler, sets `propagate=False`). Those mutations outlived each test and leaked across the session. The fixture now snapshots and restores the registry so this file is order-independent and can't mute unrelated loggers. Also add a concurrency test exercising get_logger()/set_log_level() from several threads, locking in the thread-safety fix. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * test(cancel): capture cancel log directly, not via caplog/root Fixing get_logger() to honour the requested name means get_logger() now creates the real "agentfield" logger, on which the SDK sets propagate=False. That stops every "agentfield.*" child (including the plain "agentfield.cancel" logger) from reaching the root logger — where pytest's `caplog` handler lives. The assertion only ever passed because the old singleton bug meant the real "agentfield" logger was usually never created, so this was silently order-dependent and failed once test_logger ran first. Attach a handler directly to the "agentfield.cancel" logger instead. It asserts the identical contract (an INFO "cancel-callback fired" record is emitted) but is independent of namespace propagation and suite ordering. Use getMessage() since no formatter runs to set record.message on a bare handler. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * docs(logger): note set_log_level no longer implicitly creates a logger Document the behavior change flagged in review: set_log_level() now only records the level and updates cached loggers; it no longer creates the default logger as a side effect. New loggers pick up the stored level when created via get_logger(). Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * test(conftest): isolate execution-context state and drain leaked tasks A pre-existing flake surfaced on Python 3.12 CI: tests that rely on the agent / execution-context ContextVars (e.g. test_execute_with_tracking_registers_child_context) intermittently saw get_current_agent_instance() return None mid-test, skipping workflow registration (assert 0 == 1). The suite also leaked many fire-and-forget asyncio tasks across tests ("Task was destroyed but it is pending!"). Add an autouse fixture that resets the agent/execution-context ContextVars around every test and best-effort drains tasks the test left pending, so ordering and stray tasks can't pollute later tests. All teardown work is guarded to never raise. Verified locally on 3.10 and 3.12: full suite green and the leaked-task warnings drop from dozens to zero. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * fix(logger): forward structured logs to loggers created after set_cp_client set_cp_client() only mutated loggers already in the cache, so any logger created afterward kept the class default _cp_client=None and silently dropped all structured telemetry in _dispatch_to_cp(). The concrete victim is the agentfield.verification logger: it is created at module import time inside Agent.__init__ (lazy `from agentfield.verification import LocalVerifier`) which runs *after* set_cp_client(self.client), so under local_verification=True none of its execution logs ever reached the control plane. Mirror the existing _global_log_level pattern: record the client in a module-level _global_cp_client under the cache lock, and apply it to new loggers in get_logger(). Forwarding now works regardless of import/creation order. set_cp_client(None) detaches globally as well. Add regression tests covering loggers created after set_cp_client, the existing already-cached path, and the None reset; extend reset_logger_state to isolate the new global. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> --------- Co-authored-by: SWE-AF <eng@agentfield.ai> Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent 0eb3a9a commit ccfde97

5 files changed

Lines changed: 349 additions & 25 deletions

File tree

.gitignore

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,8 @@
66
*.swo
77
test-reports/
88
.env
9+
.worktrees/
10+
.artifacts/
911

1012
# Go
1113
bin/

sdk/python/agentfield/logger.py

Lines changed: 66 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -75,8 +75,9 @@ def __init__(self, name: str = "agentfield"):
7575

7676
def set_level(self, level: str):
7777
"""Set log level at runtime (e.g., 'DEBUG', 'INFO', 'WARN', 'ERROR')"""
78-
79-
self.logger.setLevel(_LEVEL_TO_LOGGING.get(level.upper(), logging.INFO))
78+
level_upper = level.upper()
79+
self.log_level = level_upper
80+
self.logger.setLevel(_LEVEL_TO_LOGGING.get(level_upper, logging.INFO))
8081

8182
def _setup_logger(self):
8283
"""Setup logger with console handler if not already configured"""
@@ -113,8 +114,10 @@ def _format_payload(self, payload: Any) -> str:
113114

114115
@staticmethod
115116
def _now_iso() -> str:
116-
return datetime.now(timezone.utc).isoformat(timespec="milliseconds").replace(
117-
"+00:00", "Z"
117+
return (
118+
datetime.now(timezone.utc)
119+
.isoformat(timespec="milliseconds")
120+
.replace("+00:00", "Z")
118121
)
119122

120123
@staticmethod
@@ -174,7 +177,9 @@ def _build_execution_record(
174177
}
175178

176179
def _emit_structured_record(self, record: Dict[str, Any]) -> Dict[str, Any]:
177-
line = json.dumps(record, ensure_ascii=False, separators=(",", ":"), default=str)
180+
line = json.dumps(
181+
record, ensure_ascii=False, separators=(",", ":"), default=str
182+
)
178183
print(line, file=sys.stdout, flush=True)
179184
self._dispatch_to_cp(record)
180185
return record
@@ -454,28 +459,74 @@ def log_execution(
454459
return self._emit_structured_record(record)
455460

456461

457-
# Global logger instance
458-
_global_logger = None
462+
# Global logger cache: name -> AgentFieldLogger instance
463+
_logger_cache: Dict[str, AgentFieldLogger] = {}
464+
465+
# Global log level override (set via set_log_level)
466+
_global_log_level: Optional[str] = None
467+
468+
# Global control-plane client (set via set_cp_client). Stored at module scope so
469+
# loggers created *after* set_cp_client() still forward structured logs — mirrors
470+
# the _global_log_level pattern. Without this, a logger created late (e.g. the
471+
# lazily-imported agentfield.verification logger) would keep the class default
472+
# _cp_client=None and silently drop telemetry in _dispatch_to_cp().
473+
_global_cp_client: Optional["AgentFieldClient"] = None
474+
475+
# Guards _logger_cache, _global_log_level and _global_cp_client against concurrent
476+
# access. Reentrant so a future helper holding the lock can still call get_logger()
477+
# safely.
478+
_logger_cache_lock = threading.RLock()
459479

460480

461481
def get_logger(name: str = "agentfield") -> AgentFieldLogger:
462482
"""Get or create a AgentField SDK logger instance"""
463483

464-
global _global_logger
465-
if _global_logger is None:
466-
_global_logger = AgentFieldLogger(name)
467-
return _global_logger
484+
with _logger_cache_lock:
485+
if name not in _logger_cache:
486+
logger = AgentFieldLogger(name)
487+
if _global_log_level is not None:
488+
logger.set_level(_global_log_level)
489+
if _global_cp_client is not None:
490+
logger._cp_client = _global_cp_client
491+
_logger_cache[name] = logger
492+
return _logger_cache[name]
468493

469494

470495
def set_log_level(level: str):
471-
"""Set log level for the global logger at runtime (e.g., 'DEBUG', 'INFO', 'WARN', 'ERROR')"""
496+
"""Set log level for all logger instances at runtime (e.g., 'DEBUG', 'INFO', 'WARN', 'ERROR').
472497
473-
get_logger().set_level(level)
498+
Behavior note: this records the level and applies it to every *cached*
499+
logger; it does not create a logger when the cache is empty. Loggers
500+
created later via ``get_logger()`` pick up the stored level on creation.
501+
(Previously this implicitly created the default logger as a side effect.)
502+
"""
503+
504+
global _global_log_level
505+
# Snapshot under the lock so a concurrent get_logger() can't mutate the dict
506+
# mid-iteration; apply levels outside the lock to avoid holding it during I/O.
507+
with _logger_cache_lock:
508+
_global_log_level = level
509+
loggers = list(_logger_cache.values())
510+
for logger in loggers:
511+
logger.set_level(level)
474512

475513

476514
def set_cp_client(client: Optional["AgentFieldClient"]) -> None:
477-
"""Attach a control-plane client so structured logs are forwarded."""
478-
get_logger()._cp_client = client
515+
"""Attach a control-plane client so structured logs are forwarded to all loggers.
516+
517+
Records the client at module scope and applies it to every *cached* logger.
518+
Loggers created later via ``get_logger()`` pick up the stored client on
519+
creation, so forwarding works regardless of import/creation order (e.g. the
520+
lazily-imported ``agentfield.verification`` logger).
521+
"""
522+
global _global_cp_client
523+
# Snapshot under the lock so a concurrent get_logger() can't mutate the dict
524+
# mid-iteration; apply to existing loggers outside the lock.
525+
with _logger_cache_lock:
526+
_global_cp_client = client
527+
loggers = list(_logger_cache.values())
528+
for logger in loggers:
529+
logger._cp_client = client
479530

480531

481532
# Convenience functions for common logging patterns

sdk/python/tests/conftest.py

Lines changed: 49 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -50,9 +50,7 @@
5050

5151

5252
def _network_allowed(node: "pytest.Node") -> bool:
53-
return bool(
54-
node.get_closest_marker("integration")
55-
)
53+
return bool(node.get_closest_marker("integration"))
5654

5755

5856
@pytest.fixture(autouse=True)
@@ -61,6 +59,7 @@ def _ensure_event_loop():
6159
raises RuntimeError in non-async contexts. Agent() constructor and
6260
handle_serverless() depend on asyncio internally."""
6361
import asyncio
62+
6463
try:
6564
asyncio.get_event_loop()
6665
except RuntimeError:
@@ -69,6 +68,53 @@ def _ensure_event_loop():
6968
yield
7069

7170

71+
@pytest.fixture(autouse=True)
72+
def _isolate_execution_context():
73+
"""Keep per-test agent/execution-context state from bleeding across tests.
74+
75+
The SDK tracks the active agent and execution context in module-level
76+
ContextVars and spawns best-effort fire-and-forget tasks (note/log
77+
forwarding). Under loaded CI on Python 3.12 these have intermittently
78+
polluted a later test's view of the context (observed flake:
79+
get_current_agent_instance() returning None mid-test, so workflow
80+
registration is skipped). Reset the vars and drain any tasks the test
81+
left pending around every test. Everything here is best-effort and must
82+
never raise — a teardown hiccup must not fail an otherwise-green test.
83+
"""
84+
import asyncio
85+
from agentfield import agent_registry
86+
from agentfield.execution_context import _context_manager
87+
88+
def _reset_vars():
89+
try:
90+
agent_registry._current_agent.set(None)
91+
except Exception:
92+
pass
93+
try:
94+
_context_manager._context_var.set(None)
95+
except Exception:
96+
pass
97+
98+
_reset_vars()
99+
try:
100+
yield
101+
finally:
102+
# Drain fire-and-forget tasks so none can resume during a later test.
103+
try:
104+
loop = asyncio.get_event_loop_policy().get_event_loop()
105+
if loop is not None and not loop.is_closed() and not loop.is_running():
106+
pending = [t for t in asyncio.all_tasks(loop) if not t.done()]
107+
for t in pending:
108+
t.cancel()
109+
if pending:
110+
loop.run_until_complete(
111+
asyncio.gather(*pending, return_exceptions=True)
112+
)
113+
except Exception:
114+
pass
115+
_reset_vars()
116+
117+
72118
@pytest.fixture(autouse=True)
73119
def _no_network_by_default(request):
74120
yield

sdk/python/tests/test_cancel.py

Lines changed: 27 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -136,12 +136,20 @@ def test_cancel_route_returns_200_for_unknown_execution():
136136

137137

138138
@pytest.mark.asyncio
139-
async def test_cancel_route_emits_info_log_on_active_cancel(caplog):
139+
async def test_cancel_route_emits_info_log_on_active_cancel():
140140
"""The route logs a structured info line when it actually cancelled
141141
something. We register the task and call the route handler directly
142142
rather than via TestClient because TestClient creates a fresh event
143143
loop per request, so a task registered in one request isn't visible
144144
from the next.
145+
146+
We capture with a handler attached directly to the ``agentfield.cancel``
147+
logger rather than pytest's ``caplog``. The SDK deliberately sets
148+
``propagate=False`` on the ``agentfield`` parent logger (see logger.py), so
149+
once any AgentField logger is created, ``agentfield.cancel`` records no
150+
longer reach the root logger where ``caplog``'s handler lives — which made
151+
this assertion silently order-dependent. A direct handler asserts the same
152+
contract independent of namespace propagation and suite ordering.
145153
"""
146154
agent = _FakeAgent()
147155
install_cancel_route(agent)
@@ -155,10 +163,7 @@ async def long() -> None:
155163
# Find the route handler we just installed.
156164
handler = None
157165
for route in agent.router.routes:
158-
if (
159-
getattr(route, "path", "")
160-
== "/_internal/executions/{execution_id}/cancel"
161-
):
166+
if getattr(route, "path", "") == "/_internal/executions/{execution_id}/cancel":
162167
handler = route.endpoint
163168
break
164169
assert handler is not None, "cancel route was not installed"
@@ -175,19 +180,34 @@ class _Request:
175180
def __init__(self, headers):
176181
self.headers = _Headers(headers)
177182

178-
with caplog.at_level(logging.INFO, logger="agentfield.cancel"):
183+
records: list[logging.LogRecord] = []
184+
185+
class _Capture(logging.Handler):
186+
def emit(self, record: logging.LogRecord) -> None:
187+
records.append(record)
188+
189+
cancel_logger = logging.getLogger("agentfield.cancel")
190+
capture = _Capture(level=logging.INFO)
191+
prev_level = cancel_logger.level
192+
cancel_logger.addHandler(capture)
193+
cancel_logger.setLevel(logging.INFO)
194+
try:
179195
resp = await handler(
180196
execution_id="exec-active",
181197
request=_Request({"X-AgentField-Source": "cancel-dispatcher"}),
182198
)
199+
finally:
200+
cancel_logger.removeHandler(capture)
201+
cancel_logger.setLevel(prev_level)
183202

184203
# FastAPI JSONResponse — body is bytes, status is on the object.
185204
import json as _json
186205

187206
assert resp.status_code == 200
188207
body = _json.loads(resp.body.decode())
189208
assert body == {"cancelled": True, "execution_id": "exec-active"}
190-
assert any("cancel-callback fired" in rec.message for rec in caplog.records)
209+
# getMessage() applies the %-args; rec.message is only set once a formatter runs.
210+
assert any("cancel-callback fired" in rec.getMessage() for rec in records)
191211

192212
with pytest.raises(asyncio.CancelledError):
193213
await task

0 commit comments

Comments
 (0)