[core] Add log rotation for job driver logs - #65006
Open
odncode wants to merge 7 commits into
Open
Conversation
Job driver logs (job-driver-{submission_id}.log) were written via a
plain append-mode file handle with no rotation, unlike other Ray log
files which respect RAY_ROTATION_MAX_BYTES/RAY_ROTATION_BACKUP_COUNT.
Long-running jobs could grow this file unbounded.
The driver subprocess holds the log file open directly via
Popen(stdout=...), so the existing C++ pipe-logging mechanism used
elsewhere in Ray (which redirects a process's own stdout/stderr at
its own startup) does not apply here, since Ray does not control the
entrypoint of the driver subprocess. Instead this uses copytruncate
semantics: JobSupervisor periodically checks the log file size and,
if over the threshold, JobLogStorageClient copies current content to
a backup file and truncates the original in place. Because the file
is opened with O_APPEND, the subprocess's next write lands cleanly
at the new end of file.
file_tail_iterator, used for live log streaming, held a persistent
read position that would go stale after an external truncation,
returning corrupted output. This adds a check to detect when the
file has shrunk below the reader's position and seek back to start.
Fixes ray-project#64528
See ray-project#64528 for full investigation notes.
Signed-off-by: odncode <nnajiodera2@gmail.com>
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
Code Review
This pull request implements log rotation for Ray job driver logs using copytruncate semantics, adding a periodic background task to monitor log sizes and updating the file tail iterator to handle truncated files. The review feedback is highly constructive, pointing out critical issues such as a blocking synchronous I/O call in the asyncio event loop, a potential race condition when truncating files, and a flaky test due to the timing of the rotation check. It also suggests fixing a minor typo introduced in a test comment.
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
ray-gardener
Bot
added
core
Fixes several issues raised by gemini-code-assist and cursor bugbot on the initial PR: - rotate_log_file does synchronous file copy/truncate that could block the JobSupervisor event loop for a long time on large log files. Moved the call into the default executor via loop.run_in_executor so subprocess polling, stop handling, and status updates are not delayed while rotation runs. - get_logs and get_last_n_log_lines only read the active log file, so after a rotation they silently lost all output written before it. Added _get_rotated_backup_paths to enumerate rotated .1/.2/... files oldest first, and updated both methods to include backup content before the active file's content. - rotate_log_file's final truncate could raise FileNotFoundError if the log file was removed between the earlier os.path.exists check and the truncate itself. Wrapped in a try/except to handle that race. - test_job_driver_log_rotation would not reliably trigger rotation: the test entrypoint runs for about 4 seconds but LOG_ROTATION_CHECK_PERIOD_S defaults to 5 seconds, so the rotation task would get cancelled before its first check ever fired. Added RAY_JOB_LOG_ROTATION_CHECK_PERIOD_S as an env override (matching the existing pattern for RAY_ROTATION_MAX_BYTES/BACKUP_COUNT) and set it to 0.5s in the test via call_ray_start's env parameter. Note this needed an env var rather than monkeypatching the class attribute, since JobSupervisor runs as a separate Ray actor process and would not see an in-process monkeypatch. - Fixed a typo in a test comment (test_utils.py). Also added TestJobLogStorageClientRotation, a set of local unit tests covering _get_rotated_backup_paths ordering and get_logs's backup concatenation behavior directly against tmp_path, without needing a running Ray cluster. Signed-off-by: odncode <nnajiodera2@gmail.com>
Two follow-ups from cursor bugbot's second review pass on the log rotation PR: - file_tail_iterator's truncation check only ran after readline() returned EOF, comparing the reader's position against the file's current size at that moment. Cursor correctly pointed out this misses a real case: if the file is truncated and then grows back past the reader's old position before the check runs, the size comparison comes back clean and the iterator resumes from a stale position instead of detecting the rotation, silently skipping or garbling content. Fixed by moving the check to run before every read, not only on EOF (a stale offset can otherwise land on a real byte boundary in new post-rotation content and return what looks like a normal line), and by tracking the largest file size observed across checks rather than only the reader's current position, the same approach log_monitor.py's LogFileInfo.reopen_if_necessary uses for the same problem. This remains a size-polling based detection, so it shares log_monitor.py's own inherent limitation: a truncate followed by regrowth past the previous size within a single write, entirely between two checks, can still go undetected. Documented this directly in the function's docstring rather than leaving it implicit. In practice this requires the file to shrink and then outgrow its previous size faster than we can observe it, which real incrementally-written subprocess output does not do. - test_job_driver_log_rotation used a 1000 byte rotation threshold against ~4200 bytes of total test output with backup_count=1. This produced multiple rotation events during the test, and since each rotation overwrites the single backup file, most of the job's early output was legitimately gone by the time the job finished, not lost to a bug, but to backup_count being too small for what the test was asserting. Raised the threshold to 2200 bytes so exactly one rotation fires, matching what the test actually verifies: a single rotation boundary is handled cleanly, not that history survives an arbitrary number of rapid rotations. Signed-off-by: odncode <nnajiodera2@gmail.com>
Cursor bugbot correctly flagged that file_tail_iterator's truncation
check compared f.tell() (a text-mode stream position) directly against
os.path.getsize() (a real byte count). Per Python's own documentation,
TextIOWrapper.tell() returns an opaque, implementation-defined number
that does not generally represent a byte offset. Comparing it directly
to a byte count can misfire, most likely with multi-byte characters or
non-Unix newline translation, causing the truncation check to
falsely trigger (or fail to trigger) and either spuriously reset a
reader with no rotation, or miss a real one.
Fixed by tracking bytes consumed ourselves (bytes_read), computed from
len(line.encode(file_encoding)) on lines we have actually decoded,
rather than relying on the stream's own opaque position. The encoding
used to open the file is now pinned explicitly so this byte count
always matches what was actually decoded from disk.
f.seek(0) itself remains correct and unaffected: Python's docs confirm
seeking to exactly offset 0 is always well-defined on a text stream,
unlike arbitrary offsets, so no change was needed there.
Verified no other f.tell() usage in this file has the same issue;
fast_tail_last_n_lines's tell() call operates on a file opened in
binary mode ("rb"), where tell() is a genuine byte offset.
Signed-off-by: odncode <nnajiodera2@gmail.com>
This was referenced Aug 3, 2026
Cursor bugbot correctly flagged that get_last_n_log_lines treated active_line_count == 0 the same as "nothing to read at all", returning early without checking rotated backups. This conflated two different situations: a job that genuinely has not produced output yet, and an active file that is empty specifically because rotation just fired and truncated it, with the real content sitting in a .1 backup. In the second case, a failed job's error message could show no logs at all even though the actual output still exists on disk. Fixed by only treating an empty active file as "nothing to read" when there are also no backup files present. When backups exist, the existing backup-then-active-file logic below already handles this correctly (remaining_lines becomes the full num_log_lines requested, since active_line_count is 0). Also removed a redundant duplicate call to _get_rotated_backup_paths, previously called once in the new guard and again to build backup_paths a few lines later; now computed once and reused. Added three tests to TestJobLogStorageClientRotation covering: empty active file with a real backup (the regression case), empty active file with no backup at all (the genuine no-output case, to make sure we did not overcorrect), and active file alone already sufficient (to confirm backups are not consulted unnecessarily). Signed-off-by: odncode <nnajiodera2@gmail.com>
Addresses two Cursor review comments on commit 7453aed: 1. Rotation could race with the failure-path log read. Task.cancel() on the log rotation task does not stop or wait for an in-flight rotate_log_file call already running in an executor, since cancelling the asyncio task only cancels the asyncio-level future it is awaiting, not the underlying thread. Verified this empirically before writing a fix. The fix keeps a reference to the raw concurrent.futures.Future for an in-flight rotation and genuinely waits for it, with a bounded timeout, before the failure path reads the log file. 2. get_last_n_log_lines did a synchronous full-file line count scan directly in an async def with no executor offload, blocking the JobSupervisor actor's event loop on large files, same category of issue as the original rotate_log_file blocking fix. The method is now a thin async wrapper around a synchronous helper that can run inline (default, unchanged behavior) or on a supplied executor. JobSupervisor now passes a dedicated executor for this on the failure path. Both fixes verified locally: existing test_utils.py suite (32 tests) passes unchanged, two new tests added confirming the executor path is genuinely used and the no-executor default is unchanged. The rotation-wait fix could not get local unit coverage since JobSupervisor's constructor requires a real GcsClient connection, consistent with every existing test in test_job_manager.py, so it relies on hand-tracing plus standalone asyncio repro scripts and the existing test_job_driver_log_rotation integration test in CI. Signed-off-by: odncode <nnajiodera2@gmail.com>
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes using default effort and found 1 potential issue.
Reviewed by Cursor Bugbot for commit e729e60. Configure here.
Addresses Cursor comment on commit e729e60: 'Rotation wait can cancel job completion.' _wait_for_rotation_to_finish read self._log_rotation_future fresh after log_rotation_task.cancel() had already been called. _rotate_driver_log_if_needed clears that attribute to None in a finally block as part of its own cancellation cleanup, and that finally can run synchronously enough that the attribute is already None by the time _wait_for_rotation_to_finish reads it, so the method silently treated a genuinely in-flight rotation as nothing to wait for and returned immediately, defeating the entire point of the prior fix. Verified this specific race empirically with a standalone repro script before writing the fix, since Cursor's stated mechanism (asyncio.wrap_future chaining a cancel back to the source future) did not reproduce, but a related and real race did, once the repro matched the real code's finally-block cleanup shape exactly, not a simplified version. Fix: run() now captures self._log_rotation_future into a local variable before calling log_rotation_task.cancel(), and passes that captured reference into _wait_for_rotation_to_finish, which no longer reads self._log_rotation_future itself. The captured reference is unaffected by the coroutine's own cleanup clearing the instance attribute afterward. Verified the fix closes the gap with a second repro matching this exact sequence. No new local test added, same constraint as the original method, JobSupervisor's constructor requires a real GcsClient connection. Existing 32-test test_utils.py suite passes unchanged. Signed-off-by: odncode <nnajiodera2@gmail.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Fixes #64528
Why
Job driver logs (
job-driver-{submission_id}.log) are written via a plain append-mode file handle with no rotation, unlike other Ray log files which respectRAY_ROTATION_MAX_BYTES/RAY_ROTATION_BACKUP_COUNT. Long-running jobs can grow this file unbounded.Why not the existing C++ pipe-logging mechanism
I initially looked at reusing the existing
StreamRedirectormechanism from #49733 and related PRs, since @Kunchd pointed at it as prior art. That mechanism redirects a process's own stdout/stderr at its own startup, and every existing caller uses it that way.JobSupervisor's situation is different: it spawns the job driver as an arbitrary shell command viasubprocess.Popen(shell=True), and there is no hook to inject a redirect call into a process whose contents Ray does not control before it starts. Full investigation notes are on the issue.What this does instead
Copytruncate semantics as suggested by @nadongjun , the same approach used by
logrotate --copytruncate.JobSupervisorperiodically checks the driver log file size, and if it exceeds the configured threshold,JobLogStorageClientcopies the current content to a backup file and truncates the original in place. Because the file is opened withO_APPEND, the subprocess's next write lands cleanly at the new end of file with no gap or corruption, verified locally against a real subprocess.Also fixes a related bug this surfaced:
file_tail_iterator(used for live log streaming viaray job logs -f) held a persistent read position that would go stale after an external truncation, returning corrupted output. Added a check to detect when the file has shrunk below the reader's position and seek back to start.Testing
test_recovers_after_external_truncatetotest_utils.py, passing locally, covering thefile_tail_iteratorfix directly.test_job_driver_log_rotationtotest_job_manager.py, a full integration test against a real cluster and subprocess confirming rotation triggers correctly and no log lines are lost, duplicated, or corrupted across the rotation boundary. I wasn't able to run this one locally due to a pre-existing, seemingly unrelated environment issue in my checkout (a stale compiled protobuf mismatch incustom_types.pythat also blocks the file's existing tests, unrelated to this change), so I am relying on CI for this one.