From dd2d8324b2107bc63d7d6e2f91c8d09d8d5709fc Mon Sep 17 00:00:00 2001 From: Carlo Cecco Date: Wed, 12 Aug 2026 16:21:46 +0200 Subject: [PATCH] fix: log worker crashes at warn level instead of debug 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. #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). --- testdata/crashing-worker.php | 15 +++++++++++++++ threadworker.go | 8 +++++--- worker_test.go | 12 ++++++++++++ 3 files changed, 32 insertions(+), 3 deletions(-) create mode 100644 testdata/crashing-worker.php diff --git a/testdata/crashing-worker.php b/testdata/crashing-worker.php new file mode 100644 index 0000000000..a1243a78cf --- /dev/null +++ b/testdata/crashing-worker.php @@ -0,0 +1,15 @@ += 2) { + exit(1); + } + + echo 'ok'; +}; + +while (frankenphp_handle_request($handler)) { +} diff --git a/threadworker.go b/threadworker.go index 843e1dd331..1b08b91591 100644 --- a/threadworker.go +++ b/threadworker.go @@ -160,8 +160,10 @@ func tearDownWorkerScript(handler *workerThread, exitStatus int) { if !handler.isBootingScript { // fatal error (could be due to exit(1), timeouts, etc.) - if globalLogger.Enabled(globalCtx, slog.LevelDebug) { - globalLogger.LogAttrs(globalCtx, slog.LevelDebug, "restarting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("exit_status", exitStatus)) + // unlike a clean restart, this took down any in-flight request, so + // surface it above debug level, with the exit status needed to triage it + if globalLogger.Enabled(globalCtx, slog.LevelWarn) { + globalLogger.LogAttrs(globalCtx, slog.LevelWarn, "unexpected termination, restarting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("exit_status", exitStatus)) } return @@ -175,7 +177,7 @@ func tearDownWorkerScript(handler *workerThread, exitStatus int) { if watcherIsEnabled { // worker script has probably failed due to script changes while watcher is enabled - if globalLogger.Enabled(globalCtx, slog.LevelError) { + if globalLogger.Enabled(globalCtx, slog.LevelWarn) { globalLogger.LogAttrs(globalCtx, slog.LevelWarn, "(watcher enabled) worker script has not reached frankenphp_handle_request()", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex)) } } else { diff --git a/worker_test.go b/worker_test.go index 3fd2d63f94..dc423294f6 100644 --- a/worker_test.go +++ b/worker_test.go @@ -112,6 +112,18 @@ func TestWorkerGetOpt(t *testing.T) { assert.NotRegexp(t, buf.String(), "exit_status=[1-9]") } +func TestWorkerCrashIsLoggedAboveDebugLevel(t *testing.T) { + logger, buf := newTestLogger(t) + + runTest(t, func(handler func(http.ResponseWriter, *http.Request), _ *httptest.Server, i int) { + req := httptest.NewRequest("GET", "http://example.com/crashing-worker.php", nil) + w := httptest.NewRecorder() + handler(w, req) + }, &testOptions{logger: logger, workerScript: "crashing-worker.php", nbWorkers: 1, nbParallelRequests: 4}) + + assert.Regexp(t, `level=WARN msg="unexpected termination, restarting" worker=\S+ thread=\d+ exit_status=1`, buf.String()) +} + func ExampleServeHTTP_workers() { if err := frankenphp.Init( frankenphp.WithWorkers("worker1", "worker1.php", 4,