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