blob: 0211f560747192a67593eb22a5e81723f4173ba1 [file] [log] [blame]
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001#!/usr/bin/env python
Brett Cannon56c4deb2008-03-03 00:38:58 +00002#
Georg Brandl8cdc9bc2010-01-01 13:07:05 +00003# Copyright 2001-2010 by Vinay Sajip. All Rights Reserved.
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Georg Brandl8cdc9bc2010-01-01 13:07:05 +000021Copyright (C) 2001-2010 Vinay Sajip. All Rights Reserved.
Neal Norwitzb4a2df02003-01-02 14:56:39 +000022"""
23
Brett Cannon56c4deb2008-03-03 00:38:58 +000024import logging
25import logging.handlers
26import logging.config
Brett Cannonf9db8a32008-02-17 01:59:18 +000027
Vinay Sajipb20af942009-02-08 19:06:08 +000028import codecs
Brett Cannon56c4deb2008-03-03 00:38:58 +000029import cPickle
30import cStringIO
31import gc
Vinay Sajip28c382f2010-02-04 18:48:53 +000032import json
Brett Cannon56c4deb2008-03-03 00:38:58 +000033import os
34import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000035import select
Brett Cannon56c4deb2008-03-03 00:38:58 +000036import socket
Georg Brandle152a772008-05-24 18:31:28 +000037from SocketServer import ThreadingTCPServer, StreamRequestHandler
Brett Cannon56c4deb2008-03-03 00:38:58 +000038import struct
39import sys
40import tempfile
Vinay Sajip3dd734f2010-02-05 14:52:05 +000041from test.test_support import captured_stdout, run_with_locale, run_unittest,\
42 find_unused_port
Brett Cannon56c4deb2008-03-03 00:38:58 +000043import textwrap
Brett Cannon56c4deb2008-03-03 00:38:58 +000044import unittest
Vinay Sajip213faca2008-12-03 23:22:58 +000045import warnings
Brett Cannon56c4deb2008-03-03 00:38:58 +000046import weakref
Victor Stinner6a102812010-04-27 23:55:59 +000047try:
48 import threading
49except ImportError:
50 threading = None
Brett Cannonf9db8a32008-02-17 01:59:18 +000051
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannonf9db8a32008-02-17 01:59:18 +000064 logging._acquireLock()
65 try:
Brett Cannon56c4deb2008-03-03 00:38:58 +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()
Brett Cannonf9db8a32008-02-17 01:59:18 +000070 finally:
71 logging._releaseLock()
72
Vinay Sajip31e928e2010-03-22 13:02:28 +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(u"\u013f\u00d6\u0047")
78
Brett Cannon56c4deb2008-03-03 00:38:58 +000079 self.root_logger = logging.getLogger("")
80 self.original_logging_level = self.root_logger.getEffectiveLevel()
81
82 self.stream = cStringIO.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 Sajip28c382f2010-02-04 18:48:53 +000094 while self.root_logger.handlers:
95 h = self.root_logger.handlers[0]
96 self.root_logger.removeHandler(h)
97 h.close()
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000112 def assert_log_lines(self, expected_values, stream=None):
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000178 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000210 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000241 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000269 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000298 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +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)
368 for k, v in my_logging_levels.items():
369 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 Peterson4d3f18f2009-07-01 00:36:41 +0000380 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000395 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000426 self.assert_log_lines(first_lines)
Brett Cannon56c4deb2008-03-03 00:38:58 +0000427
428 specific_filter = VerySpecificFilter()
429 self.root_logger.addFilter(specific_filter)
430 self.log_at_all_levels(self.root_logger)
Benjamin Peterson4d3f18f2009-07-01 00:36:41 +0000431 self.assert_log_lines(first_lines + [
Brett Cannon56c4deb2008-03-03 00:38:58 +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()
Amaury Forgeot d'Arc2aece572008-03-29 01:42:31 +0000465 BaseTest.tearDown(self)
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000471 self.assert_log_lines([])
Brett Cannon56c4deb2008-03-03 00:38:58 +0000472 self.mem_logger.info(self.next_message())
Benjamin Peterson4d3f18f2009-07-01 00:36:41 +0000473 self.assert_log_lines([])
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000481 self.assert_log_lines(lines)
Brett Cannon56c4deb2008-03-03 00:38:58 +0000482 for n in (4, 14):
483 for i in range(9):
484 self.mem_logger.debug(self.next_message())
Benjamin Peterson4d3f18f2009-07-01 00:36:41 +0000485 self.assert_log_lines(lines)
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000490 self.assert_log_lines(lines)
Brett Cannon56c4deb2008-03-03 00:38:58 +0000491
492 self.mem_logger.debug(self.next_message())
Benjamin Peterson4d3f18f2009-07-01 00:36:41 +0000493 self.assert_log_lines(lines)
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Vinay Sajip70fdc952008-07-18 09:00:00 +0000599 # config5 specifies a custom handler class to be loaded
600 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
601
Vinay Sajip6a2fd812008-09-03 09:20:05 +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]
Vinay Sajip844f7412008-09-09 13:42:08 +0000630 class=StreamHandler
Vinay Sajip6a2fd812008-09-03 09:20:05 +0000631 level=NOTSET
632 formatter=form1
Vinay Sajip844f7412008-09-09 13:42:08 +0000633 args=(sys.stderr,)
Vinay Sajip6a2fd812008-09-03 09:20:05 +0000634
635 [formatter_form1]
636 format=%(levelname)s ++ %(message)s
637 datefmt=
638
639 [formatter_form2]
640 format=%(message)s
641 datefmt=
642 """
643
Brett Cannon56c4deb2008-03-03 00:38:58 +0000644 def apply_config(self, conf):
Vinay Sajip28c382f2010-02-04 18:48:53 +0000645 file = cStringIO.StringIO(textwrap.dedent(conf))
646 logging.config.fileConfig(file)
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000657 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +0000658 ('ERROR', '2'),
659 ], stream=output)
660 # Original logger output is empty.
Benjamin Peterson4d3f18f2009-07-01 00:36:41 +0000661 self.assert_log_lines([])
Brett Cannon56c4deb2008-03-03 00:38:58 +0000662
Vinay Sajip70fdc952008-07-18 09:00:00 +0000663 def test_config1_ok(self, config=config1):
Brett Cannon56c4deb2008-03-03 00:38:58 +0000664 # A config file defining a sub-parser as well.
665 with captured_stdout() as output:
Vinay Sajip70fdc952008-07-18 09:00:00 +0000666 self.apply_config(config)
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000671 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +0000672 ('INFO', '1'),
673 ('ERROR', '2'),
674 ], stream=output)
675 # Original logger output is empty.
Benjamin Peterson4d3f18f2009-07-01 00:36:41 +0000676 self.assert_log_lines([])
Brett Cannon56c4deb2008-03-03 00:38:58 +0000677
678 def test_config2_failure(self):
679 # A simple config file which overrides the default settings.
680 self.assertRaises(StandardError, 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(StandardError, 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 Peterson4d3f18f2009-07-01 00:36:41 +0000699 self.assert_log_lines([])
Brett Cannon56c4deb2008-03-03 00:38:58 +0000700
Vinay Sajip70fdc952008-07-18 09:00:00 +0000701 def test_config5_ok(self):
702 self.test_config1_ok(config=self.config5)
Brett Cannon56c4deb2008-03-03 00:38:58 +0000703
Vinay Sajip6a2fd812008-09-03 09:20:05 +0000704 def test_config6_ok(self):
705 self.test_config1_ok(config=self.config6)
706
Brett Cannon56c4deb2008-03-03 00:38:58 +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 cPickle.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):
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannon56c4deb2008-03-03 00:38:58 +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)
Georg Brandl57826cf2008-02-23 15:06:25 +0000754 self.abort = False
Brett Cannon56c4deb2008-03-03 00:38:58 +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()
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Stinner6a102812010-04-27 23:55:59 +0000770@unittest.skipUnless(threading, 'Threading required for this test.')
Brett Cannon56c4deb2008-03-03 00:38:58 +0000771class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000772
Brett Cannon56c4deb2008-03-03 00:38:58 +0000773 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000774
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannon56c4deb2008-03-03 00:38:58 +0000818class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000819
Brett Cannon56c4deb2008-03-03 00:38:58 +0000820 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000821
Brett Cannon56c4deb2008-03-03 00:38:58 +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
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson5c8da862009-06-30 22:57:08 +0000834 def _assertTruesurvival(self):
Brett Cannon56c4deb2008-03-03 00:38:58 +0000835 """Assert that all objects watched for survival have survived."""
836 # Trigger cycle breaking.
837 gc.collect()
838 dead = []
839 for (id_, repr_), ref in self._survivors.items():
840 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
Brett Cannon56c4deb2008-03-03 00:38:58 +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 Peterson4d3f18f2009-07-01 00:36:41 +0000855 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +0000856 ('foo', 'DEBUG', '2'),
857 ])
858 del foo
859 # foo has survived.
Benjamin Peterson5c8da862009-06-30 22:57:08 +0000860 self._assertTruesurvival()
Brett Cannon56c4deb2008-03-03 00:38:58 +0000861 # foo has retained its settings.
862 bar = logging.getLogger("foo")
863 bar.debug(self.next_message())
Benjamin Peterson4d3f18f2009-07-01 00:36:41 +0000864 self.assert_log_lines([
Brett Cannon56c4deb2008-03-03 00:38:58 +0000865 ('foo', 'DEBUG', '2'),
866 ('foo', 'DEBUG', '3'),
867 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000868
Vinay Sajipb20af942009-02-08 19:06:08 +0000869
Vinay Sajip65d66e12008-09-04 07:31:21 +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:
878 handler = logging.FileHandler(fn)
879 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
887 f = open(fn)
888 try:
Benjamin Peterson5c8da862009-06-30 22:57:08 +0000889 self.assertEqual(f.read().rstrip(), data)
Vinay Sajip65d66e12008-09-04 07:31:21 +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
Vinay Sajipb20af942009-02-08 19:06:08 +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 = u'\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')
Vinay Sajip74f04502009-04-16 19:07:37 +0000902 writer_class.encoding = 'cp1251'
Vinay Sajipb20af942009-02-08 19:06:08 +0000903 stream = cStringIO.StringIO()
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, '\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
916
917
Vinay Sajip213faca2008-12-03 23:22:58 +0000918class WarningsTest(BaseTest):
Brett Cannon2da4d622009-04-01 19:57:10 +0000919
Vinay Sajip213faca2008-12-03 23:22:58 +0000920 def test_warnings(self):
Brett Cannon2da4d622009-04-01 19:57:10 +0000921 with warnings.catch_warnings():
Vinay Sajip1e566ce2009-04-05 11:06:24 +0000922 logging.captureWarnings(True)
Brett Cannon2da4d622009-04-01 19:57:10 +0000923 try:
Vinay Sajip14bf0a02009-04-07 17:18:24 +0000924 warnings.filterwarnings("always", category=UserWarning)
Brett Cannon2da4d622009-04-01 19:57:10 +0000925 file = cStringIO.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)
Vinay Sajip213faca2008-12-03 23:22:58 +0000934
Brett Cannon2da4d622009-04-01 19:57:10 +0000935 #See if an explicit file uses the original implementation
936 file = cStringIO.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)
Vinay Sajip213faca2008-12-03 23:22:58 +0000945
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +0000964 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +0000986 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001013 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001040 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001068 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001095 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001122 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001145 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001179 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001207 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001236 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001262 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001291 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001317 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001332 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +00001348 'version': 1,
Vinay Sajip28c382f2010-02-04 18:48:53 +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
Vinay Sajipf7610b22010-02-04 21:40:56 +00001380 #As config1 but using cfg:// references
1381 config11 = {
Vinay Sajipd45a2782010-03-06 15:12:08 +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 Sajipf7610b22010-02-04 21:40:56 +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
Vinay Sajip28c382f2010-02-04 18:48:53 +00001472 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(StandardError, self.apply_config, self.config2)
1508
1509 def test_config2a_failure(self):
1510 # A simple config which overrides the default settings.
1511 self.assertRaises(StandardError, self.apply_config, self.config2a)
1512
1513 def test_config2b_failure(self):
1514 # A simple config which overrides the default settings.
1515 self.assertRaises(StandardError, self.apply_config, self.config2b)
1516
1517 def test_config3_failure(self):
1518 # A simple config which overrides the default settings.
1519 self.assertRaises(StandardError, 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(StandardError, 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
Vinay Sajipf7610b22010-02-04 21:40:56 +00001656 def test_config11_ok(self):
1657 self.test_config1_ok(self.config11)
1658
Vinay Sajipd45a2782010-03-06 15:12:08 +00001659 def test_config12_failure(self):
1660 self.assertRaises(StandardError, self.apply_config, self.config12)
1661
1662 def test_config13_failure(self):
1663 self.assertRaises(StandardError, self.apply_config, self.config13)
1664
Victor Stinner6a102812010-04-27 23:55:59 +00001665 @unittest.skipUnless(threading, 'listen() needs threading to work')
Vinay Sajip28c382f2010-02-04 18:48:53 +00001666 def setup_via_listener(self, text):
Vinay Sajip3dd734f2010-02-05 14:52:05 +00001667 port = find_unused_port()
1668 t = logging.config.listen(port)
Vinay Sajip28c382f2010-02-04 18:48:53 +00001669 t.start()
Benjamin Peterson239f1382010-02-06 22:08:15 +00001670 t.ready.wait()
Vinay Sajip9a164ac2010-02-08 16:05:50 +00001671 t.ready.clear()
Vinay Sajip3dd734f2010-02-05 14:52:05 +00001672 try:
1673 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
Vinay Sajip23739262010-02-05 23:43:11 +00001674 sock.settimeout(2.0)
Vinay Sajip3dd734f2010-02-05 14:52:05 +00001675 sock.connect(('localhost', port))
Vinay Sajip28c382f2010-02-04 18:48:53 +00001676
Vinay Sajip3dd734f2010-02-05 14:52:05 +00001677 slen = struct.pack('>L', len(text))
1678 s = slen + text
1679 sentsofar = 0
1680 left = len(s)
1681 while left > 0:
1682 sent = sock.send(s[sentsofar:])
1683 sentsofar += sent
1684 left -= sent
1685 sock.close()
1686 finally:
Vinay Sajip9a164ac2010-02-08 16:05:50 +00001687 t.ready.wait(2.0)
Vinay Sajip3dd734f2010-02-05 14:52:05 +00001688 logging.config.stopListening()
Vinay Sajip23739262010-02-05 23:43:11 +00001689 t.join(2.0)
Vinay Sajip28c382f2010-02-04 18:48:53 +00001690
Vinay Sajip23739262010-02-05 23:43:11 +00001691 def test_listen_config_10_ok(self):
Vinay Sajip28c382f2010-02-04 18:48:53 +00001692 with captured_stdout() as output:
1693 self.setup_via_listener(json.dumps(self.config10))
1694 logger = logging.getLogger("compiler.parser")
1695 logger.warning(self.next_message())
1696 logger = logging.getLogger('compiler')
1697 #Not output, because filtered
1698 logger.warning(self.next_message())
1699 logger = logging.getLogger('compiler.lexer')
1700 #Not output, because filtered
1701 logger.warning(self.next_message())
1702 logger = logging.getLogger("compiler.parser.codegen")
1703 #Output, as not filtered
1704 logger.error(self.next_message())
1705 self.assert_log_lines([
1706 ('WARNING', '1'),
1707 ('ERROR', '4'),
1708 ], stream=output)
1709
Vinay Sajip23739262010-02-05 23:43:11 +00001710 def test_listen_config_1_ok(self):
Vinay Sajip28c382f2010-02-04 18:48:53 +00001711 with captured_stdout() as output:
1712 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
1713 logger = logging.getLogger("compiler.parser")
1714 # Both will output a message
1715 logger.info(self.next_message())
1716 logger.error(self.next_message())
1717 self.assert_log_lines([
1718 ('INFO', '1'),
1719 ('ERROR', '2'),
1720 ], stream=output)
1721 # Original logger output is empty.
1722 self.assert_log_lines([])
1723
1724
Vinay Sajip657514a2010-02-07 01:37:08 +00001725class ManagerTest(BaseTest):
1726 def test_manager_loggerclass(self):
1727 logged = []
1728
1729 class MyLogger(logging.Logger):
1730 def _log(self, level, msg, args, exc_info=None, extra=None):
1731 logged.append(msg)
1732
1733 man = logging.Manager(None)
1734 self.assertRaises(TypeError, man.setLoggerClass, int)
1735 man.setLoggerClass(MyLogger)
1736 logger = man.getLogger('test')
Vinay Sajip657514a2010-02-07 01:37:08 +00001737 logger.warning('should appear in logged')
1738 logging.warning('should not appear in logged')
1739
1740 self.assertEqual(logged, ['should appear in logged'])
1741
1742
Vinay Sajip804899b2010-03-22 15:29:01 +00001743class ChildLoggerTest(BaseTest):
1744 def test_child_loggers(self):
1745 r = logging.getLogger()
1746 l1 = logging.getLogger('abc')
1747 l2 = logging.getLogger('def.ghi')
1748 c1 = r.getChild('xyz')
1749 c2 = r.getChild('uvw.xyz')
1750 self.assertTrue(c1 is logging.getLogger('xyz'))
1751 self.assertTrue(c2 is logging.getLogger('uvw.xyz'))
1752 c1 = l1.getChild('def')
1753 c2 = c1.getChild('ghi')
1754 c3 = l1.getChild('def.ghi')
1755 self.assertTrue(c1 is logging.getLogger('abc.def'))
1756 self.assertTrue(c2 is logging.getLogger('abc.def.ghi'))
1757 self.assertTrue(c2 is c3)
1758
1759
Brett Cannon56c4deb2008-03-03 00:38:58 +00001760# Set the locale to the platform-dependent default. I have no idea
1761# why the test does this, but in any case we save the current locale
1762# first and restore it at the end.
1763@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00001764def test_main():
Brett Cannon56c4deb2008-03-03 00:38:58 +00001765 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajip657514a2010-02-07 01:37:08 +00001766 CustomLevelsAndFiltersTest, MemoryHandlerTest,
1767 ConfigFileTest, SocketHandlerTest, MemoryTest,
Vinay Sajip804899b2010-03-22 15:29:01 +00001768 EncodingTest, WarningsTest, ConfigDictTest, ManagerTest,
1769 ChildLoggerTest)
Jeremy Hylton096d9862003-07-18 03:19:20 +00001770
Brett Cannon56c4deb2008-03-03 00:38:58 +00001771if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001772 test_main()