From 336e7bda1b5758fe3d715117ecf2ca61b6a1d0f1 Mon Sep 17 00:00:00 2001 From: legendecas Date: Fri, 11 Nov 2022 11:09:06 +0800 Subject: [PATCH 1/3] fix(instrumentation-http): close server span when response finishes --- experimental/CHANGELOG.md | 2 + .../src/http.ts | 92 +++++++++---------- .../src/types.ts | 4 - .../test/functionals/http-enable.test.ts | 18 ++++ 4 files changed, 62 insertions(+), 54 deletions(-) diff --git a/experimental/CHANGELOG.md b/experimental/CHANGELOG.md index f0e7bf5ab3..f874d1166e 100644 --- a/experimental/CHANGELOG.md +++ b/experimental/CHANGELOG.md @@ -12,6 +12,8 @@ All notable changes to experimental packages in this project will be documented ### :bug: (Bug Fix) +* feat(instrumentation-http): close server span when response finishes [#3407](https://github.com/open-telemetry/opentelemetry-js/pull/3407) @legendecas + ### :books: (Refine Doc) ### :house: (Internal) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index 71f3363f2d..035689c6db 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -43,7 +43,6 @@ import { HttpInstrumentationConfig, HttpRequestArgs, Https, - ResponseEndArgs, } from './types'; import * as utils from './utils'; import { VERSION } from './version'; @@ -451,7 +450,7 @@ export class HttpInstrumentation extends InstrumentationBase { }; const startTime = hrTime(); - let metricAttributes: MetricAttributes = utils.getIncomingRequestMetricAttributes(spanAttributes); + const metricAttributes = utils.getIncomingRequestMetricAttributes(spanAttributes); const ctx = propagation.extract(ROOT_CONTEXT, headers); const span = instrumentation._startHttpSpan( @@ -479,54 +478,13 @@ export class HttpInstrumentation extends InstrumentationBase { instrumentation._headerCapture.server.captureRequestHeaders(span, header => request.headers[header]); - // Wraps end (inspired by: - // https://github.com/GoogleCloudPlatform/cloud-trace-nodejs/blob/master/src/instrumentations/instrumentation-connect.ts#L75) - const originalEnd = response.end; - response.end = function ( - this: http.ServerResponse, - ..._args: ResponseEndArgs - ) { - response.end = originalEnd; - // Cannot pass args of type ResponseEndArgs, - const returned = safeExecuteInTheMiddle( - () => response.end.apply(this, arguments as never), - error => { - if (error) { - utils.setSpanWithError(span, error); - instrumentation._closeHttpSpan(span, SpanKind.SERVER, startTime, metricAttributes); - throw error; - } - } - ); - - const attributes = utils.getIncomingRequestAttributesOnResponse( - request, - response - ); - metricAttributes = Object.assign(metricAttributes, utils.getIncomingRequestMetricAttributesOnResponse(attributes)); - - instrumentation._headerCapture.server.captureResponseHeaders(span, header => response.getHeader(header)); - - span - .setAttributes(attributes) - .setStatus({ code: utils.parseResponseStatus(SpanKind.SERVER, response.statusCode) }); - - if (instrumentation._getConfig().applyCustomAttributesOnSpan) { - safeExecuteInTheMiddle( - () => - instrumentation._getConfig().applyCustomAttributesOnSpan!( - span, - request, - response - ), - () => { }, - true - ); - } - - instrumentation._closeHttpSpan(span, SpanKind.SERVER, startTime, metricAttributes); - return returned; - }; + // After 'error', no further events other than 'close' should be emitted. + response.on('finish', () => { + instrumentation._onServerResponseFinish(request, response, span, metricAttributes, startTime); + }); + response.on(errorMonitor, (err: Err) => { + instrumentation._onServerResponseError(span, metricAttributes, startTime, err); + }); return safeExecuteInTheMiddle( () => original.apply(this, [event, ...args]), @@ -661,6 +619,40 @@ export class HttpInstrumentation extends InstrumentationBase { }; } + private _onServerResponseFinish(request: http.IncomingMessage, response: http.ServerResponse, span: Span, metricAttributes: MetricAttributes, startTime: HrTime) { + const attributes = utils.getIncomingRequestAttributesOnResponse( + request, + response + ); + metricAttributes = Object.assign(metricAttributes, utils.getIncomingRequestMetricAttributesOnResponse(attributes)); + + this._headerCapture.server.captureResponseHeaders(span, header => response.getHeader(header)); + + span + .setAttributes(attributes) + .setStatus({ code: utils.parseResponseStatus(SpanKind.SERVER, response.statusCode) }); + + if (this._getConfig().applyCustomAttributesOnSpan) { + safeExecuteInTheMiddle( + () => + this._getConfig().applyCustomAttributesOnSpan!( + span, + request, + response + ), + () => { }, + true + ); + } + + this._closeHttpSpan(span, SpanKind.SERVER, startTime, metricAttributes); + } + + private _onServerResponseError(span: Span, metricAttributes: MetricAttributes, startTime: HrTime, error: Err) { + utils.setSpanWithError(span, error); + this._closeHttpSpan(span, SpanKind.SERVER, startTime, metricAttributes); + } + private _startHttpSpan( name: string, options: SpanOptions, diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/types.ts b/experimental/packages/opentelemetry-instrumentation-http/src/types.ts index c0f2adab34..87e6407702 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/types.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/types.ts @@ -50,10 +50,6 @@ export type Http = typeof http; export type Https = typeof https; // eslint-disable-next-line @typescript-eslint/no-explicit-any export type Func = (...args: any[]) => T; -export type ResponseEndArgs = - | [((() => void) | undefined)?] - | [unknown, ((() => void) | undefined)?] - | [unknown, string, ((() => void) | undefined)?]; export interface HttpCustomAttributeFunction { ( diff --git a/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts b/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts index ecf5191427..57760cae0e 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts @@ -95,6 +95,14 @@ export const responseHookFunction = ( response: IncomingMessage | ServerResponse ): void => { span.setAttribute('custom response hook attribute', 'response'); + // IncomingMessage (Readable) 'end'. + response.on('end', () => { + span.setAttribute('custom incoming message attribute', 'end'); + }); + // ServerResponse (writable) 'finish'. + response.on('finish', () => { + span.setAttribute('custom server response attribute', 'finish'); + }); }; export const startIncomingSpanHookFunction = ( @@ -772,6 +780,7 @@ describe('HttpInstrumentation', () => { const spans = memoryExporter.getFinishedSpans(); const [incomingSpan, outgoingSpan] = spans; + // server request assert.strictEqual( incomingSpan.attributes['custom request hook attribute'], 'request' @@ -780,6 +789,10 @@ describe('HttpInstrumentation', () => { incomingSpan.attributes['custom response hook attribute'], 'response' ); + assert.strictEqual( + incomingSpan.attributes['custom server response attribute'], + 'finish' + ); assert.strictEqual( incomingSpan.attributes['guid'], 'user_guid' @@ -789,6 +802,7 @@ describe('HttpInstrumentation', () => { SpanKind.CLIENT ); + // client request assert.strictEqual( outgoingSpan.attributes['custom request hook attribute'], 'request' @@ -797,6 +811,10 @@ describe('HttpInstrumentation', () => { outgoingSpan.attributes['custom response hook attribute'], 'response' ); + assert.strictEqual( + outgoingSpan.attributes['custom incoming message attribute'], + 'end' + ); assert.strictEqual( outgoingSpan.attributes['guid'], 'user_guid' From a4f54a6d10bbae3a062fd11e2ae008d7f9ca1ebf Mon Sep 17 00:00:00 2001 From: Chengzhong Wu Date: Wed, 7 Dec 2022 11:22:52 +0800 Subject: [PATCH 2/3] fixup! close server spans on response#close --- .../src/http.ts | 7 ++- .../test/functionals/http-enable.test.ts | 61 +++++++++++++++++++ 2 files changed, 67 insertions(+), 1 deletion(-) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index 035689c6db..8e33d643cf 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -479,10 +479,15 @@ export class HttpInstrumentation extends InstrumentationBase { instrumentation._headerCapture.server.captureRequestHeaders(span, header => request.headers[header]); // After 'error', no further events other than 'close' should be emitted. - response.on('finish', () => { + let hasError = false; + response.on('close', () => { + if (hasError) { + return; + } instrumentation._onServerResponseFinish(request, response, span, metricAttributes, startTime); }); response.on(errorMonitor, (err: Err) => { + hasError = true; instrumentation._onServerResponseError(span, metricAttributes, startTime, err); }); diff --git a/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts b/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts index 57760cae0e..fb53a56356 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts @@ -249,6 +249,16 @@ describe('HttpInstrumentation', () => { }); instrumentation.enable(); server = http.createServer((request, response) => { + if (request.url?.includes('/premature-close')) { + response.destroy(); + return; + } + if (request.url?.includes('/hang')) { + // write response headers. + response.write(''); + // hang the request. + return; + } if (request.url?.includes('/ignored')) { provider.getTracer('test').startSpan('some-span').end(); } @@ -840,6 +850,57 @@ describe('HttpInstrumentation', () => { }); }); }); + + it('should have 2 ended span when client prematurely close', async () => { + const promise = new Promise((resolve, reject) => { + const req = http.get(`${protocol}://${hostname}:${serverPort}/hang`, res => { + res.on('close', () => {}); + }); + // close the socket. + setTimeout(() => { + req.destroy(); + }, 10); + + req.on('error', reject); + + req.on('close', () => { + // yield to server to end the span. + setTimeout(resolve, 10); + }); + }); + + await promise; + + const spans = memoryExporter.getFinishedSpans(); + assert.strictEqual(spans.length, 2); + const [serverSpan, clientSpan] = spans.sort((lhs, rhs) => lhs.kind - rhs.kind); + assert.strictEqual(serverSpan.kind, SpanKind.SERVER); + assert.ok(Object.keys(serverSpan.attributes).length >= 6); + + assert.strictEqual(clientSpan.kind, SpanKind.CLIENT); + assert.ok(Object.keys(clientSpan.attributes).length >= 6); + }); + + it('should have 2 ended span when server prematurely close', async () => { + const promise = new Promise(resolve => { + const req = http.get(`${protocol}://${hostname}:${serverPort}/premature-close`); + req.on('error', err => { + resolve(); + }); + }); + + await promise; + + const spans = memoryExporter.getFinishedSpans(); + assert.strictEqual(spans.length, 2); + const [serverSpan, clientSpan] = spans.sort((lhs, rhs) => lhs.kind - rhs.kind); + assert.strictEqual(serverSpan.kind, SpanKind.SERVER); + assert.ok(Object.keys(serverSpan.attributes).length >= 6); + + assert.strictEqual(clientSpan.kind, SpanKind.CLIENT); + assert.strictEqual(clientSpan.status.code, SpanStatusCode.ERROR); + assert.ok(Object.keys(clientSpan.attributes).length >= 6); + }); }); describe('with require parent span', () => { From 2f2a99f91cff166fa12316e70b197ff67f7b2b17 Mon Sep 17 00:00:00 2001 From: Chengzhong Wu Date: Fri, 9 Dec 2022 14:55:20 +0800 Subject: [PATCH 3/3] fixup! apply linter --- .../src/http.ts | 50 +++++++++++++++---- .../test/functionals/http-enable.test.ts | 21 +++++--- 2 files changed, 54 insertions(+), 17 deletions(-) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index 736710a75e..23a3d2ee98 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -487,7 +487,8 @@ export class HttpInstrumentation extends InstrumentationBase { }; const startTime = hrTime(); - const metricAttributes = utils.getIncomingRequestMetricAttributes(spanAttributes); + const metricAttributes = + utils.getIncomingRequestMetricAttributes(spanAttributes); const ctx = propagation.extract(ROOT_CONTEXT, headers); const span = instrumentation._startHttpSpan( @@ -524,11 +525,22 @@ export class HttpInstrumentation extends InstrumentationBase { if (hasError) { return; } - instrumentation._onServerResponseFinish(request, response, span, metricAttributes, startTime); + instrumentation._onServerResponseFinish( + request, + response, + span, + metricAttributes, + startTime + ); }); response.on(errorMonitor, (err: Err) => { hasError = true; - instrumentation._onServerResponseError(span, metricAttributes, startTime, err); + instrumentation._onServerResponseError( + span, + metricAttributes, + startTime, + err + ); }); return safeExecuteInTheMiddle( @@ -684,18 +696,29 @@ export class HttpInstrumentation extends InstrumentationBase { }; } - private _onServerResponseFinish(request: http.IncomingMessage, response: http.ServerResponse, span: Span, metricAttributes: MetricAttributes, startTime: HrTime) { + private _onServerResponseFinish( + request: http.IncomingMessage, + response: http.ServerResponse, + span: Span, + metricAttributes: MetricAttributes, + startTime: HrTime + ) { const attributes = utils.getIncomingRequestAttributesOnResponse( request, response ); - metricAttributes = Object.assign(metricAttributes, utils.getIncomingRequestMetricAttributesOnResponse(attributes)); + metricAttributes = Object.assign( + metricAttributes, + utils.getIncomingRequestMetricAttributesOnResponse(attributes) + ); - this._headerCapture.server.captureResponseHeaders(span, header => response.getHeader(header)); + this._headerCapture.server.captureResponseHeaders(span, header => + response.getHeader(header) + ); - span - .setAttributes(attributes) - .setStatus({ code: utils.parseResponseStatus(SpanKind.SERVER, response.statusCode) }); + span.setAttributes(attributes).setStatus({ + code: utils.parseResponseStatus(SpanKind.SERVER, response.statusCode), + }); if (this._getConfig().applyCustomAttributesOnSpan) { safeExecuteInTheMiddle( @@ -705,7 +728,7 @@ export class HttpInstrumentation extends InstrumentationBase { request, response ), - () => { }, + () => {}, true ); } @@ -713,7 +736,12 @@ export class HttpInstrumentation extends InstrumentationBase { this._closeHttpSpan(span, SpanKind.SERVER, startTime, metricAttributes); } - private _onServerResponseError(span: Span, metricAttributes: MetricAttributes, startTime: HrTime, error: Err) { + private _onServerResponseError( + span: Span, + metricAttributes: MetricAttributes, + startTime: HrTime, + error: Err + ) { utils.setSpanWithError(span, error); this._closeHttpSpan(span, SpanKind.SERVER, startTime, metricAttributes); } diff --git a/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts b/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts index cc727f32a9..fb10580739 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/test/functionals/http-enable.test.ts @@ -846,9 +846,12 @@ describe('HttpInstrumentation', () => { it('should have 2 ended span when client prematurely close', async () => { const promise = new Promise((resolve, reject) => { - const req = http.get(`${protocol}://${hostname}:${serverPort}/hang`, res => { - res.on('close', () => {}); - }); + const req = http.get( + `${protocol}://${hostname}:${serverPort}/hang`, + res => { + res.on('close', () => {}); + } + ); // close the socket. setTimeout(() => { req.destroy(); @@ -866,7 +869,9 @@ describe('HttpInstrumentation', () => { const spans = memoryExporter.getFinishedSpans(); assert.strictEqual(spans.length, 2); - const [serverSpan, clientSpan] = spans.sort((lhs, rhs) => lhs.kind - rhs.kind); + const [serverSpan, clientSpan] = spans.sort( + (lhs, rhs) => lhs.kind - rhs.kind + ); assert.strictEqual(serverSpan.kind, SpanKind.SERVER); assert.ok(Object.keys(serverSpan.attributes).length >= 6); @@ -876,7 +881,9 @@ describe('HttpInstrumentation', () => { it('should have 2 ended span when server prematurely close', async () => { const promise = new Promise(resolve => { - const req = http.get(`${protocol}://${hostname}:${serverPort}/premature-close`); + const req = http.get( + `${protocol}://${hostname}:${serverPort}/premature-close` + ); req.on('error', err => { resolve(); }); @@ -886,7 +893,9 @@ describe('HttpInstrumentation', () => { const spans = memoryExporter.getFinishedSpans(); assert.strictEqual(spans.length, 2); - const [serverSpan, clientSpan] = spans.sort((lhs, rhs) => lhs.kind - rhs.kind); + const [serverSpan, clientSpan] = spans.sort( + (lhs, rhs) => lhs.kind - rhs.kind + ); assert.strictEqual(serverSpan.kind, SpanKind.SERVER); assert.ok(Object.keys(serverSpan.attributes).length >= 6);