blob: d7634593dcb03dc51b3666d98a998edd4840295b [file] [log] [blame]
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001#!/usr/bin/env python
Christian Heimes180510d2008-03-03 19:15:45 +00002#
Benjamin Peterson46a99002010-01-09 18:45:30 +00003# Copyright 2001-2010 by Vinay Sajip. All Rights Reserved.
Christian Heimes180510d2008-03-03 19:15:45 +00004#
5# Permission to use, copy, modify, and distribute this software and its
6# documentation for any purpose and without fee is hereby granted,
7# provided that the above copyright notice appear in all copies and that
8# both that copyright notice and this permission notice appear in
9# supporting documentation, and that the name of Vinay Sajip
10# not be used in advertising or publicity pertaining to distribution
11# of the software without specific, written prior permission.
12# VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING
13# ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
14# VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR
15# ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER
16# IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
17# OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
18
19"""Test harness for the logging module. Run all tests.
20
Benjamin Peterson46a99002010-01-09 18:45:30 +000021Copyright (C) 2001-2010 Vinay Sajip. All Rights Reserved.
Neal Norwitzb4a2df02003-01-02 14:56:39 +000022"""
23
Christian Heimes180510d2008-03-03 19:15:45 +000024import logging
25import logging.handlers
26import logging.config
Christian Heimes18c66892008-02-17 13:31:39 +000027
Benjamin Petersonf91df042009-02-13 02:50:59 +000028import codecs
Christian Heimes180510d2008-03-03 19:15:45 +000029import pickle
30import io
31import gc
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000032import json
Christian Heimes180510d2008-03-03 19:15:45 +000033import os
34import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000035import select
Christian Heimes180510d2008-03-03 19:15:45 +000036import socket
Alexandre Vassalottice261952008-05-12 02:31:37 +000037from socketserver import ThreadingTCPServer, StreamRequestHandler
Christian Heimes180510d2008-03-03 19:15:45 +000038import struct
39import sys
40import tempfile
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000041from test.support import captured_stdout, run_with_locale, run_unittest,\
42 find_unused_port
Christian Heimes180510d2008-03-03 19:15:45 +000043import textwrap
Christian Heimes180510d2008-03-03 19:15:45 +000044import unittest
Georg Brandlf9734072008-12-07 15:30:06 +000045import warnings
Christian Heimes180510d2008-03-03 19:15:45 +000046import weakref
Victor Stinner45df8202010-04-28 22:31:17 +000047try:
48 import threading
49except ImportError:
50 threading = None
Christian Heimes18c66892008-02-17 13:31:39 +000051
52
Christian Heimes180510d2008-03-03 19:15:45 +000053class BaseTest(unittest.TestCase):
54
55 """Base class for logging tests."""
56
57 log_format = "%(name)s -> %(levelname)s: %(message)s"
58 expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$"
59 message_num = 0
60
61 def setUp(self):
62 """Setup the default logging stream to an internal StringIO instance,
63 so that we can examine log output as we want."""
64 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000065 logging._acquireLock()
66 try:
Christian Heimes180510d2008-03-03 19:15:45 +000067 self.saved_handlers = logging._handlers.copy()
68 self.saved_handler_list = logging._handlerList[:]
69 self.saved_loggers = logger_dict.copy()
70 self.saved_level_names = logging._levelNames.copy()
Christian Heimes18c66892008-02-17 13:31:39 +000071 finally:
72 logging._releaseLock()
73
Benjamin Peterson22005fc2010-04-11 16:25:06 +000074 # Set two unused loggers: one non-ASCII and one Unicode.
75 # This is to test correct operation when sorting existing
76 # loggers in the configuration code. See issue 8201.
77 logging.getLogger("\xab\xd7\xbb")
78 logging.getLogger("\u013f\u00d6\u0047")
79
Christian Heimes180510d2008-03-03 19:15:45 +000080 self.root_logger = logging.getLogger("")
81 self.original_logging_level = self.root_logger.getEffectiveLevel()
82
83 self.stream = io.StringIO()
84 self.root_logger.setLevel(logging.DEBUG)
85 self.root_hdlr = logging.StreamHandler(self.stream)
86 self.root_formatter = logging.Formatter(self.log_format)
87 self.root_hdlr.setFormatter(self.root_formatter)
88 self.root_logger.addHandler(self.root_hdlr)
89
90 def tearDown(self):
91 """Remove our logging stream, and restore the original logging
92 level."""
93 self.stream.close()
94 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000095 while self.root_logger.handlers:
96 h = self.root_logger.handlers[0]
97 self.root_logger.removeHandler(h)
98 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +000099 self.root_logger.setLevel(self.original_logging_level)
100 logging._acquireLock()
101 try:
102 logging._levelNames.clear()
103 logging._levelNames.update(self.saved_level_names)
104 logging._handlers.clear()
105 logging._handlers.update(self.saved_handlers)
106 logging._handlerList[:] = self.saved_handler_list
107 loggerDict = logging.getLogger().manager.loggerDict
108 loggerDict.clear()
109 loggerDict.update(self.saved_loggers)
110 finally:
111 logging._releaseLock()
112
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000113 def assert_log_lines(self, expected_values, stream=None):
Christian Heimes180510d2008-03-03 19:15:45 +0000114 """Match the collected log lines against the regular expression
115 self.expected_log_pat, and compare the extracted group values to
116 the expected_values list of tuples."""
117 stream = stream or self.stream
118 pat = re.compile(self.expected_log_pat)
119 try:
120 stream.reset()
121 actual_lines = stream.readlines()
122 except AttributeError:
123 # StringIO.StringIO lacks a reset() method.
124 actual_lines = stream.getvalue().splitlines()
125 self.assertEquals(len(actual_lines), len(expected_values))
126 for actual, expected in zip(actual_lines, expected_values):
127 match = pat.search(actual)
128 if not match:
129 self.fail("Log line does not match expected pattern:\n" +
130 actual)
131 self.assertEquals(tuple(match.groups()), expected)
132 s = stream.read()
133 if s:
134 self.fail("Remaining output at end of log stream:\n" + s)
135
136 def next_message(self):
137 """Generate a message consisting solely of an auto-incrementing
138 integer."""
139 self.message_num += 1
140 return "%d" % self.message_num
141
142
143class BuiltinLevelsTest(BaseTest):
144 """Test builtin levels and their inheritance."""
145
146 def test_flat(self):
147 #Logging levels in a flat logger namespace.
148 m = self.next_message
149
150 ERR = logging.getLogger("ERR")
151 ERR.setLevel(logging.ERROR)
152 INF = logging.getLogger("INF")
153 INF.setLevel(logging.INFO)
154 DEB = logging.getLogger("DEB")
155 DEB.setLevel(logging.DEBUG)
156
157 # These should log.
158 ERR.log(logging.CRITICAL, m())
159 ERR.error(m())
160
161 INF.log(logging.CRITICAL, m())
162 INF.error(m())
163 INF.warn(m())
164 INF.info(m())
165
166 DEB.log(logging.CRITICAL, m())
167 DEB.error(m())
168 DEB.warn (m())
169 DEB.info (m())
170 DEB.debug(m())
171
172 # These should not log.
173 ERR.warn(m())
174 ERR.info(m())
175 ERR.debug(m())
176
177 INF.debug(m())
178
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000179 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000180 ('ERR', 'CRITICAL', '1'),
181 ('ERR', 'ERROR', '2'),
182 ('INF', 'CRITICAL', '3'),
183 ('INF', 'ERROR', '4'),
184 ('INF', 'WARNING', '5'),
185 ('INF', 'INFO', '6'),
186 ('DEB', 'CRITICAL', '7'),
187 ('DEB', 'ERROR', '8'),
188 ('DEB', 'WARNING', '9'),
189 ('DEB', 'INFO', '10'),
190 ('DEB', 'DEBUG', '11'),
191 ])
192
193 def test_nested_explicit(self):
194 # Logging levels in a nested namespace, all explicitly set.
195 m = self.next_message
196
197 INF = logging.getLogger("INF")
198 INF.setLevel(logging.INFO)
199 INF_ERR = logging.getLogger("INF.ERR")
200 INF_ERR.setLevel(logging.ERROR)
201
202 # These should log.
203 INF_ERR.log(logging.CRITICAL, m())
204 INF_ERR.error(m())
205
206 # These should not log.
207 INF_ERR.warn(m())
208 INF_ERR.info(m())
209 INF_ERR.debug(m())
210
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000211 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000212 ('INF.ERR', 'CRITICAL', '1'),
213 ('INF.ERR', 'ERROR', '2'),
214 ])
215
216 def test_nested_inherited(self):
217 #Logging levels in a nested namespace, inherited from parent loggers.
218 m = self.next_message
219
220 INF = logging.getLogger("INF")
221 INF.setLevel(logging.INFO)
222 INF_ERR = logging.getLogger("INF.ERR")
223 INF_ERR.setLevel(logging.ERROR)
224 INF_UNDEF = logging.getLogger("INF.UNDEF")
225 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
226 UNDEF = logging.getLogger("UNDEF")
227
228 # These should log.
229 INF_UNDEF.log(logging.CRITICAL, m())
230 INF_UNDEF.error(m())
231 INF_UNDEF.warn(m())
232 INF_UNDEF.info(m())
233 INF_ERR_UNDEF.log(logging.CRITICAL, m())
234 INF_ERR_UNDEF.error(m())
235
236 # These should not log.
237 INF_UNDEF.debug(m())
238 INF_ERR_UNDEF.warn(m())
239 INF_ERR_UNDEF.info(m())
240 INF_ERR_UNDEF.debug(m())
241
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000242 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000243 ('INF.UNDEF', 'CRITICAL', '1'),
244 ('INF.UNDEF', 'ERROR', '2'),
245 ('INF.UNDEF', 'WARNING', '3'),
246 ('INF.UNDEF', 'INFO', '4'),
247 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
248 ('INF.ERR.UNDEF', 'ERROR', '6'),
249 ])
250
251 def test_nested_with_virtual_parent(self):
252 # Logging levels when some parent does not exist yet.
253 m = self.next_message
254
255 INF = logging.getLogger("INF")
256 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
257 CHILD = logging.getLogger("INF.BADPARENT")
258 INF.setLevel(logging.INFO)
259
260 # These should log.
261 GRANDCHILD.log(logging.FATAL, m())
262 GRANDCHILD.info(m())
263 CHILD.log(logging.FATAL, m())
264 CHILD.info(m())
265
266 # These should not log.
267 GRANDCHILD.debug(m())
268 CHILD.debug(m())
269
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000270 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000271 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
272 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
273 ('INF.BADPARENT', 'CRITICAL', '3'),
274 ('INF.BADPARENT', 'INFO', '4'),
275 ])
276
277
278class BasicFilterTest(BaseTest):
279
280 """Test the bundled Filter class."""
281
282 def test_filter(self):
283 # Only messages satisfying the specified criteria pass through the
284 # filter.
285 filter_ = logging.Filter("spam.eggs")
286 handler = self.root_logger.handlers[0]
287 try:
288 handler.addFilter(filter_)
289 spam = logging.getLogger("spam")
290 spam_eggs = logging.getLogger("spam.eggs")
291 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
292 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
293
294 spam.info(self.next_message())
295 spam_eggs.info(self.next_message()) # Good.
296 spam_eggs_fish.info(self.next_message()) # Good.
297 spam_bakedbeans.info(self.next_message())
298
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000299 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000300 ('spam.eggs', 'INFO', '2'),
301 ('spam.eggs.fish', 'INFO', '3'),
302 ])
303 finally:
304 handler.removeFilter(filter_)
305
306
307#
308# First, we define our levels. There can be as many as you want - the only
309# limitations are that they should be integers, the lowest should be > 0 and
310# larger values mean less information being logged. If you need specific
311# level values which do not fit into these limitations, you can use a
312# mapping dictionary to convert between your application levels and the
313# logging system.
314#
315SILENT = 120
316TACITURN = 119
317TERSE = 118
318EFFUSIVE = 117
319SOCIABLE = 116
320VERBOSE = 115
321TALKATIVE = 114
322GARRULOUS = 113
323CHATTERBOX = 112
324BORING = 111
325
326LEVEL_RANGE = range(BORING, SILENT + 1)
327
328#
329# Next, we define names for our levels. You don't need to do this - in which
330# case the system will use "Level n" to denote the text for the level.
331#
332my_logging_levels = {
333 SILENT : 'Silent',
334 TACITURN : 'Taciturn',
335 TERSE : 'Terse',
336 EFFUSIVE : 'Effusive',
337 SOCIABLE : 'Sociable',
338 VERBOSE : 'Verbose',
339 TALKATIVE : 'Talkative',
340 GARRULOUS : 'Garrulous',
341 CHATTERBOX : 'Chatterbox',
342 BORING : 'Boring',
343}
344
345class GarrulousFilter(logging.Filter):
346
347 """A filter which blocks garrulous messages."""
348
349 def filter(self, record):
350 return record.levelno != GARRULOUS
351
352class VerySpecificFilter(logging.Filter):
353
354 """A filter which blocks sociable and taciturn messages."""
355
356 def filter(self, record):
357 return record.levelno not in [SOCIABLE, TACITURN]
358
359
360class CustomLevelsAndFiltersTest(BaseTest):
361
362 """Test various filtering possibilities with custom logging levels."""
363
364 # Skip the logger name group.
365 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
366
367 def setUp(self):
368 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000369 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000370 logging.addLevelName(k, v)
371
372 def log_at_all_levels(self, logger):
373 for lvl in LEVEL_RANGE:
374 logger.log(lvl, self.next_message())
375
376 def test_logger_filter(self):
377 # Filter at logger level.
378 self.root_logger.setLevel(VERBOSE)
379 # Levels >= 'Verbose' are good.
380 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000381 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000382 ('Verbose', '5'),
383 ('Sociable', '6'),
384 ('Effusive', '7'),
385 ('Terse', '8'),
386 ('Taciturn', '9'),
387 ('Silent', '10'),
388 ])
389
390 def test_handler_filter(self):
391 # Filter at handler level.
392 self.root_logger.handlers[0].setLevel(SOCIABLE)
393 try:
394 # Levels >= 'Sociable' are good.
395 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000396 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000397 ('Sociable', '6'),
398 ('Effusive', '7'),
399 ('Terse', '8'),
400 ('Taciturn', '9'),
401 ('Silent', '10'),
402 ])
403 finally:
404 self.root_logger.handlers[0].setLevel(logging.NOTSET)
405
406 def test_specific_filters(self):
407 # Set a specific filter object on the handler, and then add another
408 # filter object on the logger itself.
409 handler = self.root_logger.handlers[0]
410 specific_filter = None
411 garr = GarrulousFilter()
412 handler.addFilter(garr)
413 try:
414 self.log_at_all_levels(self.root_logger)
415 first_lines = [
416 # Notice how 'Garrulous' is missing
417 ('Boring', '1'),
418 ('Chatterbox', '2'),
419 ('Talkative', '4'),
420 ('Verbose', '5'),
421 ('Sociable', '6'),
422 ('Effusive', '7'),
423 ('Terse', '8'),
424 ('Taciturn', '9'),
425 ('Silent', '10'),
426 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000427 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000428
429 specific_filter = VerySpecificFilter()
430 self.root_logger.addFilter(specific_filter)
431 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000432 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000433 # Not only 'Garrulous' is still missing, but also 'Sociable'
434 # and 'Taciturn'
435 ('Boring', '11'),
436 ('Chatterbox', '12'),
437 ('Talkative', '14'),
438 ('Verbose', '15'),
439 ('Effusive', '17'),
440 ('Terse', '18'),
441 ('Silent', '20'),
442 ])
443 finally:
444 if specific_filter:
445 self.root_logger.removeFilter(specific_filter)
446 handler.removeFilter(garr)
447
448
449class MemoryHandlerTest(BaseTest):
450
451 """Tests for the MemoryHandler."""
452
453 # Do not bother with a logger name group.
454 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
455
456 def setUp(self):
457 BaseTest.setUp(self)
458 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
459 self.root_hdlr)
460 self.mem_logger = logging.getLogger('mem')
461 self.mem_logger.propagate = 0
462 self.mem_logger.addHandler(self.mem_hdlr)
463
464 def tearDown(self):
465 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +0000466 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +0000467
468 def test_flush(self):
469 # The memory handler flushes to its target handler based on specific
470 # criteria (message count and message level).
471 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000472 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000473 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000474 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000475 # This will flush because the level is >= logging.WARNING
476 self.mem_logger.warn(self.next_message())
477 lines = [
478 ('DEBUG', '1'),
479 ('INFO', '2'),
480 ('WARNING', '3'),
481 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000482 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000483 for n in (4, 14):
484 for i in range(9):
485 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000486 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000487 # This will flush because it's the 10th message since the last
488 # flush.
489 self.mem_logger.debug(self.next_message())
490 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000491 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000492
493 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000494 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000495
496
497class ExceptionFormatter(logging.Formatter):
498 """A special exception formatter."""
499 def formatException(self, ei):
500 return "Got a [%s]" % ei[0].__name__
501
502
503class ConfigFileTest(BaseTest):
504
505 """Reading logging config from a .ini-style config file."""
506
507 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
508
509 # config0 is a standard configuration.
510 config0 = """
511 [loggers]
512 keys=root
513
514 [handlers]
515 keys=hand1
516
517 [formatters]
518 keys=form1
519
520 [logger_root]
521 level=WARNING
522 handlers=hand1
523
524 [handler_hand1]
525 class=StreamHandler
526 level=NOTSET
527 formatter=form1
528 args=(sys.stdout,)
529
530 [formatter_form1]
531 format=%(levelname)s ++ %(message)s
532 datefmt=
533 """
534
535 # config1 adds a little to the standard configuration.
536 config1 = """
537 [loggers]
538 keys=root,parser
539
540 [handlers]
541 keys=hand1
542
543 [formatters]
544 keys=form1
545
546 [logger_root]
547 level=WARNING
548 handlers=
549
550 [logger_parser]
551 level=DEBUG
552 handlers=hand1
553 propagate=1
554 qualname=compiler.parser
555
556 [handler_hand1]
557 class=StreamHandler
558 level=NOTSET
559 formatter=form1
560 args=(sys.stdout,)
561
562 [formatter_form1]
563 format=%(levelname)s ++ %(message)s
564 datefmt=
565 """
566
567 # config2 has a subtle configuration error that should be reported
568 config2 = config1.replace("sys.stdout", "sys.stbout")
569
570 # config3 has a less subtle configuration error
571 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
572
573 # config4 specifies a custom formatter class to be loaded
574 config4 = """
575 [loggers]
576 keys=root
577
578 [handlers]
579 keys=hand1
580
581 [formatters]
582 keys=form1
583
584 [logger_root]
585 level=NOTSET
586 handlers=hand1
587
588 [handler_hand1]
589 class=StreamHandler
590 level=NOTSET
591 formatter=form1
592 args=(sys.stdout,)
593
594 [formatter_form1]
595 class=""" + __name__ + """.ExceptionFormatter
596 format=%(levelname)s:%(name)s:%(message)s
597 datefmt=
598 """
599
Georg Brandl3dbca812008-07-23 16:10:53 +0000600 # config5 specifies a custom handler class to be loaded
601 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
602
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000603 # config6 uses ', ' delimiters in the handlers and formatters sections
604 config6 = """
605 [loggers]
606 keys=root,parser
607
608 [handlers]
609 keys=hand1, hand2
610
611 [formatters]
612 keys=form1, form2
613
614 [logger_root]
615 level=WARNING
616 handlers=
617
618 [logger_parser]
619 level=DEBUG
620 handlers=hand1
621 propagate=1
622 qualname=compiler.parser
623
624 [handler_hand1]
625 class=StreamHandler
626 level=NOTSET
627 formatter=form1
628 args=(sys.stdout,)
629
630 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +0000631 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000632 level=NOTSET
633 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +0000634 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000635
636 [formatter_form1]
637 format=%(levelname)s ++ %(message)s
638 datefmt=
639
640 [formatter_form2]
641 format=%(message)s
642 datefmt=
643 """
644
Christian Heimes180510d2008-03-03 19:15:45 +0000645 def apply_config(self, conf):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000646 file = io.StringIO(textwrap.dedent(conf))
647 logging.config.fileConfig(file)
Christian Heimes180510d2008-03-03 19:15:45 +0000648
649 def test_config0_ok(self):
650 # A simple config file which overrides the default settings.
651 with captured_stdout() as output:
652 self.apply_config(self.config0)
653 logger = logging.getLogger()
654 # Won't output anything
655 logger.info(self.next_message())
656 # Outputs a message
657 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000658 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000659 ('ERROR', '2'),
660 ], stream=output)
661 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000662 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000663
Georg Brandl3dbca812008-07-23 16:10:53 +0000664 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +0000665 # A config file defining a sub-parser as well.
666 with captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +0000667 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +0000668 logger = logging.getLogger("compiler.parser")
669 # Both will output a message
670 logger.info(self.next_message())
671 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000672 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000673 ('INFO', '1'),
674 ('ERROR', '2'),
675 ], stream=output)
676 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000677 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000678
679 def test_config2_failure(self):
680 # A simple config file which overrides the default settings.
681 self.assertRaises(Exception, self.apply_config, self.config2)
682
683 def test_config3_failure(self):
684 # A simple config file which overrides the default settings.
685 self.assertRaises(Exception, self.apply_config, self.config3)
686
687 def test_config4_ok(self):
688 # A config file specifying a custom formatter class.
689 with captured_stdout() as output:
690 self.apply_config(self.config4)
691 logger = logging.getLogger()
692 try:
693 raise RuntimeError()
694 except RuntimeError:
695 logging.exception("just testing")
696 sys.stdout.seek(0)
697 self.assertEquals(output.getvalue(),
698 "ERROR:root:just testing\nGot a [RuntimeError]\n")
699 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000700 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000701
Georg Brandl3dbca812008-07-23 16:10:53 +0000702 def test_config5_ok(self):
703 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +0000704
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000705 def test_config6_ok(self):
706 self.test_config1_ok(config=self.config6)
707
Christian Heimes180510d2008-03-03 19:15:45 +0000708class LogRecordStreamHandler(StreamRequestHandler):
709
710 """Handler for a streaming logging request. It saves the log message in the
711 TCP server's 'log_output' attribute."""
712
713 TCP_LOG_END = "!!!END!!!"
714
715 def handle(self):
716 """Handle multiple requests - each expected to be of 4-byte length,
717 followed by the LogRecord in pickle format. Logs the record
718 according to whatever policy is configured locally."""
719 while True:
720 chunk = self.connection.recv(4)
721 if len(chunk) < 4:
722 break
723 slen = struct.unpack(">L", chunk)[0]
724 chunk = self.connection.recv(slen)
725 while len(chunk) < slen:
726 chunk = chunk + self.connection.recv(slen - len(chunk))
727 obj = self.unpickle(chunk)
728 record = logging.makeLogRecord(obj)
729 self.handle_log_record(record)
730
731 def unpickle(self, data):
732 return pickle.loads(data)
733
734 def handle_log_record(self, record):
735 # If the end-of-messages sentinel is seen, tell the server to
736 # terminate.
737 if self.TCP_LOG_END in record.msg:
738 self.server.abort = 1
739 return
740 self.server.log_output += record.msg + "\n"
741
Guido van Rossum376e6362003-04-25 14:22:00 +0000742
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000743class LogRecordSocketReceiver(ThreadingTCPServer):
Christian Heimes180510d2008-03-03 19:15:45 +0000744
745 """A simple-minded TCP socket-based logging receiver suitable for test
746 purposes."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000747
748 allow_reuse_address = 1
Christian Heimes180510d2008-03-03 19:15:45 +0000749 log_output = ""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000750
751 def __init__(self, host='localhost',
752 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
753 handler=LogRecordStreamHandler):
754 ThreadingTCPServer.__init__(self, (host, port), handler)
Christian Heimes8640e742008-02-23 16:23:06 +0000755 self.abort = False
Christian Heimes180510d2008-03-03 19:15:45 +0000756 self.timeout = 0.1
757 self.finished = threading.Event()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000758
759 def serve_until_stopped(self):
Neal Norwitz55cd82f2006-02-05 08:21:08 +0000760 while not self.abort:
Neal Norwitz5bab0f82006-03-05 02:16:12 +0000761 rd, wr, ex = select.select([self.socket.fileno()], [], [],
762 self.timeout)
763 if rd:
764 self.handle_request()
Christian Heimes180510d2008-03-03 19:15:45 +0000765 # Notify the main thread that we're about to exit
766 self.finished.set()
Martin v. Löwisf6848882006-01-29 19:55:18 +0000767 # close the listen socket
768 self.server_close()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000769
Guido van Rossum2a1d5162003-01-21 21:05:22 +0000770
Victor Stinner45df8202010-04-28 22:31:17 +0000771@unittest.skipUnless(threading, 'Threading required for this test.')
Christian Heimes180510d2008-03-03 19:15:45 +0000772class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000773
Christian Heimes180510d2008-03-03 19:15:45 +0000774 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000775
Christian Heimes180510d2008-03-03 19:15:45 +0000776 def setUp(self):
777 """Set up a TCP server to receive log messages, and a SocketHandler
778 pointing to that server's address and port."""
779 BaseTest.setUp(self)
780 self.tcpserver = LogRecordSocketReceiver(port=0)
781 self.port = self.tcpserver.socket.getsockname()[1]
782 self.threads = [
783 threading.Thread(target=self.tcpserver.serve_until_stopped)]
784 for thread in self.threads:
785 thread.start()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000786
Christian Heimes180510d2008-03-03 19:15:45 +0000787 self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port)
788 self.sock_hdlr.setFormatter(self.root_formatter)
789 self.root_logger.removeHandler(self.root_logger.handlers[0])
790 self.root_logger.addHandler(self.sock_hdlr)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000791
Christian Heimes180510d2008-03-03 19:15:45 +0000792 def tearDown(self):
793 """Shutdown the TCP server."""
794 try:
795 self.tcpserver.abort = True
796 del self.tcpserver
797 self.root_logger.removeHandler(self.sock_hdlr)
798 self.sock_hdlr.close()
799 for thread in self.threads:
800 thread.join(2.0)
801 finally:
802 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000803
Christian Heimes180510d2008-03-03 19:15:45 +0000804 def get_output(self):
805 """Get the log output as received by the TCP server."""
806 # Signal the TCP receiver and wait for it to terminate.
807 self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END)
808 self.tcpserver.finished.wait(2.0)
809 return self.tcpserver.log_output
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000810
Christian Heimes180510d2008-03-03 19:15:45 +0000811 def test_output(self):
812 # The log message sent to the SocketHandler is properly received.
813 logger = logging.getLogger("tcp")
814 logger.error("spam")
815 logger.debug("eggs")
816 self.assertEquals(self.get_output(), "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000817
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000818
Christian Heimes180510d2008-03-03 19:15:45 +0000819class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000820
Christian Heimes180510d2008-03-03 19:15:45 +0000821 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000822
Christian Heimes180510d2008-03-03 19:15:45 +0000823 def setUp(self):
824 """Create a dict to remember potentially destroyed objects."""
825 BaseTest.setUp(self)
826 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000827
Christian Heimes180510d2008-03-03 19:15:45 +0000828 def _watch_for_survival(self, *args):
829 """Watch the given objects for survival, by creating weakrefs to
830 them."""
831 for obj in args:
832 key = id(obj), repr(obj)
833 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000834
Benjamin Petersonc9c0f202009-06-30 23:06:06 +0000835 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +0000836 """Assert that all objects watched for survival have survived."""
837 # Trigger cycle breaking.
838 gc.collect()
839 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000840 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000841 if ref() is None:
842 dead.append(repr_)
843 if dead:
844 self.fail("%d objects should have survived "
845 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000846
Christian Heimes180510d2008-03-03 19:15:45 +0000847 def test_persistent_loggers(self):
848 # Logger objects are persistent and retain their configuration, even
849 # if visible references are destroyed.
850 self.root_logger.setLevel(logging.INFO)
851 foo = logging.getLogger("foo")
852 self._watch_for_survival(foo)
853 foo.setLevel(logging.DEBUG)
854 self.root_logger.debug(self.next_message())
855 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000856 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000857 ('foo', 'DEBUG', '2'),
858 ])
859 del foo
860 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +0000861 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +0000862 # foo has retained its settings.
863 bar = logging.getLogger("foo")
864 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000865 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000866 ('foo', 'DEBUG', '2'),
867 ('foo', 'DEBUG', '3'),
868 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000869
Benjamin Petersonf91df042009-02-13 02:50:59 +0000870
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000871class EncodingTest(BaseTest):
872 def test_encoding_plain_file(self):
873 # In Python 2.x, a plain file object is treated as having no encoding.
874 log = logging.getLogger("test")
875 fn = tempfile.mktemp(".log")
876 # the non-ascii data we write to the log.
877 data = "foo\x80"
878 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000879 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000880 log.addHandler(handler)
881 try:
882 # write non-ascii data to the log.
883 log.warning(data)
884 finally:
885 log.removeHandler(handler)
886 handler.close()
887 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000888 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000889 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +0000890 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000891 finally:
892 f.close()
893 finally:
894 if os.path.isfile(fn):
895 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000896
Benjamin Petersonf91df042009-02-13 02:50:59 +0000897 def test_encoding_cyrillic_unicode(self):
898 log = logging.getLogger("test")
899 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
900 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
901 #Ensure it's written in a Cyrillic encoding
902 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +0000903 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +0000904 stream = io.BytesIO()
905 writer = writer_class(stream, 'strict')
906 handler = logging.StreamHandler(writer)
907 log.addHandler(handler)
908 try:
909 log.warning(message)
910 finally:
911 log.removeHandler(handler)
912 handler.close()
913 # check we wrote exactly those bytes, ignoring trailing \n etc
914 s = stream.getvalue()
915 #Compare against what the data should be when encoded in CP-1251
916 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
917
918
Georg Brandlf9734072008-12-07 15:30:06 +0000919class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +0000920
Georg Brandlf9734072008-12-07 15:30:06 +0000921 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +0000922 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +0000923 logging.captureWarnings(True)
Brett Cannondf8709d2009-04-01 20:01:47 +0000924 try:
Brett Cannon5b9082a2009-04-05 18:57:32 +0000925 warnings.filterwarnings("always", category=UserWarning)
Brett Cannondf8709d2009-04-01 20:01:47 +0000926 file = io.StringIO()
927 h = logging.StreamHandler(file)
928 logger = logging.getLogger("py.warnings")
929 logger.addHandler(h)
930 warnings.warn("I'm warning you...")
931 logger.removeHandler(h)
932 s = file.getvalue()
933 h.close()
934 self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0)
Georg Brandlf9734072008-12-07 15:30:06 +0000935
Brett Cannondf8709d2009-04-01 20:01:47 +0000936 #See if an explicit file uses the original implementation
937 file = io.StringIO()
938 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
939 file, "Dummy line")
940 s = file.getvalue()
941 file.close()
942 self.assertEqual(s,
943 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
944 finally:
945 logging.captureWarnings(False)
Georg Brandlf9734072008-12-07 15:30:06 +0000946
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000947
948def formatFunc(format, datefmt=None):
949 return logging.Formatter(format, datefmt)
950
951def handlerFunc():
952 return logging.StreamHandler()
953
954class CustomHandler(logging.StreamHandler):
955 pass
956
957class ConfigDictTest(BaseTest):
958
959 """Reading logging config from a dictionary."""
960
961 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
962
963 # config0 is a standard configuration.
964 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000965 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000966 'formatters': {
967 'form1' : {
968 'format' : '%(levelname)s ++ %(message)s',
969 },
970 },
971 'handlers' : {
972 'hand1' : {
973 'class' : 'logging.StreamHandler',
974 'formatter' : 'form1',
975 'level' : 'NOTSET',
976 'stream' : 'ext://sys.stdout',
977 },
978 },
979 'root' : {
980 'level' : 'WARNING',
981 'handlers' : ['hand1'],
982 },
983 }
984
985 # config1 adds a little to the standard configuration.
986 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000987 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000988 'formatters': {
989 'form1' : {
990 'format' : '%(levelname)s ++ %(message)s',
991 },
992 },
993 'handlers' : {
994 'hand1' : {
995 'class' : 'logging.StreamHandler',
996 'formatter' : 'form1',
997 'level' : 'NOTSET',
998 'stream' : 'ext://sys.stdout',
999 },
1000 },
1001 'loggers' : {
1002 'compiler.parser' : {
1003 'level' : 'DEBUG',
1004 'handlers' : ['hand1'],
1005 },
1006 },
1007 'root' : {
1008 'level' : 'WARNING',
1009 },
1010 }
1011
1012 # config2 has a subtle configuration error that should be reported
1013 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001014 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001015 'formatters': {
1016 'form1' : {
1017 'format' : '%(levelname)s ++ %(message)s',
1018 },
1019 },
1020 'handlers' : {
1021 'hand1' : {
1022 'class' : 'logging.StreamHandler',
1023 'formatter' : 'form1',
1024 'level' : 'NOTSET',
1025 'stream' : 'ext://sys.stdbout',
1026 },
1027 },
1028 'loggers' : {
1029 'compiler.parser' : {
1030 'level' : 'DEBUG',
1031 'handlers' : ['hand1'],
1032 },
1033 },
1034 'root' : {
1035 'level' : 'WARNING',
1036 },
1037 }
1038
1039 #As config1 but with a misspelt level on a handler
1040 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001041 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001042 'formatters': {
1043 'form1' : {
1044 'format' : '%(levelname)s ++ %(message)s',
1045 },
1046 },
1047 'handlers' : {
1048 'hand1' : {
1049 'class' : 'logging.StreamHandler',
1050 'formatter' : 'form1',
1051 'level' : 'NTOSET',
1052 'stream' : 'ext://sys.stdout',
1053 },
1054 },
1055 'loggers' : {
1056 'compiler.parser' : {
1057 'level' : 'DEBUG',
1058 'handlers' : ['hand1'],
1059 },
1060 },
1061 'root' : {
1062 'level' : 'WARNING',
1063 },
1064 }
1065
1066
1067 #As config1 but with a misspelt level on a logger
1068 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001069 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001070 'formatters': {
1071 'form1' : {
1072 'format' : '%(levelname)s ++ %(message)s',
1073 },
1074 },
1075 'handlers' : {
1076 'hand1' : {
1077 'class' : 'logging.StreamHandler',
1078 'formatter' : 'form1',
1079 'level' : 'NOTSET',
1080 'stream' : 'ext://sys.stdout',
1081 },
1082 },
1083 'loggers' : {
1084 'compiler.parser' : {
1085 'level' : 'DEBUG',
1086 'handlers' : ['hand1'],
1087 },
1088 },
1089 'root' : {
1090 'level' : 'WRANING',
1091 },
1092 }
1093
1094 # config3 has a less subtle configuration error
1095 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001096 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001097 'formatters': {
1098 'form1' : {
1099 'format' : '%(levelname)s ++ %(message)s',
1100 },
1101 },
1102 'handlers' : {
1103 'hand1' : {
1104 'class' : 'logging.StreamHandler',
1105 'formatter' : 'misspelled_name',
1106 'level' : 'NOTSET',
1107 'stream' : 'ext://sys.stdout',
1108 },
1109 },
1110 'loggers' : {
1111 'compiler.parser' : {
1112 'level' : 'DEBUG',
1113 'handlers' : ['hand1'],
1114 },
1115 },
1116 'root' : {
1117 'level' : 'WARNING',
1118 },
1119 }
1120
1121 # config4 specifies a custom formatter class to be loaded
1122 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001123 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001124 'formatters': {
1125 'form1' : {
1126 '()' : __name__ + '.ExceptionFormatter',
1127 'format' : '%(levelname)s:%(name)s:%(message)s',
1128 },
1129 },
1130 'handlers' : {
1131 'hand1' : {
1132 'class' : 'logging.StreamHandler',
1133 'formatter' : 'form1',
1134 'level' : 'NOTSET',
1135 'stream' : 'ext://sys.stdout',
1136 },
1137 },
1138 'root' : {
1139 'level' : 'NOTSET',
1140 'handlers' : ['hand1'],
1141 },
1142 }
1143
1144 # As config4 but using an actual callable rather than a string
1145 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001146 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001147 'formatters': {
1148 'form1' : {
1149 '()' : ExceptionFormatter,
1150 'format' : '%(levelname)s:%(name)s:%(message)s',
1151 },
1152 'form2' : {
1153 '()' : __name__ + '.formatFunc',
1154 'format' : '%(levelname)s:%(name)s:%(message)s',
1155 },
1156 'form3' : {
1157 '()' : formatFunc,
1158 'format' : '%(levelname)s:%(name)s:%(message)s',
1159 },
1160 },
1161 'handlers' : {
1162 'hand1' : {
1163 'class' : 'logging.StreamHandler',
1164 'formatter' : 'form1',
1165 'level' : 'NOTSET',
1166 'stream' : 'ext://sys.stdout',
1167 },
1168 'hand2' : {
1169 '()' : handlerFunc,
1170 },
1171 },
1172 'root' : {
1173 'level' : 'NOTSET',
1174 'handlers' : ['hand1'],
1175 },
1176 }
1177
1178 # config5 specifies a custom handler class to be loaded
1179 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001180 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001181 'formatters': {
1182 'form1' : {
1183 'format' : '%(levelname)s ++ %(message)s',
1184 },
1185 },
1186 'handlers' : {
1187 'hand1' : {
1188 'class' : __name__ + '.CustomHandler',
1189 'formatter' : 'form1',
1190 'level' : 'NOTSET',
1191 'stream' : 'ext://sys.stdout',
1192 },
1193 },
1194 'loggers' : {
1195 'compiler.parser' : {
1196 'level' : 'DEBUG',
1197 'handlers' : ['hand1'],
1198 },
1199 },
1200 'root' : {
1201 'level' : 'WARNING',
1202 },
1203 }
1204
1205 # config6 specifies a custom handler class to be loaded
1206 # but has bad arguments
1207 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001208 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001209 'formatters': {
1210 'form1' : {
1211 'format' : '%(levelname)s ++ %(message)s',
1212 },
1213 },
1214 'handlers' : {
1215 'hand1' : {
1216 'class' : __name__ + '.CustomHandler',
1217 'formatter' : 'form1',
1218 'level' : 'NOTSET',
1219 'stream' : 'ext://sys.stdout',
1220 '9' : 'invalid parameter name',
1221 },
1222 },
1223 'loggers' : {
1224 'compiler.parser' : {
1225 'level' : 'DEBUG',
1226 'handlers' : ['hand1'],
1227 },
1228 },
1229 'root' : {
1230 'level' : 'WARNING',
1231 },
1232 }
1233
1234 #config 7 does not define compiler.parser but defines compiler.lexer
1235 #so compiler.parser should be disabled after applying it
1236 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001237 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001238 'formatters': {
1239 'form1' : {
1240 'format' : '%(levelname)s ++ %(message)s',
1241 },
1242 },
1243 'handlers' : {
1244 'hand1' : {
1245 'class' : 'logging.StreamHandler',
1246 'formatter' : 'form1',
1247 'level' : 'NOTSET',
1248 'stream' : 'ext://sys.stdout',
1249 },
1250 },
1251 'loggers' : {
1252 'compiler.lexer' : {
1253 'level' : 'DEBUG',
1254 'handlers' : ['hand1'],
1255 },
1256 },
1257 'root' : {
1258 'level' : 'WARNING',
1259 },
1260 }
1261
1262 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001263 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001264 'disable_existing_loggers' : False,
1265 'formatters': {
1266 'form1' : {
1267 'format' : '%(levelname)s ++ %(message)s',
1268 },
1269 },
1270 'handlers' : {
1271 'hand1' : {
1272 'class' : 'logging.StreamHandler',
1273 'formatter' : 'form1',
1274 'level' : 'NOTSET',
1275 'stream' : 'ext://sys.stdout',
1276 },
1277 },
1278 'loggers' : {
1279 'compiler' : {
1280 'level' : 'DEBUG',
1281 'handlers' : ['hand1'],
1282 },
1283 'compiler.lexer' : {
1284 },
1285 },
1286 'root' : {
1287 'level' : 'WARNING',
1288 },
1289 }
1290
1291 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001292 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001293 'formatters': {
1294 'form1' : {
1295 'format' : '%(levelname)s ++ %(message)s',
1296 },
1297 },
1298 'handlers' : {
1299 'hand1' : {
1300 'class' : 'logging.StreamHandler',
1301 'formatter' : 'form1',
1302 'level' : 'WARNING',
1303 'stream' : 'ext://sys.stdout',
1304 },
1305 },
1306 'loggers' : {
1307 'compiler.parser' : {
1308 'level' : 'WARNING',
1309 'handlers' : ['hand1'],
1310 },
1311 },
1312 'root' : {
1313 'level' : 'NOTSET',
1314 },
1315 }
1316
1317 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001318 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001319 'incremental' : True,
1320 'handlers' : {
1321 'hand1' : {
1322 'level' : 'WARNING',
1323 },
1324 },
1325 'loggers' : {
1326 'compiler.parser' : {
1327 'level' : 'INFO',
1328 },
1329 },
1330 }
1331
1332 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001333 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001334 'incremental' : True,
1335 'handlers' : {
1336 'hand1' : {
1337 'level' : 'INFO',
1338 },
1339 },
1340 'loggers' : {
1341 'compiler.parser' : {
1342 'level' : 'INFO',
1343 },
1344 },
1345 }
1346
1347 #As config1 but with a filter added
1348 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001349 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001350 'formatters': {
1351 'form1' : {
1352 'format' : '%(levelname)s ++ %(message)s',
1353 },
1354 },
1355 'filters' : {
1356 'filt1' : {
1357 'name' : 'compiler.parser',
1358 },
1359 },
1360 'handlers' : {
1361 'hand1' : {
1362 'class' : 'logging.StreamHandler',
1363 'formatter' : 'form1',
1364 'level' : 'NOTSET',
1365 'stream' : 'ext://sys.stdout',
1366 'filters' : ['filt1'],
1367 },
1368 },
1369 'loggers' : {
1370 'compiler.parser' : {
1371 'level' : 'DEBUG',
1372 'filters' : ['filt1'],
1373 },
1374 },
1375 'root' : {
1376 'level' : 'WARNING',
1377 'handlers' : ['hand1'],
1378 },
1379 }
1380
1381 #As config1 but using cfg:// references
1382 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001383 'version': 1,
1384 'true_formatters': {
1385 'form1' : {
1386 'format' : '%(levelname)s ++ %(message)s',
1387 },
1388 },
1389 'handler_configs': {
1390 'hand1' : {
1391 'class' : 'logging.StreamHandler',
1392 'formatter' : 'form1',
1393 'level' : 'NOTSET',
1394 'stream' : 'ext://sys.stdout',
1395 },
1396 },
1397 'formatters' : 'cfg://true_formatters',
1398 'handlers' : {
1399 'hand1' : 'cfg://handler_configs[hand1]',
1400 },
1401 'loggers' : {
1402 'compiler.parser' : {
1403 'level' : 'DEBUG',
1404 'handlers' : ['hand1'],
1405 },
1406 },
1407 'root' : {
1408 'level' : 'WARNING',
1409 },
1410 }
1411
1412 #As config11 but missing the version key
1413 config12 = {
1414 'true_formatters': {
1415 'form1' : {
1416 'format' : '%(levelname)s ++ %(message)s',
1417 },
1418 },
1419 'handler_configs': {
1420 'hand1' : {
1421 'class' : 'logging.StreamHandler',
1422 'formatter' : 'form1',
1423 'level' : 'NOTSET',
1424 'stream' : 'ext://sys.stdout',
1425 },
1426 },
1427 'formatters' : 'cfg://true_formatters',
1428 'handlers' : {
1429 'hand1' : 'cfg://handler_configs[hand1]',
1430 },
1431 'loggers' : {
1432 'compiler.parser' : {
1433 'level' : 'DEBUG',
1434 'handlers' : ['hand1'],
1435 },
1436 },
1437 'root' : {
1438 'level' : 'WARNING',
1439 },
1440 }
1441
1442 #As config11 but using an unsupported version
1443 config13 = {
1444 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001445 'true_formatters': {
1446 'form1' : {
1447 'format' : '%(levelname)s ++ %(message)s',
1448 },
1449 },
1450 'handler_configs': {
1451 'hand1' : {
1452 'class' : 'logging.StreamHandler',
1453 'formatter' : 'form1',
1454 'level' : 'NOTSET',
1455 'stream' : 'ext://sys.stdout',
1456 },
1457 },
1458 'formatters' : 'cfg://true_formatters',
1459 'handlers' : {
1460 'hand1' : 'cfg://handler_configs[hand1]',
1461 },
1462 'loggers' : {
1463 'compiler.parser' : {
1464 'level' : 'DEBUG',
1465 'handlers' : ['hand1'],
1466 },
1467 },
1468 'root' : {
1469 'level' : 'WARNING',
1470 },
1471 }
1472
1473 def apply_config(self, conf):
1474 logging.config.dictConfig(conf)
1475
1476 def test_config0_ok(self):
1477 # A simple config which overrides the default settings.
1478 with captured_stdout() as output:
1479 self.apply_config(self.config0)
1480 logger = logging.getLogger()
1481 # Won't output anything
1482 logger.info(self.next_message())
1483 # Outputs a message
1484 logger.error(self.next_message())
1485 self.assert_log_lines([
1486 ('ERROR', '2'),
1487 ], stream=output)
1488 # Original logger output is empty.
1489 self.assert_log_lines([])
1490
1491 def test_config1_ok(self, config=config1):
1492 # A config defining a sub-parser as well.
1493 with captured_stdout() as output:
1494 self.apply_config(config)
1495 logger = logging.getLogger("compiler.parser")
1496 # Both will output a message
1497 logger.info(self.next_message())
1498 logger.error(self.next_message())
1499 self.assert_log_lines([
1500 ('INFO', '1'),
1501 ('ERROR', '2'),
1502 ], stream=output)
1503 # Original logger output is empty.
1504 self.assert_log_lines([])
1505
1506 def test_config2_failure(self):
1507 # A simple config which overrides the default settings.
1508 self.assertRaises(Exception, self.apply_config, self.config2)
1509
1510 def test_config2a_failure(self):
1511 # A simple config which overrides the default settings.
1512 self.assertRaises(Exception, self.apply_config, self.config2a)
1513
1514 def test_config2b_failure(self):
1515 # A simple config which overrides the default settings.
1516 self.assertRaises(Exception, self.apply_config, self.config2b)
1517
1518 def test_config3_failure(self):
1519 # A simple config which overrides the default settings.
1520 self.assertRaises(Exception, self.apply_config, self.config3)
1521
1522 def test_config4_ok(self):
1523 # A config specifying a custom formatter class.
1524 with captured_stdout() as output:
1525 self.apply_config(self.config4)
1526 #logger = logging.getLogger()
1527 try:
1528 raise RuntimeError()
1529 except RuntimeError:
1530 logging.exception("just testing")
1531 sys.stdout.seek(0)
1532 self.assertEquals(output.getvalue(),
1533 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1534 # Original logger output is empty
1535 self.assert_log_lines([])
1536
1537 def test_config4a_ok(self):
1538 # A config specifying a custom formatter class.
1539 with captured_stdout() as output:
1540 self.apply_config(self.config4a)
1541 #logger = logging.getLogger()
1542 try:
1543 raise RuntimeError()
1544 except RuntimeError:
1545 logging.exception("just testing")
1546 sys.stdout.seek(0)
1547 self.assertEquals(output.getvalue(),
1548 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1549 # Original logger output is empty
1550 self.assert_log_lines([])
1551
1552 def test_config5_ok(self):
1553 self.test_config1_ok(config=self.config5)
1554
1555 def test_config6_failure(self):
1556 self.assertRaises(Exception, self.apply_config, self.config6)
1557
1558 def test_config7_ok(self):
1559 with captured_stdout() as output:
1560 self.apply_config(self.config1)
1561 logger = logging.getLogger("compiler.parser")
1562 # Both will output a message
1563 logger.info(self.next_message())
1564 logger.error(self.next_message())
1565 self.assert_log_lines([
1566 ('INFO', '1'),
1567 ('ERROR', '2'),
1568 ], stream=output)
1569 # Original logger output is empty.
1570 self.assert_log_lines([])
1571 with captured_stdout() as output:
1572 self.apply_config(self.config7)
1573 logger = logging.getLogger("compiler.parser")
1574 self.assertTrue(logger.disabled)
1575 logger = logging.getLogger("compiler.lexer")
1576 # Both will output a message
1577 logger.info(self.next_message())
1578 logger.error(self.next_message())
1579 self.assert_log_lines([
1580 ('INFO', '3'),
1581 ('ERROR', '4'),
1582 ], stream=output)
1583 # Original logger output is empty.
1584 self.assert_log_lines([])
1585
1586 #Same as test_config_7_ok but don't disable old loggers.
1587 def test_config_8_ok(self):
1588 with captured_stdout() as output:
1589 self.apply_config(self.config1)
1590 logger = logging.getLogger("compiler.parser")
1591 # Both will output a message
1592 logger.info(self.next_message())
1593 logger.error(self.next_message())
1594 self.assert_log_lines([
1595 ('INFO', '1'),
1596 ('ERROR', '2'),
1597 ], stream=output)
1598 # Original logger output is empty.
1599 self.assert_log_lines([])
1600 with captured_stdout() as output:
1601 self.apply_config(self.config8)
1602 logger = logging.getLogger("compiler.parser")
1603 self.assertFalse(logger.disabled)
1604 # Both will output a message
1605 logger.info(self.next_message())
1606 logger.error(self.next_message())
1607 logger = logging.getLogger("compiler.lexer")
1608 # Both will output a message
1609 logger.info(self.next_message())
1610 logger.error(self.next_message())
1611 self.assert_log_lines([
1612 ('INFO', '3'),
1613 ('ERROR', '4'),
1614 ('INFO', '5'),
1615 ('ERROR', '6'),
1616 ], stream=output)
1617 # Original logger output is empty.
1618 self.assert_log_lines([])
1619
1620 def test_config_9_ok(self):
1621 with captured_stdout() as output:
1622 self.apply_config(self.config9)
1623 logger = logging.getLogger("compiler.parser")
1624 #Nothing will be output since both handler and logger are set to WARNING
1625 logger.info(self.next_message())
1626 self.assert_log_lines([], stream=output)
1627 self.apply_config(self.config9a)
1628 #Nothing will be output since both handler is still set to WARNING
1629 logger.info(self.next_message())
1630 self.assert_log_lines([], stream=output)
1631 self.apply_config(self.config9b)
1632 #Message should now be output
1633 logger.info(self.next_message())
1634 self.assert_log_lines([
1635 ('INFO', '3'),
1636 ], stream=output)
1637
1638 def test_config_10_ok(self):
1639 with captured_stdout() as output:
1640 self.apply_config(self.config10)
1641 logger = logging.getLogger("compiler.parser")
1642 logger.warning(self.next_message())
1643 logger = logging.getLogger('compiler')
1644 #Not output, because filtered
1645 logger.warning(self.next_message())
1646 logger = logging.getLogger('compiler.lexer')
1647 #Not output, because filtered
1648 logger.warning(self.next_message())
1649 logger = logging.getLogger("compiler.parser.codegen")
1650 #Output, as not filtered
1651 logger.error(self.next_message())
1652 self.assert_log_lines([
1653 ('WARNING', '1'),
1654 ('ERROR', '4'),
1655 ], stream=output)
1656
1657 def test_config11_ok(self):
1658 self.test_config1_ok(self.config11)
1659
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001660 def test_config12_failure(self):
1661 self.assertRaises(Exception, self.apply_config, self.config12)
1662
1663 def test_config13_failure(self):
1664 self.assertRaises(Exception, self.apply_config, self.config13)
1665
Victor Stinner45df8202010-04-28 22:31:17 +00001666 @unittest.skipUnless(threading, 'listen() needs threading to work')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001667 def setup_via_listener(self, text):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001668 text = text.encode("utf-8")
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001669 port = find_unused_port()
1670 t = logging.config.listen(port)
1671 t.start()
1672 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00001673 # Now get the port allocated
1674 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001675 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001676 try:
1677 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
1678 sock.settimeout(2.0)
1679 sock.connect(('localhost', port))
1680
1681 slen = struct.pack('>L', len(text))
1682 s = slen + text
1683 sentsofar = 0
1684 left = len(s)
1685 while left > 0:
1686 sent = sock.send(s[sentsofar:])
1687 sentsofar += sent
1688 left -= sent
1689 sock.close()
1690 finally:
1691 t.ready.wait(2.0)
1692 logging.config.stopListening()
1693 t.join(2.0)
1694
1695 def test_listen_config_10_ok(self):
1696 with captured_stdout() as output:
1697 self.setup_via_listener(json.dumps(self.config10))
1698 logger = logging.getLogger("compiler.parser")
1699 logger.warning(self.next_message())
1700 logger = logging.getLogger('compiler')
1701 #Not output, because filtered
1702 logger.warning(self.next_message())
1703 logger = logging.getLogger('compiler.lexer')
1704 #Not output, because filtered
1705 logger.warning(self.next_message())
1706 logger = logging.getLogger("compiler.parser.codegen")
1707 #Output, as not filtered
1708 logger.error(self.next_message())
1709 self.assert_log_lines([
1710 ('WARNING', '1'),
1711 ('ERROR', '4'),
1712 ], stream=output)
1713
1714 def test_listen_config_1_ok(self):
1715 with captured_stdout() as output:
1716 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
1717 logger = logging.getLogger("compiler.parser")
1718 # Both will output a message
1719 logger.info(self.next_message())
1720 logger.error(self.next_message())
1721 self.assert_log_lines([
1722 ('INFO', '1'),
1723 ('ERROR', '2'),
1724 ], stream=output)
1725 # Original logger output is empty.
1726 self.assert_log_lines([])
1727
1728
1729class ManagerTest(BaseTest):
1730 def test_manager_loggerclass(self):
1731 logged = []
1732
1733 class MyLogger(logging.Logger):
1734 def _log(self, level, msg, args, exc_info=None, extra=None):
1735 logged.append(msg)
1736
1737 man = logging.Manager(None)
1738 self.assertRaises(TypeError, man.setLoggerClass, int)
1739 man.setLoggerClass(MyLogger)
1740 logger = man.getLogger('test')
1741 logger.warning('should appear in logged')
1742 logging.warning('should not appear in logged')
1743
1744 self.assertEqual(logged, ['should appear in logged'])
1745
1746
Benjamin Peterson22005fc2010-04-11 16:25:06 +00001747class ChildLoggerTest(BaseTest):
1748 def test_child_loggers(self):
1749 r = logging.getLogger()
1750 l1 = logging.getLogger('abc')
1751 l2 = logging.getLogger('def.ghi')
1752 c1 = r.getChild('xyz')
1753 c2 = r.getChild('uvw.xyz')
1754 self.assertTrue(c1 is logging.getLogger('xyz'))
1755 self.assertTrue(c2 is logging.getLogger('uvw.xyz'))
1756 c1 = l1.getChild('def')
1757 c2 = c1.getChild('ghi')
1758 c3 = l1.getChild('def.ghi')
1759 self.assertTrue(c1 is logging.getLogger('abc.def'))
1760 self.assertTrue(c2 is logging.getLogger('abc.def.ghi'))
1761 self.assertTrue(c2 is c3)
1762
1763
Christian Heimes180510d2008-03-03 19:15:45 +00001764# Set the locale to the platform-dependent default. I have no idea
1765# why the test does this, but in any case we save the current locale
1766# first and restore it at the end.
1767@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00001768def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +00001769 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001770 CustomLevelsAndFiltersTest, MemoryHandlerTest,
1771 ConfigFileTest, SocketHandlerTest, MemoryTest,
Benjamin Peterson22005fc2010-04-11 16:25:06 +00001772 EncodingTest, WarningsTest, ConfigDictTest, ManagerTest,
1773 ChildLoggerTest)
Jeremy Hylton096d9862003-07-18 03:19:20 +00001774
Christian Heimes180510d2008-03-03 19:15:45 +00001775if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001776 test_main()