Introducing about:logging

[Paul Adenot]

All,

A new about: page, about:logging, has been extracted from its previous location at about:networking, improved, and is now available in current Beta.

It makes gathering MOZ_LOG output very easy compared to the other ways of enabling logging, especially for end users, but I'm sure that Firefox developers will find it useful. In particular, it allows gathering logs at runtime, without restarting the browser, and without disabling the sandbox, using the Firefox Profiler. This was possible previously, but was too hard to use, again, especially for end users.

Here's a 40 seconds video demo that shows the basic functionality: gathering logs from various modules related to media playback:

https://paul.cx/public/about-logging-presentation.webm

Here is an explanation of the video, with timestamps:

- At 0:00, a new tab is opened and about:logging is entered in the address bar, loading this new page

- At 0:04, the logging preset "Media playback" is selected in the dropdown -- it is straightforward to add a new logging preset [2], it's the same list of modules we've been using for years. By default, the page is set to log to the Firefox Profiler, but it can also log to files by choosing the option.

- At 0:06, the button "Start logging" is clicked. Logging is now enabled. Since we're logging to the Firefox Profiler, the profiler button is added to the toolbar, and it's clear that profiling is enabled.

- At 0:08, another tab is opened, and a YouTube video is loaded, I start playback, as if there was an issue that I wanted to reproduce -- the video plays for a few seconds

- At 0:18, I switch back to the about:logging tab, and click "Stop logging". The profiler button now shows that profiling has stopped

- At 0:20, after a few milliseconds, a Firefox Profiler tab opens, containing a profile, and our logs, as markers. I then navigate to a thread of interest (multiple threads can be selected at once, the logs messages being merged as expected)

- At 0:28, I navigate to the markers list and start filtering the markers list, so that it only contains MOZ_LOG statements

- At 0:35, I pretend to have found a log message of interest, and I clear the filter to get some context, with all the other markers

The profiles can be shared as usual, directly uploaded or stored locally, the log message are just regular markers.

about:logging sports a number of other features, that are documented in an overhauled Gecko Logging [0] documentation page, but here's a few assorted info that can be useful:

• It is possible to customize any aspect of the logging behavior using URL parameters, e.g. opening the page with about:logging?modules=cubeb:5,MediaDecoderStateMachine:4&output=profiler&profilerpreset=media will lock most of the options on the page, and more or less only allow starting and stopping the log. This is useful to ask users to reproduce a bug, and get exactly the right logs [3].
  
• It is possible for a preset to be associated with specific threads or a profiler preset to have a combined profiler / logging view. It is also possible to get stacks for each logging statements, by adding profilermarkers to the module list. This often allows tracking down the path the code took to arrive to a particular error
  
• Logging to a file: this still works as usual, with the same sandbox problems we've always had (I'm planning to add a warning when sandboxing is enabled).
  
• Logging via prefs/environment variables/command line arguments still works like it always has
• Logging statements are only recorded in the profile if the thread is being profiled, so please adjust your thread list or profiler presets accordingly for the best experience.
  
• It doesn't really work on mobile, but it really should, this needs to be investigated
  
• You can log lots of messages without fear. In the media team, we're logging thousands of messages per second and it's fine. If you're slowed down by logging, we have solutions (asynchronous lock-free logging)
  

Please file bugs blocking about_logging [1] for improvements, and more importantly please add your logging presets to the file aboutLogging.js [2] so we can all debug efficiently. The design is quite bad and the UX isn't what it could be, and that will be improved, but I wanted to have something working before having something beautiful.

It's already useful, but I'm sure it can be even better, allowing all of us to get good information about hard-to-reproduce problems in the field, directly from users, without having to ask them to fiddle with the terminal or worse, have them mess with dangerous sandboxing prefs.

Best,

Paul.

[0]: https://firefox-source-docs.mozilla.org/xpcom/logging.html#enabling-logging-using-about-logging

[1]: https://bugzilla.mozilla.org/show_bug.cgi?id=about_logging

[2]: https://searchfox.org/mozilla-central/source/toolkit/content/aboutLogging.js#40

[3]: In our experience in the media team, it's pretty rare that folks that can reproduce a problem follow the numerous steps to get profiles, and when they did, they often made mistakes, giving us empty files or otherwise useless information, because the process of gathering logs was to complicated. However we've had very little issues getting performance profiles, especially now that it supports presets.