Skip to content

Commit dd2d832

Browse files
committed
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).
1 parent a765b08 commit dd2d832

3 files changed

Lines changed: 32 additions & 3 deletions

File tree

testdata/crashing-worker.php

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
<?php
2+
3+
// Boots successfully, then terminates with a non-zero exit status while
4+
// handling its second request, simulating a worker crash after boot.
5+
$requests = 0;
6+
$handler = static function () use (&$requests) {
7+
if (++$requests >= 2) {
8+
exit(1);
9+
}
10+
11+
echo 'ok';
12+
};
13+
14+
while (frankenphp_handle_request($handler)) {
15+
}

threadworker.go

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -160,8 +160,10 @@ func tearDownWorkerScript(handler *workerThread, exitStatus int) {
160160

161161
if !handler.isBootingScript {
162162
// fatal error (could be due to exit(1), timeouts, etc.)
163-
if globalLogger.Enabled(globalCtx, slog.LevelDebug) {
164-
globalLogger.LogAttrs(globalCtx, slog.LevelDebug, "restarting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("exit_status", exitStatus))
163+
// unlike a clean restart, this took down any in-flight request, so
164+
// surface it above debug level, with the exit status needed to triage it
165+
if globalLogger.Enabled(globalCtx, slog.LevelWarn) {
166+
globalLogger.LogAttrs(globalCtx, slog.LevelWarn, "unexpected termination, restarting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("exit_status", exitStatus))
165167
}
166168

167169
return
@@ -175,7 +177,7 @@ func tearDownWorkerScript(handler *workerThread, exitStatus int) {
175177

176178
if watcherIsEnabled {
177179
// worker script has probably failed due to script changes while watcher is enabled
178-
if globalLogger.Enabled(globalCtx, slog.LevelError) {
180+
if globalLogger.Enabled(globalCtx, slog.LevelWarn) {
179181
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))
180182
}
181183
} else {

worker_test.go

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -112,6 +112,18 @@ func TestWorkerGetOpt(t *testing.T) {
112112
assert.NotRegexp(t, buf.String(), "exit_status=[1-9]")
113113
}
114114

115+
func TestWorkerCrashIsLoggedAboveDebugLevel(t *testing.T) {
116+
logger, buf := newTestLogger(t)
117+
118+
runTest(t, func(handler func(http.ResponseWriter, *http.Request), _ *httptest.Server, i int) {
119+
req := httptest.NewRequest("GET", "http://example.com/crashing-worker.php", nil)
120+
w := httptest.NewRecorder()
121+
handler(w, req)
122+
}, &testOptions{logger: logger, workerScript: "crashing-worker.php", nbWorkers: 1, nbParallelRequests: 4})
123+
124+
assert.Regexp(t, `level=WARN msg="unexpected termination, restarting" worker=\S+ thread=\d+ exit_status=1`, buf.String())
125+
}
126+
115127
func ExampleServeHTTP_workers() {
116128
if err := frankenphp.Init(
117129
frankenphp.WithWorkers("worker1", "worker1.php", 4,

0 commit comments

Comments
 (0)