http: trace http request / response

PR-URL: #44102
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Paolo Insogna <paolo@cowtech.it>

Author: theanarkh

doc/api/tracing.md

@@ -36,6 +36,7 @@ The available categories are:
 * `node.vm.script`: Enables capture of trace data for the `node:vm` module's
   `runInNewContext()`, `runInContext()`, and `runInThisContext()` methods.
 * `v8`: The [V8][] events are GC, compiling, and execution related.
+* `node.http`: Enables capture of trace data for http request / response.
 
 By default the `node`, `node.async_hooks`, and `v8` categories are enabled.
 

lib/_http_client.js

@@ -64,7 +64,14 @@ const Agent = require('_http_agent');
 const { Buffer } = require('buffer');
 const { defaultTriggerAsyncIdScope } = require('internal/async_hooks');
 const { URL, urlToHttpOptions, searchParamsSymbol } = require('internal/url');
-const { kOutHeaders, kNeedDrain } = require('internal/http');
+const {
+  kOutHeaders,
+  kNeedDrain,
+  isTraceHTTPEnabled,
+  traceBegin,
+  traceEnd,
+  getNextTraceEventId,
+} = require('internal/http');
 const { connResetException, codes } = require('internal/errors');
 const {
   ERR_HTTP_HEADERS_SENT,
@@ -106,6 +113,8 @@ const kError = Symbol('kError');
 const kLenientAll = HTTPParser.kLenientAll | 0;
 const kLenientNone = HTTPParser.kLenientNone | 0;
 
+const HTTP_CLIENT_TRACE_EVENT_NAME = 'http.client.request';
+
 function validateHost(host, name) {
   if (host !== null && host !== undefined && typeof host !== 'string') {
     throw new ERR_INVALID_ARG_TYPE(`options.${name}`,
@@ -376,6 +385,10 @@ ClientRequest.prototype._finish = function _finish() {
       request: this,
     });
   }
+  if (isTraceHTTPEnabled()) {
+    this._traceEventId = getNextTraceEventId();
+    traceBegin(HTTP_CLIENT_TRACE_EVENT_NAME, this._traceEventId);
+  }
 };
 
 ClientRequest.prototype._implicitHeader = function _implicitHeader() {
@@ -660,6 +673,12 @@ function parserOnIncomingClient(res, shouldKeepAlive) {
       response: res,
     });
   }
+  if (isTraceHTTPEnabled() && typeof req._traceEventId === 'number') {
+    traceEnd(HTTP_CLIENT_TRACE_EVENT_NAME, req._traceEventId, {
+      path: req.path,
+      statusCode: res.statusCode,
+    });
+  }
   req.res = res;
   res.req = req;
 

lib/_http_server.js

@@ -55,6 +55,10 @@ const {
 const {
   kOutHeaders,
   kNeedDrain,
+  isTraceHTTPEnabled,
+  traceBegin,
+  traceEnd,
+  getNextTraceEventId,
 } = require('internal/http');
 const {
   defaultTriggerAsyncIdScope,
@@ -174,6 +178,8 @@ const kLenientNone = HTTPParser.kLenientNone | 0;
 const kConnections = Symbol('http.server.connections');
 const kConnectionsCheckingInterval = Symbol('http.server.connectionsCheckingInterval');
 
+const HTTP_SERVER_TRACE_EVENT_NAME = 'http.server.request';
+
 class HTTPServerAsyncResource {
   constructor(type, socket) {
     this.type = type;
@@ -210,6 +216,10 @@ function ServerResponse(req) {
       },
     });
   }
+  if (isTraceHTTPEnabled()) {
+    this._traceEventId = getNextTraceEventId();
+    traceBegin(HTTP_SERVER_TRACE_EVENT_NAME, this._traceEventId);
+  }
 }
 ObjectSetPrototypeOf(ServerResponse.prototype, OutgoingMessage.prototype);
 ObjectSetPrototypeOf(ServerResponse, OutgoingMessage);
@@ -228,6 +238,13 @@ ServerResponse.prototype._finish = function _finish() {
     });
   }
   OutgoingMessage.prototype._finish.call(this);
+  if (isTraceHTTPEnabled() && typeof this._traceEventId === 'number') {
+    const data = {
+      url: this.req?.url,
+      statusCode: this.statusCode,
+    };
+    traceEnd(HTTP_SERVER_TRACE_EVENT_NAME, this._traceEventId, data);
+  }
 };
 
 

lib/internal/http.js

@@ -8,6 +8,11 @@ const {
 } = primordials;
 
 const { setUnrefTimeout } = require('internal/timers');
+const { trace, isTraceCategoryEnabled } = internalBinding('trace_events');
+const {
+  CHAR_LOWERCASE_B,
+  CHAR_LOWERCASE_E,
+} = require('internal/constants');
 
 let utcCache;
 
@@ -26,8 +31,32 @@ function resetCache() {
   utcCache = undefined;
 }
 
+let traceEventId = 0;
+
+function getNextTraceEventId() {
+  return ++traceEventId;
+}
+
+function isTraceHTTPEnabled() {
+  return isTraceCategoryEnabled('node.http');
+}
+
+const traceEventCategory = 'node,node.http';
+
+function traceBegin(...args) {
+  trace(CHAR_LOWERCASE_B, traceEventCategory, ...args);
+}
+
+function traceEnd(...args) {
+  trace(CHAR_LOWERCASE_E, traceEventCategory, ...args);
+}
+
 module.exports = {
   kOutHeaders: Symbol('kOutHeaders'),
   kNeedDrain: Symbol('kNeedDrain'),
   utcDate,
+  traceBegin,
+  traceEnd,
+  getNextTraceEventId,
+  isTraceHTTPEnabled,
 };

test/parallel/test-trace-events-http.js

@@ -0,0 +1,44 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+const path = require('path');
+const tmpdir = require('../common/tmpdir');
+
+const CODE = `
+  const http = require('http');
+  const server = http.createServer((req, res) => {
+    res.end('ok');
+    server.close();
+  }).listen(0, () => {
+    http.get({port: server.address().port});
+  });
+`;
+
+tmpdir.refresh();
+const FILE_NAME = path.join(tmpdir.path, 'node_trace.1.log');
+
+const proc = cp.spawn(process.execPath,
+                      [ '--trace-events-enabled',
+                        '--trace-event-categories', 'node.http',
+                        '-e', CODE ],
+                      { cwd: tmpdir.path });
+
+proc.once('exit', common.mustCall(() => {
+  assert(fs.existsSync(FILE_NAME));
+  fs.readFile(FILE_NAME, common.mustCall((err, data) => {
+    assert(!err);
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+    let count = 0;
+    traces.forEach((trace) => {
+      if (trace.cat === 'node,node.http' &&
+          ['http.server.request', 'http.client.request'].includes(trace.name)) {
+        count++;
+      }
+    });
+    // Two begin, two end
+    assert.strictEqual(count, 4);
+  }));
+}));