FPM logs are getting corrupted with this log statement.

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

@HeenaBansal20

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).

@devnexen

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);

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).

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.

Is php compiled with ZTS ?

Merge branch 'PHP-8.4'

Will this fix won't be back ported to 8.1. and 8.0 ?

8.0 and 8.1 are out of bugfix support, so the fix is only in 8.2, 8.3, 8.4.

Building 8.4.0RC4 and 8.3.14RC1 for Alpinelinux this test failed on all arches, probably it needs new issue but the log is full of debug information

16665+ [05-Nov-2024 17:50:35.002680] DEBUG: pid 43132, fpm_pctl_perform_idle_server_maintenance(), line 398: [pool unconfined] currently 0 active children, 1 spare children, 1 running children. Spawning rate 1
16666+ [05-Nov-2024 17:50:36.003728] DEBUG: pid 43132, fpm_pctl_perform_idle_server_maintenance(), line 398: [pool unconfined] currently 0 active children, 1 spare children, 1 running children. Spawning rate 1
16667+ --------------------------------------------------------------------
16668+ 
       Done
========DONE========
FAIL GH-16628 (FPM logs are getting corrupted with this log statement) [sapi/fpm/tests/gh16628.phpt]

@andypost

@andypost At the top of the log it complains that zend_test_log_err_debug is not found, but we declare to load that extension here:

php-src/sapi/fpm/tests/gh16628.phpt

Line 4 in 24a4cb2

zend_test

Our own Alpine job also succeeds: https://github.com/php/php-src/actions/runs/11675875670/job/32511214414
Are you using an old version of zend_test in your build?

Yes, there's --enable-zend-test=shared https://gitlab.alpinelinux.org/alpine/aports/-/blob/5ce837c7253059758fdf6d5b26a2e506100f67d1/testing/php84/APKBUILD#L327

Then I don't know why it's not defined for you. It's clearly working for us and the function is defined.

I guess somehow zend_test extension is not enabled for started fpm

very probably the same as #9854

Ok I see, thanks for finding that. I'll get a patch up.

See #16705

Navigation Menu

Repository navigation

FPM logs are getting corrupted with this log statement. #16628

Description

PHP Version

Operating System

25 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

FPM logs are getting corrupted with this log statement. #16628

Description

Description

PHP Version

Operating System

Activity

devnexen commented on Oct 28, 2024

HeenaBansal20 commented on Oct 28, 2024

devnexen commented on Oct 28, 2024

HeenaBansal20 commented on Oct 28, 2024

devnexen commented on Oct 28, 2024

25 remaining items

HeenaBansal20 commented on Nov 4, 2024

ndossche commented on Nov 4, 2024

andypost commented on Nov 5, 2024

ndossche commented on Nov 5, 2024

andypost commented on Nov 5, 2024

ndossche commented on Nov 5, 2024

andypost commented on Nov 5, 2024

andypost commented on Nov 5, 2024

ndossche commented on Nov 5, 2024

ndossche commented on Nov 5, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions