Repository navigation
feat(logging): add managed file output and worker log aggregation - #2196
Conversation
There was a problem hiding this comment.
Copilot was unable to review this pull request because the user who requested the review has reached their quota limit.
An organization owner can choose the repository organization as the billing source for reviews requested by members with a paid Copilot license. Learn about Copilot code review billing.
There was a problem hiding this comment.
Copilot was unable to review this pull request because the user who requested the review has reached their quota limit.
An organization owner can choose the repository organization as the billing source for reviews requested by members with a paid Copilot license. Learn about Copilot code review billing.
There was a problem hiding this comment.
Copilot was unable to review this pull request because the user who requested the review has reached their quota limit.
An organization owner can choose the repository organization as the billing source for reviews requested by members with a paid Copilot license. Learn about Copilot code review billing.
hidb4ai
left a comment
hidb4ai
left a comment
There was a problem hiding this comment.
Two P2 issues remain in managed file logging: a blocked writer can prevent shutdown, and receiver-confirmed log loss is missing from the drop counter. Reproductions and required behavior are inline. Reviewed at fe8baf76.
| self._receiver = None | ||
| if self._listener is not None: | ||
| # Drain Worker streams before placing the writer's final sentinel. | ||
| self._listener.stop() |
There was a problem hiding this comment.
[P2] Bound the complete file-writer shutdown path
If file I/O or gzip compression stalls, QueueListener.stop() joins the writer without a timeout; enqueue_sentinel() also waits indefinitely when the queue is full. The receiver's one-second drain deadline does not bound either wait. In a controlled probe, blocking FileHandler.emit kept shutdown_server_logging() pending after three seconds; it returned only after the write was released. This path runs from the Server CLI finally block and atexit, so a diagnostic sink can prevent normal Server shutdown or restart, contrary to RFC 0046's bounded telemetry flush. Please bound the complete cleanup path, including interpreter-exit cleanup, and allow remaining diagnostic output to be abandoned after the deadline.
There was a problem hiding this comment.
Rechecked the current head fe8baf768770 with the blocked-file-writer probe. shutdown_server_logging() was still running after 3.0 seconds and returned only after FileHandler.emit was released. The receiver drain deadline still does not bound the listener join or a full-queue sentinel insertion, so this P2 remains reproducible.
There was a problem hiding this comment.
Shutdown bounds Worker-channel draining, then uses native logging to finish queued writes and close files. Permanently blocked file I/O requires host-level termination; there is no in-process hard deadline. This boundary is documented in 921894c0. Is that scope acceptable?
There was a problem hiding this comment.
复核 head 921894c0：本条 P2 没有按「给停机路径加上界」处理，而是把现状写进契约。
- 代码侧未变：
_DrainingQueueListener.stop()等队列排空，文件 handler 的写入、gzip 压缩与close()走logging原生清理，没有独立 deadline。 - 文档侧已同步中英四处：
docs/{en,zh}/docs/operate/observability.md明写「File writes, compression, and close use native logging cleanup without a separate timeout. A stalled file sink can therefore delay Server process exit.」，docs/{en,zh}/development/observability.md与docs/{en,zh}/rfcs/0046_observability_foundations.md同口径，我逐句对回源码一致。
残留风险因此从「未声明的无界等待」变成「已声明的无界等待」，读者不会再误以为进程退出有超时保护；如果维护者认为个人服务停机必须可中断，这仍是一条待决的设计选择，而不是文档问题。
另有一处与本条相邻的事实，供确认而非要求改动：_OperationalQueueHandler.close() 在 _receiver.close() 返回 False（接收线程仍在 _DRAIN_TIMEOUT + 0.5 后存活）时直接 return，此时 listener.stop() 与 _resources.close() 都不会执行，只能依赖后续 atexit 再调一次 close()。
There was a problem hiding this comment.
Confirmed. If the receiver is still active, close() leaves the sink open and the registered atexit callback can retry cleanup. This retry is best-effort; permanently stalled I/O requires host-level termination.
|
@PsiACE Please prioritize updating this PR for 1.4.1. Both P2s remain reproducible at Please push the fixes with regression coverage and reply with the updated commit and validation results. Please also share an ETA for the update. |
There was a problem hiding this comment.
Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.
An organization owner can choose the repository organization as the billing source for reviews requested by members with a paid Copilot license. Learn about Copilot code review billing.
| process.join(timeout=5) | ||
| process.close() | ||
| resume.set() | ||
| assert registry.get_sample_value(metric) == before + 1 |
There was a problem hiding this comment.
[P1] 新增的 Windows 步骤在 head 上直接失败：用例依赖内核发送缓冲制造丢包，Windows 上记录被完整送达
windows-unit-portability 的 Verify spawned worker logging on Windows 步骤正是本 PR 新增（.github/workflows/master.yml 三行），在 head 921894c0 执行 uv run --locked --no-sync pytest -q tests/e2e/test_worker_logging.py 报：
FAILED tests/e2e/test_worker_logging.py::test_discarded_worker_record_is_counted_in_prometheus - AssertionError: assert 0 == (0 + 1)
同 head 的四个 tests (x, e2e)（ubuntu）全绿，所以失败只在 Windows 出现，而我用 exact head 树在本机（Windows）复跑得到同一签名：-k discarded → 1 failed, 30 deselected，assert 0 == (0 + 1)。
根因不是计数器坏了，而是用例无法在 Windows 上造出背压：SO_SNDBUF=4096 只限制发送端，接收端窗口仍会吸收整条记录。探针（probes/probe_drop_metric2.py）用同一段代码路径、不设 capfd，在子进程写出 200,000 字符记录后，父进程把整条记录落进了 background.log（400,608 字节，含 Large observation），_buffers 在 _close_channel 前已为空 ⇒ 没有残余行 ⇒ on_drop 不被调用，指标保持 0。stderr 也没有 observability.log_failed，进一步说明发送端从未超时。
计数逻辑本身可用，且可确定性验证（probes/probe_partial_close.py）：向 socketpair 写入一条完整记录 "delivered-record"\n 和一条截断记录 "truncated 后正常关闭，得到 delivered=['delivered-record']、drop_counts=[1]。
建议把该用例改成确定性驱动，而不是依赖 socket 缓冲：用上述「一条完整记录 + 一条截断记录再关闭」的形态断言 +1（或让 deliver 抛出 Full 以覆盖队列满路径），必要时再用平台标记把依赖内核缓冲的版本限制在 Linux。请同时补一条在 Windows 上游走的断言，因为该步骤目前是这套子系统唯一的 Windows 覆盖。
There was a problem hiding this comment.
Replaced the buffer-dependent probe with deterministic clean and truncated closes from a real spawned Worker. Both cases check persisted output and the Prometheus delta.
There was a problem hiding this comment.
Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.
An organization owner can choose the repository organization as the billing source for reviews requested by members with a paid Copilot license. Learn about Copilot code review billing.
Which issue or RFC does this PR close?
Related: RFC 0046: Observability foundations.
Rationale for this change
Short-lived workers need shared log output without creating a file per task or concurrently rotating the same file.
What changes are included in this PR?
Workers send formatted, allowlisted logs through dedicated socketpairs to their owning Server. A bounded queue feeds standard Python logging handlers.
File output supports a configurable directory, size threshold, retention, and gzip compression. Defaults are 20 MiB and 10 gzip archives. Logs remain best-effort; overload can drop records without changing task results. Includes bilingual documentation and behavior tests.
Are there any user-facing changes?
File output replaces stdout when enabled. macOS/Windows personal services enable it by default; Linux keeps journal output. Workers share their owning Server's role-based file.
How was this change tested?
make checkandmake docs-test.AI usage statement
Codex assisted with implementation, documentation, and tests.