Meta: Tracing

[seanmonstar]

hyper uses tracing for logging and events. This issue is meant to be a meta or tracking issue around the overall usage of tracing inside hyper. Eventually, users should be able to depend on certain spans and events. Which exactly, we need to figure out.

Relevant issues

• Document that hyper is using tracing #2498
• Design spans specific to the server
• Design spans specific to the client
• By hyper 1.0, make tracing support "unstable" if not also 1.0

[taqtiqa-mark]

@seanmonstar do you want to ignore events that are not in the context of a span? Currently, it appears these events come from within Hyper, as well as external crates, e.g. want and mio

Using:

1. the current tracing code (still early),
2. the example client_json,
3. the existing Hyper code without any instrumentation,

the span-free events currently look like:

Hyper tracing event:
  level=Level(Info)
  target="client_json_tracing"
  name="event examples/client_json_tracing.rs:38"
  field=status value=true
  field=answer value=42
  field=message value=first event
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::pool"
  name="event src/client/pool.rs:636"
  field=message value=checkout waiting for idle connection: ("http", jsonplaceholder.typicode.com)
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::connect::http"
  name="event src/client/connect/http.rs:277"
  field=message value=Http::connect; scheme=Some("http"), host=Some("jsonplaceholder.typicode.com"), port=None
Hyper tracing event:
  level=Level(Debug)
  target="hyper::client::connect::dns"
  name="event src/client/connect/dns.rs:122"
  field=message value=resolving host="jsonplaceholder.typicode.com"
Hyper tracing event:
  level=Level(Debug)
  target="hyper::client::connect::http"
  name="event src/client/connect/http.rs:531"
  field=message value=connecting to 172.67.131.170:80
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
  field=log.target value=mio::poll
  field=log.module_path value=mio::poll
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.7.14/src/poll.rs
  field=log.line value=478
Hyper tracing event:
  level=Level(Debug)
  target="hyper::client::connect::http"
  name="event src/client/connect/http.rs:534"
  field=message value=connected to 172.67.131.170:80
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::conn"
  name="event src/client/conn.rs:851"
  field=message value=client handshake Http1
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::client"
  name="event src/client/client.rs:486"
  field=message value=handshake complete, spawning background dispatcher task
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=signal: Want
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=341
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=signal found waiting giver, notifying
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=355
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Busy }
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=poll_want: taker wants!
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=200
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::pool"
  name="event src/client/pool.rs:678"
  field=message value=checkout dropped for ("http", jsonplaceholder.typicode.com)
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::role"
  name="event src/proto/h1/role.rs:1015"
  field=message value=Client::encode method=GET, body=None
Hyper tracing event:
  level=Level(Debug)
  target="hyper::proto::h1::io"
  name="event src/proto/h1/io.rs:278"
  field=message value=flushed 59 bytes
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Init, writing: KeepAlive, keep_alive: Busy }
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:173"
  field=message value=Conn::read_head
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::io"
  name="event src/proto/h1/io.rs:227"
  field=message value=received 1412 bytes
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::role"
  name="event src/proto/h1/role.rs:877"
  field=message value=Response.parse
  field=bytes value=1412
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::role"
  name="event src/proto/h1/role.rs:886"
  field=message value=Response.parse Complete(1016)
Hyper tracing event:
  level=Level(Debug)
  target="hyper::proto::h1::io"
  name="event src/proto/h1/io.rs:193"
  field=message value=parsed 23 headers
Hyper tracing event:
  level=Level(Debug)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:196"
  field=message value=incoming body is chunked encoding
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:106"
  field=message value=decode; state=Chunked(Size, 0)
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:211"
  field=message value=Read chunk hex size
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:211"
  field=message value=Read chunk hex size
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:211"
  field=message value=Read chunk hex size
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:211"
  field=message value=Read chunk hex size
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:211"
  field=message value=Read chunk hex size
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:292"
  field=message value=Chunk size is 5645
Hyper tracing event:
  level=Level(Debug)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:298"
  field=message value=incoming chunked header: 0x160D (5645 bytes)
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:315"
  field=message value=Chunked read, remaining=5645
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Body(Chunked(Body, 5255)), writing: KeepAlive, keep_alive: Busy }
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:106"
  field=message value=decode; state=Chunked(Body, 5255)
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:315"
  field=message value=Chunked read, remaining=5255
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::io"
  name="event src/proto/h1/io.rs:227"
  field=message value=received 5262 bytes
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Body(Chunked(BodyCr, 0)), writing: KeepAlive, keep_alive: Busy }
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:106"
  field=message value=decode; state=Chunked(BodyCr, 0)
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:211"
  field=message value=Read chunk hex size
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:211"
  field=message value=Read chunk hex size
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:292"
  field=message value=Chunk size is 0
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::decode"
  name="event src/proto/h1/decode.rs:134"
  field=message value=end of chunked
Hyper tracing event:
  level=Level(Debug)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:272"
  field=message value=incoming body completed
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:446"
  field=message value=maybe_notify; read_from_io blocked
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=signal: Want
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=341
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=signal found waiting giver, notifying
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=355
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=signal: Want
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=341
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=poll_want: taker wants!
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=200
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::pool"
  name="event src/client/pool.rs:329"
  field=message value=put; add idle connection for ("http", jsonplaceholder.typicode.com)
Hyper tracing event:
  level=Level(Debug)
  target="hyper::client::pool"
  name="event src/client/pool.rs:376"
  field=message value=pooling idle connection for ("http", jsonplaceholder.typicode.com)
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=signal: Want
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=341
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Init, writing: Init, keep_alive: Idle }
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::pool"
  name="event src/client/pool.rs:764"
  field=message value=idle interval checking for expired
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::dispatch"
  name="event src/proto/h1/dispatch.rs:590"
  field=message value=client tx closed
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:923"
  field=message value=State::close_read()
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:929"
  field=message value=State::close_write()
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:710"
  field=message value=flushed({role=client}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
Hyper tracing event:
  level=Level(Trace)
  target="hyper::proto::h1::conn"
  name="event src/proto/h1/conn.rs:717"
  field=message value=shut down IO complete
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=deregistering event source from poller
  field=log.target value=mio::poll
  field=log.module_path value=mio::poll
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/mio-0.7.14/src/poll.rs
  field=log.line value=609
Hyper tracing event:
  level=Level(Trace)
  target="log"
  name="log event"
  field=message value=signal: Closed
  field=log.target value=want
  field=log.module_path value=want
  field=log.file value=/home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/want-0.3.0/src/lib.rs
  field=log.line value=330
Hyper tracing event:
  level=Level(Trace)
  target="hyper::client::pool"
  name="event src/client/pool.rs:755"
  field=message value=pool closed, canceling idle interval

[taqtiqa-mark]

Recording some issues related to OpenTelemetry, these do not appear to impact other layers (json, print, jounald).
Context: With OTel none of the data shown above is currently visible. We are not alone, and existing issues are still open. As they are resolved the OTel tracing story in Hyper will improve:

• Representing events with no clear operation/span to map the event to open-telemetry/opentelemetry-specification#1682
• Clarify if zero-duration spans are valid? open-telemetry/opentelemetry-specification#2125
• Add trace-id as a field for other tracing layers open-telemetry/opentelemetry-rust#625
• Allow configuring a formatter with extra fields to include tokio-rs/tracing#1531
• Include Trace ID and Span ID in formatted logs tokio-rs/tracing#1481

[Geal]

Adding some context on seanmonstar/warp#923: from a server point of view, it would be useful to have a span that is valid from the first byte received to the last byte sent. Otherwise, when using the Service trait with a chunked response, a span created in the service will not include any event sent when writing the body. Currently they appear under their own trace id, different from the request's trace id.

Such a span would need to be changed for each new request on an existing connection (in keep alive) for integration with opentelemetry.

I have looked a bit at how it could be implemented, at least for HTTP1, that would require adding a span member to proto::h1::conn::Conn and enter the span on every operation. I can make an attempt at it if there is no ongoing work in it right now

[davidpdrsn]

@Geal this is exactly how tower-http's Trace middleware works. The span it creates lasts from request is received until the entire response body is sent (or earlier if the client doesn't consume the entire body).

[Geal]

@davidpdrsn Thanks, that worked perfectly

[EliSnow]

Related #56