blob: 92514533d959ea8f5b26fda9740948fd8b3aa700 [file] [log] [blame]
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001#!/usr/bin/env python
Christian Heimes180510d2008-03-03 19:15:45 +00002#
Vinay Sajip66b8b082012-04-24 23:25:30 +01003# Copyright 2001-2012 by Vinay Sajip. All Rights Reserved.
Christian Heimes180510d2008-03-03 19:15:45 +00004#
5# Permission to use, copy, modify, and distribute this software and its
6# documentation for any purpose and without fee is hereby granted,
7# provided that the above copyright notice appear in all copies and that
8# both that copyright notice and this permission notice appear in
9# supporting documentation, and that the name of Vinay Sajip
10# not be used in advertising or publicity pertaining to distribution
11# of the software without specific, written prior permission.
12# VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING
13# ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
14# VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR
15# ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER
16# IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
17# OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
18
19"""Test harness for the logging module. Run all tests.
20
Vinay Sajip66b8b082012-04-24 23:25:30 +010021Copyright (C) 2001-2012 Vinay Sajip. All Rights Reserved.
Neal Norwitzb4a2df02003-01-02 14:56:39 +000022"""
23
Christian Heimes180510d2008-03-03 19:15:45 +000024import logging
25import logging.handlers
26import logging.config
Christian Heimes18c66892008-02-17 13:31:39 +000027
Benjamin Petersonf91df042009-02-13 02:50:59 +000028import codecs
Vinay Sajipcf9e2f22012-10-09 09:06:03 +010029import configparser
Vinay Sajip19ec67a2010-09-17 18:57:36 +000030import datetime
Christian Heimes180510d2008-03-03 19:15:45 +000031import pickle
32import io
33import gc
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000034import json
Christian Heimes180510d2008-03-03 19:15:45 +000035import os
Vinay Sajip8552d1f2010-09-14 09:34:09 +000036import queue
Vinay Sajip66b8b082012-04-24 23:25:30 +010037import random
Christian Heimes180510d2008-03-03 19:15:45 +000038import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000039import select
Christian Heimes180510d2008-03-03 19:15:45 +000040import socket
Christian Heimes180510d2008-03-03 19:15:45 +000041import struct
42import sys
43import tempfile
Eric V. Smith851cad72012-03-11 22:46:04 -070044from test.support import (captured_stdout, run_with_locale, run_unittest,
45 patch, requires_zlib, TestHandler, Matcher)
Christian Heimes180510d2008-03-03 19:15:45 +000046import textwrap
Vinay Sajip37eb3382011-04-26 20:26:41 +010047import time
Christian Heimes180510d2008-03-03 19:15:45 +000048import unittest
Georg Brandlf9734072008-12-07 15:30:06 +000049import warnings
Christian Heimes180510d2008-03-03 19:15:45 +000050import weakref
Victor Stinner45df8202010-04-28 22:31:17 +000051try:
52 import threading
Vinay Sajipce7c9782011-05-17 07:15:53 +010053 # The following imports are needed only for tests which
Florent Xicluna5252f9f2011-11-07 19:43:05 +010054 # require threading
Vinay Sajipce7c9782011-05-17 07:15:53 +010055 import asynchat
56 import asyncore
57 import errno
58 from http.server import HTTPServer, BaseHTTPRequestHandler
59 import smtpd
60 from urllib.parse import urlparse, parse_qs
61 from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
62 ThreadingTCPServer, StreamRequestHandler)
Victor Stinner45df8202010-04-28 22:31:17 +000063except ImportError:
64 threading = None
Vinay Sajip60ccd822011-05-09 17:32:09 +010065try:
66 import win32evtlog
67except ImportError:
68 win32evtlog = None
69try:
70 import win32evtlogutil
71except ImportError:
72 win32evtlogutil = None
73 win32evtlog = None
Eric V. Smith851cad72012-03-11 22:46:04 -070074try:
75 import zlib
76except ImportError:
77 pass
Christian Heimes18c66892008-02-17 13:31:39 +000078
79
Christian Heimes180510d2008-03-03 19:15:45 +000080class BaseTest(unittest.TestCase):
81
82 """Base class for logging tests."""
83
84 log_format = "%(name)s -> %(levelname)s: %(message)s"
Ezio Melotti3ffd29b2012-10-02 19:45:00 +030085 expected_log_pat = r"^([\w.]+) -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +000086 message_num = 0
87
88 def setUp(self):
89 """Setup the default logging stream to an internal StringIO instance,
90 so that we can examine log output as we want."""
91 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000092 logging._acquireLock()
93 try:
Christian Heimes180510d2008-03-03 19:15:45 +000094 self.saved_handlers = logging._handlers.copy()
95 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000096 self.saved_loggers = saved_loggers = logger_dict.copy()
Christian Heimes180510d2008-03-03 19:15:45 +000097 self.saved_level_names = logging._levelNames.copy()
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000098 self.logger_states = logger_states = {}
99 for name in saved_loggers:
100 logger_states[name] = getattr(saved_loggers[name],
101 'disabled', None)
Christian Heimes18c66892008-02-17 13:31:39 +0000102 finally:
103 logging._releaseLock()
104
Florent Xicluna5252f9f2011-11-07 19:43:05 +0100105 # Set two unused loggers
Vinay Sajipb4a08092010-09-20 09:55:00 +0000106 self.logger1 = logging.getLogger("\xab\xd7\xbb")
107 self.logger2 = logging.getLogger("\u013f\u00d6\u0047")
Benjamin Peterson22005fc2010-04-11 16:25:06 +0000108
Christian Heimes180510d2008-03-03 19:15:45 +0000109 self.root_logger = logging.getLogger("")
110 self.original_logging_level = self.root_logger.getEffectiveLevel()
111
112 self.stream = io.StringIO()
113 self.root_logger.setLevel(logging.DEBUG)
114 self.root_hdlr = logging.StreamHandler(self.stream)
115 self.root_formatter = logging.Formatter(self.log_format)
116 self.root_hdlr.setFormatter(self.root_formatter)
Vinay Sajip7b0e86e2010-12-30 23:26:50 +0000117 if self.logger1.hasHandlers():
118 hlist = self.logger1.handlers + self.root_logger.handlers
119 raise AssertionError('Unexpected handlers: %s' % hlist)
120 if self.logger2.hasHandlers():
121 hlist = self.logger2.handlers + self.root_logger.handlers
122 raise AssertionError('Unexpected handlers: %s' % hlist)
Christian Heimes180510d2008-03-03 19:15:45 +0000123 self.root_logger.addHandler(self.root_hdlr)
Vinay Sajipb4a08092010-09-20 09:55:00 +0000124 self.assertTrue(self.logger1.hasHandlers())
125 self.assertTrue(self.logger2.hasHandlers())
Christian Heimes180510d2008-03-03 19:15:45 +0000126
127 def tearDown(self):
128 """Remove our logging stream, and restore the original logging
129 level."""
130 self.stream.close()
131 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000132 while self.root_logger.handlers:
133 h = self.root_logger.handlers[0]
134 self.root_logger.removeHandler(h)
135 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +0000136 self.root_logger.setLevel(self.original_logging_level)
137 logging._acquireLock()
138 try:
139 logging._levelNames.clear()
140 logging._levelNames.update(self.saved_level_names)
141 logging._handlers.clear()
142 logging._handlers.update(self.saved_handlers)
143 logging._handlerList[:] = self.saved_handler_list
144 loggerDict = logging.getLogger().manager.loggerDict
145 loggerDict.clear()
146 loggerDict.update(self.saved_loggers)
Vinay Sajip7b60f4e2010-12-27 14:31:52 +0000147 logger_states = self.logger_states
148 for name in self.logger_states:
149 if logger_states[name] is not None:
150 self.saved_loggers[name].disabled = logger_states[name]
Christian Heimes180510d2008-03-03 19:15:45 +0000151 finally:
152 logging._releaseLock()
153
Vinay Sajip4ded5512012-10-02 15:56:16 +0100154 def assert_log_lines(self, expected_values, stream=None, pat=None):
Christian Heimes180510d2008-03-03 19:15:45 +0000155 """Match the collected log lines against the regular expression
156 self.expected_log_pat, and compare the extracted group values to
157 the expected_values list of tuples."""
158 stream = stream or self.stream
Vinay Sajip4ded5512012-10-02 15:56:16 +0100159 pat = re.compile(pat or self.expected_log_pat)
Christian Heimes180510d2008-03-03 19:15:45 +0000160 try:
Vinay Sajip4ded5512012-10-02 15:56:16 +0100161 if hasattr(stream, 'reset'):
162 stream.reset()
163 elif hasattr(stream, 'seek'):
164 stream.seek(0)
Christian Heimes180510d2008-03-03 19:15:45 +0000165 actual_lines = stream.readlines()
166 except AttributeError:
167 # StringIO.StringIO lacks a reset() method.
168 actual_lines = stream.getvalue().splitlines()
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100169 self.assertEqual(len(actual_lines), len(expected_values))
Christian Heimes180510d2008-03-03 19:15:45 +0000170 for actual, expected in zip(actual_lines, expected_values):
171 match = pat.search(actual)
172 if not match:
173 self.fail("Log line does not match expected pattern:\n" +
174 actual)
Ezio Melottib3aedd42010-11-20 19:04:17 +0000175 self.assertEqual(tuple(match.groups()), expected)
Christian Heimes180510d2008-03-03 19:15:45 +0000176 s = stream.read()
177 if s:
178 self.fail("Remaining output at end of log stream:\n" + s)
179
180 def next_message(self):
181 """Generate a message consisting solely of an auto-incrementing
182 integer."""
183 self.message_num += 1
184 return "%d" % self.message_num
185
186
187class BuiltinLevelsTest(BaseTest):
188 """Test builtin levels and their inheritance."""
189
190 def test_flat(self):
191 #Logging levels in a flat logger namespace.
192 m = self.next_message
193
194 ERR = logging.getLogger("ERR")
195 ERR.setLevel(logging.ERROR)
Vinay Sajipc84f0162010-09-21 11:25:39 +0000196 INF = logging.LoggerAdapter(logging.getLogger("INF"), {})
Christian Heimes180510d2008-03-03 19:15:45 +0000197 INF.setLevel(logging.INFO)
198 DEB = logging.getLogger("DEB")
199 DEB.setLevel(logging.DEBUG)
200
201 # These should log.
202 ERR.log(logging.CRITICAL, m())
203 ERR.error(m())
204
205 INF.log(logging.CRITICAL, m())
206 INF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100207 INF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000208 INF.info(m())
209
210 DEB.log(logging.CRITICAL, m())
211 DEB.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100212 DEB.warning(m())
213 DEB.info(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000214 DEB.debug(m())
215
216 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100217 ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000218 ERR.info(m())
219 ERR.debug(m())
220
221 INF.debug(m())
222
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000223 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000224 ('ERR', 'CRITICAL', '1'),
225 ('ERR', 'ERROR', '2'),
226 ('INF', 'CRITICAL', '3'),
227 ('INF', 'ERROR', '4'),
228 ('INF', 'WARNING', '5'),
229 ('INF', 'INFO', '6'),
230 ('DEB', 'CRITICAL', '7'),
231 ('DEB', 'ERROR', '8'),
232 ('DEB', 'WARNING', '9'),
233 ('DEB', 'INFO', '10'),
234 ('DEB', 'DEBUG', '11'),
235 ])
236
237 def test_nested_explicit(self):
238 # Logging levels in a nested namespace, all explicitly set.
239 m = self.next_message
240
241 INF = logging.getLogger("INF")
242 INF.setLevel(logging.INFO)
243 INF_ERR = logging.getLogger("INF.ERR")
244 INF_ERR.setLevel(logging.ERROR)
245
246 # These should log.
247 INF_ERR.log(logging.CRITICAL, m())
248 INF_ERR.error(m())
249
250 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100251 INF_ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000252 INF_ERR.info(m())
253 INF_ERR.debug(m())
254
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000255 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000256 ('INF.ERR', 'CRITICAL', '1'),
257 ('INF.ERR', 'ERROR', '2'),
258 ])
259
260 def test_nested_inherited(self):
261 #Logging levels in a nested namespace, inherited from parent loggers.
262 m = self.next_message
263
264 INF = logging.getLogger("INF")
265 INF.setLevel(logging.INFO)
266 INF_ERR = logging.getLogger("INF.ERR")
267 INF_ERR.setLevel(logging.ERROR)
268 INF_UNDEF = logging.getLogger("INF.UNDEF")
269 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
270 UNDEF = logging.getLogger("UNDEF")
271
272 # These should log.
273 INF_UNDEF.log(logging.CRITICAL, m())
274 INF_UNDEF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100275 INF_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000276 INF_UNDEF.info(m())
277 INF_ERR_UNDEF.log(logging.CRITICAL, m())
278 INF_ERR_UNDEF.error(m())
279
280 # These should not log.
281 INF_UNDEF.debug(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100282 INF_ERR_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000283 INF_ERR_UNDEF.info(m())
284 INF_ERR_UNDEF.debug(m())
285
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000286 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000287 ('INF.UNDEF', 'CRITICAL', '1'),
288 ('INF.UNDEF', 'ERROR', '2'),
289 ('INF.UNDEF', 'WARNING', '3'),
290 ('INF.UNDEF', 'INFO', '4'),
291 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
292 ('INF.ERR.UNDEF', 'ERROR', '6'),
293 ])
294
295 def test_nested_with_virtual_parent(self):
296 # Logging levels when some parent does not exist yet.
297 m = self.next_message
298
299 INF = logging.getLogger("INF")
300 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
301 CHILD = logging.getLogger("INF.BADPARENT")
302 INF.setLevel(logging.INFO)
303
304 # These should log.
305 GRANDCHILD.log(logging.FATAL, m())
306 GRANDCHILD.info(m())
307 CHILD.log(logging.FATAL, m())
308 CHILD.info(m())
309
310 # These should not log.
311 GRANDCHILD.debug(m())
312 CHILD.debug(m())
313
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000314 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000315 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
316 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
317 ('INF.BADPARENT', 'CRITICAL', '3'),
318 ('INF.BADPARENT', 'INFO', '4'),
319 ])
320
321
322class BasicFilterTest(BaseTest):
323
324 """Test the bundled Filter class."""
325
326 def test_filter(self):
327 # Only messages satisfying the specified criteria pass through the
328 # filter.
329 filter_ = logging.Filter("spam.eggs")
330 handler = self.root_logger.handlers[0]
331 try:
332 handler.addFilter(filter_)
333 spam = logging.getLogger("spam")
334 spam_eggs = logging.getLogger("spam.eggs")
335 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
336 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
337
338 spam.info(self.next_message())
339 spam_eggs.info(self.next_message()) # Good.
340 spam_eggs_fish.info(self.next_message()) # Good.
341 spam_bakedbeans.info(self.next_message())
342
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000343 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000344 ('spam.eggs', 'INFO', '2'),
345 ('spam.eggs.fish', 'INFO', '3'),
346 ])
347 finally:
348 handler.removeFilter(filter_)
349
Vinay Sajip6dbed2e2010-10-19 20:53:01 +0000350 def test_callable_filter(self):
351 # Only messages satisfying the specified criteria pass through the
352 # filter.
353
354 def filterfunc(record):
355 parts = record.name.split('.')
356 prefix = '.'.join(parts[:2])
357 return prefix == 'spam.eggs'
358
359 handler = self.root_logger.handlers[0]
360 try:
361 handler.addFilter(filterfunc)
362 spam = logging.getLogger("spam")
363 spam_eggs = logging.getLogger("spam.eggs")
364 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
365 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
366
367 spam.info(self.next_message())
368 spam_eggs.info(self.next_message()) # Good.
369 spam_eggs_fish.info(self.next_message()) # Good.
370 spam_bakedbeans.info(self.next_message())
371
372 self.assert_log_lines([
373 ('spam.eggs', 'INFO', '2'),
374 ('spam.eggs.fish', 'INFO', '3'),
375 ])
376 finally:
377 handler.removeFilter(filterfunc)
378
Vinay Sajip985ef872011-04-26 19:34:04 +0100379 def test_empty_filter(self):
380 f = logging.Filter()
381 r = logging.makeLogRecord({'name': 'spam.eggs'})
382 self.assertTrue(f.filter(r))
Christian Heimes180510d2008-03-03 19:15:45 +0000383
384#
385# First, we define our levels. There can be as many as you want - the only
386# limitations are that they should be integers, the lowest should be > 0 and
387# larger values mean less information being logged. If you need specific
388# level values which do not fit into these limitations, you can use a
389# mapping dictionary to convert between your application levels and the
390# logging system.
391#
392SILENT = 120
393TACITURN = 119
394TERSE = 118
395EFFUSIVE = 117
396SOCIABLE = 116
397VERBOSE = 115
398TALKATIVE = 114
399GARRULOUS = 113
400CHATTERBOX = 112
401BORING = 111
402
403LEVEL_RANGE = range(BORING, SILENT + 1)
404
405#
406# Next, we define names for our levels. You don't need to do this - in which
407# case the system will use "Level n" to denote the text for the level.
408#
409my_logging_levels = {
410 SILENT : 'Silent',
411 TACITURN : 'Taciturn',
412 TERSE : 'Terse',
413 EFFUSIVE : 'Effusive',
414 SOCIABLE : 'Sociable',
415 VERBOSE : 'Verbose',
416 TALKATIVE : 'Talkative',
417 GARRULOUS : 'Garrulous',
418 CHATTERBOX : 'Chatterbox',
419 BORING : 'Boring',
420}
421
422class GarrulousFilter(logging.Filter):
423
424 """A filter which blocks garrulous messages."""
425
426 def filter(self, record):
427 return record.levelno != GARRULOUS
428
429class VerySpecificFilter(logging.Filter):
430
431 """A filter which blocks sociable and taciturn messages."""
432
433 def filter(self, record):
434 return record.levelno not in [SOCIABLE, TACITURN]
435
436
437class CustomLevelsAndFiltersTest(BaseTest):
438
439 """Test various filtering possibilities with custom logging levels."""
440
441 # Skip the logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +0300442 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +0000443
444 def setUp(self):
445 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000446 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000447 logging.addLevelName(k, v)
448
449 def log_at_all_levels(self, logger):
450 for lvl in LEVEL_RANGE:
451 logger.log(lvl, self.next_message())
452
453 def test_logger_filter(self):
454 # Filter at logger level.
455 self.root_logger.setLevel(VERBOSE)
456 # Levels >= 'Verbose' are good.
457 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000458 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000459 ('Verbose', '5'),
460 ('Sociable', '6'),
461 ('Effusive', '7'),
462 ('Terse', '8'),
463 ('Taciturn', '9'),
464 ('Silent', '10'),
465 ])
466
467 def test_handler_filter(self):
468 # Filter at handler level.
469 self.root_logger.handlers[0].setLevel(SOCIABLE)
470 try:
471 # Levels >= 'Sociable' are good.
472 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000473 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000474 ('Sociable', '6'),
475 ('Effusive', '7'),
476 ('Terse', '8'),
477 ('Taciturn', '9'),
478 ('Silent', '10'),
479 ])
480 finally:
481 self.root_logger.handlers[0].setLevel(logging.NOTSET)
482
483 def test_specific_filters(self):
484 # Set a specific filter object on the handler, and then add another
485 # filter object on the logger itself.
486 handler = self.root_logger.handlers[0]
487 specific_filter = None
488 garr = GarrulousFilter()
489 handler.addFilter(garr)
490 try:
491 self.log_at_all_levels(self.root_logger)
492 first_lines = [
493 # Notice how 'Garrulous' is missing
494 ('Boring', '1'),
495 ('Chatterbox', '2'),
496 ('Talkative', '4'),
497 ('Verbose', '5'),
498 ('Sociable', '6'),
499 ('Effusive', '7'),
500 ('Terse', '8'),
501 ('Taciturn', '9'),
502 ('Silent', '10'),
503 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000504 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000505
506 specific_filter = VerySpecificFilter()
507 self.root_logger.addFilter(specific_filter)
508 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000509 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000510 # Not only 'Garrulous' is still missing, but also 'Sociable'
511 # and 'Taciturn'
512 ('Boring', '11'),
513 ('Chatterbox', '12'),
514 ('Talkative', '14'),
515 ('Verbose', '15'),
516 ('Effusive', '17'),
517 ('Terse', '18'),
518 ('Silent', '20'),
519 ])
520 finally:
521 if specific_filter:
522 self.root_logger.removeFilter(specific_filter)
523 handler.removeFilter(garr)
524
525
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100526class HandlerTest(BaseTest):
527 def test_name(self):
528 h = logging.Handler()
529 h.name = 'generic'
530 self.assertEqual(h.name, 'generic')
531 h.name = 'anothergeneric'
532 self.assertEqual(h.name, 'anothergeneric')
533 self.assertRaises(NotImplementedError, h.emit, None)
534
Vinay Sajip5a35b062011-04-27 11:31:14 +0100535 def test_builtin_handlers(self):
536 # We can't actually *use* too many handlers in the tests,
537 # but we can try instantiating them with various options
Victor Stinnere6747472011-08-21 00:39:18 +0200538 if sys.platform in ('linux', 'darwin'):
Vinay Sajip5a35b062011-04-27 11:31:14 +0100539 for existing in (True, False):
540 fd, fn = tempfile.mkstemp()
541 os.close(fd)
542 if not existing:
543 os.unlink(fn)
544 h = logging.handlers.WatchedFileHandler(fn, delay=True)
545 if existing:
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100546 dev, ino = h.dev, h.ino
Vinay Sajipa5798de2012-04-24 23:33:33 +0100547 self.assertEqual(dev, -1)
548 self.assertEqual(ino, -1)
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100549 r = logging.makeLogRecord({'msg': 'Test'})
550 h.handle(r)
551 # Now remove the file.
552 os.unlink(fn)
553 self.assertFalse(os.path.exists(fn))
554 # The next call should recreate the file.
555 h.handle(r)
556 self.assertTrue(os.path.exists(fn))
Vinay Sajip5a35b062011-04-27 11:31:14 +0100557 else:
558 self.assertEqual(h.dev, -1)
559 self.assertEqual(h.ino, -1)
560 h.close()
561 if existing:
562 os.unlink(fn)
563 if sys.platform == 'darwin':
Vinay Sajip6bba65c2011-04-27 14:31:55 +0100564 sockname = '/var/run/syslog'
Vinay Sajip5a35b062011-04-27 11:31:14 +0100565 else:
566 sockname = '/dev/log'
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100567 try:
568 h = logging.handlers.SysLogHandler(sockname)
569 self.assertEqual(h.facility, h.LOG_USER)
570 self.assertTrue(h.unixsocket)
571 h.close()
572 except socket.error: # syslogd might not be available
573 pass
Vinay Sajip5a35b062011-04-27 11:31:14 +0100574 for method in ('GET', 'POST', 'PUT'):
575 if method == 'PUT':
576 self.assertRaises(ValueError, logging.handlers.HTTPHandler,
577 'localhost', '/log', method)
578 else:
579 h = logging.handlers.HTTPHandler('localhost', '/log', method)
580 h.close()
581 h = logging.handlers.BufferingHandler(0)
582 r = logging.makeLogRecord({})
583 self.assertTrue(h.shouldFlush(r))
584 h.close()
585 h = logging.handlers.BufferingHandler(1)
586 self.assertFalse(h.shouldFlush(r))
587 h.close()
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100588
Vinay Sajip5e86eed2012-05-29 22:48:10 +0100589 @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.')
Vinay Sajipa5798de2012-04-24 23:33:33 +0100590 @unittest.skipUnless(threading, 'Threading required for this test.')
591 def test_race(self):
592 # Issue #14632 refers.
593 def remove_loop(fname, tries):
594 for _ in range(tries):
595 try:
596 os.unlink(fname)
597 except OSError:
598 pass
599 time.sleep(0.004 * random.randint(0, 4))
600
Vinay Sajipc94871a2012-04-25 10:51:35 +0100601 del_count = 500
602 log_count = 500
Vinay Sajipa5798de2012-04-24 23:33:33 +0100603
Vinay Sajipa5798de2012-04-24 23:33:33 +0100604 for delay in (False, True):
Vinay Sajipc94871a2012-04-25 10:51:35 +0100605 fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
606 os.close(fd)
607 remover = threading.Thread(target=remove_loop, args=(fn, del_count))
608 remover.daemon = True
609 remover.start()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100610 h = logging.handlers.WatchedFileHandler(fn, delay=delay)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100611 f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
612 h.setFormatter(f)
Vinay Sajipc94871a2012-04-25 10:51:35 +0100613 try:
614 for _ in range(log_count):
615 time.sleep(0.005)
616 r = logging.makeLogRecord({'msg': 'testing' })
617 h.handle(r)
618 finally:
Vinay Sajipc94871a2012-04-25 10:51:35 +0100619 remover.join()
Vinay Sajipac20f462012-05-03 12:09:38 +0100620 h.close()
Vinay Sajipc94871a2012-04-25 10:51:35 +0100621 if os.path.exists(fn):
622 os.unlink(fn)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100623
624
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100625class BadStream(object):
626 def write(self, data):
627 raise RuntimeError('deliberate mistake')
628
629class TestStreamHandler(logging.StreamHandler):
630 def handleError(self, record):
631 self.error_record = record
632
633class StreamHandlerTest(BaseTest):
634 def test_error_handling(self):
635 h = TestStreamHandler(BadStream())
636 r = logging.makeLogRecord({})
637 old_raise = logging.raiseExceptions
Vinay Sajip985ef872011-04-26 19:34:04 +0100638 old_stderr = sys.stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100639 try:
640 h.handle(r)
641 self.assertIs(h.error_record, r)
Vinay Sajip985ef872011-04-26 19:34:04 +0100642 h = logging.StreamHandler(BadStream())
643 sys.stderr = sio = io.StringIO()
644 h.handle(r)
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100645 self.assertIn('\nRuntimeError: deliberate mistake\n',
646 sio.getvalue())
Vinay Sajip985ef872011-04-26 19:34:04 +0100647 logging.raiseExceptions = False
648 sys.stderr = sio = io.StringIO()
649 h.handle(r)
650 self.assertEqual('', sio.getvalue())
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100651 finally:
652 logging.raiseExceptions = old_raise
Vinay Sajip985ef872011-04-26 19:34:04 +0100653 sys.stderr = old_stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100654
Vinay Sajip7367d082011-05-02 13:17:27 +0100655# -- The following section could be moved into a server_helper.py module
656# -- if it proves to be of wider utility than just test_logging
Vinay Sajipa463d252011-04-30 21:52:48 +0100657
Vinay Sajipce7c9782011-05-17 07:15:53 +0100658if threading:
659 class TestSMTPChannel(smtpd.SMTPChannel):
Vinay Sajip314b92b2011-05-02 14:31:16 +0100660 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100661 This derived class has had to be created because smtpd does not
662 support use of custom channel maps, although they are allowed by
663 asyncore's design. Issue #11959 has been raised to address this,
664 and if resolved satisfactorily, some of this code can be removed.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100665 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100666 def __init__(self, server, conn, addr, sockmap):
667 asynchat.async_chat.__init__(self, conn, sockmap)
668 self.smtp_server = server
669 self.conn = conn
670 self.addr = addr
R David Murrayd1a30c92012-05-26 14:33:59 -0400671 self.data_size_limit = None
Vinay Sajipce7c9782011-05-17 07:15:53 +0100672 self.received_lines = []
673 self.smtp_state = self.COMMAND
674 self.seen_greeting = ''
675 self.mailfrom = None
676 self.rcpttos = []
677 self.received_data = ''
678 self.fqdn = socket.getfqdn()
679 self.num_bytes = 0
680 try:
681 self.peer = conn.getpeername()
682 except socket.error as err:
683 # a race condition may occur if the other end is closing
684 # before we can get the peername
685 self.close()
686 if err.args[0] != errno.ENOTCONN:
687 raise
688 return
689 self.push('220 %s %s' % (self.fqdn, smtpd.__version__))
690 self.set_terminator(b'\r\n')
R David Murrayd1a30c92012-05-26 14:33:59 -0400691 self.extended_smtp = False
Vinay Sajipa463d252011-04-30 21:52:48 +0100692
Vinay Sajip314b92b2011-05-02 14:31:16 +0100693
Vinay Sajipce7c9782011-05-17 07:15:53 +0100694 class TestSMTPServer(smtpd.SMTPServer):
Vinay Sajip314b92b2011-05-02 14:31:16 +0100695 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100696 This class implements a test SMTP server.
Vinay Sajipa463d252011-04-30 21:52:48 +0100697
Vinay Sajipce7c9782011-05-17 07:15:53 +0100698 :param addr: A (host, port) tuple which the server listens on.
699 You can specify a port value of zero: the server's
700 *port* attribute will hold the actual port number
701 used, which can be used in client connections.
702 :param handler: A callable which will be called to process
703 incoming messages. The handler will be passed
704 the client address tuple, who the message is from,
705 a list of recipients and the message data.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100706 :param poll_interval: The interval, in seconds, used in the underlying
707 :func:`select` or :func:`poll` call by
708 :func:`asyncore.loop`.
Vinay Sajipce7c9782011-05-17 07:15:53 +0100709 :param sockmap: A dictionary which will be used to hold
710 :class:`asyncore.dispatcher` instances used by
711 :func:`asyncore.loop`. This avoids changing the
712 :mod:`asyncore` module's global state.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100713 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100714 channel_class = TestSMTPChannel
715
716 def __init__(self, addr, handler, poll_interval, sockmap):
717 self._localaddr = addr
718 self._remoteaddr = None
R David Murrayd1a30c92012-05-26 14:33:59 -0400719 self.data_size_limit = None
Vinay Sajipce7c9782011-05-17 07:15:53 +0100720 self.sockmap = sockmap
721 asyncore.dispatcher.__init__(self, map=sockmap)
722 try:
723 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
724 sock.setblocking(0)
725 self.set_socket(sock, map=sockmap)
726 # try to re-use a server port if possible
727 self.set_reuse_addr()
728 self.bind(addr)
729 self.port = sock.getsockname()[1]
730 self.listen(5)
731 except:
732 self.close()
Vinay Sajipe73afad2011-05-10 07:48:28 +0100733 raise
Vinay Sajipce7c9782011-05-17 07:15:53 +0100734 self._handler = handler
735 self._thread = None
736 self.poll_interval = poll_interval
Vinay Sajipa463d252011-04-30 21:52:48 +0100737
Vinay Sajipce7c9782011-05-17 07:15:53 +0100738 def handle_accepted(self, conn, addr):
739 """
740 Redefined only because the base class does not pass in a
741 map, forcing use of a global in :mod:`asyncore`.
742 """
743 channel = self.channel_class(self, conn, addr, self.sockmap)
Vinay Sajip314b92b2011-05-02 14:31:16 +0100744
Vinay Sajipce7c9782011-05-17 07:15:53 +0100745 def process_message(self, peer, mailfrom, rcpttos, data):
746 """
747 Delegates to the handler passed in to the server's constructor.
Vinay Sajipa463d252011-04-30 21:52:48 +0100748
Vinay Sajipce7c9782011-05-17 07:15:53 +0100749 Typically, this will be a test case method.
750 :param peer: The client (host, port) tuple.
751 :param mailfrom: The address of the sender.
752 :param rcpttos: The addresses of the recipients.
753 :param data: The message.
754 """
755 self._handler(peer, mailfrom, rcpttos, data)
Vinay Sajip7367d082011-05-02 13:17:27 +0100756
Vinay Sajipce7c9782011-05-17 07:15:53 +0100757 def start(self):
758 """
759 Start the server running on a separate daemon thread.
760 """
761 self._thread = t = threading.Thread(target=self.serve_forever,
762 args=(self.poll_interval,))
763 t.setDaemon(True)
764 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100765
Vinay Sajipce7c9782011-05-17 07:15:53 +0100766 def serve_forever(self, poll_interval):
767 """
768 Run the :mod:`asyncore` loop until normal termination
769 conditions arise.
770 :param poll_interval: The interval, in seconds, used in the underlying
771 :func:`select` or :func:`poll` call by
772 :func:`asyncore.loop`.
773 """
774 try:
775 asyncore.loop(poll_interval, map=self.sockmap)
776 except select.error:
777 # On FreeBSD 8, closing the server repeatably
778 # raises this error. We swallow it if the
779 # server has been closed.
780 if self.connected or self.accepting:
781 raise
Vinay Sajip7367d082011-05-02 13:17:27 +0100782
Vinay Sajipce7c9782011-05-17 07:15:53 +0100783 def stop(self, timeout=None):
784 """
785 Stop the thread by closing the server instance.
786 Wait for the server thread to terminate.
Vinay Sajip7367d082011-05-02 13:17:27 +0100787
Vinay Sajipce7c9782011-05-17 07:15:53 +0100788 :param timeout: How long to wait for the server thread
789 to terminate.
790 """
791 self.close()
Vinay Sajip7367d082011-05-02 13:17:27 +0100792 self._thread.join(timeout)
793 self._thread = None
Vinay Sajip7367d082011-05-02 13:17:27 +0100794
Vinay Sajipce7c9782011-05-17 07:15:53 +0100795 class ControlMixin(object):
796 """
797 This mixin is used to start a server on a separate thread, and
798 shut it down programmatically. Request handling is simplified - instead
799 of needing to derive a suitable RequestHandler subclass, you just
800 provide a callable which will be passed each received request to be
801 processed.
Vinay Sajip7367d082011-05-02 13:17:27 +0100802
Vinay Sajipce7c9782011-05-17 07:15:53 +0100803 :param handler: A handler callable which will be called with a
804 single parameter - the request - in order to
805 process the request. This handler is called on the
806 server thread, effectively meaning that requests are
807 processed serially. While not quite Web scale ;-),
808 this should be fine for testing applications.
809 :param poll_interval: The polling interval in seconds.
810 """
811 def __init__(self, handler, poll_interval):
812 self._thread = None
813 self.poll_interval = poll_interval
814 self._handler = handler
815 self.ready = threading.Event()
Vinay Sajip7367d082011-05-02 13:17:27 +0100816
Vinay Sajipce7c9782011-05-17 07:15:53 +0100817 def start(self):
818 """
819 Create a daemon thread to run the server, and start it.
820 """
821 self._thread = t = threading.Thread(target=self.serve_forever,
822 args=(self.poll_interval,))
823 t.setDaemon(True)
824 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100825
Vinay Sajipce7c9782011-05-17 07:15:53 +0100826 def serve_forever(self, poll_interval):
827 """
828 Run the server. Set the ready flag before entering the
829 service loop.
830 """
831 self.ready.set()
832 super(ControlMixin, self).serve_forever(poll_interval)
Vinay Sajip7367d082011-05-02 13:17:27 +0100833
Vinay Sajipce7c9782011-05-17 07:15:53 +0100834 def stop(self, timeout=None):
835 """
836 Tell the server thread to stop, and wait for it to do so.
Vinay Sajip7367d082011-05-02 13:17:27 +0100837
Vinay Sajipce7c9782011-05-17 07:15:53 +0100838 :param timeout: How long to wait for the server thread
839 to terminate.
840 """
841 self.shutdown()
842 if self._thread is not None:
843 self._thread.join(timeout)
844 self._thread = None
845 self.server_close()
846 self.ready.clear()
Vinay Sajip7367d082011-05-02 13:17:27 +0100847
Vinay Sajipce7c9782011-05-17 07:15:53 +0100848 class TestHTTPServer(ControlMixin, HTTPServer):
849 """
850 An HTTP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100851
Vinay Sajipce7c9782011-05-17 07:15:53 +0100852 :param addr: A tuple with the IP address and port to listen on.
853 :param handler: A handler callable which will be called with a
854 single parameter - the request - in order to
855 process the request.
856 :param poll_interval: The polling interval in seconds.
857 :param log: Pass ``True`` to enable log messages.
858 """
Vinay Sajip32565b62011-05-21 00:34:51 +0100859 def __init__(self, addr, handler, poll_interval=0.5,
860 log=False, sslctx=None):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100861 class DelegatingHTTPRequestHandler(BaseHTTPRequestHandler):
862 def __getattr__(self, name, default=None):
863 if name.startswith('do_'):
864 return self.process_request
865 raise AttributeError(name)
Vinay Sajip7367d082011-05-02 13:17:27 +0100866
Vinay Sajipce7c9782011-05-17 07:15:53 +0100867 def process_request(self):
868 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +0100869
Vinay Sajipce7c9782011-05-17 07:15:53 +0100870 def log_message(self, format, *args):
871 if log:
872 super(DelegatingHTTPRequestHandler,
873 self).log_message(format, *args)
874 HTTPServer.__init__(self, addr, DelegatingHTTPRequestHandler)
875 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajip32565b62011-05-21 00:34:51 +0100876 self.sslctx = sslctx
877
878 def get_request(self):
879 try:
880 sock, addr = self.socket.accept()
881 if self.sslctx:
882 sock = self.sslctx.wrap_socket(sock, server_side=True)
883 except socket.error as e:
884 # socket errors are silenced by the caller, print them here
885 sys.stderr.write("Got an error:\n%s\n" % e)
886 raise
887 return sock, addr
Vinay Sajip7367d082011-05-02 13:17:27 +0100888
Vinay Sajipce7c9782011-05-17 07:15:53 +0100889 class TestTCPServer(ControlMixin, ThreadingTCPServer):
890 """
891 A TCP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100892
Vinay Sajipce7c9782011-05-17 07:15:53 +0100893 :param addr: A tuple with the IP address and port to listen on.
894 :param handler: A handler callable which will be called with a single
895 parameter - the request - in order to process the request.
896 :param poll_interval: The polling interval in seconds.
897 :bind_and_activate: If True (the default), binds the server and starts it
898 listening. If False, you need to call
899 :meth:`server_bind` and :meth:`server_activate` at
900 some later time before calling :meth:`start`, so that
901 the server will set up the socket and listen on it.
902 """
Vinay Sajip7367d082011-05-02 13:17:27 +0100903
Vinay Sajipce7c9782011-05-17 07:15:53 +0100904 allow_reuse_address = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100905
Vinay Sajipce7c9782011-05-17 07:15:53 +0100906 def __init__(self, addr, handler, poll_interval=0.5,
907 bind_and_activate=True):
908 class DelegatingTCPRequestHandler(StreamRequestHandler):
909
910 def handle(self):
911 self.server._handler(self)
912 ThreadingTCPServer.__init__(self, addr, DelegatingTCPRequestHandler,
913 bind_and_activate)
914 ControlMixin.__init__(self, handler, poll_interval)
915
916 def server_bind(self):
917 super(TestTCPServer, self).server_bind()
918 self.port = self.socket.getsockname()[1]
919
920 class TestUDPServer(ControlMixin, ThreadingUDPServer):
921 """
922 A UDP server which is controllable using :class:`ControlMixin`.
923
924 :param addr: A tuple with the IP address and port to listen on.
925 :param handler: A handler callable which will be called with a
926 single parameter - the request - in order to
927 process the request.
928 :param poll_interval: The polling interval for shutdown requests,
929 in seconds.
930 :bind_and_activate: If True (the default), binds the server and
931 starts it listening. If False, you need to
932 call :meth:`server_bind` and
933 :meth:`server_activate` at some later time
934 before calling :meth:`start`, so that the server will
935 set up the socket and listen on it.
936 """
Vinay Sajip3ef12292011-05-23 23:00:42 +0100937 def __init__(self, addr, handler, poll_interval=0.5,
938 bind_and_activate=True):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100939 class DelegatingUDPRequestHandler(DatagramRequestHandler):
940
941 def handle(self):
942 self.server._handler(self)
Vinay Sajipba980db2011-05-23 21:37:54 +0100943
944 def finish(self):
945 data = self.wfile.getvalue()
Vinay Sajip3ef12292011-05-23 23:00:42 +0100946 if data:
947 try:
948 super(DelegatingUDPRequestHandler, self).finish()
949 except socket.error:
950 if not self.server._closed:
951 raise
Vinay Sajipba980db2011-05-23 21:37:54 +0100952
Vinay Sajip3ef12292011-05-23 23:00:42 +0100953 ThreadingUDPServer.__init__(self, addr,
954 DelegatingUDPRequestHandler,
Vinay Sajipce7c9782011-05-17 07:15:53 +0100955 bind_and_activate)
956 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajipba980db2011-05-23 21:37:54 +0100957 self._closed = False
Vinay Sajipce7c9782011-05-17 07:15:53 +0100958
959 def server_bind(self):
960 super(TestUDPServer, self).server_bind()
961 self.port = self.socket.getsockname()[1]
Vinay Sajip7367d082011-05-02 13:17:27 +0100962
Vinay Sajipba980db2011-05-23 21:37:54 +0100963 def server_close(self):
964 super(TestUDPServer, self).server_close()
965 self._closed = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100966
967# - end of server_helper section
Vinay Sajipa463d252011-04-30 21:52:48 +0100968
Vinay Sajipce7c9782011-05-17 07:15:53 +0100969@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipa463d252011-04-30 21:52:48 +0100970class SMTPHandlerTest(BaseTest):
971 def test_basic(self):
Vinay Sajip7367d082011-05-02 13:17:27 +0100972 sockmap = {}
973 server = TestSMTPServer(('localhost', 0), self.process_message, 0.001,
974 sockmap)
975 server.start()
976 addr = ('localhost', server.port)
Vinay Sajip4c3f4782012-04-22 18:19:50 +0100977 h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log', timeout=5.0)
Vinay Sajipa463d252011-04-30 21:52:48 +0100978 self.assertEqual(h.toaddrs, ['you'])
979 self.messages = []
Vinay Sajipa463d252011-04-30 21:52:48 +0100980 r = logging.makeLogRecord({'msg': 'Hello'})
Vinay Sajip7367d082011-05-02 13:17:27 +0100981 self.handled = threading.Event()
Vinay Sajipa463d252011-04-30 21:52:48 +0100982 h.handle(r)
Vinay Sajip17160fd2012-03-15 12:02:08 +0000983 self.handled.wait(5.0) # 14314: don't wait forever
Vinay Sajipa463d252011-04-30 21:52:48 +0100984 server.stop()
Vinay Sajip17160fd2012-03-15 12:02:08 +0000985 self.assertTrue(self.handled.is_set())
Vinay Sajipa463d252011-04-30 21:52:48 +0100986 self.assertEqual(len(self.messages), 1)
987 peer, mailfrom, rcpttos, data = self.messages[0]
988 self.assertEqual(mailfrom, 'me')
989 self.assertEqual(rcpttos, ['you'])
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100990 self.assertIn('\nSubject: Log\n', data)
Vinay Sajipa463d252011-04-30 21:52:48 +0100991 self.assertTrue(data.endswith('\n\nHello'))
992 h.close()
993
994 def process_message(self, *args):
995 self.messages.append(args)
Vinay Sajip7367d082011-05-02 13:17:27 +0100996 self.handled.set()
Vinay Sajipa463d252011-04-30 21:52:48 +0100997
Christian Heimes180510d2008-03-03 19:15:45 +0000998class MemoryHandlerTest(BaseTest):
999
1000 """Tests for the MemoryHandler."""
1001
1002 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001003 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001004
1005 def setUp(self):
1006 BaseTest.setUp(self)
1007 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
1008 self.root_hdlr)
1009 self.mem_logger = logging.getLogger('mem')
1010 self.mem_logger.propagate = 0
1011 self.mem_logger.addHandler(self.mem_hdlr)
1012
1013 def tearDown(self):
1014 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +00001015 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +00001016
1017 def test_flush(self):
1018 # The memory handler flushes to its target handler based on specific
1019 # criteria (message count and message level).
1020 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001021 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001022 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001023 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001024 # This will flush because the level is >= logging.WARNING
Vinay Sajipb9e46e92011-10-26 13:17:20 +01001025 self.mem_logger.warning(self.next_message())
Christian Heimes180510d2008-03-03 19:15:45 +00001026 lines = [
1027 ('DEBUG', '1'),
1028 ('INFO', '2'),
1029 ('WARNING', '3'),
1030 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001031 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001032 for n in (4, 14):
1033 for i in range(9):
1034 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001035 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001036 # This will flush because it's the 10th message since the last
1037 # flush.
1038 self.mem_logger.debug(self.next_message())
1039 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001040 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001041
1042 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001043 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001044
1045
1046class ExceptionFormatter(logging.Formatter):
1047 """A special exception formatter."""
1048 def formatException(self, ei):
1049 return "Got a [%s]" % ei[0].__name__
1050
1051
1052class ConfigFileTest(BaseTest):
1053
1054 """Reading logging config from a .ini-style config file."""
1055
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001056 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001057
1058 # config0 is a standard configuration.
1059 config0 = """
1060 [loggers]
1061 keys=root
1062
1063 [handlers]
1064 keys=hand1
1065
1066 [formatters]
1067 keys=form1
1068
1069 [logger_root]
1070 level=WARNING
1071 handlers=hand1
1072
1073 [handler_hand1]
1074 class=StreamHandler
1075 level=NOTSET
1076 formatter=form1
1077 args=(sys.stdout,)
1078
1079 [formatter_form1]
1080 format=%(levelname)s ++ %(message)s
1081 datefmt=
1082 """
1083
1084 # config1 adds a little to the standard configuration.
1085 config1 = """
1086 [loggers]
1087 keys=root,parser
1088
1089 [handlers]
1090 keys=hand1
1091
1092 [formatters]
1093 keys=form1
1094
1095 [logger_root]
1096 level=WARNING
1097 handlers=
1098
1099 [logger_parser]
1100 level=DEBUG
1101 handlers=hand1
1102 propagate=1
1103 qualname=compiler.parser
1104
1105 [handler_hand1]
1106 class=StreamHandler
1107 level=NOTSET
1108 formatter=form1
1109 args=(sys.stdout,)
1110
1111 [formatter_form1]
1112 format=%(levelname)s ++ %(message)s
1113 datefmt=
1114 """
1115
Vinay Sajip3f84b072011-03-07 17:49:33 +00001116 # config1a moves the handler to the root.
1117 config1a = """
1118 [loggers]
1119 keys=root,parser
1120
1121 [handlers]
1122 keys=hand1
1123
1124 [formatters]
1125 keys=form1
1126
1127 [logger_root]
1128 level=WARNING
1129 handlers=hand1
1130
1131 [logger_parser]
1132 level=DEBUG
1133 handlers=
1134 propagate=1
1135 qualname=compiler.parser
1136
1137 [handler_hand1]
1138 class=StreamHandler
1139 level=NOTSET
1140 formatter=form1
1141 args=(sys.stdout,)
1142
1143 [formatter_form1]
1144 format=%(levelname)s ++ %(message)s
1145 datefmt=
1146 """
1147
Christian Heimes180510d2008-03-03 19:15:45 +00001148 # config2 has a subtle configuration error that should be reported
1149 config2 = config1.replace("sys.stdout", "sys.stbout")
1150
1151 # config3 has a less subtle configuration error
1152 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
1153
1154 # config4 specifies a custom formatter class to be loaded
1155 config4 = """
1156 [loggers]
1157 keys=root
1158
1159 [handlers]
1160 keys=hand1
1161
1162 [formatters]
1163 keys=form1
1164
1165 [logger_root]
1166 level=NOTSET
1167 handlers=hand1
1168
1169 [handler_hand1]
1170 class=StreamHandler
1171 level=NOTSET
1172 formatter=form1
1173 args=(sys.stdout,)
1174
1175 [formatter_form1]
1176 class=""" + __name__ + """.ExceptionFormatter
1177 format=%(levelname)s:%(name)s:%(message)s
1178 datefmt=
1179 """
1180
Georg Brandl3dbca812008-07-23 16:10:53 +00001181 # config5 specifies a custom handler class to be loaded
1182 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
1183
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001184 # config6 uses ', ' delimiters in the handlers and formatters sections
1185 config6 = """
1186 [loggers]
1187 keys=root,parser
1188
1189 [handlers]
1190 keys=hand1, hand2
1191
1192 [formatters]
1193 keys=form1, form2
1194
1195 [logger_root]
1196 level=WARNING
1197 handlers=
1198
1199 [logger_parser]
1200 level=DEBUG
1201 handlers=hand1
1202 propagate=1
1203 qualname=compiler.parser
1204
1205 [handler_hand1]
1206 class=StreamHandler
1207 level=NOTSET
1208 formatter=form1
1209 args=(sys.stdout,)
1210
1211 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001212 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001213 level=NOTSET
1214 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001215 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001216
1217 [formatter_form1]
1218 format=%(levelname)s ++ %(message)s
1219 datefmt=
1220
1221 [formatter_form2]
1222 format=%(message)s
1223 datefmt=
1224 """
1225
Vinay Sajip3f84b072011-03-07 17:49:33 +00001226 # config7 adds a compiler logger.
1227 config7 = """
1228 [loggers]
1229 keys=root,parser,compiler
1230
1231 [handlers]
1232 keys=hand1
1233
1234 [formatters]
1235 keys=form1
1236
1237 [logger_root]
1238 level=WARNING
1239 handlers=hand1
1240
1241 [logger_compiler]
1242 level=DEBUG
1243 handlers=
1244 propagate=1
1245 qualname=compiler
1246
1247 [logger_parser]
1248 level=DEBUG
1249 handlers=
1250 propagate=1
1251 qualname=compiler.parser
1252
1253 [handler_hand1]
1254 class=StreamHandler
1255 level=NOTSET
1256 formatter=form1
1257 args=(sys.stdout,)
1258
1259 [formatter_form1]
1260 format=%(levelname)s ++ %(message)s
1261 datefmt=
1262 """
1263
Christian Heimes180510d2008-03-03 19:15:45 +00001264 def apply_config(self, conf):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001265 file = io.StringIO(textwrap.dedent(conf))
1266 logging.config.fileConfig(file)
Christian Heimes180510d2008-03-03 19:15:45 +00001267
1268 def test_config0_ok(self):
1269 # A simple config file which overrides the default settings.
1270 with captured_stdout() as output:
1271 self.apply_config(self.config0)
1272 logger = logging.getLogger()
1273 # Won't output anything
1274 logger.info(self.next_message())
1275 # Outputs a message
1276 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001277 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001278 ('ERROR', '2'),
1279 ], stream=output)
1280 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001281 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001282
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001283 def test_config0_using_cp_ok(self):
1284 # A simple config file which overrides the default settings.
1285 with captured_stdout() as output:
1286 file = io.StringIO(textwrap.dedent(self.config0))
1287 cp = configparser.ConfigParser()
1288 cp.read_file(file)
1289 logging.config.fileConfig(cp)
1290 logger = logging.getLogger()
1291 # Won't output anything
1292 logger.info(self.next_message())
1293 # Outputs a message
1294 logger.error(self.next_message())
1295 self.assert_log_lines([
1296 ('ERROR', '2'),
1297 ], stream=output)
1298 # Original logger output is empty.
1299 self.assert_log_lines([])
1300
Georg Brandl3dbca812008-07-23 16:10:53 +00001301 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +00001302 # A config file defining a sub-parser as well.
1303 with captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +00001304 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +00001305 logger = logging.getLogger("compiler.parser")
1306 # Both will output a message
1307 logger.info(self.next_message())
1308 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001309 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001310 ('INFO', '1'),
1311 ('ERROR', '2'),
1312 ], stream=output)
1313 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001314 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001315
1316 def test_config2_failure(self):
1317 # A simple config file which overrides the default settings.
1318 self.assertRaises(Exception, self.apply_config, self.config2)
1319
1320 def test_config3_failure(self):
1321 # A simple config file which overrides the default settings.
1322 self.assertRaises(Exception, self.apply_config, self.config3)
1323
1324 def test_config4_ok(self):
1325 # A config file specifying a custom formatter class.
1326 with captured_stdout() as output:
1327 self.apply_config(self.config4)
1328 logger = logging.getLogger()
1329 try:
1330 raise RuntimeError()
1331 except RuntimeError:
1332 logging.exception("just testing")
1333 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00001334 self.assertEqual(output.getvalue(),
Christian Heimes180510d2008-03-03 19:15:45 +00001335 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1336 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001337 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001338
Georg Brandl3dbca812008-07-23 16:10:53 +00001339 def test_config5_ok(self):
1340 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +00001341
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001342 def test_config6_ok(self):
1343 self.test_config1_ok(config=self.config6)
1344
Vinay Sajip3f84b072011-03-07 17:49:33 +00001345 def test_config7_ok(self):
1346 with captured_stdout() as output:
1347 self.apply_config(self.config1a)
1348 logger = logging.getLogger("compiler.parser")
1349 # See issue #11424. compiler-hyphenated sorts
1350 # between compiler and compiler.xyz and this
1351 # was preventing compiler.xyz from being included
1352 # in the child loggers of compiler because of an
1353 # overzealous loop termination condition.
1354 hyphenated = logging.getLogger('compiler-hyphenated')
1355 # All will output a message
1356 logger.info(self.next_message())
1357 logger.error(self.next_message())
1358 hyphenated.critical(self.next_message())
1359 self.assert_log_lines([
1360 ('INFO', '1'),
1361 ('ERROR', '2'),
1362 ('CRITICAL', '3'),
1363 ], stream=output)
1364 # Original logger output is empty.
1365 self.assert_log_lines([])
1366 with captured_stdout() as output:
1367 self.apply_config(self.config7)
1368 logger = logging.getLogger("compiler.parser")
1369 self.assertFalse(logger.disabled)
1370 # Both will output a message
1371 logger.info(self.next_message())
1372 logger.error(self.next_message())
1373 logger = logging.getLogger("compiler.lexer")
1374 # Both will output a message
1375 logger.info(self.next_message())
1376 logger.error(self.next_message())
1377 # Will not appear
1378 hyphenated.critical(self.next_message())
1379 self.assert_log_lines([
1380 ('INFO', '4'),
1381 ('ERROR', '5'),
1382 ('INFO', '6'),
1383 ('ERROR', '7'),
1384 ], stream=output)
1385 # Original logger output is empty.
1386 self.assert_log_lines([])
1387
Guido van Rossum2a1d5162003-01-21 21:05:22 +00001388
Victor Stinner45df8202010-04-28 22:31:17 +00001389@unittest.skipUnless(threading, 'Threading required for this test.')
Christian Heimes180510d2008-03-03 19:15:45 +00001390class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001391
Christian Heimes180510d2008-03-03 19:15:45 +00001392 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001393
Christian Heimes180510d2008-03-03 19:15:45 +00001394 def setUp(self):
1395 """Set up a TCP server to receive log messages, and a SocketHandler
1396 pointing to that server's address and port."""
1397 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001398 addr = ('localhost', 0)
1399 self.server = server = TestTCPServer(addr, self.handle_socket,
1400 0.01)
1401 server.start()
1402 server.ready.wait()
1403 self.sock_hdlr = logging.handlers.SocketHandler('localhost',
1404 server.port)
1405 self.log_output = ''
Christian Heimes180510d2008-03-03 19:15:45 +00001406 self.root_logger.removeHandler(self.root_logger.handlers[0])
1407 self.root_logger.addHandler(self.sock_hdlr)
Vinay Sajip7367d082011-05-02 13:17:27 +01001408 self.handled = threading.Semaphore(0)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001409
Christian Heimes180510d2008-03-03 19:15:45 +00001410 def tearDown(self):
1411 """Shutdown the TCP server."""
1412 try:
Vinay Sajip7367d082011-05-02 13:17:27 +01001413 self.server.stop(2.0)
Christian Heimes180510d2008-03-03 19:15:45 +00001414 self.root_logger.removeHandler(self.sock_hdlr)
1415 self.sock_hdlr.close()
Christian Heimes180510d2008-03-03 19:15:45 +00001416 finally:
1417 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001418
Vinay Sajip7367d082011-05-02 13:17:27 +01001419 def handle_socket(self, request):
1420 conn = request.connection
1421 while True:
1422 chunk = conn.recv(4)
1423 if len(chunk) < 4:
1424 break
1425 slen = struct.unpack(">L", chunk)[0]
1426 chunk = conn.recv(slen)
1427 while len(chunk) < slen:
1428 chunk = chunk + conn.recv(slen - len(chunk))
1429 obj = pickle.loads(chunk)
1430 record = logging.makeLogRecord(obj)
1431 self.log_output += record.msg + '\n'
1432 self.handled.release()
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001433
Christian Heimes180510d2008-03-03 19:15:45 +00001434 def test_output(self):
1435 # The log message sent to the SocketHandler is properly received.
1436 logger = logging.getLogger("tcp")
1437 logger.error("spam")
Vinay Sajip7367d082011-05-02 13:17:27 +01001438 self.handled.acquire()
Christian Heimes180510d2008-03-03 19:15:45 +00001439 logger.debug("eggs")
Vinay Sajip7367d082011-05-02 13:17:27 +01001440 self.handled.acquire()
1441 self.assertEqual(self.log_output, "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001442
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001443 def test_noserver(self):
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001444 # Avoid timing-related failures due to SocketHandler's own hard-wired
1445 # one-second timeout on socket.create_connection() (issue #16264).
1446 self.sock_hdlr.retryStart = 2.5
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001447 # Kill the server
Vinay Sajip7367d082011-05-02 13:17:27 +01001448 self.server.stop(2.0)
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001449 # The logging call should try to connect, which should fail
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001450 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()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02001456 self.assertGreater(self.sock_hdlr.retryTime, now)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001457 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()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02001782 self.assertGreater(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
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001820 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001821
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
2392 def apply_config(self, conf):
2393 logging.config.dictConfig(conf)
2394
2395 def test_config0_ok(self):
2396 # A simple config which overrides the default settings.
2397 with captured_stdout() as output:
2398 self.apply_config(self.config0)
2399 logger = logging.getLogger()
2400 # Won't output anything
2401 logger.info(self.next_message())
2402 # Outputs a message
2403 logger.error(self.next_message())
2404 self.assert_log_lines([
2405 ('ERROR', '2'),
2406 ], stream=output)
2407 # Original logger output is empty.
2408 self.assert_log_lines([])
2409
2410 def test_config1_ok(self, config=config1):
2411 # A config defining a sub-parser as well.
2412 with captured_stdout() as output:
2413 self.apply_config(config)
2414 logger = logging.getLogger("compiler.parser")
2415 # Both will output a message
2416 logger.info(self.next_message())
2417 logger.error(self.next_message())
2418 self.assert_log_lines([
2419 ('INFO', '1'),
2420 ('ERROR', '2'),
2421 ], stream=output)
2422 # Original logger output is empty.
2423 self.assert_log_lines([])
2424
2425 def test_config2_failure(self):
2426 # A simple config which overrides the default settings.
2427 self.assertRaises(Exception, self.apply_config, self.config2)
2428
2429 def test_config2a_failure(self):
2430 # A simple config which overrides the default settings.
2431 self.assertRaises(Exception, self.apply_config, self.config2a)
2432
2433 def test_config2b_failure(self):
2434 # A simple config which overrides the default settings.
2435 self.assertRaises(Exception, self.apply_config, self.config2b)
2436
2437 def test_config3_failure(self):
2438 # A simple config which overrides the default settings.
2439 self.assertRaises(Exception, self.apply_config, self.config3)
2440
2441 def test_config4_ok(self):
2442 # A config specifying a custom formatter class.
2443 with captured_stdout() as output:
2444 self.apply_config(self.config4)
2445 #logger = logging.getLogger()
2446 try:
2447 raise RuntimeError()
2448 except RuntimeError:
2449 logging.exception("just testing")
2450 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002451 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002452 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2453 # Original logger output is empty
2454 self.assert_log_lines([])
2455
2456 def test_config4a_ok(self):
2457 # A config specifying a custom formatter class.
2458 with captured_stdout() as output:
2459 self.apply_config(self.config4a)
2460 #logger = logging.getLogger()
2461 try:
2462 raise RuntimeError()
2463 except RuntimeError:
2464 logging.exception("just testing")
2465 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002466 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002467 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2468 # Original logger output is empty
2469 self.assert_log_lines([])
2470
2471 def test_config5_ok(self):
2472 self.test_config1_ok(config=self.config5)
2473
2474 def test_config6_failure(self):
2475 self.assertRaises(Exception, self.apply_config, self.config6)
2476
2477 def test_config7_ok(self):
2478 with captured_stdout() as output:
2479 self.apply_config(self.config1)
2480 logger = logging.getLogger("compiler.parser")
2481 # Both will output a message
2482 logger.info(self.next_message())
2483 logger.error(self.next_message())
2484 self.assert_log_lines([
2485 ('INFO', '1'),
2486 ('ERROR', '2'),
2487 ], stream=output)
2488 # Original logger output is empty.
2489 self.assert_log_lines([])
2490 with captured_stdout() as output:
2491 self.apply_config(self.config7)
2492 logger = logging.getLogger("compiler.parser")
2493 self.assertTrue(logger.disabled)
2494 logger = logging.getLogger("compiler.lexer")
2495 # Both will output a message
2496 logger.info(self.next_message())
2497 logger.error(self.next_message())
2498 self.assert_log_lines([
2499 ('INFO', '3'),
2500 ('ERROR', '4'),
2501 ], stream=output)
2502 # Original logger output is empty.
2503 self.assert_log_lines([])
2504
2505 #Same as test_config_7_ok but don't disable old loggers.
2506 def test_config_8_ok(self):
2507 with captured_stdout() as output:
2508 self.apply_config(self.config1)
2509 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002510 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002511 logger.info(self.next_message())
2512 logger.error(self.next_message())
2513 self.assert_log_lines([
2514 ('INFO', '1'),
2515 ('ERROR', '2'),
2516 ], stream=output)
2517 # Original logger output is empty.
2518 self.assert_log_lines([])
2519 with captured_stdout() as output:
2520 self.apply_config(self.config8)
2521 logger = logging.getLogger("compiler.parser")
2522 self.assertFalse(logger.disabled)
2523 # Both will output a message
2524 logger.info(self.next_message())
2525 logger.error(self.next_message())
2526 logger = logging.getLogger("compiler.lexer")
2527 # Both will output a message
2528 logger.info(self.next_message())
2529 logger.error(self.next_message())
2530 self.assert_log_lines([
2531 ('INFO', '3'),
2532 ('ERROR', '4'),
2533 ('INFO', '5'),
2534 ('ERROR', '6'),
2535 ], stream=output)
2536 # Original logger output is empty.
2537 self.assert_log_lines([])
2538
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002539 def test_config_8a_ok(self):
2540 with captured_stdout() as output:
2541 self.apply_config(self.config1a)
2542 logger = logging.getLogger("compiler.parser")
2543 # See issue #11424. compiler-hyphenated sorts
2544 # between compiler and compiler.xyz and this
2545 # was preventing compiler.xyz from being included
2546 # in the child loggers of compiler because of an
2547 # overzealous loop termination condition.
2548 hyphenated = logging.getLogger('compiler-hyphenated')
2549 # All will output a message
2550 logger.info(self.next_message())
2551 logger.error(self.next_message())
2552 hyphenated.critical(self.next_message())
2553 self.assert_log_lines([
2554 ('INFO', '1'),
2555 ('ERROR', '2'),
2556 ('CRITICAL', '3'),
2557 ], stream=output)
2558 # Original logger output is empty.
2559 self.assert_log_lines([])
2560 with captured_stdout() as output:
2561 self.apply_config(self.config8a)
2562 logger = logging.getLogger("compiler.parser")
2563 self.assertFalse(logger.disabled)
2564 # Both will output a message
2565 logger.info(self.next_message())
2566 logger.error(self.next_message())
2567 logger = logging.getLogger("compiler.lexer")
2568 # Both will output a message
2569 logger.info(self.next_message())
2570 logger.error(self.next_message())
2571 # Will not appear
2572 hyphenated.critical(self.next_message())
2573 self.assert_log_lines([
2574 ('INFO', '4'),
2575 ('ERROR', '5'),
2576 ('INFO', '6'),
2577 ('ERROR', '7'),
2578 ], stream=output)
2579 # Original logger output is empty.
2580 self.assert_log_lines([])
2581
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002582 def test_config_9_ok(self):
2583 with captured_stdout() as output:
2584 self.apply_config(self.config9)
2585 logger = logging.getLogger("compiler.parser")
2586 #Nothing will be output since both handler and logger are set to WARNING
2587 logger.info(self.next_message())
2588 self.assert_log_lines([], stream=output)
2589 self.apply_config(self.config9a)
2590 #Nothing will be output since both handler is still set to WARNING
2591 logger.info(self.next_message())
2592 self.assert_log_lines([], stream=output)
2593 self.apply_config(self.config9b)
2594 #Message should now be output
2595 logger.info(self.next_message())
2596 self.assert_log_lines([
2597 ('INFO', '3'),
2598 ], stream=output)
2599
2600 def test_config_10_ok(self):
2601 with captured_stdout() as output:
2602 self.apply_config(self.config10)
2603 logger = logging.getLogger("compiler.parser")
2604 logger.warning(self.next_message())
2605 logger = logging.getLogger('compiler')
2606 #Not output, because filtered
2607 logger.warning(self.next_message())
2608 logger = logging.getLogger('compiler.lexer')
2609 #Not output, because filtered
2610 logger.warning(self.next_message())
2611 logger = logging.getLogger("compiler.parser.codegen")
2612 #Output, as not filtered
2613 logger.error(self.next_message())
2614 self.assert_log_lines([
2615 ('WARNING', '1'),
2616 ('ERROR', '4'),
2617 ], stream=output)
2618
2619 def test_config11_ok(self):
2620 self.test_config1_ok(self.config11)
2621
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002622 def test_config12_failure(self):
2623 self.assertRaises(Exception, self.apply_config, self.config12)
2624
2625 def test_config13_failure(self):
2626 self.assertRaises(Exception, self.apply_config, self.config13)
2627
Victor Stinner45df8202010-04-28 22:31:17 +00002628 @unittest.skipUnless(threading, 'listen() needs threading to work')
Vinay Sajip4ded5512012-10-02 15:56:16 +01002629 def setup_via_listener(self, text, verify=None):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002630 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00002631 # Ask for a randomly assigned port (by using port 0)
Vinay Sajip4ded5512012-10-02 15:56:16 +01002632 t = logging.config.listen(0, verify)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002633 t.start()
2634 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00002635 # Now get the port allocated
2636 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002637 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002638 try:
2639 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
2640 sock.settimeout(2.0)
2641 sock.connect(('localhost', port))
2642
2643 slen = struct.pack('>L', len(text))
2644 s = slen + text
2645 sentsofar = 0
2646 left = len(s)
2647 while left > 0:
2648 sent = sock.send(s[sentsofar:])
2649 sentsofar += sent
2650 left -= sent
2651 sock.close()
2652 finally:
2653 t.ready.wait(2.0)
2654 logging.config.stopListening()
2655 t.join(2.0)
2656
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002657 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002658 def test_listen_config_10_ok(self):
2659 with captured_stdout() as output:
2660 self.setup_via_listener(json.dumps(self.config10))
2661 logger = logging.getLogger("compiler.parser")
2662 logger.warning(self.next_message())
2663 logger = logging.getLogger('compiler')
2664 #Not output, because filtered
2665 logger.warning(self.next_message())
2666 logger = logging.getLogger('compiler.lexer')
2667 #Not output, because filtered
2668 logger.warning(self.next_message())
2669 logger = logging.getLogger("compiler.parser.codegen")
2670 #Output, as not filtered
2671 logger.error(self.next_message())
2672 self.assert_log_lines([
2673 ('WARNING', '1'),
2674 ('ERROR', '4'),
2675 ], stream=output)
2676
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002677 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002678 def test_listen_config_1_ok(self):
2679 with captured_stdout() as output:
2680 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
2681 logger = logging.getLogger("compiler.parser")
2682 # Both will output a message
2683 logger.info(self.next_message())
2684 logger.error(self.next_message())
2685 self.assert_log_lines([
2686 ('INFO', '1'),
2687 ('ERROR', '2'),
2688 ], stream=output)
2689 # Original logger output is empty.
2690 self.assert_log_lines([])
2691
Vinay Sajip4ded5512012-10-02 15:56:16 +01002692 @unittest.skipUnless(threading, 'Threading required for this test.')
2693 def test_listen_verify(self):
2694
2695 def verify_fail(stuff):
2696 return None
2697
2698 def verify_reverse(stuff):
2699 return stuff[::-1]
2700
2701 logger = logging.getLogger("compiler.parser")
2702 to_send = textwrap.dedent(ConfigFileTest.config1)
2703 # First, specify a verification function that will fail.
2704 # We expect to see no output, since our configuration
2705 # never took effect.
2706 with captured_stdout() as output:
2707 self.setup_via_listener(to_send, verify_fail)
2708 # Both will output a message
2709 logger.info(self.next_message())
2710 logger.error(self.next_message())
2711 self.assert_log_lines([], stream=output)
2712 # Original logger output has the stuff we logged.
2713 self.assert_log_lines([
2714 ('INFO', '1'),
2715 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002716 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002717
2718 # Now, perform no verification. Our configuration
2719 # should take effect.
2720
2721 with captured_stdout() as output:
2722 self.setup_via_listener(to_send) # no verify callable specified
2723 logger = logging.getLogger("compiler.parser")
2724 # Both will output a message
2725 logger.info(self.next_message())
2726 logger.error(self.next_message())
2727 self.assert_log_lines([
2728 ('INFO', '3'),
2729 ('ERROR', '4'),
2730 ], stream=output)
2731 # Original logger output still has the stuff we logged before.
2732 self.assert_log_lines([
2733 ('INFO', '1'),
2734 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002735 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002736
2737 # Now, perform verification which transforms the bytes.
2738
2739 with captured_stdout() as output:
2740 self.setup_via_listener(to_send[::-1], verify_reverse)
2741 logger = logging.getLogger("compiler.parser")
2742 # Both will output a message
2743 logger.info(self.next_message())
2744 logger.error(self.next_message())
2745 self.assert_log_lines([
2746 ('INFO', '5'),
2747 ('ERROR', '6'),
2748 ], stream=output)
2749 # Original logger output still has the stuff we logged before.
2750 self.assert_log_lines([
2751 ('INFO', '1'),
2752 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002753 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002754
Vinay Sajip373baef2011-04-26 20:05:24 +01002755 def test_baseconfig(self):
2756 d = {
2757 'atuple': (1, 2, 3),
2758 'alist': ['a', 'b', 'c'],
2759 'adict': {'d': 'e', 'f': 3 },
2760 'nest1': ('g', ('h', 'i'), 'j'),
2761 'nest2': ['k', ['l', 'm'], 'n'],
2762 'nest3': ['o', 'cfg://alist', 'p'],
2763 }
2764 bc = logging.config.BaseConfigurator(d)
2765 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
2766 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
2767 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
2768 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
2769 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
2770 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
2771 v = bc.convert('cfg://nest3')
2772 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
2773 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
2774 self.assertRaises(ValueError, bc.convert, 'cfg://!')
2775 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002776
2777class ManagerTest(BaseTest):
2778 def test_manager_loggerclass(self):
2779 logged = []
2780
2781 class MyLogger(logging.Logger):
2782 def _log(self, level, msg, args, exc_info=None, extra=None):
2783 logged.append(msg)
2784
2785 man = logging.Manager(None)
2786 self.assertRaises(TypeError, man.setLoggerClass, int)
2787 man.setLoggerClass(MyLogger)
2788 logger = man.getLogger('test')
2789 logger.warning('should appear in logged')
2790 logging.warning('should not appear in logged')
2791
2792 self.assertEqual(logged, ['should appear in logged'])
2793
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002794 def test_set_log_record_factory(self):
2795 man = logging.Manager(None)
2796 expected = object()
2797 man.setLogRecordFactory(expected)
2798 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002799
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002800class ChildLoggerTest(BaseTest):
2801 def test_child_loggers(self):
2802 r = logging.getLogger()
2803 l1 = logging.getLogger('abc')
2804 l2 = logging.getLogger('def.ghi')
2805 c1 = r.getChild('xyz')
2806 c2 = r.getChild('uvw.xyz')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02002807 self.assertIs(c1, logging.getLogger('xyz'))
2808 self.assertIs(c2, logging.getLogger('uvw.xyz'))
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002809 c1 = l1.getChild('def')
2810 c2 = c1.getChild('ghi')
2811 c3 = l1.getChild('def.ghi')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02002812 self.assertIs(c1, logging.getLogger('abc.def'))
2813 self.assertIs(c2, logging.getLogger('abc.def.ghi'))
2814 self.assertIs(c2, c3)
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002815
2816
Vinay Sajip6fac8172010-10-19 20:44:14 +00002817class DerivedLogRecord(logging.LogRecord):
2818 pass
2819
Vinay Sajip61561522010-12-03 11:50:38 +00002820class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00002821
2822 def setUp(self):
2823 class CheckingFilter(logging.Filter):
2824 def __init__(self, cls):
2825 self.cls = cls
2826
2827 def filter(self, record):
2828 t = type(record)
2829 if t is not self.cls:
2830 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
2831 self.cls)
2832 raise TypeError(msg)
2833 return True
2834
2835 BaseTest.setUp(self)
2836 self.filter = CheckingFilter(DerivedLogRecord)
2837 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00002838 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00002839
2840 def tearDown(self):
2841 self.root_logger.removeFilter(self.filter)
2842 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00002843 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002844
2845 def test_logrecord_class(self):
2846 self.assertRaises(TypeError, self.root_logger.warning,
2847 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00002848 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002849 self.root_logger.error(self.next_message())
2850 self.assert_log_lines([
2851 ('root', 'ERROR', '2'),
2852 ])
2853
2854
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002855class QueueHandlerTest(BaseTest):
2856 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002857 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002858
2859 def setUp(self):
2860 BaseTest.setUp(self)
2861 self.queue = queue.Queue(-1)
2862 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
2863 self.que_logger = logging.getLogger('que')
2864 self.que_logger.propagate = False
2865 self.que_logger.setLevel(logging.WARNING)
2866 self.que_logger.addHandler(self.que_hdlr)
2867
2868 def tearDown(self):
2869 self.que_hdlr.close()
2870 BaseTest.tearDown(self)
2871
2872 def test_queue_handler(self):
2873 self.que_logger.debug(self.next_message())
2874 self.assertRaises(queue.Empty, self.queue.get_nowait)
2875 self.que_logger.info(self.next_message())
2876 self.assertRaises(queue.Empty, self.queue.get_nowait)
2877 msg = self.next_message()
2878 self.que_logger.warning(msg)
2879 data = self.queue.get_nowait()
2880 self.assertTrue(isinstance(data, logging.LogRecord))
2881 self.assertEqual(data.name, self.que_logger.name)
2882 self.assertEqual((data.msg, data.args), (msg, None))
2883
Victor Stinnercafa2ef2011-05-02 16:11:28 +02002884 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
2885 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01002886 def test_queue_listener(self):
2887 handler = TestHandler(Matcher())
2888 listener = logging.handlers.QueueListener(self.queue, handler)
2889 listener.start()
2890 try:
2891 self.que_logger.warning(self.next_message())
2892 self.que_logger.error(self.next_message())
2893 self.que_logger.critical(self.next_message())
2894 finally:
2895 listener.stop()
2896 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
2897 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
2898 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
2899
Vinay Sajip37eb3382011-04-26 20:26:41 +01002900ZERO = datetime.timedelta(0)
2901
2902class UTC(datetime.tzinfo):
2903 def utcoffset(self, dt):
2904 return ZERO
2905
2906 dst = utcoffset
2907
2908 def tzname(self, dt):
2909 return 'UTC'
2910
2911utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01002912
Vinay Sajipa39c5712010-10-25 13:57:39 +00002913class FormatterTest(unittest.TestCase):
2914 def setUp(self):
2915 self.common = {
2916 'name': 'formatter.test',
2917 'level': logging.DEBUG,
2918 'pathname': os.path.join('path', 'to', 'dummy.ext'),
2919 'lineno': 42,
2920 'exc_info': None,
2921 'func': None,
2922 'msg': 'Message with %d %s',
2923 'args': (2, 'placeholders'),
2924 }
2925 self.variants = {
2926 }
2927
2928 def get_record(self, name=None):
2929 result = dict(self.common)
2930 if name is not None:
2931 result.update(self.variants[name])
2932 return logging.makeLogRecord(result)
2933
2934 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002935 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002936 r = self.get_record()
2937 f = logging.Formatter('${%(message)s}')
2938 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
2939 f = logging.Formatter('%(random)s')
2940 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002941 self.assertFalse(f.usesTime())
2942 f = logging.Formatter('%(asctime)s')
2943 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002944 f = logging.Formatter('%(asctime)-15s')
2945 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002946 f = logging.Formatter('asctime')
2947 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002948
2949 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002950 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002951 r = self.get_record()
2952 f = logging.Formatter('$%{message}%$', style='{')
2953 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2954 f = logging.Formatter('{random}', style='{')
2955 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002956 self.assertFalse(f.usesTime())
2957 f = logging.Formatter('{asctime}', style='{')
2958 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002959 f = logging.Formatter('{asctime!s:15}', style='{')
2960 self.assertTrue(f.usesTime())
2961 f = logging.Formatter('{asctime:15}', style='{')
2962 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002963 f = logging.Formatter('asctime', style='{')
2964 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002965
2966 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002967 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002968 r = self.get_record()
2969 f = logging.Formatter('$message', style='$')
2970 self.assertEqual(f.format(r), 'Message with 2 placeholders')
2971 f = logging.Formatter('$$%${message}%$$', style='$')
2972 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2973 f = logging.Formatter('${random}', style='$')
2974 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002975 self.assertFalse(f.usesTime())
2976 f = logging.Formatter('${asctime}', style='$')
2977 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002978 f = logging.Formatter('${asctime', style='$')
2979 self.assertFalse(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002980 f = logging.Formatter('$asctime', style='$')
2981 self.assertTrue(f.usesTime())
2982 f = logging.Formatter('asctime', style='$')
2983 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002984
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002985 def test_invalid_style(self):
2986 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
2987
Vinay Sajip86a96ce2011-04-27 08:30:30 +01002988 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002989 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01002990 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
2991 # We use None to indicate we want the local timezone
2992 # We're essentially converting a UTC time to local time
2993 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002994 r.msecs = 123
2995 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01002996 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002997 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
2998 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01002999 f.format(r)
3000 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
3001
3002class TestBufferingFormatter(logging.BufferingFormatter):
3003 def formatHeader(self, records):
3004 return '[(%d)' % len(records)
3005
3006 def formatFooter(self, records):
3007 return '(%d)]' % len(records)
3008
3009class BufferingFormatterTest(unittest.TestCase):
3010 def setUp(self):
3011 self.records = [
3012 logging.makeLogRecord({'msg': 'one'}),
3013 logging.makeLogRecord({'msg': 'two'}),
3014 ]
3015
3016 def test_default(self):
3017 f = logging.BufferingFormatter()
3018 self.assertEqual('', f.format([]))
3019 self.assertEqual('onetwo', f.format(self.records))
3020
3021 def test_custom(self):
3022 f = TestBufferingFormatter()
3023 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
3024 lf = logging.Formatter('<%(message)s>')
3025 f = TestBufferingFormatter(lf)
3026 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003027
3028class ExceptionTest(BaseTest):
3029 def test_formatting(self):
3030 r = self.root_logger
3031 h = RecordingHandler()
3032 r.addHandler(h)
3033 try:
3034 raise RuntimeError('deliberate mistake')
3035 except:
3036 logging.exception('failed', stack_info=True)
3037 r.removeHandler(h)
3038 h.close()
3039 r = h.records[0]
3040 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
3041 'call last):\n'))
3042 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
3043 'deliberate mistake'))
3044 self.assertTrue(r.stack_info.startswith('Stack (most recent '
3045 'call last):\n'))
3046 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
3047 'stack_info=True)'))
3048
3049
Vinay Sajip5a27d402010-12-10 11:42:57 +00003050class LastResortTest(BaseTest):
3051 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003052 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00003053 root = self.root_logger
3054 root.removeHandler(self.root_hdlr)
3055 old_stderr = sys.stderr
3056 old_lastresort = logging.lastResort
3057 old_raise_exceptions = logging.raiseExceptions
3058 try:
3059 sys.stderr = sio = io.StringIO()
Vinay Sajip8188f582011-07-25 19:58:13 +01003060 root.debug('This should not appear')
3061 self.assertEqual(sio.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00003062 root.warning('This is your final chance!')
3063 self.assertEqual(sio.getvalue(), 'This is your final chance!\n')
3064 #No handlers and no last resort, so 'No handlers' message
3065 logging.lastResort = None
3066 sys.stderr = sio = io.StringIO()
3067 root.warning('This is your final chance!')
3068 self.assertEqual(sio.getvalue(), 'No handlers could be found for logger "root"\n')
3069 # 'No handlers' message only printed once
3070 sys.stderr = sio = io.StringIO()
3071 root.warning('This is your final chance!')
3072 self.assertEqual(sio.getvalue(), '')
3073 root.manager.emittedNoHandlerWarning = False
3074 #If raiseExceptions is False, no message is printed
3075 logging.raiseExceptions = False
3076 sys.stderr = sio = io.StringIO()
3077 root.warning('This is your final chance!')
3078 self.assertEqual(sio.getvalue(), '')
3079 finally:
3080 sys.stderr = old_stderr
3081 root.addHandler(self.root_hdlr)
3082 logging.lastResort = old_lastresort
3083 logging.raiseExceptions = old_raise_exceptions
3084
3085
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003086class FakeHandler:
3087
3088 def __init__(self, identifier, called):
3089 for method in ('acquire', 'flush', 'close', 'release'):
3090 setattr(self, method, self.record_call(identifier, method, called))
3091
3092 def record_call(self, identifier, method_name, called):
3093 def inner():
3094 called.append('{} - {}'.format(identifier, method_name))
3095 return inner
3096
3097
3098class RecordingHandler(logging.NullHandler):
3099
3100 def __init__(self, *args, **kwargs):
3101 super(RecordingHandler, self).__init__(*args, **kwargs)
3102 self.records = []
3103
3104 def handle(self, record):
3105 """Keep track of all the emitted records."""
3106 self.records.append(record)
3107
3108
3109class ShutdownTest(BaseTest):
3110
Vinay Sajip5e66b162011-04-20 15:41:14 +01003111 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003112
3113 def setUp(self):
3114 super(ShutdownTest, self).setUp()
3115 self.called = []
3116
3117 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003118 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003119
3120 def raise_error(self, error):
3121 def inner():
3122 raise error()
3123 return inner
3124
3125 def test_no_failure(self):
3126 # create some fake handlers
3127 handler0 = FakeHandler(0, self.called)
3128 handler1 = FakeHandler(1, self.called)
3129 handler2 = FakeHandler(2, self.called)
3130
3131 # create live weakref to those handlers
3132 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
3133
3134 logging.shutdown(handlerList=list(handlers))
3135
3136 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
3137 '1 - acquire', '1 - flush', '1 - close', '1 - release',
3138 '0 - acquire', '0 - flush', '0 - close', '0 - release']
3139 self.assertEqual(expected, self.called)
3140
3141 def _test_with_failure_in_method(self, method, error):
3142 handler = FakeHandler(0, self.called)
3143 setattr(handler, method, self.raise_error(error))
3144 handlers = [logging.weakref.ref(handler)]
3145
3146 logging.shutdown(handlerList=list(handlers))
3147
3148 self.assertEqual('0 - release', self.called[-1])
3149
3150 def test_with_ioerror_in_acquire(self):
3151 self._test_with_failure_in_method('acquire', IOError)
3152
3153 def test_with_ioerror_in_flush(self):
3154 self._test_with_failure_in_method('flush', IOError)
3155
3156 def test_with_ioerror_in_close(self):
3157 self._test_with_failure_in_method('close', IOError)
3158
3159 def test_with_valueerror_in_acquire(self):
3160 self._test_with_failure_in_method('acquire', ValueError)
3161
3162 def test_with_valueerror_in_flush(self):
3163 self._test_with_failure_in_method('flush', ValueError)
3164
3165 def test_with_valueerror_in_close(self):
3166 self._test_with_failure_in_method('close', ValueError)
3167
3168 def test_with_other_error_in_acquire_without_raise(self):
3169 logging.raiseExceptions = False
3170 self._test_with_failure_in_method('acquire', IndexError)
3171
3172 def test_with_other_error_in_flush_without_raise(self):
3173 logging.raiseExceptions = False
3174 self._test_with_failure_in_method('flush', IndexError)
3175
3176 def test_with_other_error_in_close_without_raise(self):
3177 logging.raiseExceptions = False
3178 self._test_with_failure_in_method('close', IndexError)
3179
3180 def test_with_other_error_in_acquire_with_raise(self):
3181 logging.raiseExceptions = True
3182 self.assertRaises(IndexError, self._test_with_failure_in_method,
3183 'acquire', IndexError)
3184
3185 def test_with_other_error_in_flush_with_raise(self):
3186 logging.raiseExceptions = True
3187 self.assertRaises(IndexError, self._test_with_failure_in_method,
3188 'flush', IndexError)
3189
3190 def test_with_other_error_in_close_with_raise(self):
3191 logging.raiseExceptions = True
3192 self.assertRaises(IndexError, self._test_with_failure_in_method,
3193 'close', IndexError)
3194
3195
3196class ModuleLevelMiscTest(BaseTest):
3197
Vinay Sajip5e66b162011-04-20 15:41:14 +01003198 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003199
3200 def test_disable(self):
3201 old_disable = logging.root.manager.disable
3202 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003203 self.assertEqual(old_disable, 0)
3204 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003205
3206 logging.disable(83)
3207 self.assertEqual(logging.root.manager.disable, 83)
3208
3209 def _test_log(self, method, level=None):
3210 called = []
3211 patch(self, logging, 'basicConfig',
Vinay Sajip00bdbe12011-04-22 00:17:46 +01003212 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003213
3214 recording = RecordingHandler()
3215 logging.root.addHandler(recording)
3216
3217 log_method = getattr(logging, method)
3218 if level is not None:
3219 log_method(level, "test me: %r", recording)
3220 else:
3221 log_method("test me: %r", recording)
3222
3223 self.assertEqual(len(recording.records), 1)
3224 record = recording.records[0]
3225 self.assertEqual(record.getMessage(), "test me: %r" % recording)
3226
3227 expected_level = level if level is not None else getattr(logging, method.upper())
3228 self.assertEqual(record.levelno, expected_level)
3229
3230 # basicConfig was not called!
3231 self.assertEqual(called, [])
3232
3233 def test_log(self):
3234 self._test_log('log', logging.ERROR)
3235
3236 def test_debug(self):
3237 self._test_log('debug')
3238
3239 def test_info(self):
3240 self._test_log('info')
3241
3242 def test_warning(self):
3243 self._test_log('warning')
3244
3245 def test_error(self):
3246 self._test_log('error')
3247
3248 def test_critical(self):
3249 self._test_log('critical')
3250
3251 def test_set_logger_class(self):
3252 self.assertRaises(TypeError, logging.setLoggerClass, object)
3253
3254 class MyLogger(logging.Logger):
3255 pass
3256
3257 logging.setLoggerClass(MyLogger)
3258 self.assertEqual(logging.getLoggerClass(), MyLogger)
3259
3260 logging.setLoggerClass(logging.Logger)
3261 self.assertEqual(logging.getLoggerClass(), logging.Logger)
3262
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003263class LogRecordTest(BaseTest):
3264 def test_str_rep(self):
3265 r = logging.makeLogRecord({})
3266 s = str(r)
3267 self.assertTrue(s.startswith('<LogRecord: '))
3268 self.assertTrue(s.endswith('>'))
3269
3270 def test_dict_arg(self):
3271 h = RecordingHandler()
3272 r = logging.getLogger()
3273 r.addHandler(h)
3274 d = {'less' : 'more' }
3275 logging.warning('less is %(less)s', d)
3276 self.assertIs(h.records[0].args, d)
3277 self.assertEqual(h.records[0].message, 'less is more')
3278 r.removeHandler(h)
3279 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003280
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003281 def test_multiprocessing(self):
3282 r = logging.makeLogRecord({})
3283 self.assertEqual(r.processName, 'MainProcess')
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003284 try:
3285 import multiprocessing as mp
3286 r = logging.makeLogRecord({})
3287 self.assertEqual(r.processName, mp.current_process().name)
3288 except ImportError:
3289 pass
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003290
3291 def test_optional(self):
3292 r = logging.makeLogRecord({})
3293 NOT_NONE = self.assertIsNotNone
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003294 if threading:
3295 NOT_NONE(r.thread)
3296 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003297 NOT_NONE(r.process)
3298 NOT_NONE(r.processName)
3299 log_threads = logging.logThreads
3300 log_processes = logging.logProcesses
3301 log_multiprocessing = logging.logMultiprocessing
3302 try:
3303 logging.logThreads = False
3304 logging.logProcesses = False
3305 logging.logMultiprocessing = False
3306 r = logging.makeLogRecord({})
3307 NONE = self.assertIsNone
3308 NONE(r.thread)
3309 NONE(r.threadName)
3310 NONE(r.process)
3311 NONE(r.processName)
3312 finally:
3313 logging.logThreads = log_threads
3314 logging.logProcesses = log_processes
3315 logging.logMultiprocessing = log_multiprocessing
3316
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003317class BasicConfigTest(unittest.TestCase):
3318
Vinay Sajip95bf5042011-04-20 11:50:56 +01003319 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003320
3321 def setUp(self):
3322 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01003323 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01003324 self.saved_handlers = logging._handlers.copy()
3325 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003326 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003327 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003328 logging.root.handlers = []
3329
3330 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01003331 for h in logging.root.handlers[:]:
3332 logging.root.removeHandler(h)
3333 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003334 super(BasicConfigTest, self).tearDown()
3335
Vinay Sajip3def7e02011-04-20 10:58:06 +01003336 def cleanup(self):
3337 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01003338 logging._handlers.clear()
3339 logging._handlers.update(self.saved_handlers)
3340 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003341 logging.root.level = self.original_logging_level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003342
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003343 def test_no_kwargs(self):
3344 logging.basicConfig()
3345
3346 # handler defaults to a StreamHandler to sys.stderr
3347 self.assertEqual(len(logging.root.handlers), 1)
3348 handler = logging.root.handlers[0]
3349 self.assertIsInstance(handler, logging.StreamHandler)
3350 self.assertEqual(handler.stream, sys.stderr)
3351
3352 formatter = handler.formatter
3353 # format defaults to logging.BASIC_FORMAT
3354 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
3355 # datefmt defaults to None
3356 self.assertIsNone(formatter.datefmt)
3357 # style defaults to %
3358 self.assertIsInstance(formatter._style, logging.PercentStyle)
3359
Florent Xiclunae41f0de2011-11-11 19:39:25 +01003360 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01003361 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003362
3363 def test_filename(self):
3364 logging.basicConfig(filename='test.log')
3365
3366 self.assertEqual(len(logging.root.handlers), 1)
3367 handler = logging.root.handlers[0]
3368 self.assertIsInstance(handler, logging.FileHandler)
3369
3370 expected = logging.FileHandler('test.log', 'a')
3371 self.addCleanup(expected.close)
3372 self.assertEqual(handler.stream.mode, expected.stream.mode)
3373 self.assertEqual(handler.stream.name, expected.stream.name)
3374
3375 def test_filemode(self):
3376 logging.basicConfig(filename='test.log', filemode='wb')
3377
3378 handler = logging.root.handlers[0]
3379 expected = logging.FileHandler('test.log', 'wb')
3380 self.addCleanup(expected.close)
3381 self.assertEqual(handler.stream.mode, expected.stream.mode)
3382
3383 def test_stream(self):
3384 stream = io.StringIO()
3385 self.addCleanup(stream.close)
3386 logging.basicConfig(stream=stream)
3387
3388 self.assertEqual(len(logging.root.handlers), 1)
3389 handler = logging.root.handlers[0]
3390 self.assertIsInstance(handler, logging.StreamHandler)
3391 self.assertEqual(handler.stream, stream)
3392
3393 def test_format(self):
3394 logging.basicConfig(format='foo')
3395
3396 formatter = logging.root.handlers[0].formatter
3397 self.assertEqual(formatter._style._fmt, 'foo')
3398
3399 def test_datefmt(self):
3400 logging.basicConfig(datefmt='bar')
3401
3402 formatter = logging.root.handlers[0].formatter
3403 self.assertEqual(formatter.datefmt, 'bar')
3404
3405 def test_style(self):
3406 logging.basicConfig(style='$')
3407
3408 formatter = logging.root.handlers[0].formatter
3409 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
3410
3411 def test_level(self):
3412 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003413 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003414
3415 logging.basicConfig(level=57)
3416 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003417 # Test that second call has no effect
3418 logging.basicConfig(level=58)
3419 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003420
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003421 def test_incompatible(self):
3422 assertRaises = self.assertRaises
3423 handlers = [logging.StreamHandler()]
3424 stream = sys.stderr
3425 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3426 stream=stream)
3427 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3428 handlers=handlers)
3429 assertRaises(ValueError, logging.basicConfig, stream=stream,
3430 handlers=handlers)
3431
3432 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003433 handlers = [
3434 logging.StreamHandler(),
3435 logging.StreamHandler(sys.stdout),
3436 logging.StreamHandler(),
3437 ]
3438 f = logging.Formatter()
3439 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003440 logging.basicConfig(handlers=handlers)
3441 self.assertIs(handlers[0], logging.root.handlers[0])
3442 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003443 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003444 self.assertIsNotNone(handlers[0].formatter)
3445 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003446 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003447 self.assertIs(handlers[0].formatter, handlers[1].formatter)
3448
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003449 def _test_log(self, method, level=None):
3450 # logging.root has no handlers so basicConfig should be called
3451 called = []
3452
3453 old_basic_config = logging.basicConfig
3454 def my_basic_config(*a, **kw):
3455 old_basic_config()
3456 old_level = logging.root.level
3457 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003458 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003459 called.append((a, kw))
3460
3461 patch(self, logging, 'basicConfig', my_basic_config)
3462
3463 log_method = getattr(logging, method)
3464 if level is not None:
3465 log_method(level, "test me")
3466 else:
3467 log_method("test me")
3468
3469 # basicConfig was called with no arguments
3470 self.assertEqual(called, [((), {})])
3471
3472 def test_log(self):
3473 self._test_log('log', logging.WARNING)
3474
3475 def test_debug(self):
3476 self._test_log('debug')
3477
3478 def test_info(self):
3479 self._test_log('info')
3480
3481 def test_warning(self):
3482 self._test_log('warning')
3483
3484 def test_error(self):
3485 self._test_log('error')
3486
3487 def test_critical(self):
3488 self._test_log('critical')
3489
3490
3491class LoggerAdapterTest(unittest.TestCase):
3492
3493 def setUp(self):
3494 super(LoggerAdapterTest, self).setUp()
3495 old_handler_list = logging._handlerList[:]
3496
3497 self.recording = RecordingHandler()
3498 self.logger = logging.root
3499 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003500 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003501 self.addCleanup(self.recording.close)
3502
3503 def cleanup():
3504 logging._handlerList[:] = old_handler_list
3505
3506 self.addCleanup(cleanup)
3507 self.addCleanup(logging.shutdown)
3508 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
3509
3510 def test_exception(self):
3511 msg = 'testing exception: %r'
3512 exc = None
3513 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003514 1 / 0
3515 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003516 exc = e
3517 self.adapter.exception(msg, self.recording)
3518
3519 self.assertEqual(len(self.recording.records), 1)
3520 record = self.recording.records[0]
3521 self.assertEqual(record.levelno, logging.ERROR)
3522 self.assertEqual(record.msg, msg)
3523 self.assertEqual(record.args, (self.recording,))
3524 self.assertEqual(record.exc_info,
3525 (exc.__class__, exc, exc.__traceback__))
3526
3527 def test_critical(self):
3528 msg = 'critical test! %r'
3529 self.adapter.critical(msg, self.recording)
3530
3531 self.assertEqual(len(self.recording.records), 1)
3532 record = self.recording.records[0]
3533 self.assertEqual(record.levelno, logging.CRITICAL)
3534 self.assertEqual(record.msg, msg)
3535 self.assertEqual(record.args, (self.recording,))
3536
3537 def test_is_enabled_for(self):
3538 old_disable = self.adapter.logger.manager.disable
3539 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003540 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
3541 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003542 self.assertFalse(self.adapter.isEnabledFor(32))
3543
3544 def test_has_handlers(self):
3545 self.assertTrue(self.adapter.hasHandlers())
3546
3547 for handler in self.logger.handlers:
3548 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003549
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003550 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003551 self.assertFalse(self.adapter.hasHandlers())
3552
3553
3554class LoggerTest(BaseTest):
3555
3556 def setUp(self):
3557 super(LoggerTest, self).setUp()
3558 self.recording = RecordingHandler()
3559 self.logger = logging.Logger(name='blah')
3560 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003561 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003562 self.addCleanup(self.recording.close)
3563 self.addCleanup(logging.shutdown)
3564
3565 def test_set_invalid_level(self):
3566 self.assertRaises(TypeError, self.logger.setLevel, object())
3567
3568 def test_exception(self):
3569 msg = 'testing exception: %r'
3570 exc = None
3571 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003572 1 / 0
3573 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003574 exc = e
3575 self.logger.exception(msg, self.recording)
3576
3577 self.assertEqual(len(self.recording.records), 1)
3578 record = self.recording.records[0]
3579 self.assertEqual(record.levelno, logging.ERROR)
3580 self.assertEqual(record.msg, msg)
3581 self.assertEqual(record.args, (self.recording,))
3582 self.assertEqual(record.exc_info,
3583 (exc.__class__, exc, exc.__traceback__))
3584
3585 def test_log_invalid_level_with_raise(self):
3586 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003587 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003588
3589 logging.raiseExceptions = True
3590 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
3591
3592 def test_log_invalid_level_no_raise(self):
3593 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003594 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003595
3596 logging.raiseExceptions = False
3597 self.logger.log('10', 'test message') # no exception happens
3598
3599 def test_find_caller_with_stack_info(self):
3600 called = []
3601 patch(self, logging.traceback, 'print_stack',
3602 lambda f, file: called.append(file.getvalue()))
3603
3604 self.logger.findCaller(stack_info=True)
3605
3606 self.assertEqual(len(called), 1)
3607 self.assertEqual('Stack (most recent call last):\n', called[0])
3608
3609 def test_make_record_with_extra_overwrite(self):
3610 name = 'my record'
3611 level = 13
3612 fn = lno = msg = args = exc_info = func = sinfo = None
3613 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
3614 exc_info, func, sinfo)
3615
3616 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
3617 extra = {key: 'some value'}
3618 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
3619 fn, lno, msg, args, exc_info,
3620 extra=extra, sinfo=sinfo)
3621
3622 def test_make_record_with_extra_no_overwrite(self):
3623 name = 'my record'
3624 level = 13
3625 fn = lno = msg = args = exc_info = func = sinfo = None
3626 extra = {'valid_key': 'some value'}
3627 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
3628 exc_info, extra=extra, sinfo=sinfo)
3629 self.assertIn('valid_key', result.__dict__)
3630
3631 def test_has_handlers(self):
3632 self.assertTrue(self.logger.hasHandlers())
3633
3634 for handler in self.logger.handlers:
3635 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003636 self.assertFalse(self.logger.hasHandlers())
3637
3638 def test_has_handlers_no_propagate(self):
3639 child_logger = logging.getLogger('blah.child')
3640 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003641 self.assertFalse(child_logger.hasHandlers())
3642
3643 def test_is_enabled_for(self):
3644 old_disable = self.logger.manager.disable
3645 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003646 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003647 self.assertFalse(self.logger.isEnabledFor(22))
3648
Florent Xicluna5252f9f2011-11-07 19:43:05 +01003649 def test_root_logger_aliases(self):
3650 root = logging.getLogger()
3651 self.assertIs(root, logging.root)
3652 self.assertIs(root, logging.getLogger(None))
3653 self.assertIs(root, logging.getLogger(''))
3654 self.assertIs(root, logging.getLogger('foo').root)
3655 self.assertIs(root, logging.getLogger('foo.bar').root)
3656 self.assertIs(root, logging.getLogger('foo').parent)
3657
3658 self.assertIsNot(root, logging.getLogger('\0'))
3659 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
3660
3661 def test_invalid_names(self):
3662 self.assertRaises(TypeError, logging.getLogger, any)
3663 self.assertRaises(TypeError, logging.getLogger, b'foo')
3664
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003665
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003666class BaseFileTest(BaseTest):
3667 "Base class for handler tests that write log files"
3668
3669 def setUp(self):
3670 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003671 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
3672 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003673 self.rmfiles = []
3674
3675 def tearDown(self):
3676 for fn in self.rmfiles:
3677 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003678 if os.path.exists(self.fn):
3679 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00003680 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003681
3682 def assertLogFile(self, filename):
3683 "Assert a log file is there and register it for deletion"
3684 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01003685 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003686 self.rmfiles.append(filename)
3687
3688
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003689class FileHandlerTest(BaseFileTest):
3690 def test_delay(self):
3691 os.unlink(self.fn)
3692 fh = logging.FileHandler(self.fn, delay=True)
3693 self.assertIsNone(fh.stream)
3694 self.assertFalse(os.path.exists(self.fn))
3695 fh.handle(logging.makeLogRecord({}))
3696 self.assertIsNotNone(fh.stream)
3697 self.assertTrue(os.path.exists(self.fn))
3698 fh.close()
3699
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003700class RotatingFileHandlerTest(BaseFileTest):
3701 def next_rec(self):
3702 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
3703 self.next_message(), None, None, None)
3704
3705 def test_should_not_rollover(self):
3706 # If maxbytes is zero rollover never occurs
3707 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
3708 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00003709 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003710
3711 def test_should_rollover(self):
3712 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
3713 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00003714 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003715
3716 def test_file_created(self):
3717 # checks that the file is created and assumes it was created
3718 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003719 rh = logging.handlers.RotatingFileHandler(self.fn)
3720 rh.emit(self.next_rec())
3721 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00003722 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003723
3724 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00003725 def namer(name):
3726 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003727 rh = logging.handlers.RotatingFileHandler(
3728 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003729 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003730 rh.emit(self.next_rec())
3731 self.assertLogFile(self.fn)
3732 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003733 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003734 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003735 self.assertLogFile(namer(self.fn + ".2"))
3736 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
3737 rh.close()
3738
Eric V. Smith851cad72012-03-11 22:46:04 -07003739 @requires_zlib
Vinay Sajip23b94d02012-01-04 12:02:26 +00003740 def test_rotator(self):
3741 def namer(name):
3742 return name + ".gz"
3743
3744 def rotator(source, dest):
3745 with open(source, "rb") as sf:
3746 data = sf.read()
3747 compressed = zlib.compress(data, 9)
3748 with open(dest, "wb") as df:
3749 df.write(compressed)
3750 os.remove(source)
3751
3752 rh = logging.handlers.RotatingFileHandler(
3753 self.fn, backupCount=2, maxBytes=1)
3754 rh.rotator = rotator
3755 rh.namer = namer
3756 m1 = self.next_rec()
3757 rh.emit(m1)
3758 self.assertLogFile(self.fn)
3759 m2 = self.next_rec()
3760 rh.emit(m2)
3761 fn = namer(self.fn + ".1")
3762 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003763 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00003764 with open(fn, "rb") as f:
3765 compressed = f.read()
3766 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003767 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003768 rh.emit(self.next_rec())
3769 fn = namer(self.fn + ".2")
3770 self.assertLogFile(fn)
3771 with open(fn, "rb") as f:
3772 compressed = f.read()
3773 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003774 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003775 rh.emit(self.next_rec())
3776 fn = namer(self.fn + ".2")
3777 with open(fn, "rb") as f:
3778 compressed = f.read()
3779 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003780 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003781 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00003782 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003783
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003784class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01003785 # other test methods added below
3786 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01003787 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
3788 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00003789 fmt = logging.Formatter('%(asctime)s %(message)s')
3790 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003791 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003792 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01003793 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003794 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00003795 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003796 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01003797 fh.close()
3798 # At this point, we should have a recent rotated file which we
3799 # can test for the existence of. However, in practice, on some
3800 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01003801 # in time to go to look for the log file. So, we go back a fair
3802 # bit, and stop as soon as we see a rotated file. In theory this
3803 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01003804 found = False
3805 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01003806 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01003807 for secs in range(GO_BACK):
3808 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01003809 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
3810 found = os.path.exists(fn)
3811 if found:
3812 self.rmfiles.append(fn)
3813 break
Vinay Sajip672c5812011-05-13 07:09:40 +01003814 msg = 'No rotated files found, went back %d seconds' % GO_BACK
3815 if not found:
3816 #print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01003817 dn, fn = os.path.split(self.fn)
3818 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02003819 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
3820 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00003821 for f in files:
3822 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00003823 path = os.path.join(dn, f)
3824 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00003825 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01003826 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003827
Vinay Sajip0372e102011-05-05 12:59:14 +01003828 def test_invalid(self):
3829 assertRaises = self.assertRaises
3830 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003831 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003832 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003833 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003834 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003835 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003836
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003837def secs(**kw):
3838 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
3839
3840for when, exp in (('S', 1),
3841 ('M', 60),
3842 ('H', 60 * 60),
3843 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00003844 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003845 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00003846 ('W0', secs(days=4, hours=24)),
3847 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003848 def test_compute_rollover(self, when=when, exp=exp):
3849 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00003850 self.fn, when=when, interval=1, backupCount=0, utc=True)
3851 currentTime = 0.0
3852 actual = rh.computeRollover(currentTime)
3853 if exp != actual:
3854 # Failures occur on some systems for MIDNIGHT and W0.
3855 # Print detailed calculation for MIDNIGHT so we can try to see
3856 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00003857 if when == 'MIDNIGHT':
3858 try:
3859 if rh.utc:
3860 t = time.gmtime(currentTime)
3861 else:
3862 t = time.localtime(currentTime)
3863 currentHour = t[3]
3864 currentMinute = t[4]
3865 currentSecond = t[5]
3866 # r is the number of seconds left between now and midnight
3867 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
3868 currentMinute) * 60 +
3869 currentSecond)
3870 result = currentTime + r
3871 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
3872 print('currentHour: %s' % currentHour, file=sys.stderr)
3873 print('currentMinute: %s' % currentMinute, file=sys.stderr)
3874 print('currentSecond: %s' % currentSecond, file=sys.stderr)
3875 print('r: %s' % r, file=sys.stderr)
3876 print('result: %s' % result, file=sys.stderr)
3877 except Exception:
3878 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
3879 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00003880 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003881 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
3882
Vinay Sajip60ccd822011-05-09 17:32:09 +01003883
3884@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil required for this test.')
3885class NTEventLogHandlerTest(BaseTest):
3886 def test_basic(self):
3887 logtype = 'Application'
3888 elh = win32evtlog.OpenEventLog(None, logtype)
3889 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
3890 h = logging.handlers.NTEventLogHandler('test_logging')
3891 r = logging.makeLogRecord({'msg': 'Test Log Message'})
3892 h.handle(r)
3893 h.close()
3894 # Now see if the event is recorded
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02003895 self.assertLess(num_recs, win32evtlog.GetNumberOfEventLogRecords(elh))
Vinay Sajip60ccd822011-05-09 17:32:09 +01003896 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
3897 win32evtlog.EVENTLOG_SEQUENTIAL_READ
3898 found = False
3899 GO_BACK = 100
3900 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
3901 for e in events:
3902 if e.SourceName != 'test_logging':
3903 continue
3904 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
3905 if msg != 'Test Log Message\r\n':
3906 continue
3907 found = True
3908 break
3909 msg = 'Record not found in event log, went back %d records' % GO_BACK
3910 self.assertTrue(found, msg=msg)
3911
Christian Heimes180510d2008-03-03 19:15:45 +00003912# Set the locale to the platform-dependent default. I have no idea
3913# why the test does this, but in any case we save the current locale
3914# first and restore it at the end.
3915@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00003916def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +00003917 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003918 CustomLevelsAndFiltersTest, HandlerTest, MemoryHandlerTest,
Vinay Sajip7367d082011-05-02 13:17:27 +01003919 ConfigFileTest, SocketHandlerTest, DatagramHandlerTest,
3920 MemoryTest, EncodingTest, WarningsTest, ConfigDictTest,
3921 ManagerTest, FormatterTest, BufferingFormatterTest,
3922 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
3923 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest,
3924 BasicConfigTest, LoggerAdapterTest, LoggerTest,
3925 SMTPHandlerTest, FileHandlerTest, RotatingFileHandlerTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003926 LastResortTest, LogRecordTest, ExceptionTest,
Vinay Sajip60ccd822011-05-09 17:32:09 +01003927 SysLogHandlerTest, HTTPHandlerTest, NTEventLogHandlerTest,
Vinay Sajip89807a52011-02-26 16:06:02 +00003928 TimedRotatingFileHandlerTest
Vinay Sajipbc85d842010-09-17 23:35:29 +00003929 )
Jeremy Hylton096d9862003-07-18 03:19:20 +00003930
Christian Heimes180510d2008-03-03 19:15:45 +00003931if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00003932 test_main()