fs instrumentation not working correctly with TypeScript path aliases

[akwodkiewicz]

What happened?

Steps to Reproduce

A typescript app repository with tsconfig.json including paths, for example:

// ...
  "compilerOptions": {
        "rootDir": ".",
        "baseUrl": ".",
        "outDir": "dist",
        "paths": {
            "@support/*": ["src/support/*"],
            "@app/*": ["src/*"]
    }
// ...

Expected Result

Tracing works correctly

Actual Result

Tracing contains mostly fs.existsSync and fs.statSync entries, many of them are errors. See

Example stacktrace when running the app via ts-node-dev: [log output 1]

Different stacktrace when running the app via node (with tsconfig-paths/register): [log output 2]

FYI, I'm pasting 2 different errors. There are many more related to various files and libraries. Wanted to paste both ts-node-dev and node stacktraces to see any differences between the file paths, but I did not see any.

Additional Details

It looks like there's either a problem with my setup or the monkey-patching does not work like it should.

I'm running the node command like this:

TS_NODE_PROJECT=tsconfig-js.json node --require tsconfig-paths/register --require ./dist/src/tracing.js ./dist/src/main.js"

and the ts-node-dev command like this:

ts-node-dev --transpile-only -r tsconfig-paths/register -r src/tracing.ts --respawn -- src/main.ts

OpenTelemetry Setup Code

import { diag, DiagConsoleLogger, DiagLogLevel } from '@opentelemetry/api';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import * as opentelemetry from '@opentelemetry/sdk-node';

// For troubleshooting, set the log level to DiagLogLevel.DEBUG
diag.setLogger(new DiagConsoleLogger(), DiagLogLevel.DEBUG);

export const otelSdk = new opentelemetry.NodeSDK({
    traceExporter: new OTLPTraceExporter({
        url: 'http://jaeger:4318/v1/traces',
    }),
    instrumentations: [getNodeAutoInstrumentations()],
    serviceName: 'backend',
});

// eslint-disable-next-line no-console
otelSdk.start().catch(e => console.error(e));

package.json

"@opentelemetry/api": "^1.3.0",
"@opentelemetry/auto-instrumentations-node": "^0.35.0",
"@opentelemetry/exporter-trace-otlp-http": "^0.34.0",
"@opentelemetry/sdk-node": "^0.34.0",

Relevant log output

1:

Error: ENOENT: no such file or directory, stat '/home/node/app/packages/backend/@nestjs/core/adapters/http-adapter/index.jsx'
    at Object.statSync (node:fs:1591:3)
    at AsyncLocalStorage.run (node:async_hooks:330:14)
    at AsyncLocalStorageContextManager.with (/home/node/app/node_modules/@opentelemetry/context-async-hooks/src/AsyncLocalStorageContextManager.ts:40:36)
    at ContextAPI.with (/home/node/app/node_modules/@opentelemetry/api/src/api/context.ts:77:42)
    at Object.statSync (/home/node/app/node_modules/@opentelemetry/instrumentation-fs/src/instrumentation.ts:155:37)
    at fileExistsSync (/home/node/app/node_modules/tsconfig-paths/src/filesystem.ts:37:22)
    at findFirstExistingPath (/home/node/app/node_modules/tsconfig-paths/src/match-path-sync.ts:120:11)
    at matchFromAbsolutePaths (/home/node/app/node_modules/tsconfig-paths/src/match-path-sync.ts:82:10)
    at /home/node/app/node_modules/tsconfig-paths/src/match-path-sync.ts:44:5
    at Function.Module._resolveFilename (/home/node/app/node_modules/tsconfig-paths/src/register.ts:82:21)
    at Module.Hook._require.Module.require (/home/node/app/node_modules/require-in-the-middle/index.js:81:25)
    at require (node:internal/modules/cjs/helpers:103:18)
    at Object.<anonymous> (/home/node/app/node_modules/@nestjs/platform-express/adapters/express-adapter.js:6:24)
    at Module._compile (node:internal/modules/cjs/loader:1149:14)
    at Module._compile (/home/node/app/node_modules/ts-node-dev/node_modules/source-map-support/source-map-support.js:568:25)
    at Module._extensions..js (node:internal/modules/cjs/loader:1203:10)
    at require.extensions..jsx.require.extensions..js (/tmp/ts-node-dev-hook-6581189445318922.js:114:20)
    at Object.nodeDevHook [as .js] (/home/node/app/node_modules/ts-node-dev/lib/hook.js:63:13)
    at Module.load (node:internal/modules/cjs/loader:1027:32)
    at Function.Module._load (node:internal/modules/cjs/loader:868:12)
    at Module.require (node:internal/modules/cjs/loader:1051:19)
    at Module.Hook._require.Module.require (/home/node/app/node_modules/require-in-the-middle/index.js:101:39)

2:

Error: ENOENT: no such file or directory, stat '/home/node/app/packages/backend/@nestjs/platform-express'
    at Object.statSync (node:fs:1591:3)
    at AsyncLocalStorage.run (node:async_hooks:330:14)
    at AsyncLocalStorageContextManager.with (/home/node/app/node_modules/@opentelemetry/context-async-hooks/src/AsyncLocalStorageContextManager.ts:40:36)
    at ContextAPI.with (/home/node/app/node_modules/@opentelemetry/api/src/api/context.ts:77:42)
    at Object.statSync (/home/node/app/node_modules/@opentelemetry/instrumentation-fs/src/instrumentation.ts:155:37)
    at fileExistsSync (/home/node/app/node_modules/tsconfig-paths/src/filesystem.ts:37:22)
    at findFirstExistingPath (/home/node/app/node_modules/tsconfig-paths/src/match-path-sync.ts:120:11)
    at matchFromAbsolutePaths (/home/node/app/node_modules/tsconfig-paths/src/match-path-sync.ts:82:10)
    at <anonymous> (/home/node/app/node_modules/tsconfig-paths/src/match-path-sync.ts:44:5)
    at Function.Module._resolveFilename (/home/node/app/node_modules/tsconfig-paths/src/register.ts:82:21)
    at Hook._require.Module.require (/home/node/app/node_modules/require-in-the-middle/index.js:81:25)
    at require (node:internal/modules/cjs/helpers:103:18)
    at /home/node/app/node_modules/@nestjs/core/nest-factory.js:152:110
    at loadAdapter (/home/node/app/node_modules/@nestjs/core/helpers/load-adapter.js:9:27)
    at NestFactoryStatic.createHttpAdapter (/home/node/app/node_modules/@nestjs/core/nest-factory.js:152:67)
    at NestFactoryStatic.create (/home/node/app/node_modules/@nestjs/core/nest-factory.js:32:21)
    at <anonymous> (/home/node/app/node_modules/@opentelemetry/instrumentation-nestjs-core/src/instrumentation.ts:147:33)
    at AsyncLocalStorage.run (node:async_hooks:330:14)
    at AsyncLocalStorageContextManager.with (/home/node/app/node_modules/@opentelemetry/context-async-hooks/src/AsyncLocalStorageContextManager.ts:40:36)
    at ContextAPI.with (/home/node/app/node_modules/@opentelemetry/api/src/api/context.ts:77:42)
    at NestFactoryStatic.createWithTrace (/home/node/app/node_modules/@opentelemetry/instrumentation-nestjs-core/src/instrumentation.ts:145:30)
    at <anonymous> (/home/node/app/packages/backend/src/main.ts:18:35)

[akwodkiewicz]

Weird... When I change the OTLPTraceExporter to ConsoleSpanExporter I don't see these errors anymore, just regular fs tracing.

So maybe the problem lies in the OTLPTraceExporter?

[dyladan]

Hmm it is quite possible that it is. The OTLP exporters are quite complex and rely on generated code. It is quite weird that it causes problems in other seemingly unrelated parts of your code though. I'm going to label this as p3 since it causes problems in your code, but is not a production runtime crash but rather a compile time issue.

I don't see anything in your stacktraces that point to anything specific to OTLP expoters, but i'll try to reproduce this today.

[akwodkiewicz]

With 75% confidence (I did it weeks ago, but only read a notification from you @dyladan) I believe that the same errors were present when using ConsoleSpanExporter as well. It's just I did not see them the first time, because there were a lot of traces. So it would mean it's not about the exporter, like I originally thought. Maybe it's the fs (?) instrumentation.

[secondfry]

Well, I did this to debug the issue (and I'm not sure if mine is the same as yours, but this is the only issue I could find on the topic):

const fs = require('fs');
const _fsStatSync = fs.statSync.bind(fs);
fs.statSync = (...args) => {
  if (args[0].includes('node_modules')) return _fsStatSync(...args);
  const err = new Error();
  console.log(args, err);
  return _fsStatSync(...args);
};

Which indeed resulted in millions of calls to fs.statSync with output looking like this:

[
  '[REDACTED_PROJECT_DIR]/src/API/error/ValidationError.js'
] Error
    at Object.fs.statSync ([REDACTED_PROJECT_DIR]/tracing.js:5:15)
    at AsyncLocalStorage.run (node:async_hooks:330:14)
    at AsyncLocalStorageContextManager.with ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/sdk-trace-node/node_modules/@opentelemetry/context-async-hooks/src/AsyncLocalStorageContextManager.ts:40:36)
    at ContextAPI.with ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/api/src/api/context.ts:77:42)
    at Object.patchedFunction [as statSync] ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/instrumentation-fs/src/instrumentation.ts:196:37)
    at fileExistsSync ([REDACTED_PROJECT_DIR]/node_modules/tsconfig-paths/src/filesystem.ts:41:22)
    at findFirstExistingPath ([REDACTED_PROJECT_DIR]/node_modules/tsconfig-paths/src/match-path-sync.ts:125:11)
    at matchFromAbsolutePaths ([REDACTED_PROJECT_DIR]/node_modules/tsconfig-paths/src/match-path-sync.ts:84:10)
    at [REDACTED_PROJECT_DIR]/node_modules/tsconfig-paths/src/match-path-sync.ts:45:5
    at Function.Module._resolveFilename ([REDACTED_PROJECT_DIR]/node_modules/tsconfig-paths/src/register.ts:109:21)
    at Module.Hook._require.Module.require ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/instrumentation-grpc/node_modules/require-in-the-middle/index.js:81:25)
    at Module.Hook._require.Module.require ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/instrumentation-hapi/node_modules/require-in-the-middle/index.js:101:39)
    at Module.Hook._require.Module.require ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/instrumentation-http/node_modules/require-in-the-middle/index.js:101:39)
    at Module.Hook._require.Module.require ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/instrumentation-ioredis/node_modules/require-in-the-middle/index.js:101:39)
    at Module.Hook._require.Module.require ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/instrumentation-knex/node_modules/require-in-the-middle/index.js:101:39)
    at Module.Hook._require.Module.require ([REDACTED_PROJECT_DIR]/node_modules/@opentelemetry/instrumentation-koa/node_modules/require-in-the-middle/index.js:101:39)

Disabling @opentelemetry/instrumentation-fs "fixes" the problem.

  instrumentations: [
    getNodeAutoInstrumentations({
      '@opentelemetry/instrumentation-fs': {
        enabled: false,
      },
    }),
  ],

I guess proper fix would be to hook tsconfig-paths/src/filesystem.ts in such a way that following calls to fs.statSync wouldn't create spans.

[secondfry]

Also there is tsc-alias which transpiles aliased paths back to relative ones.
https://www.npmjs.com/package/tsc-alias

[timonmasberg]

A weird behavior we encounter is, that if we do use a path alias to import the NodeSDK instance, it is not working, but if we use a relative path, everything works fine.

[mderazon]

I am also seeing many fs statSync calls in traces, but no errors

Not sure where it's coming from. It's not from our own code, so either 3rd party or from the instrumentation library itself

I read that it's overall recommended to turn fs instrumentation off (open-telemetry/opentelemetry-js-contrib#1344 (comment)) but not sure how to do it via otel operator (open-telemetry/opentelemetry-operator#1283 (comment))