Adds support for undici tracing

[flovilmart]

What does this PR do?

This PR adds support for tracing undici, for the upcoming release.

Closes #1615

Motivation

Undici does not use the standard HTTP / HTTPS modules from node.js.
This is required so we can properly trace undici requests.

Plugin Checklist

• Unit tests.
• TypeScript definitions.
• TypeScript tests.
• API documentation.
• CircleCI jobs/workflows.
• Plugin is exported.

Additional Notes

[flovilmart]

@Qard , any suggestion regarding the node-ext and upstream koa failures? Is my setup wrong?

[Qard]

I'm pretty sure it's due to next.js tests trying to bundle it when it shouldn't. I believe there was a place to exclude things, but I forget where exactly. @rochdev might know how to deal with that.

[flovilmart]

Got bitten by this; https://github.com/nodejs/node/blob/v16.11.1/lib/diagnostics_channel.js#L101-L103;

the channels are weak ref'd and I've spent about 2 days trying to understand why my tracing would not work while deployed and was working from the REPL / tests 😮‍💨
Will adjust the PR.

[rochdev]

any suggestion regarding the node-ext and upstream koa failures? Is my setup wrong?

For upstream koa they are also failing on master so you can ignore them. For next I think rebasing might fix it since there was a recent change to how it's tested.

the channels are weak ref'd and I've spent about 2 days trying to understand why my tracing would not work

We were also bitten by this while implementing diagnostics_channel. This is supposed to be an implementation details but is impacting common use cases enough that it should be changed. I'll open a PR to Node when I have some time.

[flovilmart]

is impacting common use cases enough that it should be changed

glad to know I'm not alone! Will rebase and see how it goes!

[flovilmart]

@rochdev should I gate here for multiple registrations? or is the framework guaranteeing a single installation of the plugin?

[flovilmart]

Hi there! Any update on this one?

[rochdev]

Sorry for the late reply as we've been trying to move the plugin system to diagnostics_channel and figuring out the details of how to properly use it ourselves.

It turns out that undici cannot be instrumented using DC in its current state because it doesn't have the proper channels/events for context propagation, which we need for spans to be connected together properly and for tracking the execution and control flows. This is something we'll have to work with @mcollina to support for both undici and fastify when we have finalized the design. The short version is that in order for AsyncLocalStorage to be used properly, there must be points at which to call enterWith() both at the beginning and synchronous end of a function for a client. Without this we cannot activate the span properly without leaking to the callback. So we need a minimum of 4 events (start, end, async-end, error) and undici only implements 3.

In the meantime, can you alter the integration to monkey-patch undici instead of using DC? It's not ideal, but unfortunately it's the only way short-term, and it will have the benefit of supporting older versions as well. At least most of the current logic should remain untouched other than the instrumentation points.

[rochdev]

A lot of code including this one seems to have been copied from the http plugin. Can it all be deduplicated with some sort of helper? Other helpers can be found in the plugins/util folder, so for example adding a http.js.

For this one specifically, it shouldn't even be needed at all since span.setTag('error', error) now handles this logic for you.

[flovilmart]

perfect! Let me have a look at how I can get the implementation going for the monkey patch as well.

[mcollina]

callback. So we need a minimum of 4 events (start, end, async-end, error) and undici only implements 3.

I do not have the time to look into it right now, but adding the missing one is just a PR away. It would probably take less time and be more maintenance friendly to just do that.

[flovilmart]

@rochdev , if I recap, in order to use diagnostics_channels, we need to implement the event handling through async storage.
We cannot currently properly implement async_storage as we're missing an event from undici, (end or async-end I assume).
@mcollina or @rochdev do you happen to know where this 4th event need to be emitted from? I really wish to move forwards with diags channels, as the monkey patch implementation is not trivial coming from there.

[rochdev]

@flovilmart The events that are needed are basically:

• start: When the operation starts, which would usually be when the function from the public API is called. We need this event to create a span, create a new AsyncLocalStorage store, and add the span to the store.
• end: When the operation ends but on the current stack, so not the entire asynchronous operation but only the synchronous part of it, which would usually be when the function from the public API returns. We need this event to restore the previous store from before the function was called.
• error: When any error occurs, which is needed to attach the error to the current span.
• async-end: When the operation finished completely, including anything asynchronous that it was waiting on. We need this to finish the span.

Additionally, while promises are handled automatically by async_hooks, callbacks are not, so any callback needs to be properly bound to the correct AsyncResource.

So an example fake request function could look something like this:

const { AsyncResource } = require('async_hooks')

function request (callback) {
  const req = {}

  callback = AsyncResource.bind(callback)

  startChannel.publish(req)

  doActualAsyncRequest(req, (err, res) => {
    if (err) {
      errorChannel.publish(err)
    }

    asyncEndChannel.publish(req)

    callback(req, res)
  })

  endChannel.publish(req)
}

[flovilmart]

Oh great! Thanks @rochdev ; let me see how I can get this implemented.

[flovilmart]

@rochdev , I'm curious; and perhaps the current implementation is completely wrong, but given that this implementation keeps a WeakMap of Request -> Spans, isn't it circumventing this problem by manually creating / terminating spans?
I'm currently running this implementation in a production service, and the traces are sane 🤔

[rochdev]

@flovilmart The context is never activated in the current implementation, unlike http, so any child of undici would end up in a different context. Since this is a client, it's less likely to have children, and when it does it could be less often, for example tcp.connect, which is why it appears to be working properly for your use case. However, for tracing we shouldn't assume what can or cannot have children so this should be handled. The problem is that without the missing event, handling it would be impossible since you would have no way to know when the function returns, meaning that the new context holding the span would leak after the function call. The same issue would potentially affect the callback if it's not properly bound with async_hooks.

Unfortunately these are issues that are much easier to solve with monkey-patching, but since undici is in active development it should also be relatively straightforward to add the missing events/bindings to the library itself and then use that in this PR which would only require small changes.

We're also working on a doc to explain how to do tracing using DC, especially since it's much more involved to get it right compared to monkey-patching, which makes it more difficult to use for external contributors.

[flovilmart]

Thanks a lot @rochdev for taking the time for this explanation! I concur that monkey patching is more straightforward then! Let me reevaluate both approaches.

[rochdev]

@flovilmart Sorry for the runaround with this PR. We hadn't quite realized that the current events were incomplete when we recommended trying to use DC for this. Let me know if you need any help to bring this to the finish line or have any questions about either approach.

[flovilmart]

@rochdev no problem! All's good; I did not realize we were missing so many events.

[artur-ma]

@rochdev

async-end: When the operation finished completely, including anything asynchronous that it was waiting on. We need this to finish the span.

Does it mean the "async-end" should be emitted when body is consumed (read end from socket) ?
If so, @flovilmart correct me if im wrong the current implementation with WeakMap is wrong, since the user is receiving "Readable" instance which may be consumed at any time later, means the span does not include the socket read time.

[rochdev]

@artur-ma According to the current implementation for http yes, it would be after the response has been received. However, these are just the bare minimum required for tracing to work at all, but it definitely wouldn't hurt to have more events that are more precise, for example adding some sort of response or headers-received or something similar, which I believe already exist in Undici although I haven't looked for a few weeks.

[flovilmart]

@artur-ma sure, this doesn't include body reading probably it would need it's own span outside of the request span. What do you think? I'm saying outside, as some users may not even read the body, but simply rely on the headers.

[flovilmart]

we init the span early and pass it through the asyncLocalStorage. not sure this is exactly what was intended

[flovilmart]

we keep the request in the WeakMap as for some reason, they're not available in the subsequent diagnostics channels events. Which makes me wonder why? and also if we can rely on this span to exist in the undici:request:create event

[mcollina]

Can you open an issue about this? Or a PR to add them? saving the WeakMap will greatly reduce overhead.

[flovilmart]

Not sure what you mean. Is that more efficient to store through the weak map than the async context?
or would you want something on the request object to add external context in the form of a weak map?

[flovilmart]

@rochdev I believe I made some strides in the right direction:

• calls are now wrapped
• we use diagnostics channels in order to
  • inject span with all the request info
  • inject propagation headers in the request
  • capture connect / abort errors
  • capture status code
• we use the wrapping to
  • initially create the spans
  • propagate the async context
  • properly wrap the pipeline command
  • finish the spans when the promise resolves

I also extracted commons from the http client wrapper as suggested.
The test suite covers both using client.[method] and undici.[method] and ensure both emit traces properly at a high level.

❓ If we want to be extensive, we should run the whole suite with all methods we'll probably find some wholes in there.

The instrumentation is a bit all over the place with the 2 wrapping strategies, I could attempt to simplify a bit 😅.

let me know what you think.

[flovilmart]

@mcollina how would you approach instrumenting reading the response body? Is there a single member that I can wrap on the response and watch for an end event? Ideally, I'd love to add a child span that just represents reading the request body. Is it possible to get an event when the stream starts being consumed? Or should I simply finish the span only when the body end event is emitted?

[mcollina]

This is a bit tricky and I don't have the solution at the top of my head without digging deep into the code.

What I would try first is to add one event listeners for the 'close' event on the stream body itself.

[flovilmart]

Thanks for the tip @mcollina !

[flovilmart]

closing as another implementation is coming.

[ezequielmiranda87]

Hey, there @flovilmart Just wanted to check in on this. Any updates on the new implementation? Thanks.