flypig.co.uk

Good morning! It's a bright, crisp, cold morning in the UK today. Bright sun but also frost on the ground. And I'm feeling quite energised about getting to the bottom of this address bar search issue that I've been working on over the last couple of days.

If you've been following along you'll recall that we got to the point where the URIFixup class is requesting the search engine to use from the SearchService service. It goes like this:

    // Try falling back to the search service's default search engine
    // We must use an appropriate search engine depending on the private
    // context.
    let engine = isPrivateContext
      ? Services.search.defaultPrivateEngine
      : Services.search.defaultEngine;

To understand that I'm going to need a better way to debug the code. Gecko and EmbedLite both have their own logging mechanisms. EmbedLite has the EMBED_CONSOLE environment variable while most of gecko uses MOZ_LOG. Ultimately they EmbedLite logging is implemented using the dump() function. We can see this in the jsscripts/Loggger.js file in embedlite-components.

Not all of these logging approaches work well in different situations, but I did some testing and this dump() function works nicely in all the places I'm interested in. Now I wouldn't use it for real logging, but I'm just doing debugging so need an approach that will always work. There's no need for me to be able to activate and deactivate it later, because I'm going to remove all usage of it before I commit anything. So dump() is the perfect solution for my needs. I just have to remember to put newlines at the end of everything.

To complicate matters I want to compare the JavaScript execution between ESR 78 and ESR 91. That will require me to annotate on two devices. I'm working with omni.ja which we discussed on day 86. It's a bit of a pain to work with because the contents have to be unpacked, so that they can then be edited, repacked and reinstalled for every change. It's a messy process compared to being able to edit something in-place.

So for my first task today I'm going to create a helper shell script to make this process a little easier. The idea is to allow the omni.ja archive in the gecko install directory to be unpacked to a working folder where I can edit it. The script will then package it back up and reinstall it so that the changes take effect. Doing this cleanly with a single command to pack and unpack will make my life that little bit easier.

Here's what I've come up with.

#!/bin/bash

set -e
OPTION=$1
INSTALL="/usr/lib64/xulrunner-qt5-91.9.1"
WORKSPACE="./omni"
STARTUPCACHE="${HOME}/.local/share/org.sailfishos/browser/.mozilla/startupCache/"

if [ "${OPTION}" == "" ]; then
  OPTION="no action provided"
fi

echo "Omni action: ${OPTION}"

function unpack() {
  echo "Unpacking from: ${INSTALL}"
  echo "Unpacking to:   ${WORKSPACE}"
  echo ""
  if [ -d ${WORKSPACE} ]; then
    rm -r ${WORKSPACE}
  fi
  mkdir ${WORKSPACE}
  unzip -q ${INSTALL}/omni.ja -d ${WORKSPACE}
}

function pack() {
  echo "Packing from: ${WORKSPACE}"
  echo "Packing to:   ${INSTALL}"
  echo ""
  cd omni
  zip -qr9XD ../omni.ja *
  cd ..
  devel-su mv omni.ja ${INSTALL}/
  rm -rf ${STARTUPCACHE}
}

function help() {
  echo "Please pass in a parameter of either \"pack\" or \"unpack\"."
  echo ""
}

case ${OPTION} in
  "unpack") unpack;;
  "pack") pack;;
  *) help;;
esac

Notice that after packing up and installing the omni.js back into the gecko directory the script also deletes the startupCache. This is a common gotcha that I've been caught be several times myself. When gecko initialises it performs some serialisation of its own default JavaScript scripts. This takes some time, so the library dumps the result out into the startupCache to avoid having to do this every time the browser is started. However, this can mean that even after a file in omni.js has been changed, the edits won't affect execution which is using the files in the startupCache instead. Deleting the startupCache forces the library to recreate the startupCache from the newly installed files.

I've copied this script over to both my phones and carefully set the INSTALL path appropriate. This should make this whole debugging process easier. If you see me using either of these commands in future examples, it'll be making use of this script:

$ ./omni.sh unpack
$ ./omni.sh pack

Now it's time to pepper the code with some dump() output. I've started with some output at the start of the _setEngineDefault() function in SearchService.jsm like this:

  /**
   * Helper function to set the current default engine.
   *
   * @param {boolean} privateMode
   *   If true, sets the default engine for private browsing mode, otherwise
   *   sets the default engine for the normal mode. Note, this function does not
   *   check the "separatePrivateDefault" preference - that is up to the caller.
   * @param {nsISearchEngine} newEngine
   *   The search engine to select
   */
  _setEngineDefault(privateMode, newEngine) {
    dump("SEARCH: _setEngineDefault(): " + newEngine.name + "\n");
    dump("SEARCH: stack start\n");
    dump(Error().stack);
    dump("SEARCH: stack end\n");
    this._ensureInitialized();
[...]

I've also added some debug output in the URIFixup.jsm file as well:

  getFixupURIInfo(uriString, fixupFlags = FIXUP_FLAG_NONE) {
    let isPrivateContext = fixupFlags & FIXUP_FLAG_PRIVATE_CONTEXT;

    dump("SEARCH: getFixupURIInfo() fixupFlags: " + fixupFlags.toString(16) + "\n");

And finally also into the EmbedLiteSearchEngine.js file:

  case "setdefault": {
    dump("SEARCH: EmbedLiteSearchEngine setdefault received\n");
    var engine = Services.search.getEngineByName(data.name);
    if (engine) {
      dump("SEARCH: EmbedLiteSearchEngine engine: " + engine.name + "\n");
      Services.search.defaultEngine = engine;
      dump("SEARCH: EmbedLiteSearchEngine set\n");
[...]

Now when I run the ESR 78 code I see this in the output:

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
SEARCH: getFixupURIInfo() fixupFlags: 8
SEARCH: EmbedLiteSearchEngine setdefault received
SEARCH: EmbedLiteSearchEngine engine: DuckDuckGo
SEARCH: _setEngineDefault(): DuckDuckGo
SEARCH: stack start
_setEngineDefault@resource://gre/modules/SearchService.jsm:2992:10
set defaultEngine@resource://gre/modules/SearchService.jsm:3076:10
observe@file:///usr/lib64/mozembedlite/components/EmbedLiteSearchEngine.js:78:15
SEARCH: stack end
SEARCH: EmbedLiteSearchEngine set

From this we can tell that the search engine is being set to DuckDuckGo. From the call stack we can see this is triggered from line 78 of EmbedLiteSearchEngine.js.

But there's nothing similar appearing in the output from ESR 91:

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
SEARCH: getFixupURIInfo() fixupFlags: 8
JavaScript error: chrome://embedlite/content/embedhelper.js, line 259:
    TypeError: sessionHistory is null
CONSOLE message:
[JavaScript Error: "TypeError: sessionHistory is null"
    {file: "chrome://embedlite/content/embedhelper.js" line: 259}]
receiveMessage@chrome://embedlite/content/embedhelper.js:259:29

In particular, we can see here that there's no "EmbedLiteSearchEngine setdefault received" message appearing. That means there's no embedui:search message being received by EmbedLiteSearchEngine with the topic set to setdefault.

When I change the search provider in the settings on the ESR 78 version I also see this output:

SEARCH: EmbedLiteSearchEngine setdefault received
SEARCH: EmbedLiteSearchEngine engine: Google
SEARCH: _setEngineDefault(): Google
SEARCH: stack start
_setEngineDefault@resource://gre/modules/SearchService.jsm:2992:10
set defaultEngine@resource://gre/modules/SearchService.jsm:3076:10
observe@file:///usr/lib64/mozembedlite/components/EmbedLiteSearchEngine.js:78:15
SEARCH: stack end
SEARCH: EmbedLiteSearchEngine set

Whereas on ESR 91 I see no output at all when changing search providers. There's clearly something going wrong here and certainly the search isn't going to work until this is working, so fixing this is next on my list of tasks.

So the question now is, what should be sending this embedui:search message with setdefault topic and why is it either not being sent, or not being received?

To figure this out we're going over to the sailfish-browser repository and the settingmanger.cpp file that's kept there. In that we can see a SettingManager::setSearchEngine() method which is one of the places where this embedui:search messages is sent from.

(gdb) break SettingManager::setSearchEngine
Breakpoint 2 at 0x55555a7e30: file ../core/settingmanager.cpp, line 116.
(gdb) r
[...]
Thread 1 "sailfish-browse" hit Breakpoint 2, SettingManager::setSearchEngine
    (this=0x5555894f60) at ../core/settingmanager.cpp:116
116         if (m_searchEnginesInitialized) {
(gdb) p m_searchEnginesInitialized
$1 = false

Here we can see that the reason the event isn't being sent is because m_searchEnginesInitialized is set to false. Here's the bit of code that should be setting it to true just below in the same file (see the last line of this extract):

void SettingManager::handleObserve(const QString &message, const QVariant &data)
{
    const QVariantMap dataMap = data.toMap();
    if (message == QLatin1String("embed:search")) {
        QString msg = dataMap.value("msg").toString();
        if (msg == QLatin1String("init")) {
            const StringMap configs(
              OpenSearchConfigs::getAvailableOpenSearchConfigs());
            const QStringList configuredEngines = configs.keys();
            QStringList registeredSearches(dataMap.value(QLatin1String
              ("engines")).toStringList());
            QString defaultSearchEngine = dataMap.value(QLatin1String
              ("defaultEngine")).toString();
            m_searchEnginesInitialized = !registeredSearches.isEmpty();

As we can see from this, there may be two reasons why it's never being set to true. Either the embed:Search message with msg parameter set to init isn't being received, or it is being received and the registeredSearches list is empty. Let's find out which.

(gdb) break SettingManager::handleObserve
Breakpoint 3 at 0x55555a8188: file ../core/settingmanager.cpp, line 132.
(gdb) r
Thread 1 "sailfish-browse" hit Breakpoint 3, SettingManager::handleObserve
    (this=0x55558acfe0, message=..., data=...) at ../core/settingmanager.cpp:132
132         const QVariantMap dataMap = data.toMap();
(gdb) printqs5static message
(Qt5 QString)0xffffe6d8 length=19: "embed:nsPrefChanged"
(gdb) c
Thread 1 "sailfish-browse" hit Breakpoint 3, SettingManager::handleObserve
    (this=0x55558acfe0, message=..., data=...) at ../core/settingmanager.cpp:132
132         const QVariantMap dataMap = data.toMap();
(gdb) printqs5static message
(Qt5 QString)0xffffe6d8 length=19: "embed:nsPrefChanged"
(gdb) c

You'll notice that I'm using a non-standard printqs5static command here. This is a very handy gdb macro from Konrad Rosenbaum for printing out Qt QString structures so that they show the string inside. Using this is far easier than working through all of the substructures manually.

We can see that the messages coming through are of type embed:nsPrefChanged, not the embed::search messages I'm interested in. Stepping through the code I continued to get these embed:nsPrefChanged messages. Eventually I got bored of stepping through them and refined my breakpoint so it would only be hit if the message was the one I'm interested in:

(gdb) delete break 3
(gdb) b settingmanager.cpp:134
Breakpoint 4 at 0x55555a8288: file ../core/settingmanager.cpp, line 136.
(gdb) c
Thread 1 "sailfish-browse" hit Breakpoint 4, SettingManager::handleObserve
    (this=0x55558acfe0, message=..., data=...) at ../core/settingmanager.cpp:136
136                 const StringMap configs(OpenSearchConfigs::
                                            getAvailableOpenSearchConfigs());
(gdb) printqs5static message
(Qt5 QString)0xffffe6d8 length=12: "embed:search"
(gdb) printqs5static msg
(Qt5 QString)0xffffe4f8 length=4: "init"
(gdb) 

That's more like it. Now we can see that the init message is received. So what about that list of search engines? Well, as I continue to step through we can see something interesting.

(gdb) n
137                 const QStringList configuredEngines = configs.keys();
(gdb) n
JavaScript error: resource://gre/modules/SessionStoreFunctions.jsm, line 120:
    NS_ERROR_FILE_NOT_FOUND: 
CONSOLE message:
[JavaScript Error: "NS_ERROR_FILE_NOT_FOUND: "
    {file: "resource://gre/modules/SessionStoreFunctions.jsm" line: 120}]
SSF_updateSessionStoreForWindow@resource://gre/modules/
    SessionStoreFunctions.jsm:120:5
UpdateSessionStoreForStorage@resource://gre/modules/
    SessionStoreFunctions.jsm:54:35

138                 QStringList registeredSearches(dataMap.value(QLatin1String
                        ("engines")).toStringList());
(gdb) n
139                 QString defaultSearchEngine = dataMap.value(QLatin1String
                        ("defaultEngine")).toString();
(gdb) n
1066    /usr/include/qt5/QtCore/qstring.h: No such file or directory.
(gdb) n
140                 m_searchEnginesInitialized = !registeredSearches.isEmpty();
(gdb) n
108     /usr/include/qt5/QtCore/qlist.h: No such file or directory.
(gdb) p m_searchEnginesInitialized
$6 = false
(gdb) p registeredSearches
(gdb) p registeredSearches.p.d->end - registeredSearches.p.d->begin
$12 = 0
(gdb) n
144                 if (!m_searchEnginesInitialized) {

Note here that the registeredSearches.p.d->end - registeredSearches.p.d->begin calculation is returning the size of the registeredSearches list, as found in the Qt source code.

So, the message is being received, but the value that's supposed to contain the list of search engines is empty and moreover we're also getting the NS_ERROR_FILE_NOT_FOUND error midway through the process. That error may be a red herring (something random happening on a different thread), but we should keep it in mind just in case.

So, onward, let's find out why the list being sent is empty.

The place where this gets sent from is the EmbedLiteSearchEngine.js file which, on receiving the infamous "profile-after-change" event sends out the list of search engines like this:

  case "profile-after-change": {
    Services.obs.removeObserver(this, "profile-after-change");
    Services.search.getEngines().then((engines) => {
      let engineNames = engines.map(function (element) {
        return element.name;
      });
      let enginesAvailable = (engines && engines.length > 0);
      var messg = {
        msg: "init",
        engines: engineNames,
        defaultEngine: enginesAvailable && Services.search.defaultEngine
                         ? Services.search.defaultEngine.name : null
      }
      Services.obs.notifyObservers(null, "embed:search", JSON.stringify(messg));
    });
    break;
  }

We should get some debug output printed from this file to find out what's going on. Here's the newly annotated version:

  case "profile-after-change": {
    dump("SEARCH: profile-after-change\n");
    Services.obs.removeObserver(this, "profile-after-change");
    Services.search.getEngines().then((engines) => {
      dump("SEARCH: engine num: " + engines.length + "\n");
      let engineNames = engines.map(function (element) {
        dump("SEARCH: engine name: " + element.name + "\n");
        return element.name;
      }); 
[...]

And here's the output we get from this:

UserAgentOverrideHelper app-startup
SEARCH: profile-after-change
Created LOG for EmbedPrefs
[...]
Frame script: embedhelper.js loaded
SEARCH: getFixupURIInfo() fixupFlags: 8
SEARCH: engine num: 0

So no search engines. There should be search engines.

We need to follow up on this line here:

Services.search.getEngines()

This takes us all the way back to SearchService.jsm. Sometimes there are these strange circles in the code, but we're not quite back all the way to where we started, we're definitely making progress.

It's getting late here. I was really hoping to get this all sorted today, but it's turned out to be a deeper and more thorny problem than I'd anticipated. Not to worry, idle hands and all that; we're continuing to make important fixes as we work through the code. So we'll get there.

If you'd like to catch up on all the diary entries, they're all available on my Gecko-dev Diary page.