Add SecretManager tracing

[qfel]

This is mostly for debugging unit tests (well, a bit late but still). I imagine may be also useful for app-level logging (it seems we use tracing for that already?) - let me know if the verbosity levels should be tuned.

Contains:

• Add the asynctrace dev-only module (for printing traces in a format useful in tokio unit tests)
• Factor out parts of manager::Worker::run into separate methods (for easier tracing)
• Instrument SecretManager code for tracing

[howardjohn]

Whats wrong with the standard subscriber?

[qfel]

Heh I guess I didn't end up putting in the details after all. Pretty much the sole reason is to have time measured via tokio::time::Instant::now() (and print maybe trees, but there are packages for that). When running tests with paused time, it helps a lot in understanding what's happening.

You can cargo test --lib identity::manager::tests -- --nocapture for sample output:

identity::manager::tests::test_forget_pending
  @0 run
    @0 handle_request req=Fetch(spiffe://test/ns/test/sa/test, RealTime)
      @0 request queued foo="bar"
    @0 fetch_certificate id=spiffe://test/ns/test/sa/test
    @1 handle_request req=Forget(Spiffe { trust_domain: "test", namespace: "test", service_account: "test" })
      @1 the identity will be forgotten once the current certificate fetch completes
  @0 fetch_certificate_pri id=spiffe://test/ns/test/sa/test
    @0 start_fetch id=spiffe://test/ns/test/sa/test
    @0-1 wait
  @1 forget_certificate id=spiffe://test/ns/test/sa/test
identity::manager::tests::test_duplicate_requests
  @0 start_fetch id=spiffe://test/ns/test/sa/id1
  @0 start_fetch id=spiffe://test/ns/test/sa/id1
  @0 start_fetch id=spiffe://test/ns/test/sa/id1
  @0 start_fetch id=spiffe://test/ns/test/sa/id1
  @0-1000 wait
  @0 run
    @0 handle_request req=Fetch(spiffe://test/ns/test/sa/id1, RealTime)
      @0 request queued foo="bar"
    @0-1000 fetch_certificate id=spiffe://test/ns/test/sa/id1
    @1000 handle_fetch_results id=spiffe://test/ns/test/sa/id1
  @1000 wait
  @1000 wait
  @1000 wait

[howardjohn]

So basically converting timestamps into delta-time-since-test-start?

Kind of annoying to have to have this massive implementation just to add that, but it does seem useful

[qfel]

Delta and (more importantly) using tokio's Instant::now. That's because in unit tests it can be controlled (paused time) and seeing exact timestamps in a controlled time environment is much more useful than wall time.

It started out as my fun mini-project (even more than ztunnel is) to figure out how tracing works, but the interface to the module is minimal and the module itself is cfg(test). So I figured we can just as well submit it and it will either grow or rot without affecting too much.

[howardjohn]

Ahh, fake time as well, that makes sense.

[qfel]

So, should we merge it? Alternatively I can factor out the tracing annotations and submit just that.

[istio-testing]

PR needs rebase.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.