flypig.co.uk

We're getting perilously close to 2⁷ days on this now. I admit this printing issue has turned out to be more gnarly than I'd hopped. But I don't feel ready to give up on it just yet. Yesterday we got the page hidden but couldn't figure out why that prevented the print from successfully completing. Today I plan to debug the print process again to try to find out why.

Let's get the error output that we're dealing with. There are some additional debug print outputs that I've added (all of the ones starting with PRINT:) to help clarify the flow. Whenever I add temporary debug prints in this way I like to give them all the same prefix. It makes them easier to spot, but also makes it easier to filter on them all using grep in case there's so much debug output that it makes them hard to spot.

$ EMBED_CONSOLE=1 MOZ_LOG="EmbedLite:5" sailfish-browser
[...]
PRINT: Window: [object Window]
PRINT: Window document: [object HTMLDocument]
PRINT: Window MozElement: undefined
[Parent 15251: Unnamed thread 7718002670]: E/EmbedLite FUNC::virtual nsresult mozilla::embedlite::EmbedLiteAppChild::Observe(nsISupports*, const char*,
    const char16_t*):68 topic:embed:download
[D] unknown:0 - PRINT: onNewTabRequested pre activeTab:  10
[D] unknown:0 - PRINT: new tab is hidden; recording previous ID:  10
[D] unknown:0 - PRINT: onNewTabRequested post activeTab:  11
[W] unknown:0 - bool DBWorker::execute(QSqlQuery&) failed execute query
[W] unknown:0 - "INSERT INTO tab (tab_id, tab_history_id) VALUES (?,?);"
[W] unknown:0 - QSqlError("19", "Unable to fetch row", "UNIQUE constraint
    failed: tab.tab_id")
[D] unknown:0 - PRINT: onActiveTabChanged:  11
[D] unknown:0 - PRINT: onActiveTabChanged hidden:  true
[D] unknown:0 - PRINT: new tab is hidden, activating previous ID:  10
[D] unknown:0 - PRINT: activateTab: old:  11
[D] unknown:0 - PRINT: activateTab: new:  4
[D] unknown:0 - PRINT: activateTab: activate tab:  4 Tab(tabId = 10,
    parentId = 0, isValid = true, url = "https://jolla.com/",
    requested url = "", url resolved: true, title = "Jolla", thumbnailPath =
    "~/.cache/org.sailfishos/browser/tab-10-thumb.jpg", desktopMode = false)
[D] unknown:0 - PRINT: onActiveTabChanged:  10
[D] unknown:0 - PRINT: onActiveTabChanged hidden:  false
EmbedliteDownloadManager error: [Exception... "Abort"  nsresult: "0x80004004
    (NS_ERROR_ABORT)"  location: "JS frame ::
    resource://gre/modules/DownloadCore.jsm :: DownloadError :: line 1755"
    data: no]
[Parent 15251: Unnamed thread 7718002670]: E/EmbedLite FUNC::virtual nsresult 
    mozilla::embedlite::EmbedLiteAppChild::Observe(nsISupports*, const char*,
    const char16_t*):68 topic:embed:download
[Parent 15251: Unnamed thread 7718002670]: I/EmbedLite WARN: EmbedLite::virtual
    void* mozilla::embedlite::EmbedLitePuppetWidget::GetNativeData(uint32_t):127
    EmbedLitePuppetWidget::GetNativeData not implemented for this type
JavaScript error: , line 0: uncaught exception: Object
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
CONSOLE message:
[JavaScript Error: "uncaught exception: Object"]
[...]

There are two things I need to look into from this debug output. First the database error:

[W] unknown:0 - QSqlError("19", "Unable to fetch row", "UNIQUE constraint failed:
    tab.tab_id")

It looks like something has messed up the tab database. That's not so surprising given that I made some (not very carefully thought-through) changes to the dbworker.cpp code. However my suspicion is that these database changes won't be affecting printing adversely. Second the download error:

EmbedliteDownloadManager error: [Exception... "Abort"  nsresult: "0x80004004
    (NS_ERROR_ABORT)"  location: "JS frame ::
    resource://gre/modules/DownloadCore.jsm :: DownloadError :: line 1755"
    data: no]

I'm going to start with the latter because it seems more likely to be the underlying issue. The exception is being thrown here, in the last of the three conditional blocks found in DownloadCore.js:

var DownloadError = function(aProperties) {
[...]
  if (aProperties.message) {
    this.message = aProperties.message;
  } else if (
    aProperties.becauseBlocked ||
    aProperties.becauseBlockedByParentalControls ||
    aProperties.becauseBlockedByReputationCheck ||
    aProperties.becauseBlockedByRuntimePermissions
  ) {
    this.message = "Download blocked.";
  } else {
    let exception = new Components.Exception("", this.result);
    this.message = exception.toString();
  }

That's not super helpful though because this is just the code that's called when there's an error of any kind. We need to find out where this is being called from.

There are 19 places in the DownloadCore.js file that might trigger an error using this DownloadError() method. Of these, nine include a message field and so will fall into the first block of the condition, four have one of the becauseBlocked... flags set and so fall into the second block of the condition. Finally one of them is the method used for deserialisation of the message.

That leaves five left which could potentially be one of the ones triggering the error we're seeing. These five can be found on lines 518, 557, 2164, 2740 and 3035 of the DownloadCore.jsm file.

That's not too many; let's find out which one exactly by adding in different messages to all of these six entries and seeing which one pops up. Here's the result:

EmbedliteDownloadManager error: Line 3035

That means the error is happening inside this block:

    try {
      await new Promise((resolve, reject) => {
        this._browsingContext.print(printSettings)
        .then(() => {
          resolve();
        })
        .catch(exception => {
          reject(new DownloadError({ result: exception, inferCause: true }));
        });
      });
    }

That's not too surprising or revealing. That means there's an exception being thrown inside the C++ code from somewhere following this call:

already_AddRefed<Promise> CanonicalBrowsingContext::Print(
    nsIPrintSettings* aPrintSettings, ErrorResult& aRv)

Inside this method there are all sorts of calls to get the window details. So it might be worth checking whether we're switching tabs before or after all this is happening. Maybe it's just a timing issue?

A horrible thought suddenly occurred to me: what if it's the printing part that's broken and not the window changes causing it to break? I've been reinstalling various files, but maybe I didn't re-apply some manual change that had fixed the printing earlier?

Just to double check this I've removed the code that switches the tab back again to check whether the printing works correctly with this removed:

void DeclarativeWebContainer::onActiveTabChanged(int activeTabId)
{
    if (activeTabId <= 0) {
        return;
    }

    reload(false);

    if (m_model->activeTab().hidden()) {
        // Switch back to the old tab
        //m_model->activateTabById(mPreviousTabWhenHidden);
    }
}

Rebuild, reinstall, rerun. But now the printing does work. So it's definitely the introduction of this one line that's causing the issue. I'm going to put the line back in again, but this time with just a slight 100 millisecond delay to see whether that makes any difference. This will help confirm or deny my suspicion that this may be a timing issue.

void DeclarativeWebContainer::onActiveTabChanged(int activeTabId)
{
    if (activeTabId <= 0) {
        return;
    }

    reload(false);

    if (m_model->activeTab().hidden()) {
        // Switch back to the old tab
        hiddenTabTimer.setSingleShot(true);
        disconnect(&hiddenTabTimer, &QTimer::timeout, this, nullptr);
		connect(&hiddenTabTimer, &QTimer::timeout, this, [this]() {
        	m_model->activateTabById(mPreviousTabWhenHidden);
		});
		hiddenTabTimer.start(100);
    }
}

Now with this slight delay the window appears visibly to the user for a fraction of a second, then disappears. The print then continues and the PDF is output successfully, no longer a zero-byte file:

$ ls -l
total 4596
-rw-rw-r-- 1 defaultuser defaultuser 4703901 Dec 24 18:39 Jolla.pdf

So that confirms it: it's a timing issue. Most likely the print code is expecting to get details from the current window. But if the window switches before it can do this, it'll end up getting the details from the original window, causing the print to fail.

If this is indeed what's going wrong, we should be able to pull that delay right down to zero. Adding a delay of zero time isn't the same as adding in no timer at all. The big difference is that by using the timer, execution will be force once round the event loop before the switch back to the window occurs. In this case, it could be enough for the print code to pick up all of the info it needs in order to avoid the print failing.

So I've made this change:

		hiddenTabTimer.start(0);

With a timeout time set to zero like this the window barely appears: it's more like a flicker of the screen, no different to when we had no timer at all. What's more the file is still generated in the background and this time gets filled up with data; the error that we were seeing earlier doesn't occur. Printing multiple times also seems to work correctly.

So this is a good result. I don't think I'm going to be able to remove the initial flicker entirely, which is a shame, but maybe further down the line someone will think of a way to address that. I'm also not totally done because the "hidden" window is also currently still appearing in the tab view. I need to filter it out. The good news is that I'm much more comfortable with how to do that as there are standard approaches to filtering items from models using the QSortFilterProxyModel class.

I'm not going to do that right now though, I'll pick that up tomorrow.

Over the last few weeks there have been many times when I wasn't convinced I'd be able to get the "Save page to PDF" functionality back up and working satisfactorily again. So it's a huge relief to get to this stage where I know it will get to a place that I'm happy with. That seems like a great place to end for the day.

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