Got this after installing Margaret's Pocket add-on, as it was refreshing data. This looks very much like Bug 947939 -- that is, SQLiteBridge and itself, or something else, are concurrently accessing the same database file. That's a no-no, and should not ship. Margaret saw this when testing with large numbers of items, and filed Bug 965452 to avoid queries taking so long that it provokes this bug, so filing this to track the root cause. E/GeckoConsole(11323): [JavaScript Error: "ConstraintError" {file: "chrome://browser/content/browser.js" line: 7511}] E/GeckoHomeProvider(11323): Error querying database E/GeckoHomeProvider(11323): org.mozilla.gecko.sqlite.SQLiteBridgeException: Can't step statement: (5) database is locked E/GeckoHomeProvider(11323): at org.mozilla.gecko.sqlite.SQLiteBridge.sqliteCall(Native Method) E/GeckoHomeProvider(11323): at org.mozilla.gecko.sqlite.SQLiteBridge.internalQuery(SQLiteBridge.java:236) E/GeckoHomeProvider(11323): at org.mozilla.gecko.sqlite.SQLiteBridge.rawQuery(SQLiteBridge.java:129) E/GeckoHomeProvider(11323): at org.mozilla.gecko.sqlite.SQLiteBridge.query$18cfc304(SQLiteBridge.java:119) E/GeckoHomeProvider(11323): at org.mozilla.gecko.db.SQLiteBridgeContentProvider.query(SQLiteBridgeContentProvider.java:386) E/GeckoHomeProvider(11323): at org.mozilla.gecko.db.HomeProvider.query(HomeProvider.java:88) E/GeckoHomeProvider(11323): at android.content.ContentProvider.query(ContentProvider.java:869) E/GeckoHomeProvider(11323): at android.content.ContentProvider$Transport.query(ContentProvider.java:212) E/GeckoHomeProvider(11323): at android.content.ContentResolver.query(ContentResolver.java:476) E/GeckoHomeProvider(11323): at android.content.ContentResolver.query(ContentResolver.java:419) E/GeckoHomeProvider(11323): at org.mozilla.gecko.home.DynamicPanel$PanelDatasetLoader.loadCursor(DynamicPanel.java:388) E/GeckoHomeProvider(11323): at org.mozilla.gecko.home.SimpleCursorLoader.loadInBackground(SimpleCursorLoader.java:44) E/GeckoHomeProvider(11323): at org.mozilla.gecko.home.SimpleCursorLoader.loadInBackground(SimpleCursorLoader.java:26) E/GeckoHomeProvider(11323): at android.support.v4.content.AsyncTaskLoader.onLoadInBackground(AsyncTaskLoader.java:242) E/GeckoHomeProvider(11323): at android.support.v4.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:51) E/GeckoHomeProvider(11323): at android.support.v4.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:40) E/GeckoHomeProvider(11323): at android.support.v4.content.ModernAsyncTask$2.call(ModernAsyncTask.java:123) E/GeckoHomeProvider(11323): at java.util.concurrent.FutureTask.run(FutureTask.java:237) E/GeckoHomeProvider(11323): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) E/GeckoHomeProvider(11323): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) E/GeckoHomeProvider(11323): at java.lang.Thread.run(Thread.java:864)

FYI, the "[JavaScript Error: "ConstraintError" {file: "chrome://browser/content/browser.js" line: 7511}]" bit is caused by my reader mode hacks to cache Pocket articles, which is a separate issue than this one. However, this HomeProvider problem sounds bad, we should fix that.

Putting this tentatively on my plate. Feel free to steal it.

Mere pull to refresh on Wikipedia panel from AMO → "No content could be found for this panel."

(In reply to Aaron Train [:aaronmt] from comment #3) > Created attachment 8419679 [details] > log.log > > Mere pull to refresh on Wikipedia panel from AMO → "No content could be > found for this panel." Was there data there, then you pulled to refresh, then it was empty? The add-on does a deleteAll followed by a save, so this exception must have happened in between. Bug 999756 might help fix that testcase, but yeah, there's a bug under here.

Yes there was the initial feed on first view after install. I then did a pull to refresh and the panel emptied.

rnewman, have you had time to look into this? I'm a bit worried about this bug if we're going to start promoting these panel add-ons. Also, I bet this affects Fx30, not just 31 and beyond.

Not yet, but it's on my list. This afternoon, I hope.

Observed findings from code reading: * SQLiteBridge is not intrinsically thread safe. (For example: isOpen(), mDbPointer, and friends.) This alone could cause bugs if, say, the UI thread and the background thread both touch the same instance. We rely on SQLiteBridgeContentProvider to synchronize access. That provider looks OK, but there might be a bug hiding here. * Calls into SQLiteBridge.cpp from multiple threads can result in multiple calls to f_sqlite_open. There's no synchronization at all in the native code. * HomeProvider uses Sqlite.jsm to open the same database that the Java code is opening, but without any coordination. This is the most likely culprit: it means that a Java thread and the Gecko thread both have open DB handles. * I haven't yet checked for any multiple-init bugs.

The fundamental problem here is that there is no overlap in the two consumers of this database above the level of sqlite3_open -- SQLiteBridge doesn't even use mozStorage -- and sqlite will report that the DB is locked at the file level whenever they contend. (There's only overlap at all by the happy coincidence of being in the same process and using the same library. Not much.) First plan of attack: as far as I can tell, SQLiteBridge doesn't specify WAL when opening a DB. (PRAGMA journal_mode=WAL;) If I'm right, this is a huge oversight: WAL is the only thing that allows any amount of concurrent access to a sqlite DB, so we shouldn't be surprised that this bug is very easy to reproduce. Beyond that -- if I'm wrong, or we need to do concurrent access including writes -- then just about the only way I see this working is for mozStorageConnection to delegate handling of `sqlite3 *` to code in mozglue. Bear in mind that opening a sqlite database involves writing (e.g., to set the journal mode itself!) -- Bug 752287 comment 6. So enabling the WAL will not be a total solution for this problem; it'll reduce the frequency of problems down to what we had prior to Bug 986114. But it might be enough for us to not disable this feature before it gets to release.

First stab. I wish this were part of Sqlite.jsm, but so it goes. Note that this patch doesn't work: adding a home panel silently fails, and it's 8pm, so I'm not planning to debug it now.

Setting P1 hub bugs to block hub v1 EPIC bug (targeting fx30 release). Filter on epic-hub-bugs.

Trivial part 0 cleanup.

I was expecting this to be the first of two parts, the other being inside HomeProvider.jsm itself. But with this change alone I can't reproduce the crash. Margaret, Aaron: please give this a shot (I'll push to Try momentarily), see if it's enough.

Comment on attachment 8429684 [details] [diff] [review] Part 1: enable WAL for SQLiteBridge. v1 Review of attachment 8429684 [details] [diff] [review]: ----------------------------------------------------------------- Nothing against this patch, but it's also quite obvious this doesn't really fix anything and what is happening right now (trying to use SQLite DBs from multiple places simultaneously) is fundamentally totally broken.

>If I'm right, this is a huge oversight: WAL is the only thing that allows any amount of concurrent >access to a sqlite DB, so we shouldn't be surprised that this bug is very easy to reproduce. Note that SQLiteBridge just provides access to the Gecko-bundled SQLite, nothing more. Setting the journal mode should be done by the user. I would actually prefer a patch like that because it adds more pain to the users. In this case, that's a *good* thing.

Comment on attachment 8429684 [details] [diff] [review] Part 1: enable WAL for SQLiteBridge. v1 Review of attachment 8429684 [details] [diff] [review]: ----------------------------------------------------------------- After thinking more: this would be cleaner if done in SQLiteBridge.java, and I believe the responsibility to enable WAL should be in the callers of that, so it's easier to see which code is broken.

(In reply to Gian-Carlo Pascutto [:gcp] from comment #16) > Nothing against this patch, but it's also quite obvious this doesn't really > fix anything Depending on your definition of "fix", that's not true, if my analysis is correct. The current situation with the home provider is that Java only reads, and Gecko writes. That situation -- multiple readers, single writer, different connections -- *is* supported by SQLite, so long as a WAL is used. If a WAL is not used, then Java's reads will block Gecko's writes, and vice versa -- SQLITE_BUSY. That's what we see in this bug. Simply switching the home provider DB to use WAL isn't perfect -- it wouldn't allow both Java and Gecko to write, for example, and there's some evidence that doing non-write operations on the DB involves taking the write lock -- but it's a solution to at least one (possibly all) of the root causes of the errors we see today. See Comment 10 for more. Please provide counter-reasoning if you have it! The fix for this needs to chase 31 up the train tracks, so I'm keen to find a solution sooner rather than later. > and what is happening right now (trying to use SQLite DBs from > multiple places simultaneously) is fundamentally totally broken. Correct. There are a limited set of solutions to that: 1. Don't use sqlite, instead building our own storage layer that allows for simultaneous read/writes from two different programming environments in two different threads. 2. Build a serialized access layer to sqlite -- effectively replicating the CP/CR interface into Gecko, managing the DBs in Java. 2.b) Don't directly access the database from HomeProvider.jsm, instead passing data in a home panel-specific channel (messaging, JNI, whatever) to Java. 3. Have mozStorage delegate its sqlite handle management to mozglue, so that SQLiteBridge and Sqlite.jsm end up working with the same sqlite connection, which is more tractable. I don't consider any of these solutions, thorough and perfect though they might be, to be something we can feasibly ship in 31. 2.b) might be an exception, and that's the avenue I'll explore next if this patch doesn't eliminate the errors.

(In reply to Gian-Carlo Pascutto [:gcp] from comment #17) > Note that SQLiteBridge just provides access to the Gecko-bundled SQLite, > nothing more. Setting the journal mode should be done by the user. The reason I did it in mozglue itself is twofold: 1. Don't ship footguns. There is no reason at all why any of our SQLiteBridge consumers should *not* be using a WAL, and forcing callers to do it just means that they'll forget -- exactly as we did when we built HomeProvider on top of it! 2. Enabling the WAL should be the first operation performed on the connection. That's easier to guarantee if it happens in the code that opens the DB.

>Depending on your definition of "fix", that's not true, if my analysis is correct >...there's some evidence that doing non-write operations on the DB involves taking the write lock That's what I meant with "not really fixing". This will reduce the incidence greatly, but we're not sure if we can still hit the problem condition? >I don't consider any of these solutions, thorough and perfect though they might be, >to be something we can feasibly ship in 31. Back out all the new features that caused the need for this until it's fixed? "Wouldn't it be nice..." :) >forcing callers to do it just means that they'll forget -- exactly as we did when we >built HomeProvider on top of it! And then it blows up quickly and we see we have a problem. Again, I think that's good. I prefer stuff that explodes in our face rather than a few fairly low frequency crash bugs due to SQLite locking that we can't ever seem to figure out (this should sound very familiar). Okay, I understand that this new HomePanel stuff needs to ship and likely can't wait until we unfoo SQLite, so we need to plaster over it. I also agree that the restrictions mean this must happen in the SQLiteBridge open, and I even agree that there's no reason to not use WAL every time. I think the patch will be a lot cleaner if you do it on the Java side instead of the C side, though.

(In reply to Gian-Carlo Pascutto [:gcp] from comment #21) > That's what I meant with "not really fixing". This will reduce the incidence > greatly, but we're not sure if we can still hit the problem condition? I'm moderately confident that we won't hit the problem condition at all with the current feature. I'll be more confident after QA, and if that still shows the problem, I'll finish up Part 2 (specify WAL for the other half), see if that's necessary. If we only do reads from Java, we should be 100% safe if WAL is correctly enabled. (Most of my doubt is that we correctly enable WAL!) If we don't only do reads, then the slowness of Gecko startup de facto prevents any concurrent write caused by the Java side accidentally triggering a write during opening. (I'm not sure if the SQLiteBridge will trigger the same writes that Android's SQLiteDatabase classes do. Those end up doing writes to set the locale of the database, amongst other things. We don't seem to do that, so I'm operating on the safe side here.) > Back out all the new features that caused the need for this until it's fixed? > > "Wouldn't it be nice..." :) :) > Okay, I understand that this new HomePanel stuff needs to ship and likely > can't wait until we unfoo SQLite, so we need to plaster over it. I also > agree that the restrictions mean this must happen in the SQLiteBridge open, > and I even agree that there's no reason to not use WAL every time. I think > the patch will be a lot cleaner if you do it on the Java side instead of the > C side, though. I'll hack up a patch for comparison. Thanks for the thoughtful review!

Comment on attachment 8430224 [details] [diff] [review] Part 1: enable WAL on the Java side of SQLiteBridge. This patch: * Cleans up a little more, adds comments, etc. * Fixes isOpen -- testing on my Nexus 10 reveals that mDbPointer is usually something like -2100846584, which obviously isn't greater than 0. * Does more than the C++ version -- we also set appropriate synchronous/autocheckpoint values, and log. I elected not to try to preprocess to include DEFAULT_PAGE_SIZE from the build stuff. Let me know if you want that as a separate patch.

New try build for testing: https://tbpl.mozilla.org/?tree=Try&rev=47d9c56febfe

Part 0: https://hg.mozilla.org/integration/fx-team/rev/d675b7fc9a0b

Not sure why this landed prior to Try build testing, but anyways this does work for me now. On swipe, I see the empty pane content and then after a second or two the data is fetched and the view is refreshed with content just fine. D/HomePanelsManager(14485): Refresh request for dataset: wikipedia.dataset@margaretleibovic.com D/GeckoHomeProvider(14485): No profile provided, using 'default' D/GeckoDynamicPanel(14485): Finished loader for request: { index: 0, type: DATASET_LOAD, dataset: wikipedia.dataset@margaretleibovic.com, filter: org.mozilla.gecko.home.PanelLayout$FilterDetail@42ae15b0 } D/GeckoPanelLayout(14485): Delivering request: { index: 0, type: DATASET_LOAD, dataset: wikipedia.dataset@margaretleibovic.com, filter: org.mozilla.gecko.home.PanelLayout$FilterDetail@42ae15b0 } D/GeckoPanelLayout(14485): Creating empty view: list D/GeckoPanelListView(14485): Setting dataset: wikipedia.dataset@margaretleibovic.com D/HomePanelsManager(14485): HomePanels:RefreshDataset

(In reply to Aaron Train [:aaronmt] from comment #28) > Not sure why this landed prior to Try build testing Only Part 0 landed, which was a cleanup patch. > but anyways this does work for me now. Testing that last Try build?

(In reply to Richard Newman [:rnewman] from comment #29) > (In reply to Aaron Train [:aaronmt] from comment #28) > > Not sure why this landed prior to Try build testing > > Only Part 0 landed, which was a cleanup patch. Ok. > > but anyways this does work for me now. > > Testing that last Try build? Yes.

I'm delighted to note that this is still happening (at a low rate, obv) in the wild: https://crash-stats.mozilla.com/report/index/2414ada8-03f2-4460-86d8-9a2dd2140529 so good to know that this might be the fix! Thanks, Aaron.

Clearing needinfo since Aaron was able to help test. I have most definitely run into this in the wild, but it only happens if you have hub add-ons installed, which is likely why the crash stats numbers are pretty low.

When will we ask for uplift?

(In reply to Mark Finkle (:mfinkle) from comment #33) > When will we ask for uplift? When gcp reviews Part 1 (the Java version), it gets landed and merged to m-c, and we take a look at new crashes over a couple of days and see no regressions (and, ideally, that it fixes the problem).

When I ran into this it wasn't a crash.

(In reply to Aaron Train [:aaronmt] from comment #35) > When I ran into this it wasn't a crash. I've seen this crash in the wild a few times. I was trying to find reliable STR yesterday, but I wasn't able to.

(In reply to Aaron Train [:aaronmt] from comment #35) > When I ran into this it wasn't a crash. Me neither: it was a log message (see Comment 0). But I imagine some DB hits aren't wrapped in a try block, so we do see some crashes. Time to put together a telemetry probe.

I was able to reproduce the crash by commenting out the check we have in HomeProvider.jsm to only save 100 items at once, creating an add-on that makes multiple lists, including one that has 10000 items, then trying to refresh them all at once (basically, saving 10000 items takes many seconds, plenty of time for the databse to get locked). With the most recent patch applied, I couldn't reproduce the crash using the same steps, so tentatively calling this a success.

Comment on attachment 8430224 [details] [diff] [review] Part 1: enable WAL on the Java side of SQLiteBridge. Review of attachment 8430224 [details] [diff] [review]: ----------------------------------------------------------------- r- because I'd like to see the final patch. ::: mobile/android/base/sqlite/SQLiteBridge.java @@ +28,5 @@ > // Path to the database. If this database was not opened with openDatabase, we reopen it every query. > private String mDb; > + > + // Pointer to the database if it was opened with openDatabase. 0 implies closed. > + protected volatile long mDbPointer = 0L; If you're going to try to make this threadsafe, I presume mTransactionSuccess/mInTransaction also need to be volatile. And probably the routines that use it would need to be synchronized as well? Does it make sense to split this off to a separate patch or bug? @@ +39,5 @@ > > private static final int RESULT_INSERT_ROW_ID = 0; > private static final int RESULT_ROWS_CHANGED = 1; > > + private static final int DEFAULT_PAGE_SIZE_BYTES = 32768; // Shamelessly cribbed from db/sqlite3/src/moz.build. Put the comment above the line for some consistency. @@ +40,5 @@ > private static final int RESULT_INSERT_ROW_ID = 0; > private static final int RESULT_ROWS_CHANGED = 1; > > + private static final int DEFAULT_PAGE_SIZE_BYTES = 32768; // Shamelessly cribbed from db/sqlite3/src/moz.build. > + private static final int MAX_WAL_SIZE_BYTES = 262144; This appears to be randomly chosen (all other code uses 512k). Add a comment why? @@ +263,4 @@ > throw new SQLiteException(ex.getMessage()); > } > + > + // Prepare for WAL mode. If we can, we switch to journal_mode=WAL, then Maybe put it into a separate function? @@ +281,5 @@ > + Log.w(LOGTAG, "Unable to activate WAL journal mode. Using truncate instead."); > + bridge.internalQuery("PRAGMA journal_mode=TRUNCATE", null).close(); > + } > + Log.w(LOGTAG, "Not using WAL mode: using synchronous=FULL instead."); > + bridge.internalQuery("PRAGMA synchronous=FULL", null).close(); This is actually the default, but I guess it makes sense to keep it for consistency with other storage layers, and to protect if the default should ever change. @@ +285,5 @@ > + bridge.internalQuery("PRAGMA synchronous=FULL", null).close(); > + } > + } > + } finally { > + cursor.close(); if (cursor != null) @@ +370,5 @@ > + } > + > + return cursor.getInt(0); > + } finally { > + cursor.close(); if (cursor != null)

(In reply to Gian-Carlo Pascutto [:gcp] from comment #39) > If you're going to try to make this threadsafe, I presume > mTransactionSuccess/mInTransaction also need to be volatile. And probably > the routines that use it would need to be synchronized as well? > > Does it make sense to split this off to a separate patch or bug? Making the whole class thread-safe is a bigger project, yes. Consider this a reflexive "ugh, a long member that's not volatile" -- it definitely can't hurt, so I fixed it while I was commenting. > > + private static final int MAX_WAL_SIZE_BYTES = 262144; > > This appears to be randomly chosen (all other code uses 512k). Add a comment > why? Huh, I could have sworn I copied 256KB directly from elsewhere, but I guess I applied judgment. 512KB is probably fine, but I think we inherited that from desktop decisions in 2010, so we can probably do better in one direction or another. > > + cursor.close(); > > if (cursor != null) Nope. We'll always get an exception or a cursor. This is actually even stronger than the built-in SQLite classes, which (by observation) return null for malformed SQL. Even there we don't null check because we want to die hard in those cases. Old Fennec code got in a really bad habit of doing stuff like: Cursor c; try { ... c = query(...); // Maybe c.foo ... } finally { if (c != null) c.close() I've been gradually pushing us to be more explicit and less lazy for two years now, and I think we're making good progress!

Comments addressed, thanks!

>Nope. We'll always get an exception or a cursor. ...and if you get an exception, you'll end up in finally, are guaranteed(!) to have a null cursor, which you now try to close, causing you to bail out of the finally block with a new one. Does our crash reporter even get to the *original* exception in that case? What's the point of putting the close in the finally block then? It's *guaranteed* to be useless code except that it'll throw an exception on top of it. If you claim you want to bomb out of Fennec entirely when this (entirely optional) setting fails, then I can sortof buy that (though IIRC blassey disagrees), but aside from the above, then what's the point of the "DEFAULT_PAGE_SIZE_BYTES" fallback in "getPageSizeBytes()"? Why don't you want bomb out there if a function that should really work, doesn't?

Clarified on IRC, the code is doing Cursor = query() try { } finally { cursor.close(); } not try { cursor = query() } finally { cursor.close() }

Comment on attachment 8431639 [details] [diff] [review] Part 1: enable WAL on the Java side of SQLiteBridge. v2 Approval request for this and the trivial cleanup in Part 0. I don't plan to uplift this until I have preliminary crash/telemetry support that it helps (or at least doesn't make things worse), but flagging to get it in the queue. [Approval Request Comment] Bug caused by (feature/regressing bug #): Bug 941312: initial landing of Home Provider feature in fx30. User impact if declined: Occasional crashes or non-loading data in home panel add-ons. Testing completed (on m-c, etc.): Landed on Nightly. Seems to be working -- margaret can't reproduce the bug with this change -- but we just uplifted telemetry to try to verify this on a slightly broader population. Risk to taking this patch (and alternatives if risky): I'd consider this to have a level of risk acceptable for late Aurora/early Beta. Most users won't be interacting with home panels, because they require add-ons to be installed, but the users who do will be vulnerable to this bug. That it's an add-on related feature and doesn't always crash is why I'm not pushing to try to uplift this into a late 30 beta, or disable home panels in 30. This patch does change how the provider database is accessed, which is a non-trivial alteration. However, that change is identical to how we open almost every other database in the codebase, and the code carefully follows those patterns. The alternative courses of action are: * Disable the home panels feature. * Build an alternative data storage mechanism, as described in comments earlier in this bug. * Don't release the fix until 32, and delay promoting the feature until then. String or IDL/UUID changes made by this patch: None.

Comment on attachment 8431639 [details] [diff] [review] Part 1: enable WAL on the Java side of SQLiteBridge. v2 31 is not yet in beta. So, we have still sometime to disable it in case it goes wrong.

telemetry.mo isn't giving me any data to refute this, so let's give it a shot. https://hg.mozilla.org/releases/mozilla-aurora/rev/ae6cc31bba60 https://hg.mozilla.org/releases/mozilla-aurora/rev/94eb5c1fec36