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 C++ driver does not ban the user to call `cass_log_*` functions
after a function call that might log, so the implementation keeps the
same behavior. But it warns the user after the logging initialization
that `cass_log_*` functions should not be called, as the documentation
of the C++ driver suggests.

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

@@ -40,6 +40,7 @@ jobs:
 :PreparedTests.*\
 :CassandraTypes/CassandraTypesTests/*.Integration_Cassandra_*\
 :BatchSingleNodeClusterTests*:BatchCounterSingleNodeClusterTests*:BatchCounterThreeNodeClusterTests*\
+:LoggingTests.*\
 :-PreparedTests.Integration_Cassandra_PreparedIDUnchangedDuringReprepare\
 :*5.Integration_Cassandra_*\
 :*19.Integration_Cassandra_*\

.github/workflows/cassandra.yml

@@ -45,6 +45,7 @@ jobs:
 :BasicsTests.*\
 :PreparedTests.*\
 :CassandraTypes/CassandraTypesTests/*.Integration_Cassandra_*\
+:LoggingTests.*\
 :-PreparedTests.Integration_Cassandra_PreparedIDUnchangedDuringReprepare\
 :*5.Integration_Cassandra_*\
 :*19.Integration_Cassandra_*\

scylla-rust-wrapper/Cargo.toml

@@ -20,6 +20,8 @@ rand = "0.8.4"
 num-traits = "0.2"
 num-derive = "0.3"
 libc = "0.2.108"
+tracing-subscriber = { version = "0.3.15", features = ["env-filter"] }
+tracing = "0.1.25"
 
 [build-dependencies]
 bindgen = "0.59.1"

scylla-rust-wrapper/build.rs

@@ -85,6 +85,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

@@ -38,6 +38,32 @@ 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; N]) -> String {
+    let mut vec = ['\0'; N];
+    let mut i = 0;
+
+    while i < N {
+        if arr[i] != '\0' as c_char {
+            vec[i] = arr[i] as u8 as char;
+        }
+        i += 1;
+    }
+
+    vec.iter().collect::<String>()
+}
+
+pub fn str_to_arr<const N: usize>(s: &str) -> [c_char; N] {
+    let mut result = ['\0' as c_char; N];
+
+    for (i, c) in s.chars().enumerate() {
+        if i < N {
+            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 i8;
     *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,34 @@
 #![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::os::raw::{c_char, c_void};
+use std::sync::RwLock;
+use std::time::{SystemTime, UNIX_EPOCH};
 use tokio::runtime::Runtime;
+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;
@@ -25,8 +41,96 @@ 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(message.message).trim_end_matches('\0'),
+    )
+}
+
+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) {
+        self.log_message = format!("{}{}: {:?}, ", self.log_message, field, value);
+    }
+}
+
+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_secs() * 1000 + since_the_epoch.subsec_nanos() as u64 / 1_000_000;
+
+        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();
+
+        match logger.cb {
+            Some(log_cb) => unsafe {
+                log_cb(&log_message as *const CassLogMessage, logger.data);
+            },
+            None => {}
+        }
+    }
+}
+
 lazy_static! {
     pub static ref RUNTIME: Runtime = Runtime::new().unwrap();
+    pub static ref LOG_LEVEL: RwLock<Level> = RwLock::new(tracing::Level::WARN);
+    pub static ref LOGGER: RwLock<Logger> = RwLock::new(Logger {
+        cb: Some(stderr_log_callback),
+        data: std::ptr::null_mut(),
+    });
+    pub static ref LOG: () = tracing::subscriber::set_global_default(
+        tracing_subscriber::registry()
+            .with(
+                tracing_subscriber::EnvFilter::from_default_env()
+                    .add_directive(LOG_LEVEL.read().unwrap().to_owned().into())
+            )
+            .with(CustomLayer)
+    )
+    .expect("Failed to set global default subscriber");
 }
 
 // To send a Rust object to C: