Problems with `@sentry/astro` on Netlify

mydea commented 2 months ago

Raised by @whitep4nth3r , there seem to be some issues with an astro app deployed to netfliy.

Repro: https://github.com/whitep4nth3r/p4nth3rworld

When running locally, stuff seems to work as far as I can tell. But when deployed to production (on Netlify), you can see that often no server transaction is sent: https://the-claw.sentry.io/performance/trace/ffcc30d02ff374907a3bef54c998f338/ (only a pageload).

It is sent sometimes but not always, leading to broken traces etc.

While looking more into this, when enabling debug logs, we found some things:

This log:

WARN   Sentry Logger [warn]: Failed to register ESM hook Error [ERR_MODULE_NOT_FOUND]: Cannot find module '/var/task/node_modules/@opentelemetry/instrumentation/hook.mjs' imported from /var/task/node_modules/@sentry/node/esm/sdk/initOtel.js
    at finalizeResolution (node:internal/modules/esm/resolve:269:11)
    at moduleResolve (node:internal/modules/esm/resolve:937:10)
    at moduleResolveWithNodePath (node:internal/modules/esm/resolve:1161:14)
    at defaultResolve (node:internal/modules/esm/resolve:1204:79)
    at nextResolve (node:internal/modules/esm/hooks:866:28)
    at Hooks.resolve (node:internal/modules/esm/hooks:304:30)
    at ModuleLoader.resolve (node:internal/modules/esm/loader:345:35)
    at ModuleLoader.getModuleJob (node:internal/modules/esm/loader:227:38)
    at ModuleLoader.import (node:internal/modules/esm/loader:315:34)
    at Hooks.register (node:internal/modules/esm/hooks:165:53) {
  code: 'ERR_MODULE_NOT_FOUND',
  url: 'file:///var/task/node_modules/@opentelemetry/instrumentation/hook.mjs'
}

These logs:

something seems to be off there 🤔

whitep4nth3r commented 2 months ago

If anyone needs any more info, I'm here!

s1gr1d commented 2 months ago

I could reproduce it with my own example (repo: https://github.com/s1gr1d/example.astro-sentry-netlify).

Some things I saw in the function log on Netlify:

Sentry Logger [log]: Could not load NodeFetch instrumentation. on Netlify (does not happen locally)
I don't see all events in Sentry (but I am getting them in the function logs). I just got the success spans in Sentry
- [Tracing] Finishing "http.server" root span "GET /" with ID 4743f742c010d44a
- [Tracing] Finishing "http.server" root span "GET /" with ID 44621bba8f17b5e9
- [Tracing] Finishing "http.server" root span "GET /test-param-success/[param]" with ID e6ce337a1e36aec9
- [Tracing] Finishing "http.server" root span "GET /test-param-error/[param]" with ID b95ae735524c9139
- the span for /test-success/ is missing -> this one is a static page with no fetch call
ESM error on server start

ESM hook error


a7364239 WARN   Sentry Logger [warn]: Failed to register ESM hook Error [ERR_MODULE_NOT_FOUND]: Cannot find module '/var/task/node_modules/@opentelemetry/instrumentation/hook.mjs' imported from /var/task/node_modules/@sentry/node/esm/sdk/initOtel.js
    at new NodeError (node:internal/errors:405:5)
    at finalizeResolution (node:internal/modules/esm/resolve:332:11)
    at moduleResolve (node:internal/modules/esm/resolve:1029:10)
    at moduleResolveWithNodePath (node:internal/modules/esm/resolve:876:12)
    at defaultResolve (node:internal/modules/esm/resolve:1242:79)
    at nextResolve (node:internal/modules/esm/hooks:864:28)
    at Hooks.resolve (node:internal/modules/esm/hooks:302:30)
    at ModuleLoader.resolve (node:internal/modules/esm/loader:366:35)
    at ModuleLoader.getModuleJob (node:internal/modules/esm/loader:250:38)
    at ModuleLoader.import (node:internal/modules/esm/loader:336:34) {
  url: 'file:///var/task/node_modules/@opentelemetry/instrumentation/hook.mjs',
  code: 'ERR_MODULE_NOT_FOUND'
}

Complete Logs

```bash Jun 24, 11:23:13 AM: INIT_START Runtime Version: nodejs:18.v30 Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:f89c264158db39a1cfcbb5f9b3741413df1cfce4d550c9a475a67d923e19e2f4 Jun 24, 11:23:15 AM: a7364239 WARN Sentry Logger [warn]: Failed to register ESM hook Error [ERR_MODULE_NOT_FOUND]: Cannot find module '/var/task/node_modules/@opentelemetry/instrumentation/hook.mjs' imported from /var/task/node_modules/@sentry/node/esm/sdk/initOtel.js at new NodeError (node:internal/errors:405:5) at finalizeResolution (node:internal/modules/esm/resolve:332:11) at moduleResolve (node:internal/modules/esm/resolve:1029:10) at moduleResolveWithNodePath (node:internal/modules/esm/resolve:876:12) at defaultResolve (node:internal/modules/esm/resolve:1242:79) at nextResolve (node:internal/modules/esm/hooks:864:28) at Hooks.resolve (node:internal/modules/esm/hooks:302:30) at ModuleLoader.resolve (node:internal/modules/esm/loader:366:35) at ModuleLoader.getModuleJob (node:internal/modules/esm/loader:250:38) at ModuleLoader.import (node:internal/modules/esm/loader:336:34) { url: 'file:///var/task/node_modules/@opentelemetry/instrumentation/hook.mjs', code: 'ERR_MODULE_NOT_FOUND' } Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Initializing Sentry: process: 17, thread: main. Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: InboundFilters Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: FunctionToString Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: LinkedErrors Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: RequestData Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Console Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Http Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: NodeFetch Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: OnUncaughtException Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: OnUnhandledRejection Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: ContextLines Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: LocalVariables Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Context Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Express Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Fastify Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Graphql Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Mongo Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Mongoose Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Mysql Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Mysql2 Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Redis Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Postgres Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Nest Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Hapi Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Koa Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Integration installed: Connect Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Running in ESM mode. Jun 24, 11:23:15 AM: a7364239 DEBUG Sentry Logger [debug]: @opentelemetry/api: Registered a global for diag v1.9.0. Jun 24, 11:23:15 AM: a7364239 DEBUG Sentry Logger [debug]: @opentelemetry/api: Registered a global for trace v1.9.0. Jun 24, 11:23:15 AM: a7364239 DEBUG Sentry Logger [debug]: @opentelemetry/api: Registered a global for context v1.9.0. Jun 24, 11:23:15 AM: a7364239 DEBUG Sentry Logger [debug]: @opentelemetry/api: Registered a global for propagation v1.9.0. Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: [Tracing] Starting sampled root span op: < unknown op > name: GET / ID: 4743f742c010d44a Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: [Tracing] Finishing "http.server" root span "GET /" with ID 4743f742c010d44a Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: Could not load NodeFetch instrumentation. Jun 24, 11:23:15 AM: a7364239 INFO Sentry Logger [log]: SpanExporter exported 1 spans, 0 unsent spans remaining Jun 24, 11:23:15 AM: a7364239 Duration: 675.74 ms Memory Usage: 176 MB Init Duration: 1475.44 ms Jun 24, 11:28:07 AM: 4d234179 INFO Sentry Logger [log]: [Tracing] Starting sampled root span op: < unknown op > name: GET / ID: 44621bba8f17b5e9 Jun 24, 11:28:07 AM: 4d234179 INFO Sentry Logger [log]: [Tracing] Finishing "http.server" root span "GET /" with ID 44621bba8f17b5e9 Jun 24, 11:28:07 AM: 4d234179 INFO Sentry Logger [log]: SpanExporter exported 1 spans, 0 unsent spans remaining Jun 24, 11:28:07 AM: 4d234179 Duration: 188.16 ms Memory Usage: 178 MB Jun 24, 11:28:33 AM: INIT_START Runtime Version: nodejs:18.v30 Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:f89c264158db39a1cfcbb5f9b3741413df1cfce4d550c9a475a67d923e19e2f4 Jun 24, 11:28:35 AM: c1a73ec1 INFO Sentry Logger [log]: [Tracing] Finishing "http.server" root span "GET /test-param-success/[param]" with ID e6ce337a1e36aec9 Jun 24, 11:28:35 AM: c1a73ec1 INFO Sentry Logger [log]: SpanExporter exported 1 spans, 0 unsent spans remaining Jun 24, 11:28:35 AM: c1a73ec1 Duration: 2072.18 ms Memory Usage: 178 MB Jun 24, 11:28:55 AM: 52973d5e INFO Sentry Logger [log]: [Tracing] Starting sampled root span op: < unknown op > name: GET /test-param-error/[param] ID: b95ae735524c9139 Jun 24, 11:28:55 AM: fc013641 Duration: 109.92 ms Memory Usage: 160 MB Jun 24, 11:28:55 AM: 52973d5e INFO Sentry Logger [log]: [Tracing] Finishing "http.server" root span "GET /test-param-error/[param]" with ID b95ae735524c9139 Jun 24, 11:28:55 AM: 52973d5e INFO Sentry Logger [log]: SpanExporter exported 1 spans, 0 unsent spans remaining Jun 24, 11:28:55 AM: 52973d5e Duration: 202.21 ms Memory Usage: 178 MB Jun 24, 11:29:34 AM: INIT_START Runtime Version: nodejs:18.v30 Runtime Version ARN: arn:aws:lambda:us-east-2::runtime:f89c264158db39a1cfcbb5f9b3741413df1cfce4d550c9a475a67d923e19e2f4 ```

timfish commented 2 months ago

Without trying the code out yet myself, the ESM hook error suggests the app is bundled in some way or the full node_modules isn't getting deployed.

It's trying to load /var/task/node_modules/@opentelemetry/instrumentation/hook.mjs but it can't be found.

timfish commented 2 months ago

I still need to test this locally to confirm but I think this issue is caused by the Netlify tooling not including all the required files in production builds. Netlify uses @netlify/zip-it-and-ship-it to collect all the files required for a production deploy, which in turn uses @vercel/nft to resolve all the required source files.

My best guess so far is that this does not pick up that the otel hook should be included in the production build.

timfish commented 2 months ago

I suspect this is caused by https://github.com/vercel/nft/issues/428

You can probably work around this for now by specifying included_files in your config and forcing it to include the missing files.

whitep4nth3r commented 2 months ago

I attempted this.

Attempt 1

Include the node_modules/@opentelemetry/instrumentation/hook.mjs in my netlify.toml file as follows:

[functions]
  included_files = ["node_modules/@opentelemetry/instrumentation/hook.mjs"]

The initial error disappeared, and now the logs were showing a different error:

Jun 25, 11:31:19 AM: 518d1b15 WARN   Sentry Logger [warn]: Failed to register ESM hook Error [ERR_MODULE_NOT_FOUND]: Cannot find module '/var/task/node_modules/import-in-the-middle/hook.js' imported from /var/task/node_modules/import-in-the-middle/hook.mjs
    at finalizeResolution (node:internal/modules/esm/resolve:269:11)
    at moduleResolve (node:internal/modules/esm/resolve:937:10)
    at moduleResolveWithNodePath (node:internal/modules/esm/resolve:1161:14)
    at defaultResolve (node:internal/modules/esm/resolve:1204:79)
    at nextResolve (node:internal/modules/esm/hooks:866:28)
    at Hooks.resolve (node:internal/modules/esm/hooks:304:30)
    at ModuleLoader.resolve (node:internal/modules/esm/loader:345:35)
    at ModuleLoader.getModuleJob (node:internal/modules/esm/loader:227:38)
    at ModuleWrap.<anonymous> (node:internal/modules/esm/module_job:87:39)
    at link (node:internal/modules/esm/module_job:86:36) {
  code: 'ERR_MODULE_NOT_FOUND',
  url: 'file:///var/task/node_modules/import-in-the-middle/hook.js'
}

The file that is now missing is the file mentioned in https://github.com/vercel/nft/issues/428.

Attempt 2

Let's see if including the second missing file solves things.

New netlify.toml configuration:

[functions]
  included_files = ["node_modules/@opentelemetry/instrumentation/hook.mjs", "node_modules/import-in-the-middle/hook.mjs"]

This did not fix it. I saw the same error where the import-in-the-middle hook file was reported missing.

I also saw this error in the logs a little time after, presumably because of the previous errors.

Jun 25, 11:34:53 AM: b82c400a ERROR  Sentry Logger [error]: Error while sending event: Error: Client network socket disconnected before secure TLS connection was established
    at TLSSocket.onConnectEnd (node:_tls_wrap:1727:19)
    at TLSSocket.emit (node:events:531:35)
    at endReadableNT (node:internal/streams/readable:1696:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
  code: 'ECONNRESET',
  path: null,
  host: 'o4505635661873152.ingest.us.sentry.io',
  port: 443,
  localAddress: undefined
}

timfish commented 2 months ago

I suspect you might need to include more so that not only the missing file is included, but also all the files it references too:

[functions]
  included_files = ["node_modules/@opentelemetry/instrumentation/*", "node_modules/import-in-the-middle/*"]

However, both of these dependencies have their own dependencies too so you might need to go as far as including all of node_modules:

[functions]
  included_files = ["node_modules/*"]

This is far from ideal though as I suspect this increases the deployment bundle size considerably!

whitep4nth3r commented 2 months ago

Oof, yeah I'm not going to do that 😅

s1gr1d commented 2 months ago

What I found out so far: Netlify is automatically creating a Netlify Function for the Astro server-side rendering (source) and this function is throwing the error. However, I found no way to test this locally with the CLI, as I have no function defined in the code and Netlify just generates the function automatically. Locally, there seems to be no issue.

It looks like this is not a problem with Astro, but rather one with Netlify and how they get their dependencies.

I attempted something similar as @whitep4nth3r (the changes to the netlify.toml can be seen in the history of the file here)

Attempt 1: Adding the OTel module with the hook

I tried different variants (can be seen in the history of the file here). But those led to the same outcome.

Those are all the variants:

[functions]
  node_bundler = "esbuild"
  external_node_modules = ["@opentelemetry/instrumentation/hook.mjs"]

[functions]
  external_node_modules = ["/var/task/node_modules/@opentelemetry/instrumentation/hook.mjs"]

[functions]
  node_bundler = "esbuild"
  external_node_modules = ["@opentelemetry/instrumentation/hook.mjs"]

[functions]
  node_bundler = "esbuild"
  included_files = ["node_modules/@opentelemetry/instrumentation/hook.mjs"]

[functions]
  node_bundler = "esbuild"
  external_node_modules = ["@opentelemetry/instrumentation"]

[functions]
  node_bundler = "esbuild"
  external_node_modules = ["@opentelemetry/instrumentation"]
  included_files = ["node_modules/@opentelemetry/instrumentation/**"]

[functions]
  node_bundler = "esbuild"
  external_node_modules = ["@opentelemetry/instrumentation", "import-in-the-middle"]
  included_files = ["node_modules/@opentelemetry/instrumentation/**", "node_modules/import-in-the-middle/**"]

--> no change in the error message

Attempt 2: include all node_modules

  [functions]
     node_bundler = "esbuild"
     external_node_modules = ["@opentelemetry/instrumentation", "import-in-the-middle"]
     included_files = ["node_modules/*"]

also this:

  [functions]
     included_files = ["node_modules/*"]

--> no change in the error message

Attempt 3: Adding various different files

[functions]
  included_files = ["node_modules/@opentelemetry/instrumentation/*", "node_modules/import-in-the-middle/*", "node_modules/acorn-import-attributes/*"]

This gave the following error message:

  Error: Cannot find module './lib/get-exports.js'
Require stack:
- /var/task/node_modules/import-in-the-middle/hook.js
    at Module._resolveFilename (node:internal/modules/cjs/loader:1140:15)
    at Module._load (node:internal/modules/cjs/loader:981:27)
    at Module.require (node:internal/modules/cjs/loader:1231:19)
    at require (node:internal/modules/helpers:177:18)
    at Object.<anonymous> (/var/task/node_modules/import-in-the-middle/hook.js:20:16)
    at Module._compile (node:internal/modules/cjs/loader:1364:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1422:10)
    at Module.load (node:internal/modules/cjs/loader:1203:32)
    at Module._load (node:internal/modules/cjs/loader:1019:12)
    at ModuleWrap.<anonymous> (node:internal/modules/esm/translators:203:29) {
  code: 'MODULE_NOT_FOUND',
  requireStack: [ '/var/task/node_modules/import-in-the-middle/hook.js' ]
}

Attempt 4: Adding OTel to the package.json

  "@opentelemetry/instrumentation": "^0.52.1",

New error message:

  Failed to register ESM hook Error [ERR_MODULE_NOT_FOUND]: Cannot find module '/var/task/node_modules/import-in-the-middle/hook.mjs' imported from /var/task/node_modules/@opentelemetry/instrumentation/hook.mjs

Attempt 5: Adding import-in-the-middle

  "import-in-the-middle": "1.8.1"

New error message:

  rror: Cannot find module 'acorn-import-attributes'
Require stack:
- /var/task/node_modules/import-in-the-middle/lib/get-esm-exports.js
- /var/task/node_modules/import-in-the-middle/lib/get-exports.js
- /var/task/node_modules/import-in-the-middle/hook.js
    at Module._resolveFilename (node:internal/modules/cjs/loader:1140:15)
    at Module._load (node:internal/modules/cjs/loader:981:27)
    at Module.require (node:internal/modules/cjs/loader:1231:19)
    at require (node:internal/modules/helpers:177:18)
    at Object.<anonymous> (/var/task/node_modules/import-in-the-middle/lib/get-esm-exports.js:4:30)
    at Module._compile (node:internal/modules/cjs/loader:1364:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1422:10)
    at Module.load (node:internal/modules/cjs/loader:1203:32)
    at Module._load (node:internal/modules/cjs/loader:1019:12)
    at Module.require (node:internal/modules/cjs/loader:1231:19) {
  code: 'MODULE_NOT_FOUND',
  requireStack: [
    '/var/task/node_modules/import-in-the-middle/lib/get-esm-exports.js',
    '/var/task/node_modules/import-in-the-middle/lib/get-exports.js',
    '/var/task/node_modules/import-in-the-middle/hook.js'
  ]
}

Other stuff

I changed the build command in the Netlify configuration, so it prints the content of the file. This will happen after "Initializing" which installs the packages.

[build]
  command = "cd node_modules/@opentelemetry/instrumentation && ls"

In the output we can see that the hook.mjs file is there. But at some stage (maybe after the build?), netlify is deleting those files.

11:23:14 AM: $ cd node_modules/@opentelemetry/instrumentation && ls
11:23:14 AM: build
11:23:14 AM: hook.mjs
11:23:14 AM: LICENSE
11:23:14 AM: node_modules
11:23:14 AM: package.json
11:23:14 AM: README.md

whitep4nth3r commented 2 months ago

I've opened an issue in the Netlify organisation and have referenced this issue.

AbhiPrasad commented 1 month ago

NFT PR: https://github.com/vercel/nft/pull/429

getsentry / sentry-javascript