From d441c194a297fc1809b1a39cba147c4a009c2e33 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 25 Nov 2024 16:41:41 -0800 Subject: [PATCH 01/26] checkpoint --- ffi/Cargo.toml | 1 + ffi/src/ffi_tracing.rs | 172 +++++++++++++++++++++++++++++++++++++++++ ffi/src/lib.rs | 2 + 3 files changed, 175 insertions(+) create mode 100644 ffi/src/ffi_tracing.rs diff --git a/ffi/Cargo.toml b/ffi/Cargo.toml index 30db5eb9a..f3a00d0f7 100644 --- a/ffi/Cargo.toml +++ b/ffi/Cargo.toml @@ -15,6 +15,7 @@ crate-type = ["lib", "cdylib", "staticlib"] [dependencies] tracing = "0.1" +tracing-subscriber = { version = "0.3", optional = false } # TODO Make optional url = "2" delta_kernel = { path = "../kernel", default-features = false, features = [ "developer-visibility", diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs new file mode 100644 index 000000000..9510b09ae --- /dev/null +++ b/ffi/src/ffi_tracing.rs @@ -0,0 +1,172 @@ +//! FFI functions to allow engines to receive log and tracing events from kernel + +use core::fmt; + +use delta_kernel::{DeltaResult, Error}; +use tracing::{field::{Field as TracingField, Visit}, Event as TracingEvent, Subscriber}; +use tracing_subscriber::{filter::LevelFilter, layer::Context, registry::LookupSpan, Layer}; + +use crate::{kernel_string_slice, KernelStringSlice}; + +#[repr(C)] +pub enum Level { + ERROR, + WARN, + INFO, + DEBUG, + TRACE, +} + +impl From<&tracing::Level> for Level { + fn from(value: &tracing::Level) -> Self { + match *value { + tracing::Level::TRACE => Level::TRACE, + tracing::Level::DEBUG => Level::DEBUG, + tracing::Level::INFO => Level::INFO, + tracing::Level::WARN => Level::WARN, + tracing::Level::ERROR => Level::ERROR, + } + } +} + +impl From for LevelFilter { + fn from(value: Level) -> Self { + match value { + Level::TRACE => LevelFilter::TRACE, + Level::DEBUG => LevelFilter::DEBUG, + Level::INFO => LevelFilter::INFO, + Level::WARN => LevelFilter::WARN, + Level::ERROR => LevelFilter::ERROR, + } + } +} + +/// An `Event` can generally be thought of a "log message". It contains all the relevant bits such +/// that an engine can generate a log message in its format +#[repr(C)] +pub struct Event { + message: KernelStringSlice, + level: Level, +} + +impl TryFrom<&TracingEvent<'_>> for Event { + type Error = Error; + + fn try_from(event: &TracingEvent<'_>) -> DeltaResult { + let metadata = event.metadata(); + let level = metadata.level().into(); + let mut message_visitor = MessageFieldVisitor { message: None }; + event.record(&mut message_visitor); + let msg = message_visitor.message.ok_or_else(|| + Error::missing_data("message field") + )?; + let msg = kernel_string_slice!(msg); + Ok(Self { + message: msg, + level, + }) + } +} + +pub type TracingEventFn = extern "C" fn(event: Event); + +/// Enable getting called back for tracing (logging) events in the kernel. `max_level` specifies +/// that only events `<=` to the specified level should be reported. More verbose Levels are "greater +/// than" less verbose ones. So Level::ERROR is the lowest, and Level::TRACE the highest. +#[no_mangle] +pub unsafe extern "C" fn enable_event_tracing(callback: TracingEventFn, max_level: Level) { + setup_event_subscriber(callback, max_level); +} + + +// utility code below for setting up the tracing subscriber stuff + + +struct MessageFieldVisitor { + message: Option, +} + +impl Visit for MessageFieldVisitor { + fn record_debug(&mut self, field: &TracingField, value: &dyn fmt::Debug) { + if field.name() == "message" { + self.message = Some(format!("{:?}", value)); + } + } + + fn record_str(&mut self, field: &TracingField, value: &str) { + if field.name() == "message" { + self.message = Some(value.to_string()); + } + } +} + +struct EventLayer { + callback: TracingEventFn, +} + +impl Layer for EventLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_event(&self, event: &TracingEvent<'_>, _context: Context<'_, S>) { + if let Ok(event) = event.try_into() { + // ignore if event doesn't have a "message" field + (self.callback)(event); + } + } +} + +fn setup_event_subscriber(callback: TracingEventFn, max_level: Level) { + use tracing_subscriber::{registry::Registry, layer::SubscriberExt}; + let filter: LevelFilter = max_level.into(); + let event_layer = EventLayer { callback }.with_filter(filter); + let subscriber = Registry::default().with(event_layer); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to set global subscriber"); +} + + +// type SharedBuffer = Arc>>; + +// struct TriggerLayer { +// buf: SharedBuffer, +// } + +// impl Layer for TriggerLayer +// where +// S: Subscriber + for<'a> LookupSpan<'a>, +// { +// fn on_event(&self, event: &TracingEvent<'_>, _context: Context<'_, S>) { +// println!("EVENT"); +// let mut buf = self.buf.lock().unwrap(); +// let output = String::from_utf8_lossy(&buf); +// println!("Buf is:\n{output}"); +// buf.clear(); +// } +// } + +// #[derive(Default)] +// struct BufferedMessageWriter { +// current_buffer: SharedBuffer, +// } + +// impl io::Write for BufferedMessageWriter { +// fn write(&mut self, buf: &[u8]) -> io::Result { +// self.current_buffer.lock().unwrap().extend_from_slice(buf); +// Ok(buf.len()) +// } + +// fn flush(&mut self) -> io::Result<()> { +// Ok(()) +// } +// } + +// impl<'a> MakeWriter<'a> for BufferedMessageWriter { +// type Writer = Self; + +// fn make_writer(&'a self) -> Self::Writer { +// BufferedMessageWriter { +// current_buffer: self.current_buffer.clone() +// } +// } +// } diff --git a/ffi/src/lib.rs b/ffi/src/lib.rs index c3f0df935..1554a6050 100644 --- a/ffi/src/lib.rs +++ b/ffi/src/lib.rs @@ -39,6 +39,8 @@ pub mod scan; pub mod schema; #[cfg(feature = "test-ffi")] pub mod test_ffi; +// todo: feature flag +pub mod ffi_tracing; pub(crate) type NullableCvoid = Option>; From e66118c8306f39ed07677989cddf53c4192afa88 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 25 Nov 2024 17:11:09 -0800 Subject: [PATCH 02/26] works :) --- ffi/examples/read-table/read_table.c | 22 +++++++++++++++++ ffi/src/ffi_tracing.rs | 37 ++++++++++++---------------- 2 files changed, 38 insertions(+), 21 deletions(-) diff --git a/ffi/examples/read-table/read_table.c b/ffi/examples/read-table/read_table.c index 2c8738cd1..9fda74f54 100644 --- a/ffi/examples/read-table/read_table.c +++ b/ffi/examples/read-table/read_table.c @@ -1,6 +1,7 @@ #include #include #include +#include #include "arrow.h" #include "read_table.h" @@ -150,6 +151,21 @@ void free_partition_list(PartitionList* list) { free(list); } +static const char *LEVEL_STRING[] = { + "ERROR", "WARN", "INFO", "DEBUG", "TRACE" +}; + +void tracing_callback(struct Event event) { + struct timeval tv; + char buffer[32]; + gettimeofday(&tv, NULL); + struct tm *tm_info = gmtime(&tv.tv_sec); + strftime(buffer, 26, "%Y-%m-%dT%H:%M:%S", tm_info); + char* message = allocate_string(event.message); + printf("%s.%06ldZ [Kernel %s]: %s\n", buffer, tv.tv_usec, LEVEL_STRING[event.level], message); + free(message); +} + int main(int argc, char* argv[]) { if (argc < 2) { @@ -157,6 +173,12 @@ int main(int argc, char* argv[]) return -1; } +#ifdef VERBOSE + enable_event_tracing(tracing_callback, TRACE); +#else + enable_event_tracing(tracing_callback, INFO); +#endif + char* table_path = argv[1]; printf("Reading table at %s\n", table_path); diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 9510b09ae..7d0f7bfd8 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -41,6 +41,7 @@ impl From for LevelFilter { } } + /// An `Event` can generally be thought of a "log message". It contains all the relevant bits such /// that an engine can generate a log message in its format #[repr(C)] @@ -49,25 +50,6 @@ pub struct Event { level: Level, } -impl TryFrom<&TracingEvent<'_>> for Event { - type Error = Error; - - fn try_from(event: &TracingEvent<'_>) -> DeltaResult { - let metadata = event.metadata(); - let level = metadata.level().into(); - let mut message_visitor = MessageFieldVisitor { message: None }; - event.record(&mut message_visitor); - let msg = message_visitor.message.ok_or_else(|| - Error::missing_data("message field") - )?; - let msg = kernel_string_slice!(msg); - Ok(Self { - message: msg, - level, - }) - } -} - pub type TracingEventFn = extern "C" fn(event: Event); /// Enable getting called back for tracing (logging) events in the kernel. `max_level` specifies @@ -109,8 +91,21 @@ where S: Subscriber + for<'a> LookupSpan<'a>, { fn on_event(&self, event: &TracingEvent<'_>, _context: Context<'_, S>) { - if let Ok(event) = event.try_into() { - // ignore if event doesn't have a "message" field + // it would be tempting to `impl TryFrom` to convert the `TracingEvent` into an `Event`, but + // we want to use a KernelStringSlice, so we need the extracted string to live long enough + // for the callback which won't happen if we convert inside a `try_from` call + let metadata = event.metadata(); + let level = metadata.level().into(); + let mut message_visitor = MessageFieldVisitor { message: None }; + event.record(&mut message_visitor); + if let Some(message) = message_visitor.message { + // we ignore events without a message + //println!("Message here {msg}"); + let msg = kernel_string_slice!(message); + let event = Event { + message: msg, + level, + }; (self.callback)(event); } } From 9150a0dcb14078d0cae26404f3cbb054315067b9 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 26 Nov 2024 10:09:22 -0800 Subject: [PATCH 03/26] add file/line and COLORS --- ffi/examples/read-table/read_table.c | 27 ++++++++++++++++++++++++++- ffi/src/ffi_tracing.rs | 24 ++++++++++++++++++++++-- 2 files changed, 48 insertions(+), 3 deletions(-) diff --git a/ffi/examples/read-table/read_table.c b/ffi/examples/read-table/read_table.c index 9fda74f54..8f94f6c08 100644 --- a/ffi/examples/read-table/read_table.c +++ b/ffi/examples/read-table/read_table.c @@ -155,6 +155,11 @@ static const char *LEVEL_STRING[] = { "ERROR", "WARN", "INFO", "DEBUG", "TRACE" }; +#define RED "\x1b[31m" +#define BLUE "\x1b[34m" +#define DIM "\x1b[2m" +#define RESET "\x1b[0m" + void tracing_callback(struct Event event) { struct timeval tv; char buffer[32]; @@ -162,7 +167,27 @@ void tracing_callback(struct Event event) { struct tm *tm_info = gmtime(&tv.tv_sec); strftime(buffer, 26, "%Y-%m-%dT%H:%M:%S", tm_info); char* message = allocate_string(event.message); - printf("%s.%06ldZ [Kernel %s]: %s\n", buffer, tv.tv_usec, LEVEL_STRING[event.level], message); + char* level_color = event.level < 3 ? RED : BLUE; + printf( + "%s%s.%06ldZ%s [%sKernel %s%s]: %s\n", + DIM, + buffer, + tv.tv_usec, + RESET, + level_color, + LEVEL_STRING[event.level], + RESET, + message); + if (event.file.ptr) { + char* file = allocate_string(event.file); + printf( + " %sat%s %s:%i\n", + DIM, + RESET, + file, + event.line); + free(file); + } free(message); } diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 7d0f7bfd8..dadd98045 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -2,7 +2,6 @@ use core::fmt; -use delta_kernel::{DeltaResult, Error}; use tracing::{field::{Field as TracingField, Visit}, Event as TracingEvent, Subscriber}; use tracing_subscriber::{filter::LevelFilter, layer::Context, registry::LookupSpan, Layer}; @@ -46,8 +45,16 @@ impl From for LevelFilter { /// that an engine can generate a log message in its format #[repr(C)] pub struct Event { + /// The log message associated with the event message: KernelStringSlice, + /// Level that the event was emitted at level: Level, + /// A string that specifies in what part of the system the event occurred + target: KernelStringSlice, + /// source file line number where the event occurred, or 0 (zero) if unknown + line: u32, + /// file where the event occurred. If unknown the slice `ptr` will be null and the len will be 0 + file: KernelStringSlice, } pub type TracingEventFn = extern "C" fn(event: Event); @@ -100,11 +107,24 @@ where event.record(&mut message_visitor); if let Some(message) = message_visitor.message { // we ignore events without a message - //println!("Message here {msg}"); let msg = kernel_string_slice!(message); + let target = metadata.target(); + let target = kernel_string_slice!(target); + let file = match metadata.file() { + Some(file) => kernel_string_slice!(file), + None => { + KernelStringSlice { + ptr: std::ptr::null(), + len: 0, + } + } + }; let event = Event { message: msg, level, + target, + line: metadata.line().unwrap_or(0), + file, }; (self.callback)(event); } From 9107d04632955a3bbc9a38aaf58f3e35d0f1355d Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 26 Nov 2024 12:01:47 -0800 Subject: [PATCH 04/26] proper log line formatting --- ffi/Cargo.toml | 2 +- ffi/examples/read-table/read_table.c | 8 + ffi/src/ffi_tracing.rs | 285 +++++++++++++++++++++------ 3 files changed, 234 insertions(+), 61 deletions(-) diff --git a/ffi/Cargo.toml b/ffi/Cargo.toml index f3a00d0f7..21feec564 100644 --- a/ffi/Cargo.toml +++ b/ffi/Cargo.toml @@ -15,7 +15,7 @@ crate-type = ["lib", "cdylib", "staticlib"] [dependencies] tracing = "0.1" -tracing-subscriber = { version = "0.3", optional = false } # TODO Make optional +tracing-subscriber = { version = "0.3", optional = false, features = [ "json" ] } # TODO Make optional url = "2" delta_kernel = { path = "../kernel", default-features = false, features = [ "developer-visibility", diff --git a/ffi/examples/read-table/read_table.c b/ffi/examples/read-table/read_table.c index 8f94f6c08..fbf3b8ba4 100644 --- a/ffi/examples/read-table/read_table.c +++ b/ffi/examples/read-table/read_table.c @@ -191,6 +191,12 @@ void tracing_callback(struct Event event) { free(message); } +void log_line_callback(KernelStringSlice line) { + char* message = allocate_string(line); + printf("%s", message); + free(message); +} + int main(int argc, char* argv[]) { if (argc < 2) { @@ -200,6 +206,8 @@ int main(int argc, char* argv[]) #ifdef VERBOSE enable_event_tracing(tracing_callback, TRACE); + // we could also do something like this if we want less control over formatting + // enable_formatted_log_line_tracing(log_line_callback, TRACE, FULL, true, true, false, false); #else enable_event_tracing(tracing_callback, INFO); #endif diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index dadd98045..eff518923 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -1,8 +1,13 @@ //! FFI functions to allow engines to receive log and tracing events from kernel -use core::fmt; +use std::sync::{Arc, Mutex}; +use std::{fmt, io}; -use tracing::{field::{Field as TracingField, Visit}, Event as TracingEvent, Subscriber}; +use tracing::{ + field::{Field as TracingField, Visit}, + Event as TracingEvent, Subscriber, +}; +use tracing_subscriber::fmt::MakeWriter; use tracing_subscriber::{filter::LevelFilter, layer::Context, registry::LookupSpan, Layer}; use crate::{kernel_string_slice, KernelStringSlice}; @@ -40,7 +45,6 @@ impl From for LevelFilter { } } - /// An `Event` can generally be thought of a "log message". It contains all the relevant bits such /// that an engine can generate a log message in its format #[repr(C)] @@ -62,14 +66,107 @@ pub type TracingEventFn = extern "C" fn(event: Event); /// Enable getting called back for tracing (logging) events in the kernel. `max_level` specifies /// that only events `<=` to the specified level should be reported. More verbose Levels are "greater /// than" less verbose ones. So Level::ERROR is the lowest, and Level::TRACE the highest. +/// +/// [`Event`] based tracing gives an engine maximal flexibility in formatting event log +/// lines. Kernel can also format events for the engine. If this is desired call +/// [`enable_log_line_tracing`] instead of this method. #[no_mangle] pub unsafe extern "C" fn enable_event_tracing(callback: TracingEventFn, max_level: Level) { setup_event_subscriber(callback, max_level); } +pub type TracingLogLineFn = extern "C" fn(line: KernelStringSlice); -// utility code below for setting up the tracing subscriber stuff +/// Format to use for log lines. These correspond to the formats from [`tracing_subscriber` +/// formats](https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/format/index.html). +#[repr(C)] +pub enum LogLineFormat { + /// The default formatter. This emits human-readable, single-line logs for each event that + /// occurs, with the context displayed before the formatted representation of the event. + /// Example: + /// `2022-02-15T18:40:14.289898Z INFO fmt: preparing to shave yaks number_of_yaks=3` + FULL, + /// A variant of the FULL formatter, optimized for short line lengths. Fields from the context + /// are appended to the fields of the formatted event, and targets are not shown; the verbosity + /// level is abbreviated to a single character. + /// Example: + COMPACT, + /// Emits excessively pretty, multi-line logs, optimized for human readability. This is + /// primarily intended to be used in local development and debugging, or for command-line + /// applications, where automated analysis and compact storage of logs is less of a priority + /// than readability and visual appeal. + /// Example: + /// ``` + /// 2022-02-15T18:44:24.535324Z INFO fmt_pretty: preparing to shave yaks, number_of_yaks: 3 + /// at examples/examples/fmt-pretty.rs:16 on main + /// ``` + PRETTY, + /// Outputs newline-delimited JSON logs. This is intended for production use with systems where + /// structured logs are consumed as JSON by analysis and viewing tools. The JSON output is not + /// optimized for human readability. + /// Example: + /// `{"timestamp":"2022-02-15T18:47:10.821315Z","level":"INFO","fields":{"message":"preparing to shave yaks","number_of_yaks":3},"target":"fmt_json"}` + JSON, +} +/// Enable getting called back with log lines in the kernel using default settings: +/// - FULL format +/// - include ansi color +/// - include timestamps +/// - include level +/// - include target +/// `max_level` specifies that only logs `<=` to the specified level should be reported. More +/// verbose Levels are "greater than" less verbose ones. So Level::ERROR is the lowest, and +/// Level::TRACE the highest. +/// +/// Log lines passed to the callback will already have a newline at the end. +/// +/// Log line based tracing is simple for an engine as it can just log the passed string, but does +/// not provide flexibility for an engine to format events. If the engine wants to use a specific +/// format for events it should call [`enable_event_tracing`] instead of this function. +#[no_mangle] +pub unsafe extern "C" fn enable_log_line_tracing(callback: TracingLogLineFn, max_level: Level) { + setup_log_line_subscriber( + callback, + max_level, + LogLineFormat::FULL, + true, + true, + true, + true, + ); +} + +/// Enable getting called back with log lines in the kernel. This variant allows specifying +/// formatting options for the log lines. See [`enable_log_line_tracing`] for general info on +/// getting called back for log lines. Options that can be set here: +/// - `format`: see [`LogLineFormat`] +/// - `ansi`: should the formatter use ansi escapes for color +/// - `with_time`: should the formatter include a timestamp in the log message +/// - `with_level`: should the formatter include the level in the log message +/// - `with_target`: should the formatter include what part of the system the event occurred +#[no_mangle] +pub unsafe extern "C" fn enable_formatted_log_line_tracing( + callback: TracingLogLineFn, + max_level: Level, + format: LogLineFormat, + ansi: bool, + with_time: bool, + with_level: bool, + with_target: bool, +) { + setup_log_line_subscriber( + callback, + max_level, + format, + ansi, + with_time, + with_level, + with_target, + ); +} + +// utility code below for setting up the tracing subscriber for events struct MessageFieldVisitor { message: Option, @@ -112,12 +209,10 @@ where let target = kernel_string_slice!(target); let file = match metadata.file() { Some(file) => kernel_string_slice!(file), - None => { - KernelStringSlice { - ptr: std::ptr::null(), - len: 0, - } - } + None => KernelStringSlice { + ptr: std::ptr::null(), + len: 0, + }, }; let event = Event { message: msg, @@ -132,56 +227,126 @@ where } fn setup_event_subscriber(callback: TracingEventFn, max_level: Level) { - use tracing_subscriber::{registry::Registry, layer::SubscriberExt}; + use tracing_subscriber::{layer::SubscriberExt, registry::Registry}; let filter: LevelFilter = max_level.into(); let event_layer = EventLayer { callback }.with_filter(filter); let subscriber = Registry::default().with(event_layer); - tracing::subscriber::set_global_default(subscriber) - .expect("Failed to set global subscriber"); -} - - -// type SharedBuffer = Arc>>; - -// struct TriggerLayer { -// buf: SharedBuffer, -// } - -// impl Layer for TriggerLayer -// where -// S: Subscriber + for<'a> LookupSpan<'a>, -// { -// fn on_event(&self, event: &TracingEvent<'_>, _context: Context<'_, S>) { -// println!("EVENT"); -// let mut buf = self.buf.lock().unwrap(); -// let output = String::from_utf8_lossy(&buf); -// println!("Buf is:\n{output}"); -// buf.clear(); -// } -// } - -// #[derive(Default)] -// struct BufferedMessageWriter { -// current_buffer: SharedBuffer, -// } - -// impl io::Write for BufferedMessageWriter { -// fn write(&mut self, buf: &[u8]) -> io::Result { -// self.current_buffer.lock().unwrap().extend_from_slice(buf); -// Ok(buf.len()) -// } - -// fn flush(&mut self) -> io::Result<()> { -// Ok(()) -// } -// } - -// impl<'a> MakeWriter<'a> for BufferedMessageWriter { -// type Writer = Self; - -// fn make_writer(&'a self) -> Self::Writer { -// BufferedMessageWriter { -// current_buffer: self.current_buffer.clone() -// } -// } -// } + tracing::subscriber::set_global_default(subscriber).expect("Failed to set global subscriber"); +} + +// utility code below for setting up the tracing subscriber for log lines + +type SharedBuffer = Arc>>; + +struct TriggerLayer { + buf: SharedBuffer, + callback: TracingLogLineFn, +} + +impl Layer for TriggerLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_event(&self, _: &TracingEvent<'_>, _context: Context<'_, S>) { + let mut buf = self.buf.lock().unwrap(); + let output = String::from_utf8_lossy(&buf); + let message = kernel_string_slice!(output); + (self.callback)(message); + buf.clear(); + } +} + +#[derive(Default)] +struct BufferedMessageWriter { + current_buffer: SharedBuffer, +} + +impl io::Write for BufferedMessageWriter { + fn write(&mut self, buf: &[u8]) -> io::Result { + self.current_buffer.lock().unwrap().extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } +} + +impl<'a> MakeWriter<'a> for BufferedMessageWriter { + type Writer = Self; + + fn make_writer(&'a self) -> Self::Writer { + BufferedMessageWriter { + current_buffer: self.current_buffer.clone(), + } + } +} + +fn setup_log_line_subscriber( + callback: TracingLogLineFn, + max_level: Level, + format: LogLineFormat, + ansi: bool, + with_time: bool, + with_level: bool, + with_target: bool, +) { + use tracing_subscriber::{layer::SubscriberExt, registry::Registry}; + let buffer = Arc::new(Mutex::new(vec![])); + let writer = BufferedMessageWriter { + current_buffer: buffer.clone(), + }; + let fmt_layer = tracing_subscriber::fmt::layer() + .with_writer(writer) + .with_ansi(ansi) + .with_level(with_level) + .with_target(with_target); + let filter: LevelFilter = max_level.into(); + let tracking_layer = TriggerLayer { + buf: buffer.clone(), + callback, + }; + + // This repeats some code, but avoids some insane generic wrangling if we try to abstract the + // type of `fmt_layer` over the formatter + macro_rules! setup_subscriber { + ( $format_fn:ident ) => { + if with_time { + let fmt_layer = fmt_layer.$format_fn().with_filter(filter); + let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to set global subscriber"); + } else { + let fmt_layer = fmt_layer.without_time().$format_fn().with_filter(filter); + let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to set global subscriber"); + } + }; + } + match format { + LogLineFormat::FULL => { + // can't use macro as there's no `full()` function, it's just the default + if with_time { + let fmt_layer = fmt_layer.with_filter(filter); + let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to set global subscriber"); + } else { + let fmt_layer = fmt_layer.without_time().with_filter(filter); + let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); + tracing::subscriber::set_global_default(subscriber) + .expect("Failed to set global subscriber"); + } + } + LogLineFormat::COMPACT => { + setup_subscriber!(compact); + } + LogLineFormat::PRETTY => { + setup_subscriber!(pretty); + } + LogLineFormat::JSON => { + setup_subscriber!(json); + } + } +} From 41c08bf438c34eaf2bfeb2b2b323bbb4e937d506 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 26 Nov 2024 12:05:12 -0800 Subject: [PATCH 05/26] feature flag it all --- .github/workflows/build.yml | 2 +- ffi/Cargo.toml | 3 ++- ffi/examples/read-table/README.md | 6 +++--- ffi/src/lib.rs | 2 +- 4 files changed, 7 insertions(+), 6 deletions(-) diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 9bdbe6c0d..343f086ff 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -145,7 +145,7 @@ jobs: cargo build popd pushd ffi - cargo b --features default-engine,sync-engine,test-ffi + cargo b --features default-engine,sync-engine,test-ffi,tracing popd - name: build and run read-table test run: | diff --git a/ffi/Cargo.toml b/ffi/Cargo.toml index 21feec564..4add080f7 100644 --- a/ffi/Cargo.toml +++ b/ffi/Cargo.toml @@ -15,7 +15,7 @@ crate-type = ["lib", "cdylib", "staticlib"] [dependencies] tracing = "0.1" -tracing-subscriber = { version = "0.3", optional = false, features = [ "json" ] } # TODO Make optional +tracing-subscriber = { version = "0.3", optional = true, features = [ "json" ] } # TODO Make optional url = "2" delta_kernel = { path = "../kernel", default-features = false, features = [ "developer-visibility", @@ -47,6 +47,7 @@ default-engine = [ "arrow-data", "arrow-schema", ] +tracing = [ "tracing-subscriber" ] sync-engine = ["delta_kernel/sync-engine"] developer-visibility = [] test-ffi = [] diff --git a/ffi/examples/read-table/README.md b/ffi/examples/read-table/README.md index 11bef7f66..4debb048e 100644 --- a/ffi/examples/read-table/README.md +++ b/ffi/examples/read-table/README.md @@ -10,9 +10,9 @@ This example is built with [cmake]. Instructions below assume you start in the d Note that prior to building these examples you must build `delta_kernel_ffi` (see [the FFI readme] for details). TLDR: ```bash # from repo root -$ cargo build -p delta_kernel_ffi [--release] [--features default-engine] +$ cargo build -p delta_kernel_ffi [--release] [--features default-engine, tracing] # from ffi/ dir -$ cargo build [--release] [--features default-engine] +$ cargo build [--release] [--features default-engine, tracing] ``` There are two configurations that can currently be configured in cmake: @@ -62,4 +62,4 @@ If you don't want to have to install this, you can run `ccmake ..` (`cmake-gui.e from the `build` directory, and turn `OFF`/uncheckmark `PRINT_DATA`. Then "configure" and "generate" and follow the above instructions again. -[cmake]: https://cmake.org/ \ No newline at end of file +[cmake]: https://cmake.org/ diff --git a/ffi/src/lib.rs b/ffi/src/lib.rs index 1554a6050..c369ae109 100644 --- a/ffi/src/lib.rs +++ b/ffi/src/lib.rs @@ -39,7 +39,7 @@ pub mod scan; pub mod schema; #[cfg(feature = "test-ffi")] pub mod test_ffi; -// todo: feature flag +#[cfg(feature = "tracing")] pub mod ffi_tracing; pub(crate) type NullableCvoid = Option>; From 1ee3092d5c68c34a4e515acad39f1ea5274bad8a Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 26 Nov 2024 12:08:03 -0800 Subject: [PATCH 06/26] remove comment --- ffi/Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ffi/Cargo.toml b/ffi/Cargo.toml index 4add080f7..9c6b68da0 100644 --- a/ffi/Cargo.toml +++ b/ffi/Cargo.toml @@ -15,7 +15,7 @@ crate-type = ["lib", "cdylib", "staticlib"] [dependencies] tracing = "0.1" -tracing-subscriber = { version = "0.3", optional = true, features = [ "json" ] } # TODO Make optional +tracing-subscriber = { version = "0.3", optional = true, features = [ "json" ] } url = "2" delta_kernel = { path = "../kernel", default-features = false, features = [ "developer-visibility", From c84e02d8f3f5b51954efc054f449975a8dc0524d Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 26 Nov 2024 12:21:00 -0800 Subject: [PATCH 07/26] update docs a bit --- ffi/src/ffi_tracing.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index eff518923..517f9d4a8 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -12,6 +12,8 @@ use tracing_subscriber::{filter::LevelFilter, layer::Context, registry::LookupSp use crate::{kernel_string_slice, KernelStringSlice}; +/// Definitions of level verbosity. Verbose Levels are "greater than" less verbose ones. So +/// Level::ERROR is the lowest, and Level::TRACE the highest. #[repr(C)] pub enum Level { ERROR, @@ -87,9 +89,9 @@ pub enum LogLineFormat { /// `2022-02-15T18:40:14.289898Z INFO fmt: preparing to shave yaks number_of_yaks=3` FULL, /// A variant of the FULL formatter, optimized for short line lengths. Fields from the context - /// are appended to the fields of the formatted event, and targets are not shown; the verbosity - /// level is abbreviated to a single character. + /// are appended to the fields of the formatted event, and targets are not shown. /// Example: + /// `2022-02-17T19:51:05.809287Z INFO fmt_compact: preparing to shave yaks number_of_yaks=3` COMPACT, /// Emits excessively pretty, multi-line logs, optimized for human readability. This is /// primarily intended to be used in local development and debugging, or for command-line From ca674d2cd99f5d14bb26738ab8f53465662765b4 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 26 Nov 2024 12:58:39 -0800 Subject: [PATCH 08/26] minor fixes --- ffi/examples/read-table/read_table.c | 4 ++-- ffi/src/ffi_tracing.rs | 2 +- ffi/src/lib.rs | 4 ++-- 3 files changed, 5 insertions(+), 5 deletions(-) diff --git a/ffi/examples/read-table/read_table.c b/ffi/examples/read-table/read_table.c index fbf3b8ba4..8e55103ad 100644 --- a/ffi/examples/read-table/read_table.c +++ b/ffi/examples/read-table/read_table.c @@ -169,10 +169,10 @@ void tracing_callback(struct Event event) { char* message = allocate_string(event.message); char* level_color = event.level < 3 ? RED : BLUE; printf( - "%s%s.%06ldZ%s [%sKernel %s%s]: %s\n", + "%s%s.%06dZ%s [%sKernel %s%s]: %s\n", DIM, buffer, - tv.tv_usec, + (int)tv.tv_usec, // safe, microseconds are in int range RESET, level_color, LEVEL_STRING[event.level], diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 517f9d4a8..1b5acd1bb 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -98,7 +98,7 @@ pub enum LogLineFormat { /// applications, where automated analysis and compact storage of logs is less of a priority /// than readability and visual appeal. /// Example: - /// ``` + /// ```ignore /// 2022-02-15T18:44:24.535324Z INFO fmt_pretty: preparing to shave yaks, number_of_yaks: 3 /// at examples/examples/fmt-pretty.rs:16 on main /// ``` diff --git a/ffi/src/lib.rs b/ffi/src/lib.rs index c369ae109..7561eba9a 100644 --- a/ffi/src/lib.rs +++ b/ffi/src/lib.rs @@ -35,12 +35,12 @@ pub mod engine_funcs; pub mod error; use error::{AllocateError, AllocateErrorFn, ExternResult, IntoExternResult}; pub mod expressions; +#[cfg(feature = "tracing")] +pub mod ffi_tracing; pub mod scan; pub mod schema; #[cfg(feature = "test-ffi")] pub mod test_ffi; -#[cfg(feature = "tracing")] -pub mod ffi_tracing; pub(crate) type NullableCvoid = Option>; From 34e53f63b6f98bc3cefa51a3220edec19f53a179 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 26 Nov 2024 16:25:47 -0800 Subject: [PATCH 09/26] add a test --- ffi/src/ffi_tracing.rs | 95 ++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 95 insertions(+) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 1b5acd1bb..439fb1218 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -72,6 +72,9 @@ pub type TracingEventFn = extern "C" fn(event: Event); /// [`Event`] based tracing gives an engine maximal flexibility in formatting event log /// lines. Kernel can also format events for the engine. If this is desired call /// [`enable_log_line_tracing`] instead of this method. +/// +/// # Safety +/// Caller must pass a valid function pointer for the callback #[no_mangle] pub unsafe extern "C" fn enable_event_tracing(callback: TracingEventFn, max_level: Level) { setup_event_subscriber(callback, max_level); @@ -117,6 +120,7 @@ pub enum LogLineFormat { /// - include timestamps /// - include level /// - include target +/// /// `max_level` specifies that only logs `<=` to the specified level should be reported. More /// verbose Levels are "greater than" less verbose ones. So Level::ERROR is the lowest, and /// Level::TRACE the highest. @@ -126,6 +130,9 @@ pub enum LogLineFormat { /// Log line based tracing is simple for an engine as it can just log the passed string, but does /// not provide flexibility for an engine to format events. If the engine wants to use a specific /// format for events it should call [`enable_event_tracing`] instead of this function. +/// +/// # Safety +/// Caller must pass a valid function pointer for the callback #[no_mangle] pub unsafe extern "C" fn enable_log_line_tracing(callback: TracingLogLineFn, max_level: Level) { setup_log_line_subscriber( @@ -147,6 +154,9 @@ pub unsafe extern "C" fn enable_log_line_tracing(callback: TracingLogLineFn, max /// - `with_time`: should the formatter include a timestamp in the log message /// - `with_level`: should the formatter include the level in the log message /// - `with_target`: should the formatter include what part of the system the event occurred +/// +/// # Safety +/// Caller must pass a valid function pointer for the callback #[no_mangle] pub unsafe extern "C" fn enable_formatted_log_line_tracing( callback: TracingLogLineFn, @@ -352,3 +362,88 @@ fn setup_log_line_subscriber( } } } + +#[cfg(test)] +mod tests { + use tracing::info; + use tracing_subscriber::fmt::time::FormatTime; + + use crate::TryFromStringSlice; + + use super::*; + + static MESSAGES: Mutex>> = Mutex::new(None); + + extern "C" fn record_callback(line: KernelStringSlice) { + let s: &str = unsafe { TryFromStringSlice::try_from_slice(&line).unwrap() }; + let s = s.to_string(); + let mut lock = MESSAGES.lock().unwrap(); + if let Some(ref mut msgs) = *lock { + msgs.push(s); + } + } + + fn setup_messages() { + *MESSAGES.lock().unwrap() = Some(vec![]); + } + + // get the string that we should ensure is in log messages for the time. If current time seconds + // is >= 50, return None because the minute might roll over before we actually log which would + // invalidate this check + fn get_time_test_str() -> Option { + #[derive(Default)] + struct W { + s: String, + } + impl fmt::Write for W { + fn write_str(&mut self, s: &str) -> fmt::Result { + self.s.push_str(s); + Ok(()) + } + } + + let mut w = W::default(); + let mut writer = tracing_subscriber::fmt::format::Writer::new(&mut w); + let now = tracing_subscriber::fmt::time::SystemTime; + now.format_time(&mut writer).unwrap(); + let tstr = w.s; + if tstr.len() < 19 { + return None; + } + let secs: u32 = tstr[17..19].parse().expect("Failed to parse secs"); + if secs >= 50 { + // risk of roll-over, don't check + return None; + } + // Trim to just hours and minutes + Some(tstr[..19].to_string()) + } + + #[test] + fn info_logs_with_log_line_tracing() { + setup_messages(); + unsafe { + enable_log_line_tracing(record_callback, Level::TRACE); + } + let lines = ["Testing 1\n", "Another line\n"]; + let test_time_str = get_time_test_str(); + for line in lines { + // remove final newline which will be added back by logging + info!("{}", &line[..(line.len() - 1)]); + } + let lock = MESSAGES.lock().unwrap(); + if let Some(ref msgs) = *lock { + assert_eq!(msgs.len(), lines.len()); + for (got, expect) in msgs.iter().zip(lines) { + assert!(got.ends_with(expect)); + assert!(got.contains("INFO")); + assert!(got.contains("delta_kernel_ffi::ffi_tracing::tests")); + if let Some(ref tstr) = test_time_str { + assert!(got.contains(tstr)); + } + } + } else { + panic!("Messages wasn't Some"); + } + } +} From 7ad2c09b93055a3966af2377928fb7e6b5efa258 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Wed, 27 Nov 2024 11:01:22 -0800 Subject: [PATCH 10/26] cleanups for docs and tests --- ffi/Cargo.toml | 3 +- ffi/src/ffi_tracing.rs | 166 ++++++++++++++++++++++++++++++++++------- 2 files changed, 140 insertions(+), 29 deletions(-) diff --git a/ffi/Cargo.toml b/ffi/Cargo.toml index 9c6b68da0..ef452f2c1 100644 --- a/ffi/Cargo.toml +++ b/ffi/Cargo.toml @@ -15,6 +15,7 @@ crate-type = ["lib", "cdylib", "staticlib"] [dependencies] tracing = "0.1" +tracing-core = { version = "0.1", optional = true } tracing-subscriber = { version = "0.3", optional = true, features = [ "json" ] } url = "2" delta_kernel = { path = "../kernel", default-features = false, features = [ @@ -47,7 +48,7 @@ default-engine = [ "arrow-data", "arrow-schema", ] -tracing = [ "tracing-subscriber" ] +tracing = [ "tracing-core", "tracing-subscriber" ] sync-engine = ["delta_kernel/sync-engine"] developer-visibility = [] test-ffi = [] diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 439fb1218..f47c2a4c6 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -3,6 +3,7 @@ use std::sync::{Arc, Mutex}; use std::{fmt, io}; +use delta_kernel::{DeltaResult, Error}; use tracing::{ field::{Field as TracingField, Visit}, Event as TracingEvent, Subscriber, @@ -69,15 +70,22 @@ pub type TracingEventFn = extern "C" fn(event: Event); /// that only events `<=` to the specified level should be reported. More verbose Levels are "greater /// than" less verbose ones. So Level::ERROR is the lowest, and Level::TRACE the highest. /// -/// [`Event`] based tracing gives an engine maximal flexibility in formatting event log +/// Note that setting up such a call back can only be done ONCE. Calling any of +/// `enable_event_tracing`, `enable_log_line_tracing`, or `enable_formatted_log_line_tracing` more +/// than once is a no-op. +/// +/// Returns `true` if the callback was setup successfully, false on failure (i.e. if called a second +/// time) +/// +/// [`event`] based tracing gives an engine maximal flexibility in formatting event log /// lines. Kernel can also format events for the engine. If this is desired call /// [`enable_log_line_tracing`] instead of this method. /// /// # Safety /// Caller must pass a valid function pointer for the callback #[no_mangle] -pub unsafe extern "C" fn enable_event_tracing(callback: TracingEventFn, max_level: Level) { - setup_event_subscriber(callback, max_level); +pub unsafe extern "C" fn enable_event_tracing(callback: TracingEventFn, max_level: Level) -> bool { + setup_event_subscriber(callback, max_level).is_ok() } pub type TracingLogLineFn = extern "C" fn(line: KernelStringSlice); @@ -127,6 +135,13 @@ pub enum LogLineFormat { /// /// Log lines passed to the callback will already have a newline at the end. /// +/// Note that setting up such a call back can only be done ONCE. Calling any of +/// `enable_event_tracing`, `enable_log_line_tracing`, or `enable_formatted_log_line_tracing` more +/// than once is a no-op. +/// +/// Returns `true` if the callback was setup successfully, false on failure (i.e. if called a second +/// time) +/// /// Log line based tracing is simple for an engine as it can just log the passed string, but does /// not provide flexibility for an engine to format events. If the engine wants to use a specific /// format for events it should call [`enable_event_tracing`] instead of this function. @@ -134,7 +149,10 @@ pub enum LogLineFormat { /// # Safety /// Caller must pass a valid function pointer for the callback #[no_mangle] -pub unsafe extern "C" fn enable_log_line_tracing(callback: TracingLogLineFn, max_level: Level) { +pub unsafe extern "C" fn enable_log_line_tracing( + callback: TracingLogLineFn, + max_level: Level, +) -> bool { setup_log_line_subscriber( callback, max_level, @@ -143,12 +161,22 @@ pub unsafe extern "C" fn enable_log_line_tracing(callback: TracingLogLineFn, max true, true, true, - ); + ) + .is_ok() } /// Enable getting called back with log lines in the kernel. This variant allows specifying /// formatting options for the log lines. See [`enable_log_line_tracing`] for general info on -/// getting called back for log lines. Options that can be set here: +/// getting called back for log lines. +/// +/// Note that setting up such a call back can only be done ONCE. Calling any of +/// `enable_event_tracing`, `enable_log_line_tracing`, or `enable_formatted_log_line_tracing` more +/// than once is a no-op. +/// +/// Returns `true` if the callback was setup successfully, false on failure (i.e. if called a second +/// time) +/// +/// Options that can be set: /// - `format`: see [`LogLineFormat`] /// - `ansi`: should the formatter use ansi escapes for color /// - `with_time`: should the formatter include a timestamp in the log message @@ -166,7 +194,7 @@ pub unsafe extern "C" fn enable_formatted_log_line_tracing( with_time: bool, with_level: bool, with_target: bool, -) { +) -> bool { setup_log_line_subscriber( callback, max_level, @@ -175,11 +203,18 @@ pub unsafe extern "C" fn enable_formatted_log_line_tracing( with_time, with_level, with_target, - ); + ) + .is_ok() } // utility code below for setting up the tracing subscriber for events +pub fn set_global_default(dispatch: tracing_core::Dispatch) -> DeltaResult<()> { + tracing_core::dispatcher::set_global_default(dispatch).map_err(|_| { + Error::generic("Unable to set global default subscriber. Trying to set more than once?") + }) +} + struct MessageFieldVisitor { message: Option, } @@ -238,12 +273,17 @@ where } } -fn setup_event_subscriber(callback: TracingEventFn, max_level: Level) { +fn get_event_dispatcher(callback: TracingEventFn, max_level: Level) -> tracing_core::Dispatch { use tracing_subscriber::{layer::SubscriberExt, registry::Registry}; let filter: LevelFilter = max_level.into(); let event_layer = EventLayer { callback }.with_filter(filter); let subscriber = Registry::default().with(event_layer); - tracing::subscriber::set_global_default(subscriber).expect("Failed to set global subscriber"); + tracing_core::Dispatch::new(subscriber) +} + +fn setup_event_subscriber(callback: TracingEventFn, max_level: Level) -> DeltaResult<()> { + let dispatch = get_event_dispatcher(callback, max_level); + set_global_default(dispatch) } // utility code below for setting up the tracing subscriber for log lines @@ -294,7 +334,7 @@ impl<'a> MakeWriter<'a> for BufferedMessageWriter { } } -fn setup_log_line_subscriber( +fn get_log_line_dispatch( callback: TracingLogLineFn, max_level: Level, format: LogLineFormat, @@ -302,7 +342,7 @@ fn setup_log_line_subscriber( with_time: bool, with_level: bool, with_target: bool, -) { +) -> tracing_core::Dispatch { use tracing_subscriber::{layer::SubscriberExt, registry::Registry}; let buffer = Arc::new(Mutex::new(vec![])); let writer = BufferedMessageWriter { @@ -325,14 +365,16 @@ fn setup_log_line_subscriber( ( $format_fn:ident ) => { if with_time { let fmt_layer = fmt_layer.$format_fn().with_filter(filter); - let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); - tracing::subscriber::set_global_default(subscriber) - .expect("Failed to set global subscriber"); + let subscriber = Registry::default() + .with(fmt_layer) + .with(tracking_layer.with_filter(filter)); + tracing_core::Dispatch::new(subscriber) } else { let fmt_layer = fmt_layer.without_time().$format_fn().with_filter(filter); - let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); - tracing::subscriber::set_global_default(subscriber) - .expect("Failed to set global subscriber"); + let subscriber = Registry::default() + .with(fmt_layer) + .with(tracking_layer.with_filter(filter)); + tracing_core::Dispatch::new(subscriber) } }; } @@ -341,30 +383,54 @@ fn setup_log_line_subscriber( // can't use macro as there's no `full()` function, it's just the default if with_time { let fmt_layer = fmt_layer.with_filter(filter); - let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); - tracing::subscriber::set_global_default(subscriber) - .expect("Failed to set global subscriber"); + let subscriber = Registry::default() + .with(fmt_layer) + .with(tracking_layer.with_filter(filter)); + tracing_core::Dispatch::new(subscriber) } else { let fmt_layer = fmt_layer.without_time().with_filter(filter); - let subscriber = Registry::default().with(fmt_layer).with(tracking_layer); - tracing::subscriber::set_global_default(subscriber) - .expect("Failed to set global subscriber"); + let subscriber = Registry::default() + .with(fmt_layer) + .with(tracking_layer.with_filter(filter)); + tracing_core::Dispatch::new(subscriber) } } LogLineFormat::COMPACT => { - setup_subscriber!(compact); + setup_subscriber!(compact) } LogLineFormat::PRETTY => { - setup_subscriber!(pretty); + setup_subscriber!(pretty) } LogLineFormat::JSON => { - setup_subscriber!(json); + setup_subscriber!(json) } } } +fn setup_log_line_subscriber( + callback: TracingLogLineFn, + max_level: Level, + format: LogLineFormat, + ansi: bool, + with_time: bool, + with_level: bool, + with_target: bool, +) -> DeltaResult<()> { + let dispatch = get_log_line_dispatch( + callback, + max_level, + format, + ansi, + with_time, + with_level, + with_target, + ); + set_global_default(dispatch) +} #[cfg(test)] mod tests { + use std::sync::LazyLock; + use tracing::info; use tracing_subscriber::fmt::time::FormatTime; @@ -372,6 +438,9 @@ mod tests { use super::*; + // Because we have to access a global messages buffer, we have to force tests to run one at a + // time + static TEST_LOCK: LazyLock> = LazyLock::new(|| Mutex::new(())); static MESSAGES: Mutex>> = Mutex::new(None); extern "C" fn record_callback(line: KernelStringSlice) { @@ -419,11 +488,15 @@ mod tests { Some(tstr[..19].to_string()) } + // IMPORTANT: This is the only test that should call the actual `extern "C"` function, as we can + // only call it once to set the global subscriber. Other tests ALL need to use + // `get_X_dispatcher` and set it locally using `with_default` #[test] fn info_logs_with_log_line_tracing() { + let _lock = TEST_LOCK.lock().unwrap(); setup_messages(); unsafe { - enable_log_line_tracing(record_callback, Level::TRACE); + enable_log_line_tracing(record_callback, Level::INFO); } let lines = ["Testing 1\n", "Another line\n"]; let test_time_str = get_time_test_str(); @@ -446,4 +519,41 @@ mod tests { panic!("Messages wasn't Some"); } } + + #[test] + fn info_logs_with_formatted_log_line_tracing() { + let _lock = TEST_LOCK.lock().unwrap(); + setup_messages(); + let dispatch = get_log_line_dispatch( + record_callback, + Level::INFO, + LogLineFormat::COMPACT, + false, + true, + false, + false, + ); + tracing_core::dispatcher::with_default(&dispatch, || { + let lines = ["Testing 1\n", "Another line\n"]; + let test_time_str = get_time_test_str(); + for line in lines { + // remove final newline which will be added back by logging + info!("{}", &line[..(line.len() - 1)]); + } + let lock = MESSAGES.lock().unwrap(); + if let Some(ref msgs) = *lock { + assert_eq!(msgs.len(), lines.len()); + for (got, expect) in msgs.iter().zip(lines) { + assert!(got.ends_with(expect)); + assert!(!got.contains("INFO")); + assert!(!got.contains("delta_kernel_ffi::ffi_tracing::tests")); + if let Some(ref tstr) = test_time_str { + assert!(got.contains(tstr)); + } + } + } else { + panic!("Messages wasn't Some"); + } + }) + } } From cb272a9bd9280bf6412abc75944cc0984d5f3ca6 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 15:37:24 -0800 Subject: [PATCH 11/26] print target + don't allocate --- ffi/examples/read-table/read_table.c | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/ffi/examples/read-table/read_table.c b/ffi/examples/read-table/read_table.c index 8e55103ad..4e5b05281 100644 --- a/ffi/examples/read-table/read_table.c +++ b/ffi/examples/read-table/read_table.c @@ -166,10 +166,9 @@ void tracing_callback(struct Event event) { gettimeofday(&tv, NULL); struct tm *tm_info = gmtime(&tv.tv_sec); strftime(buffer, 26, "%Y-%m-%dT%H:%M:%S", tm_info); - char* message = allocate_string(event.message); char* level_color = event.level < 3 ? RED : BLUE; printf( - "%s%s.%06dZ%s [%sKernel %s%s]: %s\n", + "%s%s.%06dZ%s [%sKernel %s%s] %s%.*s%s: %.*s\n", DIM, buffer, (int)tv.tv_usec, // safe, microseconds are in int range @@ -177,24 +176,25 @@ void tracing_callback(struct Event event) { level_color, LEVEL_STRING[event.level], RESET, - message); + DIM, + (int)event.target.len, + event.target.ptr, + RESET, + (int)event.message.len, + event.message.ptr); if (event.file.ptr) { - char* file = allocate_string(event.file); printf( - " %sat%s %s:%i\n", + " %sat%s %.*s:%i\n", DIM, RESET, - file, + (int)event.file.len, + event.file.ptr, event.line); - free(file); } - free(message); } void log_line_callback(KernelStringSlice line) { - char* message = allocate_string(line); - printf("%s", message); - free(message); + printf("%.*s", (int)line.len, line.ptr); } int main(int argc, char* argv[]) From 43435c2013abf7cc2284c17db3cb13018cf38360 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 15:51:40 -0800 Subject: [PATCH 12/26] validate max_level --- ffi/src/ffi_tracing.rs | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index f47c2a4c6..98265eec4 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -16,12 +16,20 @@ use crate::{kernel_string_slice, KernelStringSlice}; /// Definitions of level verbosity. Verbose Levels are "greater than" less verbose ones. So /// Level::ERROR is the lowest, and Level::TRACE the highest. #[repr(C)] +#[derive(Clone, Copy)] pub enum Level { - ERROR, - WARN, - INFO, - DEBUG, - TRACE, + ERROR = 0, + WARN = 1, + INFO = 2, + DEBUG = 3, + TRACE = 4, +} + +impl Level { + fn is_valid(value: u32) -> bool { + static VALID_VALUES: &[u32] = &[0, 1, 2, 3, 4]; + VALID_VALUES.contains(&value) + } } impl From<&tracing::Level> for Level { @@ -282,6 +290,10 @@ fn get_event_dispatcher(callback: TracingEventFn, max_level: Level) -> tracing_c } fn setup_event_subscriber(callback: TracingEventFn, max_level: Level) -> DeltaResult<()> { + let level_int = max_level as u32; + if !Level::is_valid(level_int) { + return Err(Error::generic("max_level out of range")); + } let dispatch = get_event_dispatcher(callback, max_level); set_global_default(dispatch) } @@ -406,6 +418,7 @@ fn get_log_line_dispatch( } } } + fn setup_log_line_subscriber( callback: TracingLogLineFn, max_level: Level, @@ -415,6 +428,10 @@ fn setup_log_line_subscriber( with_level: bool, with_target: bool, ) -> DeltaResult<()> { + let level_int = max_level as u32; + if !Level::is_valid(level_int) { + return Err(Error::generic("max_level out of range")); + } let dispatch = get_log_line_dispatch( callback, max_level, From 7378cfef8bffdf2c9a0e8e52370ac86a01f83d24 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 16:16:25 -0800 Subject: [PATCH 13/26] address comments --- ffi/src/ffi_tracing.rs | 52 ++++++++++++++++++++++-------------------- ffi/src/lib.rs | 8 +++++++ 2 files changed, 35 insertions(+), 25 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 98265eec4..38a294464 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -165,10 +165,10 @@ pub unsafe extern "C" fn enable_log_line_tracing( callback, max_level, LogLineFormat::FULL, - true, - true, - true, - true, + true, /* ansi color on */ + true, /* time included */ + true, /* level included */ + true, /* target included */ ) .is_ok() } @@ -254,27 +254,19 @@ where // we want to use a KernelStringSlice, so we need the extracted string to live long enough // for the callback which won't happen if we convert inside a `try_from` call let metadata = event.metadata(); - let level = metadata.level().into(); + let target = metadata.target(); let mut message_visitor = MessageFieldVisitor { message: None }; event.record(&mut message_visitor); if let Some(message) = message_visitor.message { // we ignore events without a message - let msg = kernel_string_slice!(message); - let target = metadata.target(); - let target = kernel_string_slice!(target); - let file = match metadata.file() { - Some(file) => kernel_string_slice!(file), - None => KernelStringSlice { - ptr: std::ptr::null(), - len: 0, - }, - }; let event = Event { - message: msg, - level, - target, + message: kernel_string_slice!(message), + level: metadata.level().into(), + target: kernel_string_slice!(target), line: metadata.line().unwrap_or(0), - file, + file: metadata + .file() + .map_or(KernelStringSlice::empty(), |f| kernel_string_slice!(f)), }; (self.callback)(event); } @@ -312,11 +304,19 @@ where S: Subscriber + for<'a> LookupSpan<'a>, { fn on_event(&self, _: &TracingEvent<'_>, _context: Context<'_, S>) { - let mut buf = self.buf.lock().unwrap(); - let output = String::from_utf8_lossy(&buf); - let message = kernel_string_slice!(output); - (self.callback)(message); - buf.clear(); + match self.buf.lock() { + Ok(mut buf) => { + let output = String::from_utf8_lossy(&buf); + let message = kernel_string_slice!(output); + (self.callback)(message); + buf.clear(); + } + Err(_) => { + let message = "INTERNAL KERNEL ERROR: Could not lock message buffer."; + let message = kernel_string_slice!(message); + (self.callback)(message); + } + } } } @@ -327,7 +327,9 @@ struct BufferedMessageWriter { impl io::Write for BufferedMessageWriter { fn write(&mut self, buf: &[u8]) -> io::Result { - self.current_buffer.lock().unwrap().extend_from_slice(buf); + self.current_buffer.lock().map_err(|_| { + io::Error::new(io::ErrorKind::Other, "Could not lock buffer") + })?.extend_from_slice(buf); Ok(buf.len()) } diff --git a/ffi/src/lib.rs b/ffi/src/lib.rs index 7561eba9a..5f9757196 100644 --- a/ffi/src/lib.rs +++ b/ffi/src/lib.rs @@ -121,6 +121,14 @@ impl KernelStringSlice { len: source.len(), } } + + /// Create a new empty `KernelStringSlice`. `len` will be 0, and `ptr` will be `null`. + pub(crate) fn empty() -> Self { + Self { + ptr: std::ptr::null(), + len: 0, + } + } } /// Creates a new [`KernelStringSlice`] from a string reference (which must be an identifier, to From 130ece621ad770502b242ba9b210a9671c1b5522 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 16:54:51 -0800 Subject: [PATCH 14/26] update macro --- ffi/src/ffi_tracing.rs | 60 +++++++++++++----------------------------- 1 file changed, 19 insertions(+), 41 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 38a294464..c59a3ea75 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -376,48 +376,26 @@ fn get_log_line_dispatch( // This repeats some code, but avoids some insane generic wrangling if we try to abstract the // type of `fmt_layer` over the formatter macro_rules! setup_subscriber { - ( $format_fn:ident ) => { - if with_time { - let fmt_layer = fmt_layer.$format_fn().with_filter(filter); - let subscriber = Registry::default() - .with(fmt_layer) - .with(tracking_layer.with_filter(filter)); - tracing_core::Dispatch::new(subscriber) - } else { - let fmt_layer = fmt_layer.without_time().$format_fn().with_filter(filter); - let subscriber = Registry::default() - .with(fmt_layer) - .with(tracking_layer.with_filter(filter)); - tracing_core::Dispatch::new(subscriber) - } - }; + ($($transform:ident($($arg:ident)?)).+) => {{ + let fmt_layer = fmt_layer$(.$transform($($arg)?))+.with_filter(filter); + let subscriber = Registry::default() + .with(fmt_layer) + .with(tracking_layer.with_filter(filter)); + tracing_core::Dispatch::new(subscriber) + }}; } - match format { - LogLineFormat::FULL => { - // can't use macro as there's no `full()` function, it's just the default - if with_time { - let fmt_layer = fmt_layer.with_filter(filter); - let subscriber = Registry::default() - .with(fmt_layer) - .with(tracking_layer.with_filter(filter)); - tracing_core::Dispatch::new(subscriber) - } else { - let fmt_layer = fmt_layer.without_time().with_filter(filter); - let subscriber = Registry::default() - .with(fmt_layer) - .with(tracking_layer.with_filter(filter)); - tracing_core::Dispatch::new(subscriber) - } - } - LogLineFormat::COMPACT => { - setup_subscriber!(compact) - } - LogLineFormat::PRETTY => { - setup_subscriber!(pretty) - } - LogLineFormat::JSON => { - setup_subscriber!(json) - } + use LogLineFormat::*; + match (format, with_time) { + // NOTE: There is no `full()` method (it's the default), so just call `with_ansi` + // a second time instead (as a no-op) to keep the macro happy. + (FULL, true) => setup_subscriber!(with_ansi(ansi)), + (FULL, false) => setup_subscriber!(without_time()), + (COMPACT, true) => setup_subscriber!(compact()), + (COMPACT, false) => setup_subscriber!(compact().without_time()), + (PRETTY, true) => setup_subscriber!(pretty()), + (PRETTY, false) => setup_subscriber!(pretty().without_time()), + (JSON, true) => setup_subscriber!(json()), + (JSON, false) => setup_subscriber!(json().without_time()), } } From 679556e1f4ed5aee481c4606df63789913f8e718 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 16:55:22 -0800 Subject: [PATCH 15/26] fmt --- ffi/src/ffi_tracing.rs | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index c59a3ea75..0fb0e9ded 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -327,9 +327,10 @@ struct BufferedMessageWriter { impl io::Write for BufferedMessageWriter { fn write(&mut self, buf: &[u8]) -> io::Result { - self.current_buffer.lock().map_err(|_| { - io::Error::new(io::ErrorKind::Other, "Could not lock buffer") - })?.extend_from_slice(buf); + self.current_buffer + .lock() + .map_err(|_| io::Error::new(io::ErrorKind::Other, "Could not lock buffer"))? + .extend_from_slice(buf); Ok(buf.len()) } @@ -388,8 +389,8 @@ fn get_log_line_dispatch( match (format, with_time) { // NOTE: There is no `full()` method (it's the default), so just call `with_ansi` // a second time instead (as a no-op) to keep the macro happy. - (FULL, true) => setup_subscriber!(with_ansi(ansi)), - (FULL, false) => setup_subscriber!(without_time()), + (FULL, true) => setup_subscriber!(with_ansi(ansi)), + (FULL, false) => setup_subscriber!(without_time()), (COMPACT, true) => setup_subscriber!(compact()), (COMPACT, false) => setup_subscriber!(compact().without_time()), (PRETTY, true) => setup_subscriber!(pretty()), From dc7a2e40558cf36f410068afb1361600194549c2 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 16:56:18 -0800 Subject: [PATCH 16/26] clippy fix --- ffi/src/handle.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/ffi/src/handle.rs b/ffi/src/handle.rs index c34282e16..b3be3d434 100644 --- a/ffi/src/handle.rs +++ b/ffi/src/handle.rs @@ -176,7 +176,6 @@ mod private { { /// Obtains a mutable reference to the handle's underlying object. Unsafe equivalent to /// [`AsMut::as_mut`]. - /// /// # Safety /// From 973eed1f3fb53bd6c354504f010c9261416f9d3f Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 17:01:06 -0800 Subject: [PATCH 17/26] macro cleanup --- ffi/src/ffi_tracing.rs | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 0fb0e9ded..1bf4b16c6 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -377,8 +377,8 @@ fn get_log_line_dispatch( // This repeats some code, but avoids some insane generic wrangling if we try to abstract the // type of `fmt_layer` over the formatter macro_rules! setup_subscriber { - ($($transform:ident($($arg:ident)?)).+) => {{ - let fmt_layer = fmt_layer$(.$transform($($arg)?))+.with_filter(filter); + ($($transform:ident($($arg:ident)?)).*) => {{ + let fmt_layer = fmt_layer$(.$transform($($arg)?))*.with_filter(filter); let subscriber = Registry::default() .with(fmt_layer) .with(tracking_layer.with_filter(filter)); @@ -387,9 +387,7 @@ fn get_log_line_dispatch( } use LogLineFormat::*; match (format, with_time) { - // NOTE: There is no `full()` method (it's the default), so just call `with_ansi` - // a second time instead (as a no-op) to keep the macro happy. - (FULL, true) => setup_subscriber!(with_ansi(ansi)), + (FULL, true) => setup_subscriber!(), (FULL, false) => setup_subscriber!(without_time()), (COMPACT, true) => setup_subscriber!(compact()), (COMPACT, false) => setup_subscriber!(compact().without_time()), From 76743da4d588ce80e2c5e87dae662b67bab810f5 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Mon, 2 Dec 2024 17:04:04 -0800 Subject: [PATCH 18/26] actually is even more simple --- ffi/src/ffi_tracing.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 1bf4b16c6..da0c55168 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -377,8 +377,8 @@ fn get_log_line_dispatch( // This repeats some code, but avoids some insane generic wrangling if we try to abstract the // type of `fmt_layer` over the formatter macro_rules! setup_subscriber { - ($($transform:ident($($arg:ident)?)).*) => {{ - let fmt_layer = fmt_layer$(.$transform($($arg)?))*.with_filter(filter); + ($($transform:ident()).*) => {{ + let fmt_layer = fmt_layer$(.$transform())*.with_filter(filter); let subscriber = Registry::default() .with(fmt_layer) .with(tracking_layer.with_filter(filter)); From f5716cf5c6a67ec4ed76104eb1662a2c4cc7ab21 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Tue, 3 Dec 2024 16:33:00 -0800 Subject: [PATCH 19/26] address comments --- ffi/examples/read-table/read_table.c | 1 + ffi/src/ffi_tracing.rs | 15 ++++++--------- ffi/src/lib.rs | 8 -------- 3 files changed, 7 insertions(+), 17 deletions(-) diff --git a/ffi/examples/read-table/read_table.c b/ffi/examples/read-table/read_table.c index 4e5b05281..0aa8caa41 100644 --- a/ffi/examples/read-table/read_table.c +++ b/ffi/examples/read-table/read_table.c @@ -155,6 +155,7 @@ static const char *LEVEL_STRING[] = { "ERROR", "WARN", "INFO", "DEBUG", "TRACE" }; +// define some ansi color escapes so we can have nice colored output in our logs #define RED "\x1b[31m" #define BLUE "\x1b[34m" #define DIM "\x1b[2m" diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index da0c55168..f55dc4df2 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -26,9 +26,9 @@ pub enum Level { } impl Level { - fn is_valid(value: u32) -> bool { + fn is_valid(self) -> bool { static VALID_VALUES: &[u32] = &[0, 1, 2, 3, 4]; - VALID_VALUES.contains(&value) + VALID_VALUES.contains(&(self as u32)) } } @@ -259,14 +259,13 @@ where event.record(&mut message_visitor); if let Some(message) = message_visitor.message { // we ignore events without a message + let file = metadata.file().unwrap_or(""); let event = Event { message: kernel_string_slice!(message), level: metadata.level().into(), target: kernel_string_slice!(target), line: metadata.line().unwrap_or(0), - file: metadata - .file() - .map_or(KernelStringSlice::empty(), |f| kernel_string_slice!(f)), + file: kernel_string_slice!(file), }; (self.callback)(event); } @@ -282,8 +281,7 @@ fn get_event_dispatcher(callback: TracingEventFn, max_level: Level) -> tracing_c } fn setup_event_subscriber(callback: TracingEventFn, max_level: Level) -> DeltaResult<()> { - let level_int = max_level as u32; - if !Level::is_valid(level_int) { + if !max_level.is_valid() { return Err(Error::generic("max_level out of range")); } let dispatch = get_event_dispatcher(callback, max_level); @@ -407,8 +405,7 @@ fn setup_log_line_subscriber( with_level: bool, with_target: bool, ) -> DeltaResult<()> { - let level_int = max_level as u32; - if !Level::is_valid(level_int) { + if !max_level.is_valid() { return Err(Error::generic("max_level out of range")); } let dispatch = get_log_line_dispatch( diff --git a/ffi/src/lib.rs b/ffi/src/lib.rs index 5f9757196..7561eba9a 100644 --- a/ffi/src/lib.rs +++ b/ffi/src/lib.rs @@ -121,14 +121,6 @@ impl KernelStringSlice { len: source.len(), } } - - /// Create a new empty `KernelStringSlice`. `len` will be 0, and `ptr` will be `null`. - pub(crate) fn empty() -> Self { - Self { - ptr: std::ptr::null(), - len: 0, - } - } } /// Creates a new [`KernelStringSlice`] from a string reference (which must be an identifier, to From cee2caa6cc566d7a42d953c2a07444bdcc0e5d5c Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Wed, 4 Dec 2024 17:30:51 -0800 Subject: [PATCH 20/26] moar testing --- ffi/src/ffi_tracing.rs | 69 +++++++++++++++++++++++++++++++++++++++++- 1 file changed, 68 insertions(+), 1 deletion(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index f55dc4df2..969e07a8d 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -16,7 +16,7 @@ use crate::{kernel_string_slice, KernelStringSlice}; /// Definitions of level verbosity. Verbose Levels are "greater than" less verbose ones. So /// Level::ERROR is the lowest, and Level::TRACE the highest. #[repr(C)] -#[derive(Clone, Copy)] +#[derive(Clone, Copy, Debug, PartialEq)] pub enum Level { ERROR = 0, WARN = 1, @@ -511,6 +511,21 @@ mod tests { } else { panic!("Messages wasn't Some"); } + + // ensure we can't setup again + // do in the same test to ensure ordering + let ok = unsafe { + enable_formatted_log_line_tracing( + record_callback, + Level::TRACE, + LogLineFormat::FULL, + true, + true, + true, + true, + ) + }; + assert!(!ok, "Should have not set up a second time") } #[test] @@ -549,4 +564,56 @@ mod tests { } }) } + + static EVENTS_OK: Mutex>> = Mutex::new(None); + fn setup_events() { + *EVENTS_OK.lock().unwrap() = Some(vec![]); + } + + extern "C" fn event_callback(event: Event) { + let msg: &str = unsafe { TryFromStringSlice::try_from_slice(&event.message).unwrap() }; + let target: &str = unsafe { TryFromStringSlice::try_from_slice(&event.target).unwrap() }; + let file: &str = unsafe { TryFromStringSlice::try_from_slice(&event.file).unwrap() }; + let ok = event.level == Level::INFO + && target == "delta_kernel_ffi::ffi_tracing::tests" + && file == "ffi/src/ffi_tracing.rs" + && (msg == "Testing 1" || msg == "Another line"); + let mut lock = EVENTS_OK.lock().unwrap(); + if let Some(ref mut events) = *lock { + events.push(ok); + } + } + + #[test] + fn trace_event_tracking() { + let _lock = TEST_LOCK.lock().unwrap(); + setup_events(); + let dispatch = get_event_dispatcher(event_callback, Level::TRACE); + tracing_core::dispatcher::with_default(&dispatch, || { + let lines = ["Testing 1", "Another line"]; + for line in lines { + info!("{line}"); + } + }); + let lock = EVENTS_OK.lock().unwrap(); + if let Some(ref results) = *lock { + assert!(results.iter().all(|x| *x)); + } else { + panic!("Events wasn't Some"); + } + } + + #[test] + fn level_from_impl() { + let trace: Level = (&tracing::Level::TRACE).into(); + assert_eq!(trace, Level::TRACE); + let debug: Level = (&tracing::Level::DEBUG).into(); + assert_eq!(debug, Level::DEBUG); + let info: Level = (&tracing::Level::INFO).into(); + assert_eq!(info, Level::INFO); + let warn: Level = (&tracing::Level::WARN).into(); + assert_eq!(warn, Level::WARN); + let error: Level = (&tracing::Level::ERROR).into(); + assert_eq!(error, Level::ERROR); + } } From eab81057a2a8f8bddd3724ad483bf462acc67d2f Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Thu, 5 Dec 2024 16:03:53 -0800 Subject: [PATCH 21/26] address nit --- ffi/src/ffi_tracing.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 969e07a8d..9be91dd1d 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -304,8 +304,8 @@ where fn on_event(&self, _: &TracingEvent<'_>, _context: Context<'_, S>) { match self.buf.lock() { Ok(mut buf) => { - let output = String::from_utf8_lossy(&buf); - let message = kernel_string_slice!(output); + let message = String::from_utf8_lossy(&buf); + let message = kernel_string_slice!(message); (self.callback)(message); buf.clear(); } From 9918bb0db872a3fe97d343051073b40b1d87e064 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Thu, 5 Dec 2024 16:05:28 -0800 Subject: [PATCH 22/26] address nit --- ffi/src/ffi_tracing.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 9be91dd1d..77bb8d797 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -519,10 +519,10 @@ mod tests { record_callback, Level::TRACE, LogLineFormat::FULL, - true, - true, - true, - true, + true, // ansi + true, // with_time + true, // with_level + true, // with_target ) }; assert!(!ok, "Should have not set up a second time") From 20de800a01784868e689ec8b737f0efd917a317d Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Thu, 5 Dec 2024 16:10:16 -0800 Subject: [PATCH 23/26] printlns for windwos --- ffi/src/ffi_tracing.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 77bb8d797..13cefba21 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -574,6 +574,9 @@ mod tests { let msg: &str = unsafe { TryFromStringSlice::try_from_slice(&event.message).unwrap() }; let target: &str = unsafe { TryFromStringSlice::try_from_slice(&event.target).unwrap() }; let file: &str = unsafe { TryFromStringSlice::try_from_slice(&event.file).unwrap() }; + println!("msg: {msg}"); + println!("target: {target}"); + println!("file: {file}"); let ok = event.level == Level::INFO && target == "delta_kernel_ffi::ffi_tracing::tests" && file == "ffi/src/ffi_tracing.rs" From ef50fe94426640d8a128803ce1aba0e070930098 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Thu, 5 Dec 2024 16:18:08 -0800 Subject: [PATCH 24/26] fix windows test --- ffi/src/ffi_tracing.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 13cefba21..4d2b793b4 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -574,12 +574,14 @@ mod tests { let msg: &str = unsafe { TryFromStringSlice::try_from_slice(&event.message).unwrap() }; let target: &str = unsafe { TryFromStringSlice::try_from_slice(&event.target).unwrap() }; let file: &str = unsafe { TryFromStringSlice::try_from_slice(&event.file).unwrap() }; - println!("msg: {msg}"); - println!("target: {target}"); - println!("file: {file}"); + + // file path will use \ on windows + use std::path::MAIN_SEPARATOR; + let expected_file = format!("ffi{}src{}ffi_tracing.rs",MAIN_SEPARATOR,MAIN_SEPARATOR); + let ok = event.level == Level::INFO && target == "delta_kernel_ffi::ffi_tracing::tests" - && file == "ffi/src/ffi_tracing.rs" + && file == expected_file && (msg == "Testing 1" || msg == "Another line"); let mut lock = EVENTS_OK.lock().unwrap(); if let Some(ref mut events) = *lock { From 07de21834c59cb0d238e7fb7d84d8cda40ef6d48 Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Thu, 5 Dec 2024 16:19:48 -0800 Subject: [PATCH 25/26] fmt --- ffi/src/ffi_tracing.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 4d2b793b4..31eee56df 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -577,7 +577,7 @@ mod tests { // file path will use \ on windows use std::path::MAIN_SEPARATOR; - let expected_file = format!("ffi{}src{}ffi_tracing.rs",MAIN_SEPARATOR,MAIN_SEPARATOR); + let expected_file = format!("ffi{}src{}ffi_tracing.rs", MAIN_SEPARATOR, MAIN_SEPARATOR); let ok = event.level == Level::INFO && target == "delta_kernel_ffi::ffi_tracing::tests" From 4f3429d8d596e5472bdcfc005b4dbfa04746fa9b Mon Sep 17 00:00:00 2001 From: Nick Lanham Date: Fri, 6 Dec 2024 12:32:32 -0800 Subject: [PATCH 26/26] don't need set_global_default to be pub --- ffi/src/ffi_tracing.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ffi/src/ffi_tracing.rs b/ffi/src/ffi_tracing.rs index 31eee56df..1f49e750f 100644 --- a/ffi/src/ffi_tracing.rs +++ b/ffi/src/ffi_tracing.rs @@ -217,7 +217,7 @@ pub unsafe extern "C" fn enable_formatted_log_line_tracing( // utility code below for setting up the tracing subscriber for events -pub fn set_global_default(dispatch: tracing_core::Dispatch) -> DeltaResult<()> { +fn set_global_default(dispatch: tracing_core::Dispatch) -> DeltaResult<()> { tracing_core::dispatcher::set_global_default(dispatch).map_err(|_| { Error::generic("Unable to set global default subscriber. Trying to set more than once?") })