Uncaught throwable caused by PHP 8.1 Deprecated warning

[nizacegodk]

Describe the bug
Uncaught exception from unknown class triggered by Deprecation warning in php 8.1

Handling onPhpError call from extension let a throwable escape - skipping the rest of the steps. Error: Class "Elastic\Apm\CustomErrorData" not found

PHP Deprecated: Return type of Cego\Math\Decimal::jsonSerialize() should either be compatible with JsonSerializable::jsonSerialize(): mixed, or the #[\ReturnTypeWillChange] attribute should be used to temporarily suppress the notice in /var/www/html/vendor/cego/math/src/Decimal.php on line 631

To Reproduce
Steps to reproduce the behavior:

1. Make php class which implements interface JsonSerializable
2. Define the jsonSerialize method with no defined return typehinting -> public function jsonSerialize() {return 'test';}
3. Run the code with APM enabled

Expected behavior
I would expect APM to not crash, and break the flow of the application because of deprecation warnings.

[nizacegodk]

Update:

We do not seem to have this problem in the latest release of our internal php image, with updated PHP and APM versions.
I was sadly unable to identify what exactly caused the problem, but one thing i did figure out was that the problem seems to be "time based".

Meaning, when I run the exact image, from our registry, we had the problems with and run the code immediately afterwards - Then only the PHP warning appears. If I then let the image idle for a few minutes, and then rerun the exact same code, without even exiting the image, then the APM error appears consistently.

2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension] Handling onPhpError call from extension let a throwable escape - skipping the rest of the steps. Error: Class "Elastic\Apm\CustomErrorData" not found
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     Stack trace:
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #0 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/TransactionForExtensionRequest.php(302): Elastic\Apm\Impl\Tracer->onPhpError(8192, '/var/www/html/t...', 4, 'Return type of ...', NULL)
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #1 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(283): Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest->onPhpError(8192, '/var/www/html/t...', 4, 'Return type of ...')
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #2 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(254): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument\{closure}(Object(Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #3 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(212): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument\{closure}(Object(Elastic\Apm\Impl\AutoInstrument\PhpPartFacade))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #4 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(255): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callFromExtension('onPhpError', Object(Closure))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #5 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(284): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callFromExtensionToTransaction('onPhpError', Object(Closure))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #6 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/Autoloader.php(87): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::onPhpError(8192, '/var/www/html/t...', 4, 'Return type of ...')
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #7 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/Autoloader.php(87): require('/opt/apm-agent-...')
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #8 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/Tracer.php(295): Elastic\Apm\Impl\AutoInstrument\Autoloader::autoloadCodeForClass('Elastic\\Apm\\Cus...')
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #9 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/TransactionForExtensionRequest.php(302): Elastic\Apm\Impl\Tracer->onPhpError(8192, '/var/www/html/t...', 4, 'Return type of ...', NULL)
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #10 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(283): Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest->onPhpError(8192, '/var/www/html/t...', 4, 'Return type of ...')
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #11 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(254): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument\{closure}(Object(Elastic\Apm\Impl\AutoInstrument\TransactionForExtensionRequest))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #12 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(212): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::Elastic\Apm\Impl\AutoInstrument\{closure}(Object(Elastic\Apm\Impl\AutoInstrument\PhpPartFacade))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #13 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(255): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callFromExtension('onPhpError', Object(Closure))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #14 /opt/apm-agent-php-1.5.1/src/ElasticApm/Impl/AutoInstrument/PhpPartFacade.php(284): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::callFromExtensionToTransaction('onPhpError', Object(Closure))
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #15 /var/www/html/test.php(3): Elastic\Apm\Impl\AutoInstrument\PhpPartFacade::onPhpError(8192, '/var/www/html/t...', 4, 'Return type of ...')
2022-09-20 08:53:15.561343+00:00 [PID: 67] [TID: 67] [CRITICAL] [Bootstrap] [BootstrapStageLogger.php:218] [callFromExtension]     #16 {main}
PHP Deprecated:  Return type of Example::jsonSerialize() should either be compatible with JsonSerializable::jsonSerialize(): mixed, or the #[\ReturnTypeWillChange] attribute should be used to temporarily suppress the notice in /var/www/html/test.php on line 4

[nizacegodk]

I was too fast on the trigger. I went back and gave it another shot... I have now identified the setting which causes the problem, which is file opcache.

If I add/remove the following from our php.ini file:

opcache.enable_cli=1
opcache.file_cache=/tmp/php-file-cache

Without, then only the PHP warning appears. With then APM error also appears.

I will try to produce a minimal docker image which can replicate the issue.

[nizacegodk]

Minimal reproducible docker image can be found at: SergeyKleyman/elastic_apm_php_agent_aux#1

The timing aspect was related to clearing of opcache happening. Which is why the attached example code must be executed twice.