Debug mode to instrument all user functions (#144)

elastic · Jan 7, 2025 · 2e9db4c · 2e9db4c
1 parent 11d0872
commit 2e9db4c
Show file tree

Hide file tree

Showing 7 changed files with 110 additions and 29 deletions.
diff --git a/prod/native/extension/code/InternalFunctionInstrumentation.cpp b/prod/native/extension/code/InternalFunctionInstrumentation.cpp
@@ -435,32 +435,37 @@ zend_observer_fcall_handlers elasticRegisterObserver(zend_execute_data *execute_
             ELOGF_TRACE(EAPM_GL(logger_), INSTRUMENTATION, "elasticRegisterObserver hash: 0x%X " PRsv "::" PRsv ", not marked to be instrumented", hash, PRsvArg(cls), PRsvArg(func));
         }
 
-        auto ce = execute_data->func->common.scope;
-        if (!ce) {
-            return {nullptr, nullptr};
-        }
-
         // lookup for class interfaces
-        for (uint32_t i = 0; i < ce->num_interfaces; ++i) {
-            auto classHash = ZSTR_HASH(ce->interfaces[i]->name);
-            zend_ulong funcHash = ZSTR_HASH(execute_data->func->common.function_name);
-            zend_ulong ifaceHash = classHash ^ (funcHash << 1);
-
-            callbacks = reinterpret_cast<InstrumentedFunctionHooksStorage_t *>(EAPM_GL(hooksStorage_).get())->find(ifaceHash);
-            if (callbacks) {
-                if (EAPM_GL(logger_)->doesMeetsLevelCondition(LogLevel::logLevel_trace)) {
-                    auto [cls, func] = getClassAndFunctionName(execute_data);
-                    ELOGF_TRACE(EAPM_GL(logger_), INSTRUMENTATION, "elasticRegisterObserver hash: 0x%X " PRsv "::" PRsv ", will be instrumented because interface 0x%X '" PRsv "' was marked to be instrumented", hash, PRsvArg(cls), PRsvArg(func), ifaceHash, PRzsArg(ce->interfaces[i]->name));
-                }
-                // copy callbacks from interface storage hash to implementation hash
-                for (auto &item : *callbacks) {
-                    reinterpret_cast<InstrumentedFunctionHooksStorage_t *>(EAPM_GL(hooksStorage_).get())->store(hash, AutoZval(item.first.get()), AutoZval(item.second.get()));
+        auto ce = execute_data->func->common.scope;
+        if (ce) {
+            for (uint32_t i = 0; i < ce->num_interfaces; ++i) {
+                auto classHash = ZSTR_HASH(ce->interfaces[i]->name);
+                zend_ulong funcHash = ZSTR_HASH(execute_data->func->common.function_name);
+                zend_ulong ifaceHash = classHash ^ (funcHash << 1);
+
+                callbacks = reinterpret_cast<InstrumentedFunctionHooksStorage_t *>(EAPM_GL(hooksStorage_).get())->find(ifaceHash);
+                if (callbacks) {
+                    if (EAPM_GL(logger_)->doesMeetsLevelCondition(LogLevel::logLevel_trace)) {
+                        auto [cls, func] = getClassAndFunctionName(execute_data);
+                        ELOGF_TRACE(EAPM_GL(logger_), INSTRUMENTATION, "elasticRegisterObserver hash: 0x%X " PRsv "::" PRsv ", will be instrumented because interface 0x%X '" PRsv "' was marked to be instrumented", hash, PRsvArg(cls), PRsvArg(func), ifaceHash, PRzsArg(ce->interfaces[i]->name));
+                    }
+                    // copy callbacks from interface storage hash to implementation hash
+                    for (auto &item : *callbacks) {
+                        reinterpret_cast<InstrumentedFunctionHooksStorage_t *>(EAPM_GL(hooksStorage_).get())->store(hash, AutoZval(item.first.get()), AutoZval(item.second.get()));
+                    }
+                    break;
                 }
-                break;
             }
         }
     }
 
+    if (EAPM_GL(config_)->get().debug_instrument_all && EAPM_GL(requestScope_)->isFunctional()) {
+        std::string_view filename(ZSTR_VAL(execute_data->func->op_array.filename), ZSTR_LEN(execute_data->func->op_array.filename));
+        if (!(execute_data->func->common.fn_flags & ZEND_ACC_CLOSURE) && filename.find("/ElasticOTel/") == std::string_view::npos && filename.find("/open-telemetry/") == std::string_view::npos) {
+            callbacks = reinterpret_cast<InstrumentedFunctionHooksStorage_t *>(EAPM_GL(hooksStorage_).get())->storeFront(hash, AutoZval("Elastic\\OTel\\PhpPartFacade::debugPreHook"sv), AutoZval("Elastic\\OTel\\PhpPartFacade::debugPostHook"));
+        }
+    }
+
     if (!callbacks) {
         return {nullptr, nullptr};
     }

diff --git a/prod/native/extension/code/ModuleIniEntries.cpp b/prod/native/extension/code/ModuleIniEntries.cpp
@@ -65,7 +65,7 @@ ELASTIC_OTEL_INI_ENTRY(EL_STRINGIFY(ELASTIC_OTEL_CFG_OPT_NAME_VERIFY_SERVER_CERT
 ELASTIC_OTEL_INI_ENTRY(EL_STRINGIFY(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_DIAGNOSTICS_FILE))
 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))
 PHP_INI_END()
 
 namespace elasticapm::php {

diff --git a/prod/native/libcommon/code/ConfigurationManager.h b/prod/native/libcommon/code/ConfigurationManager.h
@@ -111,7 +111,8 @@ class ConfigurationManager {
         BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_VERIFY_SERVER_CERT, OptionMetadata::type::boolean, false),
         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_ASYNC_TRANSPORT_SHUTDOWN_TIMEOUT, OptionMetadata::type::duration, false),
+        BUILD_METADATA(ELASTIC_OTEL_CFG_OPT_NAME_DEBUG_INSTRUMENT_ALL, OptionMetadata::type::boolean, false)};
     // clang-format on
 };
 

diff --git a/prod/native/libcommon/code/ConfigurationSnapshot.h b/prod/native/libcommon/code/ConfigurationSnapshot.h
@@ -38,6 +38,8 @@
 #define ELASTIC_OTEL_CFG_OPT_NAME_ASYNC_TRANSPORT async_transport
 #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
+
 namespace elasticapm::php {
 
 using namespace std::string_literals;
@@ -56,6 +58,7 @@ struct ConfigurationSnapshot {
     std::size_t ELASTIC_OTEL_CFG_OPT_NAME_MAX_SEND_QUEUE_SIZE = 2 * 1024 * 1204;
     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;
 
     uint64_t revision = 0;
 };

diff --git a/prod/native/libcommon/code/InstrumentedFunctionHooksStorage.h b/prod/native/libcommon/code/InstrumentedFunctionHooksStorage.h
@@ -42,6 +42,11 @@ class InstrumentedFunctionHooksStorage : public InstrumentedFunctionHooksStorage
         callbacks_[functionKey].emplace_back(callbacks_t(std::move(callableOnEntry), std::move(callableOnExit)));
     }
 
+    std::list<callbacks_t> *storeFront(key_t functionKey, callback_t callableOnEntry, callback_t callableOnExit) {
+        callbacks_[functionKey].emplace_front(callbacks_t(std::move(callableOnEntry), std::move(callableOnExit)));
+        return &callbacks_[functionKey];
+    }
+
     std::list<callbacks_t> *find(key_t functionKey) {
         auto found = callbacks_.find(functionKey);
         if (found == std::end(callbacks_)) {

diff --git a/prod/php/ElasticOTel/PhpPartFacade.php b/prod/php/ElasticOTel/PhpPartFacade.php
@@ -26,7 +26,14 @@
 use Elastic\OTel\Util\HiddenConstructorTrait;
 use Elastic\OTel\Log\ElasticLogWriter;
 use Elastic\OTel\HttpTransport\ElasticHttpTransportFactory;
+use OpenTelemetry\API\Globals;
 use OpenTelemetry\SDK\SdkAutoloader;
+use OpenTelemetry\API\Trace\Span;
+use OpenTelemetry\API\Trace\SpanKind;
+use OpenTelemetry\API\Trace\StatusCode;
+use OpenTelemetry\Context\Context;
+use OpenTelemetry\SemConv\TraceAttributes;
+use OpenTelemetry\SemConv\Version;
 use RuntimeException;
 use Throwable;
 
@@ -47,6 +54,7 @@ final class PhpPartFacade
     use HiddenConstructorTrait;
 
     private static ?self $singletonInstance = null;
+    private static bool $rootSpanEnded = false;
 
     /**
      * Called by the extension
@@ -98,7 +106,9 @@ public static function bootstrap(string $elasticOTelNativePartVersion, int $maxE
                 return false;
             }
 
-            Traces\ElasticRootSpan::startRootSpan();
+            Traces\ElasticRootSpan::startRootSpan(function () {
+                PhpPartFacade::$rootSpanEnded = true;
+            });
 
             self::$singletonInstance = new self();
         } catch (Throwable $throwable) {
@@ -228,4 +238,57 @@ public static function shutdown(): void
     {
         self::$singletonInstance = null;
     }
+
+    /** @phpstan-ignore-next-line */
+    public static function debugPreHook(mixed $object, array $params, ?string $class, string $function, ?string $filename, ?int $lineno): void
+    {
+        if (self::$rootSpanEnded) {
+            return;
+        }
+
+        $tracer = Globals::tracerProvider()->getTracer(
+            'co.elastic.edot.php.debug',
+            null,
+            Version::VERSION_1_25_0->url(),
+        );
+
+        $parent = Context::getCurrent();
+        /** @phpstan-ignore-next-line */
+        $span = $tracer->spanBuilder($class ? $class . "::" . $function : $function)
+            ->setSpanKind(SpanKind::KIND_CLIENT)
+            ->setParent($parent)
+            ->setAttribute(TraceAttributes::CODE_NAMESPACE, $class)
+            ->setAttribute(TraceAttributes::CODE_FUNCTION, $function)
+            ->setAttribute(TraceAttributes::CODE_FILEPATH, $filename)
+            ->setAttribute(TraceAttributes::CODE_LINENO, $lineno)
+            ->setAttribute('call.arguments', print_r($params, true))
+            ->startSpan();
+
+        $context = $span->storeInContext($parent);
+        Context::storage()->attach($context);
+    }
+
+    /** @phpstan-ignore-next-line */
+    public static function debugPostHook(mixed $object, array $params, mixed $retval, ?Throwable $exception): void
+    {
+        if (self::$rootSpanEnded) {
+            return;
+        }
+
+        $scope = Context::storage()->scope();
+        if (!$scope) {
+            return;
+        }
+
+        $scope->detach();
+        $span = Span::fromContext($scope->context());
+        $span->setAttribute('call.return_value', print_r($retval, true));
+
+        if ($exception) {
+            $span->recordException($exception, [TraceAttributes::EXCEPTION_ESCAPED => true]);
+            $span->setStatus(StatusCode::STATUS_ERROR, $exception->getMessage());
+        }
+
+        $span->end();
+    }
 }
diff --git a/prod/php/ElasticOTel/Traces/ElasticRootSpan.php b/prod/php/ElasticOTel/Traces/ElasticRootSpan.php
@@ -46,7 +46,7 @@ class ElasticRootSpan
 
     private const DEFAULT_SPAN_NAME_FOR_SCRIPT = '<script>';
 
-    public static function startRootSpan(): void
+    public static function startRootSpan(?callable $notifySpanEnded): void
     {
         if (php_sapi_name() === 'cli') {
             if (!Configuration::getBoolean('ELASTIC_OTEL_TRANSACTION_SPAN_ENABLED_CLI', true)) {
@@ -61,7 +61,7 @@ public static function startRootSpan(): void
         $request = self::createRequest();
         if ($request) {
             self::create($request);
-            self::registerShutdownHandler($request);
+            self::registerShutdownHandler($request, $notifySpanEnded);
         } else {
             self::logWarning('Unable to create server request');
         }
@@ -132,11 +132,15 @@ private static function createRequest(): ?ServerRequestInterface
     /**
      * @internal
      */
-    private static function registerShutdownHandler(ServerRequestInterface $request): void
+    private static function registerShutdownHandler(ServerRequestInterface $request, ?callable $notifySpanEnded): void
     {
-        $shutdownFunc = function () use ($request) {
-            self::shutdownHandler($request);
-        };
+        $shutdownFunc =
+            function () use ($request, $notifySpanEnded) {
+                if ($notifySpanEnded) {
+                    $notifySpanEnded();
+                }
+                self::shutdownHandler($request);
+            };
 
         ShutdownHandler::register($shutdownFunc(...));
     }