/Lib/test/test_logging.py

  1#!/usr/bin/env python
  2#
  3# Copyright 2001-2004 by Vinay Sajip. All Rights Reserved.
  4#
  5# Permission to use, copy, modify, and distribute this software and its
  6# documentation for any purpose and without fee is hereby granted,
  7# provided that the above copyright notice appear in all copies and that
  8# both that copyright notice and this permission notice appear in
  9# supporting documentation, and that the name of Vinay Sajip
 10# not be used in advertising or publicity pertaining to distribution
 11# of the software without specific, written prior permission.
 12# VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING
 13# ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
 14# VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR
 15# ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER
 16# IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
 17# OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
 18
 19"""Test harness for the logging module. Run all tests.
 20
 21Copyright (C) 2001-2002 Vinay Sajip. All Rights Reserved.
 22"""
 23
 24import logging
 25import logging.handlers
 26import logging.config
 27
 28import codecs
 29import copy
 30import cPickle
 31import cStringIO
 32import gc
 33import os
 34import re
 35import select
 36import socket
 37from SocketServer import ThreadingTCPServer, StreamRequestHandler
 38import string
 39import struct
 40import sys
 41import tempfile
 42from test.test_support import captured_stdout, run_with_locale, run_unittest
 43import textwrap
 44import threading
 45import time
 46import types
 47import unittest
 48import weakref
 49
 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        self.root_logger = logging.getLogger("")
 73        self.original_logging_level = self.root_logger.getEffectiveLevel()
 74
 75        self.stream = cStringIO.StringIO()
 76        self.root_logger.setLevel(logging.DEBUG)
 77        self.root_hdlr = logging.StreamHandler(self.stream)
 78        self.root_formatter = logging.Formatter(self.log_format)
 79        self.root_hdlr.setFormatter(self.root_formatter)
 80        self.root_logger.addHandler(self.root_hdlr)
 81
 82    def tearDown(self):
 83        """Remove our logging stream, and restore the original logging
 84        level."""
 85        self.stream.close()
 86        self.root_logger.removeHandler(self.root_hdlr)
 87        self.root_logger.setLevel(self.original_logging_level)
 88        logging._acquireLock()
 89        try:
 90            logging._levelNames.clear()
 91            logging._levelNames.update(self.saved_level_names)
 92            logging._handlers.clear()
 93            logging._handlers.update(self.saved_handlers)
 94            logging._handlerList[:] = self.saved_handler_list
 95            loggerDict = logging.getLogger().manager.loggerDict
 96            loggerDict.clear()
 97            loggerDict.update(self.saved_loggers)
 98        finally:
 99            logging._releaseLock()
100
101    def assert_log_lines(self, expected_values, stream=None):
102        """Match the collected log lines against the regular expression
103        self.expected_log_pat, and compare the extracted group values to
104        the expected_values list of tuples."""
105        stream = stream or self.stream
106        pat = re.compile(self.expected_log_pat)
107        try:
108            stream.reset()
109            actual_lines = stream.readlines()
110        except AttributeError:
111            # StringIO.StringIO lacks a reset() method.
112            actual_lines = stream.getvalue().splitlines()
113        self.assertEquals(len(actual_lines), len(expected_values))
114        for actual, expected in zip(actual_lines, expected_values):
115            match = pat.search(actual)
116            if not match:
117                self.fail("Log line does not match expected pattern:\n" +
118                            actual)
119            self.assertEquals(tuple(match.groups()), expected)
120        s = stream.read()
121        if s:
122            self.fail("Remaining output at end of log stream:\n" + s)
123
124    def next_message(self):
125        """Generate a message consisting solely of an auto-incrementing
126        integer."""
127        self.message_num += 1
128        return "%d" % self.message_num
129
130
131class BuiltinLevelsTest(BaseTest):
132    """Test builtin levels and their inheritance."""
133
134    def test_flat(self):
135        #Logging levels in a flat logger namespace.
136        m = self.next_message
137
138        ERR = logging.getLogger("ERR")
139        ERR.setLevel(logging.ERROR)
140        INF = logging.getLogger("INF")
141        INF.setLevel(logging.INFO)
142        DEB = logging.getLogger("DEB")
143        DEB.setLevel(logging.DEBUG)
144
145        # These should log.
146        ERR.log(logging.CRITICAL, m())
147        ERR.error(m())
148
149        INF.log(logging.CRITICAL, m())
150        INF.error(m())
151        INF.warn(m())
152        INF.info(m())
153
154        DEB.log(logging.CRITICAL, m())
155        DEB.error(m())
156        DEB.warn (m())
157        DEB.info (m())
158        DEB.debug(m())
159
160        # These should not log.
161        ERR.warn(m())
162        ERR.info(m())
163        ERR.debug(m())
164
165        INF.debug(m())
166
167        self.assert_log_lines([
168            ('ERR', 'CRITICAL', '1'),
169            ('ERR', 'ERROR', '2'),
170            ('INF', 'CRITICAL', '3'),
171            ('INF', 'ERROR', '4'),
172            ('INF', 'WARNING', '5'),
173            ('INF', 'INFO', '6'),
174            ('DEB', 'CRITICAL', '7'),
175            ('DEB', 'ERROR', '8'),
176            ('DEB', 'WARNING', '9'),
177            ('DEB', 'INFO', '10'),
178            ('DEB', 'DEBUG', '11'),
179        ])
180
181    def test_nested_explicit(self):
182        # Logging levels in a nested namespace, all explicitly set.
183        m = self.next_message
184
185        INF = logging.getLogger("INF")
186        INF.setLevel(logging.INFO)
187        INF_ERR  = logging.getLogger("INF.ERR")
188        INF_ERR.setLevel(logging.ERROR)
189
190        # These should log.
191        INF_ERR.log(logging.CRITICAL, m())
192        INF_ERR.error(m())
193
194        # These should not log.
195        INF_ERR.warn(m())
196        INF_ERR.info(m())
197        INF_ERR.debug(m())
198
199        self.assert_log_lines([
200            ('INF.ERR', 'CRITICAL', '1'),
201            ('INF.ERR', 'ERROR', '2'),
202        ])
203
204    def test_nested_inherited(self):
205        #Logging levels in a nested namespace, inherited from parent loggers.
206        m = self.next_message
207
208        INF = logging.getLogger("INF")
209        INF.setLevel(logging.INFO)
210        INF_ERR  = logging.getLogger("INF.ERR")
211        INF_ERR.setLevel(logging.ERROR)
212        INF_UNDEF = logging.getLogger("INF.UNDEF")
213        INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
214        UNDEF = logging.getLogger("UNDEF")
215
216        # These should log.
217        INF_UNDEF.log(logging.CRITICAL, m())
218        INF_UNDEF.error(m())
219        INF_UNDEF.warn(m())
220        INF_UNDEF.info(m())
221        INF_ERR_UNDEF.log(logging.CRITICAL, m())
222        INF_ERR_UNDEF.error(m())
223
224        # These should not log.
225        INF_UNDEF.debug(m())
226        INF_ERR_UNDEF.warn(m())
227        INF_ERR_UNDEF.info(m())
228        INF_ERR_UNDEF.debug(m())
229
230        self.assert_log_lines([
231            ('INF.UNDEF', 'CRITICAL', '1'),
232            ('INF.UNDEF', 'ERROR', '2'),
233            ('INF.UNDEF', 'WARNING', '3'),
234            ('INF.UNDEF', 'INFO', '4'),
235            ('INF.ERR.UNDEF', 'CRITICAL', '5'),
236            ('INF.ERR.UNDEF', 'ERROR', '6'),
237        ])
238
239    def test_nested_with_virtual_parent(self):
240        # Logging levels when some parent does not exist yet.
241        m = self.next_message
242
243        INF = logging.getLogger("INF")
244        GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
245        CHILD = logging.getLogger("INF.BADPARENT")
246        INF.setLevel(logging.INFO)
247
248        # These should log.
249        GRANDCHILD.log(logging.FATAL, m())
250        GRANDCHILD.info(m())
251        CHILD.log(logging.FATAL, m())
252        CHILD.info(m())
253
254        # These should not log.
255        GRANDCHILD.debug(m())
256        CHILD.debug(m())
257
258        self.assert_log_lines([
259            ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
260            ('INF.BADPARENT.UNDEF', 'INFO', '2'),
261            ('INF.BADPARENT', 'CRITICAL', '3'),
262            ('INF.BADPARENT', 'INFO', '4'),
263        ])
264
265
266class BasicFilterTest(BaseTest):
267
268    """Test the bundled Filter class."""
269
270    def test_filter(self):
271        # Only messages satisfying the specified criteria pass through the
272        #  filter.
273        filter_ = logging.Filter("spam.eggs")
274        handler = self.root_logger.handlers[0]
275        try:
276            handler.addFilter(filter_)
277            spam = logging.getLogger("spam")
278            spam_eggs = logging.getLogger("spam.eggs")
279            spam_eggs_fish = logging.getLogger("spam.eggs.fish")
280            spam_bakedbeans = logging.getLogger("spam.bakedbeans")
281
282            spam.info(self.next_message())
283            spam_eggs.info(self.next_message())  # Good.
284            spam_eggs_fish.info(self.next_message())  # Good.
285            spam_bakedbeans.info(self.next_message())
286
287            self.assert_log_lines([
288                ('spam.eggs', 'INFO', '2'),
289                ('spam.eggs.fish', 'INFO', '3'),
290            ])
291        finally:
292            handler.removeFilter(filter_)
293
294
295#
296#   First, we define our levels. There can be as many as you want - the only
297#     limitations are that they should be integers, the lowest should be > 0 and
298#   larger values mean less information being logged. If you need specific
299#   level values which do not fit into these limitations, you can use a
300#   mapping dictionary to convert between your application levels and the
301#   logging system.
302#
303SILENT      = 120
304TACITURN    = 119
305TERSE       = 118
306EFFUSIVE    = 117
307SOCIABLE    = 116
308VERBOSE     = 115
309TALKATIVE   = 114
310GARRULOUS   = 113
311CHATTERBOX  = 112
312BORING      = 111
313
314LEVEL_RANGE = range(BORING, SILENT + 1)
315
316#
317#   Next, we define names for our levels. You don't need to do this - in which
318#   case the system will use "Level n" to denote the text for the level.
319#
320my_logging_levels = {
321    SILENT      : 'Silent',
322    TACITURN    : 'Taciturn',
323    TERSE       : 'Terse',
324    EFFUSIVE    : 'Effusive',
325    SOCIABLE    : 'Sociable',
326    VERBOSE     : 'Verbose',
327    TALKATIVE   : 'Talkative',
328    GARRULOUS   : 'Garrulous',
329    CHATTERBOX  : 'Chatterbox',
330    BORING      : 'Boring',
331}
332
333class GarrulousFilter(logging.Filter):
334
335    """A filter which blocks garrulous messages."""
336
337    def filter(self, record):
338        return record.levelno != GARRULOUS
339
340class VerySpecificFilter(logging.Filter):
341
342    """A filter which blocks sociable and taciturn messages."""
343
344    def filter(self, record):
345        return record.levelno not in [SOCIABLE, TACITURN]
346
347
348class CustomLevelsAndFiltersTest(BaseTest):
349
350    """Test various filtering possibilities with custom logging levels."""
351
352    # Skip the logger name group.
353    expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
354
355    def setUp(self):
356        BaseTest.setUp(self)
357        for k, v in my_logging_levels.items():
358            logging.addLevelName(k, v)
359
360    def log_at_all_levels(self, logger):
361        for lvl in LEVEL_RANGE:
362            logger.log(lvl, self.next_message())
363
364    def test_logger_filter(self):
365        # Filter at logger level.
366        self.root_logger.setLevel(VERBOSE)
367        # Levels >= 'Verbose' are good.
368        self.log_at_all_levels(self.root_logger)
369        self.assert_log_lines([
370            ('Verbose', '5'),
371            ('Sociable', '6'),
372            ('Effusive', '7'),
373            ('Terse', '8'),
374            ('Taciturn', '9'),
375            ('Silent', '10'),
376        ])
377
378    def test_handler_filter(self):
379        # Filter at handler level.
380        self.root_logger.handlers[0].setLevel(SOCIABLE)
381        try:
382            # Levels >= 'Sociable' are good.
383            self.log_at_all_levels(self.root_logger)
384            self.assert_log_lines([
385                ('Sociable', '6'),
386                ('Effusive', '7'),
387                ('Terse', '8'),
388                ('Taciturn', '9'),
389                ('Silent', '10'),
390            ])
391        finally:
392            self.root_logger.handlers[0].setLevel(logging.NOTSET)
393
394    def test_specific_filters(self):
395        # Set a specific filter object on the handler, and then add another
396        #  filter object on the logger itself.
397        handler = self.root_logger.handlers[0]
398        specific_filter = None
399        garr = GarrulousFilter()
400        handler.addFilter(garr)
401        try:
402            self.log_at_all_levels(self.root_logger)
403            first_lines = [
404                # Notice how 'Garrulous' is missing
405                ('Boring', '1'),
406                ('Chatterbox', '2'),
407                ('Talkative', '4'),
408                ('Verbose', '5'),
409                ('Sociable', '6'),
410                ('Effusive', '7'),
411                ('Terse', '8'),
412                ('Taciturn', '9'),
413                ('Silent', '10'),
414            ]
415            self.assert_log_lines(first_lines)
416
417            specific_filter = VerySpecificFilter()
418            self.root_logger.addFilter(specific_filter)
419            self.log_at_all_levels(self.root_logger)
420            self.assert_log_lines(first_lines + [
421                # Not only 'Garrulous' is still missing, but also 'Sociable'
422                # and 'Taciturn'
423                ('Boring', '11'),
424                ('Chatterbox', '12'),
425                ('Talkative', '14'),
426                ('Verbose', '15'),
427                ('Effusive', '17'),
428                ('Terse', '18'),
429                ('Silent', '20'),
430        ])
431        finally:
432            if specific_filter:
433                self.root_logger.removeFilter(specific_filter)
434            handler.removeFilter(garr)
435
436
437class MemoryHandlerTest(BaseTest):
438
439    """Tests for the MemoryHandler."""
440
441    # Do not bother with a logger name group.
442    expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
443
444    def setUp(self):
445        BaseTest.setUp(self)
446        self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
447                                                        self.root_hdlr)
448        self.mem_logger = logging.getLogger('mem')
449        self.mem_logger.propagate = 0
450        self.mem_logger.addHandler(self.mem_hdlr)
451
452    def tearDown(self):
453        self.mem_hdlr.close()
454        BaseTest.tearDown(self)
455
456    def test_flush(self):
457        # The memory handler flushes to its target handler based on specific
458        #  criteria (message count and message level).
459        self.mem_logger.debug(self.next_message())
460        self.assert_log_lines([])
461        self.mem_logger.info(self.next_message())
462        self.assert_log_lines([])
463        # This will flush because the level is >= logging.WARNING
464        self.mem_logger.warn(self.next_message())
465        lines = [
466            ('DEBUG', '1'),
467            ('INFO', '2'),
468            ('WARNING', '3'),
469        ]
470        self.assert_log_lines(lines)
471        for n in (4, 14):
472            for i in range(9):
473                self.mem_logger.debug(self.next_message())
474            self.assert_log_lines(lines)
475            # This will flush because it's the 10th message since the last
476            #  flush.
477            self.mem_logger.debug(self.next_message())
478            lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
479            self.assert_log_lines(lines)
480
481        self.mem_logger.debug(self.next_message())
482        self.assert_log_lines(lines)
483
484
485class ExceptionFormatter(logging.Formatter):
486    """A special exception formatter."""
487    def formatException(self, ei):
488        return "Got a [%s]" % ei[0].__name__
489
490
491class ConfigFileTest(BaseTest):
492
493    """Reading logging config from a .ini-style config file."""
494
495    expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
496
497    # config0 is a standard configuration.
498    config0 = """
499    [loggers]
500    keys=root
501
502    [handlers]
503    keys=hand1
504
505    [formatters]
506    keys=form1
507
508    [logger_root]
509    level=WARNING
510    handlers=hand1
511
512    [handler_hand1]
513    class=StreamHandler
514    level=NOTSET
515    formatter=form1
516    args=(sys.stdout,)
517
518    [formatter_form1]
519    format=%(levelname)s ++ %(message)s
520    datefmt=
521    """
522
523    # config1 adds a little to the standard configuration.
524    config1 = """
525    [loggers]
526    keys=root,parser
527
528    [handlers]
529    keys=hand1
530
531    [formatters]
532    keys=form1
533
534    [logger_root]
535    level=WARNING
536    handlers=
537
538    [logger_parser]
539    level=DEBUG
540    handlers=hand1
541    propagate=1
542    qualname=compiler.parser
543
544    [handler_hand1]
545    class=StreamHandler
546    level=NOTSET
547    formatter=form1
548    args=(sys.stdout,)
549
550    [formatter_form1]
551    format=%(levelname)s ++ %(message)s
552    datefmt=
553    """
554
555    # config2 has a subtle configuration error that should be reported
556    config2 = config1.replace("sys.stdout", "sys.stbout")
557
558    # config3 has a less subtle configuration error
559    config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
560
561    # config4 specifies a custom formatter class to be loaded
562    config4 = """
563    [loggers]
564    keys=root
565
566    [handlers]
567    keys=hand1
568
569    [formatters]
570    keys=form1
571
572    [logger_root]
573    level=NOTSET
574    handlers=hand1
575
576    [handler_hand1]
577    class=StreamHandler
578    level=NOTSET
579    formatter=form1
580    args=(sys.stdout,)
581
582    [formatter_form1]
583    class=""" + __name__ + """.ExceptionFormatter
584    format=%(levelname)s:%(name)s:%(message)s
585    datefmt=
586    """
587
588    # config5 specifies a custom handler class to be loaded
589    config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
590
591    # config6 uses ', ' delimiters in the handlers and formatters sections
592    config6 = """
593    [loggers]
594    keys=root,parser
595
596    [handlers]
597    keys=hand1, hand2
598
599    [formatters]
600    keys=form1, form2
601
602    [logger_root]
603    level=WARNING
604    handlers=
605
606    [logger_parser]
607    level=DEBUG
608    handlers=hand1
609    propagate=1
610    qualname=compiler.parser
611
612    [handler_hand1]
613    class=StreamHandler
614    level=NOTSET
615    formatter=form1
616    args=(sys.stdout,)
617
618    [handler_hand2]
619    class=StreamHandler
620    level=NOTSET
621    formatter=form1
622    args=(sys.stderr,)
623
624    [formatter_form1]
625    format=%(levelname)s ++ %(message)s
626    datefmt=
627
628    [formatter_form2]
629    format=%(message)s
630    datefmt=
631    """
632
633    def apply_config(self, conf):
634        try:
635            fn = tempfile.mktemp(".ini")
636            f = open(fn, "w")
637            f.write(textwrap.dedent(conf))
638            f.close()
639            logging.config.fileConfig(fn)
640        finally:
641            os.remove(fn)
642
643    def test_config0_ok(self):
644        # A simple config file which overrides the default settings.
645        with captured_stdout() as output:
646            self.apply_config(self.config0)
647            logger = logging.getLogger()
648            # Won't output anything
649            logger.info(self.next_message())
650            # Outputs a message
651            logger.error(self.next_message())
652            self.assert_log_lines([
653                ('ERROR', '2'),
654            ], stream=output)
655            # Original logger output is empty.
656            self.assert_log_lines([])
657
658    def test_config1_ok(self, config=config1):
659        # A config file defining a sub-parser as well.
660        with captured_stdout() as output:
661            self.apply_config(config)
662            logger = logging.getLogger("compiler.parser")
663            # Both will output a message
664            logger.info(self.next_message())
665            logger.error(self.next_message())
666            self.assert_log_lines([
667                ('INFO', '1'),
668                ('ERROR', '2'),
669            ], stream=output)
670            # Original logger output is empty.
671            self.assert_log_lines([])
672
673    def test_config2_failure(self):
674        # A simple config file which overrides the default settings.
675        self.assertRaises(StandardError, self.apply_config, self.config2)
676
677    def test_config3_failure(self):
678        # A simple config file which overrides the default settings.
679        self.assertRaises(StandardError, self.apply_config, self.config3)
680
681    def test_config4_ok(self):
682        # A config file specifying a custom formatter class.
683        with captured_stdout() as output:
684            self.apply_config(self.config4)
685            logger = logging.getLogger()
686            try:
687                raise RuntimeError()
688            except RuntimeError:
689                logging.exception("just testing")
690            sys.stdout.seek(0)
691            self.assertEquals(output.getvalue(),
692                "ERROR:root:just testing\nGot a [RuntimeError]\n")
693            # Original logger output is empty
694            self.assert_log_lines([])
695
696    def test_config5_ok(self):
697        self.test_config1_ok(config=self.config5)
698
699    def test_config6_ok(self):
700        self.test_config1_ok(config=self.config6)
701
702class LogRecordStreamHandler(StreamRequestHandler):
703
704    """Handler for a streaming logging request. It saves the log message in the
705    TCP server's 'log_output' attribute."""
706
707    TCP_LOG_END = "!!!END!!!"
708
709    def handle(self):
710        """Handle multiple requests - each expected to be of 4-byte length,
711        followed by the LogRecord in pickle format. Logs the record
712        according to whatever policy is configured locally."""
713        while True:
714            chunk = self.connection.recv(4)
715            if len(chunk) < 4:
716                break
717            slen = struct.unpack(">L", chunk)[0]
718            chunk = self.connection.recv(slen)
719            while len(chunk) < slen:
720                chunk = chunk + self.connection.recv(slen - len(chunk))
721            obj = self.unpickle(chunk)
722            record = logging.makeLogRecord(obj)
723            self.handle_log_record(record)
724
725    def unpickle(self, data):
726        return cPickle.loads(data)
727
728    def handle_log_record(self, record):
729        # If the end-of-messages sentinel is seen, tell the server to
730        #  terminate.
731        if self.TCP_LOG_END in record.msg:
732            self.server.abort = 1
733            return
734        self.server.log_output += record.msg + "\n"
735
736
737class LogRecordSocketReceiver(ThreadingTCPServer):
738
739    """A simple-minded TCP socket-based logging receiver suitable for test
740    purposes."""
741
742    allow_reuse_address = 1
743    log_output = ""
744
745    def __init__(self, host='localhost',
746                             port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
747                     handler=LogRecordStreamHandler):
748        ThreadingTCPServer.__init__(self, (host, port), handler)
749        self.abort = False
750        self.timeout = 0.1
751        self.finished = threading.Event()
752
753    def serve_until_stopped(self):
754        while not self.abort:
755            rd, wr, ex = select.select([self.socket.fileno()], [], [],
756                                       self.timeout)
757            if rd:
758                self.handle_request()
759        # Notify the main thread that we're about to exit
760        self.finished.set()
761        # close the listen socket
762        self.server_close()
763
764
765class SocketHandlerTest(BaseTest):
766
767    """Test for SocketHandler objects."""
768
769    def setUp(self):
770        """Set up a TCP server to receive log messages, and a SocketHandler
771        pointing to that server's address and port."""
772        BaseTest.setUp(self)
773        self.tcpserver = LogRecordSocketReceiver(port=0)
774        self.port = self.tcpserver.socket.getsockname()[1]
775        self.threads = [
776                threading.Thread(target=self.tcpserver.serve_until_stopped)]
777        for thread in self.threads:
778            thread.start()
779
780        self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port)
781        self.sock_hdlr.setFormatter(self.root_formatter)
782        self.root_logger.removeHandler(self.root_logger.handlers[0])
783        self.root_logger.addHandler(self.sock_hdlr)
784
785    def tearDown(self):
786        """Shutdown the TCP server."""
787        try:
788            self.tcpserver.abort = True
789            del self.tcpserver
790            self.root_logger.removeHandler(self.sock_hdlr)
791            self.sock_hdlr.close()
792            for thread in self.threads:
793                thread.join(2.0)
794        finally:
795            BaseTest.tearDown(self)
796
797    def get_output(self):
798        """Get the log output as received by the TCP server."""
799        # Signal the TCP receiver and wait for it to terminate.
800        self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END)
801        self.tcpserver.finished.wait(2.0)
802        return self.tcpserver.log_output
803
804    def test_output(self):
805        # The log message sent to the SocketHandler is properly received.
806        logger = logging.getLogger("tcp")
807        logger.error("spam")
808        logger.debug("eggs")
809        self.assertEquals(self.get_output(), "spam\neggs\n")
810
811
812class MemoryTest(BaseTest):
813
814    """Test memory persistence of logger objects."""
815
816    def setUp(self):
817        """Create a dict to remember potentially destroyed objects."""
818        BaseTest.setUp(self)
819        self._survivors = {}
820
821    def _watch_for_survival(self, *args):
822        """Watch the given objects for survival, by creating weakrefs to
823        them."""
824        for obj in args:
825            key = id(obj), repr(obj)
826            self._survivors[key] = weakref.ref(obj)
827
828    def _assert_survival(self):
829        """Assert that all objects watched for survival have survived."""
830        # Trigger cycle breaking.
831        gc.collect()
832        dead = []
833        for (id_, repr_), ref in self._survivors.items():
834            if ref() is None:
835                dead.append(repr_)
836        if dead:
837            self.fail("%d objects should have survived "
838                "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
839
840    def test_persistent_loggers(self):
841        # Logger objects are persistent and retain their configuration, even
842        #  if visible references are destroyed.
843        self.root_logger.setLevel(logging.INFO)
844        foo = logging.getLogger("foo")
845        self._watch_for_survival(foo)
846        foo.setLevel(logging.DEBUG)
847        self.root_logger.debug(self.next_message())
848        foo.debug(self.next_message())
849        self.assert_log_lines([
850            ('foo', 'DEBUG', '2'),
851        ])
852        del foo
853        # foo has survived.
854        self._assert_survival()
855        # foo has retained its settings.
856        bar = logging.getLogger("foo")
857        bar.debug(self.next_message())
858        self.assert_log_lines([
859            ('foo', 'DEBUG', '2'),
860            ('foo', 'DEBUG', '3'),
861        ])
862
863
864class EncodingTest(BaseTest):
865    def test_encoding_plain_file(self):
866        # In Python 2.x, a plain file object is treated as having no encoding.
867        log = logging.getLogger("test")
868        fn = tempfile.mktemp(".log")
869        # the non-ascii data we write to the log.
870        data = "foo\x80"
871        try:
872            handler = logging.FileHandler(fn)
873            log.addHandler(handler)
874            try:
875                # write non-ascii data to the log.
876                log.warning(data)
877            finally:
878                log.removeHandler(handler)
879                handler.close()
880            # check we wrote exactly those bytes, ignoring trailing \n etc
881            f = open(fn)
882            try:
883                self.failUnlessEqual(f.read().rstrip(), data)
884            finally:
885                f.close()
886        finally:
887            if os.path.isfile(fn):
888                os.remove(fn)
889
890    def test_encoding_cyrillic_unicode(self):
891        log = logging.getLogger("test")
892        #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
893        message = u'\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
894        #Ensure it's written in a Cyrillic encoding
895        writer_class = codecs.getwriter('cp1251')
896        writer_class.encoding = 'cp1251'
897        stream = cStringIO.StringIO()
898        writer = writer_class(stream, 'strict')
899        handler = logging.StreamHandler(writer)
900        log.addHandler(handler)
901        try:
902            log.warning(message)
903        finally:
904            log.removeHandler(handler)
905            handler.close()
906        # check we wrote exactly those bytes, ignoring trailing \n etc
907        s = stream.getvalue()
908        #Compare against what the data should be when encoded in CP-1251
909        self.assertEqual(s, '\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
910
911
912# Set the locale to the platform-dependent default.  I have no idea
913# why the test does this, but in any case we save the current locale
914# first and restore it at the end.
915@run_with_locale('LC_ALL', '')
916def test_main():
917    run_unittest(BuiltinLevelsTest, BasicFilterTest,
918                    CustomLevelsAndFiltersTest, MemoryHandlerTest,
919                    ConfigFileTest, SocketHandlerTest, MemoryTest,
920                    EncodingTest)
921
922if __name__ == "__main__":
923    test_main()