flypig.co.uk

Yesterday we were looking at the following error:

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

I put a breakpoint and several log outputs lines in the code and established that the same "profile-after-change" event that's causing the URLQueryStrippingListService module to be initialised is also causing the error to fire. Everything about the sequence of events — event message being sent; module initialising; module receiving the event — seems sensible and exactly as I'd expected it to work, apart from the fact that the error is also being generated.

Searching across the Web doesn't bring up an obvious reason for the error. There are two posts that look relevant, but which don't quite provide an answer. The first is on the Mozilla support forum where one user mentions they're seeing the error, while also experiencing pages displaying poorly.

The error is fixed by making a configuration change. What's not clear from the discussion is whether the configuration change stops the error from appearing in the console, or just fixes the rendering problems. I suspect it's just the latter, since with pages rendering correctly I can imagine the user no longer worrying further about the log output.

I did also track down the configuration change to being equivalent to setting the value of the browser.display.document_color_use option in about:config. Changing the value of this didn't have any effect on whether the error is generated on Sailfish OS (and to be honest, I'd have been surprised if it had).

The second page discusses the same error appearing in the Thunderbird console for release 91.0b6. As of now this bug is still open and there's no proposed fix. That makes me think that this error can't be too important.

There are quite a few modules that use the "profile-after-change" event to trigger their initialisation: InstallerPrefs, CrashService, BHRTelemetryService, CrashMonitor, PurgeTrackerService, URLQueryStrippingListService, nsTerminatorTelemetry, nsUpdateTimerManager, SanityTest, formHistoryStartup, nsUpdateServiceStub.

I looked carefully through the code for all these modules and in the majority of cases the "profile-after-change" is specifically handled, usually to perform some startup/initialisation task. In none of the cases apart from URLQueryStrippingListService is there code that would generate an error if the event is received.

I've convinced myself that the current flow is reasonable and that the error is harmless. At least it's harmless enough for Thunderbird to ignore it.

But I don't much like it so I'm going to patch the file like this:

$ git diff
diff --git a/toolkit/components/antitracking/URLQueryStrippingListService.jsm
           b/toolkit/components/antitracking/URLQueryStrippingListService.jsm
index 991fd0d11f0d..b8eb2c25c358 100644
--- a/toolkit/components/antitracking/URLQueryStrippingListService.jsm
+++ b/toolkit/components/antitracking/URLQueryStrippingListService.jsm
@@ -220,6 +220,10 @@ class URLQueryStrippingListService {
         let prefValue = Services.prefs.getStringPref(data, "");
         this._onPrefUpdate(data, prefValue);
         break;
+      case "profile-after-change":
+        if (!!this.initialized) {
+          Cu.reportError(`Unexpected post-init event ${topic}`);
+        }
       default:
         Cu.reportError(`Unexpected event ${topic}`);
     }

This will mask the error as long as the "profile-after-change" event occurs only before the module has initialised. I'm not totally happy with making this change: it doesn't feel like it should be necessary. I don't see evidence of it triggering on my desktop Firefox instance. But this change does really seem reasonable to me.

If you've been following closely you might wonder why this change should work: the this.initialized variable is set in the _init() method and we already established that this gets called before the event is received.

This is all true. Nevertheless by the time the observe() method is called with a "profile-after-change" topic this.initialized still hasn't been set. That's because _init() is an async method that awaits for certain settings to be updated. While it's waiting the observe() method is triggered. After which the _init() method completes, setting the this.initialized variable in the process. If a second "profile-after-change" message were to be received it will now still cause an error. But the first one won't. That shouldn't have any practical effect, except to clean up our log output a little.

I'm going to leave it there for today. Once I've committed these changes and closed the task I'll pick another one to look at for tomorrow.

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