readystatechange listeners and re-dispatching of events still racy

[denschub]

I've been digging into an issue where I have a Rails 7 application with importmap-rails and Turbo that's sometimes working in Firefox/Safari, and sometimes not. Essentially, this looks like https://github.com/guybedford/es-module-shims/issues/161 still/again. It might also be a duplicate of #285 - I'm not entirely sure.

I found your code that's supposed to dispatch a readystatechange event once everything is loaded. To fully understand what's going on, I added some hacky console.log() statements to the top of some application JS files, and I added some logging statements to the code that's supposed to dispatch the event. Based on the build for the shim version 1.5.4, I added

  let readyStateCompleteCnt = 1;
+ console.log("es-module-shims, first check", {readyState: document.readyState});
  if (document.readyState === 'complete') {
    readyStateCompleteCheck();
  }
  else {
+   console.log("es-module-shims, adding readystatechange listener");
    document.addEventListener('readystatechange', async () => {
+     console.log("es-module-shims, readystatechange listener", {readyState: document.readyState});
      processImportMaps();
      await initPromise;
      readyStateCompleteCheck();
    });
  }
  function readyStateCompleteCheck () {
+   console.log("es-module-shims, readyStateCompleteCheck call", {
+     readyState: document.readyState,
+     readyStateCompleteCnt: readyStateCompleteCnt
+   });
    if (--readyStateCompleteCnt === 0 && !noLoadEventRetriggers) {
      document.dispatchEvent(new Event('readystatechange'));
+     console.log("es-module-shims, readyStateCompleteCheck, dispatching readystatechange event");
    }
  }

In the event where the app works (in this case with a hot cache), I see what I'd expect:

First some setup from the shim, then the application files loading, and then the shim dispatching an event. However, in the event where it doesn't work (in this case this was relatively easy to reproduce by disabling the cache), I see the following:

Here, the shim fires the event before the application logic files actually run. And interestingly, readyStateCompleteCheck gets called an additional time, causing readyStateCompleteCnt to be -1. I don't think that's expected.

Unfortunately, I appear to be unable to build an isolated testcase for that. One real-world example that breaks is https://visualizer.coffee/shots/036337c9-8e68-4d53-aa56-90fbcce2764d - where sometimes the graphs don't render (the graphs are rendered in a turbo:load event listener, which itself gets triggered by an event dispatched by a readystatechange listener, which never fires.) It may be worth noting that this site loads some JS assets from a CDN. No idea if that plays a role or not, but...

I have also found an existing issue in the turbo-rails repo, https://github.com/hotwired/turbo-rails/issues/286, which indicates that this might be an issue with multiple applications.

Do you have any clue how I could narrow this down further, how to build a test case, or generally how to turn this into a more actionable bug report? :)

[denschub]

As an additional thing, since this appears to be related to cache behavior somehow, I can share the same console logs as before, but with the network requests. Maybe that helps narrow it down:

• Working load with network requests
• Broken load with network requests

[guybedford]

Thanks for the clear reporting here, that's a huge help. Agreed given there's another issue this must be a bug.

The -1 is actually possible, and is designed to avoid its own event triggering itself. I think the issue is not checking the interactive v completed state as I might have assumed it would arleady be in interactive by the time es module shims executes.

I've posted a possible fix in https://github.com/guybedford/es-module-shims/pull/287 - can you try that out and let me know if it works for you?

[denschub]

Unfortunately, even with the version from your PR, I still see this issue. It seems like it's rarer, but one out of 5 page loads or so still fails.

[guybedford]

@denschub I've added some further commits to the PR, please try it out again. Otherwise if you are able to add more debugging to processScripts or share a complete clonable replication that would help a lot.

[denschub]

Okay, this is now making even less sense. I see the shim firing an event after the "top of xxx" logging statements, but I still don't see a turbo:load event... Edit: see comment below - the logging was bogus, but the situation is still the same.

I have essentially downloaded the production app, packaged it into a directory, and replaces the es-module-shim with the version from your PR. Here is everything in a zip-file. It's 532 KiB, and you should get a local server on port 3000 with npm install && npm start. This reproduces for me in Firefox 100 Release and 102 Nightly with a 50/50 success rate or something. There's also a bit of git history in case that's useful.

In addition, if you're familiar with Replay.io, I've been able to capture it there. They're also using Firefox, and it just so happens to reproduce in their build as well. Here is the recording, and you'll see three page loads: the first one works fine and the graphs show up (it also logs turbo:load fired!, which I added). The second and third reload don't work, the graph never shows up.

I really hope this is useful...

[denschub]

Ah no, I'm a dufus. The readystatechange dispatching code isn't actually firing, I just messed up the logging (I somehow missed that the if body isn't a block).

diff --git a/assets/es-module-shims.min-73351493b82b20135079098556c87522422c3b2d.js b/assets/es-module-shims.min-73351493b82b20135079098556c87522422c3b2d.js
index 8430e37..f0cb7ff 100644
--- a/assets/es-module-shims.min-73351493b82b20135079098556c87522422c3b2d.js
+++ b/assets/es-module-shims.min-73351493b82b20135079098556c87522422c3b2d.js
@@ -782,9 +782,10 @@
       readyState: document.readyState,
       readyStateCompleteCnt: readyStateCompleteCnt
     });
-    if (--readyStateCompleteCnt === 0 && !noLoadEventRetriggers)
+    if (--readyStateCompleteCnt === 0 && !noLoadEventRetriggers) {
       document.dispatchEvent(new Event('readystatechange'));
       console.log("es-module-shims, readyStateCompleteCheck, dispatching readystatechange event");
+    }
   }

   function processImportMap (script) {

fixes the logging, and you're still not dispatching the event properly. Here is a fixed version of the archive mentioned above.

[guybedford]

@denschub I just cloned the replication from https://github.com/guybedford/es-module-shims/issues/286#issuecomment-1120477466 here and refreshed about 10 times but saw the graph render every time. Which browser and browser version are you using to get the issue?

[denschub]

Firefox Release 100.1, Beta 101.0b5, and the current 102 Nightly. The Reply.io browser is based on some Firefox build that I don't exactly now (something recent). This is on a beefy M1 MacBook Pro, which I think contributes to the issue. I have not been able to reproduce this at all on an older, slower machine.

Unfortunately, other colleagues with similarly fast hardware can reproduce as well. Might also be a internet-speed thing. No idea, honestly. Which probably makes this issue a joy to reproduce (and which is why I recorded a replay on Reply.io)

[denschub]

Oh, and in the Turbo issue at https://github.com/hotwired/turbo-rails/issues/286#issuecomment-1119962069, someone said they can only reproduce one in 50 times. I... honestly have no clue under what circumstances this explodes.

[denschub]

The replication also reproduces locally on the same machine in Safari Version 15.4, and Safari Tech Preview 145. But much, much less often. Had to refresh 50 times or so to get it break once.

[guybedford]

@denschub thanks for the info, I believe I've finally tracked this down, and the PR at https://github.com/guybedford/es-module-shims/pull/287 should be fixing it now. Please test it out again if you can - I will aim to merge and release tomorrow.

[denschub]

I spent about 5 minutes reloading the local test case, and 5 minutes reloading the production site with a proxied version of the shim - with all kinds of different cache states and network speed emulations. Couldn't get this to break a single time.

So indeed, I think this is fixed with your PR. 🧡

[guybedford]

Thanks again for the report and for testing it thoroughly! I've released the fix in 1.5.5.