Do not let the signal handler's own logging stop it dying by danielhanchen · Pull Request #9083 · unslothai/unsloth · GitHub
Skip to content

Do not let the signal handler's own logging stop it dying - #9083

Merged
danielhanchen merged 7 commits into
mainfrom
fix-signal-handler-reentrancy
Aug 17, 2026
Merged

Do not let the signal handler's own logging stop it dying#9083
danielhanchen merged 7 commits into
mainfrom
fix-signal-handler-reentrancy

Conversation

@danielhanchen

Copy link
Copy Markdown
Member

A cancelled Kaggle launcher exited 0 instead of dying of its signal. Intermittently, and only on loaded CI runners. This is the cause, and it is in the handler's first line.

What it is

A signal handler runs on the main thread, wherever that thread happened to be. If it was inside a write to stdout, the interpreter refuses the second one:

RuntimeError: reentrant call inside <_io.BufferedWriter name='<stdout>'>

That is exactly what _release_and_die opened with:

def _release_and_die(signum, _frame):
    _log(f"received signal {signum}; deleting kernels before exiting")   # <- outside the try
    try:
        release()
    ...
    signal.signal(signum, signal.SIG_DFL)
    os.kill(os.getpid(), signum)                                          # <- never reached

When that _log raises, the handler never reaches os.kill. The exception propagates into the main thread, main()'s except BaseException catches it, and the process exits on whatever code main computed. A cancelled job then reads as a completed one.

It requires the signal to land inside a print, which is why it never reproduced locally under any amount of contention I could arrange, and why it took a real runner to show it.

How it was found

The diagnostic merged in #9079, which prints the launcher's own log when a signal test fails. On staging:

Launcher said: [launch] the launcher aborted:
  RuntimeError: reentrant call inside <_io.BufferedWriter name='<stdout>'>.
  Every kernel it had pushed was deleted on the way out

Before that line existed, the failure said only expected death by SIGTERM, got returncode 0, which is consistent with several mechanisms and identifies none.

The fix

Two changes. Either alone is sufficient; both are kept because they fail independently.

  1. Logging from the handler is best effort, via _log_from_signal. It tries _log, and on failure falls back to os.write straight to the file descriptor, which takes no lock the interrupted frame could already hold.
  2. The death moves into a finally, so nothing above it can stop the process dying of its signal.

Verification

The regression test makes the reentrancy deterministic by raising from the handler's log call, rather than racing a print and hoping. Against current main it fails with:

a log call that raised inside the handler turned SIGTERM into returncode 0

which is the symptom as observed on CI. With the fix it passes, and the kernel is still deleted -- the logging is what failed, not the cleanup. Full tests/kaggle/ suite: 535 passed.

A correction to #9072

#9072 attributed this failure to a transient OSError out of release() and added a retry. That mechanism is real, its fix stands, and its test is unaffected. But it was not what CI was hitting, and I should not have presented it as the explanation while the symptom kept recurring.

A cancelled launcher exited 0 instead of dying of its signal, intermittently, and
only on loaded CI runners. The cause was in the handler's first line.

A signal handler runs on the main thread wherever that thread happened to be. If it
was inside a write to stdout, the interpreter refuses the second one:

  RuntimeError: reentrant call inside <_io.BufferedWriter name='<stdout>'>

That is what the handler's opening _log call did. The exception escaped the handler
before it could re-raise the signal, main()'s except BaseException caught it, and the
process exited on whatever code main computed. A cancelled job then reads as a
completed one.

It needs the signal to land inside a print, which is why it never reproduced locally
and why it took a contended runner to show it. The line that identified it is the
diagnostic added in 9079, which printed the launcher's own log on failure.

Two changes, either of which is sufficient, kept because they fail independently:
logging from the handler is now best effort, falling back to os.write, which goes
straight to the file descriptor and takes no lock the interrupted frame could hold;
and the death moves into a finally, so nothing above it can prevent the process
dying of its signal.

The regression test makes the reentrancy deterministic by raising from the handler's
log call rather than racing a print. Against the current main it fails with
returncode 0, which is the symptom as observed.

Worth recording: 9072 attributed this to a transient OSError from release(). That
mechanism is real and its fix stands, but it was not what CI was hitting.

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: d014979eaa

ℹ️ About Codex in GitHub

Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".

Comment thread .github/scripts/kaggle_t4_ci/launch.py Outdated

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

P1 Badge Avoid a blocking fallback write in the signal handler

When stdout is a pipe whose buffer is full—the same backpressure scenario that can leave the main thread interrupted inside its original write—this os.write blocks rather than raising, so neither the surrounding except nor _release_and_die's finally can run. A cancellation can therefore hang before release() and leave the Kaggle kernel billing until an external hard kill; the signal-safe path should skip the diagnostic or make the descriptor nonblocking.

Useful? React with 👍 / 👎.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Correct, and worse than I had it: the announcement is the FIRST thing the handler does, so a stalled write sits ahead of release() entirely. Raising was the only failure mode I covered, and blocking is not an exception, so no except and no finally saves it. The kernels then bill until something kills the launcher from outside, which is the one outcome this file exists to prevent. Your point about the two arriving together is the part I had missed: the backpressure that fills the pipe is also what leaves the main thread parked mid-write, so the reentrancy and the stall are the same runner condition.

Fixed in 24e4500. _log_from_signal now asks whether the descriptor is writable before touching it, and drops the line if not. POSIX reports a pipe writable only when at least PIPE_BUF bytes fit and these lines are far shorter, so a positive answer means the write completes; any error from select answers no. I took the skip rather than the nonblocking descriptor because O_NONBLOCK lives on the open file description, which dup shares, so setting it would change the main thread's writes too.

The new test reproduces it rather than simulating it: the launcher writes until the pipe is full and the test never reads a byte, so the main thread is asleep inside a write holding the buffer lock when SIGTERM lands. Remove the guard and it hangs the whole 120s death budget with the kernel never deleted. 536 kaggle tests pass.

pre-commit-ci Bot and others added 2 commits August 17, 2026 10:32
Raising is not the only way a log line can stop the handler. stdout in CI is a pipe,
and if the collector stops draining it a write parks in the kernel instead of failing,
so no except and no finally runs. The announcement is the FIRST thing the handler does,
before release(), so the kernels would keep billing until something killed the launcher
from outside: the one outcome this file exists to prevent. That backpressure is also
what leaves the main thread interrupted mid-write, so it arrives with the reentrancy the
previous commit fixed rather than instead of it.

_log_from_signal now asks whether the descriptor is writable before touching it and
drops the line if not. POSIX reports a pipe writable only when PIPE_BUF bytes fit, and
these lines are far shorter, so a positive answer means the write completes. Any error
from select answers no.

The new test reproduces it rather than simulating it: the launcher writes until the pipe
is full and the test never reads a byte, so the main thread is asleep inside a write,
holding the buffer lock, when SIGTERM lands. Without the guard it hangs the full 120s
budget and the kernel is never deleted. 536 kaggle tests pass.
@danielhanchen

Copy link
Copy Markdown
Member Author

@codex review

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: 24e4500c9e

ℹ️ About Codex in GitHub

Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".

# that returns normally leaves the process exiting on whatever code main()
# computes, and a cancelled job then reads as a completed one.
try:
_log_from_signal(f"received signal {signum}; deleting kernels before exiting")

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

P1 Badge Make cleanup logging nonblocking too

When stdout is full and a deletion raises or returns a nonzero status, this call enters release(), whose delete_kernel() path still reports failures through the blocking _log; the handler therefore stalls before reaching its retry or finally, so the process does not die and the kernel can remain billable. The full-pipe regression test misses this because its fake deletion succeeds without logging. Fresh evidence in this revision is that only the handler's direct diagnostics use _log_from_signal, while logging transitively reached through release() remains buffered and blocking.

Useful? React with 👍 / 👎.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Correct on both halves, including the one about my test. The fake deletion succeeded silently, so nothing in it ever reached a _log the handler did not call itself.

Fixed in 6c4891b at the choke point rather than per call site: _log now drops instead of stalling whenever a module flag the handler sets on entry is true, so every line printed from that point on is covered however it was reached, release() and delete_kernel() included. The ordinary path is unchanged, which is every line this script prints before something kills it.

The test now logs on the way through the deletion, which is what a refused delete actually does. Remove the _log guard and it hangs the full 120s budget with the kernel never deleted, and the previous commit's fallback guard does not save it, which is your point exactly. 536 kaggle tests pass.

…overed

The previous commit guarded only the lines the handler prints itself. release() logs
through the ordinary path -- delete_kernel() reports a refused delete that way -- so on a
full stdout pipe the handler still stalled, just one frame deeper, before its retry and
before the finally that re-raises the signal. Same outcome: a kernel billing until
something kills the launcher from outside.

The check now sits in _log, gated on a flag the handler sets on entry, so every line
printed from that point on drops instead of stalling however it was reached. Nothing
changes on the ordinary path, which is every line this script prints before something
kills it.

The regression test missed this because its fake deletion succeeded silently. It now logs
on the way through, which is what a real refused delete does. Remove the guard and the
test hangs the full 120s budget with the kernel never deleted; the previous commit's
fallback guard does not save it. 536 kaggle tests pass.
@danielhanchen

Copy link
Copy Markdown
Member Author

@codex review

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: 0c3ad5ef33

ℹ️ About Codex in GitHub

Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".

Comment thread .github/scripts/kaggle_t4_ci/launch.py Outdated
Comment on lines 233 to 235
if _IN_SIGNAL_HANDLER and not _writable(_STDOUT_FD):
return
print(f"[launch] {msg}", flush = True)

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

P1 Badge Suppress reentrant failures from cleanup logging

When a signal interrupts a write while sys.stdout holds its buffer lock but fd 1 remains writable, this check passes and print() raises RuntimeError: reentrant call; unlike handler-owned calls wrapped by _log_from_signal, the ordinary _log calls reached inside delete_kernel() propagate through release(). If Kaggle rejects the first two delete calls but would accept its configured third retry, each of the handler's two release() attempts instead aborts after one log failure, so the third deletion is never attempted and the kernel may remain billable. Fresh evidence after the prior fix is that the new _log guard handles backpressure but still does not swallow the reentrancy failure on the transitive cleanup path.

Useful? React with 👍 / 👎.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Also correct, and this is the sharper of the two: dropping a line and swallowing a failure are different guarantees, and I had only added the first. With the descriptor writable but the buffer lock held, print() raises, and on the transitive path that exception leaves delete_kernel(), leaves release(), and takes the remaining retries with it. Your example is the case that costs money: Kaggle refuses twice and would accept the third, and the third never happens.

Fixed in the same commit. _write_line now routes through the signal-safe path whenever the handler is running, so a line reached from anywhere is dropped on a full pipe and swallowed on a reentrant one, and neither can leave the retry loop.

The test refuses the first two deletes, accepts the third, and makes every write raise while the handler runs, so all three attempts only happen if the failure is contained where it occurs. Reverting the routing reproduces your description exactly: release() failed under signal 15: RuntimeError: reentrant call inside <_io.BufferedWriter ...> for both attempts, with the kernel left in the registry.

Comment thread .github/scripts/kaggle_t4_ci/launch.py Outdated
Comment on lines +233 to +234
if _IN_SIGNAL_HANDLER and not _writable(_STDOUT_FD):
return

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

P1 Badge Route the unreleased-kernel warning through the safe logger

When stdout is already full as the handler starts and a deletion ultimately returns false, this guard drops the _log calls but release() subsequently emits its leaked warning with the direct blocking print() at lines 1143-1149. The handler then stalls before its finally can restore and re-raise the signal, leaving the failed kernel running; the new full-pipe test does not exercise this branch because its fake deletion succeeds, so leaked stays empty. Fresh evidence after the prior cleanup-logging fix is this remaining output path that bypasses _log entirely.

Useful? React with 👍 / 👎.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

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

Correct. That print() is on exactly the branch where a kernel is still billing, so it is the worst place left to stall, and your note that the full-pipe test could not reach it is right: its deletion succeeds, so leaked stays empty.

Fixed in 65064c3, with one wrinkle worth flagging. Routing it through _log would emit [launch] ::warning ..., and GitHub matches an annotation from the START of the line, so that would have silently demoted the one message that tells a human a kernel is still running. The split is now between what a line IS and how it is written: _write_line carries the protections, _log adds the prefix on top, and this warning goes through _write_line directly.

New test drives a launcher whose deletes never succeed with a full pipe, and it must still die of SIGTERM. A second test reads the warning back out of a real main() run and asserts it still starts with ::warning; my first version of that called the writer directly and passed on the mutation it was meant to catch, so it now goes through release().

danielhanchen and others added 2 commits August 17, 2026 11:37
…handler's own

Two paths still bypassed them. release() warns about a kernel it could not delete with a
raw print(), which is emitted on exactly the branch where a kernel is still billing, so a
full pipe stalls the handler there before the finally can re-raise the signal. And _log
dropped a line when the descriptor was unwritable but still raised when the buffer lock
was held, and that reentrancy propagates out of delete_kernel() and out of release(), so
a kernel Kaggle would have accepted on its third retry is never asked a third time.

So the split is now between what a line IS and how it is written. _write_line carries the
protections, _log adds the [launch] prefix on top, and the leaked-kernel warning goes
through _write_line directly: through _log it would arrive as '[launch] ::warning ...',
and GitHub matches an annotation from the start of the line, which would silently demote
the one message that says a kernel is still billing.

Three tests, each failing on the unfixed shape: a delete that is refused twice and
accepted on the third still makes all three attempts while every write raises; a launcher
whose deletes never succeed still dies of its signal with a full pipe; and the warning is
read back out of a real main() run rather than from the source. The first version of that
last one called the writer directly and passed on the mutation it was meant to catch.

536 kaggle tests pass.
@danielhanchen

Copy link
Copy Markdown
Member Author

@codex review

@chatgpt-codex-connector

Copy link
Copy Markdown

@danielhanchen
danielhanchen merged commit 68815aa into main Aug 17, 2026
14 of 15 checks passed
@danielhanchen
danielhanchen deleted the fix-signal-handler-reentrancy branch August 17, 2026 12:06
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant