FPM logs are getting corrupted with this log statement.

[HeenaBansal20]

Description

This crash is happening in all versions PHP 7.4 - PHP 8.3
The log is attached from PHP 7.4
The following code:

        php_log_err_with_severity(logmessage.c_str(), LOG_DEBUG);

Resulted in this output: SIGSEGV

#10 _int_malloc (av=av@entry=0x7f69f99e9b80 <main_arena>, bytes=bytes@entry=56) at malloc.c:3742
#11 0x00007f69f9897154 in __GI___libc_malloc (bytes=bytes@entry=56) at malloc.c:3058
#12 0x000056318b7291e9 in zlog_stream_buf_alloc_ex (stream=stream@entry=0x7ffca5e1c960, needed=needed@entry=0) at /root/php-7.4.33/sapi/fpm/fpm/zlog.c:295
#13 0x000056318b72a10d in zlog_stream_buf_alloc (stream=0x7ffca5e1c960) at /root/php-7.4.33/sapi/fpm/fpm/zlog.c:315
#14 zlog_stream_prefix_ex (stream=stream@entry=0x7ffca5e1c960, function=function@entry=0x56318beb8380 <__func__.24189> "sapi_cgi_log_message", 
    line=line@entry=618) at /root/php-7.4.33/sapi/fpm/fpm/zlog.c:681
#15 0x000056318b72c081 in zlog_msg_ex (function=0x56318beb8380 <__func__.24189> "sapi_cgi_log_message", line=618, flags=2, 
    prefix=0x56318beb7518 "PHP message: ", msg=0x56318d7fabe0 “[abcdef.LL_Debug:500517] keywords:") at /root/php-7.4.33/sapi/fpm/fpm/zlog.c:275
#16 0x000056318b3842f5 in php_log_err_with_severity (log_message=0x56318d7fabe0 “[abcdef.LL_Debug:500517] keywords:", syslog_type_int=7)
    at /root/php-7.4.33/main/main.c:944
#17 0x00007f69f65eeb01 in my class::Logger::Flush() () from /usr/local/php-nts/lib/php/extensions/no-debug-non-zts-20190902/abcdef.so
#18 0x00007f69f9891ad0 in __run_fork_handlers (who=<optimized out>, who@entry=atfork_run_prepare, do_locking=do_locking@entry=false)
    at register-atfork.c:123
#19 0x00007f69f98dff14 in __libc_fork () at ../sysdeps/nptl/fork.c:58
#20 0x000056318b7196ed in fpm_children_make (wp=wp@entry=0x56318d7f9310, in_event_loop=in_event_loop@entry=0, nb_to_spawn=nb_to_spawn@entry=0, 
    is_debug=is_debug@entry=1) at /root/php-7.4.33/sapi/fpm/fpm/fpm_children.c:412
#21 0x000056318b719f0b in fpm_children_create_initial (wp=wp@entry=0x56318d7f9310) at /root/php-7.4.33/sapi/fpm/fpm/fpm_children.c:471
#22 0x000056318b719480 in fpm_run (max_requests=0x7ffca5e1cdbc) at /root/php-7.4.33/sapi/fpm/fpm/fpm.c:99
#23 0x000056318b3a3d4d in main (argc=4, argv=0x7ffca5e1d2f8) at /root/php-7.4.33/sapi/fpm/fpm/fpm_main.c:1854

But I expected this output instead:
NO Crash

PHP Version

PHP 8.3

Operating System

No response

[devnexen]

Hi @HeenaBansal20 is it a C++ extension of yours ? Would it be possible to see more code if that s fine with you ? it is difficult to assess the root cause, it can be a lot of different things (e.g. this std::string lifetime).

[HeenaBansal20]

Hi @devnexen ,
Just to mention, this is not occurring all the time and I have seen crashing a different log messages.
for example LOG("qsbdksjadhfgdk");
We have seen instances ,when it crashes at when I am trying to print hash table values too
For example:
where list is a extension global hahstable and created using pmalloc and its values are populated using _ZVAL_PSTRINGLI()and idx , key and zval are of size_t idx , zend_string* key , zval* value ;

ZEND_HASH_FOREACH_KEY_VAL( list, idx, key, value)
{
LOG("- %s", Z_STRVAL_P(value));
}
ZEND_HASH_FOREACH_END();

From implementation perspective , I am using internal macro which reads these log messages and store it in a vector which gets flushed on need basis.

So, I use very typical way of collecting all log messages in vector using std::vsnprintf.

std::va_list args1;
 va_start(args1, formatString);
 std::va_list args2;
 va_copy(args2, args1);
 const auto len = std::vsnprintf(nullptr, 0, logString, args1);
 va_end(args1);
 std::string message(len, 0);
 const auto written = std::vsnprintf(message.data(), message.size() + 1, logString, args2);
 va_end(args2);

Then i flush the whole vector time to time , the very flush happens at before forking() and this is when it is crashing. The observed behavior is that it print few log messages correctly and then it dumps with above stack trace.

Then we iterate over the vector to flush the buffer .

 const auto buffer = std::invoke([this] {
     const std::lock_guard logmessageGuard(logmutex);
     return std::exchange(logBuffer, {});
 });

for (const auto& [level, message] : buffer) {
     const auto logmessage = std::format("[{}:{}] {}", magic_enum::enum_name(level), getpid(), message);
     const auto* logMessagePtr = logmessage.c_str();
     php_log_err_with_severity(logessagePtr, LOG_DEBUG);

[devnexen]

std::va_list args1;
 va_start(args1, formatString);
 std::va_list args2;
 va_copy(args2, args1);
 const auto len = std::vsnprintf(nullptr, 0, logString, args1);
 va_end(args1);
 std::string message(len, 0);
 const auto written = std::vsnprintf(message.data(), message.size() + 1, logString, args2);
 va_end(args2);

Just a quick look here, I see a tiny issue in this part. You re allocating a buffer of len then doing message.size() + 1. I would suggest the other way around (especially you are filling it with \0 anyway).

std::string message(len + 1, 0);
const auto written = std::vsnprintf(message.data(), message.size(), logString, args2);

I assume you re using modern C++ standard ? (ie >= C++17).

[HeenaBansal20]

std::va_list args1;
 va_start(args1, formatString);
 std::va_list args2;
 va_copy(args2, args1);
 const auto len = std::vsnprintf(nullptr, 0, logString, args1);
 va_end(args1);
 std::string message(len, 0);
 const auto written = std::vsnprintf(message.data(), message.size() + 1, logString, args2);
 va_end(args2);

Just a quick look here, I see a tiny issue in this part. You re allocating a buffer of len then doing message.size() + 1. I would suggest the other way around (especially you are filling it with \0 anyway).

std::string message(len + 1, 0);
const auto written = std::vsnprintf(message.data(), message.size(), logString, args2);

I assume you re using modern C++ standard ? (ie >= C++17).

Thanks for the quick response. Yes we are using C++18 and I tested this way before as well as suggested but it still crashes on the same place.

[devnexen]

Is php compiled with ZTS ?