flypig.co.uk

We've not quite left the printing harbour, but we're getting closer to sailing. Yesterday we got to the point where it was possible to print a copy of the page, but there were some glitches: a new blank tab is opened when the print starts, and the user interface doesn't recognise when the print finishes.

I'm hoping these might be easy to fix, but at this point, without further investigation, that's impossible to tell.

So, let's get stuck in to getting things seaworthy.

First up, I've amended the print() method to assume it returns a promise rather than the progress and status change messages that the previous code assumed. I've also added some debug prints so that it now looks like this:

    this._browsingContext = BrowsingContext.getFromWindow(win)

    try {
      dump("PRINT: printing\n");
      this._browsingContext.print(printSettings)
        .then(() => dump("PRINT: Printing finished\n"))
        .catch(exception => dump("PRINT: Printing exception: " + exception + "\n"));
    } finally {
      // Remove the print object to avoid leaks
      this._browsingContext = null;
      dump("PRINT: finally\n");
    }

    dump("PRINT: returning\n");
    let fileInfo = await OS.File.stat(targetPath);
    aSetProgressBytesFn(fileInfo.size, fileInfo.size, false);

When I execute this the following output is generated:

PRINT: printing
PRINT: finally
PRINT: returning
JSScript: ContextMenuHandler.js loaded
JSScript: SelectionPrototype.js loaded
JSScript: SelectionHandler.js loaded
JSScript: SelectAsyncHelper.js loaded
JSScript: FormAssistant.js loaded
JSScript: InputMethodHandler.js loaded
EmbedHelper init called
Available locales: en-US, fi, ru
Frame script: embedhelper.js loaded
PRINT: Printing finished
JavaScript error: file:///usr/lib64/mozembedlite/components/
    EmbedLiteChromeManager.js, line 170: TypeError: chromeListener is undefined
onWindowClosed@file:///usr/lib64/mozembedlite/components/EmbedLiteChromeManager.js:170:7
observe@file:///usr/lib64/mozembedlite/components/EmbedLiteChromeManager.js:201:12

That all looks pretty healthy. The promise is clearly being returned and eventually resolved. There's also positive results in the user interface: now that this is working correctly the window that opens at the start of the printing process now also closes at the end of it. The menu item is no longer greyed out.

So probably the code that was there before was failing because of the incorrect semantics, which also caused the print process not to complete cleanly. One small issue is that the menu item doesn't get greyed out at all now. It should be greyed out while the printing is taking place.

My suspicion is that this is because the function is returning immediately, leaving the promise to run asynchronously, rather than waiting for the promise to resolve before returning. To test the theory out I've updated the code inside the try clause to look like this:

      dump("PRINT: printing\n");
      await new Promise((resolve, reject) => {
        this._browsingContext.print(printSettings)
        .then(() => {
          dump("PRINT: Printing finished\n")
          resolve();
        })
        .catch(exception => {
          dump("PRINT: Printing exception: " + exception + "\n");
          reject(new DownloadError({ result: exception, inferCause: true }));
        });
      });

Now when it's run we see the following output:

PRINT: printing
JSScript: ContextMenuHandler.js loaded
JSScript: SelectionPrototype.js loaded
JSScript: SelectionHandler.js loaded
JSScript: SelectAsyncHelper.js loaded
JSScript: FormAssistant.js loaded
JSScript: InputMethodHandler.js loaded
EmbedHelper init called
Available locales: en-US, fi, ru
Frame script: embedhelper.js loaded
PRINT: Printing finished
PRINT: finally
PRINT: returning
JavaScript error: file:///usr/lib64/mozembedlite/components/
    EmbedLiteChromeManager.js, line 170: TypeError: chromeListener is undefined
onWindowClosed@file:///usr/lib64/mozembedlite/components/EmbedLiteChromeManager.js:170:7
observe@file:///usr/lib64/mozembedlite/components/EmbedLiteChromeManager.js:201:12

That's pretty similar to the output from last time, but notice how the "finally" and "returning" output now waits for the printing to finish before appearing. That's because of the await we've added to the promise. But the good news is that this also produces better results with the user interface too: the menu item is greyed out until the printing finishes, at which point it's restored. The remorse timer and notifications work better too.

So it now appears to be completing cleanly with good results. That means the only thing now to try to fix is the new window that's opening.

One of the nice things about the fact the printing is working is that I can now debug it properly and exclusively on the ESR 91 side to see what's happening (in the C++ portions at least).

My first breakpoints go on the various ShowPrintDialog() methods. This could potentially be the source of the extra window. But when I run the executable and trigger a PDF save the breakpoint isn't hit. So I guess it's not. Instead the SetupSilentPrinting() method is being called, following the explanation in nsIPrintSettings.idl:

  /**
   * We call this function so that anything that requires a run of the event loop
   * can do so safely. The print dialog runs the event loop but in silent printing
   * that doesn't happen.
   *
   * Either this or ShowPrintDialog (but not both) MUST be called by the print
   * engine before printing, otherwise printing can fail on some platforms.
   */
  [noscript] void SetupSilentPrinting();

The backtrace when this hits looks like this:

Thread 8 "GeckoWorkerThre" hit Breakpoint 2,
    nsPrintSettingsQt::SetupSilentPrinting (this=0x7e2c255760)
    at widget/qt/nsPrintSettingsQt.cpp:383
383         return NS_OK;
(gdb) bt
#0  nsPrintSettingsQt::SetupSilentPrinting (this=0x7e2c255760)
    at widget/qt/nsPrintSettingsQt.cpp:383
#1  0x0000007fbc3bb4e4 in nsPrintJob::DoCommonPrint (this=this@entry=0x7e2c14ba30, aIsPrintPreview=aIsPrintPreview@entry=false, 
    aPrintSettings=aPrintSettings@entry=0x7e2c255760,
    aWebProgressListener=aWebProgressListener@entry=0x7f8a0902b0,
    aDoc=aDoc@entry=0x7f8abf4040)
    at ${PROJECT}/obj-build-mer-qt-xr/dist/include/nsCOMPtr.h:869
#2  0x0000007fbc3bb718 in nsPrintJob::CommonPrint (this=this@entry=0x7e2c14ba30,
    aIsPrintPreview=aIsPrintPreview@entry=false, 
    aPrintSettings=aPrintSettings@entry=0x7e2c255760,
    aWebProgressListener=aWebProgressListener@entry=0x7f8a0902b0, 
    aSourceDoc=aSourceDoc@entry=0x7f8abf4040)
    at layout/printing/nsPrintJob.cpp:488
#3  0x0000007fbc3bb840 in nsPrintJob::Print (this=this@entry=0x7e2c14ba30,
    aSourceDoc=<optimized out>, aPrintSettings=aPrintSettings@entry=0x7e2c255760, 
    aWebProgressListener=aWebProgressListener@entry=0x7f8a0902b0)
    at layout/printing/nsPrintJob.cpp:824
#4  0x0000007fbc108fe4 in nsDocumentViewer::Print (this=0x7e2ffabd80,
    aPrintSettings=0x7e2c255760, aWebProgressListener=0x7f8a0902b0)
    at ${PROJECT}/obj-build-mer-qt-xr/dist/include/nsCOMPtr.h:859
#5  0x0000007fba96f49c in nsGlobalWindowOuter::Print(nsIPrintSettings*,
    nsIWebProgressListener*, nsIDocShell*, nsGlobalWindowOuter::IsPreview,
    nsGlobalWindowOuter::IsForWindowDotPrint, std::function>void
    (mozilla::dom::PrintPreviewResultInfo const&)>&&, mozilla::ErrorResult&)
    (this=this@entry=0x7f88b85de0,
    aPrintSettings=aPrintSettings@entry=0x7e2c255760,
    aListener=aListener@entry=0x7f8a0902b0,
    aDocShellToCloneInto=aDocShellToCloneInto@entry=0x0, 
    aIsPreview=aIsPreview@entry=nsGlobalWindowOuter::IsPreview::No, 
    aForWindowDotPrint=aForWindowDotPrint@entry=nsGlobalWindowOuter::
    IsForWindowDotPrint::No, aPrintPreviewCallback=..., aError=...)
    at ${PROJECT}/obj-build-mer-qt-xr/dist/include/nsCOMPtr.h:859
#6  0x0000007fbc7eb714 in mozilla::dom::CanonicalBrowsingContext::Print
    (this=this@entry=0x7f88b85870, aPrintSettings=0x7e2c255760, aRv=...)
    at cross/aarch64-meego-linux-gnu/include/c++/8.3.0/bits/std_function.h:402
#7  0x0000007fbab82f08 in mozilla::dom::CanonicalBrowsingContext_Binding::print
    (args=..., void_self=0x7f88b85870, obj=..., cx_=0x7f881df460)
    at BrowsingContextBinding.cpp:4674
#8  mozilla::dom::CanonicalBrowsingContext_Binding::print_promiseWrapper
    (cx=0x7f881df460, obj=..., void_self=0x7f88b85870, args=...)
    at BrowsingContextBinding.cpp:4688
[...]
#34 0x0000007fbd16635c in js::jit::MaybeEnterJit (cx=0x7f881df460, state=...)
    at js/src/jit/Jit.cpp:207
#35 0x0000007f882b8211 in ?? ()
Backtrace stopped: Cannot access memory at address 0x228ea24c1e0c
(gdb) 

The thing I find interesting about this is that it's entering the nsPrintSettingsQt version of the SetupSilentPrinting() method. That's Sailfish-specific code coming from patch 002 "Bring back Qt Layer" and so worth taking a look at.

Unfortunately after looking through it carefully the nsPrintSettingsQt implementation doesn't yield any secrets. The SetupSilentPrinting() method is essentially empty, which isn't out of line with the GTK or default implementations. I don't see anything else in there that shouts "open new window"; it just looks like a largely passive class for capturing settings.

Nevertheless this callstack can still be useful for us. I notice that, even though the app is still stuck on this SetupSilentPrinting() breakpoint, the new blank window has already opened — hanging in a state of suspended animation — on my phone. We can also see the call to CanonicalBrowsingContext::Print() is item six in the stack.

That means that the trigger for opening the window must be somewhere between these two points in the callstack. My next task will be to work my way through all of them to see if one of them could be the culprit. Six methods to work through isn't too many. Here's a slightly cleaner version of the stack to work with:

1. nsPrintSettingsQt::SetupSilentPrinting() file nsPrintSettingsQt.cpp line 383
2. nsPrintJob::DoCommonPrint() file nsPrintJob.cpp line 768
3. nsPrintJob::CommonPrint() file nsPrintJob.cpp line 488
4. nsPrintJob::Print() file nsPrintJob.cpp line 824
5. nsDocumentViewer::Print() file nsDocumentViewer.cpp line 2930
6. nsGlobalWindowOuter::Print() file nsGlobalWindowOuter.cpp line 5412
7. CanonicalBrowsingContext::Print() file CanonicalBrowsingContext.cpp line 682

Inside the nsGlobalWindowOuter::Print() method, between the start of the method and the call to nsDocumentViewer::Print() on line 5412, I see the following bit of code:

      aError = OpenInternal(u""_ns, u""_ns, u""_ns,
                            false,             // aDialog
                            false,             // aContentModal
                            true,              // aCalledNoScript
                            false,             // aDoJSFixups
                            true,              // aNavigate
                            nullptr, nullptr,  // No args
                            nullptr,           // aLoadState
                            false,             // aForceNoOpener
                            printKind, getter_AddRefs(bc));

I'm wondering whether that might be the opening of a window; all the signs are that it is. I've placed a breakpoint on nsGlobalWindowOuter::Print() and plan to step through the method to this point to try to find out.

As I step through, the moment I step over this OpenInternal() call, the window opens in the browser. The printKind parameter is set to PrintKind::InternalPrint which makes me think that the window should be hidden, or something to that effect. Here's the debugging step-through for anyone interested:

Thread 8 "GeckoWorkerThre" hit Breakpoint 2,
    nsGlobalWindowOuter::Print(nsIPrintSettings*, nsIWebProgressListener*,
    nsIDocShell*, nsGlobalWindowOuter::IsPreview,
    nsGlobalWindowOuter::IsForWindowDotPrint, std::function<void
    (mozilla::dom::PrintPreviewResultInfo const&)>&&, mozilla::ErrorResult&) (
    this=this@entry=0x7f888d23e0,
    aPrintSettings=aPrintSettings@entry=0x7e2f2f0ce0,
    aListener=aListener@entry=0x7ea013c4a0, 
    aDocShellToCloneInto=aDocShellToCloneInto@entry=0x0,
    aIsPreview=aIsPreview@entry=nsGlobalWindowOuter::IsPreview::No, 
    aForWindowDotPrint=aForWindowDotPrint@entry=nsGlobalWindowOuter::
    IsForWindowDotPrint::No, aPrintPreviewCallback=..., aError=...)
    at dom/base/nsGlobalWindowOuter.cpp:5258
5258        PrintPreviewResolver&& aPrintPreviewCallback, ErrorResult& aError) {
(gdb) n
[LWP 8816 exited]
5261          do_GetService("@mozilla.org/gfx/printsettings-service;1");
(gdb) n
867     ${PROJECT}/obj-build-mer-qt-xr/dist/include/nsCOMPtr.h: No such file or directory.
(gdb) n
5268      nsCOMPtr<nsIPrintSettings> ps = aPrintSettings;
(gdb) n
867     ${PROJECT}/obj-build-mer-qt-xr/dist/include/nsCOMPtr.h: No such file or directory.
(gdb) n
5274      RefPtr<Document> docToPrint = mDoc;
(gdb) n
5280      RefPtr<BrowsingContext> sourceBC = docToPrint->GetBrowsingContext();
(gdb) n
5287      nsAutoSyncOperation sync(docToPrint, SyncOperationBehavior::eAllowInput);
(gdb) n
5288      AutoModalState modalState(*this);
(gdb) n
5290      nsCOMPtr<nsIContentViewer> cv;
(gdb) p modalState
$1 = {mModalStateWin = {mRawPtr = 0x7f888d23e0}}
(gdb) n
5291      RefPtr<BrowsingContext> bc;
(gdb) n
5292      bool hasPrintCallbacks = false;
(gdb) n
5293      if (docToPrint->IsStaticDocument() &&
(gdb) n
5320        if (aDocShellToCloneInto) {
(gdb) p aDocShellToCloneInto
$2 = (nsIDocShell *) 0x0
(gdb) n
5325          AutoNoJSAPI nojsapi;
(gdb) n
5326          auto printKind = aForWindowDotPrint == IsForWindowDotPrint::Yes
(gdb) n
5329          aError = OpenInternal(u""_ns, u""_ns, u""_ns,
(gdb) p printKind
$3 = nsGlobalWindowOuter::PrintKind::InternalPrint
(gdb) n
[LWP 8736 exited]
[LWP 8737 exited]
[LWP 8711 exited]
[New LWP 9166]
[New LWP 9167]
5329          aError = OpenInternal(u""_ns, u""_ns, u""_ns,
(gdb) p aError
$4 = (mozilla::ErrorResult &) @0x7f9f3d8dc0: {<mozilla::binding_danger::
    TErrorResult<mozilla::binding_danger::AssertAndSuppressCleanupPolicy>> =
    {mResult = nsresult::NS_OK, mExtra = {mMessage = 0x41e,
    mJSException = {asBits_ = 1054}, mDOMExceptionInfo = 0x41e}},
    <No data fields>}
(gdb) 

Looking through the nsGlobalWindowOuter code eventually leads me to the nsWindowWatcher::OpenWindowInternal() method. There's a lot happening in this method. About halfway through there are some comments about visibility, which pique my interest because I'm wondering whether the window that's opening has a visibility flag which is either not being set properly, or being ignored.

But I've reached the end of my mental capacity today, it's time for bed. So I'll have to come back to this tomorrow.

If you'd like to read any of my other gecko diary entries, they're all available on my Gecko-dev Diary page.