diff --git a/xpcom/docs/logging.rst b/xpcom/docs/logging.rst index e96e7781023a..0249b0e2fa17 100644 --- a/xpcom/docs/logging.rst +++ b/xpcom/docs/logging.rst @@ -1,7 +1,352 @@ Gecko Logging ============= -A minimal C++ logging framework is provided for use in core Gecko code. It is enabled for all builds and is thread-safe. +A minimal C++ logging framework is provided for use in core Gecko code. It is +enabled for all builds and is thread-safe. + +This page covers enabling logging for particular logging module, configuring +the logging output, and how to use the logging facilities in native code. + +Enabling and configuring logging +++++++++++++++++++++++++++++++++ + +Caveat: sandboxing when logging to a file +----------------------------------------- + +A sandboxed content process cannot write to ``stderr`` or any file. The easiest +way to log these processes is to disable the content sandbox by setting the +preference ``security.sandbox.content.level`` to ``0``, or setting the environment +variable ``MOZ_DISABLE_CONTENT_SANDBOX`` to ``1``. + +On Windows, you can still see child process messages by using DOS (not the +``MOZ_LOG_FILE`` variable defined below) to redirect output to a file. For +example: ``MOZ_LOG="CameraChild:5" mach run >& my_log_file.txt`` will include +debug messages from the camera's child actor that lives in a (sandboxed) content +process. + +Logging to the Firefox Profiler +------------------------------- + +When a log statement is logged on a thread and the `Firefox Profiler +`_ is profiling that thread, the log statements is +recorded as a profiler marker. + +This allows getting logs alongside profiler markers and lots of performance +and contextual informations, in a way that doesn't require disabling the +sandbox, and works accross all processes. + +The profile can be downloaded and shared e.g. via Bugzilla or email, or +uploaded, and the logging statements will be visible either in the marker chart +or the marker table. + +While it is possible to manually configure logging module and start the profiler +with the right set of threads to profile, ``about:logging`` makes this task a lot +simpler and error-proof. + + +The ``MOZ_LOG`` syntax +---------------------- + +Logging is configured using a special but simple syntax: which module should be +enabled, at which level, and what logging options should be enabled or disabled. + +The syntax is a list of terms, separated by commas. There are two types of +terms: + +- A log module and its level, separated by a colon (``:``), such as + ``example_module:5`` to enable the module ``example_module`` at logging level + ``5`` (verbose). This `searchfox query + `_ + returns the complete list of modules available. +- A special string in the following table, to configure the logging behaviour. + Some configuration switch take an integer parameter, in which case it's + separated from the string by a colon (``:``). Most switches only apply in a + specific output context, noted in the **Context** column. + ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| Special module name | Context | Action | ++======================+=========+===========================================================================================+ +| append | File | Append new logs to existing log file. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| sync | File | Print each log synchronously, this is useful to check behavior in real time or get logs | +| | | immediately before crash. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| raw | File | Print exactly what has been specified in the format string, without the | +| | | process/thread/timestamp, etc. prefix. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| timestamp | File | Insert timestamp at start of each log line. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| rotate:**N** | File | | This limits the produced log files' size. Only most recent **N megabytes** of log data | +| | | | is saved. We rotate four log files with .0, .1, .2, .3 extensions. Note: this option | +| | | | disables 'append' and forces 'timestamp'. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| maxsize:**N** | File | Limit the log to **N** MB. Only work in append mode. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| prependheader | File | Prepend a simple header while distinguishing logging. Useful in append mode. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ +| profilerstacks | Profiler| | When profiling with the Firefox Profiler and log modules are enabled, capture the call | +| | | | stack for each log statement. | ++----------------------+---------+-------------------------------------------------------------------------------------------+ + +This syntax is used for most methods of enabling logging, with the exception of +settings preferences directly, see :ref:`this section ` for directions. + + +Enabling Logging +---------------- + +Enabling logging can be done in a variety of ways: + +- via environment variables +- via command line switches +- using ``about:config`` preferences +- using ``about:logging`` + +The first two allow logging from the start of the application and are also +useful in case of a crash (when ``sync`` output is requested, this can also be +done with ``about:config`` as well to a certain extent). The last two +allow enabling and disabling logging at runtime and don't require using the +command-line. + +By default all logging output is disabled. + +Enabling logging using ``about:logging`` +'''''''''''''''''''''''''''''''''''''''' + +``about:logging`` allows enabling logging by entering a ``MOZ_LOG`` string in the +text input, and validating. + +Options allow logging to a file or using the Firefox Profiler, that can be +started and stopped right from the page. + +Logging presets for common scenarios are available in a drop-down. They can be +associated with a profiler preset. + +It is possible, via URL parameters, to select a particular logging +configuration, or to override certain parameters in a preset. This is useful to +ask a user to gather logs efficiently without having to fiddle with prefs and/or +environment variable. + +URL parameters are described in the following table: + ++---------------------+---------------------------------------------------------------------------------------------+ +| Parameter | Description | ++=====================+=============================================================================================+ +| ``preset`` | a `logging preset `_ | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``logging-preset`` | alias for ``preset`` | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``modules`` | a string in ``MOZ_LOG`` syntax | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``module`` | alias for ``modules`` | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``threads`` | a list of threads to profile, overrides what a profiler preset would have picked | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``thread`` | alias for ``threads`` | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``output`` | either ``profiler`` or ``file`` | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``output-type`` | alias for ``output`` | ++---------------------+---------------------------------------------------------------------------------------------+ +| ``profiler-preset`` | a `profiler preset `_ | ++---------------------+---------------------------------------------------------------------------------------------+ + +If a preset is selected, then ``threads`` or ``modules`` can be used to override the +profiled threads or logging modules enabled, but keeping other aspects of the +preset. If no preset is selected, then a generic profiling preset is used, +``firefox-platform``. For example: + +:: + + about:logging?output=profiler&preset=media-playback&modules=cubeb:4,AudioSinkWrapper:4:AudioSink:4 + +will profile the threads in the ``Media`` profiler preset, but will only log +specific log modules (instead of the `long list +`_ +in the ``media-playback`` preset). In addition, it disallows logging to a file. + +Enabling logging using environment variables +'''''''''''''''''''''''''''''''''''''''''''' + +On UNIX, setting and environment variable can be done in a variety of ways + +:: + + set MOZ_LOG="example_logger:3" + export MOZ_LOG="example_logger:3" + MOZ_LOG="example_logger:3" ./mach run + +In the Windows Command Prompt (``cmd.exe``), don't use quotes: + +:: + + set MOZ_LOG=example_logger:3 + +If you want this on GeckoView example, use the following adb command to launch process: + +:: + + adb shell am start -n org.mozilla.geckoview_example/.GeckoViewActivity --es env0 "MOZ_LOG=example_logger:3" + +There are special module names to change logging behavior. You can specify one or more special module names without logging level. + +For example, if you want to specify ``sync``, ``timestamp`` and ``rotate``: + +:: + + set MOZ_LOG="example_logger:3,timestamp,sync,rotate:10" + +Enabling logging usually outputs the logging statements to the terminal. To +have the logs written to a file instead (one file per process), the environment +variable ``MOZ_LOG_FILE`` can be used. Logs will be written at this path +(either relative or absolute), suffixed by a process type and its PID. +``MOZ_LOG`` files are text files and have the extension ``.moz_log``. + +For example, setting: + +:: + + set MOZ_LOG_FILE="firefox-logs" + +can create a number of files like so: + +:: + + firefox-log-main.96353.moz_log + firefox-log-child.96354.moz_log + +respectively for a parent process of PID 96353 and a child process of PID +96354. + +Enabling logging using command-line flags +''''''''''''''''''''''''''''''''''''''''' + +The ``MOZ_LOG`` syntax can be used with the command line switch on the same +name, and specifying a file with ``MOZ_LOG_FILE`` works in the same way: + +:: + + ./mach run -MOZ_LOG=timestamp,rotate:200,example_module:5 -MOZ_LOG_FILE=%TEMP%\firefox-logs + +will enable verbose (``5``) logging for the module ``example_module``, with +timestamp prepended to each line, rotate the logs with 4 files of each 50MB +(for a total of 200MB), and write the output to the temporary directory on +Windows, with name starting with ``firefox-logs``. + +.. _Enabling logging using preferences: + +Enabling logging using preferences +'''''''''''''''''''''''''''''''''' + +To adjust the logging after Firefox has started, you can set prefs under the +`logging.` prefix. For example, setting `logging.foo` to `3` will set the log +module `foo` to start logging at level 3. A number of special prefs can be set, +described in the table below: + ++-------------------------------------+------------+-------------------------------+--------------------------------------------------------+ +| Preference name | Preference | Preference value | Description | ++=====================================+============+===============================+========================================================+ +| ``logging.config.clear_on_startup`` | bool | -- | Whether to clear all prefs under ``logging.`` | ++-------------------------------------+------------+-------------------------------+--------------------------------------------------------+ +| ``logging.config.LOG_FILE`` | string | A path (relative or absolute) | The path to which the log files will be written. | ++-------------------------------------+------------+-------------------------------+--------------------------------------------------------+ +| ``logging.config.add_timestamp`` | bool | -- | Whether to prefix all lines by a timestamp. | ++-------------------------------------+------------+-------------------------------+--------------------------------------------------------+ +| ``logging.config.sync`` | bool | -- | Whether to flush the stream after each log statements. | ++-------------------------------------+------------+-------------------------------+--------------------------------------------------------+ +| ``logging.config.profilerstacks`` | bool | -- | | When logging to the Firefox Profiler, whether to | +| | | | | include the call stack in each logging statement. | ++-------------------------------------+------------+-------------------------------+--------------------------------------------------------+ + +Enabling logging in Rust code +----------------------------- + +We're gradually adding more Rust code to Gecko, and Rust crates typically use a +different approach to logging. Many Rust libraries use the `log +`_ crate to log messages, which works together with +`env_logger `_ at the application level to control +what's actually printed via `RUST_LOG`. + +You can set an overall logging level, though it could be quite verbose: + +:: + + set RUST_LOG="debug" + +You can also target individual modules by path: + +:: + + set RUST_LOG="style::style_resolver=debug" + +.. note:: + For Linux/MacOS users, you need to use `export` rather than `set`. + +.. note:: + Sometimes it can be useful to only log child processes and ignore the parent + process. In Firefox 57 and later, you can use `RUST_LOG_CHILD` instead of + `RUST_LOG` to specify log settings that will only apply to child processes. + +The `log` crate lists the available `log levels `_: + ++-----------+---------------------------------------------------------------------------------------------------------+ +| Log Level | Purpose | ++===========+=========================================================================================================+ +| error | Designates very serious errors. | ++-----------+---------------------------------------------------------------------------------------------------------+ +| warn | Designates hazardous situations. | ++-----------+---------------------------------------------------------------------------------------------------------+ +| info | Designates useful information. | ++-----------+---------------------------------------------------------------------------------------------------------+ +| debug | Designates lower priority information. | ++-----------+---------------------------------------------------------------------------------------------------------+ +| trace | Designates very low priority, often extremely verbose, information. | ++-----------+---------------------------------------------------------------------------------------------------------+ + +It is common for debug and trace to be disabled at compile time in release builds, so you may need a debug build if you want logs from those levels. + +Check the `env_logger `_ docs for more details on logging options. + +Additionally, a mapping from `RUST_LOG` is available. When using the `MOZ_LOG` +syntax, it is possible to enable logging in rust crate using a similar syntax: + +:: + + MOZ_LOG=rust_crate_name::*:4 + +will enable `debug` logging for all log statements in the crate +``rust_crate_name``. + +`*` can be replaced by a series of modules if more specificity is needed: + +:: + + MOZ_LOG=rust_crate_name::module::submodule:4 + +will enable `debug` logging for all log statements in the sub-module +``submodule`` of the module ``module`` of the crate ``rust_crate_name``. + + +A table mapping Rust log levels to `MOZ_LOG` log level is available below: + ++----------------+---------------+-----------------+ +| Rust log level | MOZ_LOG level | Numerical value | ++================+===============+=================+ +| off | Disabled | 0 | ++----------------+---------------+-----------------+ +| error | Error | 1 | ++----------------+---------------+-----------------+ +| warn | Warning | 2 | ++----------------+---------------+-----------------+ +| info | Info | 3 | ++----------------+---------------+-----------------+ +| debug | Debug | 4 | ++----------------+---------------+-----------------+ +| trace | Verbose | 5 | ++----------------+---------------+-----------------+ + +Working with ``MOZ_LOG`` in the code +++++++++++++++++++++++++++++++++++++ Declaring a Log Module ---------------------- @@ -88,114 +433,3 @@ Example Usage MOZ_LOG(sLogger, LogLevel::Error, ("i should be 10!")); } } - -Enabling Logging ----------------- - -The log level for a module is controlled by setting an environment variable before launching the application. It can also be adjusted by setting prefs. By default all logging output is disabled. - -:: - - set MOZ_LOG="example_logger:3" - -In the Windows Command Prompt (`cmd.exe`), don't use quotes: - -:: - - set MOZ_LOG=example_logger:3 - -If you want this on GeckoView example, use the following adb command to launch process: - -:: - - adb shell am start -n org.mozilla.geckoview_example/.GeckoViewActivity --es env0 "MOZ_LOG=example_logger:3" - -There are special module names to change logging behavior. You can specify one or more special module names without logging level. - -+-------------------------+-------------------------------------------------------------------------------------------+ -| Special module name | Action | -+=========================+===========================================================================================+ -| append | Append new logs to existing log file. | -+-------------------------+-------------------------------------------------------------------------------------------+ -| sync | Print each log synchronously, this is useful to check behavior in real time or get logs | -| | immediately before crash. | -+-------------------------+-------------------------------------------------------------------------------------------+ -| raw | Print exactly what has been specified in the format string, without the | -| | process/thread/timestamp, etc. prefix. | -+-------------------------+-------------------------------------------------------------------------------------------+ -| timestamp | Insert timestamp at start of each log line. | -+-------------------------+-------------------------------------------------------------------------------------------+ -| rotate: **N** | | This limits the produced log files' size. Only most recent **N megabytes** of log data | -| | | is saved. We rotate four log files with .0, .1, .2, .3 extensions. Note: this option | -| | | disables 'append' and forces 'timestamp'. | -+-------------------------+-------------------------------------------------------------------------------------------+ - -For example, if you want to specify `sync`, `timestamp` and `rotate`: - -:: - - set MOZ_LOG="example_logger:3,timestamp,sync,rotate:10" - -To adjust the logging after Firefox has started, you can set prefs under the `logging.` prefix. For example, setting `logging.foo` to `3` will set the log module `foo` to start logging at level 3. The special boolean prefs `logging.config.sync` and `logging.config.add_timestamp` can be used to control the `sync` and `timestamp` properties described above. - -.. warning:: - A sandboxed content process cannot write to stderr or any file. The easiest way to log these processes is to disable the content sandbox by setting the preference `security.sandbox.content.level` to `0`. On Windows, you can still see child process messages by using DOS (not the `MOZ_LOG_FILE` variable defined below) to redirect output to a file. For example: `MOZ_LOG="CameraChild:5" mach run >& my_log_file.txt` will include debug messages from the camera's child actor that lives in a (sandboxed) content process. - -Redirecting logging output to a file ------------------------------------- - -Logging output can be redirected to a file by passing its path via an environment variable. - -.. note:: - By default logging output goes to `stderr`. - -:: - - set MOZ_LOG_FILE="log.txt" - -The `rotate` and `append` options described above only apply when logging to a file. - -The special pref `logging.config.LOG_FILE` can be set at runtime to change the log file being output to. - -Logging Rust ------------- - -We're gradually adding more Rust code to Gecko, and Rust crates typically use a different approach to logging. Many Rust libraries use the `log `_ crate to log messages, which works together with `env_logger `_ at the application level to control what's actually printed via `RUST_LOG`. - -You can set an overall logging level, though it could be quite verbose: - -:: - - set RUST_LOG="debug" - -You can also target individual modules by path: - -:: - - set RUST_LOG="style::style_resolver=debug" - -.. note:: - For Linux/MacOS users, you need to use `export` rather than `set`. - -.. note:: - Sometimes it can be useful to only log child processes and ignore the parent process. In Firefox 57 and later, you can use `RUST_LOG_CHILD` instead of `RUST_LOG` to specify log settings that will only apply to child processes. - -The `log` crate lists the available `log levels `_: - -+-----------+---------------------------------------------------------------------------------------------------------+ -| Log Level | Purpose | -+===========+=========================================================================================================+ -| error | Designates very serious errors. | -+-----------+---------------------------------------------------------------------------------------------------------+ -| warn | Designates hazardous situations. | -+-----------+---------------------------------------------------------------------------------------------------------+ -| info | Designates useful information. | -+-----------+---------------------------------------------------------------------------------------------------------+ -| debug | Designates lower priority information. | -+-----------+---------------------------------------------------------------------------------------------------------+ -| trace | Designates very low priority, often extremely verbose, information. | -+-----------+---------------------------------------------------------------------------------------------------------+ - -It is common for debug and trace to be disabled at compile time in release builds, so you may need a debug build if you want logs from those levels. - -Check the `env_logger `_ docs for more details on logging options.