[php-src] Issue #8164: PHP8.1.3. opcache bug with monolog/monolog

Issue: https://github.com/php/php-src/issues/8164 Comment Author: Levivb 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  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: <img width="1707" alt="Screenshot 2022-04-19 at 06 41 14" src="https://user-images.githubusercontent.com/2494320/164414708-6a561e52-0051-4384-92a5-85ec7f884899.png"> Deprecation notices which are also logged using the logging, causing the same class not found loop error. <img width="1719" alt="Screenshot 2022-04-19 at 06 40 32" src="https://user-images.githubusercontent.com/2494320/164414768-5dfab711-8a9b-4ede-a416-3bfcf8d32c6c.png"> 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:** - private code calls $logger->debug() - debug is called on the default stack channel/driver: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L643 - Monolog\Logger::error is called: https://github.com/Seldaek/monolog/blob/2.4.0/src/Monolog/Logger.php#L538 - new DateTimeImmutable is called in Monolog\Logger::addRecord: https://github.com/Seldaek/monolog/blob/2.4.0/src/Monolog/Logger.php#L311 - **Class Monolog\DateTimeImmutable is not found** - handleException is triggered: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L165 - Illuminate\Foundation\Exceptions\Handler::report: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Exceptions/Handler.php#L247 - LogManager::error: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L180 - error is called on the default stack channel/driver: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L590 - Monolog\Logger::error is called: https://github.com/Seldaek/monolog/blob/2.4.0/src/Monolog/Logger.php#L538 - new DateTimeImmutable is called in Monolog\Logger::addRecord: https://github.com/Seldaek/monolog/blob/2.4.0/src/Monolog/Logger.php#L311 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:** - handleError is triggered: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L68 - Error is deprecation: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L71 - Deprecation handling is called: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L87 - Deprecation log channel is being created: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L104 - channel call: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L101 - channel call forwards to driver: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L112 - driver forwards to get: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L125 - with callback runs new Logger: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L126 - Logger is not found. Falling back to Emergency logger in the catch: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L129 - Emergency logger also needs Logger: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L180 - handleException is called: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Bootstrap/HandleExceptions.php#L165 - Illuminate\Foundation\Exceptions\Handler::report: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Foundation/Exceptions/Handler.php#L247 - LogManager::error: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L180 - which creates the stack driver. also needing the Logger class: https://github.com/laravel/framework/blob/v8.83.9/src/Illuminate/Log/LogManager.php#L126 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](https://github.com/laravel/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 https://github.com/php/php-src/issues/8358#issuecomment-1100775251 => <details> <summary>opcache ini</summary> ``` { "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 } } ``` </details> --- 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: - https://github.com/laravel/framework/issues/41035 (one of Laravel's main issue reports regarding this issue. I joined there are well with some additional stacktraces which are probably(?) irrelevant here) - https://github.com/php/php-src/issues/8358 - https://github.com/laravel/framework/issues/41070 - https://github.com/laravel/framework/pull/39938 (the 'fix' mentioned in previous issue within the Laravel framework to work around this issue, but doesn't actually solve it) - https://github.com/laravel/sail/issues/286 - https://laracasts.com/discuss/channels/laravel/error-class-illuminatelogeventsmessagelogged-not-found - https://laracasts.com/discuss/channels/laravel/logmanager-not-found - https://laracasts.com/discuss/channels/servers/class-logmanager-not-found-in-logserviceprovider-after-upgrade-to-php81 - https://github.com/laravel/framework/compare/v8.64.0...v8.65.0 (Laravel introduces custom deprecation error handling) - https://github.com/Seldaek/monolog/issues/1626 (original report by OP on Seldaek/monolog)