Structured logging

[drothlis]

TODO:

• stbt.debug
• Configuration
• stderr or stdout? A: stderr, otherwise it messes up doctest output.
• Should we run init_logging on import stbt?
• Make all stb-tester code use logging directly, with fine-grained loggers under the stbt logger (e.g. stbt.match).
• Once all stb-tester code is using logging instead of stbt.debug, switch stbt.debug to use the root logger -- so that log messages from the test script don't get logged as stbt messages.
• Deprecate stbt.debug.

[drothlis]

I'm using logging.config.fileConfig so that you can change the logging behaviour just by changing stbt.conf. I had to jump through some hoops to get it working on Python 2. Also, the Python documentation recommends using dictConfig instead of fileConfig in the note here. Nevertheless, this is the easiest way of configuring the logging framework without having to write explicit code in the user's test scripts.

[drothlis]

There's no need to run init_logging for the unit-tests because pytest automatically captures the logging calls. Pytest shows separate sections with "Captured stdout call", "Capturred stderr call", and "Captured log call", so it helps if the tests use logging (rather than print) to see the log messages interleaved in the right order.

[drothlis]

Thoughts on log-levels: INFO should be for high(-ish) level actions, and DEBUG should be for things that happen for every frame (such as the result of every match inside wait_for_match).

"High-level" is relative to the logger; for example in your test script's logger, a high-level action would be "Search for EASTENDERS" but in the "stbt.keyboard" logger a high-level action would be "Navigating from A to H by pressing KEY_DOWN, KEY_RIGHT".

Ultimately you could have some kind of javascripty log-file viewer where you could interactively filter by logger name & level.

[wmanley]

How would you feel about adding a dependency on structlog? Ubuntu 18.04 has 17.2.0

[drothlis]

How would you feel about adding a dependency on structlog? Ubuntu 18.04 has 17.2.0

I thought we could achieve that just via the standard logging module by specifying a custom formatter in the configuration file.

But looking at "Implementing structured logging" from the logging cookbook, it seems we'd also have to change the Python code in every log invocation (or provide our own log functions):
https://docs.python.org/3.6/howto/logging-cookbook.html#implementing-structured-logging

class StructuredMessage(object):
    ...
_ = StructuredMessage   # optional, to improve readability
logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))

[drothlis]

structlog doesn't seem to have the ability to "tee" the output to 2 different streams (e.g. a structured log in json, as well as the human-readable stdout.log). You'd still have to do that in the underlying stdlib logging framework. This implies that the formatting has to be done within the logging framework; see Rendering Using structlog-based Formatters Within logging.

[drothlis]

Alternately we could use structlog.stdlib.render_to_log_kwargs (which puts the structlog kwargs into logging's extra field) and create our own logging.Formatter subclass that formats the keys from extra into the log message. See Rendering Using logging-based Formatters.

[drothlis]

Closing. See #763.