Skip to content

fix: log worker crashes at warn level instead of debug - #2602

Open
luminalpark wants to merge 1 commit into
php:mainfrom
luminalpark:fix/log-worker-crashes-above-debug
Open

fix: log worker crashes at warn level instead of debug#2602
luminalpark wants to merge 1 commit into
php:mainfrom
luminalpark:fix/log-worker-crashes-above-debug

Conversation

@luminalpark

Copy link
Copy Markdown

A worker script that dies after boot (non-zero exit status) currently logs the same debug-level "restarting" message as a clean FRANKENPHP_LOOP_MAX recycle — same level, same message text. At the default log level a crash is therefore invisible to operators:

  • the in-flight request surfaces as an empty 500 (0 bytes after normal processing time),
  • the application never gets to log anything — the script died mid-request,
  • and exit_status, the one datum needed to triage the death, is only obtainable by running the whole server at debug level.
    We hit this in production (Shopware on FrankenPHP 1.12.4, worker mode): frankenphp_worker_crashes was steadily incrementing at ~0.03% of requests, each crash converting one user request into an empty 500, with zero trace in any log — app log, stderr, or FrankenPHP's own output. It took us three debugging sessions to find the Prometheus counter, and we still could not see the exit statuses.

This is a regression

Up to v1.2.x the crash path was clearly distinguished (worker.go @ v1.2.5):

if fc.exitStatus == 0 {
    if c := l.Check(zapcore.InfoLevel, "restarting"); c != nil { ... }
} else {
    if c := l.Check(zapcore.ErrorLevel, "unexpected termination, restarting"); c != nil {
        c.Write(zap.String("worker", absFileName), zap.Int("exit_status", int(fc.exitStatus)))
    }
}

That error-level line is, for instance, how the reporter of #774 noticed their problem at all. Somewhere in the worker-thread refactoring both paths converged on debug-level "restarting".

What this PR does

  • The crash branch of tearDownWorkerScript (non-zero exit after boot, StopReasonCrash) now logs at warn with the historical, distinct message "unexpected termination, restarting", keeping the worker / thread / exit_status attributes. Warn matches the neighboring worker-failure logs in the same function; happy to bump it to error (the 1.2.x level) if preferred.
  • Clean restarts (exit 0, LOOP_MAX recycling) stay at debug — they are frequent and healthy, raising them would be noise.
  • Fixes a mismatched guard in the watcher-enabled boot-failure path: Enabled() checked LevelError while LogAttrs wrote LevelWarn.
  • Adds testdata/crashing-worker.php (boots fine, exit(1) on its second request — the exact scenario of the code comment) and a test asserting the warn-level line with exit_status=1 is emitted.
    No behavior change beyond logging.
    Fixes Worker crashes are logged at debug level only: invisible in production, in-flight request becomes an empty 500 #2601

A worker script that dies after boot (non-zero exit status) currently logs
the same debug-level "restarting" message as a clean FRANKENPHP_LOOP_MAX
recycle. At the default log level a crash is therefore invisible: the
in-flight request surfaces as an empty 500, the application never gets to
log anything (the script died mid-request), and the exit status - the one
datum needed to triage the death - is only available by running the whole
server at debug level.

Up to v1.2.x these terminations were logged at error level with the
distinct message "unexpected termination, restarting" (see e.g. php#774,
where that log line is how the reporter noticed the problem at all). This
restores that message at warn level, matching the other worker-failure
logs in tearDownWorkerScript, and keeps clean restarts at debug.

Also aligns the guard of the watcher-enabled boot-failure log with the
level it actually logs at (Enabled checked Error, LogAttrs wrote Warn).

@dunglas dunglas left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

LGTM, but I wonder why we changed that behavior in the first time.

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.

Worker crashes are logged at debug level only: invisible in production, in-flight request becomes an empty 500

2 participants