Right now a span entry prints something like

path::to::span::name{field=value, field2=value}

or in the case of no fields and just a message

path::to:span::name{message="foo"}

@RalfJung brought this up in rust-lang/rust#75143 (comment)

Basically we could leave the { and } off, as there's no confusion about what belongs to the span and what not like in the regular tracing printer. Additionally the message="foo" could just be "foo" or even foo.

See rust-lang/rust#79238.

(I am not a direct user of this crate but involved via reviewing rust-lang/rust#75143, which will make Miri use this crate)

@oli-obk pointed me to this example of how the crate repeats log entries when subtrees start and end. However, I find it hard to tell which of these are new information vs. repeating old information to increase readability. I made a proposal but I am not sure if that's actually all that much better...

FWIW, Miri already does something like this kind of repetition, and translated back to tracing-tree that would look something like this:

1:mainbasic::hierarchical-example{version=0.1}
1:main├┐basic::hierarchical-example{version=0.1}
1:main│└┐basic::server{host="localhost", port=8080}
1:main│ ├─ms INFO basic starting
1:main│ ├─ms INFO basic listening
1:main│ ├┐PAUSING basic::server{host="localhost", port=8080}
1:main│ │└┐basic::conn{peer_addr="82.9.9.9", port=42381}
1:main│ │ ├─ms DEBUG basic connected
1:main│ │ ├─ms DEBUG basic message received, length=2
1:main│ │┌┘ENDING basic::conn{peer_addr="82.9.9.9", port=42381}
1:main│ ├┘CONTINUING basic::server{host="localhost", port=8080}
1:main│ ├┐PAUSING basic::server{host="localhost", port=8080}
1:main│ │└┐basic::conn{peer_addr="8.8.8.8", port=18230}
1:main│ │ ├─ms DEBUG basic connected
1:main│ │┌┘ENDING basic::conn{peer_addr="8.8.8.8", port=18230}
1:main│ ├┘CONTINUING basic::server{host="localhost", port=8080}
1:main│ ├┐PAUSING basic::server{host="localhost", port=8080}
1:main│ │└┐basic::conn{peer_addr="82.9.9.9", port=42381}
1:main│ │ ├─ms WARN basic weak encryption requested, algo="xor"
1:main│ │ ├─ms DEBUG basic response sent, length=8
1:main│ │ ├─ms DEBUG basic disconnected
1:main│ │┌┘ENDING basic::conn{peer_addr="82.9.9.9", port=42381}
1:main│ ├┘CONTINUING basic::server{host="localhost", port=8080}
1:main│ ├┐PAUSING basic::server{host="localhost", port=8080}
1:main│ │└┐basic::conn{peer_addr="8.8.8.8", port=18230}
1:main│ │ ├─ms DEBUG basic message received, length=5
1:main│ │ ├─ms DEBUG basic response sent, length=8
1:main│ │ ├─ms DEBUG basic disconnected
1:main│ │┌┘ENDING basic::conn{peer_addr="8.8.8.8", port=18230}
1:main│ ├┘CONTINUING basic::server{host="localhost", port=8080}
1:main│ ├─ms WARN basic internal error
1:main│ ├─ms INFO basic exit
1:main│┌┘ENDING basic::server{host="localhost", port=8080}
1:main├┘ENDING basic::hierarchical-example{version=0.1}
1:mainbasic::hierarchical-example{version=0.1}

In fact Miri also prints something like STARTING when the subtree starts, but I am less sure about that.

There are probably better ways to do this, but I find the current rendering hard to interpret.

Would it be possible to publish a new release to crates.io, with the updated dependency from ansi_term to nu_ansi_term? We'd like to use that release once it's ready. Thank you!

verbose_exit(false) and verbose_entry(true):

1:main┐basic::hierarchical-example version=0.1
1:main│└┐basic::server host="localhost", port=8080
1:main│ ├─  0ms  INFO basic starting
1:main│ ├─  3s   INFO basic listening
1:main│ │└┐basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │ ├─  0ms DEBUG basic connected
1:main│ │ ├─301ms DEBUG basic message received, length=2
1:main│ ├─┘basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │└┐basic::conn peer_addr="8.8.8.8", port=18230
1:main│ │ ├─305ms DEBUG basic connected
1:main│ ├─┘basic::conn peer_addr="8.8.8.8", port=18230
1:main│ │└┐basic::foomp 42 <- format string, normal_var=43
1:main│ │ ├─  0ms ERROR basic hello
1:main│ ├─┘basic::foomp 42 <- format string, normal_var=43
1:main│ │└┐basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │ ├─  0ms  WARN basic weak encryption requested, algo="xor"
1:main│ │ ├─303ms DEBUG basic response sent, length=8
1:main│ │ ├─303ms DEBUG basic disconnected
1:main│ ├─┘basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │└┐basic::conn peer_addr="8.8.8.8", port=18230
1:main│ │ ├─  0ms DEBUG basic message received, length=5
1:main│ │ ├─301ms DEBUG basic response sent, length=8
1:main│ │ ├─302ms DEBUG basic disconnected
1:main│ ├─┘basic::conn peer_addr="8.8.8.8", port=18230
1:main│ ├─  4s   WARN basic internal error
1:main│ ├─  4s  ERROR basic this is a log message
1:main│ ├─  4s   INFO basic exit
1:main├─┘basic::server host="localhost", port=8080
1:main┘basic::hierarchical-example version=0.1

verbose_exit(true) and verbose_entry(false):

1:main┐basic::hierarchical-example version=0.1
1:main├┐
1:main├─┐basic::server host="localhost", port=8080
1:main│ ├─  0ms  INFO basic starting
1:main│ ├─  3s   INFO basic listening
1:main│ ├┐
1:main│ ├─┐basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │ ├─  0ms DEBUG basic connected
1:main│ │ ├─303ms DEBUG basic message received, length=2
1:main│ │┌┘
1:main│ ├┘
1:main│ ├┐
1:main│ ├─┐basic::conn peer_addr="8.8.8.8", port=18230
1:main│ │ ├─305ms DEBUG basic connected
1:main│ │┌┘
1:main│ ├┘
1:main│ ├┐
1:main│ ├─┐basic::foomp 42 <- format string, normal_var=43
1:main│ │ ├─  0ms ERROR basic hello
1:main│ │┌┘
1:main│ ├┘
1:main│ ├┐
1:main│ ├─┐basic::conn peer_addr="82.9.9.9", port=42381
1:main│ │ ├─  0ms  WARN basic weak encryption requested, algo="xor"
1:main│ │ ├─300ms DEBUG basic response sent, length=8
1:main│ │ ├─300ms DEBUG basic disconnected
1:main│ │┌┘
1:main│ ├┘
1:main│ ├┐
1:main│ ├─┐basic::conn peer_addr="8.8.8.8", port=18230
1:main│ │ ├─  0ms DEBUG basic message received, length=5
1:main│ │ ├─303ms DEBUG basic response sent, length=8
1:main│ │ ├─303ms DEBUG basic disconnected
1:main│ │┌┘
1:main│ ├┘
1:main│ ├─  4s   WARN basic internal error
1:main│ ├─  4s  ERROR basic this is a log message
1:main│ ├─  4s   INFO basic exit
1:main│┌┘
1:main├┘
1:main┘

Given the code, I believe it is partly caused by the write_span_info eagerly printing the exit span if verbose_entry=true regardless of if the SpanMode::Exit will print anything; and conversely and not printing it if verbose_entry=false but the exit span is SpanMode::Exit { verbose: true }.

My PR: #64 adds a debugging label which allows you too see which event/SpanMode generated a line, so it would help in this issue as well.

That PR is not far of at all either, as both retracing and lazy spans are working using almost the same code

I noticed tracing_tree seemed to be logging a lot for functions i had decorated with instrument, like so:

synth{tm=App(Ann(Lambda(x, Var(x)), Forall(A, Forall(B, Arrow(Arrow(Var(A), Var(B)), Arrow(Var(A), Var(B)))))), Lambda(x, Var(x)))}
├─┐synth{tm=App(Ann(Lambda(x, Var(x)), Forall(A, Forall(B, Arrow(Arrow(Var(A), Var(B)), Arrow(Var(A), Var(B)))))), Lambda(x, Var(x)))}
│ └─┐synth{tm=Ann(Lambda(x, Var(x)), Forall(A, Forall(B, Arrow(Arrow(Var(A), Var(B)), Arrow(Var(A), Var(B))))))}
│   ├─┐synth{tm=Ann(Lambda(x, Var(x)), Forall(A, Forall(B, Arrow(Arrow(Var(A), Var(B)), Arrow(Var(A), Var(B))))))}

which corresponds to only a single nested recursive call, eg synth only gets called with each repeated set of arguments once.

I noticed that verbose_entry defaults to false, but it doesn't seem to be checked anywhere in the codebase, and thus seems to be a no-op. I imagine there should be some check similar to this added for verbose_entry?

I see that tracing tree is using chrono. But, judging from the sample output, only relative times are nessecarry? That is, std::time::Instant should be enough?

Currently, spans are printed when they are created, exited, and when a child span is opened depending on configuration.

However, if you have concurrently running futures which are instrumented (which easily occurs in larger applications) there is no way to tell which span the event belongs to.

Printing the span again when switching span parents, I.e, when a span another span is entered would solve this issue.

Example:

use std::time::Duration;
use tokio::join;
use tracing_subscriber::prelude::*;
use tracing_tree::HierarchicalLayer;

#[tokio::main]
async fn main() {
    tracing_subscriber::registry()
        .with(
            HierarchicalLayer::new(4)
                .with_verbose_entry(true)
                .with_verbose_exit(true)
                .with_indent_lines(true),
        )
        .init();
    let task1 = tokio::spawn(foo());
    tokio::time::sleep(Duration::from_millis(1700)).await;
    let task2 = tokio::spawn(bar());

    let _ = join!(task1, task2);
}

#[tracing::instrument(level = "info")]
async fn foo() {
    loop {
        tokio::time::sleep(Duration::from_millis(500)).await;
        tracing::info!("Foo");
    }
}

#[tracing::instrument(level = "info")]
async fn bar() {
    loop {
        tokio::time::sleep(Duration::from_millis(300)).await;
        tracing::info!("Bar");
    }
}

Output:

┐foo 
├───501ms  INFO Foo
├───1004ms  INFO Foo
├───1507ms  INFO Foo
┐bar 
├───302ms  INFO Bar
├───2008ms  INFO Foo
├───604ms  INFO Bar
├───2510ms  INFO Foo
├───907ms  INFO Bar
├───1208ms  INFO Bar
├───3013ms  INFO Foo
├───1511ms  INFO Bar
├───1813ms  INFO Bar
├───3515ms  INFO Foo
├───2116ms  INFO Bar
├───4017ms  INFO Foo

The output makes it look like Foo is printed from the bar span

Please add a license so that people know if they can use this in their projects.

Thanks for writing this!

If I make a simple webserver with axum that just sleeps for 3 seconds before sending a response, then it works great with just one request at a time:

log{}
  0ms  INFO Will sleep
  3001ms  INFO Done sleeping

log{}
  0ms  INFO Will sleep
  3002ms  INFO Done sleeping

However, if I make three requests simultaneously, then it gets confusing:

log{}
  0ms  INFO Will sleep
log{}
  0ms  INFO Will sleep
log{}
  0ms  INFO Will sleep
  3001ms  INFO Done sleeping

  3001ms  INFO Done sleeping

  3001ms  INFO Done sleeping

It could be complicated, but it would be very useful to make sure that each message is under the correct tree visually, so it looks more like the first example, even if multiple requests were made simultaneously. That was the expectation I had when I tried this library.

The current time precision does not account for durations less than 1ms, rendering them as 0ms. Also, the absence of decimal points in the time unit output often results in events that are hard to distinguish on the timeline when the unit becomes seconds.

For example, the current output looks like this:

┐run{hostname="localhost"}
├─  0ms TRACE Request received
├─┐fetch_httpbin{method=GET, path="/"}
│ ├─  4s  DEBUG Response received, backend=httpbin, status=200 OK, cache_status=MISS
├─┘
├─┐fetch_example{method=GET, path="/"}
│ ├─588ms DEBUG Response received from example, backend=example, status=200 OK, cache_status=HIT
│ ├─┐open_datastore{name="subscriptions"}
│ ├─┘
│ ├─┐read_from_datastore{key="[email protected]"}
│ │ ├─  0ms  WARN Item found, [email protected]
│ ├─┘
├─┘
├─  4s  TRACE Returning response, status=200 OK
┘

I would like to propose adding a configuration mode that allows for higher time precision with decimals in the output.
The output with the proposed changes would look like this:

┐run{hostname="localhost"}
├─ 45.96μs TRACE Request received
├─┐fetch_httpbin{method=GET, path="/"}
│ ├─ 3.70s  DEBUG Response received, backend=httpbin, status=200 OK, cache_status=MISS
├─┘
├─┐fetch_example{method=GET, path="/"}
│ ├─ 587.93ms DEBUG Response received from example, backend=example, status=200 OK, cache_status=HIT
│ ├─┐open_datastore{name="subscriptions"}
│ ├─┘
│ ├─┐read_from_datastore{key="[email protected]"}
│ │ ├─ 43.04μs  WARN Item found, [email protected]
│ ├─┘
├─┘
├─ 4.29s  TRACE Returning response, status=200 OK
┘

Tracing-subscriber 0.3 was released, would be great to see an upgrade here as well.

Currently, the targets of spans and events are not displayed. It would be nice to have the option to enable them (it doesn't really matter to me whether they're on by default or not).

I imagine something like this, based on the example in the README. Note that "example" is the only target.

 
 example::server{host="localhost", port=8080}
    0ms  INFO example: starting
    300ms  INFO example: istening
    example::conn{peer_addr="82.9.9.9", port=42381}
      0ms DEBUG example: connected
      300ms DEBUG example: message received, length=2
    example::conn{peer_addr="8.8.8.8", port=18230}
      300ms DEBUG example:  connected
    example::conn{peer_addr="82.9.9.9", port=42381}
      600ms  WARN example: weak encryption requested, algo="xor"
      901ms DEBUG example: response sent, length=8
      901ms DEBUG example: disconnected
    example::conn{peer_addr="8.8.8.8", port=18230}
      600ms DEBUG example: message received, length=5
      901ms DEBUG example: response sent, length=8
      901ms DEBUG example: disconnected
    1502ms  WARN example: internal error
    1502ms  INFO example: exit

Right now, the tree hierarchy is expressed only with indentation. It would be nice to have the option to draw a line as well, using either ASCII characters like pipes and dashes, or Unicode box drawing characters. Ideally we would auto-detect whether the console supports Unicode, but it could probably start out as a config option.

In rustc and clippy we're using the compiletest-rs framework for committing the output of programs (in that case error messages) to git so we see diffs in PRs and realize if we do accidental changes. It's not trivial to maintain (causes breakage every now and then, uses nightly, probably causes your CI time to go up significantly), but it's very powerful.

Alternatively we could just write tests that write to files that are commited if a specific env var is set and otherwise tests whether the files are the same (so on CI).

Are you interested in either framework for testing the rendered output?

I may have missed it, but how can one add timestamps to output of tracing-tree?

Logging events are printed two indentation level deeper than the scope that produced them rather than one. Minimal example:

use tracing::instrument;
use tracing_subscriber::{prelude::__tracing_subscriber_SubscriberExt, EnvFilter, Registry};
use tracing_tree::HierarchicalLayer;

fn main() {
    let subscriber = Registry::default()
        .with(
            HierarchicalLayer::new(2)
                .with_bracketed_fields(true)
                .with_wraparound(100),
        )
        .with(EnvFilter::from_default_env());
    tracing::subscriber::set_global_default(subscriber).expect("Failed to initialize logging.");

    inst();
}

#[instrument(level = "debug", ret)]
fn inst() -> Result<(), ()> {
    inst2()?;
    tracing::error!("temp");
    Ok(())
}

#[instrument(level = "debug", ret)]
fn inst2() -> Result<(), ()> {
    tracing::error!("temp2");
    Ok(())
}

produces the following output for me:

 inst{}
   inst2{}
       0ms ERROR temp2
       0ms DEBUG return=Ok(())
     0ms ERROR temp
     0ms DEBUG return=Ok(())

In deeply nested logs, this makes it highly non-obvious which events correspond with which span. Furthermore, this doesn't play well with indentation based folding.

Currently, timestamps are padded like this:

    0ms  INFO starting
    300ms  INFO listening

There are always two spaces after the "ms", regardless of how many characters there are in the actual timestamp value. This means that the rest of the message is not aligned, which is ugly.

Ideally, it would look like this:

    0ms    INFO starting
    300ms  INFO listening

See the mostly empty lines in https://github.com/davidbarsky/tracing-tree/blob/main/examples/stderr.stderr.

These also show up when you do not use indent_lines, but are empty, and can result in the logs looking too spread out

Consider this code:

#[tracing::instrument]
async fn a1() {
}

#[tracing::instrument]
async fn a2() {
}

#[tracing::instrument]
async fn t1() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    a1().await;
}

#[tracing::instrument]
async fn t2() {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    a2().await;
}

#[tokio::main]
async fn main() {
    use tracing_subscriber::layer::SubscriberExt;
    use tracing_subscriber::util::SubscriberInitExt;
    tracing_subscriber::Registry::default()
        .with(tracing_tree::HierarchicalLayer::new(4)
            .with_span_retrace(true)
        )
        .init();
    tokio::spawn(t1());
    tokio::time::sleep(std::time::Duration::from_secs(1)).await;
    tokio::spawn(t2());
    tokio::time::sleep(std::time::Duration::from_secs(10)).await;
}

Versions:

├── tracing v0.1.40
│   ├── tracing-attributes v0.1.27 (proc-macro)
│   └── tracing-core v0.1.32
├── tracing-subscriber v0.3.17
│   ├── tracing-core v0.1.32 (*)
│   └── tracing-log v0.1.4
│       └── tracing-core v0.1.32 (*)
└── tracing-tree v0.2.5
    ├── tracing-core v0.1.32 (*)
    ├── tracing-log v0.1.4 (*)
    └── tracing-subscriber v0.3.17 (*)

Here is what I see:

 t1 
 t2 
     a1 
     a2

Here is what I expected to see:

 t1
 t2
 t1
     a1
 t2
     a2

Current output implies that a1 and a2 are both children of t2, which is wrong.

I need support for interleaved futures in my actual application. Examples ( https://github.com/davidbarsky/tracing-tree/blob/8723df3e66d9e244760ece546f7f1ce415a2c953/examples/concurrent.rs ) suggest that I need to add with_span_retrace. As you can see, I added this option, and still get wrong output. That example also suggest with_deferred_spans, but if I add it, I get no output at all, so I omitted this option. I need to see creation of spans

I think it'd be great to use tracing-tree in rust-analyzer (if only to display Chalk logs), but that's not possible as long as it writes to stdout (that's reserved for LSP communication). Could it just write to stderr instead, or alternatively be configurable?

The current implementation of event time formatting only allows for the default date time formatting 2023-10-11 13:57:26.676558 +02:00:00 which can be very verbose and creates long lines in the terminal output.

Proposal

Add an extra field to UtcDateTime and LocalDateTime that allows the user to specify their own time formatter using https://docs.rs/time/latest/time/formatting/trait.Formattable.html

This would allow timestamps such as 13:57:26 or other user preference

The ansi_term crate is no longer maintained: https://rustsec.org/advisories/RUSTSEC-2021-0139

Would you consider replacing it with another library that is maintained, like yansi (which has similar APIs)?

I have a fork of tracing-tree using yansi and would be happy to open a PR.

The license field in Cargo.toml indicates that this package is licensed under "MIT OR Apache-2.0". It's good to have the license(s) text(s) in the repository as well (and into the cargo package) so this work can be properly attributed downstream.

Just for completeness, https://github.com/gimli-rs/addr2line is an example of a similarly licensed package. It includes the texts in LICENSE-APACHE and LICENSE-MIT.

Or, to be honest, this needs to be a trait like FormatTime already is, with an option to disable.

I've noticed that we always configure tracing tree with with_ansi(false) in rust-analyzer, so I think we can shave a couple of dependencies off here!

* I'd like to be able to visually distinguish between a span that has _exited_ and a span that has _closed_. That could be done with durations, but that's not the only approach.
  
  * As I'm writing this comment, I remembered that tracing-tree isn't really used with asynchronous or non-blocking code. Therefore, I'm not sure how useful this feature is _in the first place_.

* One idea I had was to use durations from the _start_ of the span. However, after thinking about it a bit more, I realized that this opens a larger design space that's best discussed in a separate issue. I'd prefer to _not_ block merging this PR on that point.

In the latter case we have to store the opening somewhere, any tips?

Sure! Here's the approach I was thinking of:

* `new_span` creates a [`DateTime<Local>`](https://github.com/davidbarsky/tracing-tree/blob/main/src/lib.rs#L23). Nothing needs to change here.

* In an `on_exit` or `on_close` method, copy [this approach](https://github.com/davidbarsky/tracing-tree/blob/6a81afb008ac2af974620d06491376c329c04893/src/lib.rs#L269-L282) to calculate the elapsed time of the span.

I did not realize all timings are from the start of the current span. I thought they were from the start of the program 🤦

Ok, this seems easy enough to do. Though I'm now also wondering if the start of a span should also have a timing printed, basically giving the time from the start of its parent span.

Is there any reason why the HeirarchicalLayer needs the S: fmt::Debug bound? The code doesn't seem to use it anywhere

Originally reported in rust-lang/rust#78931.

2:rustc INFO rustc_interface::passes Pre-codegen
2:rustcTy interner             total           ty lt ct all
2:rustc    Adt               :   1078 81.3%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Array             :      1  0.1%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Slice             :      1  0.1%,  0.0%   0.0%  0.0%  0.0%
2:rustc    RawPtr            :      2  0.2%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Ref               :      4  0.3%,  0.1%   0.1%  0.0%  0.0%
2:rustc    FnDef             :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    FnPtr             :     76  5.7%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Placeholder       :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Generator         :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    GeneratorWitness  :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Dynamic           :      3  0.2%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Closure           :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Tuple             :     13  1.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Bound             :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Param             :    146 11.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Infer             :      2  0.2%,  0.1%   0.0%  0.0%  0.0%
2:rustc    Projection        :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Opaque            :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc    Foreign           :      0  0.0%,  0.0%   0.0%  0.0%  0.0%
2:rustc                  total   1326         0.2%   0.1%  0.0%  0.0%
2:rustcInternalSubsts interner: #437
2:rustcRegion interner: #355
2:rustcStability interner: #1
2:rustcConst Stability interner: #0
2:rustcAllocation interner: #0
2:rustcLayout interner: #0

I think the issue is that this is multi-line logging, and tracing-tree assumes that there will only be one line?

We will likely end up with super-deep span trees in the rust compiler. One suggestion to not drift right too much was to reset after a specific number of spans. Basically a "wraparound" for the depth. We could additionally dump some extra info at the wraparound. What do you think?

I just tried using tracing-tree on async-heavy code, and that gave me many many messages about spans being entered and exited, without anything actually happening. This is because instrument invokes enter every time the future is polled and exit whenever that poll is done.

So... what I'm wondering is whether we can somehow allow tracing-tree to be used on async code by only emitting messages on a span's new_span invocation and on its on_close invocation instead of on_enter and on_exit. I'm aware this is not "correct" from tracing's Span model, since we'd be missing intermediate enter and exit invocations, but I'm not sure how else to do it without introducing more config flags and state.