FPM: Implement configurable access log limit

It sets the access log limit as configurable log_limit to allow larger
log limit than the currently fixed limit of 1024 characters.

Fixes GH-12302
Closes GH-18725
This commit is contained in:
Jakub Zelenka 2025-05-14 23:44:37 +02:00
parent 35a4656a59
commit cfb3e98c84
No known key found for this signature in database
GPG key ID: 1C0779DC5C0A9DE4
7 changed files with 186 additions and 89 deletions

4
NEWS
View file

@ -12,13 +12,15 @@ PHP NEWS
. Add support for CURLINFO_QUEUE_TIME_T in curl_getinfo() (thecaliskan)
. Add support for CURLOPT_SSL_SIGNATURE_ALGORITHMS. (Ayesh Karunaratne)
- FPM:
. Make FPM access log limit configurable using log_limit. (Jakub Zelenka)
- GD:
. Fix incorrect comparison with result of php_stream_can_cast(). (Girgias)
- Intl:
. Fix return value on failure for resourcebundle count handler. (Girgias)
- OPcache:
. Disallow changing opcache.memory_consumption when SHM is already set up.
(timwolla)

View file

@ -298,6 +298,7 @@ PHP 8.5 UPGRADE NOTES
- FPM:
. FPM with httpd ProxyPass decodes the full script path. Added
fastcgi.script_path_encoded INI setting to prevent this new behavior.
. FPM access log limit now respects log_limit value.
========================================
4. Deprecated Functionality

View file

@ -24,6 +24,7 @@
static char *fpm_log_format = NULL;
static int fpm_log_fd = -1;
static struct key_value_s *fpm_access_suppress_paths = NULL;
static struct zlog_stream fpm_log_stream;
static int fpm_access_log_suppress(struct fpm_scoreboard_proc_s *proc);
@ -92,7 +93,8 @@ int fpm_log_init_child(struct fpm_worker_pool_s *wp) /* {{{ */
if (fpm_log_fd == -1) {
fpm_log_fd = wp->log_fd;
}
zlog_stream_init_ex(&fpm_log_stream, ZLOG_ACCESS_LOG, fpm_log_fd);
zlog_stream_set_wrapping(&fpm_log_stream, 0);
for (wp = fpm_worker_all_pools; wp; wp = wp->next) {
if (wp->log_fd > -1 && wp->log_fd != fpm_log_fd) {
@ -107,12 +109,11 @@ int fpm_log_init_child(struct fpm_worker_pool_s *wp) /* {{{ */
int fpm_log_write(char *log_format) /* {{{ */
{
char *s, *b;
char buffer[FPM_LOG_BUFFER+1];
int token, test;
size_t len, len2;
char *s;
bool test, token = false;
struct fpm_scoreboard_proc_s proc, *proc_p;
struct fpm_scoreboard_s *scoreboard;
struct zlog_stream *stream;
char tmp[129];
char format[129];
time_t now_epoch;
@ -126,9 +127,9 @@ int fpm_log_write(char *log_format) /* {{{ */
if (!log_format) {
log_format = fpm_log_format;
test = 0;
test = false;
} else {
test = 1;
test = true;
}
now_epoch = time(NULL);
@ -152,38 +153,25 @@ int fpm_log_write(char *log_format) /* {{{ */
}
}
token = 0;
memset(buffer, '\0', sizeof(buffer));
b = buffer;
len = 0;
s = log_format;
stream = &fpm_log_stream;
zlog_stream_start(stream);
while (*s != '\0') {
/* Test is we have place for 1 more char. */
if (len >= FPM_LOG_BUFFER) {
zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
len = FPM_LOG_BUFFER;
break;
}
if (!token && *s == '%') {
token = 1;
token = true;
memset(format, '\0', sizeof(format)); /* reset format */
s++;
continue;
}
if (token) {
token = 0;
len2 = 0;
token = false;
switch (*s) {
case '%': /* '%' */
*b = '%';
len2 = 1;
zlog_stream_char(stream, '%');
break;
#ifdef HAVE_TIMES
@ -207,7 +195,7 @@ int fpm_log_write(char *log_format) /* {{{ */
format[0] = '\0';
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.2f", tms_total / fpm_scoreboard_get_tick() / (proc.cpu_duration.tv_sec + proc.cpu_duration.tv_usec / 1000000.) * 100.);
zlog_stream_format(stream, "%.2f", tms_total / fpm_scoreboard_get_tick() / (proc.cpu_duration.tv_sec + proc.cpu_duration.tv_usec / 1000000.) * 100.);
}
break;
#endif
@ -216,7 +204,7 @@ int fpm_log_write(char *log_format) /* {{{ */
/* seconds */
if (format[0] == '\0' || !strcasecmp(format, "seconds")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.);
zlog_stream_format(stream, "%.3f", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.);
}
/* milliseconds */
@ -225,13 +213,13 @@ int fpm_log_write(char *log_format) /* {{{ */
!strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili")
) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.);
zlog_stream_format(stream, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.);
}
/* microseconds */
} else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", (unsigned long)(proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec));
zlog_stream_format(stream, "%lu", (unsigned long)(proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec));
}
} else {
@ -249,26 +237,26 @@ int fpm_log_write(char *log_format) /* {{{ */
if (!test) {
char *env = fcgi_getenv((fcgi_request*) SG(server_context), format, strlen(format));
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", env ? env : "-");
zlog_stream_cstr(stream, env ? env : "-");
}
format[0] = '\0';
break;
case 'f': /* script */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.script_filename ? proc.script_filename : "-");
zlog_stream_cstr(stream, *proc.script_filename ? proc.script_filename : "-");
}
break;
case 'l': /* content length */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.content_length);
zlog_stream_format(stream, "%zu", proc.content_length);
}
break;
case 'm': /* method */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.request_method ? proc.request_method : "-");
zlog_stream_cstr(stream, *proc.request_method ? proc.request_method : "-");
}
break;
@ -276,19 +264,19 @@ int fpm_log_write(char *log_format) /* {{{ */
/* seconds */
if (format[0] == '\0' || !strcasecmp(format, "bytes")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory);
zlog_stream_format(stream, "%zu", proc.memory);
}
/* kilobytes */
} else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory / 1024);
zlog_stream_format(stream, "%zu", proc.memory / 1024);
}
/* megabytes */
} else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory / 1024 / 1024);
zlog_stream_format(stream, "%zu", proc.memory / 1024 / 1024);
}
} else {
@ -300,7 +288,7 @@ int fpm_log_write(char *log_format) /* {{{ */
case 'n': /* pool name */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", scoreboard->pool[0] ? scoreboard->pool : "-");
zlog_stream_cstr(stream, scoreboard->pool[0] ? scoreboard->pool : "-");
}
break;
@ -314,6 +302,7 @@ int fpm_log_write(char *log_format) /* {{{ */
zend_llist_position pos;
sapi_headers_struct *sapi_headers = &SG(sapi_headers);
size_t format_len = strlen(format);
ssize_t written = 0;
h = (sapi_header_struct*)zend_llist_get_first_ex(&sapi_headers->headers, &pos);
while (h) {
@ -339,14 +328,13 @@ int fpm_log_write(char *log_format) /* {{{ */
}
header = h->header + format_len + 2;
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", header && *header ? header : "-");
written += zlog_stream_cstr(stream, header && *header ? header : "-");
/* found, done */
break;
}
if (!len2) {
len2 = 1;
*b = '-';
if (!written) {
zlog_stream_char(stream, '-');
}
}
format[0] = '\0';
@ -354,44 +342,44 @@ int fpm_log_write(char *log_format) /* {{{ */
case 'p': /* PID */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getpid());
zlog_stream_format(stream, "%ld", (long)getpid());
}
break;
case 'P': /* PID */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getppid());
zlog_stream_format(stream, "%ld", (long)getppid());
}
break;
case 'q': /* query_string */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.query_string);
zlog_stream_cstr(stream, proc.query_string);
}
break;
case 'Q': /* '?' */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.query_string ? "?" : "");
zlog_stream_cstr(stream, *proc.query_string ? "?" : "");
}
break;
case 'r': /* request URI */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_uri);
zlog_stream_cstr(stream, proc.request_uri);
}
break;
case 'R': /* remote IP address */
if (!test) {
const char *tmp = fcgi_get_last_client_ip();
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp ? tmp : "-");
zlog_stream_cstr(stream, tmp ? tmp : "-");
}
break;
case 's': /* status */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%d", SG(sapi_headers).http_response_code);
zlog_stream_format(stream, "%d", SG(sapi_headers).http_response_code);
}
break;
@ -409,14 +397,14 @@ int fpm_log_write(char *log_format) /* {{{ */
} else {
strftime(tmp, sizeof(tmp) - 1, format, localtime(t));
}
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp);
zlog_stream_cstr(stream, tmp);
}
format[0] = '\0';
break;
case 'u': /* remote user */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.auth_user);
zlog_stream_cstr(stream, proc.auth_user);
}
break;
@ -459,30 +447,28 @@ int fpm_log_write(char *log_format) /* {{{ */
return -1;
}
s++;
if (!test) {
b += len2;
len += len2;
}
if (len >= FPM_LOG_BUFFER) {
zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
len = FPM_LOG_BUFFER;
if (zlog_stream_is_over_limit(stream)) {
zlog(ZLOG_NOTICE, "the log buffer is over the configured limit. The access log request has been truncated.");
break;
}
continue;
}
if (zlog_stream_is_over_limit(stream)) {
zlog(ZLOG_NOTICE, "the log buffer is over the configured limit. The access log request has been truncated.");
break;
}
if (!test) {
// push the normal char to the output buffer
*b = *s;
b++;
len++;
zlog_stream_char(stream, *s);
}
s++;
}
if (!test && strlen(buffer) > 0) {
buffer[len] = '\n';
zend_quiet_write(fpm_log_fd, buffer, len + 1);
if (!test) {
zlog_stream_finish(stream);
}
return 0;

View file

@ -34,11 +34,11 @@ struct fpm_scoreboard_proc_s {
struct timeval duration;
time_t accepted_epoch;
struct timeval tv;
char request_uri[128];
char query_string[512];
char request_uri[512];
char query_string[2048];
char request_method[16];
size_t content_length; /* used with POST only */
char script_filename[256];
char script_filename[512];
char auth_user[32];
#ifdef HAVE_TIMES
struct tms cpu_accepted;

View file

@ -410,8 +410,16 @@ static inline ssize_t zlog_stream_unbuffered_write(
}
/* }}} */
static inline ssize_t zlog_stream_buf_copy_cstr(
struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */
void zlog_stream_start(struct zlog_stream *stream)
{
stream->finished = 0;
stream->len = 0;
stream->full = 0;
stream->over_limit = 0;
}
static ssize_t zlog_stream_buf_copy_cstr(
struct zlog_stream *stream, const char *str, size_t str_len)
{
ZEND_ASSERT(stream->len <= stream->buf.size);
if (stream->buf.size - stream->len <= str_len &&
@ -419,25 +427,32 @@ static inline ssize_t zlog_stream_buf_copy_cstr(
return -1;
}
if (stream->buf.size - stream->len <= str_len) {
stream->over_limit = 1;
str_len = stream->buf.size - stream->len;
}
memcpy(stream->buf.data + stream->len, str, str_len);
stream->len += str_len;
return str_len;
}
/* }}} */
static inline ssize_t zlog_stream_buf_copy_char(struct zlog_stream *stream, char c) /* {{{ */
static ssize_t zlog_stream_buf_copy_char(struct zlog_stream *stream, char c)
{
ZEND_ASSERT(stream->len <= stream->buf.size);
if (stream->buf.size - stream->len < 1 && !zlog_stream_buf_alloc_ex(stream, 1)) {
if (stream->buf.size == stream->len && !zlog_stream_buf_alloc_ex(stream, 1)) {
return -1;
}
if (stream->buf.size == stream->len) {
stream->over_limit = 1;
return 0;
}
stream->buf.data[stream->len++] = c;
return 1;
}
/* }}} */
static ssize_t zlog_stream_buf_flush(struct zlog_stream *stream) /* {{{ */
{
@ -466,8 +481,8 @@ static ssize_t zlog_stream_buf_flush(struct zlog_stream *stream) /* {{{ */
static ssize_t zlog_stream_buf_append(
struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */
{
int over_limit = 0;
size_t available_len, required_len, reserved_len;
int over_limit = 0;
if (stream->len == 0) {
stream->len = zlog_stream_prefix_ex(stream, stream->function, stream->line);
@ -477,7 +492,7 @@ static ssize_t zlog_stream_buf_append(
reserved_len = stream->len + stream->msg_suffix_len + stream->msg_quote;
required_len = reserved_len + str_len;
if (required_len >= zlog_limit) {
over_limit = 1;
stream->over_limit = over_limit = 1;
available_len = zlog_limit - reserved_len - 1;
} else {
available_len = str_len;
@ -521,16 +536,21 @@ static inline void zlog_stream_init_internal(
stream->flags = flags;
stream->use_syslog = fd == ZLOG_SYSLOG;
stream->use_fd = fd > 0;
stream->use_buffer = zlog_buffering || external_logger != NULL || stream->use_syslog;
stream->buf_init_size = capacity;
stream->use_stderr = fd < 0 ||
(
fd != STDERR_FILENO && fd != STDOUT_FILENO && !launched &&
(flags & ZLOG_LEVEL_MASK) >= ZLOG_NOTICE
);
stream->prefix_buffer = (flags & ZLOG_LEVEL_MASK) >= zlog_level &&
(stream->use_fd || stream->use_stderr || stream->use_syslog);
stream->fd = fd > -1 ? fd : STDERR_FILENO;
stream->buf_init_size = capacity;
if (flags & ZLOG_ACCESS_LOG) {
stream->use_buffer = 1;
stream->use_stderr = fd < 0;
} else {
stream->use_buffer = zlog_buffering || external_logger != NULL || stream->use_syslog;
stream->use_stderr = fd < 0 ||
(
fd != STDERR_FILENO && fd != STDOUT_FILENO && !launched &&
(flags & ZLOG_LEVEL_MASK) >= ZLOG_NOTICE
);
stream->prefix_buffer = (flags & ZLOG_LEVEL_MASK) >= zlog_level &&
(stream->use_fd || stream->use_stderr || stream->use_syslog);
}
}
/* }}} */
@ -745,7 +765,7 @@ ssize_t zlog_stream_format(struct zlog_stream *stream, const char *fmt, ...) /*
}
/* }}} */
ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len) /* {{{ */
ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len)
{
/* do not write anything if the stream is full or str is empty */
if (str_len == 0 || stream->full) {
@ -754,9 +774,7 @@ ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_
/* reset stream if it is finished */
if (stream->finished) {
stream->finished = 0;
stream->len = 0;
stream->full = 0;
zlog_stream_start(stream);
}
if (stream->use_buffer) {
@ -765,7 +783,25 @@ ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_
return zlog_stream_unbuffered_write(stream, str, str_len);
}
/* }}} */
ssize_t zlog_stream_char(struct zlog_stream *stream, char c)
{
/* do not write anything if the stream is full */
if (stream->full) {
return 0;
}
/* reset stream if it is finished */
if (stream->finished) {
zlog_stream_start(stream);
}
if (stream->use_buffer) {
return zlog_stream_buf_copy_char(stream, c);
}
const char tmp[1] = {c};
return zlog_stream_direct_write(stream, tmp, 1);
}
static inline void zlog_stream_finish_buffer_suffix(struct zlog_stream *stream) /* {{{ */
{
@ -883,3 +919,8 @@ zlog_bool zlog_stream_close(struct zlog_stream *stream) /* {{{ */
return finished;
}
/* }}} */
zlog_bool zlog_stream_is_over_limit(struct zlog_stream *stream)
{
return stream->over_limit;
}

View file

@ -48,6 +48,8 @@ enum {
#define ZLOG_LEVEL_MASK 7
#define ZLOG_ACCESS_LOG 16
#define ZLOG_HAVE_ERRNO 0x100
#define ZLOG_SYSERROR (ZLOG_ERROR | ZLOG_HAVE_ERRNO)
@ -74,6 +76,7 @@ struct zlog_stream {
unsigned int msg_quote:1;
unsigned int decorate:1;
unsigned int is_stdout:1;
unsigned int over_limit:1;
int fd;
int line;
int child_pid;
@ -103,14 +106,22 @@ zlog_bool zlog_stream_set_msg_suffix(
struct zlog_stream *stream, const char *suffix, const char *final_suffix);
#define zlog_stream_prefix(stream) \
zlog_stream_prefix_ex(stream, __func__, __LINE__)
void zlog_stream_start(struct zlog_stream *stream);
ssize_t zlog_stream_prefix_ex(struct zlog_stream *stream, const char *function, int line);
ssize_t zlog_stream_format(struct zlog_stream *stream, const char *fmt, ...)
__attribute__ ((format(printf,2,3)));
ssize_t zlog_stream_vformat(struct zlog_stream *stream, const char *fmt, va_list args);
ssize_t zlog_stream_str(struct zlog_stream *stream, const char *str, size_t str_len);
ssize_t zlog_stream_char(struct zlog_stream *stream, char c);
zlog_bool zlog_stream_finish(struct zlog_stream *stream);
void zlog_stream_destroy(struct zlog_stream *stream);
zlog_bool zlog_stream_close(struct zlog_stream *stream);
zlog_bool zlog_stream_is_over_limit(struct zlog_stream *stream);
static inline ssize_t zlog_stream_cstr(struct zlog_stream *stream, const char *cstr)
{
return zlog_stream_str(stream, cstr, strlen(cstr));
}
/* default log limit */
#define ZLOG_DEFAULT_LIMIT 1024

View file

@ -0,0 +1,56 @@
--TEST--
FPM: Test extended access log limit
--SKIPIF--
<?php include "skipif.inc"; ?>
--FILE--
<?php
require_once "tester.inc";
$src = <<<EOT
<?php
echo "OK";
EOT;
$cfg = <<<EOT
[global]
error_log = {{RFILE:LOG:ERR}}
pid = {{RFILE:PID}}
log_limit = 2048
[unconfined]
listen = {{ADDR}}
access.log = {{RFILE:LOG:ACC}}
access.format = "'%m %r%Q%q' %s"
slowlog = {{RFILE:LOG:SLOW}}
request_slowlog_timeout = 1
ping.path = /ping
ping.response = pong
pm = dynamic
pm.max_children = 5
pm.start_servers = 2
pm.min_spare_servers = 1
pm.max_spare_servers = 3
EOT;
$prefix = __DIR__;
$tester = new FPM\Tester($cfg, $src);
$tester->start(['--prefix', $prefix]);
$tester->expectLogStartNotices();
$tester->request(query: 'a=' . str_repeat('a', 1500))->expectBody('OK');
$tester->expectAccessLog("'GET /log-access-extended-limit.src.php?a=" . str_repeat('a', 1500) . "' 200");
$tester->request(query: 'a=' . str_repeat('a', 2040))->expectBody('OK');
$tester->expectAccessLog("'GET /log-access-extended-limit.src.php?a=" . str_repeat('a', 2002) . '...');
$tester->terminate();
$tester->expectLogTerminatingNotices();
$tester->close();
$tester->checkAccessLog();
?>
Done
--EXPECT--
Done
--CLEAN--
<?php
require_once "tester.inc";
FPM\Tester::clean();
?>