Debug option ELASTIC_OTEL_DEBUG_PHP_HOOKS_ENABLED to log data from al…

…l instrumented hooks (#155)
elastic · Feb 3, 2025 · 9fbc639 · 9fbc639
1 parent afc52bc
commit 9fbc639
Show file tree

Hide file tree

Showing 5 changed files with 69 additions and 7 deletions.
diff --git a/prod/native/extension/code/ModuleFunctions.cpp b/prod/native/extension/code/ModuleFunctions.cpp
@@ -109,7 +109,7 @@ ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, level, IS_LONG, /* allow_null: */ 0)
 ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, feature, IS_LONG, /* allow_null: */ 0)
 ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, category, IS_STRING, /* allow_null: */ 0)
 ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, file, IS_STRING, /* allow_null: */ 0)
-ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, line, IS_LONG, /* allow_null: */ 0)
+ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, line, IS_LONG, /* allow_null: */ 1)
 ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, func, IS_STRING, /* allow_null: */ 0)
 ZEND_ARG_TYPE_INFO(/* pass_by_ref: */ 0, message, IS_STRING, /* allow_null: */ 0)
 ZEND_END_ARG_INFO()
@@ -120,7 +120,7 @@ ZEND_END_ARG_INFO()
  *      int $feature,
  *      string $category,
  *      string $file,
- *      int $line,
+ *      ?int $line,
  *      string $func,
  *      string $message
  *  ): void
@@ -134,6 +134,7 @@ PHP_FUNCTION(elastic_otel_log_feature) {
     char *category = nullptr;
     size_t categoryLength = 0;
     zend_long line = 0;
+    bool lineNull = true;
     char *func = nullptr;
     size_t funcLength = 0;
     char *message = nullptr;
@@ -145,12 +146,15 @@ PHP_FUNCTION(elastic_otel_log_feature) {
     Z_PARAM_LONG(feature)
     Z_PARAM_STRING(category, categoryLength)
     Z_PARAM_STRING(file, fileLength)
-    Z_PARAM_LONG(line)
+    Z_PARAM_LONG_OR_NULL(line, lineNull)
     Z_PARAM_STRING(func, funcLength)
     Z_PARAM_STRING(message, messageLength)
     ZEND_PARSE_PARAMETERS_END();
 
-    if (ELASTICAPM_G(globals)->logger_->doesFeatureMeetsLevelCondition(static_cast<LogLevel>(level), static_cast<elasticapm::php::LogFeature>(feature))) {
+    if (isForced || ELASTICAPM_G(globals)->logger_->doesFeatureMeetsLevelCondition(static_cast<LogLevel>(level), static_cast<elasticapm::php::LogFeature>(feature))) {
+        if (lineNull) {
+            ELASTICAPM_G(globals)->logger_->printf(static_cast<LogLevel>(level), PRsv " " PRsv " " PRsv " " PRsv, PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), PRcsvArg(func, funcLength), PRcsvArg(message, messageLength));
+        }
         ELASTICAPM_G(globals)->logger_->printf(static_cast<LogLevel>(level), PRsv " " PRsv " %d " PRsv " " PRsv, PRcsvArg(category, categoryLength), PRcsvArg(file, fileLength), line, PRcsvArg(func, funcLength), PRcsvArg(message, messageLength));
     }
 }

diff --git a/prod/native/extension/code/ModuleIniEntries.cpp b/prod/native/extension/code/ModuleIniEntries.cpp
@@ -66,6 +66,7 @@ ELASTIC_OTEL_INI_ENTRY(EL_STRINGIFY(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_DIAGNOSTICS_
 ELASTIC_OTEL_INI_ENTRY(EL_STRINGIFY(ELASTIC_OTEL_CFG_OPT_NAME_MAX_SEND_QUEUE_SIZE))
 ELASTIC_OTEL_INI_ENTRY(EL_STRINGIFY(ELASTIC_OTEL_CFG_OPT_NAME_ASYNC_TRANSPORT))
 ELASTIC_OTEL_INI_ENTRY(EL_STRINGIFY(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_INSTRUMENT_ALL))
+ELASTIC_OTEL_INI_ENTRY(EL_STRINGIFY(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_PHP_HOOKS_ENABLED))
 PHP_INI_END()
 
 namespace elasticapm::php {

diff --git a/prod/native/libcommon/code/ConfigurationManager.h b/prod/native/libcommon/code/ConfigurationManager.h
@@ -112,7 +112,9 @@ class ConfigurationManager {
         BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_MAX_SEND_QUEUE_SIZE, OptionMetadata::type::bytes, false),
         BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_ASYNC_TRANSPORT, OptionMetadata::type::boolean, false),
         BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_ASYNC_TRANSPORT_SHUTDOWN_TIMEOUT, OptionMetadata::type::duration, false),
-        BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_INSTRUMENT_ALL, OptionMetadata::type::boolean, false)};
+        BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_INSTRUMENT_ALL, OptionMetadata::type::boolean, false),
+        BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_PHP_HOOKS_ENABLED, OptionMetadata::type::boolean, false)};
+
     // clang-format on
 };
 

diff --git a/prod/native/libcommon/code/ConfigurationSnapshot.h b/prod/native/libcommon/code/ConfigurationSnapshot.h
@@ -39,6 +39,7 @@
 #define ELASTIC_OTEL_CFG_OPT_NAME_ASYNC_TRANSPORT_SHUTDOWN_TIMEOUT async_transport_shutdown_timeout
 
 #define ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_INSTRUMENT_ALL debug_instrument_all
+#define ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_PHP_HOOKS_ENABLED debug_php_hooks_enabled
 
 namespace elasticapm::php {
 
@@ -59,6 +60,7 @@ struct ConfigurationSnapshot {
     bool ELASTIC_OTEL_CFG_OPT_NAME_ASYNC_TRANSPORT = true;
     std::chrono::milliseconds ELASTIC_OTEL_CFG_OPT_NAME_ASYNC_TRANSPORT_SHUTDOWN_TIMEOUT = std::chrono::seconds(30);
     bool ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_INSTRUMENT_ALL = false;
+    bool ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_PHP_HOOKS_ENABLED = false;
 
     uint64_t revision = 0;
 };

diff --git a/prod/php/ElasticOTel/InstrumentationBridge.php b/prod/php/ElasticOTel/InstrumentationBridge.php
@@ -24,8 +24,8 @@
 namespace Elastic\OTel;
 
 use Closure;
-use Elastic\OTel\Util\SingletonInstanceTrait;
 use Throwable;
+use Elastic\OTel\Util\SingletonInstanceTrait;
 
 /**
  * Code in this file is part of implementation internals, and thus it is not covered by the backward compatibility.
@@ -45,12 +45,16 @@ final class InstrumentationBridge
      */
     public array $delayedHooks = [];
 
+    private bool $enableDebugHooks;
+
     public function bootstrap(): void
     {
         self::elasticOTelHook(null, 'spl_autoload_register', null, Closure::fromCallable([$this, 'retryDelayedHooks']));
 
         require ProdPhpDir::$fullPath . DIRECTORY_SEPARATOR . 'OpenTelemetry' . DIRECTORY_SEPARATOR . 'Instrumentation' . DIRECTORY_SEPARATOR . 'hook.php';
 
+        $this->enableDebugHooks = (bool)\elastic_otel_get_config_option_by_name('debug_php_hooks_enabled'); // @phpstan-ignore function.notFound
+
         BootstrapStageLogger::logDebug('Finished successfully', __FILE__, __LINE__, __CLASS__, __FUNCTION__);
     }
 
@@ -63,7 +67,13 @@ public function hook(?string $class, string $function, ?Closure $pre = null, ?Cl
             return true;
         }
 
-        return self::elasticOTelHookNoThrow($class, $function, $pre, $post);
+        $success = self::elasticOTelHookNoThrow($class, $function, $pre, $post);
+
+        if ($this->enableDebugHooks) {
+            self::placeDebugHooks($class, $function);
+        }
+
+        return $success;
     }
 
     private function addToDelayedHooks(string $class, string $function, ?Closure $pre = null, ?Closure $post = null): void
@@ -132,4 +142,47 @@ private static function classOrInterfaceExists(string $classOrInterface): bool
     {
         return class_exists($classOrInterface) || interface_exists($classOrInterface);
     }
+
+    private static function placeDebugHooks(?string $class, string $function): void
+    {
+        $func = '\'';
+        if ($class) {
+            $func = $class . '::';
+        }
+        $func .= $function . '\'';
+
+        self::elasticOTelHookNoThrow($class, $function, function () use ($func) {
+          /**
+             * elastic_otel_* functions are provided by the extension
+             *
+             * @noinspection PhpFullyQualifiedNameUsageInspection, PhpUndefinedFunctionInspection
+             */
+            \elastic_otel_log_feature( // @phpstan-ignore function.notFound
+                0,
+                Log\Level::DEBUG,
+                Log\LogFeature::INSTRUMENTATION,
+                'PRE HOOK',
+                '',
+                null,
+                $func,
+                ('pre-hook data: ' . var_export(func_get_args(), true))
+            );
+        }, function () use ($func) {
+            /**
+             * elastic_otel_* functions are provided by the extension
+             *
+             * @noinspection PhpFullyQualifiedNameUsageInspection, PhpUndefinedFunctionInspection
+             */
+            \elastic_otel_log_feature( // @phpstan-ignore function.notFound
+                0,
+                Log\Level::DEBUG,
+                Log\LogFeature::INSTRUMENTATION,
+                'POST HOOK',
+                '',
+                null,
+                $func,
+                ('post-hook data: ' . var_export(func_get_args(), true))
+            );
+        });
+    }
 }