1 #!/usr/bin/env python

     2 #

     3 # Copyright 2001-2004 by Vinay Sajip. All Rights Reserved.

     4 #

     5 # Permission to use, copy, modify, and distribute this software and its

     6 # documentation for any purpose and without fee is hereby granted,

     7 # provided that the above copyright notice appear in all copies and that

     8 # both that copyright notice and this permission notice appear in

     9 # supporting documentation, and that the name of Vinay Sajip

    10 # not be used in advertising or publicity pertaining to distribution

    11 # of the software without specific, written prior permission.

    12 # VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING

    13 # ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL

    14 # VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR

    15 # ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER

    16 # IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT

    17 # OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.

    18 

    19 """Test harness for the logging module. Run all tests.

    20 

    21 Copyright (C) 2001-2002 Vinay Sajip. All Rights Reserved.

    22 """

    23 

    24 import logging

    25 import logging.handlers

    26 import logging.config

    27 

    28 import copy

    29 import cPickle

    30 import cStringIO

    31 import gc

    32 import os

    33 import re

    34 import select

    35 import socket

    36 from SocketServer import ThreadingTCPServer, StreamRequestHandler

    37 import string

    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 threading

    44 import time

    45 import types

    46 import unittest

    47 import weakref

    48 

    49 

    50 class BaseTest(unittest.TestCase):

    51 

    52     """Base class for logging tests."""

    53 

    54     log_format = "%(name)s -> %(levelname)s: %(message)s"

    55     expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$"

    56     message_num = 0

    57 

    58     def setUp(self):

    59         """Setup the default logging stream to an internal StringIO instance,

    60         so that we can examine log output as we want."""

    61         logger_dict = logging.getLogger().manager.loggerDict

    62         logging._acquireLock()

    63         try:

    64             self.saved_handlers = logging._handlers.copy()

    65             self.saved_handler_list = logging._handlerList[:]

    66             self.saved_loggers = logger_dict.copy()

    67             self.saved_level_names = logging._levelNames.copy()

    68         finally:

    69             logging._releaseLock()

    70 

    71         self.root_logger = logging.getLogger("")

    72         self.original_logging_level = self.root_logger.getEffectiveLevel()

    73 

    74         self.stream = cStringIO.StringIO()

    75         self.root_logger.setLevel(logging.DEBUG)

    76         self.root_hdlr = logging.StreamHandler(self.stream)

    77         self.root_formatter = logging.Formatter(self.log_format)

    78         self.root_hdlr.setFormatter(self.root_formatter)

    79         self.root_logger.addHandler(self.root_hdlr)

    80 

    81     def tearDown(self):

    82         """Remove our logging stream, and restore the original logging

    83         level."""

    84         self.stream.close()

    85         self.root_logger.removeHandler(self.root_hdlr)

    86         self.root_logger.setLevel(self.original_logging_level)

    87         logging._acquireLock()

    88         try:

    89             logging._levelNames.clear()

    90             logging._levelNames.update(self.saved_level_names)

    91             logging._handlers.clear()

    92             logging._handlers.update(self.saved_handlers)

    93             logging._handlerList[:] = self.saved_handler_list

    94             loggerDict = logging.getLogger().manager.loggerDict

    95             loggerDict.clear()

    96             loggerDict.update(self.saved_loggers)

    97         finally:

    98             logging._releaseLock()

    99 

   100     def assert_log_lines(self, expected_values, stream=None):

   101         """Match the collected log lines against the regular expression

   102         self.expected_log_pat, and compare the extracted group values to

   103         the expected_values list of tuples."""

   104         stream = stream or self.stream

   105         pat = re.compile(self.expected_log_pat)

   106         try:

   107             stream.reset()

   108             actual_lines = stream.readlines()

   109         except AttributeError:

   110             # StringIO.StringIO lacks a reset() method.

   111             actual_lines = stream.getvalue().splitlines()

   112         self.assertEquals(len(actual_lines), len(expected_values))

   113         for actual, expected in zip(actual_lines, expected_values):

   114             match = pat.search(actual)

   115             if not match:

   116                 self.fail("Log line does not match expected pattern:\n" +

   117                             actual)

   118             self.assertEquals(tuple(match.groups()), expected)

   119         s = stream.read()

   120         if s:

   121             self.fail("Remaining output at end of log stream:\n" + s)

   122 

   123     def next_message(self):

   124         """Generate a message consisting solely of an auto-incrementing

   125         integer."""

   126         self.message_num += 1

   127         return "%d" % self.message_num

   128 

   129 

   130 class BuiltinLevelsTest(BaseTest):

   131     """Test builtin levels and their inheritance."""

   132 

   133     def test_flat(self):

   134         #Logging levels in a flat logger namespace.

   135         m = self.next_message

   136 

   137         ERR = logging.getLogger("ERR")

   138         ERR.setLevel(logging.ERROR)

   139         INF = logging.getLogger("INF")

   140         INF.setLevel(logging.INFO)

   141         DEB = logging.getLogger("DEB")

   142         DEB.setLevel(logging.DEBUG)

   143 

   144         # These should log.

   145         ERR.log(logging.CRITICAL, m())

   146         ERR.error(m())

   147 

   148         INF.log(logging.CRITICAL, m())

   149         INF.error(m())

   150         INF.warn(m())

   151         INF.info(m())

   152 

   153         DEB.log(logging.CRITICAL, m())

   154         DEB.error(m())

   155         DEB.warn (m())

   156         DEB.info (m())

   157         DEB.debug(m())

   158 

   159         # These should not log.

   160         ERR.warn(m())

   161         ERR.info(m())

   162         ERR.debug(m())

   163 

   164         INF.debug(m())

   165 

   166         self.assert_log_lines([

   167             ('ERR', 'CRITICAL', '1'),

   168             ('ERR', 'ERROR', '2'),

   169             ('INF', 'CRITICAL', '3'),

   170             ('INF', 'ERROR', '4'),

   171             ('INF', 'WARNING', '5'),

   172             ('INF', 'INFO', '6'),

   173             ('DEB', 'CRITICAL', '7'),

   174             ('DEB', 'ERROR', '8'),

   175             ('DEB', 'WARNING', '9'),

   176             ('DEB', 'INFO', '10'),

   177             ('DEB', 'DEBUG', '11'),

   178         ])

   179 

   180     def test_nested_explicit(self):

   181         # Logging levels in a nested namespace, all explicitly set.

   182         m = self.next_message

   183 

   184         INF = logging.getLogger("INF")

   185         INF.setLevel(logging.INFO)

   186         INF_ERR  = logging.getLogger("INF.ERR")

   187         INF_ERR.setLevel(logging.ERROR)

   188 

   189         # These should log.

   190         INF_ERR.log(logging.CRITICAL, m())

   191         INF_ERR.error(m())

   192 

   193         # These should not log.

   194         INF_ERR.warn(m())

   195         INF_ERR.info(m())

   196         INF_ERR.debug(m())

   197 

   198         self.assert_log_lines([

   199             ('INF.ERR', 'CRITICAL', '1'),

   200             ('INF.ERR', 'ERROR', '2'),

   201         ])

   202 

   203     def test_nested_inherited(self):

   204         #Logging levels in a nested namespace, inherited from parent loggers.

   205         m = self.next_message

   206 

   207         INF = logging.getLogger("INF")

   208         INF.setLevel(logging.INFO)

   209         INF_ERR  = logging.getLogger("INF.ERR")

   210         INF_ERR.setLevel(logging.ERROR)

   211         INF_UNDEF = logging.getLogger("INF.UNDEF")

   212         INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")

   213         UNDEF = logging.getLogger("UNDEF")

   214 

   215         # These should log.

   216         INF_UNDEF.log(logging.CRITICAL, m())

   217         INF_UNDEF.error(m())

   218         INF_UNDEF.warn(m())

   219         INF_UNDEF.info(m())

   220         INF_ERR_UNDEF.log(logging.CRITICAL, m())

   221         INF_ERR_UNDEF.error(m())

   222 

   223         # These should not log.

   224         INF_UNDEF.debug(m())

   225         INF_ERR_UNDEF.warn(m())

   226         INF_ERR_UNDEF.info(m())

   227         INF_ERR_UNDEF.debug(m())

   228 

   229         self.assert_log_lines([

   230             ('INF.UNDEF', 'CRITICAL', '1'),

   231             ('INF.UNDEF', 'ERROR', '2'),

   232             ('INF.UNDEF', 'WARNING', '3'),

   233             ('INF.UNDEF', 'INFO', '4'),

   234             ('INF.ERR.UNDEF', 'CRITICAL', '5'),

   235             ('INF.ERR.UNDEF', 'ERROR', '6'),

   236         ])

   237 

   238     def test_nested_with_virtual_parent(self):

   239         # Logging levels when some parent does not exist yet.

   240         m = self.next_message

   241 

   242         INF = logging.getLogger("INF")

   243         GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")

   244         CHILD = logging.getLogger("INF.BADPARENT")

   245         INF.setLevel(logging.INFO)

   246 

   247         # These should log.

   248         GRANDCHILD.log(logging.FATAL, m())

   249         GRANDCHILD.info(m())

   250         CHILD.log(logging.FATAL, m())

   251         CHILD.info(m())

   252 

   253         # These should not log.

   254         GRANDCHILD.debug(m())

   255         CHILD.debug(m())

   256 

   257         self.assert_log_lines([

   258             ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),

   259             ('INF.BADPARENT.UNDEF', 'INFO', '2'),

   260             ('INF.BADPARENT', 'CRITICAL', '3'),

   261             ('INF.BADPARENT', 'INFO', '4'),

   262         ])

   263 

   264 

   265 class BasicFilterTest(BaseTest):

   266 

   267     """Test the bundled Filter class."""

   268 

   269     def test_filter(self):

   270         # Only messages satisfying the specified criteria pass through the

   271         #  filter.

   272         filter_ = logging.Filter("spam.eggs")

   273         handler = self.root_logger.handlers[0]

   274         try:

   275             handler.addFilter(filter_)

   276             spam = logging.getLogger("spam")

   277             spam_eggs = logging.getLogger("spam.eggs")

   278             spam_eggs_fish = logging.getLogger("spam.eggs.fish")

   279             spam_bakedbeans = logging.getLogger("spam.bakedbeans")

   280 

   281             spam.info(self.next_message())

   282             spam_eggs.info(self.next_message())  # Good.

   283             spam_eggs_fish.info(self.next_message())  # Good.

   284             spam_bakedbeans.info(self.next_message())

   285 

   286             self.assert_log_lines([

   287                 ('spam.eggs', 'INFO', '2'),

   288                 ('spam.eggs.fish', 'INFO', '3'),

   289             ])

   290         finally:

   291             handler.removeFilter(filter_)

   292 

   293 

   294 #

   295 #   First, we define our levels. There can be as many as you want - the only

   296 #     limitations are that they should be integers, the lowest should be > 0 and

   297 #   larger values mean less information being logged. If you need specific

   298 #   level values which do not fit into these limitations, you can use a

   299 #   mapping dictionary to convert between your application levels and the

   300 #   logging system.

   301 #

   302 SILENT      = 120

   303 TACITURN    = 119

   304 TERSE       = 118

   305 EFFUSIVE    = 117

   306 SOCIABLE    = 116

   307 VERBOSE     = 115

   308 TALKATIVE   = 114

   309 GARRULOUS   = 113

   310 CHATTERBOX  = 112

   311 BORING      = 111

   312 

   313 LEVEL_RANGE = range(BORING, SILENT + 1)

   314 

   315 #

   316 #   Next, we define names for our levels. You don't need to do this - in which

   317 #   case the system will use "Level n" to denote the text for the level.

   318 #

   319 my_logging_levels = {

   320     SILENT      : 'Silent',

   321     TACITURN    : 'Taciturn',

   322     TERSE       : 'Terse',

   323     EFFUSIVE    : 'Effusive',

   324     SOCIABLE    : 'Sociable',

   325     VERBOSE     : 'Verbose',

   326     TALKATIVE   : 'Talkative',

   327     GARRULOUS   : 'Garrulous',

   328     CHATTERBOX  : 'Chatterbox',

   329     BORING      : 'Boring',

   330 }

   331 

   332 class GarrulousFilter(logging.Filter):

   333 

   334     """A filter which blocks garrulous messages."""

   335 

   336     def filter(self, record):

   337         return record.levelno != GARRULOUS

   338 

   339 class VerySpecificFilter(logging.Filter):

   340 

   341     """A filter which blocks sociable and taciturn messages."""

   342 

   343     def filter(self, record):

   344         return record.levelno not in [SOCIABLE, TACITURN]

   345 

   346 

   347 class CustomLevelsAndFiltersTest(BaseTest):

   348 

   349     """Test various filtering possibilities with custom logging levels."""

   350 

   351     # Skip the logger name group.

   352     expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"

   353 

   354     def setUp(self):

   355         BaseTest.setUp(self)

   356         for k, v in my_logging_levels.items():

   357             logging.addLevelName(k, v)

   358 

   359     def log_at_all_levels(self, logger):

   360         for lvl in LEVEL_RANGE:

   361             logger.log(lvl, self.next_message())

   362 

   363     def test_logger_filter(self):

   364         # Filter at logger level.

   365         self.root_logger.setLevel(VERBOSE)

   366         # Levels >= 'Verbose' are good.

   367         self.log_at_all_levels(self.root_logger)

   368         self.assert_log_lines([

   369             ('Verbose', '5'),

   370             ('Sociable', '6'),

   371             ('Effusive', '7'),

   372             ('Terse', '8'),

   373             ('Taciturn', '9'),

   374             ('Silent', '10'),

   375         ])

   376 

   377     def test_handler_filter(self):

   378         # Filter at handler level.

   379         self.root_logger.handlers[0].setLevel(SOCIABLE)

   380         try:

   381             # Levels >= 'Sociable' are good.

   382             self.log_at_all_levels(self.root_logger)

   383             self.assert_log_lines([

   384                 ('Sociable', '6'),

   385                 ('Effusive', '7'),

   386                 ('Terse', '8'),

   387                 ('Taciturn', '9'),

   388                 ('Silent', '10'),

   389             ])

   390         finally:

   391             self.root_logger.handlers[0].setLevel(logging.NOTSET)

   392 

   393     def test_specific_filters(self):

   394         # Set a specific filter object on the handler, and then add another

   395         #  filter object on the logger itself.

   396         handler = self.root_logger.handlers[0]

   397         specific_filter = None

   398         garr = GarrulousFilter()

   399         handler.addFilter(garr)

   400         try:

   401             self.log_at_all_levels(self.root_logger)

   402             first_lines = [

   403                 # Notice how 'Garrulous' is missing

   404                 ('Boring', '1'),

   405                 ('Chatterbox', '2'),

   406                 ('Talkative', '4'),

   407                 ('Verbose', '5'),

   408                 ('Sociable', '6'),

   409                 ('Effusive', '7'),

   410                 ('Terse', '8'),

   411                 ('Taciturn', '9'),

   412                 ('Silent', '10'),

   413             ]

   414             self.assert_log_lines(first_lines)

   415 

   416             specific_filter = VerySpecificFilter()

   417             self.root_logger.addFilter(specific_filter)

   418             self.log_at_all_levels(self.root_logger)

   419             self.assert_log_lines(first_lines + [

   420                 # Not only 'Garrulous' is still missing, but also 'Sociable'

   421                 # and 'Taciturn'

   422                 ('Boring', '11'),

   423                 ('Chatterbox', '12'),

   424                 ('Talkative', '14'),

   425                 ('Verbose', '15'),

   426                 ('Effusive', '17'),

   427                 ('Terse', '18'),

   428                 ('Silent', '20'),

   429         ])

   430         finally:

   431             if specific_filter:

   432                 self.root_logger.removeFilter(specific_filter)

   433             handler.removeFilter(garr)

   434 

   435 

   436 class MemoryHandlerTest(BaseTest):

   437 

   438     """Tests for the MemoryHandler."""

   439 

   440     # Do not bother with a logger name group.

   441     expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"

   442 

   443     def setUp(self):

   444         BaseTest.setUp(self)

   445         self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,

   446                                                         self.root_hdlr)

   447         self.mem_logger = logging.getLogger('mem')

   448         self.mem_logger.propagate = 0

   449         self.mem_logger.addHandler(self.mem_hdlr)

   450 

   451     def tearDown(self):

   452         self.mem_hdlr.close()

   453         BaseTest.tearDown(self)

   454 

   455     def test_flush(self):

   456         # The memory handler flushes to its target handler based on specific

   457         #  criteria (message count and message level).

   458         self.mem_logger.debug(self.next_message())

   459         self.assert_log_lines([])

   460         self.mem_logger.info(self.next_message())

   461         self.assert_log_lines([])

   462         # This will flush because the level is >= logging.WARNING

   463         self.mem_logger.warn(self.next_message())

   464         lines = [

   465             ('DEBUG', '1'),

   466             ('INFO', '2'),

   467             ('WARNING', '3'),

   468         ]

   469         self.assert_log_lines(lines)

   470         for n in (4, 14):

   471             for i in range(9):

   472                 self.mem_logger.debug(self.next_message())

   473             self.assert_log_lines(lines)

   474             # This will flush because it's the 10th message since the last

   475             #  flush.

   476             self.mem_logger.debug(self.next_message())

   477             lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]

   478             self.assert_log_lines(lines)

   479 

   480         self.mem_logger.debug(self.next_message())

   481         self.assert_log_lines(lines)

   482 

   483 

   484 class ExceptionFormatter(logging.Formatter):

   485     """A special exception formatter."""

   486     def formatException(self, ei):

   487         return "Got a [%s]" % ei[0].__name__

   488 

   489 

   490 class ConfigFileTest(BaseTest):

   491 

   492     """Reading logging config from a .ini-style config file."""

   493 

   494     expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"

   495 

   496     # config0 is a standard configuration.

   497     config0 = """

   498     [loggers]

   499     keys=root

   500 

   501     [handlers]

   502     keys=hand1

   503 

   504     [formatters]

   505     keys=form1

   506 

   507     [logger_root]

   508     level=WARNING

   509     handlers=hand1

   510 

   511     [handler_hand1]

   512     class=StreamHandler

   513     level=NOTSET

   514     formatter=form1

   515     args=(sys.stdout,)

   516 

   517     [formatter_form1]

   518     format=%(levelname)s ++ %(message)s

   519     datefmt=

   520     """

   521 

   522     # config1 adds a little to the standard configuration.

   523     config1 = """

   524     [loggers]

   525     keys=root,parser

   526 

   527     [handlers]

   528     keys=hand1

   529 

   530     [formatters]

   531     keys=form1

   532 

   533     [logger_root]

   534     level=WARNING

   535     handlers=

   536 

   537     [logger_parser]

   538     level=DEBUG

   539     handlers=hand1

   540     propagate=1

   541     qualname=compiler.parser

   542 

   543     [handler_hand1]

   544     class=StreamHandler

   545     level=NOTSET

   546     formatter=form1

   547     args=(sys.stdout,)

   548 

   549     [formatter_form1]

   550     format=%(levelname)s ++ %(message)s

   551     datefmt=

   552     """

   553 

   554     # config2 has a subtle configuration error that should be reported

   555     config2 = config1.replace("sys.stdout", "sys.stbout")

   556 

   557     # config3 has a less subtle configuration error

   558     config3 = config1.replace("formatter=form1", "formatter=misspelled_name")

   559 

   560     # config4 specifies a custom formatter class to be loaded

   561     config4 = """

   562     [loggers]

   563     keys=root

   564 

   565     [handlers]

   566     keys=hand1

   567 

   568     [formatters]

   569     keys=form1

   570 

   571     [logger_root]

   572     level=NOTSET

   573     handlers=hand1

   574 

   575     [handler_hand1]

   576     class=StreamHandler

   577     level=NOTSET

   578     formatter=form1

   579     args=(sys.stdout,)

   580 

   581     [formatter_form1]

   582     class=""" + __name__ + """.ExceptionFormatter

   583     format=%(levelname)s:%(name)s:%(message)s

   584     datefmt=

   585     """

   586 

   587     # config5 specifies a custom handler class to be loaded

   588     config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')

   589 

   590     # config6 uses ', ' delimiters in the handlers and formatters sections

   591     config6 = """

   592     [loggers]

   593     keys=root,parser

   594 

   595     [handlers]

   596     keys=hand1, hand2

   597 

   598     [formatters]

   599     keys=form1, form2

   600 

   601     [logger_root]

   602     level=WARNING

   603     handlers=

   604 

   605     [logger_parser]

   606     level=DEBUG

   607     handlers=hand1

   608     propagate=1

   609     qualname=compiler.parser

   610 

   611     [handler_hand1]

   612     class=StreamHandler

   613     level=NOTSET

   614     formatter=form1

   615     args=(sys.stdout,)

   616 

   617     [handler_hand2]

   618     class=StreamHandler

   619     level=NOTSET

   620     formatter=form1

   621     args=(sys.stderr,)

   622 

   623     [formatter_form1]

   624     format=%(levelname)s ++ %(message)s

   625     datefmt=

   626 

   627     [formatter_form2]

   628     format=%(message)s

   629     datefmt=

   630     """

   631 

   632     def apply_config(self, conf):

   633         try:

   634             fn = tempfile.mktemp(".ini")

   635             f = open(fn, "w")

   636             f.write(textwrap.dedent(conf))

   637             f.close()

   638             logging.config.fileConfig(fn)

   639         finally:

   640             os.remove(fn)

   641 

   642     def test_config0_ok(self):

   643         # A simple config file which overrides the default settings.

   644         with captured_stdout() as output:

   645             self.apply_config(self.config0)

   646             logger = logging.getLogger()

   647             # Won't output anything

   648             logger.info(self.next_message())

   649             # Outputs a message

   650             logger.error(self.next_message())

   651             self.assert_log_lines([

   652                 ('ERROR', '2'),

   653             ], stream=output)

   654             # Original logger output is empty.

   655             self.assert_log_lines([])

   656 

   657     def test_config1_ok(self, config=config1):

   658         # A config file defining a sub-parser as well.

   659         with captured_stdout() as output:

   660             self.apply_config(config)

   661             logger = logging.getLogger("compiler.parser")

   662             # Both will output a message

   663             logger.info(self.next_message())

   664             logger.error(self.next_message())

   665             self.assert_log_lines([

   666                 ('INFO', '1'),

   667                 ('ERROR', '2'),

   668             ], stream=output)

   669             # Original logger output is empty.

   670             self.assert_log_lines([])

   671 

   672     def test_config2_failure(self):

   673         # A simple config file which overrides the default settings.

   674         self.assertRaises(StandardError, self.apply_config, self.config2)

   675 

   676     def test_config3_failure(self):

   677         # A simple config file which overrides the default settings.

   678         self.assertRaises(StandardError, self.apply_config, self.config3)

   679 

   680     def test_config4_ok(self):

   681         # A config file specifying a custom formatter class.

   682         with captured_stdout() as output:

   683             self.apply_config(self.config4)

   684             logger = logging.getLogger()

   685             try:

   686                 raise RuntimeError()

   687             except RuntimeError:

   688                 logging.exception("just testing")

   689             sys.stdout.seek(0)

   690             self.assertEquals(output.getvalue(),

   691                 "ERROR:root:just testing\nGot a [RuntimeError]\n")

   692             # Original logger output is empty

   693             self.assert_log_lines([])

   694 

   695     def test_config5_ok(self):

   696         self.test_config1_ok(config=self.config5)

   697 

   698     def test_config6_ok(self):

   699         self.test_config1_ok(config=self.config6)

   700 

   701 class LogRecordStreamHandler(StreamRequestHandler):

   702 

   703     """Handler for a streaming logging request. It saves the log message in the

   704     TCP server's 'log_output' attribute."""

   705 

   706     TCP_LOG_END = "!!!END!!!"

   707 

   708     def handle(self):

   709         """Handle multiple requests - each expected to be of 4-byte length,

   710         followed by the LogRecord in pickle format. Logs the record

   711         according to whatever policy is configured locally."""

   712         while True:

   713             chunk = self.connection.recv(4)

   714             if len(chunk) < 4:

   715                 break

   716             slen = struct.unpack(">L", chunk)[0]

   717             chunk = self.connection.recv(slen)

   718             while len(chunk) < slen:

   719                 chunk = chunk + self.connection.recv(slen - len(chunk))

   720             obj = self.unpickle(chunk)

   721             record = logging.makeLogRecord(obj)

   722             self.handle_log_record(record)

   723 

   724     def unpickle(self, data):

   725         return cPickle.loads(data)

   726 

   727     def handle_log_record(self, record):

   728         # If the end-of-messages sentinel is seen, tell the server to

   729         #  terminate.

   730         if self.TCP_LOG_END in record.msg:

   731             self.server.abort = 1

   732             return

   733         self.server.log_output += record.msg + "\n"

   734 

   735 

   736 class LogRecordSocketReceiver(ThreadingTCPServer):

   737 

   738     """A simple-minded TCP socket-based logging receiver suitable for test

   739     purposes."""

   740 

   741     allow_reuse_address = 1

   742     log_output = ""

   743 

   744     def __init__(self, host='localhost',

   745                              port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,

   746                      handler=LogRecordStreamHandler):

   747         ThreadingTCPServer.__init__(self, (host, port), handler)

   748         self.abort = False

   749         self.timeout = 0.1

   750         self.finished = threading.Event()

   751 

   752     def serve_until_stopped(self):

   753         while not self.abort:

   754             rd, wr, ex = select.select([self.socket.fileno()], [], [],

   755                                        self.timeout)

   756             if rd:

   757                 self.handle_request()

   758         # Notify the main thread that we're about to exit

   759         self.finished.set()

   760         # close the listen socket

   761         self.server_close()

   762 

   763 

   764 class SocketHandlerTest(BaseTest):

   765 

   766     """Test for SocketHandler objects."""

   767 

   768     def setUp(self):

   769         """Set up a TCP server to receive log messages, and a SocketHandler

   770         pointing to that server's address and port."""

   771         BaseTest.setUp(self)

   772         self.tcpserver = LogRecordSocketReceiver(port=0)

   773         self.port = self.tcpserver.socket.getsockname()[1]

   774         self.threads = [

   775                 threading.Thread(target=self.tcpserver.serve_until_stopped)]

   776         for thread in self.threads:

   777             thread.start()

   778 

   779         self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port)

   780         self.sock_hdlr.setFormatter(self.root_formatter)

   781         self.root_logger.removeHandler(self.root_logger.handlers[0])

   782         self.root_logger.addHandler(self.sock_hdlr)

   783 

   784     def tearDown(self):

   785         """Shutdown the TCP server."""

   786         try:

   787             self.tcpserver.abort = True

   788             del self.tcpserver

   789             self.root_logger.removeHandler(self.sock_hdlr)

   790             self.sock_hdlr.close()

   791             for thread in self.threads:

   792                 thread.join(2.0)

   793         finally:

   794             BaseTest.tearDown(self)

   795 

   796     def get_output(self):

   797         """Get the log output as received by the TCP server."""

   798         # Signal the TCP receiver and wait for it to terminate.

   799         self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END)

   800         self.tcpserver.finished.wait(2.0)

   801         return self.tcpserver.log_output

   802 

   803     def test_output(self):

   804         # The log message sent to the SocketHandler is properly received.

   805         logger = logging.getLogger("tcp")

   806         logger.error("spam")

   807         logger.debug("eggs")

   808         self.assertEquals(self.get_output(), "spam\neggs\n")

   809 

   810 

   811 class MemoryTest(BaseTest):

   812 

   813     """Test memory persistence of logger objects."""

   814 

   815     def setUp(self):

   816         """Create a dict to remember potentially destroyed objects."""

   817         BaseTest.setUp(self)

   818         self._survivors = {}

   819 

   820     def _watch_for_survival(self, *args):

   821         """Watch the given objects for survival, by creating weakrefs to

   822         them."""

   823         for obj in args:

   824             key = id(obj), repr(obj)

   825             self._survivors[key] = weakref.ref(obj)

   826 

   827     def _assert_survival(self):

   828         """Assert that all objects watched for survival have survived."""

   829         # Trigger cycle breaking.

   830         gc.collect()

   831         dead = []

   832         for (id_, repr_), ref in self._survivors.items():

   833             if ref() is None:

   834                 dead.append(repr_)

   835         if dead:

   836             self.fail("%d objects should have survived "

   837                 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))

   838 

   839     def test_persistent_loggers(self):

   840         # Logger objects are persistent and retain their configuration, even

   841         #  if visible references are destroyed.

   842         self.root_logger.setLevel(logging.INFO)

   843         foo = logging.getLogger("foo")

   844         self._watch_for_survival(foo)

   845         foo.setLevel(logging.DEBUG)

   846         self.root_logger.debug(self.next_message())

   847         foo.debug(self.next_message())

   848         self.assert_log_lines([

   849             ('foo', 'DEBUG', '2'),

   850         ])

   851         del foo

   852         # foo has survived.

   853         self._assert_survival()

   854         # foo has retained its settings.

   855         bar = logging.getLogger("foo")

   856         bar.debug(self.next_message())

   857         self.assert_log_lines([

   858             ('foo', 'DEBUG', '2'),

   859             ('foo', 'DEBUG', '3'),

   860         ])

   861 

   862 class EncodingTest(BaseTest):

   863     def test_encoding_plain_file(self):

   864         # In Python 2.x, a plain file object is treated as having no encoding.

   865         log = logging.getLogger("test")

   866         fn = tempfile.mktemp(".log")

   867         # the non-ascii data we write to the log.

   868         data = "foo\x80"

   869         try:

   870             handler = logging.FileHandler(fn)

   871             log.addHandler(handler)

   872             try:

   873                 # write non-ascii data to the log.

   874                 log.warning(data)

   875             finally:

   876                 log.removeHandler(handler)

   877                 handler.close()

   878             # check we wrote exactly those bytes, ignoring trailing \n etc

   879             f = open(fn)

   880             try:

   881                 self.failUnlessEqual(f.read().rstrip(), data)

   882             finally:

   883                 f.close()

   884         finally:

   885             if os.path.isfile(fn):

   886                 os.remove(fn)

   887 

   888 # Set the locale to the platform-dependent default.  I have no idea

   889 # why the test does this, but in any case we save the current locale

   890 # first and restore it at the end.

   891 @run_with_locale('LC_ALL', '')

   892 def test_main():

   893     run_unittest(BuiltinLevelsTest, BasicFilterTest,

   894                     CustomLevelsAndFiltersTest, MemoryHandlerTest,

   895                     ConfigFileTest, SocketHandlerTest, MemoryTest,

   896                     EncodingTest)

   897 

   898 if __name__ == "__main__":

   899     test_main()