TraceId persisting and not re-generating after Transactions Flush

[thinkocapo]

Platform

iOS

Installed

CocoaPods

Version

7.11.0

Steps to Reproduce

1. Auto instrument transactions from MainViewController (first one that opens when you Cold Start boot your iOS mobile app)
2. These transactions call a backend in Python instrumented with Sentry SDK for Performance
3. Verify traceId is set appropriately on each so far. Call this traceId-A
4. User sits idle for a few seconds, no transactions are started (none waiting to flush)
5. Navigate to a different ViewController, and see that new traceId+transactions are started and flushed, as traceId-B
6. Call a Custom Transaction on this final ViewController, it must call a backend in Python instrumented with Sentry SDK for Performance. When this transaction+trace flushes, see that hte traceId is now traceId-A again, and did not become a new one (like a traceId-C)

Also, the final error that gets made, does not have a traceId.

Problem also described this way: Problem: The first ViewController that loads during app start gets a traceId, and the next ViewControllers that are loaded due to user navigation get new trace Ids, which makes sense, because the transactions from the first trace have flushed already. However, the backend transactions for the 2nd and 3rd ViewControllers have the traceId from the 1st ViewController. This sucks to explain and I will re-read this again tomorrow hoping this isn’t happening.

Expected Result

When the final custom transaction is flushed, I'm expecting a traceId-C, as this is happening many seconds after the initial app load and the initial transactions+trace.

Expecting the final error that gets made in iOS, to have a traceId (same as from purchase/checkout, the traceId-C I'm speaking of)

Expected Behavior: trace:f418e658 should not be appearing on application-monitoring-python here. The ‘purchase’ transaction from iOS generates a new trace called 37c765b5 and I expect to see 37c765b5 on the application-monitoring-python’s ‘checkout’ transaction (the purchase function in iOS calls /checkout on the backend)

Actual Result

also available by this debugging video

https://www.loom.com/share/d5758309b31642bbb3933fca829bd638

and here's a link to the the problematic events: https://sentry.io/organizations/testorg-az/discover/results/?end=2022-05-11T18%3A24%3A00&field=title&field=event.type&field=project&field=trace&field=timestamp&name=All+Events&project=6249899&project=5808655&query=project%3Awill-cocoa+OR+url%3A%22http%3A%2F%2F127%2A%22&sort=-timestamp&start=2022-05-11T17%3A48%3A35&yAxis=count%28%29

[github-actions[bot]]

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 label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

---

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

[brustolin]

Hey @thinkocapo, can you link your test projects here? The App and server side project. Will be easier to reproduce the problem with the sample.

[thinkocapo]

Hi @brustolin here is the ios code http://github.com/sentry-demos/ios

The ios app calls a cloud hosted backend, so you shouldn't have to run it. But here is the code https://github.com/sentry-demos/application-monitoring/tree/master/flask

[github-actions[bot]]

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 label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

---

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

[kevinrenskers]

@brustolin I looked into this and found something interesting.

When the app starts, it gets items from the server, with an HTTP request (getAllProductsFromServer). This request get enriched (by addTraceHeader) with a header with a traceID, let's call it A.

I can see that traceID A is getting logged in the iOS app.

I add a few items to the cart, and press the cart button in the top right. A new traceID is getting logged in the client, let's call that B.

On the cart screen, I press the Purchase button, which does another HTTP request. However, at this point in the addTraceHeader method, span equals nil and as such no headers are added to the request.

[kevinrenskers]

We found 2 things that caused this issue.

The first thing is a user error in the implementation of the sample app: you're not binding the transaction to the scope, thus when the HTTP request is made, SentrySDK.currentHub.scope.span is nil. That brings us to the second problem: when SentrySDK.currentHub.scope.span is nil, it sends along the existing headers, and those are getting cached (by NSURLSession itself) and thus contain the trace ID of the previous request.

We can do a fix on our end to clear out the trace id from the old headers, so we don't get this strange scenario anymore. But the real fix is to properly bind the transaction of making the purchase to the scope.

[brustolin]

properly bind the transaction of making the purchase to the scope

BTW, SentrySDK.startTransaction has a bindToScope parameter to do this