[Python SDK] Structured logs, event loop and Postgres instance

[pocesar]

Describe the bug

agentfield/sdk/python/agentfield/logger.py

Lines 178 to 184 in 4d4d54e

	def _emit_structured_record(self, record: Dict[str, Any]) -> Dict[str, Any]:
	line = json.dumps(
	record, ensure_ascii=False, separators=(",", ":"), default=str
	)
	print(line, file=sys.stdout, flush=True)
	self._dispatch_to_cp(record)
	return record

_emit_structured_record do 2 things at once:

1. Dumps to stdout, that depending on the size of the payload (ie >1MB) it will block the event loop if the stdout is for any reason busy or slow. logging default StreamHandler uses a threading.RLock internally also, for double trouble, besides the Agentfield logger also using another global lock instance

   agentfield/sdk/python/agentfield/logger.py

   Lines 81 to 89 in 4d4d54e

   	def _setup_logger(self):
   	"""Setup logger with console handler if not already configured"""
   	if not self.logger.handlers:
   	handler = logging.StreamHandler(stream=sys.stdout)
   	formatter = logging.Formatter("%(message)s")
   	handler.setFormatter(formatter)
   	self.logger.addHandler(handler)
   	self.logger.propagate = False

   In highly concurrent or heavy I/O driven deployments, it's a dice roll until something stalls.
2. The only way to omit this JSON dump is to manually patch _emit_structured_record and _emit_plain the agentfield logger module during initialization and make it a no-op.

Ideally it should be an opt-in. There's a ambiguous env var AGENTFIELD_LOGS_ENABLED but it's a misnomer, since what it does is to watch for its own process stdout / stderr and intercept that.

agentfield/sdk/python/agentfield/node_logs.py

Lines 223 to 232 in 4d4d54e

	def install_stdio_tee() -> None:
	"""Replace sys.stdout/sys.stderr with tees into the process log ring."""
	global _tee_installed
	if _tee_installed or not logs_enabled():
	return
	ring = get_ring()
	ml = max_line_bytes()
	sys.stdout = _TeeTextIO("stdout", cast(TextIO, sys.__stdout__), ring, ml)
	sys.stderr = _TeeTextIO("stderr", cast(TextIO, sys.__stderr__), ring, ml)
	_tee_installed = True

Steps to reproduce

1. Go to '...'
2. Run '...'
3. See error

Expected behavior

When logs are enabled but no stdout setting (that doesn't exist today, let's say AGENTFIELD_ONLY_EMIT_LOGS), only sends to the Postgres instance, through _dispatch_to_cp and no print line.

Additionally if locks must be used to ensure order, either use a non-blocking Lock (with a tiny timeout that constantly yields) or use a FIFO queue that is async friendly, and will deal with global locks only when it needs to output.

Screenshots / Logs

Environment

• Control plane version:
• SDK version (if applicable):
• Deployment environment (local, docker, kubernetes, etc.):

Additional context

[AbirAbbas]

Triage

Classification: bug ✓
Suggested labels: bug

Likely affected files:

• ./reasoners/helpers.py (matched: reason, help)
• ./cla-signatures.json (matched: json)
• ./.env.example (matched: env)
• ./reasoners/models.py (matched: reason)
• ./reasoners/init.py (matched: reason)

---

Triage by github-buddy

[mikemikimike]

Implemented in PR #994.

• Changed: Added AGENTFIELD_LOG_STDOUT to disable structured execution record mirroring to stdout while preserving control-plane dispatch; the default remains enabled.
• Tests: uv run --frozen pytest sdk/python/tests/test_logger.py -q (14 passed).
• Validation: Ruff check, Ruff format check, and git diff --check passed.

PR: #994

[pocesar]

@mikemikimike thanks for stepping up, although #994 is just a partial fix for the issue. thread / async mixing is still in place, mostly due to how node_logger is wired

[AbirAbbas]

Three fixes landed since you opened this; none of them are in 0.1.127.

• fix(sdk/python): dispatch execution logs without a throwaway loop, and finish AsyncExecutionManager teardown when a cancel raises #972 (v0.1.135): _dispatch_to_cp runs on one long-lived background loop — no throwaway loop per record, and per-loop httpx clients are released when their loop closes. That's the thread/async mixing you pointed at.
• feat(sdk): allow disabling structured log stdout mirroring #994 + fix(sdk/python): bounded, non-blocking structured log mirror; safe tee; async log follower #1002 (v0.1.137): AGENTFIELD_LOG_STDOUT=false turns the stdout mirror off with no serialization at all; with it on, the line is capped by AGENTFIELD_LOG_MAX_LINE_BYTES (default 16384, largest attributes elided first); and the /agentfield/v1/logs follower is async, so follow=true no longer pins a threadpool worker.

Two more small ones are up: #1028 stops serializing the full record before deciding it's oversized (that was O(payload) CPU on the loop thread — ~15ms at 5MB, roughly halved), and #1020 makes the TypeScript SDK honor AGENTFIELD_LOG_STDOUT too and documents the per-SDK logging knobs in one place.

On the FIFO / background-writer idea: I looked at it seriously and I'm not doing it, at least not now. With the 16KB cap the multi-MB stdout write can't happen any more, what's left on the loop thread is CPU, and the one residual risk — a stalled log collector back-pressuring the pipe — is fully removable today with AGENTFIELD_LOG_STDOUT=false. A queue writer costs real things in exchange: capsys/StringIO capture in users' tests breaks, the last lines are lost on os._exit, ordering between structured and plain lines goes, and fork safety gets interesting. If you hit an actual collector stall on 0.1.137 with numbers, reopen that part and I'll revisit.

Default stays opt-out (mirror on). That was decided inside #994 — the opt-in version landed and was reverted in the same PR, because it silently blanks structured records from kubectl logs and from the node log ring with no signal. And AGENTFIELD_LOGS_ENABLED keeps its name; the docs now say plainly that it controls stdout/stderr capture, not control-plane dispatch.

[7vignesh]

I dug into what's left after #994 / #972 and I think the remaining defect is narrow and concrete. Sharing the trace and a proposed fix before I open a PR.

What's already handled

• _dispatch_to_cp is non-blocking - it goes through run_async.fire_and_forget onto the shared background loop (fix(sdk/python): dispatch execution logs without a throwaway loop, and finish AsyncExecutionManager teardown when a cancel raises #972 / [Python SDK] Mixing threads and async code #620), so the Postgres/CP write no longer runs inline on the caller.
• The stdout mirror is size-bounded by _bounded_mirror_line (capped at max_line_bytes(), default 16 KiB), so the ">1MB payload" case is already trimmed before printing.
• AGENTFIELD_LOG_STDOUT (feat(sdk): allow disabling structured log stdout mirroring #994) lets you turn the mirror off entirely.

What still blocks the event loop (the remaining bug)

The default path in _emit_structured_record is still a synchronous, blocking write on the calling thread:

def _emit_structured_record(self, record):
    if self._stdout_mirror_enabled():
        line = self._bounded_mirror_line(record)
        print(line, file=sys.stdout, flush=True)   # <-- blocking, on the caller's thread
    ...

When a reasoner logs from the running event loop, log_execution / _emit_optional_structured call this inline. And sys.stdout here is the _TeeTextIO wrapper installed by node_logs.install_stdio_tee(), so a single emit does:

1. acquire _TeeTextIO._write_lock (a threading.Lock)
2. self._original.write(line)
3. ProcessLogRing.append(...) under the ring's _lock
4. flush=True re-acquires _write_lock and calls self._original.flush() - the actual blocking OS write

So even bounded in size, a flush=True to a slow/full stdout pipe (busy tty, piped consumer not draining, a kubectl logs reader stalling) blocks the event loop for the duration, under two thread locks that also serialize against any other thread writing to stdout. That matches the "dice roll until something stalls" symptom, and it's independent of payload size.

AGENTFIELD_LOG_STDOUT=false avoids it, but that's all-or-nothing: you lose the local-dev mirror to kill an event-loop hazard.

Proposed fix

Make the mirror write non-blocking from the event loop's perspective, without changing default behavior or dropping the mirror:

1. When _emit_structured_record runs on a running event loop, offload the bounded print to a thread executor (loop.run_in_executor(None, ...)) so the loop never waits on the OS write or the tee locks. When there's no running loop (sync context, CLI), keep the direct print - it's already correct there and offloading would only add overhead.
2. Keep the write best-effort and swallow exceptions exactly as today (a broken stdout must never fail a caller).
3. Preserve ordering guarantees at the "good enough for a mirror" level: mirror lines are advisory (the CP dispatch is the source of truth), so strict cross-record ordering isn't required - but I'll route offloaded writes through a single-worker executor / serialized helper so lines from the same logger don't interleave mid-line.

This keeps AGENTFIELD_LOG_STDOUT semantics, keeps the size bounding, and removes the last synchronous OS write from the loop thread.

Deliberately out of scope (happy to split if you want them):

• Replacing the _TeeTextIO / ProcessLogRing threading.Locks with a lock-free / queue design. Those are held very briefly and the offload above already keeps them off the loop thread; a queue rewrite is a larger change with its own ordering/backpressure tradeoffs.
• A new AGENTFIELD_ONLY_EMIT_LOGS env var - AGENTFIELD_LOG_STDOUT=false already gives "CP dispatch only, no print", so a second flag would overlap.

Question before I code

Does offloading the mirror write to a thread executor when on a running loop (option above) match what you want, or would you rather the default flip to a background-queue writer (single dedicated thread draining a bounded queue.Queue, dropping oldest under backpressure)? The executor approach is smaller and preserves today's behavior off the loop; the queue approach fully decouples but adds a drain thread and a drop policy. I'll implement whichever you prefer.

[pocesar]

@7vignesh a separate queue for I/O that shouldn't affect the main workflow execution makes sense, and not only for print to stdout. Anything that would cause contention or congestion in the same process could have a separate backpressure in a lower priority mechanism instead of adding more async tasks to an array and hope it goes through