From be375a307d087b699b08d608504d45279b039967 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Tue, 21 Feb 2023 16:47:26 +0100 Subject: [PATCH 1/9] fix(http): listen to `close` event instead of `end` --- CHANGELOG.md | 1 + .../packages/opentelemetry-instrumentation-http/src/http.ts | 4 ++-- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 640b1072f2..aeb2573360 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,6 +16,7 @@ For experimental package changes, see the [experimental CHANGELOG](experimental/ ### :bug: (Bug Fix) +* fix(http-instrumentation): listen to `response`'s `close` event instead of `end` [#3625](https://github.com/open-telemetry/opentelemetry-js/pull/3625) @SimenB * fix(sdk-trace-web): make `parseUrl()` respect document.baseURI [#3670](https://github.com/open-telemetry/opentelemetry-js/pull/3670) @domasx2 * fix(resource): make properties for async resource resolution optional [#3677](https://github.com/open-telemetry/opentelemetry-js/pull/3677) @pichlermarc diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index 7291780e86..4f788b137e 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -345,8 +345,8 @@ export class HttpInstrumentation extends InstrumentationBase { context.bind(context.active(), response); this._diag.debug('outgoingRequest on response()'); - response.on('end', () => { - this._diag.debug('outgoingRequest on end()'); + response.on('close', () => { + this._diag.debug('outgoingRequest on close()'); let status: SpanStatus; if (response.aborted && !response.complete) { From 523b7d851be6b13ff1a17034bc114aa8d4223765 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Thu, 16 Mar 2023 12:36:54 +0100 Subject: [PATCH 2/9] stop closing span once request closes if we've got a response --- CHANGELOG.md | 2 +- .../opentelemetry-instrumentation-http/src/http.ts | 9 ++++++--- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index aeb2573360..5baf529d40 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,7 +16,7 @@ For experimental package changes, see the [experimental CHANGELOG](experimental/ ### :bug: (Bug Fix) -* fix(http-instrumentation): listen to `response`'s `close` event instead of `end` [#3625](https://github.com/open-telemetry/opentelemetry-js/pull/3625) @SimenB +* fix(http-instrumentation): stop listening to `request`'s `close` event once it has emitted `response` [#3625](https://github.com/open-telemetry/opentelemetry-js/pull/3625) @SimenB * fix(sdk-trace-web): make `parseUrl()` respect document.baseURI [#3670](https://github.com/open-telemetry/opentelemetry-js/pull/3670) @domasx2 * fix(resource): make properties for async resource resolution optional [#3677](https://github.com/open-telemetry/opentelemetry-js/pull/3677) @pichlermarc diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index 4f788b137e..808a48bba1 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -315,6 +315,8 @@ export class HttpInstrumentation extends InstrumentationBase { this._callRequestHook(span, request); } + let requestHasResponse = false; + /* * User 'response' event listeners can be added before our listener, * force our listener to be the first, so response emitter is bound @@ -323,6 +325,7 @@ export class HttpInstrumentation extends InstrumentationBase { request.prependListener( 'response', (response: http.IncomingMessage & { aborted?: boolean }) => { + requestHasResponse = true; const responseAttributes = utils.getOutgoingRequestAttributesOnResponse(response); span.setAttributes(responseAttributes); @@ -345,8 +348,8 @@ export class HttpInstrumentation extends InstrumentationBase { context.bind(context.active(), response); this._diag.debug('outgoingRequest on response()'); - response.on('close', () => { - this._diag.debug('outgoingRequest on close()'); + response.on('end', () => { + this._diag.debug('outgoingRequest on end()'); let status: SpanStatus; if (response.aborted && !response.complete) { @@ -401,7 +404,7 @@ export class HttpInstrumentation extends InstrumentationBase { ); request.on('close', () => { this._diag.debug('outgoingRequest on request close()'); - if (!request.aborted) { + if (!request.aborted && !requestHasResponse) { this._closeHttpSpan(span, SpanKind.CLIENT, startTime, metricAttributes); } }); From 75eacb1d3a5ac447be26644a24a9cb26acce6368 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Sun, 19 Mar 2023 14:58:41 +0100 Subject: [PATCH 3/9] fix one test --- .../test/functionals/http-enable.test.ts | 1 + 1 file changed, 1 insertion(+) 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 5a5588993f..ef0030141a 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 @@ -866,6 +866,7 @@ describe('HttpInstrumentation', () => { `${protocol}://${hostname}:${serverPort}/hang`, res => { res.on('close', () => {}); + res.on('error', () => {}); } ); // close the socket. From 1609b1a39fbc0172ffdb531f296685b6d4f39629 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Sun, 19 Mar 2023 15:02:52 +0100 Subject: [PATCH 4/9] fix other test --- .../packages/opentelemetry-instrumentation-http/src/http.ts | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index 808a48bba1..ee0ffeb51b 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -325,7 +325,11 @@ export class HttpInstrumentation extends InstrumentationBase { request.prependListener( 'response', (response: http.IncomingMessage & { aborted?: boolean }) => { - requestHasResponse = true; + // if there are no other response listeners, we don't wanna set this as there won't ever be any response + if (request.listenerCount('response') > 1) { + requestHasResponse = true; + } + const responseAttributes = utils.getOutgoingRequestAttributesOnResponse(response); span.setAttributes(responseAttributes); From f2c139d6129a57496d1585391241c499aefb44ec Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Mon, 20 Mar 2023 05:01:32 +0000 Subject: [PATCH 5/9] Update experimental/packages/opentelemetry-instrumentation-http/src/http.ts Co-authored-by: Chengzhong Wu --- .../packages/opentelemetry-instrumentation-http/src/http.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index ee0ffeb51b..f36b4333ba 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -325,7 +325,7 @@ export class HttpInstrumentation extends InstrumentationBase { request.prependListener( 'response', (response: http.IncomingMessage & { aborted?: boolean }) => { - // if there are no other response listeners, we don't wanna set this as there won't ever be any response + // if there are no other response listeners, we don't wanna set this as the data of the response is not consumed and no 'end' event is emitted. if (request.listenerCount('response') > 1) { requestHasResponse = true; } From 1f07e5ffad887810593e13d9522a8b30d58e5e64 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Mon, 20 Mar 2023 07:42:50 +0000 Subject: [PATCH 6/9] manually emit `end` event from `close` if one has not already been emited --- .../opentelemetry-instrumentation-http/src/http.ts | 13 +++++++++++++ .../test/functionals/http-enable.test.ts | 2 +- 2 files changed, 14 insertions(+), 1 deletion(-) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index f36b4333ba..8d4561d26c 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -352,8 +352,21 @@ export class HttpInstrumentation extends InstrumentationBase { context.bind(context.active(), response); this._diag.debug('outgoingRequest on response()'); + + // See https://github.com/open-telemetry/opentelemetry-js/pull/3625#issuecomment-1475673533 + let endEmitted = false; + if (semver.lt(process.version, '16.0.0')) { + response.on('close', () => { + this._diag.debug('outgoingRequest on close()'); + if (!endEmitted) { + response.emit('end'); + } + }); + } + response.on('end', () => { this._diag.debug('outgoingRequest on end()'); + endEmitted = true; let status: SpanStatus; if (response.aborted && !response.complete) { 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 ef0030141a..adc8ba3412 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 @@ -866,7 +866,7 @@ describe('HttpInstrumentation', () => { `${protocol}://${hostname}:${serverPort}/hang`, res => { res.on('close', () => {}); - res.on('error', () => {}); + res.on('error', reject); } ); // close the socket. From 225e24a880ab2b5495401f1abd6246531cbf89bc Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Mon, 20 Mar 2023 10:24:44 +0100 Subject: [PATCH 7/9] attempt to add a test --- .../test/functionals/http-enable.test.ts | 41 +++++++++++++++++++ 1 file changed, 41 insertions(+) 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 adc8ba3412..7f70c7118c 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 @@ -16,11 +16,13 @@ import { SpanStatusCode, context, + diag, propagation, Span as ISpan, SpanKind, trace, SpanAttributes, + DiagConsoleLogger, } from '@opentelemetry/api'; import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; import { @@ -269,6 +271,14 @@ describe('HttpInstrumentation', () => { // hang the request. return; } + if (request.url?.includes('/destroy-request')) { + // force flush http response header to trigger client response callback + response.write(''); + setTimeout(() => { + request.socket.destroy(); + }, 100); + return; + } if (request.url?.includes('/ignored')) { provider.getTracer('test').startSpan('some-span').end(); } @@ -920,6 +930,37 @@ describe('HttpInstrumentation', () => { assert.strictEqual(clientSpan.status.code, SpanStatusCode.ERROR); assert.ok(Object.keys(clientSpan.attributes).length >= 6); }); + + it('should not end span multiple times if request socket destroyed before response completes', async () => { + const warnMessages: string[] = []; + diag.setLogger({ + ...new DiagConsoleLogger(), + warn: message => { + warnMessages.push(message); + }, + }); + const promise = new Promise(resolve => { + const req = http.get( + `${protocol}://${hostname}:${serverPort}/destroy-request`, + res => { + res.on('end', () => {}); + res.on('close', () => {}); + res.on('error', () => { + resolve(); + }); + } + ); + // force flush http request header to trigger client response callback + req.write(''); + req.on('error', () => {}); + }); + + await promise; + + diag.disable(); + + assert.strictEqual(warnMessages, []); + }); }); describe('with require parent span', () => { From 684f77f0b57dbb62196019948d71e50d3172065a Mon Sep 17 00:00:00 2001 From: Chengzhong Wu Date: Tue, 11 Apr 2023 20:16:28 +0800 Subject: [PATCH 8/9] fix! nock compatibility --- .../src/http.ts | 58 ++++++++++--------- .../test/functionals/http-enable.test.ts | 14 +++-- 2 files changed, 39 insertions(+), 33 deletions(-) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index 8d4561d26c..c06192541e 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -315,7 +315,10 @@ export class HttpInstrumentation extends InstrumentationBase { this._callRequestHook(span, request); } - let requestHasResponse = false; + /** + * Determines if the request has errored or the response has ended/errored. + */ + let responseFinished = false; /* * User 'response' event listeners can be added before our listener, @@ -325,11 +328,7 @@ export class HttpInstrumentation extends InstrumentationBase { request.prependListener( 'response', (response: http.IncomingMessage & { aborted?: boolean }) => { - // if there are no other response listeners, we don't wanna set this as the data of the response is not consumed and no 'end' event is emitted. - if (request.listenerCount('response') > 1) { - requestHasResponse = true; - } - + this._diag.debug('outgoingRequest on response()'); const responseAttributes = utils.getOutgoingRequestAttributesOnResponse(response); span.setAttributes(responseAttributes); @@ -351,22 +350,13 @@ export class HttpInstrumentation extends InstrumentationBase { ); context.bind(context.active(), response); - this._diag.debug('outgoingRequest on response()'); - - // See https://github.com/open-telemetry/opentelemetry-js/pull/3625#issuecomment-1475673533 - let endEmitted = false; - if (semver.lt(process.version, '16.0.0')) { - response.on('close', () => { - this._diag.debug('outgoingRequest on close()'); - if (!endEmitted) { - response.emit('end'); - } - }); - } - response.on('end', () => { + const endHandler = () => { this._diag.debug('outgoingRequest on end()'); - endEmitted = true; + if (responseFinished) { + return; + } + responseFinished = true; let status: SpanStatus; if (response.aborted && !response.complete) { @@ -401,15 +391,21 @@ export class HttpInstrumentation extends InstrumentationBase { startTime, metricAttributes ); - }); + }; + + response.on('end', endHandler); + // See https://github.com/open-telemetry/opentelemetry-js/pull/3625#issuecomment-1475673533 + if (semver.lt(process.version, '16.0.0')) { + response.on('close', endHandler); + } response.on(errorMonitor, (error: Err) => { this._diag.debug('outgoingRequest on error()', error); + if (responseFinished) { + return; + } + responseFinished = true; utils.setSpanWithError(span, error); - const code = utils.parseResponseStatus( - SpanKind.CLIENT, - response.statusCode - ); - span.setStatus({ code, message: error.message }); + span.setStatus({ code: SpanStatusCode.ERROR, message: error.message }); this._closeHttpSpan( span, SpanKind.CLIENT, @@ -421,12 +417,18 @@ export class HttpInstrumentation extends InstrumentationBase { ); request.on('close', () => { this._diag.debug('outgoingRequest on request close()'); - if (!request.aborted && !requestHasResponse) { - this._closeHttpSpan(span, SpanKind.CLIENT, startTime, metricAttributes); + if (request.aborted || responseFinished) { + return; } + responseFinished = true; + this._closeHttpSpan(span, SpanKind.CLIENT, startTime, metricAttributes); }); request.on(errorMonitor, (error: Err) => { this._diag.debug('outgoingRequest on request error()', error); + if (responseFinished) { + return; + } + responseFinished = true; utils.setSpanWithError(span, error); this._closeHttpSpan(span, SpanKind.CLIENT, 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 7f70c7118c..9a6e413542 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 @@ -871,12 +871,12 @@ describe('HttpInstrumentation', () => { }); it('should have 2 ended span when client prematurely close', async () => { - const promise = new Promise((resolve, reject) => { + const promise = new Promise((resolve) => { const req = http.get( `${protocol}://${hostname}:${serverPort}/hang`, res => { res.on('close', () => {}); - res.on('error', reject); + res.on('error', () => {}); } ); // close the socket. @@ -884,7 +884,7 @@ describe('HttpInstrumentation', () => { req.destroy(); }, 10); - req.on('error', reject); + req.on('error', () => {}); req.on('close', () => { // yield to server to end the span. @@ -940,8 +940,12 @@ describe('HttpInstrumentation', () => { }, }); const promise = new Promise(resolve => { - const req = http.get( + const req = http.request( `${protocol}://${hostname}:${serverPort}/destroy-request`, + { + // Allow `req.write()`. + method: 'POST', + }, res => { res.on('end', () => {}); res.on('close', () => {}); @@ -959,7 +963,7 @@ describe('HttpInstrumentation', () => { diag.disable(); - assert.strictEqual(warnMessages, []); + assert.deepStrictEqual(warnMessages, []); }); }); From 9ebae5e28884d3fb004ea63be195e9c82e69960c Mon Sep 17 00:00:00 2001 From: Chengzhong Wu Date: Wed, 12 Apr 2023 11:15:54 +0800 Subject: [PATCH 9/9] fixup! node.js v14 compatibility and lint --- .../packages/opentelemetry-instrumentation-http/src/http.ts | 5 ++++- .../test/functionals/http-enable.test.ts | 6 +++--- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts index f437148b9e..0b5c166dd5 100644 --- a/experimental/packages/opentelemetry-instrumentation-http/src/http.ts +++ b/experimental/packages/opentelemetry-instrumentation-http/src/http.ts @@ -405,7 +405,10 @@ export class HttpInstrumentation extends InstrumentationBase { } responseFinished = true; utils.setSpanWithError(span, error); - span.setStatus({ code: SpanStatusCode.ERROR, message: error.message }); + span.setStatus({ + code: SpanStatusCode.ERROR, + message: error.message, + }); this._closeHttpSpan( span, SpanKind.CLIENT, 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 9a6e413542..e5b2cebb97 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 @@ -871,7 +871,7 @@ describe('HttpInstrumentation', () => { }); it('should have 2 ended span when client prematurely close', async () => { - const promise = new Promise((resolve) => { + const promise = new Promise(resolve => { const req = http.get( `${protocol}://${hostname}:${serverPort}/hang`, res => { @@ -948,10 +948,10 @@ describe('HttpInstrumentation', () => { }, res => { res.on('end', () => {}); - res.on('close', () => {}); - res.on('error', () => { + res.on('close', () => { resolve(); }); + res.on('error', () => {}); } ); // force flush http request header to trigger client response callback