From b928df9649852501968af1b9a667acc26c25ab6e Mon Sep 17 00:00:00 2001 From: Luc Vieillescazes Date: Tue, 10 Dec 2024 11:02:44 +0100 Subject: [PATCH] [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 --------- Co-authored-by: Florian Engelhardt --- loader/dd_library_loader.c | 72 ++++++++++++------- loader/php_dd_library_loader.h | 3 +- .../test_ddtrace_already_loaded.php | 37 +++++++++- .../tests/functional/test_telemetry_error.php | 41 +++++++++++ 4 files changed, 126 insertions(+), 27 deletions(-) create mode 100644 loader/tests/functional/test_telemetry_error.php diff --git a/loader/dd_library_loader.c b/loader/dd_library_loader.c index 0a3365c493..dcc9692a41 100644 --- 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 index 270f4c07c4..57f1222986 100644 --- 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 index f795ad4a68..66861b42ba 100644 --- 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 = <<