should events on an outgoing HTTP request (ClientRequest) object be bound to the Span context for that request?

[trentm]

In a recent private thread, there was a question about whether span.setLabel(...) could be used to add data to the span for an outgoing HTTP request. The issue currently is that there is no place for user code making an outgoing HTTP request to get a reference to the span for that HTTP request. I.e. there is no point in user code where apm.currentSpan returns that active span.

That's because (in "http-shared.js") we don't bind the ClientRequest event emitter to the run-context for that span. We could do so:

diff --git a/examples/trace-http-request.js b/examples/trace-http-request.js
index 1b1aed78..dfab539c 100755
--- a/examples/trace-http-request.js
+++ b/examples/trace-http-request.js
@@ -16,7 +16,7 @@ const apm = require('../').start({

 const http = require('http');

-function makeARequest(url, opts, cb) {
+function makeARequest(url, opts, data, cb) {
   const clientReq = http.request(url, opts, function (clientRes) {
     console.log(
       'client response: %s %s',
@@ -36,6 +36,22 @@ function makeARequest(url, opts, cb) {
     });
   });

+  // Use the 'socket' event as a way to get a reference to the Span for the
+  // outgoing HTTP request. This event should always be called, will be called
+  // before the span is ended, and doesn't interfere with other request
+  // handling.
+  clientReq.on('socket', () => {
+    // This log is an internal convenience to show the current async run context, e.g.:
+    //    AsyncLocalStorageRunContextManager( RunContext(Transaction(79ade48033bcf2c0, 't0'), [Span(484b4f6d8e5e150e, 'POST localhost:8200')]) )
+    console.log('XXX clientReq.on: %s', apm._instrumentation._runCtxMgr);
+    apm.currentSpan?.setLabel('body', data);
+  });
+
+  if (data) {
+    console.log('XXX data: %j', data);
+    clientReq.write(data);
+  }
+
   clientReq.end();
 }

@@ -46,8 +62,13 @@ function makeARequest(url, opts, cb) {
 // https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-transactions.html
 const t0 = apm.startTransaction('t0');
 makeARequest(
-  'http://httpstat.us/200',
-  { headers: { accept: '*/*' } },
+  // 'http://httpstat.us/200',
+  'http://localhost:8200/intake/v2/profile', // Use a local mockapmserver endpoint, instead of relying on httpstat.us being up.
+  {
+    method: 'POST',
+    headers: { accept: '*/*' },
+  },
+  JSON.stringify({ foo: 'bar' }),
   function () {
     t0.end();
   },
diff --git a/lib/instrumentation/http-shared.js b/lib/instrumentation/http-shared.js
index b01397c9..56a5194f 100644
--- a/lib/instrumentation/http-shared.js
+++ b/lib/instrumentation/http-shared.js
@@ -298,7 +298,12 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
         id,
       });

-      ins.bindEmitter(req);
+      // XXX Should we bind `ClientRequest` (https://nodejs.org/api/http.html#class-httpclientrequest)
+      //     events to the span? What does OTel do? Are there possible bad
+      //     side-effects, e.g. child spans being created under this *exit*
+      //     span that would then get dropped?
+      ins.bindEmitterToRunContext(spanRunContext, req);
+      // ins.bindEmitter(req);

       span.action = req.method;
       span.name = req.method + ' ' + getSafeHost(req);

With that change, handlers for the events on http.ClientRequest -- e.g. "socket", "finish" -- would have the currentSpan set. The examples/trace-http-request.js shows an example.

% node examples/trace-http-request.js
{"log.level":"info","@timestamp":"2023-11-15T19:02:14.976Z","log.logger":"elastic-apm-node","ecs.version":"8.10.0","agentVersion":"4.1.0","env":{"pid":90963,"proctitle":"node","os":"darwin 23.1.0","arch":"x64","host":"pink.local","timezone":"UTC-0800","runtime":"Node.js v18.18.2"},"config":{"serviceName":{"source":"start","value":"example-trace-http-request","commonName":"service_name"},"serviceVersion":{"source":"default","value":"4.1.0","commonName":"service_version"},"serverUrl":{"source":"default","value":"http://127.0.0.1:8200/","commonName":"server_url"},"logLevel":{"source":"default","value":"info","commonName":"log_level"}},"activationMethod":"require","message":"Elastic APM Node.js Agent v4.1.0"}
XXX data: "{\"foo\":\"bar\"}"
XXX clientReq.on: AsyncLocalStorageRunContextManager( RunContext(Transaction(8cecf9ae75bd48a8, 't0'), [Span(c7ea6de25175286f, 'POST localhost:8200')]) )
client response: 202 {
  date: 'Wed, 15 Nov 2023 19:02:15 GMT',
  connection: 'close',
  'transfer-encoding': 'chunked'
}
client response body: "{\"accepted\": 1}"

That results in the following span being sent:

    {
        "span": {
            "name": "POST localhost:8200",
            "type": "external",
            "id": "c7ea6de25175286f",
            "transaction_id": "8cecf9ae75bd48a8",
            "parent_id": "8cecf9ae75bd48a8",
            "trace_id": "89727556094e9700ccd3045efb22d63b",
            "subtype": "http",
            "action": "POST",
            "timestamp": 1700074934998914,
            "duration": 22.233,
            "context": {
                "service": {
                    "target": {
                        "type": "http",
                        "name": "localhost:8200"
                    }
                },
                "destination": {
                    "address": "localhost",
                    "port": 8200,
                    "service": {
                        "type": "",
                        "name": "",
                        "resource": "localhost:8200"
                    }
                },
                "http": {
                    "method": "POST",
                    "status_code": 202,
                    "url": "http://localhost:8200/intake/v2/profile"
                },
                "tags": {
                    "body": "{\"foo\":\"bar\"}"
                }
            },
            "sync": false,
            "outcome": "success",
            "sample_rate": 1
        }
    }

Notice the added "body" label (called "tags" in the intake API), added via span.setLabel("body", data).

The question is should we do this? I'm adding this now, not because there is a strong need, but because I'd dug around a little bit and didn't want to lose the context.