php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #77312 accel_replace_string_by_process_permanent: Assertion `0' failed
Submitted: 2018-12-17 15:48 UTC Modified: 2019-06-09 18:47 UTC
Votes:3
Avg. Score:4.7 ± 0.5
Reproduced:3 of 3 (100.0%)
Same Version:3 (100.0%)
Same OS:2 (66.7%)
From: sjon at hortensius dot net Assigned: bukka (profile)
Status: Closed Package: FPM related
PHP Version: 7.3.1 OS: archlinux
Private report: No CVE-ID: None
View Developer Edit
Welcome! If you don't have a Git account, you can't do anything here.
If you reported this bug, you can edit this bug over here.
(description)
Block user comment
Status: Assign to:
Package:
Bug Type:
Summary:
From: sjon at hortensius dot net
New email:
PHP Version: OS:

 

 [2018-12-17 15:48 UTC] sjon at hortensius dot net
Description:
------------
since my fpm childs started segfaulting I've installed a debug-build which yielded the given message. Since this is a production machine and this happens infrequently I would like to know how much (and what) context is required to fix this. The full message:

ext/opcache/ZendAccelerator.c:737: accel_replace_string_by_process_permanent: Assertion `0' failed.

this happens on only a subset of pools in the fpm configuration. It segfaults roughly once every ~ 100 hits and asserts roughly every hit


Patches

Pull Requests

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2018-12-18 15:43 UTC] bugs dot php dot net at mundpropaganda dot net
This might be related to bug #77289 which I reported earlier. I'm also using Archlinux. Crashes happen with official pkgs and manually compiled binaries.

Reading your report I did another run with a debug-enabled build (didn't think about enabling it before) and got these results:

Debug log:

[18-Dec-2018 16:32:26] WARNING: [pool amm-php73] child 30823 said into stderr: "3: /home/krist/tmp/php-7.3.0/Zend/zend_string.h:260: zend_string_free: Assertion `zend_gc_refcount(&(s)->gc) <= 1' failed."
[18-Dec-2018 16:32:27] WARNING: [pool amm-php73] child 30823 exited on signal 6 (SIGABRT - core dumped) after 9.728186 seconds from start

GDB backtrace:

Reading symbols from /opt/php/php-7.3/sbin/php-fpm...done.
[New LWP 30851]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".
Core was generated by `php-fpm: pool amm-php73                                                     '.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f43e1367d7f in raise () from /usr/lib/libc.so.6
(gdb) bt
#0  0x00007f43e1367d7f in raise () from /usr/lib/libc.so.6
#1  0x00007f43e1352672 in abort () from /usr/lib/libc.so.6
#2  0x00007f43e1352548 in __assert_fail_base.cold.0 () from /usr/lib/libc.so.6
#3  0x00007f43e1360396 in __assert_fail () from /usr/lib/libc.so.6
#4  0x000055e6e1fc1f49 in zend_string_free (s=0x7f43d7bdb4b0)
    at /home/krist/tmp/php-7.3.0/Zend/zend_string.h:260
#5  0x000055e6e1fc355c in zif_spl_autoload (execute_data=0x7f43e0a1fbb0,
    return_value=0x7ffed7d4a340) at /home/krist/tmp/php-7.3.0/ext/spl/php_spl.c:338
#6  0x000055e6e2280f1b in ZEND_DO_ICALL_SPEC_RETVAL_UNUSED_HANDLER ()
    at /home/krist/tmp/php-7.3.0/Zend/zend_vm_execute.h:645
#7  0x000055e6e22ee472 in execute_ex (ex=0x7f43e0a1fb20)
    at /home/krist/tmp/php-7.3.0/Zend/zend_vm_execute.h:55414
#8  0x000055e6e2201914 in zend_call_function (fci=0x7ffed7d4a680, fci_cache=0x7ffed7d4a660)
    at /home/krist/tmp/php-7.3.0/Zend/zend_execute_API.c:756
#9  0x000055e6e1fc3a47 in zif_spl_autoload_call (execute_data=0x7f43e0a1fac0,
    return_value=0x7ffed7d4a860) at /home/krist/tmp/php-7.3.0/ext/spl/php_spl.c:448
#10 0x000055e6e2201a01 in zend_call_function (fci=0x7ffed7d4a890, fci_cache=0x7ffed7d4a870)
    at /home/krist/tmp/php-7.3.0/Zend/zend_execute_API.c:770
#11 0x000055e6e22021d3 in zend_lookup_class_ex (name=0x7f43d7bdb4b0, key=0x0, use_autoload=1)
    at /home/krist/tmp/php-7.3.0/Zend/zend_execute_API.c:926
#12 0x000055e6e22022be in zend_lookup_class (name=0x7f43d7bdb4b0)
    at /home/krist/tmp/php-7.3.0/Zend/zend_execute_API.c:947
#13 0x000055e6e223b4b4 in zif_class_exists (execute_data=0x7f43e0a1fa60,
    return_value=0x7f43e0a1fa40) at /home/krist/tmp/php-7.3.0/Zend/zend_builtin_functions.c:1446
#14 0x000055e6e228113a in ZEND_DO_ICALL_SPEC_RETVAL_USED_HANDLER ()
    at /home/krist/tmp/php-7.3.0/Zend/zend_vm_execute.h:690
#15 0x000055e6e22ee47f in execute_ex (ex=0x7f43e0a1f030)
    at /home/krist/tmp/php-7.3.0/Zend/zend_vm_execute.h:55418
#16 0x000055e6e22f3aa5 in zend_execute (op_array=0x7f43e0a75000, return_value=0x0)
    at /home/krist/tmp/php-7.3.0/Zend/zend_vm_execute.h:60834
#17 0x000055e6e2219688 in zend_execute_scripts (type=8, retval=0x0, file_count=3)
    at /home/krist/tmp/php-7.3.0/Zend/zend.c:1568
#18 0x000055e6e217fbb6 in php_execute_script (primary_file=0x7ffed7d4d0c0)
    at /home/krist/tmp/php-7.3.0/main/main.c:2630
#19 0x000055e6e2306d91 in main (argc=3, argv=0x7ffed7d4d558)
    at /home/krist/tmp/php-7.3.0/sapi/fpm/fpm/fpm_main.c:1950

I hope this helps!
 [2018-12-27 17:05 UTC] lauri dot kentta at gmail dot com
I'm afraid that backtrace is for a different bug 77359 (for which I've sent a patch already).

It might be useful to get a backtrace of this specific problem and/or to see what variable str contains just before that assertion in ext/opcache/ZendAccelerator.c:737 (and to know what that value represents in the project, i.e. is it a function or a class name or what).
 [2019-01-07 19:29 UTC] lauri dot kentta at gmail dot com
This could be related to bug #77289. In that case, disabling persistent MySQL connections should fix it. Can you try that?
 [2019-01-09 08:50 UTC] sjon at hortensius dot net
@lauri thanks for trying - but we don't use persistent MySQL connections in our code. I also find it highly unlikely that could cause opcache errors
 [2019-01-09 09:05 UTC] nikic@php.net
Could you please provide a backtrace for the assertion failure? That way we'd know which string it is trying to replace.
 [2019-01-10 12:01 UTC] sjon at hortensius dot net
-Status: Open +Status: Closed
 [2019-01-10 12:01 UTC] sjon at hortensius dot net
This seems to be fixed in 7.3.1 - and while it happens frequently I cannot seem to obtain a coredump or get gdb to catch it - closing for now
 [2019-01-10 18:06 UTC] lauri dot kentta at gmail dot com
@sjon, GDB detaches from forked processes by default. You can use "set follow-fork-mode child" or "set detach-on-fork off" to debug the php-fpm child processes.

Also, just saying: since this bug was basically about a string not being found, it could have been the one I mentioned (which caused memory corruption and sometimes invalid string values). But no matter.
 [2019-01-11 09:03 UTC] sjon at hortensius dot net
@lauri thanks for the hint - I already did that and was still unsuccessful. I'm happy to see if it still happens in 7.3.1 and reopen this bug if it does
 [2019-01-15 12:08 UTC] sjon at hortensius dot net
-Status: Closed +Status: Assigned -PHP Version: 7.3.0 +PHP Version: 7.3.1
 [2019-01-15 12:08 UTC] sjon at hortensius dot net
Turns out FPM needed process.dumpable=true set as well to actually generate a coredump. Here is the backtrace after replacing the assert with a segfault:

#0  accel_replace_string_by_process_permanent (str=0x56100556b3c0) at ext/opcache/ZendAccelerator.c:737
#1  0x00007f2c06511144 in accel_copy_permanent_strings (new_interned_string=0x7f2c06511431 <accel_replace_string_by_process_permanent>) at ext/opcache/ZendAccelerator.c:689
#2  0x00007f2c06511540 in accel_use_permanent_interned_strings () at ext/opcache/ZendAccelerator.c:765
#3  0x00005610031b7bff in zend_interned_strings_switch_storage (request=0 '\000') at Zend/zend_string.c:322
#4  0x00005610030e0d1f in php_module_shutdown () at main/main.c:2473
#5  0x0000561003268912 in main (argc=4, argv=0x7ffdd655b968) at sapi/fpm/fpm/fpm_main.c:2004

This happens pretty frequently
 [2019-01-15 13:00 UTC] nikic@php.net
-Status: Assigned +Status: Re-Opened
 [2019-01-15 13:00 UTC] nikic@php.net
https://github.com/php/php-src/blob/PHP-7.3.1/ext/opcache/ZendAccelerator.c#L689

Failing to replace value of an ini directive.

In your core dump, can you please "f 2" and "p (char*)entry->key->val" and "p (char*)entry->value->val"? That should narrow down where this is happening.
 [2019-01-15 13:12 UTC] sjon at hortensius dot net
Thanks - I found in frame-1 that this is indeed an ini-setting - namely one that is pushed by nginx to fpm as PHP_ADMIN_VALUE (in our case upload_max_filesize)
 [2019-01-15 13:54 UTC] nikic@php.net
Okay, so I guess the problem here is that fpm alters the ini entry, but does not restore the old value. Right now PHP_ADMIN_VALUE ends up calling fpm_php_zend_ini_alter_master which directly touches ini directives, while it probably should go through the normal zend_alter_ini_entry API, which will also register it in modified_ini_directives, so that it will be restored after the request.
 [2019-01-15 14:13 UTC] nikic@php.net
-Status: Re-Opened +Status: Assigned -Package: opcache +Package: FPM related -Assigned To: +Assigned To: bukka
 [2019-01-15 14:13 UTC] nikic@php.net
This might do it: https://gist.github.com/nikic/c4c4ac241da02af410ce4f720c31d628

But fpm is really not my area... Maybe bukka could take a look?
 [2019-01-16 09:07 UTC] mnikulin at plesk dot com
The bug can be reproduced by accessing any php file even just

    <?php echo 10; ?>

Certainly, OpCache must be enabled in php.ini

    zend_extension=opcache.so
    opcache.enable=1

It happens during child exit, so simple way to reproduce
is to set short timeout for on-demand manager in a pool .conf file

    pm = ondemand
    pm.process_idle_timeout = 2s
    catch_workers_output = yes
    php_value[error_reporting] = 22519

Unsure which bits of error_reporting should be set.

The pool name in log messages after "child 9958 said into stderr" may be truncated.
 [2019-01-16 13:10 UTC] sjon at hortensius dot net
thanks, I've tried your patch (combined with the patch posted in #77430 ) but I did see another segfault with a similar backtrace - this time not for an entry set by nginx through fastcgi, but a setting that's directly configured in the php-fpm pool configuration through php_admin_value. 

That seems to go through this code: https://github.com/php/php-src/blob/1ad08256f349fa513157437abc4feb245cce03fc/sapi/fpm/fpm/fpm_php.c#L127 maybe that requires the same fix ?
 [2019-01-24 14:03 UTC] bukka@php.net
From a quick look I agree that we should use zend_alter_ini_entry_ex instead. However I would use it in fpm_php_apply_defines_ex and call it instead of fpm_php_zend_ini_alter_master which could be then dropped. That would also keep extension and disable_{functions,classes} working.
 [2019-01-24 14:09 UTC] nikic@php.net
I'm no longer sure if using zend_alter_ini_entry is right in this context, I think it may break the ini_restore() functionality. (Which should probably restore to the ini value specified through php_value).
 [2019-01-24 14:26 UTC] bukka@php.net
Ok I guess it will probably need a longer look then :)
 [2019-01-27 16:49 UTC] bukka@php.net
-Assigned To: bukka +Assigned To: dmitry
 [2019-01-27 16:49 UTC] bukka@php.net
I don't have much time to look what Opcache exactly does so re-assigning to Dmitry as he might have a better idea what to do and what's the best approach.

I can just comment on the FPM behaviour and requirements. Basically the ini values are set in the following cases:

* if php_value or php_admin_value is set in the FPM config, then the ini is modified on child init (it means when the process is created and ready to handle requests - it means it can handle multiple requests and should be the for the whole child life)
* if FCGI request sets PHP_VALUE or PHP_ADMIN_VALUE envs, then it is modified as well (from the code it looks that this should actually stay set for all other requests in the child even if the PHP_VALUE or PHP_ADMIN_VALUE are no longer set).

So it means that FPM needs a way to set an ini in the process that won't get changed. I'm thinking that it might make sense to either save it as an original or maybe create another field for the permanently modified ini values. Not really sure though.
 [2019-02-03 19:47 UTC] bukka@php.net
-Assigned To: dmitry +Assigned To: bukka
 [2019-02-03 19:47 UTC] bukka@php.net
I started playing with that and used zend_alter_ini_entry_ex. Just replacement will not work correctly as discussed because it returns the original value. However if it was moved and done before each request then it might work. Just need to find a clean way how to get the worker pool in main request init - basically come up with some clean implementation. Will try again next week so assigned it back to myself as it looks that Dmitry is busy anyway.
 [2019-04-17 19:13 UTC] dmitry@php.net
This should fix the problem.

https://github.com/php/php-src/commit/bfadd9fdaf46dd9d9d447de38820122383af9c71 

Please, verify and close the bug.
 [2019-04-19 07:31 UTC] sjon at hortensius dot net
thanks for your fix dmitry. However, this problem no longer occurs since (roughly) 7.3.2 so it's hard for me to verify the correctness of your change.
 [2019-04-22 17:31 UTC] bukka@php.net
-Status: Assigned +Status: Closed
 [2019-04-22 17:31 UTC] bukka@php.net
I was able to recreate before the commit in 7.3.5-dev. I tested after the commit and it really seems to be fixed now! Thanks Dmitry! Closing!
 [2019-05-15 08:38 UTC] swen dot zanon at geoglis dot de
I get this error message when I run the Zend bench-script Zend/bench.php under PHP 7.3.5

(gdb) run -f /usr/src/php-7.3.5/Zend/bench.php
Starting program: /usr/local/bin/php -f /usr/src/php-7.3.5/Zend/bench.php
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
simple             0.055
simplecall         0.026
simpleucall        0.028
simpleudcall       0.028
mandel             0.301
mandel2            0.403
ackermann(7)       0.179
ary(50000)         0.026
ary2(50000)        0.016
ary3(2000)         0.303
fibo(30)           0.492
hash1(50000)       0.089
hash2(500)         0.068
heapsort(20000)    0.142
matrix(20)         0.165
nestedloop(12)     0.159
sieve(30)          0.098
strcat(200000)     0.032
------------------------
Total              2.610
php: /usr/src/php-7.3.5/ext/opcache/ZendAccelerator.c:747: accel_replace_string_by_process_permanent: Assertion `0' failed.

Program received signal SIGABRT, Aborted.

(gdb) backtrace
#0  0x00007ffff3b20f67 in raise () from /lib64/libc.so.6
#1  0x00007ffff3b2233a in abort () from /lib64/libc.so.6
#2  0x00007ffff3b19d66 in __assert_fail_base () from /lib64/libc.so.6
#3  0x00007ffff3b19e12 in __assert_fail () from /lib64/libc.so.6
#4  0x00007ffff1143c71 in accel_replace_string_by_process_permanent (str=0x7fffe2d022e0) at /usr/src/php-7.3.5/ext/opcache/ZendAccelerator.c:747
#5  0x00007ffff114349f in accel_copy_permanent_strings (new_interned_string=0x7ffff1143c1d <accel_replace_string_by_process_permanent>)
    at /usr/src/php-7.3.5/ext/opcache/ZendAccelerator.c:649
#6  0x00007ffff1143d3b in accel_use_permanent_interned_strings () at /usr/src/php-7.3.5/ext/opcache/ZendAccelerator.c:775
#7  0x0000000000b39a29 in zend_interned_strings_switch_storage (request=0 '\000') at /usr/src/php-7.3.5/Zend/zend_string.c:322
#8  0x0000000000a6f4ba in php_module_shutdown () at /usr/src/php-7.3.5/main/main.c:2473
#9  0x0000000000bd4177 in main (argc=3, argv=0x180e1c0) at /usr/src/php-7.3.5/sapi/cli/php_cli.c:1404


So does this bug still exists in version 7.3.5 or is it a different one?
 [2019-06-09 18:47 UTC] bukka@php.net
@swen I think it ended up in 7.3.6 by the tag visible in the github for that commit but not 100% sure. Please update this but if you still see it in 7.3.6.
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved.
Last updated: Thu Nov 14 02:01:30 2024 UTC