1 #!/usr/bin/env python 2 # 3 # Copyright 2001-2010 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 21 Copyright (C) 2001-2010 Vinay Sajip. All Rights Reserved. 22 """ 23 24 import logging 25 import logging.handlers 26 import logging.config 27 28 import codecs 29 import cPickle 30 import cStringIO 31 import gc 32 import json 33 import os 34 import re 35 import select 36 import socket 37 from SocketServer import ThreadingTCPServer, StreamRequestHandler 38 import struct 39 import sys 40 import tempfile 41 from test.test_support import captured_stdout, run_with_locale, run_unittest 42 import textwrap 43 import unittest 44 import warnings 45 import weakref 46 try: 47 import threading 48 except ImportError: 49 threading = None 50 51 class 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 # 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 78 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) 93 while self.root_logger.handlers: 94 h = self.root_logger.handlers[0] 95 self.root_logger.removeHandler(h) 96 h.close() 97 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 111 def assert_log_lines(self, expected_values, stream=None): 112 """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() 123 self.assertEqual(len(actual_lines), len(expected_values)) 124 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) 129 self.assertEqual(tuple(match.groups()), expected) 130 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 141 class 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 177 self.assert_log_lines([ 178 ('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 209 self.assert_log_lines([ 210 ('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 240 self.assert_log_lines([ 241 ('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 268 self.assert_log_lines([ 269 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'), 270 ('INF.BADPARENT.UNDEF', 'INFO', '2'), 271 ('INF.BADPARENT', 'CRITICAL', '3'), 272 ('INF.BADPARENT', 'INFO', '4'), 273 ]) 274 275 276 class 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 297 self.assert_log_lines([ 298 ('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 # 313 SILENT = 120 314 TACITURN = 119 315 TERSE = 118 316 EFFUSIVE = 117 317 SOCIABLE = 116 318 VERBOSE = 115 319 TALKATIVE = 114 320 GARRULOUS = 113 321 CHATTERBOX = 112 322 BORING = 111 323 324 LEVEL_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 # 330 my_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 343 class GarrulousFilter(logging.Filter): 344 345 """A filter which blocks garrulous messages.""" 346 347 def filter(self, record): 348 return record.levelno != GARRULOUS 349 350 class 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 358 class 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) 379 self.assert_log_lines([ 380 ('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) 394 self.assert_log_lines([ 395 ('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 ] 425 self.assert_log_lines(first_lines) 426 427 specific_filter = VerySpecificFilter() 428 self.root_logger.addFilter(specific_filter) 429 self.log_at_all_levels(self.root_logger) 430 self.assert_log_lines(first_lines + [ 431 # 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 447 class 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() 464 BaseTest.tearDown(self) 465 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()) 470 self.assert_log_lines([]) 471 self.mem_logger.info(self.next_message()) 472 self.assert_log_lines([]) 473 # 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 ] 480 self.assert_log_lines(lines) 481 for n in (4, 14): 482 for i in range(9): 483 self.mem_logger.debug(self.next_message()) 484 self.assert_log_lines(lines) 485 # 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)] 489 self.assert_log_lines(lines) 490 491 self.mem_logger.debug(self.next_message()) 492 self.assert_log_lines(lines) 493 494 495 class ExceptionFormatter(logging.Formatter): 496 """A special exception formatter.""" 497 def formatException(self, ei): 498 return "Got a [%s]" % ei[0].__name__ 499 500 501 class 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 # config1a moves the handler to the root. 566 config1a = """ 567 [loggers] 568 keys=root,parser 569 570 [handlers] 571 keys=hand1 572 573 [formatters] 574 keys=form1 575 576 [logger_root] 577 level=WARNING 578 handlers=hand1 579 580 [logger_parser] 581 level=DEBUG 582 handlers= 583 propagate=1 584 qualname=compiler.parser 585 586 [handler_hand1] 587 class=StreamHandler 588 level=NOTSET 589 formatter=form1 590 args=(sys.stdout,) 591 592 [formatter_form1] 593 format=%(levelname)s ++ %(message)s 594 datefmt= 595 """ 596 597 # config2 has a subtle configuration error that should be reported 598 config2 = config1.replace("sys.stdout", "sys.stbout") 599 600 # config3 has a less subtle configuration error 601 config3 = config1.replace("formatter=form1", "formatter=misspelled_name") 602 603 # config4 specifies a custom formatter class to be loaded 604 config4 = """ 605 [loggers] 606 keys=root 607 608 [handlers] 609 keys=hand1 610 611 [formatters] 612 keys=form1 613 614 [logger_root] 615 level=NOTSET 616 handlers=hand1 617 618 [handler_hand1] 619 class=StreamHandler 620 level=NOTSET 621 formatter=form1 622 args=(sys.stdout,) 623 624 [formatter_form1] 625 class=""" + __name__ + """.ExceptionFormatter 626 format=%(levelname)s:%(name)s:%(message)s 627 datefmt= 628 """ 629 630 # config5 specifies a custom handler class to be loaded 631 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler') 632 633 # config6 uses ', ' delimiters in the handlers and formatters sections 634 config6 = """ 635 [loggers] 636 keys=root,parser 637 638 [handlers] 639 keys=hand1, hand2 640 641 [formatters] 642 keys=form1, form2 643 644 [logger_root] 645 level=WARNING 646 handlers= 647 648 [logger_parser] 649 level=DEBUG 650 handlers=hand1 651 propagate=1 652 qualname=compiler.parser 653 654 [handler_hand1] 655 class=StreamHandler 656 level=NOTSET 657 formatter=form1 658 args=(sys.stdout,) 659 660 [handler_hand2] 661 class=StreamHandler 662 level=NOTSET 663 formatter=form1 664 args=(sys.stderr,) 665 666 [formatter_form1] 667 format=%(levelname)s ++ %(message)s 668 datefmt= 669 670 [formatter_form2] 671 format=%(message)s 672 datefmt= 673 """ 674 675 # config7 adds a compiler logger. 676 config7 = """ 677 [loggers] 678 keys=root,parser,compiler 679 680 [handlers] 681 keys=hand1 682 683 [formatters] 684 keys=form1 685 686 [logger_root] 687 level=WARNING 688 handlers=hand1 689 690 [logger_compiler] 691 level=DEBUG 692 handlers= 693 propagate=1 694 qualname=compiler 695 696 [logger_parser] 697 level=DEBUG 698 handlers= 699 propagate=1 700 qualname=compiler.parser 701 702 [handler_hand1] 703 class=StreamHandler 704 level=NOTSET 705 formatter=form1 706 args=(sys.stdout,) 707 708 [formatter_form1] 709 format=%(levelname)s ++ %(message)s 710 datefmt= 711 """ 712 713 def apply_config(self, conf): 714 file = cStringIO.StringIO(textwrap.dedent(conf)) 715 logging.config.fileConfig(file) 716 717 def test_config0_ok(self): 718 # A simple config file which overrides the default settings. 719 with captured_stdout() as output: 720 self.apply_config(self.config0) 721 logger = logging.getLogger() 722 # Won't output anything 723 logger.info(self.next_message()) 724 # Outputs a message 725 logger.error(self.next_message()) 726 self.assert_log_lines([ 727 ('ERROR', '2'), 728 ], stream=output) 729 # Original logger output is empty. 730 self.assert_log_lines([]) 731 732 def test_config1_ok(self, config=config1): 733 # A config file defining a sub-parser as well. 734 with captured_stdout() as output: 735 self.apply_config(config) 736 logger = logging.getLogger("compiler.parser") 737 # Both will output a message 738 logger.info(self.next_message()) 739 logger.error(self.next_message()) 740 self.assert_log_lines([ 741 ('INFO', '1'), 742 ('ERROR', '2'), 743 ], stream=output) 744 # Original logger output is empty. 745 self.assert_log_lines([]) 746 747 def test_config2_failure(self): 748 # A simple config file which overrides the default settings. 749 self.assertRaises(StandardError, self.apply_config, self.config2) 750 751 def test_config3_failure(self): 752 # A simple config file which overrides the default settings. 753 self.assertRaises(StandardError, self.apply_config, self.config3) 754 755 def test_config4_ok(self): 756 # A config file specifying a custom formatter class. 757 with captured_stdout() as output: 758 self.apply_config(self.config4) 759 logger = logging.getLogger() 760 try: 761 raise RuntimeError() 762 except RuntimeError: 763 logging.exception("just testing") 764 sys.stdout.seek(0) 765 self.assertEqual(output.getvalue(), 766 "ERROR:root:just testing\nGot a [RuntimeError]\n") 767 # Original logger output is empty 768 self.assert_log_lines([]) 769 770 def test_config5_ok(self): 771 self.test_config1_ok(config=self.config5) 772 773 def test_config6_ok(self): 774 self.test_config1_ok(config=self.config6) 775 776 def test_config7_ok(self): 777 with captured_stdout() as output: 778 self.apply_config(self.config1a) 779 logger = logging.getLogger("compiler.parser") 780 # See issue #11424. compiler-hyphenated sorts 781 # between compiler and compiler.xyz and this 782 # was preventing compiler.xyz from being included 783 # in the child loggers of compiler because of an 784 # overzealous loop termination condition. 785 hyphenated = logging.getLogger('compiler-hyphenated') 786 # All will output a message 787 logger.info(self.next_message()) 788 logger.error(self.next_message()) 789 hyphenated.critical(self.next_message()) 790 self.assert_log_lines([ 791 ('INFO', '1'), 792 ('ERROR', '2'), 793 ('CRITICAL', '3'), 794 ], stream=output) 795 # Original logger output is empty. 796 self.assert_log_lines([]) 797 with captured_stdout() as output: 798 self.apply_config(self.config7) 799 logger = logging.getLogger("compiler.parser") 800 self.assertFalse(logger.disabled) 801 # Both will output a message 802 logger.info(self.next_message()) 803 logger.error(self.next_message()) 804 logger = logging.getLogger("compiler.lexer") 805 # Both will output a message 806 logger.info(self.next_message()) 807 logger.error(self.next_message()) 808 # Will not appear 809 hyphenated.critical(self.next_message()) 810 self.assert_log_lines([ 811 ('INFO', '4'), 812 ('ERROR', '5'), 813 ('INFO', '6'), 814 ('ERROR', '7'), 815 ], stream=output) 816 # Original logger output is empty. 817 self.assert_log_lines([]) 818 819 class LogRecordStreamHandler(StreamRequestHandler): 820 821 """Handler for a streaming logging request. It saves the log message in the 822 TCP server's 'log_output' attribute.""" 823 824 TCP_LOG_END = "!!!END!!!" 825 826 def handle(self): 827 """Handle multiple requests - each expected to be of 4-byte length, 828 followed by the LogRecord in pickle format. Logs the record 829 according to whatever policy is configured locally.""" 830 while True: 831 chunk = self.connection.recv(4) 832 if len(chunk) < 4: 833 break 834 slen = struct.unpack(">L", chunk)[0] 835 chunk = self.connection.recv(slen) 836 while len(chunk) < slen: 837 chunk = chunk + self.connection.recv(slen - len(chunk)) 838 obj = self.unpickle(chunk) 839 record = logging.makeLogRecord(obj) 840 self.handle_log_record(record) 841 842 def unpickle(self, data): 843 return cPickle.loads(data) 844 845 def handle_log_record(self, record): 846 # If the end-of-messages sentinel is seen, tell the server to 847 # terminate. 848 if self.TCP_LOG_END in record.msg: 849 self.server.abort = 1 850 return 851 self.server.log_output += record.msg + "\n" 852 853 854 class LogRecordSocketReceiver(ThreadingTCPServer): 855 856 """A simple-minded TCP socket-based logging receiver suitable for test 857 purposes.""" 858 859 allow_reuse_address = 1 860 log_output = "" 861 862 def __init__(self, host='localhost', 863 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT, 864 handler=LogRecordStreamHandler): 865 ThreadingTCPServer.__init__(self, (host, port), handler) 866 self.abort = False 867 self.timeout = 0.1 868 self.finished = threading.Event() 869 870 def serve_until_stopped(self): 871 while not self.abort: 872 rd, wr, ex = select.select([self.socket.fileno()], [], [], 873 self.timeout) 874 if rd: 875 self.handle_request() 876 # Notify the main thread that we're about to exit 877 self.finished.set() 878 # close the listen socket 879 self.server_close() 880 881 882 @unittest.skipUnless(threading, 'Threading required for this test.') 883 class SocketHandlerTest(BaseTest): 884 885 """Test for SocketHandler objects.""" 886 887 def setUp(self): 888 """Set up a TCP server to receive log messages, and a SocketHandler 889 pointing to that server's address and port.""" 890 BaseTest.setUp(self) 891 self.tcpserver = LogRecordSocketReceiver(port=0) 892 self.port = self.tcpserver.socket.getsockname()[1] 893 self.threads = [ 894 threading.Thread(target=self.tcpserver.serve_until_stopped)] 895 for thread in self.threads: 896 thread.start() 897 898 self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port) 899 self.sock_hdlr.setFormatter(self.root_formatter) 900 self.root_logger.removeHandler(self.root_logger.handlers[0]) 901 self.root_logger.addHandler(self.sock_hdlr) 902 903 def tearDown(self): 904 """Shutdown the TCP server.""" 905 try: 906 self.tcpserver.abort = True 907 del self.tcpserver 908 self.root_logger.removeHandler(self.sock_hdlr) 909 self.sock_hdlr.close() 910 for thread in self.threads: 911 thread.join(2.0) 912 finally: 913 BaseTest.tearDown(self) 914 915 def get_output(self): 916 """Get the log output as received by the TCP server.""" 917 # Signal the TCP receiver and wait for it to terminate. 918 self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END) 919 self.tcpserver.finished.wait(2.0) 920 return self.tcpserver.log_output 921 922 def test_output(self): 923 # The log message sent to the SocketHandler is properly received. 924 logger = logging.getLogger("tcp") 925 logger.error("spam") 926 logger.debug("eggs") 927 self.assertEqual(self.get_output(), "spam\neggs\n") 928 929 930 class MemoryTest(BaseTest): 931 932 """Test memory persistence of logger objects.""" 933 934 def setUp(self): 935 """Create a dict to remember potentially destroyed objects.""" 936 BaseTest.setUp(self) 937 self._survivors = {} 938 939 def _watch_for_survival(self, *args): 940 """Watch the given objects for survival, by creating weakrefs to 941 them.""" 942 for obj in args: 943 key = id(obj), repr(obj) 944 self._survivors[key] = weakref.ref(obj) 945 946 def _assertTruesurvival(self): 947 """Assert that all objects watched for survival have survived.""" 948 # Trigger cycle breaking. 949 gc.collect() 950 dead = [] 951 for (id_, repr_), ref in self._survivors.items(): 952 if ref() is None: 953 dead.append(repr_) 954 if dead: 955 self.fail("%d objects should have survived " 956 "but have been destroyed: %s" % (len(dead), ", ".join(dead))) 957 958 def test_persistent_loggers(self): 959 # Logger objects are persistent and retain their configuration, even 960 # if visible references are destroyed. 961 self.root_logger.setLevel(logging.INFO) 962 foo = logging.getLogger("foo") 963 self._watch_for_survival(foo) 964 foo.setLevel(logging.DEBUG) 965 self.root_logger.debug(self.next_message()) 966 foo.debug(self.next_message()) 967 self.assert_log_lines([ 968 ('foo', 'DEBUG', '2'), 969 ]) 970 del foo 971 # foo has survived. 972 self._assertTruesurvival() 973 # foo has retained its settings. 974 bar = logging.getLogger("foo") 975 bar.debug(self.next_message()) 976 self.assert_log_lines([ 977 ('foo', 'DEBUG', '2'), 978 ('foo', 'DEBUG', '3'), 979 ]) 980 981 982 class EncodingTest(BaseTest): 983 def test_encoding_plain_file(self): 984 # In Python 2.x, a plain file object is treated as having no encoding. 985 log = logging.getLogger("test") 986 fn = tempfile.mktemp(".log") 987 # the non-ascii data we write to the log. 988 data = "foo\x80" 989 try: 990 handler = logging.FileHandler(fn) 991 log.addHandler(handler) 992 try: 993 # write non-ascii data to the log. 994 log.warning(data) 995 finally: 996 log.removeHandler(handler) 997 handler.close() 998 # check we wrote exactly those bytes, ignoring trailing \n etc 999 f = open(fn) 1000 try: 1001 self.assertEqual(f.read().rstrip(), data) 1002 finally: 1003 f.close() 1004 finally: 1005 if os.path.isfile(fn): 1006 os.remove(fn) 1007 1008 def test_encoding_cyrillic_unicode(self): 1009 log = logging.getLogger("test") 1010 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye) 1011 message = u'\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f' 1012 #Ensure it's written in a Cyrillic encoding 1013 writer_class = codecs.getwriter('cp1251') 1014 writer_class.encoding = 'cp1251' 1015 stream = cStringIO.StringIO() 1016 writer = writer_class(stream, 'strict') 1017 handler = logging.StreamHandler(writer) 1018 log.addHandler(handler) 1019 try: 1020 log.warning(message) 1021 finally: 1022 log.removeHandler(handler) 1023 handler.close() 1024 # check we wrote exactly those bytes, ignoring trailing \n etc 1025 s = stream.getvalue() 1026 #Compare against what the data should be when encoded in CP-1251 1027 self.assertEqual(s, '\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n') 1028 1029 1030 class WarningsTest(BaseTest): 1031 1032 def test_warnings(self): 1033 with warnings.catch_warnings(): 1034 logging.captureWarnings(True) 1035 try: 1036 warnings.filterwarnings("always", category=UserWarning) 1037 file = cStringIO.StringIO() 1038 h = logging.StreamHandler(file) 1039 logger = logging.getLogger("py.warnings") 1040 logger.addHandler(h) 1041 warnings.warn("I'm warning you...") 1042 logger.removeHandler(h) 1043 s = file.getvalue() 1044 h.close() 1045 self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0) 1046 1047 #See if an explicit file uses the original implementation 1048 file = cStringIO.StringIO() 1049 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42, 1050 file, "Dummy line") 1051 s = file.getvalue() 1052 file.close() 1053 self.assertEqual(s, 1054 "dummy.py:42: UserWarning: Explicit\n Dummy line\n") 1055 finally: 1056 logging.captureWarnings(False) 1057 1058 1059 def formatFunc(format, datefmt=None): 1060 return logging.Formatter(format, datefmt) 1061 1062 def handlerFunc(): 1063 return logging.StreamHandler() 1064 1065 class CustomHandler(logging.StreamHandler): 1066 pass 1067 1068 class ConfigDictTest(BaseTest): 1069 1070 """Reading logging config from a dictionary.""" 1071 1072 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$" 1073 1074 # config0 is a standard configuration. 1075 config0 = { 1076 'version': 1, 1077 'formatters': { 1078 'form1' : { 1079 'format' : '%(levelname)s ++ %(message)s', 1080 }, 1081 }, 1082 'handlers' : { 1083 'hand1' : { 1084 'class' : 'logging.StreamHandler', 1085 'formatter' : 'form1', 1086 'level' : 'NOTSET', 1087 'stream' : 'ext://sys.stdout', 1088 }, 1089 }, 1090 'root' : { 1091 'level' : 'WARNING', 1092 'handlers' : ['hand1'], 1093 }, 1094 } 1095 1096 # config1 adds a little to the standard configuration. 1097 config1 = { 1098 'version': 1, 1099 'formatters': { 1100 'form1' : { 1101 'format' : '%(levelname)s ++ %(message)s', 1102 }, 1103 }, 1104 'handlers' : { 1105 'hand1' : { 1106 'class' : 'logging.StreamHandler', 1107 'formatter' : 'form1', 1108 'level' : 'NOTSET', 1109 'stream' : 'ext://sys.stdout', 1110 }, 1111 }, 1112 'loggers' : { 1113 'compiler.parser' : { 1114 'level' : 'DEBUG', 1115 'handlers' : ['hand1'], 1116 }, 1117 }, 1118 'root' : { 1119 'level' : 'WARNING', 1120 }, 1121 } 1122 1123 # config2 has a subtle configuration error that should be reported 1124 config2 = { 1125 'version': 1, 1126 'formatters': { 1127 'form1' : { 1128 'format' : '%(levelname)s ++ %(message)s', 1129 }, 1130 }, 1131 'handlers' : { 1132 'hand1' : { 1133 'class' : 'logging.StreamHandler', 1134 'formatter' : 'form1', 1135 'level' : 'NOTSET', 1136 'stream' : 'ext://sys.stdbout', 1137 }, 1138 }, 1139 'loggers' : { 1140 'compiler.parser' : { 1141 'level' : 'DEBUG', 1142 'handlers' : ['hand1'], 1143 }, 1144 }, 1145 'root' : { 1146 'level' : 'WARNING', 1147 }, 1148 } 1149 1150 #As config1 but with a misspelt level on a handler 1151 config2a = { 1152 'version': 1, 1153 'formatters': { 1154 'form1' : { 1155 'format' : '%(levelname)s ++ %(message)s', 1156 }, 1157 }, 1158 'handlers' : { 1159 'hand1' : { 1160 'class' : 'logging.StreamHandler', 1161 'formatter' : 'form1', 1162 'level' : 'NTOSET', 1163 'stream' : 'ext://sys.stdout', 1164 }, 1165 }, 1166 'loggers' : { 1167 'compiler.parser' : { 1168 'level' : 'DEBUG', 1169 'handlers' : ['hand1'], 1170 }, 1171 }, 1172 'root' : { 1173 'level' : 'WARNING', 1174 }, 1175 } 1176 1177 1178 #As config1 but with a misspelt level on a logger 1179 config2b = { 1180 'version': 1, 1181 'formatters': { 1182 'form1' : { 1183 'format' : '%(levelname)s ++ %(message)s', 1184 }, 1185 }, 1186 'handlers' : { 1187 'hand1' : { 1188 'class' : 'logging.StreamHandler', 1189 'formatter' : 'form1', 1190 'level' : 'NOTSET', 1191 'stream' : 'ext://sys.stdout', 1192 }, 1193 }, 1194 'loggers' : { 1195 'compiler.parser' : { 1196 'level' : 'DEBUG', 1197 'handlers' : ['hand1'], 1198 }, 1199 }, 1200 'root' : { 1201 'level' : 'WRANING', 1202 }, 1203 } 1204 1205 # config3 has a less subtle configuration error 1206 config3 = { 1207 'version': 1, 1208 'formatters': { 1209 'form1' : { 1210 'format' : '%(levelname)s ++ %(message)s', 1211 }, 1212 }, 1213 'handlers' : { 1214 'hand1' : { 1215 'class' : 'logging.StreamHandler', 1216 'formatter' : 'misspelled_name', 1217 'level' : 'NOTSET', 1218 'stream' : 'ext://sys.stdout', 1219 }, 1220 }, 1221 'loggers' : { 1222 'compiler.parser' : { 1223 'level' : 'DEBUG', 1224 'handlers' : ['hand1'], 1225 }, 1226 }, 1227 'root' : { 1228 'level' : 'WARNING', 1229 }, 1230 } 1231 1232 # config4 specifies a custom formatter class to be loaded 1233 config4 = { 1234 'version': 1, 1235 'formatters': { 1236 'form1' : { 1237 '()' : __name__ + '.ExceptionFormatter', 1238 'format' : '%(levelname)s:%(name)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 'root' : { 1250 'level' : 'NOTSET', 1251 'handlers' : ['hand1'], 1252 }, 1253 } 1254 1255 # As config4 but using an actual callable rather than a string 1256 config4a = { 1257 'version': 1, 1258 'formatters': { 1259 'form1' : { 1260 '()' : ExceptionFormatter, 1261 'format' : '%(levelname)s:%(name)s:%(message)s', 1262 }, 1263 'form2' : { 1264 '()' : __name__ + '.formatFunc', 1265 'format' : '%(levelname)s:%(name)s:%(message)s', 1266 }, 1267 'form3' : { 1268 '()' : formatFunc, 1269 'format' : '%(levelname)s:%(name)s:%(message)s', 1270 }, 1271 }, 1272 'handlers' : { 1273 'hand1' : { 1274 'class' : 'logging.StreamHandler', 1275 'formatter' : 'form1', 1276 'level' : 'NOTSET', 1277 'stream' : 'ext://sys.stdout', 1278 }, 1279 'hand2' : { 1280 '()' : handlerFunc, 1281 }, 1282 }, 1283 'root' : { 1284 'level' : 'NOTSET', 1285 'handlers' : ['hand1'], 1286 }, 1287 } 1288 1289 # config5 specifies a custom handler class to be loaded 1290 config5 = { 1291 'version': 1, 1292 'formatters': { 1293 'form1' : { 1294 'format' : '%(levelname)s ++ %(message)s', 1295 }, 1296 }, 1297 'handlers' : { 1298 'hand1' : { 1299 'class' : __name__ + '.CustomHandler', 1300 'formatter' : 'form1', 1301 'level' : 'NOTSET', 1302 'stream' : 'ext://sys.stdout', 1303 }, 1304 }, 1305 'loggers' : { 1306 'compiler.parser' : { 1307 'level' : 'DEBUG', 1308 'handlers' : ['hand1'], 1309 }, 1310 }, 1311 'root' : { 1312 'level' : 'WARNING', 1313 }, 1314 } 1315 1316 # config6 specifies a custom handler class to be loaded 1317 # but has bad arguments 1318 config6 = { 1319 'version': 1, 1320 'formatters': { 1321 'form1' : { 1322 'format' : '%(levelname)s ++ %(message)s', 1323 }, 1324 }, 1325 'handlers' : { 1326 'hand1' : { 1327 'class' : __name__ + '.CustomHandler', 1328 'formatter' : 'form1', 1329 'level' : 'NOTSET', 1330 'stream' : 'ext://sys.stdout', 1331 '9' : 'invalid parameter name', 1332 }, 1333 }, 1334 'loggers' : { 1335 'compiler.parser' : { 1336 'level' : 'DEBUG', 1337 'handlers' : ['hand1'], 1338 }, 1339 }, 1340 'root' : { 1341 'level' : 'WARNING', 1342 }, 1343 } 1344 1345 #config 7 does not define compiler.parser but defines compiler.lexer 1346 #so compiler.parser should be disabled after applying it 1347 config7 = { 1348 'version': 1, 1349 'formatters': { 1350 'form1' : { 1351 'format' : '%(levelname)s ++ %(message)s', 1352 }, 1353 }, 1354 'handlers' : { 1355 'hand1' : { 1356 'class' : 'logging.StreamHandler', 1357 'formatter' : 'form1', 1358 'level' : 'NOTSET', 1359 'stream' : 'ext://sys.stdout', 1360 }, 1361 }, 1362 'loggers' : { 1363 'compiler.lexer' : { 1364 'level' : 'DEBUG', 1365 'handlers' : ['hand1'], 1366 }, 1367 }, 1368 'root' : { 1369 'level' : 'WARNING', 1370 }, 1371 } 1372 1373 config8 = { 1374 'version': 1, 1375 'disable_existing_loggers' : False, 1376 'formatters': { 1377 'form1' : { 1378 'format' : '%(levelname)s ++ %(message)s', 1379 }, 1380 }, 1381 'handlers' : { 1382 'hand1' : { 1383 'class' : 'logging.StreamHandler', 1384 'formatter' : 'form1', 1385 'level' : 'NOTSET', 1386 'stream' : 'ext://sys.stdout', 1387 }, 1388 }, 1389 'loggers' : { 1390 'compiler' : { 1391 'level' : 'DEBUG', 1392 'handlers' : ['hand1'], 1393 }, 1394 'compiler.lexer' : { 1395 }, 1396 }, 1397 'root' : { 1398 'level' : 'WARNING', 1399 }, 1400 } 1401 1402 config9 = { 1403 'version': 1, 1404 'formatters': { 1405 'form1' : { 1406 'format' : '%(levelname)s ++ %(message)s', 1407 }, 1408 }, 1409 'handlers' : { 1410 'hand1' : { 1411 'class' : 'logging.StreamHandler', 1412 'formatter' : 'form1', 1413 'level' : 'WARNING', 1414 'stream' : 'ext://sys.stdout', 1415 }, 1416 }, 1417 'loggers' : { 1418 'compiler.parser' : { 1419 'level' : 'WARNING', 1420 'handlers' : ['hand1'], 1421 }, 1422 }, 1423 'root' : { 1424 'level' : 'NOTSET', 1425 }, 1426 } 1427 1428 config9a = { 1429 'version': 1, 1430 'incremental' : True, 1431 'handlers' : { 1432 'hand1' : { 1433 'level' : 'WARNING', 1434 }, 1435 }, 1436 'loggers' : { 1437 'compiler.parser' : { 1438 'level' : 'INFO', 1439 }, 1440 }, 1441 } 1442 1443 config9b = { 1444 'version': 1, 1445 'incremental' : True, 1446 'handlers' : { 1447 'hand1' : { 1448 'level' : 'INFO', 1449 }, 1450 }, 1451 'loggers' : { 1452 'compiler.parser' : { 1453 'level' : 'INFO', 1454 }, 1455 }, 1456 } 1457 1458 #As config1 but with a filter added 1459 config10 = { 1460 'version': 1, 1461 'formatters': { 1462 'form1' : { 1463 'format' : '%(levelname)s ++ %(message)s', 1464 }, 1465 }, 1466 'filters' : { 1467 'filt1' : { 1468 'name' : 'compiler.parser', 1469 }, 1470 }, 1471 'handlers' : { 1472 'hand1' : { 1473 'class' : 'logging.StreamHandler', 1474 'formatter' : 'form1', 1475 'level' : 'NOTSET', 1476 'stream' : 'ext://sys.stdout', 1477 'filters' : ['filt1'], 1478 }, 1479 }, 1480 'loggers' : { 1481 'compiler.parser' : { 1482 'level' : 'DEBUG', 1483 'filters' : ['filt1'], 1484 }, 1485 }, 1486 'root' : { 1487 'level' : 'WARNING', 1488 'handlers' : ['hand1'], 1489 }, 1490 } 1491 1492 #As config1 but using cfg:// references 1493 config11 = { 1494 'version': 1, 1495 'true_formatters': { 1496 'form1' : { 1497 'format' : '%(levelname)s ++ %(message)s', 1498 }, 1499 }, 1500 'handler_configs': { 1501 'hand1' : { 1502 'class' : 'logging.StreamHandler', 1503 'formatter' : 'form1', 1504 'level' : 'NOTSET', 1505 'stream' : 'ext://sys.stdout', 1506 }, 1507 }, 1508 'formatters' : 'cfg://true_formatters', 1509 'handlers' : { 1510 'hand1' : 'cfg://handler_configs[hand1]', 1511 }, 1512 'loggers' : { 1513 'compiler.parser' : { 1514 'level' : 'DEBUG', 1515 'handlers' : ['hand1'], 1516 }, 1517 }, 1518 'root' : { 1519 'level' : 'WARNING', 1520 }, 1521 } 1522 1523 #As config11 but missing the version key 1524 config12 = { 1525 'true_formatters': { 1526 'form1' : { 1527 'format' : '%(levelname)s ++ %(message)s', 1528 }, 1529 }, 1530 'handler_configs': { 1531 'hand1' : { 1532 'class' : 'logging.StreamHandler', 1533 'formatter' : 'form1', 1534 'level' : 'NOTSET', 1535 'stream' : 'ext://sys.stdout', 1536 }, 1537 }, 1538 'formatters' : 'cfg://true_formatters', 1539 'handlers' : { 1540 'hand1' : 'cfg://handler_configs[hand1]', 1541 }, 1542 'loggers' : { 1543 'compiler.parser' : { 1544 'level' : 'DEBUG', 1545 'handlers' : ['hand1'], 1546 }, 1547 }, 1548 'root' : { 1549 'level' : 'WARNING', 1550 }, 1551 } 1552 1553 #As config11 but using an unsupported version 1554 config13 = { 1555 'version': 2, 1556 'true_formatters': { 1557 'form1' : { 1558 'format' : '%(levelname)s ++ %(message)s', 1559 }, 1560 }, 1561 'handler_configs': { 1562 'hand1' : { 1563 'class' : 'logging.StreamHandler', 1564 'formatter' : 'form1', 1565 'level' : 'NOTSET', 1566 'stream' : 'ext://sys.stdout', 1567 }, 1568 }, 1569 'formatters' : 'cfg://true_formatters', 1570 'handlers' : { 1571 'hand1' : 'cfg://handler_configs[hand1]', 1572 }, 1573 'loggers' : { 1574 'compiler.parser' : { 1575 'level' : 'DEBUG', 1576 'handlers' : ['hand1'], 1577 }, 1578 }, 1579 'root' : { 1580 'level' : 'WARNING', 1581 }, 1582 } 1583 1584 def apply_config(self, conf): 1585 logging.config.dictConfig(conf) 1586 1587 def test_config0_ok(self): 1588 # A simple config which overrides the default settings. 1589 with captured_stdout() as output: 1590 self.apply_config(self.config0) 1591 logger = logging.getLogger() 1592 # Won't output anything 1593 logger.info(self.next_message()) 1594 # Outputs a message 1595 logger.error(self.next_message()) 1596 self.assert_log_lines([ 1597 ('ERROR', '2'), 1598 ], stream=output) 1599 # Original logger output is empty. 1600 self.assert_log_lines([]) 1601 1602 def test_config1_ok(self, config=config1): 1603 # A config defining a sub-parser as well. 1604 with captured_stdout() as output: 1605 self.apply_config(config) 1606 logger = logging.getLogger("compiler.parser") 1607 # Both will output a message 1608 logger.info(self.next_message()) 1609 logger.error(self.next_message()) 1610 self.assert_log_lines([ 1611 ('INFO', '1'), 1612 ('ERROR', '2'), 1613 ], stream=output) 1614 # Original logger output is empty. 1615 self.assert_log_lines([]) 1616 1617 def test_config2_failure(self): 1618 # A simple config which overrides the default settings. 1619 self.assertRaises(StandardError, self.apply_config, self.config2) 1620 1621 def test_config2a_failure(self): 1622 # A simple config which overrides the default settings. 1623 self.assertRaises(StandardError, self.apply_config, self.config2a) 1624 1625 def test_config2b_failure(self): 1626 # A simple config which overrides the default settings. 1627 self.assertRaises(StandardError, self.apply_config, self.config2b) 1628 1629 def test_config3_failure(self): 1630 # A simple config which overrides the default settings. 1631 self.assertRaises(StandardError, self.apply_config, self.config3) 1632 1633 def test_config4_ok(self): 1634 # A config specifying a custom formatter class. 1635 with captured_stdout() as output: 1636 self.apply_config(self.config4) 1637 #logger = logging.getLogger() 1638 try: 1639 raise RuntimeError() 1640 except RuntimeError: 1641 logging.exception("just testing") 1642 sys.stdout.seek(0) 1643 self.assertEqual(output.getvalue(), 1644 "ERROR:root:just testing\nGot a [RuntimeError]\n") 1645 # Original logger output is empty 1646 self.assert_log_lines([]) 1647 1648 def test_config4a_ok(self): 1649 # A config specifying a custom formatter class. 1650 with captured_stdout() as output: 1651 self.apply_config(self.config4a) 1652 #logger = logging.getLogger() 1653 try: 1654 raise RuntimeError() 1655 except RuntimeError: 1656 logging.exception("just testing") 1657 sys.stdout.seek(0) 1658 self.assertEqual(output.getvalue(), 1659 "ERROR:root:just testing\nGot a [RuntimeError]\n") 1660 # Original logger output is empty 1661 self.assert_log_lines([]) 1662 1663 def test_config5_ok(self): 1664 self.test_config1_ok(config=self.config5) 1665 1666 def test_config6_failure(self): 1667 self.assertRaises(StandardError, self.apply_config, self.config6) 1668 1669 def test_config7_ok(self): 1670 with captured_stdout() as output: 1671 self.apply_config(self.config1) 1672 logger = logging.getLogger("compiler.parser") 1673 # Both will output a message 1674 logger.info(self.next_message()) 1675 logger.error(self.next_message()) 1676 self.assert_log_lines([ 1677 ('INFO', '1'), 1678 ('ERROR', '2'), 1679 ], stream=output) 1680 # Original logger output is empty. 1681 self.assert_log_lines([]) 1682 with captured_stdout() as output: 1683 self.apply_config(self.config7) 1684 logger = logging.getLogger("compiler.parser") 1685 self.assertTrue(logger.disabled) 1686 logger = logging.getLogger("compiler.lexer") 1687 # Both will output a message 1688 logger.info(self.next_message()) 1689 logger.error(self.next_message()) 1690 self.assert_log_lines([ 1691 ('INFO', '3'), 1692 ('ERROR', '4'), 1693 ], stream=output) 1694 # Original logger output is empty. 1695 self.assert_log_lines([]) 1696 1697 #Same as test_config_7_ok but don't disable old loggers. 1698 def test_config_8_ok(self): 1699 with captured_stdout() as output: 1700 self.apply_config(self.config1) 1701 logger = logging.getLogger("compiler.parser") 1702 # Both will output a message 1703 logger.info(self.next_message()) 1704 logger.error(self.next_message()) 1705 self.assert_log_lines([ 1706 ('INFO', '1'), 1707 ('ERROR', '2'), 1708 ], stream=output) 1709 # Original logger output is empty. 1710 self.assert_log_lines([]) 1711 with captured_stdout() as output: 1712 self.apply_config(self.config8) 1713 logger = logging.getLogger("compiler.parser") 1714 self.assertFalse(logger.disabled) 1715 # Both will output a message 1716 logger.info(self.next_message()) 1717 logger.error(self.next_message()) 1718 logger = logging.getLogger("compiler.lexer") 1719 # Both will output a message 1720 logger.info(self.next_message()) 1721 logger.error(self.next_message()) 1722 self.assert_log_lines([ 1723 ('INFO', '3'), 1724 ('ERROR', '4'), 1725 ('INFO', '5'), 1726 ('ERROR', '6'), 1727 ], stream=output) 1728 # Original logger output is empty. 1729 self.assert_log_lines([]) 1730 1731 def test_config_9_ok(self): 1732 with captured_stdout() as output: 1733 self.apply_config(self.config9) 1734 logger = logging.getLogger("compiler.parser") 1735 #Nothing will be output since both handler and logger are set to WARNING 1736 logger.info(self.next_message()) 1737 self.assert_log_lines([], stream=output) 1738 self.apply_config(self.config9a) 1739 #Nothing will be output since both handler is still set to WARNING 1740 logger.info(self.next_message()) 1741 self.assert_log_lines([], stream=output) 1742 self.apply_config(self.config9b) 1743 #Message should now be output 1744 logger.info(self.next_message()) 1745 self.assert_log_lines([ 1746 ('INFO', '3'), 1747 ], stream=output) 1748 1749 def test_config_10_ok(self): 1750 with captured_stdout() as output: 1751 self.apply_config(self.config10) 1752 logger = logging.getLogger("compiler.parser") 1753 logger.warning(self.next_message()) 1754 logger = logging.getLogger('compiler') 1755 #Not output, because filtered 1756 logger.warning(self.next_message()) 1757 logger = logging.getLogger('compiler.lexer') 1758 #Not output, because filtered 1759 logger.warning(self.next_message()) 1760 logger = logging.getLogger("compiler.parser.codegen") 1761 #Output, as not filtered 1762 logger.error(self.next_message()) 1763 self.assert_log_lines([ 1764 ('WARNING', '1'), 1765 ('ERROR', '4'), 1766 ], stream=output) 1767 1768 def test_config11_ok(self): 1769 self.test_config1_ok(self.config11) 1770 1771 def test_config12_failure(self): 1772 self.assertRaises(StandardError, self.apply_config, self.config12) 1773 1774 def test_config13_failure(self): 1775 self.assertRaises(StandardError, self.apply_config, self.config13) 1776 1777 @unittest.skipUnless(threading, 'listen() needs threading to work') 1778 def setup_via_listener(self, text): 1779 # Ask for a randomly assigned port (by using port 0) 1780 t = logging.config.listen(0) 1781 t.start() 1782 t.ready.wait() 1783 # Now get the port allocated 1784 port = t.port 1785 t.ready.clear() 1786 try: 1787 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) 1788 sock.settimeout(2.0) 1789 sock.connect(('localhost', port)) 1790 1791 slen = struct.pack('>L', len(text)) 1792 s = slen + text 1793 sentsofar = 0 1794 left = len(s) 1795 while left > 0: 1796 sent = sock.send(s[sentsofar:]) 1797 sentsofar += sent 1798 left -= sent 1799 sock.close() 1800 finally: 1801 t.ready.wait(2.0) 1802 logging.config.stopListening() 1803 t.join(2.0) 1804 1805 def test_listen_config_10_ok(self): 1806 with captured_stdout() as output: 1807 self.setup_via_listener(json.dumps(self.config10)) 1808 logger = logging.getLogger("compiler.parser") 1809 logger.warning(self.next_message()) 1810 logger = logging.getLogger('compiler') 1811 #Not output, because filtered 1812 logger.warning(self.next_message()) 1813 logger = logging.getLogger('compiler.lexer') 1814 #Not output, because filtered 1815 logger.warning(self.next_message()) 1816 logger = logging.getLogger("compiler.parser.codegen") 1817 #Output, as not filtered 1818 logger.error(self.next_message()) 1819 self.assert_log_lines([ 1820 ('WARNING', '1'), 1821 ('ERROR', '4'), 1822 ], stream=output) 1823 1824 def test_listen_config_1_ok(self): 1825 with captured_stdout() as output: 1826 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1)) 1827 logger = logging.getLogger("compiler.parser") 1828 # Both will output a message 1829 logger.info(self.next_message()) 1830 logger.error(self.next_message()) 1831 self.assert_log_lines([ 1832 ('INFO', '1'), 1833 ('ERROR', '2'), 1834 ], stream=output) 1835 # Original logger output is empty. 1836 self.assert_log_lines([]) 1837 1838 1839 class ManagerTest(BaseTest): 1840 def test_manager_loggerclass(self): 1841 logged = [] 1842 1843 class MyLogger(logging.Logger): 1844 def _log(self, level, msg, args, exc_info=None, extra=None): 1845 logged.append(msg) 1846 1847 man = logging.Manager(None) 1848 self.assertRaises(TypeError, man.setLoggerClass, int) 1849 man.setLoggerClass(MyLogger) 1850 logger = man.getLogger('test') 1851 logger.warning('should appear in logged') 1852 logging.warning('should not appear in logged') 1853 1854 self.assertEqual(logged, ['should appear in logged']) 1855 1856 1857 class ChildLoggerTest(BaseTest): 1858 def test_child_loggers(self): 1859 r = logging.getLogger() 1860 l1 = logging.getLogger('abc') 1861 l2 = logging.getLogger('def.ghi') 1862 c1 = r.getChild('xyz') 1863 c2 = r.getChild('uvw.xyz') 1864 self.assertTrue(c1 is logging.getLogger('xyz')) 1865 self.assertTrue(c2 is logging.getLogger('uvw.xyz')) 1866 c1 = l1.getChild('def') 1867 c2 = c1.getChild('ghi') 1868 c3 = l1.getChild('def.ghi') 1869 self.assertTrue(c1 is logging.getLogger('abc.def')) 1870 self.assertTrue(c2 is logging.getLogger('abc.def.ghi')) 1871 self.assertTrue(c2 is c3) 1872 1873 1874 # Set the locale to the platform-dependent default. I have no idea 1875 # why the test does this, but in any case we save the current locale 1876 # first and restore it at the end. 1877 @run_with_locale('LC_ALL', '') 1878 def test_main(): 1879 run_unittest(BuiltinLevelsTest, BasicFilterTest, 1880 CustomLevelsAndFiltersTest, MemoryHandlerTest, 1881 ConfigFileTest, SocketHandlerTest, MemoryTest, 1882 EncodingTest, WarningsTest, ConfigDictTest, ManagerTest, 1883 ChildLoggerTest) 1884 1885 if __name__ == "__main__": 1886 test_main() 1887
