Add tracing subscriber to enable logging

Motivation:

Added `tracing-subscriber` crate to have one common way of logging with
the Rust driver, as the Rust driver uses `tracing` crate for logging and
cpp-rust driver should allow clients to configure logging by specifying
the max log level and providing callback that should be called on each
event.

Solution:

As logging should be configured globally, the current implementation
creates a custom tracing subscriber with default configuration, which
later can be changed by the user. The global and mutable state of the
logging configuration is initialized in the `lazy_static!` block,
however, it will be evaluated only after the first access in the code.
As, the `cass_session_new()` function most probably is the first
function that the user will call (almost all tests do that, too), the
initialization of logging is chosen to be done in this function.

The CassLogMessage has a field `function` that should always be empty,
as it cannot be properly set, because event metadata does not include
information about it.

Enabled `LoggingTests` tests in github actions.

.github/workflows/build.yml

@@ -43,6 +43,7 @@ jobs:
 :ErrorTests.*\
 :SslNoClusterTests*:SslNoSslOnClusterTests*\
 :SchemaMetadataTest.*KeyspaceMetadata:SchemaMetadataTest.*MetadataIterator\
+:LoggingTests.*\
 :-PreparedTests.Integration_Cassandra_PreparedIDUnchangedDuringReprepare\
 :*5.Integration_Cassandra_*\
 :*19.Integration_Cassandra_*"

.github/workflows/cassandra.yml

@@ -48,6 +48,7 @@ jobs:
 :ErrorTests.*\
 :SslClientAuthenticationTests*:SslNoClusterTests*:SslNoSslOnClusterTests*:SslTests*\
 :SchemaMetadataTest.*KeyspaceMetadata:SchemaMetadataTest.*MetadataIterator\
+:LoggingTests.*\
 :-PreparedTests.Integration_Cassandra_PreparedIDUnchangedDuringReprepare\
 :*5.Integration_Cassandra_*\
 :*19.Integration_Cassandra_*\

scylla-rust-wrapper/Cargo.toml

@@ -22,6 +22,8 @@ num-derive = "0.3"
 libc = "0.2.108"
 openssl-sys = "0.9.75"
 openssl = "0.10.32"
+tracing-subscriber = { version = "0.3.15", features = ["env-filter"] }
+tracing = "0.1.25"
 
 [build-dependencies]
 bindgen = "0.59.1"

scylla-rust-wrapper/build.rs

@@ -90,6 +90,16 @@ fn main() {
         &["CassInet_", "CassInet"],
         &out_path,
     );
+    prepare_cppdriver_data(
+        "cppdriver_log.rs",
+        &[
+            "CassLogLevel_",
+            "CassLogLevel",
+            "CassLogMessage_",
+            "CassLogMessage",
+        ],
+        &out_path,
+    );
     prepare_cppdriver_data(
         "cppdriver_data_query_error.rs",
         &[

scylla-rust-wrapper/src/argconv.rs

@@ -1,4 +1,5 @@
 use crate::types::size_t;
+use std::cmp::min;
 use std::ffi::CStr;
 use std::os::raw::c_char;
 use std::sync::Arc;
@@ -38,6 +39,29 @@ pub unsafe fn ptr_to_cstr_n(ptr: *const c_char, size: size_t) -> Option<&'static
     std::str::from_utf8(std::slice::from_raw_parts(ptr as *const u8, size as usize)).ok()
 }
 
+pub unsafe fn arr_to_cstr<const N: usize>(arr: &[c_char]) -> Option<&'static str> {
+    let null_char = '\0' as c_char;
+    let end_index = arr[..N].iter().position(|c| c == &null_char).unwrap_or(N);
+    ptr_to_cstr_n(arr.as_ptr(), end_index as size_t)
+}
+
+pub fn str_to_arr<const N: usize>(s: &str) -> [c_char; N] {
+    let mut result = ['\0' as c_char; N];
+
+    // Max length must be null-terminated
+    let mut max_len = min(N - 1, s.as_bytes().len());
+
+    while !s.is_char_boundary(max_len) {
+        max_len -= 1;
+    }
+
+    for (i, c) in s.as_bytes().iter().enumerate().take(max_len) {
+        result[i] = *c as c_char;
+    }
+
+    result
+}
+
 pub unsafe fn write_str_to_c(s: &str, c_str: *mut *const c_char, c_strlen: *mut size_t) {
     *c_str = s.as_ptr() as *const c_char;
     *c_strlen = s.len() as u64;

scylla-rust-wrapper/src/cass_log.rs

@@ -0,0 +1,3 @@
+#![allow(non_camel_case_types)]
+
+include!(concat!(env!("OUT_DIR"), "/cppdriver_log.rs"));

scylla-rust-wrapper/src/lib.rs

@@ -1,18 +1,36 @@
 #![allow(clippy::missing_safety_doc)]
+
+use crate::argconv::{arr_to_cstr, ptr_to_cstr, ptr_to_ref, str_to_arr};
+use crate::cass_log::*;
+use crate::logging::cass_log_level_string;
+use crate::logging::Logger;
 use lazy_static::lazy_static;
+use std::fmt::Debug;
+use std::fmt::Write;
+use std::os::raw::{c_char, c_void};
+use std::sync::RwLock;
+use std::time::{SystemTime, UNIX_EPOCH};
 use tokio::runtime::Runtime;
+use tracing::dispatcher::DefaultGuard;
+use tracing::field::Field;
+use tracing::Level;
+use tracing_subscriber::layer::Context;
+use tracing_subscriber::prelude::*;
+use tracing_subscriber::Layer;
 
 #[macro_use]
 mod binding;
 mod argconv;
 pub mod batch;
 pub mod cass_error;
+pub mod cass_log;
 pub mod cass_types;
 pub mod cluster;
 pub mod collection;
 mod external;
 pub mod future;
 pub mod inet;
+mod logging;
 pub mod prepared;
 pub mod query_error;
 pub mod query_result;
@@ -26,8 +44,104 @@ pub mod types;
 pub mod user_type;
 pub mod uuid;
 
+pub const CASS_LOG_MAX_MESSAGE_SIZE: usize = 1024;
+
+unsafe extern "C" fn stderr_log_callback(message: *const CassLogMessage, _data: *mut c_void) {
+    let message = ptr_to_ref(message);
+
+    eprintln!(
+        "{} [{}] ({}:{}) {}",
+        message.time_ms as u64,
+        ptr_to_cstr(cass_log_level_string(message.severity)).unwrap(),
+        ptr_to_cstr(message.file).unwrap(),
+        message.line,
+        arr_to_cstr::<{ CASS_LOG_MAX_MESSAGE_SIZE }>(&message.message).unwrap(),
+    )
+}
+
+pub struct CustomLayer;
+
+pub struct PrintlnVisitor {
+    log_message: String,
+}
+
+// Collects all fields and values in a single log event into a single String
+// to set into CassLogMessage::message.
+impl tracing::field::Visit for PrintlnVisitor {
+    fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
+        if self.log_message.is_empty() {
+            write!(self.log_message, "{}: {:?}", field, value).unwrap();
+        } else {
+            write!(self.log_message, ", {}: {:?}", field, value).unwrap();
+        }
+    }
+}
+
+impl<S> Layer<S> for CustomLayer
+where
+    S: tracing::Subscriber,
+{
+    fn on_event(&self, event: &tracing::Event<'_>, _ctx: Context<'_, S>) {
+        let start = SystemTime::now();
+        let since_the_epoch = start
+            .duration_since(UNIX_EPOCH)
+            .expect("Time went backwards");
+        let log_time_ms = since_the_epoch.as_millis() as u64;
+
+        let message = "";
+        let mut target = event.metadata().target().to_string();
+        target.push('\0');
+
+        let mut log_message = CassLogMessage {
+            time_ms: log_time_ms,
+            severity: (*event.metadata().level()).into(),
+            file: target.as_ptr() as *const c_char,
+            line: event.metadata().line().unwrap_or(0) as i32,
+            function: "\0".as_ptr() as *const c_char, // ignored, as cannot be fetched from event metadata
+            message: str_to_arr(message),
+        };
+
+        let mut visitor = PrintlnVisitor {
+            log_message: message.to_string(),
+        };
+        event.record(&mut visitor);
+
+        visitor.log_message.push('\0');
+        log_message.message =
+            str_to_arr::<{ CASS_LOG_MAX_MESSAGE_SIZE }>(visitor.log_message.as_str());
+
+        let logger = LOGGER.read().unwrap();
+
+        if let Some(log_cb) = logger.cb {
+            unsafe {
+                log_cb(&log_message as *const CassLogMessage, logger.data);
+            }
+        }
+    }
+}
+
+// Sets tracing subscriber with specified `level` and returns `DefaultGuard`.
+// The subscriber is valid for the duration of the lifetime of the returned `DefaultGuard`.
+pub fn set_tracing_subscriber_with_level(level: Level) -> DefaultGuard {
+    tracing::subscriber::set_default(
+        tracing_subscriber::registry()
+            .with(
+                tracing_subscriber::EnvFilter::from_default_env()
+                    .add_directive(level.to_owned().into()),
+            )
+            .with(CustomLayer),
+    )
+}
+
 lazy_static! {
     pub static ref RUNTIME: Runtime = Runtime::new().unwrap();
+    pub static ref LOGGER: RwLock<Logger> = RwLock::new(Logger {
+        cb: Some(stderr_log_callback),
+        data: std::ptr::null_mut(),
+    });
+    pub static ref LOG: RwLock<Option<DefaultGuard>> = RwLock::new(Some(
+        set_tracing_subscriber_with_level(tracing::Level::WARN)
+    ));
 }
 
 // To send a Rust object to C: