UDS timeout appears to be triggering a NodeJS crash from unhandled EPIPE exception

[bataras]

We're running a heavily loaded NodeJS app in Fargate using the dd-trace node lib, running datadog agent in a sidecar, sending metrics and traces to it via UDS. "Heavily loaded" means 10s of K websocket connections with event loop delays sporadically spiking over 1,000ms with bursts of traffic, but otherwise good in the normal case.

We sometimes see a top level uncaught exception EPIPE error that crashes the app. Unfortunately, with Node it's been impossible to see the full stack. But when this happens, we see this log in the datadog agent a few hundred ms before the app:

agent log:
2025-02-19T23:25:30.916-08:00 - 2025-02-20 07:25:30 UTC | TRACE | ERROR | (pkg/trace/api/api.go:618 in handleTraces) | Cannot decode v0.4 traces payload: read unix /var/run/datadog/apm.socket->@: i/o timeout

app log:
2025-02-19T23:25:31.325-08:00 Uncaught Exception: [Error] [uncaughtException] write EPIPE: undefined

If we set DD_TRACE_PARTIAL_FLUSH_MIN_SPANS to 100 (from the default of 1000), the frequency of these errors drops to -almost- 0. But not completely. It still happens once in a while across a cluster handling millions of connections.

I think this is happening for the following reasons:

The agent:

datadog-agent/pkg/trace/api/api.go

Line 585 in 69867d9

case r.recvsem <- struct{}{}:

And a race window in NodeJS itself:
nodejs/node#55952

In handleTraces(), the agent is doing a select, waiting for a semaphore or a "time.After", but it's not also selecting on req.Context().Done() which is a context WithTimeout that is initialized with a different timeout by timeoutMiddleware(), initialized in buildMux()

So my guess is the agent is ungracefully closing the connection rather than sending a graceful response as from case <-time.After...

And this ungraceful UDS close is hitting the small race window within NodeJS itself (linked above)

[ajgajg1134]

Thanks for the very detailed write-up! This does seem like a pretty straightforward change for us to make, and it would improve how we perform when a client closes a connection early, avoiding us doing unnecessary work. I'm not sure how this would cause us to close a connection incorrectly though as that's normally handled by http when the server handler returns. (Although some quick googling around the ResponseWriter did not reveal how it behaves when a connection was closed by the client 🤔 so it's possible there's some weird behavior here)

That specific error log about decoding the trace payload typically occurs when the client closed the connection unexpectedly, e.g. when the client hits a timeout and the trace-agent is unable to read the full body of the payload.

If you'd like us to investigate your specific setup a bit closer please feel free to open a support ticket (and link this github issue). This will let us take a closer look at the metrics here, possibly collect an agent flare and see if there's any other options to resolving this.

[bataras]

thanks for the fast reply. yeah it's possible the client (app) had an event loop lag happen between opening the connection and starting to send the body. Or while sending the body if it's big enough. The agent timed out, closed the connection and the client got an EPIPE when it came back from its event loop coma.

I have a ticket open. we've descreased DD_TRACE_PARTIAL_FLUSH_MIN_SPANS. So it -feels- like the lag coma is nailing us between the connection open and 1st byte of body rather than in the middle of a longer body. I think if I increase the agent timeout, maybe double it, that'll be enough to drive the change of it happening down to basically 0

[bataras]

looks like DD_APM_RECEIVER_TIMEOUT will do it. And the default is 5 seconds. I can't find it documented anywhere though. eg it's not here: https://docs.datadoghq.com/containers/docker/apm/?tab=linux#docker-apm-agent-environment-variables

[ajgajg1134]

Yeah this variable was* undocumented previously as most customers shouldn't adjust it. Did adjusting it for your specific issue help out here?

*I've opened #34590 to add some docs here since it's nice to have parameters documented, even if we don't recommend changing them in most cases

[bataras]

Yeah bumping DD_APM_RECEIVER_TIMEOUT from 5 to 10. works. That timeout seems to directly correlate to event loop lag/delay in our nodejs app. Our app has bursts of load (which is a separate issue) that can drive EL lag in a kind of bell curve from sub-ms to over 5s and down again. We're logging when we get these EPIPE errors. And the logs line up with a timeline in bumps of EL lag. Right when the lag curve crosses 5s going up and then again coming down, the EPIPE exceptions start and also go up and down in quantity matching the amplitude of the EL lag curve.

[dd-octo-sts]

This issue has been automatically marked as stale because it has not had activity in the past 15 days.

It will be closed in 30 days if no further activity occurs. If this issue is still relevant, adding a comment will keep it open. Also, you can always reopen the issue if you missed the window.

Thank you for your contributions!