diff --git a/frankenphp.go b/frankenphp.go index 229eb6b2a0..e560031e62 100644 --- a/frankenphp.go +++ b/frankenphp.go @@ -20,11 +20,9 @@ package frankenphp // #include import "C" import ( - "bytes" "context" "errors" "fmt" - "io" "log/slog" "net/http" "os" @@ -554,25 +552,19 @@ func go_ub_write(threadIndex C.uintptr_t, cBuf *C.char, length C.size_t) (C.size return C.size_t(length), C.bool(fc.clientHadClosed) } - var writer io.Writer if fc.responseWriter == nil { - var b bytes.Buffer - // log the output of the worker - writer = &b - } else { - writer = fc.responseWriter + if fc.logger.Enabled(fc.ctx, slog.LevelInfo) { + message := string(unsafe.Slice((*byte)(unsafe.Pointer(cBuf)), length)) + fc.logger.LogAttrs(fc.ctx, slog.LevelInfo, message) + } + return length, C.bool(fc.clientHasClosed()) } - i, e := writer.Write(unsafe.Slice((*byte)(unsafe.Pointer(cBuf)), length)) + i, e := fc.responseWriter.Write(unsafe.Slice((*byte)(unsafe.Pointer(cBuf)), length)) if e != nil && fc.logger.Enabled(fc.ctx, slog.LevelDebug) { fc.logger.LogAttrs(fc.ctx, slog.LevelDebug, "write error", slog.Any("error", e)) } - if fc.responseWriter == nil && fc.logger.Enabled(fc.ctx, slog.LevelInfo) { - // probably starting a worker script, log the output - fc.logger.LogAttrs(fc.ctx, slog.LevelInfo, writer.(*bytes.Buffer).String()) - } - return C.size_t(i), C.bool(fc.clientHasClosed()) } diff --git a/worker_internal_test.go b/worker_internal_test.go index db7b7e9797..a54ff41b43 100644 --- a/worker_internal_test.go +++ b/worker_internal_test.go @@ -2,12 +2,15 @@ package frankenphp import ( "context" + "log/slog" "net/http/httptest" "os" "path/filepath" + "reflect" "runtime" "testing" "time" + "unsafe" "github.com/dunglas/frankenphp/internal/state" "github.com/stretchr/testify/assert" @@ -165,3 +168,44 @@ func TestInitReturnsWhenARebootWaitsOnAWorkerThatGivesUp(t *testing.T) { t.Fatal("Init() hung behind a reboot waiting for a worker thread that ended on its own") } } + +func TestWorkerStartupLogOwnsMessage(t *testing.T) { + const message = "worker startup\x00\xff" + data := []byte(message) + capture := &workerStartupLogCapture{} + fc := &frankenPHPContext{ctx: context.Background(), logger: slog.New(capture)} + oldThreads := phpThreads + phpThreads = []*phpThread{{handler: ®ularThread{fc: fc}}} + t.Cleanup(func() { phpThreads = oldThreads }) + + // Reflection bridges C argument types, which cannot be imported in a Go test file. + fn := reflect.ValueOf(go_ub_write) + signature := fn.Type() + result := fn.Call([]reflect.Value{ + reflect.Zero(signature.In(0)), + reflect.NewAt(signature.In(1).Elem(), unsafe.Pointer(unsafe.SliceData(data))), + reflect.ValueOf(len(data)).Convert(signature.In(2)), + }) + require.Equal(t, uint64(len(data)), result[0].Uint()) + require.False(t, result[1].Bool()) + + // A log handler may retain the record after PHP reuses its output buffer. + for i := range data { + data[i] = 'Z' + } + require.Len(t, capture.records, 1) + assert.Equal(t, message, capture.records[0].Message) + assert.Equal(t, slog.LevelInfo, capture.records[0].Level) +} + +type workerStartupLogCapture struct { + records []slog.Record +} + +func (h *workerStartupLogCapture) Enabled(context.Context, slog.Level) bool { return true } +func (h *workerStartupLogCapture) Handle(_ context.Context, record slog.Record) error { + h.records = append(h.records, record.Clone()) + return nil +} +func (h *workerStartupLogCapture) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h *workerStartupLogCapture) WithGroup(string) slog.Handler { return h } diff --git a/worker_test.go b/worker_test.go index 0e0b61d088..5655f25f7a 100644 --- a/worker_test.go +++ b/worker_test.go @@ -260,17 +260,30 @@ func TestKeepRunningOnConnectionAbort(t *testing.T) { req := httptest.NewRequest("GET", "http://example.com/worker-with-counter.php", nil) ctx, cancel := context.WithCancel(req.Context()) + defer cancel() req = req.WithContext(ctx) - cancel() - body1, _ := testRequest(req, handler, t) + w := &cancelOnWriteResponseWriter{ResponseRecorder: httptest.NewRecorder(), cancel: cancel} + handler(w, req) - assert.Equal(t, "requests:1", body1, "should have handled exactly one request") + assert.ErrorIs(t, ctx.Err(), context.Canceled, "should have aborted during the response") + assert.Equal(t, "requests:1", w.Body.String(), "should have handled exactly one request") body2, _ := testGet("http://example.com/worker-with-counter.php", handler, t) assert.Equal(t, "requests:2", body2, "should not have stopped execution after the first request was aborted") }, &testOptions{workerScript: "worker-with-counter.php", nbWorkers: 1, nbParallelRequests: 1}) } +// Cancel only once the worker writes, so dispatch cannot discard the request first. +type cancelOnWriteResponseWriter struct { + *httptest.ResponseRecorder + cancel context.CancelFunc +} + +func (w *cancelOnWriteResponseWriter) Write(p []byte) (int, error) { + w.cancel() + return w.ResponseRecorder.Write(p) +} + // Per-request env must not leak into later requests on the same worker thread, even after putenv(). func TestWorkerRequestEnvDoesNotLeak(t *testing.T) { runTest(t, func(_ func(http.ResponseWriter, *http.Request), _ *httptest.Server, _ int) {