1411691 - Unexpected error resulting from missing storage-sync.sqlite file

Status: NEW

(WebExtensions :: Storage, defect, P3)

Description

[Olivier de Broqueville]

Attachment: Screenshot 2017-10-25 at 20.32.48 PM.jpg

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:58.0) Gecko/20100101 Firefox/58.0
Build ID: 20171025100449

Steps to reproduce:

I created a new 'test2' profile and started Nightly with that profile. I then loaded my ffx extension for debugging purposes.


Actual results:

The new 'test2' profile was created without creating a storage-sync.sqlite file (as can be seen in the attached screenshot). As a result, loading my extension which initializes with:
browser.storage.sync.get(null).then(onGot, onError);
produces an "unexpected error" and calls onError.


Expected results:

Creating a new profile should also result in the creation of a new storage-sync.sqlite file, so that 
browser.storage.sync.get(null).then(onGot, onError);
calls onGot with no data retrieved instead of calling onError.

Comment 1

[Andrew Sutherland [:asuth] (he/him)]

browser.storage is a WebExtensions API, moving.  Also, I think there may be some confusion, PROFILE/storage.sqlite and PROFILE/storage/ are owned by the QuotaManager subsystem which is used for things like IndexedDB.  I believe webextension storages live under PROFILE/browser-extension-data/{extension-name} or something along those lines and are just flat JSON files.

Comment 2

[Andy McKay]

In my testing I've been able to reproduce this, if the file isn't present, then it is created when its needed and the promise successfully resolved.

I have been able to reproduce an error by making my profile read-only on the file system. In that case I get an error: "Error(s) encountered during statement execution: attempt to write a readonly database". 

Can you confirm that your directory isn't locked and that Firefox has the ability to write to it? Sometimes this might mean rebooting your Windows machine, although there's probably a better way to test that.

Comment 3

[Andy McKay]

(In reply to Andy McKay [:andym] from comment #2)
> In my testing I've been able to reproduce this

Typo: In my testing I've been *unable* to reproduce this

Comment 4

[Olivier de Broqueville]

I'm actually using Mac OS X High Sierra 10.13.1, as shown in the attached screenshot above. The screenshot also shows that the file storage-sync.sqlite is missing in the profile folder I used to test my extension.

I've gone through the following steps again:

1) Created a new "Testing" profile using Firefox Nightly 58.0a1 (2017-11-02) (64-bit)
2) Visited the path in Finder of the newly created profile and noticed that the "storage-sync.sqlite" file doesn't exist.
https://i.imgur.com/n6dLgm3.jpg?1
3) Verified the folder permissions for the new profile folder.
https://i.imgur.com/epMQj8C.jpg
The folder doesn't seem to be locked and my login name has both Read & Write access to the folder.
4) Loaded my extension Context Search in about:debugging
5) Verified if "storage-sync.sqlite" was still non existing -> the file "storage-sync.sqlite" got created. (This appears to differ from what I had observed previously!)
6) Verified the file permissions. My login name has Read & Write access. Everyone else has Read Only access.
https://i.imgur.com/armWR7Z.jpg
7) Verified the contents of "storage-sync.sqlite" before using the extension for the first time. The file is empty. 0 records.
https://i.imgur.com/cKAusk1.jpg
8) Opened the debug window (by clicking on the "Debug" link in about:debugging). Got an "unexpected error".
https://i.imgur.com/MLvlSZR.jpg
9) Tried using the extension. The search engines failed to load, i.e. the JSON file containing the list of search engines by default did not feed into storage-sync.sqlite as would have been expected.The latter file remained empty.
10) Visited about:addons and clicked on the "More" link for Context Search to access the extension's preferences.
https://i.imgur.com/FXfxh8o.jpg
11) Accessed the extension's preferences page. The list of search engines is missing because they haven't been loaded into "storage-sync.sqlite".
https://i.imgur.com/KllP2d6.jpg
12) I clicked on the "Reset" button in the prefs page and this time the default search engines were successfully loaded into storage-sync.sqlite and displayed in the prefs page.
https://i.imgur.com/SSiIu07.jpg
https://i.imgur.com/ladTr9N.jpg

Something does indeed seem to have prevented an update of the storage-sync.sqlite when a first attempt was made. I can't quite make sense of the error message that got displayed:

"Error(s) encountered during statement execution: no such table: collection_data Sqlite.jsm:810
	handleCompletion resource://gre/modules/Sqlite.jsm:810:25"

just before the unexpected error occurred.

The only way that I have found to circumvent the error thus far is by including the loading of the default search engines from the JSON file into storage-sync.sqlite in the error handler!

Please see code below:

// To support Firefox ESR, we should check whether browser.storage.sync is supported and enabled.
function detectStorageSupportAndLoadSearchEngines() {
	browser.storage.sync.get(null).then(onGot, onNone);

    // Load search engines if they're not already loaded in storage sync
	function onGot(data){
        if (!Object.keys(data).length > 0 || reset) {
            // Storage sync is empty -> load default list of search engines
            loadSearchEngines(DEFAULT_JSON);
        } else {
            searchEngines = sortByIndex(data);
            initializeFavicons();
        }
	}

	function onNone(error){
        //loadSearchEngines(DEFAULT_JSON);
		if (error.toString().indexOf("Please set webextensions.storage.sync.enabled to true in about:config") > -1) {
			notify("Please enable storage sync by setting webextensions.storage.sync.enabled to true in about:config. Context Search will not work until you do so.");
		} else {
            onError(error);
        }
	}
}

Hope this helps. Please don't hesitate asking if you'd like me to test anything else.

Comment 5

[Andy McKay]

Marco, we think this might be about the way we initialize the sqlite storage in WebExtensions. There's another bug on github over here: https://github.com/marklieberman/foxygestures/issues/76

Would you know anything about this, or alternatively be able to point us to someone who might be able to help?

Comment 6

[Marco Bonardo [:mak]]

The code opening the db and creating the tables in kinto-storage-adapter.js looks correct.
Based on the error we see, my initial theories are:
1. something is not properly waiting for a promise, so we end up trying to use a table before it actually exists
2. multiple connections are involved and one may not yet see the changes of the other one (though Kinto doesn't use WAL so this is less likely)
3. A strange corruption? Kinto doesn't seem to have any corruption handling procedure. Though if it happens in new profiles, it's unlikely.

Something you could do if you can reproduce the bug, is using MOZ_LOG. Set MOZ_LOG env var to "mozStorage:5" and also set MOZ_LOG_FILE to a local path since it will grow quite a bit.
The log file will contain all the queries and db operations from Storage, and we should be able to see if some of those queries are executed in an unexpected order (it may take some effort to filter all the unrelated traffic).
Since it collects every single query, I'd suggest to do so in a clean profile and do as less as possible.

Comment 7

[Olivier de Broqueville]

Attachment: screenshot of terminal window

Comment 8

[Olivier de Broqueville]

Attachment: screenshot of ffx debug window

Comment 9

[Olivier de Broqueville]

Attachment: mozlog.txt

Comment 10

[Olivier de Broqueville]

I went thru the above steps to reproduce the bug in Firefox 57.0 (64-bits) and have attached the following 3 files associated to the test case:

1) screenshot of terminal window
2) screenshot of ffx debug window
3) mozlog.txt

Please note that I am not familiar with Kinto (i.e. what it is!) or with WAL (whatever that is!).

Comment 11

[Olivier de Broqueville]

Attachment: screenshot of debug window after producing bug

Comment 12

[Olivier de Broqueville]

Attachment: screenshot of debug window after producing bug in Context Search

Comment 13

[Olivier de Broqueville]

I've done some further testing. I don't know if it's helpful, but here are my findings...

I've noticed that storage.sqlite gets created when opening firefox with a new profile, but storage-sync.sqlite doesn't.
storage-sync.sqlite gets created when an extension is loaded in the browser. I don't know why storage-sync.sqlite doesn't get created at the same time as storage.sqlite, but that's the way it works now!

I created a small web extension to try and reproduce the bug I'm having with Context Search. The code may be seen here:
https://github.com/odebroqueville/webext/blob/master/background.js
It's very basic. First thing to note is that it doesn't reproduce the bug as I was hoping, but...

After loading the web extension with a new profile, storage-sync.sqlite gets created. I then changed the name of the file to hide-storage-sync.sqlite and reloaded the extension. I then got a "fail". I thought that storage-sync.sqlite would be re-created and initialized if missing, but no. The error produced isn't exactly the same, but it happens at the same spot, i.e. resource://gre/modules/Sqlite.jsm:810:25.

(Pls see screenshot 8931869 of debug window)

I then modified Context Search a little to make it start the same way as webext. storage-sync.sqlite was, as expected, created when the extension was loaded. But here, nothing got to storage-sync.sqlite, i.e. no tables were created, whereas, with webext,
the tables had been created and the db had been written to.

(Pls see screenshot 8931870 of debug window)

The debug window shows that storage-sync.sqlite has not been correctly initialized, i.e. the table collection_data had not been created, and perhaps the reason was because another request was accessing the database and it was locked. (Mind you, that's just an assumption because I don't know under which circumstances a database gets locked!).

I'm attaching another mozlog.txt file corresponding to screenshot 8931870. Personally, I can't make much sense of these files!

Comment 14

[Olivier de Broqueville]

Attachment: mozlog.txt

Comment 15

[Olivier de Broqueville]

I have found the line in Context Search that produces the BUG. When I remove that line, everything works normally!

The line is:
browser.storage.local.get(["optionsMenuAtTop", "optionsMenuLocation"]).then(setOptionsMenu, onError);

I need to give you some context so that you can find the explanation...

In Context Search, the first function that gets run is the init() function below:
_______________________
function init() {
    detectStorageSupportAndLoadSearchEngines();
    browser.runtime.getBrowserInfo().then(gotBrowserInfo);
    browser.storage.onChanged.addListener(onStorageChanges);

    browser.storage.local.get(["tabMode", "tabActive"]).then(fetchTabMode, onError);
    browser.storage.local.get("gridMode").then(setGridModeAndBuildContextMenu, onError);
    browser.storage.local.get(["optionsMenuAtTop", "optionsMenuLocation"]).then(setOptionsMenu, onError);// this is BUGGY line 

    // getBrowserInfo
    function gotBrowserInfo(info){
        let v = info.version;
        browserVersion = parseInt(v.slice(0, v.search(".") - 1));
    }
}
________________________
The other function you should be aware of is the first one called in init():

________________________
function detectStorageSupportAndLoadSearchEngines() {
        browser.storage.sync.get(null).then(onGot, onNone);

        // Load search engines if they're not already loaded in storage sync
	function onGot(data){
        if (!Object.keys(data).length > 0 || reset) {
            // Storage sync is empty -> load default list of search engines
            loadSearchEngines(DEFAULT_JSON);
        } else {
            searchEngines = sortByIndex(data);
            initializeFavicons();
            rebuildContextMenu();
        }
	}

	function onNone(error){
        //loadSearchEngines(DEFAULT_JSON);
		if (error.toString().indexOf("Please set webextensions.storage.sync.enabled to true in about:config") > -1) {
			notify("Please enable storage sync by setting webextensions.storage.sync.enabled to true in about:config. Context Search will not work until you do so.");
		} else {
            onError(error);
        }
	}
}
_______________________________

What happens is that, the first time the BUGGY line is executed, no data exists. I'm not certain whether this produces an error or not, but I'm guessing the result is that the sqlite db gets locked. The odd thing is that we're reading from local storage and it ends up locking sync storage! And the result of the db getting locked is that it doesn't get properly initialized, i.e. the collection_data table isn't created.

Comment 16

[Olivier de Broqueville]

I don't know who's responsible for this, but it would be very useful if indentation was preserved in comments here when we paste in code! I'm sorry if the above code is harder to read!

Comment 17

[Marco Bonardo [:mak]]

Attachment: cleaned up moz_log

From a quick analysis of the moz_log, looks like these kinto connections are short-lived and use a mixture of transaction types (some deferred and some exclusive). There are at least 7 thread fighting for this resource, just here.

I a see a lot of connections opened sequentially (look for "Opening connection to 'storage-sync.sqlite"), each one is trying to create the schema, and some will probably fail to do so, because a previous one did already.
Using these many short-lived connections seems fragile and inefficient, in general.

The schema seems to be created inside a deferred transaction, immediately followed by an exclusive transaction that runs the "SELECT record FROM collection_data" query, that fails.

Comment 18

[Ethan Glasser-Camp (:glasserc)]

Hi! I thought I would take a look at this since I feel like I promised to work on the linked foxygestures issue.

storage.sqlite isn't related to storage-sync.sqlite. I think it's related to quota management but I'm not really sure -- I've never touched that code.

Do we still have this bug in recent Firefoxes? The storage.sync code is meant to initialize only once, and this code got improved in bug 1414997.

Probably FirefoxAdapter#_init should execute the statements that create those tables in EXCLUSIVE mode rather than in DEFERRED mode. I have filed bug 1461435 to fix that. However, if we only do initialization once because of bug 1414997, it may no longer be such an issue.