Chrome: Scripts load inconsistently on very-fresh tabs(?)

[marcustyphoon]

Platform

MacOS 10.14.6 x86

Browser

Edge 102.0.1245.41

Addon version

f318547

Details

I am mostly at a loss here.

On a completely inconsistent basis, I sometimes open Tumblr to find that notificationblock is not active until a hard refresh. I finally got this to occur after adding logging before and after the dynamic import statements in main.js and at the top of every utility function, and discovered that it's actually any script that imports meatballs.js, as it for some reason is not resolved.

I have never had this problem with a different set of scripts, but I can't figure out what would be different about the meatballs utility based on its dependencies. I also don't know if this occurs in production or if it's just a weird artifact of my local install, but I have no reproduction method yet so I can't test that really.

[marcustyphoon]

Wait... mutual checker didn't load in this screenshot either.

Uh, what?

[AprilSylph]

The current commit isn't released, so it by definition would not occur in production right now. I don't know enough about your local install, but if you hard-reset to master and reload the extension in the browser, you should get the exact same experience as if it were released.

If you can figure out how to reliably reproduce it (even if it is just "hard-refresh Tumblr x times until it happens"; I narrowed down a fakeImport bug that way), please rewind to 98af3c5e1706d82b647d6885a1aaef7fdf78cb6a and see if it still occurs.

I'm pausing all other development until this is resolved. If 225f7fec28fc50dd2155101269a3dc813c7b354c needs to be reverted I want a clean revert.

Also, to help me test this, do you mind sharing the config you're using?

[marcustyphoon]

I'm quite sure this occurred before the 225f7fe CSS map utility commit, but I don't know how long it's been exactly. I posted about it on June 8, so it's definitely been a while (and that was before the latest release).

I did manage to reproduce it once when reopening two Tumblr tabs at once, thinking it could be a race condition thing, but that only worked once, so probably a coincidence. I've tried opening various URLs as the initial load and just opening or refreshing Tumblr a lot, but nothing has worked yet, and I haven't found anything consistent with the tabs that do it. It's pretty infrequent for me, maybe once or twice a day. I do open https://www.tumblr.com/search/xkit/recent directly a fair amount, though I don't think I did that on the bugged tab I have open now.

I'll commit my logging changes to a branch and direct message you my config file. (It does have some flags for features that never made it in, so that's certainly a possible cause, though nothing immediately comes to mind as a way that could produce inconsistent behavior).

The obvious theory for me would be the failure of one of our top-level-awaited functions that interfaces with window.tumblr, but in both instances where I observed the failure with added logging, all of them printed good data. I can't think of any race conditions. The files themselves not printing that they're loaded (and one of them being a utility file) seems to rule out an issue with local storage not resolving. And all of the other scripts appear to work just fine.

[marcustyphoon]

https://github.com/marcustyphoon/XKit-Rewritten/commit/b78307540402cb36cd6fe9f27841dbb47d98a375 https://github.com/marcustyphoon/XKit-Rewritten/tree/loading-issue-logging

Here's the current branch I'm running.

Oh, and I'm not ruling out "my Edge install is cursed" either, yet. Chromium (including Electron) occasionally crashes this laptop all the way to a reboot, so that's a thing. Really wish I had a reliable repro so we could see if it happens on any other install.

[AprilSylph]

Okay, if 225f7fec28fc50dd2155101269a3dc813c7b354c can be ruled out as the cause, that's good. Ignore my comment about other development being paused.

[AprilSylph]

Hmm, two tabs opened at once... I know Chromium handles unfocused tabs differently. What happens if you open a Tumblr tab and let it load entirely out of focus?

On Edge (Windows 10) you can do so by CTRL+clicking a link; on Mac I assume this would be CMD+click.

---

Nevermind, just tested it myself with release v0.20.1, it behaves just fine. Darn!

[marcustyphoon]

I tried that, didn't seem to work. The one time I was hopeful I'd gotten it to happen I think I command-shift-t'd to reopen a window that had two Tumblr tabs and did click both of them, but that hadn't worked since.

I did, though, just have it happen again on a simple refresh. Mutual checker did load this time, but the meatballs utility (and scripts relying on it) did not. Trying a Firefox install and a Chrome install with no other extensions now.

[marcustyphoon]

Aha! Got a repro finally. It happens when I a) navigate to tumblr really quickly after opening a new tab or window, and b) only when I have XKit 7 enabled in my Edge (??).

I have Enabled extensions: xkit_main, xkit_patches, xkit_preferences, xkit_updates, quick_tags, editable_reblogs and Disabled extensions: xwidgets, show_more, classic_tags, old_stats, estufars_sidebar_fix, old_blue, notifications_plus, messaging_tweaks, mass_plus, dont_stretch_photosets, disable_search, themes_plus, servant, tagviewer, mute, shorten_posts, profiler, one_click_postage, notificationblock, postblock, outbox, bookmarker, timestamps, hideavatars, highlighter, tweaks, classic_header, accesskit, fresh_prince, pokes, blacklist, anti_capitalism, audio_downloader, audio_plus, autoscroll, auto_tagger, disable_gifs, glowing_follow, go_to_dash, read_posts, panaroma, open_in_new_tabs, norecommended, titles, tf2_reblogs, vanilla_video, xcloud, xneko, retags, tag_replacer.

Haven't gotten it to happen in my Chrome/Firefox installs yet, but I haven't imported my XK7 data into them yet to see if it's specific to that.

Also, apparently meatballs.js isn't necessarily the culprit. (Why it would always be NotificationBlock, then, I have absolutely no idea about yet.)

[marcustyphoon]

Reproduced in Chrome 102.0.5005.115. Again, it is mutual checker and notificationblock. This is not my browser being cursed, phew.

(okay, well. clearly this issue existing is proof that something is cursed, somewhere, but at least it's not just my Edge!)

Edit: Also reproduced in Chrome with retail v0.20.1.

Not yet reproduced in Firefox, which doesn't seem at all surprising given the details of this repro.

Edit: Reproduced with the NotificationBlock script replaced with

// import { buildStyle } from '../util/interface.js';
import { registerMeatballItem, unregisterMeatballItem } from '../util/meatballs.js';
// import { pageModifications } from '../util/mutations.js';
// import { inject } from '../util/inject.js';
// import { keyToCss } from '../util/css_map.js';
// import { showModal, hideModal, modalCancelButton } from '../util/modals.js';
// import { dom } from '../util/dom.js';
import { userBlogNames } from '../util/user.js';

console.log('notificationblock loaded');
// eslint-disable-next-line no-return-assign
[...document.querySelectorAll('main')].forEach(el => el.style.outline = '3px solid green');

export const onStorageChanged = (changes, areaName) => {
};

export const main = async function () {
};

export const clean = async function () {
};

Not reproduced with most scripts disabled.

I get the feeling this is either a Chromium bug with a sufficiently long-lasting import waterfall and something in the new tab code, or something really subtle and weird with how async imports get resolved.

[marcustyphoon]

It does appear to not fail if main.js is modified to import all of the scripts sequentially instead of simultaneously, but that means waiting on things like the user info API call completing before continuing to parse js files, and it doesn't really address whatever is actually going on here.

[marcustyphoon]

I have disabled XKit 7 (so I guess it's not that) and am now encountering this with Show Originals.

[marcustyphoon]

Failed to reproduce on a Windows PC and another Mac. Maybe my system is just cursed.

[marcustyphoon]

Some sort of interesting tests:

  const importWithRetry = async function (path) {
    const result = await Promise.race([
      import(path),
      new Promise(resolve => setTimeout(() => resolve(undefined), 5000))
    ]);
    console.log(result ? `loaded ${path}` : `retrying ${path}`);
    return result ?? importWithRetry(path);
  };

-   const { main, clean, stylesheet, onStorageChanged } = await import(scriptPath);
+   const { main, clean, stylesheet, onStorageChanged } = await importWithRetry(scriptPath); 

This fix doesn't work. For the scripts that fail (which ones depend on which are enabled), it prints "retrying" forever; apparently once this bug is triggered on a file import that file will always fail to import.

-   installedScripts
-     .filter(scriptName => enabledScripts.includes(scriptName))
-     .forEach(runScript);
- 
+   for (const scriptName of installedScripts.filter(scriptName => enabledScripts.includes(scriptName))) {
+     await runScript(scriptName);
+   }

This fix, not importing all of the scripts at once, works. (With a penalty to extension load time, I assume).

-   installedScripts
-     .filter(scriptName => enabledScripts.includes(scriptName))
-     .forEach(runScript);
- 
+   const sleep = ms => new Promise(resolve => setTimeout(() => resolve(), ms));
+   for (const scriptName of installedScripts.filter(scriptName => enabledScripts.includes(scriptName))) {
+     await sleep(0);
+     runScript(scriptName);
+   }

This fix, importing all of the scripts in different function calls but allowing them to be simultaneous, mostly works but if I recall correctly it caused some tweaks to occasionally suffer the same problem unless the fix was also applied to Tweaks (and presumably No Recommended, etc).

+   const sleep = ms => new Promise(resolve => setTimeout(() => resolve(), ms));
+   await sleep(5000);

    installedScripts
      .filter(scriptName => enabledScripts.includes(scriptName))

This fix, simply delaying the unmodified simultaneous imports, works if the timeout is high enough, but not if it is very low; apparently, either the amount of other code running at the time or some specific piece of Tumblr code that runs at the time is important. It is not just the act of simultaneously importing all of these scripts.

[AprilSylph]

This fix, not importing all of the scripts at once, works. (With a penalty to extension load time, I assume).

I think we should measure this. Also, calling runScript sequentially is not the only option here - we could do await import on the file and then call runScript as normal, assuming it is just the import tree that's the problem.

[marcustyphoon]

I think we should measure this.

I haven't measured it numerically but it's definitely nonzero, as it reorders all but the first few extension loads to come after a bunch of Redpop rendering stuff.

we could do await import on the file and then call runScript as normal,

Yep. This has roughly the same effect on when everything actually gets run, I think.

Another option that seemed to work in a brief test was changing run_at back to document_idle, but I haven't looked at what that does to speed.

Anyway, I still haven't gotten this to occur on another computer, so while it obviously concerns me that it might be happening to a user and just making them think the extension is haunted, I don't feel like I've definitely confirmed that it's an issue yet.

[marcustyphoon]

Reproduced on another PC (Edge 102.0.1468.62, Windows 7, 2.4GHz Core 2 Duo, 4GB RAM). Yes, I just grabbed the oldest laptop I could find.

Sequentially calling await import before "simultaneously" running runScript does work.

[marcustyphoon]

This is fixed (without functional drawback) by #897, though it's a lot of fairly unintuitive code just to do this.