Lib/test/test_logging.py

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