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