blob: f34172a371d1ce7380024dace061ade40bee7d71 [file] [log] [blame]
Vinay Sajip3f885b52013-03-22 15:19:54 +00001# Copyright 2001-2013 by Vinay Sajip. All Rights Reserved.
Christian Heimes180510d2008-03-03 19:15:45 +00002#
3# Permission to use, copy, modify, and distribute this software and its
4# documentation for any purpose and without fee is hereby granted,
5# provided that the above copyright notice appear in all copies and that
6# both that copyright notice and this permission notice appear in
7# supporting documentation, and that the name of Vinay Sajip
8# not be used in advertising or publicity pertaining to distribution
9# of the software without specific, written prior permission.
10# VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING
11# ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
12# VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR
13# ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER
14# IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
15# OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
16
17"""Test harness for the logging module. Run all tests.
18
Vinay Sajip3f885b52013-03-22 15:19:54 +000019Copyright (C) 2001-2013 Vinay Sajip. All Rights Reserved.
Neal Norwitzb4a2df02003-01-02 14:56:39 +000020"""
21
Christian Heimes180510d2008-03-03 19:15:45 +000022import logging
23import logging.handlers
24import logging.config
Christian Heimes18c66892008-02-17 13:31:39 +000025
Benjamin Petersonf91df042009-02-13 02:50:59 +000026import codecs
Vinay Sajip19ec67a2010-09-17 18:57:36 +000027import datetime
Christian Heimes180510d2008-03-03 19:15:45 +000028import pickle
29import io
30import gc
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000031import json
Christian Heimes180510d2008-03-03 19:15:45 +000032import os
Vinay Sajip8552d1f2010-09-14 09:34:09 +000033import queue
Vinay Sajip66b8b082012-04-24 23:25:30 +010034import random
Christian Heimes180510d2008-03-03 19:15:45 +000035import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000036import select
Christian Heimes180510d2008-03-03 19:15:45 +000037import socket
Christian Heimes180510d2008-03-03 19:15:45 +000038import struct
39import sys
40import tempfile
Eric V. Smith851cad72012-03-11 22:46:04 -070041from test.support import (captured_stdout, run_with_locale, run_unittest,
42 patch, requires_zlib, TestHandler, Matcher)
Christian Heimes180510d2008-03-03 19:15:45 +000043import textwrap
Vinay Sajip37eb3382011-04-26 20:26:41 +010044import time
Christian Heimes180510d2008-03-03 19:15:45 +000045import unittest
Georg Brandlf9734072008-12-07 15:30:06 +000046import warnings
Christian Heimes180510d2008-03-03 19:15:45 +000047import weakref
Victor Stinner45df8202010-04-28 22:31:17 +000048try:
49 import threading
Vinay Sajipce7c9782011-05-17 07:15:53 +010050 # The following imports are needed only for tests which
Florent Xicluna5252f9f2011-11-07 19:43:05 +010051 # require threading
Vinay Sajipce7c9782011-05-17 07:15:53 +010052 import asynchat
53 import asyncore
54 import errno
55 from http.server import HTTPServer, BaseHTTPRequestHandler
56 import smtpd
57 from urllib.parse import urlparse, parse_qs
58 from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
59 ThreadingTCPServer, StreamRequestHandler)
Victor Stinner45df8202010-04-28 22:31:17 +000060except ImportError:
61 threading = None
Vinay Sajip60ccd822011-05-09 17:32:09 +010062try:
63 import win32evtlog
64except ImportError:
65 win32evtlog = None
66try:
67 import win32evtlogutil
68except ImportError:
69 win32evtlogutil = None
70 win32evtlog = None
Eric V. Smith851cad72012-03-11 22:46:04 -070071try:
72 import zlib
73except ImportError:
74 pass
Christian Heimes18c66892008-02-17 13:31:39 +000075
76
Christian Heimes180510d2008-03-03 19:15:45 +000077class BaseTest(unittest.TestCase):
78
79 """Base class for logging tests."""
80
81 log_format = "%(name)s -> %(levelname)s: %(message)s"
82 expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$"
83 message_num = 0
84
85 def setUp(self):
86 """Setup the default logging stream to an internal StringIO instance,
87 so that we can examine log output as we want."""
88 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000089 logging._acquireLock()
90 try:
Christian Heimes180510d2008-03-03 19:15:45 +000091 self.saved_handlers = logging._handlers.copy()
92 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000093 self.saved_loggers = saved_loggers = logger_dict.copy()
Christian Heimes180510d2008-03-03 19:15:45 +000094 self.saved_level_names = logging._levelNames.copy()
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000095 self.logger_states = logger_states = {}
96 for name in saved_loggers:
97 logger_states[name] = getattr(saved_loggers[name],
98 'disabled', None)
Christian Heimes18c66892008-02-17 13:31:39 +000099 finally:
100 logging._releaseLock()
101
Florent Xicluna5252f9f2011-11-07 19:43:05 +0100102 # Set two unused loggers
Vinay Sajipb4a08092010-09-20 09:55:00 +0000103 self.logger1 = logging.getLogger("\xab\xd7\xbb")
104 self.logger2 = logging.getLogger("\u013f\u00d6\u0047")
Benjamin Peterson22005fc2010-04-11 16:25:06 +0000105
Christian Heimes180510d2008-03-03 19:15:45 +0000106 self.root_logger = logging.getLogger("")
107 self.original_logging_level = self.root_logger.getEffectiveLevel()
108
109 self.stream = io.StringIO()
110 self.root_logger.setLevel(logging.DEBUG)
111 self.root_hdlr = logging.StreamHandler(self.stream)
112 self.root_formatter = logging.Formatter(self.log_format)
113 self.root_hdlr.setFormatter(self.root_formatter)
Vinay Sajip7b0e86e2010-12-30 23:26:50 +0000114 if self.logger1.hasHandlers():
115 hlist = self.logger1.handlers + self.root_logger.handlers
116 raise AssertionError('Unexpected handlers: %s' % hlist)
117 if self.logger2.hasHandlers():
118 hlist = self.logger2.handlers + self.root_logger.handlers
119 raise AssertionError('Unexpected handlers: %s' % hlist)
Christian Heimes180510d2008-03-03 19:15:45 +0000120 self.root_logger.addHandler(self.root_hdlr)
Vinay Sajipb4a08092010-09-20 09:55:00 +0000121 self.assertTrue(self.logger1.hasHandlers())
122 self.assertTrue(self.logger2.hasHandlers())
Christian Heimes180510d2008-03-03 19:15:45 +0000123
124 def tearDown(self):
125 """Remove our logging stream, and restore the original logging
126 level."""
127 self.stream.close()
128 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000129 while self.root_logger.handlers:
130 h = self.root_logger.handlers[0]
131 self.root_logger.removeHandler(h)
132 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +0000133 self.root_logger.setLevel(self.original_logging_level)
134 logging._acquireLock()
135 try:
136 logging._levelNames.clear()
137 logging._levelNames.update(self.saved_level_names)
138 logging._handlers.clear()
139 logging._handlers.update(self.saved_handlers)
140 logging._handlerList[:] = self.saved_handler_list
141 loggerDict = logging.getLogger().manager.loggerDict
142 loggerDict.clear()
143 loggerDict.update(self.saved_loggers)
Vinay Sajip7b60f4e2010-12-27 14:31:52 +0000144 logger_states = self.logger_states
145 for name in self.logger_states:
146 if logger_states[name] is not None:
147 self.saved_loggers[name].disabled = logger_states[name]
Christian Heimes180510d2008-03-03 19:15:45 +0000148 finally:
149 logging._releaseLock()
150
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000151 def assert_log_lines(self, expected_values, stream=None):
Christian Heimes180510d2008-03-03 19:15:45 +0000152 """Match the collected log lines against the regular expression
153 self.expected_log_pat, and compare the extracted group values to
154 the expected_values list of tuples."""
155 stream = stream or self.stream
156 pat = re.compile(self.expected_log_pat)
Serhiy Storchaka50254c52013-08-29 11:35:43 +0300157 actual_lines = stream.getvalue().splitlines()
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100158 self.assertEqual(len(actual_lines), len(expected_values))
Christian Heimes180510d2008-03-03 19:15:45 +0000159 for actual, expected in zip(actual_lines, expected_values):
160 match = pat.search(actual)
161 if not match:
162 self.fail("Log line does not match expected pattern:\n" +
163 actual)
Ezio Melottib3aedd42010-11-20 19:04:17 +0000164 self.assertEqual(tuple(match.groups()), expected)
Christian Heimes180510d2008-03-03 19:15:45 +0000165 s = stream.read()
166 if s:
167 self.fail("Remaining output at end of log stream:\n" + s)
168
169 def next_message(self):
170 """Generate a message consisting solely of an auto-incrementing
171 integer."""
172 self.message_num += 1
173 return "%d" % self.message_num
174
175
176class BuiltinLevelsTest(BaseTest):
177 """Test builtin levels and their inheritance."""
178
179 def test_flat(self):
180 #Logging levels in a flat logger namespace.
181 m = self.next_message
182
183 ERR = logging.getLogger("ERR")
184 ERR.setLevel(logging.ERROR)
Vinay Sajipc84f0162010-09-21 11:25:39 +0000185 INF = logging.LoggerAdapter(logging.getLogger("INF"), {})
Christian Heimes180510d2008-03-03 19:15:45 +0000186 INF.setLevel(logging.INFO)
187 DEB = logging.getLogger("DEB")
188 DEB.setLevel(logging.DEBUG)
189
190 # These should log.
191 ERR.log(logging.CRITICAL, m())
192 ERR.error(m())
193
194 INF.log(logging.CRITICAL, m())
195 INF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100196 INF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000197 INF.info(m())
198
199 DEB.log(logging.CRITICAL, m())
200 DEB.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100201 DEB.warning(m())
202 DEB.info(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000203 DEB.debug(m())
204
205 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100206 ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000207 ERR.info(m())
208 ERR.debug(m())
209
210 INF.debug(m())
211
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000212 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000213 ('ERR', 'CRITICAL', '1'),
214 ('ERR', 'ERROR', '2'),
215 ('INF', 'CRITICAL', '3'),
216 ('INF', 'ERROR', '4'),
217 ('INF', 'WARNING', '5'),
218 ('INF', 'INFO', '6'),
219 ('DEB', 'CRITICAL', '7'),
220 ('DEB', 'ERROR', '8'),
221 ('DEB', 'WARNING', '9'),
222 ('DEB', 'INFO', '10'),
223 ('DEB', 'DEBUG', '11'),
224 ])
225
226 def test_nested_explicit(self):
227 # Logging levels in a nested namespace, all explicitly set.
228 m = self.next_message
229
230 INF = logging.getLogger("INF")
231 INF.setLevel(logging.INFO)
232 INF_ERR = logging.getLogger("INF.ERR")
233 INF_ERR.setLevel(logging.ERROR)
234
235 # These should log.
236 INF_ERR.log(logging.CRITICAL, m())
237 INF_ERR.error(m())
238
239 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100240 INF_ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000241 INF_ERR.info(m())
242 INF_ERR.debug(m())
243
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000244 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000245 ('INF.ERR', 'CRITICAL', '1'),
246 ('INF.ERR', 'ERROR', '2'),
247 ])
248
249 def test_nested_inherited(self):
250 #Logging levels in a nested namespace, inherited from parent loggers.
251 m = self.next_message
252
253 INF = logging.getLogger("INF")
254 INF.setLevel(logging.INFO)
255 INF_ERR = logging.getLogger("INF.ERR")
256 INF_ERR.setLevel(logging.ERROR)
257 INF_UNDEF = logging.getLogger("INF.UNDEF")
258 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
259 UNDEF = logging.getLogger("UNDEF")
260
261 # These should log.
262 INF_UNDEF.log(logging.CRITICAL, m())
263 INF_UNDEF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100264 INF_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000265 INF_UNDEF.info(m())
266 INF_ERR_UNDEF.log(logging.CRITICAL, m())
267 INF_ERR_UNDEF.error(m())
268
269 # These should not log.
270 INF_UNDEF.debug(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100271 INF_ERR_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000272 INF_ERR_UNDEF.info(m())
273 INF_ERR_UNDEF.debug(m())
274
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000275 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000276 ('INF.UNDEF', 'CRITICAL', '1'),
277 ('INF.UNDEF', 'ERROR', '2'),
278 ('INF.UNDEF', 'WARNING', '3'),
279 ('INF.UNDEF', 'INFO', '4'),
280 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
281 ('INF.ERR.UNDEF', 'ERROR', '6'),
282 ])
283
284 def test_nested_with_virtual_parent(self):
285 # Logging levels when some parent does not exist yet.
286 m = self.next_message
287
288 INF = logging.getLogger("INF")
289 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
290 CHILD = logging.getLogger("INF.BADPARENT")
291 INF.setLevel(logging.INFO)
292
293 # These should log.
294 GRANDCHILD.log(logging.FATAL, m())
295 GRANDCHILD.info(m())
296 CHILD.log(logging.FATAL, m())
297 CHILD.info(m())
298
299 # These should not log.
300 GRANDCHILD.debug(m())
301 CHILD.debug(m())
302
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000303 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000304 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
305 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
306 ('INF.BADPARENT', 'CRITICAL', '3'),
307 ('INF.BADPARENT', 'INFO', '4'),
308 ])
309
310
311class BasicFilterTest(BaseTest):
312
313 """Test the bundled Filter class."""
314
315 def test_filter(self):
316 # Only messages satisfying the specified criteria pass through the
317 # filter.
318 filter_ = logging.Filter("spam.eggs")
319 handler = self.root_logger.handlers[0]
320 try:
321 handler.addFilter(filter_)
322 spam = logging.getLogger("spam")
323 spam_eggs = logging.getLogger("spam.eggs")
324 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
325 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
326
327 spam.info(self.next_message())
328 spam_eggs.info(self.next_message()) # Good.
329 spam_eggs_fish.info(self.next_message()) # Good.
330 spam_bakedbeans.info(self.next_message())
331
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000332 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000333 ('spam.eggs', 'INFO', '2'),
334 ('spam.eggs.fish', 'INFO', '3'),
335 ])
336 finally:
337 handler.removeFilter(filter_)
338
Vinay Sajip6dbed2e2010-10-19 20:53:01 +0000339 def test_callable_filter(self):
340 # Only messages satisfying the specified criteria pass through the
341 # filter.
342
343 def filterfunc(record):
344 parts = record.name.split('.')
345 prefix = '.'.join(parts[:2])
346 return prefix == 'spam.eggs'
347
348 handler = self.root_logger.handlers[0]
349 try:
350 handler.addFilter(filterfunc)
351 spam = logging.getLogger("spam")
352 spam_eggs = logging.getLogger("spam.eggs")
353 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
354 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
355
356 spam.info(self.next_message())
357 spam_eggs.info(self.next_message()) # Good.
358 spam_eggs_fish.info(self.next_message()) # Good.
359 spam_bakedbeans.info(self.next_message())
360
361 self.assert_log_lines([
362 ('spam.eggs', 'INFO', '2'),
363 ('spam.eggs.fish', 'INFO', '3'),
364 ])
365 finally:
366 handler.removeFilter(filterfunc)
367
Vinay Sajip985ef872011-04-26 19:34:04 +0100368 def test_empty_filter(self):
369 f = logging.Filter()
370 r = logging.makeLogRecord({'name': 'spam.eggs'})
371 self.assertTrue(f.filter(r))
Christian Heimes180510d2008-03-03 19:15:45 +0000372
373#
374# First, we define our levels. There can be as many as you want - the only
375# limitations are that they should be integers, the lowest should be > 0 and
376# larger values mean less information being logged. If you need specific
377# level values which do not fit into these limitations, you can use a
378# mapping dictionary to convert between your application levels and the
379# logging system.
380#
381SILENT = 120
382TACITURN = 119
383TERSE = 118
384EFFUSIVE = 117
385SOCIABLE = 116
386VERBOSE = 115
387TALKATIVE = 114
388GARRULOUS = 113
389CHATTERBOX = 112
390BORING = 111
391
392LEVEL_RANGE = range(BORING, SILENT + 1)
393
394#
395# Next, we define names for our levels. You don't need to do this - in which
396# case the system will use "Level n" to denote the text for the level.
397#
398my_logging_levels = {
399 SILENT : 'Silent',
400 TACITURN : 'Taciturn',
401 TERSE : 'Terse',
402 EFFUSIVE : 'Effusive',
403 SOCIABLE : 'Sociable',
404 VERBOSE : 'Verbose',
405 TALKATIVE : 'Talkative',
406 GARRULOUS : 'Garrulous',
407 CHATTERBOX : 'Chatterbox',
408 BORING : 'Boring',
409}
410
411class GarrulousFilter(logging.Filter):
412
413 """A filter which blocks garrulous messages."""
414
415 def filter(self, record):
416 return record.levelno != GARRULOUS
417
418class VerySpecificFilter(logging.Filter):
419
420 """A filter which blocks sociable and taciturn messages."""
421
422 def filter(self, record):
423 return record.levelno not in [SOCIABLE, TACITURN]
424
425
426class CustomLevelsAndFiltersTest(BaseTest):
427
428 """Test various filtering possibilities with custom logging levels."""
429
430 # Skip the logger name group.
431 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
432
433 def setUp(self):
434 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000435 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000436 logging.addLevelName(k, v)
437
438 def log_at_all_levels(self, logger):
439 for lvl in LEVEL_RANGE:
440 logger.log(lvl, self.next_message())
441
442 def test_logger_filter(self):
443 # Filter at logger level.
444 self.root_logger.setLevel(VERBOSE)
445 # Levels >= 'Verbose' are good.
446 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000447 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000448 ('Verbose', '5'),
449 ('Sociable', '6'),
450 ('Effusive', '7'),
451 ('Terse', '8'),
452 ('Taciturn', '9'),
453 ('Silent', '10'),
454 ])
455
456 def test_handler_filter(self):
457 # Filter at handler level.
458 self.root_logger.handlers[0].setLevel(SOCIABLE)
459 try:
460 # Levels >= 'Sociable' are good.
461 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000462 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000463 ('Sociable', '6'),
464 ('Effusive', '7'),
465 ('Terse', '8'),
466 ('Taciturn', '9'),
467 ('Silent', '10'),
468 ])
469 finally:
470 self.root_logger.handlers[0].setLevel(logging.NOTSET)
471
472 def test_specific_filters(self):
473 # Set a specific filter object on the handler, and then add another
474 # filter object on the logger itself.
475 handler = self.root_logger.handlers[0]
476 specific_filter = None
477 garr = GarrulousFilter()
478 handler.addFilter(garr)
479 try:
480 self.log_at_all_levels(self.root_logger)
481 first_lines = [
482 # Notice how 'Garrulous' is missing
483 ('Boring', '1'),
484 ('Chatterbox', '2'),
485 ('Talkative', '4'),
486 ('Verbose', '5'),
487 ('Sociable', '6'),
488 ('Effusive', '7'),
489 ('Terse', '8'),
490 ('Taciturn', '9'),
491 ('Silent', '10'),
492 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000493 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000494
495 specific_filter = VerySpecificFilter()
496 self.root_logger.addFilter(specific_filter)
497 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000498 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000499 # Not only 'Garrulous' is still missing, but also 'Sociable'
500 # and 'Taciturn'
501 ('Boring', '11'),
502 ('Chatterbox', '12'),
503 ('Talkative', '14'),
504 ('Verbose', '15'),
505 ('Effusive', '17'),
506 ('Terse', '18'),
507 ('Silent', '20'),
508 ])
509 finally:
510 if specific_filter:
511 self.root_logger.removeFilter(specific_filter)
512 handler.removeFilter(garr)
513
514
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100515class HandlerTest(BaseTest):
516 def test_name(self):
517 h = logging.Handler()
518 h.name = 'generic'
519 self.assertEqual(h.name, 'generic')
520 h.name = 'anothergeneric'
521 self.assertEqual(h.name, 'anothergeneric')
522 self.assertRaises(NotImplementedError, h.emit, None)
523
Vinay Sajip5a35b062011-04-27 11:31:14 +0100524 def test_builtin_handlers(self):
525 # We can't actually *use* too many handlers in the tests,
526 # but we can try instantiating them with various options
Victor Stinnere6747472011-08-21 00:39:18 +0200527 if sys.platform in ('linux', 'darwin'):
Vinay Sajip5a35b062011-04-27 11:31:14 +0100528 for existing in (True, False):
529 fd, fn = tempfile.mkstemp()
530 os.close(fd)
531 if not existing:
532 os.unlink(fn)
533 h = logging.handlers.WatchedFileHandler(fn, delay=True)
534 if existing:
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100535 dev, ino = h.dev, h.ino
Vinay Sajipa5798de2012-04-24 23:33:33 +0100536 self.assertEqual(dev, -1)
537 self.assertEqual(ino, -1)
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100538 r = logging.makeLogRecord({'msg': 'Test'})
539 h.handle(r)
540 # Now remove the file.
541 os.unlink(fn)
542 self.assertFalse(os.path.exists(fn))
543 # The next call should recreate the file.
544 h.handle(r)
545 self.assertTrue(os.path.exists(fn))
Vinay Sajip5a35b062011-04-27 11:31:14 +0100546 else:
547 self.assertEqual(h.dev, -1)
548 self.assertEqual(h.ino, -1)
549 h.close()
550 if existing:
551 os.unlink(fn)
552 if sys.platform == 'darwin':
Vinay Sajip6bba65c2011-04-27 14:31:55 +0100553 sockname = '/var/run/syslog'
Vinay Sajip5a35b062011-04-27 11:31:14 +0100554 else:
555 sockname = '/dev/log'
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100556 try:
557 h = logging.handlers.SysLogHandler(sockname)
558 self.assertEqual(h.facility, h.LOG_USER)
559 self.assertTrue(h.unixsocket)
560 h.close()
561 except socket.error: # syslogd might not be available
562 pass
Vinay Sajip5a35b062011-04-27 11:31:14 +0100563 for method in ('GET', 'POST', 'PUT'):
564 if method == 'PUT':
565 self.assertRaises(ValueError, logging.handlers.HTTPHandler,
566 'localhost', '/log', method)
567 else:
568 h = logging.handlers.HTTPHandler('localhost', '/log', method)
569 h.close()
570 h = logging.handlers.BufferingHandler(0)
571 r = logging.makeLogRecord({})
572 self.assertTrue(h.shouldFlush(r))
573 h.close()
574 h = logging.handlers.BufferingHandler(1)
575 self.assertFalse(h.shouldFlush(r))
576 h.close()
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100577
Vinay Sajip5e86eed2012-05-29 22:48:10 +0100578 @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.')
Vinay Sajipa5798de2012-04-24 23:33:33 +0100579 @unittest.skipUnless(threading, 'Threading required for this test.')
580 def test_race(self):
581 # Issue #14632 refers.
582 def remove_loop(fname, tries):
583 for _ in range(tries):
584 try:
585 os.unlink(fname)
586 except OSError:
587 pass
588 time.sleep(0.004 * random.randint(0, 4))
589
Vinay Sajipc94871a2012-04-25 10:51:35 +0100590 del_count = 500
591 log_count = 500
Vinay Sajipa5798de2012-04-24 23:33:33 +0100592
Vinay Sajipa5798de2012-04-24 23:33:33 +0100593 for delay in (False, True):
Vinay Sajipc94871a2012-04-25 10:51:35 +0100594 fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
595 os.close(fd)
596 remover = threading.Thread(target=remove_loop, args=(fn, del_count))
597 remover.daemon = True
598 remover.start()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100599 h = logging.handlers.WatchedFileHandler(fn, delay=delay)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100600 f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
601 h.setFormatter(f)
Vinay Sajipc94871a2012-04-25 10:51:35 +0100602 try:
603 for _ in range(log_count):
604 time.sleep(0.005)
605 r = logging.makeLogRecord({'msg': 'testing' })
606 h.handle(r)
607 finally:
Vinay Sajipc94871a2012-04-25 10:51:35 +0100608 remover.join()
Vinay Sajipac20f462012-05-03 12:09:38 +0100609 h.close()
Vinay Sajipc94871a2012-04-25 10:51:35 +0100610 if os.path.exists(fn):
611 os.unlink(fn)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100612
613
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100614class BadStream(object):
615 def write(self, data):
616 raise RuntimeError('deliberate mistake')
617
618class TestStreamHandler(logging.StreamHandler):
619 def handleError(self, record):
620 self.error_record = record
621
622class StreamHandlerTest(BaseTest):
623 def test_error_handling(self):
624 h = TestStreamHandler(BadStream())
625 r = logging.makeLogRecord({})
626 old_raise = logging.raiseExceptions
Vinay Sajip985ef872011-04-26 19:34:04 +0100627 old_stderr = sys.stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100628 try:
629 h.handle(r)
630 self.assertIs(h.error_record, r)
Vinay Sajip985ef872011-04-26 19:34:04 +0100631 h = logging.StreamHandler(BadStream())
632 sys.stderr = sio = io.StringIO()
633 h.handle(r)
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100634 self.assertIn('\nRuntimeError: deliberate mistake\n',
635 sio.getvalue())
Vinay Sajip985ef872011-04-26 19:34:04 +0100636 logging.raiseExceptions = False
637 sys.stderr = sio = io.StringIO()
638 h.handle(r)
639 self.assertEqual('', sio.getvalue())
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100640 finally:
641 logging.raiseExceptions = old_raise
Vinay Sajip985ef872011-04-26 19:34:04 +0100642 sys.stderr = old_stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100643
Vinay Sajip7367d082011-05-02 13:17:27 +0100644# -- The following section could be moved into a server_helper.py module
645# -- if it proves to be of wider utility than just test_logging
Vinay Sajipa463d252011-04-30 21:52:48 +0100646
Vinay Sajipce7c9782011-05-17 07:15:53 +0100647if threading:
648 class TestSMTPChannel(smtpd.SMTPChannel):
Vinay Sajip314b92b2011-05-02 14:31:16 +0100649 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100650 This derived class has had to be created because smtpd does not
651 support use of custom channel maps, although they are allowed by
652 asyncore's design. Issue #11959 has been raised to address this,
653 and if resolved satisfactorily, some of this code can be removed.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100654 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100655 def __init__(self, server, conn, addr, sockmap):
656 asynchat.async_chat.__init__(self, conn, sockmap)
657 self.smtp_server = server
658 self.conn = conn
659 self.addr = addr
R David Murrayd1a30c92012-05-26 14:33:59 -0400660 self.data_size_limit = None
Vinay Sajipce7c9782011-05-17 07:15:53 +0100661 self.received_lines = []
662 self.smtp_state = self.COMMAND
663 self.seen_greeting = ''
664 self.mailfrom = None
665 self.rcpttos = []
666 self.received_data = ''
667 self.fqdn = socket.getfqdn()
668 self.num_bytes = 0
669 try:
670 self.peer = conn.getpeername()
671 except socket.error as err:
672 # a race condition may occur if the other end is closing
673 # before we can get the peername
674 self.close()
675 if err.args[0] != errno.ENOTCONN:
676 raise
677 return
678 self.push('220 %s %s' % (self.fqdn, smtpd.__version__))
679 self.set_terminator(b'\r\n')
R David Murrayd1a30c92012-05-26 14:33:59 -0400680 self.extended_smtp = False
Vinay Sajipa463d252011-04-30 21:52:48 +0100681
Vinay Sajip314b92b2011-05-02 14:31:16 +0100682
Vinay Sajipce7c9782011-05-17 07:15:53 +0100683 class TestSMTPServer(smtpd.SMTPServer):
Vinay Sajip314b92b2011-05-02 14:31:16 +0100684 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100685 This class implements a test SMTP server.
Vinay Sajipa463d252011-04-30 21:52:48 +0100686
Vinay Sajipce7c9782011-05-17 07:15:53 +0100687 :param addr: A (host, port) tuple which the server listens on.
688 You can specify a port value of zero: the server's
689 *port* attribute will hold the actual port number
690 used, which can be used in client connections.
691 :param handler: A callable which will be called to process
692 incoming messages. The handler will be passed
693 the client address tuple, who the message is from,
694 a list of recipients and the message data.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100695 :param poll_interval: The interval, in seconds, used in the underlying
696 :func:`select` or :func:`poll` call by
697 :func:`asyncore.loop`.
Vinay Sajipce7c9782011-05-17 07:15:53 +0100698 :param sockmap: A dictionary which will be used to hold
699 :class:`asyncore.dispatcher` instances used by
700 :func:`asyncore.loop`. This avoids changing the
701 :mod:`asyncore` module's global state.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100702 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100703 channel_class = TestSMTPChannel
704
705 def __init__(self, addr, handler, poll_interval, sockmap):
706 self._localaddr = addr
707 self._remoteaddr = None
R David Murrayd1a30c92012-05-26 14:33:59 -0400708 self.data_size_limit = None
Vinay Sajipce7c9782011-05-17 07:15:53 +0100709 self.sockmap = sockmap
710 asyncore.dispatcher.__init__(self, map=sockmap)
711 try:
712 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
713 sock.setblocking(0)
714 self.set_socket(sock, map=sockmap)
715 # try to re-use a server port if possible
716 self.set_reuse_addr()
717 self.bind(addr)
718 self.port = sock.getsockname()[1]
719 self.listen(5)
720 except:
721 self.close()
Vinay Sajipe73afad2011-05-10 07:48:28 +0100722 raise
Vinay Sajipce7c9782011-05-17 07:15:53 +0100723 self._handler = handler
724 self._thread = None
725 self.poll_interval = poll_interval
Vinay Sajipa463d252011-04-30 21:52:48 +0100726
Vinay Sajipce7c9782011-05-17 07:15:53 +0100727 def handle_accepted(self, conn, addr):
728 """
729 Redefined only because the base class does not pass in a
730 map, forcing use of a global in :mod:`asyncore`.
731 """
732 channel = self.channel_class(self, conn, addr, self.sockmap)
Vinay Sajip314b92b2011-05-02 14:31:16 +0100733
Vinay Sajipce7c9782011-05-17 07:15:53 +0100734 def process_message(self, peer, mailfrom, rcpttos, data):
735 """
736 Delegates to the handler passed in to the server's constructor.
Vinay Sajipa463d252011-04-30 21:52:48 +0100737
Vinay Sajipce7c9782011-05-17 07:15:53 +0100738 Typically, this will be a test case method.
739 :param peer: The client (host, port) tuple.
740 :param mailfrom: The address of the sender.
741 :param rcpttos: The addresses of the recipients.
742 :param data: The message.
743 """
744 self._handler(peer, mailfrom, rcpttos, data)
Vinay Sajip7367d082011-05-02 13:17:27 +0100745
Vinay Sajipce7c9782011-05-17 07:15:53 +0100746 def start(self):
747 """
748 Start the server running on a separate daemon thread.
749 """
750 self._thread = t = threading.Thread(target=self.serve_forever,
751 args=(self.poll_interval,))
752 t.setDaemon(True)
753 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100754
Vinay Sajipce7c9782011-05-17 07:15:53 +0100755 def serve_forever(self, poll_interval):
756 """
757 Run the :mod:`asyncore` loop until normal termination
758 conditions arise.
759 :param poll_interval: The interval, in seconds, used in the underlying
760 :func:`select` or :func:`poll` call by
761 :func:`asyncore.loop`.
762 """
763 try:
764 asyncore.loop(poll_interval, map=self.sockmap)
765 except select.error:
766 # On FreeBSD 8, closing the server repeatably
767 # raises this error. We swallow it if the
768 # server has been closed.
769 if self.connected or self.accepting:
770 raise
Vinay Sajip7367d082011-05-02 13:17:27 +0100771
Vinay Sajipce7c9782011-05-17 07:15:53 +0100772 def stop(self, timeout=None):
773 """
774 Stop the thread by closing the server instance.
775 Wait for the server thread to terminate.
Vinay Sajip7367d082011-05-02 13:17:27 +0100776
Vinay Sajipce7c9782011-05-17 07:15:53 +0100777 :param timeout: How long to wait for the server thread
778 to terminate.
779 """
780 self.close()
Vinay Sajip7367d082011-05-02 13:17:27 +0100781 self._thread.join(timeout)
782 self._thread = None
Vinay Sajip7367d082011-05-02 13:17:27 +0100783
Vinay Sajipce7c9782011-05-17 07:15:53 +0100784 class ControlMixin(object):
785 """
786 This mixin is used to start a server on a separate thread, and
787 shut it down programmatically. Request handling is simplified - instead
788 of needing to derive a suitable RequestHandler subclass, you just
789 provide a callable which will be passed each received request to be
790 processed.
Vinay Sajip7367d082011-05-02 13:17:27 +0100791
Vinay Sajipce7c9782011-05-17 07:15:53 +0100792 :param handler: A handler callable which will be called with a
793 single parameter - the request - in order to
794 process the request. This handler is called on the
795 server thread, effectively meaning that requests are
796 processed serially. While not quite Web scale ;-),
797 this should be fine for testing applications.
798 :param poll_interval: The polling interval in seconds.
799 """
800 def __init__(self, handler, poll_interval):
801 self._thread = None
802 self.poll_interval = poll_interval
803 self._handler = handler
804 self.ready = threading.Event()
Vinay Sajip7367d082011-05-02 13:17:27 +0100805
Vinay Sajipce7c9782011-05-17 07:15:53 +0100806 def start(self):
807 """
808 Create a daemon thread to run the server, and start it.
809 """
810 self._thread = t = threading.Thread(target=self.serve_forever,
811 args=(self.poll_interval,))
812 t.setDaemon(True)
813 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100814
Vinay Sajipce7c9782011-05-17 07:15:53 +0100815 def serve_forever(self, poll_interval):
816 """
817 Run the server. Set the ready flag before entering the
818 service loop.
819 """
820 self.ready.set()
821 super(ControlMixin, self).serve_forever(poll_interval)
Vinay Sajip7367d082011-05-02 13:17:27 +0100822
Vinay Sajipce7c9782011-05-17 07:15:53 +0100823 def stop(self, timeout=None):
824 """
825 Tell the server thread to stop, and wait for it to do so.
Vinay Sajip7367d082011-05-02 13:17:27 +0100826
Vinay Sajipce7c9782011-05-17 07:15:53 +0100827 :param timeout: How long to wait for the server thread
828 to terminate.
829 """
830 self.shutdown()
831 if self._thread is not None:
832 self._thread.join(timeout)
833 self._thread = None
834 self.server_close()
835 self.ready.clear()
Vinay Sajip7367d082011-05-02 13:17:27 +0100836
Vinay Sajipce7c9782011-05-17 07:15:53 +0100837 class TestHTTPServer(ControlMixin, HTTPServer):
838 """
839 An HTTP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100840
Vinay Sajipce7c9782011-05-17 07:15:53 +0100841 :param addr: A tuple with the IP address and port to listen on.
842 :param handler: A handler callable which will be called with a
843 single parameter - the request - in order to
844 process the request.
845 :param poll_interval: The polling interval in seconds.
846 :param log: Pass ``True`` to enable log messages.
847 """
Vinay Sajip32565b62011-05-21 00:34:51 +0100848 def __init__(self, addr, handler, poll_interval=0.5,
849 log=False, sslctx=None):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100850 class DelegatingHTTPRequestHandler(BaseHTTPRequestHandler):
851 def __getattr__(self, name, default=None):
852 if name.startswith('do_'):
853 return self.process_request
854 raise AttributeError(name)
Vinay Sajip7367d082011-05-02 13:17:27 +0100855
Vinay Sajipce7c9782011-05-17 07:15:53 +0100856 def process_request(self):
857 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +0100858
Vinay Sajipce7c9782011-05-17 07:15:53 +0100859 def log_message(self, format, *args):
860 if log:
861 super(DelegatingHTTPRequestHandler,
862 self).log_message(format, *args)
863 HTTPServer.__init__(self, addr, DelegatingHTTPRequestHandler)
864 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajip32565b62011-05-21 00:34:51 +0100865 self.sslctx = sslctx
866
867 def get_request(self):
868 try:
869 sock, addr = self.socket.accept()
870 if self.sslctx:
871 sock = self.sslctx.wrap_socket(sock, server_side=True)
872 except socket.error as e:
873 # socket errors are silenced by the caller, print them here
874 sys.stderr.write("Got an error:\n%s\n" % e)
875 raise
876 return sock, addr
Vinay Sajip7367d082011-05-02 13:17:27 +0100877
Vinay Sajipce7c9782011-05-17 07:15:53 +0100878 class TestTCPServer(ControlMixin, ThreadingTCPServer):
879 """
880 A TCP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100881
Vinay Sajipce7c9782011-05-17 07:15:53 +0100882 :param addr: A tuple with the IP address and port to listen on.
883 :param handler: A handler callable which will be called with a single
884 parameter - the request - in order to process the request.
885 :param poll_interval: The polling interval in seconds.
886 :bind_and_activate: If True (the default), binds the server and starts it
887 listening. If False, you need to call
888 :meth:`server_bind` and :meth:`server_activate` at
889 some later time before calling :meth:`start`, so that
890 the server will set up the socket and listen on it.
891 """
Vinay Sajip7367d082011-05-02 13:17:27 +0100892
Vinay Sajipce7c9782011-05-17 07:15:53 +0100893 allow_reuse_address = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100894
Vinay Sajipce7c9782011-05-17 07:15:53 +0100895 def __init__(self, addr, handler, poll_interval=0.5,
896 bind_and_activate=True):
897 class DelegatingTCPRequestHandler(StreamRequestHandler):
898
899 def handle(self):
900 self.server._handler(self)
901 ThreadingTCPServer.__init__(self, addr, DelegatingTCPRequestHandler,
902 bind_and_activate)
903 ControlMixin.__init__(self, handler, poll_interval)
904
905 def server_bind(self):
906 super(TestTCPServer, self).server_bind()
907 self.port = self.socket.getsockname()[1]
908
909 class TestUDPServer(ControlMixin, ThreadingUDPServer):
910 """
911 A UDP server which is controllable using :class:`ControlMixin`.
912
913 :param addr: A tuple with the IP address and port to listen on.
914 :param handler: A handler callable which will be called with a
915 single parameter - the request - in order to
916 process the request.
917 :param poll_interval: The polling interval for shutdown requests,
918 in seconds.
919 :bind_and_activate: If True (the default), binds the server and
920 starts it listening. If False, you need to
921 call :meth:`server_bind` and
922 :meth:`server_activate` at some later time
923 before calling :meth:`start`, so that the server will
924 set up the socket and listen on it.
925 """
Vinay Sajip3ef12292011-05-23 23:00:42 +0100926 def __init__(self, addr, handler, poll_interval=0.5,
927 bind_and_activate=True):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100928 class DelegatingUDPRequestHandler(DatagramRequestHandler):
929
930 def handle(self):
931 self.server._handler(self)
Vinay Sajipba980db2011-05-23 21:37:54 +0100932
933 def finish(self):
934 data = self.wfile.getvalue()
Vinay Sajip3ef12292011-05-23 23:00:42 +0100935 if data:
936 try:
937 super(DelegatingUDPRequestHandler, self).finish()
938 except socket.error:
939 if not self.server._closed:
940 raise
Vinay Sajipba980db2011-05-23 21:37:54 +0100941
Vinay Sajip3ef12292011-05-23 23:00:42 +0100942 ThreadingUDPServer.__init__(self, addr,
943 DelegatingUDPRequestHandler,
Vinay Sajipce7c9782011-05-17 07:15:53 +0100944 bind_and_activate)
945 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajipba980db2011-05-23 21:37:54 +0100946 self._closed = False
Vinay Sajipce7c9782011-05-17 07:15:53 +0100947
948 def server_bind(self):
949 super(TestUDPServer, self).server_bind()
950 self.port = self.socket.getsockname()[1]
Vinay Sajip7367d082011-05-02 13:17:27 +0100951
Vinay Sajipba980db2011-05-23 21:37:54 +0100952 def server_close(self):
953 super(TestUDPServer, self).server_close()
954 self._closed = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100955
956# - end of server_helper section
Vinay Sajipa463d252011-04-30 21:52:48 +0100957
Vinay Sajipce7c9782011-05-17 07:15:53 +0100958@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipa463d252011-04-30 21:52:48 +0100959class SMTPHandlerTest(BaseTest):
Vinay Sajip827f5d32013-12-03 11:28:55 +0000960 TIMEOUT = 8.0
Vinay Sajipa463d252011-04-30 21:52:48 +0100961 def test_basic(self):
Vinay Sajip7367d082011-05-02 13:17:27 +0100962 sockmap = {}
963 server = TestSMTPServer(('localhost', 0), self.process_message, 0.001,
964 sockmap)
965 server.start()
966 addr = ('localhost', server.port)
Vinay Sajip827f5d32013-12-03 11:28:55 +0000967 h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log',
968 timeout=self.TIMEOUT)
Vinay Sajipa463d252011-04-30 21:52:48 +0100969 self.assertEqual(h.toaddrs, ['you'])
970 self.messages = []
Vinay Sajipa463d252011-04-30 21:52:48 +0100971 r = logging.makeLogRecord({'msg': 'Hello'})
Vinay Sajip7367d082011-05-02 13:17:27 +0100972 self.handled = threading.Event()
Vinay Sajipa463d252011-04-30 21:52:48 +0100973 h.handle(r)
Vinay Sajip827f5d32013-12-03 11:28:55 +0000974 self.handled.wait(self.TIMEOUT) # 14314: don't wait forever
Vinay Sajipa463d252011-04-30 21:52:48 +0100975 server.stop()
Vinay Sajip17160fd2012-03-15 12:02:08 +0000976 self.assertTrue(self.handled.is_set())
Vinay Sajipa463d252011-04-30 21:52:48 +0100977 self.assertEqual(len(self.messages), 1)
978 peer, mailfrom, rcpttos, data = self.messages[0]
979 self.assertEqual(mailfrom, 'me')
980 self.assertEqual(rcpttos, ['you'])
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100981 self.assertIn('\nSubject: Log\n', data)
Vinay Sajipa463d252011-04-30 21:52:48 +0100982 self.assertTrue(data.endswith('\n\nHello'))
983 h.close()
984
985 def process_message(self, *args):
986 self.messages.append(args)
Vinay Sajip7367d082011-05-02 13:17:27 +0100987 self.handled.set()
Vinay Sajipa463d252011-04-30 21:52:48 +0100988
Christian Heimes180510d2008-03-03 19:15:45 +0000989class MemoryHandlerTest(BaseTest):
990
991 """Tests for the MemoryHandler."""
992
993 # Do not bother with a logger name group.
994 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
995
996 def setUp(self):
997 BaseTest.setUp(self)
998 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
999 self.root_hdlr)
1000 self.mem_logger = logging.getLogger('mem')
1001 self.mem_logger.propagate = 0
1002 self.mem_logger.addHandler(self.mem_hdlr)
1003
1004 def tearDown(self):
1005 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +00001006 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +00001007
1008 def test_flush(self):
1009 # The memory handler flushes to its target handler based on specific
1010 # criteria (message count and message level).
1011 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001012 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001013 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001014 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001015 # This will flush because the level is >= logging.WARNING
Vinay Sajipb9e46e92011-10-26 13:17:20 +01001016 self.mem_logger.warning(self.next_message())
Christian Heimes180510d2008-03-03 19:15:45 +00001017 lines = [
1018 ('DEBUG', '1'),
1019 ('INFO', '2'),
1020 ('WARNING', '3'),
1021 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001022 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001023 for n in (4, 14):
1024 for i in range(9):
1025 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001026 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001027 # This will flush because it's the 10th message since the last
1028 # flush.
1029 self.mem_logger.debug(self.next_message())
1030 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001031 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001032
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
1036
1037class ExceptionFormatter(logging.Formatter):
1038 """A special exception formatter."""
1039 def formatException(self, ei):
1040 return "Got a [%s]" % ei[0].__name__
1041
1042
1043class ConfigFileTest(BaseTest):
1044
1045 """Reading logging config from a .ini-style config file."""
1046
1047 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
1048
1049 # config0 is a standard configuration.
1050 config0 = """
1051 [loggers]
1052 keys=root
1053
1054 [handlers]
1055 keys=hand1
1056
1057 [formatters]
1058 keys=form1
1059
1060 [logger_root]
1061 level=WARNING
1062 handlers=hand1
1063
1064 [handler_hand1]
1065 class=StreamHandler
1066 level=NOTSET
1067 formatter=form1
1068 args=(sys.stdout,)
1069
1070 [formatter_form1]
1071 format=%(levelname)s ++ %(message)s
1072 datefmt=
1073 """
1074
1075 # config1 adds a little to the standard configuration.
1076 config1 = """
1077 [loggers]
1078 keys=root,parser
1079
1080 [handlers]
1081 keys=hand1
1082
1083 [formatters]
1084 keys=form1
1085
1086 [logger_root]
1087 level=WARNING
1088 handlers=
1089
1090 [logger_parser]
1091 level=DEBUG
1092 handlers=hand1
1093 propagate=1
1094 qualname=compiler.parser
1095
1096 [handler_hand1]
1097 class=StreamHandler
1098 level=NOTSET
1099 formatter=form1
1100 args=(sys.stdout,)
1101
1102 [formatter_form1]
1103 format=%(levelname)s ++ %(message)s
1104 datefmt=
1105 """
1106
Vinay Sajip3f84b072011-03-07 17:49:33 +00001107 # config1a moves the handler to the root.
1108 config1a = """
1109 [loggers]
1110 keys=root,parser
1111
1112 [handlers]
1113 keys=hand1
1114
1115 [formatters]
1116 keys=form1
1117
1118 [logger_root]
1119 level=WARNING
1120 handlers=hand1
1121
1122 [logger_parser]
1123 level=DEBUG
1124 handlers=
1125 propagate=1
1126 qualname=compiler.parser
1127
1128 [handler_hand1]
1129 class=StreamHandler
1130 level=NOTSET
1131 formatter=form1
1132 args=(sys.stdout,)
1133
1134 [formatter_form1]
1135 format=%(levelname)s ++ %(message)s
1136 datefmt=
1137 """
1138
Christian Heimes180510d2008-03-03 19:15:45 +00001139 # config2 has a subtle configuration error that should be reported
1140 config2 = config1.replace("sys.stdout", "sys.stbout")
1141
1142 # config3 has a less subtle configuration error
1143 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
1144
1145 # config4 specifies a custom formatter class to be loaded
1146 config4 = """
1147 [loggers]
1148 keys=root
1149
1150 [handlers]
1151 keys=hand1
1152
1153 [formatters]
1154 keys=form1
1155
1156 [logger_root]
1157 level=NOTSET
1158 handlers=hand1
1159
1160 [handler_hand1]
1161 class=StreamHandler
1162 level=NOTSET
1163 formatter=form1
1164 args=(sys.stdout,)
1165
1166 [formatter_form1]
1167 class=""" + __name__ + """.ExceptionFormatter
1168 format=%(levelname)s:%(name)s:%(message)s
1169 datefmt=
1170 """
1171
Georg Brandl3dbca812008-07-23 16:10:53 +00001172 # config5 specifies a custom handler class to be loaded
1173 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
1174
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001175 # config6 uses ', ' delimiters in the handlers and formatters sections
1176 config6 = """
1177 [loggers]
1178 keys=root,parser
1179
1180 [handlers]
1181 keys=hand1, hand2
1182
1183 [formatters]
1184 keys=form1, form2
1185
1186 [logger_root]
1187 level=WARNING
1188 handlers=
1189
1190 [logger_parser]
1191 level=DEBUG
1192 handlers=hand1
1193 propagate=1
1194 qualname=compiler.parser
1195
1196 [handler_hand1]
1197 class=StreamHandler
1198 level=NOTSET
1199 formatter=form1
1200 args=(sys.stdout,)
1201
1202 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001203 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001204 level=NOTSET
1205 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001206 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001207
1208 [formatter_form1]
1209 format=%(levelname)s ++ %(message)s
1210 datefmt=
1211
1212 [formatter_form2]
1213 format=%(message)s
1214 datefmt=
1215 """
1216
Vinay Sajip3f84b072011-03-07 17:49:33 +00001217 # config7 adds a compiler logger.
1218 config7 = """
1219 [loggers]
1220 keys=root,parser,compiler
1221
1222 [handlers]
1223 keys=hand1
1224
1225 [formatters]
1226 keys=form1
1227
1228 [logger_root]
1229 level=WARNING
1230 handlers=hand1
1231
1232 [logger_compiler]
1233 level=DEBUG
1234 handlers=
1235 propagate=1
1236 qualname=compiler
1237
1238 [logger_parser]
1239 level=DEBUG
1240 handlers=
1241 propagate=1
1242 qualname=compiler.parser
1243
1244 [handler_hand1]
1245 class=StreamHandler
1246 level=NOTSET
1247 formatter=form1
1248 args=(sys.stdout,)
1249
1250 [formatter_form1]
1251 format=%(levelname)s ++ %(message)s
1252 datefmt=
1253 """
1254
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001255 disable_test = """
1256 [loggers]
1257 keys=root
1258
1259 [handlers]
1260 keys=screen
1261
1262 [formatters]
1263 keys=
1264
1265 [logger_root]
1266 level=DEBUG
1267 handlers=screen
1268
1269 [handler_screen]
1270 level=DEBUG
1271 class=StreamHandler
1272 args=(sys.stdout,)
1273 formatter=
1274 """
1275
1276 def apply_config(self, conf, **kwargs):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001277 file = io.StringIO(textwrap.dedent(conf))
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001278 logging.config.fileConfig(file, **kwargs)
Christian Heimes180510d2008-03-03 19:15:45 +00001279
1280 def test_config0_ok(self):
1281 # A simple config file which overrides the default settings.
1282 with captured_stdout() as output:
1283 self.apply_config(self.config0)
1284 logger = logging.getLogger()
1285 # Won't output anything
1286 logger.info(self.next_message())
1287 # Outputs a message
1288 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001289 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001290 ('ERROR', '2'),
1291 ], stream=output)
1292 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001293 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001294
Georg Brandl3dbca812008-07-23 16:10:53 +00001295 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +00001296 # A config file defining a sub-parser as well.
1297 with captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +00001298 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +00001299 logger = logging.getLogger("compiler.parser")
1300 # Both will output a message
1301 logger.info(self.next_message())
1302 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001303 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001304 ('INFO', '1'),
1305 ('ERROR', '2'),
1306 ], stream=output)
1307 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001308 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001309
1310 def test_config2_failure(self):
1311 # A simple config file which overrides the default settings.
1312 self.assertRaises(Exception, self.apply_config, self.config2)
1313
1314 def test_config3_failure(self):
1315 # A simple config file which overrides the default settings.
1316 self.assertRaises(Exception, self.apply_config, self.config3)
1317
1318 def test_config4_ok(self):
1319 # A config file specifying a custom formatter class.
1320 with captured_stdout() as output:
1321 self.apply_config(self.config4)
1322 logger = logging.getLogger()
1323 try:
1324 raise RuntimeError()
1325 except RuntimeError:
1326 logging.exception("just testing")
1327 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00001328 self.assertEqual(output.getvalue(),
Christian Heimes180510d2008-03-03 19:15:45 +00001329 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1330 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001331 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001332
Georg Brandl3dbca812008-07-23 16:10:53 +00001333 def test_config5_ok(self):
1334 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +00001335
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001336 def test_config6_ok(self):
1337 self.test_config1_ok(config=self.config6)
1338
Vinay Sajip3f84b072011-03-07 17:49:33 +00001339 def test_config7_ok(self):
1340 with captured_stdout() as output:
1341 self.apply_config(self.config1a)
1342 logger = logging.getLogger("compiler.parser")
1343 # See issue #11424. compiler-hyphenated sorts
1344 # between compiler and compiler.xyz and this
1345 # was preventing compiler.xyz from being included
1346 # in the child loggers of compiler because of an
1347 # overzealous loop termination condition.
1348 hyphenated = logging.getLogger('compiler-hyphenated')
1349 # All will output a message
1350 logger.info(self.next_message())
1351 logger.error(self.next_message())
1352 hyphenated.critical(self.next_message())
1353 self.assert_log_lines([
1354 ('INFO', '1'),
1355 ('ERROR', '2'),
1356 ('CRITICAL', '3'),
1357 ], stream=output)
1358 # Original logger output is empty.
1359 self.assert_log_lines([])
1360 with captured_stdout() as output:
1361 self.apply_config(self.config7)
1362 logger = logging.getLogger("compiler.parser")
1363 self.assertFalse(logger.disabled)
1364 # Both will output a message
1365 logger.info(self.next_message())
1366 logger.error(self.next_message())
1367 logger = logging.getLogger("compiler.lexer")
1368 # Both will output a message
1369 logger.info(self.next_message())
1370 logger.error(self.next_message())
1371 # Will not appear
1372 hyphenated.critical(self.next_message())
1373 self.assert_log_lines([
1374 ('INFO', '4'),
1375 ('ERROR', '5'),
1376 ('INFO', '6'),
1377 ('ERROR', '7'),
1378 ], stream=output)
1379 # Original logger output is empty.
1380 self.assert_log_lines([])
1381
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001382 def test_logger_disabling(self):
1383 self.apply_config(self.disable_test)
1384 logger = logging.getLogger('foo')
1385 self.assertFalse(logger.disabled)
1386 self.apply_config(self.disable_test)
1387 self.assertTrue(logger.disabled)
1388 self.apply_config(self.disable_test, disable_existing_loggers=False)
1389 self.assertFalse(logger.disabled)
1390
Guido van Rossum2a1d5162003-01-21 21:05:22 +00001391
Victor Stinner45df8202010-04-28 22:31:17 +00001392@unittest.skipUnless(threading, 'Threading required for this test.')
Christian Heimes180510d2008-03-03 19:15:45 +00001393class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001394
Christian Heimes180510d2008-03-03 19:15:45 +00001395 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001396
Christian Heimes180510d2008-03-03 19:15:45 +00001397 def setUp(self):
1398 """Set up a TCP server to receive log messages, and a SocketHandler
1399 pointing to that server's address and port."""
1400 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001401 addr = ('localhost', 0)
1402 self.server = server = TestTCPServer(addr, self.handle_socket,
1403 0.01)
1404 server.start()
1405 server.ready.wait()
1406 self.sock_hdlr = logging.handlers.SocketHandler('localhost',
1407 server.port)
1408 self.log_output = ''
Christian Heimes180510d2008-03-03 19:15:45 +00001409 self.root_logger.removeHandler(self.root_logger.handlers[0])
1410 self.root_logger.addHandler(self.sock_hdlr)
Vinay Sajip7367d082011-05-02 13:17:27 +01001411 self.handled = threading.Semaphore(0)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001412
Christian Heimes180510d2008-03-03 19:15:45 +00001413 def tearDown(self):
1414 """Shutdown the TCP server."""
1415 try:
Vinay Sajip7367d082011-05-02 13:17:27 +01001416 self.server.stop(2.0)
Christian Heimes180510d2008-03-03 19:15:45 +00001417 self.root_logger.removeHandler(self.sock_hdlr)
1418 self.sock_hdlr.close()
Christian Heimes180510d2008-03-03 19:15:45 +00001419 finally:
1420 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001421
Vinay Sajip7367d082011-05-02 13:17:27 +01001422 def handle_socket(self, request):
1423 conn = request.connection
1424 while True:
1425 chunk = conn.recv(4)
1426 if len(chunk) < 4:
1427 break
1428 slen = struct.unpack(">L", chunk)[0]
1429 chunk = conn.recv(slen)
1430 while len(chunk) < slen:
1431 chunk = chunk + conn.recv(slen - len(chunk))
1432 obj = pickle.loads(chunk)
1433 record = logging.makeLogRecord(obj)
1434 self.log_output += record.msg + '\n'
1435 self.handled.release()
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001436
Christian Heimes180510d2008-03-03 19:15:45 +00001437 def test_output(self):
1438 # The log message sent to the SocketHandler is properly received.
1439 logger = logging.getLogger("tcp")
1440 logger.error("spam")
Vinay Sajip7367d082011-05-02 13:17:27 +01001441 self.handled.acquire()
Christian Heimes180510d2008-03-03 19:15:45 +00001442 logger.debug("eggs")
Vinay Sajip7367d082011-05-02 13:17:27 +01001443 self.handled.acquire()
1444 self.assertEqual(self.log_output, "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001445
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001446 def test_noserver(self):
1447 # Kill the server
Vinay Sajip7367d082011-05-02 13:17:27 +01001448 self.server.stop(2.0)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001449 #The logging call should try to connect, which should fail
1450 try:
1451 raise RuntimeError('Deliberate mistake')
1452 except RuntimeError:
1453 self.root_logger.exception('Never sent')
1454 self.root_logger.error('Never sent, either')
1455 now = time.time()
1456 self.assertTrue(self.sock_hdlr.retryTime > now)
1457 time.sleep(self.sock_hdlr.retryTime - now + 0.001)
1458 self.root_logger.error('Nor this')
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001459
Vinay Sajip7367d082011-05-02 13:17:27 +01001460
1461@unittest.skipUnless(threading, 'Threading required for this test.')
1462class DatagramHandlerTest(BaseTest):
1463
1464 """Test for DatagramHandler."""
1465
1466 def setUp(self):
1467 """Set up a UDP server to receive log messages, and a DatagramHandler
1468 pointing to that server's address and port."""
1469 BaseTest.setUp(self)
1470 addr = ('localhost', 0)
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001471 self.server = server = TestUDPServer(addr, self.handle_datagram, 0.01)
Vinay Sajip7367d082011-05-02 13:17:27 +01001472 server.start()
1473 server.ready.wait()
1474 self.sock_hdlr = logging.handlers.DatagramHandler('localhost',
1475 server.port)
1476 self.log_output = ''
1477 self.root_logger.removeHandler(self.root_logger.handlers[0])
1478 self.root_logger.addHandler(self.sock_hdlr)
1479 self.handled = threading.Event()
1480
1481 def tearDown(self):
1482 """Shutdown the UDP server."""
1483 try:
1484 self.server.stop(2.0)
1485 self.root_logger.removeHandler(self.sock_hdlr)
1486 self.sock_hdlr.close()
1487 finally:
1488 BaseTest.tearDown(self)
1489
1490 def handle_datagram(self, request):
1491 slen = struct.pack('>L', 0) # length of prefix
1492 packet = request.packet[len(slen):]
1493 obj = pickle.loads(packet)
1494 record = logging.makeLogRecord(obj)
1495 self.log_output += record.msg + '\n'
1496 self.handled.set()
1497
1498 def test_output(self):
1499 # The log message sent to the DatagramHandler is properly received.
1500 logger = logging.getLogger("udp")
1501 logger.error("spam")
1502 self.handled.wait()
Vinay Sajip714b8dc2011-05-02 14:43:00 +01001503 self.handled.clear()
1504 logger.error("eggs")
1505 self.handled.wait()
1506 self.assertEqual(self.log_output, "spam\neggs\n")
Vinay Sajip7367d082011-05-02 13:17:27 +01001507
1508
1509@unittest.skipUnless(threading, 'Threading required for this test.')
1510class SysLogHandlerTest(BaseTest):
1511
1512 """Test for SysLogHandler using UDP."""
1513
1514 def setUp(self):
1515 """Set up a UDP server to receive log messages, and a SysLogHandler
1516 pointing to that server's address and port."""
1517 BaseTest.setUp(self)
1518 addr = ('localhost', 0)
1519 self.server = server = TestUDPServer(addr, self.handle_datagram,
1520 0.01)
1521 server.start()
1522 server.ready.wait()
1523 self.sl_hdlr = logging.handlers.SysLogHandler(('localhost',
1524 server.port))
1525 self.log_output = ''
1526 self.root_logger.removeHandler(self.root_logger.handlers[0])
1527 self.root_logger.addHandler(self.sl_hdlr)
1528 self.handled = threading.Event()
1529
1530 def tearDown(self):
1531 """Shutdown the UDP server."""
1532 try:
1533 self.server.stop(2.0)
1534 self.root_logger.removeHandler(self.sl_hdlr)
1535 self.sl_hdlr.close()
1536 finally:
1537 BaseTest.tearDown(self)
1538
1539 def handle_datagram(self, request):
1540 self.log_output = request.packet
1541 self.handled.set()
1542
1543 def test_output(self):
1544 # The log message sent to the SysLogHandler is properly received.
1545 logger = logging.getLogger("slh")
1546 logger.error("sp\xe4m")
1547 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001548 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001549 self.handled.clear()
1550 self.sl_hdlr.append_nul = False
1551 logger.error("sp\xe4m")
1552 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001553 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m')
Vinay Sajip2353e352011-06-27 15:40:06 +01001554 self.handled.clear()
1555 self.sl_hdlr.ident = "h\xe4m-"
1556 logger.error("sp\xe4m")
1557 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001558 self.assertEqual(self.log_output, b'<11>h\xc3\xa4m-sp\xc3\xa4m')
Vinay Sajip7367d082011-05-02 13:17:27 +01001559
1560
1561@unittest.skipUnless(threading, 'Threading required for this test.')
1562class HTTPHandlerTest(BaseTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01001563 """Test for HTTPHandler."""
1564
Vinay Sajip9ba87612011-05-21 11:32:15 +01001565 PEMFILE = """-----BEGIN RSA PRIVATE KEY-----
1566MIICXQIBAAKBgQDGT4xS5r91rbLJQK2nUDenBhBG6qFk+bVOjuAGC/LSHlAoBnvG
1567zQG3agOG+e7c5z2XT8m2ktORLqG3E4mYmbxgyhDrzP6ei2Anc+pszmnxPoK3Puh5
1568aXV+XKt0bU0C1m2+ACmGGJ0t3P408art82nOxBw8ZHgIg9Dtp6xIUCyOqwIDAQAB
1569AoGBAJFTnFboaKh5eUrIzjmNrKsG44jEyy+vWvHN/FgSC4l103HxhmWiuL5Lv3f7
15700tMp1tX7D6xvHwIG9VWvyKb/Cq9rJsDibmDVIOslnOWeQhG+XwJyitR0pq/KlJIB
15715LjORcBw795oKWOAi6RcOb1ON59tysEFYhAGQO9k6VL621gRAkEA/Gb+YXULLpbs
1572piXN3q4zcHzeaVANo69tUZ6TjaQqMeTxE4tOYM0G0ZoSeHEdaP59AOZGKXXNGSQy
15732z/MddcYGQJBAMkjLSYIpOLJY11ja8OwwswFG2hEzHe0cS9bzo++R/jc1bHA5R0Y
1574i6vA5iPi+wopPFvpytdBol7UuEBe5xZrxWMCQQCWxELRHiP2yWpEeLJ3gGDzoXMN
1575PydWjhRju7Bx3AzkTtf+D6lawz1+eGTuEss5i0JKBkMEwvwnN2s1ce+EuF4JAkBb
1576E96h1lAzkVW5OAfYOPY8RCPA90ZO/hoyg7PpSxR0ECuDrgERR8gXIeYUYfejBkEa
1577rab4CfRoVJKKM28Yq/xZAkBvuq670JRCwOgfUTdww7WpdOQBYPkzQccsKNCslQW8
1578/DyW6y06oQusSENUvynT6dr3LJxt/NgZPhZX2+k1eYDV
1579-----END RSA PRIVATE KEY-----
1580-----BEGIN CERTIFICATE-----
1581MIICGzCCAYSgAwIBAgIJAIq84a2Q/OvlMA0GCSqGSIb3DQEBBQUAMBQxEjAQBgNV
1582BAMTCWxvY2FsaG9zdDAeFw0xMTA1MjExMDIzMzNaFw03NTAzMjEwMzU1MTdaMBQx
1583EjAQBgNVBAMTCWxvY2FsaG9zdDCBnzANBgkqhkiG9w0BAQEFAAOBjQAwgYkCgYEA
1584xk+MUua/da2yyUCtp1A3pwYQRuqhZPm1To7gBgvy0h5QKAZ7xs0Bt2oDhvnu3Oc9
1585l0/JtpLTkS6htxOJmJm8YMoQ68z+notgJ3PqbM5p8T6Ctz7oeWl1flyrdG1NAtZt
1586vgAphhidLdz+NPGq7fNpzsQcPGR4CIPQ7aesSFAsjqsCAwEAAaN1MHMwHQYDVR0O
1587BBYEFLWaUPO6N7efGiuoS9i3DVYcUwn0MEQGA1UdIwQ9MDuAFLWaUPO6N7efGiuo
1588S9i3DVYcUwn0oRikFjAUMRIwEAYDVQQDEwlsb2NhbGhvc3SCCQCKvOGtkPzr5TAM
1589BgNVHRMEBTADAQH/MA0GCSqGSIb3DQEBBQUAA4GBAMK5whPjLNQK1Ivvk88oqJqq
15904f889OwikGP0eUhOBhbFlsZs+jq5YZC2UzHz+evzKBlgAP1u4lP/cB85CnjvWqM+
15911c/lywFHQ6HOdDeQ1L72tSYMrNOG4XNmLn0h7rx6GoTU7dcFRfseahBCq8mv0IDt
1592IRbTpvlHWPjsSvHz0ZOH
1593-----END CERTIFICATE-----"""
1594
Vinay Sajip7367d082011-05-02 13:17:27 +01001595 def setUp(self):
1596 """Set up an HTTP server to receive log messages, and a HTTPHandler
1597 pointing to that server's address and port."""
1598 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001599 self.handled = threading.Event()
1600
Vinay Sajip7367d082011-05-02 13:17:27 +01001601 def handle_request(self, request):
Vinay Sajip0372e102011-05-05 12:59:14 +01001602 self.command = request.command
Vinay Sajip7367d082011-05-02 13:17:27 +01001603 self.log_data = urlparse(request.path)
Vinay Sajip0372e102011-05-05 12:59:14 +01001604 if self.command == 'POST':
1605 try:
1606 rlen = int(request.headers['Content-Length'])
1607 self.post_data = request.rfile.read(rlen)
1608 except:
1609 self.post_data = None
Vinay Sajip7367d082011-05-02 13:17:27 +01001610 request.send_response(200)
Vinay Sajip463ac512011-05-10 09:10:08 +01001611 request.end_headers()
Vinay Sajip7367d082011-05-02 13:17:27 +01001612 self.handled.set()
1613
1614 def test_output(self):
Vinay Sajipf2231162011-05-09 22:05:50 +01001615 # The log message sent to the HTTPHandler is properly received.
Vinay Sajip7367d082011-05-02 13:17:27 +01001616 logger = logging.getLogger("http")
Vinay Sajip9ba87612011-05-21 11:32:15 +01001617 root_logger = self.root_logger
1618 root_logger.removeHandler(self.root_logger.handlers[0])
1619 for secure in (False, True):
1620 addr = ('localhost', 0)
1621 if secure:
Vinay Sajip39e35282011-05-21 16:46:41 +01001622 try:
1623 import ssl
1624 fd, fn = tempfile.mkstemp()
1625 os.close(fd)
1626 with open(fn, 'w') as f:
1627 f.write(self.PEMFILE)
1628 sslctx = ssl.SSLContext(ssl.PROTOCOL_SSLv23)
1629 sslctx.load_cert_chain(fn)
1630 os.unlink(fn)
1631 except ImportError:
1632 sslctx = None
Vinay Sajip0372e102011-05-05 12:59:14 +01001633 else:
Vinay Sajip9ba87612011-05-21 11:32:15 +01001634 sslctx = None
1635 self.server = server = TestHTTPServer(addr, self.handle_request,
1636 0.01, sslctx=sslctx)
1637 server.start()
1638 server.ready.wait()
1639 host = 'localhost:%d' % server.server_port
Vinay Sajip39e35282011-05-21 16:46:41 +01001640 secure_client = secure and sslctx
1641 self.h_hdlr = logging.handlers.HTTPHandler(host, '/frob',
1642 secure=secure_client)
Vinay Sajip9ba87612011-05-21 11:32:15 +01001643 self.log_data = None
1644 root_logger.addHandler(self.h_hdlr)
1645
1646 for method in ('GET', 'POST'):
1647 self.h_hdlr.method = method
1648 self.handled.clear()
1649 msg = "sp\xe4m"
1650 logger.error(msg)
1651 self.handled.wait()
1652 self.assertEqual(self.log_data.path, '/frob')
1653 self.assertEqual(self.command, method)
1654 if method == 'GET':
1655 d = parse_qs(self.log_data.query)
1656 else:
1657 d = parse_qs(self.post_data.decode('utf-8'))
1658 self.assertEqual(d['name'], ['http'])
1659 self.assertEqual(d['funcName'], ['test_output'])
1660 self.assertEqual(d['msg'], [msg])
1661
1662 self.server.stop(2.0)
1663 self.root_logger.removeHandler(self.h_hdlr)
1664 self.h_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001665
Christian Heimes180510d2008-03-03 19:15:45 +00001666class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001667
Christian Heimes180510d2008-03-03 19:15:45 +00001668 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001669
Christian Heimes180510d2008-03-03 19:15:45 +00001670 def setUp(self):
1671 """Create a dict to remember potentially destroyed objects."""
1672 BaseTest.setUp(self)
1673 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001674
Christian Heimes180510d2008-03-03 19:15:45 +00001675 def _watch_for_survival(self, *args):
1676 """Watch the given objects for survival, by creating weakrefs to
1677 them."""
1678 for obj in args:
1679 key = id(obj), repr(obj)
1680 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001681
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001682 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +00001683 """Assert that all objects watched for survival have survived."""
1684 # Trigger cycle breaking.
1685 gc.collect()
1686 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001687 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +00001688 if ref() is None:
1689 dead.append(repr_)
1690 if dead:
1691 self.fail("%d objects should have survived "
1692 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001693
Christian Heimes180510d2008-03-03 19:15:45 +00001694 def test_persistent_loggers(self):
1695 # Logger objects are persistent and retain their configuration, even
1696 # if visible references are destroyed.
1697 self.root_logger.setLevel(logging.INFO)
1698 foo = logging.getLogger("foo")
1699 self._watch_for_survival(foo)
1700 foo.setLevel(logging.DEBUG)
1701 self.root_logger.debug(self.next_message())
1702 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001703 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001704 ('foo', 'DEBUG', '2'),
1705 ])
1706 del foo
1707 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001708 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +00001709 # foo has retained its settings.
1710 bar = logging.getLogger("foo")
1711 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001712 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001713 ('foo', 'DEBUG', '2'),
1714 ('foo', 'DEBUG', '3'),
1715 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001716
Benjamin Petersonf91df042009-02-13 02:50:59 +00001717
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001718class EncodingTest(BaseTest):
1719 def test_encoding_plain_file(self):
1720 # In Python 2.x, a plain file object is treated as having no encoding.
1721 log = logging.getLogger("test")
Vinay Sajip60b4df12010-12-27 11:18:52 +00001722 fd, fn = tempfile.mkstemp(".log", "test_logging-1-")
1723 os.close(fd)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001724 # the non-ascii data we write to the log.
1725 data = "foo\x80"
1726 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001727 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001728 log.addHandler(handler)
1729 try:
1730 # write non-ascii data to the log.
1731 log.warning(data)
1732 finally:
1733 log.removeHandler(handler)
1734 handler.close()
1735 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001736 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001737 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001738 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001739 finally:
1740 f.close()
1741 finally:
1742 if os.path.isfile(fn):
1743 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001744
Benjamin Petersonf91df042009-02-13 02:50:59 +00001745 def test_encoding_cyrillic_unicode(self):
1746 log = logging.getLogger("test")
1747 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
1748 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
1749 #Ensure it's written in a Cyrillic encoding
1750 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +00001751 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +00001752 stream = io.BytesIO()
1753 writer = writer_class(stream, 'strict')
1754 handler = logging.StreamHandler(writer)
1755 log.addHandler(handler)
1756 try:
1757 log.warning(message)
1758 finally:
1759 log.removeHandler(handler)
1760 handler.close()
1761 # check we wrote exactly those bytes, ignoring trailing \n etc
1762 s = stream.getvalue()
1763 #Compare against what the data should be when encoded in CP-1251
1764 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
1765
1766
Georg Brandlf9734072008-12-07 15:30:06 +00001767class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +00001768
Georg Brandlf9734072008-12-07 15:30:06 +00001769 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +00001770 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +00001771 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001772 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001773 warnings.filterwarnings("always", category=UserWarning)
1774 stream = io.StringIO()
1775 h = logging.StreamHandler(stream)
1776 logger = logging.getLogger("py.warnings")
1777 logger.addHandler(h)
1778 warnings.warn("I'm warning you...")
1779 logger.removeHandler(h)
1780 s = stream.getvalue()
1781 h.close()
1782 self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0)
Georg Brandlf9734072008-12-07 15:30:06 +00001783
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001784 #See if an explicit file uses the original implementation
1785 a_file = io.StringIO()
1786 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
1787 a_file, "Dummy line")
1788 s = a_file.getvalue()
1789 a_file.close()
1790 self.assertEqual(s,
1791 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
1792
1793 def test_warnings_no_handlers(self):
1794 with warnings.catch_warnings():
1795 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001796 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001797
1798 # confirm our assumption: no loggers are set
1799 logger = logging.getLogger("py.warnings")
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001800 self.assertEqual(logger.handlers, [])
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001801
1802 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001803 self.assertEqual(len(logger.handlers), 1)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001804 self.assertIsInstance(logger.handlers[0], logging.NullHandler)
Georg Brandlf9734072008-12-07 15:30:06 +00001805
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001806
1807def formatFunc(format, datefmt=None):
1808 return logging.Formatter(format, datefmt)
1809
1810def handlerFunc():
1811 return logging.StreamHandler()
1812
1813class CustomHandler(logging.StreamHandler):
1814 pass
1815
1816class ConfigDictTest(BaseTest):
1817
1818 """Reading logging config from a dictionary."""
1819
1820 expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$"
1821
1822 # config0 is a standard configuration.
1823 config0 = {
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 'root' : {
1839 'level' : 'WARNING',
1840 'handlers' : ['hand1'],
1841 },
1842 }
1843
1844 # config1 adds a little to the standard configuration.
1845 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001846 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001847 'formatters': {
1848 'form1' : {
1849 'format' : '%(levelname)s ++ %(message)s',
1850 },
1851 },
1852 'handlers' : {
1853 'hand1' : {
1854 'class' : 'logging.StreamHandler',
1855 'formatter' : 'form1',
1856 'level' : 'NOTSET',
1857 'stream' : 'ext://sys.stdout',
1858 },
1859 },
1860 'loggers' : {
1861 'compiler.parser' : {
1862 'level' : 'DEBUG',
1863 'handlers' : ['hand1'],
1864 },
1865 },
1866 'root' : {
1867 'level' : 'WARNING',
1868 },
1869 }
1870
Vinay Sajip9f9991c2011-03-07 18:02:57 +00001871 # config1a moves the handler to the root. Used with config8a
1872 config1a = {
1873 'version': 1,
1874 'formatters': {
1875 'form1' : {
1876 'format' : '%(levelname)s ++ %(message)s',
1877 },
1878 },
1879 'handlers' : {
1880 'hand1' : {
1881 'class' : 'logging.StreamHandler',
1882 'formatter' : 'form1',
1883 'level' : 'NOTSET',
1884 'stream' : 'ext://sys.stdout',
1885 },
1886 },
1887 'loggers' : {
1888 'compiler.parser' : {
1889 'level' : 'DEBUG',
1890 },
1891 },
1892 'root' : {
1893 'level' : 'WARNING',
1894 'handlers' : ['hand1'],
1895 },
1896 }
1897
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001898 # config2 has a subtle configuration error that should be reported
1899 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001900 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001901 'formatters': {
1902 'form1' : {
1903 'format' : '%(levelname)s ++ %(message)s',
1904 },
1905 },
1906 'handlers' : {
1907 'hand1' : {
1908 'class' : 'logging.StreamHandler',
1909 'formatter' : 'form1',
1910 'level' : 'NOTSET',
1911 'stream' : 'ext://sys.stdbout',
1912 },
1913 },
1914 'loggers' : {
1915 'compiler.parser' : {
1916 'level' : 'DEBUG',
1917 'handlers' : ['hand1'],
1918 },
1919 },
1920 'root' : {
1921 'level' : 'WARNING',
1922 },
1923 }
1924
1925 #As config1 but with a misspelt level on a handler
1926 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001927 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001928 'formatters': {
1929 'form1' : {
1930 'format' : '%(levelname)s ++ %(message)s',
1931 },
1932 },
1933 'handlers' : {
1934 'hand1' : {
1935 'class' : 'logging.StreamHandler',
1936 'formatter' : 'form1',
1937 'level' : 'NTOSET',
1938 'stream' : 'ext://sys.stdout',
1939 },
1940 },
1941 'loggers' : {
1942 'compiler.parser' : {
1943 'level' : 'DEBUG',
1944 'handlers' : ['hand1'],
1945 },
1946 },
1947 'root' : {
1948 'level' : 'WARNING',
1949 },
1950 }
1951
1952
1953 #As config1 but with a misspelt level on a logger
1954 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001955 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001956 'formatters': {
1957 'form1' : {
1958 'format' : '%(levelname)s ++ %(message)s',
1959 },
1960 },
1961 'handlers' : {
1962 'hand1' : {
1963 'class' : 'logging.StreamHandler',
1964 'formatter' : 'form1',
1965 'level' : 'NOTSET',
1966 'stream' : 'ext://sys.stdout',
1967 },
1968 },
1969 'loggers' : {
1970 'compiler.parser' : {
1971 'level' : 'DEBUG',
1972 'handlers' : ['hand1'],
1973 },
1974 },
1975 'root' : {
1976 'level' : 'WRANING',
1977 },
1978 }
1979
1980 # config3 has a less subtle configuration error
1981 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001982 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001983 'formatters': {
1984 'form1' : {
1985 'format' : '%(levelname)s ++ %(message)s',
1986 },
1987 },
1988 'handlers' : {
1989 'hand1' : {
1990 'class' : 'logging.StreamHandler',
1991 'formatter' : 'misspelled_name',
1992 'level' : 'NOTSET',
1993 'stream' : 'ext://sys.stdout',
1994 },
1995 },
1996 'loggers' : {
1997 'compiler.parser' : {
1998 'level' : 'DEBUG',
1999 'handlers' : ['hand1'],
2000 },
2001 },
2002 'root' : {
2003 'level' : 'WARNING',
2004 },
2005 }
2006
2007 # config4 specifies a custom formatter class to be loaded
2008 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002009 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002010 'formatters': {
2011 'form1' : {
2012 '()' : __name__ + '.ExceptionFormatter',
2013 'format' : '%(levelname)s:%(name)s:%(message)s',
2014 },
2015 },
2016 'handlers' : {
2017 'hand1' : {
2018 'class' : 'logging.StreamHandler',
2019 'formatter' : 'form1',
2020 'level' : 'NOTSET',
2021 'stream' : 'ext://sys.stdout',
2022 },
2023 },
2024 'root' : {
2025 'level' : 'NOTSET',
2026 'handlers' : ['hand1'],
2027 },
2028 }
2029
2030 # As config4 but using an actual callable rather than a string
2031 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002032 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002033 'formatters': {
2034 'form1' : {
2035 '()' : ExceptionFormatter,
2036 'format' : '%(levelname)s:%(name)s:%(message)s',
2037 },
2038 'form2' : {
2039 '()' : __name__ + '.formatFunc',
2040 'format' : '%(levelname)s:%(name)s:%(message)s',
2041 },
2042 'form3' : {
2043 '()' : formatFunc,
2044 'format' : '%(levelname)s:%(name)s:%(message)s',
2045 },
2046 },
2047 'handlers' : {
2048 'hand1' : {
2049 'class' : 'logging.StreamHandler',
2050 'formatter' : 'form1',
2051 'level' : 'NOTSET',
2052 'stream' : 'ext://sys.stdout',
2053 },
2054 'hand2' : {
2055 '()' : handlerFunc,
2056 },
2057 },
2058 'root' : {
2059 'level' : 'NOTSET',
2060 'handlers' : ['hand1'],
2061 },
2062 }
2063
2064 # config5 specifies a custom handler class to be loaded
2065 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002066 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002067 'formatters': {
2068 'form1' : {
2069 'format' : '%(levelname)s ++ %(message)s',
2070 },
2071 },
2072 'handlers' : {
2073 'hand1' : {
2074 'class' : __name__ + '.CustomHandler',
2075 'formatter' : 'form1',
2076 'level' : 'NOTSET',
2077 'stream' : 'ext://sys.stdout',
2078 },
2079 },
2080 'loggers' : {
2081 'compiler.parser' : {
2082 'level' : 'DEBUG',
2083 'handlers' : ['hand1'],
2084 },
2085 },
2086 'root' : {
2087 'level' : 'WARNING',
2088 },
2089 }
2090
2091 # config6 specifies a custom handler class to be loaded
2092 # but has bad arguments
2093 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002094 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002095 'formatters': {
2096 'form1' : {
2097 'format' : '%(levelname)s ++ %(message)s',
2098 },
2099 },
2100 'handlers' : {
2101 'hand1' : {
2102 'class' : __name__ + '.CustomHandler',
2103 'formatter' : 'form1',
2104 'level' : 'NOTSET',
2105 'stream' : 'ext://sys.stdout',
2106 '9' : 'invalid parameter name',
2107 },
2108 },
2109 'loggers' : {
2110 'compiler.parser' : {
2111 'level' : 'DEBUG',
2112 'handlers' : ['hand1'],
2113 },
2114 },
2115 'root' : {
2116 'level' : 'WARNING',
2117 },
2118 }
2119
2120 #config 7 does not define compiler.parser but defines compiler.lexer
2121 #so compiler.parser should be disabled after applying it
2122 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002123 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002124 'formatters': {
2125 'form1' : {
2126 'format' : '%(levelname)s ++ %(message)s',
2127 },
2128 },
2129 'handlers' : {
2130 'hand1' : {
2131 'class' : 'logging.StreamHandler',
2132 'formatter' : 'form1',
2133 'level' : 'NOTSET',
2134 'stream' : 'ext://sys.stdout',
2135 },
2136 },
2137 'loggers' : {
2138 'compiler.lexer' : {
2139 'level' : 'DEBUG',
2140 'handlers' : ['hand1'],
2141 },
2142 },
2143 'root' : {
2144 'level' : 'WARNING',
2145 },
2146 }
2147
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002148 # config8 defines both compiler and compiler.lexer
2149 # so compiler.parser should not be disabled (since
2150 # compiler is defined)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002151 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002152 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002153 'disable_existing_loggers' : False,
2154 'formatters': {
2155 'form1' : {
2156 'format' : '%(levelname)s ++ %(message)s',
2157 },
2158 },
2159 'handlers' : {
2160 'hand1' : {
2161 'class' : 'logging.StreamHandler',
2162 'formatter' : 'form1',
2163 'level' : 'NOTSET',
2164 'stream' : 'ext://sys.stdout',
2165 },
2166 },
2167 'loggers' : {
2168 'compiler' : {
2169 'level' : 'DEBUG',
2170 'handlers' : ['hand1'],
2171 },
2172 'compiler.lexer' : {
2173 },
2174 },
2175 'root' : {
2176 'level' : 'WARNING',
2177 },
2178 }
2179
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002180 # config8a disables existing loggers
2181 config8a = {
2182 'version': 1,
2183 'disable_existing_loggers' : True,
2184 'formatters': {
2185 'form1' : {
2186 'format' : '%(levelname)s ++ %(message)s',
2187 },
2188 },
2189 'handlers' : {
2190 'hand1' : {
2191 'class' : 'logging.StreamHandler',
2192 'formatter' : 'form1',
2193 'level' : 'NOTSET',
2194 'stream' : 'ext://sys.stdout',
2195 },
2196 },
2197 'loggers' : {
2198 'compiler' : {
2199 'level' : 'DEBUG',
2200 'handlers' : ['hand1'],
2201 },
2202 'compiler.lexer' : {
2203 },
2204 },
2205 'root' : {
2206 'level' : 'WARNING',
2207 },
2208 }
2209
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002210 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002211 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002212 'formatters': {
2213 'form1' : {
2214 'format' : '%(levelname)s ++ %(message)s',
2215 },
2216 },
2217 'handlers' : {
2218 'hand1' : {
2219 'class' : 'logging.StreamHandler',
2220 'formatter' : 'form1',
2221 'level' : 'WARNING',
2222 'stream' : 'ext://sys.stdout',
2223 },
2224 },
2225 'loggers' : {
2226 'compiler.parser' : {
2227 'level' : 'WARNING',
2228 'handlers' : ['hand1'],
2229 },
2230 },
2231 'root' : {
2232 'level' : 'NOTSET',
2233 },
2234 }
2235
2236 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002237 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002238 'incremental' : True,
2239 'handlers' : {
2240 'hand1' : {
2241 'level' : 'WARNING',
2242 },
2243 },
2244 'loggers' : {
2245 'compiler.parser' : {
2246 'level' : 'INFO',
2247 },
2248 },
2249 }
2250
2251 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002252 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002253 'incremental' : True,
2254 'handlers' : {
2255 'hand1' : {
2256 'level' : 'INFO',
2257 },
2258 },
2259 'loggers' : {
2260 'compiler.parser' : {
2261 'level' : 'INFO',
2262 },
2263 },
2264 }
2265
2266 #As config1 but with a filter added
2267 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002268 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002269 'formatters': {
2270 'form1' : {
2271 'format' : '%(levelname)s ++ %(message)s',
2272 },
2273 },
2274 'filters' : {
2275 'filt1' : {
2276 'name' : 'compiler.parser',
2277 },
2278 },
2279 'handlers' : {
2280 'hand1' : {
2281 'class' : 'logging.StreamHandler',
2282 'formatter' : 'form1',
2283 'level' : 'NOTSET',
2284 'stream' : 'ext://sys.stdout',
2285 'filters' : ['filt1'],
2286 },
2287 },
2288 'loggers' : {
2289 'compiler.parser' : {
2290 'level' : 'DEBUG',
2291 'filters' : ['filt1'],
2292 },
2293 },
2294 'root' : {
2295 'level' : 'WARNING',
2296 'handlers' : ['hand1'],
2297 },
2298 }
2299
2300 #As config1 but using cfg:// references
2301 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002302 'version': 1,
2303 'true_formatters': {
2304 'form1' : {
2305 'format' : '%(levelname)s ++ %(message)s',
2306 },
2307 },
2308 'handler_configs': {
2309 'hand1' : {
2310 'class' : 'logging.StreamHandler',
2311 'formatter' : 'form1',
2312 'level' : 'NOTSET',
2313 'stream' : 'ext://sys.stdout',
2314 },
2315 },
2316 'formatters' : 'cfg://true_formatters',
2317 'handlers' : {
2318 'hand1' : 'cfg://handler_configs[hand1]',
2319 },
2320 'loggers' : {
2321 'compiler.parser' : {
2322 'level' : 'DEBUG',
2323 'handlers' : ['hand1'],
2324 },
2325 },
2326 'root' : {
2327 'level' : 'WARNING',
2328 },
2329 }
2330
2331 #As config11 but missing the version key
2332 config12 = {
2333 'true_formatters': {
2334 'form1' : {
2335 'format' : '%(levelname)s ++ %(message)s',
2336 },
2337 },
2338 'handler_configs': {
2339 'hand1' : {
2340 'class' : 'logging.StreamHandler',
2341 'formatter' : 'form1',
2342 'level' : 'NOTSET',
2343 'stream' : 'ext://sys.stdout',
2344 },
2345 },
2346 'formatters' : 'cfg://true_formatters',
2347 'handlers' : {
2348 'hand1' : 'cfg://handler_configs[hand1]',
2349 },
2350 'loggers' : {
2351 'compiler.parser' : {
2352 'level' : 'DEBUG',
2353 'handlers' : ['hand1'],
2354 },
2355 },
2356 'root' : {
2357 'level' : 'WARNING',
2358 },
2359 }
2360
2361 #As config11 but using an unsupported version
2362 config13 = {
2363 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002364 'true_formatters': {
2365 'form1' : {
2366 'format' : '%(levelname)s ++ %(message)s',
2367 },
2368 },
2369 'handler_configs': {
2370 'hand1' : {
2371 'class' : 'logging.StreamHandler',
2372 'formatter' : 'form1',
2373 'level' : 'NOTSET',
2374 'stream' : 'ext://sys.stdout',
2375 },
2376 },
2377 'formatters' : 'cfg://true_formatters',
2378 'handlers' : {
2379 'hand1' : 'cfg://handler_configs[hand1]',
2380 },
2381 'loggers' : {
2382 'compiler.parser' : {
2383 'level' : 'DEBUG',
2384 'handlers' : ['hand1'],
2385 },
2386 },
2387 'root' : {
2388 'level' : 'WARNING',
2389 },
2390 }
2391
Vinay Sajip3f885b52013-03-22 15:19:54 +00002392 out_of_order = {
2393 "version": 1,
2394 "formatters": {
2395 "mySimpleFormatter": {
Vinay Sajip28421c62013-03-29 17:56:54 +00002396 "format": "%(asctime)s (%(name)s) %(levelname)s: %(message)s",
2397 "style": "$"
Vinay Sajip3f885b52013-03-22 15:19:54 +00002398 }
2399 },
2400 "handlers": {
2401 "fileGlobal": {
2402 "class": "logging.StreamHandler",
2403 "level": "DEBUG",
2404 "formatter": "mySimpleFormatter"
2405 },
2406 "bufferGlobal": {
2407 "class": "logging.handlers.MemoryHandler",
2408 "capacity": 5,
2409 "formatter": "mySimpleFormatter",
2410 "target": "fileGlobal",
2411 "level": "DEBUG"
2412 }
2413 },
2414 "loggers": {
2415 "mymodule": {
2416 "level": "DEBUG",
2417 "handlers": ["bufferGlobal"],
2418 "propagate": "true"
2419 }
2420 }
2421 }
2422
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002423 def apply_config(self, conf):
2424 logging.config.dictConfig(conf)
2425
2426 def test_config0_ok(self):
2427 # A simple config which overrides the default settings.
2428 with captured_stdout() as output:
2429 self.apply_config(self.config0)
2430 logger = logging.getLogger()
2431 # Won't output anything
2432 logger.info(self.next_message())
2433 # Outputs a message
2434 logger.error(self.next_message())
2435 self.assert_log_lines([
2436 ('ERROR', '2'),
2437 ], stream=output)
2438 # Original logger output is empty.
2439 self.assert_log_lines([])
2440
2441 def test_config1_ok(self, config=config1):
2442 # A config defining a sub-parser as well.
2443 with captured_stdout() as output:
2444 self.apply_config(config)
2445 logger = logging.getLogger("compiler.parser")
2446 # Both will output a message
2447 logger.info(self.next_message())
2448 logger.error(self.next_message())
2449 self.assert_log_lines([
2450 ('INFO', '1'),
2451 ('ERROR', '2'),
2452 ], stream=output)
2453 # Original logger output is empty.
2454 self.assert_log_lines([])
2455
2456 def test_config2_failure(self):
2457 # A simple config which overrides the default settings.
2458 self.assertRaises(Exception, self.apply_config, self.config2)
2459
2460 def test_config2a_failure(self):
2461 # A simple config which overrides the default settings.
2462 self.assertRaises(Exception, self.apply_config, self.config2a)
2463
2464 def test_config2b_failure(self):
2465 # A simple config which overrides the default settings.
2466 self.assertRaises(Exception, self.apply_config, self.config2b)
2467
2468 def test_config3_failure(self):
2469 # A simple config which overrides the default settings.
2470 self.assertRaises(Exception, self.apply_config, self.config3)
2471
2472 def test_config4_ok(self):
2473 # A config specifying a custom formatter class.
2474 with captured_stdout() as output:
2475 self.apply_config(self.config4)
2476 #logger = logging.getLogger()
2477 try:
2478 raise RuntimeError()
2479 except RuntimeError:
2480 logging.exception("just testing")
2481 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002482 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002483 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2484 # Original logger output is empty
2485 self.assert_log_lines([])
2486
2487 def test_config4a_ok(self):
2488 # A config specifying a custom formatter class.
2489 with captured_stdout() as output:
2490 self.apply_config(self.config4a)
2491 #logger = logging.getLogger()
2492 try:
2493 raise RuntimeError()
2494 except RuntimeError:
2495 logging.exception("just testing")
2496 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002497 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002498 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2499 # Original logger output is empty
2500 self.assert_log_lines([])
2501
2502 def test_config5_ok(self):
2503 self.test_config1_ok(config=self.config5)
2504
2505 def test_config6_failure(self):
2506 self.assertRaises(Exception, self.apply_config, self.config6)
2507
2508 def test_config7_ok(self):
2509 with captured_stdout() as output:
2510 self.apply_config(self.config1)
2511 logger = logging.getLogger("compiler.parser")
2512 # Both will output a message
2513 logger.info(self.next_message())
2514 logger.error(self.next_message())
2515 self.assert_log_lines([
2516 ('INFO', '1'),
2517 ('ERROR', '2'),
2518 ], stream=output)
2519 # Original logger output is empty.
2520 self.assert_log_lines([])
2521 with captured_stdout() as output:
2522 self.apply_config(self.config7)
2523 logger = logging.getLogger("compiler.parser")
2524 self.assertTrue(logger.disabled)
2525 logger = logging.getLogger("compiler.lexer")
2526 # Both will output a message
2527 logger.info(self.next_message())
2528 logger.error(self.next_message())
2529 self.assert_log_lines([
2530 ('INFO', '3'),
2531 ('ERROR', '4'),
2532 ], stream=output)
2533 # Original logger output is empty.
2534 self.assert_log_lines([])
2535
2536 #Same as test_config_7_ok but don't disable old loggers.
2537 def test_config_8_ok(self):
2538 with captured_stdout() as output:
2539 self.apply_config(self.config1)
2540 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002541 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002542 logger.info(self.next_message())
2543 logger.error(self.next_message())
2544 self.assert_log_lines([
2545 ('INFO', '1'),
2546 ('ERROR', '2'),
2547 ], stream=output)
2548 # Original logger output is empty.
2549 self.assert_log_lines([])
2550 with captured_stdout() as output:
2551 self.apply_config(self.config8)
2552 logger = logging.getLogger("compiler.parser")
2553 self.assertFalse(logger.disabled)
2554 # Both will output a message
2555 logger.info(self.next_message())
2556 logger.error(self.next_message())
2557 logger = logging.getLogger("compiler.lexer")
2558 # Both will output a message
2559 logger.info(self.next_message())
2560 logger.error(self.next_message())
2561 self.assert_log_lines([
2562 ('INFO', '3'),
2563 ('ERROR', '4'),
2564 ('INFO', '5'),
2565 ('ERROR', '6'),
2566 ], stream=output)
2567 # Original logger output is empty.
2568 self.assert_log_lines([])
2569
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002570 def test_config_8a_ok(self):
2571 with captured_stdout() as output:
2572 self.apply_config(self.config1a)
2573 logger = logging.getLogger("compiler.parser")
2574 # See issue #11424. compiler-hyphenated sorts
2575 # between compiler and compiler.xyz and this
2576 # was preventing compiler.xyz from being included
2577 # in the child loggers of compiler because of an
2578 # overzealous loop termination condition.
2579 hyphenated = logging.getLogger('compiler-hyphenated')
2580 # All will output a message
2581 logger.info(self.next_message())
2582 logger.error(self.next_message())
2583 hyphenated.critical(self.next_message())
2584 self.assert_log_lines([
2585 ('INFO', '1'),
2586 ('ERROR', '2'),
2587 ('CRITICAL', '3'),
2588 ], stream=output)
2589 # Original logger output is empty.
2590 self.assert_log_lines([])
2591 with captured_stdout() as output:
2592 self.apply_config(self.config8a)
2593 logger = logging.getLogger("compiler.parser")
2594 self.assertFalse(logger.disabled)
2595 # Both will output a message
2596 logger.info(self.next_message())
2597 logger.error(self.next_message())
2598 logger = logging.getLogger("compiler.lexer")
2599 # Both will output a message
2600 logger.info(self.next_message())
2601 logger.error(self.next_message())
2602 # Will not appear
2603 hyphenated.critical(self.next_message())
2604 self.assert_log_lines([
2605 ('INFO', '4'),
2606 ('ERROR', '5'),
2607 ('INFO', '6'),
2608 ('ERROR', '7'),
2609 ], stream=output)
2610 # Original logger output is empty.
2611 self.assert_log_lines([])
2612
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002613 def test_config_9_ok(self):
2614 with captured_stdout() as output:
2615 self.apply_config(self.config9)
2616 logger = logging.getLogger("compiler.parser")
2617 #Nothing will be output since both handler and logger are set to WARNING
2618 logger.info(self.next_message())
2619 self.assert_log_lines([], stream=output)
2620 self.apply_config(self.config9a)
2621 #Nothing will be output since both handler is still set to WARNING
2622 logger.info(self.next_message())
2623 self.assert_log_lines([], stream=output)
2624 self.apply_config(self.config9b)
2625 #Message should now be output
2626 logger.info(self.next_message())
2627 self.assert_log_lines([
2628 ('INFO', '3'),
2629 ], stream=output)
2630
2631 def test_config_10_ok(self):
2632 with captured_stdout() as output:
2633 self.apply_config(self.config10)
2634 logger = logging.getLogger("compiler.parser")
2635 logger.warning(self.next_message())
2636 logger = logging.getLogger('compiler')
2637 #Not output, because filtered
2638 logger.warning(self.next_message())
2639 logger = logging.getLogger('compiler.lexer')
2640 #Not output, because filtered
2641 logger.warning(self.next_message())
2642 logger = logging.getLogger("compiler.parser.codegen")
2643 #Output, as not filtered
2644 logger.error(self.next_message())
2645 self.assert_log_lines([
2646 ('WARNING', '1'),
2647 ('ERROR', '4'),
2648 ], stream=output)
2649
2650 def test_config11_ok(self):
2651 self.test_config1_ok(self.config11)
2652
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002653 def test_config12_failure(self):
2654 self.assertRaises(Exception, self.apply_config, self.config12)
2655
2656 def test_config13_failure(self):
2657 self.assertRaises(Exception, self.apply_config, self.config13)
2658
Victor Stinner45df8202010-04-28 22:31:17 +00002659 @unittest.skipUnless(threading, 'listen() needs threading to work')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002660 def setup_via_listener(self, text):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002661 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00002662 # Ask for a randomly assigned port (by using port 0)
2663 t = logging.config.listen(0)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002664 t.start()
2665 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00002666 # Now get the port allocated
2667 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002668 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002669 try:
2670 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
2671 sock.settimeout(2.0)
2672 sock.connect(('localhost', port))
2673
2674 slen = struct.pack('>L', len(text))
2675 s = slen + text
2676 sentsofar = 0
2677 left = len(s)
2678 while left > 0:
2679 sent = sock.send(s[sentsofar:])
2680 sentsofar += sent
2681 left -= sent
2682 sock.close()
2683 finally:
2684 t.ready.wait(2.0)
2685 logging.config.stopListening()
2686 t.join(2.0)
2687
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002688 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002689 def test_listen_config_10_ok(self):
2690 with captured_stdout() as output:
2691 self.setup_via_listener(json.dumps(self.config10))
2692 logger = logging.getLogger("compiler.parser")
2693 logger.warning(self.next_message())
2694 logger = logging.getLogger('compiler')
2695 #Not output, because filtered
2696 logger.warning(self.next_message())
2697 logger = logging.getLogger('compiler.lexer')
2698 #Not output, because filtered
2699 logger.warning(self.next_message())
2700 logger = logging.getLogger("compiler.parser.codegen")
2701 #Output, as not filtered
2702 logger.error(self.next_message())
2703 self.assert_log_lines([
2704 ('WARNING', '1'),
2705 ('ERROR', '4'),
2706 ], stream=output)
2707
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002708 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002709 def test_listen_config_1_ok(self):
2710 with captured_stdout() as output:
2711 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
2712 logger = logging.getLogger("compiler.parser")
2713 # Both will output a message
2714 logger.info(self.next_message())
2715 logger.error(self.next_message())
2716 self.assert_log_lines([
2717 ('INFO', '1'),
2718 ('ERROR', '2'),
2719 ], stream=output)
2720 # Original logger output is empty.
2721 self.assert_log_lines([])
2722
Vinay Sajip3f885b52013-03-22 15:19:54 +00002723 def test_out_of_order(self):
2724 self.apply_config(self.out_of_order)
2725 handler = logging.getLogger('mymodule').handlers[0]
2726 self.assertIsInstance(handler.target, logging.Handler)
Vinay Sajip28421c62013-03-29 17:56:54 +00002727 self.assertIsInstance(handler.formatter._style,
2728 logging.StringTemplateStyle)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002729
Vinay Sajip373baef2011-04-26 20:05:24 +01002730 def test_baseconfig(self):
2731 d = {
2732 'atuple': (1, 2, 3),
2733 'alist': ['a', 'b', 'c'],
2734 'adict': {'d': 'e', 'f': 3 },
2735 'nest1': ('g', ('h', 'i'), 'j'),
2736 'nest2': ['k', ['l', 'm'], 'n'],
2737 'nest3': ['o', 'cfg://alist', 'p'],
2738 }
2739 bc = logging.config.BaseConfigurator(d)
2740 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
2741 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
2742 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
2743 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
2744 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
2745 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
2746 v = bc.convert('cfg://nest3')
2747 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
2748 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
2749 self.assertRaises(ValueError, bc.convert, 'cfg://!')
2750 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002751
2752class ManagerTest(BaseTest):
2753 def test_manager_loggerclass(self):
2754 logged = []
2755
2756 class MyLogger(logging.Logger):
2757 def _log(self, level, msg, args, exc_info=None, extra=None):
2758 logged.append(msg)
2759
2760 man = logging.Manager(None)
2761 self.assertRaises(TypeError, man.setLoggerClass, int)
2762 man.setLoggerClass(MyLogger)
2763 logger = man.getLogger('test')
2764 logger.warning('should appear in logged')
2765 logging.warning('should not appear in logged')
2766
2767 self.assertEqual(logged, ['should appear in logged'])
2768
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002769 def test_set_log_record_factory(self):
2770 man = logging.Manager(None)
2771 expected = object()
2772 man.setLogRecordFactory(expected)
2773 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002774
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002775class ChildLoggerTest(BaseTest):
2776 def test_child_loggers(self):
2777 r = logging.getLogger()
2778 l1 = logging.getLogger('abc')
2779 l2 = logging.getLogger('def.ghi')
2780 c1 = r.getChild('xyz')
2781 c2 = r.getChild('uvw.xyz')
2782 self.assertTrue(c1 is logging.getLogger('xyz'))
2783 self.assertTrue(c2 is logging.getLogger('uvw.xyz'))
2784 c1 = l1.getChild('def')
2785 c2 = c1.getChild('ghi')
2786 c3 = l1.getChild('def.ghi')
2787 self.assertTrue(c1 is logging.getLogger('abc.def'))
2788 self.assertTrue(c2 is logging.getLogger('abc.def.ghi'))
2789 self.assertTrue(c2 is c3)
2790
2791
Vinay Sajip6fac8172010-10-19 20:44:14 +00002792class DerivedLogRecord(logging.LogRecord):
2793 pass
2794
Vinay Sajip61561522010-12-03 11:50:38 +00002795class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00002796
2797 def setUp(self):
2798 class CheckingFilter(logging.Filter):
2799 def __init__(self, cls):
2800 self.cls = cls
2801
2802 def filter(self, record):
2803 t = type(record)
2804 if t is not self.cls:
2805 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
2806 self.cls)
2807 raise TypeError(msg)
2808 return True
2809
2810 BaseTest.setUp(self)
2811 self.filter = CheckingFilter(DerivedLogRecord)
2812 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00002813 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00002814
2815 def tearDown(self):
2816 self.root_logger.removeFilter(self.filter)
2817 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00002818 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002819
2820 def test_logrecord_class(self):
2821 self.assertRaises(TypeError, self.root_logger.warning,
2822 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00002823 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002824 self.root_logger.error(self.next_message())
2825 self.assert_log_lines([
2826 ('root', 'ERROR', '2'),
2827 ])
2828
2829
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002830class QueueHandlerTest(BaseTest):
2831 # Do not bother with a logger name group.
2832 expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$"
2833
2834 def setUp(self):
2835 BaseTest.setUp(self)
2836 self.queue = queue.Queue(-1)
2837 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
2838 self.que_logger = logging.getLogger('que')
2839 self.que_logger.propagate = False
2840 self.que_logger.setLevel(logging.WARNING)
2841 self.que_logger.addHandler(self.que_hdlr)
2842
2843 def tearDown(self):
2844 self.que_hdlr.close()
2845 BaseTest.tearDown(self)
2846
2847 def test_queue_handler(self):
2848 self.que_logger.debug(self.next_message())
2849 self.assertRaises(queue.Empty, self.queue.get_nowait)
2850 self.que_logger.info(self.next_message())
2851 self.assertRaises(queue.Empty, self.queue.get_nowait)
2852 msg = self.next_message()
2853 self.que_logger.warning(msg)
2854 data = self.queue.get_nowait()
2855 self.assertTrue(isinstance(data, logging.LogRecord))
2856 self.assertEqual(data.name, self.que_logger.name)
2857 self.assertEqual((data.msg, data.args), (msg, None))
2858
Victor Stinnercafa2ef2011-05-02 16:11:28 +02002859 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
2860 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01002861 def test_queue_listener(self):
2862 handler = TestHandler(Matcher())
2863 listener = logging.handlers.QueueListener(self.queue, handler)
2864 listener.start()
2865 try:
2866 self.que_logger.warning(self.next_message())
2867 self.que_logger.error(self.next_message())
2868 self.que_logger.critical(self.next_message())
2869 finally:
2870 listener.stop()
2871 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
2872 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
2873 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
2874
Vinay Sajip37eb3382011-04-26 20:26:41 +01002875ZERO = datetime.timedelta(0)
2876
2877class UTC(datetime.tzinfo):
2878 def utcoffset(self, dt):
2879 return ZERO
2880
2881 dst = utcoffset
2882
2883 def tzname(self, dt):
2884 return 'UTC'
2885
2886utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01002887
Vinay Sajipa39c5712010-10-25 13:57:39 +00002888class FormatterTest(unittest.TestCase):
2889 def setUp(self):
2890 self.common = {
2891 'name': 'formatter.test',
2892 'level': logging.DEBUG,
2893 'pathname': os.path.join('path', 'to', 'dummy.ext'),
2894 'lineno': 42,
2895 'exc_info': None,
2896 'func': None,
2897 'msg': 'Message with %d %s',
2898 'args': (2, 'placeholders'),
2899 }
2900 self.variants = {
2901 }
2902
2903 def get_record(self, name=None):
2904 result = dict(self.common)
2905 if name is not None:
2906 result.update(self.variants[name])
2907 return logging.makeLogRecord(result)
2908
2909 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002910 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002911 r = self.get_record()
2912 f = logging.Formatter('${%(message)s}')
2913 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
2914 f = logging.Formatter('%(random)s')
2915 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002916 self.assertFalse(f.usesTime())
2917 f = logging.Formatter('%(asctime)s')
2918 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002919 f = logging.Formatter('%(asctime)-15s')
2920 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002921 f = logging.Formatter('asctime')
2922 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002923
2924 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002925 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002926 r = self.get_record()
2927 f = logging.Formatter('$%{message}%$', style='{')
2928 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2929 f = logging.Formatter('{random}', style='{')
2930 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002931 self.assertFalse(f.usesTime())
2932 f = logging.Formatter('{asctime}', style='{')
2933 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002934 f = logging.Formatter('{asctime!s:15}', style='{')
2935 self.assertTrue(f.usesTime())
2936 f = logging.Formatter('{asctime:15}', style='{')
2937 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002938 f = logging.Formatter('asctime', style='{')
2939 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002940
2941 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002942 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002943 r = self.get_record()
2944 f = logging.Formatter('$message', style='$')
2945 self.assertEqual(f.format(r), 'Message with 2 placeholders')
2946 f = logging.Formatter('$$%${message}%$$', style='$')
2947 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2948 f = logging.Formatter('${random}', style='$')
2949 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002950 self.assertFalse(f.usesTime())
2951 f = logging.Formatter('${asctime}', style='$')
2952 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002953 f = logging.Formatter('${asctime', style='$')
2954 self.assertFalse(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002955 f = logging.Formatter('$asctime', style='$')
2956 self.assertTrue(f.usesTime())
2957 f = logging.Formatter('asctime', style='$')
2958 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002959
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002960 def test_invalid_style(self):
2961 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
2962
Vinay Sajip86a96ce2011-04-27 08:30:30 +01002963 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002964 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01002965 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
2966 # We use None to indicate we want the local timezone
2967 # We're essentially converting a UTC time to local time
2968 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002969 r.msecs = 123
2970 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01002971 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002972 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
2973 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01002974 f.format(r)
2975 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
2976
2977class TestBufferingFormatter(logging.BufferingFormatter):
2978 def formatHeader(self, records):
2979 return '[(%d)' % len(records)
2980
2981 def formatFooter(self, records):
2982 return '(%d)]' % len(records)
2983
2984class BufferingFormatterTest(unittest.TestCase):
2985 def setUp(self):
2986 self.records = [
2987 logging.makeLogRecord({'msg': 'one'}),
2988 logging.makeLogRecord({'msg': 'two'}),
2989 ]
2990
2991 def test_default(self):
2992 f = logging.BufferingFormatter()
2993 self.assertEqual('', f.format([]))
2994 self.assertEqual('onetwo', f.format(self.records))
2995
2996 def test_custom(self):
2997 f = TestBufferingFormatter()
2998 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
2999 lf = logging.Formatter('<%(message)s>')
3000 f = TestBufferingFormatter(lf)
3001 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003002
3003class ExceptionTest(BaseTest):
3004 def test_formatting(self):
3005 r = self.root_logger
3006 h = RecordingHandler()
3007 r.addHandler(h)
3008 try:
3009 raise RuntimeError('deliberate mistake')
3010 except:
3011 logging.exception('failed', stack_info=True)
3012 r.removeHandler(h)
3013 h.close()
3014 r = h.records[0]
3015 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
3016 'call last):\n'))
3017 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
3018 'deliberate mistake'))
3019 self.assertTrue(r.stack_info.startswith('Stack (most recent '
3020 'call last):\n'))
3021 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
3022 'stack_info=True)'))
3023
3024
Vinay Sajip5a27d402010-12-10 11:42:57 +00003025class LastResortTest(BaseTest):
3026 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003027 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00003028 root = self.root_logger
3029 root.removeHandler(self.root_hdlr)
3030 old_stderr = sys.stderr
3031 old_lastresort = logging.lastResort
3032 old_raise_exceptions = logging.raiseExceptions
3033 try:
3034 sys.stderr = sio = io.StringIO()
Vinay Sajip8188f582011-07-25 19:58:13 +01003035 root.debug('This should not appear')
3036 self.assertEqual(sio.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00003037 root.warning('This is your final chance!')
3038 self.assertEqual(sio.getvalue(), 'This is your final chance!\n')
3039 #No handlers and no last resort, so 'No handlers' message
3040 logging.lastResort = None
3041 sys.stderr = sio = io.StringIO()
3042 root.warning('This is your final chance!')
3043 self.assertEqual(sio.getvalue(), 'No handlers could be found for logger "root"\n')
3044 # 'No handlers' message only printed once
3045 sys.stderr = sio = io.StringIO()
3046 root.warning('This is your final chance!')
3047 self.assertEqual(sio.getvalue(), '')
3048 root.manager.emittedNoHandlerWarning = False
3049 #If raiseExceptions is False, no message is printed
3050 logging.raiseExceptions = False
3051 sys.stderr = sio = io.StringIO()
3052 root.warning('This is your final chance!')
3053 self.assertEqual(sio.getvalue(), '')
3054 finally:
3055 sys.stderr = old_stderr
3056 root.addHandler(self.root_hdlr)
3057 logging.lastResort = old_lastresort
3058 logging.raiseExceptions = old_raise_exceptions
3059
3060
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003061class FakeHandler:
3062
3063 def __init__(self, identifier, called):
3064 for method in ('acquire', 'flush', 'close', 'release'):
3065 setattr(self, method, self.record_call(identifier, method, called))
3066
3067 def record_call(self, identifier, method_name, called):
3068 def inner():
3069 called.append('{} - {}'.format(identifier, method_name))
3070 return inner
3071
3072
3073class RecordingHandler(logging.NullHandler):
3074
3075 def __init__(self, *args, **kwargs):
3076 super(RecordingHandler, self).__init__(*args, **kwargs)
3077 self.records = []
3078
3079 def handle(self, record):
3080 """Keep track of all the emitted records."""
3081 self.records.append(record)
3082
3083
3084class ShutdownTest(BaseTest):
3085
Vinay Sajip5e66b162011-04-20 15:41:14 +01003086 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003087
3088 def setUp(self):
3089 super(ShutdownTest, self).setUp()
3090 self.called = []
3091
3092 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003093 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003094
3095 def raise_error(self, error):
3096 def inner():
3097 raise error()
3098 return inner
3099
3100 def test_no_failure(self):
3101 # create some fake handlers
3102 handler0 = FakeHandler(0, self.called)
3103 handler1 = FakeHandler(1, self.called)
3104 handler2 = FakeHandler(2, self.called)
3105
3106 # create live weakref to those handlers
3107 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
3108
3109 logging.shutdown(handlerList=list(handlers))
3110
3111 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
3112 '1 - acquire', '1 - flush', '1 - close', '1 - release',
3113 '0 - acquire', '0 - flush', '0 - close', '0 - release']
3114 self.assertEqual(expected, self.called)
3115
3116 def _test_with_failure_in_method(self, method, error):
3117 handler = FakeHandler(0, self.called)
3118 setattr(handler, method, self.raise_error(error))
3119 handlers = [logging.weakref.ref(handler)]
3120
3121 logging.shutdown(handlerList=list(handlers))
3122
3123 self.assertEqual('0 - release', self.called[-1])
3124
3125 def test_with_ioerror_in_acquire(self):
3126 self._test_with_failure_in_method('acquire', IOError)
3127
3128 def test_with_ioerror_in_flush(self):
3129 self._test_with_failure_in_method('flush', IOError)
3130
3131 def test_with_ioerror_in_close(self):
3132 self._test_with_failure_in_method('close', IOError)
3133
3134 def test_with_valueerror_in_acquire(self):
3135 self._test_with_failure_in_method('acquire', ValueError)
3136
3137 def test_with_valueerror_in_flush(self):
3138 self._test_with_failure_in_method('flush', ValueError)
3139
3140 def test_with_valueerror_in_close(self):
3141 self._test_with_failure_in_method('close', ValueError)
3142
3143 def test_with_other_error_in_acquire_without_raise(self):
3144 logging.raiseExceptions = False
3145 self._test_with_failure_in_method('acquire', IndexError)
3146
3147 def test_with_other_error_in_flush_without_raise(self):
3148 logging.raiseExceptions = False
3149 self._test_with_failure_in_method('flush', IndexError)
3150
3151 def test_with_other_error_in_close_without_raise(self):
3152 logging.raiseExceptions = False
3153 self._test_with_failure_in_method('close', IndexError)
3154
3155 def test_with_other_error_in_acquire_with_raise(self):
3156 logging.raiseExceptions = True
3157 self.assertRaises(IndexError, self._test_with_failure_in_method,
3158 'acquire', IndexError)
3159
3160 def test_with_other_error_in_flush_with_raise(self):
3161 logging.raiseExceptions = True
3162 self.assertRaises(IndexError, self._test_with_failure_in_method,
3163 'flush', IndexError)
3164
3165 def test_with_other_error_in_close_with_raise(self):
3166 logging.raiseExceptions = True
3167 self.assertRaises(IndexError, self._test_with_failure_in_method,
3168 'close', IndexError)
3169
3170
3171class ModuleLevelMiscTest(BaseTest):
3172
Vinay Sajip5e66b162011-04-20 15:41:14 +01003173 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003174
3175 def test_disable(self):
3176 old_disable = logging.root.manager.disable
3177 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003178 self.assertEqual(old_disable, 0)
3179 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003180
3181 logging.disable(83)
3182 self.assertEqual(logging.root.manager.disable, 83)
3183
3184 def _test_log(self, method, level=None):
3185 called = []
3186 patch(self, logging, 'basicConfig',
Vinay Sajip00bdbe12011-04-22 00:17:46 +01003187 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003188
3189 recording = RecordingHandler()
3190 logging.root.addHandler(recording)
3191
3192 log_method = getattr(logging, method)
3193 if level is not None:
3194 log_method(level, "test me: %r", recording)
3195 else:
3196 log_method("test me: %r", recording)
3197
3198 self.assertEqual(len(recording.records), 1)
3199 record = recording.records[0]
3200 self.assertEqual(record.getMessage(), "test me: %r" % recording)
3201
3202 expected_level = level if level is not None else getattr(logging, method.upper())
3203 self.assertEqual(record.levelno, expected_level)
3204
3205 # basicConfig was not called!
3206 self.assertEqual(called, [])
3207
3208 def test_log(self):
3209 self._test_log('log', logging.ERROR)
3210
3211 def test_debug(self):
3212 self._test_log('debug')
3213
3214 def test_info(self):
3215 self._test_log('info')
3216
3217 def test_warning(self):
3218 self._test_log('warning')
3219
3220 def test_error(self):
3221 self._test_log('error')
3222
3223 def test_critical(self):
3224 self._test_log('critical')
3225
3226 def test_set_logger_class(self):
3227 self.assertRaises(TypeError, logging.setLoggerClass, object)
3228
3229 class MyLogger(logging.Logger):
3230 pass
3231
3232 logging.setLoggerClass(MyLogger)
3233 self.assertEqual(logging.getLoggerClass(), MyLogger)
3234
3235 logging.setLoggerClass(logging.Logger)
3236 self.assertEqual(logging.getLoggerClass(), logging.Logger)
3237
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003238class LogRecordTest(BaseTest):
3239 def test_str_rep(self):
3240 r = logging.makeLogRecord({})
3241 s = str(r)
3242 self.assertTrue(s.startswith('<LogRecord: '))
3243 self.assertTrue(s.endswith('>'))
3244
3245 def test_dict_arg(self):
3246 h = RecordingHandler()
3247 r = logging.getLogger()
3248 r.addHandler(h)
3249 d = {'less' : 'more' }
3250 logging.warning('less is %(less)s', d)
3251 self.assertIs(h.records[0].args, d)
3252 self.assertEqual(h.records[0].message, 'less is more')
3253 r.removeHandler(h)
3254 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003255
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003256 def test_multiprocessing(self):
3257 r = logging.makeLogRecord({})
3258 self.assertEqual(r.processName, 'MainProcess')
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003259 try:
3260 import multiprocessing as mp
3261 r = logging.makeLogRecord({})
3262 self.assertEqual(r.processName, mp.current_process().name)
3263 except ImportError:
3264 pass
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003265
3266 def test_optional(self):
3267 r = logging.makeLogRecord({})
3268 NOT_NONE = self.assertIsNotNone
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003269 if threading:
3270 NOT_NONE(r.thread)
3271 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003272 NOT_NONE(r.process)
3273 NOT_NONE(r.processName)
3274 log_threads = logging.logThreads
3275 log_processes = logging.logProcesses
3276 log_multiprocessing = logging.logMultiprocessing
3277 try:
3278 logging.logThreads = False
3279 logging.logProcesses = False
3280 logging.logMultiprocessing = False
3281 r = logging.makeLogRecord({})
3282 NONE = self.assertIsNone
3283 NONE(r.thread)
3284 NONE(r.threadName)
3285 NONE(r.process)
3286 NONE(r.processName)
3287 finally:
3288 logging.logThreads = log_threads
3289 logging.logProcesses = log_processes
3290 logging.logMultiprocessing = log_multiprocessing
3291
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003292class BasicConfigTest(unittest.TestCase):
3293
Vinay Sajip95bf5042011-04-20 11:50:56 +01003294 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003295
3296 def setUp(self):
3297 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01003298 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01003299 self.saved_handlers = logging._handlers.copy()
3300 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003301 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003302 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003303 logging.root.handlers = []
3304
3305 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01003306 for h in logging.root.handlers[:]:
3307 logging.root.removeHandler(h)
3308 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003309 super(BasicConfigTest, self).tearDown()
3310
Vinay Sajip3def7e02011-04-20 10:58:06 +01003311 def cleanup(self):
3312 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01003313 logging._handlers.clear()
3314 logging._handlers.update(self.saved_handlers)
3315 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003316 logging.root.level = self.original_logging_level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003317
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003318 def test_no_kwargs(self):
3319 logging.basicConfig()
3320
3321 # handler defaults to a StreamHandler to sys.stderr
3322 self.assertEqual(len(logging.root.handlers), 1)
3323 handler = logging.root.handlers[0]
3324 self.assertIsInstance(handler, logging.StreamHandler)
3325 self.assertEqual(handler.stream, sys.stderr)
3326
3327 formatter = handler.formatter
3328 # format defaults to logging.BASIC_FORMAT
3329 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
3330 # datefmt defaults to None
3331 self.assertIsNone(formatter.datefmt)
3332 # style defaults to %
3333 self.assertIsInstance(formatter._style, logging.PercentStyle)
3334
Florent Xiclunae41f0de2011-11-11 19:39:25 +01003335 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01003336 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003337
Vinay Sajip1fd12022014-01-13 21:59:56 +00003338 def test_strformatstyle(self):
3339 with captured_stdout() as output:
3340 logging.basicConfig(stream=sys.stdout, style="{")
3341 logging.error("Log an error")
3342 sys.stdout.seek(0)
3343 self.assertEqual(output.getvalue().strip(),
3344 "ERROR:root:Log an error")
3345
3346 def test_stringtemplatestyle(self):
3347 with captured_stdout() as output:
3348 logging.basicConfig(stream=sys.stdout, style="$")
3349 logging.error("Log an error")
3350 sys.stdout.seek(0)
3351 self.assertEqual(output.getvalue().strip(),
3352 "ERROR:root:Log an error")
3353
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003354 def test_filename(self):
3355 logging.basicConfig(filename='test.log')
3356
3357 self.assertEqual(len(logging.root.handlers), 1)
3358 handler = logging.root.handlers[0]
3359 self.assertIsInstance(handler, logging.FileHandler)
3360
3361 expected = logging.FileHandler('test.log', 'a')
3362 self.addCleanup(expected.close)
3363 self.assertEqual(handler.stream.mode, expected.stream.mode)
3364 self.assertEqual(handler.stream.name, expected.stream.name)
3365
3366 def test_filemode(self):
3367 logging.basicConfig(filename='test.log', filemode='wb')
3368
3369 handler = logging.root.handlers[0]
3370 expected = logging.FileHandler('test.log', 'wb')
3371 self.addCleanup(expected.close)
3372 self.assertEqual(handler.stream.mode, expected.stream.mode)
3373
3374 def test_stream(self):
3375 stream = io.StringIO()
3376 self.addCleanup(stream.close)
3377 logging.basicConfig(stream=stream)
3378
3379 self.assertEqual(len(logging.root.handlers), 1)
3380 handler = logging.root.handlers[0]
3381 self.assertIsInstance(handler, logging.StreamHandler)
3382 self.assertEqual(handler.stream, stream)
3383
3384 def test_format(self):
3385 logging.basicConfig(format='foo')
3386
3387 formatter = logging.root.handlers[0].formatter
3388 self.assertEqual(formatter._style._fmt, 'foo')
3389
3390 def test_datefmt(self):
3391 logging.basicConfig(datefmt='bar')
3392
3393 formatter = logging.root.handlers[0].formatter
3394 self.assertEqual(formatter.datefmt, 'bar')
3395
3396 def test_style(self):
3397 logging.basicConfig(style='$')
3398
3399 formatter = logging.root.handlers[0].formatter
3400 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
3401
3402 def test_level(self):
3403 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003404 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003405
3406 logging.basicConfig(level=57)
3407 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003408 # Test that second call has no effect
3409 logging.basicConfig(level=58)
3410 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003411
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003412 def test_incompatible(self):
3413 assertRaises = self.assertRaises
3414 handlers = [logging.StreamHandler()]
3415 stream = sys.stderr
3416 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3417 stream=stream)
3418 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3419 handlers=handlers)
3420 assertRaises(ValueError, logging.basicConfig, stream=stream,
3421 handlers=handlers)
3422
3423 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003424 handlers = [
3425 logging.StreamHandler(),
3426 logging.StreamHandler(sys.stdout),
3427 logging.StreamHandler(),
3428 ]
3429 f = logging.Formatter()
3430 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003431 logging.basicConfig(handlers=handlers)
3432 self.assertIs(handlers[0], logging.root.handlers[0])
3433 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003434 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003435 self.assertIsNotNone(handlers[0].formatter)
3436 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003437 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003438 self.assertIs(handlers[0].formatter, handlers[1].formatter)
3439
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003440 def _test_log(self, method, level=None):
3441 # logging.root has no handlers so basicConfig should be called
3442 called = []
3443
3444 old_basic_config = logging.basicConfig
3445 def my_basic_config(*a, **kw):
3446 old_basic_config()
3447 old_level = logging.root.level
3448 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003449 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003450 called.append((a, kw))
3451
3452 patch(self, logging, 'basicConfig', my_basic_config)
3453
3454 log_method = getattr(logging, method)
3455 if level is not None:
3456 log_method(level, "test me")
3457 else:
3458 log_method("test me")
3459
3460 # basicConfig was called with no arguments
3461 self.assertEqual(called, [((), {})])
3462
3463 def test_log(self):
3464 self._test_log('log', logging.WARNING)
3465
3466 def test_debug(self):
3467 self._test_log('debug')
3468
3469 def test_info(self):
3470 self._test_log('info')
3471
3472 def test_warning(self):
3473 self._test_log('warning')
3474
3475 def test_error(self):
3476 self._test_log('error')
3477
3478 def test_critical(self):
3479 self._test_log('critical')
3480
3481
3482class LoggerAdapterTest(unittest.TestCase):
3483
3484 def setUp(self):
3485 super(LoggerAdapterTest, self).setUp()
3486 old_handler_list = logging._handlerList[:]
3487
3488 self.recording = RecordingHandler()
3489 self.logger = logging.root
3490 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003491 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003492 self.addCleanup(self.recording.close)
3493
3494 def cleanup():
3495 logging._handlerList[:] = old_handler_list
3496
3497 self.addCleanup(cleanup)
3498 self.addCleanup(logging.shutdown)
3499 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
3500
3501 def test_exception(self):
3502 msg = 'testing exception: %r'
3503 exc = None
3504 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003505 1 / 0
3506 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003507 exc = e
3508 self.adapter.exception(msg, self.recording)
3509
3510 self.assertEqual(len(self.recording.records), 1)
3511 record = self.recording.records[0]
3512 self.assertEqual(record.levelno, logging.ERROR)
3513 self.assertEqual(record.msg, msg)
3514 self.assertEqual(record.args, (self.recording,))
3515 self.assertEqual(record.exc_info,
3516 (exc.__class__, exc, exc.__traceback__))
3517
3518 def test_critical(self):
3519 msg = 'critical test! %r'
3520 self.adapter.critical(msg, self.recording)
3521
3522 self.assertEqual(len(self.recording.records), 1)
3523 record = self.recording.records[0]
3524 self.assertEqual(record.levelno, logging.CRITICAL)
3525 self.assertEqual(record.msg, msg)
3526 self.assertEqual(record.args, (self.recording,))
3527
3528 def test_is_enabled_for(self):
3529 old_disable = self.adapter.logger.manager.disable
3530 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003531 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
3532 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003533 self.assertFalse(self.adapter.isEnabledFor(32))
3534
3535 def test_has_handlers(self):
3536 self.assertTrue(self.adapter.hasHandlers())
3537
3538 for handler in self.logger.handlers:
3539 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003540
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003541 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003542 self.assertFalse(self.adapter.hasHandlers())
3543
3544
3545class LoggerTest(BaseTest):
3546
3547 def setUp(self):
3548 super(LoggerTest, self).setUp()
3549 self.recording = RecordingHandler()
3550 self.logger = logging.Logger(name='blah')
3551 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003552 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003553 self.addCleanup(self.recording.close)
3554 self.addCleanup(logging.shutdown)
3555
3556 def test_set_invalid_level(self):
3557 self.assertRaises(TypeError, self.logger.setLevel, object())
3558
3559 def test_exception(self):
3560 msg = 'testing exception: %r'
3561 exc = None
3562 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003563 1 / 0
3564 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003565 exc = e
3566 self.logger.exception(msg, self.recording)
3567
3568 self.assertEqual(len(self.recording.records), 1)
3569 record = self.recording.records[0]
3570 self.assertEqual(record.levelno, logging.ERROR)
3571 self.assertEqual(record.msg, msg)
3572 self.assertEqual(record.args, (self.recording,))
3573 self.assertEqual(record.exc_info,
3574 (exc.__class__, exc, exc.__traceback__))
3575
3576 def test_log_invalid_level_with_raise(self):
3577 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003578 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003579
3580 logging.raiseExceptions = True
3581 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
3582
3583 def test_log_invalid_level_no_raise(self):
3584 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003585 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003586
3587 logging.raiseExceptions = False
3588 self.logger.log('10', 'test message') # no exception happens
3589
3590 def test_find_caller_with_stack_info(self):
3591 called = []
3592 patch(self, logging.traceback, 'print_stack',
3593 lambda f, file: called.append(file.getvalue()))
3594
3595 self.logger.findCaller(stack_info=True)
3596
3597 self.assertEqual(len(called), 1)
3598 self.assertEqual('Stack (most recent call last):\n', called[0])
3599
3600 def test_make_record_with_extra_overwrite(self):
3601 name = 'my record'
3602 level = 13
3603 fn = lno = msg = args = exc_info = func = sinfo = None
3604 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
3605 exc_info, func, sinfo)
3606
3607 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
3608 extra = {key: 'some value'}
3609 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
3610 fn, lno, msg, args, exc_info,
3611 extra=extra, sinfo=sinfo)
3612
3613 def test_make_record_with_extra_no_overwrite(self):
3614 name = 'my record'
3615 level = 13
3616 fn = lno = msg = args = exc_info = func = sinfo = None
3617 extra = {'valid_key': 'some value'}
3618 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
3619 exc_info, extra=extra, sinfo=sinfo)
3620 self.assertIn('valid_key', result.__dict__)
3621
3622 def test_has_handlers(self):
3623 self.assertTrue(self.logger.hasHandlers())
3624
3625 for handler in self.logger.handlers:
3626 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003627 self.assertFalse(self.logger.hasHandlers())
3628
3629 def test_has_handlers_no_propagate(self):
3630 child_logger = logging.getLogger('blah.child')
3631 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003632 self.assertFalse(child_logger.hasHandlers())
3633
3634 def test_is_enabled_for(self):
3635 old_disable = self.logger.manager.disable
3636 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003637 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003638 self.assertFalse(self.logger.isEnabledFor(22))
3639
Florent Xicluna5252f9f2011-11-07 19:43:05 +01003640 def test_root_logger_aliases(self):
3641 root = logging.getLogger()
3642 self.assertIs(root, logging.root)
3643 self.assertIs(root, logging.getLogger(None))
3644 self.assertIs(root, logging.getLogger(''))
3645 self.assertIs(root, logging.getLogger('foo').root)
3646 self.assertIs(root, logging.getLogger('foo.bar').root)
3647 self.assertIs(root, logging.getLogger('foo').parent)
3648
3649 self.assertIsNot(root, logging.getLogger('\0'))
3650 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
3651
3652 def test_invalid_names(self):
3653 self.assertRaises(TypeError, logging.getLogger, any)
3654 self.assertRaises(TypeError, logging.getLogger, b'foo')
3655
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003656
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003657class BaseFileTest(BaseTest):
3658 "Base class for handler tests that write log files"
3659
3660 def setUp(self):
3661 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003662 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
3663 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003664 self.rmfiles = []
3665
3666 def tearDown(self):
3667 for fn in self.rmfiles:
3668 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003669 if os.path.exists(self.fn):
3670 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00003671 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003672
3673 def assertLogFile(self, filename):
3674 "Assert a log file is there and register it for deletion"
3675 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01003676 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003677 self.rmfiles.append(filename)
3678
3679
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003680class FileHandlerTest(BaseFileTest):
3681 def test_delay(self):
3682 os.unlink(self.fn)
3683 fh = logging.FileHandler(self.fn, delay=True)
3684 self.assertIsNone(fh.stream)
3685 self.assertFalse(os.path.exists(self.fn))
3686 fh.handle(logging.makeLogRecord({}))
3687 self.assertIsNotNone(fh.stream)
3688 self.assertTrue(os.path.exists(self.fn))
3689 fh.close()
3690
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003691class RotatingFileHandlerTest(BaseFileTest):
3692 def next_rec(self):
3693 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
3694 self.next_message(), None, None, None)
3695
3696 def test_should_not_rollover(self):
3697 # If maxbytes is zero rollover never occurs
3698 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
3699 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00003700 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003701
3702 def test_should_rollover(self):
3703 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
3704 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00003705 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003706
3707 def test_file_created(self):
3708 # checks that the file is created and assumes it was created
3709 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003710 rh = logging.handlers.RotatingFileHandler(self.fn)
3711 rh.emit(self.next_rec())
3712 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00003713 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003714
3715 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00003716 def namer(name):
3717 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003718 rh = logging.handlers.RotatingFileHandler(
3719 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003720 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003721 rh.emit(self.next_rec())
3722 self.assertLogFile(self.fn)
3723 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003724 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003725 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003726 self.assertLogFile(namer(self.fn + ".2"))
3727 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
3728 rh.close()
3729
Eric V. Smith851cad72012-03-11 22:46:04 -07003730 @requires_zlib
Vinay Sajip23b94d02012-01-04 12:02:26 +00003731 def test_rotator(self):
3732 def namer(name):
3733 return name + ".gz"
3734
3735 def rotator(source, dest):
3736 with open(source, "rb") as sf:
3737 data = sf.read()
3738 compressed = zlib.compress(data, 9)
3739 with open(dest, "wb") as df:
3740 df.write(compressed)
3741 os.remove(source)
3742
3743 rh = logging.handlers.RotatingFileHandler(
3744 self.fn, backupCount=2, maxBytes=1)
3745 rh.rotator = rotator
3746 rh.namer = namer
3747 m1 = self.next_rec()
3748 rh.emit(m1)
3749 self.assertLogFile(self.fn)
3750 m2 = self.next_rec()
3751 rh.emit(m2)
3752 fn = namer(self.fn + ".1")
3753 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003754 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00003755 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"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003759 rh.emit(self.next_rec())
3760 fn = namer(self.fn + ".2")
3761 self.assertLogFile(fn)
3762 with open(fn, "rb") as f:
3763 compressed = f.read()
3764 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003765 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003766 rh.emit(self.next_rec())
3767 fn = namer(self.fn + ".2")
3768 with open(fn, "rb") as f:
3769 compressed = f.read()
3770 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003771 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003772 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00003773 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003774
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003775class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01003776 # other test methods added below
3777 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01003778 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
3779 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00003780 fmt = logging.Formatter('%(asctime)s %(message)s')
3781 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003782 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003783 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01003784 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003785 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00003786 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003787 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01003788 fh.close()
3789 # At this point, we should have a recent rotated file which we
3790 # can test for the existence of. However, in practice, on some
3791 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01003792 # in time to go to look for the log file. So, we go back a fair
3793 # bit, and stop as soon as we see a rotated file. In theory this
3794 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01003795 found = False
3796 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01003797 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01003798 for secs in range(GO_BACK):
3799 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01003800 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
3801 found = os.path.exists(fn)
3802 if found:
3803 self.rmfiles.append(fn)
3804 break
Vinay Sajip672c5812011-05-13 07:09:40 +01003805 msg = 'No rotated files found, went back %d seconds' % GO_BACK
3806 if not found:
3807 #print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01003808 dn, fn = os.path.split(self.fn)
3809 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02003810 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
3811 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00003812 for f in files:
3813 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00003814 path = os.path.join(dn, f)
3815 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00003816 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01003817 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003818
Vinay Sajip0372e102011-05-05 12:59:14 +01003819 def test_invalid(self):
3820 assertRaises = self.assertRaises
3821 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003822 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003823 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003824 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003825 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003826 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003827
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003828def secs(**kw):
3829 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
3830
3831for when, exp in (('S', 1),
3832 ('M', 60),
3833 ('H', 60 * 60),
3834 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00003835 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003836 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00003837 ('W0', secs(days=4, hours=24)),
3838 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003839 def test_compute_rollover(self, when=when, exp=exp):
3840 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00003841 self.fn, when=when, interval=1, backupCount=0, utc=True)
3842 currentTime = 0.0
3843 actual = rh.computeRollover(currentTime)
3844 if exp != actual:
3845 # Failures occur on some systems for MIDNIGHT and W0.
3846 # Print detailed calculation for MIDNIGHT so we can try to see
3847 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00003848 if when == 'MIDNIGHT':
3849 try:
3850 if rh.utc:
3851 t = time.gmtime(currentTime)
3852 else:
3853 t = time.localtime(currentTime)
3854 currentHour = t[3]
3855 currentMinute = t[4]
3856 currentSecond = t[5]
3857 # r is the number of seconds left between now and midnight
3858 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
3859 currentMinute) * 60 +
3860 currentSecond)
3861 result = currentTime + r
3862 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
3863 print('currentHour: %s' % currentHour, file=sys.stderr)
3864 print('currentMinute: %s' % currentMinute, file=sys.stderr)
3865 print('currentSecond: %s' % currentSecond, file=sys.stderr)
3866 print('r: %s' % r, file=sys.stderr)
3867 print('result: %s' % result, file=sys.stderr)
3868 except Exception:
3869 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
3870 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00003871 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003872 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
3873
Vinay Sajip60ccd822011-05-09 17:32:09 +01003874
3875@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil required for this test.')
3876class NTEventLogHandlerTest(BaseTest):
3877 def test_basic(self):
3878 logtype = 'Application'
3879 elh = win32evtlog.OpenEventLog(None, logtype)
3880 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
3881 h = logging.handlers.NTEventLogHandler('test_logging')
3882 r = logging.makeLogRecord({'msg': 'Test Log Message'})
3883 h.handle(r)
3884 h.close()
3885 # Now see if the event is recorded
3886 self.assertTrue(num_recs < win32evtlog.GetNumberOfEventLogRecords(elh))
3887 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
3888 win32evtlog.EVENTLOG_SEQUENTIAL_READ
3889 found = False
3890 GO_BACK = 100
3891 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
3892 for e in events:
3893 if e.SourceName != 'test_logging':
3894 continue
3895 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
3896 if msg != 'Test Log Message\r\n':
3897 continue
3898 found = True
3899 break
3900 msg = 'Record not found in event log, went back %d records' % GO_BACK
3901 self.assertTrue(found, msg=msg)
3902
Christian Heimes180510d2008-03-03 19:15:45 +00003903# Set the locale to the platform-dependent default. I have no idea
3904# why the test does this, but in any case we save the current locale
3905# first and restore it at the end.
3906@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00003907def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +00003908 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003909 CustomLevelsAndFiltersTest, HandlerTest, MemoryHandlerTest,
Vinay Sajip7367d082011-05-02 13:17:27 +01003910 ConfigFileTest, SocketHandlerTest, DatagramHandlerTest,
3911 MemoryTest, EncodingTest, WarningsTest, ConfigDictTest,
3912 ManagerTest, FormatterTest, BufferingFormatterTest,
3913 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
3914 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest,
3915 BasicConfigTest, LoggerAdapterTest, LoggerTest,
3916 SMTPHandlerTest, FileHandlerTest, RotatingFileHandlerTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003917 LastResortTest, LogRecordTest, ExceptionTest,
Vinay Sajip60ccd822011-05-09 17:32:09 +01003918 SysLogHandlerTest, HTTPHandlerTest, NTEventLogHandlerTest,
Vinay Sajip89807a52011-02-26 16:06:02 +00003919 TimedRotatingFileHandlerTest
Vinay Sajipbc85d842010-09-17 23:35:29 +00003920 )
Jeremy Hylton096d9862003-07-18 03:19:20 +00003921
Christian Heimes180510d2008-03-03 19:15:45 +00003922if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00003923 test_main()