pyo3_log/lib.rs
1#![forbid(unsafe_code)]
2#![doc(
3 html_root_url = "https://docs.rs/pyo3-log/0.2.1/pyo3-log/",
4 test(attr(deny(warnings))),
5 test(attr(allow(unknown_lints, non_local_definitions)))
6)]
7#![warn(missing_docs)]
8
9//! A bridge from Rust to Python logging
10//!
11//! The library can be used to install a [logger][log::Log] into Rust that will send the messages
12//! over to the Python [logging](https://docs.python.org/3/library/logging.html). This can be
13//! useful when writing a native Python extension module in Rust and it is desirable to log from
14//! the Rust side too.
15//!
16//! The library internally depends on the [`pyo3`] crate. This is not exposed through the public
17//! API and it should work from extension modules not using [`pyo3`] directly. It'll nevertheless
18//! still bring the dependency in, so this might be considered if the module doesn't want to use
19//! it.
20//!
21//! # Simple usage
22//!
23//! Each extension module has its own global variables, therefore the used logger is also
24//! independent of other Rust native extensions. Therefore, it is up to each one to set a logger
25//! for itself if it wants one.
26//!
27//! By using [`init`] function from a place that's run only once (maybe from the top-level module
28//! of the extension), the logger is registered and the log messages (eg. [`info`][log::info]) send
29//! their messages over to the Python side.
30//!
31//! ```rust
32//! use log::info;
33//! use pyo3::prelude::*;
34//!
35//! #[pyfunction]
36//! fn log_something() {
37//! info!("Something!");
38//! }
39//!
40//! #[pymodule]
41//! fn my_module(m: Bound<'_, PyModule>) -> PyResult<()> {
42//! pyo3_log::init();
43//!
44//! m.add_wrapped(wrap_pyfunction!(log_something))?;
45//! Ok(())
46//! }
47//! ```
48//!
49//! The following example is how this would be performed with the new declarative inline module syntax
50//! introduced in PyO3 0.23 and above.
51//!
52//! ```rust
53//! # mod test_declarative_example {
54//! use pyo3::prelude::*;
55//! use log::info;
56//!
57//! #[pymodule]
58//! mod my_module{
59//! use super::*;
60//!
61//! #[pymodule_init]
62//! fn init(_m: &Bound<'_, PyModule>) -> PyResult<()> {
63//! pyo3_log::init();
64//! Ok(())
65//! }
66//!
67//! #[pyfunction]
68//! fn log_something() {
69//! info!("Something!");
70//! }
71//! }
72//! # }
73//! ```
74//!
75//! # Performance, Filtering and Caching
76//!
77//! Ideally, the logging system would always consult the Python loggers to know which messages
78//! should or should not be logged. However, one of the reasons of using Rust instead of Python is
79//! performance. Part of that is giving up the GIL in long-running computations to let other
80//! threads run at the same time.
81//!
82//! Therefore, acquiring the GIL and calling into the Python interpreter on each
83//! [`trace`][log::trace] message only to figure out it is not to be logged would be prohibitively
84//! slow. There are two techniques employed here.
85//!
86//! First, level filters are applied before consulting the Python side. By default, only the
87//! [`Debug`][Level::Debug] level and more severe is considered to be sent over to Python. This can
88//! be overridden using the [`filter`][Logger::filter] and [`filter_target`][Logger::filter_target]
89//! methods.
90//!
91//! Second, the Python loggers and their effective log levels are cached on the Rust side on the
92//! first use of the given module. This means that on a disabled level, only the first logging
93//! attempt in the given module will acquire GIL while the future ones will short-circuit before
94//! ever reaching Python.
95//!
96//! This is good for performance, but could lead to the incorrect messages to be logged or not
97//! logged in certain situations ‒ if Rust logs before the Python logging system is set up properly
98//! or when it is reconfigured at runtime.
99//!
100//! For these reasons it is possible to turn caching off on construction of the logger (at the cost
101//! of performance) and to clear the cache manually through the [`ResetHandle`].
102//!
103//! To tune the caching and filtering, the logger needs to be created manually:
104//!
105//! ```rust
106//! # use log::LevelFilter;
107//! # use pyo3::prelude::*;
108//! # use pyo3_log::{Caching, Logger};
109//! #
110//! # fn main() -> PyResult<()> {
111//! # Python::attach(|py| {
112//! let handle = Logger::new(py, Caching::LoggersAndLevels)?
113//! .filter(LevelFilter::Trace)
114//! .filter_target("my_module::verbose_submodule".to_owned(), LevelFilter::Warn)
115//! .install()
116//! .expect("Someone installed a logger before us :-(");
117//!
118//! // Some time in the future when logging changes, reset the caches:
119//! handle.reset();
120//! # Ok(())
121//! # })
122//! # }
123//! ```
124//!
125//! # Mapping
126//!
127//! The logging `target` is mapped into the name of the logger on the Python side, replacing all
128//! `::` occurrences with `.` (both form hierarchy in their respective language).
129//!
130//! Log levels are mapped to the same-named ones. The [`Trace`][Level::Trace] doesn't exist on the
131//! Python side, but is mapped to a level with value 5.
132//!
133//! # Interaction with Python GIL
134//!
135//! Under the hook, the logging routines call into Python. That means they need to acquire the
136//! Global Interpreter Lock of Python.
137//!
138//! This has several consequences. One of them is the above mentioned performance considerations.
139//!
140//! The other is a risk of deadlocks if threads are used from within the extension code without
141//! releasing the GIL.
142//!
143//! ```rust
144//! use std::thread;
145//! use log::info;
146//! use pyo3::prelude::*;
147//!
148//! #[pyfunction]
149//! fn deadlock() {
150//! info!("This logs fine");
151//!
152//! let background_thread = thread::spawn(|| {
153//! info!("This'll deadlock");
154//! });
155//!
156//! background_thread.join().unwrap();
157//! }
158//! # let _ = deadlock;
159//! ```
160//!
161//! The above code will deadlock, because the `info` call in the background thread needs the GIL
162//! that's held by the deadlock function. One needs to give up the GIL to let the other threads
163//! run, something like this:
164//!
165//! ```rust
166//! use std::thread;
167//! use log::info;
168//! use pyo3::prelude::*;
169//!
170//! #[pyfunction]
171//! fn dont_deadlock(py: Python<'_>) {
172//! info!("This logs fine");
173//!
174//! py.detach(|| {
175//! let background_thread = thread::spawn(|| {
176//! info!("This'll not deadlock");
177//! });
178//!
179//! background_thread.join().unwrap();
180//! });
181//! }
182//! # let _ = dont_deadlock;
183//! ```
184
185use std::cmp;
186use std::collections::HashMap;
187use std::sync::Arc;
188
189use arc_swap::ArcSwap;
190use log::{Level, LevelFilter, Log, Metadata, Record, SetLoggerError};
191use pyo3::prelude::*;
192use pyo3::types::PyTuple;
193
194/// A handle into a [`Logger`], able to reset its caches.
195///
196/// This handle can be used to manipulate a [`Logger`] even after it has been installed. It's main
197/// purpose is to reset the internal caches, for example if the logging settings on the Python side
198/// changed.
199#[derive(Clone, Debug)]
200pub struct ResetHandle(Arc<ArcSwap<CacheNode>>);
201
202impl ResetHandle {
203 /// Reset the internal logger caches.
204 ///
205 /// This removes all the cached loggers and levels (if there were any). Future logging calls
206 /// may cache them again, using the current Python logging settings.
207 pub fn reset(&self) {
208 // Overwrite whatever is in the cache directly. This must win in case of any collisions
209 // (the caching uses compare_and_swap to let the reset win).
210 self.0.store(Default::default());
211 }
212}
213
214/// What the [`Logger`] can cache.
215#[derive(Copy, Clone, Debug, Eq, PartialEq)]
216#[non_exhaustive]
217#[derive(Default)]
218pub enum Caching {
219 /// Disables caching.
220 ///
221 /// Every time a log message passes the filters, the code goes to the Python side to check if
222 /// the message shall be logged.
223 Nothing,
224
225 /// Caches the Python `Logger` objects.
226 ///
227 /// The logger objects (which should stay the same during the lifetime of a Python application)
228 /// are cached. However, the log levels are not. This means there's some amount of calling of
229 /// Python code saved during a logging call, but the GIL still needs to be acquired even if the
230 /// message doesn't eventually get output anywhere.
231 Loggers,
232
233 /// Caches both the Python `Logger` and their respective effective log levels.
234 ///
235 /// Therefore, once a `Logger` has been cached, it is possible to decide on the Rust side if a
236 /// message would get logged or not. If the message is not to be logged, no Python code is
237 /// called and the GIL doesn't have to be acquired.
238 #[default]
239 LoggersAndLevels,
240}
241
242#[derive(Debug)]
243struct CacheEntry {
244 filter: LevelFilter,
245 logger: Py<PyAny>,
246}
247
248impl CacheEntry {
249 fn clone_ref(&self, py: Python<'_>) -> Self {
250 CacheEntry {
251 filter: self.filter,
252 logger: self.logger.clone_ref(py),
253 }
254 }
255}
256
257#[derive(Debug, Default)]
258struct CacheNode {
259 local: Option<CacheEntry>,
260 children: HashMap<String, Arc<CacheNode>>,
261}
262
263impl CacheNode {
264 fn store_to_cache_recursive<'a, P>(
265 &self,
266 py: Python<'_>,
267 mut path: P,
268 entry: CacheEntry,
269 ) -> Arc<Self>
270 where
271 P: Iterator<Item = &'a str>,
272 {
273 let mut me = CacheNode {
274 children: self.children.clone(),
275 local: self.local.as_ref().map(|e| e.clone_ref(py)),
276 };
277 match path.next() {
278 Some(segment) => {
279 let child = me.children.entry(segment.to_owned()).or_default();
280 *child = child.store_to_cache_recursive(py, path, entry);
281 }
282 None => me.local = Some(entry),
283 }
284 Arc::new(me)
285 }
286}
287
288/// The `Logger`
289///
290/// The actual `Logger` that can be installed into the Rust side and will send messages over to
291/// Python.
292///
293/// It can be either created directly and then installed, passed to other aggregating log systems,
294/// or the [`init`] or [`try_init`] functions may be used if defaults are good enough.
295#[derive(Debug)]
296pub struct Logger {
297 /// Filter used as a fallback if none of the `filters` match.
298 top_filter: LevelFilter,
299
300 /// Mapping of filters to modules.
301 ///
302 /// The most specific one will be used, falling back to `top_filter` if none matches. Stored as
303 /// full paths, with `::` separaters (eg. before converting them from Rust to Python).
304 filters: HashMap<String, LevelFilter>,
305
306 /// The imported Python `logging` module.
307 logging: Py<PyModule>,
308
309 /// Caching configuration.
310 caching: Caching,
311
312 /// The cache with loggers and level filters.
313 ///
314 /// The nodes form a tree ‒ each one potentially holding a cache entry (or not) and might have
315 /// some children.
316 ///
317 /// When updating, the whole path from the root is cloned in a copy-on-write manner and the Arc
318 /// here is switched. In case of collisions (eg. someone already replaced the root since
319 /// starting the update), the update is just thrown away.
320 cache: Arc<ArcSwap<CacheNode>>,
321}
322
323impl Logger {
324 /// Creates a new logger.
325 ///
326 /// It defaults to having a filter for [`Debug`][LevelFilter::Debug].
327 pub fn new(py: Python<'_>, caching: Caching) -> PyResult<Self> {
328 let logging = py.import("logging")?;
329 Ok(Self {
330 top_filter: LevelFilter::Debug,
331 filters: HashMap::new(),
332 logging: logging.into(),
333 caching,
334 cache: Default::default(),
335 })
336 }
337
338 /// Installs this logger as the global one.
339 ///
340 /// When installing, it also sets the corresponding [maximum level][log::set_max_level],
341 /// constructed using the filters in this logger.
342 pub fn install(self) -> Result<ResetHandle, SetLoggerError> {
343 let handle = self.reset_handle();
344 let level = cmp::max(
345 self.top_filter,
346 self.filters
347 .values()
348 .copied()
349 .max()
350 .unwrap_or(LevelFilter::Off),
351 );
352 log::set_boxed_logger(Box::new(self))?;
353 log::set_max_level(level);
354 Ok(handle)
355 }
356
357 /// Provides the reset handle of this logger.
358 ///
359 /// Note that installing the logger also returns a reset handle. This function is available if,
360 /// for example, the logger will be passed to some other logging system that connects multiple
361 /// loggers together.
362 pub fn reset_handle(&self) -> ResetHandle {
363 ResetHandle(Arc::clone(&self.cache))
364 }
365
366 /// Configures the default logging filter.
367 ///
368 /// Log messages will be filtered according a filter. If one provided by a
369 /// [`filter_target`][Logger::filter_target] matches, it takes preference. If none matches,
370 /// this one is used.
371 ///
372 /// The default filter if none set is [`Debug`][LevelFilter::Debug].
373 pub fn filter(mut self, filter: LevelFilter) -> Self {
374 self.top_filter = filter;
375 self
376 }
377
378 /// Sets a filter for a specific target, overriding the default.
379 ///
380 /// This'll match targets with the same name and all the children in the module hierarchy. In
381 /// case multiple match, the most specific one wins.
382 ///
383 /// With this configuration, modules will log in the following levels:
384 ///
385 /// ```rust
386 /// # use log::LevelFilter;
387 /// # use pyo3_log::Logger;
388 ///
389 /// Logger::default()
390 /// .filter(LevelFilter::Warn)
391 /// .filter_target("xy".to_owned(), LevelFilter::Debug)
392 /// .filter_target("xy::aa".to_owned(), LevelFilter::Trace);
393 /// ```
394 ///
395 /// * `whatever` => `Warn`
396 /// * `xy` => `Debug`
397 /// * `xy::aa` => `Trace`
398 /// * `xy::aabb` => `Debug`
399 pub fn filter_target(mut self, target: String, filter: LevelFilter) -> Self {
400 self.filters.insert(target, filter);
401 self
402 }
403
404 /// Finds a node in the cache.
405 ///
406 /// The hierarchy separator is `::`.
407 fn lookup(&self, target: &str) -> Option<Arc<CacheNode>> {
408 if self.caching == Caching::Nothing {
409 return None;
410 }
411
412 let root = self.cache.load();
413 let mut node: &Arc<CacheNode> = &root;
414 for segment in target.split("::") {
415 match node.children.get(segment) {
416 Some(sub) => node = sub,
417 None => return None,
418 }
419 }
420
421 Some(Arc::clone(node))
422 }
423
424 /// Logs stuff
425 ///
426 /// Returns a logger to be cached, if any. If it already found a cached logger or if caching is
427 /// turned off, returns None.
428 fn log_inner(
429 &self,
430 py: Python<'_>,
431 record: &Record,
432 cache: &Option<Arc<CacheNode>>,
433 ) -> PyResult<Option<Py<PyAny>>> {
434 let msg = format!("{}", record.args());
435 let log_level = map_level(record.level());
436 let target = record.target().replace("::", ".");
437 let cached_logger = cache
438 .as_ref()
439 .and_then(|node| node.local.as_ref())
440 .map(|local| &local.logger);
441 let (logger, cached) = match cached_logger {
442 Some(cached) => (cached.bind(py).clone(), true),
443 None => (
444 self.logging
445 .bind(py)
446 .getattr("getLogger")?
447 .call1((&target,))?,
448 false,
449 ),
450 };
451 // We need to check for this ourselves. For some reason, the logger.handle does not check
452 // it. And besides, we can save ourselves few python calls if it's turned off.
453 if is_enabled_for(&logger, record.level())? {
454 let none = py.None();
455 // TODO: kv pairs, if enabled as a feature?
456 let record = logger.call_method1(
457 "makeRecord",
458 (
459 target,
460 log_level,
461 record.file(),
462 record.line().unwrap_or_default(),
463 msg,
464 PyTuple::empty(py), // args
465 &none, // exc_info
466 ),
467 )?;
468 logger.call_method1("handle", (record,))?;
469 }
470
471 let cache_logger = if !cached && self.caching != Caching::Nothing {
472 Some(logger.into())
473 } else {
474 None
475 };
476
477 Ok(cache_logger)
478 }
479
480 fn filter_for(&self, target: &str) -> LevelFilter {
481 let mut start = 0;
482 let mut filter = self.top_filter;
483 while let Some(end) = target[start..].find("::") {
484 if let Some(f) = self.filters.get(&target[..start + end]) {
485 filter = *f;
486 }
487 start += end + 2;
488 }
489 if let Some(f) = self.filters.get(target) {
490 filter = *f;
491 }
492
493 filter
494 }
495
496 fn enabled_inner(&self, metadata: &Metadata, cache: &Option<Arc<CacheNode>>) -> bool {
497 let cache_filter = cache
498 .as_ref()
499 .and_then(|node| node.local.as_ref())
500 .map(|local| local.filter)
501 .unwrap_or_else(LevelFilter::max);
502
503 metadata.level() <= cache_filter && metadata.level() <= self.filter_for(metadata.target())
504 }
505
506 fn store_to_cache(&self, py: Python<'_>, target: &str, entry: CacheEntry) {
507 let path = target.split("::");
508
509 let orig = self.cache.load();
510 // Construct a new cache structure and insert the new root.
511 let new = orig.store_to_cache_recursive(py, path, entry);
512 // Note: In case of collision, the cache update is lost. This is fine, as we simply lose a
513 // tiny bit of performance and will cache the thing next time.
514 //
515 // We err on the side of losing it here (instead of overwriting), because if the cache is
516 // reset, we don't want to re-insert the old value we have.
517 self.cache.compare_and_swap(orig, new);
518 }
519}
520
521impl Default for Logger {
522 fn default() -> Self {
523 Python::attach(|py| {
524 Self::new(py, Caching::LoggersAndLevels).expect("Failed to initialize python logging")
525 })
526 }
527}
528
529impl Log for Logger {
530 fn enabled(&self, metadata: &Metadata) -> bool {
531 let cache = self.lookup(metadata.target());
532
533 self.enabled_inner(metadata, &cache)
534 }
535
536 fn log(&self, record: &Record) {
537 let cache = self.lookup(record.target());
538
539 if self.enabled_inner(record.metadata(), &cache) {
540 Python::attach(|py| {
541 // If an exception were triggered before this attempt to log,
542 // store it to the side for now and restore it afterwards.
543 let maybe_existing_exception = PyErr::take(py);
544 match self.log_inner(py, record, &cache) {
545 Ok(Some(logger)) => {
546 let filter = match self.caching {
547 Caching::Nothing => unreachable!(),
548 Caching::Loggers => LevelFilter::max(),
549 Caching::LoggersAndLevels => extract_max_level(logger.bind(py))
550 .unwrap_or_else(|e| {
551 // See detailed NOTE below
552 e.restore(py);
553 LevelFilter::max()
554 }),
555 };
556
557 let entry = CacheEntry { filter, logger };
558 self.store_to_cache(py, record.target(), entry);
559 }
560 Ok(None) => (),
561 Err(e) => {
562 // NOTE: If an exception was triggered _during_ logging, restore it as current Python exception.
563 // We have to use PyErr::restore because we cannot return a PyResult from the Log trait's log method.
564 e.restore(py);
565 }
566 };
567
568 // If there was a prior exception, restore it now
569 // This ensures that the earliest thrown exception will be the one that's visible to the caller.
570 if let Some(e) = maybe_existing_exception {
571 e.restore(py);
572 }
573 })
574 }
575 }
576
577 fn flush(&self) {}
578}
579
580fn map_level(level: Level) -> usize {
581 match level {
582 Level::Error => 40,
583 Level::Warn => 30,
584 Level::Info => 20,
585 Level::Debug => 10,
586 Level::Trace => 5,
587 }
588}
589
590fn is_enabled_for(logger: &Bound<'_, PyAny>, level: Level) -> PyResult<bool> {
591 let level = map_level(level);
592 logger.call_method1("isEnabledFor", (level,))?.is_truthy()
593}
594
595fn extract_max_level(logger: &Bound<'_, PyAny>) -> PyResult<LevelFilter> {
596 use Level::*;
597 for l in &[Trace, Debug, Info, Warn, Error] {
598 if is_enabled_for(logger, *l)? {
599 return Ok(l.to_level_filter());
600 }
601 }
602
603 Ok(LevelFilter::Off)
604}
605
606/// Installs a default instance of the logger.
607///
608/// In case a logger is already installed, an error is returned. On success, a handle to reset the
609/// internal caches is returned.
610///
611/// The default logger has a filter set to [`Debug`][LevelFilter::Debug] and caching enabled to
612/// [`LoggersAndLevels`][Caching::LoggersAndLevels].
613pub fn try_init() -> Result<ResetHandle, SetLoggerError> {
614 Logger::default().install()
615}
616
617/// Similar to [`try_init`], but panics if there's a previous logger already installed.
618pub fn init() -> ResetHandle {
619 try_init().unwrap()
620}
621
622#[cfg(test)]
623mod tests {
624 use super::*;
625
626 #[test]
627 fn default_filter() {
628 let logger = Logger::default();
629 assert_eq!(logger.filter_for("hello_world"), LevelFilter::Debug);
630 assert_eq!(logger.filter_for("hello_world::sub"), LevelFilter::Debug);
631 }
632
633 #[test]
634 fn set_filter() {
635 let logger = Logger::default().filter(LevelFilter::Info);
636 assert_eq!(logger.filter_for("hello_world"), LevelFilter::Info);
637 assert_eq!(logger.filter_for("hello_world::sub"), LevelFilter::Info);
638 }
639
640 #[test]
641 fn filter_specific() {
642 let logger = Logger::default()
643 .filter(LevelFilter::Warn)
644 .filter_target("hello_world".to_owned(), LevelFilter::Debug)
645 .filter_target("hello_world::sub".to_owned(), LevelFilter::Trace);
646 assert_eq!(logger.filter_for("hello_world"), LevelFilter::Debug);
647 assert_eq!(logger.filter_for("hello_world::sub"), LevelFilter::Trace);
648 assert_eq!(
649 logger.filter_for("hello_world::sub::multi::level"),
650 LevelFilter::Trace
651 );
652 assert_eq!(
653 logger.filter_for("hello_world::another"),
654 LevelFilter::Debug
655 );
656 assert_eq!(
657 logger.filter_for("hello_world::another::level"),
658 LevelFilter::Debug
659 );
660 assert_eq!(logger.filter_for("other"), LevelFilter::Warn);
661 }
662}