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::with_gil(|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.allow_threads(|| {
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: PyObject,
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<PyObject>> {
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::with_gil(|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::with_gil(|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}
pyo3_log/lib.rs

pyo3_log/
lib.rs
