diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 821eaff7..aaa2bf4c 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -44,6 +44,7 @@ jobs: :TracingTests.*\ :ByNameTests.*\ :CompressionTests.*\ +:LoggingTests.*\ :-PreparedTests.Integration_Cassandra_PreparedIDUnchangedDuringReprepare\ :*5.Integration_Cassandra_*\ :*19.Integration_Cassandra_*" diff --git a/.github/workflows/cassandra.yml b/.github/workflows/cassandra.yml index 7f9d58eb..65c62df2 100644 --- a/.github/workflows/cassandra.yml +++ b/.github/workflows/cassandra.yml @@ -49,6 +49,7 @@ jobs: :TracingTests.*\ :ByNameTests.*\ :CompressionTests.*\ +:LoggingTests.*\ :-PreparedTests.Integration_Cassandra_PreparedIDUnchangedDuringReprepare\ :*5.Integration_Cassandra_*\ :*19.Integration_Cassandra_*\ diff --git a/scylla-rust-wrapper/Cargo.lock b/scylla-rust-wrapper/Cargo.lock index a5456a49..409fcd1b 100644 --- a/scylla-rust-wrapper/Cargo.lock +++ b/scylla-rust-wrapper/Cargo.lock @@ -474,6 +474,15 @@ dependencies = [ "winreg", ] +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", +] + [[package]] name = "memchr" version = "2.5.0" @@ -756,6 +765,15 @@ dependencies = [ "regex-syntax", ] +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.27" @@ -829,6 +847,8 @@ dependencies = [ "rand", "scylla", "tokio", + "tracing", + "tracing-subscriber", "uuid", ] @@ -866,6 +886,15 @@ version = "1.0.140" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "fc855a42c7967b7c369eb5860f7164ef1f6f81c20c7cc1141f2a604e18723b03" +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.1.0" @@ -992,6 +1021,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" +dependencies = [ + "once_cell", +] + [[package]] name = "time" version = "0.1.44" @@ -1086,6 +1124,36 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7b7358be39f2f274f322d2aaed611acc57f382e8eb1e5b48cb9ae30933495ce7" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "60db860322da191b40952ad9affe65ea23e7dd6a5c442c2c42865810c6ab8e6b" +dependencies = [ + "ansi_term", + "matchers", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -1122,6 +1190,12 @@ version = "1.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "dd6469f4314d5f1ffec476e05f17cc9a78bc7a27a6a857842170bdf8d6f98d2f" +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vcpkg" version = "0.2.15" diff --git a/scylla-rust-wrapper/Cargo.toml b/scylla-rust-wrapper/Cargo.toml index 2e1eda87..17b2b73e 100644 --- a/scylla-rust-wrapper/Cargo.toml +++ b/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" diff --git a/scylla-rust-wrapper/build.rs b/scylla-rust-wrapper/build.rs index e6451133..c3826085 100644 --- a/scylla-rust-wrapper/build.rs +++ b/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", &[ diff --git a/scylla-rust-wrapper/src/argconv.rs b/scylla-rust-wrapper/src/argconv.rs index 4dadd556..feab9af2 100644 --- a/scylla-rust-wrapper/src/argconv.rs +++ b/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(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(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; diff --git a/scylla-rust-wrapper/src/lib.rs b/scylla-rust-wrapper/src/lib.rs index e7da2e46..eba46b73 100644 --- a/scylla-rust-wrapper/src/lib.rs +++ b/scylla-rust-wrapper/src/lib.rs @@ -1,6 +1,12 @@ #![allow(clippy::missing_safety_doc)] + +use crate::logging::set_tracing_subscriber_with_level; +use crate::logging::stderr_log_callback; +use crate::logging::Logger; use lazy_static::lazy_static; +use std::sync::RwLock; use tokio::runtime::Runtime; +use tracing::dispatcher::DefaultGuard; #[macro_use] mod binding; @@ -13,6 +19,7 @@ pub mod collection; mod external; pub mod future; pub mod inet; +mod logging; pub mod prepared; pub mod query_error; pub mod query_result; @@ -28,6 +35,13 @@ pub mod uuid; lazy_static! { pub static ref RUNTIME: Runtime = Runtime::new().unwrap(); + pub static ref LOGGER: RwLock = RwLock::new(Logger { + cb: Some(stderr_log_callback), + data: std::ptr::null_mut(), + }); + pub static ref LOG: RwLock> = RwLock::new(Some( + set_tracing_subscriber_with_level(tracing::Level::WARN) + )); } // To send a Rust object to C: diff --git a/scylla-rust-wrapper/src/logging.rs b/scylla-rust-wrapper/src/logging.rs new file mode 100644 index 00000000..05b80a17 --- /dev/null +++ b/scylla-rust-wrapper/src/logging.rs @@ -0,0 +1,228 @@ +mod cass_log { + #![allow(non_camel_case_types)] + include!(concat!(env!("OUT_DIR"), "/cppdriver_log.rs")); +} +use crate::argconv::{arr_to_cstr, ptr_to_cstr, ptr_to_ref, str_to_arr}; +use crate::types::size_t; +use crate::LOG; +use crate::LOGGER; +use cass_log::*; +use std::convert::TryFrom; +use std::fmt::Debug; +use std::fmt::Write; +use std::os::raw::{c_char, c_void}; +use std::time::{SystemTime, UNIX_EPOCH}; +use tracing::debug; +use tracing::dispatcher::DefaultGuard; +use tracing::field::Field; +use tracing::Level; +use tracing_subscriber::layer::Context; +use tracing_subscriber::prelude::*; +use tracing_subscriber::Layer; + +pub type CassLogCallback = + Option; + +unsafe extern "C" fn noop_log_callback(_message: *const CassLogMessage, _data: *mut c_void) {} + +pub struct Logger { + pub cb: CassLogCallback, + pub data: *mut c_void, +} + +// The field `data` in the struct `Logger` is neither Send nor Sync. +// It can be mutated only in the user-provided `CassLogCallback`, so it is safe +// to implement Sync and Send manually for the `Logger` struct. +unsafe impl Sync for Logger {} +unsafe impl Send for Logger {} + +impl From for CassLogLevel { + fn from(level: Level) -> Self { + match level { + Level::TRACE => CassLogLevel::CASS_LOG_TRACE, + Level::DEBUG => CassLogLevel::CASS_LOG_DEBUG, + Level::INFO => CassLogLevel::CASS_LOG_INFO, + Level::WARN => CassLogLevel::CASS_LOG_WARN, + Level::ERROR => CassLogLevel::CASS_LOG_ERROR, + } + } +} + +impl TryFrom for Level { + type Error = String; + + fn try_from(log_level: CassLogLevel) -> Result { + let level = match log_level { + CassLogLevel::CASS_LOG_TRACE => Level::TRACE, + CassLogLevel::CASS_LOG_DEBUG => Level::DEBUG, + CassLogLevel::CASS_LOG_INFO => Level::INFO, + CassLogLevel::CASS_LOG_WARN => Level::WARN, + CassLogLevel::CASS_LOG_ERROR => Level::ERROR, + CassLogLevel::CASS_LOG_CRITICAL => Level::ERROR, + _ => return Err("Error while converting CassLogLevel to Level".to_string()), + }; + + Ok(level) + } +} + +pub const CASS_LOG_MAX_MESSAGE_SIZE: usize = 1024; + +pub 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 Layer 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("Current time is before UNIX_EPOCH"); + 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), + ) +} + +pub fn init_logging() { + let _log = (*LOG.read().unwrap()).as_ref().unwrap(); +} + +#[no_mangle] +pub unsafe extern "C" fn cass_log_set_level(log_level: CassLogLevel) { + if log_level == CassLogLevel::CASS_LOG_DISABLED { + debug!("Logging is disabled!"); + *LOG.write().unwrap() = None; + return; + } + + let level = Level::try_from(log_level).unwrap_or(Level::WARN); + + // Drops the `DefaultGuard` of the current tracing subscriber making it invalid. + // Setting LOG to None is vital, otherwise, the new tracing subscriber created in + // `set_tracing_subscriber_with_level` will be ignored as the previous `DefaultGuard` is + // still alive. + *LOG.write().unwrap() = None; + // Sets the tracing subscriber with new log level. + *LOG.write().unwrap() = Some(set_tracing_subscriber_with_level(level)); + + debug!("Log level is set to {}", level); +} + +#[no_mangle] +pub unsafe extern "C" fn cass_log_level_string(log_level: CassLogLevel) -> *const c_char { + let log_level_str = match log_level { + CassLogLevel::CASS_LOG_TRACE => "TRACE\0", + CassLogLevel::CASS_LOG_DEBUG => "DEBUG\0", + CassLogLevel::CASS_LOG_INFO => "INFO\0", + CassLogLevel::CASS_LOG_WARN => "WARN\0", + CassLogLevel::CASS_LOG_ERROR => "ERROR\0", + CassLogLevel::CASS_LOG_CRITICAL => "CRITICAL\0", + CassLogLevel::CASS_LOG_DISABLED => "DISABLED\0", + _ => "\0", + }; + + log_level_str.as_ptr() as *const c_char +} + +#[no_mangle] +pub unsafe extern "C" fn cass_log_set_callback(callback: CassLogCallback, data: *mut c_void) { + let logger = Logger { + cb: Some(callback.unwrap_or(noop_log_callback)), + data, + }; + + *LOGGER.write().unwrap() = logger; +} + +#[no_mangle] +pub unsafe extern "C" fn cass_log_get_callback_and_data( + callback_out: *mut CassLogCallback, + data_out: *mut *const c_void, +) { + let logger = LOGGER.read().unwrap(); + + *callback_out = logger.cb; + *data_out = logger.data; +} + +#[no_mangle] +pub unsafe extern "C" fn cass_log_cleanup() { + // Deprecated +} + +#[no_mangle] +pub unsafe extern "C" fn cass_log_set_queue_size(_queue_size: size_t) { + // Deprecated +} diff --git a/scylla-rust-wrapper/src/session.rs b/scylla-rust-wrapper/src/session.rs index 92e79bde..b488ee98 100644 --- a/scylla-rust-wrapper/src/session.rs +++ b/scylla-rust-wrapper/src/session.rs @@ -7,6 +7,7 @@ use crate::cass_types::{ use crate::cluster::build_session_builder; use crate::cluster::CassCluster; use crate::future::{CassFuture, CassResultValue}; +use crate::logging::init_logging; use crate::query_result::Value::{CollectionValue, RegularValue}; use crate::query_result::{ CassResult, CassResultData, CassResult_, CassRow, CassValue, Collection, Value, @@ -65,6 +66,8 @@ pub struct CassSchemaMeta { #[no_mangle] pub unsafe extern "C" fn cass_session_new() -> *const CassSession { + init_logging(); + let session: CassSession_ = Arc::new(RwLock::new(None)); Arc::into_raw(session) } diff --git a/src/logger.cpp b/src/logger.cpp index 2ae77650..36dd5372 100644 --- a/src/logger.cpp +++ b/src/logger.cpp @@ -18,28 +18,6 @@ using namespace datastax::internal; -extern "C" { - -void cass_log_cleanup() { - // Deprecated -} - -void cass_log_set_level(CassLogLevel log_level) { Logger::set_log_level(log_level); } - -void cass_log_set_callback(CassLogCallback callback, void* data) { - Logger::set_callback(callback, data); -} - -void cass_log_get_callback_and_data(CassLogCallback* callback_out, void** data_out) { - Logger::get_callback_and_data(callback_out, data_out); -} - -void cass_log_set_queue_size(size_t queue_size) { - // Deprecated -} - -} // extern "C" - namespace datastax { namespace internal { namespace core { void stderr_log_callback(const CassLogMessage* message, void* data) { diff --git a/src/testing_unimplemented.cpp b/src/testing_unimplemented.cpp index 5805f8d7..68ca43e6 100644 --- a/src/testing_unimplemented.cpp +++ b/src/testing_unimplemented.cpp @@ -386,10 +386,6 @@ cass_keyspace_meta_materialized_view_by_name(const CassKeyspaceMeta* keyspace_me const char* view){ throw std::runtime_error("UNIMPLEMENTED cass_keyspace_meta_materialized_view_by_name\n"); } -CASS_EXPORT const char* -cass_log_level_string(CassLogLevel log_level){ - throw std::runtime_error("UNIMPLEMENTED cass_log_level_string\n"); -} CASS_EXPORT const CassTableMeta* cass_materialized_view_meta_base_table(const CassMaterializedViewMeta* view_meta){ throw std::runtime_error("UNIMPLEMENTED cass_materialized_view_meta_base_table\n"); diff --git a/tests/src/integration/tests/test_logging.cpp b/tests/src/integration/tests/test_logging.cpp index 8579c36a..4f887471 100644 --- a/tests/src/integration/tests/test_logging.cpp +++ b/tests/src/integration/tests/test_logging.cpp @@ -34,6 +34,8 @@ CASSANDRA_INTEGRATION_TEST_F(LoggingTests, Callback) { bool is_triggered = false; cass_log_set_callback(LoggingTests::log, &is_triggered); + // This will emit a log event in on debug level which will trigger the `log` callback. + cass_log_set_level(CASS_LOG_DEBUG); default_cluster().connect("", false); EXPECT_TRUE(is_triggered); } \ No newline at end of file