summaryrefslogtreecommitdiffstats
path: root/testing/mozbase/docs/mozlog.rst
diff options
context:
space:
mode:
Diffstat (limited to '')
-rw-r--r--testing/mozbase/docs/mozlog.rst520
1 files changed, 520 insertions, 0 deletions
diff --git a/testing/mozbase/docs/mozlog.rst b/testing/mozbase/docs/mozlog.rst
new file mode 100644
index 0000000000..63e3614243
--- /dev/null
+++ b/testing/mozbase/docs/mozlog.rst
@@ -0,0 +1,520 @@
+:mod:`mozlog` --- Structured logging for test output
+===============================================================
+
+:py:mod:`mozlog` is a library designed for logging the
+execution and results of test harnesses. The internal data model is a
+stream of JSON-compatible objects, with one object per log entry. The
+default output format is line-based, with one JSON object serialized
+per line.
+
+:py:mod:`mozlog` is *not* based on the stdlib logging
+module, although it shares several concepts with it.
+
+One notable difference between this module and the standard logging
+module is the way that loggers are created. The structured logging
+module does not require that loggers with a specific name are
+singleton objects accessed through a factory function. Instead the
+``StructuredLogger`` constructor may be used directly. However all
+loggers with the same name share the same internal state (the "Borg"
+pattern). In particular the list of handler functions is the same for
+all loggers with the same name.
+
+Typically, you would only instantiate one logger object per
+program. Two convenience methods are provided to set and get the
+default logger in the program.
+
+Logging is threadsafe, with access to handlers protected by a
+``threading.Lock``. However it is `not` process-safe. This means that
+applications using multiple processes, e.g. via the
+``multiprocessing`` module, should arrange for all logging to happen in
+a single process.
+
+Data Format
+-----------
+
+Structured loggers produce messages in a simple format designed to be
+compatible with the JSON data model. Each message is a single object,
+with the type of message indicated by the ``action`` key. It is
+intended that the set of ``action`` values be closed; where there are
+use cases for additional values they should be integrated into this
+module rather than extended in an ad-hoc way. The set of keys present
+on on all messages is:
+
+``action``
+ The type of the message (string).
+
+``time``
+ The timestamp of the message in ms since the epoch (int).
+
+``thread``
+ The name of the thread emitting the message (string).
+
+``pid``
+ The pid of the process creating the message (int).
+
+``source``
+ Name of the logger creating the message (string).
+
+For each ``action`` there are is a further set of specific fields
+describing the details of the event that caused the message to be
+emitted:
+
+``suite_start``
+ Emitted when the testsuite starts running.
+
+ ``tests``
+ A dict of test ids keyed by group. Groups are any logical grouping
+ of tests, for example a manifest, directory or tag. For convenience,
+ a list of test ids can be used instead. In this case all tests will
+ automatically be placed in the 'default' group name. Test ids can
+ either be strings or lists of strings (an example of the latter is
+ reftests where the id has the form [test_url, ref_type, ref_url]).
+ Test ids are assumed to be unique within a given testsuite. In cases
+ where the test list is not known upfront an empty dict or list may
+ be passed (dict).
+
+ ``name``
+ An optional string to identify the suite by.
+
+ ``run_info``
+ An optional dictionary describing the properties of the
+ build and test environment. This contains the information provided
+ by :doc:`mozinfo <mozinfo>`, plus a boolean ``debug`` field indicating
+ whether the build under test is a debug build.
+
+``suite_end``
+ Emitted when the testsuite is finished and no more results will be produced.
+
+``test_start``
+ Emitted when a test is being started.
+
+ ``test``
+ A unique id for the test (string or list of strings).
+
+ ``path``
+ Optional path to the test relative to some base (typically the root of the
+ source tree). Mainly used when ``test`` id is not a path (string).
+
+``test_status``
+ Emitted for a test which has subtests to record the result of a
+ single subtest.
+
+ ``test``
+ The same unique id for the test as in the ``test_start`` message.
+
+ ``subtest``
+ Name of the subtest (string).
+
+ ``status``
+ Result of the test (string enum; ``PASS``, ``FAIL``,
+ ``PRECONDITION_FAILED``, ``TIMEOUT``, ``NOTRUN``)
+
+ ``expected``
+ Expected result of the test. Omitted if the expected result is the
+ same as the actual result (string enum, same as ``status``).
+
+ ``known_intermittent``
+ A list of known intermittent statuses for that test. Omitted if there are
+ no intermittent statuses expected. (items in the list are string enum, same as ``status``)
+
+``test_end``
+ Emitted to give the result of a test with no subtests, or the status
+ of the overall file when there are subtests.
+
+ ``test``
+ The same unique id for the test as in the ``test_start`` message.
+
+ ``status``
+ Either result of the test (if there are no subtests) in which case
+ (string enum ``PASS``, ``FAIL``, ``PRECONDITION_FAILED``,
+ ``TIMEOUT``, ``CRASH``, ``ASSERT``, , ``SKIP``) or the status of
+ the overall file where there are subtests (string enum ``OK``,
+ ``PRECONDITION_FAILED``, ``ERROR``, ``TIMEOUT``, ``CRASH``,
+ ``ASSERT``, ``SKIP``).
+
+ ``expected``
+ The expected status, or omitted if the expected status matches the
+ actual status (string enum, same as ``status``).
+
+ ``known_intermittent``
+ A list of known intermittent statuses for that test. Omitted if there are
+ no intermittent statuses expected. (items in the list are string enum, same as ``status``)
+
+``process_output``
+ Output from a managed subprocess.
+
+ ``process``
+ pid of the subprocess.
+
+ ``command``
+ Command used to launch the subprocess.
+
+ ``data``
+ Data output by the subprocess.
+
+``log``
+ General human-readable logging message, used to debug the harnesses
+ themselves rather than to provide input to other tools.
+
+ ``level``
+ Level of the log message (string enum ``CRITICAL``, ``ERROR``,
+ ``WARNING``, ``INFO``, ``DEBUG``).
+
+ ``message``
+ Text of the log message.
+
+``shutdown``
+ This is a special action that can only be logged once per logger state.
+ It is sent when calling :meth:`StructuredLogger.shutdown` or implicitly
+ when exiting the context manager.
+
+Testsuite Protocol
+------------------
+
+When used for testsuites, the following structured logging messages must be emitted:
+
+ * One ``suite_start`` message before any ``test_*`` messages
+
+ * One ``test_start`` message per test that is run
+
+ * One ``test_status`` message per subtest that is run. This might be
+ zero if the test type doesn't have the notion of subtests.
+
+ * One ``test_end`` message per test that is run, after the
+ ``test_start`` and any ``test_status`` messages for that same test.
+
+ * One ``suite_end`` message after all ``test_*`` messages have been
+ emitted.
+
+The above mandatory events may be interspersed with ``process_output``
+and ``log`` events, as required.
+
+Subtests
+~~~~~~~~
+
+The purpose of subtests is to deal with situations where a single test
+produces more than one result, and the exact details of the number of
+results is not known ahead of time. For example consider a test
+harness that loads JavaScript-based tests in a browser. Each url
+loaded would be a single test, with corresponding ``test_start`` and
+``test_end`` messages. If there can be more than one JS-defined test
+on a page, however, it it useful to track the results of those tests
+separately. Therefore each of those tests is a subtest, and one
+``test_status`` message must be generated for each subtest result.
+
+Subtests must have a name that is unique within their parent test.
+
+Whether or not a test has subtests changes the meaning of the
+``status`` property on the test itself. When the test does not have
+any subtests, this property is the actual test result such as ``PASS``
+or ``FAIL`` . When a test does have subtests, the test itself does not
+have a result as-such; it isn't meaningful to describe it as having a
+``PASS`` result, especially if the subtests did not all pass. Instead
+this property is used to hold information about whether the test ran
+without error. If no errors were detected the test must be given the
+status ``OK``. Otherwise the test may get the status ``ERROR`` (for
+e.g. uncaught JS exceptions), ``TIMEOUT`` (if no results were reported
+in the allowed time) or ``CRASH`` (if the test caused the process
+under test to crash).
+
+StructuredLogger Objects
+------------------------
+
+.. automodule:: mozlog.structuredlog
+ :members: set_default_logger, get_default_logger, LoggerShutdownError
+
+.. autoclass:: StructuredLogger
+ :members: add_handler, remove_handler, handlers, suite_start,
+ suite_end, test_start, test_status, test_end,
+ process_output, critical, error, warning, info, debug,
+ shutdown
+
+.. autoclass:: StructuredLogFileLike
+ :members:
+
+ProxyLogger Objects
+-------------------
+
+Since :func:`mozlog.structuredlog.get_default_logger` return None when
+the default logger is not initialized, it is not possible to directly
+use it at the module level.
+
+With ProxyLogger, it is possible to write the following code: ::
+
+ from mozlog import get_proxy_logger
+
+ LOG = get_proxy_logger('component_name')
+
+
+ def my_function():
+ LOG.info('logging with a module level object')
+
+
+.. note::
+
+ mozlog still needs to be initialized before the first call occurs
+ to a ProxyLogger instance, for example with
+ :func:`mozlog.commandline.setup_logging`.
+
+.. automodule:: mozlog.proxy
+ :members: get_proxy_logger, ProxyLogger
+
+Handlers
+--------
+
+A handler is a callable that is called for each log message produced
+and is responsible for handling the processing of that
+message. The typical example of this is a ``StreamHandler`` which takes
+a log message, invokes a formatter which converts the log to a string,
+and writes it to a file.
+
+.. automodule:: mozlog.handlers
+
+.. autoclass:: BaseHandler
+ :members:
+
+.. autoclass:: StreamHandler
+ :members:
+
+.. autoclass:: LogLevelFilter
+ :members:
+
+.. autoclass:: BufferHandler
+ :members:
+
+Formatters
+----------
+
+Formatters are callables that take a log message, and return either a
+string representation of that message, or ``None`` if that message
+should not appear in the output. This allows formatters to both
+exclude certain items and create internal buffers of the output so
+that, for example, a single string might be returned for a
+``test_end`` message indicating the overall result of the test,
+including data provided in the ``test_status`` messages.
+
+Formatter modules are written so that they can take raw input on stdin
+and write formatted output on stdout. This allows the formatters to be
+invoked as part of a command line for post-processing raw log files.
+
+.. automodule:: mozlog.formatters.base
+
+.. autoclass:: BaseFormatter
+ :members:
+
+.. automodule:: mozlog.formatters.unittest
+
+.. autoclass:: UnittestFormatter
+ :members:
+
+.. automodule:: mozlog.formatters.xunit
+
+.. autoclass:: XUnitFormatter
+ :members:
+
+.. automodule:: mozlog.formatters.html
+
+.. autoclass:: HTMLFormatter
+ :members:
+
+.. automodule:: mozlog.formatters.machformatter
+
+.. autoclass:: MachFormatter
+ :members:
+
+.. automodule:: mozlog.formatters.tbplformatter
+
+.. autoclass:: TbplFormatter
+ :members:
+
+Processing Log Files
+--------------------
+
+The ``mozlog.reader`` module provides utilities for working
+with structured log files.
+
+.. automodule:: mozlog.reader
+ :members:
+
+Integration with argparse
+-------------------------
+
+The `mozlog.commandline` module provides integration with the `argparse`
+module to provide uniform logging-related command line arguments to programs
+using `mozlog`. Each known formatter gets a command line argument of the form
+``--log-{name}``, which takes the name of a file to log to with that format,
+or ``-`` to indicate stdout.
+
+.. automodule:: mozlog.commandline
+ :members:
+
+Simple Examples
+---------------
+
+Log to stdout::
+
+ from mozlog import structuredlog
+ from mozlog import handlers, formatters
+ logger = structuredlog.StructuredLogger("my-test-suite")
+ logger.add_handler(handlers.StreamHandler(sys.stdout,
+ formatters.JSONFormatter()))
+ logger.suite_start(["test-id-1"])
+ logger.test_start("test-id-1")
+ logger.info("This is a message with action='LOG' and level='INFO'")
+ logger.test_status("test-id-1", "subtest-1", "PASS")
+ logger.test_end("test-id-1", "OK")
+ logger.suite_end()
+
+Log with a context manager::
+
+ from mozlog.structuredlog import StructuredLogger
+ from mozlog.handlers import StreamHandler
+ from mozlog.formatters import JSONFormatter
+
+ with StructuredLogger("my-test-suite") as logger:
+ logger.add_handler(StreamHandler(sys.stdout,
+ JSONFormatter()))
+ logger.info("This is an info message")
+
+Populate an ``argparse.ArgumentParser`` with logging options, and
+create a logger based on the value of those options, defaulting to
+JSON output on stdout if nothing else is supplied::
+
+ import argparse
+ from mozlog import commandline
+
+ parser = argparse.ArgumentParser()
+ # Here one would populate the parser with other options
+ commandline.add_logging_group(parser)
+
+ args = parser.parse_args()
+ logger = commandline.setup_logging("testsuite-name", args, {"raw": sys.stdout})
+
+Count the number of tests that timed out in a testsuite::
+
+ from mozlog import reader
+
+ count = 0
+
+ def handle_test_end(data):
+ global count
+ if data["status"] == "TIMEOUT":
+ count += 1
+
+ reader.each_log(reader.read("my_test_run.log"),
+ {"test_end": handle_test_end})
+
+ print count
+
+More Complete Example
+---------------------
+
+This example shows a complete toy testharness set up to used
+structured logging. It is available as `structured_example.py <_static/structured_example.py>`_:
+
+.. literalinclude:: _static/structured_example.py
+
+Each global function with a name starting
+``test_`` represents a test. A passing test returns without
+throwing. A failing test throws a :py:class:`TestAssertion` exception
+via the :py:func:`assert_equals` function. Throwing anything else is
+considered an error in the test. There is also a :py:func:`expected`
+decorator that is used to annotate tests that are expected to do
+something other than pass.
+
+The main entry point to the test runner is via that :py:func:`main`
+function. This is responsible for parsing command line
+arguments, and initiating the test run. Although the test harness
+itself does not provide any command line arguments, the
+:py:class:`ArgumentParser` object is populated by
+:py:meth:`commandline.add_logging_group`, which provides a generic
+set of structured logging arguments appropriate to all tools producing
+structured logging.
+
+The values of these command line arguments are used to create a
+:py:class:`mozlog.StructuredLogger` object populated with the
+specified handlers and formatters in
+:py:func:`commandline.setup_logging`. The third argument to this
+function is the default arguments to use. In this case the default
+is to output raw (i.e. JSON-formatted) logs to stdout.
+
+The main test harness is provided by the :py:class:`TestRunner`
+class. This class is responsible for scheduling all the tests and
+logging all the results. It is passed the :py:obj:`logger` object
+created from the command line arguments. The :py:meth:`run` method
+starts the test run. Before the run is started it logs a
+``suite_start`` message containing the id of each test that will run,
+and after the testrun is done it logs a ``suite_end`` message.
+
+Individual tests are run in the :py:meth:`run_test` method. For each
+test this logs a ``test_start`` message. It then runs the test and
+logs a ``test_end`` message containing the test name, status, expected
+status, and any informational message about the reason for the
+result. In this test harness there are no subtests, so the
+``test_end`` message has the status of the test and there are no
+``test_status`` messages.
+
+Example Output
+~~~~~~~~~~~~~~
+
+When run without providing any command line options, the raw
+structured log messages are sent to stdout::
+
+ $ python structured_example.py
+
+ {"source": "structured-example", "tests": ["test_that_has_an_error", "test_that_fails", "test_expected_fail", "test_that_passes"], "thread": "MainThread", "time": 1401446682787, "action": "suite_start", "pid": 18456}
+ {"source": "structured-example", "thread": "MainThread", "time": 1401446682787, "action": "log", "message": "Running tests", "level": "INFO", "pid": 18456}
+ {"source": "structured-example", "test": "test_that_has_an_error", "thread": "MainThread", "time": 1401446682787, "action": "test_start", "pid": 18456}
+ {"status": "ERROR", "thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_that_has_an_error", "time": 1401446682788, "action": "test_end", "message": "Traceback (most recent call last):\n File \"structured_example.py\", line 61, in run_test\n func()\n File \"structured_example.py\", line 31, in test_that_has_an_error\n assert_equals(2, 1 + \"1\")\nTypeError: unsupported operand type(s) for +: 'int' and 'str'\n", "expected": "PASS"}
+ {"source": "structured-example", "test": "test_that_fails", "thread": "MainThread", "time": 1401446682788, "action": "test_start", "pid": 18456}
+ {"status": "FAIL", "thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_that_fails", "time": 1401446682788, "action": "test_end", "message": "1 not equal to 2", "expected": "PASS"}
+ {"source": "structured-example", "test": "test_expected_fail", "thread": "MainThread", "time": 1401446682788, "action": "test_start", "pid": 18456}
+ {"status": "FAIL", "thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_expected_fail", "time": 1401446682788, "action": "test_end", "message": "4 not equal to 5"}
+ {"source": "structured-example", "test": "test_that_passes", "thread": "MainThread", "time": 1401446682788, "action": "test_start", "pid": 18456}
+ {"status": "PASS", "source": "structured-example", "test": "test_that_passes", "thread": "MainThread", "time": 1401446682789, "action": "test_end", "pid": 18456}
+ {"source": "structured-example", "test": "test_with_known_intermittent", "thread": "MainThread", "time": 1401446682789, "action": "test_start", "pid": 18456}
+ {"status": "FAIL", thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_with_known_intermittent", "time": 1401446682790, "action": "test_end", "expected": "PASS", "known_intermittent": ["FAIL", "TIMEOUT"]}
+ {"action": "suite_end", "source": "structured-example", "pid": 18456, "thread": "MainThread", "time": 1401446682790}
+
+The structured logging module provides a number of command line
+options::
+
+ $ python structured_example.py --help
+
+ usage: structured_example.py [-h] [--log-unittest LOG_UNITTEST]
+ [--log-raw LOG_RAW] [--log-html LOG_HTML]
+ [--log-xunit LOG_XUNIT]
+ [--log-mach LOG_MACH]
+
+ optional arguments:
+ -h, --help show this help message and exit
+
+ Output Logging:
+ Options for logging output. Each option represents a possible logging
+ format and takes a filename to write that format to, or '-' to write to
+ stdout.
+
+ --log-unittest LOG_UNITTEST
+ Unittest style output
+ --log-raw LOG_RAW Raw structured log messages
+ --log-html LOG_HTML HTML report
+ --log-xunit LOG_XUNIT
+ xUnit compatible XML
+ --log-mach LOG_MACH Human-readable output
+
+In order to get human-readable output on stdout and the structured log
+data to go to the file ``structured.log``, we would run::
+
+ $ python structured_example.py --log-mach=- --log-raw=structured.log
+
+ 0:00.00 SUITE_START: MainThread 4
+ 0:01.00 LOG: MainThread INFO Running tests
+ 0:01.00 TEST_START: MainThread test_that_has_an_error
+ 0:01.00 TEST_END: MainThread Harness status ERROR, expected PASS. Subtests passed 0/0. Unexpected 1
+ 0:01.00 TEST_START: MainThread test_that_fails
+ 0:01.00 TEST_END: MainThread Harness status FAIL, expected PASS. Subtests passed 0/0. Unexpected 1
+ 0:01.00 TEST_START: MainThread test_expected_fail
+ 0:02.00 TEST_END: MainThread Harness status FAIL. Subtests passed 0/0. Unexpected 0
+ 0:02.00 TEST_START: MainThread test_that_passes
+ 0:02.00 TEST_END: MainThread Harness status PASS. Subtests passed 0/0. Unexpected 0
+ 0:02.00 SUITE_END: MainThread