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