blob: b937411c038ca2d97db2c5d072549f656604220a [file] [log] [blame]
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001#!/usr/bin/env python
Brett Cannon56c4deb2008-03-03 00:38:58 +00002#
3# Copyright 2001-2004 by Vinay Sajip. All Rights Reserved.
4#
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
21Copyright (C) 2001-2002 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
Brett Cannon56c4deb2008-03-03 00:38:58 +000028import copy
29import cPickle
30import cStringIO
31import gc
32import os
33import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000034import select
Brett Cannon56c4deb2008-03-03 00:38:58 +000035import socket
Neal Norwitzb4a2df02003-01-02 14:56:39 +000036from SocketServer import ThreadingTCPServer, StreamRequestHandler
Brett Cannon56c4deb2008-03-03 00:38:58 +000037import string
38import struct
39import sys
40import tempfile
41from test.test_support import captured_stdout, run_with_locale, run_unittest
42import textwrap
43import threading
44import time
45import types
46import unittest
47import weakref
Brett Cannonf9db8a32008-02-17 01:59:18 +000048
49
Brett Cannon56c4deb2008-03-03 00:38:58 +000050class BaseTest(unittest.TestCase):
51
52 """Base class for logging tests."""
53
54 log_format = "%(name)s -> %(levelname)s: %(message)s"
55 expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$"
56 message_num = 0
57
58 def setUp(self):
59 """Setup the default logging stream to an internal StringIO instance,
60 so that we can examine log output as we want."""
61 logger_dict = logging.getLogger().manager.loggerDict
Brett Cannonf9db8a32008-02-17 01:59:18 +000062 logging._acquireLock()
63 try:
Brett Cannon56c4deb2008-03-03 00:38:58 +000064 self.saved_handlers = logging._handlers.copy()
65 self.saved_handler_list = logging._handlerList[:]
66 self.saved_loggers = logger_dict.copy()
67 self.saved_level_names = logging._levelNames.copy()
Brett Cannonf9db8a32008-02-17 01:59:18 +000068 finally:
69 logging._releaseLock()
70
Brett Cannon56c4deb2008-03-03 00:38:58 +000071 self.root_logger = logging.getLogger("")
72 self.original_logging_level = self.root_logger.getEffectiveLevel()
73
74 self.stream = cStringIO.StringIO()
75 self.root_logger.setLevel(logging.DEBUG)
76 self.root_hdlr = logging.StreamHandler(self.stream)
77 self.root_formatter = logging.Formatter(self.log_format)
78 self.root_hdlr.setFormatter(self.root_formatter)
79 self.root_logger.addHandler(self.root_hdlr)
80
81 def tearDown(self):
82 """Remove our logging stream, and restore the original logging
83 level."""
84 self.stream.close()
85 self.root_logger.removeHandler(self.root_hdlr)
86 self.root_logger.setLevel(self.original_logging_level)
87 logging._acquireLock()
88 try:
89 logging._levelNames.clear()
90 logging._levelNames.update(self.saved_level_names)
91 logging._handlers.clear()
92 logging._handlers.update(self.saved_handlers)
93 logging._handlerList[:] = self.saved_handler_list
94 loggerDict = logging.getLogger().manager.loggerDict
95 loggerDict.clear()
96 loggerDict.update(self.saved_loggers)
97 finally:
98 logging._releaseLock()
99
100 def assert_log_lines(self, expected_values, stream=None):
101 """Match the collected log lines against the regular expression
102 self.expected_log_pat, and compare the extracted group values to
103 the expected_values list of tuples."""
104 stream = stream or self.stream
105 pat = re.compile(self.expected_log_pat)
106 try:
107 stream.reset()
108 actual_lines = stream.readlines()
109 except AttributeError:
110 # StringIO.StringIO lacks a reset() method.
111 actual_lines = stream.getvalue().splitlines()
112 self.assertEquals(len(actual_lines), len(expected_values))
113 for actual, expected in zip(actual_lines, expected_values):
114 match = pat.search(actual)
115 if not match:
116 self.fail("Log line does not match expected pattern:\n" +
117 actual)
118 self.assertEquals(tuple(match.groups()), expected)
119 s = stream.read()
120 if s:
121 self.fail("Remaining output at end of log stream:\n" + s)
122
123 def next_message(self):
124 """Generate a message consisting solely of an auto-incrementing
125 integer."""
126 self.message_num += 1
127 return "%d" % self.message_num
128
129
130class BuiltinLevelsTest(BaseTest):
131 """Test builtin levels and their inheritance."""
132
133 def test_flat(self):
134 #Logging levels in a flat logger namespace.
135 m = self.next_message
136
137 ERR = logging.getLogger("ERR")
138 ERR.setLevel(logging.ERROR)
139 INF = logging.getLogger("INF")
140 INF.setLevel(logging.INFO)
141 DEB = logging.getLogger("DEB")
142 DEB.setLevel(logging.DEBUG)
143
144 # These should log.
145 ERR.log(logging.CRITICAL, m())
146 ERR.error(m())
147
148 INF.log(logging.CRITICAL, m())
149 INF.error(m())
150 INF.warn(m())
151 INF.info(m())
152
153 DEB.log(logging.CRITICAL, m())
154 DEB.error(m())
155 DEB.warn (m())
156 DEB.info (m())
157 DEB.debug(m())
158
159 # These should not log.
160 ERR.warn(m())
161 ERR.info(m())
162 ERR.debug(m())
163
164 INF.debug(m())
165
166 self.assert_log_lines([
167 ('ERR', 'CRITICAL', '1'),
168 ('ERR', 'ERROR', '2'),
169 ('INF', 'CRITICAL', '3'),
170 ('INF', 'ERROR', '4'),
171 ('INF', 'WARNING', '5'),
172 ('INF', 'INFO', '6'),
173 ('DEB', 'CRITICAL', '7'),
174 ('DEB', 'ERROR', '8'),
175 ('DEB', 'WARNING', '9'),
176 ('DEB', 'INFO', '10'),
177 ('DEB', 'DEBUG', '11'),
178 ])
179
180 def test_nested_explicit(self):
181 # Logging levels in a nested namespace, all explicitly set.
182 m = self.next_message
183
184 INF = logging.getLogger("INF")
185 INF.setLevel(logging.INFO)
186 INF_ERR = logging.getLogger("INF.ERR")
187 INF_ERR.setLevel(logging.ERROR)
188
189 # These should log.
190 INF_ERR.log(logging.CRITICAL, m())
191 INF_ERR.error(m())
192
193 # These should not log.
194 INF_ERR.warn(m())
195 INF_ERR.info(m())
196 INF_ERR.debug(m())
197
198 self.assert_log_lines([
199 ('INF.ERR', 'CRITICAL', '1'),
200 ('INF.ERR', 'ERROR', '2'),
201 ])
202
203 def test_nested_inherited(self):
204 #Logging levels in a nested namespace, inherited from parent loggers.
205 m = self.next_message
206
207 INF = logging.getLogger("INF")
208 INF.setLevel(logging.INFO)
209 INF_ERR = logging.getLogger("INF.ERR")
210 INF_ERR.setLevel(logging.ERROR)
211 INF_UNDEF = logging.getLogger("INF.UNDEF")
212 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
213 UNDEF = logging.getLogger("UNDEF")
214
215 # These should log.
216 INF_UNDEF.log(logging.CRITICAL, m())
217 INF_UNDEF.error(m())
218 INF_UNDEF.warn(m())
219 INF_UNDEF.info(m())
220 INF_ERR_UNDEF.log(logging.CRITICAL, m())
221 INF_ERR_UNDEF.error(m())
222
223 # These should not log.
224 INF_UNDEF.debug(m())
225 INF_ERR_UNDEF.warn(m())
226 INF_ERR_UNDEF.info(m())
227 INF_ERR_UNDEF.debug(m())
228
229 self.assert_log_lines([
230 ('INF.UNDEF', 'CRITICAL', '1'),
231 ('INF.UNDEF', 'ERROR', '2'),
232 ('INF.UNDEF', 'WARNING', '3'),
233 ('INF.UNDEF', 'INFO', '4'),
234 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
235 ('INF.ERR.UNDEF', 'ERROR', '6'),
236 ])
237
238 def test_nested_with_virtual_parent(self):
239 # Logging levels when some parent does not exist yet.
240 m = self.next_message
241
242 INF = logging.getLogger("INF")
243 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
244 CHILD = logging.getLogger("INF.BADPARENT")
245 INF.setLevel(logging.INFO)
246
247 # These should log.
248 GRANDCHILD.log(logging.FATAL, m())
249 GRANDCHILD.info(m())
250 CHILD.log(logging.FATAL, m())
251 CHILD.info(m())
252
253 # These should not log.
254 GRANDCHILD.debug(m())
255 CHILD.debug(m())
256
257 self.assert_log_lines([
258 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
259 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
260 ('INF.BADPARENT', 'CRITICAL', '3'),
261 ('INF.BADPARENT', 'INFO', '4'),
262 ])
263
264
265class BasicFilterTest(BaseTest):
266
267 """Test the bundled Filter class."""
268
269 def test_filter(self):
270 # Only messages satisfying the specified criteria pass through the
271 # filter.
272 filter_ = logging.Filter("spam.eggs")
273 handler = self.root_logger.handlers[0]
274 try:
275 handler.addFilter(filter_)
276 spam = logging.getLogger("spam")
277 spam_eggs = logging.getLogger("spam.eggs")
278 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
279 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
280
281 spam.info(self.next_message())
282 spam_eggs.info(self.next_message()) # Good.
283 spam_eggs_fish.info(self.next_message()) # Good.
284 spam_bakedbeans.info(self.next_message())
285
286 self.assert_log_lines([
287 ('spam.eggs', 'INFO', '2'),
288 ('spam.eggs.fish', 'INFO', '3'),
289 ])
290 finally:
291 handler.removeFilter(filter_)
292
293
294#
295# First, we define our levels. There can be as many as you want - the only
296# limitations are that they should be integers, the lowest should be > 0 and
297# larger values mean less information being logged. If you need specific
298# level values which do not fit into these limitations, you can use a
299# mapping dictionary to convert between your application levels and the
300# logging system.
301#
302SILENT = 120
303TACITURN = 119
304TERSE = 118
305EFFUSIVE = 117
306SOCIABLE = 116
307VERBOSE = 115
308TALKATIVE = 114
309GARRULOUS = 113
310CHATTERBOX = 112
311BORING = 111
312
313LEVEL_RANGE = range(BORING, SILENT + 1)
314
315#
316# Next, we define names for our levels. You don't need to do this - in which
317# case the system will use "Level n" to denote the text for the level.
318#
319my_logging_levels = {
320 SILENT : 'Silent',
321 TACITURN : 'Taciturn',
322 TERSE : 'Terse',
323 EFFUSIVE : 'Effusive',
324 SOCIABLE : 'Sociable',
325 VERBOSE : 'Verbose',
326 TALKATIVE : 'Talkative',
327 GARRULOUS : 'Garrulous',
328 CHATTERBOX : 'Chatterbox',
329 BORING : 'Boring',
330}
331
332class GarrulousFilter(logging.Filter):
333
334 """A filter which blocks garrulous messages."""
335
336 def filter(self, record):
337 return record.levelno != GARRULOUS
338
339class VerySpecificFilter(logging.Filter):
340
341 """A filter which blocks sociable and taciturn messages."""
342
343 def filter(self, record):
344 return record.levelno not in [SOCIABLE, TACITURN]
345
346
347class CustomLevelsAndFiltersTest(BaseTest):
348
349 """Test various filtering possibilities with custom logging levels."""
350
351 # Skip the logger name group.
352 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
353
354 def setUp(self):
355 BaseTest.setUp(self)
356 for k, v in my_logging_levels.items():
357 logging.addLevelName(k, v)
358
359 def log_at_all_levels(self, logger):
360 for lvl in LEVEL_RANGE:
361 logger.log(lvl, self.next_message())
362
363 def test_logger_filter(self):
364 # Filter at logger level.
365 self.root_logger.setLevel(VERBOSE)
366 # Levels >= 'Verbose' are good.
367 self.log_at_all_levels(self.root_logger)
368 self.assert_log_lines([
369 ('Verbose', '5'),
370 ('Sociable', '6'),
371 ('Effusive', '7'),
372 ('Terse', '8'),
373 ('Taciturn', '9'),
374 ('Silent', '10'),
375 ])
376
377 def test_handler_filter(self):
378 # Filter at handler level.
379 self.root_logger.handlers[0].setLevel(SOCIABLE)
380 try:
381 # Levels >= 'Sociable' are good.
382 self.log_at_all_levels(self.root_logger)
383 self.assert_log_lines([
384 ('Sociable', '6'),
385 ('Effusive', '7'),
386 ('Terse', '8'),
387 ('Taciturn', '9'),
388 ('Silent', '10'),
389 ])
390 finally:
391 self.root_logger.handlers[0].setLevel(logging.NOTSET)
392
393 def test_specific_filters(self):
394 # Set a specific filter object on the handler, and then add another
395 # filter object on the logger itself.
396 handler = self.root_logger.handlers[0]
397 specific_filter = None
398 garr = GarrulousFilter()
399 handler.addFilter(garr)
400 try:
401 self.log_at_all_levels(self.root_logger)
402 first_lines = [
403 # Notice how 'Garrulous' is missing
404 ('Boring', '1'),
405 ('Chatterbox', '2'),
406 ('Talkative', '4'),
407 ('Verbose', '5'),
408 ('Sociable', '6'),
409 ('Effusive', '7'),
410 ('Terse', '8'),
411 ('Taciturn', '9'),
412 ('Silent', '10'),
413 ]
414 self.assert_log_lines(first_lines)
415
416 specific_filter = VerySpecificFilter()
417 self.root_logger.addFilter(specific_filter)
418 self.log_at_all_levels(self.root_logger)
419 self.assert_log_lines(first_lines + [
420 # Not only 'Garrulous' is still missing, but also 'Sociable'
421 # and 'Taciturn'
422 ('Boring', '11'),
423 ('Chatterbox', '12'),
424 ('Talkative', '14'),
425 ('Verbose', '15'),
426 ('Effusive', '17'),
427 ('Terse', '18'),
428 ('Silent', '20'),
429 ])
430 finally:
431 if specific_filter:
432 self.root_logger.removeFilter(specific_filter)
433 handler.removeFilter(garr)
434
435
436class MemoryHandlerTest(BaseTest):
437
438 """Tests for the MemoryHandler."""
439
440 # Do not bother with a logger name group.
441 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
442
443 def setUp(self):
444 BaseTest.setUp(self)
445 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
446 self.root_hdlr)
447 self.mem_logger = logging.getLogger('mem')
448 self.mem_logger.propagate = 0
449 self.mem_logger.addHandler(self.mem_hdlr)
450
451 def tearDown(self):
452 self.mem_hdlr.close()
Amaury Forgeot d'Arc2aece572008-03-29 01:42:31 +0000453 BaseTest.tearDown(self)
Brett Cannon56c4deb2008-03-03 00:38:58 +0000454
455 def test_flush(self):
456 # The memory handler flushes to its target handler based on specific
457 # criteria (message count and message level).
458 self.mem_logger.debug(self.next_message())
459 self.assert_log_lines([])
460 self.mem_logger.info(self.next_message())
461 self.assert_log_lines([])
462 # This will flush because the level is >= logging.WARNING
463 self.mem_logger.warn(self.next_message())
464 lines = [
465 ('DEBUG', '1'),
466 ('INFO', '2'),
467 ('WARNING', '3'),
468 ]
469 self.assert_log_lines(lines)
470 for n in (4, 14):
471 for i in range(9):
472 self.mem_logger.debug(self.next_message())
473 self.assert_log_lines(lines)
474 # This will flush because it's the 10th message since the last
475 # flush.
476 self.mem_logger.debug(self.next_message())
477 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
478 self.assert_log_lines(lines)
479
480 self.mem_logger.debug(self.next_message())
481 self.assert_log_lines(lines)
482
483
484class ExceptionFormatter(logging.Formatter):
485 """A special exception formatter."""
486 def formatException(self, ei):
487 return "Got a [%s]" % ei[0].__name__
488
489
490class ConfigFileTest(BaseTest):
491
492 """Reading logging config from a .ini-style config file."""
493
494 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
495
496 # config0 is a standard configuration.
497 config0 = """
498 [loggers]
499 keys=root
500
501 [handlers]
502 keys=hand1
503
504 [formatters]
505 keys=form1
506
507 [logger_root]
508 level=WARNING
509 handlers=hand1
510
511 [handler_hand1]
512 class=StreamHandler
513 level=NOTSET
514 formatter=form1
515 args=(sys.stdout,)
516
517 [formatter_form1]
518 format=%(levelname)s ++ %(message)s
519 datefmt=
520 """
521
522 # config1 adds a little to the standard configuration.
523 config1 = """
524 [loggers]
525 keys=root,parser
526
527 [handlers]
528 keys=hand1
529
530 [formatters]
531 keys=form1
532
533 [logger_root]
534 level=WARNING
535 handlers=
536
537 [logger_parser]
538 level=DEBUG
539 handlers=hand1
540 propagate=1
541 qualname=compiler.parser
542
543 [handler_hand1]
544 class=StreamHandler
545 level=NOTSET
546 formatter=form1
547 args=(sys.stdout,)
548
549 [formatter_form1]
550 format=%(levelname)s ++ %(message)s
551 datefmt=
552 """
553
554 # config2 has a subtle configuration error that should be reported
555 config2 = config1.replace("sys.stdout", "sys.stbout")
556
557 # config3 has a less subtle configuration error
558 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
559
560 # config4 specifies a custom formatter class to be loaded
561 config4 = """
562 [loggers]
563 keys=root
564
565 [handlers]
566 keys=hand1
567
568 [formatters]
569 keys=form1
570
571 [logger_root]
572 level=NOTSET
573 handlers=hand1
574
575 [handler_hand1]
576 class=StreamHandler
577 level=NOTSET
578 formatter=form1
579 args=(sys.stdout,)
580
581 [formatter_form1]
582 class=""" + __name__ + """.ExceptionFormatter
583 format=%(levelname)s:%(name)s:%(message)s
584 datefmt=
585 """
586
587 def apply_config(self, conf):
588 try:
589 fn = tempfile.mktemp(".ini")
590 f = open(fn, "w")
591 f.write(textwrap.dedent(conf))
592 f.close()
593 logging.config.fileConfig(fn)
594 finally:
595 os.remove(fn)
596
597 def test_config0_ok(self):
598 # A simple config file which overrides the default settings.
599 with captured_stdout() as output:
600 self.apply_config(self.config0)
601 logger = logging.getLogger()
602 # Won't output anything
603 logger.info(self.next_message())
604 # Outputs a message
605 logger.error(self.next_message())
606 self.assert_log_lines([
607 ('ERROR', '2'),
608 ], stream=output)
609 # Original logger output is empty.
610 self.assert_log_lines([])
611
612 def test_config1_ok(self):
613 # A config file defining a sub-parser as well.
614 with captured_stdout() as output:
615 self.apply_config(self.config1)
616 logger = logging.getLogger("compiler.parser")
617 # Both will output a message
618 logger.info(self.next_message())
619 logger.error(self.next_message())
620 self.assert_log_lines([
621 ('INFO', '1'),
622 ('ERROR', '2'),
623 ], stream=output)
624 # Original logger output is empty.
625 self.assert_log_lines([])
626
627 def test_config2_failure(self):
628 # A simple config file which overrides the default settings.
629 self.assertRaises(StandardError, self.apply_config, self.config2)
630
631 def test_config3_failure(self):
632 # A simple config file which overrides the default settings.
633 self.assertRaises(StandardError, self.apply_config, self.config3)
634
635 def test_config4_ok(self):
636 # A config file specifying a custom formatter class.
637 with captured_stdout() as output:
638 self.apply_config(self.config4)
639 logger = logging.getLogger()
640 try:
641 raise RuntimeError()
642 except RuntimeError:
643 logging.exception("just testing")
644 sys.stdout.seek(0)
645 self.assertEquals(output.getvalue(),
646 "ERROR:root:just testing\nGot a [RuntimeError]\n")
647 # Original logger output is empty
648 self.assert_log_lines([])
649
650
651class LogRecordStreamHandler(StreamRequestHandler):
652
653 """Handler for a streaming logging request. It saves the log message in the
654 TCP server's 'log_output' attribute."""
655
656 TCP_LOG_END = "!!!END!!!"
657
658 def handle(self):
659 """Handle multiple requests - each expected to be of 4-byte length,
660 followed by the LogRecord in pickle format. Logs the record
661 according to whatever policy is configured locally."""
662 while True:
663 chunk = self.connection.recv(4)
664 if len(chunk) < 4:
665 break
666 slen = struct.unpack(">L", chunk)[0]
667 chunk = self.connection.recv(slen)
668 while len(chunk) < slen:
669 chunk = chunk + self.connection.recv(slen - len(chunk))
670 obj = self.unpickle(chunk)
671 record = logging.makeLogRecord(obj)
672 self.handle_log_record(record)
673
674 def unpickle(self, data):
675 return cPickle.loads(data)
676
677 def handle_log_record(self, record):
678 # If the end-of-messages sentinel is seen, tell the server to
679 # terminate.
680 if self.TCP_LOG_END in record.msg:
681 self.server.abort = 1
682 return
683 self.server.log_output += record.msg + "\n"
684
Guido van Rossum376e6362003-04-25 14:22:00 +0000685
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000686class LogRecordSocketReceiver(ThreadingTCPServer):
Brett Cannon56c4deb2008-03-03 00:38:58 +0000687
688 """A simple-minded TCP socket-based logging receiver suitable for test
689 purposes."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000690
691 allow_reuse_address = 1
Brett Cannon56c4deb2008-03-03 00:38:58 +0000692 log_output = ""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000693
694 def __init__(self, host='localhost',
695 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
696 handler=LogRecordStreamHandler):
697 ThreadingTCPServer.__init__(self, (host, port), handler)
Georg Brandl57826cf2008-02-23 15:06:25 +0000698 self.abort = False
Brett Cannon56c4deb2008-03-03 00:38:58 +0000699 self.timeout = 0.1
700 self.finished = threading.Event()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000701
702 def serve_until_stopped(self):
Neal Norwitz55cd82f2006-02-05 08:21:08 +0000703 while not self.abort:
Neal Norwitz5bab0f82006-03-05 02:16:12 +0000704 rd, wr, ex = select.select([self.socket.fileno()], [], [],
705 self.timeout)
706 if rd:
707 self.handle_request()
Brett Cannon56c4deb2008-03-03 00:38:58 +0000708 # Notify the main thread that we're about to exit
709 self.finished.set()
Martin v. Löwisf6848882006-01-29 19:55:18 +0000710 # close the listen socket
711 self.server_close()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000712
Guido van Rossum2a1d5162003-01-21 21:05:22 +0000713
Brett Cannon56c4deb2008-03-03 00:38:58 +0000714class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000715
Brett Cannon56c4deb2008-03-03 00:38:58 +0000716 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000717
Brett Cannon56c4deb2008-03-03 00:38:58 +0000718 def setUp(self):
719 """Set up a TCP server to receive log messages, and a SocketHandler
720 pointing to that server's address and port."""
721 BaseTest.setUp(self)
722 self.tcpserver = LogRecordSocketReceiver(port=0)
723 self.port = self.tcpserver.socket.getsockname()[1]
724 self.threads = [
725 threading.Thread(target=self.tcpserver.serve_until_stopped)]
726 for thread in self.threads:
727 thread.start()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000728
Brett Cannon56c4deb2008-03-03 00:38:58 +0000729 self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port)
730 self.sock_hdlr.setFormatter(self.root_formatter)
731 self.root_logger.removeHandler(self.root_logger.handlers[0])
732 self.root_logger.addHandler(self.sock_hdlr)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000733
Brett Cannon56c4deb2008-03-03 00:38:58 +0000734 def tearDown(self):
735 """Shutdown the TCP server."""
736 try:
737 self.tcpserver.abort = True
738 del self.tcpserver
739 self.root_logger.removeHandler(self.sock_hdlr)
740 self.sock_hdlr.close()
741 for thread in self.threads:
742 thread.join(2.0)
743 finally:
744 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000745
Brett Cannon56c4deb2008-03-03 00:38:58 +0000746 def get_output(self):
747 """Get the log output as received by the TCP server."""
748 # Signal the TCP receiver and wait for it to terminate.
749 self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END)
750 self.tcpserver.finished.wait(2.0)
751 return self.tcpserver.log_output
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000752
Brett Cannon56c4deb2008-03-03 00:38:58 +0000753 def test_output(self):
754 # The log message sent to the SocketHandler is properly received.
755 logger = logging.getLogger("tcp")
756 logger.error("spam")
757 logger.debug("eggs")
758 self.assertEquals(self.get_output(), "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000759
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000760
Brett Cannon56c4deb2008-03-03 00:38:58 +0000761class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000762
Brett Cannon56c4deb2008-03-03 00:38:58 +0000763 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000764
Brett Cannon56c4deb2008-03-03 00:38:58 +0000765 def setUp(self):
766 """Create a dict to remember potentially destroyed objects."""
767 BaseTest.setUp(self)
768 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000769
Brett Cannon56c4deb2008-03-03 00:38:58 +0000770 def _watch_for_survival(self, *args):
771 """Watch the given objects for survival, by creating weakrefs to
772 them."""
773 for obj in args:
774 key = id(obj), repr(obj)
775 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000776
Brett Cannon56c4deb2008-03-03 00:38:58 +0000777 def _assert_survival(self):
778 """Assert that all objects watched for survival have survived."""
779 # Trigger cycle breaking.
780 gc.collect()
781 dead = []
782 for (id_, repr_), ref in self._survivors.items():
783 if ref() is None:
784 dead.append(repr_)
785 if dead:
786 self.fail("%d objects should have survived "
787 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000788
Brett Cannon56c4deb2008-03-03 00:38:58 +0000789 def test_persistent_loggers(self):
790 # Logger objects are persistent and retain their configuration, even
791 # if visible references are destroyed.
792 self.root_logger.setLevel(logging.INFO)
793 foo = logging.getLogger("foo")
794 self._watch_for_survival(foo)
795 foo.setLevel(logging.DEBUG)
796 self.root_logger.debug(self.next_message())
797 foo.debug(self.next_message())
798 self.assert_log_lines([
799 ('foo', 'DEBUG', '2'),
800 ])
801 del foo
802 # foo has survived.
803 self._assert_survival()
804 # foo has retained its settings.
805 bar = logging.getLogger("foo")
806 bar.debug(self.next_message())
807 self.assert_log_lines([
808 ('foo', 'DEBUG', '2'),
809 ('foo', 'DEBUG', '3'),
810 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000811
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000812
Brett Cannon56c4deb2008-03-03 00:38:58 +0000813# Set the locale to the platform-dependent default. I have no idea
814# why the test does this, but in any case we save the current locale
815# first and restore it at the end.
816@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +0000817def test_main():
Brett Cannon56c4deb2008-03-03 00:38:58 +0000818 run_unittest(BuiltinLevelsTest, BasicFilterTest,
819 CustomLevelsAndFiltersTest, MemoryHandlerTest,
820 ConfigFileTest, SocketHandlerTest, MemoryTest)
Jeremy Hylton096d9862003-07-18 03:19:20 +0000821
Brett Cannon56c4deb2008-03-03 00:38:58 +0000822if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000823 test_main()