1365601 - Crash in nsPrintEngine::GetSeqFrameAndCountPagesInternal while switching from Landscape to Portrait mode or clicking rapidly the Simplify page button

Status: VERIFIED FIXED

(Toolkit :: Printing, defect)

Description

[Ciprian Georgiu, Desktop QA]

This bug was filed from the Socorro interface and is 
report bp-ef9f71c6-6e61-4b21-b964-2ca230170515.
=============================================================
[Affected versions]:
- latest Nightly 55.0a1

[Affected platforms]:
- Windows 10 x64
- Windows 7 x64

[Steps to reproduce]:
1. Start Firefox on a fresh profile.
2. Go to: https://en.wikipedia.org/wiki/Main_Page 
3. Enable Print Preview (File -> Print Preview)
4. Click rapidly for a few times on the Simplify Page button

[Expected result]:
- The page is properly switched from Print Preview to Simplify page mode with no issues

[Actual result]:
- After step 4 the tab crashes

[Regression range]:
- This seems to be a regression as I cannot reproduce this crash on Nightly 50.a01 (2016-06-06) where this feature first landed. I will try to follow up with a regression range asap.

[Additional notes]:
- I was able to reproduce this in ~ 7 out of 10 cases, but please note that different behaviors can be observed when the tab is not crashing after step 4. In those cases where it did not crashed, Simplify page displayed 2 about:printpreview pages as you can see here: http://imgur.com/a/6kZlv. Also, another behavior encountered is this error ”An error occurred while printing” - please see here the screenshot: http://imgur.com/a/3f8aE.
- This is not repro in Print preview mode using same STR
- Another STR (as I said in the Summary) would be to enter in Simplify mode and to switch rapidly between Landscape and Portrait mode for a few seconds (~5 seconds)
- Ubuntu is unaffected and the transition seems very smooth compared to Windows

Comment 1

[Ciprian Georgiu, Desktop QA]

Attachment: crash Simplify page.gif

Here you can see a .gif with this issue.

Comment 2

[Matheus Longaray (:mlongaray)]

Possible duplicate of bug 1346873? Same about:crash page, and or behavior when toggling options very quick on preview. Can you take a look at bug 1346873 as well, Ciprian?

Comment 3

[Ciprian Georgiu, Desktop QA]

(In reply to Matheus Longaray (:mlongaray) from comment #2)
> Possible duplicate of bug 1346873? Same about:crash page, and or behavior
> when toggling options very quick on preview. Can you take a look at bug
> 1346873 as well, Ciprian?

It seems very intermittent on my Win 10 machine, but I was able to reproduce the crash one or twice in Print Preview as well, when toggling rapidly the Landscape/Portrait mode.

> [Additional notes]:
> - I was able to reproduce this in ~ 7 out of 10 cases, but please note that
> different behaviors can be observed when the tab is not crashing after step
> 4. In those cases where it did not crashed, Simplify page displayed 2
> about:printpreview pages as you can see here: http://imgur.com/a/6kZlv.
> Also, another behavior encountered is this error ”An error occurred while
> printing” - please see here the screenshot: http://imgur.com/a/3f8aE.

I'm wondering if the behaviors (where it did not crashed) mentioned above are having as a root cause this crashes. Do you have any ideas about this, Matheus?

Comment 4

[Matheus Longaray (:mlongaray)]

(In reply to Ciprian Georgiu, QA [:ciprian_georgiu] from comment #3)
> I'm wondering if the behaviors (where it did not crashed) mentioned above
> are having as a root cause this crashes. Do you have any ideas about this,
> Matheus?

Well, we'd have to dig more deep into this, although I do believe the crash signature is the same. Unfortunately, I do not have a Windows environment set up here so I can test myself.

Okay, how are you running Firefox when testing? A downloaded binary or do you have a development environment set? If the latter is true, you could attach _gdb_ to the content process to get a backtrace when/where it goes down.

If you have the time, let's try the following steps:

1> Deactivate e10s and try to reproduce the issue. Let's see what happens.

2> Try to reproduce the issue on Beta (it won't cause a crash there - if I'm not wrong), but you'd be able to see errors on Browser Console. Here's what I did when I filed bug 1346873: https://bugzilla.mozilla.org/show_bug.cgi?id=1346873#c6

Comment 5

[Ciprian Georgiu, Desktop QA]

> If you have the time, let's try the following steps:
> 
> 1> Deactivate e10s and try to reproduce the issue. Let's see what happens.

latest Nightly 55.0a1

- with e10s enable - crash or problems mentioned in [Additional notes]:
     https://crash-stats.mozilla.com/report/index/3d2f64f6-19fd-451e-9477-22ab10170519

- with e10s disable - no crash or other Print preview related issues

> 2> Try to reproduce the issue on Beta (it won't cause a crash there - if I'm
> not wrong), but you'd be able to see errors on Browser Console. Here's what
> I did when I filed bug 1346873:
> https://bugzilla.mozilla.org/show_bug.cgi?id=1346873#c6

latest Beta 54

- with e10s enable - no crash instead I see these errors (as you mentioned, https://bugzilla.mozilla.org/show_bug.cgi?id=1346873#c6) in browser console: "An error occurred while printing"
    [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIWebBrowserPrint.printPreview]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: chrome://global/content/browser-content.js :: enterPrintPreview/< :: line 661" data: no] (unknown)
    NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIWebBrowserPrint.printPreviewNumPages]

- with e10s disable - no crash or other issues related to Print preview

I tested this on my Windows 10 x64 machine and all Firefox x64 builds were downloaded as zip format and opened with a clean profile for each case.(https://archive.mozilla.org/pub/firefox/nightly/latest-mozilla-central/)

Please let me know if I can help with more info!

Comment 6

[Matheus Longaray (:mlongaray)]

Thanks, Ciprian! I can not appreciate that enough :)

It looks like the crash signature is indeed the same from bug 1346873. As per https://crash-stats.mozilla.com/report/index/3d2f64f6-19fd-451e-9477-22ab10170519, we're failing the following diagnostic assertion: https://hg.mozilla.org/mozilla-central/annotate/baf05f61bc14/layout/printing/nsPrintEngine.cpp#l339.

ni?ing mconley and bobowen to see what they think of this.

Comment 7

[Bob Owen (:bobowen)]

Thanks, hopefully this will give me a way to reproduce, so I can investigate further.
Leaving NI for now.

Comment 8

[Mike Conley (:mconley) (:⚙️)]

Sounds like bobowen is on this, so clearing ni?.

Comment 9

[Bob Owen (:bobowen)]

I can reproduce, in fact I've found that I can even with the orientation switching if I use a DEBUG build.
So, this seemed like a timing issue.

I'm pretty sure I've worked out what's going on, although I don't have a solution as yet (so I'll leave the NI to nag me).

When there is some sort of change in the toolbar, we run through the whole print preview process again in the child (but I think with the cloned print preview document a source, so we don't pick up any new changes).

As part of this we swap out the old mPrtPreview at [1] and create a new mPrt just below.
This later gets moved to mPrtPreview at [2].

If the changes are coming fast enough, we end up processing an old request for the number of pages while we spin the event loop during the call to show the print dialog at [3].
(For print preview we don't actually show the print dialog we use this to get the print settings from the printer, which we can't do in the child because of sandboxing.)

When that request is processed at [4], we use the not fully populated mPrt and hit the diagnostic assert on Nightly, elsewhere we return NS_ERROR_FAILURE.
It's possible we could use mOldPrtPreview here instead of mPrt when mPrtPreview is null, but I'm not totally sure that would always be the correct thing because of the rather confusing comment above.
That comment looks like it's been cut off, but as far as I can tell it was always like that.

Ideally we wouldn't make the call at all when the print engine isn't ready.
I'm not quite sure why we don't send up the page count with the Printing:Preview:Entered message, as I assume it can't change until we re-call down into the whole print preview process in the child.

[1] https://hg.mozilla.org/mozilla-central/file/0ed0fd886134/layout/printing/nsPrintEngine.cpp#l432
[2] https://hg.mozilla.org/mozilla-central/file/0ed0fd886134/layout/printing/nsPrintEngine.cpp#l3622
[3] https://hg.mozilla.org/mozilla-central/file/0ed0fd886134/layout/printing/nsPrintEngine.cpp#l621
[4] https://hg.mozilla.org/mozilla-central/file/0ed0fd886134/layout/printing/nsPrintEngine.cpp#l889

Comment 10

[Matheus Longaray (:mlongaray)]

What a great analysis, bobowen!

(In reply to Bob Owen (:bobowen) from comment #9)
> It's possible we could use mOldPrtPreview here instead of mPrt when
> mPrtPreview is null, but I'm not totally sure that would always be the
> correct thing because of the rather confusing comment above.
> That comment looks like it's been cut off, but as far as I can tell it was
> always like that.

Yep, I think that comment was always like that indeed. I've tracked down where this comment was first introduced.

Revision: https://hg.mozilla.org/mozilla-central/rev/84317c2f199c (bug 468568)

Maybe https://bugzilla.mozilla.org/show_bug.cgi?id=468568#c93 and https://bugzilla.mozilla.org/show_bug.cgi?id=468568#c95 can help you figure out what that comment does actually mean.

Comment 11

[Bob Owen (:bobowen)]

(In reply to Bob Owen (:bobowen) from comment #9)
...
> I'm not quite sure why we don't send up the page count with the
> Printing:Preview:Entered message, as I assume it can't change until we
> re-call down into the whole print preview process in the child.

I've had some time to look at this and I think this will work.
I have a patch which I'll post tomorrow.

Comment 12

[Bob Owen (:bobowen)]

(In reply to Bob Owen (:bobowen) from comment #9)
...
> I'm not quite sure why we don't send up the page count with the
> Printing:Preview:Entered message, as I assume it can't change until we
> re-call down into the whole print preview process in the child.

Here's my reasoning as to why this is OK.

The Printing:Preview:UpdatePageCount message is only sent at [1] as part of updateToolbar.

This is called from:
(1) printUtils.js onEntered [2] (the message listener in the parent for Printing:Preview:Entered)
(2) printPreviewBindings.xml initialize at [3] (which is also only called from printUtils.js onEntered [2])
(3) printPreviewBindings.xml doPageSetup at [4]

Any page count consequences of (3), won't actually affect the print preview doc until the call to PrintUtils.printPreview() just afterwards, so the update of the page count that happens in updateToolbar here is potentially wrong and will get updated when PrintUtils.printPreview() finishes in the child and we get the Printing:Preview:Entered message.

So, (1) and (2) are the only real cases we have to worry about and they are both as a result of the Printing:Preview:Entered message.

While writing the above I realised that we have a slight issue with this and the current way things work, if the page has content that has to be downloaded during the print (for example fonts, not sure if there are others).
In this case we end up firing more than one printPreviewUpdate event (which results in the Printing:Preview:Entered message to the parent). We only react to the first of these, because the listener is removed.
However, printPreviewUpdate is only used for this (and not by any addons as far as I can see), so I think we can just change this to fire in FinishPrintPreview.
It probably makes sense to change this event to include an nsresult, so we can use it if we have an error as well.
At the moment I'm not totally sure we would drop out of print preview in some cases, if the error occurs after the first printPreviewUpdate firing.


[1] https://hg.mozilla.org/mozilla-central/file/95543bdc59bd/toolkit/components/printing/content/printPreviewBindings.xml#l393
[2] https://hg.mozilla.org/mozilla-central/file/95543bdc59bd/toolkit/components/printing/content/printUtils.js#l601
[3] https://hg.mozilla.org/mozilla-central/file/95543bdc59bd/toolkit/components/printing/content/printPreviewBindings.xml#l160
[4] https://hg.mozilla.org/mozilla-central/file/95543bdc59bd/toolkit/components/printing/content/printPreviewBindings.xml#l195

Comment 13

[Bob Owen (:bobowen)]

Attachment: Page with font downloads that timeout to demonstrate page count issue.

(In reply to Bob Owen (:bobowen) from comment #12)
...
> While writing the above I realised that we have a slight issue with this and
> the current way things work, if the page has content that has to be
> downloaded during the print (for example fonts, not sure if there are
> others).
> In this case we end up firing more than one printPreviewUpdate event (which
> results in the Printing:Preview:Entered message to the parent). We only
> react to the first of these, because the listener is removed.

Here's a test page that demonstrates this issue.

If you print preview this with A4 paper size and default margins (12.7mm) then this should say 1 page, but after the font download times out it is actually 2 pages.

Comment 15

[Bob Owen (:bobowen)]

Attachment: Part 1: Send number of pages on printPreviewUpdate event instead of requesting from parent

This also makes sure that we don't call nsIWebBrowserPrint::PrintPreview while we're still in a previous call.

Comment 16

[Bob Owen (:bobowen)]

Attachment: Part 2: Disable parts of the Print Preview toolbar until update has finished

This takes things a step further and disables elements in the toolbar that cause processing in the child while another update is already running.
We could just go with part 1, which I think resolves the immediate issues, but I think this might prevent some other low-level crashes/failures as well.

Comment 17

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 8880811 [details] [diff] [review]
Part 1: Send number of pages on printPreviewUpdate event instead of requesting from parent

Review of attachment 8880811 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks! This was a bit tricky to follow, because of the waiting we need to do for those printPreviewUpdate events for the nextUpdate things, but I think I get it.

::: toolkit/content/browser-content.js
@@ +650,5 @@
>          printSettings.docURL = contentWindow.document.baseURI;
>  
>        // The print preview docshell will be in a different TabGroup,
>        // so we run it in a separate runnable to avoid touching a
>        // different TabGroup in our own runnable.

Since we're now separating the definition of printPreviewInitialize from the dispatch, it might make more sense to either:

a) Move the above comment so that it's placed above each point where we do the dispatch

or (maybe preferably)

b) Add some clarification to this comment saying that printPreviewInitialize _must_ be dispatched as a new runnable. I don't know if we can assert that somehow, but that might be nice too.

Comment 18

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 8880812 [details] [diff] [review]
Part 2: Disable parts of the Print Preview toolbar until update has finished

Review of attachment 8880812 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks!

Comment 19

[Bob Owen (:bobowen)]

(In reply to Mike Conley (:mconley) - Digging out of needinfo / review backlog. from comment #17)
...
> >        // The print preview docshell will be in a different TabGroup,
> >        // so we run it in a separate runnable to avoid touching a
> >        // different TabGroup in our own runnable.
> 
> Since we're now separating the definition of printPreviewInitialize from the
> dispatch, it might make more sense to either:
> 
> a) Move the above comment so that it's placed above each point where we do
> the dispatch
> 
> or (maybe preferably)
> 
> b) Add some clarification to this comment saying that printPreviewInitialize
> _must_ be dispatched as a new runnable. I don't know if we can assert that
> somehow, but that might be nice too.

Thanks for the reviews.
I went for option b, although I know of no way we can ensure it currently.
Part 2 should in theory prevent it from happening anyway as well (or at least make it much less likely).

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/7fbe19a6f88e
Part 1: Send number of pages on printPreviewUpdate event instead of requesting from parent. r=mconley
https://hg.mozilla.org/integration/mozilla-inbound/rev/6035f7b2a12c
Part 2: Disable parts of the Print Preview toolbar until update has finished. r=mconley

Comment 21

[Pulsebot]

Backout by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f21099b23eb8
Backed out changeset 6035f7b2a12c 
https://hg.mozilla.org/integration/mozilla-inbound/rev/1280a0161c12
Backed out changeset 7fbe19a6f88e as requested by bobowen for c3 failures. r=backout

Comment 22

[Bob Owen (:bobowen)]

Attachment: Part 1: Send number of pages on printPreviewUpdate event instead of requesting from parent

This also makes sure that we don't call nsIWebBrowserPrint::PrintPreview while we're still in a previous call.

Had to change this a little, because apparently some tests invoke PrintPreview in a non-standard way using the window.
The events still get picked up via the JS and when we get the nsIWebBrowserPrint through the docshell (to get the page count) it overwrites the original one.
I don't want to remove this behaviour in case addons use it, but we probably should properly disallow PrintPreview unless retrieved through the docshell after 57. I've filed bug 1379117 for this.

The change was to leave the printPreviewInitializingInfo in place until exitPrintPreview, so we know that we initiated the preview and add an entered property, so we only send the entered message once.
Then we can ignore the events when we didn't invoke the print preview via this JS.

Try push with this change (the lint issues should be fixed):
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5313e9ae0249189d63983f2d93a55ab193a0562d

Comment 23

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 8884248 [details] [diff] [review]
Part 1: Send number of pages on printPreviewUpdate event instead of requesting from parent

Review of attachment 8884248 [details] [diff] [review]:
-----------------------------------------------------------------

This is great, thanks!

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e98f6402860e
Part 1: Send number of pages on printPreviewUpdate event instead of requesting from parent. r=mconley
https://hg.mozilla.org/integration/mozilla-inbound/rev/bbaec4a5fc39
Part 2: Disable parts of the Print Preview toolbar until update has finished. r=mconley

Comment 25

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/e98f6402860e
https://hg.mozilla.org/mozilla-central/rev/bbaec4a5fc39

Comment 26

[Ryan VanderMeulen [:RyanVM]]

Should we consider backporting this to Beta or let it ride the 56 train?

Comment 27

[Bob Owen (:bobowen)]

(In reply to Ryan VanderMeulen [:RyanVM] from comment #26)
> Should we consider backporting this to Beta or let it ride the 56 train?

Given the fragility of this code I think we should just let it ride the trains.

This crash only happens on Nightly and the related one in bug 1346873 isn't bad enough to risk the uplift in my opinion.

Comment 28

[Ciprian Georgiu, Desktop QA]

I cannot reproduce this crash anymore by following the STR from comment 0. Tested on 56.0b12 (20170914024831) using Windows 10 x64.