From ec3b9c87aa2c79dc8cdcb4023df71dcafc6f08a4 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 4 Sep 2024 08:29:12 -0700 Subject: [PATCH 1/3] fix(instrumentation-redis-4): avoid diag.error spam when configured client URL is the empty string (#2399) Issue #2389 showed that this instrumentation would crash on a Redis client configured with {url: ''} (an empty string). The crash was fixed in #2397. This change avoids the once-crashy code, and hence the diag.error spam, by using the same guard before attempting to parse the configured client URL that the Redis client itself does, if (options?.url), Refs: #2389 --- .../src/utils.ts | 2 +- .../test/redis.test.ts | 32 +++++++++++++++++++ 2 files changed, 33 insertions(+), 1 deletion(-) diff --git a/plugins/node/opentelemetry-instrumentation-redis-4/src/utils.ts b/plugins/node/opentelemetry-instrumentation-redis-4/src/utils.ts index 7bdbf768ac..b7cc79628d 100644 --- a/plugins/node/opentelemetry-instrumentation-redis-4/src/utils.ts +++ b/plugins/node/opentelemetry-instrumentation-redis-4/src/utils.ts @@ -46,7 +46,7 @@ function removeCredentialsFromDBConnectionStringAttribute( diag: DiagLogger, url?: unknown ): string | undefined { - if (typeof url !== 'string') { + if (typeof url !== 'string' || !url) { return; } diff --git a/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts b/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts index 6200b4c1eb..14b439e797 100644 --- a/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts +++ b/plugins/node/opentelemetry-instrumentation-redis-4/test/redis.test.ts @@ -13,6 +13,8 @@ * See the License for the specific language governing permissions and * limitations under the License. */ + +import { diag, DiagLogLevel } from '@opentelemetry/api'; import { getTestSpans, registerInstrumentationTesting, @@ -288,6 +290,36 @@ describe('redis@^4.0.0', () => { expectAttributeConnString ); }); + + it('with empty string for client URL, there is no crash and no diag.error', async () => { + // Note: This messily leaves the diag logger set for other tests. + const diagErrors = [] as any; + diag.setLogger( + { + verbose() {}, + debug() {}, + info() {}, + warn() {}, + error(...args) { + diagErrors.push(args); + }, + }, + DiagLogLevel.WARN + ); + + const newClient = createClient({ url: '' }); + try { + await newClient.connect(); + } catch (_err) { + // Ignore. If the test Redis is not at the default port we expect this + // to error. + } + await newClient.disconnect(); + + const [span] = getTestSpans(); + assert.strictEqual(span.name, 'redis-connect'); + assert.strictEqual(diagErrors.length, 0, "no diag.error's"); + }); }); describe('multi (transactions) commands', () => { From bc69fffc106142ed4c8333d3f6122329f51e4039 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Serkan=20=C3=96ZAL?= Date: Wed, 4 Sep 2024 23:20:22 +0300 Subject: [PATCH 2/3] feat: Record AWS Lambda coldstarts (#2403) Co-authored-by: Daniel Dyla --- .../src/instrumentation.ts | 52 +++++++++- .../src/types.ts | 1 + .../test/integrations/lambda-handler.test.ts | 96 +++++++++++++++++++ 3 files changed, 145 insertions(+), 4 deletions(-) diff --git a/plugins/node/opentelemetry-instrumentation-aws-lambda/src/instrumentation.ts b/plugins/node/opentelemetry-instrumentation-aws-lambda/src/instrumentation.ts index 4aef1509ce..276ef63518 100644 --- a/plugins/node/opentelemetry-instrumentation-aws-lambda/src/instrumentation.ts +++ b/plugins/node/opentelemetry-instrumentation-aws-lambda/src/instrumentation.ts @@ -48,6 +48,7 @@ import { SEMRESATTRS_CLOUD_ACCOUNT_ID, SEMRESATTRS_FAAS_ID, } from '@opentelemetry/semantic-conventions'; +import { ATTR_FAAS_COLDSTART } from '@opentelemetry/semantic-conventions/incubating'; import { APIGatewayProxyEventHeaders, @@ -72,6 +73,7 @@ const headerGetter: TextMapGetter = { }; export const traceContextEnvironmentKey = '_X_AMZN_TRACE_ID'; +export const lambdaMaxInitInMilliseconds = 10_000; export class AwsLambdaInstrumentation extends InstrumentationBase { private _traceForceFlusher?: () => Promise; @@ -135,6 +137,10 @@ export class AwsLambdaInstrumentation extends InstrumentationBase { @@ -164,16 +174,47 @@ export class AwsLambdaInstrumentation extends InstrumentationBase { - return this._getPatchHandler(original); + return this._getPatchHandler(original, handlerLoadStartTime); }; } - private _getPatchHandler(original: Handler) { + private _getPatchHandler(original: Handler, lambdaStartTime: number) { diag.debug('patch handler function'); const plugin = this; + let requestHandledBefore = false; + let requestIsColdStart = true; + + function _onRequest(): void { + if (requestHandledBefore) { + // Non-first requests cannot be coldstart. + requestIsColdStart = false; + } else { + if ( + process.env.AWS_LAMBDA_INITIALIZATION_TYPE === + 'provisioned-concurrency' + ) { + // If sandbox environment is initialized with provisioned concurrency, + // even the first requests should not be considered as coldstart. + requestIsColdStart = false; + } else { + // Check whether it is proactive initialization or not: + // https://aaronstuyvenberg.com/posts/understanding-proactive-initialization + const passedTimeSinceHandlerLoad: number = + Date.now() - lambdaStartTime; + const proactiveInitialization: boolean = + passedTimeSinceHandlerLoad > lambdaMaxInitInMilliseconds; + + // If sandbox has been initialized proactively before the actual request, + // even the first requests should not be considered as coldstart. + requestIsColdStart = !proactiveInitialization; + } + requestHandledBefore = true; + } + } + return function patchedHandler( this: never, // The event can be a user type, it truly is any. @@ -182,6 +223,8 @@ export class AwsLambdaInstrumentation extends InstrumentationBase { assert.strictEqual(span.parentSpanId, undefined); }); + it('should record coldstart', async () => { + initializeHandler('lambda-test/sync.handler'); + + const handlerModule = lambdaRequire('lambda-test/sync'); + + const result1 = await new Promise((resolve, reject) => { + handlerModule.handler('arg', ctx, (err: Error, res: any) => { + if (err) { + reject(err); + } else { + resolve(res); + } + }); + }); + + const result2 = await new Promise((resolve, reject) => { + handlerModule.handler('arg', ctx, (err: Error, res: any) => { + if (err) { + reject(err); + } else { + resolve(res); + } + }); + }); + + const spans = memoryExporter.getFinishedSpans(); + assert.strictEqual(spans.length, 2); + const [span1, span2] = spans; + + assert.strictEqual(result1, 'ok'); + assertSpanSuccess(span1); + assert.strictEqual(span1.parentSpanId, undefined); + assert.strictEqual(span1.attributes[SEMATTRS_FAAS_COLDSTART], true); + + assert.strictEqual(result2, 'ok'); + assertSpanSuccess(span2); + assert.strictEqual(span2.parentSpanId, undefined); + assert.strictEqual(span2.attributes[SEMATTRS_FAAS_COLDSTART], false); + }); + + it('should record coldstart with provisioned concurrency', async () => { + process.env.AWS_LAMBDA_INITIALIZATION_TYPE = 'provisioned-concurrency'; + + initializeHandler('lambda-test/sync.handler'); + + const result = await new Promise((resolve, reject) => { + lambdaRequire('lambda-test/sync').handler( + 'arg', + ctx, + (err: Error, res: any) => { + if (err) { + reject(err); + } else { + resolve(res); + } + } + ); + }); + assert.strictEqual(result, 'ok'); + const spans = memoryExporter.getFinishedSpans(); + const [span] = spans; + assert.strictEqual(spans.length, 1); + assertSpanSuccess(span); + assert.strictEqual(span.parentSpanId, undefined); + assert.strictEqual(span.attributes[SEMATTRS_FAAS_COLDSTART], false); + }); + + it('should record coldstart with proactive initialization', async () => { + initializeHandler('lambda-test/sync.handler', { + lambdaStartTime: Date.now() - 2 * lambdaMaxInitInMilliseconds, + }); + + const result = await new Promise((resolve, reject) => { + lambdaRequire('lambda-test/sync').handler( + 'arg', + ctx, + (err: Error, res: any) => { + if (err) { + reject(err); + } else { + resolve(res); + } + } + ); + }); + assert.strictEqual(result, 'ok'); + const spans = memoryExporter.getFinishedSpans(); + const [span] = spans; + assert.strictEqual(spans.length, 1); + assertSpanSuccess(span); + assert.strictEqual(span.parentSpanId, undefined); + assert.strictEqual(span.attributes[SEMATTRS_FAAS_COLDSTART], false); + }); + it('should record error', async () => { initializeHandler('lambda-test/sync.error'); From b09cb40242f09c0a52bacd15a7d8c84e954d57e0 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Thu, 5 Sep 2024 02:11:05 -0700 Subject: [PATCH 3/3] test(instrumentation-express): update to use correct span kind enum; also fix test flakiness (#2421) This is a follow-up on #2408 (comment) to update one more usage of SpanKind.* to testUtils.OtlpSpanKind.*. While testing this locally I also noticed that the instr-express tests using runTestFixture are flaky. The issue is that TestCollector#sortedSpans can get the span ordering wrong when spans start in the same millisecond (the resolution of span.startTimeUnixNano). This happens with Express middleware spans on a fast machine. I've updated sortedSpans to fallback to using span.parentSpanId to attempt to get more reliable sorting. --- .../src/test-fixtures.ts | 28 +++++++++++++++++-- .../test/express.test.ts | 4 +-- 2 files changed, 28 insertions(+), 4 deletions(-) diff --git a/packages/opentelemetry-test-utils/src/test-fixtures.ts b/packages/opentelemetry-test-utils/src/test-fixtures.ts index 6a3563978f..ff0dd9e313 100644 --- a/packages/opentelemetry-test-utils/src/test-fixtures.ts +++ b/packages/opentelemetry-test-utils/src/test-fixtures.ts @@ -110,14 +110,38 @@ export class TestCollector { return this._http.close(); } - // Return the spans sorted by start time for testing convenience. + /** + * Return the spans sorted by which started first, for testing convenience. + * + * Note: This sorting is a *best effort*. `span.startTimeUnixNano` has + * millisecond accuracy, so if multiple spans start in the same millisecond + * then this cannot know the start ordering. If `startTimeUnixNano` are the + * same, this attempts to get the correct ordering using `parentSpanId` -- a + * parent span starts before any of its direct children. This isn't perfect. + */ get sortedSpans(): Array { return this.spans.slice().sort((a, b) => { assert(typeof a.startTimeUnixNano === 'string'); assert(typeof b.startTimeUnixNano === 'string'); const aStartInt = BigInt(a.startTimeUnixNano); const bStartInt = BigInt(b.startTimeUnixNano); - return aStartInt < bStartInt ? -1 : aStartInt > bStartInt ? 1 : 0; + if (aStartInt < bStartInt) { + return -1; + } else if (aStartInt > bStartInt) { + return 1; + } else { + // Same startTimeUnixNano, which has millisecond accuracy. This is + // common for Express middleware spans on a fast enough dev machine. + // Attempt to use spanId/parentSpanId to decide on span ordering. + if (a.traceId === b.traceId) { + if (a.spanId === b.parentSpanId) { + return -1; + } else if (a.parentSpanId === b.spanId) { + return 1; + } + } + return 0; + } }); } diff --git a/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts b/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts index 0ae9a53a78..7f52e90e35 100644 --- a/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts +++ b/plugins/node/opentelemetry-instrumentation-express/test/express.test.ts @@ -14,7 +14,7 @@ * limitations under the License. */ -import { SpanStatusCode, context, SpanKind, trace } from '@opentelemetry/api'; +import { SpanStatusCode, context, trace } from '@opentelemetry/api'; import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node'; import { AsyncHooksContextManager } from '@opentelemetry/context-async-hooks'; import { @@ -675,7 +675,7 @@ describe('ExpressInstrumentation', () => { spans[5].name, 'request handler - /\\/test\\/regex/' ); - assert.strictEqual(spans[5].kind, SpanKind.SERVER); + assert.strictEqual(spans[5].kind, testUtils.OtlpSpanKind.INTERNAL); assert.strictEqual(spans[5].parentSpanId, spans[1].spanId); }, });