From 1fa81a2f5181cccc3cdfae92f1f8a4b817a7e075 Mon Sep 17 00:00:00 2001 From: Sergey Kleyman Date: Mon, 13 Oct 2025 11:28:48 +0300 Subject: [PATCH 1/3] Log interceptRegistrationId on elasticApmInterceptCallsToInternalMethod exit interceptRegistrationId is already logged on elasticApmInterceptCallsToInternalFunctionEx exit --- agent/native/ext/elastic_apm_API.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/agent/native/ext/elastic_apm_API.cpp b/agent/native/ext/elastic_apm_API.cpp index 78eabf42a..6debe3aa3 100644 --- a/agent/native/ext/elastic_apm_API.cpp +++ b/agent/native/ext/elastic_apm_API.cpp @@ -198,7 +198,7 @@ ResultCode elasticApmInterceptCallsToInternalMethod( String className, String me finally: - ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT(); + ELASTIC_APM_LOG_DEBUG_RESULT_CODE_FUNCTION_EXIT_MSG( "interceptRegistrationId: %u", *interceptRegistrationId ); return resultCode; failure: From 165b26d748edb04e0f269b2b4f97bebd5ec05a1d Mon Sep 17 00:00:00 2001 From: Sergey Kleyman Date: Mon, 13 Oct 2025 16:02:07 +0300 Subject: [PATCH 2/3] Prepend interceptRegistration when logging --- .../Impl/AutoInstrument/InterceptionManager.php | 15 +++++++-------- agent/php/ElasticApm/Impl/Log/Logger.php | 15 ++++++++++++--- 2 files changed, 19 insertions(+), 11 deletions(-) diff --git a/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php b/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php index 6f795d796..063b756d4 100644 --- a/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php +++ b/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php @@ -89,26 +89,25 @@ public function internalFuncCallPreHook( array $interceptedCallArgs ): bool { $localLogger = $this->logger->inherit()->addAllContext( - [ - 'interceptRegistrationId' => $interceptRegistrationId, - 'thisObj type' => DbgUtil::getType($thisObj), + compact('interceptRegistrationId') + + [ + 'thisObj type' => DbgUtil::getType($thisObj), 'interceptedCallArgs count' => count($interceptedCallArgs), - 'thisObj' => $this->logger->possiblySecuritySensitive($thisObj), - 'interceptedCallArgs' => $this->logger->possiblySecuritySensitive($interceptedCallArgs), + 'thisObj' => $this->logger->possiblySecuritySensitive($thisObj), + 'interceptedCallArgs' => $this->logger->possiblySecuritySensitive($interceptedCallArgs), ] ); $loggerProxyTrace = $localLogger->ifTraceLevelEnabledNoLine(__FUNCTION__); $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'Entered'); - $interceptRegistration - = ArrayUtil::getValueIfKeyExistsElse($interceptRegistrationId, $this->interceptedCallRegistrations, null); + $interceptRegistration = ArrayUtil::getValueIfKeyExistsElse($interceptRegistrationId, $this->interceptedCallRegistrations, null); if ($interceptRegistration === null) { ($loggerProxy = $localLogger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) && $loggerProxy->log('There is no registration with the given interceptRegistrationId'); return false; } - $localLogger->addContext('interceptRegistration', $interceptRegistration); + $localLogger->prependAllToContext(compact('interceptRegistration')); $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'Calling preHook...'); try { diff --git a/agent/php/ElasticApm/Impl/Log/Logger.php b/agent/php/ElasticApm/Impl/Log/Logger.php index fd393d70a..5f888f20e 100644 --- a/agent/php/ElasticApm/Impl/Log/Logger.php +++ b/agent/php/ElasticApm/Impl/Log/Logger.php @@ -83,9 +83,18 @@ public function addContext(string $key, $value): self */ public function addAllContext(array $keyValuePairs): self { - foreach ($keyValuePairs as $key => $value) { - $this->addContext($key, $value); - } + $this->data->context = array_merge($this->data->context, $keyValuePairs); + return $this; + } + + /** + * @param array $keyValuePairs + * + * @return Logger + */ + public function prependAllToContext(array $keyValuePairs): self + { + $this->data->context = $keyValuePairs + $this->data->context; return $this; } From 527f571505ce955f747c9d25d712b7d6580f9ba5 Mon Sep 17 00:00:00 2001 From: Sergey Kleyman Date: Mon, 13 Oct 2025 16:35:35 +0300 Subject: [PATCH 3/3] Log pre/post hooks at DEBUG level --- agent/native/ext/lifecycle.cpp | 6 ++-- .../AutoInstrument/InterceptionManager.php | 32 +++++++++---------- 2 files changed, 20 insertions(+), 18 deletions(-) diff --git a/agent/native/ext/lifecycle.cpp b/agent/native/ext/lifecycle.cpp index e4fb860b8..a7e8c6bf5 100644 --- a/agent/native/ext/lifecycle.cpp +++ b/agent/native/ext/lifecycle.cpp @@ -400,6 +400,8 @@ auto buildPeriodicTaskExecutor() { return periodicTaskExecutor; } +static const char* gs_custom_build_log_msg_str = "(CUSTOM BUILD 2025-10-13)"; + void elasticApmRequestInit() { if (!ELASTICAPM_G(globals)->sapi_.isSupported()) { @@ -442,7 +444,7 @@ void elasticApmRequestInit() g_pidOnRequestInit = getCurrentProcessId(); - ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY_MSG( "parent PID: %d", (int)(getParentProcessId()) ); + ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY_MSG( "%s parent PID: %d", gs_custom_build_log_msg_str, (int)(getParentProcessId()) ); ResultCode resultCode; @@ -560,7 +562,7 @@ void elasticApmRequestShutdown() return; } - ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY(); + ELASTIC_APM_LOG_DEBUG_FUNCTION_ENTRY_MSG( "%s", gs_custom_build_log_msg_str ); Tracer* const tracer = getGlobalTracer(); const ConfigSnapshot* const config = getTracerCurrentConfigSnapshot( tracer ); diff --git a/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php b/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php index 063b756d4..de2adc273 100644 --- a/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php +++ b/agent/php/ElasticApm/Impl/AutoInstrument/InterceptionManager.php @@ -97,24 +97,24 @@ public function internalFuncCallPreHook( 'interceptedCallArgs' => $this->logger->possiblySecuritySensitive($interceptedCallArgs), ] ); - $loggerProxyTrace = $localLogger->ifTraceLevelEnabledNoLine(__FUNCTION__); + $loggerProxy = $localLogger->ifDebugLevelEnabledNoLine(__FUNCTION__); - $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'Entered'); + $loggerProxy && $loggerProxy->log(__LINE__, 'Entered'); $interceptRegistration = ArrayUtil::getValueIfKeyExistsElse($interceptRegistrationId, $this->interceptedCallRegistrations, null); if ($interceptRegistration === null) { - ($loggerProxy = $localLogger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) - && $loggerProxy->log('There is no registration with the given interceptRegistrationId'); + ($loggerProxyError = $localLogger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) + && $loggerProxyError->log('There is no registration with the given interceptRegistrationId'); return false; } $localLogger->prependAllToContext(compact('interceptRegistration')); - $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'Calling preHook...'); + $loggerProxy && $loggerProxy->log(__LINE__, 'Calling preHook...'); try { $preHookRetVal = ($interceptRegistration->preHook)($thisObj, $interceptedCallArgs); } catch (Throwable $throwable) { - ($loggerProxy = $localLogger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) - && $loggerProxy->logThrowable( + ($loggerProxyError = $localLogger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) + && $loggerProxyError->logThrowable( $throwable, 'preHook has let a Throwable to escape' ); @@ -128,7 +128,7 @@ public function internalFuncCallPreHook( $this->interceptedCallInProgressPreHookRetVal = $preHookRetVal; } - $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'preHook completed successfully', ['shouldCallPostHook' => $shouldCallPostHook]); + $loggerProxy && $loggerProxy->log(__LINE__, 'preHook completed successfully', ['shouldCallPostHook' => $shouldCallPostHook]); return $shouldCallPostHook; } @@ -149,28 +149,28 @@ public function internalFuncCallPostHook( 'interceptRegistration' => $this->interceptedCallInProgressRegistration, ] ); - $loggerProxyTrace = $localLogger->ifTraceLevelEnabledNoLine(__FUNCTION__); - $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'Entered'); + $loggerProxy = $localLogger->ifDebugLevelEnabledNoLine(__FUNCTION__); + $loggerProxy && $loggerProxy->log(__LINE__, 'Entered'); if ($this->interceptedCallInProgressRegistrationId === null) { - ($loggerProxy = $this->logger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) - && $loggerProxy->log('There is no intercepted call in progress'); + ($loggerProxyError = $this->logger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) + && $loggerProxyError->log('There is no intercepted call in progress'); return; } assert($this->interceptedCallInProgressRegistration !== null); assert($this->interceptedCallInProgressPreHookRetVal !== null); - $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'Calling postHook...'); + $loggerProxy && $loggerProxy->log(__LINE__, 'Calling postHook...'); try { ($this->interceptedCallInProgressPreHookRetVal)( $numberOfStackFramesToSkip + 1, $hasExitedByException, $returnValueOrThrown ); - $loggerProxyTrace && $loggerProxyTrace->log(__LINE__, 'postHook completed without throwing'); + $loggerProxy && $loggerProxy->log(__LINE__, 'postHook completed without throwing'); } catch (Throwable $throwable) { - ($loggerProxy = $localLogger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) - && $loggerProxy->logThrowable($throwable, 'postHook has thrown'); + ($loggerProxyError = $localLogger->ifErrorLevelEnabled(__LINE__, __FUNCTION__)) + && $loggerProxyError->logThrowable($throwable, 'postHook has thrown'); } $this->interceptedCallInProgressRegistrationId = null;