PHP-FPM: “NOTICE: the log buffer is full (1024). The access log request has been truncated.”

Running the official php:7.3-fpm-alpine Docker image. I'm getting the following output on the console: NOTICE: the log buffer is full (1024). The access log request has been truncated.

A custom access.format is configured in the www.conf config. Additionally, the following config is set inside php-fpm.conf:

log_limit = 32768
log_buffering = yes

To be able to write logs that are longer than 1024 characters on a single line, as described in the PHP documentation.

Otherwise the defaults are used.

This is needed because the logs are read from stdout & stderr line-by-line and stashed in a central logging tool. So a single log message might not be broken up into multiple lines.

Example request where PHP-FPM prints a few log messages, one per line:

{"Timestamp":"2020-05-20T08:06:43+0000","MessageTemplate":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36","Properties":{"level":"ERROR","message":"File public//media/svg/2020-03/icon_info.svg (ID 44) does not exists in filesystem.","channel":"file","referer":"","request_uri":"https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url","user_id":"1","user":"admin","memory_usage":"16 MB"}}

{"Timestamp":"2020-05-20T08:06:44+0000","MessageTemplate":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36","Properties":{"level":"ERROR","message":"File public//media/svg/2020-03/icon_info.svg (ID 44) does not exists in filesystem.","channel":"file","referer":"","request_uri":"https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url","user_id":"1","user":"admin","memory_usage":"16 MB"}}

{"Timestamp":"2020-05-20T08:06:48+0000","MessageTemplate":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36","Properties":{"level":"ERROR","message":"File public//media/svg/2019-09/safari-pinned-tab.svg (ID 21) does not exists in filesystem.","channel":"file","referer":"","request_uri":"https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url","user_id":"1","user":"admin","memory_usage":"26 MB"}}

{"Timestamp":"2020-05-20T08:06:48+0000","MessageTemplate":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36","Properties":{"level":"ERROR","message":"File public//media/svg/2019-09/safari-pinned-tab.svg (ID 21) does not exists in filesystem.","channel":"file","referer":"","request_uri":"https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url","user_id":"1","user":"admin","memory_usage":"26 MB"}}

{"Timestamp":"2020-05-20T08:06:48+0000","MessageTemplate":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36","Properties":{"level":"ERROR","message":"File public//media/svg/2019-09/safari-pinned-tab.svg (ID 21) does not exists in filesystem.","channel":"file","referer":"","request_uri":"https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url","user_id":"1","user":"admin","memory_usage":"26 MB"}}

{"Timestamp":"2020-05-20T08:06:49+0000","MessageTemplate":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36","Properties":{"level":"ERROR","message":"File public//media/svg/2019-09/safari-pinned-tab.svg (ID 21) does not exists in filesystem.","channel":"file","referer":"","request_uri":"https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url","user_id":"1","user":"admin","memory_usage":"26 MB"}}

{"Timestamp":"2020-05-20T08:06:50+0000","MessageTemplate":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36","Properties":{"level":"ERROR","message":"File public//media/svg/2019-09/safari-pinned-tab.svg (ID 21) does not exists in filesystem.","channel":"file","referer":"","request_uri":"https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url","user_id":"1","user":"admin","memory_usage":"26 MB"}}

{"Timestamp": "2020-05-20T08:06:51+0000", "MessageTemplate": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36", "Properties": {"level": "INFO", "channel": "php-fpm", "type": "access",  "remote_address":"172.20.0.6", "host": "localhost", "method": "GET", "url":"GET /long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url

NOTICE: the log buffer is full (1024). The access log request has been truncated.

{"Timestamp": "2020-05-20T08:06:53+0000", "MessageTemplate": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.138 Safari/537.36", "Properties": {"level": "INFO", "channel": "php-fpm", "type": "access",  "remote_address":"172.20.0.6", "host": "localhost", "method": "GET", "url":"GET /de/api/cookie-banner", "server_protocol": "HTTP/2.0", "status_code": "200", "referrer": "https://localhost/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/long-url/

NOTICE: the log buffer is full (1024). The access log request has been truncated.

NOTICE: the log buffer is full (1024). The access log request has been truncated.

The first log entry - which is displayed correctly - has 1811 chars, so more than 1024 chars and more than 1024 bytes. The last two log messages are truncated and the buffer full message printed. I also tried turning log_buffering = yes off, but didn't have any effect on this behaviour.

Is there any way to prevent this? To have the full logs, without them being truncated.

Edit: Only affects access logs. Logs that are written by the application work.

The message is written here: https://github.com/php/php-src/blob/master/sapi/fpm/fpm/fpm_log.c#L153 and the log buffer size defined here: https://github.com/php/php-src/blob/master/sapi/fpm/fpm/fpm_log.c#L25 I couldn't find any definitions of MAX_LINE_LENGTH in the repository. Also compiled it and searched for MAX_LINE_LENGTH, without results.

Solution 1:

I have patched the PHP source and compiled it myself.

Increased the value of the MAX_LINE_LENGTH constant to 8192. Now PHP-FPM access logs that are longer than 1024 characters also work.

Patch used:

diff --git a/sapi/fpm/fpm/fpm_log.c b/sapi/fpm/fpm/fpm_log.c
index a09e80a490..63cd221ce9 100644
--- a/sapi/fpm/fpm/fpm_log.c
+++ b/sapi/fpm/fpm/fpm_log.c
@@ -19,11 +19,7 @@
 #include "fastcgi.h"
 #include "zlog.h"
 
-#ifdef MAX_LINE_LENGTH
-# define FPM_LOG_BUFFER MAX_LINE_LENGTH
-#else
-# define FPM_LOG_BUFFER 1024
-#endif
+# define FPM_LOG_BUFFER 8192
 
 static char *fpm_log_format = NULL;
 static int fpm_log_fd = -1;

Issue at PHP-src: https://github.com/php/php-src/pull/5634

PHP-FPM: “NOTICE: the log buffer is full (1024). The access log request has been truncated.”

Solution 1:

Related

Recent Posts