diff --git a/Cargo.toml b/Cargo.toml index b7c5c3ee6..553844d4d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -18,6 +18,8 @@ regex = "1.11.1" thiserror = "2.0.12" num-bigint = "0.4.6" openssl = "0.10.70" +tracing = "0.1" +tracing-subscriber = { version = "0.3", features = ["registry"] } [lints.rust] unsafe-op-in-unsafe-fn = "warn" diff --git a/docs/src/SUMMARY.md b/docs/src/SUMMARY.md index 9e13f6bcc..7e63f0067 100644 --- a/docs/src/SUMMARY.md +++ b/docs/src/SUMMARY.md @@ -4,6 +4,7 @@ - [Fetching large result sets](./paging.md) - [Batch statements](./batch.md) - [Shutdown](./shutdown.md) +- [Logging](./logging.md) - [Migration guide](./migration_guide.md) - [Load balancing](./load_balancing.md) - [Unprepared statement parameters](./unprepared_statements.md) diff --git a/docs/src/logging.md b/docs/src/logging.md new file mode 100644 index 000000000..5f177475b --- /dev/null +++ b/docs/src/logging.md @@ -0,0 +1,119 @@ +# Logging + +The driver uses [events](https://nodejs.org/api/events.html) to expose logging +information, keeping it decoupled from any specific logging framework. + +The `Client` class inherits from +[EventEmitter](https://nodejs.org/api/events.html#events_class_eventemitter) +and emits `'log'` events: + +```js +client.on('log', (level, target, message, furtherInfo) => { + console.log(`${level} - ${target}: ${message}`); +}); +``` + +## Enabling logging + +Logging is **disabled by default**. To enable it, set the `logLevel` client +option to the minimum severity you want to receive: + +```js +const { Client, types } = require('scylladb-driver-alpha'); + +const client = new Client({ + contactPoints: ['127.0.0.1'], + logLevel: types.logLevels.info, +}); +``` + +The callback is registered when `connect()` is called and unregistered on +`shutdown()`. No log events are emitted before the client connects. + +## Log levels + +Log levels are exposed through the `types.logLevels` enum: + +| Enum variant | Raw value | Description | +| ------------------- | ----------- | ---------------------------------------------------- | +| `logLevels.trace` | `'trace'` | Finest-grained diagnostic information (TRACE events) | +| `logLevels.debug` | `'debug'` | Fine-grained diagnostic information (DEBUG events) | +| `logLevels.info` | `'info'` | High-level informational messages | +| `logLevels.warning` | `'warning'` | Potentially harmful situations | +| `logLevels.error` | `'error'` | Error conditions | +| `logLevels.off` | `'off'` | Disables logging entirely (default) | + +The `logLevel` option acts as a **filter**: only events at or above the +configured severity are delivered to the listener. Filtering happens on the +native side, before crossing the FFI boundary, so suppressed events have +virtually zero overhead. + +| `logLevel` value | Events delivered | +| ------------------- | -------------------------- | +| `logLevels.off` | None (default) | +| `logLevels.trace` | All (TRACE and above) | +| `logLevels.debug` | DEBUG and above | +| `logLevels.info` | INFO and above | +| `logLevels.warning` | WARN and above | +| `logLevels.error` | ERROR only | + +The `trace` level is only suitable for debugging and is usually very +noisy. We recommend gathering events from `info` and above in production +environments. + +## Event arguments + +Each `'log'` event delivers four arguments: + +| Argument | Type | Description | +| ------------- | -------- | ----------------------------------------------------------------------------------------------------------------------------------------------- | +| `level` | `string` | One of the level strings from the table above. | +| `target` | `string` | Identifies the source of the event. Either a class name (e.g. `"Client"`) or an internal module path (e.g. `"scylla::network::connection"`). | +| `message` | `string` | Human-readable description of the event. | +| `furtherInfo` | `string` | Additional structured context. Some events include key=value pairs from tracing spans (e.g. `peer_addr=10.0.0.1:9042`). May be an empty string. | + +### Event sources + +Log events originate from two layers: + +- **Internal driver** — connection, query routing, and protocol events from + the driver internals. These carry module paths in `target` + (e.g. `"scylla::network::connection"`). +- **Client** — high-level lifecycle events emitted by the `Client` class + (e.g. *"Connecting to cluster"*). These carry `"Client"` as the `target`. + +Both kinds arrive through the same `'log'` event, so a single listener +receives everything. + +## Multiple clients + +Each `Client` registers its own logging callback independently. Multiple +clients can coexist, each with its own `logLevel`. + +> **WARNING:** all clients share the same underlying Rust tracing subscriber. +> This means every client receives log events from the entire process — +> including events triggered by other `Client` instances. Keep this in mind +> when filtering or routing events. + +## Example + +```js +const { Client, types } = require('scylladb-driver-alpha'); + +const client = new Client({ + contactPoints: ['10.0.1.101', '10.0.1.102'], + logLevel: types.logLevels.info, +}); + +client.on('log', (level, target, message, furtherInfo) => { + const extra = furtherInfo ? ` (${furtherInfo})` : ''; + console.log(`[${level}] ${target}: ${message}${extra}`); +}); + +await client.connect(); +// [info] Client: Connecting to cluster using 'ScyllaDB JavaScript Driver' version ... +// [info] scylla::cluster::worker: Node added to cluster: ... +// ... + +await client.shutdown(); +``` diff --git a/docs/src/migration_guide.md b/docs/src/migration_guide.md index 7e0d1c8e9..2c68eaa1c 100644 --- a/docs/src/migration_guide.md +++ b/docs/src/migration_guide.md @@ -154,3 +154,47 @@ The `cassandra-driver` driver had some undocumented assumptions about the order when using `client.hosts.keys()` - see issue [#282](https://github.com/scylladb/nodejs-rs-driver/issues/282) (they were checked in the driver tests). Those assumptions no longer hold true, the hosts returned from `client.hosts.keys()` may be in a random order, that may vary from run to run. + +## Logging + +See the [Logging](./logging.md) page for the full documentation of the new logging system. +Below are the key differences from the `cassandra-driver`. + +### Logging is off by default + +The `cassandra-driver` always emitted `'log'` events. In this driver, logging +is **disabled by default** and must be explicitly enabled via the `logLevel` +client option. See [Enabling logging](./logging.md#enabling-logging). + +### `verbose` level removed + +The old `verbose` level has been **removed** and replaced by two separate +levels — `trace` and `debug` — giving finer control over diagnostic output. + +See [Log levels](./logging.md#log-levels) for the full list. + +### `target` replaces `className` + +The `cassandra-driver` passed a JS class name (e.g. `"Client"`, +`"Connection"`) as the second argument of the `'log'` event. This driver +passes a `target` string instead: + +- For Rust driver events it is a Rust module path + (e.g. `scylla::network::connection`). +- For JS-side events it is `"Client"`. + +See [Event arguments](./logging.md#event-arguments) for details. + +### Event interface preserved + +The `'log'` event signature is unchanged: + +```js +client.on('log', (level, target, message, furtherInfo) => { ... }); +``` + +### Cross-client event visibility + +All clients share the same underlying Rust tracing subscriber. Each client +receives log events from the entire process, including those triggered by +other `Client` instances. diff --git a/lib/client-options.js b/lib/client-options.js index 6821116b7..4c40ef16f 100644 --- a/lib/client-options.js +++ b/lib/client-options.js @@ -223,6 +223,18 @@ const { ExecutionProfile } = require("./execution-profile.js"); * to represent CQL varint data type. Defaults to true. * * Note, that using Integer as Varint (`useBigIntAsVarint == false`) is deprecated. + * @property {String} [logLevel] The minimum severity of log events emitted by the driver. + * + * **WARNING:** While you can configure different log levels for different clients, each client will receive + * log messages from all clients. + * + * Valid values are defined in the {@link module:types~logLevels} enum (introduced in this driver). + * We recommend using the enum values (e.g. `types.logLevels.info`) rather than raw strings. + * + * When set to a value other than `'off'`, additional driver log messages (connection events, query routing, + * retries, etc.) will be emitted as `'log'` events on the {@link Client} instance. + * + * Default: {@link module:types~logLevels.off}. * @property {Array.} [profiles] The array of [execution profiles]{@link ExecutionProfile}. * @property {Function} [promiseFactory] Function to be used to create a `Promise` from a * callback-style function. @@ -469,6 +481,7 @@ function defaultOptions() { useBigIntAsLong: true, useBigIntAsVarint: true, }, + logLevel: types.logLevels.off, }; } @@ -544,6 +557,8 @@ function extend(baseOptions, userOptions) { validateEncodingOptions(options.encoding); + validateLogLevel(options.logLevel); + if (options.profiles && !Array.isArray(options.profiles)) { throw new TypeError( "profiles must be an Array of ExecutionProfile instances", @@ -712,6 +727,21 @@ function validateEncodingOptions(encodingOptions) { } } +const validLogLevels = Object.values(types.logLevels); + +/** + * Validates the logLevel option. + * @param {string} logLevel + * @private + */ +function validateLogLevel(logLevel) { + if (typeof logLevel !== "string" || !validLogLevels.includes(logLevel)) { + throw new TypeError( + `logLevel must be one of ${validLogLevels.map((l) => `'${l}'`).join(", ")}`, + ); + } +} + function validateApplicationInfo(options) { function validateString(key) { const str = options[key]; diff --git a/lib/client.js b/lib/client.js index dfff6fc8c..b2fda05af 100644 --- a/lib/client.js +++ b/lib/client.js @@ -56,6 +56,7 @@ class Client extends events.EventEmitter { */ rustClient; #encoder; + #loggingId; /** * Creates a new instance of {@link Client}. * @param {clientOptions.ClientOptions} options The options for this instance. @@ -229,6 +230,19 @@ class Client extends events.EventEmitter { ), ); + if ( + this.options.logLevel && + this.options.logLevel !== types.logLevels.off + ) { + const emitter = this.emit.bind(this); + this.#loggingId = rust.setupLogging( + (level, target, message, furtherInfo) => { + emitter("log", level, target, message, furtherInfo); + }, + this.options.logLevel, + ); + } + try { this.rustClient = await rust.SessionWrapper.createSession( this.rustOptions, @@ -237,6 +251,10 @@ class Client extends events.EventEmitter { // We should close the pools (if any) and reset the state to allow successive calls to connect() this.connected = false; this.connecting = false; + if (this.#loggingId !== undefined) { + rust.removeLogging(this.#loggingId); + this.#loggingId = undefined; + } this.emit("connected", err); throw err; } @@ -819,6 +837,11 @@ class Client extends events.EventEmitter { "Drop this client to close the connection to the database.", ); + if (this.#loggingId !== undefined) { + rust.removeLogging(this.#loggingId); + this.#loggingId = undefined; + } + if (!this.connected) { // not initialized return; diff --git a/lib/types/index.d.ts b/lib/types/index.d.ts index 2a822e923..d1f5d802b 100644 --- a/lib/types/index.d.ts +++ b/lib/types/index.d.ts @@ -54,6 +54,15 @@ export enum distance { ignored, } +export enum logLevels { + trace = "trace", + debug = "debug", + info = "info", + warning = "warning", + error = "error", + off = "off", +} + export enum responseErrorCodes { serverError = 0x0000, protocolError = 0x000a, diff --git a/lib/types/index.js b/lib/types/index.js index a9ca2d823..a0ccd5149 100644 --- a/lib/types/index.js +++ b/lib/types/index.js @@ -208,6 +208,25 @@ const distance = { ignored: 2, }; +/** + * Log level values used for the `logLevel` client option and emitted in `'log'` events. + * @type {Object} + * @property {String} trace Finest-grained diagnostic information (TRACE level events). + * @property {String} debug Fine-grained diagnostic information useful during development (DEBUG level events). + * @property {String} info High-level informational messages. + * @property {String} warning Potentially harmful situations. + * @property {String} error Error conditions. + * @property {String} off Disables internal driver log forwarding (default). + */ +const logLevels = { + trace: "trace", + debug: "debug", + info: "info", + warning: "warning", + error: "error", + off: "off", +}; + /** * Server error codes returned by Cassandra * @type {Object} @@ -491,6 +510,7 @@ exports.consistencyToString = consistencyToString; exports.dataTypes = dataTypes; exports.getDataTypeNameByCode = getDataTypeNameByCode; exports.distance = distance; +exports.logLevels = logLevels; exports.protocolVersion = protocolVersion; exports.responseErrorCodes = responseErrorCodes; exports.BigDecimal = require("./big-decimal"); diff --git a/lib/utils.js b/lib/utils.js index 4aee64112..8fbc8de2d 100644 --- a/lib/utils.js +++ b/lib/utils.js @@ -20,6 +20,16 @@ const emptyObject = Object.freeze({}); const emptyArray = Object.freeze([]); +/** @private */ +const logLevelSeverity = { + trace: 0, + debug: 1, + info: 2, + warning: 3, + error: 4, + off: 5, +}; + function noop() {} /** @@ -57,19 +67,27 @@ function fixStack(stackTrace, error) { } /** - * Uses the logEmitter to emit log events + * Uses the logEmitter to emit log events. + * Respects the `logLevel` option — events below the configured severity are suppressed. * @param {String} type * @param {String} info * @param [furtherInfo] */ function log(type, info, furtherInfo, options) { + const effectiveOptions = options || this.options; + if (!this.logEmitter) { - const effectiveOptions = options || this.options; if (!effectiveOptions || !effectiveOptions.logEmitter) { throw new Error("Log emitter not defined"); } this.logEmitter = effectiveOptions.logEmitter; } + + const logLevel = effectiveOptions && effectiveOptions.logLevel; + if (logLevel && logLevelSeverity[type] < logLevelSeverity[logLevel]) { + return; + } + this.logEmitter( "log", type, diff --git a/main.d.ts b/main.d.ts index a11aac74b..0db5e50b9 100644 --- a/main.d.ts +++ b/main.d.ts @@ -240,6 +240,7 @@ export interface ClientOptions { tcpNoDelay?: boolean; }; sslOptions?: SslOptions; + logLevel?: types.logLevels; id?: Uuid; applicationName?: string; applicationVersion?: string; diff --git a/src/lib.rs b/src/lib.rs index b178c3f8f..31ed428b5 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -3,6 +3,7 @@ extern crate napi_derive; // Link other files pub mod errors; +pub mod logging; pub mod metadata; pub mod options; pub mod paging; diff --git a/src/logging.rs b/src/logging.rs new file mode 100644 index 000000000..3d1fae54a --- /dev/null +++ b/src/logging.rs @@ -0,0 +1,209 @@ +use std::fmt; +use std::sync::atomic::{AtomicU32, Ordering}; +use std::sync::{OnceLock, RwLock}; + +use napi::bindgen_prelude::FnArgs; +use napi::threadsafe_function::{ThreadsafeFunction, ThreadsafeFunctionCallMode}; +use tracing::Level; +use tracing::field::{Field, Visit}; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::{Layer, Registry}; + +/// Shorthand for the NAPI callback type. +/// +/// Generic parameters: `CalleeHandled = false`, `Weak = true` so that the +/// callback does not prevent the Node.js event-loop from exiting. +type LogCallback = ThreadsafeFunction< + /* T: */ FnArgs<(String, String, String, String)>, + /* Return: */ (), + /* CallJsBackArgs: */ FnArgs<(String, String, String, String)>, + /* ErrorStatus: */ napi::Status, + /* CalleeHandled: */ false, + /* Weak: */ true, +>; + +/// A callback registered by one client, together with the minimum severity +/// level it is interested in. +struct RegisteredCallback { + id: u32, + callback: LogCallback, + min_level: Level, +} + +/// Monotonically increasing id counter for registered callbacks. +static NEXT_ID: AtomicU32 = AtomicU32::new(0); + +/// Registry of all currently-active per-client callbacks. +/// Initialized (and the global subscriber installed) on the first call to +/// `setup_logging`. +static CALLBACKS: OnceLock>> = OnceLock::new(); + +/// Return the callback registry, lazily installing the global tracing +/// subscriber the very first time this is called. +fn get_or_init_callbacks() -> &'static RwLock> { + CALLBACKS.get_or_init(|| { + let subscriber = Registry::default().with(JsForwardingLayer); + tracing::subscriber::set_global_default(subscriber).unwrap_or_else(|e| { + // This will fail only of there is already a global subscriber, which we should prevent from happening. + panic!("This is likely due to a bug in the driver: failed to initialized logger. {e}"); + }); + RwLock::new(Vec::new()) + }) +} + +/// Maps a Rust `tracing::Level` to the JS log-level strings. +fn level_to_js(level: &Level) -> &'static str { + match *level { + Level::TRACE => "trace", + Level::DEBUG => "debug", + Level::INFO => "info", + Level::WARN => "warning", + Level::ERROR => "error", + } +} + +/// Parses a JS-side log-level name. +/// Returns `None` for `"off"` or unrecognized strings. +fn parse_level(level: &str) -> Option { + match level { + "trace" => Some(Level::TRACE), + "debug" => Some(Level::DEBUG), + "info" => Some(Level::INFO), + "warning" => Some(Level::WARN), + "error" => Some(Level::ERROR), + _ => None, + } +} + +struct MessageVisitor { + message: String, + extras: String, +} + +impl MessageVisitor { + fn new() -> Self { + Self { + message: String::new(), + extras: String::new(), + } + } +} + +impl Visit for MessageVisitor { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + if field.name() == "message" { + self.message = format!("{:?}", value); + } else { + if !self.extras.is_empty() { + self.extras.push_str(", "); + } + self.extras + .push_str(&format!("{}={:?}", field.name(), value)); + } + } + + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + self.message = value.to_owned(); + } else { + if !self.extras.is_empty() { + self.extras.push_str(", "); + } + self.extras.push_str(&format!("{}={}", field.name(), value)); + } + } +} + +/// A single global `Layer` that, on each event, iterates every registered +/// per-client callback and forwards the event data to those whose +/// `min_level` is permissive enough. +struct JsForwardingLayer; + +impl Layer for JsForwardingLayer { + fn on_event( + &self, + event: &tracing::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let Some(lock) = CALLBACKS.get() else { + return; + }; + let callbacks = lock.read().unwrap(); + if callbacks.is_empty() { + return; + } + + let meta = event.metadata(); + let event_level = meta.level(); + + // Quick pre-check: is *any* callback interested in this level? + // Level ordering in tracing: TRACE > DEBUG > INFO > WARN > ERROR + // (more verbose = greater). An event passes if it is at most as + // verbose as the callback's threshold, i.e. event_level <= min_level. + if !callbacks.iter().any(|cb| *event_level <= cb.min_level) { + return; + } + + // At least one callback wants this event — extract the fields. + let level_str = level_to_js(event_level).to_owned(); + let target = meta.target().to_owned(); + + let mut visitor = MessageVisitor::new(); + event.record(&mut visitor); + + for cb in callbacks.iter() { + if *event_level <= cb.min_level { + cb.callback.call( + FnArgs { + data: ( + level_str.clone(), + target.clone(), + visitor.message.clone(), + visitor.extras.clone(), + ), + }, + ThreadsafeFunctionCallMode::NonBlocking, + ); + } + } + } +} + +/// Register a per-client logging callback. +/// +/// Each call adds a **new** callback to the global registry, allowing +/// multiple `Client` instances to receive Rust driver log events +/// independently. +/// +/// Returns a numeric `id` that must be passed to [`removeLogging`] when the +/// client shuts down, so the callback can be unregistered. +/// +/// Returns `None` (`null` on the JS side) when `min_level` is `"off"` or +/// unrecognized — no callback is registered in that case. +#[napi] +pub fn setup_logging(callback: LogCallback, min_level: String) -> Option { + let level = parse_level(&min_level)?; + + let id = NEXT_ID.fetch_add(1, Ordering::Relaxed); + + let callbacks = get_or_init_callbacks(); + callbacks.write().unwrap().push(RegisteredCallback { + id, + callback, + min_level: level, + }); + + Some(id) +} + +/// Unregister a previously-registered logging callback. +/// +/// After this call the callback associated with `id` will no longer receive +/// any tracing events. If `id` does not match any registered callback the +/// call is a silent no-op. +#[napi] +pub fn remove_logging(id: u32) { + if let Some(lock) = CALLBACKS.get() { + lock.write().unwrap().retain(|cb| cb.id != id); + } +} diff --git a/src/tests/logging_tests.rs b/src/tests/logging_tests.rs new file mode 100644 index 000000000..fecac1729 --- /dev/null +++ b/src/tests/logging_tests.rs @@ -0,0 +1,22 @@ +//! Test helpers for the logging module. +//! +//! These functions emit `tracing` events at specific levels so that the +//! JS-side test suite can verify that the forwarding layer works correctly. + +/// Emit one `tracing` event at each standard level (TRACE, DEBUG, INFO, WARN, +/// ERROR) with a predictable message and an extra field. +#[napi] +pub fn tests_emit_log_events() { + tracing::trace!(test_field = "trace_extra", "trace message from rust"); + tracing::debug!(test_field = "debug_extra", "debug message from rust"); + tracing::info!(test_field = "info_extra", "info message from rust"); + tracing::warn!(test_field = "warn_extra", "warn message from rust"); + tracing::error!(test_field = "error_extra", "error message from rust"); +} + +/// Emit a single `tracing::info!` event with the given message. +/// Useful for verifying that arbitrary messages arrive on the JS side. +#[napi] +pub fn tests_emit_log_info(message: String) { + tracing::info!("{}", message); +} diff --git a/src/tests/mod.rs b/src/tests/mod.rs index 6817428c7..74762b732 100644 --- a/src/tests/mod.rs +++ b/src/tests/mod.rs @@ -1,4 +1,5 @@ pub mod js_results_tests; +pub mod logging_tests; pub mod option_tests; pub mod socket_addr_tests; pub mod test_utils; diff --git a/test/integration/supported/client-logging-tests.js b/test/integration/supported/client-logging-tests.js new file mode 100644 index 000000000..c57a3b0d3 --- /dev/null +++ b/test/integration/supported/client-logging-tests.js @@ -0,0 +1,265 @@ +"use strict"; + +const { assert } = require("chai"); +const Client = require("../../../lib/client"); +const helper = require("../../test-helper"); +const { types } = require("../../../main"); +const { logLevels } = types; + +/** + * Wait briefly for any NonBlocking ThreadsafeFunction calls queued on the + * event-loop to be delivered. + */ +function drain() { + return new Promise((resolve) => setTimeout(resolve, 100)); +} + +describe("Client logging @SERVER_API", function () { + this.timeout(300000); + + // Start a single-node cluster shared by all tests in this file. + const _setup = helper.setup(1); + + describe("during connect", function () { + it("should emit Rust driver log events when logLevel is set", async function () { + const logEvents = []; + + const client = new Client( + Object.assign({}, helper.baseOptions, { + logLevel: logLevels.trace, + }), + ); + + client.on("log", (level, target, message, furtherInfo) => { + logEvents.push({ level, target, message, furtherInfo }); + }); + + await client.connect(); + await drain(); + + // In this and following tests, we assume rust will generate this specific log event. + // But when we filter for we guarantee we get the logs from the driver, not some random other place. + // So if at some point rust driver decides to change / rename this log event, + // those tests would need to be updated. + const rustEvents = logEvents.filter( + (e) => + e.target && + e.target.includes("scylla::network::connection"), + ); + + assert.isAbove( + rustEvents.length, + 0, + "expected at least one log event from the Rust driver during connect", + ); + + // Every Rust event must have a valid structure + for (const event of rustEvents) { + assert.isString(event.level); + assert.include( + [ + logLevels.trace, + logLevels.debug, + logLevels.info, + logLevels.warning, + logLevels.error, + ], + event.level, + `unexpected log level: ${event.level}`, + ); + assert.isString(event.target); + assert.isString(event.message); + } + + await client.shutdown(); + }); + + it("should still emit JS-side log events alongside Rust events", async function () { + const jsEvents = []; + + const client = new Client( + Object.assign({}, helper.baseOptions, { + logLevel: logLevels.info, + }), + ); + + client.on("log", (level, className, message) => { + if (className === "Client") { + jsEvents.push({ level, className, message }); + } + }); + + await client.connect(); + + const connectLog = jsEvents.find((e) => + e.message.includes("Connecting to cluster"), + ); + assert.isDefined( + connectLog, + "expected the JS-side 'Connecting to cluster' log event", + ); + assert.strictEqual(connectLog.level, logLevels.info); + + await client.shutdown(); + }); + }); + + describe("during query execution", function () { + it("should receive Rust driver logs when executing queries", async function () { + const logEvents = []; + + const client = new Client( + Object.assign({}, helper.baseOptions, { + logLevel: logLevels.trace, + }), + ); + + client.on("log", (level, target, message, furtherInfo) => { + logEvents.push({ level, target, message, furtherInfo }); + }); + + await client.connect(); + + // Clear events accumulated during connect + logEvents.length = 0; + + // Execute several queries to trigger Rust driver activity + await client.execute(helper.queries.basic); + await client.execute(helper.queries.basic, [], { prepare: true }); + await client.execute(helper.queries.basicNoResults); + await drain(); + + const rustEvents = logEvents.filter( + (e) => + e.target && + e.target.includes("scylla::network::connection"), + ); + + assert.isAbove( + rustEvents.length, + 0, + "expected Rust driver log events during query execution", + ); + + await client.shutdown(); + }); + + it("should receive Rust driver logs during DDL operations", async function () { + const logEvents = []; + const ks = helper.getRandomName("ks"); + + const client = new Client( + Object.assign({}, helper.baseOptions, { + logLevel: logLevels.trace, + }), + ); + + client.on("log", (level, target, message, furtherInfo) => { + logEvents.push({ level, target, message, furtherInfo }); + }); + + await client.connect(); + + // Clear events from connect + logEvents.length = 0; + + // DDL statements trigger internal driver activity (schema + // agreement checks, metadata refresh, etc.) + await client.execute( + `CREATE KEYSPACE ${ks} WITH replication = {'class': 'SimpleStrategy', 'replication_factor': 1}`, + ); + await client.execute(`USE ${ks}`); + await client.execute( + `CREATE TABLE ${ks}.log_test (id int PRIMARY KEY, value text)`, + ); + await drain(); + + const rustEvents = logEvents.filter( + (e) => + e.target && + e.target.includes("scylla::network::connection"), + ); + + assert.isAbove( + rustEvents.length, + 0, + "expected Rust driver log events during DDL operations", + ); + + await client.execute(`DROP KEYSPACE ${ks}`); + await client.shutdown(); + }); + }); + + describe("log event structure from real driver activity", function () { + it("should have target containing scylla module paths", async function () { + const logEvents = []; + + const client = new Client( + Object.assign({}, helper.baseOptions, { + logLevel: logLevels.trace, + }), + ); + + client.on("log", (level, target, message, furtherInfo) => { + logEvents.push({ level, target, message, furtherInfo }); + }); + + await client.connect(); + await client.execute(helper.queries.basic); + await drain(); + + const rustEvents = logEvents.filter( + (e) => + e.target && + e.target.includes("scylla::network::connection"), + ); + + // At least some events should come from the scylla crate itself + const scyllaEvents = rustEvents.filter((e) => + e.target.startsWith("scylla"), + ); + assert.isAbove( + scyllaEvents.length, + 0, + "expected log events originating from the 'scylla' crate", + ); + + await client.shutdown(); + }); + + it("should have non-empty messages from the driver", async function () { + const logEvents = []; + + const client = new Client( + Object.assign({}, helper.baseOptions, { + logLevel: logLevels.trace, + }), + ); + + client.on("log", (level, target, message, furtherInfo) => { + logEvents.push({ level, target, message, furtherInfo }); + }); + + await client.connect(); + await drain(); + + const rustEvents = logEvents.filter( + (e) => + e.target && + e.target.includes("scylla::network::connection"), + ); + + const withMessages = rustEvents.filter( + (e) => e.message && e.message.length > 0, + ); + assert.isAbove( + withMessages.length, + 0, + "expected at least some Rust driver events to have non-empty messages", + ); + + await client.shutdown(); + }); + }); +}); diff --git a/test/typescript/api-generation-test.ts b/test/typescript/api-generation-test.ts index c6971a6c5..163228ac8 100644 --- a/test/typescript/api-generation-test.ts +++ b/test/typescript/api-generation-test.ts @@ -57,6 +57,7 @@ export async function generatedFn() { printEnum(types.protocolVersion, "types.protocolVersion"); printEnum(types.distance, "types.distance"); printEnum(types.responseErrorCodes, "types.responseErrorCodes"); + printStringEnum(types.logLevels, "types.logLevels"); console.log(` o = types.unset;\n\n`); printClasses( types, @@ -89,6 +90,17 @@ function printEnum(enumObject: { [key: string]: any }, name: string): void { console.log(); } +function printStringEnum(enumObject: { [key: string]: any }, name: string): void { + console.log(` // ${name} enum values`); + + Object.keys(enumObject) + .filter((k) => typeof enumObject[k] === "string") + .forEach((k) => { + console.log(` s = ${name}.${k};`); + }); + console.log(); +} + /** * Prints classes and interfaces */ diff --git a/test/typescript/client-tests.ts b/test/typescript/client-tests.ts index 97aea3e21..6a53bb3da 100644 --- a/test/typescript/client-tests.ts +++ b/test/typescript/client-tests.ts @@ -93,6 +93,18 @@ async function myTest(): Promise { applicationVersion: "3.1.2", }); + otherClient = new Client({ + contactPoints: ["h1", "h2"], + localDataCenter: "dc1", + logLevel: types.logLevels.info, + }); + + otherClient = new Client({ + contactPoints: ["h1", "h2"], + localDataCenter: "dc1", + logLevel: types.logLevels.off, + }); + let ep1: ExecutionProfile = new ExecutionProfile("oltp1", { consistency: types.consistencies.localOne, }); diff --git a/test/typescript/types-test.ts b/test/typescript/types-test.ts index cfe4c94e4..7e22b2949 100644 --- a/test/typescript/types-test.ts +++ b/test/typescript/types-test.ts @@ -22,6 +22,15 @@ async function myTest(): Promise { types.protocolVersion.isSupported(types.protocolVersion.v4); + // logLevels enum + let ll: types.logLevels; + ll = types.logLevels.trace; + ll = types.logLevels.debug; + ll = types.logLevels.info; + ll = types.logLevels.warning; + ll = types.logLevels.error; + ll = types.logLevels.off; + id = Uuid.random(); id = TimeUuid.now(); diff --git a/test/unit-not-supported/api-tests.js b/test/unit-not-supported/api-tests.js index 615b168a4..412338265 100644 --- a/test/unit-not-supported/api-tests.js +++ b/test/unit-not-supported/api-tests.js @@ -51,6 +51,16 @@ describe("API", function () { checkConstructor(api.types, "Uuid"); checkConstructor(api.types, "TimeUuid"); }); + + it("should expose logLevels enum on types", function () { + assert.ok(api.types.logLevels); + assert.strictEqual(api.types.logLevels.trace, "trace"); + assert.strictEqual(api.types.logLevels.debug, "debug"); + assert.strictEqual(api.types.logLevels.info, "info"); + assert.strictEqual(api.types.logLevels.warning, "warning"); + assert.strictEqual(api.types.logLevels.error, "error"); + assert.strictEqual(api.types.logLevels.off, "off"); + }); }); function checkConstructor(module, constructorName) { diff --git a/test/unit/logging-tests.js b/test/unit/logging-tests.js new file mode 100644 index 000000000..09dd1c403 --- /dev/null +++ b/test/unit/logging-tests.js @@ -0,0 +1,226 @@ +"use strict"; + +const { assert } = require("chai"); +const rust = require("../../index"); +const { types } = require("../../main"); +const { logLevels } = types; + +// --------------------------------------------------------------------------- +// Because `tracing` has a single global subscriber per process, all tests +// share that subscriber. However, `setupLogging` now registers a +// *per-client* callback and returns an id. We register in `before` and +// unregister in `after` so each `describe` block gets a clean slate. +// --------------------------------------------------------------------------- + +const allEvents = []; + +/** + * Wait briefly for any NonBlocking ThreadsafeFunction calls queued on the + * event-loop to be delivered. + */ +function drain() { + return new Promise((resolve) => setTimeout(resolve, 50)); +} + +describe("Logging", function () { + let loggingId; + + before(function () { + // Register a callback at the "trace" level so we capture everything. + loggingId = rust.setupLogging((level, target, message, furtherInfo) => { + allEvents.push({ level, target, message, furtherInfo }); + }, logLevels.trace); + }); + + after(function () { + rust.removeLogging(loggingId); + }); + + afterEach(function () { + // Clear collected events between tests so assertions are isolated. + allEvents.length = 0; + }); + + describe("testsEmitLogEvents", function () { + it("should forward events at all five tracing levels", async function () { + rust.testsEmitLogEvents(); + await drain(); + + // TRACE→"trace", DEBUG→"debug", INFO→"info", WARN→"warning", ERROR→"error" + const levels = allEvents.map((e) => e.level); + assert.include(levels, logLevels.trace); + assert.include(levels, logLevels.debug); + assert.include(levels, logLevels.info); + assert.include(levels, logLevels.warning); + assert.include(levels, logLevels.error); + }); + + it("should include the correct messages", async function () { + rust.testsEmitLogEvents(); + await drain(); + + const messages = allEvents.map((e) => e.message); + assert.include(messages, "trace message from rust"); + assert.include(messages, "debug message from rust"); + assert.include(messages, "info message from rust"); + assert.include(messages, "warn message from rust"); + assert.include(messages, "error message from rust"); + }); + + it("should set target to the Rust module path", async function () { + rust.testsEmitLogEvents(); + await drain(); + + for (const event of allEvents) { + assert.isString(event.target); + assert.isNotEmpty(event.target); + // The target should contain the crate/module path + assert.include( + event.target, + "logging_tests", + "target should reference the Rust module that emitted the event", + ); + } + }); + + it("should forward furtherInfo with extra fields", async function () { + rust.testsEmitLogEvents(); + await drain(); + + // Events from testsEmitLogEvents include a `test_field` extra field. + const withExtras = allEvents.filter( + (e) => e.furtherInfo && e.furtherInfo.length > 0, + ); + assert.isAbove( + withExtras.length, + 0, + "at least some events should carry furtherInfo", + ); + + for (const event of withExtras) { + assert.include(event.furtherInfo, "test_field"); + } + }); + }); + + describe("testsEmitLogInfo", function () { + it("should forward a custom info message", async function () { + const msg = "hello from unit test " + Date.now(); + rust.testsEmitLogInfo(msg); + await drain(); + + const match = allEvents.find((e) => e.message === msg); + assert.isDefined(match, "expected to find the custom message"); + assert.strictEqual(match.level, logLevels.info); + }); + }); + + describe("multiple callbacks (per-client)", function () { + it("should deliver events to all registered callbacks", async function () { + const secondEvents = []; + const secondId = rust.setupLogging( + (level, target, message, furtherInfo) => { + secondEvents.push({ level, target, message, furtherInfo }); + }, + logLevels.trace, + ); + + rust.testsEmitLogInfo("multi-callback test"); + await drain(); + + // Both callbacks should receive the event + const first = allEvents.find( + (e) => e.message === "multi-callback test", + ); + const second = secondEvents.find( + (e) => e.message === "multi-callback test", + ); + assert.isDefined(first, "first callback should receive the event"); + assert.isDefined( + second, + "second callback should receive the event", + ); + + rust.removeLogging(secondId); + }); + + it("should stop delivering after removeLogging", async function () { + const removableEvents = []; + const removableId = rust.setupLogging( + (level, target, message, furtherInfo) => { + removableEvents.push({ + level, + target, + message, + furtherInfo, + }); + }, + logLevels.trace, + ); + + rust.testsEmitLogInfo("before remove"); + await drain(); + + assert.isDefined( + removableEvents.find((e) => e.message === "before remove"), + "should receive events before removal", + ); + + // Now remove + rust.removeLogging(removableId); + removableEvents.length = 0; + + rust.testsEmitLogInfo("after remove"); + await drain(); + + assert.strictEqual( + removableEvents.length, + 0, + "should NOT receive events after removeLogging", + ); + + // The main callback should still work + const main = allEvents.find((e) => e.message === "after remove"); + assert.isDefined( + main, + "original callback should still receive events", + ); + }); + }); + + describe("level filtering", function () { + it("should only deliver events at or above the registered level", async function () { + const errorOnlyEvents = []; + const errorId = rust.setupLogging( + (level, target, message, furtherInfo) => { + errorOnlyEvents.push({ + level, + target, + message, + furtherInfo, + }); + }, + logLevels.error, + ); + + rust.testsEmitLogEvents(); // emits TRACE, DEBUG, INFO, WARN, ERROR + await drain(); + + // Should only have error-level events + for (const event of errorOnlyEvents) { + assert.strictEqual( + event.level, + logLevels.error, + "error-only callback should not receive non-error events", + ); + } + assert.isAbove( + errorOnlyEvents.length, + 0, + "should have received at least the ERROR event", + ); + + rust.removeLogging(errorId); + }); + }); +});