1490848 - Firefox stuck spinning on "NOT NULL constraint failed: moz_annos.place_id"

Status: RESOLVED FIXED

(Toolkit :: Places, defect, P1)

Description

[Stephan Sokolow]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0
Build ID: 20180906162647

Steps to reproduce:

Uncertain.

I was just browsing normally and then noticed that, for no apparent reason, Firefox was misbehaving.


Actual results:

I noticed that Firefox had started to take multiple seconds to respond to input and the chrome process was taking up 100% of one of my CPU cores.

I slogged my way to the Browser Console and found it producing this error message over and over again, as quickly as it could:

Error: "Error(s) encountered during statement execution: NOT NULL constraint failed: moz_annos.place_id"
	handleCompletion resource://gre/modules/Sqlite.jsm:822:25
executeTransaction/this._transactionQueue< resource://gre/modules/Sqlite.jsm:660:52


Expected results:

The browser shouldn't have brought itself to its knees retrying a broken SQL statement.

Comment 1

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

(In reply to Stephan Sokolow from comment #0)
> I slogged my way to the Browser Console and found it producing this error
> message over and over again, as quickly as it could:
> 
> Error: "Error(s) encountered during statement execution: NOT NULL constraint
> failed: moz_annos.place_id"
> 	handleCompletion resource://gre/modules/Sqlite.jsm:822:25
> executeTransaction/this._transactionQueue<
> resource://gre/modules/Sqlite.jsm:660:52

The strangest thing is that this should just fail, but should not really cause an hang, at a maximum some part of the ui would be broken/not responding, but the rest of the ui should work normally.

It could be the new code inserting annotations through history from bug 1468980. It doesn't seem to do any check that place exists, and indeed the query fails if update is invoked wrongly. Unfortunately I don't see a stack in the above report, thus I'm not sure who is calling into this with bogus data.
Though I can't find a loop that may be causing this continuously.

This must be investigated, for sure the query is wrong, because it doesn't check for place validity before trying the insert.
We must also check the consumers, because they should not try to do that.
And we should try to inderstand this apparent loop.

Were you downloading, or did you start a download when this happened?

Comment 2

[Sylvestre Ledru [:Sylvestre]]

[Tracking Requested - why for this release]:
As Marco marked this as a P1, we probably want to monitor that for 63.

Comment 3

[Stephan Sokolow]

(In reply to Marco Bonardo [::mak] from comment #1)
> Were you downloading, or did you start a download when this happened?

It's entirely possible, but I don't clearly remember.

I often trigger the WebScrapbook extension after I finish reading something, which saves the current page and all subresources it depends on to disk (by firing off what is often hundreds of download API calls and then removing all but the root page from the download history once the process completes) but it's such a routine thing that I don't remember whether I'd done it around the time I noticed the problem.

Comment 4

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

ah that's likely, the downloads API indeed goes through this code

Comment 5

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

another question, do you use permanent private browsing (history disabled), or do you remember if you were in private browsing mode when this happened?

Comment 6

[Mike de Boer [:mikedeboer]]

Since this bug is tracked for 63, assigning to Marco for the time being.

Comment 7

[Stephan Sokolow]

(In reply to Marco Bonardo [::mak] from comment #5)
> another question, do you use permanent private browsing (history disabled),
> or do you remember if you were in private browsing mode when this happened?

I don't use permanent private browsing. As for the second question, the answer is again "Probably. It's too routine for me to remember clearly."

That said, your question prompted me to do some testing which led me to a relevant observation and a surprisingly simple reproducer:

First, I opened the browser console and noticed that it had happened again but then stopped on its own. Given that I've got a tab which is auto-reloaded by a userscript every hour, I know it happened less than an hour ago because there was no GOG.com "Developer? Here's our jobs link" message after it in the log, but the lack of timestamps in the browser console means I don't know whether it happened before or after I woke up and started opening links from RSS feeds.

Second, I managed to distill down a surprisingly simple reproducer:

1. Install Firefox Nightly and create a fresh profile
   (I used 64.0a1 (2018-09-13) (64-bit) on Kubuntu Linux 14.04.5 LTS 64-bit, if it becomes relevant)
2. Install the Web ScrapBook extension from 
   https://addons.mozilla.org/en-US/firefox/addon/web-scrapbook/
3. Visit a webpage (I tested on http://blog.ssokolow.com/ in both regular and private browsing windows)
4. Select `Web ScrapBook > Capture Page` from the context menu

If you want a flood of errors rather than just one, open up Web ScrapBook's options, set these two options and save a page with a lot of subresources:

Save captured data as: Folder
[X] Save captured data in ScrapBook

Given that I don't remember these errors happening when I first installed Web ScrapBook, I'd say that's pretty conclusive proof that it's a regression.

Comment 8

[Stephan Sokolow]

Oh, it got lost in the editing of that post, but I meant to say that the reoccurrence and the reproducer stopped on their own, so they're only partial reproducers.

That said, they do reproduce the NOT NULL constraint failure.

Comment 9

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

thanks, this is very useful.

Comment 10

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Attachment: Bug 1490848 - Constraint failed errors when trying to download urls not present in history. r=standard8

Comment 11

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

I honestly have no idea where we could have looped, I don't see any specific reasons for a loop here, and as such I'm assuming it was just slow due to many requests and some main-thread I/O at the "wrong" time. Since main-thread I/O is unpredictable (can last 1s or minutes), that is a possibility.
Additionally dumping console errors can slow down things a bit.

What I'm fixing here is the clear cause for the error, we try to store data for an entry that doesn't exist, either because history is disabled/private, the url can't be stored, or history has been recently cleared.
I couldn't find things that may cause a loop though. I just noticed the add-on can cause a lot of requests to start at once on very complex pages.

If you can reproduce the hang "at will", it may be interesting to catch a performance profile:
https://developer.mozilla.org/docs/Mozilla/Performance/Reporting_a_Performance_Problem

Comment 12

[Stephan Sokolow]

Based on what I was doing at the time, I think the hang may have just been because I left the browser console open and the flood of messages was triggering another bug I reported after this one. Bug 1490880. (Browser Console locks up the browser under heavy load)

I haven't had time to confirm, but I get the impression that the browser bogs down proportional to the length of the browser console's scrollback buffer.

Comment 13

[Mark Banner (:standard8)]

Comment on attachment 9011462 [details]
Bug 1490848 - Constraint failed errors when trying to download urls not present in history. r=standard8

Mark Banner (:standard8) has approved the revision.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/daa8803c67e4
Constraint failed errors when trying to download urls not present in history. r=Standard8

Comment 15

[Eliza Balazs [:ebalazs_]]

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

Comment 16

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Comment on attachment 9011462 [details]
Bug 1490848 - Constraint failed errors when trying to download urls not present in history. r=standard8

Approval Request Comment
[Feature/Bug causing the regression]: bug 1468980 
[User impact if declined]: Downloads API may cause a waterfall of errors in the console, and slow down the browser by doing that
[Is this code covered by automated tests?]: yes
[Has the fix been verified in Nightly?]: not yet
[Needs manual test from QE? If yes, steps to reproduce]: not strictly necessary, but eventually STR are in comment 7
[List of other uplifts needed for the feature/fix]: none
[Is the change risky?]: no
[Why is the change risky/not risky?]: trivial change
[String changes made/needed]: none

Comment 17

[Pascal Chevrel:pascalc (PTO until April 26)]

Comment on attachment 9011462 [details]
Bug 1490848 - Constraint failed errors when trying to download urls not present in history. r=standard8

P1 tracked for 63, uplift approved for 63 beta 10, thanks.

Comment 18

[Dorel Luca [:dluca]]

https://hg.mozilla.org/releases/mozilla-beta/rev/db44e1bed0c6