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