Enhance logging

components-rs/Cargo.toml

@@ -18,10 +18,18 @@ spawn_worker = { path = "../libdatadog/spawn_worker" }
 bitflags = "2.3.3"
 json = "0.12.4"
 lazy_static = "1.4"
+log = "0.4.20"
+env_logger = "0.10.1"
 uuid = { version = "1.0", features = ["v4"] }
 paste = "1"
 tempfile = {version = "3.3"}
-
+tracing = { version = "0.1", default-features = false, features = ["std"] }
+tracing-core = "0.1.32"
+tracing-subscriber = { version = "0.3", default-features = false, features = [
+    "std",
+    "fmt",
+    "env-filter",
+] }
 
 [build-dependencies]
 cbindgen = "0.24"

components-rs/ddtrace.h

@@ -8,13 +8,19 @@
 #include "telemetry.h"
 #include "sidecar.h"
 
-#define ddog_Log_None (ddog_Log){ .bits = (uint32_t)0 }
-#define ddog_Log_Once (ddog_Log){ .bits = (uint32_t)(1 << 0) }
-#define ddog_Log_Error (ddog_Log){ .bits = (uint32_t)(1 << 1) }
-#define ddog_Log_Warn (ddog_Log){ .bits = (uint32_t)(1 << 2) }
-#define ddog_Log_Info (ddog_Log){ .bits = (uint32_t)(1 << 3) }
-#define ddog_Log_Deprecated (ddog_Log){ .bits = (uint32_t)((1 << 4) | 1) }
-#define ddog_Log_Startup (ddog_Log){ .bits = (uint32_t)(1 << 5) }
+#define ddog_Log_Error (ddog_Log){ .bits = (uint32_t)1 }
+#define ddog_Log_Warn (ddog_Log){ .bits = (uint32_t)2 }
+#define ddog_Log_Info (ddog_Log){ .bits = (uint32_t)3 }
+#define ddog_Log_Debug (ddog_Log){ .bits = (uint32_t)4 }
+#define ddog_Log_Trace (ddog_Log){ .bits = (uint32_t)5 }
+#define ddog_Log_Once (ddog_Log){ .bits = (uint32_t)(1 << 3) }
+#define ddog_Log__Deprecated (ddog_Log){ .bits = (uint32_t)(3 | (1 << 4)) }
+#define ddog_Log_Deprecated (ddog_Log){ .bits = (uint32_t)((3 | (1 << 4)) | (1 << 3)) }
+#define ddog_Log_Startup (ddog_Log){ .bits = (uint32_t)(3 | (2 << 4)) }
+#define ddog_Log_Startup_Warn (ddog_Log){ .bits = (uint32_t)(1 | (2 << 4)) }
+#define ddog_Log_Span (ddog_Log){ .bits = (uint32_t)(4 | (3 << 4)) }
+#define ddog_Log_Span_Trace (ddog_Log){ .bits = (uint32_t)(5 | (3 << 4)) }
+#define ddog_Log_Hook_Trace (ddog_Log){ .bits = (uint32_t)(5 | (4 << 4)) }
 
 typedef uint64_t ddog_QueueId;
 
@@ -127,7 +133,7 @@ typedef ddog_Bytes ddog_Uuid;
 
 extern ddog_Uuid ddtrace_runtime_id;
 
-extern void (*ddog_log_callback)(struct ddog_Log, ddog_CharSlice);
+extern void (*ddog_log_callback)(ddog_CharSlice);
 
 /**
  * # Safety
@@ -141,13 +147,9 @@ ddog_CharSlice ddtrace_get_container_id(void);
 
 void ddtrace_set_container_cgroup_path(ddog_CharSlice path);
 
-bool ddog_shall_log(struct ddog_Log level);
+bool ddog_shall_log(struct ddog_Log category);
 
-void ddog_set_log_category(struct ddog_Log level);
-
-void ddog_parse_log_category(const ddog_CharSlice *category_names,
-                             uintptr_t num,
-                             bool startup_logs_by_default);
+void ddog_set_log_level(ddog_CharSlice level, bool once);
 
 void ddog_log(struct ddog_Log category, ddog_CharSlice msg);
 
@@ -158,7 +160,10 @@ bool ddtrace_detect_composer_installed_json(ddog_SidecarTransport **transport,
                                             const ddog_QueueId *queue_id,
                                             ddog_CharSlice path);
 
-ddog_MaybeError ddog_sidecar_connect_php(ddog_SidecarTransport **connection, bool enable_telemetry);
+ddog_MaybeError ddog_sidecar_connect_php(ddog_SidecarTransport **connection,
+                                         const char *error_path,
+                                         ddog_CharSlice log_level,
+                                         bool enable_telemetry);
 
 struct ddog_TelemetryActionsBuffer *ddog_sidecar_telemetry_buffer_alloc(void);
 

components-rs/lib.rs

@@ -1,4 +1,5 @@
 #![feature(allow_internal_unstable)]
+#![feature(local_key_cell_methods)]
 
 pub mod log;
 pub mod telemetry;

components-rs/log.rs

@@ -1,114 +1,176 @@
 use std::cell::RefCell;
 use std::collections::BTreeSet;
 use std::ffi::c_char;
-use std::slice;
+use std::fmt::Debug;
 use bitflags::bitflags;
+use tracing::Level;
+use tracing_core::{Event, Field, Subscriber};
+use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields};
+use tracing_subscriber::fmt::format::Writer;
+use tracing_subscriber::registry::LookupSpan;
+use tracing_subscriber::util::SubscriberInitExt;
 use ddcommon_ffi::CharSlice;
 use ddcommon_ffi::slice::AsBytes;
 
 bitflags! {
     #[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)]
     #[repr(C)]
     pub struct Log: u32 {
-        const None = 0;
-        const Once = 1 << 0; // I.e. once per request
-        const Error = 1 << 1;
-        const Warn = 1 << 2;
-        const Info = 1 << 3;
-        const Deprecated = (1 << 4) | 1 /* Once */;
-        const Startup = 1 << 5;
-    }
-}
-
-#[macro_export]
-macro_rules! log {
-    ($source:ident, $msg:expr) => { if ($crate::ddog_shall_log($crate::Log::$source)) { $crate::log($crate::Log::$source, $msg) } }
-}
-
-#[allow_internal_unstable(thread_local)]
-macro_rules! thread_local {
-    ($($tokens:tt)*) => {
-        #[thread_local]
-        $($tokens)*
+        const Error = 1;
+        const Warn = 2;
+        const Info = 3;
+        const Debug = 4;
+        const Trace = 5;
+        const Once = 1 << 3; // I.e. once per request
+        const _Deprecated = 3 | (1 << 4);
+        const Deprecated = 3 | (1 << 4) | (1 << 3) /* Once */;
+        const Startup = 3 | (2 << 4);
+        const Startup_Warn = 1 | (2 << 4);
+        const Span = 4 | (3 << 4);
+        const Span_Trace = 5 | (3 << 4);
+        const Hook_Trace = 5 | (4 << 4);
     }
 }
 
 #[no_mangle]
 #[allow(non_upper_case_globals)]
-pub static mut ddog_log_callback: Option<extern "C" fn(Log, CharSlice)> = None;
+pub static mut ddog_log_callback: Option<extern "C" fn(CharSlice)> = None;
 
 // Avoid RefCell for performance
-thread_local! { static mut LOG_CATEGORY: Log = Log::Once.union(Log::Error); }
 std::thread_local! {
     static LOGGED_MSGS: RefCell<BTreeSet<String>> = RefCell::default();
+    static TRACING_GUARDS: RefCell<Option<tracing_core::dispatcher::DefaultGuard>> = RefCell::default();
+}
+
+macro_rules! with_target {
+    ($cat:ident, tracing::$p:ident!($($t:tt)*)) => {
+        match $cat {
+            Log::Error => tracing::$p!(target: "ddtrace", Level::ERROR, $($t)*),
+            Log::Warn => tracing::$p!(target: "ddtrace", Level::WARN, $($t)*),
+            Log::Info => tracing::$p!(target: "ddtrace", Level::INFO, $($t)*),
+            Log::Debug => tracing::$p!(target: "ddtrace", Level::DEBUG, $($t)*),
+            Log::Trace => tracing::$p!(target: "ddtrace", Level::TRACE, $($t)*),
+            Log::_Deprecated => tracing::$p!(target: "deprecated", Level::INFO, $($t)*),
+            Log::Startup => tracing::$p!(target: "startup", Level::INFO, $($t)*),
+            Log::Span => tracing::$p!(target: "span", Level::DEBUG, $($t)*),
+            Log::Span_Trace => tracing::$p!(target: "span", Level::TRACE, $($t)*),
+            Log::Hook_Trace => tracing::$p!(target: "hook", Level::TRACE, $($t)*),
+            _ => unreachable!()
+        }
+    }
 }
 
 #[no_mangle]
-pub extern "C" fn ddog_shall_log(level: Log) -> bool {
-    unsafe { LOG_CATEGORY }.contains(level & !Log::Once)
+pub extern "C" fn ddog_shall_log(category: Log) -> bool {
+    let category = category & !Log::Once;
+    with_target!(category, tracing::event_enabled!())
 }
 
-pub fn log<S>(level: Log, msg: S) where S: AsRef<str> {
-    ddog_log(level, CharSlice::from(msg.as_ref()))
+pub fn log<S>(category: Log, msg: S) where S: AsRef<str> + tracing::Value {
+    let once = !(category & Log::Once).is_empty();
+    let category = category & !Log::Once;
+    if once {
+        with_target!(category, tracing::event!(once = true, msg));
+    } else {
+        with_target!(category, tracing::event!(msg));
+    }
 }
 
-#[no_mangle]
-pub extern "C" fn ddog_set_log_category(level: Log) {
-    unsafe { LOG_CATEGORY = level; }
+struct LogFormatter {
+    pub once: bool,
 }
 
-#[no_mangle]
-pub unsafe extern "C" fn ddog_parse_log_category(category_names: *const CharSlice, num: usize, startup_logs_by_default: bool) {
-    let mut categories = Log::None;
-    let category_names = slice::from_raw_parts(category_names, num);
-
-    if category_names.len() == 1 {
-        let first_level = category_names[0].to_utf8_lossy();
-        if first_level == "1" || first_level == "true" || first_level == "On" {
-            categories = Log::Error | Log::Warn | Log::Info | Log::Deprecated;
-            if startup_logs_by_default {
-                categories |= Log::Startup;
-            }
-        }
+struct LogVisitor {
+    pub msg: Option<String>,
+    pub once: bool,
+}
+
+impl tracing_core::field::Visit for LogVisitor {
+    fn record_bool(&mut self, _field: &Field, value: bool) {
+        self.once = value;
     }
 
-    for category_name in category_names {
-        for (name, category) in Log::all().iter_names() {
-            if name.eq_ignore_ascii_case(&category_name.to_utf8_lossy()) {
-                categories |= category;
-            }
-        }
+    fn record_str(&mut self, _field: &Field, msg: &str) {
+        self.msg = Some(msg.to_string());
     }
 
-    // Info always implies warn
-    if categories.contains(Log::Info) {
-        categories |= Log::Warn;
+    fn record_debug(&mut self, _field: &Field, value: &dyn Debug) {
+        self.msg = Some(format!("{value:?}"));
     }
-    // Warn always implies error
-    if categories.contains(Log::Warn) {
-        categories |= Log::Error;
+}
+
+impl<S, N> FormatEvent<S, N> for LogFormatter
+    where
+        S: Subscriber + for<'a> LookupSpan<'a>,
+        N: for<'a> FormatFields<'a> + 'static {
+    fn format_event(
+        &self,
+        _ctx: &FmtContext<'_, S, N>,
+        _writer: Writer<'_>,
+        event: &Event<'_>
+    ) -> core::fmt::Result {
+        let mut visitor = LogVisitor { msg: None, once: false };
+        event.record(&mut visitor);
+
+        fn fmt_msg(event: &Event<'_>, msg: &str, suffix: &str) -> String {
+            let data = event.metadata();
+            let target = if data.target() == "ddtrace" {
+                match *data.level() {
+                    Level::ERROR => "error",
+                    Level::WARN => "warning",
+                    Level::INFO => "info",
+                    Level::DEBUG => "debug",
+                    Level::TRACE => "trace",
+                }
+            } else {
+                data.target()
+            };
+            format!("[ddtrace] [{}] {}{}\0", target, msg, suffix)
+        }
+
+        if let Some(msg) = visitor.msg {
+            if let Some(cb) = unsafe { ddog_log_callback } {
+                let msg = if self.once && visitor.once {
+                    if let Some(formatted) = LOGGED_MSGS.with(|logged| {
+                        let mut logged = logged.borrow_mut();
+                        if logged.contains(msg.as_str()) {
+                            return None;
+                        }
+                        let formatted = Some(fmt_msg(event, &msg, "; This message is only displayed once. Specify DD_TRACE_ONCE_LOGS=0 to show all messages."));
+                        logged.insert(msg);
+                        formatted
+                    }) {
+                        formatted
+                    } else {
+                        return Ok(());
+                    }
+                } else {
+                    fmt_msg(event, &msg, "")
+                };
+                cb(unsafe { CharSlice::new(msg.as_ptr() as *const c_char, msg.len() - 1) });
+            }
+        }
+        Ok(())
     }
+}
 
-    ddog_set_log_category(categories);
+#[no_mangle]
+pub unsafe extern "C" fn ddog_set_log_level(level: CharSlice, once: bool) {
+    let subscriber = tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::filter::EnvFilter::builder().parse_lossy(level.to_utf8_lossy()))
+        .event_format(LogFormatter { once });
+    TRACING_GUARDS.replace(None); // drop first to avoid a prior guard to reset the thread local subscriber it upon replace()
+    TRACING_GUARDS.replace(Some(subscriber.set_default()));
 }
 
 #[no_mangle]
-pub extern "C" fn ddog_log(category: Log, msg: CharSlice) {
-    if let Some(cb) = unsafe { ddog_log_callback } {
-        if category.contains(Log::Once) && !unsafe { LOG_CATEGORY }.contains(Log::Once) {
-            LOGGED_MSGS.with(|logged| {
-                let mut logged = logged.borrow_mut();
-                let msgstr = unsafe { msg.to_utf8_lossy() };
-                if !logged.contains(msgstr.as_ref()) {
-                    let msg = msgstr.to_string();
-                    let once_msg = format!("{}; This message is only displayed once. Specify DD_TRACE_ONCE_LOGS=0 to show all messages.\0", msg);
-                    cb(category, unsafe { CharSlice::new(once_msg.as_ptr() as *const c_char, once_msg.len() - 1) });
-                    logged.insert(msg);
-                }
-            });
-        } else {
-            cb(category, msg);
-        }
+pub unsafe extern "C" fn ddog_log(category: Log, msg: CharSlice) {
+    let once = !(category & Log::Once).is_empty();
+    let category = category & !Log::Once;
+    if once {
+        with_target!(category, tracing::event!(once = true, "{}", msg.to_utf8_lossy()));
+    } else {
+        with_target!(category, tracing::event!("{}", msg.to_utf8_lossy()));
     }
 }
 

components-rs/sidecar.h

@@ -119,7 +119,9 @@ ddog_MaybeError ddog_sidecar_session_set_config(ddog_SidecarTransport **transpor
                                                 const struct ddog_Endpoint *endpoint,
                                                 uint64_t flush_interval_milliseconds,
                                                 uintptr_t force_flush_size,
-                                                uintptr_t force_drop_size);
+                                                uintptr_t force_drop_size,
+                                                ddog_CharSlice log_level,
+                                                ddog_CharSlice log_path);
 
 ddog_MaybeError ddog_sidecar_send_trace_v04_shm(ddog_SidecarTransport **transport,
                                                 const struct ddog_InstanceId *instance_id,
@@ -131,4 +133,6 @@ ddog_MaybeError ddog_sidecar_send_trace_v04_bytes(ddog_SidecarTransport **transp
                                                   ddog_CharSlice data,
                                                   const struct ddog_TracerHeaderTags *tracer_header_tags);
 
+ddog_CharSlice ddog_sidecar_dump(ddog_SidecarTransport **transport);
+
 #endif /* DDOG_SIDECAR_H */

components-rs/telemetry.rs

@@ -12,6 +12,9 @@ use spawn_worker::LibDependency;
 use std::error::Error;
 use std::path::Path;
 use std::{fs, io};
+use std::ffi::{c_char, CStr, OsStr};
+use std::os::unix::ffi::OsStrExt;
+use datadog_sidecar::config::LogMethod;
 
 #[must_use]
 #[no_mangle]
@@ -76,10 +79,18 @@ fn run_sidecar(cfg: config::Config) -> io::Result<SidecarTransport> {
 #[no_mangle]
 pub extern "C" fn ddog_sidecar_connect_php(
     connection: &mut *mut SidecarTransport,
+    error_path: *const c_char,
+    log_level: CharSlice,
     enable_telemetry: bool,
 ) -> MaybeError {
     let mut cfg = config::FromEnv::config();
     cfg.self_telemetry = enable_telemetry;
+    unsafe {
+        if *error_path != 0 {
+            cfg.log_method = LogMethod::File(OsStr::from_bytes(CStr::from_ptr(error_path).to_bytes()).into())
+        }
+        cfg.child_env.insert(OsStr::new("DD_TRACE_LOG_LEVEL").into(), OsStr::from_bytes(log_level.as_bytes()).into());
+    }
     let stream = Box::new(try_c!(run_sidecar(cfg)));
     *connection = Box::into_raw(stream);
 

config.m4

@@ -289,7 +289,7 @@ if test "$PHP_DDTRACE" != "no"; then
 
   cat <<EOT >> Makefile.fragments
 \$(builddir)/target/$ddtrace_cargo_profile/libddtrace_php.a: $( (find "$ext_srcdir/components-rs" -name "*.c" -o -name "*.rs" -o -name "Cargo.toml"; find "$ext_srcdir/../../libdatadog" -name "*.rs" -not -path "*/target/*"; find "$ext_srcdir/libdatadog" -name "*.rs" -not -path "*/target/*"; echo "$all_object_files" ) 2>/dev/null | xargs )
-	(cd "$ext_srcdir/components-rs"; $ddtrace_mock_sources CARGO_TARGET_DIR=\$(builddir)/target/ RUSTC_BOOTSTRAP=1 \$(DDTRACE_CARGO) build $(test "$ddtrace_cargo_profile" == debug || echo --profile tracer-release) \$(shell echo "\$(MAKEFLAGS)" | $EGREP -o "[[-]]j[[0-9]]+") && test "$PHP_DDTRACE_RUST_SYMBOLS" == yes || strip -d \$(builddir)/target/$ddtrace_cargo_profile/libddtrace_php.a)
+	(cd "$ext_srcdir/components-rs"; $ddtrace_mock_sources CARGO_TARGET_DIR=\$(builddir)/target/ RUSTFLAGS="${RUSTFLAGS:-} --cfg tokio_unstable --cfg tokio_taskdump" RUSTC_BOOTSTRAP=1 \$(DDTRACE_CARGO) build $(test "$ddtrace_cargo_profile" == debug || echo --profile tracer-release) \$(shell echo "\$(MAKEFLAGS)" | $EGREP -o "[[-]]j[[0-9]]+") && test "$PHP_DDTRACE_RUST_SYMBOLS" == yes || strip -d \$(builddir)/target/$ddtrace_cargo_profile/libddtrace_php.a)
 EOT
 
   if test "$ext_shared" = "shared" || test "$ext_shared" = "yes"; then