Skip to content

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

@ten3roberts

Description

@ten3roberts

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions