Add responseBodyHook for http request and response #3104

haddasbronfman · 2022-07-21T15:58:02Z

Is your feature request related to a problem? Please describe.

I work on otel distribution, and as part of our HTTP instrumentation, we want to have the HTTP request body and the HTTP response body. These apparently are not easy to get. This is because otel is closing the span before the 'end' callback on my request/response has been triggered.
This is happening here and here

Describe the solution you'd like

I want to add a responseBodyHook of this type:

export interface HttpResponseBodyFunction {
    (span: Span, response: IncomingMessage | ServerResponse, body: String): void;
}

(I think the body should be of type to be String | Buffer, but for POC I tried it with 'String')

Describe alternatives you've considered

In order to get the body, I tried to override the 'end' function in the same way otel overrides it. something like this:

const originalEnd = clientRequest.end;
clientRequest.end = function (..._args: ResponseEndArgs) {
        clientRequest.end = originalEnd;
        span.setAttribute('http.request.body', _args[0] as AttributeValue);
        return clientRequest.end.apply(this, arguments as never);
};

This works but not for all cases, and I think the solution should come from otel, because it shouldn't close the span before the user got the body. The user should have the opportunity to have the body and add attributes according to it to his span.

Additional context

I would like to solve this issue, if this is acceptable can you assign it to me?

The text was updated successfully, but these errors were encountered:

legendecas · 2022-07-25T02:16:30Z

Are requestHook and responseHook sufficient for the problem? You can add body listeners on the given request and response.

haddasbronfman · 2022-07-25T06:37:06Z

I think they are not sufficient. When I tried to use them I added this code to my responseHook:

      const listener = (chunk: any) => {
        bodyHandler.addChunk(chunk); //bodyHandler aggregates the chunks
      };
      response.on('data', listener);

      response.on('end', () => {
        span.setAttribute(SemanticAttributes.HTTP_RESPONSE_BODY, bodyHandler.getChunks());
        response.removeListener('data', listener);
      });

but when the end callback was called, the span was already closed and setAttribute failed.
This happens because the end function (overridden in line 448) is closing the span, and only after that, my end callback is called.

legendecas · 2022-07-25T08:33:17Z

I believe the problem is that response.end is asynchronous -- however, in the instrumentation, it is been treated as a synchronous method.

haddasbronfman · 2022-07-25T09:56:53Z

What do you mean by "treated as a synchronous method"? I see that my end callback is called after the span is closed. what can I do differently?

legendecas · 2022-07-25T14:36:07Z

response.end accepts a callback as the last parameter. Only when the callback is invoked, we can safely assert that the data passed to response.end is sent to the other end. So, I think the span should be marked as ended when the callback of response.end is invoked, which should solve the problem in the OP. I'd believe this is a bug of the http-instrumentation.

haddasbronfman · 2022-07-27T06:29:42Z

But this callback argument is optional

legendecas · 2022-07-29T06:27:08Z

It is asynchronous regardless of the presence of the optional callback.

github-actions · 2022-10-03T06:46:41Z

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days.

dyladan · 2022-10-12T16:28:01Z

@legendecas is there some reason you think this is a bug? If so can you add a priority label for it?

legendecas · 2022-10-13T02:29:52Z

Yeah, the http-instrumentation didn't end the span in the end callback of the response, which may end up finishing the span earlier in conditions mentioned in #3104 (comment).

I'm tagging this as priority:p2 Bugs and spec inconsistencies which cause telemetry to be incomplete or incorrect as it causes correctness issues.

legendecas · 2022-11-14T08:47:51Z

@haddasbronfman I've submitted a fix at #3407. Would you mind verifying if it meets your use case? Thank you.

haddasbronfman · 2022-11-22T06:37:19Z

Hi, I'm no longer working on this so I can't answer for sure. thanks for your solution!

gmann42 · 2023-01-27T15:24:52Z

@legendecas @haddasbronfman @dyladan
Hey folks, I've been trying to capture the body by using responseHook.
However not able to make this work, any inputs/directions please ?

 responseHook: (span, response) => {
          response.on('data', (chunk) => {
            if(!response['myBody']){
              response['myBody'] = [];
              response['myBody'].push(chunk);
            }
            else{
              response['myBody'].push(chunk);
            }
          });
          response.on('end', () => {
            const responseBody = Buffer.concat(response['myBody']).toString();
            console.log('respnse body is', responseBody);
            console.log('response headers are', response.headers);
            span.setAttribute('http.response.body',responseBody);
            span.setAttributes('http.response.headers', response.headers);

          });

legendecas · 2023-01-31T03:07:38Z

@gmann42 response is a writable and writable emit finish when the write has completed.

gmann42 · 2023-01-31T12:07:37Z

@gmann42 response is a writable and writable emit finish when the write has completed.

@legendecas Thanks, I don't quite follow will look at docs.

But I've managed to do this one level above by using opentelemetry-express. Patched the send method of response object from express to add the body as a span attribute.

u11d-michal-miler · 2023-04-14T07:06:06Z

@haddasbronfman I've submitted a fix at #3407. Would you mind verifying if it meets your use case? Thank you.

I confirm the following works fine:

const responseHook = async (
  span: api.Span,
  response: IncomingMessage | ServerResponse,
) => {
  let body = '';
  response.on('data', (chunk: Buffer) => {
    body += chunk.toString();
  });
  response.on('end', () => {
    span.setAttribute('http.response.body', body);
    response.removeAllListeners();
  });
};

haddasbronfman · 2023-04-16T07:23:53Z

@u11d-michal-miler I no longer use this use case.

helloworld · 2023-07-02T02:37:55Z

@legendecas thank you so much for the fix! I'm sorry to bump an old thread here—

@u11d-michal-miler's code example works, but only for non compressed responses. When we have a gzip/deflate/br compressed response, we see gibberish in the span. Here's an example:

const { HttpInstrumentation } = require("@opentelemetry/instrumentation-http");
const { NodeTracerProvider } = require("@opentelemetry/sdk-trace-node");
const { registerInstrumentations } = require("@opentelemetry/instrumentation");
const {
  ConsoleSpanExporter,
  BatchSpanProcessor,
} = require("@opentelemetry/sdk-trace-base");

registerInstrumentations({
  instrumentations: [new HttpInstrumentation({
    responseHook: async (
      span,
      response
    ) => {
      if (!response.headers) return;

      const contentEncoding = response.headers['content-encoding'];
      span.setAttribute('http.response.content_encoding', contentEncoding);

      let body = '';
      response.on('data', (chunk) => {
        body += chunk.toString();
      });
      response.on('end', () => {
        span.setAttribute('http.response.body', body);
        response.removeAllListeners();
      });
    },
  })],
});

const provider = new NodeTracerProvider();
const exporter = new ConsoleSpanExporter();
const processor = new BatchSpanProcessor(exporter);
provider.addSpanProcessor(processor);
provider.register();

const http = require("http");
const axios = require('axios');

const server = http.createServer(async (req, res) => {
  console.log("Request started")
  // No compression
  await axios.get(
    `https://api.github.com/users/defunkt`,
    {
      headers: {
        'Accept-Encoding': 'identity',
        Accept: 'application/vnd.github+json',
      },
    }
  );

  // Gzip compressed response
  await axios.get(
    `https://api.github.com/users/defunkt`,
  );

  res.end("Success");
});

server.listen(3000, () => {
  console.log("Server running at http://localhost:3000");
});

Here we have a server with two requests, one that has a gzip'd response and one that doesn't. Here are the resulting spans:

{
  traceId: 'af939f97f5cc6ed91562669ecf1fa45f',
  parentId: '528bf06e369592df',
  traceState: undefined,
  name: 'GET',
  id: 'aa2ecd5ba2654566',
  kind: 2,
  timestamp: 1688264149851000,
  duration: 95547,
  attributes: {
    'http.url': 'https://api.github.com/users/defunkt',
    'http.method': 'GET',
    'http.target': '/users/defunkt',
    'net.peer.name': 'api.github.com',
    'http.host': 'api.github.com:443',
    'net.peer.ip': '140.82.113.5',
    'net.peer.port': 443,
    'http.status_code': 200,
    'http.status_text': 'OK',
    'http.flavor': '1.1',
    'net.transport': 'ip_tcp',
    'http.response.content_encoding': 'gzip',
    'http.response.body': '\x1F�\b\x00\x00\x00\x00\x00\x00\x03���n�@\x14E\x7F����\x01��1R�E�颕"%m��5�\x18�\x1Df��\x03�E����/�\x13z\x07p�zQ�����}�ǻ�L�R\x19��B\x1EZ�؂���ɂ\x19[�}�f\x1F��m>\x7F���o\x1Fnq_t��۷N�^E������_���6k�t�5$\r]��-O�v�k����A\x19\x07\x172��$F\x0E:��X���\x17�ǆC�K��jm�`/]�G�?Cp5^+S�\x17\x00�sK�Ĉ`�)<��4��\x00�<��\x15\x04\t��;Y̱3!0s4��s\'\x1B;h��ϝjHY3��? ��+�Q?�l!�\x1E|04��\x00\x00�\x1D6k\x169\x12=o��D~\n' +
      "cp2���L�]�\x10�S#��\x0Fx�a\x8A�^\x14uH�Ah/\x11'Q��w�S��\x17a<9A\x15j���0'��V�\x05�\x10�)W�U\x1Eʏ��aˁh�\x0F3?3�\x16\n" +
      'a\x1C\x05*��4�M��B���ͣ"�6st4\x165m�U�\x1F���v���a\x15�AخΩ@��?��ܼ�I8Y�aЛ0RA�D�v\x19G�$����d�ƻGxh��uM�ZF�e��O�t�M�7���/͗u�\x04\x00\x00'
  },
  status: { code: 0 },
  events: [],
  links: []
}
{
  traceId: '301574b2815191e189fc0e714511029b',
  parentId: '28c2684141a1cf96',
  traceState: undefined,
  name: 'GET',
  id: 'bd6658905463b6de',
  kind: 2,
  timestamp: 1688264149932000,
  duration: 92838,
  attributes: {
    'http.url': 'https://api.github.com/users/defunkt',
    'http.method': 'GET',
    'http.target': '/users/defunkt',
    'net.peer.name': 'api.github.com',
    'http.host': 'api.github.com:443',
    'net.peer.ip': '140.82.112.6',
    'net.peer.port': 443,
    'http.response_content_length': 485,
    'http.status_code': 200,
    'http.status_text': 'OK',
    'http.flavor': '1.1',
    'net.transport': 'ip_tcp',
    'http.response.content_encoding': 'gzip',
    'http.response.body': '\x1F�\b\x00\x00\x00\x00\x00\x00\x03���n�@\x14E\x7F����\x01��1R�E�颕"%m��5�\x18�\x1Df��\x03�E����/�\x13z\x07p�zQ�����}�ǻ�L�R\x19��B\x1EZ�؂���ɂ\x19[�}�f\x1F��m>\x7F���o\x1Fnq_t��۷N�^E������_���6k�t�5$\r]��-O�v�k����A\x19\x07\x172��$F\x0E:��X���\x17�ǆC�K��jm�`/]�G�?Cp5^+S�\x17\x00�sK�Ĉ`�)<��4��\x00�<��\x15\x04\t��;Y̱3!0s4��s\'\x1B;h��ϝjHY3��? ��+�Q?�l!�\x1E|04��\x00\x00�\x1D6k\x169\x12=o��D~\n' +
      "cp2���L�]�\x10�S#��\x0Fx�a\x8A�^\x14uH�Ah/\x11'Q��w�S��\x17a<9A\x15j���0'��V�\x05�\x10�)W�U\x1Eʏ��aˁh�\x0F3?3�\x16\n" +
      'a\x1C\x05*��4�M��B���ͣ"�6st4\x165m�U�\x1F���v���a\x15�AخΩ@��?��ܼ�I8Y�aЛ0RA�D�v\x19G�$����d�ƻGxh��uM�ZF�e��O�t�M�7���/͗u�\x04\x00\x00'
  },
  status: { code: 0 },
  events: [],
  links: []
}

I tried updating the response hook like so, but it still doesn't work. My guess is that there is a race condition where we are not seeing all the chunks by the time the response closes.

responseHook: async (
      span,
      response
    ) => {
      const encoding = response.headers['content-encoding'];
      span.setAttribute('http.response.content_encoding', encoding);

      let stream = response;

      // Handle different types of encoding.
      if (['gzip', 'deflate', 'br'].includes(encoding)) {
        const decompress = encoding === 'gzip' ? zlib.createGunzip() :
                          encoding === 'deflate' ? zlib.createInflate() :
                          zlib.createBrotliDecompress();
        
        await pipelineAsync(response, decompress);
        stream = decompress;
      }
      const chunks = [];
      for await (const chunk of stream) {
        chunks.push(chunk.toString());
      }

      const body = chunks.join('');
      span.setAttribute('http.response.body', body);
    },
  })],

Here's a reproduction: HTTP response body reproduction

legendecas · 2023-07-07T09:26:58Z

@helloworld I don't think it is helpful to decompress the server response to collect span attributes. It is computational costing and should be avoided. I'd suggest hooking a server framework instrumentation instead.

helloworld · 2023-07-07T17:00:15Z

@legendecas do you have any pointers to server framework instrumentation I should be looking at? Do you mean express instrumentation, and such?

emilys314 · 2023-11-20T21:00:43Z

I believe I'm encountering the same issue with try to get the response added as a custom attribute.

The requestHook is working fine for me:

new HttpInstrumentation({
      requestHook: (span, req) => {
        let body = "";
        req.on("data", (chunk) => {
          body += chunk;
        });
        req.on("end", (chunk) => {
          span.setAttribute("http.request.body", body);
        });
      }
      // responseHook: async (span, response) => {
      // console.log(response.req);
      // }
    }),

But trying the same thing for the responseHook, the response callback functions don't execute:

responseHook: (span, res) => {
        console.log("This is run");
        res.on("data", (chunk) => {
          console.log("not run");
        });
        res.on("end", (chunk) => {
          console.log("not run");
        });
      }

haddasbronfman added the feature-request label Jul 21, 2022

github-actions bot added the stale label Oct 3, 2022

legendecas added bug Something isn't working pkg:instrumentation-http signal:traces Issues and PRs related to general traces signal and removed feature-request stale labels Oct 8, 2022

legendecas mentioned this issue Nov 14, 2022

fix(instrumentation-http): close server span when response finishes #3407

Merged

4 tasks

legendecas closed this as completed in #3407 Dec 20, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add responseBodyHook for http request and response #3104

Add responseBodyHook for http request and response #3104

haddasbronfman commented Jul 21, 2022 •

edited

Loading

legendecas commented Jul 25, 2022

haddasbronfman commented Jul 25, 2022

legendecas commented Jul 25, 2022

haddasbronfman commented Jul 25, 2022

legendecas commented Jul 25, 2022 •

edited

Loading

haddasbronfman commented Jul 27, 2022

legendecas commented Jul 29, 2022

github-actions bot commented Oct 3, 2022

dyladan commented Oct 12, 2022

legendecas commented Oct 13, 2022

legendecas commented Nov 14, 2022 •

edited

Loading

haddasbronfman commented Nov 22, 2022

gmann42 commented Jan 27, 2023

legendecas commented Jan 31, 2023

gmann42 commented Jan 31, 2023

u11d-michal-miler commented Apr 14, 2023

haddasbronfman commented Apr 16, 2023

helloworld commented Jul 2, 2023

legendecas commented Jul 7, 2023

helloworld commented Jul 7, 2023

emilys314 commented Nov 20, 2023

Add responseBodyHook for http request and response #3104

Add responseBodyHook for http request and response #3104

Comments

haddasbronfman commented Jul 21, 2022 • edited Loading

Is your feature request related to a problem? Please describe.

Describe the solution you'd like

Describe alternatives you've considered

Additional context

legendecas commented Jul 25, 2022

haddasbronfman commented Jul 25, 2022

legendecas commented Jul 25, 2022

haddasbronfman commented Jul 25, 2022

legendecas commented Jul 25, 2022 • edited Loading

haddasbronfman commented Jul 27, 2022

legendecas commented Jul 29, 2022

github-actions bot commented Oct 3, 2022

dyladan commented Oct 12, 2022

legendecas commented Oct 13, 2022

legendecas commented Nov 14, 2022 • edited Loading

haddasbronfman commented Nov 22, 2022

gmann42 commented Jan 27, 2023

legendecas commented Jan 31, 2023

gmann42 commented Jan 31, 2023

u11d-michal-miler commented Apr 14, 2023

haddasbronfman commented Apr 16, 2023

helloworld commented Jul 2, 2023

legendecas commented Jul 7, 2023

helloworld commented Jul 7, 2023

emilys314 commented Nov 20, 2023

haddasbronfman commented Jul 21, 2022 •

edited

Loading

legendecas commented Jul 25, 2022 •

edited

Loading

legendecas commented Nov 14, 2022 •

edited

Loading