Error applying name updates on Windows 7

[birtles]

From AMO:

This is a great tool, but for some reason it keeps downloading the dictionary every time I restart firefox, which is quite anoying since it makes firefox take up necessary CPU from other applications.

For some reason, under Windows 7, Name Data 2.0.13 and newer does not want to be installed.
Under Windows 10, this doesnt seem to be a problem (latest Firefox versions on both machines, 82.0.3 64-bit).

Follow up on Twitter:

https://imgur.com/a/Z3dwBlo

After reinstalling Firefox (83.0, 64 bit) and rikaichamp (0.26). the name dictionary wont update beyond 2.0.8, even though I previously had up 2.0.12.

This is on a Windows 7 Pro, 64 bit (running from a VM)

I even tried to copy the profile from my host OS (Windows 10 Pro, with the same version of Firefox and rikaichamp), but rikaichamp will still redownload the files

Log image for posterity:

[birtles]

I've spent quite a while digging through the Firefox IDB implementation to work out how we'd end up with an undefined error here but so far I can't find it.

My best guesses so far are:

• There is some codepath that ends up returning an undefined error for this that I haven't found (i.e. dispatching the error event without setting the error member on the corresponding request object)
• There is some lifetime issue / race condition where, by the time the idb wrapper reads the error member, it has already been cleared
• There is some other bug on the app side that means we end up dropping the error code here

As for the root cause, I can only guess at that too but some of the following seem possible:

• We run out of disk space or hit some other unanticipated disk issue as a result of running Win 7 in a VM
• The batch size we are using (4,000 puts per transaction) is too large for this particular configuration (which may be the same actual cause as the previous option)

The comments in bug 944918 and bug 1502077 are particularly interesting. It suggests that QuotaManager errors in a less-than-elegant way when it finds unexpected files in the IndexedDB folder.

Given that in this case the reporter could update to 2.0.12 initially but after re-installing could only update to 2.0.8, that does seem consistent with hitting a disk space limit (and perhaps invoking some part of QuotaManager that otherwise isn't triggered).

What's also odd is that I can't seem to find any reports for this in Bugsnag. Are we ignoring this error somewhere perhaps? Or perhaps the error reporting path is erroring? Perhaps because somewhere we try to access error.name but it is undefined? (However, I would expect that to produce some error in the console but perhaps we're catching and ignoring it?)

Some possible next steps:

• Make hikibiki-data actually dump the error object to the console inside bulkUpdateTable
  • This is unlikely to achieve anything. If there is a race condition where we clear the error condition before reading it, it likely occurs before this point, but it can't hurt to add this. The next step might be to actually wrap each put Promise and dump its error immediately, before passing to Promise.all.
• Drop the batch size to, say, 2,000 to see if that fixes anything. Again, not expecting any effect here.
• Try to detect an undefined error message and dump the results of quota manager to the console navigator.storage.estimate().
  • If we can accurately detect a quota exceeded state, we should consider how to report this to the user in a helpful way. This probably warrants some extra error state: "Fatal error where there's nothing we can do about it, but we should still re-try each time". i.e. we should still try to update the database each time the add-on is loaded, but if it fails, we shouldn't report any error in the toolbar or retry (but we should report the error when the user opens the options page).
• Audit all places where we access error.name and use error?.name or some such means.

[birtles]

Oh, and in another follow up Twitter comment:

I have an issue where it wont update name data beyond 2.0.12 and keeps redownloading 2.0.0 to 2.0.13 every time

We should work out why, after encountering an error downloading 2.0.13, we re-start downloading from 2.0.0 every time. That seems really wasteful and wrong. It certainly shouldn't do that unless Firefox is somehow dropping the table when it encounters the quota limit?

Unfortunately, that's going to be really hard to fix without being able to reproduce the situation locally.

[SaltfishAmi]

I have Windows 7 Ult 64-bit in a VM and FF 83.0 64-bit, I was not able to reproduce this.

[birtles]

Thank you so much for checking!

My guess here is that it's to do with the amount of disk space configured for the VM.

If I could venture a further guess, I wonder if QuotaManager is kicking in, hitting some unexpected condition (e.g. unexpected file in the IndexedDB directory, perhaps something from an anti-virus tool, or even some interference from the VM), throws an unexpected error, and ends up dropping the tables being updated.

The update transaction covers both the "names" table and the "version" table. If we end up dropping the "version" table we will end up downloading from the start again each time.

I might try reaching out to @asutherland or someone else on the DOM team to see if there are some prefs I can use to simulate the low-disk situation in order to reproduce this. It's possible this situation only occurs for extensions.

[SaltfishAmi]

I'm playing with Win7's builtin disk quota management. When I reach the maximum quota, Firefox gives DataCloneError: The object could not be cloned. at rikaichamp-jpdict.js:3633

Update: Instead of using quota management, I filled the drive with crap and left 1.2GiB of free space; it still gives the same DataCloneError.

[KataStrofY]

I'm the user who posted this on Twitter and the firefox addon review.

My VM currently is set to 12GB RAM and has 1.6GiB free on the drive the firefox profiles and windows is saved to. I manages to clear so it has 2GiB free without editing the disk size, but still can't update past 2.0.9, which is one step further than my tweet (2.0.8) I never saw the disk space go below 1.7GiB

[KataStrofY]

After having disabled virtual-ram (12GB should be enough for a VM, and the virtual-ram took 8GB of the little space I actually have allocated) I now have more than 9GB free on this partition it's currently updated to the latest versions. So I guess it was a disk quota issue or a virtual-ram issue? Even though 1.6GB should be enough for downloading and applying. Windows 7 isn't Sony PlayStation 4 after all :P

[birtles]

@SaltfishAmi @KataStrofY Thank you both very much!

That certainly sounds like the issue.

The way the limit is calculated is described here: https://developer.mozilla.org/docs/Web/API/IndexedDB_API/Browser_storage_limits_and_eviction_criteria

So I think in your case, if you have 1.6Gb free space, Firefox sets the global storage limit at 800Mb. Then Rikaichamp would get 20% as its origin limit, i.e. 160Mb.

The name data is actually not that large. The raw XML file it is derived from is about 145Mb, but we process it down to a set of ~16 JSON files at about 550Kb each, after being Brotli compressed, so about 9Mb over the wire. Uncompressed that's still only roughly 72Mb.

However, we then generate a few indices on that data (kanji index, kana index, normalized hiragana index etc.) which means the SQLlite file on disk used by IndexedDB can take up ~300Mb, hence why we hit the quota limit.

As for why Firefox is sometimes generating an undefined error, I'm not sure but seems like a (somewhat known) Firefox bug.

Furthermore, we should still find a way to handle this more gracefully than, "Try to download the whole thing every time and fail".

There are also possibly a few unused indices on the kanji data we could drop to reduce the file size on disk further.

(For my own reference, if we ever have similar issues, the way to check the IDB folder is below)

1. about:profiles
2. Root directory → Open folder
3. storage \ default \ moz-extension+++<EXTENSION ID> \ idb where the EXTENSION ID is the one listed in about:debugging → This Firefox → Rikaichamp → Internal ID

According to some bug reports, there can be errors when unexpected files are found there (or presumably one of the subdirectories). In the past, files like thumbs.db or desktop.ini have caused issues it seems.

[Kala-J]

On this cheap laptop I needed 3 gb of free space to update to the latest 3.0.22 name dictionary, and I had to delete everything but the OS to do it. Does turning off automatic updates of the extension also turn off the automatic dictionary updates? I don't want it to update again when a new dictionary version is released since it will fail and break what I have currently.

[birtles]

On this cheap laptop I needed 3 gb of free space to update to the latest 3.0.22 name dictionary, and I had to delete everything but the OS to do it.

Yeah, that's crazy. I still need to look into what's going on here. I suspect Firefox isn't applying the unlimited storage preference in this case (either because it doesn't apply to IndexedDB or because it doesn't apply to workers). If I can't work around it, I certainly hope to make it fail more gracefully.

Does turning off automatic updates of the extension also turn off the automatic dictionary updates?

I'm afraid not. There's no way to turn that off yet. Note that for the names dictionary, after the first 14 patches, the rest are very very small diffs, often just a half a dozen records. (This week's patch, 3.0.22, was larger at about ~100 records because there was a big change to all the entries ending in 霊園 to include "Cemetery".)

[birtles]

I started working on this today and here's what I have so far.

A) I've updated rikaichamp and my fork of web-ext-webpack-plugin so that we can run it using a specific profile directory.

Using this I can reproduce the error as follows:

1. Create a RAM disk, e.g. using ImDisk Toolkit, of about 1Gb at say R:
2. Run Rikaichamp as follows:

$ yarn start --env firefoxProfile=R:\profile --env keepProfileChanges --env profileCreateIfMissing

Doing this I can reproduce the errors as follows:

B) The DataClone errors are due to trying to postMessage the errors (due to bug 1556604)

We should convert the errors to something serializable before posting. That way we will get actual QuoteExceededErrors in this case.

C) I don't know why we get Error: undefined, but I have one idea.

In bug 944918 "juraj.master" reports exactly the same symptoms as this.

Furthermore, they are getting them from an add-on. Following the comments in that bug, I think it's quite likely that this is some sort of issue that arises from the combination of using IndexedDB in an extension background page that causes the error to be sometimes dropped.

I dug around the code for this but couldn't find anything suspicious. However, I did notice the following error in the browser console:

IO error: ファンクションが間違っています。 (os error 1) ExtensionStorageSync.jsm:69
    handleError resource://gre/modules/ExtensionStorageSync.jsm:69

Source line: https://searchfox.org/mozilla-central/rev/362676fcadac37f9f585141a244a9a640948794a/toolkit/components/extensions/ExtensionStorageSync.jsm#69

Perhaps whatever we're expecting the message to be here is not something that Error() takes.

For posterity, the following error is:

Error: Can't find profile directory. 5 XULStore.jsm:66:15
    load resource://gre/modules/XULStore.jsm:66
    XULStore resource://gre/modules/XULStore.jsm:24

A second occurrence appeared in the following sequence:

NS_ERROR_UNEXPECTED
Error: Can't find profile directory. XULStore.jsm:66:15
    load resource://gre/modules/XULStore.jsm:66
    XULStore resource://gre/modules/XULStore.jsm:24
IO error: ファンクションが間違っています。 (os error 1) ExtensionStorageSync.jsm:69
    handleError resource://gre/modules/ExtensionStorageSync.jsm:69
Error: Can't find profile directory. XULStore.jsm:66:15
    load resource://gre/modules/XULStore.jsm:66
    XULStore resource://gre/modules/XULStore.jsm:24

D) unlimitedStorage does not appear to apply to IndexedDB.

As per MDN:

The unlimitedStorage permission:

• Enables extensions to exceed any quota imposed by the storage.local API
• In Firefox, enables extensions to create a "persistent" IndexedDB database, without the browser prompting the user for permission at the time the database is created.

This seems to match my testing too.

With the 1Gb RAMDisk, if I call navigator.storage.estimate() I get:

• quota: ~86Mb
• usage: ~97Mb

If I look up R:\profile\storage\default\moz-extension+++24c702b7-88d3-4308-b837-718b91994071 I can see that the folder is 97Mb.

This too matches the calculations for storage limits:

• Global limit = 50% of available disk space = 500Mb
• Group limit = 20% of global limit = 100Mb

So that's bad news, but there's nothing much we can do about it for now.

Next steps:

• Fix the serialization of Errors passed from worker to background page (9fc8276)
• Make hikibiki-data dump errors to the console in bulkUpdateTable (birchill/hikibiki-data@e4fce37)
• Make hikibiki-data produce a GenericPutError if it encounters an error when updating and the error is suspiciously generic (e.g. no message etc.) (birchill/hikibiki-data@34380bf)
• (While we're at it, tweak hikibiki-data's abort handling since it's pretty awful)
• Update rikaichamp to the updated hikibiki-data (e250931)
• In Rikaichamp, somewhere convert GenericPutErrors to QuotaExceededErrors, possibly after inspecting the result of storage.estimate() first to see if that's a likely cause. Alternatively, we might just decide to do this translation inside hikibiki-data.
• Don't display an error icon in the toolbar when we hit a QuotaExceededError (fa5ed68)
• See if we have any unnecessary indices in hikibiki-data we can remove to reduce the on-disk size of the database.

[birtles]

I dug around the code for this but couldn't find anything suspicious. However, I did notice the following error in the browser console:

IO error: ファンクションが間違っています。 (os error 1) ExtensionStorageSync.jsm:69
    handleError resource://gre/modules/ExtensionStorageSync.jsm:69

I'm pretty sure this is unrelated. This seems to happen after-the-fact. I run a debug build of Firefox and tried to see where it was coming from, but all I worked out was it is not a problem with that function per-se. This is coming from a Windows API somewhere. It may be, however, that when we translate it into a JS error at some point we end up with something very generic.

[asutherland]

You may need to call navigator.storage.persist() to actually take advantage of the "unlimitedStorage" permission. There's a weird 2-step dance from the perspective of the Web API where the permissions manager permission is just an automatic yes or an automatic no, but you need to actually call the above API for QuotaManager to actually mark the origin as persistent. This is confusing and arguably wrong and there may be bugs tracking this or not; https://bugzilla.mozilla.org/show_bug.cgi?id=1558478#c2 tracks the start of some discussion about things.

Other potentially related bug: https://bugzilla.mozilla.org/show_bug.cgi?id=1630413 removed prompting related to the permission for webext purposes; I think the idea was that it's always a reasonable thing to ask for.

[birtles]

You may need to call navigator.storage.persist() to actually take advantage of the "unlimitedStorage" permission.

I can't thank you enough for this. This is such a huge help.

Other potentially related bug: https://bugzilla.mozilla.org/show_bug.cgi?id=1630413 removed prompting related to the permission for webext purposes; I think the idea was that it's always a reasonable thing to ask for.

Thank you for this too. This add-on still has a number of users on Firefox versions earlier than 77 (roughly ~1.08%) so I might make the call to persist() conditional on being Firefox 77 or later to avoid annoying users with permission prompts.