From b7041cef74708fd8da34aab4581c6871219cfca4 Mon Sep 17 00:00:00 2001 From: Niels Dossche <7771979+nielsdos@users.noreply.github.com> Date: Sat, 2 Nov 2024 12:59:52 +0100 Subject: [PATCH] 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. --- ext/zend_test/test.c | 11 ++++++++ ext/zend_test/test.stub.php | 2 ++ ext/zend_test/test_arginfo.h | 8 +++++- sapi/fpm/fpm/zlog.c | 19 +++++++++++-- sapi/fpm/tests/gh16628.phpt | 53 ++++++++++++++++++++++++++++++++++++ 5 files changed, 90 insertions(+), 3 deletions(-) create mode 100644 sapi/fpm/tests/gh16628.phpt diff --git a/ext/zend_test/test.c b/ext/zend_test/test.c index 55e21a6c40a5..100ef25800f9 100644 --- a/ext/zend_test/test.c +++ b/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); diff --git a/ext/zend_test/test.stub.php b/ext/zend_test/test.stub.php index 8a605bdcd328..547e82d60ca2 100644 --- a/ext/zend_test/test.stub.php +++ b/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 { diff --git a/ext/zend_test/test_arginfo.h b/ext/zend_test/test_arginfo.h index 9c0735a1d6f8..bd86f090ff10 100644 --- a/ext/zend_test/test_arginfo.h +++ b/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) diff --git a/sapi/fpm/fpm/zlog.c b/sapi/fpm/fpm/zlog.c index e5e49f8385d2..232f0cb1b2b2 100644 --- a/sapi/fpm/fpm/zlog.c +++ b/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); diff --git a/sapi/fpm/tests/gh16628.phpt b/sapi/fpm/tests/gh16628.phpt new file mode 100644 index 000000000000..e2df0c8cb84d --- /dev/null +++ b/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-- + +--FILE-- +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-- +