LukeMathWalker / LukeMathWalker/tracing-bunyan-formatter

Infinite loop in some circumstances

Open
#33 3 comments 0 reactions 0 assignees View on GitHub
Dominant language
Rust
Stars
112
Forks
44
PR merge metrics
No merged PRs in 30d

Description

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](https://github.com/LukeMathWalker/tracing-bunyan-formatter/blob/master/src/formatting_layer.rs#L228)): 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:
```rust
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");
}
```

Contributor guide

No contributing guide indexed for this repository

Research direction

Reproduce the crash with the provided sample and debug logging, then inspect src/formatting_layer.rs around the conflict warning and BunyanFormattingLayer::on_event(). Trace how the event and current span are selected; done means conflicting fields no longer recurse into an infinite loop or stack overflow while the warning behavior remains covered by a regression test.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
observability-sre
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.