Fix GH-16628: FPM logs are getting corrupted with this log statement

ext/zend_test/test.c

@@ -639,6 +639,17 @@ static ZEND_FUNCTION(zend_test_is_zend_ptr)
 	RETURN_BOOL(is_zend_ptr((void*)addr));
 }
 
+static ZEND_FUNCTION(zend_test_log_err_debug)
+{
+	zend_string *str;
+
+	ZEND_PARSE_PARAMETERS_START(1, 1)
+		Z_PARAM_STR(str);
+	ZEND_PARSE_PARAMETERS_END();
+
+	php_log_err_with_severity(ZSTR_VAL(str), LOG_DEBUG);
+}
+
 static zend_object *zend_test_class_new(zend_class_entry *class_type)
 {
 	zend_object *obj = zend_objects_new(class_type);

ext/zend_test/test.stub.php

@@ -196,6 +196,8 @@ function zend_test_set_fmode(bool $binary): void {}
     function zend_test_cast_fread($stream): void {}
 
     function zend_test_is_zend_ptr(int $addr): bool {}
+
+    function zend_test_log_err_debug(string $str): void {}
 }
 
 namespace ZendTestNS {

sapi/fpm/fpm/zlog.c

@@ -150,6 +150,7 @@ static inline void zlog_external(
 }
 /* }}} */
 
+/* Returns the length if the print were complete, this can be larger than buf_size. */
 static size_t zlog_buf_prefix(
 		const char *function, int line, int flags,
 		char *buf, size_t buf_size, int use_syslog) /* {{{ */
@@ -186,6 +187,7 @@ static size_t zlog_buf_prefix(
 		}
 	}
 
+	/* Important: snprintf returns the number of bytes if the print were complete. */
 	return len;
 }
 /* }}} */
@@ -408,6 +410,7 @@ 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) /* {{{ */
 {
+	ZEND_ASSERT(stream->len <= stream->buf.size);
 	if (stream->buf.size - stream->len <= str_len &&
 			!zlog_stream_buf_alloc_ex(stream, str_len + stream->len)) {
 		return -1;
@@ -422,6 +425,7 @@ static inline ssize_t zlog_stream_buf_copy_cstr(
 
 static inline 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)) {
 		return -1;
 	}
@@ -678,6 +682,17 @@ ssize_t zlog_stream_prefix_ex(struct zlog_stream *stream, const char *function,
 		len = zlog_buf_prefix(
 				function, line, stream->flags,
 				stream->buf.data, stream->buf.size, stream->use_syslog);
+		if (!EXPECTED(len + 1 <= stream->buf.size)) {
+			/* If the buffer was not large enough, try with a larger buffer.
+			 * Note that this may still truncate if the zlog_limit is reached. */
+			len = MIN(len + 1, zlog_limit);
+			if (!zlog_stream_buf_alloc_ex(stream, len)) {
+				return -1;
+			}
+			zlog_buf_prefix(
+				function, line, stream->flags,
+				stream->buf.data, stream->buf.size, stream->use_syslog);
+		}
 		stream->len = stream->prefix_len = len;
 		if (stream->msg_prefix != NULL) {
 			zlog_stream_buf_copy_cstr(stream, stream->msg_prefix, stream->msg_prefix_len);
@@ -689,8 +704,8 @@ ssize_t zlog_stream_prefix_ex(struct zlog_stream *stream, const char *function,
 	} else {
 		char sbuf[1024];
 		ssize_t written;
-		len = zlog_buf_prefix(function, line, stream->flags, sbuf, 1024, stream->use_syslog);
-		written = zlog_stream_direct_write(stream, sbuf, len);
+		len = zlog_buf_prefix(function, line, stream->flags, sbuf, sizeof(sbuf), stream->use_syslog);
+		written = zlog_stream_direct_write(stream, sbuf, MIN(len, sizeof(sbuf)));
 		if (stream->msg_prefix != NULL) {
 			written += zlog_stream_direct_write(
 					stream, stream->msg_prefix, stream->msg_prefix_len);

sapi/fpm/tests/gh16628.phpt

@@ -0,0 +1,53 @@
+--TEST--
+GH-16628 (FPM logs are getting corrupted with this log statement)
+--EXTENSIONS--
+zend_test
+--SKIPIF--
+<?php include "skipif.inc"; ?>
+--FILE--
+<?php
+
+require_once "tester.inc";
+
+$cfg = <<<EOT
+[global]
+error_log = {{FILE:LOG}}
+log_level = debug
+[unconfined]
+listen = {{ADDR}}
+pm = dynamic
+pm.max_children = 5
+pm.start_servers = 1
+pm.min_spare_servers = 1
+pm.max_spare_servers = 3
+catch_workers_output = yes
+decorate_workers_output = no
+EOT;
+
+$code = <<<'EOT'
+<?php
+for ($i = 1; $i < 100; $i++) {
+	zend_test_log_err_debug(str_repeat("a", $i));
+}
+EOT;
+
+$tester = new FPM\Tester($cfg, $code);
+$tester->start();
+$tester->expectLogStartNotices();
+$tester->request()->expectEmptyBody();
+for ($i = 1; $i < 100; $i++) {
+    $tester->expectLogNotice("%sPHP message: " . str_repeat("a", $i));
+}
+$tester->terminate();
+$tester->expectLogTerminatingNotices();
+$tester->close();
+
+?>
+Done
+--EXPECT--
+Done
+--CLEAN--
+<?php
+require_once "tester.inc";
+FPM\Tester::clean();
+?>