flypig.co.uk

Now that I'm back looking at gecko it's been fun to dig into the JavaScript rather than the C++ for a change. There are pros and cons with both, but not having to recompile the code when working with JavaScript makes a nice change. On the other hand, and perhaps ironically, I don't have a good JavaScript debugger to match gdb. Is there even such a thing? I've always found JavaScript debugging to be more painful than it should be... non-sequential event-based programming.

So I've been tackling some of the JavaScript errors generated in the logs. Since we finished off those being generated from EmbedLiteGlobalHelper.js last night, that means this morning it's time to choose another.

Let's go for issue #1045:

JavaScript Error: "Unexpected event profile-after-change"
    {file: "resource://gre/modules/URLQueryStrippingListService.jsm" line: 224}

The standard stages are going to start looking familiar: find the file, check the line, check the file the line relates to.

So, find the file. The URLQueryStrippingListService.jsm file is in the gecko-dev source tree as ./toolkit/components/antitracking/URLQueryStrippingListService.jsm. The problematic block of code looks like this:

  observe(subject, topic, data) {
    switch (topic) {
      case "xpcom-shutdown":
        this._shutdown();
        break;
      case "nsPref:changed":
        let prefValue = Services.prefs.getStringPref(data, "");
        this._onPrefUpdate(data, prefValue);
        break;
      default:
        Cu.reportError(`Unexpected event ${topic}`);
    }
  }

The error output is coming from the Cu.reportError() call at the end. At this stage it may also be worth noting that the URLQueryStrippingListService.jsm file doesn't exist in the ESR 78 codebase, However there is a very similar block of code in a file called UrlClassifierSkipListService.jsm instead:

  observe(subject, topic, data) {
    if (topic != "nsPref:changed" || data != this.prefName) {
      Cu.reportError(`Unexpected event ${topic} with ${data}`);
      return;
    }

    this.prefValue = Services.prefs.getStringPref(this.prefName, null);
    this.notifyObservers();
  }

Now the error is flagging up the event named profile-after-change. That must be being fired somewhere, so we should find out where.

There are multiple observers put on this event in the embedlite-components code:

$ grep -rIn "profile-after-change" *
jscomps/EmbedliteDownloadManager.js:184:
    Services.obs.addObserver(this, "profile-after-change", false);
jscomps/EmbedliteDownloadManager.js:187:
    case "profile-after-change":
jscomps/EmbedliteDownloadManager.js:188:
    Services.obs.removeObserver(this, "profile-after-change");
jscomps/EmbedLiteSearchEngine.js:30:
    Services.obs.addObserver(this, "profile-after-change", false);
jscomps/EmbedLiteSearchEngine.js:33:
    case "profile-after-change": {
jscomps/EmbedLiteSearchEngine.js:34:
    Services.obs.removeObserver(this, "profile-after-change");
jscomps/EmbedLiteGlobalHelper.js:49:
    Services.obs.addObserver(this, "profile-after-change", false);
jscomps/EmbedLiteGlobalHelper.js:61:
    case "profile-after-change": {

But none of these are responsible for sending the event. If it turns out that the event has been removed, or renamed, we may need to circle back to update all of these references.

The name of the event appears all over the place in the gecko code, so it doesn't look like it's been removed or changed. At least one place where the event is fired is in toolkit/xre/nsXREDirProvider.cpp line 978:

    obsSvc->NotifyObservers(nullptr, "profile-after-change", kStartup);

There's also a similar line in the ESR 78 code — it doesn't look like it's changed — which makes me think this probably isn't the cause. But let's continue looking through the code.

There are other instances, but from what I can tell all the other places are part of the test code, so not what we're interested in. While digging through the grep output I also discover the following in toolkit/profile/notifications.txt which could turn out to be useful:

"profile-after-change"
  Called after the profile has changed. Use this notification
  to make changes that are dependent on what some other listener
  did during its profile-do-change. For example, to respond to
  new preferences.

At this point I'm still quite unclear as to why the error is being triggered. Earlier I mentioned that debugging the JavaScript is more troublesome. In this case it looks like the event might be firing in the C++ code, in which case I can stick a breakpoint on it to see whether it tallies with the error being printed to the log. That might help identify what's firing this event and why the URLQueryStrippingListService event is suddenly so unhappy about receiving it. It feels like an ordering issue to me.

But I'm currently on the train, due to arrive in to St. Pancras Station soon and so not about to start wiring up an SSH session for debugging. So this will have to wait now until this evening.

[...]

I'm on the train back home now and have spent most of the journey working my way through the code linked in Bug 1706608. After reading through it carefully it's still not clear to me why the "profile-after-change" event is triggering an error. I thought maybe the discussion in changeset D117376 was a hint: there it talks about not being able to rely on the event to start up the URLQueryStrippingListService module. But that doesn't explain why the event causes problems.

This is a little frustrating, but maybe once I'm home I'll be able to run some debugging and that might help.

[...]

So now I'm home and in a much better position to performs some debugging. Firs let's do a vanilla run without the debugger to compare against. The thing to notice is that the error message is the next log output line after the UserAgentOverrideHelper app-startup output and before the Created LOG for EmbedPrefs output.

[defaultuser@Xperia10II-DualSIM gecko]$ EMBED_CONSOLE=1 sailfish-browser
[D] unknown:0 - Using Wayland-EGL
library "libGLESv2_adreno.so" not found
library "eglSubDriverAndroid.so" not found
greHome from GRE_HOME:/usr/bin
libxul.so is not found, in /usr/bin/libxul.so
Created LOG for EmbedLiteTrace
[W] unknown:0 - Unable to open bookmarks
    "/home/defaultuser/.local/share/org.sailfishos/browser/bookmarks.json"
[D] onCompleted:105 - ViewPlaceholder requires a SilicaFlickable parent
Created LOG for EmbedLite
JSComp: EmbedLiteConsoleListener.js loaded
JSComp: ContentPermissionManager.js loaded
JSComp: EmbedLiteChromeManager.js loaded
JSComp: EmbedLiteErrorPageHandler.js loaded
JSComp: EmbedLiteFaviconService.js loaded
JSComp: EmbedLiteGlobalHelper.js loaded
EmbedLiteGlobalHelper app-startup
JSComp: EmbedLiteOrientationChangeHandler.js loaded
JSComp: EmbedLiteSearchEngine.js loaded
JSComp: EmbedLiteSyncService.js loaded
EmbedLiteSyncService app-startup
JSComp: EmbedLiteWebrtcUI.js: loaded
JSComp: EmbedLiteWebrtcUI.js: got app-startup
JSComp: EmbedPrefService.js loaded
EmbedPrefService app-startup
JSComp: EmbedliteDownloadManager.js loaded
JSComp: LoginsHelper.js loaded
JSComp: PrivateDataManager.js loaded
JSComp: UserAgentOverrideHelper.js loaded
UserAgentOverrideHelper app-startup
CONSOLE message:
[JavaScript Error: "Unexpected event profile-after-change"
    {file: "resource://gre/modules/URLQueryStrippingListService.jsm" line: 224}]
observe@resource://gre/modules/URLQueryStrippingListService.jsm:224:12

Created LOG for EmbedPrefs
Created LOG for EmbedLiteLayerManager

Now I'm going to add in a breakpoint on line 978 of nsXREDirProvider.cpp. This is the one line I was able to identify that sends out a profile-after-change event. Recall that one of the things we'd like to find out is whether this is the event that's triggering the error message, or if there are some instances that I missed in my visual check.

Here's the gdb output from running with this breakpoint. In the debugging output you'll see lots of "New LWP", "Switching to LWP" or "LWP exited" lines. LWP stands for "Lightweight Process" which is the term used for a thread. These lines aren't output when you just run the app, which is why we see them in this gdb output but not in the standard execution output that we saw above. In short, these "LWP" lines can be ignored when comparing the debug output here with the previous debug output.

(gdb) b nsXREDirProvider.cpp:978
[...]
JSComp: EmbedLiteConsoleListener.js loaded
JSComp: ContentPermissionManager.js loaded
JSComp: EmbedLiteChromeManager.js loaded
JSComp: EmbedLiteErrorPageHandler.js loaded
JSComp: EmbedLiteFaviconService.js loaded
Missing separate debuginfo for /lib64/libnss_db.so.2
Try: zypper install -C "debuginfo(build-id)=08373f23b9c39aa3af7ef3008920a379a5e7df7e"
[New LWP 16903]
JSComp: EmbedLiteGlobalHelper.js loaded
EmbedLiteGlobalHelper app-startup
JSComp: EmbedLiteOrientationChangeHandler.js loaded
JSComp: EmbedLiteSearchEngine.js loaded
JSComp: EmbedLiteSyncService.js loaded
EmbedLiteSyncService app-startup
JSComp: EmbedLiteWebrtcUI.js: loaded
JSComp: EmbedLiteWebrtcUI.js: got app-startup
JSComp: EmbedPrefService.js loaded
EmbedPrefService app-startup
JSComp: EmbedliteDownloadManager.js loaded
JSComp: LoginsHelper.js loaded
JSComp: PrivateDataManager.js loaded
[LWP 16900 exited]
JSComp: UserAgentOverrideHelper.js loaded
UserAgentOverrideHelper app-startup
[New LWP 16904]
[New LWP 16905]
[New LWP 16906]
[New LWP 16907]
[New LWP 16908]
[Switching to LWP 16885]

Thread 8 "GeckoWorkerThre" hit Breakpoint 1,
    nsXREDirProvider::DoStartup (this=)
    at /usr/src/debug/xulrunner-qt5-91.9.1-1.aarch64/toolkit/xre/
    nsXREDirProvider.cpp:978
978	    obsSvc->NotifyObservers(nullptr, "profile-after-change", kStartup);
(gdb) n
Missing separate debuginfo for /usr/lib64/libsoftokn3.so
Try: zypper install -C "debuginfo(build-id)=932611cf165ab104fa7bae7176d0bfb63368f6bc"
Missing separate debuginfo for /usr/lib64/libfreeblpriv3.so
Try: zypper install -C "debuginfo(build-id)=ea9e4dc0f2a49e2a02ae37540a8561bf4f1ac79a"
[New LWP 16941]
[New LWP 16942]
982	    (void)NS_CreateServicesFromCategory("profile-after-change", nullptr,
(gdb) n
Missing separate debuginfo for /usr/lib64/libnssckbi.so
Try: zypper install -C "debuginfo(build-id)=c2e22ddaa9e2d7802fd7ff14979ba02fb6508bcd"
Missing separate debuginfo for /usr/lib64/libtasn1.so.6
Try: zypper install -C "debuginfo(build-id)=95f83c2cec19f8b9030e796b6c25c31a10c185e8"
985	    if (gSafeMode && safeModeNecessary) {
(gdb) n
999	    mozilla::Telemetry::Accumulate(mozilla::Telemetry::SAFE_MODE_USAGE, mode);
(gdb) n
1001	    obsSvc->NotifyObservers(nullptr, "profile-initial-state", nullptr);
(gdb) n
899	        mozilla::components::AppStartup::Service());
(gdb) n
885	        mozilla::services::GetObserverService();
(gdb) n
GeckoLoader::InitEmbedding (aProfilePath=0x555585a310
    "/home/defaultuser/.local/share/org.sailfishos/browser")
    at /usr/src/debug/xulrunner-qt5-91.9.1-1.aarch64/mobile/sailfishos/utils/
    GeckoLoader.cpp:230
230	  LOGF("InitEmbedding successfully");
(gdb) c
Continuing.
[New LWP 16974]
[LWP 16901 exited]
CONSOLE message:
[LWP 16941 exited]
[JavaScript Error: "Unexpected event profile-after-change"
    {file: "resource://gre/modules/URLQueryStrippingListService.jsm" line: 224}]
observe@resource://gre/modules/URLQueryStrippingListService.jsm:224:12

Created LOG for EmbedPrefs
Created LOG for EmbedLiteLayerManager
[...]

What's interesting about this output for me is that it's consistent with a situation where the "profile-after-change" event triggered in nsXREDirProvider.cpp is also the event that causes the error.

Here we see UserAgentOverrideHelper app-startup in the output, followed by the breakpoint being hit. I step through seven lines of C++ code before continuing. After continuing we get the error message "Unexpected event profile-after-change" followed by the Created LOG for EmbedPrefs output.

My next thought is that maybe the problem is that URLQueryStrippingListService.jsm is being initialised too early. According to what I've read in the bug reports and comments in the code, it's the "profile-after-change" event that's supposed to trigger the start up of the URLQueryStrippingListService.jsm module. If so, maybe it's already started when the "profile-after-change" event is triggered and that's why the error is happening.

As a little background, we can see some evidence of this reasoning in this comment that can be found in toolkit/xre/nsXREDirProvider.cpp:

    obsSvc->NotifyObservers(nullptr, "profile-after-change", kStartup);

    // Any component that has registered for the profile-after-change category
    // should also be created at this time.
    (void)NS_CreateServicesFromCategory("profile-after-change", nullptr,
                                        "profile-after-change");

This is from directly before the "profile-after-change" event is triggered. We can see that the URLQueryStrippingListService service is registered to be started by this event in the toolkit/components/antitracking/components.conf file. Notice the categories section:

    {
        'cid': '{afff16f0-3fd2-4153-9ccd-c6d9abd879e4}',
        'contract_ids': ['@mozilla.org/query-stripping-list-service;1'],
        'singleton': True,
        'jsm': 'resource://gre/modules/URLQueryStrippingListService.jsm',
        'constructor': 'URLQueryStrippingListService',
        'categories': {'profile-after-change': 'URLQueryStrippingListService'},
    },

To see whether the module is being started up too early — before the "profile-after-change" event is sent — I put debug output in a few further places. Well I didn't actually use debug output, instead I copied the error generating line and used that. So the output will actually appear as errors in the log.

I placed these error generators all in the URLQueryStrippingListService code in the following places:

1. At the top of the constructor; this should happen at the point when the module is initialised.
2. At the top of the _init() method. This is where the observers are registered.
3. At the top of the observe() method. This will be triggered whenever an event message is received.

With these added here's what happens, starting at the breakpoint, which is the point where the "profile-after-change" event is triggered.

Thread 8 "GeckoWorkerThre" hit Breakpoint 1, nsXREDirProvider::DoStartup
    (this=)
    at /usr/src/debug/xulrunner-qt5-91.9.1-1.aarch64/toolkit/xre/
    nsXREDirProvider.cpp:978
978         obsSvc->NotifyObservers(nullptr, "profile-after-change", kStartup);
(gdb) c
Continuing.
Missing separate debuginfo for /usr/lib64/libsoftokn3.so
Try: zypper install -C "debuginfo(build-id)=932611cf165ab104fa7bae7176d0bfb63368f6bc"
Missing separate debuginfo for /usr/lib64/libfreeblpriv3.so
Try: zypper install -C "debuginfo(build-id)=ea9e4dc0f2a49e2a02ae37540a8561bf4f1ac79a"
[New LWP 18838]
[New LWP 18839]
Missing separate debuginfo for /usr/lib64/libnssckbi.so
Try: zypper install -C "debuginfo(build-id)=c2e22ddaa9e2d7802fd7ff14979ba02fb6508bcd"
Missing separate debuginfo for /usr/lib64/libtasn1.so.6
Try: zypper install -C "debuginfo(build-id)=95f83c2cec19f8b9030e796b6c25c31a10c185e8"
[New LWP 18840]
[LWP 18817 exited]
[New LWP 18841]
CONSOLE message:
[JavaScript Error: "URLQUERYSTRIPPINGLISTSERVICE: constructor"
    {file: "resource://gre/modules/URLQueryStrippingListService.jsm" line: 29}]
URLQueryStrippingListService@resource://gre/modules/
    URLQueryStrippingListService.jsm:29:8

CONSOLE message:
[JavaScript Error: "URLQUERYSTRIPPINGLISTSERVICE: init"
    {file: "resource://gre/modules/URLQueryStrippingListService.jsm" line: 49}]
_init@resource://gre/modules/URLQueryStrippingListService.jsm:49:8
URLQueryStrippingListService@resource://gre/modules/
    URLQueryStrippingListService.jsm:45:30

CONSOLE message:
[JavaScript Error: "URLQUERYSTRIPPINGLISTSERVICE: observe"
    {file: "resource://gre/modules/URLQueryStrippingListService.jsm" line: 217}]
observe@resource://gre/modules/URLQueryStrippingListService.jsm:217:8

CONSOLE message:
[JavaScript Error: "Unexpected event profile-after-change"
    {file: "resource://gre/modules/URLQueryStrippingListService.jsm" line: 227}]
observe@resource://gre/modules/URLQueryStrippingListService.jsm:227:12

Created LOG for EmbedPrefs

The code progresses exactly as we might expected and completely consistent with a model where it's the event which causes the class to be instantiated:

1. On continuing after the breakpoint the constructor is called.
2. Immediately following this the _init() method is called.
3. Immediately following this the "profile-after-change" event is received.

So the module is definitely instantiated after nsXREDirProvider sends out the event. It's initialised before the event is received. Immediately after being initialised the event is received. No other events are received in between these two points.

This means that things appear to be working exactly as expected. So why generate an error? I'm going to have to continue trying to find an answer to this question tomorrow.

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