getsentry / sentry-react-native

Official Sentry SDK for React Native
https://sentry.io
MIT License
1.57k stars 333 forks source link

[ReactNavigationInstrumentation] Will not send transactiondue to beforeNavigate on react navigation v5 #4109

Open Lerosen opened 1 week ago

Lerosen commented 1 week ago

OS:

Platform:

SDK:

SDK version: 5.32.0

react-native version: 0.74.3

Are you using Expo?

Are you using sentry.io or on-premise?

If you are using sentry.io, please post a link to your issue so we can take a look:

[Link to issue]

Configuration:

(@sentry/react-native)

const routingInstrumentation = Sentry.reactNavigationIntegration({
  enableTimeToInitialDisplay: true
});

Sentry.init({
  dsn: "XXX",
  debug: true, // If `true`, Sentry will try to print out useful debugging information if something goes wrong with sending the event. Set it to `false` in production
  enabled: !__DEV__ || true,
  environment: __DEV__ ? "development" : "production",
  integrations: [
    Sentry.reactNativeTracingIntegration({
      routingInstrumentation
    })
  ],
  enableTracing: true,
  tracesSampleRate: 1.0
});

I have the following issue:

I am using Sentry with ReactNavigation v5 ("@react-navigation/native": "^5.9.8"). I set up the screen tracing instrumentation as documented. For debugging purposes I also added my own logging of routing events.

The issue that I don't get any Screen load events. THe log indicated that all navigation events are correctly detected but each transaction is discarded because the sample property is false. I tried to find the cause for this but had no luck so far. I don't have any beforeNavigate handler configured.

Steps to reproduce:

Actual result:

  Sentry Logger [log]: [TouchEvents] Touch event within element: View
 LOG  Sentry Logger [log]: [TouchEvents] Touch event within element: View
 LOG  Sentry Logger [log]: Setting idle transaction on scope. Span ID: 846bcc77673deb37
 DEBUG  Sentry Logger [debug]: [NativeFrames] Fetching frames for root span start (846bcc77673deb37).
 LOG  Sentry Logger [log]: [ReactNativeTracing] Starting navigation transaction "Route Change" on scope
 LOG  before[event=__unsafe_action__] undefined {"action": {"payload": {"name": "test_screen", "params": undefined}, "target": "tab-eoC-AJVrF_9H8QZchBZHd", "type": "JUMP_TO"}, "noop": false}
 LOG  Sentry Logger [log]: [ReactNavigationInstrumentation] Will not send transaction "test_screen" due to beforeNavigate.
 LOG  after[event=state] {"key": "update_notes-BxXRVcpR-K59Cvc6hnoxB", "name": "test_screen", "params": undefined}
 LOG  Sentry Logger [log]: [Tracing] No active IdleTransaction
 LOG  Sentry Logger [log]: [Tracing] Discarding transaction because its trace was not chosen to be sampled.
 LOG  Sentry Logger [log]: Recording outcome: "sample_rate:transaction"

Expected result: The transaction should not be discarded but send.

rwachtler commented 6 days ago

Hey @Lerosen! 👋

Since I'm not a seasoned contributor, please consider my advice as my personal take at your issue.

I've compared your configuration to the documented reference (and also cross-checked the examples here, since you're using 5.32.0). Didn't really discover any discrepancies there and given the logs you provided, the instrumentation is obviously detecting the events.

TLDR: I assume that you run into a state-change timeout. You could try setting routeChangeTimeoutMs to some higher value than 1000.

Long version:

Here is my shot at what's happening:

  1. I've looked up the log
[ReactNavigationInstrumentation] Will not send transaction [...] due to beforeNavigate.

and found it here, which gave me a clue that finalContext.sampled must be still false.

  1. Since you're not manipulating the sampled prop, I've also searched for __unsafe_action__ which led me to _onDispatch here.

Its description being the following:

/**
   * To be called on every React-Navigation action dispatch.
   * It does not name the transaction or populate it with route information. Instead, it waits for the state to fully change
   * and gets the route information from there, @see _onStateChange
   */

the description above plus an explanation

  1. While looking into the body of _onDispatch , I was wondering if you actually run into a state-change timeout. As noted here
 * - If `_onStateChange` isn't called within `STATE_CHANGE_TIMEOUT_DURATION` of the dispatch, then the transaction is not sampled and finished.

resulting in sampled being set to false (see this).

  1. Resolution proposal would be setting routeChangeTimeoutMs > 1000.
Lerosen commented 6 days ago

Thank you for taking the time to look into this and for your detailed answer. But the timeout is not the problem, it is triggered much later, way after the log iscarding transaction because its trace was not chosen to be sampled.. I also tried a higher value of 10000 for the routeChangeTimeoutMs, but that didn't help.

I also checked the context in thebeforeNavigate callback, at that point context.sampled is already false which is clearly not expected.

If I override it as follows

beforeNavigate: (context) => {
        console.info("--> beforeNavigate, sampled=", context.sampled);
        return ({...context, sampled: true});
      }

i get the efollowing log

LOG  Sentry Logger [log]: [ReactNativeTracing] Starting navigation transaction "Route Change" on scope
 LOG  before[event=__unsafe_action__] undefined {"action": {"payload": {"name": "update_content", "params": [Object]}, "source": "welcome-NTgh13p3bkwSFrDOgXxev", "type": "PUSH"}, "noop": false}
 INFO  --> beforeNavigate, sampled= false
 LOG  after[event=state] {"key": "test_screen-_0dZX1AkYU55SSC-XDLXn", "name": "test_screen", "params": undefined}
 LOG  Sentry Logger [log]: [Tracing] No active IdleTransaction
 LOG  Sentry Logger [log]: [Tracing] Finishing navigation transaction: test_screen.

which indicates that there may be a problem with the "idle transaction" not getting created correctly or removed too early or something else 😨

/**
 * Instrumentation for React-Navigation V5 and above. See docs or sample app for usage.
 *
 * How this works:
 * - `_onDispatch` is called every time a dispatch happens and sets an IdleTransaction on the scope without any route context.
 * - `_onStateChange` is then called AFTER the state change happens due to a dispatch and sets the route context onto the active transaction.
 * - If `_onStateChange` isn't called within `STATE_CHANGE_TIMEOUT_DURATION` of the dispatch, then the transaction is not sampled and finished.
 */
rwachtler commented 6 days ago

Thank you for providing additional context!

But the timeout is not the problem, it is triggered much later, way after the log iscarding transaction because its trace was not chosen to be sampled..

Hmm, good point. I'm currently on my mobile, I will look into it further once I've access to my Mac again. 😅

Update:

It looks like the log

 LOG  Sentry Logger [log]: [Tracing] Discarding transaction because its trace was not chosen to be sampled.

is from here.

Given that if you override sampled: true manually (as you've done in your latest comment), that seems to "capture" the transaction as expected. 🤔

Regarding Sentry Logger [log]: [Tracing] No active IdleTransaction --> it seems like this check is evaluated as falsy.

Do you actually mind sharing your NavigationContainer as well?

lucas-zimerman commented 4 days ago

Hi and thank you for opening this issue! Did the transaction get discarded right away, or after the defined time on routeChangeTimeoutMs?