/
logging.txt
443 lines (338 loc) · 13.2 KB
/
logging.txt
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
Testing logging
===============
.. currentmodule:: testfixtures
Python includes a :mod:`logging` package, and while it is widely used, many
people assume that logging calls do not need to be tested or find the prospect too daunting.
To help with this, TestFixtures allows you to easily capture the
output of calls to Python's logging framework and make sure they were
as expected.
.. note:: The :class:`LogCapture` class is useful for checking that
your code logs the right messages. If you want to check that
the configuration of your handlers is correct, please see
the :ref:`section <check-log-config>` below.
Methods of capture
------------------
There are three different techniques for capturing messages logged to
the Python logging framework, depending on the type of test you are
writing. They are all described in the sections below.
The context manager
~~~~~~~~~~~~~~~~~~~
If you're using a version of Python where the ``with`` keyword is
available, the context manager provided by TestFixtures can be used:
>>> import logging
>>> from testfixtures import LogCapture
>>> with LogCapture() as l:
... logger = logging.getLogger()
... logger.info('a message')
... logger.error('an error')
For the duration of the ``with`` block, log messages are captured. The
context manager provides a check method that raises an exception if
the logging wasn't as you expected:
>>> l.check(
... ('root', 'INFO', 'a message'),
... ('root', 'ERROR', 'another error'),
... )
Traceback (most recent call last):
...
AssertionError: sequence not as expected:
<BLANKLINE>
same:
(('root', 'INFO', 'a message'),)
<BLANKLINE>
expected:
(('root', 'ERROR', 'another error'),)
<BLANKLINE>
actual:
(('root', 'ERROR', 'an error'),)
It also has a string representation that allows you to see what has
been logged, which is useful for doc tests:
>>> print(l)
root INFO
a message
root ERROR
an error
The decorator
~~~~~~~~~~~~~
If you are working in a traditional :mod:`unittest` environment and
only want to capture logging for a particular test function, you may
find the decorator suits your needs better:
.. code-block:: python
from testfixtures import log_capture
@log_capture()
def test_function(capture):
logger = logging.getLogger()
logger.info('a message')
logger.error('an error')
capture.check(
('root', 'INFO', 'a message'),
('root', 'ERROR', 'an error'),
)
.. check the above raises no assertion error:
>>> test_function()
.. note::
This method is not compatible with pytest's fixture discovery stuff.
Instead, put a fixture such as the following in your `conftest.py`:
.. code-block:: python
import pytest
@pytest.fixture(autouse=True)
def capture():
with LogCapture() as capture:
yield capture
Manual usage
~~~~~~~~~~~~
If you want to capture logging for the duration of a doctest or
in every test in a :class:`~unittest.TestCase`, then you can use the
:class:`~testfixtures.LogCapture` manually.
The instantiation and replacement are done in the ``setUp`` function
of the :class:`~unittest.TestCase` or passed to the
:class:`~doctest.DocTestSuite` constructor:
>>> from testfixtures import LogCapture
>>> l = LogCapture()
You can then execute whatever will log the messages you want to test
for:
>>> from logging import getLogger
>>> getLogger().info('a message')
At any point, you can check what has been logged using the
check method:
>>> l.check(('root', 'INFO', 'a message'))
Alternatively, you can use the string representation of the
:class:`~testfixtures.LogCapture`:
>>> print(l)
root INFO
a message
Then, in the ``tearDown`` function
of the :class:`~unittest.TestCase` or passed to the
:class:`~doctest.DocTestSuite` constructor, you should make sure you
stop the capturing:
>>> l.uninstall()
If you have multiple :class:`~testfixtures.LogCapture` objects in use,
you can easily uninstall them all:
>>> LogCapture.uninstall_all()
Checking captured log messages
------------------------------
Regardless of how you use the :class:`~testfixtures.LogCapture` to
capture messages, there are three ways of checking that the messages
captured were as expected.
The following example is useful for showing these:
.. code-block:: python
from testfixtures import LogCapture
from logging import getLogger
logger = getLogger()
with LogCapture() as log:
logger.info('start of block number %i', 1)
try:
logger.debug('inside try block')
raise RuntimeError('No code to run!')
except:
logger.error('error occurred', exc_info=True)
The check methods
~~~~~~~~~~~~~~~~~
:obj:`~testfixtures.LogCapture` instances have :meth:`~testfixtures.LogCapture.check`
and :meth:`~testfixtures.LogCapture.check_present` methods to make assertions about
entries that have been logged.
:meth:`~testfixtures.LogCapture.check` will compare the
log messages captured with those you expect. Expected messages are
expressed, by default, as three-element tuples where the first element is the name
of the logger to which the message should have been logged, the
second element is the string representation of the level at which the
message should have been logged and the third element is the message
that should have been logged after any parameter interpolation has
taken place.
If things are as you expected, the method will not raise any exceptions:
>>> log.check(
... ('root', 'INFO', 'start of block number 1'),
... ('root', 'DEBUG', 'inside try block'),
... ('root', 'ERROR', 'error occurred'),
... )
However, if the actual messages logged were different, you'll get an
:class:`~exceptions.AssertionError` explaining what happened:
>>> log.check(('root', 'INFO', 'start of block number 1'))
Traceback (most recent call last):
...
AssertionError: sequence not as expected:
<BLANKLINE>
same:
(('root', 'INFO', 'start of block number 1'),)
<BLANKLINE>
expected:
()
<BLANKLINE>
actual:
(('root', 'DEBUG', 'inside try block'), ('root', 'ERROR', 'error occurred'))
In contrast, :meth:`~testfixtures.LogCapture.check_present` will only check that the messages you
specify are present, and that their order is as specified. Other messages will be ignored:
>>> log.check_present(
... ('root', 'INFO', 'start of block number 1'),
... ('root', 'ERROR', 'error occurred'),
... )
If the order of messages is non-deterministic, then you can be explict that the order doesn't
matter:
>>> log.check_present(
... ('root', 'ERROR', 'error occurred'),
... ('root', 'INFO', 'start of block number 1'),
... order_matters=False
... )
Printing
~~~~~~~~
The :obj:`~testfixtures.LogCapture` has a string representation that
shows what messages it has captured. This can be useful in doc tests:
>>> print(log)
root INFO
start of block number 1
root DEBUG
inside try block
root ERROR
error occurred
This representation can also be used to check that no logging has
occurred:
>>> empty = LogCapture()
>>> print(empty)
No logging captured
Inspecting
~~~~~~~~~~
The :obj:`~testfixtures.LogCapture` also keeps a list of the
:class:`~logging.LogRecord` instances it captures. This is useful when
you want to check specifics of the captured logging that aren't
available from either the string representation or the
:meth:`~testfixtures.LogCapture.check` method.
A common case of this is where you want to check that exception
information was logged for certain messages:
.. code-block:: python
from testfixtures import compare, Comparison as C
compare(C(RuntimeError('No code to run!')), log.records[-1].exc_info[1])
If you wish the extraction specified in the ``attributes`` parameter to the
:obj:`~testfixtures.LogCapture` constructor to be taken into account, you can examine the list
of recorded entries returned by the :meth:`~testfixtures.LogCapture.actual` method:
.. code-block:: python
assert log.actual()[-1][-1] == 'error occurred'
Only capturing specific logging
-------------------------------
Some actions that you want to test may generate a lot of logging, only
some of which you actually need to care about.
The logging you care about is often only that above a certain log
level. If this is the case, you can configure :obj:`~testfixtures.LogCapture` to
only capture logging at or above a specific level:
>>> with LogCapture(level=logging.INFO) as l:
... logger = getLogger()
... logger.debug('junk')
... logger.info('something we care about')
... logger.error('an error')
>>> print(l)
root INFO
something we care about
root ERROR
an error
In other cases this problem can be alleviated by only capturing a
specific logger:
>>> with LogCapture('specific') as l:
... getLogger('something').info('junk')
... getLogger('specific').info('what we care about')
... getLogger().info('more junk')
>>> print(l)
specific INFO
what we care about
However, it may be that while you don't want to capture all logging,
you do want to capture logging from multiple specific loggers:
>>> with LogCapture(('one','two')) as l:
... getLogger('three').info('3')
... getLogger('two').info('2')
... getLogger('one').info('1')
>>> print(l)
two INFO
2
one INFO
1
It may also be that the simplest thing to do is only capture logging
for part of your test. This is particularly common with long doc
tests. To make this easier, :class:`~testfixtures.LogCapture` supports
manual installation and un-installation as shown in the following
example:
>>> l = LogCapture(install=False)
>>> getLogger().info('junk')
>>> l.install()
>>> getLogger().info('something we care about')
>>> l.uninstall()
>>> getLogger().info('more junk')
>>> l.install()
>>> getLogger().info('something else we care about')
>>> print(l)
root INFO
something we care about
root INFO
something else we care about
.. uninstall:
>>> LogCapture.uninstall_all()
Once you have the filtered to the entries you would like to make assertions about, you may also
want to look at a different set of attributes that the defaults for
:class:`~testfixtures.LogCapture`:
>>> with LogCapture(attributes=('levelname', 'getMessage')) as log:
... logger = getLogger()
... logger.debug('a debug message')
... logger.info('something %s', 'info')
... logger.error('an error')
>>> log.check(('DEBUG', 'a debug message'), ('INFO', 'something info'), ('ERROR', 'an error'))
As you can see, if a specified attribute is callable, it will be called and the result used to
form part of the entry. If you need even more control, you can pass a callable to the
``attributes`` parameter, which can extract any required information from the records and return
it in the most appropriate form:
.. code-block:: python
def extract(record):
return {'level': record.levelname, 'message': record.getMessage()}
>>> with LogCapture(attributes=extract) as log:
... logger = getLogger()
... logger.debug('a debug message')
... logger.error('an error')
>>> log.check(
... {'level': 'DEBUG', 'message': 'a debug message'},
... {'level': 'ERROR', 'message': 'an error'},
... )
.. _check-log-config:
Checking the configuration of your log handlers
-----------------------------------------------
:class:`LogCapture` is good for checking that your code is logging the
correct messages; just as important is checking that your application
has correctly configured log handers. This can be done using a unit
test such as the following:
.. code-block:: python
from testfixtures import Comparison as C, compare
from unittest import TestCase
import logging
import sys
class LoggingConfigurationTests(TestCase):
# We mock out the handlers list for the logger we're
# configuring in such a way that we have no handlers
# configured at the start of the test and the handlers our
# configuration installs are removed at the end of the test.
def setUp(self):
self.logger = logging.getLogger()
self.orig_handlers = self.logger.handlers
self.logger.handlers = []
self.level = self.logger.level
def tearDown(self):
self.logger.handlers = self.orig_handlers
self.logger.level = self.level
def test_basic_configuration(self):
# Our logging configuration code, in this case just a
# call to basicConfig:
logging.basicConfig(format='%(levelname)s %(message)s',
level=logging.INFO)
# Now we check the configuration is as expected:
compare(self.logger.level, 20)
compare([
C('logging.StreamHandler',
stream=sys.stderr,
formatter=C('logging.Formatter',
_fmt='%(levelname)s %(message)s',
strict=False),
level=logging.NOTSET,
strict=False)
], self.logger.handlers)
.. the result:
>>> import unittest
>>> from testfixtures.compat import StringIO
>>> suite = unittest.TestLoader().loadTestsFromTestCase(LoggingConfigurationTests)
>>> stream = StringIO()
>>> result = unittest.TextTestRunner(verbosity=0, stream=stream).run(suite)
>>> if result.errors or result.failures: print(stream.getvalue())
>>> result
<unittest...TextTestResult run=1 errors=0 failures=0>