subscriber: fix span data for new, exit, and close events

[akinnane]

Motivation

Span on_events don't display correct span data when using JSON formatter and the on_event is triggered from a parent context.
Ref: #1032

[dependencies]
tracing = "0.1.25"
tracing-subscriber = "0.2.17"

use tracing_subscriber::fmt::format::FmtSpan;

fn main() {
    tracing_subscriber::fmt()
        .json()
        .with_current_span(true)
        .with_span_list(true)
        .with_span_events(FmtSpan::FULL)
        .init();

    tracing::info_span!("parent",  foo=42).in_scope(|| {
        tracing::info_span!("child", bar=24).in_scope(|| {
            tracing::info!("logline")
        });
    });
}

{"timestamp":"Mar 29 00:26:03.749","level":"INFO","fields":{"message":"new"},"target":"i1032"}
{"timestamp":"Mar 29 00:26:03.749","level":"INFO","fields":{"message":"enter"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:26:03.750","level":"INFO","fields":{"message":"new"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:26:03.750","level":"INFO","fields":{"message":"enter"},"target":"i1032","span":{"bar":24,"name":"child"},"spans":[{"foo":42,"name":"parent"},{"bar":24,"name":"child"}]}
{"timestamp":"Mar 29 00:26:03.750","level":"INFO","fields":{"message":"logline"},"target":"i1032","span":{"bar":24,"name":"child"},"spans":[{"foo":42,"name":"parent"},{"bar":24,"name":"child"}]}
{"timestamp":"Mar 29 00:26:03.750","level":"INFO","fields":{"message":"exit"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:26:03.750","level":"INFO","fields":{"message":"close","time.busy":"281µs","time.idle":"250µs"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:26:03.750","level":"INFO","fields":{"message":"exit"},"target":"i1032"}
{"timestamp":"Mar 29 00:26:03.750","level":"INFO","fields":{"message":"close","time.busy":"854µs","time.idle":"212µs"},"target":"i1032"}

The enter and logline events correctly show the span subject's metadata. However, the new, exit, and close events show the span's parent span's metadata instead. The final exit and close events show no metadata as there is no grandparent span to retrieve metadata from.

This shows the timeline of events and the span context they display.

<--1--↓--------no-span---------8--9-->
   <--2--3--↓--parent----6--7--↑-->
         <--4--child--5--↑-->

1. new   `parent`
2. enter `parent`
3. new   `child`
4. enter `child`
5. info! `logline`
6. exit  `child`
7. close `child`
8. exit  `parent`
9. close `parent`

This is primarily caused because FomatEvents::format_event uses ctx.ctx.current_span() to determine the context for the current event.

I think the new, close and exit events should show the metadata for the span referenced in the event's message, however, these on_event actions exist outside the context of the referenced span and show the metadata for that context/span instead.

Solution

This change tries to use event.parent() to determine the correct span context for the event, falling back to ctx.ctx.current_span() If there is no event.parent() in the current event. It produces the following output where each JSON line displays the event subject's metadata.

{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"new"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"enter"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"new"},"target":"i1032","span":{"bar":24,"name":"child"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"enter"},"target":"i1032","span":{"bar":24,"name":"child"},"spans":[{"foo":42,"name":"parent"},{"bar":24,"name":"child"}]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"testevent"},"target":"i1032","span":{"bar":24,"name":"child"},"spans":[{"foo":42,"name":"parent"},{"bar":24,"name":"child"}]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"exit"},"target":"i1032","span":{"bar":24,"name":"child"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"close","time.busy":"24.2µs","time.idle":"21.4µs"},"target":"i1032","span":{"bar":24,"name":"child"},"spans":[{"foo":42,"name":"parent"}]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"exit"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[]}
{"timestamp":"Mar 29 00:33:36.552","level":"INFO","fields":{"message":"close","time.busy":"76.4µs","time.idle":"78.1µs"},"target":"i1032","span":{"foo":42,"name":"parent"},"spans":[]}

[akinnane]

Based on the test feedback in #1333 and the improved test from #1350 I've updated this PR to use the record_works test strategy.

[hawkw]

This looks good to me --- I had a couple of non-blocking style suggestions.