727803 - [B2G] Not possible to open (Error Unknown) and recovery a DB in Akami handset

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Maria Angeles Oteo (:oteo)]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_2) AppleWebKit/534.51.22 (KHTML, like Gecko) Version/5.1.1 Safari/534.51.22

Steps to reproduce:

Open a DataBase in Akami handset.


Actual results:

Sometimes, Error Code 1 (Unknown) is fired and the only way to recover it is removing directly the database in the filesystem.

Comment 1

[[:fabrice] Fabrice Desré]

Maria,

can you provide a test page?

Comment 2

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Did this maybe get fixed with bug 726814? Or is this somehow different?

Comment 3

[Maria Angeles Oteo (:oteo)]

No, Ben is another failure.

Comment 4

[[:fabrice] Fabrice Desré]

I did reproduce this bug by adding a bunch of contacts and then restarting.

The first restart was stuck in a loop like this one:
I/Gecko   (  514): OPENX   45  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/2919527460O5WBDD_yRretgsi.sqlite 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/2919527460O5WBDD_yRretgsi.sqlite-journal 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/2919527460O5WBDD_yRretgsi.sqlite-journal 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/2919527460O5WBDD_yRretgsi.sqlite 0400000
I/Gecko   (  514): OPENX   45  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/1502770231Csotncta.sqlite 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/1502770231Csotncta.sqlite-journal 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/1502770231Csotncta.sqlite-journal 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/1502770231Csotncta.sqlite 0400000
I/Gecko   (  514): OPENX   45  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/30115ssm.sqlite 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/30115ssm.sqlite-journal 0400102
I/Gecko   (  514): OPENX   46  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/30115ssm.sqlite-journal 0400102

I killed b2g again, and got the "error 1" :
    E/GeckoConsole(  567): [JavaScript Warning: "Unknown property 'transition-duration'.  Declaration dropped." {file: "http://localhost:6666/css/TIDHome.css" line: 43}]
    E/GeckoConsole(  567): [JavaScript Warning: "Error in parsing value for 'border-radius'.  Declaration dropped." {file: "http://localhost:6666/css/TIDHome.css" line: 151}]
    I/Gecko   (  567): OPENX   56  /data/b2g/mozilla/qc3pg70y.default/places.sqlite 0400000
    I/Gecko   (  567): OPENX   57  /data/b2g/mozilla/qc3pg70y.default/places.sqlite-wal 0400102
    I/Gecko   (  567): OPENX   58  /data/b2g/mozilla/qc3pg70y.default/webappsstore.sqlite 0400102
    I/Gecko   (  567): OPENX   62  /data/b2g/mozilla/qc3pg70y.default/chromeappsstore.sqlite 0400102
    E/GeckoConsole(  567): Content JS LOG at http://localhost:6666/People/script/owd_contacts.js:88 in openDB: Indexed DB is here
    I/Gecko   (  567): OPENX   66  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/30115ssm.sqlite 0400102
    I/Gecko   (  567): OPENX   67  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/30115ssm.sqlite-journal 0400000
    I/Gecko   (  567): OPENX   67  /data/b2g/mozilla/qc3pg70y.default/indexedDB/http+++localhost+6666/30115ssm.sqlite-journal 0400002
    E/GeckoConsole(  567): Content JS ERROR at http://localhost:6666/People/script/owd_contacts.js:100 in anonymous: Database error: 1
    E/GeckoConsole(  567): Content JS LOG at http://localhost:6666/People/script/owd_contacts.js:29 in populate: Populating contacts data base for demo!
    E/GeckoConsole(  567): Content JS ERROR at http://localhost:6666/script/owd_os.js:773 in anonymous: Upsss IndexedDB crashes!!
    I/GeckoDump(  567): ***OWD***: ------WebAPI event listeners-----
    I/GeckoDump(  567): ***OWD***: SMS received event listener added
    I/GeckoDump(  567): ***OWD***: ------END WebAPI event listeners-----

Comment 5

[Fernando Jiménez Moreno [:ferjm]]

Attachment: IDB Test case

IDB test case that inserts 15 records in a test DB. To get the IDB error, you have to run this test and reboot the device.

Comment 6

[[:fabrice] Fabrice Desré]

This test fails also on firefox desktop, so it's not akami specific. It's either:
- a bug in the test itself
- a bug in our indexedDB implementation

Comment 7

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

    newTxn: function newTxn(txn_type, callback, oncompleteCb, onerrorCb) {
      <snip>
    },

    addRecord: function addRecord(id1, id2, id3, successCb, failureCb) {
      <snip>
      this.newTxn(IDBTransaction.READ_WRITE, function(txn, store, error) {
        var request = store.put(record);
        request.onsuccess = function(event) {
          txn.result = record;
        };
      }, failureCb);
    },

This testcase is passing in failureCB to newTxn as oncompleteCb.

Comment 8

[Fernando Jiménez Moreno [:ferjm]]

Attachment: IDB Test case v2

Comment 9

[[:fabrice] Fabrice Desré]

(In reply to Fernando Jiménez Moreno [:ferjm] from comment #8)
> Created attachment 597983 [details]
> IDB Test case v2

this test doesn't fail on the akami

Comment 10

[Fernando Jiménez Moreno [:ferjm]]

Attachment: IDB Test case v3

Sorry to keep pushing on this. The previous test failed on akami when another IDB was opened before.
Here it goes another test case which let you open 2 different databases. In order to reproduce the error, you have to:

- Click 'OpenDB1' and 'OpenDB2'. It will open the database without any problem. Logcat result:
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:15 in openDB: **IDBTEST** Opening DB Test
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:30 in anonymous: **IDBTEST** onupgradeneeded 
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:20 in anonymous: **IDBTEST** Database opened Test
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:15 in openDB: **IDBTEST** Opening DB another db
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:30 in anonymous: **IDBTEST** onupgradeneeded 
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:20 in anonymous: **IDBTEST** Database opened another db

- Reboot the device.

- Click again both buttons. Nothing happens. It just get stacked on "Opening DB". Logcat result:
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:15 in openDB: **IDBTEST** Opening DB Test

- Reboot the device.
- Click button. An alert error showing error code 1 is shown. Logcat result:
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:15 in openDB: **IDBTEST** Opening DB Test
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:25 in anonymous: **IDBTEST** Error 1
E/GeckoConsole(   82): [JavaScript Error: "Couldn't play common dialog event sound: TypeError: Cc['@mozilla.org/sound;1'] is undefined" {file: "resource://gre/modules/CommonDialog.jsm" line: 213}]
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:15 in openDB: **IDBTEST** Opening DB another db
E/GeckoConsole(   82): Content JS LOG at http://localhost:6666/index.html:25 in anonymous: **IDBTEST** Error 1
E/GeckoConsole(   82): [JavaScript Error: "Couldn't play common dialog event sound: TypeError: Cc['@mozilla.org/sound;1'] is undefined" {file: "resource://gre/modules/CommonDialog.jsm" line: 213}]

Am I doing anything wrong?

Comment 11

[[:fabrice] Fabrice Desré]

I confirm that the testcase pass on desktop and fennec, but fails on the akami. Reopening and investigating

Comment 12

[[:fabrice] Fabrice Desré]

the SQlite error we get in this case at https://mxr.mozilla.org/mozilla-central/source/storage/src/mozStoragePrivateHelpers.cpp#69 is unfortunately SQLITE_ERROR ( = 1) which is some kind of catch-all error in sqlite.

I'm doing a debug build to backtrace from here.

Comment 13

[[:fabrice] Fabrice Desré]

Here's a backtrace:

(gdb) bt
#0  0x82b89574 in mozilla::storage::convertResultCode (aSQLiteResultCode=<value optimized out>) at /home/fabrice/dev/b2g/inbound/storage/src/mozStoragePrivateHelpers.cpp:77
#1  0x82b7d860 in mozilla::storage::Connection::ExecuteSimpleSQL (this=<value optimized out>, aSQLStatement=<value optimized out>)
    at /home/fabrice/dev/b2g/inbound/storage/src/mozStorageConnection.cpp:1222
#2  0x827f814a in mozilla::dom::indexedDB::FileManager::Init (this=<value optimized out>, aDirectory=0x41a45230, aConnection=0x435cf470)
    at /home/fabrice/dev/b2g/inbound/dom/indexedDB/FileManager.cpp:96
#3  0x82818e34 in mozilla::dom::indexedDB::IndexedDatabaseManager::EnsureOriginIsInitialized (this=<value optimized out>, aOrigin=<value optimized out>, 
    aDirectory=<value optimized out>) at /home/fabrice/dev/b2g/inbound/dom/indexedDB/IndexedDatabaseManager.cpp:761
#4  0x82821902 in mozilla::dom::indexedDB::OpenDatabaseHelper::DoDatabaseWork (this=0x40311c10) at /home/fabrice/dev/b2g/inbound/dom/indexedDB/OpenDatabaseHelper.cpp:1625
#5  0x82822f12 in mozilla::dom::indexedDB::OpenDatabaseHelper::Run (this=0x40311c10) at /home/fabrice/dev/b2g/inbound/dom/indexedDB/OpenDatabaseHelper.cpp:2036
#6  0x82db7430 in nsThread::ProcessNextEvent (this=0x43c01680, mayWait=<value optimized out>, result=0x4439fe7f) at /home/fabrice/dev/b2g/inbound/xpcom/threads/nsThread.cpp:657
#7  0x82d814ee in NS_ProcessNextEvent_P (thread=0x43c01680, mayWait=true) at /home/fabrice/dev/b2g/inbound/objdir-prof-gonk/xpcom/build/nsThreadUtils.cpp:245
#8  0x82db79ae in nsThread::ThreadFunc (arg=<value optimized out>) at /home/fabrice/dev/b2g/inbound/xpcom/threads/nsThread.cpp:289
#9  0x8011d0b8 in _pt_root (arg=<value optimized out>) at /home/fabrice/dev/b2g/inbound/nsprpub/pr/src/pthreads/ptthread.c:187
#10 0xafd11c38 in __thread_entry (func=0x8011d051 <_pt_root>, arg=0x435cf240, tls=<value optimized out>) at bionic/libc/bionic/pthread.c:213
#11 0xafd117ec in pthread_create (thread_out=<value optimized out>, attr=0xbee7b384, start_routine=0x8011d051 <_pt_root>, arg=<value optimized out>)
    at bionic/libc/bionic/pthread.c:349
#12 0x00000000 in ?? ()

Comment 14

[[:fabrice] Fabrice Desré]

ignore the previous backtrace, it's not where we crash.

Comment 15

[[:fabrice] Fabrice Desré]

hm, actually this was the good stack, breaking when we hit SQLITE_ERROR:

#0  mozilla::storage::convertResultCode (aSQLiteResultCode=1148474480) at /home/fabrice/dev/b2g/inbound/storage/src/mozStoragePrivateHelpers.cpp:82
#1  0x82b7d4e0 in mozilla::storage::Connection::ExecuteSimpleSQL (this=<value optimized out>, aSQLStatement=<value optimized out>)
    at /home/fabrice/dev/b2g/inbound/storage/src/mozStorageConnection.cpp:1222
#2  0x827f7d32 in mozilla::dom::indexedDB::FileManager::Init (this=<value optimized out>, aDirectory=0x41b9d110, aConnection=0x43e6d390)
    at /home/fabrice/dev/b2g/inbound/dom/indexedDB/FileManager.cpp:96
#3  0x82818a1c in mozilla::dom::indexedDB::IndexedDatabaseManager::EnsureOriginIsInitialized (this=<value optimized out>, aOrigin=<value optimized out>, 
    aDirectory=<value optimized out>) at /home/fabrice/dev/b2g/inbound/dom/indexedDB/IndexedDatabaseManager.cpp:761
#4  0x828214ea in mozilla::dom::indexedDB::OpenDatabaseHelper::DoDatabaseWork (this=0x40411790) at /home/fabrice/dev/b2g/inbound/dom/indexedDB/OpenDatabaseHelper.cpp:1625
#5  0x82822afa in mozilla::dom::indexedDB::OpenDatabaseHelper::Run (this=0x40411790) at /home/fabrice/dev/b2g/inbound/dom/indexedDB/OpenDatabaseHelper.cpp:2036
#6  0x82db7088 in nsThread::ProcessNextEvent (this=0x41cf1380, mayWait=<value optimized out>, result=0x44745e7f) at /home/fabrice/dev/b2g/inbound/xpcom/threads/nsThread.cpp:657
#7  0x82d81146 in NS_ProcessNextEvent_P (thread=0x41cf1380, mayWait=true) at /home/fabrice/dev/b2g/inbound/objdir-prof-gonk/xpcom/build/nsThreadUtils.cpp:245
#8  0x82db7606 in nsThread::ThreadFunc (arg=<value optimized out>) at /home/fabrice/dev/b2g/inbound/xpcom/threads/nsThread.cpp:289
#9  0x8011d0b8 in _pt_root (arg=<value optimized out>) at /home/fabrice/dev/b2g/inbound/nsprpub/pr/src/pthreads/ptthread.c:187
#10 0xafd11c38 in __thread_entry (func=0x8011d051 <_pt_root>, arg=0x43e6d160, tls=<value optimized out>) at bionic/libc/bionic/pthread.c:213
#11 0xafd117ec in pthread_create (thread_out=<value optimized out>, attr=0xbea4f384, start_routine=0x8011d051 <_pt_root>, arg=<value optimized out>)
    at bionic/libc/bionic/pthread.c:349
#12 0x80118b32 in PR_Unlock (lock=0x4040c740) at /home/fabrice/dev/b2g/inbound/nsprpub/pr/src/pthreads/ptsynch.c:237
#13 0x82d83358 in mozilla::BlockingResourceBase::CheckAcquire (this=<value optimized out>, aCallContext=...)
    at /home/fabrice/dev/b2g/inbound/objdir-prof-gonk/xpcom/build/BlockingResourceBase.cpp:161

The SQL query that fails in Connection::ExecuteSimpleSQL is:
CREATE VIRTUAL TABLE fs USING filesystem;

Comment 16

[[:fabrice] Fabrice Desré]

I traced the error in sqlite at:
http://mxr.mozilla.org/mozilla-central/source/db/sqlite3/src/sqlite3.c#90722
that calls into
http://mxr.mozilla.org/mozilla-central/source/db/sqlite3/src/sqlite3.c#94079
the sqlite3RunParser() method returns the following error message:
"table fs already exists"

Comment 17

[Ben Turner (not reading bugmail, use the needinfo flag!)]

I have an experiment to try. Please change 'fs' here:

https://mxr.mozilla.org/mozilla-central/source/storage/src/FileSystemModule.cpp#147

to something unlikely to conflict, something like 'moz_filesystem_virtual_table'.

Then see if this still happens? My bet is that it does, because there's no reason this should be specific to the akami. Worth a shot though.

I'll be back on Monday and can really dive in then.

Comment 18

[[:fabrice] Fabrice Desré]

Ben, the query that fails is "CREATE VIRTUAL TABLE fs USING filesystem;", from
http://mxr.mozilla.org/mozilla-central/source/dom/indexedDB/FileManager.cpp#97

Comment 19

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to Fabrice Desré [:fabrice] from comment #18)
> Ben, the query that fails is "CREATE VIRTUAL TABLE fs USING filesystem;",
> from
> http://mxr.mozilla.org/mozilla-central/source/dom/indexedDB/FileManager.
> cpp#97

Yes. Presumably it conflicts with the table name I suggested to change in comment 17.

Comment 20

[[:fabrice] Fabrice Desré]

I can also reproduce the bug with fennec native running on an akami.

Comment 21

[[:fabrice] Fabrice Desré]

So we hit a yaffs2 bug in readdir looping endlessly. There's a patch proposed at http://www.aleph1.co.uk/lurker/message/20081104.222059.30cf53c4.nl.html that is not applied to our yaffs2 source tree. I'm building with it applied now.

Comment 22

[[:fabrice] Fabrice Desré]

Applying the patch at http://www.aleph1.co.uk/lurker/message/20081104.222059.30cf53c4.nl.html to boot/msm/fs/yaffs2/yaffs_vfs.c fixes the problem!

Comment 23

[[:fabrice] Fabrice Desré]

fixed by https://github.com/andreasgal/B2G/commit/d8ef06a01536704d86bd5aac0a0be120df3ebe37