diff --git a/frankenphp.c b/frankenphp.c index 04782a9b6..a6772a86e 100644 --- a/frankenphp.c +++ b/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 diff --git a/frankenphp.go b/frankenphp.go index da0bdead3..744439138 100644 --- a/frankenphp.go +++ b/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 diff --git a/frankenphp.stub.php b/frankenphp.stub.php index 60ac5d588..d6c85aa05 100644 --- a/frankenphp.stub.php +++ b/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 $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 {} diff --git a/frankenphp_arginfo.h b/frankenphp_arginfo.h index 558c6e3cf..4f2707cbc 100644 --- a/frankenphp_arginfo.h +++ b/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,6 +35,12 @@ 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); @@ -42,6 +48,7 @@ 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); +} diff --git a/frankenphp_test.go b/frankenphp_test.go index f8f175a92..d5368d145 100644 --- a/frankenphp_test.go +++ b/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,36 +415,60 @@ 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()) @@ -460,7 +476,7 @@ func testConnectionAbort(t *testing.T, opts *testOptions) { 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"}) }) } diff --git a/go.mod b/go.mod index 4210b0f44..35c89f37d 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 822ca3b39..bea3f847b 100644 --- a/go.sum +++ b/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= diff --git a/log_test.go b/log_test.go new file mode 100644 index 000000000..607da6fb9 --- /dev/null +++ b/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() +} diff --git a/phpmainthread_test.go b/phpmainthread_test.go index b777c3394..7e6bf32c1 100644 --- a/phpmainthread_test.go +++ b/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 diff --git a/scaling_test.go b/scaling_test.go index c0f848c44..f7ecc05e0 100644 --- a/scaling_test.go +++ b/scaling_test.go @@ -1,8 +1,6 @@ package frankenphp import ( - "io" - "log/slog" "testing" "time" @@ -16,7 +14,6 @@ func TestScaleARegularThreadUpAndDown(t *testing.T) { assert.NoError(t, Init( WithNumThreads(1), WithMaxThreads(2), - WithLogger(slog.New(slog.NewTextHandler(io.Discard, nil))), )) autoScaledThread := phpThreads[1] @@ -45,7 +42,6 @@ func TestScaleAWorkerThreadUpAndDown(t *testing.T) { WithWorkerWatchMode([]string{}), WithWorkerMaxFailures(0), ), - WithLogger(slog.New(slog.NewTextHandler(io.Discard, nil))), )) autoScaledThread := phpThreads[2] diff --git a/testdata/connectionStatusLog.php b/testdata/connection_status.php similarity index 100% rename from testdata/connectionStatusLog.php rename to testdata/connection_status.php diff --git a/testdata/log.php b/testdata/log-error_log.php similarity index 100% rename from testdata/log.php rename to testdata/log-error_log.php diff --git a/testdata/log-frankenphp_log.php b/testdata/log-frankenphp_log.php new file mode 100644 index 000000000..ab587f6e6 --- /dev/null +++ b/testdata/log-frankenphp_log.php @@ -0,0 +1,19 @@ + 1, + ]); + + frankenphp_log("some info message {$_GET['i']}", FRANKENPHP_LOG_LEVEL_INFO, [ + "key string" => "string", + ]); + + frankenphp_log("some warn message {$_GET['i']}", FRANKENPHP_LOG_LEVEL_WARN); + + frankenphp_log("some error message {$_GET['i']}", FRANKENPHP_LOG_LEVEL_ERROR, [ + "err" => ["a", "v"], + ]); +}; diff --git a/testdata/worker-getopt.php b/testdata/worker-getopt.php index 0d714eb9f..df22c2693 100644 --- a/testdata/worker-getopt.php +++ b/testdata/worker-getopt.php @@ -3,17 +3,17 @@ do { $ok = frankenphp_handle_request(function (): void { print_r($_SERVER); + + if (!isset($_SERVER['HTTP_REQUEST'])) { + exit(1); + } + if (isset($_SERVER['FRANKENPHP_WORKER'])) { + exit(2); + } + if (isset($_SERVER['FOO'])) { + exit(3); + } }); getopt('abc'); - - if (!isset($_SERVER['HTTP_REQUEST'])) { - exit(1); - } - if (isset($_SERVER['FRANKENPHP_WORKER'])) { - exit(2); - } - if (isset($_SERVER['FOO'])) { - exit(3); - } } while ($ok); diff --git a/types_test.go b/types_test.go index c6b81f710..a08f90725 100644 --- a/types_test.go +++ b/types_test.go @@ -1,7 +1,6 @@ package frankenphp import ( - "io" "log/slog" "testing" @@ -13,7 +12,8 @@ import ( // this is necessary if tests make use of PHP's internal allocation func testOnDummyPHPThread(t *testing.T, test func()) { t.Helper() - globalLogger = slog.New(slog.NewTextHandler(io.Discard, nil)) + + globalLogger = slog.Default() _, err := initPHPThreads(1, 1, nil) // boot 1 thread assert.NoError(t, err) handler := convertToTaskThread(phpThreads[0]) diff --git a/worker_test.go b/worker_test.go index c6b4245d4..37ba19206 100644 --- a/worker_test.go +++ b/worker_test.go @@ -4,7 +4,6 @@ import ( "fmt" "io" "log" - "log/slog" "net/http" "net/http/httptest" "net/url" @@ -17,9 +16,6 @@ import ( "github.com/dunglas/frankenphp" "github.com/stretchr/testify/assert" - "go.uber.org/zap/exp/zapslog" - "go.uber.org/zap/zapcore" - "go.uber.org/zap/zaptest/observer" ) func TestWorker(t *testing.T) { @@ -97,8 +93,7 @@ func TestWorkerEnv(t *testing.T) { } func TestWorkerGetOpt(t *testing.T) { - obs, logs := observer.New(zapcore.InfoLevel) - logger := slog.New(zapslog.NewHandler(obs)) + 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/worker-getopt.php?i=%d", i), nil) @@ -114,9 +109,7 @@ func TestWorkerGetOpt(t *testing.T) { assert.Contains(t, string(body), fmt.Sprintf("[REQUEST_URI] => /worker-getopt.php?i=%d", i)) }, &testOptions{logger: logger, workerScript: "worker-getopt.php", env: map[string]string{"FOO": "bar"}}) - for _, l := range logs.FilterFieldKey("exit_status").All() { - assert.Failf(t, "unexpected exit status", "exit status: %d", l.ContextMap()["exit_status"]) - } + assert.NotRegexp(t, buf.String(), "exit_status=[1-9]") } func ExampleServeHTTP_workers() {