Infinite loop in some circumstances

[abusch]

I've encountered an infinite loop (leading to a stack overflow and crash) when the following criteria are met:

1. A span contains a field that conflicts with one of Bunyan's "standard" fields (e.g. name)
2. Debug logging is enabled for the tracing_bunyan_formatter::formatting_layer target

(Note that it is pretty easy to accidentally fall into that scenario. 1. can happen if you add #[instrument] to a function that has a parameter called name, and 2. can happen if you set RUST_LOG=debug to quickly debug something.)

The problem is due to the use of tracing::debug!(...) to warn when there are conflicting fields (for instance this line): An Event is logged, the code collects all the fields from all the parent spans, finds one that is invalid, calls tracing::debug!() which creates a new Event in the current span, which gets dispatched, the code tries to collect all the fields from all the parent spans, and so on...

I'm not sure what the proper fix is here (assuming we want to keep the logs). One option I tried is to make the log event generated by tracing::debug!() not be a child of the current span, by using tracing::debug!(parent: None, "..."), but that didn't work because BunyanFormattingLayer::on_event() doesn't seem to consider the event's parent at all. It always gets the "current span" from the context. I feel like maybe the current span should be retrieved with event.parent().and_then(|id| ctx.span(id)) instead of ctx.lookup_current(), which fixes my test case, but I don't know enough to know if that's correct, or what the side effects would be...

Sample code to reproduce the problem:

use tracing::{info, instrument};
use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::{EnvFilter, Registry};

fn main() {
    let subscriber = Registry::default()
        .with(EnvFilter::builder().parse("debug").unwrap())
        .with(JsonStorageLayer)
        .with(BunyanFormattingLayer::new(
            "bunyan_crash".to_string(),
            std::io::stdout,
        ));
    tracing::subscriber::set_global_default(subscriber).unwrap();

    info!("Calling foo");
    foo("boom");
}

#[instrument]
fn foo(name: &str) {
    // do something
    info!("Hello");
}

[LukeMathWalker]

Thanks for reporting it! Definitely nasty.

Setting the parent to None is something we already do elsewhere (https://github.com/LukeMathWalker/tracing-bunyan-formatter/blob/c506eafde6062da628147e64039ad7602ee1de75/src/storage_layer.rs#L112) to prevent this specific issue. Switching to using the parent() for an event would lead to undesirable side-effects (see https://docs.rs/tracing/latest/tracing/event/struct.Event.html#method.parent) since it would be None for events that are descendants of the current span. A hack could be to use a span rather than an event there 🤔

[abusch]

Oh right, I totally misread what .parent() does... Maybe using is_root() then?

Maybe something like this could work?

        let current_span = if event.is_root() {
            None
        } else {
            ctx.lookup_current()
        };

[LukeMathWalker]

Merged #34 as a stop-gap solution, while we work on #35