Errors and crashes of traced application while using the module without REQUEST_URI

[NicolaD77]

Describe the bug I have installed the APM agent on an Icinga2/IcingaWeb2 environment and everything works fine during normal Web Navigation but as soon as a php batch mode is used (i.e. icingacli) the php-agent crashes the expected php elaboration results. This is critical as the APM should not interfere with the environment is running in, right?

To Reproduce Steps to reproduce the behavior:

1. Use this config

extension = elastic_apm.so elastic_apm.bootstrap_php_part_file=/opt/elastic/apm-agent-> php/src/bootstrap_php_part.php elastic_apm.verify_server_cert = false elastic_apm.environment = "production" elastic_apm.service_name="icinga-php" elastic_apm.server_url=

2. Then call icingacli in Icinga2

3. here the log:

php[21411]: Elastic APM

PHP Tracer [PID: 21411] 2021-05-04 10:07:43.430198+02:00 [ERROR] [Auto-Instrumentation] [TransactionForExtensionRequest.php:286] [getMandatoryServerVarElement] $_SERVER does not contain REQUEST_MET May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.430377+02:00 [ERROR] [Auto-Instrumentation] [TransactionForExtensionRequest.php:286] [getMandatoryServerVarElement] $_SERVER does not contain HTTP_HOST' May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.430480+02:00 [ERROR] [Auto-Instrumentation] [TransactionForExtensionRequest.php:286] [getMandatoryServerVarElement] $_SERVER does not contain REQUEST_URI May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.462888+02:00 [ERROR] [Util] [util_for_PHP.c:138] [callPhpFunction] call_user_function failed. Return value: -1. PHP function name: \Elastic\Apm\Impl\Auto May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.462916+02:00 [ERROR] [C-to-PHP] [tracer_PHP_part.c:160] [tracerPhpPartInterceptedCall] Exiting: resultCode: resultFailure (4) May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.463215+02:00 [ERROR] [Util] [util_for_PHP.c:138] [callPhpFunction] call_user_function failed. Return value: -1. PHP function name: \Elastic\Apm\Impl\Auto May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.463230+02:00 [ERROR] [C-to-PHP] [tracer_PHP_part.c:160] [tracerPhpPartInterceptedCall] Exiting: resultCode: resultFailure (4) May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.463771+02:00 [ERROR] [Util] [util_for_PHP.c:138] [callPhpFunction] call_user_function failed. Return value: -1. PHP function name: \Elastic\Apm\Impl\Auto May 04 10:07:43 neteyedemo.wuerth-phoenix.com php[21411]: Elastic APM PHP Tracer [PID: 21411] 2021-05-04 10:07:43.463787+02:00 [ERROR] [C-to-PHP] [tracer_PHP_part.c:160] [tracerPhpPartInterceptedCall] Exiting: resultCode: resultFailure (4)

Expected behavior If any error in tracing the traced application should continue to work without impact :-)

[NicolaD77]

Hello, any feedback about this issue? Without this fix it is not safe for service stability the use of the agent...

[SergeyKleyman]

@NicolaD77 I definitely agree with you on "If any error in tracing the traced application should continue to work without impact :-)" so I would like to fix it. Unfortunately I am not familiar with icingacli so it will take me some time to build an environment where the bug is reproducible. Could advise on how to build such an environment quickly or maybe you can share a docker image with such an environment?

[NicolaD77]

I guess that this could be a possible test environment: https://github.com/Icinga/docker-icinga2

[NicolaD77]

Hello. Based on a suggestion of Icinga Team I've tried to execute the following command with apm-agent enabled.

/opt/rh/rh-php73/root/usr/bin/php -r "echo phpversion('tidy');"

Please find the log here log-phpversion.txt

when I try to navigate through the Web Application or invoke any php cli functions I get errors like: icinga-errors.txt

[mikkeschiren]

I get more or less the same error:

2021-06-09 20:34:19.318914+00:00 [ERROR]    [Auto-Instrumentation] [TransactionForExtensionRequest.php:286] [getMandatoryServerVarElement] $_SERVER does not contain `REQUEST_METHOD' key. {"namespace":"Elastic\\Apm\\Impl\\AutoInstrument","class":"TransactionForExtensionRequest","stacktrace":[{"class":"Elastic\\Apm\\Impl\\Log\\Backend","function":"log","file":"EnabledLoggerProxy.php","line":80,"this":{"type":"Elastic\\Apm\\Impl\\Log\\Backend","object_ID":35,"object_hash":"0000000028b240760000000051a020ce"},"args":[2,"$_SERVER does not contain `REQUEST_METHOD' key",[],286,"getMandatoryServerVarElement",{"category":"Auto-Instrumentation","namespace":"Elastic\\Apm\\Impl\\AutoInstrument","fqClassName":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","srcCodeFile":"\/opt\/elastic\/apm-agent-php\/src\/ElasticApm\/Impl\/AutoInstrument\/TransactionForExtensionRequest.php","inheritedData":null,"context":[],"backend":{}},null,1]},{"class":"Elastic\\Apm\\Impl\\Log\\EnabledLoggerProxy","function":"log","file":"TransactionForExtensionRequest.php","line":287,"this":{"type":"Elastic\\Apm\\Impl\\Log\\EnabledLoggerProxy","object_ID":32,"object_hash":"0000000028b240750000000051a020ce"},"args":["$_SERVER does not contain `REQUEST_METHOD' key"]},{"class":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","function":"getMandatoryServerVarElement","file":"TransactionForExtensionRequest.php","line":124,"this":{"type":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","object_ID":3,"object_hash":"0000000028b240560000000051a020ce"},"args":["REQUEST_METHOD"]},{"class":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","function":"discoverHttpRequestData","file":"TransactionForExtensionRequest.php","line":76,"this":{"type":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","object_ID":3,"object_hash":"0000000028b240560000000051a020ce"},"args":[]},{"class":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","function":"beginTransaction","file":"TransactionForExtensionRequest.php","line":68,"this":{"type":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","object_ID":3,"object_hash":"0000000028b240560000000051a020ce"},"args":[1623270859304532]},{"class":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","function":"__construct","file":"PhpPartFacade.php","line":75,"this":{"type":"Elastic\\Apm\\Impl\\AutoInstrument\\TransactionForExtensionRequest","object_ID":3,"object_hash":"0000000028b240560000000051a020ce"},"args":[{"isRecording":true,"providedDependencies":{"clock":null,"configRawSnapshotSource":null,"eventSink":null,"logSink":null},"config":{"enabled":true,"environment":"staging","logLevel":6,"logLevelStderr":3,"logLevelSyslog":6,"serverTimeout":30000,"serviceName":"FooSite","serviceVersion":"1ef660cd","transactionMaxSpans":2000,"transactionSampleRate":1,"verifyServerCert":false,"optNameToParsedValue":{"enabled":true,"environment":"staging","log_level":6,"log_level_stderr":3,"log_level_syslog":6,"server_timeout":30000,"service_name":"FooSite","service_version":"1ef660cd","transaction_max_spans":2000,"transaction_sample_rate":1,"verify_server_cert":false}}},1623270859304532]},{"class":"Elastic\\Apm\\Impl\\AutoInstrument\\PhpPartFacade","function":"__construct","file":"PhpPartFacade.php","line":109,"this":{"type":"Elastic\\Apm\\Impl\\AutoInstrument\\PhpPartFacade","object_ID":1,"object_hash":"0000000028b240540000000051a020ce"},"args":[1623270859304532]},{"class":"Elastic\\Apm\\Impl\\AutoInstrument\\PhpPartFacade","function":"bootstrap","args":[6,1623270859304532]}]}

This is running in a docker container, based on official php image with tag 7.4.19-fpm-alpine3.13

[SergeyKleyman]

@mikkeschiren @NicolaD77 Could you please check if this issue still occurs with the latest release (v1.9.1)?

[SergeyKleyman]

We are going to close it for now. Please let us know if it's still not resolved.