feat: add support for structured logging with the frankenphp_log() PHP function (#1979)

As discussed in https://github.com/php/frankenphp/discussions/1961,
there is no real way to pass a severity/level to any log handler offered
by PHP that would make it to the FrankenPHP layer. This new function
allows applications embedding FrankenPHP to integrate PHP logging into
the application itself, thus offering a more streamlined experience.

---------

Co-authored-by: Quentin Burgess <qutn.burgess@gmail.com>
Co-authored-by: Kévin Dunglas <kevin@dunglas.fr>
This commit is contained in:
Raphael Coeffic
2025-12-15 16:10:35 +01:00
committed by GitHub
parent 7fca07ed67
commit 91c553f3d9
16 changed files with 211 additions and 67 deletions

View File

@@ -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

View File

@@ -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,26 +674,63 @@ 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
func go_is_context_done(threadIndex C.uintptr_t) C.bool {
return C.bool(phpThreads[threadIndex].frankenPHPContext().isDone)

View File

@@ -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 {}

View File

@@ -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);
}

View File

@@ -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(t *testing.T, opts *testOptions) {
logger, logs := observer.New(zapcore.InfoLevel)
opts.logger = slog.New(zapslog.NewHandler(logger))
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.php?i=%d", i), nil)
req := httptest.NewRequest("GET", fmt.Sprintf("http://example.com/log-error_log.php?i=%d", i), nil)
w := httptest.NewRecorder()
handler(w, req)
for logs.FilterMessage(fmt.Sprintf("request %d", i)).Len() <= 0 {
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_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-frankenphp_log.php?i=%d", i), nil)
w := httptest.NewRecorder()
handler(w, req)
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"})
})
}

3
go.mod
View File

@@ -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

6
go.sum
View File

@@ -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=

37
log_test.go Normal file
View File

@@ -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()
}

View File

@@ -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

View File

@@ -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]

19
testdata/log-frankenphp_log.php vendored Normal file
View File

@@ -0,0 +1,19 @@
<?php
require_once __DIR__.'/_executor.php';
return function () {
frankenphp_log("some debug message {$_GET['i']}", FRANKENPHP_LOG_LEVEL_DEBUG, [
"key int" => 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"],
]);
};

View File

@@ -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);

View File

@@ -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])

View File

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