blob: dc49fc16c76fca4b7ebc4dc86f35f346292b1f7b [file] [log] [blame]
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001#!/usr/bin/env python
Christian Heimes180510d2008-03-03 19:15:45 +00002#
Vinay Sajip66b8b082012-04-24 23:25:30 +01003# Copyright 2001-2012 by Vinay Sajip. All Rights Reserved.
Christian Heimes180510d2008-03-03 19:15:45 +00004#
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
Vinay Sajip66b8b082012-04-24 23:25:30 +010021Copyright (C) 2001-2012 Vinay Sajip. All Rights Reserved.
Neal Norwitzb4a2df02003-01-02 14:56:39 +000022"""
23
Christian Heimes180510d2008-03-03 19:15:45 +000024import logging
25import logging.handlers
26import logging.config
Christian Heimes18c66892008-02-17 13:31:39 +000027
Benjamin Petersonf91df042009-02-13 02:50:59 +000028import codecs
Vinay Sajip19ec67a2010-09-17 18:57:36 +000029import datetime
Christian Heimes180510d2008-03-03 19:15:45 +000030import pickle
31import io
32import gc
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000033import json
Christian Heimes180510d2008-03-03 19:15:45 +000034import os
Vinay Sajip8552d1f2010-09-14 09:34:09 +000035import queue
Vinay Sajip66b8b082012-04-24 23:25:30 +010036import random
Christian Heimes180510d2008-03-03 19:15:45 +000037import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000038import select
Christian Heimes180510d2008-03-03 19:15:45 +000039import socket
Christian Heimes180510d2008-03-03 19:15:45 +000040import struct
41import sys
42import tempfile
Eric V. Smith851cad72012-03-11 22:46:04 -070043from test.support import (captured_stdout, run_with_locale, run_unittest,
44 patch, requires_zlib, TestHandler, Matcher)
Christian Heimes180510d2008-03-03 19:15:45 +000045import textwrap
Vinay Sajip37eb3382011-04-26 20:26:41 +010046import time
Christian Heimes180510d2008-03-03 19:15:45 +000047import unittest
Georg Brandlf9734072008-12-07 15:30:06 +000048import warnings
Christian Heimes180510d2008-03-03 19:15:45 +000049import weakref
Victor Stinner45df8202010-04-28 22:31:17 +000050try:
51 import threading
Vinay Sajipce7c9782011-05-17 07:15:53 +010052 # The following imports are needed only for tests which
Florent Xicluna5252f9f2011-11-07 19:43:05 +010053 # require threading
Vinay Sajipce7c9782011-05-17 07:15:53 +010054 import asynchat
55 import asyncore
56 import errno
57 from http.server import HTTPServer, BaseHTTPRequestHandler
58 import smtpd
59 from urllib.parse import urlparse, parse_qs
60 from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
61 ThreadingTCPServer, StreamRequestHandler)
Victor Stinner45df8202010-04-28 22:31:17 +000062except ImportError:
63 threading = None
Vinay Sajip60ccd822011-05-09 17:32:09 +010064try:
65 import win32evtlog
66except ImportError:
67 win32evtlog = None
68try:
69 import win32evtlogutil
70except ImportError:
71 win32evtlogutil = None
72 win32evtlog = None
Eric V. Smith851cad72012-03-11 22:46:04 -070073try:
74 import zlib
75except ImportError:
76 pass
Christian Heimes18c66892008-02-17 13:31:39 +000077
78
Christian Heimes180510d2008-03-03 19:15:45 +000079class BaseTest(unittest.TestCase):
80
81 """Base class for logging tests."""
82
83 log_format = "%(name)s -> %(levelname)s: %(message)s"
Ezio Melotti3ffd29b2012-10-02 19:45:00 +030084 expected_log_pat = r"^([\w.]+) -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +000085 message_num = 0
86
87 def setUp(self):
88 """Setup the default logging stream to an internal StringIO instance,
89 so that we can examine log output as we want."""
90 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000091 logging._acquireLock()
92 try:
Christian Heimes180510d2008-03-03 19:15:45 +000093 self.saved_handlers = logging._handlers.copy()
94 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000095 self.saved_loggers = saved_loggers = logger_dict.copy()
Christian Heimes180510d2008-03-03 19:15:45 +000096 self.saved_level_names = logging._levelNames.copy()
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000097 self.logger_states = logger_states = {}
98 for name in saved_loggers:
99 logger_states[name] = getattr(saved_loggers[name],
100 'disabled', None)
Christian Heimes18c66892008-02-17 13:31:39 +0000101 finally:
102 logging._releaseLock()
103
Florent Xicluna5252f9f2011-11-07 19:43:05 +0100104 # Set two unused loggers
Vinay Sajipb4a08092010-09-20 09:55:00 +0000105 self.logger1 = logging.getLogger("\xab\xd7\xbb")
106 self.logger2 = logging.getLogger("\u013f\u00d6\u0047")
Benjamin Peterson22005fc2010-04-11 16:25:06 +0000107
Christian Heimes180510d2008-03-03 19:15:45 +0000108 self.root_logger = logging.getLogger("")
109 self.original_logging_level = self.root_logger.getEffectiveLevel()
110
111 self.stream = io.StringIO()
112 self.root_logger.setLevel(logging.DEBUG)
113 self.root_hdlr = logging.StreamHandler(self.stream)
114 self.root_formatter = logging.Formatter(self.log_format)
115 self.root_hdlr.setFormatter(self.root_formatter)
Vinay Sajip7b0e86e2010-12-30 23:26:50 +0000116 if self.logger1.hasHandlers():
117 hlist = self.logger1.handlers + self.root_logger.handlers
118 raise AssertionError('Unexpected handlers: %s' % hlist)
119 if self.logger2.hasHandlers():
120 hlist = self.logger2.handlers + self.root_logger.handlers
121 raise AssertionError('Unexpected handlers: %s' % hlist)
Christian Heimes180510d2008-03-03 19:15:45 +0000122 self.root_logger.addHandler(self.root_hdlr)
Vinay Sajipb4a08092010-09-20 09:55:00 +0000123 self.assertTrue(self.logger1.hasHandlers())
124 self.assertTrue(self.logger2.hasHandlers())
Christian Heimes180510d2008-03-03 19:15:45 +0000125
126 def tearDown(self):
127 """Remove our logging stream, and restore the original logging
128 level."""
129 self.stream.close()
130 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000131 while self.root_logger.handlers:
132 h = self.root_logger.handlers[0]
133 self.root_logger.removeHandler(h)
134 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +0000135 self.root_logger.setLevel(self.original_logging_level)
136 logging._acquireLock()
137 try:
138 logging._levelNames.clear()
139 logging._levelNames.update(self.saved_level_names)
140 logging._handlers.clear()
141 logging._handlers.update(self.saved_handlers)
142 logging._handlerList[:] = self.saved_handler_list
143 loggerDict = logging.getLogger().manager.loggerDict
144 loggerDict.clear()
145 loggerDict.update(self.saved_loggers)
Vinay Sajip7b60f4e2010-12-27 14:31:52 +0000146 logger_states = self.logger_states
147 for name in self.logger_states:
148 if logger_states[name] is not None:
149 self.saved_loggers[name].disabled = logger_states[name]
Christian Heimes180510d2008-03-03 19:15:45 +0000150 finally:
151 logging._releaseLock()
152
Vinay Sajip4ded5512012-10-02 15:56:16 +0100153 def assert_log_lines(self, expected_values, stream=None, pat=None):
Christian Heimes180510d2008-03-03 19:15:45 +0000154 """Match the collected log lines against the regular expression
155 self.expected_log_pat, and compare the extracted group values to
156 the expected_values list of tuples."""
157 stream = stream or self.stream
Vinay Sajip4ded5512012-10-02 15:56:16 +0100158 pat = re.compile(pat or self.expected_log_pat)
Christian Heimes180510d2008-03-03 19:15:45 +0000159 try:
Vinay Sajip4ded5512012-10-02 15:56:16 +0100160 if hasattr(stream, 'reset'):
161 stream.reset()
162 elif hasattr(stream, 'seek'):
163 stream.seek(0)
Christian Heimes180510d2008-03-03 19:15:45 +0000164 actual_lines = stream.readlines()
165 except AttributeError:
166 # StringIO.StringIO lacks a reset() method.
167 actual_lines = stream.getvalue().splitlines()
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100168 self.assertEqual(len(actual_lines), len(expected_values))
Christian Heimes180510d2008-03-03 19:15:45 +0000169 for actual, expected in zip(actual_lines, expected_values):
170 match = pat.search(actual)
171 if not match:
172 self.fail("Log line does not match expected pattern:\n" +
173 actual)
Ezio Melottib3aedd42010-11-20 19:04:17 +0000174 self.assertEqual(tuple(match.groups()), expected)
Christian Heimes180510d2008-03-03 19:15:45 +0000175 s = stream.read()
176 if s:
177 self.fail("Remaining output at end of log stream:\n" + s)
178
179 def next_message(self):
180 """Generate a message consisting solely of an auto-incrementing
181 integer."""
182 self.message_num += 1
183 return "%d" % self.message_num
184
185
186class BuiltinLevelsTest(BaseTest):
187 """Test builtin levels and their inheritance."""
188
189 def test_flat(self):
190 #Logging levels in a flat logger namespace.
191 m = self.next_message
192
193 ERR = logging.getLogger("ERR")
194 ERR.setLevel(logging.ERROR)
Vinay Sajipc84f0162010-09-21 11:25:39 +0000195 INF = logging.LoggerAdapter(logging.getLogger("INF"), {})
Christian Heimes180510d2008-03-03 19:15:45 +0000196 INF.setLevel(logging.INFO)
197 DEB = logging.getLogger("DEB")
198 DEB.setLevel(logging.DEBUG)
199
200 # These should log.
201 ERR.log(logging.CRITICAL, m())
202 ERR.error(m())
203
204 INF.log(logging.CRITICAL, m())
205 INF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100206 INF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000207 INF.info(m())
208
209 DEB.log(logging.CRITICAL, m())
210 DEB.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100211 DEB.warning(m())
212 DEB.info(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000213 DEB.debug(m())
214
215 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100216 ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000217 ERR.info(m())
218 ERR.debug(m())
219
220 INF.debug(m())
221
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000222 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000223 ('ERR', 'CRITICAL', '1'),
224 ('ERR', 'ERROR', '2'),
225 ('INF', 'CRITICAL', '3'),
226 ('INF', 'ERROR', '4'),
227 ('INF', 'WARNING', '5'),
228 ('INF', 'INFO', '6'),
229 ('DEB', 'CRITICAL', '7'),
230 ('DEB', 'ERROR', '8'),
231 ('DEB', 'WARNING', '9'),
232 ('DEB', 'INFO', '10'),
233 ('DEB', 'DEBUG', '11'),
234 ])
235
236 def test_nested_explicit(self):
237 # Logging levels in a nested namespace, all explicitly set.
238 m = self.next_message
239
240 INF = logging.getLogger("INF")
241 INF.setLevel(logging.INFO)
242 INF_ERR = logging.getLogger("INF.ERR")
243 INF_ERR.setLevel(logging.ERROR)
244
245 # These should log.
246 INF_ERR.log(logging.CRITICAL, m())
247 INF_ERR.error(m())
248
249 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100250 INF_ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000251 INF_ERR.info(m())
252 INF_ERR.debug(m())
253
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000254 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000255 ('INF.ERR', 'CRITICAL', '1'),
256 ('INF.ERR', 'ERROR', '2'),
257 ])
258
259 def test_nested_inherited(self):
260 #Logging levels in a nested namespace, inherited from parent loggers.
261 m = self.next_message
262
263 INF = logging.getLogger("INF")
264 INF.setLevel(logging.INFO)
265 INF_ERR = logging.getLogger("INF.ERR")
266 INF_ERR.setLevel(logging.ERROR)
267 INF_UNDEF = logging.getLogger("INF.UNDEF")
268 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
269 UNDEF = logging.getLogger("UNDEF")
270
271 # These should log.
272 INF_UNDEF.log(logging.CRITICAL, m())
273 INF_UNDEF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100274 INF_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000275 INF_UNDEF.info(m())
276 INF_ERR_UNDEF.log(logging.CRITICAL, m())
277 INF_ERR_UNDEF.error(m())
278
279 # These should not log.
280 INF_UNDEF.debug(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100281 INF_ERR_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000282 INF_ERR_UNDEF.info(m())
283 INF_ERR_UNDEF.debug(m())
284
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000285 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000286 ('INF.UNDEF', 'CRITICAL', '1'),
287 ('INF.UNDEF', 'ERROR', '2'),
288 ('INF.UNDEF', 'WARNING', '3'),
289 ('INF.UNDEF', 'INFO', '4'),
290 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
291 ('INF.ERR.UNDEF', 'ERROR', '6'),
292 ])
293
294 def test_nested_with_virtual_parent(self):
295 # Logging levels when some parent does not exist yet.
296 m = self.next_message
297
298 INF = logging.getLogger("INF")
299 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
300 CHILD = logging.getLogger("INF.BADPARENT")
301 INF.setLevel(logging.INFO)
302
303 # These should log.
304 GRANDCHILD.log(logging.FATAL, m())
305 GRANDCHILD.info(m())
306 CHILD.log(logging.FATAL, m())
307 CHILD.info(m())
308
309 # These should not log.
310 GRANDCHILD.debug(m())
311 CHILD.debug(m())
312
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000313 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000314 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
315 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
316 ('INF.BADPARENT', 'CRITICAL', '3'),
317 ('INF.BADPARENT', 'INFO', '4'),
318 ])
319
320
321class BasicFilterTest(BaseTest):
322
323 """Test the bundled Filter class."""
324
325 def test_filter(self):
326 # Only messages satisfying the specified criteria pass through the
327 # filter.
328 filter_ = logging.Filter("spam.eggs")
329 handler = self.root_logger.handlers[0]
330 try:
331 handler.addFilter(filter_)
332 spam = logging.getLogger("spam")
333 spam_eggs = logging.getLogger("spam.eggs")
334 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
335 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
336
337 spam.info(self.next_message())
338 spam_eggs.info(self.next_message()) # Good.
339 spam_eggs_fish.info(self.next_message()) # Good.
340 spam_bakedbeans.info(self.next_message())
341
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000342 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000343 ('spam.eggs', 'INFO', '2'),
344 ('spam.eggs.fish', 'INFO', '3'),
345 ])
346 finally:
347 handler.removeFilter(filter_)
348
Vinay Sajip6dbed2e2010-10-19 20:53:01 +0000349 def test_callable_filter(self):
350 # Only messages satisfying the specified criteria pass through the
351 # filter.
352
353 def filterfunc(record):
354 parts = record.name.split('.')
355 prefix = '.'.join(parts[:2])
356 return prefix == 'spam.eggs'
357
358 handler = self.root_logger.handlers[0]
359 try:
360 handler.addFilter(filterfunc)
361 spam = logging.getLogger("spam")
362 spam_eggs = logging.getLogger("spam.eggs")
363 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
364 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
365
366 spam.info(self.next_message())
367 spam_eggs.info(self.next_message()) # Good.
368 spam_eggs_fish.info(self.next_message()) # Good.
369 spam_bakedbeans.info(self.next_message())
370
371 self.assert_log_lines([
372 ('spam.eggs', 'INFO', '2'),
373 ('spam.eggs.fish', 'INFO', '3'),
374 ])
375 finally:
376 handler.removeFilter(filterfunc)
377
Vinay Sajip985ef872011-04-26 19:34:04 +0100378 def test_empty_filter(self):
379 f = logging.Filter()
380 r = logging.makeLogRecord({'name': 'spam.eggs'})
381 self.assertTrue(f.filter(r))
Christian Heimes180510d2008-03-03 19:15:45 +0000382
383#
384# First, we define our levels. There can be as many as you want - the only
385# limitations are that they should be integers, the lowest should be > 0 and
386# larger values mean less information being logged. If you need specific
387# level values which do not fit into these limitations, you can use a
388# mapping dictionary to convert between your application levels and the
389# logging system.
390#
391SILENT = 120
392TACITURN = 119
393TERSE = 118
394EFFUSIVE = 117
395SOCIABLE = 116
396VERBOSE = 115
397TALKATIVE = 114
398GARRULOUS = 113
399CHATTERBOX = 112
400BORING = 111
401
402LEVEL_RANGE = range(BORING, SILENT + 1)
403
404#
405# Next, we define names for our levels. You don't need to do this - in which
406# case the system will use "Level n" to denote the text for the level.
407#
408my_logging_levels = {
409 SILENT : 'Silent',
410 TACITURN : 'Taciturn',
411 TERSE : 'Terse',
412 EFFUSIVE : 'Effusive',
413 SOCIABLE : 'Sociable',
414 VERBOSE : 'Verbose',
415 TALKATIVE : 'Talkative',
416 GARRULOUS : 'Garrulous',
417 CHATTERBOX : 'Chatterbox',
418 BORING : 'Boring',
419}
420
421class GarrulousFilter(logging.Filter):
422
423 """A filter which blocks garrulous messages."""
424
425 def filter(self, record):
426 return record.levelno != GARRULOUS
427
428class VerySpecificFilter(logging.Filter):
429
430 """A filter which blocks sociable and taciturn messages."""
431
432 def filter(self, record):
433 return record.levelno not in [SOCIABLE, TACITURN]
434
435
436class CustomLevelsAndFiltersTest(BaseTest):
437
438 """Test various filtering possibilities with custom logging levels."""
439
440 # Skip the logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +0300441 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +0000442
443 def setUp(self):
444 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000445 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000446 logging.addLevelName(k, v)
447
448 def log_at_all_levels(self, logger):
449 for lvl in LEVEL_RANGE:
450 logger.log(lvl, self.next_message())
451
452 def test_logger_filter(self):
453 # Filter at logger level.
454 self.root_logger.setLevel(VERBOSE)
455 # Levels >= 'Verbose' are good.
456 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000457 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000458 ('Verbose', '5'),
459 ('Sociable', '6'),
460 ('Effusive', '7'),
461 ('Terse', '8'),
462 ('Taciturn', '9'),
463 ('Silent', '10'),
464 ])
465
466 def test_handler_filter(self):
467 # Filter at handler level.
468 self.root_logger.handlers[0].setLevel(SOCIABLE)
469 try:
470 # Levels >= 'Sociable' are good.
471 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000472 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000473 ('Sociable', '6'),
474 ('Effusive', '7'),
475 ('Terse', '8'),
476 ('Taciturn', '9'),
477 ('Silent', '10'),
478 ])
479 finally:
480 self.root_logger.handlers[0].setLevel(logging.NOTSET)
481
482 def test_specific_filters(self):
483 # Set a specific filter object on the handler, and then add another
484 # filter object on the logger itself.
485 handler = self.root_logger.handlers[0]
486 specific_filter = None
487 garr = GarrulousFilter()
488 handler.addFilter(garr)
489 try:
490 self.log_at_all_levels(self.root_logger)
491 first_lines = [
492 # Notice how 'Garrulous' is missing
493 ('Boring', '1'),
494 ('Chatterbox', '2'),
495 ('Talkative', '4'),
496 ('Verbose', '5'),
497 ('Sociable', '6'),
498 ('Effusive', '7'),
499 ('Terse', '8'),
500 ('Taciturn', '9'),
501 ('Silent', '10'),
502 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000503 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000504
505 specific_filter = VerySpecificFilter()
506 self.root_logger.addFilter(specific_filter)
507 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000508 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000509 # Not only 'Garrulous' is still missing, but also 'Sociable'
510 # and 'Taciturn'
511 ('Boring', '11'),
512 ('Chatterbox', '12'),
513 ('Talkative', '14'),
514 ('Verbose', '15'),
515 ('Effusive', '17'),
516 ('Terse', '18'),
517 ('Silent', '20'),
518 ])
519 finally:
520 if specific_filter:
521 self.root_logger.removeFilter(specific_filter)
522 handler.removeFilter(garr)
523
524
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100525class HandlerTest(BaseTest):
526 def test_name(self):
527 h = logging.Handler()
528 h.name = 'generic'
529 self.assertEqual(h.name, 'generic')
530 h.name = 'anothergeneric'
531 self.assertEqual(h.name, 'anothergeneric')
532 self.assertRaises(NotImplementedError, h.emit, None)
533
Vinay Sajip5a35b062011-04-27 11:31:14 +0100534 def test_builtin_handlers(self):
535 # We can't actually *use* too many handlers in the tests,
536 # but we can try instantiating them with various options
Victor Stinnere6747472011-08-21 00:39:18 +0200537 if sys.platform in ('linux', 'darwin'):
Vinay Sajip5a35b062011-04-27 11:31:14 +0100538 for existing in (True, False):
539 fd, fn = tempfile.mkstemp()
540 os.close(fd)
541 if not existing:
542 os.unlink(fn)
543 h = logging.handlers.WatchedFileHandler(fn, delay=True)
544 if existing:
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100545 dev, ino = h.dev, h.ino
Vinay Sajipa5798de2012-04-24 23:33:33 +0100546 self.assertEqual(dev, -1)
547 self.assertEqual(ino, -1)
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100548 r = logging.makeLogRecord({'msg': 'Test'})
549 h.handle(r)
550 # Now remove the file.
551 os.unlink(fn)
552 self.assertFalse(os.path.exists(fn))
553 # The next call should recreate the file.
554 h.handle(r)
555 self.assertTrue(os.path.exists(fn))
Vinay Sajip5a35b062011-04-27 11:31:14 +0100556 else:
557 self.assertEqual(h.dev, -1)
558 self.assertEqual(h.ino, -1)
559 h.close()
560 if existing:
561 os.unlink(fn)
562 if sys.platform == 'darwin':
Vinay Sajip6bba65c2011-04-27 14:31:55 +0100563 sockname = '/var/run/syslog'
Vinay Sajip5a35b062011-04-27 11:31:14 +0100564 else:
565 sockname = '/dev/log'
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100566 try:
567 h = logging.handlers.SysLogHandler(sockname)
568 self.assertEqual(h.facility, h.LOG_USER)
569 self.assertTrue(h.unixsocket)
570 h.close()
571 except socket.error: # syslogd might not be available
572 pass
Vinay Sajip5a35b062011-04-27 11:31:14 +0100573 for method in ('GET', 'POST', 'PUT'):
574 if method == 'PUT':
575 self.assertRaises(ValueError, logging.handlers.HTTPHandler,
576 'localhost', '/log', method)
577 else:
578 h = logging.handlers.HTTPHandler('localhost', '/log', method)
579 h.close()
580 h = logging.handlers.BufferingHandler(0)
581 r = logging.makeLogRecord({})
582 self.assertTrue(h.shouldFlush(r))
583 h.close()
584 h = logging.handlers.BufferingHandler(1)
585 self.assertFalse(h.shouldFlush(r))
586 h.close()
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100587
Vinay Sajip5e86eed2012-05-29 22:48:10 +0100588 @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.')
Vinay Sajipa5798de2012-04-24 23:33:33 +0100589 @unittest.skipUnless(threading, 'Threading required for this test.')
590 def test_race(self):
591 # Issue #14632 refers.
592 def remove_loop(fname, tries):
593 for _ in range(tries):
594 try:
595 os.unlink(fname)
596 except OSError:
597 pass
598 time.sleep(0.004 * random.randint(0, 4))
599
Vinay Sajipc94871a2012-04-25 10:51:35 +0100600 del_count = 500
601 log_count = 500
Vinay Sajipa5798de2012-04-24 23:33:33 +0100602
Vinay Sajipa5798de2012-04-24 23:33:33 +0100603 for delay in (False, True):
Vinay Sajipc94871a2012-04-25 10:51:35 +0100604 fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
605 os.close(fd)
606 remover = threading.Thread(target=remove_loop, args=(fn, del_count))
607 remover.daemon = True
608 remover.start()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100609 h = logging.handlers.WatchedFileHandler(fn, delay=delay)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100610 f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
611 h.setFormatter(f)
Vinay Sajipc94871a2012-04-25 10:51:35 +0100612 try:
613 for _ in range(log_count):
614 time.sleep(0.005)
615 r = logging.makeLogRecord({'msg': 'testing' })
616 h.handle(r)
617 finally:
Vinay Sajipc94871a2012-04-25 10:51:35 +0100618 remover.join()
Vinay Sajipac20f462012-05-03 12:09:38 +0100619 h.close()
Vinay Sajipc94871a2012-04-25 10:51:35 +0100620 if os.path.exists(fn):
621 os.unlink(fn)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100622
623
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100624class BadStream(object):
625 def write(self, data):
626 raise RuntimeError('deliberate mistake')
627
628class TestStreamHandler(logging.StreamHandler):
629 def handleError(self, record):
630 self.error_record = record
631
632class StreamHandlerTest(BaseTest):
633 def test_error_handling(self):
634 h = TestStreamHandler(BadStream())
635 r = logging.makeLogRecord({})
636 old_raise = logging.raiseExceptions
Vinay Sajip985ef872011-04-26 19:34:04 +0100637 old_stderr = sys.stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100638 try:
639 h.handle(r)
640 self.assertIs(h.error_record, r)
Vinay Sajip985ef872011-04-26 19:34:04 +0100641 h = logging.StreamHandler(BadStream())
642 sys.stderr = sio = io.StringIO()
643 h.handle(r)
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100644 self.assertIn('\nRuntimeError: deliberate mistake\n',
645 sio.getvalue())
Vinay Sajip985ef872011-04-26 19:34:04 +0100646 logging.raiseExceptions = False
647 sys.stderr = sio = io.StringIO()
648 h.handle(r)
649 self.assertEqual('', sio.getvalue())
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100650 finally:
651 logging.raiseExceptions = old_raise
Vinay Sajip985ef872011-04-26 19:34:04 +0100652 sys.stderr = old_stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100653
Vinay Sajip7367d082011-05-02 13:17:27 +0100654# -- The following section could be moved into a server_helper.py module
655# -- if it proves to be of wider utility than just test_logging
Vinay Sajipa463d252011-04-30 21:52:48 +0100656
Vinay Sajipce7c9782011-05-17 07:15:53 +0100657if threading:
658 class TestSMTPChannel(smtpd.SMTPChannel):
Vinay Sajip314b92b2011-05-02 14:31:16 +0100659 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100660 This derived class has had to be created because smtpd does not
661 support use of custom channel maps, although they are allowed by
662 asyncore's design. Issue #11959 has been raised to address this,
663 and if resolved satisfactorily, some of this code can be removed.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100664 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100665 def __init__(self, server, conn, addr, sockmap):
666 asynchat.async_chat.__init__(self, conn, sockmap)
667 self.smtp_server = server
668 self.conn = conn
669 self.addr = addr
R David Murrayd1a30c92012-05-26 14:33:59 -0400670 self.data_size_limit = None
Vinay Sajipce7c9782011-05-17 07:15:53 +0100671 self.received_lines = []
672 self.smtp_state = self.COMMAND
673 self.seen_greeting = ''
674 self.mailfrom = None
675 self.rcpttos = []
676 self.received_data = ''
677 self.fqdn = socket.getfqdn()
678 self.num_bytes = 0
679 try:
680 self.peer = conn.getpeername()
681 except socket.error as err:
682 # a race condition may occur if the other end is closing
683 # before we can get the peername
684 self.close()
685 if err.args[0] != errno.ENOTCONN:
686 raise
687 return
688 self.push('220 %s %s' % (self.fqdn, smtpd.__version__))
689 self.set_terminator(b'\r\n')
R David Murrayd1a30c92012-05-26 14:33:59 -0400690 self.extended_smtp = False
Vinay Sajipa463d252011-04-30 21:52:48 +0100691
Vinay Sajip314b92b2011-05-02 14:31:16 +0100692
Vinay Sajipce7c9782011-05-17 07:15:53 +0100693 class TestSMTPServer(smtpd.SMTPServer):
Vinay Sajip314b92b2011-05-02 14:31:16 +0100694 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100695 This class implements a test SMTP server.
Vinay Sajipa463d252011-04-30 21:52:48 +0100696
Vinay Sajipce7c9782011-05-17 07:15:53 +0100697 :param addr: A (host, port) tuple which the server listens on.
698 You can specify a port value of zero: the server's
699 *port* attribute will hold the actual port number
700 used, which can be used in client connections.
701 :param handler: A callable which will be called to process
702 incoming messages. The handler will be passed
703 the client address tuple, who the message is from,
704 a list of recipients and the message data.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100705 :param poll_interval: The interval, in seconds, used in the underlying
706 :func:`select` or :func:`poll` call by
707 :func:`asyncore.loop`.
Vinay Sajipce7c9782011-05-17 07:15:53 +0100708 :param sockmap: A dictionary which will be used to hold
709 :class:`asyncore.dispatcher` instances used by
710 :func:`asyncore.loop`. This avoids changing the
711 :mod:`asyncore` module's global state.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100712 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100713 channel_class = TestSMTPChannel
714
715 def __init__(self, addr, handler, poll_interval, sockmap):
716 self._localaddr = addr
717 self._remoteaddr = None
R David Murrayd1a30c92012-05-26 14:33:59 -0400718 self.data_size_limit = None
Vinay Sajipce7c9782011-05-17 07:15:53 +0100719 self.sockmap = sockmap
720 asyncore.dispatcher.__init__(self, map=sockmap)
721 try:
722 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
723 sock.setblocking(0)
724 self.set_socket(sock, map=sockmap)
725 # try to re-use a server port if possible
726 self.set_reuse_addr()
727 self.bind(addr)
728 self.port = sock.getsockname()[1]
729 self.listen(5)
730 except:
731 self.close()
Vinay Sajipe73afad2011-05-10 07:48:28 +0100732 raise
Vinay Sajipce7c9782011-05-17 07:15:53 +0100733 self._handler = handler
734 self._thread = None
735 self.poll_interval = poll_interval
Vinay Sajipa463d252011-04-30 21:52:48 +0100736
Vinay Sajipce7c9782011-05-17 07:15:53 +0100737 def handle_accepted(self, conn, addr):
738 """
739 Redefined only because the base class does not pass in a
740 map, forcing use of a global in :mod:`asyncore`.
741 """
742 channel = self.channel_class(self, conn, addr, self.sockmap)
Vinay Sajip314b92b2011-05-02 14:31:16 +0100743
Vinay Sajipce7c9782011-05-17 07:15:53 +0100744 def process_message(self, peer, mailfrom, rcpttos, data):
745 """
746 Delegates to the handler passed in to the server's constructor.
Vinay Sajipa463d252011-04-30 21:52:48 +0100747
Vinay Sajipce7c9782011-05-17 07:15:53 +0100748 Typically, this will be a test case method.
749 :param peer: The client (host, port) tuple.
750 :param mailfrom: The address of the sender.
751 :param rcpttos: The addresses of the recipients.
752 :param data: The message.
753 """
754 self._handler(peer, mailfrom, rcpttos, data)
Vinay Sajip7367d082011-05-02 13:17:27 +0100755
Vinay Sajipce7c9782011-05-17 07:15:53 +0100756 def start(self):
757 """
758 Start the server running on a separate daemon thread.
759 """
760 self._thread = t = threading.Thread(target=self.serve_forever,
761 args=(self.poll_interval,))
762 t.setDaemon(True)
763 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100764
Vinay Sajipce7c9782011-05-17 07:15:53 +0100765 def serve_forever(self, poll_interval):
766 """
767 Run the :mod:`asyncore` loop until normal termination
768 conditions arise.
769 :param poll_interval: The interval, in seconds, used in the underlying
770 :func:`select` or :func:`poll` call by
771 :func:`asyncore.loop`.
772 """
773 try:
774 asyncore.loop(poll_interval, map=self.sockmap)
775 except select.error:
776 # On FreeBSD 8, closing the server repeatably
777 # raises this error. We swallow it if the
778 # server has been closed.
779 if self.connected or self.accepting:
780 raise
Vinay Sajip7367d082011-05-02 13:17:27 +0100781
Vinay Sajipce7c9782011-05-17 07:15:53 +0100782 def stop(self, timeout=None):
783 """
784 Stop the thread by closing the server instance.
785 Wait for the server thread to terminate.
Vinay Sajip7367d082011-05-02 13:17:27 +0100786
Vinay Sajipce7c9782011-05-17 07:15:53 +0100787 :param timeout: How long to wait for the server thread
788 to terminate.
789 """
790 self.close()
Vinay Sajip7367d082011-05-02 13:17:27 +0100791 self._thread.join(timeout)
792 self._thread = None
Vinay Sajip7367d082011-05-02 13:17:27 +0100793
Vinay Sajipce7c9782011-05-17 07:15:53 +0100794 class ControlMixin(object):
795 """
796 This mixin is used to start a server on a separate thread, and
797 shut it down programmatically. Request handling is simplified - instead
798 of needing to derive a suitable RequestHandler subclass, you just
799 provide a callable which will be passed each received request to be
800 processed.
Vinay Sajip7367d082011-05-02 13:17:27 +0100801
Vinay Sajipce7c9782011-05-17 07:15:53 +0100802 :param handler: A handler callable which will be called with a
803 single parameter - the request - in order to
804 process the request. This handler is called on the
805 server thread, effectively meaning that requests are
806 processed serially. While not quite Web scale ;-),
807 this should be fine for testing applications.
808 :param poll_interval: The polling interval in seconds.
809 """
810 def __init__(self, handler, poll_interval):
811 self._thread = None
812 self.poll_interval = poll_interval
813 self._handler = handler
814 self.ready = threading.Event()
Vinay Sajip7367d082011-05-02 13:17:27 +0100815
Vinay Sajipce7c9782011-05-17 07:15:53 +0100816 def start(self):
817 """
818 Create a daemon thread to run the server, and start it.
819 """
820 self._thread = t = threading.Thread(target=self.serve_forever,
821 args=(self.poll_interval,))
822 t.setDaemon(True)
823 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100824
Vinay Sajipce7c9782011-05-17 07:15:53 +0100825 def serve_forever(self, poll_interval):
826 """
827 Run the server. Set the ready flag before entering the
828 service loop.
829 """
830 self.ready.set()
831 super(ControlMixin, self).serve_forever(poll_interval)
Vinay Sajip7367d082011-05-02 13:17:27 +0100832
Vinay Sajipce7c9782011-05-17 07:15:53 +0100833 def stop(self, timeout=None):
834 """
835 Tell the server thread to stop, and wait for it to do so.
Vinay Sajip7367d082011-05-02 13:17:27 +0100836
Vinay Sajipce7c9782011-05-17 07:15:53 +0100837 :param timeout: How long to wait for the server thread
838 to terminate.
839 """
840 self.shutdown()
841 if self._thread is not None:
842 self._thread.join(timeout)
843 self._thread = None
844 self.server_close()
845 self.ready.clear()
Vinay Sajip7367d082011-05-02 13:17:27 +0100846
Vinay Sajipce7c9782011-05-17 07:15:53 +0100847 class TestHTTPServer(ControlMixin, HTTPServer):
848 """
849 An HTTP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100850
Vinay Sajipce7c9782011-05-17 07:15:53 +0100851 :param addr: A tuple with the IP address and port to listen on.
852 :param handler: A handler callable which will be called with a
853 single parameter - the request - in order to
854 process the request.
855 :param poll_interval: The polling interval in seconds.
856 :param log: Pass ``True`` to enable log messages.
857 """
Vinay Sajip32565b62011-05-21 00:34:51 +0100858 def __init__(self, addr, handler, poll_interval=0.5,
859 log=False, sslctx=None):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100860 class DelegatingHTTPRequestHandler(BaseHTTPRequestHandler):
861 def __getattr__(self, name, default=None):
862 if name.startswith('do_'):
863 return self.process_request
864 raise AttributeError(name)
Vinay Sajip7367d082011-05-02 13:17:27 +0100865
Vinay Sajipce7c9782011-05-17 07:15:53 +0100866 def process_request(self):
867 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +0100868
Vinay Sajipce7c9782011-05-17 07:15:53 +0100869 def log_message(self, format, *args):
870 if log:
871 super(DelegatingHTTPRequestHandler,
872 self).log_message(format, *args)
873 HTTPServer.__init__(self, addr, DelegatingHTTPRequestHandler)
874 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajip32565b62011-05-21 00:34:51 +0100875 self.sslctx = sslctx
876
877 def get_request(self):
878 try:
879 sock, addr = self.socket.accept()
880 if self.sslctx:
881 sock = self.sslctx.wrap_socket(sock, server_side=True)
882 except socket.error as e:
883 # socket errors are silenced by the caller, print them here
884 sys.stderr.write("Got an error:\n%s\n" % e)
885 raise
886 return sock, addr
Vinay Sajip7367d082011-05-02 13:17:27 +0100887
Vinay Sajipce7c9782011-05-17 07:15:53 +0100888 class TestTCPServer(ControlMixin, ThreadingTCPServer):
889 """
890 A TCP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100891
Vinay Sajipce7c9782011-05-17 07:15:53 +0100892 :param addr: A tuple with the IP address and port to listen on.
893 :param handler: A handler callable which will be called with a single
894 parameter - the request - in order to process the request.
895 :param poll_interval: The polling interval in seconds.
896 :bind_and_activate: If True (the default), binds the server and starts it
897 listening. If False, you need to call
898 :meth:`server_bind` and :meth:`server_activate` at
899 some later time before calling :meth:`start`, so that
900 the server will set up the socket and listen on it.
901 """
Vinay Sajip7367d082011-05-02 13:17:27 +0100902
Vinay Sajipce7c9782011-05-17 07:15:53 +0100903 allow_reuse_address = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100904
Vinay Sajipce7c9782011-05-17 07:15:53 +0100905 def __init__(self, addr, handler, poll_interval=0.5,
906 bind_and_activate=True):
907 class DelegatingTCPRequestHandler(StreamRequestHandler):
908
909 def handle(self):
910 self.server._handler(self)
911 ThreadingTCPServer.__init__(self, addr, DelegatingTCPRequestHandler,
912 bind_and_activate)
913 ControlMixin.__init__(self, handler, poll_interval)
914
915 def server_bind(self):
916 super(TestTCPServer, self).server_bind()
917 self.port = self.socket.getsockname()[1]
918
919 class TestUDPServer(ControlMixin, ThreadingUDPServer):
920 """
921 A UDP server which is controllable using :class:`ControlMixin`.
922
923 :param addr: A tuple with the IP address and port to listen on.
924 :param handler: A handler callable which will be called with a
925 single parameter - the request - in order to
926 process the request.
927 :param poll_interval: The polling interval for shutdown requests,
928 in seconds.
929 :bind_and_activate: If True (the default), binds the server and
930 starts it listening. If False, you need to
931 call :meth:`server_bind` and
932 :meth:`server_activate` at some later time
933 before calling :meth:`start`, so that the server will
934 set up the socket and listen on it.
935 """
Vinay Sajip3ef12292011-05-23 23:00:42 +0100936 def __init__(self, addr, handler, poll_interval=0.5,
937 bind_and_activate=True):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100938 class DelegatingUDPRequestHandler(DatagramRequestHandler):
939
940 def handle(self):
941 self.server._handler(self)
Vinay Sajipba980db2011-05-23 21:37:54 +0100942
943 def finish(self):
944 data = self.wfile.getvalue()
Vinay Sajip3ef12292011-05-23 23:00:42 +0100945 if data:
946 try:
947 super(DelegatingUDPRequestHandler, self).finish()
948 except socket.error:
949 if not self.server._closed:
950 raise
Vinay Sajipba980db2011-05-23 21:37:54 +0100951
Vinay Sajip3ef12292011-05-23 23:00:42 +0100952 ThreadingUDPServer.__init__(self, addr,
953 DelegatingUDPRequestHandler,
Vinay Sajipce7c9782011-05-17 07:15:53 +0100954 bind_and_activate)
955 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajipba980db2011-05-23 21:37:54 +0100956 self._closed = False
Vinay Sajipce7c9782011-05-17 07:15:53 +0100957
958 def server_bind(self):
959 super(TestUDPServer, self).server_bind()
960 self.port = self.socket.getsockname()[1]
Vinay Sajip7367d082011-05-02 13:17:27 +0100961
Vinay Sajipba980db2011-05-23 21:37:54 +0100962 def server_close(self):
963 super(TestUDPServer, self).server_close()
964 self._closed = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100965
966# - end of server_helper section
Vinay Sajipa463d252011-04-30 21:52:48 +0100967
Vinay Sajipce7c9782011-05-17 07:15:53 +0100968@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipa463d252011-04-30 21:52:48 +0100969class SMTPHandlerTest(BaseTest):
970 def test_basic(self):
Vinay Sajip7367d082011-05-02 13:17:27 +0100971 sockmap = {}
972 server = TestSMTPServer(('localhost', 0), self.process_message, 0.001,
973 sockmap)
974 server.start()
975 addr = ('localhost', server.port)
Vinay Sajip4c3f4782012-04-22 18:19:50 +0100976 h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log', timeout=5.0)
Vinay Sajipa463d252011-04-30 21:52:48 +0100977 self.assertEqual(h.toaddrs, ['you'])
978 self.messages = []
Vinay Sajipa463d252011-04-30 21:52:48 +0100979 r = logging.makeLogRecord({'msg': 'Hello'})
Vinay Sajip7367d082011-05-02 13:17:27 +0100980 self.handled = threading.Event()
Vinay Sajipa463d252011-04-30 21:52:48 +0100981 h.handle(r)
Vinay Sajip17160fd2012-03-15 12:02:08 +0000982 self.handled.wait(5.0) # 14314: don't wait forever
Vinay Sajipa463d252011-04-30 21:52:48 +0100983 server.stop()
Vinay Sajip17160fd2012-03-15 12:02:08 +0000984 self.assertTrue(self.handled.is_set())
Vinay Sajipa463d252011-04-30 21:52:48 +0100985 self.assertEqual(len(self.messages), 1)
986 peer, mailfrom, rcpttos, data = self.messages[0]
987 self.assertEqual(mailfrom, 'me')
988 self.assertEqual(rcpttos, ['you'])
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100989 self.assertIn('\nSubject: Log\n', data)
Vinay Sajipa463d252011-04-30 21:52:48 +0100990 self.assertTrue(data.endswith('\n\nHello'))
991 h.close()
992
993 def process_message(self, *args):
994 self.messages.append(args)
Vinay Sajip7367d082011-05-02 13:17:27 +0100995 self.handled.set()
Vinay Sajipa463d252011-04-30 21:52:48 +0100996
Christian Heimes180510d2008-03-03 19:15:45 +0000997class MemoryHandlerTest(BaseTest):
998
999 """Tests for the MemoryHandler."""
1000
1001 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001002 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001003
1004 def setUp(self):
1005 BaseTest.setUp(self)
1006 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
1007 self.root_hdlr)
1008 self.mem_logger = logging.getLogger('mem')
1009 self.mem_logger.propagate = 0
1010 self.mem_logger.addHandler(self.mem_hdlr)
1011
1012 def tearDown(self):
1013 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +00001014 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +00001015
1016 def test_flush(self):
1017 # The memory handler flushes to its target handler based on specific
1018 # criteria (message count and message level).
1019 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001020 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001021 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001022 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001023 # This will flush because the level is >= logging.WARNING
Vinay Sajipb9e46e92011-10-26 13:17:20 +01001024 self.mem_logger.warning(self.next_message())
Christian Heimes180510d2008-03-03 19:15:45 +00001025 lines = [
1026 ('DEBUG', '1'),
1027 ('INFO', '2'),
1028 ('WARNING', '3'),
1029 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001030 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001031 for n in (4, 14):
1032 for i in range(9):
1033 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001034 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001035 # This will flush because it's the 10th message since the last
1036 # flush.
1037 self.mem_logger.debug(self.next_message())
1038 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001039 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001040
1041 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001042 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001043
1044
1045class ExceptionFormatter(logging.Formatter):
1046 """A special exception formatter."""
1047 def formatException(self, ei):
1048 return "Got a [%s]" % ei[0].__name__
1049
1050
1051class ConfigFileTest(BaseTest):
1052
1053 """Reading logging config from a .ini-style config file."""
1054
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001055 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001056
1057 # config0 is a standard configuration.
1058 config0 = """
1059 [loggers]
1060 keys=root
1061
1062 [handlers]
1063 keys=hand1
1064
1065 [formatters]
1066 keys=form1
1067
1068 [logger_root]
1069 level=WARNING
1070 handlers=hand1
1071
1072 [handler_hand1]
1073 class=StreamHandler
1074 level=NOTSET
1075 formatter=form1
1076 args=(sys.stdout,)
1077
1078 [formatter_form1]
1079 format=%(levelname)s ++ %(message)s
1080 datefmt=
1081 """
1082
1083 # config1 adds a little to the standard configuration.
1084 config1 = """
1085 [loggers]
1086 keys=root,parser
1087
1088 [handlers]
1089 keys=hand1
1090
1091 [formatters]
1092 keys=form1
1093
1094 [logger_root]
1095 level=WARNING
1096 handlers=
1097
1098 [logger_parser]
1099 level=DEBUG
1100 handlers=hand1
1101 propagate=1
1102 qualname=compiler.parser
1103
1104 [handler_hand1]
1105 class=StreamHandler
1106 level=NOTSET
1107 formatter=form1
1108 args=(sys.stdout,)
1109
1110 [formatter_form1]
1111 format=%(levelname)s ++ %(message)s
1112 datefmt=
1113 """
1114
Vinay Sajip3f84b072011-03-07 17:49:33 +00001115 # config1a moves the handler to the root.
1116 config1a = """
1117 [loggers]
1118 keys=root,parser
1119
1120 [handlers]
1121 keys=hand1
1122
1123 [formatters]
1124 keys=form1
1125
1126 [logger_root]
1127 level=WARNING
1128 handlers=hand1
1129
1130 [logger_parser]
1131 level=DEBUG
1132 handlers=
1133 propagate=1
1134 qualname=compiler.parser
1135
1136 [handler_hand1]
1137 class=StreamHandler
1138 level=NOTSET
1139 formatter=form1
1140 args=(sys.stdout,)
1141
1142 [formatter_form1]
1143 format=%(levelname)s ++ %(message)s
1144 datefmt=
1145 """
1146
Christian Heimes180510d2008-03-03 19:15:45 +00001147 # config2 has a subtle configuration error that should be reported
1148 config2 = config1.replace("sys.stdout", "sys.stbout")
1149
1150 # config3 has a less subtle configuration error
1151 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
1152
1153 # config4 specifies a custom formatter class to be loaded
1154 config4 = """
1155 [loggers]
1156 keys=root
1157
1158 [handlers]
1159 keys=hand1
1160
1161 [formatters]
1162 keys=form1
1163
1164 [logger_root]
1165 level=NOTSET
1166 handlers=hand1
1167
1168 [handler_hand1]
1169 class=StreamHandler
1170 level=NOTSET
1171 formatter=form1
1172 args=(sys.stdout,)
1173
1174 [formatter_form1]
1175 class=""" + __name__ + """.ExceptionFormatter
1176 format=%(levelname)s:%(name)s:%(message)s
1177 datefmt=
1178 """
1179
Georg Brandl3dbca812008-07-23 16:10:53 +00001180 # config5 specifies a custom handler class to be loaded
1181 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
1182
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001183 # config6 uses ', ' delimiters in the handlers and formatters sections
1184 config6 = """
1185 [loggers]
1186 keys=root,parser
1187
1188 [handlers]
1189 keys=hand1, hand2
1190
1191 [formatters]
1192 keys=form1, form2
1193
1194 [logger_root]
1195 level=WARNING
1196 handlers=
1197
1198 [logger_parser]
1199 level=DEBUG
1200 handlers=hand1
1201 propagate=1
1202 qualname=compiler.parser
1203
1204 [handler_hand1]
1205 class=StreamHandler
1206 level=NOTSET
1207 formatter=form1
1208 args=(sys.stdout,)
1209
1210 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001211 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001212 level=NOTSET
1213 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001214 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001215
1216 [formatter_form1]
1217 format=%(levelname)s ++ %(message)s
1218 datefmt=
1219
1220 [formatter_form2]
1221 format=%(message)s
1222 datefmt=
1223 """
1224
Vinay Sajip3f84b072011-03-07 17:49:33 +00001225 # config7 adds a compiler logger.
1226 config7 = """
1227 [loggers]
1228 keys=root,parser,compiler
1229
1230 [handlers]
1231 keys=hand1
1232
1233 [formatters]
1234 keys=form1
1235
1236 [logger_root]
1237 level=WARNING
1238 handlers=hand1
1239
1240 [logger_compiler]
1241 level=DEBUG
1242 handlers=
1243 propagate=1
1244 qualname=compiler
1245
1246 [logger_parser]
1247 level=DEBUG
1248 handlers=
1249 propagate=1
1250 qualname=compiler.parser
1251
1252 [handler_hand1]
1253 class=StreamHandler
1254 level=NOTSET
1255 formatter=form1
1256 args=(sys.stdout,)
1257
1258 [formatter_form1]
1259 format=%(levelname)s ++ %(message)s
1260 datefmt=
1261 """
1262
Christian Heimes180510d2008-03-03 19:15:45 +00001263 def apply_config(self, conf):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001264 file = io.StringIO(textwrap.dedent(conf))
1265 logging.config.fileConfig(file)
Christian Heimes180510d2008-03-03 19:15:45 +00001266
1267 def test_config0_ok(self):
1268 # A simple config file which overrides the default settings.
1269 with captured_stdout() as output:
1270 self.apply_config(self.config0)
1271 logger = logging.getLogger()
1272 # Won't output anything
1273 logger.info(self.next_message())
1274 # Outputs a message
1275 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001276 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001277 ('ERROR', '2'),
1278 ], stream=output)
1279 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001280 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001281
Georg Brandl3dbca812008-07-23 16:10:53 +00001282 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +00001283 # A config file defining a sub-parser as well.
1284 with captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +00001285 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +00001286 logger = logging.getLogger("compiler.parser")
1287 # Both will output a message
1288 logger.info(self.next_message())
1289 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001290 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001291 ('INFO', '1'),
1292 ('ERROR', '2'),
1293 ], stream=output)
1294 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001295 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001296
1297 def test_config2_failure(self):
1298 # A simple config file which overrides the default settings.
1299 self.assertRaises(Exception, self.apply_config, self.config2)
1300
1301 def test_config3_failure(self):
1302 # A simple config file which overrides the default settings.
1303 self.assertRaises(Exception, self.apply_config, self.config3)
1304
1305 def test_config4_ok(self):
1306 # A config file specifying a custom formatter class.
1307 with captured_stdout() as output:
1308 self.apply_config(self.config4)
1309 logger = logging.getLogger()
1310 try:
1311 raise RuntimeError()
1312 except RuntimeError:
1313 logging.exception("just testing")
1314 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00001315 self.assertEqual(output.getvalue(),
Christian Heimes180510d2008-03-03 19:15:45 +00001316 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1317 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001318 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001319
Georg Brandl3dbca812008-07-23 16:10:53 +00001320 def test_config5_ok(self):
1321 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +00001322
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001323 def test_config6_ok(self):
1324 self.test_config1_ok(config=self.config6)
1325
Vinay Sajip3f84b072011-03-07 17:49:33 +00001326 def test_config7_ok(self):
1327 with captured_stdout() as output:
1328 self.apply_config(self.config1a)
1329 logger = logging.getLogger("compiler.parser")
1330 # See issue #11424. compiler-hyphenated sorts
1331 # between compiler and compiler.xyz and this
1332 # was preventing compiler.xyz from being included
1333 # in the child loggers of compiler because of an
1334 # overzealous loop termination condition.
1335 hyphenated = logging.getLogger('compiler-hyphenated')
1336 # All will output a message
1337 logger.info(self.next_message())
1338 logger.error(self.next_message())
1339 hyphenated.critical(self.next_message())
1340 self.assert_log_lines([
1341 ('INFO', '1'),
1342 ('ERROR', '2'),
1343 ('CRITICAL', '3'),
1344 ], stream=output)
1345 # Original logger output is empty.
1346 self.assert_log_lines([])
1347 with captured_stdout() as output:
1348 self.apply_config(self.config7)
1349 logger = logging.getLogger("compiler.parser")
1350 self.assertFalse(logger.disabled)
1351 # Both will output a message
1352 logger.info(self.next_message())
1353 logger.error(self.next_message())
1354 logger = logging.getLogger("compiler.lexer")
1355 # Both will output a message
1356 logger.info(self.next_message())
1357 logger.error(self.next_message())
1358 # Will not appear
1359 hyphenated.critical(self.next_message())
1360 self.assert_log_lines([
1361 ('INFO', '4'),
1362 ('ERROR', '5'),
1363 ('INFO', '6'),
1364 ('ERROR', '7'),
1365 ], stream=output)
1366 # Original logger output is empty.
1367 self.assert_log_lines([])
1368
Guido van Rossum2a1d5162003-01-21 21:05:22 +00001369
Victor Stinner45df8202010-04-28 22:31:17 +00001370@unittest.skipUnless(threading, 'Threading required for this test.')
Christian Heimes180510d2008-03-03 19:15:45 +00001371class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001372
Christian Heimes180510d2008-03-03 19:15:45 +00001373 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001374
Christian Heimes180510d2008-03-03 19:15:45 +00001375 def setUp(self):
1376 """Set up a TCP server to receive log messages, and a SocketHandler
1377 pointing to that server's address and port."""
1378 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001379 addr = ('localhost', 0)
1380 self.server = server = TestTCPServer(addr, self.handle_socket,
1381 0.01)
1382 server.start()
1383 server.ready.wait()
1384 self.sock_hdlr = logging.handlers.SocketHandler('localhost',
1385 server.port)
1386 self.log_output = ''
Christian Heimes180510d2008-03-03 19:15:45 +00001387 self.root_logger.removeHandler(self.root_logger.handlers[0])
1388 self.root_logger.addHandler(self.sock_hdlr)
Vinay Sajip7367d082011-05-02 13:17:27 +01001389 self.handled = threading.Semaphore(0)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001390
Christian Heimes180510d2008-03-03 19:15:45 +00001391 def tearDown(self):
1392 """Shutdown the TCP server."""
1393 try:
Vinay Sajip7367d082011-05-02 13:17:27 +01001394 self.server.stop(2.0)
Christian Heimes180510d2008-03-03 19:15:45 +00001395 self.root_logger.removeHandler(self.sock_hdlr)
1396 self.sock_hdlr.close()
Christian Heimes180510d2008-03-03 19:15:45 +00001397 finally:
1398 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001399
Vinay Sajip7367d082011-05-02 13:17:27 +01001400 def handle_socket(self, request):
1401 conn = request.connection
1402 while True:
1403 chunk = conn.recv(4)
1404 if len(chunk) < 4:
1405 break
1406 slen = struct.unpack(">L", chunk)[0]
1407 chunk = conn.recv(slen)
1408 while len(chunk) < slen:
1409 chunk = chunk + conn.recv(slen - len(chunk))
1410 obj = pickle.loads(chunk)
1411 record = logging.makeLogRecord(obj)
1412 self.log_output += record.msg + '\n'
1413 self.handled.release()
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001414
Christian Heimes180510d2008-03-03 19:15:45 +00001415 def test_output(self):
1416 # The log message sent to the SocketHandler is properly received.
1417 logger = logging.getLogger("tcp")
1418 logger.error("spam")
Vinay Sajip7367d082011-05-02 13:17:27 +01001419 self.handled.acquire()
Christian Heimes180510d2008-03-03 19:15:45 +00001420 logger.debug("eggs")
Vinay Sajip7367d082011-05-02 13:17:27 +01001421 self.handled.acquire()
1422 self.assertEqual(self.log_output, "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001423
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001424 def test_noserver(self):
1425 # Kill the server
Vinay Sajip7367d082011-05-02 13:17:27 +01001426 self.server.stop(2.0)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001427 #The logging call should try to connect, which should fail
1428 try:
1429 raise RuntimeError('Deliberate mistake')
1430 except RuntimeError:
1431 self.root_logger.exception('Never sent')
1432 self.root_logger.error('Never sent, either')
1433 now = time.time()
1434 self.assertTrue(self.sock_hdlr.retryTime > now)
1435 time.sleep(self.sock_hdlr.retryTime - now + 0.001)
1436 self.root_logger.error('Nor this')
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001437
Vinay Sajip7367d082011-05-02 13:17:27 +01001438
1439@unittest.skipUnless(threading, 'Threading required for this test.')
1440class DatagramHandlerTest(BaseTest):
1441
1442 """Test for DatagramHandler."""
1443
1444 def setUp(self):
1445 """Set up a UDP server to receive log messages, and a DatagramHandler
1446 pointing to that server's address and port."""
1447 BaseTest.setUp(self)
1448 addr = ('localhost', 0)
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001449 self.server = server = TestUDPServer(addr, self.handle_datagram, 0.01)
Vinay Sajip7367d082011-05-02 13:17:27 +01001450 server.start()
1451 server.ready.wait()
1452 self.sock_hdlr = logging.handlers.DatagramHandler('localhost',
1453 server.port)
1454 self.log_output = ''
1455 self.root_logger.removeHandler(self.root_logger.handlers[0])
1456 self.root_logger.addHandler(self.sock_hdlr)
1457 self.handled = threading.Event()
1458
1459 def tearDown(self):
1460 """Shutdown the UDP server."""
1461 try:
1462 self.server.stop(2.0)
1463 self.root_logger.removeHandler(self.sock_hdlr)
1464 self.sock_hdlr.close()
1465 finally:
1466 BaseTest.tearDown(self)
1467
1468 def handle_datagram(self, request):
1469 slen = struct.pack('>L', 0) # length of prefix
1470 packet = request.packet[len(slen):]
1471 obj = pickle.loads(packet)
1472 record = logging.makeLogRecord(obj)
1473 self.log_output += record.msg + '\n'
1474 self.handled.set()
1475
1476 def test_output(self):
1477 # The log message sent to the DatagramHandler is properly received.
1478 logger = logging.getLogger("udp")
1479 logger.error("spam")
1480 self.handled.wait()
Vinay Sajip714b8dc2011-05-02 14:43:00 +01001481 self.handled.clear()
1482 logger.error("eggs")
1483 self.handled.wait()
1484 self.assertEqual(self.log_output, "spam\neggs\n")
Vinay Sajip7367d082011-05-02 13:17:27 +01001485
1486
1487@unittest.skipUnless(threading, 'Threading required for this test.')
1488class SysLogHandlerTest(BaseTest):
1489
1490 """Test for SysLogHandler using UDP."""
1491
1492 def setUp(self):
1493 """Set up a UDP server to receive log messages, and a SysLogHandler
1494 pointing to that server's address and port."""
1495 BaseTest.setUp(self)
1496 addr = ('localhost', 0)
1497 self.server = server = TestUDPServer(addr, self.handle_datagram,
1498 0.01)
1499 server.start()
1500 server.ready.wait()
1501 self.sl_hdlr = logging.handlers.SysLogHandler(('localhost',
1502 server.port))
1503 self.log_output = ''
1504 self.root_logger.removeHandler(self.root_logger.handlers[0])
1505 self.root_logger.addHandler(self.sl_hdlr)
1506 self.handled = threading.Event()
1507
1508 def tearDown(self):
1509 """Shutdown the UDP server."""
1510 try:
1511 self.server.stop(2.0)
1512 self.root_logger.removeHandler(self.sl_hdlr)
1513 self.sl_hdlr.close()
1514 finally:
1515 BaseTest.tearDown(self)
1516
1517 def handle_datagram(self, request):
1518 self.log_output = request.packet
1519 self.handled.set()
1520
1521 def test_output(self):
1522 # The log message sent to the SysLogHandler is properly received.
1523 logger = logging.getLogger("slh")
1524 logger.error("sp\xe4m")
1525 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001526 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001527 self.handled.clear()
1528 self.sl_hdlr.append_nul = False
1529 logger.error("sp\xe4m")
1530 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001531 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m')
Vinay Sajip2353e352011-06-27 15:40:06 +01001532 self.handled.clear()
1533 self.sl_hdlr.ident = "h\xe4m-"
1534 logger.error("sp\xe4m")
1535 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001536 self.assertEqual(self.log_output, b'<11>h\xc3\xa4m-sp\xc3\xa4m')
Vinay Sajip7367d082011-05-02 13:17:27 +01001537
1538
1539@unittest.skipUnless(threading, 'Threading required for this test.')
1540class HTTPHandlerTest(BaseTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01001541 """Test for HTTPHandler."""
1542
Vinay Sajip9ba87612011-05-21 11:32:15 +01001543 PEMFILE = """-----BEGIN RSA PRIVATE KEY-----
1544MIICXQIBAAKBgQDGT4xS5r91rbLJQK2nUDenBhBG6qFk+bVOjuAGC/LSHlAoBnvG
1545zQG3agOG+e7c5z2XT8m2ktORLqG3E4mYmbxgyhDrzP6ei2Anc+pszmnxPoK3Puh5
1546aXV+XKt0bU0C1m2+ACmGGJ0t3P408art82nOxBw8ZHgIg9Dtp6xIUCyOqwIDAQAB
1547AoGBAJFTnFboaKh5eUrIzjmNrKsG44jEyy+vWvHN/FgSC4l103HxhmWiuL5Lv3f7
15480tMp1tX7D6xvHwIG9VWvyKb/Cq9rJsDibmDVIOslnOWeQhG+XwJyitR0pq/KlJIB
15495LjORcBw795oKWOAi6RcOb1ON59tysEFYhAGQO9k6VL621gRAkEA/Gb+YXULLpbs
1550piXN3q4zcHzeaVANo69tUZ6TjaQqMeTxE4tOYM0G0ZoSeHEdaP59AOZGKXXNGSQy
15512z/MddcYGQJBAMkjLSYIpOLJY11ja8OwwswFG2hEzHe0cS9bzo++R/jc1bHA5R0Y
1552i6vA5iPi+wopPFvpytdBol7UuEBe5xZrxWMCQQCWxELRHiP2yWpEeLJ3gGDzoXMN
1553PydWjhRju7Bx3AzkTtf+D6lawz1+eGTuEss5i0JKBkMEwvwnN2s1ce+EuF4JAkBb
1554E96h1lAzkVW5OAfYOPY8RCPA90ZO/hoyg7PpSxR0ECuDrgERR8gXIeYUYfejBkEa
1555rab4CfRoVJKKM28Yq/xZAkBvuq670JRCwOgfUTdww7WpdOQBYPkzQccsKNCslQW8
1556/DyW6y06oQusSENUvynT6dr3LJxt/NgZPhZX2+k1eYDV
1557-----END RSA PRIVATE KEY-----
1558-----BEGIN CERTIFICATE-----
1559MIICGzCCAYSgAwIBAgIJAIq84a2Q/OvlMA0GCSqGSIb3DQEBBQUAMBQxEjAQBgNV
1560BAMTCWxvY2FsaG9zdDAeFw0xMTA1MjExMDIzMzNaFw03NTAzMjEwMzU1MTdaMBQx
1561EjAQBgNVBAMTCWxvY2FsaG9zdDCBnzANBgkqhkiG9w0BAQEFAAOBjQAwgYkCgYEA
1562xk+MUua/da2yyUCtp1A3pwYQRuqhZPm1To7gBgvy0h5QKAZ7xs0Bt2oDhvnu3Oc9
1563l0/JtpLTkS6htxOJmJm8YMoQ68z+notgJ3PqbM5p8T6Ctz7oeWl1flyrdG1NAtZt
1564vgAphhidLdz+NPGq7fNpzsQcPGR4CIPQ7aesSFAsjqsCAwEAAaN1MHMwHQYDVR0O
1565BBYEFLWaUPO6N7efGiuoS9i3DVYcUwn0MEQGA1UdIwQ9MDuAFLWaUPO6N7efGiuo
1566S9i3DVYcUwn0oRikFjAUMRIwEAYDVQQDEwlsb2NhbGhvc3SCCQCKvOGtkPzr5TAM
1567BgNVHRMEBTADAQH/MA0GCSqGSIb3DQEBBQUAA4GBAMK5whPjLNQK1Ivvk88oqJqq
15684f889OwikGP0eUhOBhbFlsZs+jq5YZC2UzHz+evzKBlgAP1u4lP/cB85CnjvWqM+
15691c/lywFHQ6HOdDeQ1L72tSYMrNOG4XNmLn0h7rx6GoTU7dcFRfseahBCq8mv0IDt
1570IRbTpvlHWPjsSvHz0ZOH
1571-----END CERTIFICATE-----"""
1572
Vinay Sajip7367d082011-05-02 13:17:27 +01001573 def setUp(self):
1574 """Set up an HTTP server to receive log messages, and a HTTPHandler
1575 pointing to that server's address and port."""
1576 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001577 self.handled = threading.Event()
1578
Vinay Sajip7367d082011-05-02 13:17:27 +01001579 def handle_request(self, request):
Vinay Sajip0372e102011-05-05 12:59:14 +01001580 self.command = request.command
Vinay Sajip7367d082011-05-02 13:17:27 +01001581 self.log_data = urlparse(request.path)
Vinay Sajip0372e102011-05-05 12:59:14 +01001582 if self.command == 'POST':
1583 try:
1584 rlen = int(request.headers['Content-Length'])
1585 self.post_data = request.rfile.read(rlen)
1586 except:
1587 self.post_data = None
Vinay Sajip7367d082011-05-02 13:17:27 +01001588 request.send_response(200)
Vinay Sajip463ac512011-05-10 09:10:08 +01001589 request.end_headers()
Vinay Sajip7367d082011-05-02 13:17:27 +01001590 self.handled.set()
1591
1592 def test_output(self):
Vinay Sajipf2231162011-05-09 22:05:50 +01001593 # The log message sent to the HTTPHandler is properly received.
Vinay Sajip7367d082011-05-02 13:17:27 +01001594 logger = logging.getLogger("http")
Vinay Sajip9ba87612011-05-21 11:32:15 +01001595 root_logger = self.root_logger
1596 root_logger.removeHandler(self.root_logger.handlers[0])
1597 for secure in (False, True):
1598 addr = ('localhost', 0)
1599 if secure:
Vinay Sajip39e35282011-05-21 16:46:41 +01001600 try:
1601 import ssl
1602 fd, fn = tempfile.mkstemp()
1603 os.close(fd)
1604 with open(fn, 'w') as f:
1605 f.write(self.PEMFILE)
1606 sslctx = ssl.SSLContext(ssl.PROTOCOL_SSLv23)
1607 sslctx.load_cert_chain(fn)
1608 os.unlink(fn)
1609 except ImportError:
1610 sslctx = None
Vinay Sajip0372e102011-05-05 12:59:14 +01001611 else:
Vinay Sajip9ba87612011-05-21 11:32:15 +01001612 sslctx = None
1613 self.server = server = TestHTTPServer(addr, self.handle_request,
1614 0.01, sslctx=sslctx)
1615 server.start()
1616 server.ready.wait()
1617 host = 'localhost:%d' % server.server_port
Vinay Sajip39e35282011-05-21 16:46:41 +01001618 secure_client = secure and sslctx
1619 self.h_hdlr = logging.handlers.HTTPHandler(host, '/frob',
1620 secure=secure_client)
Vinay Sajip9ba87612011-05-21 11:32:15 +01001621 self.log_data = None
1622 root_logger.addHandler(self.h_hdlr)
1623
1624 for method in ('GET', 'POST'):
1625 self.h_hdlr.method = method
1626 self.handled.clear()
1627 msg = "sp\xe4m"
1628 logger.error(msg)
1629 self.handled.wait()
1630 self.assertEqual(self.log_data.path, '/frob')
1631 self.assertEqual(self.command, method)
1632 if method == 'GET':
1633 d = parse_qs(self.log_data.query)
1634 else:
1635 d = parse_qs(self.post_data.decode('utf-8'))
1636 self.assertEqual(d['name'], ['http'])
1637 self.assertEqual(d['funcName'], ['test_output'])
1638 self.assertEqual(d['msg'], [msg])
1639
1640 self.server.stop(2.0)
1641 self.root_logger.removeHandler(self.h_hdlr)
1642 self.h_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001643
Christian Heimes180510d2008-03-03 19:15:45 +00001644class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001645
Christian Heimes180510d2008-03-03 19:15:45 +00001646 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001647
Christian Heimes180510d2008-03-03 19:15:45 +00001648 def setUp(self):
1649 """Create a dict to remember potentially destroyed objects."""
1650 BaseTest.setUp(self)
1651 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001652
Christian Heimes180510d2008-03-03 19:15:45 +00001653 def _watch_for_survival(self, *args):
1654 """Watch the given objects for survival, by creating weakrefs to
1655 them."""
1656 for obj in args:
1657 key = id(obj), repr(obj)
1658 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001659
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001660 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +00001661 """Assert that all objects watched for survival have survived."""
1662 # Trigger cycle breaking.
1663 gc.collect()
1664 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001665 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +00001666 if ref() is None:
1667 dead.append(repr_)
1668 if dead:
1669 self.fail("%d objects should have survived "
1670 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001671
Christian Heimes180510d2008-03-03 19:15:45 +00001672 def test_persistent_loggers(self):
1673 # Logger objects are persistent and retain their configuration, even
1674 # if visible references are destroyed.
1675 self.root_logger.setLevel(logging.INFO)
1676 foo = logging.getLogger("foo")
1677 self._watch_for_survival(foo)
1678 foo.setLevel(logging.DEBUG)
1679 self.root_logger.debug(self.next_message())
1680 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001681 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001682 ('foo', 'DEBUG', '2'),
1683 ])
1684 del foo
1685 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001686 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +00001687 # foo has retained its settings.
1688 bar = logging.getLogger("foo")
1689 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001690 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001691 ('foo', 'DEBUG', '2'),
1692 ('foo', 'DEBUG', '3'),
1693 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001694
Benjamin Petersonf91df042009-02-13 02:50:59 +00001695
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001696class EncodingTest(BaseTest):
1697 def test_encoding_plain_file(self):
1698 # In Python 2.x, a plain file object is treated as having no encoding.
1699 log = logging.getLogger("test")
Vinay Sajip60b4df12010-12-27 11:18:52 +00001700 fd, fn = tempfile.mkstemp(".log", "test_logging-1-")
1701 os.close(fd)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001702 # the non-ascii data we write to the log.
1703 data = "foo\x80"
1704 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001705 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001706 log.addHandler(handler)
1707 try:
1708 # write non-ascii data to the log.
1709 log.warning(data)
1710 finally:
1711 log.removeHandler(handler)
1712 handler.close()
1713 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001714 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001715 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001716 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001717 finally:
1718 f.close()
1719 finally:
1720 if os.path.isfile(fn):
1721 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001722
Benjamin Petersonf91df042009-02-13 02:50:59 +00001723 def test_encoding_cyrillic_unicode(self):
1724 log = logging.getLogger("test")
1725 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
1726 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
1727 #Ensure it's written in a Cyrillic encoding
1728 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +00001729 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +00001730 stream = io.BytesIO()
1731 writer = writer_class(stream, 'strict')
1732 handler = logging.StreamHandler(writer)
1733 log.addHandler(handler)
1734 try:
1735 log.warning(message)
1736 finally:
1737 log.removeHandler(handler)
1738 handler.close()
1739 # check we wrote exactly those bytes, ignoring trailing \n etc
1740 s = stream.getvalue()
1741 #Compare against what the data should be when encoded in CP-1251
1742 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
1743
1744
Georg Brandlf9734072008-12-07 15:30:06 +00001745class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +00001746
Georg Brandlf9734072008-12-07 15:30:06 +00001747 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +00001748 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +00001749 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001750 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001751 warnings.filterwarnings("always", category=UserWarning)
1752 stream = io.StringIO()
1753 h = logging.StreamHandler(stream)
1754 logger = logging.getLogger("py.warnings")
1755 logger.addHandler(h)
1756 warnings.warn("I'm warning you...")
1757 logger.removeHandler(h)
1758 s = stream.getvalue()
1759 h.close()
1760 self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0)
Georg Brandlf9734072008-12-07 15:30:06 +00001761
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001762 #See if an explicit file uses the original implementation
1763 a_file = io.StringIO()
1764 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
1765 a_file, "Dummy line")
1766 s = a_file.getvalue()
1767 a_file.close()
1768 self.assertEqual(s,
1769 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
1770
1771 def test_warnings_no_handlers(self):
1772 with warnings.catch_warnings():
1773 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001774 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001775
1776 # confirm our assumption: no loggers are set
1777 logger = logging.getLogger("py.warnings")
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001778 self.assertEqual(logger.handlers, [])
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001779
1780 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001781 self.assertEqual(len(logger.handlers), 1)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001782 self.assertIsInstance(logger.handlers[0], logging.NullHandler)
Georg Brandlf9734072008-12-07 15:30:06 +00001783
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001784
1785def formatFunc(format, datefmt=None):
1786 return logging.Formatter(format, datefmt)
1787
1788def handlerFunc():
1789 return logging.StreamHandler()
1790
1791class CustomHandler(logging.StreamHandler):
1792 pass
1793
1794class ConfigDictTest(BaseTest):
1795
1796 """Reading logging config from a dictionary."""
1797
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001798 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001799
1800 # config0 is a standard configuration.
1801 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001802 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001803 'formatters': {
1804 'form1' : {
1805 'format' : '%(levelname)s ++ %(message)s',
1806 },
1807 },
1808 'handlers' : {
1809 'hand1' : {
1810 'class' : 'logging.StreamHandler',
1811 'formatter' : 'form1',
1812 'level' : 'NOTSET',
1813 'stream' : 'ext://sys.stdout',
1814 },
1815 },
1816 'root' : {
1817 'level' : 'WARNING',
1818 'handlers' : ['hand1'],
1819 },
1820 }
1821
1822 # config1 adds a little to the standard configuration.
1823 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001824 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001825 'formatters': {
1826 'form1' : {
1827 'format' : '%(levelname)s ++ %(message)s',
1828 },
1829 },
1830 'handlers' : {
1831 'hand1' : {
1832 'class' : 'logging.StreamHandler',
1833 'formatter' : 'form1',
1834 'level' : 'NOTSET',
1835 'stream' : 'ext://sys.stdout',
1836 },
1837 },
1838 'loggers' : {
1839 'compiler.parser' : {
1840 'level' : 'DEBUG',
1841 'handlers' : ['hand1'],
1842 },
1843 },
1844 'root' : {
1845 'level' : 'WARNING',
1846 },
1847 }
1848
Vinay Sajip9f9991c2011-03-07 18:02:57 +00001849 # config1a moves the handler to the root. Used with config8a
1850 config1a = {
1851 'version': 1,
1852 'formatters': {
1853 'form1' : {
1854 'format' : '%(levelname)s ++ %(message)s',
1855 },
1856 },
1857 'handlers' : {
1858 'hand1' : {
1859 'class' : 'logging.StreamHandler',
1860 'formatter' : 'form1',
1861 'level' : 'NOTSET',
1862 'stream' : 'ext://sys.stdout',
1863 },
1864 },
1865 'loggers' : {
1866 'compiler.parser' : {
1867 'level' : 'DEBUG',
1868 },
1869 },
1870 'root' : {
1871 'level' : 'WARNING',
1872 'handlers' : ['hand1'],
1873 },
1874 }
1875
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001876 # config2 has a subtle configuration error that should be reported
1877 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001878 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001879 'formatters': {
1880 'form1' : {
1881 'format' : '%(levelname)s ++ %(message)s',
1882 },
1883 },
1884 'handlers' : {
1885 'hand1' : {
1886 'class' : 'logging.StreamHandler',
1887 'formatter' : 'form1',
1888 'level' : 'NOTSET',
1889 'stream' : 'ext://sys.stdbout',
1890 },
1891 },
1892 'loggers' : {
1893 'compiler.parser' : {
1894 'level' : 'DEBUG',
1895 'handlers' : ['hand1'],
1896 },
1897 },
1898 'root' : {
1899 'level' : 'WARNING',
1900 },
1901 }
1902
1903 #As config1 but with a misspelt level on a handler
1904 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001905 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001906 'formatters': {
1907 'form1' : {
1908 'format' : '%(levelname)s ++ %(message)s',
1909 },
1910 },
1911 'handlers' : {
1912 'hand1' : {
1913 'class' : 'logging.StreamHandler',
1914 'formatter' : 'form1',
1915 'level' : 'NTOSET',
1916 'stream' : 'ext://sys.stdout',
1917 },
1918 },
1919 'loggers' : {
1920 'compiler.parser' : {
1921 'level' : 'DEBUG',
1922 'handlers' : ['hand1'],
1923 },
1924 },
1925 'root' : {
1926 'level' : 'WARNING',
1927 },
1928 }
1929
1930
1931 #As config1 but with a misspelt level on a logger
1932 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001933 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001934 'formatters': {
1935 'form1' : {
1936 'format' : '%(levelname)s ++ %(message)s',
1937 },
1938 },
1939 'handlers' : {
1940 'hand1' : {
1941 'class' : 'logging.StreamHandler',
1942 'formatter' : 'form1',
1943 'level' : 'NOTSET',
1944 'stream' : 'ext://sys.stdout',
1945 },
1946 },
1947 'loggers' : {
1948 'compiler.parser' : {
1949 'level' : 'DEBUG',
1950 'handlers' : ['hand1'],
1951 },
1952 },
1953 'root' : {
1954 'level' : 'WRANING',
1955 },
1956 }
1957
1958 # config3 has a less subtle configuration error
1959 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001960 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001961 'formatters': {
1962 'form1' : {
1963 'format' : '%(levelname)s ++ %(message)s',
1964 },
1965 },
1966 'handlers' : {
1967 'hand1' : {
1968 'class' : 'logging.StreamHandler',
1969 'formatter' : 'misspelled_name',
1970 'level' : 'NOTSET',
1971 'stream' : 'ext://sys.stdout',
1972 },
1973 },
1974 'loggers' : {
1975 'compiler.parser' : {
1976 'level' : 'DEBUG',
1977 'handlers' : ['hand1'],
1978 },
1979 },
1980 'root' : {
1981 'level' : 'WARNING',
1982 },
1983 }
1984
1985 # config4 specifies a custom formatter class to be loaded
1986 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001987 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001988 'formatters': {
1989 'form1' : {
1990 '()' : __name__ + '.ExceptionFormatter',
1991 'format' : '%(levelname)s:%(name)s:%(message)s',
1992 },
1993 },
1994 'handlers' : {
1995 'hand1' : {
1996 'class' : 'logging.StreamHandler',
1997 'formatter' : 'form1',
1998 'level' : 'NOTSET',
1999 'stream' : 'ext://sys.stdout',
2000 },
2001 },
2002 'root' : {
2003 'level' : 'NOTSET',
2004 'handlers' : ['hand1'],
2005 },
2006 }
2007
2008 # As config4 but using an actual callable rather than a string
2009 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002010 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002011 'formatters': {
2012 'form1' : {
2013 '()' : ExceptionFormatter,
2014 'format' : '%(levelname)s:%(name)s:%(message)s',
2015 },
2016 'form2' : {
2017 '()' : __name__ + '.formatFunc',
2018 'format' : '%(levelname)s:%(name)s:%(message)s',
2019 },
2020 'form3' : {
2021 '()' : formatFunc,
2022 'format' : '%(levelname)s:%(name)s:%(message)s',
2023 },
2024 },
2025 'handlers' : {
2026 'hand1' : {
2027 'class' : 'logging.StreamHandler',
2028 'formatter' : 'form1',
2029 'level' : 'NOTSET',
2030 'stream' : 'ext://sys.stdout',
2031 },
2032 'hand2' : {
2033 '()' : handlerFunc,
2034 },
2035 },
2036 'root' : {
2037 'level' : 'NOTSET',
2038 'handlers' : ['hand1'],
2039 },
2040 }
2041
2042 # config5 specifies a custom handler class to be loaded
2043 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002044 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002045 'formatters': {
2046 'form1' : {
2047 'format' : '%(levelname)s ++ %(message)s',
2048 },
2049 },
2050 'handlers' : {
2051 'hand1' : {
2052 'class' : __name__ + '.CustomHandler',
2053 'formatter' : 'form1',
2054 'level' : 'NOTSET',
2055 'stream' : 'ext://sys.stdout',
2056 },
2057 },
2058 'loggers' : {
2059 'compiler.parser' : {
2060 'level' : 'DEBUG',
2061 'handlers' : ['hand1'],
2062 },
2063 },
2064 'root' : {
2065 'level' : 'WARNING',
2066 },
2067 }
2068
2069 # config6 specifies a custom handler class to be loaded
2070 # but has bad arguments
2071 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002072 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002073 'formatters': {
2074 'form1' : {
2075 'format' : '%(levelname)s ++ %(message)s',
2076 },
2077 },
2078 'handlers' : {
2079 'hand1' : {
2080 'class' : __name__ + '.CustomHandler',
2081 'formatter' : 'form1',
2082 'level' : 'NOTSET',
2083 'stream' : 'ext://sys.stdout',
2084 '9' : 'invalid parameter name',
2085 },
2086 },
2087 'loggers' : {
2088 'compiler.parser' : {
2089 'level' : 'DEBUG',
2090 'handlers' : ['hand1'],
2091 },
2092 },
2093 'root' : {
2094 'level' : 'WARNING',
2095 },
2096 }
2097
2098 #config 7 does not define compiler.parser but defines compiler.lexer
2099 #so compiler.parser should be disabled after applying it
2100 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002101 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002102 'formatters': {
2103 'form1' : {
2104 'format' : '%(levelname)s ++ %(message)s',
2105 },
2106 },
2107 'handlers' : {
2108 'hand1' : {
2109 'class' : 'logging.StreamHandler',
2110 'formatter' : 'form1',
2111 'level' : 'NOTSET',
2112 'stream' : 'ext://sys.stdout',
2113 },
2114 },
2115 'loggers' : {
2116 'compiler.lexer' : {
2117 'level' : 'DEBUG',
2118 'handlers' : ['hand1'],
2119 },
2120 },
2121 'root' : {
2122 'level' : 'WARNING',
2123 },
2124 }
2125
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002126 # config8 defines both compiler and compiler.lexer
2127 # so compiler.parser should not be disabled (since
2128 # compiler is defined)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002129 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002130 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002131 'disable_existing_loggers' : False,
2132 'formatters': {
2133 'form1' : {
2134 'format' : '%(levelname)s ++ %(message)s',
2135 },
2136 },
2137 'handlers' : {
2138 'hand1' : {
2139 'class' : 'logging.StreamHandler',
2140 'formatter' : 'form1',
2141 'level' : 'NOTSET',
2142 'stream' : 'ext://sys.stdout',
2143 },
2144 },
2145 'loggers' : {
2146 'compiler' : {
2147 'level' : 'DEBUG',
2148 'handlers' : ['hand1'],
2149 },
2150 'compiler.lexer' : {
2151 },
2152 },
2153 'root' : {
2154 'level' : 'WARNING',
2155 },
2156 }
2157
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002158 # config8a disables existing loggers
2159 config8a = {
2160 'version': 1,
2161 'disable_existing_loggers' : True,
2162 'formatters': {
2163 'form1' : {
2164 'format' : '%(levelname)s ++ %(message)s',
2165 },
2166 },
2167 'handlers' : {
2168 'hand1' : {
2169 'class' : 'logging.StreamHandler',
2170 'formatter' : 'form1',
2171 'level' : 'NOTSET',
2172 'stream' : 'ext://sys.stdout',
2173 },
2174 },
2175 'loggers' : {
2176 'compiler' : {
2177 'level' : 'DEBUG',
2178 'handlers' : ['hand1'],
2179 },
2180 'compiler.lexer' : {
2181 },
2182 },
2183 'root' : {
2184 'level' : 'WARNING',
2185 },
2186 }
2187
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002188 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002189 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002190 'formatters': {
2191 'form1' : {
2192 'format' : '%(levelname)s ++ %(message)s',
2193 },
2194 },
2195 'handlers' : {
2196 'hand1' : {
2197 'class' : 'logging.StreamHandler',
2198 'formatter' : 'form1',
2199 'level' : 'WARNING',
2200 'stream' : 'ext://sys.stdout',
2201 },
2202 },
2203 'loggers' : {
2204 'compiler.parser' : {
2205 'level' : 'WARNING',
2206 'handlers' : ['hand1'],
2207 },
2208 },
2209 'root' : {
2210 'level' : 'NOTSET',
2211 },
2212 }
2213
2214 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002215 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002216 'incremental' : True,
2217 'handlers' : {
2218 'hand1' : {
2219 'level' : 'WARNING',
2220 },
2221 },
2222 'loggers' : {
2223 'compiler.parser' : {
2224 'level' : 'INFO',
2225 },
2226 },
2227 }
2228
2229 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002230 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002231 'incremental' : True,
2232 'handlers' : {
2233 'hand1' : {
2234 'level' : 'INFO',
2235 },
2236 },
2237 'loggers' : {
2238 'compiler.parser' : {
2239 'level' : 'INFO',
2240 },
2241 },
2242 }
2243
2244 #As config1 but with a filter added
2245 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002246 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002247 'formatters': {
2248 'form1' : {
2249 'format' : '%(levelname)s ++ %(message)s',
2250 },
2251 },
2252 'filters' : {
2253 'filt1' : {
2254 'name' : 'compiler.parser',
2255 },
2256 },
2257 'handlers' : {
2258 'hand1' : {
2259 'class' : 'logging.StreamHandler',
2260 'formatter' : 'form1',
2261 'level' : 'NOTSET',
2262 'stream' : 'ext://sys.stdout',
2263 'filters' : ['filt1'],
2264 },
2265 },
2266 'loggers' : {
2267 'compiler.parser' : {
2268 'level' : 'DEBUG',
2269 'filters' : ['filt1'],
2270 },
2271 },
2272 'root' : {
2273 'level' : 'WARNING',
2274 'handlers' : ['hand1'],
2275 },
2276 }
2277
2278 #As config1 but using cfg:// references
2279 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002280 'version': 1,
2281 'true_formatters': {
2282 'form1' : {
2283 'format' : '%(levelname)s ++ %(message)s',
2284 },
2285 },
2286 'handler_configs': {
2287 'hand1' : {
2288 'class' : 'logging.StreamHandler',
2289 'formatter' : 'form1',
2290 'level' : 'NOTSET',
2291 'stream' : 'ext://sys.stdout',
2292 },
2293 },
2294 'formatters' : 'cfg://true_formatters',
2295 'handlers' : {
2296 'hand1' : 'cfg://handler_configs[hand1]',
2297 },
2298 'loggers' : {
2299 'compiler.parser' : {
2300 'level' : 'DEBUG',
2301 'handlers' : ['hand1'],
2302 },
2303 },
2304 'root' : {
2305 'level' : 'WARNING',
2306 },
2307 }
2308
2309 #As config11 but missing the version key
2310 config12 = {
2311 'true_formatters': {
2312 'form1' : {
2313 'format' : '%(levelname)s ++ %(message)s',
2314 },
2315 },
2316 'handler_configs': {
2317 'hand1' : {
2318 'class' : 'logging.StreamHandler',
2319 'formatter' : 'form1',
2320 'level' : 'NOTSET',
2321 'stream' : 'ext://sys.stdout',
2322 },
2323 },
2324 'formatters' : 'cfg://true_formatters',
2325 'handlers' : {
2326 'hand1' : 'cfg://handler_configs[hand1]',
2327 },
2328 'loggers' : {
2329 'compiler.parser' : {
2330 'level' : 'DEBUG',
2331 'handlers' : ['hand1'],
2332 },
2333 },
2334 'root' : {
2335 'level' : 'WARNING',
2336 },
2337 }
2338
2339 #As config11 but using an unsupported version
2340 config13 = {
2341 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002342 'true_formatters': {
2343 'form1' : {
2344 'format' : '%(levelname)s ++ %(message)s',
2345 },
2346 },
2347 'handler_configs': {
2348 'hand1' : {
2349 'class' : 'logging.StreamHandler',
2350 'formatter' : 'form1',
2351 'level' : 'NOTSET',
2352 'stream' : 'ext://sys.stdout',
2353 },
2354 },
2355 'formatters' : 'cfg://true_formatters',
2356 'handlers' : {
2357 'hand1' : 'cfg://handler_configs[hand1]',
2358 },
2359 'loggers' : {
2360 'compiler.parser' : {
2361 'level' : 'DEBUG',
2362 'handlers' : ['hand1'],
2363 },
2364 },
2365 'root' : {
2366 'level' : 'WARNING',
2367 },
2368 }
2369
2370 def apply_config(self, conf):
2371 logging.config.dictConfig(conf)
2372
2373 def test_config0_ok(self):
2374 # A simple config which overrides the default settings.
2375 with captured_stdout() as output:
2376 self.apply_config(self.config0)
2377 logger = logging.getLogger()
2378 # Won't output anything
2379 logger.info(self.next_message())
2380 # Outputs a message
2381 logger.error(self.next_message())
2382 self.assert_log_lines([
2383 ('ERROR', '2'),
2384 ], stream=output)
2385 # Original logger output is empty.
2386 self.assert_log_lines([])
2387
2388 def test_config1_ok(self, config=config1):
2389 # A config defining a sub-parser as well.
2390 with captured_stdout() as output:
2391 self.apply_config(config)
2392 logger = logging.getLogger("compiler.parser")
2393 # Both will output a message
2394 logger.info(self.next_message())
2395 logger.error(self.next_message())
2396 self.assert_log_lines([
2397 ('INFO', '1'),
2398 ('ERROR', '2'),
2399 ], stream=output)
2400 # Original logger output is empty.
2401 self.assert_log_lines([])
2402
2403 def test_config2_failure(self):
2404 # A simple config which overrides the default settings.
2405 self.assertRaises(Exception, self.apply_config, self.config2)
2406
2407 def test_config2a_failure(self):
2408 # A simple config which overrides the default settings.
2409 self.assertRaises(Exception, self.apply_config, self.config2a)
2410
2411 def test_config2b_failure(self):
2412 # A simple config which overrides the default settings.
2413 self.assertRaises(Exception, self.apply_config, self.config2b)
2414
2415 def test_config3_failure(self):
2416 # A simple config which overrides the default settings.
2417 self.assertRaises(Exception, self.apply_config, self.config3)
2418
2419 def test_config4_ok(self):
2420 # A config specifying a custom formatter class.
2421 with captured_stdout() as output:
2422 self.apply_config(self.config4)
2423 #logger = logging.getLogger()
2424 try:
2425 raise RuntimeError()
2426 except RuntimeError:
2427 logging.exception("just testing")
2428 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002429 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002430 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2431 # Original logger output is empty
2432 self.assert_log_lines([])
2433
2434 def test_config4a_ok(self):
2435 # A config specifying a custom formatter class.
2436 with captured_stdout() as output:
2437 self.apply_config(self.config4a)
2438 #logger = logging.getLogger()
2439 try:
2440 raise RuntimeError()
2441 except RuntimeError:
2442 logging.exception("just testing")
2443 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002444 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002445 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2446 # Original logger output is empty
2447 self.assert_log_lines([])
2448
2449 def test_config5_ok(self):
2450 self.test_config1_ok(config=self.config5)
2451
2452 def test_config6_failure(self):
2453 self.assertRaises(Exception, self.apply_config, self.config6)
2454
2455 def test_config7_ok(self):
2456 with captured_stdout() as output:
2457 self.apply_config(self.config1)
2458 logger = logging.getLogger("compiler.parser")
2459 # Both will output a message
2460 logger.info(self.next_message())
2461 logger.error(self.next_message())
2462 self.assert_log_lines([
2463 ('INFO', '1'),
2464 ('ERROR', '2'),
2465 ], stream=output)
2466 # Original logger output is empty.
2467 self.assert_log_lines([])
2468 with captured_stdout() as output:
2469 self.apply_config(self.config7)
2470 logger = logging.getLogger("compiler.parser")
2471 self.assertTrue(logger.disabled)
2472 logger = logging.getLogger("compiler.lexer")
2473 # Both will output a message
2474 logger.info(self.next_message())
2475 logger.error(self.next_message())
2476 self.assert_log_lines([
2477 ('INFO', '3'),
2478 ('ERROR', '4'),
2479 ], stream=output)
2480 # Original logger output is empty.
2481 self.assert_log_lines([])
2482
2483 #Same as test_config_7_ok but don't disable old loggers.
2484 def test_config_8_ok(self):
2485 with captured_stdout() as output:
2486 self.apply_config(self.config1)
2487 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002488 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002489 logger.info(self.next_message())
2490 logger.error(self.next_message())
2491 self.assert_log_lines([
2492 ('INFO', '1'),
2493 ('ERROR', '2'),
2494 ], stream=output)
2495 # Original logger output is empty.
2496 self.assert_log_lines([])
2497 with captured_stdout() as output:
2498 self.apply_config(self.config8)
2499 logger = logging.getLogger("compiler.parser")
2500 self.assertFalse(logger.disabled)
2501 # Both will output a message
2502 logger.info(self.next_message())
2503 logger.error(self.next_message())
2504 logger = logging.getLogger("compiler.lexer")
2505 # Both will output a message
2506 logger.info(self.next_message())
2507 logger.error(self.next_message())
2508 self.assert_log_lines([
2509 ('INFO', '3'),
2510 ('ERROR', '4'),
2511 ('INFO', '5'),
2512 ('ERROR', '6'),
2513 ], stream=output)
2514 # Original logger output is empty.
2515 self.assert_log_lines([])
2516
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002517 def test_config_8a_ok(self):
2518 with captured_stdout() as output:
2519 self.apply_config(self.config1a)
2520 logger = logging.getLogger("compiler.parser")
2521 # See issue #11424. compiler-hyphenated sorts
2522 # between compiler and compiler.xyz and this
2523 # was preventing compiler.xyz from being included
2524 # in the child loggers of compiler because of an
2525 # overzealous loop termination condition.
2526 hyphenated = logging.getLogger('compiler-hyphenated')
2527 # All will output a message
2528 logger.info(self.next_message())
2529 logger.error(self.next_message())
2530 hyphenated.critical(self.next_message())
2531 self.assert_log_lines([
2532 ('INFO', '1'),
2533 ('ERROR', '2'),
2534 ('CRITICAL', '3'),
2535 ], stream=output)
2536 # Original logger output is empty.
2537 self.assert_log_lines([])
2538 with captured_stdout() as output:
2539 self.apply_config(self.config8a)
2540 logger = logging.getLogger("compiler.parser")
2541 self.assertFalse(logger.disabled)
2542 # Both will output a message
2543 logger.info(self.next_message())
2544 logger.error(self.next_message())
2545 logger = logging.getLogger("compiler.lexer")
2546 # Both will output a message
2547 logger.info(self.next_message())
2548 logger.error(self.next_message())
2549 # Will not appear
2550 hyphenated.critical(self.next_message())
2551 self.assert_log_lines([
2552 ('INFO', '4'),
2553 ('ERROR', '5'),
2554 ('INFO', '6'),
2555 ('ERROR', '7'),
2556 ], stream=output)
2557 # Original logger output is empty.
2558 self.assert_log_lines([])
2559
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002560 def test_config_9_ok(self):
2561 with captured_stdout() as output:
2562 self.apply_config(self.config9)
2563 logger = logging.getLogger("compiler.parser")
2564 #Nothing will be output since both handler and logger are set to WARNING
2565 logger.info(self.next_message())
2566 self.assert_log_lines([], stream=output)
2567 self.apply_config(self.config9a)
2568 #Nothing will be output since both handler is still set to WARNING
2569 logger.info(self.next_message())
2570 self.assert_log_lines([], stream=output)
2571 self.apply_config(self.config9b)
2572 #Message should now be output
2573 logger.info(self.next_message())
2574 self.assert_log_lines([
2575 ('INFO', '3'),
2576 ], stream=output)
2577
2578 def test_config_10_ok(self):
2579 with captured_stdout() as output:
2580 self.apply_config(self.config10)
2581 logger = logging.getLogger("compiler.parser")
2582 logger.warning(self.next_message())
2583 logger = logging.getLogger('compiler')
2584 #Not output, because filtered
2585 logger.warning(self.next_message())
2586 logger = logging.getLogger('compiler.lexer')
2587 #Not output, because filtered
2588 logger.warning(self.next_message())
2589 logger = logging.getLogger("compiler.parser.codegen")
2590 #Output, as not filtered
2591 logger.error(self.next_message())
2592 self.assert_log_lines([
2593 ('WARNING', '1'),
2594 ('ERROR', '4'),
2595 ], stream=output)
2596
2597 def test_config11_ok(self):
2598 self.test_config1_ok(self.config11)
2599
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002600 def test_config12_failure(self):
2601 self.assertRaises(Exception, self.apply_config, self.config12)
2602
2603 def test_config13_failure(self):
2604 self.assertRaises(Exception, self.apply_config, self.config13)
2605
Victor Stinner45df8202010-04-28 22:31:17 +00002606 @unittest.skipUnless(threading, 'listen() needs threading to work')
Vinay Sajip4ded5512012-10-02 15:56:16 +01002607 def setup_via_listener(self, text, verify=None):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002608 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00002609 # Ask for a randomly assigned port (by using port 0)
Vinay Sajip4ded5512012-10-02 15:56:16 +01002610 t = logging.config.listen(0, verify)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002611 t.start()
2612 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00002613 # Now get the port allocated
2614 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002615 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002616 try:
2617 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
2618 sock.settimeout(2.0)
2619 sock.connect(('localhost', port))
2620
2621 slen = struct.pack('>L', len(text))
2622 s = slen + text
2623 sentsofar = 0
2624 left = len(s)
2625 while left > 0:
2626 sent = sock.send(s[sentsofar:])
2627 sentsofar += sent
2628 left -= sent
2629 sock.close()
2630 finally:
2631 t.ready.wait(2.0)
2632 logging.config.stopListening()
2633 t.join(2.0)
2634
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002635 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002636 def test_listen_config_10_ok(self):
2637 with captured_stdout() as output:
2638 self.setup_via_listener(json.dumps(self.config10))
2639 logger = logging.getLogger("compiler.parser")
2640 logger.warning(self.next_message())
2641 logger = logging.getLogger('compiler')
2642 #Not output, because filtered
2643 logger.warning(self.next_message())
2644 logger = logging.getLogger('compiler.lexer')
2645 #Not output, because filtered
2646 logger.warning(self.next_message())
2647 logger = logging.getLogger("compiler.parser.codegen")
2648 #Output, as not filtered
2649 logger.error(self.next_message())
2650 self.assert_log_lines([
2651 ('WARNING', '1'),
2652 ('ERROR', '4'),
2653 ], stream=output)
2654
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002655 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002656 def test_listen_config_1_ok(self):
2657 with captured_stdout() as output:
2658 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
2659 logger = logging.getLogger("compiler.parser")
2660 # Both will output a message
2661 logger.info(self.next_message())
2662 logger.error(self.next_message())
2663 self.assert_log_lines([
2664 ('INFO', '1'),
2665 ('ERROR', '2'),
2666 ], stream=output)
2667 # Original logger output is empty.
2668 self.assert_log_lines([])
2669
Vinay Sajip4ded5512012-10-02 15:56:16 +01002670 @unittest.skipUnless(threading, 'Threading required for this test.')
2671 def test_listen_verify(self):
2672
2673 def verify_fail(stuff):
2674 return None
2675
2676 def verify_reverse(stuff):
2677 return stuff[::-1]
2678
2679 logger = logging.getLogger("compiler.parser")
2680 to_send = textwrap.dedent(ConfigFileTest.config1)
2681 # First, specify a verification function that will fail.
2682 # We expect to see no output, since our configuration
2683 # never took effect.
2684 with captured_stdout() as output:
2685 self.setup_via_listener(to_send, verify_fail)
2686 # Both will output a message
2687 logger.info(self.next_message())
2688 logger.error(self.next_message())
2689 self.assert_log_lines([], stream=output)
2690 # Original logger output has the stuff we logged.
2691 self.assert_log_lines([
2692 ('INFO', '1'),
2693 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002694 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002695
2696 # Now, perform no verification. Our configuration
2697 # should take effect.
2698
2699 with captured_stdout() as output:
2700 self.setup_via_listener(to_send) # no verify callable specified
2701 logger = logging.getLogger("compiler.parser")
2702 # Both will output a message
2703 logger.info(self.next_message())
2704 logger.error(self.next_message())
2705 self.assert_log_lines([
2706 ('INFO', '3'),
2707 ('ERROR', '4'),
2708 ], stream=output)
2709 # Original logger output still has the stuff we logged before.
2710 self.assert_log_lines([
2711 ('INFO', '1'),
2712 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002713 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002714
2715 # Now, perform verification which transforms the bytes.
2716
2717 with captured_stdout() as output:
2718 self.setup_via_listener(to_send[::-1], verify_reverse)
2719 logger = logging.getLogger("compiler.parser")
2720 # Both will output a message
2721 logger.info(self.next_message())
2722 logger.error(self.next_message())
2723 self.assert_log_lines([
2724 ('INFO', '5'),
2725 ('ERROR', '6'),
2726 ], stream=output)
2727 # Original logger output still has the stuff we logged before.
2728 self.assert_log_lines([
2729 ('INFO', '1'),
2730 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002731 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002732
Vinay Sajip373baef2011-04-26 20:05:24 +01002733 def test_baseconfig(self):
2734 d = {
2735 'atuple': (1, 2, 3),
2736 'alist': ['a', 'b', 'c'],
2737 'adict': {'d': 'e', 'f': 3 },
2738 'nest1': ('g', ('h', 'i'), 'j'),
2739 'nest2': ['k', ['l', 'm'], 'n'],
2740 'nest3': ['o', 'cfg://alist', 'p'],
2741 }
2742 bc = logging.config.BaseConfigurator(d)
2743 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
2744 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
2745 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
2746 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
2747 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
2748 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
2749 v = bc.convert('cfg://nest3')
2750 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
2751 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
2752 self.assertRaises(ValueError, bc.convert, 'cfg://!')
2753 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002754
2755class ManagerTest(BaseTest):
2756 def test_manager_loggerclass(self):
2757 logged = []
2758
2759 class MyLogger(logging.Logger):
2760 def _log(self, level, msg, args, exc_info=None, extra=None):
2761 logged.append(msg)
2762
2763 man = logging.Manager(None)
2764 self.assertRaises(TypeError, man.setLoggerClass, int)
2765 man.setLoggerClass(MyLogger)
2766 logger = man.getLogger('test')
2767 logger.warning('should appear in logged')
2768 logging.warning('should not appear in logged')
2769
2770 self.assertEqual(logged, ['should appear in logged'])
2771
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002772 def test_set_log_record_factory(self):
2773 man = logging.Manager(None)
2774 expected = object()
2775 man.setLogRecordFactory(expected)
2776 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002777
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002778class ChildLoggerTest(BaseTest):
2779 def test_child_loggers(self):
2780 r = logging.getLogger()
2781 l1 = logging.getLogger('abc')
2782 l2 = logging.getLogger('def.ghi')
2783 c1 = r.getChild('xyz')
2784 c2 = r.getChild('uvw.xyz')
2785 self.assertTrue(c1 is logging.getLogger('xyz'))
2786 self.assertTrue(c2 is logging.getLogger('uvw.xyz'))
2787 c1 = l1.getChild('def')
2788 c2 = c1.getChild('ghi')
2789 c3 = l1.getChild('def.ghi')
2790 self.assertTrue(c1 is logging.getLogger('abc.def'))
2791 self.assertTrue(c2 is logging.getLogger('abc.def.ghi'))
2792 self.assertTrue(c2 is c3)
2793
2794
Vinay Sajip6fac8172010-10-19 20:44:14 +00002795class DerivedLogRecord(logging.LogRecord):
2796 pass
2797
Vinay Sajip61561522010-12-03 11:50:38 +00002798class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00002799
2800 def setUp(self):
2801 class CheckingFilter(logging.Filter):
2802 def __init__(self, cls):
2803 self.cls = cls
2804
2805 def filter(self, record):
2806 t = type(record)
2807 if t is not self.cls:
2808 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
2809 self.cls)
2810 raise TypeError(msg)
2811 return True
2812
2813 BaseTest.setUp(self)
2814 self.filter = CheckingFilter(DerivedLogRecord)
2815 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00002816 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00002817
2818 def tearDown(self):
2819 self.root_logger.removeFilter(self.filter)
2820 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00002821 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002822
2823 def test_logrecord_class(self):
2824 self.assertRaises(TypeError, self.root_logger.warning,
2825 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00002826 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002827 self.root_logger.error(self.next_message())
2828 self.assert_log_lines([
2829 ('root', 'ERROR', '2'),
2830 ])
2831
2832
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002833class QueueHandlerTest(BaseTest):
2834 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002835 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002836
2837 def setUp(self):
2838 BaseTest.setUp(self)
2839 self.queue = queue.Queue(-1)
2840 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
2841 self.que_logger = logging.getLogger('que')
2842 self.que_logger.propagate = False
2843 self.que_logger.setLevel(logging.WARNING)
2844 self.que_logger.addHandler(self.que_hdlr)
2845
2846 def tearDown(self):
2847 self.que_hdlr.close()
2848 BaseTest.tearDown(self)
2849
2850 def test_queue_handler(self):
2851 self.que_logger.debug(self.next_message())
2852 self.assertRaises(queue.Empty, self.queue.get_nowait)
2853 self.que_logger.info(self.next_message())
2854 self.assertRaises(queue.Empty, self.queue.get_nowait)
2855 msg = self.next_message()
2856 self.que_logger.warning(msg)
2857 data = self.queue.get_nowait()
2858 self.assertTrue(isinstance(data, logging.LogRecord))
2859 self.assertEqual(data.name, self.que_logger.name)
2860 self.assertEqual((data.msg, data.args), (msg, None))
2861
Victor Stinnercafa2ef2011-05-02 16:11:28 +02002862 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
2863 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01002864 def test_queue_listener(self):
2865 handler = TestHandler(Matcher())
2866 listener = logging.handlers.QueueListener(self.queue, handler)
2867 listener.start()
2868 try:
2869 self.que_logger.warning(self.next_message())
2870 self.que_logger.error(self.next_message())
2871 self.que_logger.critical(self.next_message())
2872 finally:
2873 listener.stop()
2874 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
2875 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
2876 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
2877
Vinay Sajip37eb3382011-04-26 20:26:41 +01002878ZERO = datetime.timedelta(0)
2879
2880class UTC(datetime.tzinfo):
2881 def utcoffset(self, dt):
2882 return ZERO
2883
2884 dst = utcoffset
2885
2886 def tzname(self, dt):
2887 return 'UTC'
2888
2889utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01002890
Vinay Sajipa39c5712010-10-25 13:57:39 +00002891class FormatterTest(unittest.TestCase):
2892 def setUp(self):
2893 self.common = {
2894 'name': 'formatter.test',
2895 'level': logging.DEBUG,
2896 'pathname': os.path.join('path', 'to', 'dummy.ext'),
2897 'lineno': 42,
2898 'exc_info': None,
2899 'func': None,
2900 'msg': 'Message with %d %s',
2901 'args': (2, 'placeholders'),
2902 }
2903 self.variants = {
2904 }
2905
2906 def get_record(self, name=None):
2907 result = dict(self.common)
2908 if name is not None:
2909 result.update(self.variants[name])
2910 return logging.makeLogRecord(result)
2911
2912 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002913 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002914 r = self.get_record()
2915 f = logging.Formatter('${%(message)s}')
2916 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
2917 f = logging.Formatter('%(random)s')
2918 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002919 self.assertFalse(f.usesTime())
2920 f = logging.Formatter('%(asctime)s')
2921 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002922 f = logging.Formatter('%(asctime)-15s')
2923 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002924 f = logging.Formatter('asctime')
2925 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002926
2927 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002928 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002929 r = self.get_record()
2930 f = logging.Formatter('$%{message}%$', style='{')
2931 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2932 f = logging.Formatter('{random}', style='{')
2933 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002934 self.assertFalse(f.usesTime())
2935 f = logging.Formatter('{asctime}', style='{')
2936 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002937 f = logging.Formatter('{asctime!s:15}', style='{')
2938 self.assertTrue(f.usesTime())
2939 f = logging.Formatter('{asctime:15}', style='{')
2940 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002941 f = logging.Formatter('asctime', style='{')
2942 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002943
2944 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002945 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002946 r = self.get_record()
2947 f = logging.Formatter('$message', style='$')
2948 self.assertEqual(f.format(r), 'Message with 2 placeholders')
2949 f = logging.Formatter('$$%${message}%$$', style='$')
2950 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2951 f = logging.Formatter('${random}', style='$')
2952 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002953 self.assertFalse(f.usesTime())
2954 f = logging.Formatter('${asctime}', style='$')
2955 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002956 f = logging.Formatter('${asctime', style='$')
2957 self.assertFalse(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002958 f = logging.Formatter('$asctime', style='$')
2959 self.assertTrue(f.usesTime())
2960 f = logging.Formatter('asctime', style='$')
2961 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002962
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002963 def test_invalid_style(self):
2964 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
2965
Vinay Sajip86a96ce2011-04-27 08:30:30 +01002966 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002967 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01002968 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
2969 # We use None to indicate we want the local timezone
2970 # We're essentially converting a UTC time to local time
2971 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002972 r.msecs = 123
2973 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01002974 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002975 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
2976 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01002977 f.format(r)
2978 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
2979
2980class TestBufferingFormatter(logging.BufferingFormatter):
2981 def formatHeader(self, records):
2982 return '[(%d)' % len(records)
2983
2984 def formatFooter(self, records):
2985 return '(%d)]' % len(records)
2986
2987class BufferingFormatterTest(unittest.TestCase):
2988 def setUp(self):
2989 self.records = [
2990 logging.makeLogRecord({'msg': 'one'}),
2991 logging.makeLogRecord({'msg': 'two'}),
2992 ]
2993
2994 def test_default(self):
2995 f = logging.BufferingFormatter()
2996 self.assertEqual('', f.format([]))
2997 self.assertEqual('onetwo', f.format(self.records))
2998
2999 def test_custom(self):
3000 f = TestBufferingFormatter()
3001 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
3002 lf = logging.Formatter('<%(message)s>')
3003 f = TestBufferingFormatter(lf)
3004 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003005
3006class ExceptionTest(BaseTest):
3007 def test_formatting(self):
3008 r = self.root_logger
3009 h = RecordingHandler()
3010 r.addHandler(h)
3011 try:
3012 raise RuntimeError('deliberate mistake')
3013 except:
3014 logging.exception('failed', stack_info=True)
3015 r.removeHandler(h)
3016 h.close()
3017 r = h.records[0]
3018 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
3019 'call last):\n'))
3020 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
3021 'deliberate mistake'))
3022 self.assertTrue(r.stack_info.startswith('Stack (most recent '
3023 'call last):\n'))
3024 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
3025 'stack_info=True)'))
3026
3027
Vinay Sajip5a27d402010-12-10 11:42:57 +00003028class LastResortTest(BaseTest):
3029 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003030 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00003031 root = self.root_logger
3032 root.removeHandler(self.root_hdlr)
3033 old_stderr = sys.stderr
3034 old_lastresort = logging.lastResort
3035 old_raise_exceptions = logging.raiseExceptions
3036 try:
3037 sys.stderr = sio = io.StringIO()
Vinay Sajip8188f582011-07-25 19:58:13 +01003038 root.debug('This should not appear')
3039 self.assertEqual(sio.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00003040 root.warning('This is your final chance!')
3041 self.assertEqual(sio.getvalue(), 'This is your final chance!\n')
3042 #No handlers and no last resort, so 'No handlers' message
3043 logging.lastResort = None
3044 sys.stderr = sio = io.StringIO()
3045 root.warning('This is your final chance!')
3046 self.assertEqual(sio.getvalue(), 'No handlers could be found for logger "root"\n')
3047 # 'No handlers' message only printed once
3048 sys.stderr = sio = io.StringIO()
3049 root.warning('This is your final chance!')
3050 self.assertEqual(sio.getvalue(), '')
3051 root.manager.emittedNoHandlerWarning = False
3052 #If raiseExceptions is False, no message is printed
3053 logging.raiseExceptions = False
3054 sys.stderr = sio = io.StringIO()
3055 root.warning('This is your final chance!')
3056 self.assertEqual(sio.getvalue(), '')
3057 finally:
3058 sys.stderr = old_stderr
3059 root.addHandler(self.root_hdlr)
3060 logging.lastResort = old_lastresort
3061 logging.raiseExceptions = old_raise_exceptions
3062
3063
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003064class FakeHandler:
3065
3066 def __init__(self, identifier, called):
3067 for method in ('acquire', 'flush', 'close', 'release'):
3068 setattr(self, method, self.record_call(identifier, method, called))
3069
3070 def record_call(self, identifier, method_name, called):
3071 def inner():
3072 called.append('{} - {}'.format(identifier, method_name))
3073 return inner
3074
3075
3076class RecordingHandler(logging.NullHandler):
3077
3078 def __init__(self, *args, **kwargs):
3079 super(RecordingHandler, self).__init__(*args, **kwargs)
3080 self.records = []
3081
3082 def handle(self, record):
3083 """Keep track of all the emitted records."""
3084 self.records.append(record)
3085
3086
3087class ShutdownTest(BaseTest):
3088
Vinay Sajip5e66b162011-04-20 15:41:14 +01003089 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003090
3091 def setUp(self):
3092 super(ShutdownTest, self).setUp()
3093 self.called = []
3094
3095 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003096 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003097
3098 def raise_error(self, error):
3099 def inner():
3100 raise error()
3101 return inner
3102
3103 def test_no_failure(self):
3104 # create some fake handlers
3105 handler0 = FakeHandler(0, self.called)
3106 handler1 = FakeHandler(1, self.called)
3107 handler2 = FakeHandler(2, self.called)
3108
3109 # create live weakref to those handlers
3110 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
3111
3112 logging.shutdown(handlerList=list(handlers))
3113
3114 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
3115 '1 - acquire', '1 - flush', '1 - close', '1 - release',
3116 '0 - acquire', '0 - flush', '0 - close', '0 - release']
3117 self.assertEqual(expected, self.called)
3118
3119 def _test_with_failure_in_method(self, method, error):
3120 handler = FakeHandler(0, self.called)
3121 setattr(handler, method, self.raise_error(error))
3122 handlers = [logging.weakref.ref(handler)]
3123
3124 logging.shutdown(handlerList=list(handlers))
3125
3126 self.assertEqual('0 - release', self.called[-1])
3127
3128 def test_with_ioerror_in_acquire(self):
3129 self._test_with_failure_in_method('acquire', IOError)
3130
3131 def test_with_ioerror_in_flush(self):
3132 self._test_with_failure_in_method('flush', IOError)
3133
3134 def test_with_ioerror_in_close(self):
3135 self._test_with_failure_in_method('close', IOError)
3136
3137 def test_with_valueerror_in_acquire(self):
3138 self._test_with_failure_in_method('acquire', ValueError)
3139
3140 def test_with_valueerror_in_flush(self):
3141 self._test_with_failure_in_method('flush', ValueError)
3142
3143 def test_with_valueerror_in_close(self):
3144 self._test_with_failure_in_method('close', ValueError)
3145
3146 def test_with_other_error_in_acquire_without_raise(self):
3147 logging.raiseExceptions = False
3148 self._test_with_failure_in_method('acquire', IndexError)
3149
3150 def test_with_other_error_in_flush_without_raise(self):
3151 logging.raiseExceptions = False
3152 self._test_with_failure_in_method('flush', IndexError)
3153
3154 def test_with_other_error_in_close_without_raise(self):
3155 logging.raiseExceptions = False
3156 self._test_with_failure_in_method('close', IndexError)
3157
3158 def test_with_other_error_in_acquire_with_raise(self):
3159 logging.raiseExceptions = True
3160 self.assertRaises(IndexError, self._test_with_failure_in_method,
3161 'acquire', IndexError)
3162
3163 def test_with_other_error_in_flush_with_raise(self):
3164 logging.raiseExceptions = True
3165 self.assertRaises(IndexError, self._test_with_failure_in_method,
3166 'flush', IndexError)
3167
3168 def test_with_other_error_in_close_with_raise(self):
3169 logging.raiseExceptions = True
3170 self.assertRaises(IndexError, self._test_with_failure_in_method,
3171 'close', IndexError)
3172
3173
3174class ModuleLevelMiscTest(BaseTest):
3175
Vinay Sajip5e66b162011-04-20 15:41:14 +01003176 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003177
3178 def test_disable(self):
3179 old_disable = logging.root.manager.disable
3180 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003181 self.assertEqual(old_disable, 0)
3182 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003183
3184 logging.disable(83)
3185 self.assertEqual(logging.root.manager.disable, 83)
3186
3187 def _test_log(self, method, level=None):
3188 called = []
3189 patch(self, logging, 'basicConfig',
Vinay Sajip00bdbe12011-04-22 00:17:46 +01003190 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003191
3192 recording = RecordingHandler()
3193 logging.root.addHandler(recording)
3194
3195 log_method = getattr(logging, method)
3196 if level is not None:
3197 log_method(level, "test me: %r", recording)
3198 else:
3199 log_method("test me: %r", recording)
3200
3201 self.assertEqual(len(recording.records), 1)
3202 record = recording.records[0]
3203 self.assertEqual(record.getMessage(), "test me: %r" % recording)
3204
3205 expected_level = level if level is not None else getattr(logging, method.upper())
3206 self.assertEqual(record.levelno, expected_level)
3207
3208 # basicConfig was not called!
3209 self.assertEqual(called, [])
3210
3211 def test_log(self):
3212 self._test_log('log', logging.ERROR)
3213
3214 def test_debug(self):
3215 self._test_log('debug')
3216
3217 def test_info(self):
3218 self._test_log('info')
3219
3220 def test_warning(self):
3221 self._test_log('warning')
3222
3223 def test_error(self):
3224 self._test_log('error')
3225
3226 def test_critical(self):
3227 self._test_log('critical')
3228
3229 def test_set_logger_class(self):
3230 self.assertRaises(TypeError, logging.setLoggerClass, object)
3231
3232 class MyLogger(logging.Logger):
3233 pass
3234
3235 logging.setLoggerClass(MyLogger)
3236 self.assertEqual(logging.getLoggerClass(), MyLogger)
3237
3238 logging.setLoggerClass(logging.Logger)
3239 self.assertEqual(logging.getLoggerClass(), logging.Logger)
3240
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003241class LogRecordTest(BaseTest):
3242 def test_str_rep(self):
3243 r = logging.makeLogRecord({})
3244 s = str(r)
3245 self.assertTrue(s.startswith('<LogRecord: '))
3246 self.assertTrue(s.endswith('>'))
3247
3248 def test_dict_arg(self):
3249 h = RecordingHandler()
3250 r = logging.getLogger()
3251 r.addHandler(h)
3252 d = {'less' : 'more' }
3253 logging.warning('less is %(less)s', d)
3254 self.assertIs(h.records[0].args, d)
3255 self.assertEqual(h.records[0].message, 'less is more')
3256 r.removeHandler(h)
3257 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003258
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003259 def test_multiprocessing(self):
3260 r = logging.makeLogRecord({})
3261 self.assertEqual(r.processName, 'MainProcess')
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003262 try:
3263 import multiprocessing as mp
3264 r = logging.makeLogRecord({})
3265 self.assertEqual(r.processName, mp.current_process().name)
3266 except ImportError:
3267 pass
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003268
3269 def test_optional(self):
3270 r = logging.makeLogRecord({})
3271 NOT_NONE = self.assertIsNotNone
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003272 if threading:
3273 NOT_NONE(r.thread)
3274 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003275 NOT_NONE(r.process)
3276 NOT_NONE(r.processName)
3277 log_threads = logging.logThreads
3278 log_processes = logging.logProcesses
3279 log_multiprocessing = logging.logMultiprocessing
3280 try:
3281 logging.logThreads = False
3282 logging.logProcesses = False
3283 logging.logMultiprocessing = False
3284 r = logging.makeLogRecord({})
3285 NONE = self.assertIsNone
3286 NONE(r.thread)
3287 NONE(r.threadName)
3288 NONE(r.process)
3289 NONE(r.processName)
3290 finally:
3291 logging.logThreads = log_threads
3292 logging.logProcesses = log_processes
3293 logging.logMultiprocessing = log_multiprocessing
3294
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003295class BasicConfigTest(unittest.TestCase):
3296
Vinay Sajip95bf5042011-04-20 11:50:56 +01003297 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003298
3299 def setUp(self):
3300 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01003301 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01003302 self.saved_handlers = logging._handlers.copy()
3303 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003304 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003305 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003306 logging.root.handlers = []
3307
3308 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01003309 for h in logging.root.handlers[:]:
3310 logging.root.removeHandler(h)
3311 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003312 super(BasicConfigTest, self).tearDown()
3313
Vinay Sajip3def7e02011-04-20 10:58:06 +01003314 def cleanup(self):
3315 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01003316 logging._handlers.clear()
3317 logging._handlers.update(self.saved_handlers)
3318 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003319 logging.root.level = self.original_logging_level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003320
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003321 def test_no_kwargs(self):
3322 logging.basicConfig()
3323
3324 # handler defaults to a StreamHandler to sys.stderr
3325 self.assertEqual(len(logging.root.handlers), 1)
3326 handler = logging.root.handlers[0]
3327 self.assertIsInstance(handler, logging.StreamHandler)
3328 self.assertEqual(handler.stream, sys.stderr)
3329
3330 formatter = handler.formatter
3331 # format defaults to logging.BASIC_FORMAT
3332 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
3333 # datefmt defaults to None
3334 self.assertIsNone(formatter.datefmt)
3335 # style defaults to %
3336 self.assertIsInstance(formatter._style, logging.PercentStyle)
3337
Florent Xiclunae41f0de2011-11-11 19:39:25 +01003338 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01003339 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003340
3341 def test_filename(self):
3342 logging.basicConfig(filename='test.log')
3343
3344 self.assertEqual(len(logging.root.handlers), 1)
3345 handler = logging.root.handlers[0]
3346 self.assertIsInstance(handler, logging.FileHandler)
3347
3348 expected = logging.FileHandler('test.log', 'a')
3349 self.addCleanup(expected.close)
3350 self.assertEqual(handler.stream.mode, expected.stream.mode)
3351 self.assertEqual(handler.stream.name, expected.stream.name)
3352
3353 def test_filemode(self):
3354 logging.basicConfig(filename='test.log', filemode='wb')
3355
3356 handler = logging.root.handlers[0]
3357 expected = logging.FileHandler('test.log', 'wb')
3358 self.addCleanup(expected.close)
3359 self.assertEqual(handler.stream.mode, expected.stream.mode)
3360
3361 def test_stream(self):
3362 stream = io.StringIO()
3363 self.addCleanup(stream.close)
3364 logging.basicConfig(stream=stream)
3365
3366 self.assertEqual(len(logging.root.handlers), 1)
3367 handler = logging.root.handlers[0]
3368 self.assertIsInstance(handler, logging.StreamHandler)
3369 self.assertEqual(handler.stream, stream)
3370
3371 def test_format(self):
3372 logging.basicConfig(format='foo')
3373
3374 formatter = logging.root.handlers[0].formatter
3375 self.assertEqual(formatter._style._fmt, 'foo')
3376
3377 def test_datefmt(self):
3378 logging.basicConfig(datefmt='bar')
3379
3380 formatter = logging.root.handlers[0].formatter
3381 self.assertEqual(formatter.datefmt, 'bar')
3382
3383 def test_style(self):
3384 logging.basicConfig(style='$')
3385
3386 formatter = logging.root.handlers[0].formatter
3387 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
3388
3389 def test_level(self):
3390 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003391 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003392
3393 logging.basicConfig(level=57)
3394 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003395 # Test that second call has no effect
3396 logging.basicConfig(level=58)
3397 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003398
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003399 def test_incompatible(self):
3400 assertRaises = self.assertRaises
3401 handlers = [logging.StreamHandler()]
3402 stream = sys.stderr
3403 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3404 stream=stream)
3405 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3406 handlers=handlers)
3407 assertRaises(ValueError, logging.basicConfig, stream=stream,
3408 handlers=handlers)
3409
3410 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003411 handlers = [
3412 logging.StreamHandler(),
3413 logging.StreamHandler(sys.stdout),
3414 logging.StreamHandler(),
3415 ]
3416 f = logging.Formatter()
3417 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003418 logging.basicConfig(handlers=handlers)
3419 self.assertIs(handlers[0], logging.root.handlers[0])
3420 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003421 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003422 self.assertIsNotNone(handlers[0].formatter)
3423 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003424 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003425 self.assertIs(handlers[0].formatter, handlers[1].formatter)
3426
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003427 def _test_log(self, method, level=None):
3428 # logging.root has no handlers so basicConfig should be called
3429 called = []
3430
3431 old_basic_config = logging.basicConfig
3432 def my_basic_config(*a, **kw):
3433 old_basic_config()
3434 old_level = logging.root.level
3435 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003436 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003437 called.append((a, kw))
3438
3439 patch(self, logging, 'basicConfig', my_basic_config)
3440
3441 log_method = getattr(logging, method)
3442 if level is not None:
3443 log_method(level, "test me")
3444 else:
3445 log_method("test me")
3446
3447 # basicConfig was called with no arguments
3448 self.assertEqual(called, [((), {})])
3449
3450 def test_log(self):
3451 self._test_log('log', logging.WARNING)
3452
3453 def test_debug(self):
3454 self._test_log('debug')
3455
3456 def test_info(self):
3457 self._test_log('info')
3458
3459 def test_warning(self):
3460 self._test_log('warning')
3461
3462 def test_error(self):
3463 self._test_log('error')
3464
3465 def test_critical(self):
3466 self._test_log('critical')
3467
3468
3469class LoggerAdapterTest(unittest.TestCase):
3470
3471 def setUp(self):
3472 super(LoggerAdapterTest, self).setUp()
3473 old_handler_list = logging._handlerList[:]
3474
3475 self.recording = RecordingHandler()
3476 self.logger = logging.root
3477 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003478 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003479 self.addCleanup(self.recording.close)
3480
3481 def cleanup():
3482 logging._handlerList[:] = old_handler_list
3483
3484 self.addCleanup(cleanup)
3485 self.addCleanup(logging.shutdown)
3486 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
3487
3488 def test_exception(self):
3489 msg = 'testing exception: %r'
3490 exc = None
3491 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003492 1 / 0
3493 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003494 exc = e
3495 self.adapter.exception(msg, self.recording)
3496
3497 self.assertEqual(len(self.recording.records), 1)
3498 record = self.recording.records[0]
3499 self.assertEqual(record.levelno, logging.ERROR)
3500 self.assertEqual(record.msg, msg)
3501 self.assertEqual(record.args, (self.recording,))
3502 self.assertEqual(record.exc_info,
3503 (exc.__class__, exc, exc.__traceback__))
3504
3505 def test_critical(self):
3506 msg = 'critical test! %r'
3507 self.adapter.critical(msg, self.recording)
3508
3509 self.assertEqual(len(self.recording.records), 1)
3510 record = self.recording.records[0]
3511 self.assertEqual(record.levelno, logging.CRITICAL)
3512 self.assertEqual(record.msg, msg)
3513 self.assertEqual(record.args, (self.recording,))
3514
3515 def test_is_enabled_for(self):
3516 old_disable = self.adapter.logger.manager.disable
3517 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003518 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
3519 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003520 self.assertFalse(self.adapter.isEnabledFor(32))
3521
3522 def test_has_handlers(self):
3523 self.assertTrue(self.adapter.hasHandlers())
3524
3525 for handler in self.logger.handlers:
3526 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003527
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003528 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003529 self.assertFalse(self.adapter.hasHandlers())
3530
3531
3532class LoggerTest(BaseTest):
3533
3534 def setUp(self):
3535 super(LoggerTest, self).setUp()
3536 self.recording = RecordingHandler()
3537 self.logger = logging.Logger(name='blah')
3538 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003539 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003540 self.addCleanup(self.recording.close)
3541 self.addCleanup(logging.shutdown)
3542
3543 def test_set_invalid_level(self):
3544 self.assertRaises(TypeError, self.logger.setLevel, object())
3545
3546 def test_exception(self):
3547 msg = 'testing exception: %r'
3548 exc = None
3549 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003550 1 / 0
3551 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003552 exc = e
3553 self.logger.exception(msg, self.recording)
3554
3555 self.assertEqual(len(self.recording.records), 1)
3556 record = self.recording.records[0]
3557 self.assertEqual(record.levelno, logging.ERROR)
3558 self.assertEqual(record.msg, msg)
3559 self.assertEqual(record.args, (self.recording,))
3560 self.assertEqual(record.exc_info,
3561 (exc.__class__, exc, exc.__traceback__))
3562
3563 def test_log_invalid_level_with_raise(self):
3564 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003565 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003566
3567 logging.raiseExceptions = True
3568 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
3569
3570 def test_log_invalid_level_no_raise(self):
3571 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003572 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003573
3574 logging.raiseExceptions = False
3575 self.logger.log('10', 'test message') # no exception happens
3576
3577 def test_find_caller_with_stack_info(self):
3578 called = []
3579 patch(self, logging.traceback, 'print_stack',
3580 lambda f, file: called.append(file.getvalue()))
3581
3582 self.logger.findCaller(stack_info=True)
3583
3584 self.assertEqual(len(called), 1)
3585 self.assertEqual('Stack (most recent call last):\n', called[0])
3586
3587 def test_make_record_with_extra_overwrite(self):
3588 name = 'my record'
3589 level = 13
3590 fn = lno = msg = args = exc_info = func = sinfo = None
3591 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
3592 exc_info, func, sinfo)
3593
3594 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
3595 extra = {key: 'some value'}
3596 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
3597 fn, lno, msg, args, exc_info,
3598 extra=extra, sinfo=sinfo)
3599
3600 def test_make_record_with_extra_no_overwrite(self):
3601 name = 'my record'
3602 level = 13
3603 fn = lno = msg = args = exc_info = func = sinfo = None
3604 extra = {'valid_key': 'some value'}
3605 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
3606 exc_info, extra=extra, sinfo=sinfo)
3607 self.assertIn('valid_key', result.__dict__)
3608
3609 def test_has_handlers(self):
3610 self.assertTrue(self.logger.hasHandlers())
3611
3612 for handler in self.logger.handlers:
3613 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003614 self.assertFalse(self.logger.hasHandlers())
3615
3616 def test_has_handlers_no_propagate(self):
3617 child_logger = logging.getLogger('blah.child')
3618 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003619 self.assertFalse(child_logger.hasHandlers())
3620
3621 def test_is_enabled_for(self):
3622 old_disable = self.logger.manager.disable
3623 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003624 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003625 self.assertFalse(self.logger.isEnabledFor(22))
3626
Florent Xicluna5252f9f2011-11-07 19:43:05 +01003627 def test_root_logger_aliases(self):
3628 root = logging.getLogger()
3629 self.assertIs(root, logging.root)
3630 self.assertIs(root, logging.getLogger(None))
3631 self.assertIs(root, logging.getLogger(''))
3632 self.assertIs(root, logging.getLogger('foo').root)
3633 self.assertIs(root, logging.getLogger('foo.bar').root)
3634 self.assertIs(root, logging.getLogger('foo').parent)
3635
3636 self.assertIsNot(root, logging.getLogger('\0'))
3637 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
3638
3639 def test_invalid_names(self):
3640 self.assertRaises(TypeError, logging.getLogger, any)
3641 self.assertRaises(TypeError, logging.getLogger, b'foo')
3642
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003643
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003644class BaseFileTest(BaseTest):
3645 "Base class for handler tests that write log files"
3646
3647 def setUp(self):
3648 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003649 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
3650 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003651 self.rmfiles = []
3652
3653 def tearDown(self):
3654 for fn in self.rmfiles:
3655 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003656 if os.path.exists(self.fn):
3657 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00003658 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003659
3660 def assertLogFile(self, filename):
3661 "Assert a log file is there and register it for deletion"
3662 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01003663 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003664 self.rmfiles.append(filename)
3665
3666
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003667class FileHandlerTest(BaseFileTest):
3668 def test_delay(self):
3669 os.unlink(self.fn)
3670 fh = logging.FileHandler(self.fn, delay=True)
3671 self.assertIsNone(fh.stream)
3672 self.assertFalse(os.path.exists(self.fn))
3673 fh.handle(logging.makeLogRecord({}))
3674 self.assertIsNotNone(fh.stream)
3675 self.assertTrue(os.path.exists(self.fn))
3676 fh.close()
3677
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003678class RotatingFileHandlerTest(BaseFileTest):
3679 def next_rec(self):
3680 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
3681 self.next_message(), None, None, None)
3682
3683 def test_should_not_rollover(self):
3684 # If maxbytes is zero rollover never occurs
3685 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
3686 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00003687 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003688
3689 def test_should_rollover(self):
3690 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
3691 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00003692 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003693
3694 def test_file_created(self):
3695 # checks that the file is created and assumes it was created
3696 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003697 rh = logging.handlers.RotatingFileHandler(self.fn)
3698 rh.emit(self.next_rec())
3699 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00003700 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003701
3702 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00003703 def namer(name):
3704 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003705 rh = logging.handlers.RotatingFileHandler(
3706 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003707 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003708 rh.emit(self.next_rec())
3709 self.assertLogFile(self.fn)
3710 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003711 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003712 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003713 self.assertLogFile(namer(self.fn + ".2"))
3714 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
3715 rh.close()
3716
Eric V. Smith851cad72012-03-11 22:46:04 -07003717 @requires_zlib
Vinay Sajip23b94d02012-01-04 12:02:26 +00003718 def test_rotator(self):
3719 def namer(name):
3720 return name + ".gz"
3721
3722 def rotator(source, dest):
3723 with open(source, "rb") as sf:
3724 data = sf.read()
3725 compressed = zlib.compress(data, 9)
3726 with open(dest, "wb") as df:
3727 df.write(compressed)
3728 os.remove(source)
3729
3730 rh = logging.handlers.RotatingFileHandler(
3731 self.fn, backupCount=2, maxBytes=1)
3732 rh.rotator = rotator
3733 rh.namer = namer
3734 m1 = self.next_rec()
3735 rh.emit(m1)
3736 self.assertLogFile(self.fn)
3737 m2 = self.next_rec()
3738 rh.emit(m2)
3739 fn = namer(self.fn + ".1")
3740 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003741 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00003742 with open(fn, "rb") as f:
3743 compressed = f.read()
3744 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003745 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003746 rh.emit(self.next_rec())
3747 fn = namer(self.fn + ".2")
3748 self.assertLogFile(fn)
3749 with open(fn, "rb") as f:
3750 compressed = f.read()
3751 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003752 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003753 rh.emit(self.next_rec())
3754 fn = namer(self.fn + ".2")
3755 with open(fn, "rb") as f:
3756 compressed = f.read()
3757 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003758 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003759 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00003760 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003761
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003762class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01003763 # other test methods added below
3764 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01003765 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
3766 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00003767 fmt = logging.Formatter('%(asctime)s %(message)s')
3768 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003769 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003770 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01003771 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003772 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00003773 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003774 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01003775 fh.close()
3776 # At this point, we should have a recent rotated file which we
3777 # can test for the existence of. However, in practice, on some
3778 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01003779 # in time to go to look for the log file. So, we go back a fair
3780 # bit, and stop as soon as we see a rotated file. In theory this
3781 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01003782 found = False
3783 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01003784 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01003785 for secs in range(GO_BACK):
3786 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01003787 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
3788 found = os.path.exists(fn)
3789 if found:
3790 self.rmfiles.append(fn)
3791 break
Vinay Sajip672c5812011-05-13 07:09:40 +01003792 msg = 'No rotated files found, went back %d seconds' % GO_BACK
3793 if not found:
3794 #print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01003795 dn, fn = os.path.split(self.fn)
3796 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02003797 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
3798 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00003799 for f in files:
3800 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00003801 path = os.path.join(dn, f)
3802 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00003803 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01003804 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003805
Vinay Sajip0372e102011-05-05 12:59:14 +01003806 def test_invalid(self):
3807 assertRaises = self.assertRaises
3808 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003809 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003810 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003811 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003812 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003813 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003814
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003815def secs(**kw):
3816 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
3817
3818for when, exp in (('S', 1),
3819 ('M', 60),
3820 ('H', 60 * 60),
3821 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00003822 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003823 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00003824 ('W0', secs(days=4, hours=24)),
3825 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003826 def test_compute_rollover(self, when=when, exp=exp):
3827 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00003828 self.fn, when=when, interval=1, backupCount=0, utc=True)
3829 currentTime = 0.0
3830 actual = rh.computeRollover(currentTime)
3831 if exp != actual:
3832 # Failures occur on some systems for MIDNIGHT and W0.
3833 # Print detailed calculation for MIDNIGHT so we can try to see
3834 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00003835 if when == 'MIDNIGHT':
3836 try:
3837 if rh.utc:
3838 t = time.gmtime(currentTime)
3839 else:
3840 t = time.localtime(currentTime)
3841 currentHour = t[3]
3842 currentMinute = t[4]
3843 currentSecond = t[5]
3844 # r is the number of seconds left between now and midnight
3845 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
3846 currentMinute) * 60 +
3847 currentSecond)
3848 result = currentTime + r
3849 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
3850 print('currentHour: %s' % currentHour, file=sys.stderr)
3851 print('currentMinute: %s' % currentMinute, file=sys.stderr)
3852 print('currentSecond: %s' % currentSecond, file=sys.stderr)
3853 print('r: %s' % r, file=sys.stderr)
3854 print('result: %s' % result, file=sys.stderr)
3855 except Exception:
3856 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
3857 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00003858 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003859 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
3860
Vinay Sajip60ccd822011-05-09 17:32:09 +01003861
3862@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil required for this test.')
3863class NTEventLogHandlerTest(BaseTest):
3864 def test_basic(self):
3865 logtype = 'Application'
3866 elh = win32evtlog.OpenEventLog(None, logtype)
3867 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
3868 h = logging.handlers.NTEventLogHandler('test_logging')
3869 r = logging.makeLogRecord({'msg': 'Test Log Message'})
3870 h.handle(r)
3871 h.close()
3872 # Now see if the event is recorded
3873 self.assertTrue(num_recs < win32evtlog.GetNumberOfEventLogRecords(elh))
3874 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
3875 win32evtlog.EVENTLOG_SEQUENTIAL_READ
3876 found = False
3877 GO_BACK = 100
3878 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
3879 for e in events:
3880 if e.SourceName != 'test_logging':
3881 continue
3882 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
3883 if msg != 'Test Log Message\r\n':
3884 continue
3885 found = True
3886 break
3887 msg = 'Record not found in event log, went back %d records' % GO_BACK
3888 self.assertTrue(found, msg=msg)
3889
Christian Heimes180510d2008-03-03 19:15:45 +00003890# Set the locale to the platform-dependent default. I have no idea
3891# why the test does this, but in any case we save the current locale
3892# first and restore it at the end.
3893@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00003894def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +00003895 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003896 CustomLevelsAndFiltersTest, HandlerTest, MemoryHandlerTest,
Vinay Sajip7367d082011-05-02 13:17:27 +01003897 ConfigFileTest, SocketHandlerTest, DatagramHandlerTest,
3898 MemoryTest, EncodingTest, WarningsTest, ConfigDictTest,
3899 ManagerTest, FormatterTest, BufferingFormatterTest,
3900 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
3901 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest,
3902 BasicConfigTest, LoggerAdapterTest, LoggerTest,
3903 SMTPHandlerTest, FileHandlerTest, RotatingFileHandlerTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003904 LastResortTest, LogRecordTest, ExceptionTest,
Vinay Sajip60ccd822011-05-09 17:32:09 +01003905 SysLogHandlerTest, HTTPHandlerTest, NTEventLogHandlerTest,
Vinay Sajip89807a52011-02-26 16:06:02 +00003906 TimedRotatingFileHandlerTest
Vinay Sajipbc85d842010-09-17 23:35:29 +00003907 )
Jeremy Hylton096d9862003-07-18 03:19:20 +00003908
Christian Heimes180510d2008-03-03 19:15:45 +00003909if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00003910 test_main()