v0.1.2-pre.002

crates/ksp-logging-lib/tests/callsite.rs

@@ -0,0 +1,157 @@
+// file: crates/ksp-logging-lib/tests/callsite.rs
+// version: 1
+
+const TEST_TARGET: &str = "ksp-logging-lib";
+
+#[derive(Clone, Debug, Eq, PartialEq)]
+struct CapturedMetadata {
+    target: std::string::String,
+    file: std::option::Option<std::string::String>,
+    module_path: std::option::Option<std::string::String>,
+    line: std::option::Option<u32>,
+    is_event: bool,
+    is_span: bool,
+}
+
+impl CapturedMetadata {
+    fn from_metadata(metadata: &tracing::Metadata<'_>) -> Self {
+        return Self {
+            target: metadata.target().to_owned(),
+            file: metadata.file().map(str::to_owned),
+            module_path: metadata.module_path().map(str::to_owned),
+            line: metadata.line(),
+            is_event: metadata.is_event(),
+            is_span: metadata.is_span(),
+        };
+    }
+}
+
+#[derive(Clone)]
+struct CaptureSubscriber {
+    captured: std::sync::Arc<std::sync::Mutex<std::vec::Vec<CapturedMetadata>>>,
+    enters: std::sync::Arc<std::sync::atomic::AtomicU64>,
+    exits: std::sync::Arc<std::sync::atomic::AtomicU64>,
+    next_id: std::sync::Arc<std::sync::atomic::AtomicU64>,
+}
+
+impl CaptureSubscriber {
+    fn new(
+        captured: std::sync::Arc<std::sync::Mutex<std::vec::Vec<CapturedMetadata>>>,
+        enters: std::sync::Arc<std::sync::atomic::AtomicU64>,
+        exits: std::sync::Arc<std::sync::atomic::AtomicU64>,
+    ) -> Self {
+        return Self { captured, enters, exits, next_id: std::sync::Arc::new(std::sync::atomic::AtomicU64::new(1)) };
+    }
+
+    fn capture(&self, metadata: &tracing::Metadata<'_>) {
+        let lock = self.captured.lock();
+        if let std::result::Result::Ok(mut values) = lock {
+            values.push(CapturedMetadata::from_metadata(metadata));
+        }
+    }
+}
+
+impl tracing::Subscriber for CaptureSubscriber {
+    fn enabled(&self, _metadata: &tracing::Metadata<'_>) -> bool {
+        return true;
+    }
+
+    fn new_span(&self, span: &tracing::span::Attributes<'_>) -> tracing::span::Id {
+        self.capture(span.metadata());
+        let id = self.next_id.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
+        return tracing::span::Id::from_u64(id);
+    }
+
+    fn record(&self, _span: &tracing::span::Id, _values: &tracing::span::Record<'_>) {
+        return;
+    }
+
+    fn record_follows_from(&self, _span: &tracing::span::Id, _follows: &tracing::span::Id) {
+        return;
+    }
+
+    fn event(&self, event: &tracing::Event<'_>) {
+        self.capture(event.metadata());
+        return;
+    }
+
+    fn enter(&self, _span: &tracing::span::Id) {
+        self.enters.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
+        return;
+    }
+
+    fn exit(&self, _span: &tracing::span::Id) {
+        self.exits.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
+        return;
+    }
+}
+
+fn captured_values(captured: &std::sync::Arc<std::sync::Mutex<std::vec::Vec<CapturedMetadata>>>) -> std::vec::Vec<CapturedMetadata> {
+    let lock = captured.lock();
+    return match lock {
+        std::result::Result::Ok(values) => values.clone(),
+        std::result::Result::Err(error) => error.into_inner().clone(),
+    };
+}
+
+#[test]
+fn event_macro_preserves_consumer_callsite() {
+    let captured = std::sync::Arc::new(std::sync::Mutex::new(std::vec::Vec::new()));
+    let enters = std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0));
+    let exits = std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0));
+    let subscriber = CaptureSubscriber::new(captured.clone(), enters, exits);
+    let expected_line = line!() + 2;
+    tracing::subscriber::with_default(subscriber, || {
+        ksp_logging_lib::info!(target: TEST_TARGET, domain = "logging", "callsite event");
+        return;
+    });
+    let values = captured_values(&captured);
+    assert_eq!(values.len(), 1);
+    assert_eq!(values[0].target, TEST_TARGET);
+    assert_eq!(values[0].file.as_deref(), std::option::Option::Some(file!()));
+    assert_eq!(values[0].module_path.as_deref(), std::option::Option::Some(module_path!()));
+    assert_eq!(values[0].line, std::option::Option::Some(expected_line));
+    assert!(values[0].is_event);
+    assert!(!values[0].is_span);
+}
+
+#[test]
+fn span_macro_preserves_consumer_callsite() {
+    let captured = std::sync::Arc::new(std::sync::Mutex::new(std::vec::Vec::new()));
+    let enters = std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0));
+    let exits = std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0));
+    let subscriber = CaptureSubscriber::new(captured.clone(), enters, exits);
+    let expected_line = line!() + 2;
+    tracing::subscriber::with_default(subscriber, || {
+        let _span = ksp_logging_lib::trace_span!(target: TEST_TARGET, "callsite_span", component = "test");
+        return;
+    });
+    let values = captured_values(&captured);
+    assert_eq!(values.len(), 1);
+    assert_eq!(values[0].target, TEST_TARGET);
+    assert_eq!(values[0].file.as_deref(), std::option::Option::Some(file!()));
+    assert_eq!(values[0].module_path.as_deref(), std::option::Option::Some(module_path!()));
+    assert_eq!(values[0].line, std::option::Option::Some(expected_line));
+    assert!(!values[0].is_event);
+    assert!(values[0].is_span);
+}
+
+#[test]
+fn async_instrumentation_enters_and_exits_span_during_poll() {
+    let captured = std::sync::Arc::new(std::sync::Mutex::new(std::vec::Vec::new()));
+    let enters = std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0));
+    let exits = std::sync::Arc::new(std::sync::atomic::AtomicU64::new(0));
+    let subscriber = CaptureSubscriber::new(captured, std::sync::Arc::clone(&enters), std::sync::Arc::clone(&exits));
+    tracing::subscriber::with_default(subscriber, || {
+        let span = ksp_logging_lib::trace_span!(target: TEST_TARGET, "async_poll_span", domain = "logging");
+        let future = ksp_logging_lib::instrument(span, std::future::ready(42_u32));
+        let mut future = std::boxed::Box::pin(future);
+        let waker = std::task::Waker::noop();
+        let mut context = std::task::Context::from_waker(waker);
+        let poll = std::future::Future::poll(future.as_mut(), &mut context);
+        assert_eq!(poll, std::task::Poll::Ready(42_u32));
+        return;
+    });
+    assert_eq!(enters.load(std::sync::atomic::Ordering::Relaxed), 1);
+    assert_eq!(exits.load(std::sync::atomic::Ordering::Relaxed), 1);
+}

crates/ksp-logging-lib/tests/public_api.rs

@@ -0,0 +1,52 @@
+// file: crates/ksp-logging-lib/tests/public_api.rs
+// version: 1
+
+const TEST_TARGET: &str = "ksp-logging-lib";
+
+#[test]
+fn public_settings_surface_is_usable() {
+    let settings = ksp_logging_lib::LoggingSettings::new(
+        ksp_logging_lib::LogFilterLevel::Info,
+        ksp_logging_lib::SpanEvents::NewAndClose,
+        std::option::Option::Some(ksp_logging_lib::ConsoleSettings::stdout()),
+        std::option::Option::Some(ksp_logging_lib::FileSettings::new("logs", "ksp", ksp_logging_lib::FileRotation::Daily)),
+    )
+    .with_target_filter(ksp_logging_lib::TargetFilter::new(TEST_TARGET, ksp_logging_lib::LogFilterLevel::Trace));
+    assert!(settings.validate().is_ok());
+    assert_eq!(settings.default_filter(), ksp_logging_lib::LogFilterLevel::Info);
+    assert_eq!(settings.console().map(ksp_logging_lib::ConsoleSettings::output), std::option::Option::Some(ksp_logging_lib::ConsoleOutput::Stdout));
+}
+
+#[test]
+fn public_event_macros_are_usable() {
+    ksp_logging_lib::error!(target: TEST_TARGET, operation = "public_api", "error event");
+    ksp_logging_lib::warn!(target: TEST_TARGET, operation = "public_api", "warn event");
+    ksp_logging_lib::info!(target: TEST_TARGET, operation = "public_api", "info event");
+    ksp_logging_lib::debug!(target: TEST_TARGET, operation = "public_api", "debug event");
+    ksp_logging_lib::trace!(target: TEST_TARGET, operation = "public_api", "trace event");
+}
+
+#[test]
+fn public_span_surface_is_usable_for_sync_and_async() {
+    let span = ksp_logging_lib::trace_span!(target: TEST_TARGET, "public_sync", domain = "logging");
+    let value = span.in_scope(|| -> u32 {
+        return 7;
+    });
+    assert_eq!(value, 7);
+    let async_span = ksp_logging_lib::debug_span!(target: TEST_TARGET, "public_async", component = "test");
+    let future = ksp_logging_lib::instrument(async_span, std::future::ready(9_u32));
+    let mut future = std::boxed::Box::pin(future);
+    let waker = std::task::Waker::noop();
+    let mut context = std::task::Context::from_waker(waker);
+    let poll = std::future::Future::poll(future.as_mut(), &mut context);
+    assert_eq!(poll, std::task::Poll::Ready(9_u32));
+}
+
+#[test]
+fn all_span_levels_are_usable() {
+    let _error = ksp_logging_lib::error_span!(target: TEST_TARGET, "error_span");
+    let _warn = ksp_logging_lib::warn_span!(target: TEST_TARGET, "warn_span");
+    let _info = ksp_logging_lib::info_span!(target: TEST_TARGET, "info_span");
+    let _debug = ksp_logging_lib::debug_span!(target: TEST_TARGET, "debug_span");
+    let _trace = ksp_logging_lib::trace_span!(target: TEST_TARGET, "trace_span");
+}