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

Status: VERIFIED FIXED

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

Description

[AJ Jordan [:strugee] (he/they)]

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).

Comment 1

[Aaron Train [:aaronmt]]

Are you using Sync alongside Master Password?

Comment 2

[AJ Jordan [:strugee] (he/they)]

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).

Comment 3

[Aaron Train [:aaronmt]]

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.

Comment 4

[AJ Jordan [:strugee] (he/they)]

Attachment: 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.

Comment 5

[Aaron Train [:aaronmt]]

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.)

Comment 6

[Richard Newman [: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.

Comment 7

[AJ Jordan [:strugee] (he/they)]

(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?

Comment 8

[Richard Newman [:rnewman]]

(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.

Comment 9

[Richard Newman [:rnewman]]

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.

Comment 10

[AJ Jordan [:strugee] (he/they)]

(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.

Comment 11

[Richard Newman [:rnewman]]

> This returns "[object BackstagePass]". I have JS logging turned on.

OK, so nothing logged. Humph.

Comment 12

[Richard Newman [:rnewman]]

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!

Comment 13

[AJ Jordan [:strugee] (he/they)]

Attachment: adb logcat with setprop foobar VERBOSE

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.

Comment 14

[AJ Jordan [:strugee] (he/they)]

Attachment: adb logcat with setprop foobar DEBUG

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.

Comment 15

[AJ Jordan [:strugee] (he/they)]

(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.

Comment 16

[Richard Newman [:rnewman]]

(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!)

Comment 17

[Richard Newman [:rnewman]]

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.

Comment 18

[AJ Jordan [:strugee] (he/they)]

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?

Comment 19

[Gian-Carlo Pascutto [:gcp]]

I don't think that's all that unusual among Firefox devs at least.

Comment 20

[AJ Jordan [:strugee] (he/they)]

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.

Comment 21

[Richard Newman [: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`.

Comment 22

[Richard Newman [: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.

Comment 23

[Richard Newman [:rnewman]]

Attachment: Trivial fix.

Comment 24

[Richard Newman [:rnewman]]

https://hg.mozilla.org/integration/fx-team/rev/b7858028c781

Comment 25

[Tim Taubert [:ttaubert] (inactive)]

https://hg.mozilla.org/mozilla-central/rev/b7858028c781

Comment 26

[AJ Jordan [:strugee] (he/they)]

I can confirm that updating to a recent Nightly fixes this crash for me. Marking VERIFIED.

Comment 27

[Richard Newman [:rnewman]]

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.

Comment 28

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/c07438fae168

Comment 29

[Lukas Blakk [:lsblakk] use ?needinfo]

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.