From 0daa4b872845e8f2617b529a0cdf7f4d188b3859 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Fri, 7 Oct 2022 14:12:05 +0300 Subject: [PATCH 1/5] test: add failing tests for exists --- .../instrumentation-fs/test/definitions.ts | 16 ++++++++++- .../instrumentation-fs/test/index.test.ts | 27 +++++++++++-------- 2 files changed, 31 insertions(+), 12 deletions(-) diff --git a/plugins/node/instrumentation-fs/test/definitions.ts b/plugins/node/instrumentation-fs/test/definitions.ts index cb854ea6b3..06ad78195e 100644 --- a/plugins/node/instrumentation-fs/test/definitions.ts +++ b/plugins/node/instrumentation-fs/test/definitions.ts @@ -23,7 +23,7 @@ export type Opts = { callback?: boolean; promise?: boolean; }; -export type Result = { error?: RegExp; result?: any }; +export type Result = { error?: RegExp; result?: any, resultAsError?: any }; export type TestCase = [FsFunction, any[], Result, any[], Opts?]; export type TestCreator = ( name: FsFunction, @@ -65,6 +65,20 @@ const tests: TestCase[] = [ { result: undefined }, [{ name: 'fs %NAME' }], ], + [ + 'exists' as FsFunction, // turning off testing async functions + ['./test/fixtures/exists-404'], + { resultAsError: false }, + [{ name: 'fs %NAME' }], + { promise: false } + ], + [ + 'exists' as FsFunction, // turning off testing async functions + ['./test/fixtures/readtest'], + { resultAsError: true }, + [{ name: 'fs %NAME' }], + { promise: false } + ], ]; export default tests; diff --git a/plugins/node/instrumentation-fs/test/index.test.ts b/plugins/node/instrumentation-fs/test/index.test.ts index 4933841a03..4bfeb0591b 100644 --- a/plugins/node/instrumentation-fs/test/index.test.ts +++ b/plugins/node/instrumentation-fs/test/index.test.ts @@ -82,7 +82,7 @@ describe('fs instrumentation', () => { const syncTest: TestCreator = ( name: FMember, args, - { error, result }, + { error, result, resultAsError = null }, spans ) => { const syncName: FMember = `${name}Sync` as FMember; @@ -95,7 +95,7 @@ describe('fs instrumentation', () => { if (error) { assert.throws(() => Reflect.apply(fs[syncName], fs, args), error); } else { - assert.deepEqual(Reflect.apply(fs[syncName], fs, args), result); + assert.deepEqual(Reflect.apply(fs[syncName], fs, args), result ?? resultAsError); } }); rootSpan.end(); @@ -121,7 +121,7 @@ describe('fs instrumentation', () => { const callbackTest: TestCreator = ( name: FMember, args, - { error, result }, + { error, result, resultAsError = null }, spans ) => { const rootSpanName = `${name} test span`; @@ -144,9 +144,19 @@ describe('fs instrumentation', () => { `Expected ${actualError?.message} to match ${error}` ); } else { - if (actualError) { - return done(actualError); + if (actualError !== undefined) { + // this usually would mean that there is an error, but with `exists` function + // returns the result as the error, check whether we expect that behavior + // and if not, error the test + if (resultAsError === undefined) { + if (actualError instanceof Error) { + return done(actualError); + } else { + return done(new Error(`Expected callback to be called without an error got: ${actualError}`)); + } + } } + assert.deepEqual(actualError, resultAsError); assert.deepEqual(actualResult, result); } assertSpans(memoryExporter.getFinishedSpans(), [ @@ -188,6 +198,7 @@ describe('fs instrumentation', () => { await context .with(trace.setSpan(context.active(), rootSpan), () => { // eslint-disable-next-line node/no-unsupported-features/node-builtins + assert(typeof fs.promises[name] === 'function', `Expected fs.promises.${name} to be a function`); return Reflect.apply(fs.promises[name], fs.promises, args); }) .then((actualResult: any) => { @@ -355,12 +366,6 @@ const assertSpans = (spans: ReadableSpan[], expected: any) => { spans.forEach((span, i) => { assertSpan(span, expected[i]); }); - - assert.strictEqual( - spans.length, - expected.length, - `Expected ${expected.length} spans, got ${spans.length}` - ); }; const assertSpan = (span: ReadableSpan, expected: any) => { From 8ad77072a5efaae15894d16584aabba22b08dbad Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Fri, 7 Oct 2022 14:38:35 +0300 Subject: [PATCH 2/5] test: add tests for promisified exists --- plugins/node/instrumentation-fs/test/definitions.ts | 6 ++---- plugins/node/instrumentation-fs/test/index.test.ts | 10 ++++++++-- 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/plugins/node/instrumentation-fs/test/definitions.ts b/plugins/node/instrumentation-fs/test/definitions.ts index 06ad78195e..ba95369400 100644 --- a/plugins/node/instrumentation-fs/test/definitions.ts +++ b/plugins/node/instrumentation-fs/test/definitions.ts @@ -66,18 +66,16 @@ const tests: TestCase[] = [ [{ name: 'fs %NAME' }], ], [ - 'exists' as FsFunction, // turning off testing async functions + 'exists' as FsFunction, // we are defining promisified version of exists in the tests, so this is OK ['./test/fixtures/exists-404'], { resultAsError: false }, [{ name: 'fs %NAME' }], - { promise: false } ], [ - 'exists' as FsFunction, // turning off testing async functions + 'exists' as FsFunction, // we are defining promisified version of exists in the tests, so this is OK ['./test/fixtures/readtest'], { resultAsError: true }, [{ name: 'fs %NAME' }], - { promise: false } ], ]; diff --git a/plugins/node/instrumentation-fs/test/index.test.ts b/plugins/node/instrumentation-fs/test/index.test.ts index 4bfeb0591b..ec08a8d155 100644 --- a/plugins/node/instrumentation-fs/test/index.test.ts +++ b/plugins/node/instrumentation-fs/test/index.test.ts @@ -22,6 +22,7 @@ import { SimpleSpanProcessor, } from '@opentelemetry/sdk-trace-base'; import * as assert from 'assert'; +import { promisify } from 'util'; import Instrumentation from '../src'; import * as sinon from 'sinon'; import type * as FSType from 'fs'; @@ -70,10 +71,14 @@ describe('fs instrumentation', () => { plugin.setTracerProvider(provider); plugin.enable(); fs = require('fs'); + Object.defineProperty(fs.promises, 'exists', { value: (...args: any[]) => { + return Reflect.apply(promisify(fs.exists), fs, args); + }, configurable: true }); assert.strictEqual(memoryExporter.getFinishedSpans().length, 0); }); afterEach(() => { + delete (fs.promises as any)['exists']; plugin.disable(); memoryExporter.reset(); context.disable(); @@ -187,7 +192,7 @@ describe('fs instrumentation', () => { const promiseTest: TestCreator = ( name: FPMember, args, - { error, result }, + { error, result, resultAsError = null }, spans ) => { const rootSpanName = `${name} test span`; @@ -205,10 +210,11 @@ describe('fs instrumentation', () => { if (error) { assert.fail(`promises.${name} did not reject`); } else { - assert.deepEqual(actualResult, result); + assert.deepEqual(actualResult, result ?? resultAsError); } }) .catch((actualError: any) => { + assert(actualError instanceof Error, `Expected caugth error to be instance of Error. Got ${actualError}`); if (error) { assert( error.test(actualError?.message ?? ''), From edc88fa8f5d5cd9b9e70bbaecf7a07c9a2389c7e Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Fri, 7 Oct 2022 14:20:34 +0300 Subject: [PATCH 3/5] fix: fix patching exists --- .../node/instrumentation-fs/src/constants.ts | 2 +- .../instrumentation-fs/src/instrumentation.ts | 97 +++++++++++++++++++ 2 files changed, 98 insertions(+), 1 deletion(-) diff --git a/plugins/node/instrumentation-fs/src/constants.ts b/plugins/node/instrumentation-fs/src/constants.ts index 2247951aa5..4b2a8ac0fc 100644 --- a/plugins/node/instrumentation-fs/src/constants.ts +++ b/plugins/node/instrumentation-fs/src/constants.ts @@ -54,7 +54,7 @@ export const CALLBACK_FUNCTIONS: FMember[] = [ 'chown', 'copyFile', 'cp' as FMember, // added in v16 - 'exists', // deprecated, inconsistent cb signature + 'exists', // deprecated, inconsistent cb signature, handling separately when patching 'lchown', 'link', 'lstat', diff --git a/plugins/node/instrumentation-fs/src/instrumentation.ts b/plugins/node/instrumentation-fs/src/instrumentation.ts index 86959ac370..88f57cb4ce 100644 --- a/plugins/node/instrumentation-fs/src/instrumentation.ts +++ b/plugins/node/instrumentation-fs/src/instrumentation.ts @@ -35,6 +35,7 @@ import type { EndHook, FsInstrumentationConfig, } from './types'; +import { promisify } from 'util'; type FS = typeof fs; @@ -63,6 +64,19 @@ export default class FsInstrumentation extends InstrumentationBase { ); } for (const fName of CALLBACK_FUNCTIONS) { + if (fName === 'exists') { + // handling separately because of the inconsistent cb style: + // `exists` doesn't have error as the first argument, but the result + if (isWrapped(fs[fName])) { + this._unwrap(fs, fName); + } + this._wrap( + fs, + fName, + this._patchExistsCallbackFunction.bind(this, fName) + ); + continue; + } if (isWrapped(fs[fName])) { this._unwrap(fs, fName); } @@ -244,6 +258,89 @@ export default class FsInstrumentation extends InstrumentationBase { }; } + protected _patchExistsCallbackFunction ReturnType>( + functionName: FMember, + original: T + ): T { + const instrumentation = this; + const patchedFunction = function (this: any, ...args: any[]) { + if (isTracingSuppressed(api.context.active())) { + // Performance optimization. Avoid creating additional contexts and spans + // if we already know that the tracing is being suppressed. + return original.apply(this, args); + } + if ( + instrumentation._runCreateHook(functionName, { + args: args, + }) === false + ) { + return api.context.with( + suppressTracing(api.context.active()), + original, + this, + ...args + ); + } + + const lastIdx = args.length - 1; + const cb = args[lastIdx]; + if (typeof cb === 'function') { + const span = instrumentation.tracer.startSpan( + `fs ${functionName}` + ) as api.Span; + + // Return to the context active during the call in the callback + args[lastIdx] = api.context.bind( + api.context.active(), + function (this: unknown) { + // `exists` never calls the callback with an error + instrumentation._runEndHook(functionName, { + args: args, + span, + }); + span.end(); + return cb.apply(this, arguments); + } + ); + + try { + // Suppress tracing for internal fs calls + return api.context.with( + suppressTracing(api.trace.setSpan(api.context.active(), span)), + original, + this, + ...args + ); + } catch (error) { + span.recordException(error); + span.setStatus({ + message: error.message, + code: api.SpanStatusCode.ERROR, + }); + instrumentation._runEndHook(functionName, { + args: args, + span, + error, + }); + span.end(); + throw error; + } + } else { + return original.apply(this, args); + } + }; + + // `exists` has a custom promisify function because of the inconsistent signature + // replicating that on the patched function + const promisified = function (path: unknown) { + return new Promise((resolve) => patchedFunction(path, resolve)); + }; + Object.defineProperty(promisified, 'name', { value: functionName }); + Object.defineProperty(patchedFunction, promisify.custom, { value: promisified }); + + return patchedFunction; + } + protected _patchPromiseFunction ReturnType>( functionName: FPMember, original: T From b9658e161b9a6e163c69b12d6a1e6054c6e64fab Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Fri, 7 Oct 2022 15:59:35 +0300 Subject: [PATCH 4/5] style: lint --- .../instrumentation-fs/src/instrumentation.ts | 13 ++++---- .../instrumentation-fs/test/definitions.ts | 2 +- .../instrumentation-fs/test/index.test.ts | 30 ++++++++++++++----- 3 files changed, 31 insertions(+), 14 deletions(-) diff --git a/plugins/node/instrumentation-fs/src/instrumentation.ts b/plugins/node/instrumentation-fs/src/instrumentation.ts index 88f57cb4ce..53ec3fed1e 100644 --- a/plugins/node/instrumentation-fs/src/instrumentation.ts +++ b/plugins/node/instrumentation-fs/src/instrumentation.ts @@ -258,10 +258,9 @@ export default class FsInstrumentation extends InstrumentationBase { }; } - protected _patchExistsCallbackFunction ReturnType>( - functionName: FMember, - original: T - ): T { + protected _patchExistsCallbackFunction< + T extends (...args: any[]) => ReturnType + >(functionName: FMember, original: T): T { const instrumentation = this; const patchedFunction = function (this: any, ...args: any[]) { if (isTracingSuppressed(api.context.active())) { @@ -333,10 +332,12 @@ export default class FsInstrumentation extends InstrumentationBase { // `exists` has a custom promisify function because of the inconsistent signature // replicating that on the patched function const promisified = function (path: unknown) { - return new Promise((resolve) => patchedFunction(path, resolve)); + return new Promise(resolve => patchedFunction(path, resolve)); }; Object.defineProperty(promisified, 'name', { value: functionName }); - Object.defineProperty(patchedFunction, promisify.custom, { value: promisified }); + Object.defineProperty(patchedFunction, promisify.custom, { + value: promisified, + }); return patchedFunction; } diff --git a/plugins/node/instrumentation-fs/test/definitions.ts b/plugins/node/instrumentation-fs/test/definitions.ts index ba95369400..551f104986 100644 --- a/plugins/node/instrumentation-fs/test/definitions.ts +++ b/plugins/node/instrumentation-fs/test/definitions.ts @@ -23,7 +23,7 @@ export type Opts = { callback?: boolean; promise?: boolean; }; -export type Result = { error?: RegExp; result?: any, resultAsError?: any }; +export type Result = { error?: RegExp; result?: any; resultAsError?: any }; export type TestCase = [FsFunction, any[], Result, any[], Opts?]; export type TestCreator = ( name: FsFunction, diff --git a/plugins/node/instrumentation-fs/test/index.test.ts b/plugins/node/instrumentation-fs/test/index.test.ts index ec08a8d155..cb49a5f5d0 100644 --- a/plugins/node/instrumentation-fs/test/index.test.ts +++ b/plugins/node/instrumentation-fs/test/index.test.ts @@ -71,9 +71,12 @@ describe('fs instrumentation', () => { plugin.setTracerProvider(provider); plugin.enable(); fs = require('fs'); - Object.defineProperty(fs.promises, 'exists', { value: (...args: any[]) => { - return Reflect.apply(promisify(fs.exists), fs, args); - }, configurable: true }); + Object.defineProperty(fs.promises, 'exists', { + value: (...args: any[]) => { + return Reflect.apply(promisify(fs.exists), fs, args); + }, + configurable: true, + }); assert.strictEqual(memoryExporter.getFinishedSpans().length, 0); }); @@ -100,7 +103,10 @@ describe('fs instrumentation', () => { if (error) { assert.throws(() => Reflect.apply(fs[syncName], fs, args), error); } else { - assert.deepEqual(Reflect.apply(fs[syncName], fs, args), result ?? resultAsError); + assert.deepEqual( + Reflect.apply(fs[syncName], fs, args), + result ?? resultAsError + ); } }); rootSpan.end(); @@ -157,7 +163,11 @@ describe('fs instrumentation', () => { if (actualError instanceof Error) { return done(actualError); } else { - return done(new Error(`Expected callback to be called without an error got: ${actualError}`)); + return done( + new Error( + `Expected callback to be called without an error got: ${actualError}` + ) + ); } } } @@ -203,7 +213,10 @@ describe('fs instrumentation', () => { await context .with(trace.setSpan(context.active(), rootSpan), () => { // eslint-disable-next-line node/no-unsupported-features/node-builtins - assert(typeof fs.promises[name] === 'function', `Expected fs.promises.${name} to be a function`); + assert( + typeof fs.promises[name] === 'function', + `Expected fs.promises.${name} to be a function` + ); return Reflect.apply(fs.promises[name], fs.promises, args); }) .then((actualResult: any) => { @@ -214,7 +227,10 @@ describe('fs instrumentation', () => { } }) .catch((actualError: any) => { - assert(actualError instanceof Error, `Expected caugth error to be instance of Error. Got ${actualError}`); + assert( + actualError instanceof Error, + `Expected caugth error to be instance of Error. Got ${actualError}` + ); if (error) { assert( error.test(actualError?.message ?? ''), From b34355de5c3f1a548213965cd34538ed973b5025 Mon Sep 17 00:00:00 2001 From: Rauno Viskus Date: Mon, 10 Oct 2022 12:37:56 +0300 Subject: [PATCH 5/5] refactor: remove code duplication on unwrapping --- plugins/node/instrumentation-fs/src/instrumentation.ts | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/plugins/node/instrumentation-fs/src/instrumentation.ts b/plugins/node/instrumentation-fs/src/instrumentation.ts index 53ec3fed1e..6bd778da83 100644 --- a/plugins/node/instrumentation-fs/src/instrumentation.ts +++ b/plugins/node/instrumentation-fs/src/instrumentation.ts @@ -64,12 +64,12 @@ export default class FsInstrumentation extends InstrumentationBase { ); } for (const fName of CALLBACK_FUNCTIONS) { + if (isWrapped(fs[fName])) { + this._unwrap(fs, fName); + } if (fName === 'exists') { // handling separately because of the inconsistent cb style: // `exists` doesn't have error as the first argument, but the result - if (isWrapped(fs[fName])) { - this._unwrap(fs, fName); - } this._wrap( fs, fName, @@ -77,9 +77,6 @@ export default class FsInstrumentation extends InstrumentationBase { ); continue; } - if (isWrapped(fs[fName])) { - this._unwrap(fs, fName); - } this._wrap( fs, fName,