Deadlock in tracing-core v0.1.33 when Drop logs during rebuild_interest

[u-kai]

Bug Report

Version

tracing-core v0.1.33

Platform

Darwin Kernel Version 24.4.0 arm64

Crates

tracing-core

Description

Summary

A potential deadlock can occur in tracing-core v0.1.33 when a Drop implementation with info!() (or similar macros), within a context where LOCKED_DISPATCHERS is write-locked.

This can happen when multiple threads are setting default subscribers, and one thread drops a Layer while another thread is holding the write lock during rebuild_interest.

Reproduction

// Test is written in tracing-subscriber for easier access to necessary imports.
impl Layer<Registry> for MockLayer {}

impl Drop for MockLayer {
    fn drop(&mut self) {
        tracing::info!("MockLayer dropped");
    }
}

#[test]
fn test1() {
    let level_filter = crate::filter::LevelFilter::DEBUG;
    let log_layer = MockLayer.with_filter(level_filter);
    let subscriber = crate::registry().with(log_layer);
    let _guard = tracing::subscriber::set_default(subscriber);
}

#[test]
fn test2() {
    let level_filter = crate::filter::LevelFilter::INFO;
    let log_layer = MockLayer.with_filter(level_filter);
    let subscriber = crate::registry().with(log_layer);
    let _guard = tracing::subscriber::set_default(subscriber);
}

This code can trigger a deadlock if test1 and test2 run in parallel under certain timing conditions.
The issue does not occur consistently, but can be observed intermittently when running the tests repeatedly.

Root Cause

Inside rebuild_interest, a write lock is held on LOCKED_DISPATCHERS, and during that time, Dispatch instances may be dropped. If a Drop implementation performs info!(), it reads from LOCKED_DISPATCHERS, which causes a write-then-read deadlock on a RwLock in the same thread.

Suggested Fix

Modify Rebuilder::for_each and rebuild_interest to retain cloned Dispatch Arc counts until the write is complete, ensuring that Drop (and any logging within it) is deferred.

impl Rebuilder<'_> {
    pub(super) fn for_each(
        &self,
        mut f: impl FnMut(&dispatcher::Dispatch),
    ) -> Vec<crate::Dispatch> {
        let iter = match self {
            Rebuilder::JustOne => {
                dispatcher::get_default(f);
                return vec![]; // no need to return anything
            }
            Rebuilder::Read(vec) => vec.iter(),
            Rebuilder::Write(vec) => vec.iter(),
        };
        let mut guard = vec![];
        iter.filter_map(dispatcher::Registrar::upgrade)
            .for_each(|dispatch| {
                f(&dispatch);
                guard.push(dispatch);
            });
        guard
    }
}

fn rebuild_interest(&self, dispatchers: dispatchers::Rebuilder<'_>) -> Vec<Dispatch> {
    let mut max_level = LevelFilter::OFF;

    /// During `Drop`, if a `Dispatch` triggers a log (e.g. `info!()`), it will attempt to
    /// read from `LOCKED_DISPATCHERS`. If this happens while the current thread holds
    /// a write lock (e.g. during `rebuild_interest`), a deadlock occurs.
    /// To prevent this, we retain `Dispatch` clones until the rebuild completes.
    let _guard = dispatchers.for_each(|dispatch| {
        let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE);
        if level_hint > max_level {
            max_level = level_hint;
        }
    });

    self.for_each(|callsite| {
        rebuild_callsite_interest(callsite, &dispatchers);
    });

    LevelFilter::set_max(max_level);
    _guard
}

If this approach sounds reasonable, I would like to submit a PR myself to address this issue.

Expected behavior

No deadlock should occur, even if Drop on a Layer performs logging while the global dispatcher registry is being modified.