Skip to content

chore: add more logs for the worker #1587

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
dunglas merged 1 commit into from
May 19, 2025
Merged

chore: add more logs for the worker #1587

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 0 additions & 1 deletion threadregular.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,6 @@ func (handler *regularThread) beforeScriptExecution() string {
panic("unexpected state: " + handler.state.name())
}

// return true if the worker should continue to run
Copy link
Copy Markdown
Member Author

@dunglas dunglas May 19, 2025

Choose a reason for hiding this comment

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

This comment seems unaccurate/outdated

func (handler *regularThread) afterScriptExecution(int) {
handler.afterRequest()
}
Expand Down
21 changes: 12 additions & 9 deletions threadworker.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -119,27 +119,30 @@ func tearDownWorkerScript(handler *workerThread, exitStatus int) {
// TODO: make the max restart configurable
metrics.StopWorker(worker.name, StopReasonRestart)
handler.backoff.recordSuccess()
logger.LogAttrs(ctx, slog.LevelDebug, "restarting", slog.String("worker", worker.name))
logger.LogAttrs(ctx, slog.LevelDebug, "restarting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("exit_status", exitStatus))

return
}

// worker has thrown a fatal error or has not reached frankenphp_handle_request
metrics.StopWorker(worker.name, StopReasonCrash)

if !handler.isBootingScript {
// fatal error (could be due to timeouts, etc.)
// fatal error (could be due to exit(1), timeouts, etc.)
logger.LogAttrs(ctx, slog.LevelDebug, "restarting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("exit_status", exitStatus))

return
}

logger.LogAttrs(ctx, slog.LevelError, "worker script has not reached frankenphp_handle_request", slog.String("worker", worker.name))
logger.LogAttrs(ctx, slog.LevelError, "worker script has not reached frankenphp_handle_request()", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex))

// panic after exponential backoff if the worker has never reached frankenphp_handle_request
if handler.backoff.recordFailure() {
if !watcherIsEnabled && !handler.state.is(stateReady) {
logger.LogAttrs(ctx, slog.LevelError, "too many consecutive worker failures", slog.String("worker", worker.name), slog.Int("failures", handler.backoff.failureCount))
logger.LogAttrs(ctx, slog.LevelError, "too many consecutive worker failures", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("failures", handler.backoff.failureCount))
panic("too many consecutive worker failures")
}
logger.LogAttrs(ctx, slog.LevelWarn, "many consecutive worker failures", slog.String("worker", worker.name), slog.Int("failures", handler.backoff.failureCount))
logger.LogAttrs(ctx, slog.LevelWarn, "many consecutive worker failures", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex), slog.Int("failures", handler.backoff.failureCount))
}
}

Expand All @@ -149,7 +152,7 @@ func (handler *workerThread) waitForWorkerRequest() bool {
handler.thread.Unpin()

ctx := context.Background()
logger.LogAttrs(ctx, slog.LevelDebug, "waiting for request", slog.String("worker", handler.worker.name))
logger.LogAttrs(ctx, slog.LevelDebug, "waiting for request", slog.String("worker", handler.worker.name), slog.Int("thread", handler.thread.threadIndex))

// Clear the first dummy request created to initialize the worker
if handler.isBootingScript {
Expand All @@ -172,7 +175,7 @@ func (handler *workerThread) waitForWorkerRequest() bool {
var fc *frankenPHPContext
select {
case <-handler.thread.drainChan:
logger.LogAttrs(ctx, slog.LevelDebug, "shutting down", slog.String("worker", handler.worker.name))
logger.LogAttrs(ctx, slog.LevelDebug, "shutting down", slog.String("worker", handler.worker.name), slog.Int("thread", handler.thread.threadIndex))

// flush the opcache when restarting due to watcher or admin api
// note: this is done right before frankenphp_handle_request() returns 'false'
Expand All @@ -188,11 +191,11 @@ func (handler *workerThread) waitForWorkerRequest() bool {
handler.workerContext = fc
handler.state.markAsWaiting(false)

logger.LogAttrs(ctx, slog.LevelDebug, "request handling started", slog.String("worker", handler.worker.name), slog.String("url", fc.request.RequestURI))
logger.LogAttrs(ctx, slog.LevelDebug, "request handling started", slog.String("worker", handler.worker.name), slog.Int("thread", handler.thread.threadIndex), slog.String("url", fc.request.RequestURI))

if err := updateServerContext(handler.thread, fc, true); err != nil {
// Unexpected error or invalid request
logger.LogAttrs(ctx, slog.LevelDebug, "unexpected error", slog.String("worker", handler.worker.name), slog.String("url", fc.request.RequestURI), slog.Any("error", err))
logger.LogAttrs(ctx, slog.LevelDebug, "unexpected error", slog.String("worker", handler.worker.name), slog.Int("thread", handler.thread.threadIndex), slog.String("url", fc.request.RequestURI), slog.Any("error", err))
fc.rejectBadRequest(err.Error())
handler.workerContext = nil

Expand Down