From 2753f2a9bc8f1db247c2e842c17d92a17151d4cc Mon Sep 17 00:00:00 2001 From: theanarkh Date: Wed, 3 Aug 2022 01:37:26 +0800 Subject: [PATCH] http: trace http request / response --- doc/api/tracing.md | 1 + lib/_http_client.js | 21 +++++++++++- lib/_http_server.js | 17 ++++++++++ lib/internal/http.js | 29 ++++++++++++++++ test/parallel/test-trace-events-http.js | 44 +++++++++++++++++++++++++ 5 files changed, 111 insertions(+), 1 deletion(-) create mode 100644 test/parallel/test-trace-events-http.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index 7766412ed0b75a..e4ab6f16c50221 100644 --- a/doc/api/tracing.md +++ b/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. diff --git a/lib/_http_client.js b/lib/_http_client.js index 66977351870a80..bd35d4620a7851 100644 --- a/lib/_http_client.js +++ b/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, @@ -101,6 +108,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}`, @@ -370,6 +379,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() { @@ -653,6 +666,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; diff --git a/lib/_http_server.js b/lib/_http_server.js index 6e4147a3ca2050..a2eba953cfc2ba 100644 --- a/lib/_http_server.js +++ b/lib/_http_server.js @@ -55,6 +55,10 @@ const { const { kOutHeaders, kNeedDrain, + isTraceHTTPEnabled, + traceBegin, + traceEnd, + getNextTraceEventId, } = require('internal/http'); const { defaultTriggerAsyncIdScope, @@ -170,6 +174,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; @@ -206,6 +212,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); @@ -223,6 +233,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); + } }; diff --git a/lib/internal/http.js b/lib/internal/http.js index 337d155340f7e6..b20b3cd229efcd 100644 --- a/lib/internal/http.js +++ b/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, }; diff --git a/test/parallel/test-trace-events-http.js b/test/parallel/test-trace-events-http.js new file mode 100644 index 00000000000000..54e3d4f06e492b --- /dev/null +++ b/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); + })); +}));