search

davidbarsky / tracing-tree

Apache License 2.0
123 stars 31 forks source link

Using verbose_entry without verbose_exit leads and vice-versa leads to incorrect indent lines #66

Open ten3roberts opened 1 year ago

ten3roberts commented 1 year ago

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: https://github.com/davidbarsky/tracing-tree/pull/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