Closed Bug 1201018 Opened 4 years ago Closed 4 years ago

Intermittent java-exception | android.database.sqlite.SQLiteException: error code 14: unable to open database file at android.database.sqlite.SQLiteStatement.native_execute(Native Method)

Categories

(Firefox for Android :: General, defect)

All
Android
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 45
Tracking Status
firefox45 --- fixed

People

(Reporter: nigelb, Assigned: gbrown)

References

()

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

No description provided.
This seems to happen on testGeckoProfile teardown.

07:36:04     INFO -  11-20 07:35:43.348 I/Database(  528): sqlite returned: error code = 14, msg = cannot open file at source line 25467
07:36:04     INFO -  11-20 07:35:43.348 I/Database(  528): sqlite returned: error code = 14, msg = prepared statement aborts at 40: [DELETE FROM tabs WHERE client_guid IS NULL]
07:36:04     INFO -  11-20 07:35:43.398 W/dalvikvm(  528): threadid=10: thread exiting with uncaught exception (group=0x40015560)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 11 ("GeckoBackgroundThread")
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): android.database.sqlite.SQLiteException: error code 14: unable to open database file
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.database.sqlite.SQLiteStatement.native_execute(Native Method)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.database.sqlite.SQLiteStatement.execute(SQLiteStatement.java:61)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.database.sqlite.SQLiteDatabase.delete(SQLiteDatabase.java:1632)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at org.mozilla.gecko.db.TabsProvider.deleteValues(TabsProvider.java:361)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at org.mozilla.gecko.db.TabsProvider.deleteInTransaction(TabsProvider.java:183)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at org.mozilla.gecko.db.AbstractTransactionalProvider.delete(AbstractTransactionalProvider.java:189)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.content.ContentProvider$Transport.delete(ContentProvider.java:222)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.content.ContentResolver.delete(ContentResolver.java:692)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at org.mozilla.gecko.db.LocalTabsAccessor.persistLocalTabs(LocalTabsAccessor.java:304)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at org.mozilla.gecko.Tabs$PersistTabsRunnable.run(Tabs.java:92)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.os.Handler.handleCallback(Handler.java:587)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.os.Handler.dispatchMessage(Handler.java:92)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at android.os.Looper.loop(Looper.java:130)
07:36:04     INFO -  11-20 07:35:43.428 E/GeckoCrashHandler(  528): 	at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:43)
07:36:04     INFO -  11-20 07:35:43.448 E/GeckoCrashHandler(  528): Main thread (1) stack:
07:36:04     INFO -  11-20 07:35:43.489 E/GeckoCrashHandler(  528):     android.view.Surface.lockCanvasNative(Native Method)
07:36:04     INFO -  11-20 07:35:43.508 E/GeckoCrashHandler(  528):     android.view.Surface.lockCanvas(Surface.java:314)
07:36:04     INFO -  11-20 07:35:43.541 E/GeckoCrashHandler(  528):     android.view.ViewRoot.draw(ViewRoot.java:1456)
07:36:04     INFO -  11-20 07:35:43.549 E/GeckoCrashHandler(  528):     android.view.ViewRoot.performTraversals(ViewRoot.java:1258)
07:36:04     INFO -  11-20 07:35:43.549 E/GeckoCrashHandler(  528):     android.view.ViewRoot.handleMessage(ViewRoot.java:1859)
07:36:04     INFO -  11-20 07:35:43.569 E/GeckoCrashHandler(  528):     android.os.Handler.dispatchMessage(Handler.java:99)
07:36:04     INFO -  11-20 07:35:43.592 E/GeckoCrashHandler(  528):     android.os.Looper.loop(Looper.java:130)
07:36:04     INFO -  11-20 07:35:43.592 E/GeckoCrashHandler(  528):     android.app.ActivityThread.main(ActivityThread.java:3683)
07:36:04     INFO -  11-20 07:35:43.592 E/GeckoCrashHandler(  528):     java.lang.reflect.Method.invokeNative(Native Method)
07:36:04     INFO -  11-20 07:35:43.592 E/GeckoCrashHandler(  528):     java.lang.reflect.Method.invoke(Method.java:507)
07:36:04     INFO -  11-20 07:35:43.609 E/GeckoCrashHandler(  528):     com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:839)
07:36:04     INFO -  11-20 07:35:43.609 E/GeckoCrashHandler(  528):     com.android.internal.os.ZygoteInit.main(ZygoteInit.java:597)
07:36:04     INFO -  11-20 07:35:43.609 E/GeckoCrashHandler(  528):     dalvik.system.NativeStart.main(Native Method)
Assignee: nobody → gbrown
Bug first noted shortly after http://hg.mozilla.org/mozilla-central/rev/fa2ee4b3a700, which modified PERSIST_TABS_AFTER_MILLISECONDS.
> This seems to happen on testGeckoProfile teardown.

The failures occur after the test has ended, but it looks like at least some occur after testGeckoProfile.tearDown() (note that Robocop:Quit is being processed in some logs).

PersistTabsRunnable gets a db reference from GeckoProfile.get(context).getDB() when the runnable is constructed, and then uses that reference 2 seconds+ later, when the runnable runs. What if that profile has been removed? Is the test cleaning up profiles too aggressively, or is the PersistTabsRunnable making incorrect assumptions about profile lifetimes?
I don't really know what is going wrong here, but I think the problem could be that the PersistTabsRunnable gets a db reference from the profile when the runnable is constructed, then the test removes the profile, and then the runnable runs and finds there is no db to operate on. 

My simplistic, speculative fix is to check for the profile dir at run() time and bail out if the directory is missing. I'm totally open to other approaches!
Attachment #8694953 - Flags: review?(rnewman)
Comment on attachment 8694953 [details] [diff] [review]
avoid db access in PersistTabsRunnable when profile has been removed

Review of attachment 8694953 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/Tabs.java
@@ +92,5 @@
>  
>          @Override
>          public void run() {
> +            if (dir.exists()) {
> +                db.getTabsAccessor().persistLocalTabs(context.getContentResolver(), tabs);

This is expedient but wrong -- it assumes that the tabs DB is in the profile directory, and that the tabs content provider uses a DB!

The right thing to do here is simply to assume that the write can fail, which it always can -- wrap the write in a try..catch and simply log.
Attachment #8694953 - Flags: review?(rnewman) → review-
Status: NEW → ASSIGNED
OS: Unspecified → Android
Hardware: Unspecified → All
(In reply to Geoff Brown [:gbrown] from comment #54)
> What if that
> profile has been removed? Is the test cleaning up profiles too aggressively,
> or is the PersistTabsRunnable making incorrect assumptions about profile
> lifetimes?

To address this --

I think your diagnosis is correct, and the ContentProvider is having its database file deleted out from under it.

We shouldn't really do that; we should only delete the profile when the process has been killed, or all outstanding tasks completed. If we were to do so this bug wouldn't be visible.

But in general writes can always fail (e.g., disk full or SQLITE_BUSY), and we should accept that. So I suggest try..catch instead.
Yes, this feels better - thanks!
Attachment #8694953 - Attachment is obsolete: true
Attachment #8695095 - Flags: review?(rnewman)
Attachment #8695095 - Flags: review?(rnewman) → review+
https://hg.mozilla.org/mozilla-central/rev/c326c11ff8dd
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 45
You need to log in before you can comment on or make changes to this bug.