Log exceptions in tests to stderr #10657
Conversation
This makes it easy to see errors in background processes when you're writing unit tests. Otherwise, you have to know/remember to look at the test logs in `_trial_temp`.
tests/test_utils/logging_setup.py
Outdated
| @@ -35,7 +36,8 @@ def emit(self, record): | |||
| def setup_logging(): | |||
| """Configure the python logging appropriately for the tests. | |||
|
|
|||
| (Logs will end up in _trial_temp.) | |||
| Logs will end up in _trial_temp. Exceptions are additionally | |||
There was a problem hiding this comment.
Not everything logged at logger.error is an exception! s/exceptions/errors/.
Likewise in the changelog, and the name of the handler.
tests/test_utils/logging_setup.py
Outdated
| handler.addFilter(LoggingContextFilter()) | ||
| root_logger.addHandler(handler) | ||
| to_twisted_handler.setFormatter(formatter) | ||
| to_twisted_handler.addFilter(LoggingContextFilter()) |
There was a problem hiding this comment.
I think this is redundant, as of #8051. (If it's not redundant, we need to do it for the other handler too.)
There was a problem hiding this comment.
Alright. I propose to test if this is redundant by
- removing filter here
- changing LoggingContextFilter to have some obvious side effect
- trigger the new log-to-stderr behaviour, and look for the side effect
There was a problem hiding this comment.
Appears to be needed. Otherwise the call to debug in synapse/metrics/init.py:596 will fail because the record doesn't have a "request" field.
|
I'm a bit concerned that this makes the test output hard to parse - there's actually quite a lot of stuff logged at ERROR which is expected in the tests, and this makes it look like things are failing when they're not. Might be worth getting opinions from the rest of the team, in the room? |
|
(on the other hand, possibly a bunch of those things logged at ERROR shouldn't be...) |
|
Don't think anyone was super keen on this, so I'll close this down. Maybe something simpler would suffice. (If a test fails, print out "check homeserver.log in _trial_temp" in bright yellow) |
|
Argh. Just lost about an hour to this again. Can we do better? I'm guessing somewhere high up we catch any remaining uncaught exceptions and If the concern is "but some tests are supposed to cause exceptions", in the past I've used pytest.raises to allow (and inspect!) that behaviour. |
|
uncaught exceptions will cause a test to fail. |
|
(I think the problem is that the exceptions being logged are caught) It would be instructive to see the sorts of errors that you are seeing being logged that would have been useful to make a test fail. Then we can see where it is being caught, and whether it would make sense to stop catching it during tests. |
This makes it easy to see errors in background processes when you're
writing unit tests. Otherwise, you have to know/remember to look at the
test logs in
_trial_temp.