standard-ai / ya-gcp

Apache License 2.0
7 stars 8 forks source link

Add better tracing support #16

Closed zmitchell closed 1 year ago

zmitchell commented 1 year ago

This PR adds tracing spans to publish/subscribe paths as well as a few debug! events for good measure to aid in debugging. It also adds tracing_subscriber to the pubsub_stream example to visualize the spans and events that were added. With the current clippy settings it's necessary to comment out the #![cfg_attr(not(test), deny(unused))] line in lib.rs in order to compile the tests (it complains about the project_ref method on some pin_project structs), but that's unrelated to this PR.

The output when viewed with tracing_tree contains logs that look like this:

ya_gcp::pubsub::publish_sink::sink_flush{}
  ya_gcp::pubsub::publish_sink::sink_flush{}
    ya_gcp::pubsub::publish_sink::publish_request{}
      0ms DEBUG yup_oauth2::authenticator access token requested for scopes: [https://www.googleapis.com/auth/pubsub]
      0ms DEBUG yup_oauth2::authenticator found valid token in cache: <truncated>
      0ms DEBUG tower::buffer::worker service.ready=true, "processing request"
      ya_gcp::pubsub::publish_sink::sink_flush{}
        ya_gcp::pubsub::publish_sink::sink_flush{}

and this

ya_gcp::pubsub::streaming_subscription::sub_stream_pull{}
  21939ms DEBUG h2::codec::framed_write send, frame=Data { stream_id: StreamId(3) }
  21940ms DEBUG h2::codec::framed_write send, frame=Data { stream_id: StreamId(3) }

Note that the multiple sink_flush spans come from the fact that our flushing logic is recursive.

rnarubin commented 1 year ago

it's necessary to comment out the #![cfg_attr(not(test), deny(unused))] line

Fortunately this has been fixed upstream https://github.com/taiki-e/pin-project/blob/main/CHANGELOG.md#1011---2022-07-02

Including a bump to pin_project 1.0.11 should fix this

zmitchell commented 1 year ago

This looks super useful. From your example it looks like yup_oauth uses tracing spans too? I know tower already does, this is nice interop

Yeah, a lot of the async ecosystem uses tracing since otherwise it's really hard to know the order of operations and what's getting run when.

zmitchell commented 1 year ago

I had to bump the MSRV (1.57.0 -> 1.59.0) in order to get this to compile.

Btw, I learned that you can filter the logs to particular crates and particular levels like this:

$ RUST_LOG=ya_gcp=info,h2=info

That's pretty handy when you want to shut h2 up but see logs/spans from other crates, h2 is pretty chatty.

zmitchell commented 1 year ago

Btw, I can merge this without a review, so we should adjust whatever setting that is to require reviews.