fix(instrumentation-fs): fix fs.exists when it's util.promisified (#…

…1222)

* test: add failing tests for exists

* test: add tests for promisified exists

* fix: fix patching exists

* style: lint

* refactor: remove code duplication on unwrapping

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',

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;
 
@@ -66,6 +67,16 @@ export default class FsInstrumentation extends InstrumentationBase<FS> {
             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
+              this._wrap(
+                fs,
+                fName,
+                <any>this._patchExistsCallbackFunction.bind(this, fName)
+              );
+              continue;
+            }
             this._wrap(
               fs,
               fName,
@@ -244,6 +255,90 @@ export default class FsInstrumentation extends InstrumentationBase<FS> {
     };
   }
 
+  protected _patchExistsCallbackFunction<
+    T extends (...args: any[]) => ReturnType<T>
+  >(functionName: FMember, original: T): T {
+    const instrumentation = this;
+    const patchedFunction = <any>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<T extends (...args: any[]) => ReturnType<T>>(
     functionName: FPMember,
     original: T

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,18 @@ const tests: TestCase[] = [
     { result: undefined },
     [{ name: 'fs %NAME' }],
   ],
+  [
+    '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' }],
+  ],
+  [
+    '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' }],
+  ],
 ];
 
 export default tests;

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,17 @@ 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();
@@ -82,7 +90,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 +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);
+          assert.deepEqual(
+            Reflect.apply(fs[syncName], fs, args),
+            result ?? resultAsError
+          );
         }
       });
       rootSpan.end();
@@ -121,7 +132,7 @@ describe('fs instrumentation', () => {
   const callbackTest: TestCreator = (
     name: FMember,
     args,
-    { error, result },
+    { error, result, resultAsError = null },
     spans
   ) => {
     const rootSpanName = `${name} test span`;
@@ -144,9 +155,23 @@ 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(), [
@@ -177,7 +202,7 @@ describe('fs instrumentation', () => {
   const promiseTest: TestCreator = (
     name: FPMember,
     args,
-    { error, result },
+    { error, result, resultAsError = null },
     spans
   ) => {
     const rootSpanName = `${name} test span`;
@@ -188,16 +213,24 @@ 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) => {
           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 ?? ''),
@@ -355,12 +388,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) => {