classification
Title: add unittest assertion for logging
Type: enhancement Stage: resolved
Components: Library (Lib) Versions: Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: ezio.melotti, michael.foord, pitrou, python-dev, r.david.murray, vinay.sajip
Priority: normal Keywords: patch

Created on 2013-09-05 20:26 by pitrou, last changed 2013-09-14 17:46 by pitrou. This issue is now closed.

Files
File name Uploaded Description Edit
assertlogs.patch pitrou, 2013-09-06 20:13 review
assertlogs2.patch pitrou, 2013-09-13 20:20 review
Messages (15)
msg197022 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-05 20:26
It is sometimes useful to check for the log messages emitted by some piece of code (especially a library). Would it be a good idea to add a dedicated assertion method for that? I would propose the following API:


with self.assertLogging("logger.name", level="WARN") as cm:
    ...

The `cm` context manager could give access to all the log records and formatted output lines for the given logger name (and children) and at least the given logging level. I have something like that here, except not with a dedicated assertion method:
https://bitbucket.org/optiflowsrd/obelus/src/c2a2f78068123264adde8cc3ece4889c61773f00/obelus/test/__init__.py?at=default#cl-20
msg197023 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2013-09-05 20:42
I have project in which that would be useful, so +1 from me for the general concept.
msg197029 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-09-05 21:43
I agree a context manager would be useful. Note that I have already provided a Handler subclass (TestHandler) as well as a Matcher class which allows matching of LogRecords, and which can be used in assertions. These are in test.support as they were originally intended for Python's own tests, but could be moved to the logging package if they are considered more generally useful.

See this for how to use them:

http://plumberjack.blogspot.co.uk/2010/09/unit-testing-and-logging.html
msg197034 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-09-05 22:16
Whoops, meant to say "... moved to the unittest package ...".
msg197103 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-06 20:13
Proposed patch with an assertLogs() method.
msg197120 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2013-09-06 22:54
So making assertions about logging is very common, but I *always* do this by just mocking out the logger and making an assertion about the call. It's trivially easy to do.
msg197122 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-07 00:10
> So making assertions about logging is very common, but I *always* do
> this by just mocking out the logger and making an assertion about the
> call. It's trivially easy to do.

Only works if you test the exact logger that will be triggered, rather
than e.g. a child in the hierarchy (and the exact logging method, for
that matter, too).
msg197123 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2013-09-07 00:21
Do you have a lot of circumstances where you want to test logging but you don't know the specific logger and method called? That's not a situation I've been in.
msg197124 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-07 00:26
> Do you have a lot of circumstances where you want to test logging but
> you don't know the specific logger and method called? That's not a
> situation I've been in.

I have a lot of circumstances where I do not *care* about the specific
logger (as long as it's somewhere in a subhierarchy) and the specific
level (as long as it's e.g. a warning or above).
msg197129 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2013-09-07 02:20
Exactly.  It is the difference between black box testing and white box testing.  IMO mock, while a great tool, should be used with caution, because it tends to lead to white box testing.
msg197212 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2013-09-08 02:13
The patch and approach look good to me (with docs needed).

Note, personally I would not use a leading underscore for the assertion methods (in the tests) _assertNoStderr and _assertLogRecords.
msg197636 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-13 19:53
Question: should the default level threshold be INFO or WARNING?
My initial patch uses INFO, but WARNING might be better since that's also logging's default level filter when not configured.
msg197642 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-13 20:20
Here is an updated patch:
- documentation added
- tests improved a bit and style fixed (removed leading underscores on helper methods)
msg197722 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-09-14 17:42
David told me he was in favour of keeping INFO the default, so I'll leave it like that.
msg197723 - (view) Author: Roundup Robot (python-dev) Date: 2013-09-14 17:45
New changeset 4f5815747f58 by Antoine Pitrou in branch 'default':
Issue #18937: Add an assertLogs() context manager to unittest.TestCase to ensure that a block of code emits a message using the logging module.
http://hg.python.org/cpython/rev/4f5815747f58
History
Date User Action Args
2013-09-14 17:46:29pitrousetstatus: open -> closed
resolution: fixed
stage: resolved
2013-09-14 17:45:53python-devsetnosy: + python-dev
messages: + msg197723
2013-09-14 17:42:12pitrousetmessages: + msg197722
2013-09-13 20:20:43pitrousetfiles: + assertlogs2.patch

messages: + msg197642
2013-09-13 19:53:38pitrousetmessages: + msg197636
2013-09-08 02:13:32michael.foordsetmessages: + msg197212
2013-09-07 02:20:20r.david.murraysetmessages: + msg197129
2013-09-07 00:26:07pitrousetmessages: + msg197124
2013-09-07 00:21:20michael.foordsetmessages: + msg197123
2013-09-07 00:10:40pitrousetmessages: + msg197122
2013-09-06 22:54:05michael.foordsetmessages: + msg197120
2013-09-06 20:13:55pitrousetfiles: + assertlogs.patch
keywords: + patch
messages: + msg197103
2013-09-05 22:16:17vinay.sajipsetmessages: + msg197034
2013-09-05 21:43:36vinay.sajipsetmessages: + msg197029
2013-09-05 20:42:40r.david.murraysetnosy: + r.david.murray
messages: + msg197023
2013-09-05 20:26:01pitroucreate