feat: add frankenphp_log() PHP function

frankenphp.c

@@ -549,7 +549,30 @@ PHP_FUNCTION(mercure_publish) {
   RETURN_THROWS();
 }
 
+PHP_FUNCTION(frankenphp_log) {
+  zend_string *message = NULL;
+  zend_long level = 0;
+  zval *context = NULL;
+
+  ZEND_PARSE_PARAMETERS_START(2, 3)
+  Z_PARAM_STR(message)
+  Z_PARAM_LONG(level)
+  Z_PARAM_OPTIONAL
+  Z_PARAM_ARRAY(context)
+  ZEND_PARSE_PARAMETERS_END();
+
+  char *ret = NULL;
+  ret = go_log_attrs(thread_index, message, level, context);
+  if (ret != NULL) {
+    zend_throw_exception(spl_ce_RuntimeException, ret, 0);
+    free(ret);
+    RETURN_THROWS();
+  }
+}
+
 PHP_MINIT_FUNCTION(frankenphp) {
+  register_frankenphp_symbols(module_number);
+
   zend_function *func;
 
   // Override putenv

frankenphp.go

@@ -663,6 +663,7 @@ func go_read_cookies(threadIndex C.uintptr_t) *C.char {
 //export go_log
 func go_log(threadIndex C.uintptr_t, message *C.char, level C.int) {
 	ctx := phpThreads[threadIndex].context()
+	logger := phpThreads[threadIndex].frankenPHPContext().logger
 
 	m := C.GoString(message)
 	le := syslogLevelInfo
@@ -673,24 +674,61 @@ func go_log(threadIndex C.uintptr_t, message *C.char, level C.int) {
 
 	switch le {
 	case syslogLevelEmerg, syslogLevelAlert, syslogLevelCrit, syslogLevelErr:
-		if globalLogger.Enabled(ctx, slog.LevelError) {
-			globalLogger.LogAttrs(ctx, slog.LevelError, m, slog.String("syslog_level", syslogLevel(level).String()))
+		if logger.Enabled(ctx, slog.LevelError) {
+			logger.LogAttrs(ctx, slog.LevelError, m, slog.String("syslog_level", le.String()))
 		}
 
 	case syslogLevelWarn:
-		if globalLogger.Enabled(ctx, slog.LevelWarn) {
-			globalLogger.LogAttrs(ctx, slog.LevelWarn, m, slog.String("syslog_level", syslogLevel(level).String()))
+		if logger.Enabled(ctx, slog.LevelWarn) {
+			logger.LogAttrs(ctx, slog.LevelWarn, m, slog.String("syslog_level", le.String()))
 		}
+
 	case syslogLevelDebug:
-		if globalLogger.Enabled(ctx, slog.LevelDebug) {
-			globalLogger.LogAttrs(ctx, slog.LevelDebug, m, slog.String("syslog_level", syslogLevel(level).String()))
+		if logger.Enabled(ctx, slog.LevelDebug) {
+			logger.LogAttrs(ctx, slog.LevelDebug, m, slog.String("syslog_level", le.String()))
 		}
 
 	default:
-		if globalLogger.Enabled(ctx, slog.LevelInfo) {
-			globalLogger.LogAttrs(ctx, slog.LevelInfo, m, slog.String("syslog_level", syslogLevel(level).String()))
+		if logger.Enabled(ctx, slog.LevelInfo) {
+			logger.LogAttrs(ctx, slog.LevelInfo, m, slog.String("syslog_level", le.String()))
+		}
+	}
+}
+
+//export go_log_attrs
+func go_log_attrs(threadIndex C.uintptr_t, message *C.zend_string, cLevel C.zend_long, cAttrs *C.zval) *C.char {
+	ctx := phpThreads[threadIndex].context()
+	logger := phpThreads[threadIndex].frankenPHPContext().logger
+
+	level := slog.Level(cLevel)
+
+	if !logger.Enabled(ctx, level) {
+		return nil
+	}
+
+	var attrs map[string]any
+
+	if cAttrs != nil {
+		var err error
+		if attrs, err = GoMap[any](unsafe.Pointer(*(**C.zend_array)(unsafe.Pointer(&cAttrs.value[0])))); err != nil {
+			// PHP exception message.
+			return C.CString("Failed to log message: converting attrs: " + err.Error())
 		}
 	}
+
+	logger.LogAttrs(ctx, level, GoString(unsafe.Pointer(message)), mapToAttr(attrs)...)
+
+	return nil
+}
+
+func mapToAttr(input map[string]any) []slog.Attr {
+	out := make([]slog.Attr, 0, len(input))
+
+	for key, val := range input {
+		out = append(out, slog.Any(key, val))
+	}
+
+	return out
 }
 
 //export go_is_context_done

frankenphp.stub.php

@@ -2,6 +2,18 @@
 
 /** @generate-class-entries */
 
+/** @var int */
+const FRANKENPHP_LOG_LEVEL_DEBUG = -4;
+
+/** @var int */
+const FRANKENPHP_LOG_LEVEL_INFO = 0;
+
+/** @var int */
+const FRANKENPHP_LOG_LEVEL_WARN = 4;
+
+/** @var int */
+const FRANKENPHP_LOG_LEVEL_ERROR = 8;
+
 function frankenphp_handle_request(callable $callback): bool {}
 
 function headers_send(int $status = 200): int {}
@@ -36,3 +48,9 @@ function apache_response_headers(): array|bool {}
  * @param string|string[] $topics
  */
 function mercure_publish(string|array $topics, string $data = '', bool $private = false, ?string $id = null, ?string $type = null, ?int $retry = null): string {}
+
+/**
+ * @param int $level The importance or severity of a log event. The higher the level, the more important or severe the event. For more details, see: https://pkg.go.dev/log/slog#Level
+ * array<string, any> $context Values of the array will be converted to the corresponding Go type (if supported by FrankenPHP) and added to the context of the structured logs using https://pkg.go.dev/log/slog#Attr
+ */
+function frankenphp_log(string $message, int $level = 0, array $context = []): void {}

frankenphp_arginfo.h

@@ -1,5 +1,5 @@
 /* This is a generated file, edit the .stub.php file instead.
- * Stub hash: cd534a8394f535a600bf45a333955d23b5154756 */
+ * Stub hash: 60f0d27c04f94d7b24c052e91ef294595a2bc421 */
 
 ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_frankenphp_handle_request, 0, 1, _IS_BOOL, 0)
 	ZEND_ARG_TYPE_INFO(0, callback, IS_CALLABLE, 0)
@@ -35,13 +35,20 @@ ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_mercure_publish, 0, 1, IS_STRING
 	ZEND_ARG_TYPE_INFO_WITH_DEFAULT_VALUE(0, retry, IS_LONG, 1, "null")
 ZEND_END_ARG_INFO()
 
+ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_frankenphp_log, 0, 1, IS_VOID, 0)
+	ZEND_ARG_TYPE_INFO(0, message, IS_STRING, 0)
+	ZEND_ARG_TYPE_INFO_WITH_DEFAULT_VALUE(0, level, IS_LONG, 0, "0")
+	ZEND_ARG_TYPE_INFO_WITH_DEFAULT_VALUE(0, context, IS_ARRAY, 0, "[]")
+ZEND_END_ARG_INFO()
+
 
 ZEND_FUNCTION(frankenphp_handle_request);
 ZEND_FUNCTION(headers_send);
 ZEND_FUNCTION(frankenphp_finish_request);
 ZEND_FUNCTION(frankenphp_request_headers);
 ZEND_FUNCTION(frankenphp_response_headers);
 ZEND_FUNCTION(mercure_publish);
+ZEND_FUNCTION(frankenphp_log);
 
 
 static const zend_function_entry ext_functions[] = {
@@ -55,5 +62,14 @@ static const zend_function_entry ext_functions[] = {
 	ZEND_FE(frankenphp_response_headers, arginfo_frankenphp_response_headers)
 	ZEND_FALIAS(apache_response_headers, frankenphp_response_headers, arginfo_apache_response_headers)
 	ZEND_FE(mercure_publish, arginfo_mercure_publish)
+	ZEND_FE(frankenphp_log, arginfo_frankenphp_log)
 	ZEND_FE_END
 };
+
+static void register_frankenphp_symbols(int module_number)
+{
+	REGISTER_LONG_CONSTANT("FRANKENPHP_LOG_LEVEL_DEBUG", -4, CONST_PERSISTENT);
+	REGISTER_LONG_CONSTANT("FRANKENPHP_LOG_LEVEL_INFO", 0, CONST_PERSISTENT);
+	REGISTER_LONG_CONSTANT("FRANKENPHP_LOG_LEVEL_WARN", 4, CONST_PERSISTENT);
+	REGISTER_LONG_CONSTANT("FRANKENPHP_LOG_LEVEL_ERROR", 8, CONST_PERSISTENT);
+}

frankenphp_test.go

@@ -32,10 +32,6 @@ import (
 	"github.com/dunglas/frankenphp/internal/fastabs"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
-	"go.uber.org/zap/exp/zapslog"
-	"go.uber.org/zap/zapcore"
-	"go.uber.org/zap/zaptest"
-	"go.uber.org/zap/zaptest/observer"
 )
 
 type testOptions struct {
@@ -62,10 +58,6 @@ func runTest(t *testing.T, test func(func(http.ResponseWriter, *http.Request), *
 	cwd, _ := os.Getwd()
 	testDataDir := cwd + "/testdata/"
 
-	if opts.logger == nil {
-		opts.logger = slog.New(zapslog.NewHandler(zaptest.NewLogger(t).Core()))
-	}
-
 	initOpts := []frankenphp.Option{frankenphp.WithLogger(opts.logger)}
 	if opts.workerScript != "" {
 		workerOpts := []frankenphp.WorkerOption{
@@ -423,44 +415,68 @@ my_autoloader`, i), body)
 	}, opts)
 }
 
-func TestLog_module(t *testing.T) { testLog(t, &testOptions{}) }
-func TestLog_worker(t *testing.T) {
-	testLog(t, &testOptions{workerScript: "log.php"})
+func TestLog_error_log_module(t *testing.T) { testLog_error_log(t, &testOptions{}) }
+func TestLog_error_log_worker(t *testing.T) {
+	testLog_error_log(t, &testOptions{workerScript: "log-error_log.php"})
+}
+func testLog_error_log(t *testing.T, opts *testOptions) {
+	var buf fmt.Stringer
+	opts.logger, buf = newTestLogger(t)
+
+	runTest(t, func(handler func(http.ResponseWriter, *http.Request), _ *httptest.Server, i int) {
+		req := httptest.NewRequest("GET", fmt.Sprintf("http://example.com/log-error_log.php?i=%d", i), nil)
+		w := httptest.NewRecorder()
+		handler(w, req)
+
+		assert.Contains(t, buf.String(), fmt.Sprintf("request %d", i))
+	}, opts)
+}
+
+func TestLog_frankenphp_log_module(t *testing.T) { testLog_frankenphp_log(t, &testOptions{}) }
+func TestLog_frankenphp_log_worker(t *testing.T) {
+	testLog_frankenphp_log(t, &testOptions{workerScript: "log-frankenphp_log.php"})
 }
-func testLog(t *testing.T, opts *testOptions) {
-	logger, logs := observer.New(zapcore.InfoLevel)
-	opts.logger = slog.New(zapslog.NewHandler(logger))
+func testLog_frankenphp_log(t *testing.T, opts *testOptions) {
+	var buf fmt.Stringer
+	opts.logger, buf = newTestLogger(t)
 
 	runTest(t, func(handler func(http.ResponseWriter, *http.Request), _ *httptest.Server, i int) {
-		req := httptest.NewRequest("GET", fmt.Sprintf("http://example.com/log.php?i=%d", i), nil)
+		req := httptest.NewRequest("GET", fmt.Sprintf("http://example.com/log-frankenphp_log.php?i=%d", i), nil)
 		w := httptest.NewRecorder()
 		handler(w, req)
 
-		for logs.FilterMessage(fmt.Sprintf("request %d", i)).Len() <= 0 {
+		logs := buf.String()
+		for _, message := range []string{
+			fmt.Sprintf(`level=DEBUG msg="some debug message %d" "key int"=1`, i),
+			fmt.Sprintf(`level=INFO msg="some info message %d" "key string"=string`, i),
+			fmt.Sprintf(`level=WARN msg="some warn message %d"`, i),
+			fmt.Sprintf(`level=ERROR msg="some error message %d" err="[a v]"`, i),
+		} {
+			assert.Contains(t, logs, message)
 		}
 	}, opts)
 }
 
 func TestConnectionAbort_module(t *testing.T) { testConnectionAbort(t, &testOptions{}) }
 func TestConnectionAbort_worker(t *testing.T) {
-	testConnectionAbort(t, &testOptions{workerScript: "connectionStatusLog.php"})
+	testConnectionAbort(t, &testOptions{workerScript: "connection_status.php"})
 }
 func testConnectionAbort(t *testing.T, opts *testOptions) {
 	testFinish := func(finish string) {
 		t.Run(fmt.Sprintf("finish=%s", finish), func(t *testing.T) {
-			logger, logs := observer.New(zapcore.InfoLevel)
-			opts.logger = slog.New(zapslog.NewHandler(logger))
+			var buf syncBuffer
+			opts.logger = slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}))
 
 			runTest(t, func(handler func(http.ResponseWriter, *http.Request), _ *httptest.Server, i int) {
-				req := httptest.NewRequest("GET", fmt.Sprintf("http://example.com/connectionStatusLog.php?i=%d&finish=%s", i, finish), nil)
+				req := httptest.NewRequest("GET", fmt.Sprintf("http://example.com/connection_status.php?i=%d&finish=%s", i, finish), nil)
 				w := httptest.NewRecorder()
 
 				ctx, cancel := context.WithCancel(req.Context())
 				req = req.WithContext(ctx)
 				cancel()
 				handler(w, req)
 
-				for logs.FilterMessage(fmt.Sprintf("request %d: 1", i)).Len() <= 0 {
+				for !strings.Contains(buf.String(), fmt.Sprintf("request %d: 1", i)) {
 				}
 			}, opts)
 		})
@@ -1058,7 +1074,6 @@ func FuzzRequest(f *testing.F) {
 			// Headers should always be present even if empty
 			assert.Contains(t, body, fmt.Sprintf("[CONTENT_TYPE] => %s", fuzzedString))
 			assert.Contains(t, body, fmt.Sprintf("[HTTP_FUZZED] => %s", fuzzedString))
-
 		}, &testOptions{workerScript: "request-headers.php"})
 	})
 }

go.mod

@@ -11,8 +11,6 @@ require (
 	github.com/maypok86/otter/v2 v2.2.1
 	github.com/prometheus/client_golang v1.23.2
 	github.com/stretchr/testify v1.11.1
-	go.uber.org/zap v1.27.1
-	go.uber.org/zap/exp v0.3.0
 	golang.org/x/net v0.47.0
 )
 
@@ -58,7 +56,6 @@ require (
 	github.com/unrolled/secure v1.17.0 // indirect
 	github.com/yosida95/uritemplate/v3 v3.0.2 // indirect
 	go.etcd.io/bbolt v1.4.3 // indirect
-	go.uber.org/multierr v1.11.0 // indirect
 	go.yaml.in/yaml/v2 v2.4.3 // indirect
 	go.yaml.in/yaml/v3 v3.0.4 // indirect
 	golang.org/x/crypto v0.45.0 // indirect

go.sum

@@ -104,12 +104,6 @@ go.etcd.io/bbolt v1.4.3 h1:dEadXpI6G79deX5prL3QRNP6JB8UxVkqo4UPnHaNXJo=
 go.etcd.io/bbolt v1.4.3/go.mod h1:tKQlpPaYCVFctUIgFKFnAlvbmB3tpy1vkTnDWohtc0E=
 go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto=
 go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE=
-go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0=
-go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
-go.uber.org/zap v1.27.1 h1:08RqriUEv8+ArZRYSTXy1LeBScaMpVSTBhCeaZYfMYc=
-go.uber.org/zap v1.27.1/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E=
-go.uber.org/zap/exp v0.3.0 h1:6JYzdifzYkGmTdRR59oYH+Ng7k49H9qVpWwNSsGJj3U=
-go.uber.org/zap/exp v0.3.0/go.mod h1:5I384qq7XGxYyByIhHm6jg5CHkGY0nsTfbDLgDDlgJQ=
 go.yaml.in/yaml/v2 v2.4.3 h1:6gvOSjQoTB3vt1l+CU+tSyi/HOjfOjRLJ4YwYZGwRO0=
 go.yaml.in/yaml/v2 v2.4.3/go.mod h1:zSxWcmIDjOzPXpjlTTbAsKokqkDNAVtZO0WOMiT90s8=
 go.yaml.in/yaml/v3 v3.0.4 h1:tfq32ie2Jv2UxXFdLJdh3jXuOzWiL1fo0bu/FbuKpbc=

log_test.go

@@ -0,0 +1,37 @@
+package frankenphp_test
+
+import (
+	"bytes"
+	"fmt"
+	"log/slog"
+	"sync"
+	"testing"
+)
+
+func newTestLogger(t *testing.T) (*slog.Logger, fmt.Stringer) {
+	t.Helper()
+
+	var buf syncBuffer
+
+	return slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})), &buf
+}
+
+// SyncBuffer is a thread-safe buffer for capturing logs in tests.
+type syncBuffer struct {
+	b  bytes.Buffer
+	mu sync.RWMutex
+}
+
+func (s *syncBuffer) Write(p []byte) (n int, err error) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+
+	return s.b.Write(p)
+}
+
+func (s *syncBuffer) String() string {
+	s.mu.RLock()
+	defer s.mu.RUnlock()
+
+	return s.b.String()
+}

phpmainthread_test.go

@@ -2,7 +2,6 @@ package frankenphp
 
 import (
 	"io"
-	"log/slog"
 	"math/rand/v2"
 	"net/http/httptest"
 	"path/filepath"
@@ -119,7 +118,6 @@ func TestTransitionThreadsWhileDoingRequests(t *testing.T) {
 			WithWorkerWatchMode([]string{}),
 			WithWorkerMaxFailures(0),
 		),
-		WithLogger(slog.New(slog.NewTextHandler(io.Discard, nil))),
 	))
 
 	// try all possible permutations of transition, transition every ms