[loader] Assign an appropriate tag to each type of error (#2985)

* Assign an appropriate tag to each type of error * Update loader/dd_library_loader.c Co-authored-by: Florian Engelhardt <[email protected]> --------- Co-authored-by: Florian Engelhardt <[email protected]>
DataDog · Dec 10, 2024 · b928df9 · b928df9
1 parent b0da77f
commit b928df9
Show file tree

Hide file tree

Showing 4 changed files with 126 additions and 27 deletions.
diff --git a/loader/dd_library_loader.c b/loader/dd_library_loader.c
@@ -32,7 +32,7 @@ static bool already_done = false;
 # define OS_PATH "linux-gnu/"
 #endif
 
-static void ddloader_telemetryf(telemetry_reason reason, const char *format, ...);
+static void ddloader_telemetryf(telemetry_reason reason, const char *error, const char *format, ...);
 
 static char *ddtrace_pre_load_hook(void) {
     char *libddtrace_php;
@@ -218,7 +218,11 @@ void ddloader_logf(log_level level, const char *format, ...) {
     va_end(va);
 }
 
-static void ddloader_telemetryf(telemetry_reason reason, const char *format, ...) {
+/**
+ * @param error The c-string this is pointing to must not exceed 150 bytes
+ */
+static void ddloader_telemetryf(telemetry_reason reason, const char *error, const char *format, ...) {
+    log_level level = ERROR;
     switch (reason) {
         case REASON_ERROR:
             LOG(ERROR, "Error during instrumentation of application. Aborting.");
@@ -229,13 +233,17 @@ static void ddloader_telemetryf(telemetry_reason reason, const char *format, ...
         case REASON_INCOMPATIBLE_RUNTIME:
             LOG(ERROR, "Aborting application instrumentation due to an incompatible runtime");
             break;
+        case REASON_COMPLETE:
+        case REASON_ALREADY_LOADED:
+            level = INFO;
+            break;
         default:
             break;
     }
 
     va_list va;
     va_start(va, format);
-    ddloader_logv(reason == REASON_COMPLETE ? INFO : ERROR, format, va);
+    ddloader_logv(level, format, va);
     va_end(va);
 
     if (!telemetry_forwarder_path) {
@@ -257,13 +265,15 @@ static void ddloader_telemetryf(telemetry_reason reason, const char *format, ...
         return;  // parent
     }
 
-    char *points = "";
+    char points_buf[256] = {0};
+    char *points = points_buf;
     switch (reason) {
         case REASON_ERROR:
-            points =
-                "\
-                {\"name\": \"library_entrypoint.error\"}, \"tags\": [\"error_type:NA\"]}\
-            ";
+            snprintf(points_buf, sizeof(points_buf), "\
+                    {\"name\": \"library_entrypoint.error\", \"tags\": [\"error_type:%s\"]}\
+                ",
+                error ? error : "NA"
+            );
             break;
 
         case REASON_EOL_RUNTIME:
@@ -282,6 +292,13 @@ static void ddloader_telemetryf(telemetry_reason reason, const char *format, ...
             ";
             break;
 
+        case REASON_ALREADY_LOADED:
+            points =
+                "\
+                {\"name\": \"library_entrypoint.abort\", \"tags\": [\"reason:already_loaded\"]}\
+            ";
+            break;
+
         case REASON_COMPLETE:
             if (injection_forced) {
                 points =
@@ -417,13 +434,13 @@ static PHP_MINIT_FUNCTION(ddloader_injected_extension_minit) {
         }
     }
     if (!config) {
-        TELEMETRY(REASON_ERROR, "Unable to find the configuration for the injected extension. Something went wrong");
+        TELEMETRY(REASON_ERROR, "ext_not_found", "Unable to find the configuration for the injected extension. Something went wrong");
         return SUCCESS;
     }
 
     zend_module_entry *module = ddloader_zend_hash_str_find_ptr(php_api_no, &module_registry, config->ext_name, strlen(config->ext_name));
     if (module) {
-        LOG(INFO, "Extension '%s' is already loaded, unregister the injected extension", config->ext_name);
+        TELEMETRY(REASON_ALREADY_LOADED, NULL, "Extension '%s' is already loaded, unregister the injected extension", config->ext_name);
         ddloader_unregister_module(config->tmp_name);
 
         return SUCCESS;
@@ -433,7 +450,7 @@ static PHP_MINIT_FUNCTION(ddloader_injected_extension_minit) {
 
     // Normally done by zend_startup_module_ex, but we temporarily replaced these to skip potential errors. Check it ourselves here.
     if (!ddloader_check_deps(config->orig_module_deps)) {
-        TELEMETRY(REASON_INCOMPATIBLE_RUNTIME, "Extension '%s' dependencies are not met, unregister the injected extension", config->ext_name);
+        TELEMETRY(REASON_INCOMPATIBLE_RUNTIME, NULL, "Extension '%s' dependencies are not met, unregister the injected extension", config->ext_name);
         ddloader_unregister_module(config->tmp_name);
 
         return SUCCESS;
@@ -455,7 +472,7 @@ static PHP_MINIT_FUNCTION(ddloader_injected_extension_minit) {
 
     module = ddloader_zend_hash_str_find_ptr(php_api_no, &module_registry, config->ext_name, strlen(config->ext_name));
     if (!module) {
-        TELEMETRY(REASON_ERROR, "Extension '%s' not found after renaming. Something wrong happened", config->ext_name);
+        TELEMETRY(REASON_ERROR, "renamed_ext_not_found", "Extension '%s' not found after renaming. Something wrong happened", config->ext_name);
         return SUCCESS;
     }
 
@@ -465,7 +482,7 @@ static PHP_MINIT_FUNCTION(ddloader_injected_extension_minit) {
     module->deps = config->orig_module_deps;
     module->functions = config->orig_module_functions;
     if (module->functions && zend_register_functions(NULL, module->functions, NULL, module->type) == FAILURE) {
-        TELEMETRY(REASON_ERROR, "Unable to register extension's functions");
+        TELEMETRY(REASON_ERROR, "cannot_register_functions", "Unable to register extension's functions");
         return SUCCESS;
     }
 
@@ -475,9 +492,9 @@ static PHP_MINIT_FUNCTION(ddloader_injected_extension_minit) {
 
     zend_result ret = module->module_startup_func(INIT_FUNC_ARGS_PASSTHRU);
     if (ret == FAILURE) {
-        TELEMETRY(REASON_ERROR, "'%s' MINIT function failed", config->ext_name);
+        TELEMETRY(REASON_ERROR, "error_minit", "'%s' MINIT function failed", config->ext_name);
     } else {
-        TELEMETRY(REASON_COMPLETE, "Application instrumentation bootstrapping complete ('%s')", config->ext_name)
+        TELEMETRY(REASON_COMPLETE, NULL, "Application instrumentation bootstrapping complete ('%s')", config->ext_name)
     }
 
     return ret;
@@ -486,7 +503,12 @@ static PHP_MINIT_FUNCTION(ddloader_injected_extension_minit) {
 static int ddloader_load_extension(unsigned int php_api_no, char *module_build_id, bool is_zts, bool is_debug, injected_ext *config) {
     char *ext_path = ddloader_find_ext_path(config->ext_dir, config->ext_name, php_api_no, is_zts, is_debug);
     if (!ext_path) {
-        TELEMETRY(REASON_INCOMPATIBLE_RUNTIME, "'%s' extension file not found", config->ext_name);
+        if (is_debug) {
+            TELEMETRY(REASON_INCOMPATIBLE_RUNTIME, NULL, "'%s' extension file not found (debug build)", config->ext_name);
+        } else {
+            TELEMETRY(REASON_ERROR, "so_not_found", "'%s' extension file not found", config->ext_name);
+        }
+
         return SUCCESS;
     }
 
@@ -499,32 +521,32 @@ static int ddloader_load_extension(unsigned int php_api_no, char *module_build_i
         LOG(INFO, "Running '%s' pre-load hook", config->ext_name);
         char *err = config->pre_load_hook();
         if (err) {
-            TELEMETRY(REASON_ERROR, "An error occurred while running '%s' pre-load hook: %s", config->ext_name, err);
+            TELEMETRY(REASON_ERROR, "error_ext_pre_load", "An error occurred while running '%s' pre-load hook: %s", config->ext_name, err);
             goto abort;
         }
     }
 
     void *handle = DL_LOAD(ext_path);
     if (!handle) {
-        TELEMETRY(REASON_ERROR, "Cannot load '%s' extension file: %s", config->ext_name, dlerror());
+        TELEMETRY(REASON_ERROR, "cannot_load_file", "Cannot load '%s' extension file: %s", config->ext_name, dlerror());
         goto abort;
     }
 
     zend_module_entry *(*get_module)(void) = (zend_module_entry * (*)(void)) ddloader_dl_fetch_symbol(handle, "_get_module");
     if (!get_module) {
-        TELEMETRY(REASON_ERROR, "Cannot fetch '%s' module entry", config->ext_name);
+        TELEMETRY(REASON_ERROR, "cannot_fetch_mod_entry", "Cannot fetch '%s' module entry", config->ext_name);
         goto abort_and_unload;
     }
 
     zend_module_entry *module_entry = get_module();
 
     if (module_entry->zend_api != php_api_no) {
-        TELEMETRY(REASON_ERROR, "'%s' API number mismatch between module (%d) and runtime (%d)", config->ext_name, module_entry->zend_api,
+        TELEMETRY(REASON_ERROR, "api_mismatch", "'%s' API number mismatch between module (%d) and runtime (%d)", config->ext_name, module_entry->zend_api,
                   php_api_no);
         goto abort_and_unload;
     }
     if (strcmp(module_entry->build_id, module_build_id)) {
-        TELEMETRY(REASON_ERROR, "'%s' Build ID mismatch between module (%s) and runtime (%s)", config->ext_name, module_entry->build_id,
+        TELEMETRY(REASON_ERROR, "build_id_mismatch", "'%s' Build ID mismatch between module (%s) and runtime (%s)", config->ext_name, module_entry->build_id,
                   module_build_id);
         goto abort_and_unload;
     }
@@ -554,7 +576,7 @@ static int ddloader_load_extension(unsigned int php_api_no, char *module_build_i
     ddloader_restore_zend_error_cb();
 
     if (module_entry == NULL) {
-        TELEMETRY(REASON_ERROR, "Cannot register '%s' module", config->ext_name);
+        TELEMETRY(REASON_ERROR, "cannot_register_ext", "Cannot register '%s' module", config->ext_name);
         goto abort_and_unload;
     }
 
@@ -660,7 +682,7 @@ static int ddloader_api_no_check(int api_no) {
     }
 
     if (!package_path) {
-        TELEMETRY(REASON_ERROR, "DD_LOADER_PACKAGE_PATH environment variable is not set");
+        TELEMETRY(REASON_ERROR, "path_env_var_not_set", "DD_LOADER_PACKAGE_PATH environment variable is not set");
         return SUCCESS;
     }
 
@@ -680,7 +702,7 @@ static int ddloader_api_no_check(int api_no) {
         default:
             if (!force_load || api_no < 320151012) {
                 telemetry_reason reason = api_no < 320151012 ? REASON_EOL_RUNTIME : REASON_INCOMPATIBLE_RUNTIME;
-                TELEMETRY(reason, "Found incompatible runtime (api no: %d). Supported runtimes: PHP 7.0 to 8.3", api_no);
+                TELEMETRY(reason, NULL, "Found incompatible runtime (api no: %d). Supported runtimes: PHP 7.0 to 8.3", api_no);
 
                 // If we return FAILURE, this Zend extension would be unload, BUT it would produce an error
                 // similar to "The Zend Engine API version 220100525 which is installed, is newer."
@@ -720,7 +742,7 @@ static int ddloader_build_id_check(const char *build_id) {
 
     // Guardrail
     if (*module_build_id == '\0') {
-        TELEMETRY(REASON_ERROR, "Invalid build id");
+        TELEMETRY(REASON_ERROR, "invalid_build_id", "Invalid build id");
         return SUCCESS;
     }
 

diff --git a/loader/php_dd_library_loader.h b/loader/php_dd_library_loader.h
@@ -24,10 +24,11 @@ typedef enum {
     REASON_ERROR,
     REASON_EOL_RUNTIME,
     REASON_INCOMPATIBLE_RUNTIME,
+    REASON_ALREADY_LOADED,
     REASON_COMPLETE,
 } telemetry_reason;
 
-#define TELEMETRY(reason, format, ...) ddloader_telemetryf(reason, format, ##__VA_ARGS__);
+#define TELEMETRY(reason, error, format, ...) ddloader_telemetryf(reason, error, format, ##__VA_ARGS__);
 
 #define DECLARE_INJECTED_EXT(name, dir, _pre_load_hook, _pre_minit_hook, deps)                      \
     {                                                                                               \

diff --git a/loader/tests/functional/test_ddtrace_already_loaded.php b/loader/tests/functional/test_ddtrace_already_loaded.php
@@ -12,8 +12,43 @@
 $tmp = tempnam(sys_get_temp_dir(), 'test_loader_');
 copy($ext, $tmp);
 
-$output = runCLI('-dextension='.$tmp.' -v', true, ['DD_TRACE_DEBUG=1']);
+$telemetryLogPath = tempnam(sys_get_temp_dir(), 'test_loader_');
+
+$output = runCLI('-dextension='.$tmp.' -v', true, [
+    'DD_TRACE_DEBUG=1',
+    'FAKE_FORWARDER_LOG_PATH='.$telemetryLogPath,
+    'DD_TELEMETRY_FORWARDER_PATH='.__DIR__.'/../../bin/fake_forwarder.sh',
+]);
 assertContains($output, 'Found extension file');
 assertContains($output, 'Extension \'ddtrace\' is already loaded, unregister the injected extension');
 assertContains($output, 'with ddtrace v');
 assertContains($output, 'with dd_library_loader v');
+
+// Let time to the fork to write the telemetry log
+usleep(5000);
+
+$raw = file_get_contents($telemetryLogPath);
+$payload = json_decode($raw, true);
+
+$format = <<<EOS
+{
+    "metadata": {
+        "runtime_name": "php",
+        "runtime_version": "%d.%d.%d%S",
+        "language_name": "php",
+        "language_version": "%d.%d.%d%S",
+        "tracer_version": "%s",
+        "pid": %d
+    },
+    "points": [
+        {
+            "name": "library_entrypoint.abort",
+            "tags": [
+                "reason:already_loaded"
+            ]
+        }
+    ]
+}
+EOS;
+
+assertMatchesFormat(json_encode($payload, JSON_PRETTY_PRINT), $format);
diff --git a/loader/tests/functional/test_telemetry_error.php b/loader/tests/functional/test_telemetry_error.php
@@ -0,0 +1,41 @@
+<?php
+
+require_once __DIR__."/includes/autoload.php";
+skip_if_php5();
+
+$telemetryLogPath = tempnam(sys_get_temp_dir(), 'test_loader_');
+
+$output = runCLI('-v', true, [
+    'FAKE_FORWARDER_LOG_PATH='.$telemetryLogPath,
+    'DD_TELEMETRY_FORWARDER_PATH='.__DIR__.'/../../bin/fake_forwarder.sh',
+    'DD_LOADER_PACKAGE_PATH=/foo/bar'
+]);
+
+// Let time to the fork to write the telemetry log
+usleep(5000);
+
+$raw = file_get_contents($telemetryLogPath);
+$payload = json_decode($raw, true);
+
+$format = <<<EOS
+{
+    "metadata": {
+        "runtime_name": "php",
+        "runtime_version": "%d.%d.%d%S",
+        "language_name": "php",
+        "language_version": "%d.%d.%d%S",
+        "tracer_version": "%s",
+        "pid": %d
+    },
+    "points": [
+        {
+            "name": "library_entrypoint.error",
+            "tags": [
+                "error_type:so_not_found"
+            ]
+        }
+    ]
+}
+EOS;
+
+assertMatchesFormat(json_encode($payload, JSON_PRETTY_PRINT), $format);