split info spans when logging request IDs

[joeshaw]

Otherwise we end up with log messages that include multiple request
IDs when we are processing concurrent requests.

[joeshaw]

Following #146, concurrent requests would look like:

2024-08-26T23:23:14.155726Z  INFO request{id=5}:request{id=14}:request{id=18}:request{id=23}:request{id=39}:request{id=51}:request{id=60}:request{id=61}:request{id=62}:request{id=76}:request{id=80}:request{id=115}:request{id=117}:request{id=119}:request{id=129}:request{id=135}:request{id=141}:request{id=147}: request completed using 1.7 MB of WebAssembly heap

This PR addresses that by using two info spans, one for the tokio task itself and one for handling the request after reading off the receiver channel.

[cee-dub]

Is the tokio task like a "global span" or is the scope a bit smaller than that? Two reasons:

• It could be a memory leak
• not sure of the utility of a single span for a whole series of requests

Also, my question might be irrelevant if I'm thinking of something like OTEL tracing and this is a more basic thing.

[joeshaw]

The tokio task is the thing that runs the Wasm guest code, so the first span applies only to that task.

The bigger issue I think was the span across the receiver.await. What I think is happening is that each incoming request was creating a span, then blocking waiting for the response. When the response was popped off, there were still a bunch of spans still alive and blocking on their own, so you got request IDs for each of the waiting ones.

This breaks things into two spans, with the same data (the request ID). One for the task which tokio runs (this is basically a revert of #146), and then another one that's created just after the response is taken off the receiver channel, and only applies to the work after it's done.

[cee-dub]

Ah ha, I see #416 and how this relates. Are there any messages that now lack the request ID on this branch? I imagine perfecting this isn’t currently worth much more effort. Fixing the obvious bug is great.

[joeshaw]

Are there any messages that now lack the request ID on this branch?

I don't think so, but I have only anecdotal evidence. Rrunning 4 services locally and then running a highly parallel integration test suite against them, all the messages that are generated by Viceroy itself include the request ID.