From e721e3489ae50480cb331304547f085faa2379fa Mon Sep 17 00:00:00 2001 From: Luc Vieillescazes Date: Fri, 12 Apr 2024 19:35:39 +0200 Subject: [PATCH] Collect 'logs_created' internal metric (#2604) * Collect 'logs_created' internal metric * Replace usage of zend_string_concat2 by zai_string_concat3 for compatibility * Send 'logs_created' metric when count is greater than 0 * Make agent's dump filename unique for each tests so they can run in parallel * Try to fix compilation on Windows * Fix flaky test * Current collected metrics are all commons * Fix wrong namespace --- components-rs/common.h | 28 ++--- components-rs/ddtrace.h | 9 +- components-rs/log.rs | 27 +++- components-rs/telemetry.rs | 15 ++- ext/ddtrace.c | 7 +- ext/sidecar.h | 4 + ext/telemetry.c | 25 +++- .../Custom/Autoloaded/InstrumentationTest.php | 38 +++--- tests/ext/telemetry/metrics_logs_created.phpt | 115 ++++++++++++++++++ ...etrics.phpt => metrics_spans_created.phpt} | 23 ++-- 10 files changed, 233 insertions(+), 58 deletions(-) create mode 100644 tests/ext/telemetry/metrics_logs_created.phpt rename tests/ext/telemetry/{metrics.phpt => metrics_spans_created.phpt} (90%) diff --git a/components-rs/common.h b/components-rs/common.h index 969b38a7c0..e989c43bf8 100644 --- a/components-rs/common.h +++ b/components-rs/common.h @@ -146,6 +146,20 @@ typedef enum ddog_Log { DDOG_LOG_HOOK_TRACE = (5 | (4 << 4)), } ddog_Log; +typedef enum ddog_MetricNamespace { + DDOG_METRIC_NAMESPACE_TRACERS, + DDOG_METRIC_NAMESPACE_PROFILERS, + DDOG_METRIC_NAMESPACE_RUM, + DDOG_METRIC_NAMESPACE_APPSEC, + DDOG_METRIC_NAMESPACE_IDE_PLUGINS, + DDOG_METRIC_NAMESPACE_LIVE_DEBUGGER, + DDOG_METRIC_NAMESPACE_IAST, + DDOG_METRIC_NAMESPACE_GENERAL, + DDOG_METRIC_NAMESPACE_TELEMETRY, + DDOG_METRIC_NAMESPACE_APM, + DDOG_METRIC_NAMESPACE_SIDECAR, +} ddog_MetricNamespace; + typedef struct ddog_BlockingTransport_SidecarInterfaceResponse__SidecarInterfaceRequest ddog_BlockingTransport_SidecarInterfaceResponse__SidecarInterfaceRequest; typedef struct ddog_InstanceId ddog_InstanceId; @@ -176,20 +190,6 @@ typedef enum ddog_LogLevel { DDOG_LOG_LEVEL_DEBUG, } ddog_LogLevel; -typedef enum ddog_MetricNamespace { - DDOG_METRIC_NAMESPACE_TRACERS, - DDOG_METRIC_NAMESPACE_PROFILERS, - DDOG_METRIC_NAMESPACE_RUM, - DDOG_METRIC_NAMESPACE_APPSEC, - DDOG_METRIC_NAMESPACE_IDE_PLUGINS, - DDOG_METRIC_NAMESPACE_LIVE_DEBUGGER, - DDOG_METRIC_NAMESPACE_IAST, - DDOG_METRIC_NAMESPACE_GENERAL, - DDOG_METRIC_NAMESPACE_TELEMETRY, - DDOG_METRIC_NAMESPACE_APM, - DDOG_METRIC_NAMESPACE_SIDECAR, -} ddog_MetricNamespace; - typedef enum ddog_MetricType { DDOG_METRIC_TYPE_GAUGE, DDOG_METRIC_TYPE_COUNT, diff --git a/components-rs/ddtrace.h b/components-rs/ddtrace.h index 7981ea96ea..4dd7af7122 100644 --- a/components-rs/ddtrace.h +++ b/components-rs/ddtrace.h @@ -143,7 +143,9 @@ void ddog_set_log_level(ddog_CharSlice level, bool once); void ddog_log(enum ddog_Log category, bool once, ddog_CharSlice msg); -void ddog_reset_log_once(void); +void ddog_reset_logger(void); + +uint32_t ddog_get_logs_count(ddog_CharSlice level); bool ddtrace_detect_composer_installed_json(ddog_SidecarTransport **transport, const struct ddog_InstanceId *instance_id, @@ -172,12 +174,13 @@ ddog_MaybeError ddog_sidecar_telemetry_buffer_flush(ddog_SidecarTransport **tran struct ddog_SidecarActionsBuffer *buffer); void ddog_sidecar_telemetry_register_metric_buffer(struct ddog_SidecarActionsBuffer *buffer, - ddog_CharSlice metric_name); + ddog_CharSlice metric_name, + enum ddog_MetricNamespace namespace_); void ddog_sidecar_telemetry_add_span_metric_point_buffer(struct ddog_SidecarActionsBuffer *buffer, ddog_CharSlice metric_name, double metric_value, - ddog_CharSlice integration_name); + ddog_CharSlice tags); ddog_MaybeError ddog_sidecar_connect_php(ddog_SidecarTransport **connection, const char *error_path, diff --git a/components-rs/log.rs b/components-rs/log.rs index cd66a532eb..30a4f4f25a 100644 --- a/components-rs/log.rs +++ b/components-rs/log.rs @@ -1,7 +1,8 @@ use std::cell::RefCell; -use std::collections::BTreeSet; +use std::collections::{BTreeSet, HashMap}; use std::ffi::c_char; use std::fmt::Debug; +use std::str::FromStr; use tracing::Level; use tracing_core::{Event, Field, LevelFilter, Subscriber}; use tracing_subscriber::EnvFilter; @@ -39,6 +40,7 @@ pub static mut ddog_log_callback: Option = None; std::thread_local! { static LOGGED_MSGS: RefCell> = RefCell::default(); static TRACING_GUARDS: RefCell> = RefCell::default(); + static COUNTERS: RefCell> = RefCell::default(); } macro_rules! with_target { @@ -144,6 +146,12 @@ impl FormatEvent for LogFormatter } else { fmt_msg(event, &msg, "") }; + + COUNTERS.with(|counter| { + let mut counter = counter.borrow_mut(); + *counter.entry(event.metadata().level().to_owned()).or_default() += 1; + }); + cb(unsafe { CharSlice::from_raw_parts(msg.as_ptr() as *const c_char, msg.len() - 1) }); } } @@ -182,9 +190,24 @@ pub unsafe extern "C" fn ddog_log(category: Log, once: bool, msg: CharSlice) { } #[no_mangle] -pub extern "C" fn ddog_reset_log_once() { +pub extern "C" fn ddog_reset_logger() { LOGGED_MSGS.with(|logged| { let mut logged = logged.borrow_mut(); logged.clear(); }); + + COUNTERS.with(|counter| { + let mut counter = counter.borrow_mut(); + counter.clear(); + }); +} + +#[no_mangle] +pub extern "C" fn ddog_get_logs_count(level: CharSlice) -> u32 { + return COUNTERS.with(|counter| { + let level = Level::from_str(&level.to_utf8_lossy()).unwrap(); + + let mut counter = counter.borrow_mut(); + *counter.entry(level).or_default() + }); } diff --git a/components-rs/telemetry.rs b/components-rs/telemetry.rs index cf6bbb36a4..197ea293d8 100644 --- a/components-rs/telemetry.rs +++ b/components-rs/telemetry.rs @@ -2,8 +2,9 @@ use datadog_sidecar::interface::blocking::SidecarTransport; use datadog_sidecar::interface::{blocking, InstanceId, QueueId, SidecarAction}; use ddcommon_ffi::slice::AsBytes; use ddcommon_ffi::CharSlice; -use ddcommon::tag::Tag; +use ddcommon::tag::parse_tags; use ddtelemetry::data; +use ddtelemetry::data::metrics::MetricNamespace; use ddtelemetry::data::{Dependency, Integration}; use ddtelemetry::metrics::MetricContext; use ddtelemetry::worker::TelemetryActions; @@ -134,14 +135,15 @@ pub extern "C" fn ddog_sidecar_telemetry_buffer_flush( pub unsafe extern "C" fn ddog_sidecar_telemetry_register_metric_buffer( buffer: &mut SidecarActionsBuffer, metric_name: CharSlice, + namespace: MetricNamespace, ) { buffer.buffer.push(SidecarAction::RegisterTelemetryMetric(MetricContext { name: metric_name.to_utf8_lossy().into_owned(), - namespace: data::metrics::MetricNamespace::Tracers, + namespace, metric_type: data::metrics::MetricType::Count, tags: Vec::default(), - common: false, + common: true, })); } @@ -150,12 +152,9 @@ pub unsafe extern "C" fn ddog_sidecar_telemetry_add_span_metric_point_buffer( buffer: &mut SidecarActionsBuffer, metric_name: CharSlice, metric_value: f64, - integration_name: CharSlice, + tags: CharSlice, ) { - let mut tags: Vec = Vec::default(); - if integration_name.len() > 0 { - tags.push(Tag::new("integration_name", integration_name.to_utf8_lossy().into_owned()).unwrap()) - } + let (tags, _) = parse_tags(&tags.to_utf8_lossy()); buffer.buffer.push(SidecarAction::AddTelemetryMetricPoint(( metric_name.to_utf8_lossy().into_owned(), diff --git a/ext/ddtrace.c b/ext/ddtrace.c index 015fa9a37c..76e0d514cc 100644 --- a/ext/ddtrace.c +++ b/ext/ddtrace.c @@ -413,7 +413,7 @@ static void dd_activate_once(void) { static pthread_once_t dd_activate_once_control = PTHREAD_ONCE_INIT; static void ddtrace_activate(void) { - ddog_reset_log_once(); + ddog_reset_logger(); zai_hook_rinit(); zai_interceptor_activate(); @@ -2045,6 +2045,11 @@ PHP_FUNCTION(dd_trace_internal_fn) { ddtrace_coms_synchronous_flush(timeout); RETVAL_TRUE; #endif + } else if (FUNCTION_NAME_MATCHES("test_logs")) { + ddog_logf(DDOG_LOG_WARN, false, "foo"); + ddog_logf(DDOG_LOG_WARN, false, "bar"); + ddog_logf(DDOG_LOG_ERROR, false, "Boum"); + RETVAL_TRUE; } } } diff --git a/ext/sidecar.h b/ext/sidecar.h index ce5906b73e..9673e7ea0f 100644 --- a/ext/sidecar.h +++ b/ext/sidecar.h @@ -14,6 +14,10 @@ static inline ddog_CharSlice dd_zend_string_to_CharSlice(zend_string *str) { return (ddog_CharSlice){ .len = str->len, .ptr = str->val }; } +static inline ddog_CharSlice dd_zai_string_to_CharSlice(zai_string str) { + return (ddog_CharSlice){ .len = str.len, .ptr = str.ptr }; +} + static inline bool ddtrace_ffi_try(const char *msg, ddog_Option_VecU8 maybe_error) { if (maybe_error.tag == DDOG_OPTION_VEC_U8_SOME_VEC_U8) { LOG(ERROR, "%s: %.*s", msg, (int) maybe_error.some.len, maybe_error.some.ptr); diff --git a/ext/telemetry.c b/ext/telemetry.c index 3a2bcb49ae..ae17236064 100644 --- a/ext/telemetry.c +++ b/ext/telemetry.c @@ -80,13 +80,34 @@ void ddtrace_telemetry_finalize(void) { // Telemetry metrics ddog_CharSlice metric_name = DDOG_CHARSLICE_C("spans_created"); - ddog_sidecar_telemetry_register_metric_buffer(buffer, metric_name); + ddog_sidecar_telemetry_register_metric_buffer(buffer, metric_name, DDOG_METRIC_NAMESPACE_TRACERS); zend_string *integration_name; zval *metric_value; ZEND_HASH_FOREACH_STR_KEY_VAL(&DDTRACE_G(telemetry_spans_created_per_integration), integration_name, metric_value) { - ddog_sidecar_telemetry_add_span_metric_point_buffer(buffer, metric_name, Z_DVAL_P(metric_value), dd_zend_string_to_CharSlice(integration_name)); + zai_string tags = zai_string_concat3((zai_str)ZAI_STRL("integration_name:"), (zai_str)ZAI_STR_FROM_ZSTR(integration_name), (zai_str)ZAI_STRING_EMPTY); + ddog_sidecar_telemetry_add_span_metric_point_buffer(buffer, metric_name, Z_DVAL_P(metric_value), dd_zai_string_to_CharSlice(tags)); + zai_string_destroy(&tags); } ZEND_HASH_FOREACH_END(); + metric_name = DDOG_CHARSLICE_C("logs_created"); + ddog_sidecar_telemetry_register_metric_buffer(buffer, metric_name, DDOG_METRIC_NAMESPACE_GENERAL); + static struct { + ddog_CharSlice level; + ddog_CharSlice tags; + } log_levels[] = { + {DDOG_CHARSLICE_C_BARE("trace"), DDOG_CHARSLICE_C_BARE("level:trace")}, + {DDOG_CHARSLICE_C_BARE("debug"), DDOG_CHARSLICE_C_BARE("level:debug")}, + {DDOG_CHARSLICE_C_BARE("info"), DDOG_CHARSLICE_C_BARE("level:info")}, + {DDOG_CHARSLICE_C_BARE("warn"), DDOG_CHARSLICE_C_BARE("level:warn")}, + {DDOG_CHARSLICE_C_BARE("error"), DDOG_CHARSLICE_C_BARE("level:error")}, + }; + uint32_t count; + for (size_t i = 0; i < sizeof(log_levels) / sizeof(log_levels[0]); ++i) { + if ((count = ddog_get_logs_count(log_levels[i].level)) > 0) { + ddog_sidecar_telemetry_add_span_metric_point_buffer(buffer, metric_name, (double)count, log_levels[i].tags); + } + } + ddog_sidecar_telemetry_buffer_flush(&ddtrace_sidecar, ddtrace_sidecar_instance_id, &DDTRACE_G(telemetry_queue_id), buffer); ddog_CharSlice service_name = DDOG_CHARSLICE_C_BARE("unnamed-php-service"); diff --git a/tests/Integrations/Custom/Autoloaded/InstrumentationTest.php b/tests/Integrations/Custom/Autoloaded/InstrumentationTest.php index d803e1d97a..02ab1cca6d 100644 --- a/tests/Integrations/Custom/Autoloaded/InstrumentationTest.php +++ b/tests/Integrations/Custom/Autoloaded/InstrumentationTest.php @@ -48,12 +48,13 @@ public function testInstrumentation() $this->resetRequestDumper(); $this->call(GetSpec::create("autoloaded", "/simple")); - $response = $this->retrieveDumpedData(); - if (!$response) { - $this->fail("Go no response from request-dumper"); - } + $response = $this->retrieveDumpedData(function ($request) { + return (strpos($request["uri"] ?? "", "/telemetry/") === 0) + && (strpos($request["body"] ?? "", "generate-metrics") !== false) + ; + }, true); - $this->assertCount(4, $response); + $this->assertGreaterThanOrEqual(3, $response); $payloads = $this->readTelemetryPayloads($response); $isMetric = function (array $payload) { @@ -78,19 +79,20 @@ public function testInstrumentation() // Not asserting app-closing, this is not expected to happen until shutdown $this->assertCount(1, $metrics); - $this->assertEquals("generate-metrics", $metrics[0]["request_type"]); - $this->assertEquals("tracers", $metrics[0]["payload"]["series"][0]["namespace"]); - $this->assertEquals("spans_created", $metrics[0]["payload"]["series"][0]["metric"]); - $this->assertEquals(["integration_name:datadog"], $metrics[0]["payload"]["series"][0]["tags"]); + $series = array_values(array_filter($metrics[0]["payload"]["series"], function ($p) { return $p['metric'] === 'spans_created'; })); + $this->assertEquals("tracers", $series[0]["namespace"]); + $this->assertEquals("spans_created", $series[0]["metric"]); + $this->assertEquals(["integration_name:datadog"], $series[0]["tags"]); $this->call(GetSpec::create("autoloaded", "/pdo")); - $response = $this->retrieveDumpedData(); - if (!$response) { - $this->fail("Go no response from request-dumper"); - } + $response = $this->retrieveDumpedData(function ($request) { + return (strpos($request["uri"] ?? "", "/telemetry/") === 0) + && (strpos($request["body"] ?? "", "generate-metrics") !== false) + ; + }, true); - $this->assertCount(4, $response); + $this->assertGreaterThanOrEqual(3, $response); $payloads = $this->readTelemetryPayloads($response); $metrics = array_values(array_filter($payloads, $isMetric)); @@ -124,9 +126,9 @@ public function testInstrumentation() ], $payloads[2]["payload"]["integrations"]); $this->assertCount(1, $metrics); - $this->assertEquals("generate-metrics", $metrics[0]["request_type"]); - $this->assertEquals("tracers", $metrics[0]["payload"]["series"][0]["namespace"]); - $this->assertEquals("spans_created", $metrics[0]["payload"]["series"][0]["metric"]); - $this->assertEquals(["integration_name:pdo"], $metrics[0]["payload"]["series"][0]["tags"]); + $series = array_values(array_filter($metrics[0]["payload"]["series"], function ($p) { return $p['metric'] === 'spans_created'; })); + $this->assertEquals("tracers", $series[0]["namespace"]); + $this->assertEquals("spans_created", $series[0]["metric"]); + $this->assertEquals(["integration_name:pdo"], $series[0]["tags"]); } } diff --git a/tests/ext/telemetry/metrics_logs_created.phpt b/tests/ext/telemetry/metrics_logs_created.phpt new file mode 100644 index 0000000000..042a4df218 --- /dev/null +++ b/tests/ext/telemetry/metrics_logs_created.phpt @@ -0,0 +1,115 @@ +--TEST-- +'logs_created' internal metric +--SKIPIF-- + +--ENV-- +DD_TRACE_GENERATE_ROOT_SPAN=0 +DD_INSTRUMENTATION_TELEMETRY_ENABLED=1 +DD_TRACE_LOG_LEVEL=warn +--INI-- +datadog.trace.agent_url="file://{PWD}/metrics-logs-created-telemetry.out" +--FILE-- + +--EXPECTF-- +[ddtrace] [warning] foo +[ddtrace] [warning] bar +[ddtrace] [error] Boum +array(2) { + [0]=> + array(7) { + ["namespace"]=> + string(7) "general" + ["metric"]=> + string(12) "logs_created" + ["points"]=> + array(1) { + [0]=> + array(2) { + [0]=> + int(%d) + [1]=> + float(1) + } + } + ["tags"]=> + array(1) { + [0]=> + string(11) "level:error" + } + ["common"]=> + bool(true) + ["type"]=> + string(5) "count" + ["interval"]=> + int(10) + } + [1]=> + array(7) { + ["namespace"]=> + string(7) "general" + ["metric"]=> + string(12) "logs_created" + ["points"]=> + array(1) { + [0]=> + array(2) { + [0]=> + int(%d) + [1]=> + float(2) + } + } + ["tags"]=> + array(1) { + [0]=> + string(10) "level:warn" + } + ["common"]=> + bool(true) + ["type"]=> + string(5) "count" + ["interval"]=> + int(10) + } +} +--CLEAN-- + - bool(false) + bool(true) ["type"]=> string(5) "count" ["interval"]=> @@ -165,7 +168,7 @@ array(4) { string(20) "integration_name:foo" } ["common"]=> - bool(false) + bool(true) ["type"]=> string(5) "count" ["interval"]=> @@ -193,7 +196,7 @@ array(4) { string(21) "integration_name:otel" } ["common"]=> - bool(false) + bool(true) ["type"]=> string(5) "count" ["interval"]=> @@ -221,7 +224,7 @@ array(4) { string(32) "integration_name:testintegration" } ["common"]=> - bool(false) + bool(true) ["type"]=> string(5) "count" ["interval"]=> @@ -231,4 +234,4 @@ array(4) { --CLEAN--