blob: cec3ffe44fd7449919981e686d9d134ff164361b [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
44import threading
Christian Heimes180510d2008-03-03 19:15:45 +000045import unittest
Georg Brandlf9734072008-12-07 15:30:06 +000046import warnings
Christian Heimes180510d2008-03-03 19:15:45 +000047import weakref
Christian Heimes18c66892008-02-17 13:31:39 +000048
49
Christian Heimes180510d2008-03-03 19:15:45 +000050class BaseTest(unittest.TestCase):
51
52 """Base class for logging tests."""
53
54 log_format = "%(name)s -> %(levelname)s: %(message)s"
55 expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$"
56 message_num = 0
57
58 def setUp(self):
59 """Setup the default logging stream to an internal StringIO instance,
60 so that we can examine log output as we want."""
61 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000062 logging._acquireLock()
63 try:
Christian Heimes180510d2008-03-03 19:15:45 +000064 self.saved_handlers = logging._handlers.copy()
65 self.saved_handler_list = logging._handlerList[:]
66 self.saved_loggers = logger_dict.copy()
67 self.saved_level_names = logging._levelNames.copy()
Christian Heimes18c66892008-02-17 13:31:39 +000068 finally:
69 logging._releaseLock()
70
Benjamin Peterson22005fc2010-04-11 16:25:06 +000071 # Set two unused loggers: one non-ASCII and one Unicode.
72 # This is to test correct operation when sorting existing
73 # loggers in the configuration code. See issue 8201.
74 logging.getLogger("\xab\xd7\xbb")
75 logging.getLogger("\u013f\u00d6\u0047")
76
Christian Heimes180510d2008-03-03 19:15:45 +000077 self.root_logger = logging.getLogger("")
78 self.original_logging_level = self.root_logger.getEffectiveLevel()
79
80 self.stream = io.StringIO()
81 self.root_logger.setLevel(logging.DEBUG)
82 self.root_hdlr = logging.StreamHandler(self.stream)
83 self.root_formatter = logging.Formatter(self.log_format)
84 self.root_hdlr.setFormatter(self.root_formatter)
85 self.root_logger.addHandler(self.root_hdlr)
86
87 def tearDown(self):
88 """Remove our logging stream, and restore the original logging
89 level."""
90 self.stream.close()
91 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000092 while self.root_logger.handlers:
93 h = self.root_logger.handlers[0]
94 self.root_logger.removeHandler(h)
95 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +000096 self.root_logger.setLevel(self.original_logging_level)
97 logging._acquireLock()
98 try:
99 logging._levelNames.clear()
100 logging._levelNames.update(self.saved_level_names)
101 logging._handlers.clear()
102 logging._handlers.update(self.saved_handlers)
103 logging._handlerList[:] = self.saved_handler_list
104 loggerDict = logging.getLogger().manager.loggerDict
105 loggerDict.clear()
106 loggerDict.update(self.saved_loggers)
107 finally:
108 logging._releaseLock()
109
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000110 def assert_log_lines(self, expected_values, stream=None):
Christian Heimes180510d2008-03-03 19:15:45 +0000111 """Match the collected log lines against the regular expression
112 self.expected_log_pat, and compare the extracted group values to
113 the expected_values list of tuples."""
114 stream = stream or self.stream
115 pat = re.compile(self.expected_log_pat)
116 try:
117 stream.reset()
118 actual_lines = stream.readlines()
119 except AttributeError:
120 # StringIO.StringIO lacks a reset() method.
121 actual_lines = stream.getvalue().splitlines()
122 self.assertEquals(len(actual_lines), len(expected_values))
123 for actual, expected in zip(actual_lines, expected_values):
124 match = pat.search(actual)
125 if not match:
126 self.fail("Log line does not match expected pattern:\n" +
127 actual)
128 self.assertEquals(tuple(match.groups()), expected)
129 s = stream.read()
130 if s:
131 self.fail("Remaining output at end of log stream:\n" + s)
132
133 def next_message(self):
134 """Generate a message consisting solely of an auto-incrementing
135 integer."""
136 self.message_num += 1
137 return "%d" % self.message_num
138
139
140class BuiltinLevelsTest(BaseTest):
141 """Test builtin levels and their inheritance."""
142
143 def test_flat(self):
144 #Logging levels in a flat logger namespace.
145 m = self.next_message
146
147 ERR = logging.getLogger("ERR")
148 ERR.setLevel(logging.ERROR)
149 INF = logging.getLogger("INF")
150 INF.setLevel(logging.INFO)
151 DEB = logging.getLogger("DEB")
152 DEB.setLevel(logging.DEBUG)
153
154 # These should log.
155 ERR.log(logging.CRITICAL, m())
156 ERR.error(m())
157
158 INF.log(logging.CRITICAL, m())
159 INF.error(m())
160 INF.warn(m())
161 INF.info(m())
162
163 DEB.log(logging.CRITICAL, m())
164 DEB.error(m())
165 DEB.warn (m())
166 DEB.info (m())
167 DEB.debug(m())
168
169 # These should not log.
170 ERR.warn(m())
171 ERR.info(m())
172 ERR.debug(m())
173
174 INF.debug(m())
175
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000176 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000177 ('ERR', 'CRITICAL', '1'),
178 ('ERR', 'ERROR', '2'),
179 ('INF', 'CRITICAL', '3'),
180 ('INF', 'ERROR', '4'),
181 ('INF', 'WARNING', '5'),
182 ('INF', 'INFO', '6'),
183 ('DEB', 'CRITICAL', '7'),
184 ('DEB', 'ERROR', '8'),
185 ('DEB', 'WARNING', '9'),
186 ('DEB', 'INFO', '10'),
187 ('DEB', 'DEBUG', '11'),
188 ])
189
190 def test_nested_explicit(self):
191 # Logging levels in a nested namespace, all explicitly set.
192 m = self.next_message
193
194 INF = logging.getLogger("INF")
195 INF.setLevel(logging.INFO)
196 INF_ERR = logging.getLogger("INF.ERR")
197 INF_ERR.setLevel(logging.ERROR)
198
199 # These should log.
200 INF_ERR.log(logging.CRITICAL, m())
201 INF_ERR.error(m())
202
203 # These should not log.
204 INF_ERR.warn(m())
205 INF_ERR.info(m())
206 INF_ERR.debug(m())
207
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000208 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000209 ('INF.ERR', 'CRITICAL', '1'),
210 ('INF.ERR', 'ERROR', '2'),
211 ])
212
213 def test_nested_inherited(self):
214 #Logging levels in a nested namespace, inherited from parent loggers.
215 m = self.next_message
216
217 INF = logging.getLogger("INF")
218 INF.setLevel(logging.INFO)
219 INF_ERR = logging.getLogger("INF.ERR")
220 INF_ERR.setLevel(logging.ERROR)
221 INF_UNDEF = logging.getLogger("INF.UNDEF")
222 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
223 UNDEF = logging.getLogger("UNDEF")
224
225 # These should log.
226 INF_UNDEF.log(logging.CRITICAL, m())
227 INF_UNDEF.error(m())
228 INF_UNDEF.warn(m())
229 INF_UNDEF.info(m())
230 INF_ERR_UNDEF.log(logging.CRITICAL, m())
231 INF_ERR_UNDEF.error(m())
232
233 # These should not log.
234 INF_UNDEF.debug(m())
235 INF_ERR_UNDEF.warn(m())
236 INF_ERR_UNDEF.info(m())
237 INF_ERR_UNDEF.debug(m())
238
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000239 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000240 ('INF.UNDEF', 'CRITICAL', '1'),
241 ('INF.UNDEF', 'ERROR', '2'),
242 ('INF.UNDEF', 'WARNING', '3'),
243 ('INF.UNDEF', 'INFO', '4'),
244 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
245 ('INF.ERR.UNDEF', 'ERROR', '6'),
246 ])
247
248 def test_nested_with_virtual_parent(self):
249 # Logging levels when some parent does not exist yet.
250 m = self.next_message
251
252 INF = logging.getLogger("INF")
253 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
254 CHILD = logging.getLogger("INF.BADPARENT")
255 INF.setLevel(logging.INFO)
256
257 # These should log.
258 GRANDCHILD.log(logging.FATAL, m())
259 GRANDCHILD.info(m())
260 CHILD.log(logging.FATAL, m())
261 CHILD.info(m())
262
263 # These should not log.
264 GRANDCHILD.debug(m())
265 CHILD.debug(m())
266
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000267 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000268 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
269 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
270 ('INF.BADPARENT', 'CRITICAL', '3'),
271 ('INF.BADPARENT', 'INFO', '4'),
272 ])
273
274
275class BasicFilterTest(BaseTest):
276
277 """Test the bundled Filter class."""
278
279 def test_filter(self):
280 # Only messages satisfying the specified criteria pass through the
281 # filter.
282 filter_ = logging.Filter("spam.eggs")
283 handler = self.root_logger.handlers[0]
284 try:
285 handler.addFilter(filter_)
286 spam = logging.getLogger("spam")
287 spam_eggs = logging.getLogger("spam.eggs")
288 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
289 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
290
291 spam.info(self.next_message())
292 spam_eggs.info(self.next_message()) # Good.
293 spam_eggs_fish.info(self.next_message()) # Good.
294 spam_bakedbeans.info(self.next_message())
295
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000296 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000297 ('spam.eggs', 'INFO', '2'),
298 ('spam.eggs.fish', 'INFO', '3'),
299 ])
300 finally:
301 handler.removeFilter(filter_)
302
303
304#
305# First, we define our levels. There can be as many as you want - the only
306# limitations are that they should be integers, the lowest should be > 0 and
307# larger values mean less information being logged. If you need specific
308# level values which do not fit into these limitations, you can use a
309# mapping dictionary to convert between your application levels and the
310# logging system.
311#
312SILENT = 120
313TACITURN = 119
314TERSE = 118
315EFFUSIVE = 117
316SOCIABLE = 116
317VERBOSE = 115
318TALKATIVE = 114
319GARRULOUS = 113
320CHATTERBOX = 112
321BORING = 111
322
323LEVEL_RANGE = range(BORING, SILENT + 1)
324
325#
326# Next, we define names for our levels. You don't need to do this - in which
327# case the system will use "Level n" to denote the text for the level.
328#
329my_logging_levels = {
330 SILENT : 'Silent',
331 TACITURN : 'Taciturn',
332 TERSE : 'Terse',
333 EFFUSIVE : 'Effusive',
334 SOCIABLE : 'Sociable',
335 VERBOSE : 'Verbose',
336 TALKATIVE : 'Talkative',
337 GARRULOUS : 'Garrulous',
338 CHATTERBOX : 'Chatterbox',
339 BORING : 'Boring',
340}
341
342class GarrulousFilter(logging.Filter):
343
344 """A filter which blocks garrulous messages."""
345
346 def filter(self, record):
347 return record.levelno != GARRULOUS
348
349class VerySpecificFilter(logging.Filter):
350
351 """A filter which blocks sociable and taciturn messages."""
352
353 def filter(self, record):
354 return record.levelno not in [SOCIABLE, TACITURN]
355
356
357class CustomLevelsAndFiltersTest(BaseTest):
358
359 """Test various filtering possibilities with custom logging levels."""
360
361 # Skip the logger name group.
362 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
363
364 def setUp(self):
365 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000366 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000367 logging.addLevelName(k, v)
368
369 def log_at_all_levels(self, logger):
370 for lvl in LEVEL_RANGE:
371 logger.log(lvl, self.next_message())
372
373 def test_logger_filter(self):
374 # Filter at logger level.
375 self.root_logger.setLevel(VERBOSE)
376 # Levels >= 'Verbose' are good.
377 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000378 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000379 ('Verbose', '5'),
380 ('Sociable', '6'),
381 ('Effusive', '7'),
382 ('Terse', '8'),
383 ('Taciturn', '9'),
384 ('Silent', '10'),
385 ])
386
387 def test_handler_filter(self):
388 # Filter at handler level.
389 self.root_logger.handlers[0].setLevel(SOCIABLE)
390 try:
391 # Levels >= 'Sociable' are good.
392 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000393 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000394 ('Sociable', '6'),
395 ('Effusive', '7'),
396 ('Terse', '8'),
397 ('Taciturn', '9'),
398 ('Silent', '10'),
399 ])
400 finally:
401 self.root_logger.handlers[0].setLevel(logging.NOTSET)
402
403 def test_specific_filters(self):
404 # Set a specific filter object on the handler, and then add another
405 # filter object on the logger itself.
406 handler = self.root_logger.handlers[0]
407 specific_filter = None
408 garr = GarrulousFilter()
409 handler.addFilter(garr)
410 try:
411 self.log_at_all_levels(self.root_logger)
412 first_lines = [
413 # Notice how 'Garrulous' is missing
414 ('Boring', '1'),
415 ('Chatterbox', '2'),
416 ('Talkative', '4'),
417 ('Verbose', '5'),
418 ('Sociable', '6'),
419 ('Effusive', '7'),
420 ('Terse', '8'),
421 ('Taciturn', '9'),
422 ('Silent', '10'),
423 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000424 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000425
426 specific_filter = VerySpecificFilter()
427 self.root_logger.addFilter(specific_filter)
428 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000429 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000430 # Not only 'Garrulous' is still missing, but also 'Sociable'
431 # and 'Taciturn'
432 ('Boring', '11'),
433 ('Chatterbox', '12'),
434 ('Talkative', '14'),
435 ('Verbose', '15'),
436 ('Effusive', '17'),
437 ('Terse', '18'),
438 ('Silent', '20'),
439 ])
440 finally:
441 if specific_filter:
442 self.root_logger.removeFilter(specific_filter)
443 handler.removeFilter(garr)
444
445
446class MemoryHandlerTest(BaseTest):
447
448 """Tests for the MemoryHandler."""
449
450 # Do not bother with a logger name group.
451 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
452
453 def setUp(self):
454 BaseTest.setUp(self)
455 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
456 self.root_hdlr)
457 self.mem_logger = logging.getLogger('mem')
458 self.mem_logger.propagate = 0
459 self.mem_logger.addHandler(self.mem_hdlr)
460
461 def tearDown(self):
462 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +0000463 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +0000464
465 def test_flush(self):
466 # The memory handler flushes to its target handler based on specific
467 # criteria (message count and message level).
468 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000469 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000470 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000471 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000472 # This will flush because the level is >= logging.WARNING
473 self.mem_logger.warn(self.next_message())
474 lines = [
475 ('DEBUG', '1'),
476 ('INFO', '2'),
477 ('WARNING', '3'),
478 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000479 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000480 for n in (4, 14):
481 for i in range(9):
482 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000483 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000484 # This will flush because it's the 10th message since the last
485 # flush.
486 self.mem_logger.debug(self.next_message())
487 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000488 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000489
490 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000491 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000492
493
494class ExceptionFormatter(logging.Formatter):
495 """A special exception formatter."""
496 def formatException(self, ei):
497 return "Got a [%s]" % ei[0].__name__
498
499
500class ConfigFileTest(BaseTest):
501
502 """Reading logging config from a .ini-style config file."""
503
504 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
505
506 # config0 is a standard configuration.
507 config0 = """
508 [loggers]
509 keys=root
510
511 [handlers]
512 keys=hand1
513
514 [formatters]
515 keys=form1
516
517 [logger_root]
518 level=WARNING
519 handlers=hand1
520
521 [handler_hand1]
522 class=StreamHandler
523 level=NOTSET
524 formatter=form1
525 args=(sys.stdout,)
526
527 [formatter_form1]
528 format=%(levelname)s ++ %(message)s
529 datefmt=
530 """
531
532 # config1 adds a little to the standard configuration.
533 config1 = """
534 [loggers]
535 keys=root,parser
536
537 [handlers]
538 keys=hand1
539
540 [formatters]
541 keys=form1
542
543 [logger_root]
544 level=WARNING
545 handlers=
546
547 [logger_parser]
548 level=DEBUG
549 handlers=hand1
550 propagate=1
551 qualname=compiler.parser
552
553 [handler_hand1]
554 class=StreamHandler
555 level=NOTSET
556 formatter=form1
557 args=(sys.stdout,)
558
559 [formatter_form1]
560 format=%(levelname)s ++ %(message)s
561 datefmt=
562 """
563
564 # config2 has a subtle configuration error that should be reported
565 config2 = config1.replace("sys.stdout", "sys.stbout")
566
567 # config3 has a less subtle configuration error
568 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
569
570 # config4 specifies a custom formatter class to be loaded
571 config4 = """
572 [loggers]
573 keys=root
574
575 [handlers]
576 keys=hand1
577
578 [formatters]
579 keys=form1
580
581 [logger_root]
582 level=NOTSET
583 handlers=hand1
584
585 [handler_hand1]
586 class=StreamHandler
587 level=NOTSET
588 formatter=form1
589 args=(sys.stdout,)
590
591 [formatter_form1]
592 class=""" + __name__ + """.ExceptionFormatter
593 format=%(levelname)s:%(name)s:%(message)s
594 datefmt=
595 """
596
Georg Brandl3dbca812008-07-23 16:10:53 +0000597 # config5 specifies a custom handler class to be loaded
598 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
599
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000600 # config6 uses ', ' delimiters in the handlers and formatters sections
601 config6 = """
602 [loggers]
603 keys=root,parser
604
605 [handlers]
606 keys=hand1, hand2
607
608 [formatters]
609 keys=form1, form2
610
611 [logger_root]
612 level=WARNING
613 handlers=
614
615 [logger_parser]
616 level=DEBUG
617 handlers=hand1
618 propagate=1
619 qualname=compiler.parser
620
621 [handler_hand1]
622 class=StreamHandler
623 level=NOTSET
624 formatter=form1
625 args=(sys.stdout,)
626
627 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +0000628 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000629 level=NOTSET
630 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +0000631 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000632
633 [formatter_form1]
634 format=%(levelname)s ++ %(message)s
635 datefmt=
636
637 [formatter_form2]
638 format=%(message)s
639 datefmt=
640 """
641
Christian Heimes180510d2008-03-03 19:15:45 +0000642 def apply_config(self, conf):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000643 file = io.StringIO(textwrap.dedent(conf))
644 logging.config.fileConfig(file)
Christian Heimes180510d2008-03-03 19:15:45 +0000645
646 def test_config0_ok(self):
647 # A simple config file which overrides the default settings.
648 with captured_stdout() as output:
649 self.apply_config(self.config0)
650 logger = logging.getLogger()
651 # Won't output anything
652 logger.info(self.next_message())
653 # Outputs a message
654 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000655 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000656 ('ERROR', '2'),
657 ], stream=output)
658 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000659 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000660
Georg Brandl3dbca812008-07-23 16:10:53 +0000661 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +0000662 # A config file defining a sub-parser as well.
663 with captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +0000664 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +0000665 logger = logging.getLogger("compiler.parser")
666 # Both will output a message
667 logger.info(self.next_message())
668 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000669 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000670 ('INFO', '1'),
671 ('ERROR', '2'),
672 ], stream=output)
673 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000674 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000675
676 def test_config2_failure(self):
677 # A simple config file which overrides the default settings.
678 self.assertRaises(Exception, self.apply_config, self.config2)
679
680 def test_config3_failure(self):
681 # A simple config file which overrides the default settings.
682 self.assertRaises(Exception, self.apply_config, self.config3)
683
684 def test_config4_ok(self):
685 # A config file specifying a custom formatter class.
686 with captured_stdout() as output:
687 self.apply_config(self.config4)
688 logger = logging.getLogger()
689 try:
690 raise RuntimeError()
691 except RuntimeError:
692 logging.exception("just testing")
693 sys.stdout.seek(0)
694 self.assertEquals(output.getvalue(),
695 "ERROR:root:just testing\nGot a [RuntimeError]\n")
696 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000697 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000698
Georg Brandl3dbca812008-07-23 16:10:53 +0000699 def test_config5_ok(self):
700 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +0000701
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000702 def test_config6_ok(self):
703 self.test_config1_ok(config=self.config6)
704
Christian Heimes180510d2008-03-03 19:15:45 +0000705class LogRecordStreamHandler(StreamRequestHandler):
706
707 """Handler for a streaming logging request. It saves the log message in the
708 TCP server's 'log_output' attribute."""
709
710 TCP_LOG_END = "!!!END!!!"
711
712 def handle(self):
713 """Handle multiple requests - each expected to be of 4-byte length,
714 followed by the LogRecord in pickle format. Logs the record
715 according to whatever policy is configured locally."""
716 while True:
717 chunk = self.connection.recv(4)
718 if len(chunk) < 4:
719 break
720 slen = struct.unpack(">L", chunk)[0]
721 chunk = self.connection.recv(slen)
722 while len(chunk) < slen:
723 chunk = chunk + self.connection.recv(slen - len(chunk))
724 obj = self.unpickle(chunk)
725 record = logging.makeLogRecord(obj)
726 self.handle_log_record(record)
727
728 def unpickle(self, data):
729 return pickle.loads(data)
730
731 def handle_log_record(self, record):
732 # If the end-of-messages sentinel is seen, tell the server to
733 # terminate.
734 if self.TCP_LOG_END in record.msg:
735 self.server.abort = 1
736 return
737 self.server.log_output += record.msg + "\n"
738
Guido van Rossum376e6362003-04-25 14:22:00 +0000739
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000740class LogRecordSocketReceiver(ThreadingTCPServer):
Christian Heimes180510d2008-03-03 19:15:45 +0000741
742 """A simple-minded TCP socket-based logging receiver suitable for test
743 purposes."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000744
745 allow_reuse_address = 1
Christian Heimes180510d2008-03-03 19:15:45 +0000746 log_output = ""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000747
748 def __init__(self, host='localhost',
749 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
750 handler=LogRecordStreamHandler):
751 ThreadingTCPServer.__init__(self, (host, port), handler)
Christian Heimes8640e742008-02-23 16:23:06 +0000752 self.abort = False
Christian Heimes180510d2008-03-03 19:15:45 +0000753 self.timeout = 0.1
754 self.finished = threading.Event()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000755
756 def serve_until_stopped(self):
Neal Norwitz55cd82f2006-02-05 08:21:08 +0000757 while not self.abort:
Neal Norwitz5bab0f82006-03-05 02:16:12 +0000758 rd, wr, ex = select.select([self.socket.fileno()], [], [],
759 self.timeout)
760 if rd:
761 self.handle_request()
Christian Heimes180510d2008-03-03 19:15:45 +0000762 # Notify the main thread that we're about to exit
763 self.finished.set()
Martin v. Löwisf6848882006-01-29 19:55:18 +0000764 # close the listen socket
765 self.server_close()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000766
Guido van Rossum2a1d5162003-01-21 21:05:22 +0000767
Christian Heimes180510d2008-03-03 19:15:45 +0000768class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000769
Christian Heimes180510d2008-03-03 19:15:45 +0000770 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000771
Christian Heimes180510d2008-03-03 19:15:45 +0000772 def setUp(self):
773 """Set up a TCP server to receive log messages, and a SocketHandler
774 pointing to that server's address and port."""
775 BaseTest.setUp(self)
776 self.tcpserver = LogRecordSocketReceiver(port=0)
777 self.port = self.tcpserver.socket.getsockname()[1]
778 self.threads = [
779 threading.Thread(target=self.tcpserver.serve_until_stopped)]
780 for thread in self.threads:
781 thread.start()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000782
Christian Heimes180510d2008-03-03 19:15:45 +0000783 self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port)
784 self.sock_hdlr.setFormatter(self.root_formatter)
785 self.root_logger.removeHandler(self.root_logger.handlers[0])
786 self.root_logger.addHandler(self.sock_hdlr)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000787
Christian Heimes180510d2008-03-03 19:15:45 +0000788 def tearDown(self):
789 """Shutdown the TCP server."""
790 try:
791 self.tcpserver.abort = True
792 del self.tcpserver
793 self.root_logger.removeHandler(self.sock_hdlr)
794 self.sock_hdlr.close()
795 for thread in self.threads:
796 thread.join(2.0)
797 finally:
798 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000799
Christian Heimes180510d2008-03-03 19:15:45 +0000800 def get_output(self):
801 """Get the log output as received by the TCP server."""
802 # Signal the TCP receiver and wait for it to terminate.
803 self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END)
804 self.tcpserver.finished.wait(2.0)
805 return self.tcpserver.log_output
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000806
Christian Heimes180510d2008-03-03 19:15:45 +0000807 def test_output(self):
808 # The log message sent to the SocketHandler is properly received.
809 logger = logging.getLogger("tcp")
810 logger.error("spam")
811 logger.debug("eggs")
812 self.assertEquals(self.get_output(), "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000813
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000814
Christian Heimes180510d2008-03-03 19:15:45 +0000815class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000816
Christian Heimes180510d2008-03-03 19:15:45 +0000817 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000818
Christian Heimes180510d2008-03-03 19:15:45 +0000819 def setUp(self):
820 """Create a dict to remember potentially destroyed objects."""
821 BaseTest.setUp(self)
822 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000823
Christian Heimes180510d2008-03-03 19:15:45 +0000824 def _watch_for_survival(self, *args):
825 """Watch the given objects for survival, by creating weakrefs to
826 them."""
827 for obj in args:
828 key = id(obj), repr(obj)
829 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000830
Benjamin Petersonc9c0f202009-06-30 23:06:06 +0000831 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +0000832 """Assert that all objects watched for survival have survived."""
833 # Trigger cycle breaking.
834 gc.collect()
835 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000836 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000837 if ref() is None:
838 dead.append(repr_)
839 if dead:
840 self.fail("%d objects should have survived "
841 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000842
Christian Heimes180510d2008-03-03 19:15:45 +0000843 def test_persistent_loggers(self):
844 # Logger objects are persistent and retain their configuration, even
845 # if visible references are destroyed.
846 self.root_logger.setLevel(logging.INFO)
847 foo = logging.getLogger("foo")
848 self._watch_for_survival(foo)
849 foo.setLevel(logging.DEBUG)
850 self.root_logger.debug(self.next_message())
851 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000852 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000853 ('foo', 'DEBUG', '2'),
854 ])
855 del foo
856 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +0000857 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +0000858 # foo has retained its settings.
859 bar = logging.getLogger("foo")
860 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000861 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000862 ('foo', 'DEBUG', '2'),
863 ('foo', 'DEBUG', '3'),
864 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000865
Benjamin Petersonf91df042009-02-13 02:50:59 +0000866
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000867class EncodingTest(BaseTest):
868 def test_encoding_plain_file(self):
869 # In Python 2.x, a plain file object is treated as having no encoding.
870 log = logging.getLogger("test")
871 fn = tempfile.mktemp(".log")
872 # the non-ascii data we write to the log.
873 data = "foo\x80"
874 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000875 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000876 log.addHandler(handler)
877 try:
878 # write non-ascii data to the log.
879 log.warning(data)
880 finally:
881 log.removeHandler(handler)
882 handler.close()
883 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000884 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000885 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +0000886 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +0000887 finally:
888 f.close()
889 finally:
890 if os.path.isfile(fn):
891 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000892
Benjamin Petersonf91df042009-02-13 02:50:59 +0000893 def test_encoding_cyrillic_unicode(self):
894 log = logging.getLogger("test")
895 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
896 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
897 #Ensure it's written in a Cyrillic encoding
898 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +0000899 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +0000900 stream = io.BytesIO()
901 writer = writer_class(stream, 'strict')
902 handler = logging.StreamHandler(writer)
903 log.addHandler(handler)
904 try:
905 log.warning(message)
906 finally:
907 log.removeHandler(handler)
908 handler.close()
909 # check we wrote exactly those bytes, ignoring trailing \n etc
910 s = stream.getvalue()
911 #Compare against what the data should be when encoded in CP-1251
912 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
913
914
Georg Brandlf9734072008-12-07 15:30:06 +0000915class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +0000916
Georg Brandlf9734072008-12-07 15:30:06 +0000917 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +0000918 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +0000919 logging.captureWarnings(True)
Brett Cannondf8709d2009-04-01 20:01:47 +0000920 try:
Brett Cannon5b9082a2009-04-05 18:57:32 +0000921 warnings.filterwarnings("always", category=UserWarning)
Brett Cannondf8709d2009-04-01 20:01:47 +0000922 file = io.StringIO()
923 h = logging.StreamHandler(file)
924 logger = logging.getLogger("py.warnings")
925 logger.addHandler(h)
926 warnings.warn("I'm warning you...")
927 logger.removeHandler(h)
928 s = file.getvalue()
929 h.close()
930 self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0)
Georg Brandlf9734072008-12-07 15:30:06 +0000931
Brett Cannondf8709d2009-04-01 20:01:47 +0000932 #See if an explicit file uses the original implementation
933 file = io.StringIO()
934 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
935 file, "Dummy line")
936 s = file.getvalue()
937 file.close()
938 self.assertEqual(s,
939 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
940 finally:
941 logging.captureWarnings(False)
Georg Brandlf9734072008-12-07 15:30:06 +0000942
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000943
944def formatFunc(format, datefmt=None):
945 return logging.Formatter(format, datefmt)
946
947def handlerFunc():
948 return logging.StreamHandler()
949
950class CustomHandler(logging.StreamHandler):
951 pass
952
953class ConfigDictTest(BaseTest):
954
955 """Reading logging config from a dictionary."""
956
957 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
958
959 # config0 is a standard configuration.
960 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000961 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000962 'formatters': {
963 'form1' : {
964 'format' : '%(levelname)s ++ %(message)s',
965 },
966 },
967 'handlers' : {
968 'hand1' : {
969 'class' : 'logging.StreamHandler',
970 'formatter' : 'form1',
971 'level' : 'NOTSET',
972 'stream' : 'ext://sys.stdout',
973 },
974 },
975 'root' : {
976 'level' : 'WARNING',
977 'handlers' : ['hand1'],
978 },
979 }
980
981 # config1 adds a little to the standard configuration.
982 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000983 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000984 'formatters': {
985 'form1' : {
986 'format' : '%(levelname)s ++ %(message)s',
987 },
988 },
989 'handlers' : {
990 'hand1' : {
991 'class' : 'logging.StreamHandler',
992 'formatter' : 'form1',
993 'level' : 'NOTSET',
994 'stream' : 'ext://sys.stdout',
995 },
996 },
997 'loggers' : {
998 'compiler.parser' : {
999 'level' : 'DEBUG',
1000 'handlers' : ['hand1'],
1001 },
1002 },
1003 'root' : {
1004 'level' : 'WARNING',
1005 },
1006 }
1007
1008 # config2 has a subtle configuration error that should be reported
1009 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001010 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001011 'formatters': {
1012 'form1' : {
1013 'format' : '%(levelname)s ++ %(message)s',
1014 },
1015 },
1016 'handlers' : {
1017 'hand1' : {
1018 'class' : 'logging.StreamHandler',
1019 'formatter' : 'form1',
1020 'level' : 'NOTSET',
1021 'stream' : 'ext://sys.stdbout',
1022 },
1023 },
1024 'loggers' : {
1025 'compiler.parser' : {
1026 'level' : 'DEBUG',
1027 'handlers' : ['hand1'],
1028 },
1029 },
1030 'root' : {
1031 'level' : 'WARNING',
1032 },
1033 }
1034
1035 #As config1 but with a misspelt level on a handler
1036 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001037 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001038 'formatters': {
1039 'form1' : {
1040 'format' : '%(levelname)s ++ %(message)s',
1041 },
1042 },
1043 'handlers' : {
1044 'hand1' : {
1045 'class' : 'logging.StreamHandler',
1046 'formatter' : 'form1',
1047 'level' : 'NTOSET',
1048 'stream' : 'ext://sys.stdout',
1049 },
1050 },
1051 'loggers' : {
1052 'compiler.parser' : {
1053 'level' : 'DEBUG',
1054 'handlers' : ['hand1'],
1055 },
1056 },
1057 'root' : {
1058 'level' : 'WARNING',
1059 },
1060 }
1061
1062
1063 #As config1 but with a misspelt level on a logger
1064 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001065 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001066 'formatters': {
1067 'form1' : {
1068 'format' : '%(levelname)s ++ %(message)s',
1069 },
1070 },
1071 'handlers' : {
1072 'hand1' : {
1073 'class' : 'logging.StreamHandler',
1074 'formatter' : 'form1',
1075 'level' : 'NOTSET',
1076 'stream' : 'ext://sys.stdout',
1077 },
1078 },
1079 'loggers' : {
1080 'compiler.parser' : {
1081 'level' : 'DEBUG',
1082 'handlers' : ['hand1'],
1083 },
1084 },
1085 'root' : {
1086 'level' : 'WRANING',
1087 },
1088 }
1089
1090 # config3 has a less subtle configuration error
1091 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001092 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001093 'formatters': {
1094 'form1' : {
1095 'format' : '%(levelname)s ++ %(message)s',
1096 },
1097 },
1098 'handlers' : {
1099 'hand1' : {
1100 'class' : 'logging.StreamHandler',
1101 'formatter' : 'misspelled_name',
1102 'level' : 'NOTSET',
1103 'stream' : 'ext://sys.stdout',
1104 },
1105 },
1106 'loggers' : {
1107 'compiler.parser' : {
1108 'level' : 'DEBUG',
1109 'handlers' : ['hand1'],
1110 },
1111 },
1112 'root' : {
1113 'level' : 'WARNING',
1114 },
1115 }
1116
1117 # config4 specifies a custom formatter class to be loaded
1118 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001119 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001120 'formatters': {
1121 'form1' : {
1122 '()' : __name__ + '.ExceptionFormatter',
1123 'format' : '%(levelname)s:%(name)s:%(message)s',
1124 },
1125 },
1126 'handlers' : {
1127 'hand1' : {
1128 'class' : 'logging.StreamHandler',
1129 'formatter' : 'form1',
1130 'level' : 'NOTSET',
1131 'stream' : 'ext://sys.stdout',
1132 },
1133 },
1134 'root' : {
1135 'level' : 'NOTSET',
1136 'handlers' : ['hand1'],
1137 },
1138 }
1139
1140 # As config4 but using an actual callable rather than a string
1141 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001142 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001143 'formatters': {
1144 'form1' : {
1145 '()' : ExceptionFormatter,
1146 'format' : '%(levelname)s:%(name)s:%(message)s',
1147 },
1148 'form2' : {
1149 '()' : __name__ + '.formatFunc',
1150 'format' : '%(levelname)s:%(name)s:%(message)s',
1151 },
1152 'form3' : {
1153 '()' : formatFunc,
1154 'format' : '%(levelname)s:%(name)s:%(message)s',
1155 },
1156 },
1157 'handlers' : {
1158 'hand1' : {
1159 'class' : 'logging.StreamHandler',
1160 'formatter' : 'form1',
1161 'level' : 'NOTSET',
1162 'stream' : 'ext://sys.stdout',
1163 },
1164 'hand2' : {
1165 '()' : handlerFunc,
1166 },
1167 },
1168 'root' : {
1169 'level' : 'NOTSET',
1170 'handlers' : ['hand1'],
1171 },
1172 }
1173
1174 # config5 specifies a custom handler class to be loaded
1175 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001176 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001177 'formatters': {
1178 'form1' : {
1179 'format' : '%(levelname)s ++ %(message)s',
1180 },
1181 },
1182 'handlers' : {
1183 'hand1' : {
1184 'class' : __name__ + '.CustomHandler',
1185 'formatter' : 'form1',
1186 'level' : 'NOTSET',
1187 'stream' : 'ext://sys.stdout',
1188 },
1189 },
1190 'loggers' : {
1191 'compiler.parser' : {
1192 'level' : 'DEBUG',
1193 'handlers' : ['hand1'],
1194 },
1195 },
1196 'root' : {
1197 'level' : 'WARNING',
1198 },
1199 }
1200
1201 # config6 specifies a custom handler class to be loaded
1202 # but has bad arguments
1203 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001204 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001205 'formatters': {
1206 'form1' : {
1207 'format' : '%(levelname)s ++ %(message)s',
1208 },
1209 },
1210 'handlers' : {
1211 'hand1' : {
1212 'class' : __name__ + '.CustomHandler',
1213 'formatter' : 'form1',
1214 'level' : 'NOTSET',
1215 'stream' : 'ext://sys.stdout',
1216 '9' : 'invalid parameter name',
1217 },
1218 },
1219 'loggers' : {
1220 'compiler.parser' : {
1221 'level' : 'DEBUG',
1222 'handlers' : ['hand1'],
1223 },
1224 },
1225 'root' : {
1226 'level' : 'WARNING',
1227 },
1228 }
1229
1230 #config 7 does not define compiler.parser but defines compiler.lexer
1231 #so compiler.parser should be disabled after applying it
1232 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001233 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001234 'formatters': {
1235 'form1' : {
1236 'format' : '%(levelname)s ++ %(message)s',
1237 },
1238 },
1239 'handlers' : {
1240 'hand1' : {
1241 'class' : 'logging.StreamHandler',
1242 'formatter' : 'form1',
1243 'level' : 'NOTSET',
1244 'stream' : 'ext://sys.stdout',
1245 },
1246 },
1247 'loggers' : {
1248 'compiler.lexer' : {
1249 'level' : 'DEBUG',
1250 'handlers' : ['hand1'],
1251 },
1252 },
1253 'root' : {
1254 'level' : 'WARNING',
1255 },
1256 }
1257
1258 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001259 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001260 'disable_existing_loggers' : False,
1261 'formatters': {
1262 'form1' : {
1263 'format' : '%(levelname)s ++ %(message)s',
1264 },
1265 },
1266 'handlers' : {
1267 'hand1' : {
1268 'class' : 'logging.StreamHandler',
1269 'formatter' : 'form1',
1270 'level' : 'NOTSET',
1271 'stream' : 'ext://sys.stdout',
1272 },
1273 },
1274 'loggers' : {
1275 'compiler' : {
1276 'level' : 'DEBUG',
1277 'handlers' : ['hand1'],
1278 },
1279 'compiler.lexer' : {
1280 },
1281 },
1282 'root' : {
1283 'level' : 'WARNING',
1284 },
1285 }
1286
1287 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001288 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001289 'formatters': {
1290 'form1' : {
1291 'format' : '%(levelname)s ++ %(message)s',
1292 },
1293 },
1294 'handlers' : {
1295 'hand1' : {
1296 'class' : 'logging.StreamHandler',
1297 'formatter' : 'form1',
1298 'level' : 'WARNING',
1299 'stream' : 'ext://sys.stdout',
1300 },
1301 },
1302 'loggers' : {
1303 'compiler.parser' : {
1304 'level' : 'WARNING',
1305 'handlers' : ['hand1'],
1306 },
1307 },
1308 'root' : {
1309 'level' : 'NOTSET',
1310 },
1311 }
1312
1313 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001314 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001315 'incremental' : True,
1316 'handlers' : {
1317 'hand1' : {
1318 'level' : 'WARNING',
1319 },
1320 },
1321 'loggers' : {
1322 'compiler.parser' : {
1323 'level' : 'INFO',
1324 },
1325 },
1326 }
1327
1328 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001329 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001330 'incremental' : True,
1331 'handlers' : {
1332 'hand1' : {
1333 'level' : 'INFO',
1334 },
1335 },
1336 'loggers' : {
1337 'compiler.parser' : {
1338 'level' : 'INFO',
1339 },
1340 },
1341 }
1342
1343 #As config1 but with a filter added
1344 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001345 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001346 'formatters': {
1347 'form1' : {
1348 'format' : '%(levelname)s ++ %(message)s',
1349 },
1350 },
1351 'filters' : {
1352 'filt1' : {
1353 'name' : 'compiler.parser',
1354 },
1355 },
1356 'handlers' : {
1357 'hand1' : {
1358 'class' : 'logging.StreamHandler',
1359 'formatter' : 'form1',
1360 'level' : 'NOTSET',
1361 'stream' : 'ext://sys.stdout',
1362 'filters' : ['filt1'],
1363 },
1364 },
1365 'loggers' : {
1366 'compiler.parser' : {
1367 'level' : 'DEBUG',
1368 'filters' : ['filt1'],
1369 },
1370 },
1371 'root' : {
1372 'level' : 'WARNING',
1373 'handlers' : ['hand1'],
1374 },
1375 }
1376
1377 #As config1 but using cfg:// references
1378 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001379 'version': 1,
1380 'true_formatters': {
1381 'form1' : {
1382 'format' : '%(levelname)s ++ %(message)s',
1383 },
1384 },
1385 'handler_configs': {
1386 'hand1' : {
1387 'class' : 'logging.StreamHandler',
1388 'formatter' : 'form1',
1389 'level' : 'NOTSET',
1390 'stream' : 'ext://sys.stdout',
1391 },
1392 },
1393 'formatters' : 'cfg://true_formatters',
1394 'handlers' : {
1395 'hand1' : 'cfg://handler_configs[hand1]',
1396 },
1397 'loggers' : {
1398 'compiler.parser' : {
1399 'level' : 'DEBUG',
1400 'handlers' : ['hand1'],
1401 },
1402 },
1403 'root' : {
1404 'level' : 'WARNING',
1405 },
1406 }
1407
1408 #As config11 but missing the version key
1409 config12 = {
1410 'true_formatters': {
1411 'form1' : {
1412 'format' : '%(levelname)s ++ %(message)s',
1413 },
1414 },
1415 'handler_configs': {
1416 'hand1' : {
1417 'class' : 'logging.StreamHandler',
1418 'formatter' : 'form1',
1419 'level' : 'NOTSET',
1420 'stream' : 'ext://sys.stdout',
1421 },
1422 },
1423 'formatters' : 'cfg://true_formatters',
1424 'handlers' : {
1425 'hand1' : 'cfg://handler_configs[hand1]',
1426 },
1427 'loggers' : {
1428 'compiler.parser' : {
1429 'level' : 'DEBUG',
1430 'handlers' : ['hand1'],
1431 },
1432 },
1433 'root' : {
1434 'level' : 'WARNING',
1435 },
1436 }
1437
1438 #As config11 but using an unsupported version
1439 config13 = {
1440 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001441 'true_formatters': {
1442 'form1' : {
1443 'format' : '%(levelname)s ++ %(message)s',
1444 },
1445 },
1446 'handler_configs': {
1447 'hand1' : {
1448 'class' : 'logging.StreamHandler',
1449 'formatter' : 'form1',
1450 'level' : 'NOTSET',
1451 'stream' : 'ext://sys.stdout',
1452 },
1453 },
1454 'formatters' : 'cfg://true_formatters',
1455 'handlers' : {
1456 'hand1' : 'cfg://handler_configs[hand1]',
1457 },
1458 'loggers' : {
1459 'compiler.parser' : {
1460 'level' : 'DEBUG',
1461 'handlers' : ['hand1'],
1462 },
1463 },
1464 'root' : {
1465 'level' : 'WARNING',
1466 },
1467 }
1468
1469 def apply_config(self, conf):
1470 logging.config.dictConfig(conf)
1471
1472 def test_config0_ok(self):
1473 # A simple config which overrides the default settings.
1474 with captured_stdout() as output:
1475 self.apply_config(self.config0)
1476 logger = logging.getLogger()
1477 # Won't output anything
1478 logger.info(self.next_message())
1479 # Outputs a message
1480 logger.error(self.next_message())
1481 self.assert_log_lines([
1482 ('ERROR', '2'),
1483 ], stream=output)
1484 # Original logger output is empty.
1485 self.assert_log_lines([])
1486
1487 def test_config1_ok(self, config=config1):
1488 # A config defining a sub-parser as well.
1489 with captured_stdout() as output:
1490 self.apply_config(config)
1491 logger = logging.getLogger("compiler.parser")
1492 # Both will output a message
1493 logger.info(self.next_message())
1494 logger.error(self.next_message())
1495 self.assert_log_lines([
1496 ('INFO', '1'),
1497 ('ERROR', '2'),
1498 ], stream=output)
1499 # Original logger output is empty.
1500 self.assert_log_lines([])
1501
1502 def test_config2_failure(self):
1503 # A simple config which overrides the default settings.
1504 self.assertRaises(Exception, self.apply_config, self.config2)
1505
1506 def test_config2a_failure(self):
1507 # A simple config which overrides the default settings.
1508 self.assertRaises(Exception, self.apply_config, self.config2a)
1509
1510 def test_config2b_failure(self):
1511 # A simple config which overrides the default settings.
1512 self.assertRaises(Exception, self.apply_config, self.config2b)
1513
1514 def test_config3_failure(self):
1515 # A simple config which overrides the default settings.
1516 self.assertRaises(Exception, self.apply_config, self.config3)
1517
1518 def test_config4_ok(self):
1519 # A config specifying a custom formatter class.
1520 with captured_stdout() as output:
1521 self.apply_config(self.config4)
1522 #logger = logging.getLogger()
1523 try:
1524 raise RuntimeError()
1525 except RuntimeError:
1526 logging.exception("just testing")
1527 sys.stdout.seek(0)
1528 self.assertEquals(output.getvalue(),
1529 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1530 # Original logger output is empty
1531 self.assert_log_lines([])
1532
1533 def test_config4a_ok(self):
1534 # A config specifying a custom formatter class.
1535 with captured_stdout() as output:
1536 self.apply_config(self.config4a)
1537 #logger = logging.getLogger()
1538 try:
1539 raise RuntimeError()
1540 except RuntimeError:
1541 logging.exception("just testing")
1542 sys.stdout.seek(0)
1543 self.assertEquals(output.getvalue(),
1544 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1545 # Original logger output is empty
1546 self.assert_log_lines([])
1547
1548 def test_config5_ok(self):
1549 self.test_config1_ok(config=self.config5)
1550
1551 def test_config6_failure(self):
1552 self.assertRaises(Exception, self.apply_config, self.config6)
1553
1554 def test_config7_ok(self):
1555 with captured_stdout() as output:
1556 self.apply_config(self.config1)
1557 logger = logging.getLogger("compiler.parser")
1558 # Both will output a message
1559 logger.info(self.next_message())
1560 logger.error(self.next_message())
1561 self.assert_log_lines([
1562 ('INFO', '1'),
1563 ('ERROR', '2'),
1564 ], stream=output)
1565 # Original logger output is empty.
1566 self.assert_log_lines([])
1567 with captured_stdout() as output:
1568 self.apply_config(self.config7)
1569 logger = logging.getLogger("compiler.parser")
1570 self.assertTrue(logger.disabled)
1571 logger = logging.getLogger("compiler.lexer")
1572 # Both will output a message
1573 logger.info(self.next_message())
1574 logger.error(self.next_message())
1575 self.assert_log_lines([
1576 ('INFO', '3'),
1577 ('ERROR', '4'),
1578 ], stream=output)
1579 # Original logger output is empty.
1580 self.assert_log_lines([])
1581
1582 #Same as test_config_7_ok but don't disable old loggers.
1583 def test_config_8_ok(self):
1584 with captured_stdout() as output:
1585 self.apply_config(self.config1)
1586 logger = logging.getLogger("compiler.parser")
1587 # Both will output a message
1588 logger.info(self.next_message())
1589 logger.error(self.next_message())
1590 self.assert_log_lines([
1591 ('INFO', '1'),
1592 ('ERROR', '2'),
1593 ], stream=output)
1594 # Original logger output is empty.
1595 self.assert_log_lines([])
1596 with captured_stdout() as output:
1597 self.apply_config(self.config8)
1598 logger = logging.getLogger("compiler.parser")
1599 self.assertFalse(logger.disabled)
1600 # Both will output a message
1601 logger.info(self.next_message())
1602 logger.error(self.next_message())
1603 logger = logging.getLogger("compiler.lexer")
1604 # Both will output a message
1605 logger.info(self.next_message())
1606 logger.error(self.next_message())
1607 self.assert_log_lines([
1608 ('INFO', '3'),
1609 ('ERROR', '4'),
1610 ('INFO', '5'),
1611 ('ERROR', '6'),
1612 ], stream=output)
1613 # Original logger output is empty.
1614 self.assert_log_lines([])
1615
1616 def test_config_9_ok(self):
1617 with captured_stdout() as output:
1618 self.apply_config(self.config9)
1619 logger = logging.getLogger("compiler.parser")
1620 #Nothing will be output since both handler and logger are set to WARNING
1621 logger.info(self.next_message())
1622 self.assert_log_lines([], stream=output)
1623 self.apply_config(self.config9a)
1624 #Nothing will be output since both handler is still set to WARNING
1625 logger.info(self.next_message())
1626 self.assert_log_lines([], stream=output)
1627 self.apply_config(self.config9b)
1628 #Message should now be output
1629 logger.info(self.next_message())
1630 self.assert_log_lines([
1631 ('INFO', '3'),
1632 ], stream=output)
1633
1634 def test_config_10_ok(self):
1635 with captured_stdout() as output:
1636 self.apply_config(self.config10)
1637 logger = logging.getLogger("compiler.parser")
1638 logger.warning(self.next_message())
1639 logger = logging.getLogger('compiler')
1640 #Not output, because filtered
1641 logger.warning(self.next_message())
1642 logger = logging.getLogger('compiler.lexer')
1643 #Not output, because filtered
1644 logger.warning(self.next_message())
1645 logger = logging.getLogger("compiler.parser.codegen")
1646 #Output, as not filtered
1647 logger.error(self.next_message())
1648 self.assert_log_lines([
1649 ('WARNING', '1'),
1650 ('ERROR', '4'),
1651 ], stream=output)
1652
1653 def test_config11_ok(self):
1654 self.test_config1_ok(self.config11)
1655
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001656 def test_config12_failure(self):
1657 self.assertRaises(Exception, self.apply_config, self.config12)
1658
1659 def test_config13_failure(self):
1660 self.assertRaises(Exception, self.apply_config, self.config13)
1661
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001662 def setup_via_listener(self, text):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001663 text = text.encode("utf-8")
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001664 port = find_unused_port()
1665 t = logging.config.listen(port)
1666 t.start()
1667 t.ready.wait()
1668 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001669 try:
1670 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
1671 sock.settimeout(2.0)
1672 sock.connect(('localhost', port))
1673
1674 slen = struct.pack('>L', len(text))
1675 s = slen + text
1676 sentsofar = 0
1677 left = len(s)
1678 while left > 0:
1679 sent = sock.send(s[sentsofar:])
1680 sentsofar += sent
1681 left -= sent
1682 sock.close()
1683 finally:
1684 t.ready.wait(2.0)
1685 logging.config.stopListening()
1686 t.join(2.0)
1687
1688 def test_listen_config_10_ok(self):
1689 with captured_stdout() as output:
1690 self.setup_via_listener(json.dumps(self.config10))
1691 logger = logging.getLogger("compiler.parser")
1692 logger.warning(self.next_message())
1693 logger = logging.getLogger('compiler')
1694 #Not output, because filtered
1695 logger.warning(self.next_message())
1696 logger = logging.getLogger('compiler.lexer')
1697 #Not output, because filtered
1698 logger.warning(self.next_message())
1699 logger = logging.getLogger("compiler.parser.codegen")
1700 #Output, as not filtered
1701 logger.error(self.next_message())
1702 self.assert_log_lines([
1703 ('WARNING', '1'),
1704 ('ERROR', '4'),
1705 ], stream=output)
1706
1707 def test_listen_config_1_ok(self):
1708 with captured_stdout() as output:
1709 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
1710 logger = logging.getLogger("compiler.parser")
1711 # Both will output a message
1712 logger.info(self.next_message())
1713 logger.error(self.next_message())
1714 self.assert_log_lines([
1715 ('INFO', '1'),
1716 ('ERROR', '2'),
1717 ], stream=output)
1718 # Original logger output is empty.
1719 self.assert_log_lines([])
1720
1721
1722class ManagerTest(BaseTest):
1723 def test_manager_loggerclass(self):
1724 logged = []
1725
1726 class MyLogger(logging.Logger):
1727 def _log(self, level, msg, args, exc_info=None, extra=None):
1728 logged.append(msg)
1729
1730 man = logging.Manager(None)
1731 self.assertRaises(TypeError, man.setLoggerClass, int)
1732 man.setLoggerClass(MyLogger)
1733 logger = man.getLogger('test')
1734 logger.warning('should appear in logged')
1735 logging.warning('should not appear in logged')
1736
1737 self.assertEqual(logged, ['should appear in logged'])
1738
1739
Benjamin Peterson22005fc2010-04-11 16:25:06 +00001740class ChildLoggerTest(BaseTest):
1741 def test_child_loggers(self):
1742 r = logging.getLogger()
1743 l1 = logging.getLogger('abc')
1744 l2 = logging.getLogger('def.ghi')
1745 c1 = r.getChild('xyz')
1746 c2 = r.getChild('uvw.xyz')
1747 self.assertTrue(c1 is logging.getLogger('xyz'))
1748 self.assertTrue(c2 is logging.getLogger('uvw.xyz'))
1749 c1 = l1.getChild('def')
1750 c2 = c1.getChild('ghi')
1751 c3 = l1.getChild('def.ghi')
1752 self.assertTrue(c1 is logging.getLogger('abc.def'))
1753 self.assertTrue(c2 is logging.getLogger('abc.def.ghi'))
1754 self.assertTrue(c2 is c3)
1755
1756
Christian Heimes180510d2008-03-03 19:15:45 +00001757# Set the locale to the platform-dependent default. I have no idea
1758# why the test does this, but in any case we save the current locale
1759# first and restore it at the end.
1760@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00001761def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +00001762 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001763 CustomLevelsAndFiltersTest, MemoryHandlerTest,
1764 ConfigFileTest, SocketHandlerTest, MemoryTest,
Benjamin Peterson22005fc2010-04-11 16:25:06 +00001765 EncodingTest, WarningsTest, ConfigDictTest, ManagerTest,
1766 ChildLoggerTest)
Jeremy Hylton096d9862003-07-18 03:19:20 +00001767
Christian Heimes180510d2008-03-03 19:15:45 +00001768if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001769 test_main()