gecko-dev/python/mach/docs/logging.rst

.. _mach_logging:

=======
Logging
=======

Mach configures a built-in logging facility so commands can easily log
data.

What sets the logging facility apart from most loggers you've seen is
that it encourages structured logging. Instead of conventional logging
where simple strings are logged, the internal logging mechanism logs all
events with the following pieces of information:

* A string *action*
* A dict of log message fields
* A formatting string

Essentially, instead of assembling a human-readable string at
logging-time, you create an object holding all the pieces of data that
will constitute your logged event. For each unique type of logged event,
you assign an *action* name.

Depending on how logging is configured, your logged event could get
written a couple of different ways.

JSON Logging
============

Where machines are the intended target of the logging data, a JSON
logger is configured. The JSON logger assembles an array consisting of
the following elements:

* Decimal wall clock time in seconds since UNIX epoch
* String *action* of message
* Object with structured message data

The JSON-serialized array is written to a configured file handle.
Consumers of this logging stream can just perform a readline() then feed
that into a JSON deserializer to reconstruct the original logged
message. They can key off the *action* element to determine how to
process individual events. There is no need to invent a parser.
Convenient, isn't it?

Logging for Humans
==================

Where humans are the intended consumer of a log message, the structured
log message are converted to more human-friendly form. This is done by
utilizing the *formatting* string provided at log time. The logger
simply calls the *format* method of the formatting string, passing the
dict containing the message's fields.

When *mach* is used in a terminal that supports it, the logging facility
also supports terminal features such as colorization. This is done
automatically in the logging layer - there is no need to control this at
logging time.

In addition, messages intended for humans typically prepends every line
with the time passed since the application started.

Logging HOWTO
=============

Structured logging piggybacks on top of Python's built-in logging
infrastructure provided by the *logging* package. We accomplish this by
taking advantage of *logging.Logger.log()*'s *extra* argument. To this
argument, we pass a dict with the fields *action* and *params*. These
are the string *action* and dict of message fields, respectively. The
formatting string is passed as the *msg* argument, like normal.

If you were logging to a logger directly, you would do something like:

.. code-block:: python

   logger.log(logging.INFO, 'My name is {name}',
       extra={'action': 'my_name', 'params': {'name': 'Gregory'}})

The JSON logging would produce something like::

   [1339985554.306338, "my_name", {"name": "Gregory"}]

Human logging would produce something like::

   0.52 My name is Gregory

Since there is a lot of complexity using logger.log directly, it is
recommended to go through a wrapping layer that hides part of the
complexity for you. The easiest way to do this is by utilizing the
LoggingMixin:

.. code-block:: python

   import logging
   from mach.mixin.logging import LoggingMixin

   class MyClass(LoggingMixin):
       def foo(self):
            self.log(logging.INFO, 'foo_start', {'bar': True},
                'Foo performed. Bar: {bar}')