Better indicate which log entries are repeated

[RalfJung]

(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.

[hawkw]

I think something like this seems good, either as an option that can be enabled or as default behavior.

I would probably use the language "OPENING", "ENTERING", "EXITING", and "CLOSING" rather than "STARTING", "CONTINUING", "PAUSING", and "ENDING", as that's more in line with the terminology used in the rest of tracing (although I'd be fine with substituting "STARTING" and "ENDING" for "OPENING" and "CLOSING", as I think that's quite obvious).

[RalfJung]

The terminology was just a strawman; we are using this for stackframes in Miri. "ENTERING" and "EXITING" work fine there, though I assume the order would be "EXITING" and then "RE-ENTERING" or so?
EDIT: Well, on second thought "exiting" sounds maybe a bit too final, usually when you "exit" a frame the frame is just gone and cannot be re-entered. Maybe "suspending" or so would make sense?

"OPENING" and "CLOSING" are a bit odd for stackframes but if that terminology works better for tracing-tree overall, I think we'll manage.

[hawkw]

@RalfJung "Exit" is the terminology used in tracing to refer to leaving a span that might (but is not guaranteed to be) be re-entered. We distinguish between exiting a span, which indicates "this thread is no longer currently in this span", and closing a span, which indicates "this span will not be entered again", in the tracing API, but we don't distinguish between leaving a span temporarily and leaving one permanently — permanently leaving something would just be indicated by an "exit" followed by a "close".

I agree that "suspending" might have been more descriptive for the case where a context is exited but guaranteed to be re-entered, but it seems less accurate in the case where it is being exited and will then be closed permanently. Since we don't know which is taking place at the time where the exit is recorded, we chose the more general terminology. I think seeing a "SUSPENDING" in the logs immediately followed by a "STOPPING" or "CLOSING" wouldn't be too confusing, though.

However, my two cents is that it's better to use the existing tracing terminology in log messages, so that it's as clear as possible what tracing API concepts those messages are generated by. Since there are enter and exit methods which are called to generate those logs, I have a slight preference to use the words "enter" and "exit".

With that said, I'm open to being convinced otherwise — this isn't a strongly-held preference. And, this isn't my crate, so this is all just a suggestion. :)

[oli-obk]

note that PAUSING here doesn't mean that the span is exited temporarily. We're still in the span, we just additionally opened a new span nested within the outer span.

1:main│ ├┐PAUSING basic::server{host="localhost", port=8080}
1:main│ │└┐basic::conn{peer_addr="8.8.8.8", port=18230}

means we are still in the basic::server span, but now basic::conn is on the top of the span stack

[RalfJung]

"Exit" is the terminology used in tracing to refer to leaving a span that might (but is not guaranteed to be) be re-entered. We distinguish between exiting a span, which indicates "this thread is no longer currently in this span", and closing a span, which indicates "this span will not be entered again", in the tracing API, but we don't distinguish between leaving a span temporarily and leaving one permanently — permanently leaving something would just be indicated by an "exit" followed by a "close".

This makes sense. However, keep in mind that this log will likely be read by people that didn't write the code that emits the trace, and thus they are not familiar with tracing terminology.

[davidbarsky]

This makes sense. However, keep in mind that this log will likely be read by people that didn't write the code that emits the trace, and thus they are not familiar with tracing terminology.

By default, I'd prefer to stick with tracing's terminology, but I like the idea of a builder that overrides the naming of the emitted span entry/exit/closure events. I think the below API is not terrible and could make the MIRI debugging nicer for folks less familiar with tokio-rs/tracing:

// name subject to bike-shedding...
let naming = tracing_tree::SpanEvent::builder()
    .on_span_creation("STARTING")
    .on_span_entry("CONTINUING")
    .on_span_exit("SUSPENDING")
    .on_span_close("ENDING");

let layer = HierarchicalLayer::default()
    .with_indent_lines(true)
    .with_indent_amount(2)
    .with_bracketed_fields(true)
    .with_span_event_naming(naming)
    .with_writer(std::io::stderr);

What do y'all think?

[RalfJung]

Sounds reasonable to me, assuming that we are not close to reaching too-many-options-syndrome.

[davidbarsky]

Sounds reasonable to me, assuming that we are not close to reaching too-many-options-syndrome.

I worry about that as well, but I think we'll burn that bridge once we cross it.