Skip to content

Stop log rotation and shutdown killing threads that are logging - #5196

Open
romain-intel wants to merge 1 commit into
springfall2008:mainfrom
romain-intel:pr/log-rotation
Open

romain-intel wants to merge 1 commit into
springfall2008:mainfrom
romain-intel:pr/log-rotation

Conversation

@romain-intel

Copy link
Copy Markdown
Contributor

Four faults in the same file, all of which end with a thread that was working fine being unable to log or being killed outright.

Rotation closes the logfile, renames it and opens the replacement. A component thread part-way through log() in that window writes to a closed handle and takes a ValueError all the way up. Nothing restarts a component thread mid-run, so it stays dead, is_all_alive() keeps failing, and the dashboard reports Predbat unhealthy for the rest of the run - the ML forecaster is the one this hits, since its training thread logs steadily while only the main thread rotates.

Rotation now renames first and publishes the new handle before closing the old one. POSIX is happy to rename an open file, so a thread holding the previous reference writes into the rotated log, which is harmless. write_log_line() absorbs what is left by retrying once and then going to stderr: logging must not be able to kill its caller, whatever the cause.

stop_all() joins each thread for five minutes and then closes the logfile regardless. A training run outlives that easily, so the close lands underneath it; it now only closes when nothing is still running, and names the threads that outlived the join.

create_task() threads are made daemon. Python joins every non-daemon thread before exit, so a component still working after stop_all() gave up held the whole process open - an auto-update restart sat through a full curriculum pass and then watched the next one start.

@romain-intel

Copy link
Copy Markdown
Contributor Author

I reopened this because I didn't get any feedback on the other one so I wondered if it fell out (it was old). Apologies if you meant to just not merge them (in which case I will stop keeping them in sync and just maintain my own branch).

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot review overview

🟡 Changes recommended

Rotation error handling and shutdown warning behavior still have unresolved issues.

Get a fresh assessment by requesting another Copilot review.

Review effort: Lite
Findings: 1 High severity · 1 Medium severity · 1 Low severity

Open (3)
What changed in this PR

Improves logfile rotation and shutdown safety so component threads survive logging failures and do not block process exit.

Changes:

  • Adds resilient logfile writes and safer rotation handling.
  • Keeps logs open while threads remain active and makes task threads daemonized.
  • Adds regression tests for rotation, shutdown, and thread behavior.
File Summary
apps/​predbat/​hass.py Updates logging, rotation, shutdown, and task-thread lifecycle handling.
apps/​predbat/​tests/​test_log_rotation.py Adds targeted rotation, shutdown, and thread-safety tests.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread apps/predbat/hass.py
# cannot be used to close the remaining gap: Pool() forks, so a lock held by a component
# thread at that instant is inherited already-locked by every worker, and the first worker
# to log would block forever. write_log_line() absorbs the gap instead.
rotate_predbat_logs(max_logs)
Comment thread apps/predbat/hass.py
self.logfile.close()
else:
alive = [t.name for t in self.threads if t.is_alive()]
self.log("Warn: leaving the logfile open, {} still running after the join timeout: {}".format(len(alive), ", ".join(alive)), quiet=False)
Comment on lines +628 to +634
# Thread-safety of rotation and shutdown, alongside the retention/naming checks above
failed |= test_write_survives_a_closed_handle()
failed |= test_write_retries_onto_the_new_handle()
failed |= test_rotation_publishes_before_closing()
failed |= test_shutdown_leaves_logfile_open_for_surviving_threads()
failed |= test_component_threads_are_daemon()
failed |= test_rotation_rolls_back_when_the_replacement_cannot_be_opened()
@springfall2008 springfall2008 added the BOT_CLEANUP Trigger: bot should address PR review feedback and CI failures, then commit and push label Sep 24, 2026
@springfall2008

Copy link
Copy Markdown
Owner

Automated cleanup skipped: this PR's head branch lives in a fork, and the bot's credential can only write to springfall2008/batpred, so it cannot push the fixes back to this PR. Re-open the change from a branch in springfall2008/batpred to use the cleanup flow, or apply the review feedback manually.

@springfall2008 springfall2008 added BOT_FAILED An automated triage/PR attempt failed; see the comment for details and removed BOT_CLEANUP Trigger: bot should address PR review feedback and CI failures, then commit and push labels Sep 24, 2026
…gging

Four faults in the same file, all of which end with a thread that was working fine being unable to
log or being killed outright.

Rotation closes the logfile, renames it and opens the replacement. A component thread part-way
through log() in that window writes to a closed handle and takes a ValueError all the way up. Nothing
restarts a component thread mid-run, so it stays dead, is_all_alive() keeps failing, and the dashboard
reports Predbat unhealthy for the rest of the run - the ML forecaster is the one this hits, since its
training thread logs steadily while only the main thread rotates.

Rotation now renames first and publishes the new handle before closing the old one. POSIX is happy to
rename an open file, so a thread holding the previous reference writes into the rotated log, which is
harmless. write_log_line() absorbs what is left by retrying once and then going to stderr: logging
must not be able to kill its caller, whatever the cause.

The rename and reopen are guarded, and a reopen that fails rolls the rename back. Without that the
live pathname has already moved, so writes keep going to the rotated inode and every later rotation
renames a file that is not there - logging never recovers even once the disk clears. Raised in review
on springfall2008#4684.

stop_all() joins each thread for five minutes and then closes the logfile regardless. A training run
outlives that easily, so the close lands underneath it; it now only closes when nothing is still
running, and names the threads that outlived the join.

create_task() threads are made daemon. Python joins every non-daemon thread before exit, so a
component still working after stop_all() gave up held the whole process open - an auto-update restart
sat through a full curriculum pass and then watched the next one start.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

BOT_FAILED An automated triage/PR attempt failed; see the comment for details

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants