diff --git a/frankenphp.go b/frankenphp.go index 258d7608..2d60ae17 100644 --- a/frankenphp.go +++ b/frankenphp.go @@ -30,6 +30,7 @@ package frankenphp import "C" import ( "bytes" + "context" "errors" "fmt" "io" @@ -291,9 +292,10 @@ func Init(options ...Option) error { initAutoScaling(mainThread) - logger.LogAttrs(nil, slog.LevelInfo, "FrankenPHP started 🐘", slog.String("php_version", Version().Version), slog.Int("num_threads", mainThread.numThreads), slog.Int("max_threads", mainThread.maxThreads)) + ctx := context.Background() + logger.LogAttrs(ctx, slog.LevelInfo, "FrankenPHP started 🐘", slog.String("php_version", Version().Version), slog.Int("num_threads", mainThread.numThreads), slog.Int("max_threads", mainThread.maxThreads)) if EmbeddedAppPath != "" { - logger.LogAttrs(nil, slog.LevelInfo, "embedded PHP app 📦", slog.String("path", EmbeddedAppPath)) + logger.LogAttrs(ctx, slog.LevelInfo, "embedded PHP app 📦", slog.String("path", EmbeddedAppPath)) } return nil @@ -428,7 +430,7 @@ func go_ub_write(threadIndex C.uintptr_t, cBuf *C.char, length C.int) (C.size_t, i, e := writer.Write(unsafe.Slice((*byte)(unsafe.Pointer(cBuf)), length)) if e != nil { - fc.logger.LogAttrs(nil, slog.LevelError, "write error", slog.Any("error", e)) + fc.logger.LogAttrs(context.Background(), slog.LevelError, "write error", slog.Any("error", e)) } if fc.responseWriter == nil { @@ -447,7 +449,7 @@ func go_apache_request_headers(threadIndex C.uintptr_t) (*C.go_string, C.size_t) if fc.responseWriter == nil { // worker mode, not handling a request - logger.LogAttrs(nil, slog.LevelDebug, "apache_request_headers() called in non-HTTP context", slog.String("worker", fc.scriptFilename)) + logger.LogAttrs(context.Background(), slog.LevelDebug, "apache_request_headers() called in non-HTTP context", slog.String("worker", fc.scriptFilename)) return nil, 0 } @@ -478,7 +480,7 @@ func go_apache_request_headers(threadIndex C.uintptr_t) (*C.go_string, C.size_t) func addHeader(fc *frankenPHPContext, cString *C.char, length C.int) { parts := strings.SplitN(C.GoStringN(cString, length), ": ", 2) if len(parts) != 2 { - fc.logger.LogAttrs(nil, slog.LevelDebug, "invalid header", slog.String("header", parts[0])) + fc.logger.LogAttrs(context.Background(), slog.LevelDebug, "invalid header", slog.String("header", parts[0])) return } @@ -532,7 +534,7 @@ func go_sapi_flush(threadIndex C.uintptr_t) bool { } if err := http.NewResponseController(fc.responseWriter).Flush(); err != nil { - logger.LogAttrs(nil, slog.LevelError, "the current responseWriter is not a flusher", slog.Any("error", err)) + logger.LogAttrs(context.Background(), slog.LevelError, "the current responseWriter is not a flusher", slog.Any("error", err)) } return false @@ -585,15 +587,15 @@ func go_log(message *C.char, level C.int) { switch le { case emerg, alert, crit, err: - logger.LogAttrs(nil, slog.LevelError, m, slog.String("syslog_level", syslogLevel(level).String())) + logger.LogAttrs(context.Background(), slog.LevelError, m, slog.String("syslog_level", syslogLevel(level).String())) case warning: - logger.LogAttrs(nil, slog.LevelWarn, m, slog.String("syslog_level", syslogLevel(level).String())) + logger.LogAttrs(context.Background(), slog.LevelWarn, m, slog.String("syslog_level", syslogLevel(level).String())) case debug: - logger.LogAttrs(nil, slog.LevelDebug, m, slog.String("syslog_level", syslogLevel(level).String())) + logger.LogAttrs(context.Background(), slog.LevelDebug, m, slog.String("syslog_level", syslogLevel(level).String())) default: - logger.LogAttrs(nil, slog.LevelInfo, m, slog.String("syslog_level", syslogLevel(level).String())) + logger.LogAttrs(context.Background(), slog.LevelInfo, m, slog.String("syslog_level", syslogLevel(level).String())) } } diff --git a/internal/testserver/main.go b/internal/testserver/main.go index d1c7caee..3e4af37b 100644 --- a/internal/testserver/main.go +++ b/internal/testserver/main.go @@ -1,6 +1,7 @@ package main import ( + "context" "log/slog" "net/http" "os" @@ -31,6 +32,6 @@ func main() { port = "8080" } - logger.LogAttrs(nil, slog.LevelError, "server error", slog.Any("error", http.ListenAndServe(":"+port, nil))) + logger.LogAttrs(context.Background(), slog.LevelError, "server error", slog.Any("error", http.ListenAndServe(":"+port, nil))) os.Exit(1) } diff --git a/internal/watcher/watch_pattern.go b/internal/watcher/watch_pattern.go index 58a4d609..dfd60356 100644 --- a/internal/watcher/watch_pattern.go +++ b/internal/watcher/watch_pattern.go @@ -3,6 +3,7 @@ package watcher import ( + "context" "log/slog" "path/filepath" "strings" @@ -82,7 +83,7 @@ func isValidEventType(eventType int) bool { // 0:dir,1:file,2:hard_link,3:sym_link,4:watcher,5:other, func isValidPathType(pathType int, fileName string) bool { if pathType == 4 { - logger.LogAttrs(nil, slog.LevelDebug, "special edant/watcher event", slog.String("fileName", fileName)) + logger.LogAttrs(context.Background(), slog.LevelDebug, "special edant/watcher event", slog.String("fileName", fileName)) } return pathType <= 2 } @@ -165,7 +166,7 @@ func matchPattern(pattern string, fileName string) bool { } patternMatches, err := filepath.Match(pattern, fileName) if err != nil { - logger.LogAttrs(nil, slog.LevelError, "failed to match filename", slog.String("file", fileName), slog.Any("error", err)) + logger.LogAttrs(context.Background(), slog.LevelError, "failed to match filename", slog.String("file", fileName), slog.Any("error", err)) return false } diff --git a/internal/watcher/watcher.go b/internal/watcher/watcher.go index f716cd9c..3aa82587 100644 --- a/internal/watcher/watcher.go +++ b/internal/watcher/watcher.go @@ -8,6 +8,7 @@ package watcher // #include "watcher.h" import "C" import ( + "context" "errors" "log/slog" "runtime/cgo" @@ -79,13 +80,15 @@ func DrainWatcher() { // TODO: how to test this? func retryWatching(watchPattern *watchPattern) { + ctx := context.Background() + failureMu.Lock() defer failureMu.Unlock() if watchPattern.failureCount >= maxFailureCount { - logger.LogAttrs(nil, slog.LevelWarn, "giving up watching", slog.String("dir", watchPattern.dir)) + logger.LogAttrs(ctx, slog.LevelWarn, "giving up watching", slog.String("dir", watchPattern.dir)) return } - logger.LogAttrs(nil, slog.LevelInfo, "watcher was closed prematurely, retrying...", slog.String("dir", watchPattern.dir)) + logger.LogAttrs(ctx, slog.LevelInfo, "watcher was closed prematurely, retrying...", slog.String("dir", watchPattern.dir)) watchPattern.failureCount++ session, err := startSession(watchPattern) @@ -132,15 +135,18 @@ func (w *watcher) stopWatching() { } func startSession(w *watchPattern) (C.uintptr_t, error) { + ctx := context.Background() + handle := cgo.NewHandle(w) cDir := C.CString(w.dir) defer C.free(unsafe.Pointer(cDir)) watchSession := C.start_new_watcher(cDir, C.uintptr_t(handle)) if watchSession != 0 { - logger.LogAttrs(nil, slog.LevelDebug, "watching", slog.String("dir", w.dir), slog.Any("patterns", w.patterns)) + logger.LogAttrs(ctx, slog.LevelDebug, "watching", slog.String("dir", w.dir), slog.Any("patterns", w.patterns)) + return watchSession, nil } - logger.LogAttrs(nil, slog.LevelError, "couldn't start watching", slog.String("dir", w.dir)) + logger.LogAttrs(ctx, slog.LevelError, "couldn't start watching", slog.String("dir", w.dir)) return watchSession, ErrUnableToStartWatching } @@ -190,7 +196,7 @@ func listenForFileEvents(triggerWatcher chan string, stopWatcher chan struct{}) timer.Reset(debounceDuration) case <-timer.C: timer.Stop() - logger.LogAttrs(nil, slog.LevelInfo, "filesystem change detected", slog.String("file", lastChangedFile)) + logger.LogAttrs(context.Background(), slog.LevelInfo, "filesystem change detected", slog.String("file", lastChangedFile)) scheduleReload() } } diff --git a/phpmainthread.go b/phpmainthread.go index d8613e16..3154bb77 100644 --- a/phpmainthread.go +++ b/phpmainthread.go @@ -8,6 +8,7 @@ package frankenphp // #include "frankenphp.h" import "C" import ( + "context" "log/slog" "strings" "sync" @@ -170,7 +171,7 @@ func (mainThread *phpMainThread) setAutomaticMaxThreads() { maxAllowedThreads := totalSysMemory / uint64(perThreadMemoryLimit) mainThread.maxThreads = int(maxAllowedThreads) - logger.LogAttrs(nil, slog.LevelDebug, "Automatic thread limit", slog.Int("perThreadMemoryLimitMB", int(perThreadMemoryLimit/1024/1024)), slog.Int("maxThreads", mainThread.maxThreads)) + logger.LogAttrs(context.Background(), slog.LevelDebug, "Automatic thread limit", slog.Int("perThreadMemoryLimitMB", int(perThreadMemoryLimit/1024/1024)), slog.Int("maxThreads", mainThread.maxThreads)) } //export go_frankenphp_shutdown_main_thread diff --git a/phpthread.go b/phpthread.go index d28fb153..49f673b5 100644 --- a/phpthread.go +++ b/phpthread.go @@ -4,6 +4,7 @@ package frankenphp // #include "frankenphp.h" import "C" import ( + "context" "log/slog" "runtime" "sync" @@ -55,7 +56,7 @@ func (thread *phpThread) boot() { // start the actual posix thread - TODO: try this with go threads instead if !C.frankenphp_new_php_thread(C.uintptr_t(thread.threadIndex)) { - logger.LogAttrs(nil, slog.LevelError, "unable to create thread", slog.Int("threadIndex", thread.threadIndex)) + logger.LogAttrs(context.Background(), slog.LevelError, "unable to create thread", slog.Int("threadIndex", thread.threadIndex)) panic("unable to create thread") } diff --git a/scaling.go b/scaling.go index b9b8370e..7af2349d 100644 --- a/scaling.go +++ b/scaling.go @@ -4,6 +4,7 @@ package frankenphp //#include import "C" import ( + "context" "errors" "log/slog" "sync" @@ -53,7 +54,7 @@ func initAutoScaling(mainThread *phpMainThread) { func drainAutoScaling() { scalingMu.Lock() - logger.LogAttrs(nil, slog.LevelDebug, "shutting down autoscaling", slog.Int("autoScaledThreads", len(autoScaledThreads))) + logger.LogAttrs(context.Background(), slog.LevelDebug, "shutting down autoscaling", slog.Int("autoScaledThreads", len(autoScaledThreads))) scalingMu.Unlock() } @@ -93,7 +94,7 @@ func scaleWorkerThread(worker *worker) { thread, err := addWorkerThread(worker) if err != nil { - logger.LogAttrs(nil, slog.LevelWarn, "could not increase max_threads, consider raising this limit", slog.String("worker", worker.name), slog.Any("error", err)) + logger.LogAttrs(context.Background(), slog.LevelWarn, "could not increase max_threads, consider raising this limit", slog.String("worker", worker.name), slog.Any("error", err)) return } @@ -116,7 +117,7 @@ func scaleRegularThread() { thread, err := addRegularThread() if err != nil { - logger.LogAttrs(nil, slog.LevelWarn, "could not increase max_threads, consider raising this limit", slog.Any("error", err)) + logger.LogAttrs(context.Background(), slog.LevelWarn, "could not increase max_threads, consider raising this limit", slog.Any("error", err)) return } @@ -196,7 +197,7 @@ func deactivateThreads() { // convert threads to inactive if they have been idle for too long if thread.state.is(stateReady) && waitTime > maxThreadIdleTime.Milliseconds() { - logger.LogAttrs(nil, slog.LevelDebug, "auto-converting thread to inactive", slog.Int("threadIndex", thread.threadIndex)) + logger.LogAttrs(context.Background(), slog.LevelDebug, "auto-converting thread to inactive", slog.Int("threadIndex", thread.threadIndex)) convertToInactiveThread(thread) stoppedThreadCount++ autoScaledThreads = append(autoScaledThreads[:i], autoScaledThreads[i+1:]...) diff --git a/threadworker.go b/threadworker.go index 3b0c47cb..f429fc88 100644 --- a/threadworker.go +++ b/threadworker.go @@ -3,6 +3,7 @@ package frankenphp // #include "frankenphp.h" import "C" import ( + "context" "log/slog" "path/filepath" "time" @@ -93,13 +94,15 @@ func setupWorkerScript(handler *workerThread, worker *worker) { handler.dummyContext = fc handler.isBootingScript = true clearSandboxedEnv(handler.thread) - logger.LogAttrs(nil, slog.LevelDebug, "starting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex)) + logger.LogAttrs(context.Background(), slog.LevelDebug, "starting", slog.String("worker", worker.name), slog.Int("thread", handler.thread.threadIndex)) } func tearDownWorkerScript(handler *workerThread, exitStatus int) { worker := handler.worker handler.dummyContext = nil + ctx := context.Background() + // if the worker request is not nil, the script might have crashed // make sure to close the worker request context if handler.workerContext != nil { @@ -112,7 +115,7 @@ func tearDownWorkerScript(handler *workerThread, exitStatus int) { // TODO: make the max restart configurable metrics.StopWorker(worker.name, StopReasonRestart) handler.backoff.recordSuccess() - logger.LogAttrs(nil, slog.LevelDebug, "restarting", slog.String("worker", worker.name)) + logger.LogAttrs(ctx, slog.LevelDebug, "restarting", slog.String("worker", worker.name)) return } @@ -124,15 +127,15 @@ func tearDownWorkerScript(handler *workerThread, exitStatus int) { return } - logger.LogAttrs(nil, 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)) // 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(nil, 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("failures", handler.backoff.failureCount)) panic("too many consecutive worker failures") } - logger.LogAttrs(nil, 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("failures", handler.backoff.failureCount)) } } @@ -141,7 +144,8 @@ func (handler *workerThread) waitForWorkerRequest() bool { // unpin any memory left over from previous requests handler.thread.Unpin() - logger.LogAttrs(nil, slog.LevelDebug, "waiting for request", slog.String("worker", handler.worker.name)) + ctx := context.Background() + logger.LogAttrs(ctx, slog.LevelDebug, "waiting for request", slog.String("worker", handler.worker.name)) // Clear the first dummy request created to initialize the worker if handler.isBootingScript { @@ -164,7 +168,7 @@ func (handler *workerThread) waitForWorkerRequest() bool { var fc *frankenPHPContext select { case <-handler.thread.drainChan: - logger.LogAttrs(nil, slog.LevelDebug, "shutting down", slog.String("worker", handler.worker.name)) + logger.LogAttrs(ctx, slog.LevelDebug, "shutting down", slog.String("worker", handler.worker.name)) // flush the opcache when restarting due to watcher or admin api // note: this is done right before frankenphp_handle_request() returns 'false' @@ -180,11 +184,11 @@ func (handler *workerThread) waitForWorkerRequest() bool { handler.workerContext = fc handler.state.markAsWaiting(false) - logger.LogAttrs(nil, 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.String("url", fc.request.RequestURI)) if err := updateServerContext(handler.thread, fc, true); err != nil { // Unexpected error or invalid request - logger.LogAttrs(nil, 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.String("url", fc.request.RequestURI), slog.Any("error", err)) fc.rejectBadRequest(err.Error()) handler.workerContext = nil @@ -212,7 +216,7 @@ func go_frankenphp_finish_worker_request(threadIndex C.uintptr_t) { fc.closeContext() thread.handler.(*workerThread).workerContext = nil - fc.logger.LogAttrs(nil, slog.LevelDebug, "request handling finished", slog.String("worker", fc.scriptFilename), slog.String("url", fc.request.RequestURI)) + fc.logger.LogAttrs(context.Background(), slog.LevelDebug, "request handling finished", slog.String("worker", fc.scriptFilename), slog.String("url", fc.request.RequestURI)) } // when frankenphp_finish_request() is directly called from PHP @@ -222,5 +226,5 @@ func go_frankenphp_finish_php_request(threadIndex C.uintptr_t) { fc := phpThreads[threadIndex].getRequestContext() fc.closeContext() - fc.logger.LogAttrs(nil, slog.LevelDebug, "request handling finished", slog.String("url", fc.request.RequestURI)) + fc.logger.LogAttrs(context.Background(), slog.LevelDebug, "request handling finished", slog.String("url", fc.request.RequestURI)) }