Fastify showing instrumentation warning even when instrumented

AlexDochioiu commented 4 months ago

Is there an existing issue for this?

[X] I have checked for existing issues https://github.com/getsentry/sentry-javascript/issues
[X] I have reviewed the documentation https://docs.sentry.io/
[X] I am using the latest SDK release https://github.com/getsentry/sentry-javascript/releases

How do you use Sentry?

Sentry Saas (sentry.io)

Which SDK are you using?

@sentry/node

SDK Version

8.4.0

Framework Version

No response

Link to Sentry event

No response

SDK Setup

import * as Sentry from "@sentry/node";
import { hostname } from "os";
if (config.sentryEnv !== "disabled") {
  Sentry.init({
    dsn: config.sentryDsn,
    environment: config.sentryEnv,
    release: process.env.npm_package_version,
    serverName: hostname(),
    sampleRate: 1.0,
    // tracesSampleRate: 1.0,
    tracesSampler(samplingContext) {
      if (samplingContext.parentSampled === true) {
        return 1.0;
      }

      // eslint-disable-next-line @typescript-eslint/no-unsafe-assignment, @typescript-eslint/no-unsafe-member-access
      const url = samplingContext.attributes?.["http.target"] ?? samplingContext.attributes?.["http.url"] ?? "";
      if (!_.isString(url)) {
        console.warn("tracesSampler", "url is not a string", url);
        return config.sentrySampleRate;
      }
      console.log("tracesSampler", url);
      if (_.some(["/v4/images", "/v4/asset/image"], (path) => url.includes(path))) {
        console.log("tracesSampler", url, "0.0001");
        return 0.0001; // 0.01% of traces
      }
      if (_.some(["/wallet/txsubmit", "/wallet/txssubmit", "/wallet/swap/review"], (path) => url.includes(path))) {
        console.log("tracesSampler", url, "1.0");
        return 1.0; // 100% of traces
      }
      if (_.some(["/wallet/detailed"], (path) => url.includes(path))) {
        console.log("tracesSampler", url, "0.5");
        return 0.5; // 50% of traces
      }
      console.log("tracesSampler", url, config.sentrySampleRate);
      return config.sentrySampleRate;
    },
    beforeSend(event, hint) {
      // if (hint?.originalException instanceof Error) {
      //   recordSentryError(hint.originalException);
      // }
      hint;
      return event;
    },
    beforeSendTransaction(event, hint) {
      hint;
      console.log(event.request);

      return event;
    },
  });
}

Steps to Reproduce

Run the app. I tried to setup instrumentation:

As an import using those instructions: https://docs.sentry.io/platforms/javascript/guides/fastify/install/esm-without-import/
As NODE_OPTIONS import: https://docs.sentry.io/platforms/javascript/guides/fastify/install/esm/

Both options load the instrumentation fine (and well before fastify)

Expected Result

Instrumentation should work as expected and no warning should be given.

Actual Result

I think the instrumentation works as expected (possibly)? But I still get the following message:

console message:

[Sentry] fastify is not instrumented. Please make sure to initialize Sentry in a separate file that you `--import` when running node, see: 
https://docs.sentry.io/platforms/javascript/guides/fastify/install/esm/.

AbhiPrasad commented 4 months ago

@AlexDochioiu do you get data in Sentry event with the warning about fastify?

AlexDochioiu commented 4 months ago

@AbhiPrasad yes. This is an example here: https://vespr.sentry.io/performance/trace/a89abab490b2c67c9d2a6d4ae0a6d1da/?node=txn-a578567c40f04f4d9775232ded62e45c&statsPeriod=1h&timestamp=1716803891

mydea commented 4 months ago

Do you also get errors sent to your application, from your fastify routes etc? 🤔

Also, could you share the code where you call Sentry.setupFastifyErrorHandler(app)? Really what this does is check if the passed in fastify instance was wrapped, which should work I believe, but I'll also double check!

AlexDochioiu commented 4 months ago

What do you mean by errors sent to your application? You mean if the app throws during the execution of the route API call? Or by calling Sentry.captureException(error, { level: level });?

// That should be the first import to read env file
import "./env.js";
import "./instrument.js";

import _, { CollectionChain } from "lodash-es";
import { CmlType } from "./lodash-extensions.js";

// Add the new method to lodash
_.mixin({
  nonNils: function <T>(array: ArrayLike<T | null | undefined>): T[] {
    return _.filter(array, (item) => item !== null && item !== undefined) as T[];
  },
  cmlChain: function <T>(data: CmlType<T>): CollectionChain<T> {
    return _.chain(_.range(data.len()).map((i) => data.get(i)));
  },
});

import { config } from "./config/index.js";
import { recordSentryError } from "./plugins/fastify_apm_plugin.js";

import * as Sentry from "@sentry/node";
import setupFastifyInstance from "./app.js";
import ServerUtils from "./utils/Server.js";
import addFormats from "ajv-formats";
import { addCustomFormats } from "./utils/AjvUtils.js";
import cron_tasks from "./cron_tasks.js";

/**
 * Get port from environment and store in Express.
 */
const port = ServerUtils.normalizePort(config.port);

import fastify from "fastify";
const fastifyApp = fastify({
  ajv: {
    plugins: [addFormats, addCustomFormats],
  },
  trustProxy: true,
  logger: false,
  ignoreTrailingSlash: true,

  // https://www.fastify.io/docs/latest/Server/#maxparamlength
  // if the param overflows this number, 404 will be returned
  // currently the biggest param seems to be the address which can be 30864 (haxxxors having fun)
  // select tx_id,LENGTH(address) from tx_out where LENGTH(address) > 16000 ORDER BY LENGTH(address) desc LIMIT 10;
  maxParamLength: 32_768,
});

if (config.sentryEnv !== "disabled") {
  Sentry.setupFastifyErrorHandler(fastifyApp);
}

console.log("| ------------------------ |");
console.log("| Starting cron tasks | ");
await cron_tasks.start();
console.log("| Started  cron tasks |");
console.log("| ------------------------ |");

await setupFastifyInstance(fastifyApp);

try {
  await fastifyApp.listen({ port: port, host: "0.0.0.0" });
} catch (err) {
  recordSentryError(err);
  console.error(err);
  process.exit(1);
}

mydea commented 4 months ago

You mean if the app throws during the execution of the route API call?

This is what I mean, yes - sorry for not being 100% clear there!

Your setup looks all good to me 🤔 If you set debug: true in your Sentry.init(), could you share the logs you see at the start of your app?

AlexDochioiu commented 4 months ago

➜  vending-machine git:(sentry_v8_migration) ✗ npm run start:dev

> vending-machine@1.4.1 start:dev
> tsc && node dist/server.js

Loaded env file:  PROD
Sentry Logger [log]: Initializing Sentry: process: 7571, thread: main.
Sentry Logger [log]: Integration installed: InboundFilters
Sentry Logger [log]: Integration installed: FunctionToString
Sentry Logger [log]: Integration installed: LinkedErrors
Sentry Logger [log]: Integration installed: RequestData
Sentry Logger [log]: Integration installed: Console
Sentry Logger [log]: Integration installed: Http
Sentry Logger [log]: Integration installed: NodeFetch
Sentry Logger [log]: Integration installed: OnUncaughtException
Sentry Logger [log]: Integration installed: OnUnhandledRejection
Sentry Logger [log]: Integration installed: ContextLines
Sentry Logger [log]: Integration installed: LocalVariablesAsync
Sentry Logger [log]: Integration installed: Context
Sentry Logger [log]: Integration installed: Express
Sentry Logger [log]: Integration installed: Fastify
Sentry Logger [log]: Integration installed: Graphql
Sentry Logger [log]: Integration installed: Mongo
Sentry Logger [log]: Integration installed: Mongoose
Sentry Logger [log]: Integration installed: Mysql
Sentry Logger [log]: Integration installed: Mysql2
Sentry Logger [log]: Integration installed: Redis
Sentry Logger [log]: Integration installed: Postgres
Sentry Logger [log]: Integration installed: Nest
Sentry Logger [log]: Integration installed: Hapi
Sentry Logger [log]: Integration installed: Koa
Sentry Logger [log]: Integration installed: Connect
Sentry Logger [log]: Running in ESM mode.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for diag v1.8.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for trace v1.8.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for context v1.8.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for propagation v1.8.0.
Loaded sentry instrumentation
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'https' }
Sentry Logger [debug]: @opentelemetry/instrumentation-pg Applying instrumentation patch for module on require hook {
  module: 'pg-pool',
  version: '3.6.2',
  baseDir: '/Users/alexandrudochioiu/NodeJsProjects/vending-machine/node_modules/pg-pool'
}
Sentry Logger [debug]: @opentelemetry/instrumentation-pg Applying instrumentation patch for module on require hook {
  module: 'pg',
  version: '8.11.5',
  baseDir: '/Users/alexandrudochioiu/NodeJsProjects/vending-machine/node_modules/pg'
}
Sentry Logger [debug]: @opentelemetry/instrumentation-pg Patching pg.Client.prototype.query
::Started token registry prep
(node:7571) Warning: Setting the NODE_TLS_REJECT_UNAUTHORIZED environment variable to '0' makes TLS connections and HTTPS requests insecure by disabling certificate verification.
(Use `node --trace-warnings ...` to show where the warning was created)
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'https' }
[Sentry] fastify is not instrumented. Please make sure to initialize Sentry in a separate file that you `--import` when running node, see: https://docs.sentry.io/platforms/javascript/guides/fastify/install/esm/.
| ------------------------ |
| Starting cron tasks | 
| -> Req Counter : "Running pre-server"
| -> Req Counter Last Hour : 0 requests
| -> Vespr Koios Health : "Running pre-server"
Sentry Logger [debug]: Recording is off, propagating context in a non-recording span
Sentry Logger [debug]: @opentelemetry/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [debug]: @opentelemetry/instrumentation-http http.ClientRequest return request
| -> TapTools NFT Floor Prices : 0 */1 * * * *
Sentry Logger [info]: Sending checkin: taptools-nft-floor-prices in_progress
| -> Cexplorer Staking Pools : "Running pre-server"
| -> Spot ada price : "Running pre-server"
| -> Coingecko ada chart : "Running pre-server"
| <- Req Counter : "Finished pre-server in 13 ms"
Sentry Logger [debug]: Recording is off, propagating context in a non-recording span
Sentry Logger [debug]: @opentelemetry/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [debug]: @opentelemetry/instrumentation-http http.ClientRequest return request
Sentry Logger [debug]: Recording is off, propagating context in a non-recording span
Sentry Logger [debug]: @opentelemetry/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [debug]: @opentelemetry/instrumentation-http http.ClientRequest return request
Sentry Logger [debug]: Recording is off, propagating context in a non-recording span
Sentry Logger [debug]: @opentelemetry/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [debug]: @opentelemetry/instrumentation-http http.ClientRequest return request

mydea commented 4 months ago

Hmm, looks all correct. One more question, could you share your package.json, esp. the dependency versions you have installed?

AlexDochioiu commented 4 months ago

This is the (slightly truncated) package.json:

{
  "name": "vending-machine",
  "main": "./dist/server.js",
  "engines": {
    "node": "20.10.0",
    "npm": "10.7.0"
  },
  "type": "module",
  "scripts": {
    "build": "npm run lint && tsc",
    "start:dev": "tsc && node dist/server.js",
    "start": "npm run build && node dist/server.js",
    "inspect": "npm run build && node --inspect dist/server.js",
    "lint": "sh ./tools/lint.sh",
    "lint:fix": "sh ./tools/lint.sh --fix",
    "test": "mocha -r ts-node/register 'src/**/*.test.ts'",
    "vm:fresh-setup": "sh ./scripts/setup_vm.sh",
    "vm:update": "sh ./scripts/update_vm.sh",
    "vm:update-all": "sh ./scripts/update_all_vms.sh",
    "deploy": "sh ./scripts/docker_upload.sh"
  },
  "repository": {
    "type": "git",
    "url": "git+https://github.com/vespr-wallet/vending-machine.git"
  },
  "author": "",
  "license": "ISC",
  "devDependencies": {
    "@fastify/response-validation": "^2.6.0",
    "@tsconfig/node20": "^20.1.4",
    "@types/async": "^3.2.24",
    "@types/blake2b": "^2.1.3",
    "@types/chai": "^4.3.16",
    "@types/cors": "^2.8.17",
    "@types/jsonwebtoken": "^9.0.6",
    "@types/lodash-es": "^4.17.12",
    "@types/mocha": "^10.0.6",
    "@types/node": "^20.12.12",
    "@types/node-cron": "^3.0.11",
    "@types/pg": "^8.11.6",
    "@types/sinon": "^17.0.3",
    "@typescript-eslint/eslint-plugin": "^7.10.0",
    "@typescript-eslint/parser": "^7.10.0",
    "chai": "^5.1.1",
    "eslint": "^8.57.0",
    "eslint-config-airbnb-base": "^15.0.0",
    "eslint-config-prettier": "^9.1.0",
    "eslint-plugin-import": "^2.29.1",
    "eslint-plugin-prettier": "^5.1.3",
    "mocha": "^10.4.0",
    "openapi-typescript": "^6.7.6",
    "pg": "^8.11.5",
    "prettier": "^3.2.5",
    "sinon": "^18.0.0",
    "ts-node": "^10.9.2",
    "typescript": "^5.4.5"
  },
  "dependencies": {
    "@blockfrost/blockfrost-js": "^5.5.0",
    "@fastify/autoload": "^5.8.2",
    "@fastify/basic-auth": "^5.1.1",
    "@fastify/cors": "^9.0.1",
    "@fastify/formbody": "^7.4.0",
    "@fastify/rate-limit": "^9.1.0",
    "@fastify/swagger": "^8.14.0",
    "@fastify/swagger-ui": "^3.0.0",
    "@sentry/node": "^8.4.0",
    "@stricahq/cip08": "^1.0.4",
    "@vespr-wallet/maestro-org-typescript-sdk": "1.5.5-beta.3",
    "ajv": "^8.14.0",
    "ajv-formats": "^3.0.1",
    "async": "^3.2.5",
    "axios": "^1.7.2",
    "bech32": "^2.0.0",
    "bignumber.js": "^9.1.2",
    "blake2b": "^2.1.4",
    "cors": "^2.8.5",
    "csv-parser": "^3.0.0",
    "dotenv": "^16.4.5",
    "fastify": "^4.27.0",
    "fastify-plugin": "^4.5.1",
    "http": "0.0.1-security",
    "json-bigint": "^1.0.0",
    "jsonwebtoken": "^9.0.2",
    "lodash-es": "^4.17.21",
    "lru-cache": "^10.2.2",
    "lucid-cardano": "^0.10.7",
    "node-cron": "^3.0.3",
    "pg-promise": "^11.7.7"
  }
}

Also, this is the full package-lock file:

package-lock.json

AlexDochioiu commented 4 months ago

Update for the code here: Updating my start command to npm run build && node --import ./dist/env.js --import ./dist/instrument.js dist/server.js and removing the file imports (at the top of the main app .ts file) seems to not give that fastify not instrumented error from sentry.

However, while there is no error shown, I actually do not actually see the transactions appearing in the sentry dashboard. I added the debug flag and sentry is definitely getting initialized. I also added the following:

    beforeSend(event, hint) {
      hint;
      console.log(event);

      return event;
    },
    beforeSendTransaction(event, hint) {
      hint;
      console.log(event.request);

      return event;
    },

and I can confirm that beforeSend and beforeSendTransaction are called.

Later edit: It seems that errors get reported and appear as expected. It's only the transactions that do not seem to appear. I also tried to get the event id from beforeSendTransaction and I cannot find any transaction in sentry with this event id.

AlexDochioiu commented 4 months ago

Additional info for the above: Seems that they don't come up because Sentry gives the following on all transactions:

Sentry Logger [warn]: Sentry responded with status code 400 to sent event.

This failure seems to come from transports/base.js

mydea commented 4 months ago

Ahh, yes, when running in ESM mode, you need to initialize the SDK with --import in order for performance instrumentation to work properly - see https://docs.sentry.io/platforms/javascript/guides/fastify/install/esm/. You only get limited instrumentation with adding the import at the top of the file, sadly (see https://docs.sentry.io/platforms/javascript/guides/fastify/install/esm-without-import/ for details). So that is expected, sadly!

For the 400 errors... could it be that payloads are too large? If so, could you try 8.7.0 (if you are not yet using this), we added a span limit of 1000 there, maybe you exceeded this and thus the payload was dropped 🤔

AlexDochioiu commented 4 months ago

Hey @mydea I see. Glad this has been cleared about the import!

Regarding the 400 error, I already updated to 8.7.0 and I still get the same. The request seems to be sent and rejected by the sentry servers. In terms of payload, it is indeed pretty large (content-wise, I am including a large response body for some requests via Sentry.getCurrentScope().setExtra(...)).

However, this was not an issue with Sentry v7. When the data was too big, it was just getting truncated. Is this not the same for v8?

For a larger chunk of data, how do you think it's best to include? Using scope.addAttachment instead ofscope.setExtra/Sentry.addBreadcrumb?

mydea commented 4 months ago

Could you share a payload with me? I don't know, off the top of my head, that we changed something about truncation, but it could be that something slipped through... If you could share it with me per email (francesco.novy@sentry.io) that would be super helpful, then I could reproduce this more easily!

attachments can def. be used, but we should also make this work with extra, truncating data where needed!

AlexDochioiu commented 4 months ago

I will look into sending that attachment, but I made some code changes since and I have to see if I can reproduce it again 😅. I am however running into another thing and I cannot even tell if it's an issue/bug or if I am mis-using something.

Calling Sentry.getCurrentScope(); or Sentry.getIsolationScope(); seems to return a scope with a different traceId compared to Sentry.getActiveSpan().

When I add extras on Sentry.getActiveSpan(), I can see them in the sentry dashboard. But any extra/attachement/etc added to Sentry.getCurrentScope() or Sentry.getIsolationScope() seems to just vanish and not come up anywhere. Anything added by calling Sentry.setExtra() also does not show up in the dashboard.

mydea commented 4 months ago

So generally if you want to add extra data that should be attached to spans/transactions, I would recommend using e.g. Sentry.setExtra(), which basically is equivalent to Sentry.getIsolationScope().setExtra().

The reason why setting on the current scope will not necessarily work there is because the current scope is forked frequently (e.g. for every span), so the scope that is current in a given callback is most likely not the same one that was current for when the root span was started. The isolation scope, on the other hand, should be the same per request - so that would be weird if that is not applied to the transaction 🤔

The traceId is different - this is OK, because we use the trace ID in a cascading way, meaning we use the one from the active span if there is one, only falling back to the one on the scope otherwise. So that is expected!

Could you share the code where you use Sentry.setExtra(), which is not added to the transaction? Meaning, in what context/callback/etc is that called, etc?

getsantry[bot] commented 3 months ago

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you remove the label Waiting for: Community, I will leave it alone ... forever!

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

getsentry / sentry-javascript