Closed Bug 966143 Opened 6 years ago Closed 6 years ago

Crash in org.mozilla.gecko.sqlite.SQLiteBridgeException: Can't step statement: (19) NOT NULL constraint failed: moz_logins.usernameField

Categories

(Firefox for Android :: Android Sync, defect, critical)

Firefox 29
All
Android
defect
Not set
critical

Tracking

()

VERIFIED FIXED
Firefox 30
Tracking Status
firefox27 --- wontfix
firefox28 --- affected
firefox29 --- fixed
firefox30 --- fixed
fennec 29+ ---

People

(Reporter: strugee, Assigned: rnewman)

References

Details

(Keywords: crash)

Attachments

(4 files)

A short while after I open Firefox for Android, it crashes. I can discern no real pattern to the crashes, although I frequently open chat.stackexchange.com from the top sites list when I start the browser, so that _may_ be a trigger. (If needed I'll do further testing of this.) Crashes usually happen within 1-2 minutes, AFAICT, but sometimes Nightly lasts up to five minutes. I've been seeing this issue for slightly less than a week. The crash happens regardless of whether Nightly is in the background or the foreground.

The crash is caught by the Android crash service, but Nightly's built-in crash reporter isn't triggered. If that's a separate issue, I can file another bug. Crash reports are never sent due to the Mozilla crash dialog not triggering, along with Android not offering a crash report dialog (because the app isn't from the Play Store).

I'm running a the latest Nightly build (2014-01-30, 73eefb). AFAIK, there isn't any setting that should be interfering with Nightly. I'm using a CDMA Galaxy Nexus running CyanogenMod 10.2.0-toro, based on Android 4.3.1, flashed with gapps. I have not tried to reproduce this crash in Android's Safe Mode. I have no extensions installed.

If needed, I can provide dumps of information from adb. I am also willing to run Nightly with debug symbols and a debugger attached. I'm also comfortable with the concept of regression testing and am willing to find a regression range (although I've never done this in practice before).
Are you using Sync alongside Master Password?
I have Sync enabled, but not Master Password (at least on Android - on desktop, I use either the master password or a GNOME Keyring integration extension).
Can you attach a log-cat from your device when capturing your attempt to launch the browser and attach it to this bug?

Despite you not using master password on android, it does still sound a bit like bug 961895.
Attached file adb logcat
This is the output from adb logcat. The log was done with a fresh boot, no other apps opened except for the Google Play Music app (which opened automatically due to the headphones being in). I opened Nightly, waited for the top sites list to populate, tapped on chat.stackexchange.com, dismissed the keyboard and waited. The log was terminated shortly after Nightly crashed.
This is excellent thanks for the log. This is very interesting

E/GeckPasswordsProvider( 4888): Error updating table
E/GeckPasswordsProvider( 4888): org.mozilla.gecko.sqlite.SQLiteBridgeException: Can't step statement: (19) NOT NULL constraint failed: moz_logins.usernameField
E/GeckPasswordsProvider( 4888): 
E/GeckPasswordsProvider( 4888): 	at org.mozilla.gecko.sqlite.SQLiteBridge.sqliteCallWithDb(Native Method)
E/GeckPasswordsProvider( 4888): 	at org.mozilla.gecko.sqlite.SQLiteBridge.internalQuery(SQLiteBridge.java:235)
E/GeckPasswordsProvider( 4888): 	at org.mozilla.gecko.sqlite.SQLiteBridge.update(SQLiteBridge.java:211)
E/GeckPasswordsProvider( 4888): 	at org.mozilla.gecko.db.SQLiteBridgeContentProvider.update(SQLiteBridgeContentProvider.java:352)
E/GeckPasswordsProvider( 4888): 	at android.content.ContentProvider$Transport.update(ContentProvider.java:260)
E/GeckPasswordsProvider( 4888): 	at android.content.ContentProviderNative.onTransact(ContentProviderNative.java:217)
E/GeckPasswordsProvider( 4888): 	at android.os.Binder.execTransact(Binder.java:388)
E/GeckPasswordsProvider( 4888): 	at dalvik.system.NativeStart.run(Native Method)
E/JavaBinder( 4888): *** Uncaught remote exception!  (Exceptions are not yet supported across processes.)
Severity: normal → critical
Status: UNCONFIRMED → NEW
tracking-fennec: --- → ?
Component: General → Data Providers
Ever confirmed: true
Keywords: crash
Summary: Firefox for Android crashes a short time after startup with no crash dialog → Crash in org.mozilla.gecko.sqlite.SQLiteBridgeException: Can't step statement: (19) NOT NULL constraint failed: moz_logins.usernameField
Flags: needinfo?(rnewman)
(In reply to Alex Jordan [:strugee] from comment #2)
> I have Sync enabled, but not Master Password (at least on Android - on
> desktop, I use either the master password or a GNOME Keyring integration
> extension).

Just to double check: are you using Sync (the pairing-based one), or have you set up a Firefox account (with the pretty setup screens and the email-and-password login flow)?

I ask because you're using Nightly, so it's possible that you're using the pre-release version.

If you've been using Sync for more than a week or so, then you fall into the former camp automatically.


Hypothesis so far: data got into the DB that was missing a username, and now Sync is unable to update that row in the DB because sqlite refuses to step to that row. This will crash every time because the sync doesn't complete, so it'll try again, and nothing will have changed.
Flags: needinfo?(rnewman) → needinfo?(alexander3223098)
(In reply to Richard Newman [:rnewman] from comment #6) 
> Just to double check: are you using Sync (the pairing-based one), or have
> you set up a Firefox account (with the pretty setup screens and the
> email-and-password login flow)?
I'm using Sync. I've been using it since Weave.
I _had_ recently noticed that the Firefox Sync entry in the Setting app gained a "(deprecated)" suffix. I guess Sync is going away, then?
Flags: needinfo?(alexander3223098)
(In reply to Alex Jordan [:strugee] from comment #7)

> I _had_ recently noticed that the Firefox Sync entry in the Setting app
> gained a "(deprecated)" suffix. I guess Sync is going away, then?

Nope, just evolving.
So... the root cause here is that a password got into your password DB without a username. An empty username isn't uncommon, but a null username is unexpected.

If this is on your desktop, too, that's pretty easy to find out. Open a Browser Console, and evaluate the following:


Cu.import("resource://services-sync/util.js");
let logins = Services.logins.getAllLogins();
for (let i = 0; i < logins.length; ++i) {
  let login = logins[i];
  if (login.username === null) {
    console.log("FOUND: " + login.QueryInterface(Ci.nsILoginMetaInfo).guid + ": " + login.hostname);
  }
}

Run that, see if it spits anything out.
Flags: needinfo?(alexander3223098)
(In reply to Richard Newman [:rnewman] from comment #8)
> (In reply to Alex Jordan [:strugee] from comment #7)
> 
> > I _had_ recently noticed that the Firefox Sync entry in the Setting app
> > gained a "(deprecated)" suffix. I guess Sync is going away, then?
> 
> Nope, just evolving.

I meant the current, key-based form of Sync. Not Sync in general.

(In reply to Richard Newman [:rnewman] from comment #9)
> So... the root cause here is that a password got into your password DB
> without a username. An empty username isn't uncommon, but a null username is
> unexpected.
> 
> If this is on your desktop, too, that's pretty easy to find out. Open a
> Browser Console, and evaluate the following:
> 
> 
> Cu.import("resource://services-sync/util.js");
> let logins = Services.logins.getAllLogins();
> for (let i = 0; i < logins.length; ++i) {
>   let login = logins[i];
>   if (login.username === null) {
>     console.log("FOUND: " + login.QueryInterface(Ci.nsILoginMetaInfo).guid +
> ": " + login.hostname);
>   }
> }
> 
> Run that, see if it spits anything out.

This returns "[object BackstagePass]". I have JS logging turned on.
Flags: needinfo?(alexander3223098)
> This returns "[object BackstagePass]". I have JS logging turned on.

OK, so nothing logged. Humph.
Alex: some further debugging, if you're willing.

  adb shell setprop log.tag.FxSync VERBOSE
  adb shell setprop log.tag.RepoUtils VERBOSE
  adb shell setprop log.tag.PasswordsRepoSession VERBOSE
  adb shell setprop log.tag.PasswordRecord VERBOSE
  adb shell setprop log.tag.GeckPasswordsProvider VERBOSE
  adb shell setprop log.tag.SQLiteDatabase VERBOSE
  adb shell setprop log.tag.Database VERBOSE

Then "Force Stop" Nightly, and trigger another sync. Grab adb logs while you do so, from the start of the sync through to just after the crash.

This shouldn't log anything really personally identifiable, but please skim the log to make sure it doesn't contain anything you don't want me to see, and then email it to me.

When you're done with the debugging process, you can re-run those setprop commands substituting "DEBUG" for "VERBOSE" to avoid spamming your log.

Thanks!
Flags: needinfo?(alexander3223098)
This is a dump of adb logcat after running setprop foobar VERBOSE. I'll do a run with DEBUG in just a minute.
Test conditions were the same: fresh reboot (to minimize the possible programs spewing **** into the log), open Nightly, wait for initialization and then tap on StackExchange chat. I've clipped the log to when Fennec started.
Flags: needinfo?(alexander3223098)
Output of adb logcat with setprop foobar DEBUG. Same test conditions (second reboot), and again with the log clipped.
I should mention that I'm now on a CyanogenMod 11 Milestone Snapshot (based on Android 4.4) from January 4th, in case that affects compatibility or something. I'm also on the latest Nightly as of today.
Attachment #8369013 - Attachment mime type: text/plain → text/x-log
(In reply to Richard Newman [:rnewman] from comment #12)
>   adb shell setprop log.tag.GeckPasswordsProvider VERBOSE
I'm assuming this wasn't a typo, and you meant GeckPasswordsProvider, and not GeckoPasswordsProvider.
(In reply to Alex Jordan [:strugee] from comment #15)

> I'm assuming this wasn't a typo, and you meant GeckPasswordsProvider, and
> not GeckoPasswordsProvider.

Correct. (It might well have been a typo in the original source, though!)
Well, that'll do it.

V/FxSync  ( 6595): fennec :: RepositorySession :: Incoming record {00bcf15b-4a96-564b-8a58-f55224cba75c} dupes to local record {00bcf15b-4a96-564b-8a58-f55224cba75c}
D/FxSync  ( 6595): fennec :: PasswordsRepoSession :: remote {00bcf15b-4a96-564b-8a58-f55224cba75c} dupes to {00bcf15b-4a96-564b-8a58-f55224cba75c}
D/FxSync  ( 6595): fennec :: RepositorySession :: Reconciling remote {00bcf15b-4a96-564b-8a58-f55224cba75c} against local {00bcf15b-4a96-564b-8a58-f55224cba75c}
D/FxSync  ( 6595): fennec :: PasswordRecord :: thisRecord:PasswordRecord {lastModified: 1389587631869, hostname null?: false, formSubmitURL null?: true, httpRealm null?: false, usernameField null?: false, passwordField null?: false, encryptedUsername null?: false, encryptedPassword null?: false, encType: 1, timeCreated: 1389587631870, timeLastUsed: 0, timePasswordChanged: 1389587631869, timesUsed: 0
D/FxSync  ( 6595): fennec :: PasswordRecord :: otherRecord:PasswordRecord {lastModified: 1390721910940, hostname null?: false, formSubmitURL null?: true, httpRealm null?: false, usernameField null?: true, passwordField null?: true, encryptedUsername null?: false, encryptedPassword null?: false, encType: null, timeCreated: 0, timeLastUsed: 0, timePasswordChanged: 0, timesUsed: 0
D/FxSync  ( 6595): fennec :: PasswordRecord :: super.equalPayloads returned false.
D/FxSync  ( 6595): fennec :: RepositorySession :: Local record is more recent? false
D/FxSync  ( 6595): fennec :: PasswordsRepoSession :: Replacing {00bcf15b-4a96-564b-8a58-f55224cba75c} with record {00bcf15b-4a96-564b-8a58-f55224cba75c}


Note how the local record has no formSubmitURL, username, password, or times. It does claim to have encryptedUsername and encryptedPassword, but an encType of null.

So two speculations:

* Those fields are actually null in the DB.
* The DB is encrypted with a Master Password, or is failing to be decrypted with the default empty password, and so we're getting junk.

Assuming you indeed don't have a MP set up per Comment 2, that narrows things down some.
Assignee: nobody → rnewman
tracking-fennec: ? → 29+
It only occurs to me now to mention that I use my Sync profile with a mix of the stable channel and the nightly channel. That's probably a terrible idea, but it's how I have things set up.
Could this have caused the corruption seen here?
I don't think that's all that unusual among Firefox devs at least.
Richard, is there something that I can do to preserve the testcase profile while still being able to test Nightly? I'd reinstall to get rid of the crash but it'd destroy the change of tracking this down.
Flags: needinfo?(rnewman)
Alex: you could install Copy Profile:

https://addons.mozilla.org/en-US/android/addon/copy-profile/

and copy your profile to the SD card. You can grab the output with `adb pull`.
Flags: needinfo?(rnewman)
(In reply to Richard Newman [:rnewman] from comment #17)

> Note how the local record has no formSubmitURL, username, password, or
> times. It does claim to have encryptedUsername and encryptedPassword, but an
> encType of null.

I misspoke. The local record is the one that's valid. Which makes this a much more tractable problem: we should never try to insert/update an invalid record.

That leads to two work items: Sync should validate, and so should the Passwords provider.
Attached file Trivial fix.
Attachment #8385650 - Flags: review?(nalexander)
Attachment #8385650 - Flags: review?(nalexander) → review+
https://hg.mozilla.org/integration/fx-team/rev/b7858028c781
Status: NEW → ASSIGNED
Component: Data Providers → Android Sync
Product: Firefox for Android → Android Background Services
Hardware: ARM → All
Target Milestone: --- → Firefox 30
Version: Trunk → Firefox 29
Flags: needinfo?(rnewman)
https://hg.mozilla.org/mozilla-central/rev/b7858028c781
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
I can confirm that updating to a recent Nightly fixes this crash for me. Marking VERIFIED.
Status: RESOLVED → VERIFIED
Comment on attachment 8385650 [details] [review]
Trivial fix.

Thanks, Alex!

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
  Unclear/long-standing.

User impact if declined: 
  Affected users -- those with malformed password records on their Sync server -- will be unable to successfully sync, and Fennec will visibly crash.

Testing completed (on m-c, etc.): 
  Verified by original reporter.

Risk to taking this patch (and alternatives if risky): 
  Very slim. Additional validation only.

String or IDL/UUID changes made by this patch:
  None.
Attachment #8385650 - Flags: approval-mozilla-beta?
Attachment #8385650 - Flags: approval-mozilla-aurora?
Flags: needinfo?(rnewman)
Attachment #8385650 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Comment on attachment 8385650 [details] [review]
Trivial fix.

At this stage, we're about to go to final beta and this bug is neither tracked nor high volume or sec-critical so we'll wait and let this ride from FF29.
Attachment #8385650 - Flags: approval-mozilla-beta? → approval-mozilla-beta-
Duplicate of this bug: 989398
Product: Android Background Services → Firefox for Android
You need to log in before you can comment on or make changes to this bug.