dd-trace-js icon indicating copy to clipboard operation
dd-trace-js copied to clipboard

Http trace contains an error when using keep-alive

Open serj026 opened this issue 3 years ago • 3 comments

Hi,

I'm using http agent where keepAlive option is set to true. On every POST http request I can see that http trace contains "error": 1, however status code is 200 and there are no other exceptions in the code.

Example of my code:

const httpAgent = new AgentKeepAlive({
  keepAlive: true,
  maxSockets: Infinity,
  timeout: 60 * 1000,
  freeSocketTimeout: 30 * 1000,
});

tracer.trace('exec.request', { measured: true }, async (execRequestSpan) => {
  const response$ = this.httpService.post(config.url, payload, {
    timeout: config.connectionTimeout,
    headers: getHeaders(config.headers),
    validateStatus: () => true,
    httpAgent,
  });
  const response = await firstValueFrom(response$);
  return response.data;
});

Trace when keep-alive is enable:

{
  "trace_id": "0758c8d70e8fb565",
  "span_id": "1a05373f4cb153e2",
  "parent_id": "2efa44cd43d2951d",
  "name": "http.request",
  "resource": "POST",
  "error": 1,
  "meta": {
    "service": "service_1",
    "version": "0.0.1",
    "runtime-id": "edc59a68-459f-4dd8-875d-4e90069627d1",
    "span.kind": "client",
    "http.method": "POST",
    "http.url": "http://localhost:3000/wl",
    "http.status_code": "200"
  },
  "metrics": {
    "_dd.measured": 1,
    "_sampling_priority_v1": 2
  },
  "start": 1651758081799550000,
  "duration": 18625488,
  "service": "service_1-http-client",
  "type": "http"
}

Trace when keep-alive is disable:

{
  "trace_id": "6d8c5ded5c59790f",
  "span_id": "7a15fb5e80dd1536",
  "parent_id": "686ebd331c35521b",
  "name": "http.request",
  "resource": "POST",
  "error": 0,
  "meta": {
    "service": "service_1",
    "version": "0.0.1",
    "runtime-id": "c5ea6e3f-fdf1-49eb-93ed-8590de758703",
    "span.kind": "client",
    "http.method": "POST",
    "http.url": "http://localhost:3000/wl",
    "http.status_code": "200"
  },
  "metrics": {
    "_dd.measured": 1,
    "_sampling_priority_v1": 2
  },
  "start": 1651758296853733400,
  "duration": 11136475,
  "service": "service_1-http-client",
  "type": "http"
}

Additional details: I found that when the apm:http:client:request:start event is invoked on close event type for http request, storage.getStore().span returns previous span context (tags), therefore span.setTag('error', 1) adds error:1 tag to _spanContext._tags: Annotation on 2022-05-06 at 10-55-48

Could this be a bug in the http plugin? Thanks.

Node.js version 16.13.1 dd-trace version 2.4.0 axios version 0.26.1, also checked with got version 11.8.3

serj026 avatar May 05 '22 14:05 serj026

A similar issue was recently fixed, so this might no longer be an issue in the latest version. Can you try upgrading dd-trace?

rochdev avatar May 26 '22 19:05 rochdev

I updated to v.2.8.0, but still see the same issue.

serj026 avatar Jun 01 '22 05:06 serj026

I couldn't reproduce using the above snippet, although I had to alter it quite a bit to make it run. I also wasn't able to reproduce the incorrect asynchronous context behaviour described in the additional details. Can you share a runnable reproduction snippet that ideally demonstrates both issues?

rochdev avatar Jun 02 '22 16:06 rochdev

Problem is no longer occurs after the version bump. Thanks.

serj026 avatar Sep 28 '22 18:09 serj026