Bug: no xhr breadcrumbs for error in onreadystatechange

[ilfa]

I think it's a bug

When Raven instruments XMLHttpRequest and error occurs in onreadystatechange user function we don't see current request details in breadcrumbs for current error, because Raven log request in onreadystatechange after user code.

What is the current behavior?

Here is fiddle, just check console and see order of ravenTransport breadcrumb and setBreadcrumbCallback messages.

What is the expected behavior?

It will be great if Raven can put xhr request info in breadcrumbs for onreadystatechange too.

[kamilogorek]

@ilfa sorry for such a long response time, we were swamped. I'm not sure if I understand the issue tbh. Do you by any chance still have this fiddle link? 😅

[kamilogorek]

Closed due to inactivity. Please feel free to reopen this issue if this also happens in v4 sdk. Cheers! :)

[stefan-hc]

Hello,

I think I've encountered the same problem (we can discuss if this is a problem or a bug) in current version of Sentry. I'm not sure if I should open new issue for it, or if we can reopen this one. Please guide me. /cc @kamilogorek

The problem:
When using Sentry together with https://github.com/axios/axios (it's a frontend library wrapping XMLHttpRequest with a simpler API) one can write a following webapp code: (more-less)

async function getUser() {
  try {
    const response = await axios.get('/user?ID=12345');
    ...
  } catch (error) {
    ...
    Sentry.captureException(error);
  }
}

This reports the request/response error to Sentry. So far so good. However, out-of-the-box, one important data is missing in such scenario: the report will not contain the xhr breadcrumb for the /user?ID=12345 call.

It is because both webapp handler (catch (error)) and Sentry instrumentation are attached to the same event: onreadystatechange. However, Sentry instrumentation is attached as the second handler, so the breadcrumb for this particular XHR is registered only after capturing exception to Sentry. Immediately after, but after anyway.

To better illustrate the issue, I think the following variant would capture the breadcrumb in the report perfectly:

async function getUser() {
  try {
    const response = await axios.get('/user?ID=12345');
    ...
  } catch (error) {
    ....
    setTimeout(() => Sentry.captureException(error), 0); //to allow other onreadystatechange listeners to execute
  }
}

Is this expected behavior intended by Sentry design? Or is there a flaw in Sentry xhr breadcrumb instrumentation affecting this particular scenario?

As a reference, the relevant code from axios: https://github.com/axios/axios/blob/master/lib/adapters/xhr.js#L28

var request = new XMLHttpRequest();
(...)
request.open(config.method.toUpperCase(), buildURL(fullPath, config.params, config.paramsSerializer), true); 
// above will trigger Sentry instrumentation handler: https://github.com/getsentry/sentry-javascript/blob/master/packages/utils/src/instrument.ts#L221-L232
(...)
request.onreadystatechange = function handleLoad() {
//above will add onreadystatechange handler (as first handler, prior to Sentry's one)
(...)
request.send(requestData);
// above will trigger Sentry instrumentation handler: https://github.com/getsentry/sentry-javascript/blob/master/packages/utils/src/instrument.ts#L238-L267
// which attaches Sentry's onreadystatechange handler, but it's too late - it will be already second

[kamilogorek]

@stefan-hc hey, I just tried to reproduce this exact use-case with no luck. Are you able to do that for me, please?

Here is my test case example and the results (which includes both, error and breadcrumb itself):

[kamilogorek]

@stefan-hc and more "real-world" endpoint:

[stefan-hc]

Sure, will do. Give me a moment :)

[stefan-hc]

One thing that I've noticed: you're trying to reproduce this with Node.js environment, am I correct? I've encountered this problem when using Sentry in browser. So I speculate this might be browser-specific thing? Maybe node.js has different implementation of "onreadystatechange" handlers...

In anyway, I'll try to prepare you later this day a fiddle illustrating my issue. Ok?

[kamilogorek]

Ah, you are correct. I somehow linked Axios with node environment in my head by default. Reproduced it locally. Will try to debug this week.

[stefan-hc]

Jolly good.

Just for the record: it's not very urgent/important to me, as I went with setTimeout(() => Sentry.captureException trick and it seems to work good enough™. I can live with that for a longer while. Still, I find this solution to be hack'ish - it would be cool to get rid of it at some point in the future.

Thanks for addressing my report.

[stefan-hc]

Ah, and by doing some archaeology in the repo here, I've found that in older versions it might have been working as expected:

https://github.com/getsentry/sentry-javascript/blob/5.10.2/packages/utils/src/instrument.ts#L254-L265

It seems to me that in version 5.10.2 Sentry was detecting if there is already onreadystatechange handler registered in xhr (and presuming it was done by the user), and so Sentry would wrap the original function to ensure Sentry handler would be executed as first. But I'm not 100% sure, just speculating from code analysis.

[kamilogorek]

@stefan-hc the issue was that we were attaching the handler inside send wrapper, and not open. Because of that, Axios was always before us as you mentioned.
Should be fixed in #2643

[stefan-hc]

Make sense.

There is a possibility that in future Axios (or other 3rd party) might attach its handler before even open, but I guess #2643 is viable enough for the time being.

👍

[kamilogorek]

@stefan-hc correct, but there's not much we can do about it without messing with capture logic itself ¯_(ツ)_/¯

[stefan-hc]

Aye.

I'm clearly not seeing the full picture, but it seems to me the way to go would be to reuse the same technique as in this change: 973cfde#diff-e98689aa6fecf76cef53f19d1873643bL254-L260

      if ('onreadystatechange' in xhr && typeof xhr.onreadystatechange === 'function') {
        fill(xhr, 'onreadystatechange', function(original: WrappedFunction): Function {
          return function(...readyStateArgs: any[]): void {
            onreadystatechangeHandler();
            return original.apply(xhr, readyStateArgs);
          };
        });
      } else {
        // if onreadystatechange wasn't actually set by the page on this xhr, we
        // are free to set our own and capture the breadcrumb
        xhr.onreadystatechange = onreadystatechangeHandler;
      }

Do you happen to remember why did you had to remove that 'wrap to existing handler' functionality from Sentry? ref commit: 973cfde ?

If yes - just ignore me. I really don't need the answer, I'm just double checking you don't miss some opportunity here. #2643 suits my needs perfectly.

[kamilogorek]

@stefan-hc I did some testing, and the current solution handles both cases onreadystatechange = as well as addEventListener('readystatechange'), because apparently in the browser, onreadystatechange is implemented as an object setter, which internally calls addEventListener anyway.

However, as you pointed out, it won't work if they are called before open. I updated the PR to handle onreadystatechange = called before open, but there's not much that we can do for 4th case, which is addEventListener called before open. That'd require wrapping a whole prototype of addEventListener for XHR.

So, the only way it could not work now is if someone does something like:

const xhr = new XMLHttpRequest();
xhr.addEventListener(...)

But in this case, they'd also get the listener called for the initial open event, which is very rarely desired.

Thanks for pointing that out! We should release new version Today.

[stefan-hc]

Oh wow, that's really deep - I mean, these onreadystatechange being translated to addEventListeners and other browser intricacies. 😮

Thanks for update, I think I'll switch to newer Sentry version asap...

[kamilogorek]

@stefan-hc 5.17.0 has been released. Let me know if that fixed it for you

[stefan-hc]

Fixed. The order in the universe is restored once again. ☕