[React Router] Transaction unexpectedly ended early, cancelling spans from componentDidMount() #6470

realkosty · 2022-12-08T06:15:43Z

Is there an existing issue for this?

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

How do you use Sentry?

Sentry Saas (sentry.io)

Which package are you using?

@sentry/react

SDK Version

7.17.3 - but tested on 7.23.0 with same result

Framework Version

17.0.2 (react-router-dom: 6.4.3)

Link to Sentry event

https://sentry.io/organizations/testorg-az/performance/application-monitoring-javascript:755fa61c341044a19a38b718efff2b35/?project=5808623&query=sdk.version%3A7.17.3&referrer=performance-transaction-summary&statsPeriod=30d&transaction=%2Fproducts&unselectedSeries=p100()

Steps to Reproduce

Examine our project's SDK configuration index.js#L60-65 and index.js#L104
0.1 Examine code that initiates span that gets cut short before it finishes: Products.js#L39 - called from componentDidMount()
Go to https://application-monitoring-react-dot-sales-engineering-sf.appspot.com/products
Open devtools
(optional) set breakpoint in idletransaction.tx - will eventually point you to reactrouterv6.tsx: handleNavigation() and _useEffect()
Reload page
Inspect console log (Debug level)
Get transaction ID from Network tab and plug into search in /products transaction of this project

Internal ticket: https://getsentry.atlassian.net/browse/FEEDBACK-1679

Expected Result

Transaction runs its course and does not finish prematurely before http.client span (GET https://.../products) is complete.

Actual Result

Logs show "[Tracing] cancelling span since transaction ended early"
In Sentry UI the last http.client span (GET https://.../products) of the transaction is cut short even though corresponding backend transaction is ~ 2 seconds.

The text was updated successfully, but these errors were encountered:

thinkocapo · 2022-12-08T10:00:12Z

As a result of the problem described above, see that the bottom http.client txn here says 90.40ms...

but when you click the plus '+' to open it, it says 3,447 ms

Here's an additonal transaction showing the same problem.

VIDEO - If you want to see the expected behavior (how it worked with JS SDK v6.X.X) watch this VIDEO (2minutes) where I show v6 versus v7 outcomes.

You'll see that with v6 you get all those additional spans which are now getting cancelled in v7.
https://www.loom.com/share/ff29f11806b94b94a79de46171e4c69b

thinkocapo · 2022-12-09T13:35:35Z

Here is some output from using Sentry.init({ debug:true }) regarding the cancelled spans.

example1

ENVIRONMENT test
index.js:49 RELEASE [email protected]
logger.ts:72 Sentry Logger [log]: Integration installed: InboundFilters
logger.ts:72 Sentry Logger [log]: Integration installed: FunctionToString
logger.ts:72 Sentry Logger [log]: Integration installed: TryCatch
logger.ts:72 Sentry Logger [log]: Integration installed: Breadcrumbs
logger.ts:72 Sentry Logger [log]: Global Handler attached: onerror
logger.ts:72 Sentry Logger [log]: Global Handler attached: onunhandledrejection
logger.ts:72 Sentry Logger [log]: Integration installed: GlobalHandlers
logger.ts:72 Sentry Logger [log]: Integration installed: LinkedErrors
logger.ts:72 Sentry Logger [log]: Integration installed: Dedupe
logger.ts:72 Sentry Logger [log]: Integration installed: HttpContext
logger.ts:72 Sentry Logger [log]: [Tracing] Starting pageload transaction on scope
logger.ts:72 Sentry Logger [log]: Setting idle transaction on scope. Span ID: a5bcc5765a16423b
logger.ts:72 Sentry Logger [log]: [Tracing] starting pageload transaction - /products
logger.ts:72 Sentry Logger [log]: Starting heartbeat
logger.ts:72 Sentry Logger [log]: pinging Heartbeat -> current counter: 0
logger.ts:72 Sentry Logger [log]: Integration installed: BrowserTracing
instrument.ts:124 > backendType: flask | backendUrl: http://localhost:8080
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: bb772d712718d0d2
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 1
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.mount' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: 98c45cc4588817f8
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 2
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.mount' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] popActivity bb772d712718d0d2
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 1
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: b88747278ae470fc
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 2
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: 98e6977faabf9cb5
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 3
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: 895f72bf4987c75a
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 4
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: b6b657b27c142019
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 5
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] popActivity 98c45cc4588817f8
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 4
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.long-task' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] finishing IdleTransaction 2022-12-05T15:51:40.280Z pageload
logger.ts:72 Sentry Logger [log]: [Tracing] Adding & adjusting spans using Performance API
2logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (a5bcc5765a16423b).
2logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'resource.link' span on transaction '/products' (a5bcc5765a16423b).
3logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'resource.script' span on transaction '/products' (a5bcc5765a16423b).
4logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'resource.css' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'mark' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'paint' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Measurements] Adding FP
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'paint' span on transaction '/products' (a5bcc5765a16423b).
logger.ts:72 Sentry Logger [log]: [Measurements] Adding FCP
logger.ts:72 Sentry Logger [log]: [Measurements] Adding TTFB
logger.ts:72 Sentry Logger [log]: [Measurements] Normalized fcp from 464.3999999985099 to 460.70003509521484 (-3.69996490329504)
logger.ts:72 Sentry Logger [log]: [Measurements] Normalized fp from 464.3999999985099 to 460.70003509521484 (-3.69996490329504)
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/api",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/api",
  "op": "http.client",
  "parent_span_id": "a5bcc5765a16423b",
  "span_id": "b88747278ae470fc",
  "start_timestamp": 1670255500.2338,
  "status": "cancelled",
  "timestamp": 1670255500.2808,
  "trace_id": "8ce93f2af23e4b5b9b458282e15222be"
}
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/connect",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/connect",
  "op": "http.client",
  "parent_span_id": "a5bcc5765a16423b",
  "span_id": "98e6977faabf9cb5",
  "start_timestamp": 1670255500.2353,
  "status": "cancelled",
  "timestamp": 1670255500.2808,
  "trace_id": "8ce93f2af23e4b5b9b458282e15222be"
}
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/organization",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/organization",
  "op": "http.client",
  "parent_span_id": "a5bcc5765a16423b",
  "span_id": "895f72bf4987c75a",
  "start_timestamp": 1670255500.2372003,
  "status": "cancelled",
  "timestamp": 1670255500.2808,
  "trace_id": "8ce93f2af23e4b5b9b458282e15222be"
}
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/products",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/products",
  "op": "http.client",
  "parent_span_id": "a5bcc5765a16423b",
  "span_id": "b6b657b27c142019",
  "start_timestamp": 1670255500.2388,
  "status": "cancelled",
  "timestamp": 1670255500.2808,
  "trace_id": "8ce93f2af23e4b5b9b458282e15222be"
}
logger.ts:72 Sentry Logger [log]: [Tracing] flushing IdleTransaction
logger.ts:72 Sentry Logger [log]: [Measurements] Adding measurements to transaction {
  "fp": {
    "value": 460.70003509521484,
    "unit": "millisecond"
  },
  "fcp": {
    "value": 460.70003509521484,
    "unit": "millisecond"
  },
  "connection.rtt": {
    "value": 50,
    "unit": "millisecond"
  },
  "ttfb": {
    "value": 14.299869537353516,
    "unit": "millisecond"
  },
  "ttfb.requestTime": {
    "value": 11.399984359741211,
    "unit": "millisecond"
  }
}
logger.ts:72 Sentry Logger [log]: [Tracing] Finishing pageload transaction: /products.
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.update' span on transaction '/products' (a5bcc5765a16423b).
instrument.ts:124 > Nav shouldComponentUpdate
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.update' span on transaction '/products' (a5bcc5765a16423b).
redux-logger.js:1  action SET_PRODUCTS @ 16:51:43.795
instrument.ts:124  prev state {cart: {…}, products: Array(0), flag: false}
instrument.ts:124  action     {type: 'SET_PRODUCTS', payload: {…}}
instrument.ts:124  next state {cart: {…}, products: Array(4), flag: undefined}

example2

ENVIRONMENT test
index.js:49 RELEASE [email protected]
logger.ts:72 Sentry Logger [log]: Integration installed: InboundFilters
logger.ts:72 Sentry Logger [log]: Integration installed: FunctionToString
logger.ts:72 Sentry Logger [log]: Integration installed: TryCatch
logger.ts:72 Sentry Logger [log]: Integration installed: Breadcrumbs
logger.ts:72 Sentry Logger [log]: Global Handler attached: onerror
logger.ts:72 Sentry Logger [log]: Global Handler attached: onunhandledrejection
logger.ts:72 Sentry Logger [log]: Integration installed: GlobalHandlers
logger.ts:72 Sentry Logger [log]: Integration installed: LinkedErrors
logger.ts:72 Sentry Logger [log]: Integration installed: Dedupe
logger.ts:72 Sentry Logger [log]: Integration installed: HttpContext
logger.ts:72 Sentry Logger [log]: [Tracing] Starting pageload transaction on scope
logger.ts:72 Sentry Logger [log]: Setting idle transaction on scope. Span ID: 844e01d036946228
logger.ts:72 Sentry Logger [log]: [Tracing] starting pageload transaction - /products
logger.ts:72 Sentry Logger [log]: Starting heartbeat
logger.ts:72 Sentry Logger [log]: pinging Heartbeat -> current counter: 0
logger.ts:72 Sentry Logger [log]: Integration installed: BrowserTracing
instrument.ts:124 > backendType: flask | backendUrl: http://localhost:8080
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: b9e87bc225e51447
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 1
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.mount' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: aa1dc2f175479627
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 2
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.mount' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] popActivity b9e87bc225e51447
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 1
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: 8ed131ee0a77df49
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 2
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: 8cb0c82b3bfdec0a
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 3
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: b492710e0e9d587a
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 4
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] pushActivity: abb1a35702a7ffd3
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 5
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'http.client' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] popActivity aa1dc2f175479627
logger.ts:72 Sentry Logger [log]: [Tracing] new activities count 4
2logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.long-task' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] finishing IdleTransaction 2022-12-05T15:53:37.810Z pageload
logger.ts:72 Sentry Logger [log]: [Tracing] Adding & adjusting spans using Performance API
2logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'browser' span on transaction '/products' (844e01d036946228).
2logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'resource.link' span on transaction '/products' (844e01d036946228).
3logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'resource.script' span on transaction '/products' (844e01d036946228).
4logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'resource.css' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'mark' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'paint' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Measurements] Adding FP
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'paint' span on transaction '/products' (844e01d036946228).
logger.ts:72 Sentry Logger [log]: [Measurements] Adding FCP
logger.ts:72 Sentry Logger [log]: [Measurements] Adding TTFB
logger.ts:72 Sentry Logger [log]: [Measurements] Normalized fcp from 559.6000000014901 to 553.4000396728516 (-6.199960328638554)
logger.ts:72 Sentry Logger [log]: [Measurements] Normalized fp from 559.6000000014901 to 553.4000396728516 (-6.199960328638554)
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/api",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/api",
  "op": "http.client",
  "parent_span_id": "844e01d036946228",
  "span_id": "8ed131ee0a77df49",
  "start_timestamp": 1670255617.7614002,
  "status": "cancelled",
  "timestamp": 1670255617.8103,
  "trace_id": "abae10f022ab40028b8563ebaa2de109"
}
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/connect",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/connect",
  "op": "http.client",
  "parent_span_id": "844e01d036946228",
  "span_id": "8cb0c82b3bfdec0a",
  "start_timestamp": 1670255617.7628,
  "status": "cancelled",
  "timestamp": 1670255617.8103,
  "trace_id": "abae10f022ab40028b8563ebaa2de109"
}
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/organization",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/organization",
  "op": "http.client",
  "parent_span_id": "844e01d036946228",
  "span_id": "b492710e0e9d587a",
  "start_timestamp": 1670255617.764,
  "status": "cancelled",
  "timestamp": 1670255617.8103,
  "trace_id": "abae10f022ab40028b8563ebaa2de109"
}
logger.ts:72 Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "GET",
    "url": "http://localhost:8080/products",
    "type": "fetch"
  },
  "description": "GET http://localhost:8080/products",
  "op": "http.client",
  "parent_span_id": "844e01d036946228",
  "span_id": "abb1a35702a7ffd3",
  "start_timestamp": 1670255617.7655,
  "status": "cancelled",
  "timestamp": 1670255617.8103,
  "trace_id": "abae10f022ab40028b8563ebaa2de109"
}
logger.ts:72 Sentry Logger [log]: [Tracing] flushing IdleTransaction
logger.ts:72 Sentry Logger [log]: [Measurements] Adding measurements to transaction {
  "fp": {
    "value": 553.4000396728516,
    "unit": "millisecond"
  },
  "fcp": {
    "value": 553.4000396728516,
    "unit": "millisecond"
  },
  "connection.rtt": {
    "value": 50,
    "unit": "millisecond"
  },
  "ttfb": {
    "value": 5.299806594848633,
    "unit": "millisecond"
  },
  "ttfb.requestTime": {
    "value": 0.8997917175292969,
    "unit": "millisecond"
  }
}
logger.ts:72 Sentry Logger [log]: [Tracing] Finishing pageload transaction: /products.
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.update' span on transaction '/products' (844e01d036946228).
instrument.ts:124 > Nav shouldComponentUpdate
logger.ts:72 Sentry Logger [log]: [Tracing] Starting 'ui.react.update' span on transaction '/products' (844e01d036946228).
redux-logger.js:1  action SET_PRODUCTS @ 16:53:41.992
instrument.ts:124  prev state {cart: {…}, products: Array(0), flag: false}
instrument.ts:124  action     {type: 'SET_PRODUCTS', payload: {…}}
instrument.ts:124  next state {cart: {…}, products: Array(4), flag: undefined}

ndmanvar · 2022-12-14T23:53:43Z

@smeubank - can we please get this prioritized and looked at?
It's impacting our demos as the data isn't lining up

Let us know if you need more information from us. We've posted all of our findings here and can collaborate on this issue to help move this forward.

This is a critical bug for us, as showing/tracing the /products transaction is part of the performance demo flow (/products on FE -> /products on BE [and the slowdown is a series of DB calls on the backend)

timfish · 2022-12-15T09:53:57Z

I'll take a look at this today!

timfish · 2022-12-15T22:31:27Z

I can't get application-monitoring/react to build on master.

What environment variables should I be setting? There are a lot in here but not sure which ones I need:
https://github.com/sentry-demos/application-monitoring/blob/master/env-config/example.env

I don't think the build error is related to environment variables:

> [email protected] start
> react-scripts start

node:internal/modules/cjs/loader:498
      throw e;
      ^

Error [ERR_PACKAGE_PATH_NOT_EXPORTED]: Package subpath './lib/tokenize' is not defined by "exports" in /Users/tim/Documents/Repositories/application-monitoring/react/node_modules/postcss-safe-parser/node_modules/postcss/package.json
    at new NodeError (node:internal/errors:393:5)
    at throwExportsNotFound (node:internal/modules/esm/resolve:340:9)
    at packageExportsResolve (node:internal/modules/esm/resolve:619:3)
    at resolveExports (node:internal/modules/cjs/loader:492:36)
    at Module._findPath (node:internal/modules/cjs/loader:532:31)
    at Module._resolveFilename (node:internal/modules/cjs/loader:941:27)
    at Module._load (node:internal/modules/cjs/loader:803:27)
    at Module.require (node:internal/modules/cjs/loader:1021:19)
    at require (node:internal/modules/cjs/helpers:103:18)
    at Object.<anonymous> (/Users/tim/Documents/Repositories/application-monitoring/react/node_modules/postcss-safe-parser/lib/safe-parser.js:1:17) {
  code: 'ERR_PACKAGE_PATH_NOT_EXPORTED'
}

I'm in the Sentry Discord for direct messages!

realkosty · 2022-12-16T18:25:26Z

@timfish Hey Tim, to run our app:

From top level directory

./deploy.sh --env=local react

Or if you want to run it with hot reload:

cd react
../env.sh local npm start

timfish · 2022-12-16T18:35:32Z

Both of those give me an error because env-config/local.env is not checked into the repository.

[ERROR] Missing file env-config/local.env or invalid environment 'local'.

I've tried creating env-config/local.env but what environment variables should I set? I've tried setting the obvious ones and then I get I get the above error.

realkosty · 2022-12-16T19:02:28Z

Please create env-config/local.env with following content:

SENTRY_ORG={FILL IN YOUR ORG SLUG}

REACT_APP_DSN={{FILL IN YOUR DSN}}
REACT_APP_ENGINE_SERVICE=
REACT_APP_ENVIRONMENT=test
REACT_RELEASE_PACKAGE_NAME=application.monitoring.javascript
REACT_SENTRY_PROJECT={{FILL IN YOUR PROJECT SLUG}}
REACT_SOURCEMAPS_DIR=build/static/js
REACT_SOURCEMAPS_URL_PREFIX=~/static/js
REACT_APP_FLASK_BACKEND={{DM-ed URL TO YOU}}
REACT_APP_EXPRESS_BACKEND=https://sentry.io
REACT_APP_SPRINGBOOT_BACKEND=https://sentry.io
REACT_APP_ASPNETCORE_BACKEND=https://sentry.io
REACT_APP_RUBY_BACKEND=https://sentry.io

timfish · 2022-12-17T15:30:33Z

It turns out there are some older dependencies somewhere that cause this issue which meant it wasn't working with my default node (v18). It's now working with node v16 but this should probably be documented somewhere!

For the JavaScript SDKs we use Volta which enforces the correct node version. It's nice because once setup and a version is pinned you can switch between projects and the correct version will be used with each.

timfish · 2022-12-18T20:49:18Z

When the the page is first loaded, in reactrouterv6.tsx, SentryRoutes + useEffect calls updatePageloadTransaction and later handleNavigation.

sentry-javascript/packages/react/src/reactrouterv6.tsx

Lines 189 to 201 in 2fa11eb

    
           _useEffect(() => { 
        
             // Performance concern: 
        
             // This is repeated when <Routes /> is rendered. 
        
             routes = _createRoutesFromChildren(props.children) as RouteObject[]; 
        
             isBaseLocation = true; 
        
             updatePageloadTransaction(location, routes); 
        
             // eslint-disable-next-line react-hooks/exhaustive-deps 
        
           }, [props.children]); 
        
           _useEffect(() => { 
        
             handleNavigation(location, routes, navigationType, isBaseLocation); 
        
           }, [props.children, location, navigationType, isBaseLocation]);

The problem is that it calls handleNavigation with isBaseLocation == true and that causes the transaction to be finished.

This logic doesn't seem correct to me but it's been there since v7.0

sentry-javascript/packages/react/src/reactrouterv6.tsx

Lines 130 to 143 in 2fa11eb

    
           function handleNavigation( 
        
             location: Location, 
        
             routes: RouteObject[], 
        
             navigationType: Action, 
        
             isBaseLocation: boolean, 
        
             matches?: AgnosticDataRouteMatch, 
        
           ): void { 
        
             if (isBaseLocation) { 
        
               if (activeTransaction) { 
        
                 activeTransaction.finish(); 
        
               } 
        
               return; 
        
             }

@onurtemizkan have you got any idea?

realkosty · 2022-12-20T21:26:36Z

@timfish

It turns out there are some older dependencies somewhere that cause facebook/create-react-app#11565 which meant it wasn't working with my default node (v18). It's now working with node v16 but this should probably be documented somewhere!

thank you for pointing this out Tim, we should use Volta or document it like you suggested.

@onurtemizkan
Please let me know if there's is anything I can help with investigating this.

onurtemizkan · 2022-12-21T13:51:39Z

The problem is that it calls handleNavigation with isBaseLocation == true and that causes the transaction to be finished.
This logic doesn't seem correct to me but it's been there since v7.0

Yes, that seems implemented wrongly. When isBaseLocation is true, we only need to return early without touching anything.

@realkosty, @ndmanvar: Could you confirm if the example below is what's expected on your side?
Link

realkosty · 2022-12-21T16:34:27Z

@onurtemizkan Yes, that looks right! http.client spans run their course and don't get cut prematurely.

(assuming no distributed tracing "+" and double slashes in request URL is just something specific to your setup).

onurtemizkan · 2022-12-21T16:43:25Z

Great! Opened a PR now.
@timfish, @lforst - Could you take a look please?

realkosty · 2022-12-21T17:11:59Z

wow, thanks so much for fixing this so quick Onur

realkosty · 2023-01-05T00:02:33Z

Verified fix in our app 👍

erdillon · 2023-02-17T16:17:58Z

It seems the issue isn't fixed in my case. Running with debug:true.

Sentry Logger [log]: [Tracing] cancelling span since transaction ended early {
  "data": {
    "method": "POST",
    "url": "https://api.internal.logixboard.com/graphql",
    "type": "fetch"
  },
  "description": "POST https://api.internal.logixboard.com/graphql",
  "op": "http.client",
  "parent_span_id": "ab43e1236ea09b27",
  "span_id": "ac69f764aac1f2c6",
  "start_timestamp": 1676650240.3091,
  "status": "cancelled",
  "timestamp": 1676650260.0198,
  "trace_id": "7bc3af3d6847434f862a8e151d9eff8c"
}

Not sure what to provide to help you debug further. This is with 7.38.0

lforst · 2023-02-20T09:42:29Z

@erdillon Hi, the example you shared looks a bit like it's a very long-lived request that outlives the page navigation transaction (meaning a span cancellation would actually be the intended behavior).

Because I think this is unrelated to this issue, would you mind opening a new issue with concrete reproduction steps so we can debug this further in case this is actually a bug? Thanks!

realkosty added the Type: Bug label Dec 8, 2022

realkosty changed the title ~~Transaction with active spans cut short~~ [React Router] Transaction unexpectedly ended early, cancelling spans from componentDidMount() Dec 8, 2022

smeubank assigned timfish Dec 8, 2022

ndmanvar assigned smeubank Dec 14, 2022

onurtemizkan mentioned this issue Dec 21, 2022

fix(tracing): Don't finish React Router 6 pageload transactions early #6599

Closed

lforst mentioned this issue Jan 3, 2023

fix(tracing): Don't finish React Router 6 pageload transactions early #6609

Merged

lforst closed this as completed in #6609 Jan 4, 2023

realkosty mentioned this issue Jan 5, 2023

Upgrade Sentry SDK from 7.17.3 -> 7.29.0 sentry-demos/empower#145

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[React Router] Transaction unexpectedly ended early, cancelling spans from componentDidMount() #6470

[React Router] Transaction unexpectedly ended early, cancelling spans from componentDidMount() #6470

realkosty commented Dec 8, 2022 •

edited

Loading

thinkocapo commented Dec 8, 2022 •

edited

Loading

thinkocapo commented Dec 9, 2022

ndmanvar commented Dec 14, 2022

timfish commented Dec 15, 2022

timfish commented Dec 15, 2022 •

edited

Loading

realkosty commented Dec 16, 2022

timfish commented Dec 16, 2022

realkosty commented Dec 16, 2022

timfish commented Dec 17, 2022

timfish commented Dec 18, 2022

realkosty commented Dec 20, 2022 •

edited

Loading

onurtemizkan commented Dec 21, 2022 •

edited

Loading

realkosty commented Dec 21, 2022

onurtemizkan commented Dec 21, 2022

realkosty commented Dec 21, 2022

realkosty commented Jan 5, 2023

erdillon commented Feb 17, 2023 •

edited

Loading

lforst commented Feb 20, 2023

[React Router] Transaction unexpectedly ended early, cancelling spans from componentDidMount() #6470

[React Router] Transaction unexpectedly ended early, cancelling spans from componentDidMount() #6470

Comments

realkosty commented Dec 8, 2022 • edited Loading

Is there an existing issue for this?

How do you use Sentry?

Which package are you using?

SDK Version

Framework Version

Link to Sentry event

Steps to Reproduce

Expected Result

Actual Result

thinkocapo commented Dec 8, 2022 • edited Loading

thinkocapo commented Dec 9, 2022

ndmanvar commented Dec 14, 2022

timfish commented Dec 15, 2022

timfish commented Dec 15, 2022 • edited Loading

realkosty commented Dec 16, 2022

timfish commented Dec 16, 2022

realkosty commented Dec 16, 2022

timfish commented Dec 17, 2022

timfish commented Dec 18, 2022

realkosty commented Dec 20, 2022 • edited Loading

onurtemizkan commented Dec 21, 2022 • edited Loading

realkosty commented Dec 21, 2022

onurtemizkan commented Dec 21, 2022

realkosty commented Dec 21, 2022

realkosty commented Jan 5, 2023

erdillon commented Feb 17, 2023 • edited Loading

lforst commented Feb 20, 2023

realkosty commented Dec 8, 2022 •

edited

Loading

thinkocapo commented Dec 8, 2022 •

edited

Loading

timfish commented Dec 15, 2022 •

edited

Loading

realkosty commented Dec 20, 2022 •

edited

Loading

onurtemizkan commented Dec 21, 2022 •

edited

Loading

erdillon commented Feb 17, 2023 •

edited

Loading