/Lib/test/test_logging.py
Python | 923 lines | 890 code | 9 blank | 24 comment | 1 complexity | 493042192f4e9c2a25948162d40f6e09 MD5 | raw file
1#!/usr/bin/env python 2# 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. 22""" 23 24import logging 25import logging.handlers 26import logging.config 27 28import codecs 29import copy 30import cPickle 31import cStringIO 32import gc 33import os 34import re 35import select 36import socket 37from SocketServer import ThreadingTCPServer, StreamRequestHandler 38import string 39import struct 40import sys 41import tempfile 42from test.test_support import captured_stdout, run_with_locale, run_unittest 43import textwrap 44import threading 45import time 46import types 47import unittest 48import weakref 49 50 51class 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 63 logging._acquireLock() 64 try: 65 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() 69 finally: 70 logging._releaseLock() 71 72 self.root_logger = logging.getLogger("") 73 self.original_logging_level = self.root_logger.getEffectiveLevel() 74 75 self.stream = cStringIO.StringIO() 76 self.root_logger.setLevel(logging.DEBUG) 77 self.root_hdlr = logging.StreamHandler(self.stream) 78 self.root_formatter = logging.Formatter(self.log_format) 79 self.root_hdlr.setFormatter(self.root_formatter) 80 self.root_logger.addHandler(self.root_hdlr) 81 82 def tearDown(self): 83 """Remove our logging stream, and restore the original logging 84 level.""" 85 self.stream.close() 86 self.root_logger.removeHandler(self.root_hdlr) 87 self.root_logger.setLevel(self.original_logging_level) 88 logging._acquireLock() 89 try: 90 logging._levelNames.clear() 91 logging._levelNames.update(self.saved_level_names) 92 logging._handlers.clear() 93 logging._handlers.update(self.saved_handlers) 94 logging._handlerList[:] = self.saved_handler_list 95 loggerDict = logging.getLogger().manager.loggerDict 96 loggerDict.clear() 97 loggerDict.update(self.saved_loggers) 98 finally: 99 logging._releaseLock() 100 101 def assert_log_lines(self, expected_values, stream=None): 102 """Match the collected log lines against the regular expression 103 self.expected_log_pat, and compare the extracted group values to 104 the expected_values list of tuples.""" 105 stream = stream or self.stream 106 pat = re.compile(self.expected_log_pat) 107 try: 108 stream.reset() 109 actual_lines = stream.readlines() 110 except AttributeError: 111 # StringIO.StringIO lacks a reset() method. 112 actual_lines = stream.getvalue().splitlines() 113 self.assertEquals(len(actual_lines), len(expected_values)) 114 for actual, expected in zip(actual_lines, expected_values): 115 match = pat.search(actual) 116 if not match: 117 self.fail("Log line does not match expected pattern:\n" + 118 actual) 119 self.assertEquals(tuple(match.groups()), expected) 120 s = stream.read() 121 if s: 122 self.fail("Remaining output at end of log stream:\n" + s) 123 124 def next_message(self): 125 """Generate a message consisting solely of an auto-incrementing 126 integer.""" 127 self.message_num += 1 128 return "%d" % self.message_num 129 130 131class BuiltinLevelsTest(BaseTest): 132 """Test builtin levels and their inheritance.""" 133 134 def test_flat(self): 135 #Logging levels in a flat logger namespace. 136 m = self.next_message 137 138 ERR = logging.getLogger("ERR") 139 ERR.setLevel(logging.ERROR) 140 INF = logging.getLogger("INF") 141 INF.setLevel(logging.INFO) 142 DEB = logging.getLogger("DEB") 143 DEB.setLevel(logging.DEBUG) 144 145 # These should log. 146 ERR.log(logging.CRITICAL, m()) 147 ERR.error(m()) 148 149 INF.log(logging.CRITICAL, m()) 150 INF.error(m()) 151 INF.warn(m()) 152 INF.info(m()) 153 154 DEB.log(logging.CRITICAL, m()) 155 DEB.error(m()) 156 DEB.warn (m()) 157 DEB.info (m()) 158 DEB.debug(m()) 159 160 # These should not log. 161 ERR.warn(m()) 162 ERR.info(m()) 163 ERR.debug(m()) 164 165 INF.debug(m()) 166 167 self.assert_log_lines([ 168 ('ERR', 'CRITICAL', '1'), 169 ('ERR', 'ERROR', '2'), 170 ('INF', 'CRITICAL', '3'), 171 ('INF', 'ERROR', '4'), 172 ('INF', 'WARNING', '5'), 173 ('INF', 'INFO', '6'), 174 ('DEB', 'CRITICAL', '7'), 175 ('DEB', 'ERROR', '8'), 176 ('DEB', 'WARNING', '9'), 177 ('DEB', 'INFO', '10'), 178 ('DEB', 'DEBUG', '11'), 179 ]) 180 181 def test_nested_explicit(self): 182 # Logging levels in a nested namespace, all explicitly set. 183 m = self.next_message 184 185 INF = logging.getLogger("INF") 186 INF.setLevel(logging.INFO) 187 INF_ERR = logging.getLogger("INF.ERR") 188 INF_ERR.setLevel(logging.ERROR) 189 190 # These should log. 191 INF_ERR.log(logging.CRITICAL, m()) 192 INF_ERR.error(m()) 193 194 # These should not log. 195 INF_ERR.warn(m()) 196 INF_ERR.info(m()) 197 INF_ERR.debug(m()) 198 199 self.assert_log_lines([ 200 ('INF.ERR', 'CRITICAL', '1'), 201 ('INF.ERR', 'ERROR', '2'), 202 ]) 203 204 def test_nested_inherited(self): 205 #Logging levels in a nested namespace, inherited from parent loggers. 206 m = self.next_message 207 208 INF = logging.getLogger("INF") 209 INF.setLevel(logging.INFO) 210 INF_ERR = logging.getLogger("INF.ERR") 211 INF_ERR.setLevel(logging.ERROR) 212 INF_UNDEF = logging.getLogger("INF.UNDEF") 213 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF") 214 UNDEF = logging.getLogger("UNDEF") 215 216 # These should log. 217 INF_UNDEF.log(logging.CRITICAL, m()) 218 INF_UNDEF.error(m()) 219 INF_UNDEF.warn(m()) 220 INF_UNDEF.info(m()) 221 INF_ERR_UNDEF.log(logging.CRITICAL, m()) 222 INF_ERR_UNDEF.error(m()) 223 224 # These should not log. 225 INF_UNDEF.debug(m()) 226 INF_ERR_UNDEF.warn(m()) 227 INF_ERR_UNDEF.info(m()) 228 INF_ERR_UNDEF.debug(m()) 229 230 self.assert_log_lines([ 231 ('INF.UNDEF', 'CRITICAL', '1'), 232 ('INF.UNDEF', 'ERROR', '2'), 233 ('INF.UNDEF', 'WARNING', '3'), 234 ('INF.UNDEF', 'INFO', '4'), 235 ('INF.ERR.UNDEF', 'CRITICAL', '5'), 236 ('INF.ERR.UNDEF', 'ERROR', '6'), 237 ]) 238 239 def test_nested_with_virtual_parent(self): 240 # Logging levels when some parent does not exist yet. 241 m = self.next_message 242 243 INF = logging.getLogger("INF") 244 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF") 245 CHILD = logging.getLogger("INF.BADPARENT") 246 INF.setLevel(logging.INFO) 247 248 # These should log. 249 GRANDCHILD.log(logging.FATAL, m()) 250 GRANDCHILD.info(m()) 251 CHILD.log(logging.FATAL, m()) 252 CHILD.info(m()) 253 254 # These should not log. 255 GRANDCHILD.debug(m()) 256 CHILD.debug(m()) 257 258 self.assert_log_lines([ 259 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'), 260 ('INF.BADPARENT.UNDEF', 'INFO', '2'), 261 ('INF.BADPARENT', 'CRITICAL', '3'), 262 ('INF.BADPARENT', 'INFO', '4'), 263 ]) 264 265 266class BasicFilterTest(BaseTest): 267 268 """Test the bundled Filter class.""" 269 270 def test_filter(self): 271 # Only messages satisfying the specified criteria pass through the 272 # filter. 273 filter_ = logging.Filter("spam.eggs") 274 handler = self.root_logger.handlers[0] 275 try: 276 handler.addFilter(filter_) 277 spam = logging.getLogger("spam") 278 spam_eggs = logging.getLogger("spam.eggs") 279 spam_eggs_fish = logging.getLogger("spam.eggs.fish") 280 spam_bakedbeans = logging.getLogger("spam.bakedbeans") 281 282 spam.info(self.next_message()) 283 spam_eggs.info(self.next_message()) # Good. 284 spam_eggs_fish.info(self.next_message()) # Good. 285 spam_bakedbeans.info(self.next_message()) 286 287 self.assert_log_lines([ 288 ('spam.eggs', 'INFO', '2'), 289 ('spam.eggs.fish', 'INFO', '3'), 290 ]) 291 finally: 292 handler.removeFilter(filter_) 293 294 295# 296# First, we define our levels. There can be as many as you want - the only 297# limitations are that they should be integers, the lowest should be > 0 and 298# larger values mean less information being logged. If you need specific 299# level values which do not fit into these limitations, you can use a 300# mapping dictionary to convert between your application levels and the 301# logging system. 302# 303SILENT = 120 304TACITURN = 119 305TERSE = 118 306EFFUSIVE = 117 307SOCIABLE = 116 308VERBOSE = 115 309TALKATIVE = 114 310GARRULOUS = 113 311CHATTERBOX = 112 312BORING = 111 313 314LEVEL_RANGE = range(BORING, SILENT + 1) 315 316# 317# Next, we define names for our levels. You don't need to do this - in which 318# case the system will use "Level n" to denote the text for the level. 319# 320my_logging_levels = { 321 SILENT : 'Silent', 322 TACITURN : 'Taciturn', 323 TERSE : 'Terse', 324 EFFUSIVE : 'Effusive', 325 SOCIABLE : 'Sociable', 326 VERBOSE : 'Verbose', 327 TALKATIVE : 'Talkative', 328 GARRULOUS : 'Garrulous', 329 CHATTERBOX : 'Chatterbox', 330 BORING : 'Boring', 331} 332 333class GarrulousFilter(logging.Filter): 334 335 """A filter which blocks garrulous messages.""" 336 337 def filter(self, record): 338 return record.levelno != GARRULOUS 339 340class VerySpecificFilter(logging.Filter): 341 342 """A filter which blocks sociable and taciturn messages.""" 343 344 def filter(self, record): 345 return record.levelno not in [SOCIABLE, TACITURN] 346 347 348class CustomLevelsAndFiltersTest(BaseTest): 349 350 """Test various filtering possibilities with custom logging levels.""" 351 352 # Skip the logger name group. 353 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$" 354 355 def setUp(self): 356 BaseTest.setUp(self) 357 for k, v in my_logging_levels.items(): 358 logging.addLevelName(k, v) 359 360 def log_at_all_levels(self, logger): 361 for lvl in LEVEL_RANGE: 362 logger.log(lvl, self.next_message()) 363 364 def test_logger_filter(self): 365 # Filter at logger level. 366 self.root_logger.setLevel(VERBOSE) 367 # Levels >= 'Verbose' are good. 368 self.log_at_all_levels(self.root_logger) 369 self.assert_log_lines([ 370 ('Verbose', '5'), 371 ('Sociable', '6'), 372 ('Effusive', '7'), 373 ('Terse', '8'), 374 ('Taciturn', '9'), 375 ('Silent', '10'), 376 ]) 377 378 def test_handler_filter(self): 379 # Filter at handler level. 380 self.root_logger.handlers[0].setLevel(SOCIABLE) 381 try: 382 # Levels >= 'Sociable' are good. 383 self.log_at_all_levels(self.root_logger) 384 self.assert_log_lines([ 385 ('Sociable', '6'), 386 ('Effusive', '7'), 387 ('Terse', '8'), 388 ('Taciturn', '9'), 389 ('Silent', '10'), 390 ]) 391 finally: 392 self.root_logger.handlers[0].setLevel(logging.NOTSET) 393 394 def test_specific_filters(self): 395 # Set a specific filter object on the handler, and then add another 396 # filter object on the logger itself. 397 handler = self.root_logger.handlers[0] 398 specific_filter = None 399 garr = GarrulousFilter() 400 handler.addFilter(garr) 401 try: 402 self.log_at_all_levels(self.root_logger) 403 first_lines = [ 404 # Notice how 'Garrulous' is missing 405 ('Boring', '1'), 406 ('Chatterbox', '2'), 407 ('Talkative', '4'), 408 ('Verbose', '5'), 409 ('Sociable', '6'), 410 ('Effusive', '7'), 411 ('Terse', '8'), 412 ('Taciturn', '9'), 413 ('Silent', '10'), 414 ] 415 self.assert_log_lines(first_lines) 416 417 specific_filter = VerySpecificFilter() 418 self.root_logger.addFilter(specific_filter) 419 self.log_at_all_levels(self.root_logger) 420 self.assert_log_lines(first_lines + [ 421 # Not only 'Garrulous' is still missing, but also 'Sociable' 422 # and 'Taciturn' 423 ('Boring', '11'), 424 ('Chatterbox', '12'), 425 ('Talkative', '14'), 426 ('Verbose', '15'), 427 ('Effusive', '17'), 428 ('Terse', '18'), 429 ('Silent', '20'), 430 ]) 431 finally: 432 if specific_filter: 433 self.root_logger.removeFilter(specific_filter) 434 handler.removeFilter(garr) 435 436 437class MemoryHandlerTest(BaseTest): 438 439 """Tests for the MemoryHandler.""" 440 441 # Do not bother with a logger name group. 442 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$" 443 444 def setUp(self): 445 BaseTest.setUp(self) 446 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING, 447 self.root_hdlr) 448 self.mem_logger = logging.getLogger('mem') 449 self.mem_logger.propagate = 0 450 self.mem_logger.addHandler(self.mem_hdlr) 451 452 def tearDown(self): 453 self.mem_hdlr.close() 454 BaseTest.tearDown(self) 455 456 def test_flush(self): 457 # The memory handler flushes to its target handler based on specific 458 # criteria (message count and message level). 459 self.mem_logger.debug(self.next_message()) 460 self.assert_log_lines([]) 461 self.mem_logger.info(self.next_message()) 462 self.assert_log_lines([]) 463 # This will flush because the level is >= logging.WARNING 464 self.mem_logger.warn(self.next_message()) 465 lines = [ 466 ('DEBUG', '1'), 467 ('INFO', '2'), 468 ('WARNING', '3'), 469 ] 470 self.assert_log_lines(lines) 471 for n in (4, 14): 472 for i in range(9): 473 self.mem_logger.debug(self.next_message()) 474 self.assert_log_lines(lines) 475 # This will flush because it's the 10th message since the last 476 # flush. 477 self.mem_logger.debug(self.next_message()) 478 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)] 479 self.assert_log_lines(lines) 480 481 self.mem_logger.debug(self.next_message()) 482 self.assert_log_lines(lines) 483 484 485class ExceptionFormatter(logging.Formatter): 486 """A special exception formatter.""" 487 def formatException(self, ei): 488 return "Got a [%s]" % ei[0].__name__ 489 490 491class ConfigFileTest(BaseTest): 492 493 """Reading logging config from a .ini-style config file.""" 494 495 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$" 496 497 # config0 is a standard configuration. 498 config0 = """ 499 [loggers] 500 keys=root 501 502 [handlers] 503 keys=hand1 504 505 [formatters] 506 keys=form1 507 508 [logger_root] 509 level=WARNING 510 handlers=hand1 511 512 [handler_hand1] 513 class=StreamHandler 514 level=NOTSET 515 formatter=form1 516 args=(sys.stdout,) 517 518 [formatter_form1] 519 format=%(levelname)s ++ %(message)s 520 datefmt= 521 """ 522 523 # config1 adds a little to the standard configuration. 524 config1 = """ 525 [loggers] 526 keys=root,parser 527 528 [handlers] 529 keys=hand1 530 531 [formatters] 532 keys=form1 533 534 [logger_root] 535 level=WARNING 536 handlers= 537 538 [logger_parser] 539 level=DEBUG 540 handlers=hand1 541 propagate=1 542 qualname=compiler.parser 543 544 [handler_hand1] 545 class=StreamHandler 546 level=NOTSET 547 formatter=form1 548 args=(sys.stdout,) 549 550 [formatter_form1] 551 format=%(levelname)s ++ %(message)s 552 datefmt= 553 """ 554 555 # config2 has a subtle configuration error that should be reported 556 config2 = config1.replace("sys.stdout", "sys.stbout") 557 558 # config3 has a less subtle configuration error 559 config3 = config1.replace("formatter=form1", "formatter=misspelled_name") 560 561 # config4 specifies a custom formatter class to be loaded 562 config4 = """ 563 [loggers] 564 keys=root 565 566 [handlers] 567 keys=hand1 568 569 [formatters] 570 keys=form1 571 572 [logger_root] 573 level=NOTSET 574 handlers=hand1 575 576 [handler_hand1] 577 class=StreamHandler 578 level=NOTSET 579 formatter=form1 580 args=(sys.stdout,) 581 582 [formatter_form1] 583 class=""" + __name__ + """.ExceptionFormatter 584 format=%(levelname)s:%(name)s:%(message)s 585 datefmt= 586 """ 587 588 # config5 specifies a custom handler class to be loaded 589 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler') 590 591 # config6 uses ', ' delimiters in the handlers and formatters sections 592 config6 = """ 593 [loggers] 594 keys=root,parser 595 596 [handlers] 597 keys=hand1, hand2 598 599 [formatters] 600 keys=form1, form2 601 602 [logger_root] 603 level=WARNING 604 handlers= 605 606 [logger_parser] 607 level=DEBUG 608 handlers=hand1 609 propagate=1 610 qualname=compiler.parser 611 612 [handler_hand1] 613 class=StreamHandler 614 level=NOTSET 615 formatter=form1 616 args=(sys.stdout,) 617 618 [handler_hand2] 619 class=StreamHandler 620 level=NOTSET 621 formatter=form1 622 args=(sys.stderr,) 623 624 [formatter_form1] 625 format=%(levelname)s ++ %(message)s 626 datefmt= 627 628 [formatter_form2] 629 format=%(message)s 630 datefmt= 631 """ 632 633 def apply_config(self, conf): 634 try: 635 fn = tempfile.mktemp(".ini") 636 f = open(fn, "w") 637 f.write(textwrap.dedent(conf)) 638 f.close() 639 logging.config.fileConfig(fn) 640 finally: 641 os.remove(fn) 642 643 def test_config0_ok(self): 644 # A simple config file which overrides the default settings. 645 with captured_stdout() as output: 646 self.apply_config(self.config0) 647 logger = logging.getLogger() 648 # Won't output anything 649 logger.info(self.next_message()) 650 # Outputs a message 651 logger.error(self.next_message()) 652 self.assert_log_lines([ 653 ('ERROR', '2'), 654 ], stream=output) 655 # Original logger output is empty. 656 self.assert_log_lines([]) 657 658 def test_config1_ok(self, config=config1): 659 # A config file defining a sub-parser as well. 660 with captured_stdout() as output: 661 self.apply_config(config) 662 logger = logging.getLogger("compiler.parser") 663 # Both will output a message 664 logger.info(self.next_message()) 665 logger.error(self.next_message()) 666 self.assert_log_lines([ 667 ('INFO', '1'), 668 ('ERROR', '2'), 669 ], stream=output) 670 # Original logger output is empty. 671 self.assert_log_lines([]) 672 673 def test_config2_failure(self): 674 # A simple config file which overrides the default settings. 675 self.assertRaises(StandardError, self.apply_config, self.config2) 676 677 def test_config3_failure(self): 678 # A simple config file which overrides the default settings. 679 self.assertRaises(StandardError, self.apply_config, self.config3) 680 681 def test_config4_ok(self): 682 # A config file specifying a custom formatter class. 683 with captured_stdout() as output: 684 self.apply_config(self.config4) 685 logger = logging.getLogger() 686 try: 687 raise RuntimeError() 688 except RuntimeError: 689 logging.exception("just testing") 690 sys.stdout.seek(0) 691 self.assertEquals(output.getvalue(), 692 "ERROR:root:just testing\nGot a [RuntimeError]\n") 693 # Original logger output is empty 694 self.assert_log_lines([]) 695 696 def test_config5_ok(self): 697 self.test_config1_ok(config=self.config5) 698 699 def test_config6_ok(self): 700 self.test_config1_ok(config=self.config6) 701 702class LogRecordStreamHandler(StreamRequestHandler): 703 704 """Handler for a streaming logging request. It saves the log message in the 705 TCP server's 'log_output' attribute.""" 706 707 TCP_LOG_END = "!!!END!!!" 708 709 def handle(self): 710 """Handle multiple requests - each expected to be of 4-byte length, 711 followed by the LogRecord in pickle format. Logs the record 712 according to whatever policy is configured locally.""" 713 while True: 714 chunk = self.connection.recv(4) 715 if len(chunk) < 4: 716 break 717 slen = struct.unpack(">L", chunk)[0] 718 chunk = self.connection.recv(slen) 719 while len(chunk) < slen: 720 chunk = chunk + self.connection.recv(slen - len(chunk)) 721 obj = self.unpickle(chunk) 722 record = logging.makeLogRecord(obj) 723 self.handle_log_record(record) 724 725 def unpickle(self, data): 726 return cPickle.loads(data) 727 728 def handle_log_record(self, record): 729 # If the end-of-messages sentinel is seen, tell the server to 730 # terminate. 731 if self.TCP_LOG_END in record.msg: 732 self.server.abort = 1 733 return 734 self.server.log_output += record.msg + "\n" 735 736 737class LogRecordSocketReceiver(ThreadingTCPServer): 738 739 """A simple-minded TCP socket-based logging receiver suitable for test 740 purposes.""" 741 742 allow_reuse_address = 1 743 log_output = "" 744 745 def __init__(self, host='localhost', 746 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT, 747 handler=LogRecordStreamHandler): 748 ThreadingTCPServer.__init__(self, (host, port), handler) 749 self.abort = False 750 self.timeout = 0.1 751 self.finished = threading.Event() 752 753 def serve_until_stopped(self): 754 while not self.abort: 755 rd, wr, ex = select.select([self.socket.fileno()], [], [], 756 self.timeout) 757 if rd: 758 self.handle_request() 759 # Notify the main thread that we're about to exit 760 self.finished.set() 761 # close the listen socket 762 self.server_close() 763 764 765class SocketHandlerTest(BaseTest): 766 767 """Test for SocketHandler objects.""" 768 769 def setUp(self): 770 """Set up a TCP server to receive log messages, and a SocketHandler 771 pointing to that server's address and port.""" 772 BaseTest.setUp(self) 773 self.tcpserver = LogRecordSocketReceiver(port=0) 774 self.port = self.tcpserver.socket.getsockname()[1] 775 self.threads = [ 776 threading.Thread(target=self.tcpserver.serve_until_stopped)] 777 for thread in self.threads: 778 thread.start() 779 780 self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port) 781 self.sock_hdlr.setFormatter(self.root_formatter) 782 self.root_logger.removeHandler(self.root_logger.handlers[0]) 783 self.root_logger.addHandler(self.sock_hdlr) 784 785 def tearDown(self): 786 """Shutdown the TCP server.""" 787 try: 788 self.tcpserver.abort = True 789 del self.tcpserver 790 self.root_logger.removeHandler(self.sock_hdlr) 791 self.sock_hdlr.close() 792 for thread in self.threads: 793 thread.join(2.0) 794 finally: 795 BaseTest.tearDown(self) 796 797 def get_output(self): 798 """Get the log output as received by the TCP server.""" 799 # Signal the TCP receiver and wait for it to terminate. 800 self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END) 801 self.tcpserver.finished.wait(2.0) 802 return self.tcpserver.log_output 803 804 def test_output(self): 805 # The log message sent to the SocketHandler is properly received. 806 logger = logging.getLogger("tcp") 807 logger.error("spam") 808 logger.debug("eggs") 809 self.assertEquals(self.get_output(), "spam\neggs\n") 810 811 812class MemoryTest(BaseTest): 813 814 """Test memory persistence of logger objects.""" 815 816 def setUp(self): 817 """Create a dict to remember potentially destroyed objects.""" 818 BaseTest.setUp(self) 819 self._survivors = {} 820 821 def _watch_for_survival(self, *args): 822 """Watch the given objects for survival, by creating weakrefs to 823 them.""" 824 for obj in args: 825 key = id(obj), repr(obj) 826 self._survivors[key] = weakref.ref(obj) 827 828 def _assert_survival(self): 829 """Assert that all objects watched for survival have survived.""" 830 # Trigger cycle breaking. 831 gc.collect() 832 dead = [] 833 for (id_, repr_), ref in self._survivors.items(): 834 if ref() is None: 835 dead.append(repr_) 836 if dead: 837 self.fail("%d objects should have survived " 838 "but have been destroyed: %s" % (len(dead), ", ".join(dead))) 839 840 def test_persistent_loggers(self): 841 # Logger objects are persistent and retain their configuration, even 842 # if visible references are destroyed. 843 self.root_logger.setLevel(logging.INFO) 844 foo = logging.getLogger("foo") 845 self._watch_for_survival(foo) 846 foo.setLevel(logging.DEBUG) 847 self.root_logger.debug(self.next_message()) 848 foo.debug(self.next_message()) 849 self.assert_log_lines([ 850 ('foo', 'DEBUG', '2'), 851 ]) 852 del foo 853 # foo has survived. 854 self._assert_survival() 855 # foo has retained its settings. 856 bar = logging.getLogger("foo") 857 bar.debug(self.next_message()) 858 self.assert_log_lines([ 859 ('foo', 'DEBUG', '2'), 860 ('foo', 'DEBUG', '3'), 861 ]) 862 863 864class EncodingTest(BaseTest): 865 def test_encoding_plain_file(self): 866 # In Python 2.x, a plain file object is treated as having no encoding. 867 log = logging.getLogger("test") 868 fn = tempfile.mktemp(".log") 869 # the non-ascii data we write to the log. 870 data = "foo\x80" 871 try: 872 handler = logging.FileHandler(fn) 873 log.addHandler(handler) 874 try: 875 # write non-ascii data to the log. 876 log.warning(data) 877 finally: 878 log.removeHandler(handler) 879 handler.close() 880 # check we wrote exactly those bytes, ignoring trailing \n etc 881 f = open(fn) 882 try: 883 self.failUnlessEqual(f.read().rstrip(), data) 884 finally: 885 f.close() 886 finally: 887 if os.path.isfile(fn): 888 os.remove(fn) 889 890 def test_encoding_cyrillic_unicode(self): 891 log = logging.getLogger("test") 892 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye) 893 message = u'\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f' 894 #Ensure it's written in a Cyrillic encoding 895 writer_class = codecs.getwriter('cp1251') 896 writer_class.encoding = 'cp1251' 897 stream = cStringIO.StringIO() 898 writer = writer_class(stream, 'strict') 899 handler = logging.StreamHandler(writer) 900 log.addHandler(handler) 901 try: 902 log.warning(message) 903 finally: 904 log.removeHandler(handler) 905 handler.close() 906 # check we wrote exactly those bytes, ignoring trailing \n etc 907 s = stream.getvalue() 908 #Compare against what the data should be when encoded in CP-1251 909 self.assertEqual(s, '\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n') 910 911 912# Set the locale to the platform-dependent default. I have no idea 913# why the test does this, but in any case we save the current locale 914# first and restore it at the end. 915@run_with_locale('LC_ALL', '') 916def test_main(): 917 run_unittest(BuiltinLevelsTest, BasicFilterTest, 918 CustomLevelsAndFiltersTest, MemoryHandlerTest, 919 ConfigFileTest, SocketHandlerTest, MemoryTest, 920 EncodingTest) 921 922if __name__ == "__main__": 923 test_main()