blob: ee9e392c67bc1f600744faab930970d82ab102ec [file] [log] [blame]
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001#!/usr/bin/env python
Christian Heimes180510d2008-03-03 19:15:45 +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
Christian Heimes180510d2008-03-03 19:15:45 +000024import logging
25import logging.handlers
26import logging.config
Christian Heimes18c66892008-02-17 13:31:39 +000027
Christian Heimes180510d2008-03-03 19:15:45 +000028import copy
29import pickle
30import io
31import gc
32import os
33import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000034import select
Christian Heimes180510d2008-03-03 19:15:45 +000035import socket
Neal Norwitzb4a2df02003-01-02 14:56:39 +000036from SocketServer import ThreadingTCPServer, StreamRequestHandler
Christian Heimes180510d2008-03-03 19:15:45 +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
Christian Heimes18c66892008-02-17 13:31:39 +000048
49
Christian Heimes180510d2008-03-03 19:15:45 +000050class BaseTest(unittest.TestCase):
51
52 """Base class for logging tests."""
53
54 log_format = "%(name)s -> %(levelname)s: %(message)s"
55 expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$"
56 message_num = 0
57
58 def setUp(self):
59 """Setup the default logging stream to an internal StringIO instance,
60 so that we can examine log output as we want."""
61 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000062 logging._acquireLock()
63 try:
Christian Heimes180510d2008-03-03 19:15:45 +000064 self.saved_handlers = logging._handlers.copy()
65 self.saved_handler_list = logging._handlerList[:]
66 self.saved_loggers = logger_dict.copy()
67 self.saved_level_names = logging._levelNames.copy()
Christian Heimes18c66892008-02-17 13:31:39 +000068 finally:
69 logging._releaseLock()
70
Christian Heimes180510d2008-03-03 19:15:45 +000071 self.root_logger = logging.getLogger("")
72 self.original_logging_level = self.root_logger.getEffectiveLevel()
73
74 self.stream = io.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 list(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()
453
454 def test_flush(self):
455 # The memory handler flushes to its target handler based on specific
456 # criteria (message count and message level).
457 self.mem_logger.debug(self.next_message())
458 self.assert_log_lines([])
459 self.mem_logger.info(self.next_message())
460 self.assert_log_lines([])
461 # This will flush because the level is >= logging.WARNING
462 self.mem_logger.warn(self.next_message())
463 lines = [
464 ('DEBUG', '1'),
465 ('INFO', '2'),
466 ('WARNING', '3'),
467 ]
468 self.assert_log_lines(lines)
469 for n in (4, 14):
470 for i in range(9):
471 self.mem_logger.debug(self.next_message())
472 self.assert_log_lines(lines)
473 # This will flush because it's the 10th message since the last
474 # flush.
475 self.mem_logger.debug(self.next_message())
476 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
477 self.assert_log_lines(lines)
478
479 self.mem_logger.debug(self.next_message())
480 self.assert_log_lines(lines)
481
482
483class ExceptionFormatter(logging.Formatter):
484 """A special exception formatter."""
485 def formatException(self, ei):
486 return "Got a [%s]" % ei[0].__name__
487
488
489class ConfigFileTest(BaseTest):
490
491 """Reading logging config from a .ini-style config file."""
492
493 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
494
495 # config0 is a standard configuration.
496 config0 = """
497 [loggers]
498 keys=root
499
500 [handlers]
501 keys=hand1
502
503 [formatters]
504 keys=form1
505
506 [logger_root]
507 level=WARNING
508 handlers=hand1
509
510 [handler_hand1]
511 class=StreamHandler
512 level=NOTSET
513 formatter=form1
514 args=(sys.stdout,)
515
516 [formatter_form1]
517 format=%(levelname)s ++ %(message)s
518 datefmt=
519 """
520
521 # config1 adds a little to the standard configuration.
522 config1 = """
523 [loggers]
524 keys=root,parser
525
526 [handlers]
527 keys=hand1
528
529 [formatters]
530 keys=form1
531
532 [logger_root]
533 level=WARNING
534 handlers=
535
536 [logger_parser]
537 level=DEBUG
538 handlers=hand1
539 propagate=1
540 qualname=compiler.parser
541
542 [handler_hand1]
543 class=StreamHandler
544 level=NOTSET
545 formatter=form1
546 args=(sys.stdout,)
547
548 [formatter_form1]
549 format=%(levelname)s ++ %(message)s
550 datefmt=
551 """
552
553 # config2 has a subtle configuration error that should be reported
554 config2 = config1.replace("sys.stdout", "sys.stbout")
555
556 # config3 has a less subtle configuration error
557 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
558
559 # config4 specifies a custom formatter class to be loaded
560 config4 = """
561 [loggers]
562 keys=root
563
564 [handlers]
565 keys=hand1
566
567 [formatters]
568 keys=form1
569
570 [logger_root]
571 level=NOTSET
572 handlers=hand1
573
574 [handler_hand1]
575 class=StreamHandler
576 level=NOTSET
577 formatter=form1
578 args=(sys.stdout,)
579
580 [formatter_form1]
581 class=""" + __name__ + """.ExceptionFormatter
582 format=%(levelname)s:%(name)s:%(message)s
583 datefmt=
584 """
585
586 def apply_config(self, conf):
587 try:
588 fn = tempfile.mktemp(".ini")
589 f = open(fn, "w")
590 f.write(textwrap.dedent(conf))
591 f.close()
592 logging.config.fileConfig(fn)
593 finally:
594 os.remove(fn)
595
596 def test_config0_ok(self):
597 # A simple config file which overrides the default settings.
598 with captured_stdout() as output:
599 self.apply_config(self.config0)
600 logger = logging.getLogger()
601 # Won't output anything
602 logger.info(self.next_message())
603 # Outputs a message
604 logger.error(self.next_message())
605 self.assert_log_lines([
606 ('ERROR', '2'),
607 ], stream=output)
608 # Original logger output is empty.
609 self.assert_log_lines([])
610
611 def test_config1_ok(self):
612 # A config file defining a sub-parser as well.
613 with captured_stdout() as output:
614 self.apply_config(self.config1)
615 logger = logging.getLogger("compiler.parser")
616 # Both will output a message
617 logger.info(self.next_message())
618 logger.error(self.next_message())
619 self.assert_log_lines([
620 ('INFO', '1'),
621 ('ERROR', '2'),
622 ], stream=output)
623 # Original logger output is empty.
624 self.assert_log_lines([])
625
626 def test_config2_failure(self):
627 # A simple config file which overrides the default settings.
628 self.assertRaises(Exception, self.apply_config, self.config2)
629
630 def test_config3_failure(self):
631 # A simple config file which overrides the default settings.
632 self.assertRaises(Exception, self.apply_config, self.config3)
633
634 def test_config4_ok(self):
635 # A config file specifying a custom formatter class.
636 with captured_stdout() as output:
637 self.apply_config(self.config4)
638 logger = logging.getLogger()
639 try:
640 raise RuntimeError()
641 except RuntimeError:
642 logging.exception("just testing")
643 sys.stdout.seek(0)
644 self.assertEquals(output.getvalue(),
645 "ERROR:root:just testing\nGot a [RuntimeError]\n")
646 # Original logger output is empty
647 self.assert_log_lines([])
648
649
650class LogRecordStreamHandler(StreamRequestHandler):
651
652 """Handler for a streaming logging request. It saves the log message in the
653 TCP server's 'log_output' attribute."""
654
655 TCP_LOG_END = "!!!END!!!"
656
657 def handle(self):
658 """Handle multiple requests - each expected to be of 4-byte length,
659 followed by the LogRecord in pickle format. Logs the record
660 according to whatever policy is configured locally."""
661 while True:
662 chunk = self.connection.recv(4)
663 if len(chunk) < 4:
664 break
665 slen = struct.unpack(">L", chunk)[0]
666 chunk = self.connection.recv(slen)
667 while len(chunk) < slen:
668 chunk = chunk + self.connection.recv(slen - len(chunk))
669 obj = self.unpickle(chunk)
670 record = logging.makeLogRecord(obj)
671 self.handle_log_record(record)
672
673 def unpickle(self, data):
674 return pickle.loads(data)
675
676 def handle_log_record(self, record):
677 # If the end-of-messages sentinel is seen, tell the server to
678 # terminate.
679 if self.TCP_LOG_END in record.msg:
680 self.server.abort = 1
681 return
682 self.server.log_output += record.msg + "\n"
683
Guido van Rossum376e6362003-04-25 14:22:00 +0000684
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000685class LogRecordSocketReceiver(ThreadingTCPServer):
Christian Heimes180510d2008-03-03 19:15:45 +0000686
687 """A simple-minded TCP socket-based logging receiver suitable for test
688 purposes."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000689
690 allow_reuse_address = 1
Christian Heimes180510d2008-03-03 19:15:45 +0000691 log_output = ""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000692
693 def __init__(self, host='localhost',
694 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
695 handler=LogRecordStreamHandler):
696 ThreadingTCPServer.__init__(self, (host, port), handler)
Christian Heimes8640e742008-02-23 16:23:06 +0000697 self.abort = False
Christian Heimes180510d2008-03-03 19:15:45 +0000698 self.timeout = 0.1
699 self.finished = threading.Event()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000700
701 def serve_until_stopped(self):
Neal Norwitz55cd82f2006-02-05 08:21:08 +0000702 while not self.abort:
Neal Norwitz5bab0f82006-03-05 02:16:12 +0000703 rd, wr, ex = select.select([self.socket.fileno()], [], [],
704 self.timeout)
705 if rd:
706 self.handle_request()
Christian Heimes180510d2008-03-03 19:15:45 +0000707 # Notify the main thread that we're about to exit
708 self.finished.set()
Martin v. Löwisf6848882006-01-29 19:55:18 +0000709 # close the listen socket
710 self.server_close()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000711
Guido van Rossum2a1d5162003-01-21 21:05:22 +0000712
Christian Heimes180510d2008-03-03 19:15:45 +0000713class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000714
Christian Heimes180510d2008-03-03 19:15:45 +0000715 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000716
Christian Heimes180510d2008-03-03 19:15:45 +0000717 def setUp(self):
718 """Set up a TCP server to receive log messages, and a SocketHandler
719 pointing to that server's address and port."""
720 BaseTest.setUp(self)
721 self.tcpserver = LogRecordSocketReceiver(port=0)
722 self.port = self.tcpserver.socket.getsockname()[1]
723 self.threads = [
724 threading.Thread(target=self.tcpserver.serve_until_stopped)]
725 for thread in self.threads:
726 thread.start()
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000727
Christian Heimes180510d2008-03-03 19:15:45 +0000728 self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port)
729 self.sock_hdlr.setFormatter(self.root_formatter)
730 self.root_logger.removeHandler(self.root_logger.handlers[0])
731 self.root_logger.addHandler(self.sock_hdlr)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000732
Christian Heimes180510d2008-03-03 19:15:45 +0000733 def tearDown(self):
734 """Shutdown the TCP server."""
735 try:
736 self.tcpserver.abort = True
737 del self.tcpserver
738 self.root_logger.removeHandler(self.sock_hdlr)
739 self.sock_hdlr.close()
740 for thread in self.threads:
741 thread.join(2.0)
742 finally:
743 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000744
Christian Heimes180510d2008-03-03 19:15:45 +0000745 def get_output(self):
746 """Get the log output as received by the TCP server."""
747 # Signal the TCP receiver and wait for it to terminate.
748 self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END)
749 self.tcpserver.finished.wait(2.0)
750 return self.tcpserver.log_output
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000751
Christian Heimes180510d2008-03-03 19:15:45 +0000752 def test_output(self):
753 # The log message sent to the SocketHandler is properly received.
754 logger = logging.getLogger("tcp")
755 logger.error("spam")
756 logger.debug("eggs")
757 self.assertEquals(self.get_output(), "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000758
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000759
Christian Heimes180510d2008-03-03 19:15:45 +0000760class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000761
Christian Heimes180510d2008-03-03 19:15:45 +0000762 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000763
Christian Heimes180510d2008-03-03 19:15:45 +0000764 def setUp(self):
765 """Create a dict to remember potentially destroyed objects."""
766 BaseTest.setUp(self)
767 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000768
Christian Heimes180510d2008-03-03 19:15:45 +0000769 def _watch_for_survival(self, *args):
770 """Watch the given objects for survival, by creating weakrefs to
771 them."""
772 for obj in args:
773 key = id(obj), repr(obj)
774 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000775
Christian Heimes180510d2008-03-03 19:15:45 +0000776 def _assert_survival(self):
777 """Assert that all objects watched for survival have survived."""
778 # Trigger cycle breaking.
779 gc.collect()
780 dead = []
781 for (id_, repr_), ref in list(self._survivors.items()):
782 if ref() is None:
783 dead.append(repr_)
784 if dead:
785 self.fail("%d objects should have survived "
786 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000787
Christian Heimes180510d2008-03-03 19:15:45 +0000788 def test_persistent_loggers(self):
789 # Logger objects are persistent and retain their configuration, even
790 # if visible references are destroyed.
791 self.root_logger.setLevel(logging.INFO)
792 foo = logging.getLogger("foo")
793 self._watch_for_survival(foo)
794 foo.setLevel(logging.DEBUG)
795 self.root_logger.debug(self.next_message())
796 foo.debug(self.next_message())
797 self.assert_log_lines([
798 ('foo', 'DEBUG', '2'),
799 ])
800 del foo
801 # foo has survived.
802 self._assert_survival()
803 # foo has retained its settings.
804 bar = logging.getLogger("foo")
805 bar.debug(self.next_message())
806 self.assert_log_lines([
807 ('foo', 'DEBUG', '2'),
808 ('foo', 'DEBUG', '3'),
809 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000810
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000811
Christian Heimes180510d2008-03-03 19:15:45 +0000812# Set the locale to the platform-dependent default. I have no idea
813# why the test does this, but in any case we save the current locale
814# first and restore it at the end.
815@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +0000816def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +0000817 run_unittest(BuiltinLevelsTest, BasicFilterTest,
818 CustomLevelsAndFiltersTest, MemoryHandlerTest,
819 ConfigFileTest, SocketHandlerTest, MemoryTest)
Jeremy Hylton096d9862003-07-18 03:19:20 +0000820
Christian Heimes180510d2008-03-03 19:15:45 +0000821if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +0000822 test_main()