`console.trace` causing `level:error` events in Sentry

jeysal commented 3 weeks 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/nextjs

SDK Version

7.112.2

Framework Version

Next.js 14.1.4

Link to Sentry event

https://playtnet.sentry.io/issues/5259621428

SDK Setup

Printed server-side Sentry config:

{
  dsn:
'https://d66c28aa36164b0f873a60bd0556ac90@o4504684409782272.ingest.sentry.io/4504684413845504',
  environment: 'development',
  integrations: [
    {
      name: 'CaptureConsole',
      setupOnce: [Function: setupOnce],
      setup: [Function: setup]
    },
    {
      name: 'OnUncaughtException',
      setupOnce: [Function: setupOnce],
      setup: [Function: setup]
    },
    {
      name: 'OnUnhandledRejection',
      setupOnce: [Function: setupOnce],
      setup: [Function: setup]
    },
    Mongo {
      name: 'Mongo',
      _operations: [Array],
      _describeOperations: true,
      _useMongoose: false
    },
    Prisma { name: 'Prisma' }
  ],
  tracesSampleRate: 0.02,
  beforeSend: [Function: beforeSend],
  release: '',
  beforeSendTransaction: [Function: beforeSendTransaction]
}

Notably, console capturing is set up with captureConsoleIntegration({ levels: ["warn", "error"] }) and the custom beforeSend* functions do not contain any logic that could set an event.level to 'error'

Steps to Reproduce

Some time around Thu 2024-04-25 console.traces started being captured with level:error.

We did not change our Sentry config, logging infrastructure, or relevant package versions. The Vercel/AWS Lambda Node version may or may not have changed during that time.

It could also be possible that not the logging but the pure act of capturing a stack trace (which console.trace does) is what's entering an event into Sentry?

Expected Result

console.trace calls do not cause an event in Sentry unless the console capturing integration is set up to do so.

Actual Result

console.trace calls cause a level:error event in Sentry (see example link to Sentry event)

jeysal commented 3 weeks ago

I don't know how easy it will be to track this down in case it doesn't reproduce in other Next.js apps but I can assist with that. For now my hope is that you've already seen something like this or have a clue what may have suddenly changed mid last week, so that you already have an idea where the problem could be.

mydea commented 3 weeks ago

I don't know how easy it will be to track this down in case it doesn't reproduce in other Next.js apps but I can assist with that. For now my hope is that you've already seen something like this or have a clue what may have suddenly changed mid last week, so that you already have an idea where the problem could be.

Are you sure this is actually the result of a console.trace, and not a console.error? We filter out all other console types in the capture console integration, so it must already be triggered as an error earlier 🤔 Could you check & paste one or another place from the source code that triggers this? So e.g.

// your-app.js
console.trace(...);

jeysal commented 3 weeks ago

Yes, for example for one of the simplest trace logs https://playtnet.sentry.io/issues/5259621425 , the code is

  logger.trace("Finishing match", match.id);

where logger is imported from its definition as

const statusCode = /* ... */ () => {};

const logger = {
  get error() {
    return globalThis.console.error;
  },
  get warn() {
    return globalThis.console.warn;
  },
  get info() {
    return globalThis.console.info;
  },
  get debug() {
    return globalThis.console.debug;
  },
  get trace() {
    return globalThis.console.trace;
  },
  statusCode,
};

export default logger;

It's really quite straightforward.

That's why I wondered whether perhaps it has nothing to do with console at all, but perhaps the SDK is doing some magic on globalThis.Error or so that might mean that even the act of constructing a stack trace (which console.trace probably does internally) might result in a Sentry event.

mydea commented 3 weeks ago

Hmm, so I added some tests for this specifically here: https://github.com/getsentry/sentry-javascript/pull/11830 and it seems to be working as expected 🤔

Look here: https://github.com/getsentry/sentry-javascript/pull/11830/files#diff-846c22f3c13c0f21374988eda6e64f0c844b2ba8c6561360b9050427b918faeeR70

This shows that level: 'log' for console.trace.

You can also see in the issue you linked, that there is also a breadcrumb which also shows level=error:

{
"timestamp": ....,
"type": "default",
"category": "console",
"level": "error",
"message": "Trace: Received event:  /api/events/finishMatch { json: { matchId: 'xxx' } }\n    at  ...."
},

This basically shows that this comes not from the captureConsole integration, but is already captured as level=error before that.

You can see here: https://github.com/getsentry/sentry-javascript/blob/v7/packages/utils/src/instrument/console.ts#L32 how we actually instrument the console. I can't really see how that would lead to the wrong level being captured for console.trace 🤔

jeysal commented 3 weeks ago

I'll try to reduce the issue a bit to track down the cause. One thing that's also strange is that at the same time as this started happening, in our log aggregator console.trace logs started showing up with a full stack trace like they in local Node.js, which before that they did not. That's what made me think this might come from an infrastructure change on Vercel/AWS functions. I was hoping ideally it would turn out to just be a Node.js minor bump or so that changed behavior and caused this, but it looks like most people aren't seeing this behavior like we are 😄

getsentry / sentry-javascript