mirror of
https://repo.dactyloidae.xyz/Dactyloidae/UXP.git
synced 2026-10-13 18:57:29 +09:00
import FIREFOX_52_6_0esr_RELEASE from mozilla-esr52 hg repo
This commit is contained in:
Roy Tam
commit
dcd9973243
150858 changed files with 23884658 additions and 0 deletions
486
testing/mozbase/docs/mozlog.rst
Normal file
486
testing/mozbase/docs/mozlog.rst
Normal file
|
|
@ -0,0 +1,486 @@
|
|||
: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 list of test ids. 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]) and are assumed to be unique
|
||||
within a given testsuite. In cases where the test list is not
|
||||
known upfront an empty list may be passed (list).
|
||||
|
||||
``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``, ``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``).
|
||||
|
||||
``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``, ``TIMEOUT``, ``CRASH``,
|
||||
``ASSERT``, ``SKIP``) or the status of the overall file where
|
||||
there are subtests (string enum ``OK``, ``ERROR``, ``TIMEOUT``,
|
||||
``CRASH``, ``ASSERT``, ``SKIP``).
|
||||
|
||||
``expected``
|
||||
The expected status, or omitted if the expected status matches the
|
||||
actual status (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.
|
||||
|
||||
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
|
||||
seperately. 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
|
||||
|
||||
.. 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
|
||||
|
||||
.. 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()
|
||||
|
||||
|
||||
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 avaliable 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}
|
||||
{"action": "suite_end", "source": "structured-example", "pid": 18456, "thread": "MainThread", "time": 1401446682789}
|
||||
|
||||
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
|
||||
Loading…
Add table
Add a link
Reference in a new issue