perf: avoid buffering worker startup output

frankenphp.go

@@ -20,11 +20,9 @@ package frankenphp
 // #include <SAPI.h>
 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())
 }
 

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: &regularThread{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 }

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) {