Expand the "tried to clone" panic with a hint about borrowing parents #1483

joshtriplett · 2021-07-30T09:19:13Z

This may help give the user a hint to start debugging this.

See #688 for further details
on this issue.

This may help give the user a hint to start debugging this. See tokio-rs#688 for further details on this issue.

hawkw

Thanks, this is a great idea!

In tracing 0.2, this issue will be prevented at compile-time, since we've removed the Into<Option<Id>> for &Span that allowed passing a borrowed reference to a parent span. But, in the meantime, hinting at the potential cause of this issue in the panic message is a great idea!

I left a couple minor suggestions. PLMKWYT?

hawkw · 2021-07-30T18:05:04Z

tracing-subscriber/src/registry/sharded.rs

+                This may be caused by consuming a parent span (`parent: span`) rather than borrowing it (`parent: &span`).",
+                id,


Another case where this might occur is if a span is cloned by a subscriber other than the one that originally assigned its ID.

This will never happen when using the tracing::Span type (barring implementation bugs), since the Span retains a reference to the subscriber that assigned its ID, and all operations performed by that span will be performed by that subscriber. However, it may happen in code where Subscriber::clone_span() is manually called on a tracing_core::Id, if that ID was provided by a different subscriber. I wonder if it's also worth mentioning this in the panic message?

I'd be happy to expand the message further if you think that case is common enough to provide debugging assistance for.

I also wonder if a future (incompatible) version of tracing could somehow tag the Id based on the subscriber that issued it, so that you can't mix Id values from different subscribers. (They could all implement a common trait and the type difference could be erased at runtime, but the concrete type could somehow reference the Subscriber using a lifetime.)

I also wonder if a future (incompatible) version of tracing could somehow tag the Id based on the subscriber that issued it, so that you can't mix Id values from different subscribers.

This is essentially what the tracing::Span type represents; it's an Id plus a runtime reference to a subscriber. I'm not sure if tagging IDs with subscriber types at compile-time makes a lot of sense — the loose coupling between the instrumentation-side API with the subscriber is kind of central to how tracing provides a facade layer allowing the subscriber to be modular. Something like what you're proposing here could maybe be possible, but it would only be possible as part of a pretty radical redesign of how tracing works...

I'd be happy to expand the message further if you think that case is common enough to provide debugging assistance for.

I'm less concerned that it's a particularly common case, and more concerned about inadvertently sending the message that passing an &Id to the span macro's parent field is the only way this error might occur, which isn't really the case. Not a big deal either way, though.

hawkw · 2021-07-30T18:06:25Z

tracing-subscriber/src/registry/sharded.rs

@@ -235,7 +235,11 @@ impl Subscriber for Registry {
    fn clone_span(&self, id: &span::Id) -> span::Id {
        let span = self
            .get(&id)
-            .unwrap_or_else(|| panic!("tried to clone {:?}, but no span exists with that ID", id));
+            .unwrap_or_else(|| panic!(


I wonder if we should also consider changing this function (and some other similar ones) to only panic in debug mode, and just perform no operation in release mode (maybe printing a warning?). This way, if the user code does the wrong thing, it will just result in potentially-missing trace data, rather than crashing the program in production.

I'm on the fence about this, since it might make this kind of bug harder to uncover. What do you think?

I would much rather have a crash to debug than have mysteriously missing trace data (that might make it difficult or confounding to debug some other issue). Please keep the panic.

Okay, fair enough. I feel like others have had conflicting opinions in the past ("our software absolutely mustn't crash in production, and it's fine if we lose diagnostics instead"), so I've wondered about trying to make this policy configurable...but that could introduce a lot of complexity.

@hawkw I think the planned fix in future tracing is the right long-term solution, which will void this at compile time. In the short-term, if I have a risk of a run-time issue I'd rather have it caught at compile time.

I wonder: is there any way to make this panic always trigger, such as by putting it unconditionally in the relevant trait impl rather than only if the Id isn't found?

joshtriplett · 2021-07-30T20:04:28Z

In tracing 0.2, this issue will be prevented at compile-time, since we've removed the Into<Option<Id>> for &Span that allowed passing a borrowed reference to a parent span

I thought the problem was passing an owned value (and thus consuming it), and the fix was to pass a borrowed reference?

hawkw · 2021-08-01T00:44:46Z

In tracing 0.2, this issue will be prevented at compile-time, since we've removed the Into<Option<Id>> for &Span that allowed passing a borrowed reference to a parent span

I thought the problem was passing an owned value (and thus consuming it), and the fix was to pass a borrowed reference?

er, yes, I got it backwards...

hawkw

This looks good to me!

The (unrelated) warnings that were breaking CI are fixed on master, so I'm going to go ahead and merge this. Thanks for the PR!

hawkw · 2021-08-01T14:21:11Z

tracing-subscriber/src/registry/sharded.rs

@@ -235,7 +235,11 @@ impl Subscriber for Registry {
    fn clone_span(&self, id: &span::Id) -> span::Id {
        let span = self
            .get(&id)
-            .unwrap_or_else(|| panic!("tried to clone {:?}, but no span exists with that ID", id));
+            .unwrap_or_else(|| panic!(


Okay, fair enough. I feel like others have had conflicting opinions in the past ("our software absolutely mustn't crash in production, and it's fine if we lose diagnostics instead"), so I've wondered about trying to make this policy configurable...but that could introduce a lot of complexity.

@joshtriplett

# 0.2.20 (August 17, 2021) ### Fixed - **fmt**: Fixed `fmt` printing only the first `source` for errors with a chain of sources ([#1460]) - **fmt**: Fixed missing space between level and event in the `Pretty` formatter ([#1498]) - **json**: Fixed `Json` formatter not honoring `without_time` and `with_level` configurations ([#1463]) ### Added - **registry**: Improved panic message when cloning a span whose ID doesn't exist, to aid in debugging issues with multiple subscribers ([#1483]) - **registry**: Improved documentation on span ID generation ([#1453]) Thanks to new contributors @joshtriplett and @lerouxgd, and returning contributor @teozkr, for contributing to this release! [#1460]: #1460 [#1483]: #1483 [#1463]: #1463 [#1453]: #1453

@joshtriplett

# 0.2.20 (August 17, 2021) ### Fixed - **fmt**: Fixed `fmt` printing only the first `source` for errors with a chain of sources ([#1460]) - **fmt**: Fixed missing space between level and event in the `Pretty` formatter ([#1498]) - **json**: Fixed `Json` formatter not honoring `without_time` and `with_level` configurations ([#1463]) ### Added - **registry**: Improved panic message when cloning a span whose ID doesn't exist, to aid in debugging issues with multiple subscribers ([#1483]) - **registry**: Improved documentation on span ID generation ([#1453]) Thanks to new contributors @joshtriplett and @lerouxgd, and returning contributor @teozkr, for contributing to this release! [#1460]: #1460 [#1483]: #1483 [#1463]: #1463 [#1453]: #1453

@joshtriplett

# 0.2.20 (August 17, 2021) ### Fixed - **fmt**: Fixed `fmt` printing only the first `source` for errors with a chain of sources ([#1460]) - **fmt**: Fixed missing space between level and event in the `Pretty` formatter ([#1498]) - **json**: Fixed `Json` formatter not honoring `without_time` and `with_level` configurations ([#1463]) ### Added - **registry**: Improved panic message when cloning a span whose ID doesn't exist, to aid in debugging issues with multiple subscribers ([#1483]) - **registry**: Improved documentation on span ID generation ([#1453]) Thanks to new contributors @joshtriplett and @lerouxrgd, and returning contributor @teozkr, for contributing to this release! [#1460]: #1460 [#1483]: #1483 [#1463]: #1463 [#1453]: #1453 [#1498]: #1498

@joshtriplett

# 0.2.20 (August 17, 2021) ### Fixed - **fmt**: Fixed `fmt` printing only the first `source` for errors with a chain of sources ([tokio-rs#1460]) - **fmt**: Fixed missing space between level and event in the `Pretty` formatter ([tokio-rs#1498]) - **json**: Fixed `Json` formatter not honoring `without_time` and `with_level` configurations ([tokio-rs#1463]) ### Added - **registry**: Improved panic message when cloning a span whose ID doesn't exist, to aid in debugging issues with multiple subscribers ([tokio-rs#1483]) - **registry**: Improved documentation on span ID generation ([tokio-rs#1453]) Thanks to new contributors @joshtriplett and @lerouxrgd, and returning contributor @teozkr, for contributing to this release! [tokio-rs#1460]: tokio-rs#1460 [tokio-rs#1483]: tokio-rs#1483 [tokio-rs#1463]: tokio-rs#1463 [tokio-rs#1453]: tokio-rs#1453 [tokio-rs#1498]: tokio-rs#1498

Expand the "tried to clone" panic with a hint about borrowing parents

e1f3306

This may help give the user a hint to start debugging this. See tokio-rs#688 for further details on this issue.

joshtriplett requested review from hawkw and a team as code owners July 30, 2021 09:19

hawkw approved these changes Jul 30, 2021

View reviewed changes

hawkw approved these changes Aug 1, 2021

View reviewed changes

hawkw merged commit 0af3ea6 into tokio-rs:v0.1.x Aug 1, 2021

joshtriplett deleted the tracing-parent-borrow-hint branch August 3, 2021 21:02

hawkw mentioned this pull request Aug 17, 2021

subscriber: prepare to release v0.2.20 #1514

Merged

davidbarsky mentioned this pull request Sep 26, 2023

chore: backport roughly a year's worth of changes #2728

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Expand the "tried to clone" panic with a hint about borrowing parents #1483

Expand the "tried to clone" panic with a hint about borrowing parents #1483

joshtriplett commented Jul 30, 2021

hawkw left a comment

hawkw Jul 30, 2021

joshtriplett Jul 30, 2021

hawkw Aug 1, 2021

hawkw Aug 1, 2021

hawkw Jul 30, 2021

joshtriplett Jul 30, 2021

hawkw Aug 1, 2021

joshtriplett Aug 3, 2021

joshtriplett commented Jul 30, 2021

hawkw commented Aug 1, 2021

hawkw left a comment

hawkw Aug 1, 2021

		This may be caused by consuming a parent span (`parent: span`) rather than borrowing it (`parent: &span`).",
		id,

Expand the "tried to clone" panic with a hint about borrowing parents #1483

Expand the "tried to clone" panic with a hint about borrowing parents #1483

Conversation

joshtriplett commented Jul 30, 2021

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joshtriplett commented Jul 30, 2021

hawkw commented Aug 1, 2021

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment