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

zlog_buf_prefix() can return a larger length than what actually was
written due to its use of snprintf(). The code in
zlog_stream_prefix_ex() does not take this into account, other callers
do. What ends up happening then is that stream->length is set to the
length as if snprintf() was able to write all bytes, causing
stream->length to become larger than stream->buf.size, causing a
segfault.

In case the buffer was too small we try with a larger buffer up to a
limit of zlog_limit. This makes sure that the stream length will remain
bounded by the buffer size.

This also adds assertions to make the programmer intent clear and catch
this more easily in debug builds.

Closes GH-16680.

NEWS

@@ -54,6 +54,10 @@ PHP                                                                        NEWS
 - Filter:
   . Fixed bug GH-16523 (FILTER_FLAG_HOSTNAME accepts ending hyphen). (cmb)
 
+- FPM:
+  . Fixed bug GH-16628 (FPM logs are getting corrupted with this log
+    statement). (nielsdos)
+
 - GD:
   . Fixed bug GH-16334 (imageaffine overflow on matrix elements).
     (David Carlier)

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_override_libxml_global_state(): 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 {

ext/zend_test/test_arginfo.h

@@ -1,5 +1,5 @@
 /* This is a generated file, edit the .stub.php file instead.
- * Stub hash: 5d861e05edfd57c385167b11b8b1ea977ed130a2 */
+ * Stub hash: 1c6384894b21ff02bbc3d6088440de6616878a7d */
 
 ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_zend_test_array_return, 0, 0, IS_ARRAY, 0)
 ZEND_END_ARG_INFO()
@@ -126,6 +126,10 @@ ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_zend_test_is_zend_ptr, 0, 1, _IS
 	ZEND_ARG_TYPE_INFO(0, addr, IS_LONG, 0)
 ZEND_END_ARG_INFO()
 
+ZEND_BEGIN_ARG_WITH_RETURN_TYPE_INFO_EX(arginfo_zend_test_log_err_debug, 0, 1, IS_VOID, 0)
+	ZEND_ARG_TYPE_INFO(0, str, IS_STRING, 0)
+ZEND_END_ARG_INFO()
+
 #define arginfo_ZendTestNS2_namespaced_func arginfo_zend_test_is_pcre_bundled
 
 #define arginfo_ZendTestNS2_namespaced_deprecated_func arginfo_zend_test_void_return
@@ -237,6 +241,7 @@ static ZEND_FUNCTION(zend_test_set_fmode);
 #endif
 static ZEND_FUNCTION(zend_test_cast_fread);
 static ZEND_FUNCTION(zend_test_is_zend_ptr);
+static ZEND_FUNCTION(zend_test_log_err_debug);
 static ZEND_FUNCTION(ZendTestNS2_namespaced_func);
 static ZEND_FUNCTION(ZendTestNS2_namespaced_deprecated_func);
 static ZEND_FUNCTION(ZendTestNS2_ZendSubNS_namespaced_func);
@@ -302,6 +307,7 @@ static const zend_function_entry ext_functions[] = {
 #endif
 	ZEND_FE(zend_test_cast_fread, arginfo_zend_test_cast_fread)
 	ZEND_FE(zend_test_is_zend_ptr, arginfo_zend_test_is_zend_ptr)
+	ZEND_FE(zend_test_log_err_debug, arginfo_zend_test_log_err_debug)
 	ZEND_NS_FALIAS("ZendTestNS2", namespaced_func, ZendTestNS2_namespaced_func, arginfo_ZendTestNS2_namespaced_func)
 	ZEND_NS_DEP_FALIAS("ZendTestNS2", namespaced_deprecated_func, ZendTestNS2_namespaced_deprecated_func, arginfo_ZendTestNS2_namespaced_deprecated_func)
 	ZEND_NS_FALIAS("ZendTestNS2", namespaced_aliased_func, zend_test_void_return, arginfo_ZendTestNS2_namespaced_aliased_func)

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);
+		len = zlog_buf_prefix(function, line, stream->flags, sbuf, sizeof(sbuf), stream->use_syslog);
-		written = zlog_stream_direct_write(stream, sbuf, len);
+		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();
+?>