Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PHP8.1.3. opcache bug with monolog/monolog #8164

Closed
R4c00n opened this issue Mar 2, 2022 · 31 comments
Closed

PHP8.1.3. opcache bug with monolog/monolog #8164

R4c00n opened this issue Mar 2, 2022 · 31 comments

Comments

@R4c00n
Copy link

R4c00n commented Mar 2, 2022

Description

Using monolog/monolog on PHP8.1.3 results in some very weird problems with the class vendor/monolog/monolog/src/Monolog/DateTimeImmutable.php not being found.
There's also already a bugreport in monolog Seldaek/monolog#1626, but it looks like this is an opcache bug.

Our deployment process looks like this:

  • Upload files to server into release directory
  • symlink release directory
  • reset opcache (opcache_reset)

After that, we get the PHP message: PHP Fatal error: Uncaught Error: Class "Monolog\DateTimeImmutable" not found in ... error.
Resetting opcache a second time fixes the bug and everything is fine until the next deployment.

PHP Version

PHP 8.1.3

Operating System

Debian

@R4c00n
Copy link
Author

R4c00n commented Mar 2, 2022

Also: With PHP7.4 and same opcache settings the same workflow & code is working

@cmb69
Copy link
Member

cmb69 commented Mar 2, 2022

Is a file cache involved?

@R4c00n
Copy link
Author

R4c00n commented Mar 2, 2022

All file_cache settings are on default, so should be turned off.

; ...
;opcache.file_cache=

; Enables or disables opcode caching in shared memory.
;opcache.file_cache_only=0

; Enables or disables checksum validation when script loaded from file cache.
;opcache.file_cache_consistency_checks=1

; Implies opcache.file_cache_only=1 for a certain process that failed to
; reattach to the shared memory (for Windows only). Explicitly enabled file
; cache is required.
;opcache.file_cache_fallback=1
; ...

@cmb69
Copy link
Member

cmb69 commented Mar 2, 2022

Thanks for the further info! Did you check the return value of opcache_reset() (i.e. did it return true?) Are there any relevant messages in opcache.error_log (please also check with opcache.log_verbosity_level=4).

@temp
Copy link

temp commented Mar 2, 2022

Same problem here, no file cache, will check with log and verbosity.

@R4c00n
Copy link
Author

R4c00n commented Mar 3, 2022

opcache_reset returns true, both during release and also when executing manually
The logs also look good.

Here are some logs with grep for the file in question:
After release (when it's broken) we get:

Thu Mar  3 10:51:49 2022 (24268): Message Cached script '/home/xxx/release-2882/vendor/monolog/monolog/src/Monolog/DateTimeImmutable.php'
Thu Mar  3 10:51:49 2022 (24268): Message Added key '/home/xxx/release-2882/vendor/composer/../monolog/monolog/src/Monolog/DateTimeImmutable.php'

After manual reset (when it works again) this gets added:

Thu Mar  3 10:57:23 2022 (24272): Message Cached script '/home/xxx/release-2882/vendor/monolog/monolog/src/Monolog/DateTimeImmutable.php'
Thu Mar  3 10:57:23 2022 (24272): Message Added key '/home/xxx/release-2882/vendor/composer/../monolog/monolog/src/Monolog/DateTimeImmutable.php'

@cmb69
Copy link
Member

cmb69 commented Mar 3, 2022

Thanks! First, it is important to understand that when opcache_reset() returns, the SHM cache has not necessarily been reset; it may take up to opcache.force_restart_timeout seconds for the reset to actually happen. This might cause issues when a new deployment just switches symlinks. For a more robust way to deploy a new app version, see http://blog.jpauli.tech/2015-03-05-opcache-html/#understandingtheopcachememoryconsumption.

Since in this case the issue apparently happens as of PHP 8.1.0, it might be related to the inheritance cache (introduced with commit 4b79dba).

@R4c00n
Copy link
Author

R4c00n commented Mar 3, 2022

Thanks for the link explaining a bit about the opcache!
Changing our release process for all projects would be a bit too much right now. The hotfix with requiring the monolog DateTimeImmutable seems to work for us too.

Is this something that's likely to be fixed in a future bugfix release, or do we need to invest some time and change our release process in the long run?

@felixwatzka
Copy link

felixwatzka commented Mar 3, 2022

We are facing this exact issue on one of our servers running PHP 8.0.13. And in our case this error occurs when running a Symfony (v5.4) Console command for which the OpCache is disabled (opcache.enable_cli => Off => Off).
Thought this might be a helpful information for the debugging process.

Using the "hotfix" works for us now but it's not a satisfying solution ofc.

@cmb69
Copy link
Member

cmb69 commented Mar 3, 2022

@R4c00n, does that issue occur for you with OPcache disabled? If so, we we're probably looking at the wrong places; otherwise, @felixwatzka's issue is something different.

@R4c00n
Copy link
Author

R4c00n commented Mar 4, 2022

I did a quick test and it seems like everything is working for us in CLI without opcache.

php -a
php > var_dump(opcache_get_status());
bool(false)
php > require_once __DIR__ . '/vendor/autoload.php';
php > $logger = new \Monolog\Logger('debug', [new \Monolog\Handler\StreamHandler('php://output', \Monolog\Logger::DEBUG, true, null, true)]);
php > $logger->addRecord(\Monolog\Logger::DEBUG, 'test');
[2022-03-04T08:40:17.450865+01:00] debug.DEBUG: test [] []

@unix-world
Copy link

PHP Version 7.4.27

PHP Version 7.4.27
System OpenBSD uxm-server.uxm 7.0 GENERIC.MP#5 amd64
Build Date Feb 17 2022 09:40:26
Configure Command './configure' '--with-pcre-jit=no' '--without-valgrind' '--with-zip=shared' '--enable-gd=shared' '--with-jpeg=/usr/local' '--with-png=/usr/local' '--with-webp=/usr/local' '--with-freetype=/usr/X11R6' '--enable-shared' '--disable-static' '--disable-rpath' '--with-config-file-path=/etc' '--enable-inline-optimization' '--with-pic' '--with-pear=/usr/local/share/php-7.4' '--with-config-file-scan-dir=/etc/php-7.4' '--with-pdo-sqlite' '--with-sqlite3' '--with-password-argon2' '--program-suffix=-7.4' '--with-readline' '--with-apxs2=/usr/local/sbin/apxs2' '--with-openssl' '--with-zlib' '--enable-xml' '--enable-wddx' '--enable-cli' '--with-iconv=/usr/local' '--with-gettext=/usr/local' '--enable-bcmath' '--enable-session' '--enable-calendar' '--enable-ctype' '--enable-ftp' '--with-pcre-regex' '--enable-sockets' '--enable-sysvmsg' '--enable-sysvsem' '--enable-sysvshm' '--enable-mbstring' '--enable-exif' '--enable-cgi' '--enable-fpm' '--with-fpm-user=www' '--with-fpm-group=www' '--with-bz2=shared,/usr/local' '--with-curl=shared,/usr/local' '--enable-dba=shared' '--with-gdbm=/usr/local' '--with-gd=shared' '--with-jpeg-dir=/usr/local' '--with-png-dir=/usr/local' '--with-webp-dir=/usr/local' '--with-zlib-dir=/usr' '--with-t1lib=/usr/local' '--with-freetype-dir=/usr/X11R6' '--with-xpm-dir=/usr/X11R6' '--with-gmp=shared,/usr/local' '--enable-intl=shared' '--with-icu-dir=/usr/local' '--with-imap=shared,/usr/local' '--with-imap-ssl' '--with-ldap=shared,/usr/local' '--with-mysqli=shared' '--disable-iodbc' '--enable-pcntl=shared' '--with-pdo-mysql=shared' '--with-pdo-pgsql=shared,/usr/local' '--with-pgsql=shared,/usr/local' '--with-pspell=shared,/usr/local' '--enable-shmop=shared,/usr/local' '--enable-soap=shared,/usr/local' '--with-snmp=shared,/usr/local' '--with-tidy=shared,/usr/local' '--with-xmlrpc=shared' '--with-xsl=shared' '--enable-dom' '--enable-zip=shared,/usr/local' '--prefix=/usr/local' '--sysconfdir=/etc' '--mandir=/usr/local/man' '--infodir=/usr/local/info' '--localstatedir=/var' '--disable-silent-rules' '--disable-gtk-doc' 'CFLAGS=-O2 -pipe -I/usr/local/include -pthread'
Server API Apache 2.0 Handler
Virtual Directory Support disabled
Configuration File (php.ini) Path /etc
Loaded Configuration File /etc/php-7.4.ini
Scan this dir for additional .ini files /etc/php-7.4
Additional .ini files parsed /etc/php-7.4/bz2.ini, /etc/php-7.4/curl.ini, /etc/php-7.4/dba.ini, /etc/php-7.4/gd.ini, /etc/php-7.4/gmp.ini, /etc/php-7.4/intl.ini, /etc/php-7.4/mongodb.ini, /etc/php-7.4/mysqli.ini, /etc/php-7.4/opcache.ini, /etc/php-7.4/pdo_mysql.ini, /etc/php-7.4/pdo_pgsql.ini, /etc/php-7.4/pgsql.ini, /etc/php-7.4/zip.ini
PHP API 20190902
PHP Extension 20190902
Zend Extension 320190902
Zend Extension Build API320190902,NTS
PHP Extension Build API20190902,NTS
Debug Build no
Thread Safety disabled
Zend Signal Handling enabled
Zend Memory Manager enabled
Zend Multibyte Support provided by mbstring
IPv6 Support enabled
DTrace Support disabled
Registered PHP Streams https, ftps, compress.zlib, compress.bzip2, php, file, glob, data, http, ftp, phar, zip
Registered Stream Socket Transports tcp, udp, unix, udg, ssl, tls, tlsv1.0, tlsv1.1, tlsv1.2, tlsv1.3
Registered Stream Filters zlib., convert.iconv., bzip2., string.rot13, string.toupper, string.tolower, string.strip_tags, convert., consumed, dechunk
Zend logo This program makes use of the Zend Scripting Language Engine:
Zend Engine v3.4.0, Copyright (c) Zend Technologies
with Zend OPcache v7.4.27, Copyright (c), by Zend Technologies

@unix-world
Copy link

apache2handler

Apache Version Apache
Apache API Version 20120211
Server Administrator webmaster@localsslserver
Hostname:Port 86.122.12.131:443
User/Group www(67)/67
Max Requests Per Child: 8192 - Keep Alive: on - Max Per Connection: 256
Timeouts Connection: 720 - Keep-Alive: 5
Virtual Server Yes
Server Root /var/www
Loaded Modules core mod_so http_core mod_authn_file mod_authn_core mod_authz_host mod_authz_user mod_authz_core mod_access_compat mod_auth_basic mod_auth_digest mod_allowmethods mod_file_cache mod_cache mod_cache_disk mod_cache_socache mod_socache_shmcb mod_socache_memcache mod_buffer mod_reqtimeout mod_request mod_include mod_filter mod_deflate mod_mime mod_log_config mod_env mod_mime_magic mod_expires mod_headers mod_unique_id mod_setenvif mod_version mod_session mod_ssl prefork mod_unixd mod_dav mod_status mod_autoindex mod_dav_fs mod_dav_lock mod_vhost_alias mod_negotiation mod_dir mod_alias mod_rewrite mod_php7 mod_dav_svn mod_authz_svn

apache2handler
Apache Version Apache
Apache API Version 20120211
Server Administrator webmaster@localsslserver
Hostname:Port 86.122.12.131:443
User/Group www(67)/67
Max Requests Per Child: 8192 - Keep Alive: on - Max Per Connection: 256
Timeouts Connection: 720 - Keep-Alive: 5
Virtual Server Yes
Server Root /var/www
Loaded Modules core mod_so http_core mod_authn_file mod_authn_core mod_authz_host mod_authz_user mod_authz_core mod_access_compat mod_auth_basic mod_auth_digest mod_allowmethods mod_file_cache mod_cache mod_cache_disk mod_cache_socache mod_socache_shmcb mod_socache_memcache mod_buffer mod_reqtimeout mod_request mod_include mod_filter mod_deflate mod_mime mod_log_config mod_env mod_mime_magic mod_expires mod_headers mod_unique_id mod_setenvif mod_version mod_session mod_ssl prefork mod_unixd mod_dav mod_status mod_autoindex mod_dav_fs mod_dav_lock mod_vhost_alias mod_negotiation mod_dir mod_alias mod_rewrite mod_php7 mod_dav_svn mod_authz_svn

@unix-world
Copy link

Zend OPcache

Opcode Caching Up and Running
Optimization Enabled
SHM Cache Enabled
File Cache Disabled
Startup OK
Shared memory model mmap
Cache hits 0
Cache misses 1
Used memory 17160440
Free memory 519710472
Wasted memory 0
Interned Strings Used memory 387632
Interned Strings Free memory 12194832
Cached scripts 1
Cached keys 2
Max keys 7963
OOM restarts 0
Hash keys restarts 0
Manual restarts 0

Zend OPcache
Opcode Caching Up and Running
Optimization Enabled
SHM Cache Enabled
File Cache Disabled
Startup OK
Shared memory model mmap
Cache hits 0
Cache misses 1
Used memory 17160440
Free memory 519710472
Wasted memory 0
Interned Strings Used memory 387632
Interned Strings Free memory 12194832
Cached scripts 1
Cached keys 2
Max keys 7963
OOM restarts 0
Hash keys restarts 0
Manual restarts 0
Directive Local Value Master Value
opcache.blacklist_filename no value no value
opcache.consistency_checks 0 0
opcache.dups_fix Off Off
opcache.enable On On
opcache.enable_cli Off Off
opcache.enable_file_override Off Off
opcache.error_log /var/log/apache2/php-opcache-errors.log /var/log/apache2/php-opcache-errors.log
opcache.file_cache no value no value
opcache.file_cache_consistency_checks On On
opcache.file_cache_only Off Off
opcache.file_update_protection 2 2
opcache.force_restart_timeout 180 180
opcache.huge_code_pages Off Off
opcache.interned_strings_buffer 16 16
opcache.lockfile_path /tmp /tmp
opcache.log_verbosity_level 1 1
opcache.max_accelerated_files 5000 5000
opcache.max_file_size 0 0
opcache.max_wasted_percentage 5 5
opcache.memory_consumption 512 512
opcache.opt_debug_level 0 0
opcache.optimization_level 0x7FFEBFFF 0x7FFEBFFF
opcache.preferred_memory_model no value no value
opcache.preload no value no value
opcache.preload_user no value no value
opcache.protect_memory Off Off
opcache.restrict_api no value no value
opcache.revalidate_freq 2 2
opcache.revalidate_path Off Off
opcache.save_comments Off Off
opcache.use_cwd On On
opcache.validate_permission Off Off
opcache.validate_root Off Off
opcache.validate_timestamps On On

@unix-world
Copy link

Environment

Variable Value
HOME /
PWD /
INRC 1
LD_LIBRARY_PATH /usr/local/lib
_ /usr/local/sbin/apachectl2
PATH /sbin:/bin:/usr/sbin:/usr/bin

@cmb69
Copy link
Member

cmb69 commented Mar 4, 2022

@unix-world, PHP 7.4 is no longer actively supported, and as such is irrelevant here.

@cmb69
Copy link
Member

cmb69 commented Mar 8, 2022

Is this something that's likely to be fixed in a future bugfix release, […]

It looks like a bug, so it should be fixed; the problem is that it's hard to find the root cause without a somewhat reliable reproduce script.

@unix-world
Copy link

unix-world commented Mar 11, 2022

@cmb69

@unix-world, PHP 7.4 is no longer actively supported, and as such is irrelevant here.

Yes, I know, and I agree.
The target is not PHP 7.4 but having PHP 8.0 or 8.1 without crashing.
Currently only 7.3 is not crashing ...

I put in this discussion the PHP 7.4 only for some particular reasons:

  • the opcache in PHP 7.4 changed a lot since 7.3 ; the 7.4 opcache is much more similar with 8.0 opcache
  • the opcache in 7.4 does not include opcache JIT thus it is important to know that not the opcache JIT it is the cause

Does it make sense ?

@Levivb
Copy link

Levivb commented Apr 21, 2022

Stepping in here since we're seeing this same message in excess in production.
I've been chasing this bug for the last two weeks now and as far as I can tell, the bug (whatever it is) is very much real.
It's nearly impossible to reproduce locally and even in production it irregularly happens. Daily, but not predictable.

I'll try to provide some insights which might (or mightn't) help getting to the source of the issue. It's going to be a bit of lengthy post though.

For clarity I'll focus on Monolog\ DateTimeImmutable class not found during the logging of a Deprecation notice
'class not found' errors are also triggered for Illuminate\Log\LogManager, Illuminate\Log\Logger


We're running several Laravel 8.8x applications in Kubernetes which were recently upgraded from php 8.0 to php 8.1.4.
Ever since the upgrade to php 8.1.4, our sentry looks like this
Screenshot 2022-04-21 at 00-35-44 Issues - radancy-nl - Sentry
Unfortunately this amount of errors is pretty much nuking our budget in sentry :|

The origin of the needs for logging is known, the 'missing' classes however, is not.
The LivenessProbe and ReadinessProbe in our pods point to a Laravel api endpoint which returns a {"status":"running smooth"} json response. Nothing fancy.
One of the request middleware classes logs each request to a file during the termination of the request.
Most of the time, this works as expected. But every now and then, Monolog\DateTimeImmutable class not found error occurs.

Whenever that happens, the exception handling of Laravel is triggered, which also uses the Monolog\DateTimeImmutable class to construct the message being written to laravel.log. Since the original 'class not found' error is still occurring, the exception handler crashes, causing a new exception handling flow. Effectively triggering an infinite loop causing sentry to be flooded with reports.

Anyway, the request handling will crash causing the Kubernetes probes to fail. During this time, request from legitimate traffic will fail for the same reason. After a while, Kubernetes will kill the unhealthy pods (ending the infinite loop), start new pods and the problem is gone (until it happens again).

My colleague managed to catch one of the failures in the act and shot these screenshots of the failing pods running in production:
Stacktrace:
Screenshot 2022-04-19 at 06 41 14

Deprecation notices which are also logged using the logging, causing the same class not found loop error.
Screenshot 2022-04-19 at 06 40 32

Error handlers are registered in https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L45

Stack trace through Github links when Monolog\ DateTimeImmutable is not found:

And we're back at square one. The DateTimeImmutable class is not found. Causing an exception in the exception handling, causing an infinite loop.

Stack trace through Github links when Illuminate\Log\Logger is not found:

And we're back at square one. The Logger class is not found. An attempt is made to create the emergency driver. Which also needs the Logger class. Causing an exception in the exception handling, causing an infinite loop.


Locally reproduced (sort of)
I did manage to reproduce it locally running php 8.1.4 in Valet (which basically is just nginx + php-fpm installed and ran through brew services)
When a breakpoint was hit during a failed exception handing, I got a pretty close look at stack-trace and got to run some code as well. (forgot to create screenshots though :().
Even a class_exists(\Monolog\DateTimeImmutable::class) returns false whenever the bug is triggered. A file_exists to Monolog/DateTimeImmutable.php returns true and the autoload_classmap.php from vendor/composer contains a valid mapping for the expected class(es) ('Monolog\\DateTimeImmutable' => $vendorDir . '/monolog/monolog/src/Monolog/DateTimeImmutable.php',)

But it gets even weirder, since we're talking about an infinite loop due a class not found exception I expected to see the stack-trace from the production screenshots. However, what I got was the moment the Monolog\DateTimeImmutable class not found exception triggered, not the handleException was triggered, but the handleError handler registered in the set_error_handler.

When stepping into the handleError function, prior function calls in the stack trace showed Monolog\DateTimeImmutable class not found exceptions, but in the handleError the reported error was a deprecation notice from the file https://github.com/jenssegers/model/blob/master/src/Model.php (the deprecation notices are visible in the Deprecation notices screenshot above and are reported during normal website requests on the site).
Jenssegers\Model\Model however, is not even loaded nor touched during the handing of the status api endpoint.
I emptied the Model.php file, but the error remained. I even removed vendor/jenssegers altogether and still the error remained (also in a new request and a new xdebug session). So even though the model.php file didn't even exist anymore, deprecations from that file were still being reported.

Apparently requests to unrelated webpages (on the same site) loaded the jenssegers model file and the deprecation error leaked through to separate requests to an api endpoint not using the Jenssegers\Model\Model class.

This caused me to reload the php service via brew to check if that would fix the issue. And sure enough, I haven't been able to reproduce the issue locally anymore despite thousands of requests (as I'm writing this message) and artisan commands both with and without --no-dev composer install packages. Both with and without production environment variables and with and without xdebug enabled. Manually triggering a deprecation warning with trigger_error('testing deprecation here --12ba2b--', E_USER_DEPRECATED); also doesn't initiate any class not found infinite loop (deprecation is logged just fine).


My opcache settings are the same as mentioned by SCIF in #8358 (comment) =>

opcache ini
{
"opcache.blacklist_filename": {
  "global_value": "",
  "local_value": "",
  "access": 4
},
"opcache.consistency_checks": {
  "global_value": "0",
  "local_value": "0",
  "access": 7
},
"opcache.dups_fix": {
  "global_value": "0",
  "local_value": "0",
  "access": 7
},
"opcache.enable": {
  "global_value": "1",
  "local_value": "1",
  "access": 7
},
"opcache.enable_cli": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.enable_file_override": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.error_log": {
  "global_value": "",
  "local_value": "",
  "access": 4
},
"opcache.file_cache": {
  "global_value": null,
  "local_value": null,
  "access": 4
},
"opcache.file_cache_consistency_checks": {
  "global_value": "1",
  "local_value": "1",
  "access": 4
},
"opcache.file_cache_only": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.file_update_protection": {
  "global_value": "2",
  "local_value": "2",
  "access": 7
},
"opcache.force_restart_timeout": {
  "global_value": "180",
  "local_value": "180",
  "access": 4
},
"opcache.huge_code_pages": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.interned_strings_buffer": {
  "global_value": "8",
  "local_value": "8",
  "access": 4
},
"opcache.jit": {
  "global_value": "tracing",
  "local_value": "tracing",
  "access": 7
},
"opcache.jit_bisect_limit": {
  "global_value": "0",
  "local_value": "0",
  "access": 7
},
"opcache.jit_blacklist_root_trace": {
  "global_value": "16",
  "local_value": "16",
  "access": 7
},
"opcache.jit_blacklist_side_trace": {
  "global_value": "8",
  "local_value": "8",
  "access": 7
},
"opcache.jit_buffer_size": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.jit_debug": {
  "global_value": "0",
  "local_value": "0",
  "access": 7
},
"opcache.jit_hot_func": {
  "global_value": "127",
  "local_value": "127",
  "access": 4
},
"opcache.jit_hot_loop": {
  "global_value": "64",
  "local_value": "64",
  "access": 4
},
"opcache.jit_hot_return": {
  "global_value": "8",
  "local_value": "8",
  "access": 4
},
"opcache.jit_hot_side_exit": {
  "global_value": "8",
  "local_value": "8",
  "access": 7
},
"opcache.jit_max_exit_counters": {
  "global_value": "8192",
  "local_value": "8192",
  "access": 4
},
"opcache.jit_max_loop_unrolls": {
  "global_value": "8",
  "local_value": "8",
  "access": 7
},
"opcache.jit_max_polymorphic_calls": {
  "global_value": "2",
  "local_value": "2",
  "access": 7
},
"opcache.jit_max_recursive_calls": {
  "global_value": "2",
  "local_value": "2",
  "access": 7
},
"opcache.jit_max_recursive_returns": {
  "global_value": "2",
  "local_value": "2",
  "access": 7
},
"opcache.jit_max_root_traces": {
  "global_value": "1024",
  "local_value": "1024",
  "access": 4
},
"opcache.jit_max_side_traces": {
  "global_value": "128",
  "local_value": "128",
  "access": 4
},
"opcache.jit_prof_threshold": {
  "global_value": "0.005",
  "local_value": "0.005",
  "access": 7
},
"opcache.lockfile_path": {
  "global_value": "\/tmp",
  "local_value": "\/tmp",
  "access": 4
},
"opcache.log_verbosity_level": {
  "global_value": "1",
  "local_value": "1",
  "access": 4
},
"opcache.max_accelerated_files": {
  "global_value": "10000",
  "local_value": "10000",
  "access": 4
},
"opcache.max_file_size": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.max_wasted_percentage": {
  "global_value": "5",
  "local_value": "5",
  "access": 4
},
"opcache.memory_consumption": {
  "global_value": "128",
  "local_value": "128",
  "access": 4
},
"opcache.opt_debug_level": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.optimization_level": {
  "global_value": "0x7FFEBFFF",
  "local_value": "0",
  "access": 4
},
"opcache.preferred_memory_model": {
  "global_value": "",
  "local_value": "",
  "access": 4
},
"opcache.preload": {
  "global_value": "",
  "local_value": "",
  "access": 4
},
"opcache.preload_user": {
  "global_value": "",
  "local_value": "",
  "access": 4
},
"opcache.protect_memory": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.record_warnings": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.restrict_api": {
  "global_value": "",
  "local_value": "",
  "access": 4
},
"opcache.revalidate_freq": {
  "global_value": "2",
  "local_value": "2",
  "access": 7
},
"opcache.revalidate_path": {
  "global_value": "0",
  "local_value": "0",
  "access": 7
},
"opcache.save_comments": {
  "global_value": "1",
  "local_value": "1",
  "access": 4
},
"opcache.use_cwd": {
  "global_value": "1",
  "local_value": "1",
  "access": 4
},
"opcache.validate_permission": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.validate_root": {
  "global_value": "0",
  "local_value": "0",
  "access": 4
},
"opcache.validate_timestamps": {
  "global_value": "1",
  "local_value": "1",
  "access": 7
}
}


This is pretty much as far as I can get. It's hard to reproduce and even harder to pinpoint why this is happening. But from the looks of it, it all points to php's opcache :|
The sore reality though, is that changing opcache ini settings requires a reload of php-fpm. But reloading php-fpm in and of itself is enough to return to a working code (probably by flushing opcache's cache). Effectively ditching the possibility to debug persistently.

Really hoping more information regarding this issue and possible solutions will come to light.

Perhaps someone can take a look at the diff between php 8.0 and php 8.1.x regarding opcache? Although I can read a bit of c, it's not really my area of expertise. I reckon the opcache's code is also not the easiest to understand.


Some other sources which describe the same issue in one form, or another:

@arnaud-lb
Copy link
Member

Thanks a lot for this very detailed analysis. With this new information I believe that this could be related to #8063. I will look at this tomorrow.

@Levivb
Copy link

Levivb commented Apr 21, 2022

Cool thanks! 🙃

Looking at the description of dd86987 stating Fix this by uplifting the error recording functionality from opcache to Zend, and then using it to persist a warning trace in the inheritance cache, which can then be used to replay the warnings on subsequent executions is kinda exactly what I was seeing when debugging locally when a class not found exception resulted in a deprecation notice of an (seemingly) unrelated piece of code from another request

@arnaud-lb
Copy link
Member

Should be fixed by #8297

@cmb69
Copy link
Member

cmb69 commented Apr 22, 2022

@R4c00n and others, could you please check this? Either build from source, or wait for PHP 8.1.6RC1, which is supposed to be released on April, 28th.

@github-actions
Copy link

github-actions bot commented May 7, 2022

No feedback was provided. The issue is being suspended because we assume that you are no longer experiencing the problem. If this is not the case and you are able to provide the information that was requested earlier, please do so. Thank you.

@Levivb
Copy link

Levivb commented May 9, 2022

Sorry for not getting back here.

I removed some logging on our side 3 weeks ago. Since then, the error has not occurred. (this is not really a fix for the actual issue of course)

I'll re-enable the logging and deploy some applications in production with a PHP 8.1.6RC1 build. Due to the volatility of the bug, the absence of the error might or might not indicate the issue is solved 🤷‍♂️

--
update 1: one day in. so far no Logger errors 🤞
update 2: three days in. still no Logger errors 👌

@jackwh
Copy link

jackwh commented May 12, 2022

@Levivb glad to hear RC1 has been working for you so far 👍

@cmb69 I'm ready to update as I've been impacted by this too, but I don't see any reference to this bug in the release notes for 8.1.6? Did it make in to today's release, or should I hold off a bit longer?

Thanks 🙏🏻

@rogatty
Copy link

rogatty commented May 13, 2022

Commit is in the PHP-8.1.6 branch so I assume the release notes are not complete:
https://github.com/php/php-src/commits/PHP-8.1.6/Zend/zend_inheritance.c

@arnaud-lb
Copy link
Member

arnaud-lb commented May 13, 2022

I confirm it's in 8.1.6 👍 (I updated the NEWS file too late to appear in the release notes)

@Levivb
Copy link

Levivb commented May 13, 2022

Great, thanks for your work @arnaud-lb ! 👍

Eagerly waiting for stable docker image 8.1.6 in https://hub.docker.com/_/php?tab=tags&page=1&name=8.1.6 :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

10 participants