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