-
Notifications
You must be signed in to change notification settings - Fork 100
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Structured logging #611
base: main
Are you sure you want to change the base?
Structured logging #611
Conversation
I'm using |
There's no need to run |
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 "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. |
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 But looking at "Implementing structured logging" from the
|
|
Alternately we could use |
In future commits I'll make all of stb-tester's code call the logging framework directly (`getLogger("stbt").debug(...)` etc). For now this makes `stbt.debug()` use the Python logging framework, and sets up all the configuration. If you import `stbt` as a library then you'll need to configure the logging framework yourself, e.g. by calling `logging.config.fileConfig` as we do here. If you run stbt via `stbt run` then we call `logging.config.fileConfig` pointing at your stbt.conf files.
…on 2 Python 2's `logging.config.fileConfig` has 2 limitations: * It doesn't accept a `ConfigParser` instance, only a filename or file object. But our config isn't in a single file: it's spread over /etc/stbt/stbt.conf, the ~/.config/stbt/stbt.conf, $STBT_CONFIG_FILE, etc. * It doesn't pass `raw=True` when reading `format` from the ConfigParser. Our ConfigParser doesn't have interpolation disabled, so it complains: > Bad value substitution: option 'format' in section 'formatter_basic' > contains an interpolation key u'name' which is not a valid option > name. Raw value: '%(name)s:%(levelname)s: %(message)s' (It's complaining about ConfigParser interpolation, not logging interpolation.) Arguably we should disable ConfigParser interpolation but that would be a breaking change (technically; I doubt it would actually affect anyone).
Pytest already captures & shows logging calls, similar to how it captures stdout/stderr. It shows each of these in separate sections: "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. Pytest's default log_format is the same as this, but without the timestamp. Pytest's default time format is %H:%M:%S which should be sufficient for unit tests; we don't really need the date or the timezone. Note that this captures all log levels, including DEBUG. If we set "log_level=DEBUG" in pytest.ini, then it *also* logs those calls to stderr and we end up with duplicate logs.
So that the output is interleaved in the correct order with the logging from the `stbt.Keyboard` implementation.
Now that we use the logging framework, our default configuration includes the logger name (stbt.keyboard).
So we can log (internally) using [structlog], but it still gets printed by the stdlib `logging` framework, so that users can configure the output in the same way that they configure their own logging. We expect that users will use `logging` directly, not `structlog`. In future we can "tee" the output from structlog to a structured file (e.g. jsonl) while continuing to print it to stderr.log for human users' consumption. [structlog]: https://www.structlog.org/
We'll have to fix this when we make it possible to import stbt as a library (without going via `stbt run`), too.
Avoids several problems: * I don't have to access protected attribute `structlog.stdlib._NAME_TO_LEVEL`. * Fixes "AttributeError: 'Logger' object has no attribute 'trace'" when structlog calls the underlying `logging` logger. * Fixes "TypeError: _proxy_to_logger() takes at most 3 arguments (4 given)" if I try to call `structlog.get_logger().log(5, msg, *args)` without first initialising structlog (e.g. from pytest; currently we only call `init_logging` from `stbt_run.py`, we don't do it when importing stbt).
Otherwise `stbt.debug` etc. use structlog's default configuration, which is to print everything to stdout. This messes up the doctests' expected output.
Closing. See #763. |
TODO:
init_logging
onimport stbt
?logging
directly, with fine-grained loggers under thestbt
logger (e.g.stbt.match
).logging
instead ofstbt.debug
, switchstbt.debug
to use the root logger -- so that log messages from the test script don't get logged as stbt messages.stbt.debug
.