1 #!/usr/bin/env python 2 # 3 # Copyright 2001-2013 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-2013 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 random 35 import re 36 import select 37 import socket 38 from SocketServer import ThreadingTCPServer, StreamRequestHandler 39 import struct 40 import sys 41 import tempfile 42 from test.test_support import captured_stdout, run_with_locale, run_unittest 43 import textwrap 44 import time 45 import unittest 46 import warnings 47 import weakref 48 try: 49 import threading 50 except ImportError: 51 threading = None 52 53 class BaseTest(unittest.TestCase): 54 55 """Base class for logging tests.""" 56 57 log_format = "%(name)s -> %(levelname)s: %(message)s" 58 expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$" 59 message_num = 0 60 61 def setUp(self): 62 """Setup the default logging stream to an internal StringIO instance, 63 so that we can examine log output as we want.""" 64 logger_dict = logging.getLogger().manager.loggerDict 65 logging._acquireLock() 66 try: 67 self.saved_handlers = logging._handlers.copy() 68 self.saved_handler_list = logging._handlerList[:] 69 self.saved_loggers = logger_dict.copy() 70 self.saved_level_names = logging._levelNames.copy() 71 finally: 72 logging._releaseLock() 73 74 # Set two unused loggers: one non-ASCII and one Unicode. 75 # This is to test correct operation when sorting existing 76 # loggers in the configuration code. See issue 8201. 77 logging.getLogger("\xab\xd7\xbb") 78 logging.getLogger(u"\u013f\u00d6\u0047") 79 80 self.root_logger = logging.getLogger("") 81 self.original_logging_level = self.root_logger.getEffectiveLevel() 82 83 self.stream = cStringIO.StringIO() 84 self.root_logger.setLevel(logging.DEBUG) 85 self.root_hdlr = logging.StreamHandler(self.stream) 86 self.root_formatter = logging.Formatter(self.log_format) 87 self.root_hdlr.setFormatter(self.root_formatter) 88 self.root_logger.addHandler(self.root_hdlr) 89 90 def tearDown(self): 91 """Remove our logging stream, and restore the original logging 92 level.""" 93 self.stream.close() 94 self.root_logger.removeHandler(self.root_hdlr) 95 while self.root_logger.handlers: 96 h = self.root_logger.handlers[0] 97 self.root_logger.removeHandler(h) 98 h.close() 99 self.root_logger.setLevel(self.original_logging_level) 100 logging._acquireLock() 101 try: 102 logging._levelNames.clear() 103 logging._levelNames.update(self.saved_level_names) 104 logging._handlers.clear() 105 logging._handlers.update(self.saved_handlers) 106 logging._handlerList[:] = self.saved_handler_list 107 loggerDict = logging.getLogger().manager.loggerDict 108 loggerDict.clear() 109 loggerDict.update(self.saved_loggers) 110 finally: 111 logging._releaseLock() 112 113 def assert_log_lines(self, expected_values, stream=None): 114 """Match the collected log lines against the regular expression 115 self.expected_log_pat, and compare the extracted group values to 116 the expected_values list of tuples.""" 117 stream = stream or self.stream 118 pat = re.compile(self.expected_log_pat) 119 try: 120 stream.reset() 121 actual_lines = stream.readlines() 122 except AttributeError: 123 # StringIO.StringIO lacks a reset() method. 124 actual_lines = stream.getvalue().splitlines() 125 self.assertEqual(len(actual_lines), len(expected_values)) 126 for actual, expected in zip(actual_lines, expected_values): 127 match = pat.search(actual) 128 if not match: 129 self.fail("Log line does not match expected pattern:\n" + 130 actual) 131 self.assertEqual(tuple(match.groups()), expected) 132 s = stream.read() 133 if s: 134 self.fail("Remaining output at end of log stream:\n" + s) 135 136 def next_message(self): 137 """Generate a message consisting solely of an auto-incrementing 138 integer.""" 139 self.message_num += 1 140 return "%d" % self.message_num 141 142 143 class BuiltinLevelsTest(BaseTest): 144 """Test builtin levels and their inheritance.""" 145 146 def test_flat(self): 147 #Logging levels in a flat logger namespace. 148 m = self.next_message 149 150 ERR = logging.getLogger("ERR") 151 ERR.setLevel(logging.ERROR) 152 INF = logging.getLogger("INF") 153 INF.setLevel(logging.INFO) 154 DEB = logging.getLogger("DEB") 155 DEB.setLevel(logging.DEBUG) 156 157 # These should log. 158 ERR.log(logging.CRITICAL, m()) 159 ERR.error(m()) 160 161 INF.log(logging.CRITICAL, m()) 162 INF.error(m()) 163 INF.warn(m()) 164 INF.info(m()) 165 166 DEB.log(logging.CRITICAL, m()) 167 DEB.error(m()) 168 DEB.warn (m()) 169 DEB.info (m()) 170 DEB.debug(m()) 171 172 # These should not log. 173 ERR.warn(m()) 174 ERR.info(m()) 175 ERR.debug(m()) 176 177 INF.debug(m()) 178 179 self.assert_log_lines([ 180 ('ERR', 'CRITICAL', '1'), 181 ('ERR', 'ERROR', '2'), 182 ('INF', 'CRITICAL', '3'), 183 ('INF', 'ERROR', '4'), 184 ('INF', 'WARNING', '5'), 185 ('INF', 'INFO', '6'), 186 ('DEB', 'CRITICAL', '7'), 187 ('DEB', 'ERROR', '8'), 188 ('DEB', 'WARNING', '9'), 189 ('DEB', 'INFO', '10'), 190 ('DEB', 'DEBUG', '11'), 191 ]) 192 193 def test_nested_explicit(self): 194 # Logging levels in a nested namespace, all explicitly set. 195 m = self.next_message 196 197 INF = logging.getLogger("INF") 198 INF.setLevel(logging.INFO) 199 INF_ERR = logging.getLogger("INF.ERR") 200 INF_ERR.setLevel(logging.ERROR) 201 202 # These should log. 203 INF_ERR.log(logging.CRITICAL, m()) 204 INF_ERR.error(m()) 205 206 # These should not log. 207 INF_ERR.warn(m()) 208 INF_ERR.info(m()) 209 INF_ERR.debug(m()) 210 211 self.assert_log_lines([ 212 ('INF.ERR', 'CRITICAL', '1'), 213 ('INF.ERR', 'ERROR', '2'), 214 ]) 215 216 def test_nested_inherited(self): 217 #Logging levels in a nested namespace, inherited from parent loggers. 218 m = self.next_message 219 220 INF = logging.getLogger("INF") 221 INF.setLevel(logging.INFO) 222 INF_ERR = logging.getLogger("INF.ERR") 223 INF_ERR.setLevel(logging.ERROR) 224 INF_UNDEF = logging.getLogger("INF.UNDEF") 225 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF") 226 UNDEF = logging.getLogger("UNDEF") 227 228 # These should log. 229 INF_UNDEF.log(logging.CRITICAL, m()) 230 INF_UNDEF.error(m()) 231 INF_UNDEF.warn(m()) 232 INF_UNDEF.info(m()) 233 INF_ERR_UNDEF.log(logging.CRITICAL, m()) 234 INF_ERR_UNDEF.error(m()) 235 236 # These should not log. 237 INF_UNDEF.debug(m()) 238 INF_ERR_UNDEF.warn(m()) 239 INF_ERR_UNDEF.info(m()) 240 INF_ERR_UNDEF.debug(m()) 241 242 self.assert_log_lines([ 243 ('INF.UNDEF', 'CRITICAL', '1'), 244 ('INF.UNDEF', 'ERROR', '2'), 245 ('INF.UNDEF', 'WARNING', '3'), 246 ('INF.UNDEF', 'INFO', '4'), 247 ('INF.ERR.UNDEF', 'CRITICAL', '5'), 248 ('INF.ERR.UNDEF', 'ERROR', '6'), 249 ]) 250 251 def test_nested_with_virtual_parent(self): 252 # Logging levels when some parent does not exist yet. 253 m = self.next_message 254 255 INF = logging.getLogger("INF") 256 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF") 257 CHILD = logging.getLogger("INF.BADPARENT") 258 INF.setLevel(logging.INFO) 259 260 # These should log. 261 GRANDCHILD.log(logging.FATAL, m()) 262 GRANDCHILD.info(m()) 263 CHILD.log(logging.FATAL, m()) 264 CHILD.info(m()) 265 266 # These should not log. 267 GRANDCHILD.debug(m()) 268 CHILD.debug(m()) 269 270 self.assert_log_lines([ 271 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'), 272 ('INF.BADPARENT.UNDEF', 'INFO', '2'), 273 ('INF.BADPARENT', 'CRITICAL', '3'), 274 ('INF.BADPARENT', 'INFO', '4'), 275 ]) 276 277 def test_invalid_name(self): 278 self.assertRaises(TypeError, logging.getLogger, any) 279 280 class BasicFilterTest(BaseTest): 281 282 """Test the bundled Filter class.""" 283 284 def test_filter(self): 285 # Only messages satisfying the specified criteria pass through the 286 # filter. 287 filter_ = logging.Filter("spam.eggs") 288 handler = self.root_logger.handlers[0] 289 try: 290 handler.addFilter(filter_) 291 spam = logging.getLogger("spam") 292 spam_eggs = logging.getLogger("spam.eggs") 293 spam_eggs_fish = logging.getLogger("spam.eggs.fish") 294 spam_bakedbeans = logging.getLogger("spam.bakedbeans") 295 296 spam.info(self.next_message()) 297 spam_eggs.info(self.next_message()) # Good. 298 spam_eggs_fish.info(self.next_message()) # Good. 299 spam_bakedbeans.info(self.next_message()) 300 301 self.assert_log_lines([ 302 ('spam.eggs', 'INFO', '2'), 303 ('spam.eggs.fish', 'INFO', '3'), 304 ]) 305 finally: 306 handler.removeFilter(filter_) 307 308 309 # 310 # First, we define our levels. There can be as many as you want - the only 311 # limitations are that they should be integers, the lowest should be > 0 and 312 # larger values mean less information being logged. If you need specific 313 # level values which do not fit into these limitations, you can use a 314 # mapping dictionary to convert between your application levels and the 315 # logging system. 316 # 317 SILENT = 120 318 TACITURN = 119 319 TERSE = 118 320 EFFUSIVE = 117 321 SOCIABLE = 116 322 VERBOSE = 115 323 TALKATIVE = 114 324 GARRULOUS = 113 325 CHATTERBOX = 112 326 BORING = 111 327 328 LEVEL_RANGE = range(BORING, SILENT + 1) 329 330 # 331 # Next, we define names for our levels. You don't need to do this - in which 332 # case the system will use "Level n" to denote the text for the level. 333 # 334 my_logging_levels = { 335 SILENT : 'Silent', 336 TACITURN : 'Taciturn', 337 TERSE : 'Terse', 338 EFFUSIVE : 'Effusive', 339 SOCIABLE : 'Sociable', 340 VERBOSE : 'Verbose', 341 TALKATIVE : 'Talkative', 342 GARRULOUS : 'Garrulous', 343 CHATTERBOX : 'Chatterbox', 344 BORING : 'Boring', 345 } 346 347 class GarrulousFilter(logging.Filter): 348 349 """A filter which blocks garrulous messages.""" 350 351 def filter(self, record): 352 return record.levelno != GARRULOUS 353 354 class VerySpecificFilter(logging.Filter): 355 356 """A filter which blocks sociable and taciturn messages.""" 357 358 def filter(self, record): 359 return record.levelno not in [SOCIABLE, TACITURN] 360 361 362 class CustomLevelsAndFiltersTest(BaseTest): 363 364 """Test various filtering possibilities with custom logging levels.""" 365 366 # Skip the logger name group. 367 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$" 368 369 def setUp(self): 370 BaseTest.setUp(self) 371 for k, v in my_logging_levels.items(): 372 logging.addLevelName(k, v) 373 374 def log_at_all_levels(self, logger): 375 for lvl in LEVEL_RANGE: 376 logger.log(lvl, self.next_message()) 377 378 def test_logger_filter(self): 379 # Filter at logger level. 380 self.root_logger.setLevel(VERBOSE) 381 # Levels >= 'Verbose' are good. 382 self.log_at_all_levels(self.root_logger) 383 self.assert_log_lines([ 384 ('Verbose', '5'), 385 ('Sociable', '6'), 386 ('Effusive', '7'), 387 ('Terse', '8'), 388 ('Taciturn', '9'), 389 ('Silent', '10'), 390 ]) 391 392 def test_handler_filter(self): 393 # Filter at handler level. 394 self.root_logger.handlers[0].setLevel(SOCIABLE) 395 try: 396 # Levels >= 'Sociable' are good. 397 self.log_at_all_levels(self.root_logger) 398 self.assert_log_lines([ 399 ('Sociable', '6'), 400 ('Effusive', '7'), 401 ('Terse', '8'), 402 ('Taciturn', '9'), 403 ('Silent', '10'), 404 ]) 405 finally: 406 self.root_logger.handlers[0].setLevel(logging.NOTSET) 407 408 def test_specific_filters(self): 409 # Set a specific filter object on the handler, and then add another 410 # filter object on the logger itself. 411 handler = self.root_logger.handlers[0] 412 specific_filter = None 413 garr = GarrulousFilter() 414 handler.addFilter(garr) 415 try: 416 self.log_at_all_levels(self.root_logger) 417 first_lines = [ 418 # Notice how 'Garrulous' is missing 419 ('Boring', '1'), 420 ('Chatterbox', '2'), 421 ('Talkative', '4'), 422 ('Verbose', '5'), 423 ('Sociable', '6'), 424 ('Effusive', '7'), 425 ('Terse', '8'), 426 ('Taciturn', '9'), 427 ('Silent', '10'), 428 ] 429 self.assert_log_lines(first_lines) 430 431 specific_filter = VerySpecificFilter() 432 self.root_logger.addFilter(specific_filter) 433 self.log_at_all_levels(self.root_logger) 434 self.assert_log_lines(first_lines + [ 435 # Not only 'Garrulous' is still missing, but also 'Sociable' 436 # and 'Taciturn' 437 ('Boring', '11'), 438 ('Chatterbox', '12'), 439 ('Talkative', '14'), 440 ('Verbose', '15'), 441 ('Effusive', '17'), 442 ('Terse', '18'), 443 ('Silent', '20'), 444 ]) 445 finally: 446 if specific_filter: 447 self.root_logger.removeFilter(specific_filter) 448 handler.removeFilter(garr) 449 450 451 class MemoryHandlerTest(BaseTest): 452 453 """Tests for the MemoryHandler.""" 454 455 # Do not bother with a logger name group. 456 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$" 457 458 def setUp(self): 459 BaseTest.setUp(self) 460 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING, 461 self.root_hdlr) 462 self.mem_logger = logging.getLogger('mem') 463 self.mem_logger.propagate = 0 464 self.mem_logger.addHandler(self.mem_hdlr) 465 466 def tearDown(self): 467 self.mem_hdlr.close() 468 BaseTest.tearDown(self) 469 470 def test_flush(self): 471 # The memory handler flushes to its target handler based on specific 472 # criteria (message count and message level). 473 self.mem_logger.debug(self.next_message()) 474 self.assert_log_lines([]) 475 self.mem_logger.info(self.next_message()) 476 self.assert_log_lines([]) 477 # This will flush because the level is >= logging.WARNING 478 self.mem_logger.warn(self.next_message()) 479 lines = [ 480 ('DEBUG', '1'), 481 ('INFO', '2'), 482 ('WARNING', '3'), 483 ] 484 self.assert_log_lines(lines) 485 for n in (4, 14): 486 for i in range(9): 487 self.mem_logger.debug(self.next_message()) 488 self.assert_log_lines(lines) 489 # This will flush because it's the 10th message since the last 490 # flush. 491 self.mem_logger.debug(self.next_message()) 492 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)] 493 self.assert_log_lines(lines) 494 495 self.mem_logger.debug(self.next_message()) 496 self.assert_log_lines(lines) 497 498 499 class ExceptionFormatter(logging.Formatter): 500 """A special exception formatter.""" 501 def formatException(self, ei): 502 return "Got a [%s]" % ei[0].__name__ 503 504 505 class ConfigFileTest(BaseTest): 506 507 """Reading logging config from a .ini-style config file.""" 508 509 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$" 510 511 # config0 is a standard configuration. 512 config0 = """ 513 [loggers] 514 keys=root 515 516 [handlers] 517 keys=hand1 518 519 [formatters] 520 keys=form1 521 522 [logger_root] 523 level=WARNING 524 handlers=hand1 525 526 [handler_hand1] 527 class=StreamHandler 528 level=NOTSET 529 formatter=form1 530 args=(sys.stdout,) 531 532 [formatter_form1] 533 format=%(levelname)s ++ %(message)s 534 datefmt= 535 """ 536 537 # config1 adds a little to the standard configuration. 538 config1 = """ 539 [loggers] 540 keys=root,parser 541 542 [handlers] 543 keys=hand1 544 545 [formatters] 546 keys=form1 547 548 [logger_root] 549 level=WARNING 550 handlers= 551 552 [logger_parser] 553 level=DEBUG 554 handlers=hand1 555 propagate=1 556 qualname=compiler.parser 557 558 [handler_hand1] 559 class=StreamHandler 560 level=NOTSET 561 formatter=form1 562 args=(sys.stdout,) 563 564 [formatter_form1] 565 format=%(levelname)s ++ %(message)s 566 datefmt= 567 """ 568 569 # config1a moves the handler to the root. 570 config1a = """ 571 [loggers] 572 keys=root,parser 573 574 [handlers] 575 keys=hand1 576 577 [formatters] 578 keys=form1 579 580 [logger_root] 581 level=WARNING 582 handlers=hand1 583 584 [logger_parser] 585 level=DEBUG 586 handlers= 587 propagate=1 588 qualname=compiler.parser 589 590 [handler_hand1] 591 class=StreamHandler 592 level=NOTSET 593 formatter=form1 594 args=(sys.stdout,) 595 596 [formatter_form1] 597 format=%(levelname)s ++ %(message)s 598 datefmt= 599 """ 600 601 # config2 has a subtle configuration error that should be reported 602 config2 = config1.replace("sys.stdout", "sys.stbout") 603 604 # config3 has a less subtle configuration error 605 config3 = config1.replace("formatter=form1", "formatter=misspelled_name") 606 607 # config4 specifies a custom formatter class to be loaded 608 config4 = """ 609 [loggers] 610 keys=root 611 612 [handlers] 613 keys=hand1 614 615 [formatters] 616 keys=form1 617 618 [logger_root] 619 level=NOTSET 620 handlers=hand1 621 622 [handler_hand1] 623 class=StreamHandler 624 level=NOTSET 625 formatter=form1 626 args=(sys.stdout,) 627 628 [formatter_form1] 629 class=""" + __name__ + """.ExceptionFormatter 630 format=%(levelname)s:%(name)s:%(message)s 631 datefmt= 632 """ 633 634 # config5 specifies a custom handler class to be loaded 635 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler') 636 637 # config6 uses ', ' delimiters in the handlers and formatters sections 638 config6 = """ 639 [loggers] 640 keys=root,parser 641 642 [handlers] 643 keys=hand1, hand2 644 645 [formatters] 646 keys=form1, form2 647 648 [logger_root] 649 level=WARNING 650 handlers= 651 652 [logger_parser] 653 level=DEBUG 654 handlers=hand1 655 propagate=1 656 qualname=compiler.parser 657 658 [handler_hand1] 659 class=StreamHandler 660 level=NOTSET 661 formatter=form1 662 args=(sys.stdout,) 663 664 [handler_hand2] 665 class=StreamHandler 666 level=NOTSET 667 formatter=form1 668 args=(sys.stderr,) 669 670 [formatter_form1] 671 format=%(levelname)s ++ %(message)s 672 datefmt= 673 674 [formatter_form2] 675 format=%(message)s 676 datefmt= 677 """ 678 679 # config7 adds a compiler logger. 680 config7 = """ 681 [loggers] 682 keys=root,parser,compiler 683 684 [handlers] 685 keys=hand1 686 687 [formatters] 688 keys=form1 689 690 [logger_root] 691 level=WARNING 692 handlers=hand1 693 694 [logger_compiler] 695 level=DEBUG 696 handlers= 697 propagate=1 698 qualname=compiler 699 700 [logger_parser] 701 level=DEBUG 702 handlers= 703 propagate=1 704 qualname=compiler.parser 705 706 [handler_hand1] 707 class=StreamHandler 708 level=NOTSET 709 formatter=form1 710 args=(sys.stdout,) 711 712 [formatter_form1] 713 format=%(levelname)s ++ %(message)s 714 datefmt= 715 """ 716 717 disable_test = """ 718 [loggers] 719 keys=root 720 721 [handlers] 722 keys=screen 723 724 [formatters] 725 keys= 726 727 [logger_root] 728 level=DEBUG 729 handlers=screen 730 731 [handler_screen] 732 level=DEBUG 733 class=StreamHandler 734 args=(sys.stdout,) 735 formatter= 736 """ 737 738 def apply_config(self, conf, **kwargs): 739 file = cStringIO.StringIO(textwrap.dedent(conf)) 740 logging.config.fileConfig(file, **kwargs) 741 742 def test_config0_ok(self): 743 # A simple config file which overrides the default settings. 744 with captured_stdout() as output: 745 self.apply_config(self.config0) 746 logger = logging.getLogger() 747 # Won't output anything 748 logger.info(self.next_message()) 749 # Outputs a message 750 logger.error(self.next_message()) 751 self.assert_log_lines([ 752 ('ERROR', '2'), 753 ], stream=output) 754 # Original logger output is empty. 755 self.assert_log_lines([]) 756 757 def test_config1_ok(self, config=config1): 758 # A config file defining a sub-parser as well. 759 with captured_stdout() as output: 760 self.apply_config(config) 761 logger = logging.getLogger("compiler.parser") 762 # Both will output a message 763 logger.info(self.next_message()) 764 logger.error(self.next_message()) 765 self.assert_log_lines([ 766 ('INFO', '1'), 767 ('ERROR', '2'), 768 ], stream=output) 769 # Original logger output is empty. 770 self.assert_log_lines([]) 771 772 def test_config2_failure(self): 773 # A simple config file which overrides the default settings. 774 self.assertRaises(StandardError, self.apply_config, self.config2) 775 776 def test_config3_failure(self): 777 # A simple config file which overrides the default settings. 778 self.assertRaises(StandardError, self.apply_config, self.config3) 779 780 def test_config4_ok(self): 781 # A config file specifying a custom formatter class. 782 with captured_stdout() as output: 783 self.apply_config(self.config4) 784 logger = logging.getLogger() 785 try: 786 raise RuntimeError() 787 except RuntimeError: 788 logging.exception("just testing") 789 sys.stdout.seek(0) 790 self.assertEqual(output.getvalue(), 791 "ERROR:root:just testing\nGot a [RuntimeError]\n") 792 # Original logger output is empty 793 self.assert_log_lines([]) 794 795 def test_config5_ok(self): 796 self.test_config1_ok(config=self.config5) 797 798 def test_config6_ok(self): 799 self.test_config1_ok(config=self.config6) 800 801 def test_config7_ok(self): 802 with captured_stdout() as output: 803 self.apply_config(self.config1a) 804 logger = logging.getLogger("compiler.parser") 805 # See issue #11424. compiler-hyphenated sorts 806 # between compiler and compiler.xyz and this 807 # was preventing compiler.xyz from being included 808 # in the child loggers of compiler because of an 809 # overzealous loop termination condition. 810 hyphenated = logging.getLogger('compiler-hyphenated') 811 # All will output a message 812 logger.info(self.next_message()) 813 logger.error(self.next_message()) 814 hyphenated.critical(self.next_message()) 815 self.assert_log_lines([ 816 ('INFO', '1'), 817 ('ERROR', '2'), 818 ('CRITICAL', '3'), 819 ], stream=output) 820 # Original logger output is empty. 821 self.assert_log_lines([]) 822 with captured_stdout() as output: 823 self.apply_config(self.config7) 824 logger = logging.getLogger("compiler.parser") 825 self.assertFalse(logger.disabled) 826 # Both will output a message 827 logger.info(self.next_message()) 828 logger.error(self.next_message()) 829 logger = logging.getLogger("compiler.lexer") 830 # Both will output a message 831 logger.info(self.next_message()) 832 logger.error(self.next_message()) 833 # Will not appear 834 hyphenated.critical(self.next_message()) 835 self.assert_log_lines([ 836 ('INFO', '4'), 837 ('ERROR', '5'), 838 ('INFO', '6'), 839 ('ERROR', '7'), 840 ], stream=output) 841 # Original logger output is empty. 842 self.assert_log_lines([]) 843 844 def test_logger_disabling(self): 845 self.apply_config(self.disable_test) 846 logger = logging.getLogger('foo') 847 self.assertFalse(logger.disabled) 848 self.apply_config(self.disable_test) 849 self.assertTrue(logger.disabled) 850 self.apply_config(self.disable_test, disable_existing_loggers=False) 851 self.assertFalse(logger.disabled) 852 853 class LogRecordStreamHandler(StreamRequestHandler): 854 855 """Handler for a streaming logging request. It saves the log message in the 856 TCP server's 'log_output' attribute.""" 857 858 TCP_LOG_END = "!!!END!!!" 859 860 def handle(self): 861 """Handle multiple requests - each expected to be of 4-byte length, 862 followed by the LogRecord in pickle format. Logs the record 863 according to whatever policy is configured locally.""" 864 while True: 865 chunk = self.connection.recv(4) 866 if len(chunk) < 4: 867 break 868 slen = struct.unpack(">L", chunk)[0] 869 chunk = self.connection.recv(slen) 870 while len(chunk) < slen: 871 chunk = chunk + self.connection.recv(slen - len(chunk)) 872 obj = self.unpickle(chunk) 873 record = logging.makeLogRecord(obj) 874 self.handle_log_record(record) 875 876 def unpickle(self, data): 877 return cPickle.loads(data) 878 879 def handle_log_record(self, record): 880 # If the end-of-messages sentinel is seen, tell the server to 881 # terminate. 882 if self.TCP_LOG_END in record.msg: 883 self.server.abort = 1 884 return 885 self.server.log_output += record.msg + "\n" 886 887 888 class LogRecordSocketReceiver(ThreadingTCPServer): 889 890 """A simple-minded TCP socket-based logging receiver suitable for test 891 purposes.""" 892 893 allow_reuse_address = 1 894 log_output = "" 895 896 def __init__(self, host='localhost', 897 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT, 898 handler=LogRecordStreamHandler): 899 ThreadingTCPServer.__init__(self, (host, port), handler) 900 self.abort = False 901 self.timeout = 0.1 902 self.finished = threading.Event() 903 904 def serve_until_stopped(self): 905 while not self.abort: 906 rd, wr, ex = select.select([self.socket.fileno()], [], [], 907 self.timeout) 908 if rd: 909 self.handle_request() 910 # Notify the main thread that we're about to exit 911 self.finished.set() 912 # close the listen socket 913 self.server_close() 914 915 916 @unittest.skipUnless(threading, 'Threading required for this test.') 917 class SocketHandlerTest(BaseTest): 918 919 """Test for SocketHandler objects.""" 920 921 def setUp(self): 922 """Set up a TCP server to receive log messages, and a SocketHandler 923 pointing to that server's address and port.""" 924 BaseTest.setUp(self) 925 self.tcpserver = LogRecordSocketReceiver(port=0) 926 self.port = self.tcpserver.socket.getsockname()[1] 927 self.threads = [ 928 threading.Thread(target=self.tcpserver.serve_until_stopped)] 929 for thread in self.threads: 930 thread.start() 931 932 self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port) 933 self.sock_hdlr.setFormatter(self.root_formatter) 934 self.root_logger.removeHandler(self.root_logger.handlers[0]) 935 self.root_logger.addHandler(self.sock_hdlr) 936 937 def tearDown(self): 938 """Shutdown the TCP server.""" 939 try: 940 self.tcpserver.abort = True 941 del self.tcpserver 942 self.root_logger.removeHandler(self.sock_hdlr) 943 self.sock_hdlr.close() 944 for thread in self.threads: 945 thread.join(2.0) 946 finally: 947 BaseTest.tearDown(self) 948 949 def get_output(self): 950 """Get the log output as received by the TCP server.""" 951 # Signal the TCP receiver and wait for it to terminate. 952 self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END) 953 self.tcpserver.finished.wait(2.0) 954 return self.tcpserver.log_output 955 956 def test_output(self): 957 # The log message sent to the SocketHandler is properly received. 958 logger = logging.getLogger("tcp") 959 logger.error("spam") 960 logger.debug("eggs") 961 self.assertEqual(self.get_output(), "spam\neggs\n") 962 963 964 class MemoryTest(BaseTest): 965 966 """Test memory persistence of logger objects.""" 967 968 def setUp(self): 969 """Create a dict to remember potentially destroyed objects.""" 970 BaseTest.setUp(self) 971 self._survivors = {} 972 973 def _watch_for_survival(self, *args): 974 """Watch the given objects for survival, by creating weakrefs to 975 them.""" 976 for obj in args: 977 key = id(obj), repr(obj) 978 self._survivors[key] = weakref.ref(obj) 979 980 def _assertTruesurvival(self): 981 """Assert that all objects watched for survival have survived.""" 982 # Trigger cycle breaking. 983 gc.collect() 984 dead = [] 985 for (id_, repr_), ref in self._survivors.items(): 986 if ref() is None: 987 dead.append(repr_) 988 if dead: 989 self.fail("%d objects should have survived " 990 "but have been destroyed: %s" % (len(dead), ", ".join(dead))) 991 992 def test_persistent_loggers(self): 993 # Logger objects are persistent and retain their configuration, even 994 # if visible references are destroyed. 995 self.root_logger.setLevel(logging.INFO) 996 foo = logging.getLogger("foo") 997 self._watch_for_survival(foo) 998 foo.setLevel(logging.DEBUG) 999 self.root_logger.debug(self.next_message()) 1000 foo.debug(self.next_message()) 1001 self.assert_log_lines([ 1002 ('foo', 'DEBUG', '2'), 1003 ]) 1004 del foo 1005 # foo has survived. 1006 self._assertTruesurvival() 1007 # foo has retained its settings. 1008 bar = logging.getLogger("foo") 1009 bar.debug(self.next_message()) 1010 self.assert_log_lines([ 1011 ('foo', 'DEBUG', '2'), 1012 ('foo', 'DEBUG', '3'), 1013 ]) 1014 1015 1016 class EncodingTest(BaseTest): 1017 def test_encoding_plain_file(self): 1018 # In Python 2.x, a plain file object is treated as having no encoding. 1019 log = logging.getLogger("test") 1020 fn = tempfile.mktemp(".log") 1021 # the non-ascii data we write to the log. 1022 data = "foo\x80" 1023 try: 1024 handler = logging.FileHandler(fn) 1025 log.addHandler(handler) 1026 try: 1027 # write non-ascii data to the log. 1028 log.warning(data) 1029 finally: 1030 log.removeHandler(handler) 1031 handler.close() 1032 # check we wrote exactly those bytes, ignoring trailing \n etc 1033 f = open(fn) 1034 try: 1035 self.assertEqual(f.read().rstrip(), data) 1036 finally: 1037 f.close() 1038 finally: 1039 if os.path.isfile(fn): 1040 os.remove(fn) 1041 1042 def test_encoding_cyrillic_unicode(self): 1043 log = logging.getLogger("test") 1044 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye) 1045 message = u'\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f' 1046 #Ensure it's written in a Cyrillic encoding 1047 writer_class = codecs.getwriter('cp1251') 1048 writer_class.encoding = 'cp1251' 1049 stream = cStringIO.StringIO() 1050 writer = writer_class(stream, 'strict') 1051 handler = logging.StreamHandler(writer) 1052 log.addHandler(handler) 1053 try: 1054 log.warning(message) 1055 finally: 1056 log.removeHandler(handler) 1057 handler.close() 1058 # check we wrote exactly those bytes, ignoring trailing \n etc 1059 s = stream.getvalue() 1060 #Compare against what the data should be when encoded in CP-1251 1061 self.assertEqual(s, '\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n') 1062 1063 1064 class WarningsTest(BaseTest): 1065 1066 def test_warnings(self): 1067 with warnings.catch_warnings(): 1068 logging.captureWarnings(True) 1069 try: 1070 warnings.filterwarnings("always", category=UserWarning) 1071 file = cStringIO.StringIO() 1072 h = logging.StreamHandler(file) 1073 logger = logging.getLogger("py.warnings") 1074 logger.addHandler(h) 1075 warnings.warn("I'm warning you...") 1076 logger.removeHandler(h) 1077 s = file.getvalue() 1078 h.close() 1079 self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0) 1080 1081 #See if an explicit file uses the original implementation 1082 file = cStringIO.StringIO() 1083 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42, 1084 file, "Dummy line") 1085 s = file.getvalue() 1086 file.close() 1087 self.assertEqual(s, 1088 "dummy.py:42: UserWarning: Explicit\n Dummy line\n") 1089 finally: 1090 logging.captureWarnings(False) 1091 1092 1093 def formatFunc(format, datefmt=None): 1094 return logging.Formatter(format, datefmt) 1095 1096 def handlerFunc(): 1097 return logging.StreamHandler() 1098 1099 class CustomHandler(logging.StreamHandler): 1100 pass 1101 1102 class ConfigDictTest(BaseTest): 1103 1104 """Reading logging config from a dictionary.""" 1105 1106 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$" 1107 1108 # config0 is a standard configuration. 1109 config0 = { 1110 'version': 1, 1111 'formatters': { 1112 'form1' : { 1113 'format' : '%(levelname)s ++ %(message)s', 1114 }, 1115 }, 1116 'handlers' : { 1117 'hand1' : { 1118 'class' : 'logging.StreamHandler', 1119 'formatter' : 'form1', 1120 'level' : 'NOTSET', 1121 'stream' : 'ext://sys.stdout', 1122 }, 1123 }, 1124 'root' : { 1125 'level' : 'WARNING', 1126 'handlers' : ['hand1'], 1127 }, 1128 } 1129 1130 # config1 adds a little to the standard configuration. 1131 config1 = { 1132 'version': 1, 1133 'formatters': { 1134 'form1' : { 1135 'format' : '%(levelname)s ++ %(message)s', 1136 }, 1137 }, 1138 'handlers' : { 1139 'hand1' : { 1140 'class' : 'logging.StreamHandler', 1141 'formatter' : 'form1', 1142 'level' : 'NOTSET', 1143 'stream' : 'ext://sys.stdout', 1144 }, 1145 }, 1146 'loggers' : { 1147 'compiler.parser' : { 1148 'level' : 'DEBUG', 1149 'handlers' : ['hand1'], 1150 }, 1151 }, 1152 'root' : { 1153 'level' : 'WARNING', 1154 }, 1155 } 1156 1157 # config2 has a subtle configuration error that should be reported 1158 config2 = { 1159 'version': 1, 1160 'formatters': { 1161 'form1' : { 1162 'format' : '%(levelname)s ++ %(message)s', 1163 }, 1164 }, 1165 'handlers' : { 1166 'hand1' : { 1167 'class' : 'logging.StreamHandler', 1168 'formatter' : 'form1', 1169 'level' : 'NOTSET', 1170 'stream' : 'ext://sys.stdbout', 1171 }, 1172 }, 1173 'loggers' : { 1174 'compiler.parser' : { 1175 'level' : 'DEBUG', 1176 'handlers' : ['hand1'], 1177 }, 1178 }, 1179 'root' : { 1180 'level' : 'WARNING', 1181 }, 1182 } 1183 1184 #As config1 but with a misspelt level on a handler 1185 config2a = { 1186 'version': 1, 1187 'formatters': { 1188 'form1' : { 1189 'format' : '%(levelname)s ++ %(message)s', 1190 }, 1191 }, 1192 'handlers' : { 1193 'hand1' : { 1194 'class' : 'logging.StreamHandler', 1195 'formatter' : 'form1', 1196 'level' : 'NTOSET', 1197 'stream' : 'ext://sys.stdout', 1198 }, 1199 }, 1200 'loggers' : { 1201 'compiler.parser' : { 1202 'level' : 'DEBUG', 1203 'handlers' : ['hand1'], 1204 }, 1205 }, 1206 'root' : { 1207 'level' : 'WARNING', 1208 }, 1209 } 1210 1211 1212 #As config1 but with a misspelt level on a logger 1213 config2b = { 1214 'version': 1, 1215 'formatters': { 1216 'form1' : { 1217 'format' : '%(levelname)s ++ %(message)s', 1218 }, 1219 }, 1220 'handlers' : { 1221 'hand1' : { 1222 'class' : 'logging.StreamHandler', 1223 'formatter' : 'form1', 1224 'level' : 'NOTSET', 1225 'stream' : 'ext://sys.stdout', 1226 }, 1227 }, 1228 'loggers' : { 1229 'compiler.parser' : { 1230 'level' : 'DEBUG', 1231 'handlers' : ['hand1'], 1232 }, 1233 }, 1234 'root' : { 1235 'level' : 'WRANING', 1236 }, 1237 } 1238 1239 # config3 has a less subtle configuration error 1240 config3 = { 1241 'version': 1, 1242 'formatters': { 1243 'form1' : { 1244 'format' : '%(levelname)s ++ %(message)s', 1245 }, 1246 }, 1247 'handlers' : { 1248 'hand1' : { 1249 'class' : 'logging.StreamHandler', 1250 'formatter' : 'misspelled_name', 1251 'level' : 'NOTSET', 1252 'stream' : 'ext://sys.stdout', 1253 }, 1254 }, 1255 'loggers' : { 1256 'compiler.parser' : { 1257 'level' : 'DEBUG', 1258 'handlers' : ['hand1'], 1259 }, 1260 }, 1261 'root' : { 1262 'level' : 'WARNING', 1263 }, 1264 } 1265 1266 # config4 specifies a custom formatter class to be loaded 1267 config4 = { 1268 'version': 1, 1269 'formatters': { 1270 'form1' : { 1271 '()' : __name__ + '.ExceptionFormatter', 1272 'format' : '%(levelname)s:%(name)s:%(message)s', 1273 }, 1274 }, 1275 'handlers' : { 1276 'hand1' : { 1277 'class' : 'logging.StreamHandler', 1278 'formatter' : 'form1', 1279 'level' : 'NOTSET', 1280 'stream' : 'ext://sys.stdout', 1281 }, 1282 }, 1283 'root' : { 1284 'level' : 'NOTSET', 1285 'handlers' : ['hand1'], 1286 }, 1287 } 1288 1289 # As config4 but using an actual callable rather than a string 1290 config4a = { 1291 'version': 1, 1292 'formatters': { 1293 'form1' : { 1294 '()' : ExceptionFormatter, 1295 'format' : '%(levelname)s:%(name)s:%(message)s', 1296 }, 1297 'form2' : { 1298 '()' : __name__ + '.formatFunc', 1299 'format' : '%(levelname)s:%(name)s:%(message)s', 1300 }, 1301 'form3' : { 1302 '()' : formatFunc, 1303 'format' : '%(levelname)s:%(name)s:%(message)s', 1304 }, 1305 }, 1306 'handlers' : { 1307 'hand1' : { 1308 'class' : 'logging.StreamHandler', 1309 'formatter' : 'form1', 1310 'level' : 'NOTSET', 1311 'stream' : 'ext://sys.stdout', 1312 }, 1313 'hand2' : { 1314 '()' : handlerFunc, 1315 }, 1316 }, 1317 'root' : { 1318 'level' : 'NOTSET', 1319 'handlers' : ['hand1'], 1320 }, 1321 } 1322 1323 # config5 specifies a custom handler class to be loaded 1324 config5 = { 1325 'version': 1, 1326 'formatters': { 1327 'form1' : { 1328 'format' : '%(levelname)s ++ %(message)s', 1329 }, 1330 }, 1331 'handlers' : { 1332 'hand1' : { 1333 'class' : __name__ + '.CustomHandler', 1334 'formatter' : 'form1', 1335 'level' : 'NOTSET', 1336 'stream' : 'ext://sys.stdout', 1337 }, 1338 }, 1339 'loggers' : { 1340 'compiler.parser' : { 1341 'level' : 'DEBUG', 1342 'handlers' : ['hand1'], 1343 }, 1344 }, 1345 'root' : { 1346 'level' : 'WARNING', 1347 }, 1348 } 1349 1350 # config6 specifies a custom handler class to be loaded 1351 # but has bad arguments 1352 config6 = { 1353 'version': 1, 1354 'formatters': { 1355 'form1' : { 1356 'format' : '%(levelname)s ++ %(message)s', 1357 }, 1358 }, 1359 'handlers' : { 1360 'hand1' : { 1361 'class' : __name__ + '.CustomHandler', 1362 'formatter' : 'form1', 1363 'level' : 'NOTSET', 1364 'stream' : 'ext://sys.stdout', 1365 '9' : 'invalid parameter name', 1366 }, 1367 }, 1368 'loggers' : { 1369 'compiler.parser' : { 1370 'level' : 'DEBUG', 1371 'handlers' : ['hand1'], 1372 }, 1373 }, 1374 'root' : { 1375 'level' : 'WARNING', 1376 }, 1377 } 1378 1379 #config 7 does not define compiler.parser but defines compiler.lexer 1380 #so compiler.parser should be disabled after applying it 1381 config7 = { 1382 'version': 1, 1383 'formatters': { 1384 'form1' : { 1385 'format' : '%(levelname)s ++ %(message)s', 1386 }, 1387 }, 1388 'handlers' : { 1389 'hand1' : { 1390 'class' : 'logging.StreamHandler', 1391 'formatter' : 'form1', 1392 'level' : 'NOTSET', 1393 'stream' : 'ext://sys.stdout', 1394 }, 1395 }, 1396 'loggers' : { 1397 'compiler.lexer' : { 1398 'level' : 'DEBUG', 1399 'handlers' : ['hand1'], 1400 }, 1401 }, 1402 'root' : { 1403 'level' : 'WARNING', 1404 }, 1405 } 1406 1407 config8 = { 1408 'version': 1, 1409 'disable_existing_loggers' : False, 1410 'formatters': { 1411 'form1' : { 1412 'format' : '%(levelname)s ++ %(message)s', 1413 }, 1414 }, 1415 'handlers' : { 1416 'hand1' : { 1417 'class' : 'logging.StreamHandler', 1418 'formatter' : 'form1', 1419 'level' : 'NOTSET', 1420 'stream' : 'ext://sys.stdout', 1421 }, 1422 }, 1423 'loggers' : { 1424 'compiler' : { 1425 'level' : 'DEBUG', 1426 'handlers' : ['hand1'], 1427 }, 1428 'compiler.lexer' : { 1429 }, 1430 }, 1431 'root' : { 1432 'level' : 'WARNING', 1433 }, 1434 } 1435 1436 config9 = { 1437 'version': 1, 1438 'formatters': { 1439 'form1' : { 1440 'format' : '%(levelname)s ++ %(message)s', 1441 }, 1442 }, 1443 'handlers' : { 1444 'hand1' : { 1445 'class' : 'logging.StreamHandler', 1446 'formatter' : 'form1', 1447 'level' : 'WARNING', 1448 'stream' : 'ext://sys.stdout', 1449 }, 1450 }, 1451 'loggers' : { 1452 'compiler.parser' : { 1453 'level' : 'WARNING', 1454 'handlers' : ['hand1'], 1455 }, 1456 }, 1457 'root' : { 1458 'level' : 'NOTSET', 1459 }, 1460 } 1461 1462 config9a = { 1463 'version': 1, 1464 'incremental' : True, 1465 'handlers' : { 1466 'hand1' : { 1467 'level' : 'WARNING', 1468 }, 1469 }, 1470 'loggers' : { 1471 'compiler.parser' : { 1472 'level' : 'INFO', 1473 }, 1474 }, 1475 } 1476 1477 config9b = { 1478 'version': 1, 1479 'incremental' : True, 1480 'handlers' : { 1481 'hand1' : { 1482 'level' : 'INFO', 1483 }, 1484 }, 1485 'loggers' : { 1486 'compiler.parser' : { 1487 'level' : 'INFO', 1488 }, 1489 }, 1490 } 1491 1492 #As config1 but with a filter added 1493 config10 = { 1494 'version': 1, 1495 'formatters': { 1496 'form1' : { 1497 'format' : '%(levelname)s ++ %(message)s', 1498 }, 1499 }, 1500 'filters' : { 1501 'filt1' : { 1502 'name' : 'compiler.parser', 1503 }, 1504 }, 1505 'handlers' : { 1506 'hand1' : { 1507 'class' : 'logging.StreamHandler', 1508 'formatter' : 'form1', 1509 'level' : 'NOTSET', 1510 'stream' : 'ext://sys.stdout', 1511 'filters' : ['filt1'], 1512 }, 1513 }, 1514 'loggers' : { 1515 'compiler.parser' : { 1516 'level' : 'DEBUG', 1517 'filters' : ['filt1'], 1518 }, 1519 }, 1520 'root' : { 1521 'level' : 'WARNING', 1522 'handlers' : ['hand1'], 1523 }, 1524 } 1525 1526 #As config1 but using cfg:// references 1527 config11 = { 1528 'version': 1, 1529 'true_formatters': { 1530 'form1' : { 1531 'format' : '%(levelname)s ++ %(message)s', 1532 }, 1533 }, 1534 'handler_configs': { 1535 'hand1' : { 1536 'class' : 'logging.StreamHandler', 1537 'formatter' : 'form1', 1538 'level' : 'NOTSET', 1539 'stream' : 'ext://sys.stdout', 1540 }, 1541 }, 1542 'formatters' : 'cfg://true_formatters', 1543 'handlers' : { 1544 'hand1' : 'cfg://handler_configs[hand1]', 1545 }, 1546 'loggers' : { 1547 'compiler.parser' : { 1548 'level' : 'DEBUG', 1549 'handlers' : ['hand1'], 1550 }, 1551 }, 1552 'root' : { 1553 'level' : 'WARNING', 1554 }, 1555 } 1556 1557 #As config11 but missing the version key 1558 config12 = { 1559 'true_formatters': { 1560 'form1' : { 1561 'format' : '%(levelname)s ++ %(message)s', 1562 }, 1563 }, 1564 'handler_configs': { 1565 'hand1' : { 1566 'class' : 'logging.StreamHandler', 1567 'formatter' : 'form1', 1568 'level' : 'NOTSET', 1569 'stream' : 'ext://sys.stdout', 1570 }, 1571 }, 1572 'formatters' : 'cfg://true_formatters', 1573 'handlers' : { 1574 'hand1' : 'cfg://handler_configs[hand1]', 1575 }, 1576 'loggers' : { 1577 'compiler.parser' : { 1578 'level' : 'DEBUG', 1579 'handlers' : ['hand1'], 1580 }, 1581 }, 1582 'root' : { 1583 'level' : 'WARNING', 1584 }, 1585 } 1586 1587 #As config11 but using an unsupported version 1588 config13 = { 1589 'version': 2, 1590 'true_formatters': { 1591 'form1' : { 1592 'format' : '%(levelname)s ++ %(message)s', 1593 }, 1594 }, 1595 'handler_configs': { 1596 'hand1' : { 1597 'class' : 'logging.StreamHandler', 1598 'formatter' : 'form1', 1599 'level' : 'NOTSET', 1600 'stream' : 'ext://sys.stdout', 1601 }, 1602 }, 1603 'formatters' : 'cfg://true_formatters', 1604 'handlers' : { 1605 'hand1' : 'cfg://handler_configs[hand1]', 1606 }, 1607 'loggers' : { 1608 'compiler.parser' : { 1609 'level' : 'DEBUG', 1610 'handlers' : ['hand1'], 1611 }, 1612 }, 1613 'root' : { 1614 'level' : 'WARNING', 1615 }, 1616 } 1617 1618 out_of_order = { 1619 "version": 1, 1620 "formatters": { 1621 "mySimpleFormatter": { 1622 "format": "%(asctime)s (%(name)s) %(levelname)s: %(message)s" 1623 } 1624 }, 1625 "handlers": { 1626 "fileGlobal": { 1627 "class": "logging.StreamHandler", 1628 "level": "DEBUG", 1629 "formatter": "mySimpleFormatter" 1630 }, 1631 "bufferGlobal": { 1632 "class": "logging.handlers.MemoryHandler", 1633 "capacity": 5, 1634 "formatter": "mySimpleFormatter", 1635 "target": "fileGlobal", 1636 "level": "DEBUG" 1637 } 1638 }, 1639 "loggers": { 1640 "mymodule": { 1641 "level": "DEBUG", 1642 "handlers": ["bufferGlobal"], 1643 "propagate": "true" 1644 } 1645 } 1646 } 1647 1648 def apply_config(self, conf): 1649 logging.config.dictConfig(conf) 1650 1651 def test_config0_ok(self): 1652 # A simple config which overrides the default settings. 1653 with captured_stdout() as output: 1654 self.apply_config(self.config0) 1655 logger = logging.getLogger() 1656 # Won't output anything 1657 logger.info(self.next_message()) 1658 # Outputs a message 1659 logger.error(self.next_message()) 1660 self.assert_log_lines([ 1661 ('ERROR', '2'), 1662 ], stream=output) 1663 # Original logger output is empty. 1664 self.assert_log_lines([]) 1665 1666 def test_config1_ok(self, config=config1): 1667 # A config defining a sub-parser as well. 1668 with captured_stdout() as output: 1669 self.apply_config(config) 1670 logger = logging.getLogger("compiler.parser") 1671 # Both will output a message 1672 logger.info(self.next_message()) 1673 logger.error(self.next_message()) 1674 self.assert_log_lines([ 1675 ('INFO', '1'), 1676 ('ERROR', '2'), 1677 ], stream=output) 1678 # Original logger output is empty. 1679 self.assert_log_lines([]) 1680 1681 def test_config2_failure(self): 1682 # A simple config which overrides the default settings. 1683 self.assertRaises(StandardError, self.apply_config, self.config2) 1684 1685 def test_config2a_failure(self): 1686 # A simple config which overrides the default settings. 1687 self.assertRaises(StandardError, self.apply_config, self.config2a) 1688 1689 def test_config2b_failure(self): 1690 # A simple config which overrides the default settings. 1691 self.assertRaises(StandardError, self.apply_config, self.config2b) 1692 1693 def test_config3_failure(self): 1694 # A simple config which overrides the default settings. 1695 self.assertRaises(StandardError, self.apply_config, self.config3) 1696 1697 def test_config4_ok(self): 1698 # A config specifying a custom formatter class. 1699 with captured_stdout() as output: 1700 self.apply_config(self.config4) 1701 #logger = logging.getLogger() 1702 try: 1703 raise RuntimeError() 1704 except RuntimeError: 1705 logging.exception("just testing") 1706 sys.stdout.seek(0) 1707 self.assertEqual(output.getvalue(), 1708 "ERROR:root:just testing\nGot a [RuntimeError]\n") 1709 # Original logger output is empty 1710 self.assert_log_lines([]) 1711 1712 def test_config4a_ok(self): 1713 # A config specifying a custom formatter class. 1714 with captured_stdout() as output: 1715 self.apply_config(self.config4a) 1716 #logger = logging.getLogger() 1717 try: 1718 raise RuntimeError() 1719 except RuntimeError: 1720 logging.exception("just testing") 1721 sys.stdout.seek(0) 1722 self.assertEqual(output.getvalue(), 1723 "ERROR:root:just testing\nGot a [RuntimeError]\n") 1724 # Original logger output is empty 1725 self.assert_log_lines([]) 1726 1727 def test_config5_ok(self): 1728 self.test_config1_ok(config=self.config5) 1729 1730 def test_config6_failure(self): 1731 self.assertRaises(StandardError, self.apply_config, self.config6) 1732 1733 def test_config7_ok(self): 1734 with captured_stdout() as output: 1735 self.apply_config(self.config1) 1736 logger = logging.getLogger("compiler.parser") 1737 # Both will output a message 1738 logger.info(self.next_message()) 1739 logger.error(self.next_message()) 1740 self.assert_log_lines([ 1741 ('INFO', '1'), 1742 ('ERROR', '2'), 1743 ], stream=output) 1744 # Original logger output is empty. 1745 self.assert_log_lines([]) 1746 with captured_stdout() as output: 1747 self.apply_config(self.config7) 1748 logger = logging.getLogger("compiler.parser") 1749 self.assertTrue(logger.disabled) 1750 logger = logging.getLogger("compiler.lexer") 1751 # Both will output a message 1752 logger.info(self.next_message()) 1753 logger.error(self.next_message()) 1754 self.assert_log_lines([ 1755 ('INFO', '3'), 1756 ('ERROR', '4'), 1757 ], stream=output) 1758 # Original logger output is empty. 1759 self.assert_log_lines([]) 1760 1761 #Same as test_config_7_ok but don't disable old loggers. 1762 def test_config_8_ok(self): 1763 with captured_stdout() as output: 1764 self.apply_config(self.config1) 1765 logger = logging.getLogger("compiler.parser") 1766 # Both will output a message 1767 logger.info(self.next_message()) 1768 logger.error(self.next_message()) 1769 self.assert_log_lines([ 1770 ('INFO', '1'), 1771 ('ERROR', '2'), 1772 ], stream=output) 1773 # Original logger output is empty. 1774 self.assert_log_lines([]) 1775 with captured_stdout() as output: 1776 self.apply_config(self.config8) 1777 logger = logging.getLogger("compiler.parser") 1778 self.assertFalse(logger.disabled) 1779 # Both will output a message 1780 logger.info(self.next_message()) 1781 logger.error(self.next_message()) 1782 logger = logging.getLogger("compiler.lexer") 1783 # Both will output a message 1784 logger.info(self.next_message()) 1785 logger.error(self.next_message()) 1786 self.assert_log_lines([ 1787 ('INFO', '3'), 1788 ('ERROR', '4'), 1789 ('INFO', '5'), 1790 ('ERROR', '6'), 1791 ], stream=output) 1792 # Original logger output is empty. 1793 self.assert_log_lines([]) 1794 1795 def test_config_9_ok(self): 1796 with captured_stdout() as output: 1797 self.apply_config(self.config9) 1798 logger = logging.getLogger("compiler.parser") 1799 #Nothing will be output since both handler and logger are set to WARNING 1800 logger.info(self.next_message()) 1801 self.assert_log_lines([], stream=output) 1802 self.apply_config(self.config9a) 1803 #Nothing will be output since both handler is still set to WARNING 1804 logger.info(self.next_message()) 1805 self.assert_log_lines([], stream=output) 1806 self.apply_config(self.config9b) 1807 #Message should now be output 1808 logger.info(self.next_message()) 1809 self.assert_log_lines([ 1810 ('INFO', '3'), 1811 ], stream=output) 1812 1813 def test_config_10_ok(self): 1814 with captured_stdout() as output: 1815 self.apply_config(self.config10) 1816 logger = logging.getLogger("compiler.parser") 1817 logger.warning(self.next_message()) 1818 logger = logging.getLogger('compiler') 1819 #Not output, because filtered 1820 logger.warning(self.next_message()) 1821 logger = logging.getLogger('compiler.lexer') 1822 #Not output, because filtered 1823 logger.warning(self.next_message()) 1824 logger = logging.getLogger("compiler.parser.codegen") 1825 #Output, as not filtered 1826 logger.error(self.next_message()) 1827 self.assert_log_lines([ 1828 ('WARNING', '1'), 1829 ('ERROR', '4'), 1830 ], stream=output) 1831 1832 def test_config11_ok(self): 1833 self.test_config1_ok(self.config11) 1834 1835 def test_config12_failure(self): 1836 self.assertRaises(StandardError, self.apply_config, self.config12) 1837 1838 def test_config13_failure(self): 1839 self.assertRaises(StandardError, self.apply_config, self.config13) 1840 1841 @unittest.skipUnless(threading, 'listen() needs threading to work') 1842 def setup_via_listener(self, text): 1843 # Ask for a randomly assigned port (by using port 0) 1844 t = logging.config.listen(0) 1845 t.start() 1846 t.ready.wait() 1847 # Now get the port allocated 1848 port = t.port 1849 t.ready.clear() 1850 try: 1851 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) 1852 sock.settimeout(2.0) 1853 sock.connect(('localhost', port)) 1854 1855 slen = struct.pack('>L', len(text)) 1856 s = slen + text 1857 sentsofar = 0 1858 left = len(s) 1859 while left > 0: 1860 sent = sock.send(s[sentsofar:]) 1861 sentsofar += sent 1862 left -= sent 1863 sock.close() 1864 finally: 1865 t.ready.wait(2.0) 1866 logging.config.stopListening() 1867 t.join(2.0) 1868 1869 def test_listen_config_10_ok(self): 1870 with captured_stdout() as output: 1871 self.setup_via_listener(json.dumps(self.config10)) 1872 logger = logging.getLogger("compiler.parser") 1873 logger.warning(self.next_message()) 1874 logger = logging.getLogger('compiler') 1875 #Not output, because filtered 1876 logger.warning(self.next_message()) 1877 logger = logging.getLogger('compiler.lexer') 1878 #Not output, because filtered 1879 logger.warning(self.next_message()) 1880 logger = logging.getLogger("compiler.parser.codegen") 1881 #Output, as not filtered 1882 logger.error(self.next_message()) 1883 self.assert_log_lines([ 1884 ('WARNING', '1'), 1885 ('ERROR', '4'), 1886 ], stream=output) 1887 1888 def test_listen_config_1_ok(self): 1889 with captured_stdout() as output: 1890 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1)) 1891 logger = logging.getLogger("compiler.parser") 1892 # Both will output a message 1893 logger.info(self.next_message()) 1894 logger.error(self.next_message()) 1895 self.assert_log_lines([ 1896 ('INFO', '1'), 1897 ('ERROR', '2'), 1898 ], stream=output) 1899 # Original logger output is empty. 1900 self.assert_log_lines([]) 1901 1902 def test_out_of_order(self): 1903 self.apply_config(self.out_of_order) 1904 handler = logging.getLogger('mymodule').handlers[0] 1905 self.assertIsInstance(handler.target, logging.Handler) 1906 1907 class ManagerTest(BaseTest): 1908 def test_manager_loggerclass(self): 1909 logged = [] 1910 1911 class MyLogger(logging.Logger): 1912 def _log(self, level, msg, args, exc_info=None, extra=None): 1913 logged.append(msg) 1914 1915 man = logging.Manager(None) 1916 self.assertRaises(TypeError, man.setLoggerClass, int) 1917 man.setLoggerClass(MyLogger) 1918 logger = man.getLogger('test') 1919 logger.warning('should appear in logged') 1920 logging.warning('should not appear in logged') 1921 1922 self.assertEqual(logged, ['should appear in logged']) 1923 1924 1925 class ChildLoggerTest(BaseTest): 1926 def test_child_loggers(self): 1927 r = logging.getLogger() 1928 l1 = logging.getLogger('abc') 1929 l2 = logging.getLogger('def.ghi') 1930 c1 = r.getChild('xyz') 1931 c2 = r.getChild('uvw.xyz') 1932 self.assertTrue(c1 is logging.getLogger('xyz')) 1933 self.assertTrue(c2 is logging.getLogger('uvw.xyz')) 1934 c1 = l1.getChild('def') 1935 c2 = c1.getChild('ghi') 1936 c3 = l1.getChild('def.ghi') 1937 self.assertTrue(c1 is logging.getLogger('abc.def')) 1938 self.assertTrue(c2 is logging.getLogger('abc.def.ghi')) 1939 self.assertTrue(c2 is c3) 1940 1941 1942 class HandlerTest(BaseTest): 1943 1944 @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.') 1945 @unittest.skipUnless(threading, 'Threading required for this test.') 1946 def test_race(self): 1947 # Issue #14632 refers. 1948 def remove_loop(fname, tries): 1949 for _ in range(tries): 1950 try: 1951 os.unlink(fname) 1952 except OSError: 1953 pass 1954 time.sleep(0.004 * random.randint(0, 4)) 1955 1956 del_count = 500 1957 log_count = 500 1958 1959 for delay in (False, True): 1960 fd, fn = tempfile.mkstemp('.log', 'test_logging-3-') 1961 os.close(fd) 1962 remover = threading.Thread(target=remove_loop, args=(fn, del_count)) 1963 remover.daemon = True 1964 remover.start() 1965 h = logging.handlers.WatchedFileHandler(fn, delay=delay) 1966 f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s') 1967 h.setFormatter(f) 1968 try: 1969 for _ in range(log_count): 1970 time.sleep(0.005) 1971 r = logging.makeLogRecord({'msg': 'testing' }) 1972 h.handle(r) 1973 finally: 1974 remover.join() 1975 try: 1976 h.close() 1977 except ValueError: 1978 pass 1979 if os.path.exists(fn): 1980 os.unlink(fn) 1981 1982 1983 # Set the locale to the platform-dependent default. I have no idea 1984 # why the test does this, but in any case we save the current locale 1985 # first and restore it at the end. 1986 @run_with_locale('LC_ALL', '') 1987 def test_main(): 1988 run_unittest(BuiltinLevelsTest, BasicFilterTest, 1989 CustomLevelsAndFiltersTest, MemoryHandlerTest, 1990 ConfigFileTest, SocketHandlerTest, MemoryTest, 1991 EncodingTest, WarningsTest, ConfigDictTest, ManagerTest, 1992 ChildLoggerTest, HandlerTest) 1993 1994 if __name__ == "__main__": 1995 test_main() 1996
