Closed Bug 842899 Opened 8 years ago Closed 5 years ago

Intermittent java-exception | android.database.sqlite.SQLiteDiskIOException: disk I/O error at android.database.sqlite.SQLiteStatement.native_executeSql(Native Method)

Categories

(Firefox for Android :: General, defect)

ARM
Android
defect
Not set
critical

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: philor, Unassigned)

References

Details

(Keywords: crash, intermittent-failure, Whiteboard: [native-crash])

+++ This bug was initially created as a clone of Bug #736859 +++

https://tbpl.mozilla.org/php/getParsedLog.php?id=19890168&tree=Mozilla-Inbound
Android 4.0 Panda mozilla-inbound opt test jsreftest-1 on 2013-02-19 15:23:07 PST for push fba3a342a530
slave: panda-0589

REFTEST TEST-START | http://10.12.133.22:30589/jsreftest/tests/jsreftest.html?test=ecma/Date/15.9.2.2-5.js | 62 / 899 (6%)
DeviceManager: pull unsuccessful: could not get all file data
reconnecting socket
DeviceManager: pull unsuccessful: could not get all file data
reconnecting socket

INFO | automation.py | Application ran for: 0:03:48.790958
INFO | automation.py | Reading PID log: /tmp/tmpODSjbhpidlog
PROCESS-CRASH | java-exception | android.database.sqlite.SQLiteDiskIOException: disk I/O error	at android.database.sqlite.SQLiteStatement.native_executeSql(Native Method)
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!

REFTEST INFO | runreftest.py | Running tests: end.
WARNING: Unable to retrieve log file (/mnt/sdcard/tests/reftest/reftest.log) from remote device
02-19 15:26:50.007 I/SqliteDatabaseCpp( 2156): sqlite returned: error code = 1034, msg = os_unix.c: full_fsync() at line 26035 - "" errno=5 path=/mnt/sdcard/tests/reftest/profile/browser.db-wal, db=/mnt/sdcard/tests/reftest/profile/browser.db

02-19 15:26:50.007 E/GeckoAppShell( 2156): >>> REPORTING UNCAUGHT EXCEPTION FROM THREAD 93 ("GeckoBackgroundThread")
02-19 15:26:50.007 E/GeckoAppShell( 2156): android.database.sqlite.SQLiteDiskIOException: disk I/O error
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.database.sqlite.SQLiteStatement.native_executeSql(Native Method)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.database.sqlite.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:90)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.database.sqlite.SQLiteDatabase.executeSql(SQLiteDatabase.java:1899)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.database.sqlite.SQLiteDatabase.execSQL(SQLiteDatabase.java:1839)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.database.sqlite.SQLiteDatabase.endTransaction(SQLiteDatabase.java:714)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at org.mozilla.fennec.db.BrowserProvider.update(BrowserProvider.java:2241)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.content.ContentProvider$Transport.update(ContentProvider.java:219)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.content.ContentResolver.update(ContentResolver.java:856)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at org.mozilla.gecko.db.LocalBrowserDB.updateVisitedHistory(LocalBrowserDB.java:259)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at org.mozilla.gecko.db.BrowserDB.updateVisitedHistory(BrowserDB.java:143)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at org.mozilla.gecko.GlobalHistory.add(GlobalHistory.java:122)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at org.mozilla.gecko.GeckoAppShell$15.run(GeckoAppShell.java:1829)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.os.Handler.handleCallback(Handler.java:605)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.os.Handler.dispatchMessage(Handler.java:92)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at android.os.Looper.loop(Looper.java:137)
02-19 15:26:50.007 E/GeckoAppShell( 2156): 	at org.mozilla.gecko.util.GeckoBackgroundThread.run(GeckoBackgroundThread.java:31)
sqlite returned: error code = 1034

This seems to be an FSYNC error
Whiteboard: [native-crash]
Note that these happen in clusters on certain devices. Comment 4 - Comment 12 breakdown:

5 x tegra-262
1 x tegra-078
3 x tegra-347
The log from Comment 6 shows much less space available on tegra-262's /data than I would expect:

'disk': ['/data: 221904896 total, 6868992 available', '/system: 250740736 total, 150310912 available', '/mnt/sdcard: 7736557568 total, 7666270208 available']

Similarly, Comment 9 for tegra-347 shows:

'disk': ['/data: 221904896 total, 4849664 available', '/system: 250740736 total, 150310912 available', '/mnt/sdcard: 15911780352 total, 15880413184 available']


This seems more typical:

'disk': ['/data: 222035968 total, 56942592 available', '/system: 250740736 total, 150441984 available', '/mnt/sdcard: 7949434880 total, 7914508288 available']


It looks like we are sometimes running low on disk space on /data, on some tegras.
See Also: → 872051
Depends on: 872050
See Also: 872051
This failure abruptly ceased with resolution of bug 872050: The I/O error was caused by running out of space on /data. Test logs today show available space of > 150 MB on /data on tegras, > 300 MB on pandas.

This bug will recur if we run out of space due to accumulating files or permanent errors on the storage.
4 in a row on panda-0778 -- let's disable/re-image that panda.
The last 9 failures have been on panda-0220.

It looks like there is space available:

'disk': ['/data: 534761472 total, 377069568 available', '/system: 534761472 total, 185090048 available', '/mnt/sdcard: 8573165568 total, 8540176384 available'

but I guess there's something else wrong with that panda.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.