From 9a7ef6faf4c62993d3f8f2d36db1c6ba52844ee1 Mon Sep 17 00:00:00 2001 From: "K.J. Valencik" Date: Wed, 19 Jan 2022 12:59:17 -0500 Subject: [PATCH] Logging example --- Cargo.lock | 8 ++ Cargo.toml | 1 + README.md | 2 + examples/logging/Cargo.toml | 18 ++++ examples/logging/README.md | 62 +++++++++++ examples/logging/package-lock.json | 71 +++++++++++++ examples/logging/package.json | 31 ++++++ examples/logging/run.js | 13 +++ examples/logging/src/lib.rs | 35 +++++++ examples/logging/src/logger.rs | 159 +++++++++++++++++++++++++++++ package-lock.json | 58 +++++++++++ 11 files changed, 458 insertions(+) create mode 100644 examples/logging/Cargo.toml create mode 100644 examples/logging/README.md create mode 100644 examples/logging/package-lock.json create mode 100644 examples/logging/package.json create mode 100644 examples/logging/run.js create mode 100644 examples/logging/src/lib.rs create mode 100644 examples/logging/src/logger.rs diff --git a/Cargo.lock b/Cargo.lock index 6963bb6..0d9e3f8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -437,6 +437,14 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "logging" +version = "0.1.0" +dependencies = [ + "log", + "neon 0.10.0-alpha.3", +] + [[package]] name = "matches" version = "0.1.9" diff --git a/Cargo.toml b/Cargo.toml index ef78aec..c60fad4 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -4,6 +4,7 @@ members = [ "examples/cpu-count", "examples/gzip-stream", "examples/hello-world", + "examples/logging", "examples/tokio-fetch", ] diff --git a/README.md b/README.md index ebfcf72..254ed9e 100644 --- a/README.md +++ b/README.md @@ -18,12 +18,14 @@ All examples are for [`napi-backend`][napi-migration]. For examples using `legac | [`cpu-count`][cpu-count] | Return the number of CPUs | | [`gzip-stream`][gzip-stream] | Asynchronously compress a stream of data | | [`hello-world`][hello-world] | Return a JS String with a greeting message | +| [`logging`][logging] | Connects Rust logging to Node.js logging | | [`tokio-fetch`][tokio-fetch] | Asynchronously fetch a node release date | [async-sqlite]: examples/async-sqlite [cpu-count]: examples/cpu-count [gzip-stream]: examples/gzip-stream [hello-world]: examples/hello-world +[logging]: examples/logging [tokio-fetch]: examples/tokio-fetch ## Contributing diff --git a/examples/logging/Cargo.toml b/examples/logging/Cargo.toml new file mode 100644 index 0000000..d66fb2f --- /dev/null +++ b/examples/logging/Cargo.toml @@ -0,0 +1,18 @@ +[package] +name = "logging" +version = "0.1.0" +description = "Neon Logging Example" +license = "MIT" +edition = "2018" +exclude = ["index.node"] + +[lib] +crate-type = ["cdylib"] + +[dependencies] +log = "0.4" + +[dependencies.neon] +version = "0.10.0-alpha.3" +default-features = false +features = ["napi-6", "channel-api"] diff --git a/examples/logging/README.md b/examples/logging/README.md new file mode 100644 index 0000000..5d0b5f2 --- /dev/null +++ b/examples/logging/README.md @@ -0,0 +1,62 @@ +# Logging + +The logging example connects the Rust [`log`][log] crate to the Node [`debug`][debug] module. Neon modules can write logs directly to `stdout` with typical crates like [`env_logger`][env-logger], but connecting logging to [`debug`][debug] more seamlessly integrates with the Node ecosystem. + +## Usage + +```sh +# Only `INFO` logs on the top level crate +DEBUG="INFO:logging" npm start + +# All logs on the top level crate +DEBUG="*:logging" npm start + +# All `INFO` logs on any Rust crate +DEBUG="INFO:*" npm start + +# All `WARN` and higher logs in our crate +DEBUG="WARN:logging,ERROR:logging" +``` + +## Libraries + +### [`log`][log] crate + +The [`log`][log] crate provides a logging facade used throughout the Rust ecosystem. It provides convenient macros for logging, but does not provide any facility to write or display logs. + +### [`debug`][debug] module + +the [`debug`][debug] node module provides a decorated version of `console.error` and is used throughout the Node library ecosystem, including in the [`express`][express] HTTP framework. It allows configurable log filtering with the `DEBUG` environment variable. + +## Design + +Rust code uses the typical logging facilities, but in order for it to be used, the [`Log`][log-trait] must be implemented. This example provides a simple [`Log`][log-trait] implementation that delegates to the [`debug`][debug] node module. + +### Initialization + +At initialization, the module calls `global.require("debug")` to get a copy of the function used to create logger instances. This function, as well as `enabled` and a [`Channel`][channel] are used to create a `Logger` instance and initialize the `log` crate. + +### Loggers + +The `Logger` struct maintains a map of logger names to logger instances that are lazily created as needed. Each logger is in an `Option` with `None` representing the disabled state. If an entry is missing, it is assumed to be in the `enabled` state until it can be further evaluated. + +## Limitations + +### Levels + +The provided implementation does not understand logger levels. Each level needs to be enabled individually. As an improvement, the logger level could be determined by checking `debug.enabled(...)` for each level from lowest to highest. + +### Multiple Contexts + +The `log` crate only supports a single global logger instance in a process. If the module is initialized multiple times with Web Workers, all logs will be sent to the instance that initialized. + +### Runtime level changes + +The `debug` module supports enabling and disabling logging at runtime, but for efficiency, our `Logging` implementation assumes that the result of `debug.enabled(..)` never changes. + +[log]: https://crates.io/crates/log +[log-trait]: https://docs.rs/log/latest/log/trait.Log.html +[debug]: https://www.npmjs.com/package/debug +[env-logger]: https://crates.io/crates/env-logger +[express]: https://www.npmjs.com/package/express +[channel]: https://docs.rs/neon/latest/neon/event/struct.Channel.html diff --git a/examples/logging/package-lock.json b/examples/logging/package-lock.json new file mode 100644 index 0000000..75648af --- /dev/null +++ b/examples/logging/package-lock.json @@ -0,0 +1,71 @@ +{ + "name": "logging", + "version": "0.1.0", + "lockfileVersion": 2, + "requires": true, + "packages": { + "": { + "name": "logging", + "version": "0.1.0", + "hasInstallScript": true, + "license": "MIT", + "dependencies": { + "debug": "^4.3.3" + }, + "devDependencies": { + "cargo-cp-artifact": "^0.1" + } + }, + "node_modules/cargo-cp-artifact": { + "version": "0.1.6", + "resolved": "https://registry.npmjs.org/cargo-cp-artifact/-/cargo-cp-artifact-0.1.6.tgz", + "integrity": "sha512-CQw0doK/aaF7j041666XzuilHxqMxaKkn+I5vmBsd8SAwS0cO5CqVEVp0xJwOKstyqWZ6WK4Ww3O6p26x/Goyg==", + "dev": true, + "bin": { + "cargo-cp-artifact": "bin/cargo-cp-artifact.js" + } + }, + "node_modules/debug": { + "version": "4.3.3", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.3.tgz", + "integrity": "sha512-/zxw5+vh1Tfv+4Qn7a5nsbcJKPaSvCDhojn6FEl9vupwK2VCSDtEiEtqr8DFtzYFOdz63LBkxec7DYuc2jon6Q==", + "dependencies": { + "ms": "2.1.2" + }, + "engines": { + "node": ">=6.0" + }, + "peerDependenciesMeta": { + "supports-color": { + "optional": true + } + } + }, + "node_modules/ms": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz", + "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w==" + } + }, + "dependencies": { + "cargo-cp-artifact": { + "version": "0.1.6", + "resolved": "https://registry.npmjs.org/cargo-cp-artifact/-/cargo-cp-artifact-0.1.6.tgz", + "integrity": "sha512-CQw0doK/aaF7j041666XzuilHxqMxaKkn+I5vmBsd8SAwS0cO5CqVEVp0xJwOKstyqWZ6WK4Ww3O6p26x/Goyg==", + "dev": true + }, + "debug": { + "version": "4.3.3", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.3.tgz", + "integrity": "sha512-/zxw5+vh1Tfv+4Qn7a5nsbcJKPaSvCDhojn6FEl9vupwK2VCSDtEiEtqr8DFtzYFOdz63LBkxec7DYuc2jon6Q==", + "requires": { + "ms": "2.1.2" + } + }, + "ms": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz", + "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w==" + } + } +} diff --git a/examples/logging/package.json b/examples/logging/package.json new file mode 100644 index 0000000..34677be --- /dev/null +++ b/examples/logging/package.json @@ -0,0 +1,31 @@ +{ + "name": "logging", + "version": "0.1.0", + "description": "Neon Logging Example", + "main": "index.node", + "scripts": { + "build": "cargo-cp-artifact -nc index.node -- cargo build --message-format=json-render-diagnostics", + "install": "npm run build", + "start": "node run", + "test": "cargo test" + }, + "license": "MIT", + "devDependencies": { + "cargo-cp-artifact": "^0.1" + }, + "repository": { + "type": "git", + "url": "git+https://github.com/neon-bindings/examples.git" + }, + "keywords": [ + "Neon", + "Examples" + ], + "bugs": { + "url": "https://github.com/neon-bindings/examples/issues" + }, + "homepage": "https://github.com/neon-bindings/examples#readme", + "dependencies": { + "debug": "^4.3.3" + } +} diff --git a/examples/logging/run.js b/examples/logging/run.js new file mode 100644 index 0000000..228c00a --- /dev/null +++ b/examples/logging/run.js @@ -0,0 +1,13 @@ +"use strict"; + +const debug = require("debug"); +const { hello, init } = require("."); + +// Must be called to initialized logging +init(debug); + +// Call an example function +hello(); + +// Give logs a chance to flush +setTimeout(() => {}, 500); diff --git a/examples/logging/src/lib.rs b/examples/logging/src/lib.rs new file mode 100644 index 0000000..26006b6 --- /dev/null +++ b/examples/logging/src/lib.rs @@ -0,0 +1,35 @@ +use neon::prelude::*; + +use crate::logger::Logger; + +mod logger; + +// `init(debug)` must be called before using any other functionality. +// +// An exported initialization function is a common pattern in Neon. Since +// Node-API does not expose `require`, a JavaScript wrapper requires the +// `debug` module and passes it to `init` where logging is initialized. +fn init(mut cx: FunctionContext) -> JsResult { + let debug = cx.argument::(0)?; + + Logger::init(&mut cx, debug)?; + + log::info!("Module initialized"); + + Ok(cx.undefined()) +} + +// Example function with logging +fn hello(mut cx: FunctionContext) -> JsResult { + log::trace!("Called `hello` function"); + + Ok(cx.string("hello node")) +} + +#[neon::main] +fn main(mut cx: ModuleContext) -> NeonResult<()> { + cx.export_function("init", init)?; + cx.export_function("hello", hello)?; + + Ok(()) +} diff --git a/examples/logging/src/logger.rs b/examples/logging/src/logger.rs new file mode 100644 index 0000000..ce5ffba --- /dev/null +++ b/examples/logging/src/logger.rs @@ -0,0 +1,159 @@ +use std::collections::HashMap; +use std::sync::{Arc, RwLock}; + +use log::{LevelFilter, Log, Metadata, Record}; +use neon::prelude::*; + +type Debug = Option>; + +pub struct Logger { + // Used for calling back to the main JavaScript thread + channel: Channel, + + // Reference counted internal state for the logger used to emit logs + internal: Arc, +} + +struct LoggerInternal { + // Reference to `require("debug")` function + debug: Root, + + // Reference to `debug.enabled` function + enabled: Root, + + // Set of initialized instances of `debug` + loggers: RwLock>, +} + +impl LoggerInternal { + // Get an instance of `debug` if it is enabled, lazily creating if necessary + fn debug<'a, C: Context<'a>>( + &self, + cx: &mut C, + key: String, + ) -> NeonResult>> { + // If available, return teh cached value + if let Some(logger) = self.loggers.read().unwrap().get(&key) { + return Ok(logger.as_ref().map(|root| root.to_inner(cx))); + }; + + // Call `debug.enabled(name)` to see if logging is enabled. + let name = cx.string(&key); + let is_enabled = self + .enabled + .to_inner(cx) + .call_with(cx) + .arg(name) + .apply::(cx)? + .value(cx); + + // If the logger is not enabled, insert `None` and return. + if !is_enabled { + self.loggers.write().unwrap().insert(key, None); + + return Ok(None); + } + + // Create an instance of the logger by calling `debug(name)` + let debug = self + .debug + .to_inner(cx) + .call_with(cx) + .arg(name) + .apply::(cx)?; + + // Insert the logger instance into the cache + self.loggers + .write() + .unwrap() + .insert(key, Some(debug.root(cx))); + + Ok(Some(debug)) + } +} + +impl Logger { + /// Creates an instance of [`Logger`] and sets it as the global logger in [`log`] + pub fn init<'a, C: Context<'a>>(cx: &mut C, debug: Handle) -> NeonResult<()> { + let logger = Box::new(Logger::new(cx, debug)?); + + log::set_logger(Box::leak(logger)) + .map(|_| log::set_max_level(LevelFilter::Trace)) + .or_else(|err| cx.throw_error(err.to_string())) + } + + /// Creates an instance of [`Logger`] + pub fn new<'a, C: Context<'a>>(cx: &mut C, debug: Handle) -> NeonResult { + // Create a new channel. This channel is a queue that is not shared with other + // calls, allowing more efficient collapsing of calls. + let mut channel = Channel::new(cx); + + // Prevent logging from preventing the process from being stopped. Some logs + // may be lost at shutdown. + channel.unref(cx); + + // Get a reference to `debug.enabled` + let enabled = debug + .get(cx, "enabled")? + .downcast_or_throw::(cx)?; + + let internal = Arc::new(LoggerInternal { + debug: debug.root(cx), + enabled: enabled.root(cx), + loggers: Default::default(), + }); + + Ok(Self { channel, internal }) + } + + // Name `debug` instances like `INFO:logging` + fn name(metadata: &Metadata) -> String { + format!("{}:{}", metadata.level(), metadata.target()) + } + + // Check if the logger _might_ be enabled + fn enabled(&self, name: &str) -> bool { + // If the key exists in the map and the value is `Some(_)` _or_ if the key + // does not exist, return `true`. + self.internal + .loggers + .read() + .unwrap() + .get(name) + .map(Option::is_some) + .unwrap_or(true) + } +} + +// The [`Log`] trait must be implemented by loggers installed globally to the `log` crate. +impl Log for Logger { + // Check if the logger _might_ be enabled, delegating to a version that takes a `&str` + fn enabled(&self, metadata: &Metadata) -> bool { + self.enabled(&Self::name(metadata)) + } + + fn log(&self, record: &Record) { + let name = Self::name(record.metadata()); + + // Logging is fairly expensive. Short-circuit if the log level is not enabled. + // Uses the `&str` version of `enabled` to avoid allocating an extra `String` + if !self.enabled(&name) { + return; + } + + let internal = self.internal.clone(); + let msg = record.args().to_string(); + + // Calling out to `debug` to log must happen on the main JavaScript thread. The + // closure is moved for execution. + let _ = self.channel.try_send(move |mut cx| { + if let Some(debug) = internal.debug(&mut cx, name)? { + debug.call_with(&cx).arg(cx.string(msg)).exec(&mut cx)?; + } + + Ok(()) + }); + } + + fn flush(&self) {} +} diff --git a/package-lock.json b/package-lock.json index ff702a3..92618f7 100644 --- a/package-lock.json +++ b/package-lock.json @@ -48,6 +48,38 @@ "cargo-cp-artifact": "^0.1" } }, + "examples/logging": { + "version": "0.1.0", + "hasInstallScript": true, + "license": "MIT", + "dependencies": { + "debug": "^4.3.3" + }, + "devDependencies": { + "cargo-cp-artifact": "^0.1" + } + }, + "examples/logging/node_modules/debug": { + "version": "4.3.3", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.3.tgz", + "integrity": "sha512-/zxw5+vh1Tfv+4Qn7a5nsbcJKPaSvCDhojn6FEl9vupwK2VCSDtEiEtqr8DFtzYFOdz63LBkxec7DYuc2jon6Q==", + "dependencies": { + "ms": "2.1.2" + }, + "engines": { + "node": ">=6.0" + }, + "peerDependenciesMeta": { + "supports-color": { + "optional": true + } + } + }, + "examples/logging/node_modules/ms": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz", + "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w==" + }, "examples/tokio-fetch": { "version": "0.1.0", "hasInstallScript": true, @@ -611,6 +643,10 @@ "url": "https://github.com/sponsors/sindresorhus" } }, + "node_modules/logging": { + "resolved": "examples/logging", + "link": true + }, "node_modules/minimatch": { "version": "3.0.4", "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-3.0.4.tgz", @@ -1415,6 +1451,28 @@ "is-unicode-supported": "^0.1.0" } }, + "logging": { + "version": "file:examples/logging", + "requires": { + "cargo-cp-artifact": "^0.1", + "debug": "^4.3.3" + }, + "dependencies": { + "debug": { + "version": "4.3.3", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.3.tgz", + "integrity": "sha512-/zxw5+vh1Tfv+4Qn7a5nsbcJKPaSvCDhojn6FEl9vupwK2VCSDtEiEtqr8DFtzYFOdz63LBkxec7DYuc2jon6Q==", + "requires": { + "ms": "2.1.2" + } + }, + "ms": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz", + "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w==" + } + } + }, "minimatch": { "version": "3.0.4", "resolved": "https://registry.npmjs.org/minimatch/-/minimatch-3.0.4.tgz",