blob: a2a136b0cef419f31de81f4241666c9fff1ca1ff [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):
1444 # Kill the server
Vinay Sajip7367d082011-05-02 13:17:27 +01001445 self.server.stop(2.0)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001446 #The logging call should try to connect, which should fail
1447 try:
1448 raise RuntimeError('Deliberate mistake')
1449 except RuntimeError:
1450 self.root_logger.exception('Never sent')
1451 self.root_logger.error('Never sent, either')
1452 now = time.time()
1453 self.assertTrue(self.sock_hdlr.retryTime > now)
1454 time.sleep(self.sock_hdlr.retryTime - now + 0.001)
1455 self.root_logger.error('Nor this')
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001456
Vinay Sajip7367d082011-05-02 13:17:27 +01001457
1458@unittest.skipUnless(threading, 'Threading required for this test.')
1459class DatagramHandlerTest(BaseTest):
1460
1461 """Test for DatagramHandler."""
1462
1463 def setUp(self):
1464 """Set up a UDP server to receive log messages, and a DatagramHandler
1465 pointing to that server's address and port."""
1466 BaseTest.setUp(self)
1467 addr = ('localhost', 0)
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001468 self.server = server = TestUDPServer(addr, self.handle_datagram, 0.01)
Vinay Sajip7367d082011-05-02 13:17:27 +01001469 server.start()
1470 server.ready.wait()
1471 self.sock_hdlr = logging.handlers.DatagramHandler('localhost',
1472 server.port)
1473 self.log_output = ''
1474 self.root_logger.removeHandler(self.root_logger.handlers[0])
1475 self.root_logger.addHandler(self.sock_hdlr)
1476 self.handled = threading.Event()
1477
1478 def tearDown(self):
1479 """Shutdown the UDP server."""
1480 try:
1481 self.server.stop(2.0)
1482 self.root_logger.removeHandler(self.sock_hdlr)
1483 self.sock_hdlr.close()
1484 finally:
1485 BaseTest.tearDown(self)
1486
1487 def handle_datagram(self, request):
1488 slen = struct.pack('>L', 0) # length of prefix
1489 packet = request.packet[len(slen):]
1490 obj = pickle.loads(packet)
1491 record = logging.makeLogRecord(obj)
1492 self.log_output += record.msg + '\n'
1493 self.handled.set()
1494
1495 def test_output(self):
1496 # The log message sent to the DatagramHandler is properly received.
1497 logger = logging.getLogger("udp")
1498 logger.error("spam")
1499 self.handled.wait()
Vinay Sajip714b8dc2011-05-02 14:43:00 +01001500 self.handled.clear()
1501 logger.error("eggs")
1502 self.handled.wait()
1503 self.assertEqual(self.log_output, "spam\neggs\n")
Vinay Sajip7367d082011-05-02 13:17:27 +01001504
1505
1506@unittest.skipUnless(threading, 'Threading required for this test.')
1507class SysLogHandlerTest(BaseTest):
1508
1509 """Test for SysLogHandler using UDP."""
1510
1511 def setUp(self):
1512 """Set up a UDP server to receive log messages, and a SysLogHandler
1513 pointing to that server's address and port."""
1514 BaseTest.setUp(self)
1515 addr = ('localhost', 0)
1516 self.server = server = TestUDPServer(addr, self.handle_datagram,
1517 0.01)
1518 server.start()
1519 server.ready.wait()
1520 self.sl_hdlr = logging.handlers.SysLogHandler(('localhost',
1521 server.port))
1522 self.log_output = ''
1523 self.root_logger.removeHandler(self.root_logger.handlers[0])
1524 self.root_logger.addHandler(self.sl_hdlr)
1525 self.handled = threading.Event()
1526
1527 def tearDown(self):
1528 """Shutdown the UDP server."""
1529 try:
1530 self.server.stop(2.0)
1531 self.root_logger.removeHandler(self.sl_hdlr)
1532 self.sl_hdlr.close()
1533 finally:
1534 BaseTest.tearDown(self)
1535
1536 def handle_datagram(self, request):
1537 self.log_output = request.packet
1538 self.handled.set()
1539
1540 def test_output(self):
1541 # The log message sent to the SysLogHandler is properly received.
1542 logger = logging.getLogger("slh")
1543 logger.error("sp\xe4m")
1544 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001545 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001546 self.handled.clear()
1547 self.sl_hdlr.append_nul = False
1548 logger.error("sp\xe4m")
1549 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001550 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m')
Vinay Sajip2353e352011-06-27 15:40:06 +01001551 self.handled.clear()
1552 self.sl_hdlr.ident = "h\xe4m-"
1553 logger.error("sp\xe4m")
1554 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001555 self.assertEqual(self.log_output, b'<11>h\xc3\xa4m-sp\xc3\xa4m')
Vinay Sajip7367d082011-05-02 13:17:27 +01001556
1557
1558@unittest.skipUnless(threading, 'Threading required for this test.')
1559class HTTPHandlerTest(BaseTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01001560 """Test for HTTPHandler."""
1561
Vinay Sajip9ba87612011-05-21 11:32:15 +01001562 PEMFILE = """-----BEGIN RSA PRIVATE KEY-----
1563MIICXQIBAAKBgQDGT4xS5r91rbLJQK2nUDenBhBG6qFk+bVOjuAGC/LSHlAoBnvG
1564zQG3agOG+e7c5z2XT8m2ktORLqG3E4mYmbxgyhDrzP6ei2Anc+pszmnxPoK3Puh5
1565aXV+XKt0bU0C1m2+ACmGGJ0t3P408art82nOxBw8ZHgIg9Dtp6xIUCyOqwIDAQAB
1566AoGBAJFTnFboaKh5eUrIzjmNrKsG44jEyy+vWvHN/FgSC4l103HxhmWiuL5Lv3f7
15670tMp1tX7D6xvHwIG9VWvyKb/Cq9rJsDibmDVIOslnOWeQhG+XwJyitR0pq/KlJIB
15685LjORcBw795oKWOAi6RcOb1ON59tysEFYhAGQO9k6VL621gRAkEA/Gb+YXULLpbs
1569piXN3q4zcHzeaVANo69tUZ6TjaQqMeTxE4tOYM0G0ZoSeHEdaP59AOZGKXXNGSQy
15702z/MddcYGQJBAMkjLSYIpOLJY11ja8OwwswFG2hEzHe0cS9bzo++R/jc1bHA5R0Y
1571i6vA5iPi+wopPFvpytdBol7UuEBe5xZrxWMCQQCWxELRHiP2yWpEeLJ3gGDzoXMN
1572PydWjhRju7Bx3AzkTtf+D6lawz1+eGTuEss5i0JKBkMEwvwnN2s1ce+EuF4JAkBb
1573E96h1lAzkVW5OAfYOPY8RCPA90ZO/hoyg7PpSxR0ECuDrgERR8gXIeYUYfejBkEa
1574rab4CfRoVJKKM28Yq/xZAkBvuq670JRCwOgfUTdww7WpdOQBYPkzQccsKNCslQW8
1575/DyW6y06oQusSENUvynT6dr3LJxt/NgZPhZX2+k1eYDV
1576-----END RSA PRIVATE KEY-----
1577-----BEGIN CERTIFICATE-----
1578MIICGzCCAYSgAwIBAgIJAIq84a2Q/OvlMA0GCSqGSIb3DQEBBQUAMBQxEjAQBgNV
1579BAMTCWxvY2FsaG9zdDAeFw0xMTA1MjExMDIzMzNaFw03NTAzMjEwMzU1MTdaMBQx
1580EjAQBgNVBAMTCWxvY2FsaG9zdDCBnzANBgkqhkiG9w0BAQEFAAOBjQAwgYkCgYEA
1581xk+MUua/da2yyUCtp1A3pwYQRuqhZPm1To7gBgvy0h5QKAZ7xs0Bt2oDhvnu3Oc9
1582l0/JtpLTkS6htxOJmJm8YMoQ68z+notgJ3PqbM5p8T6Ctz7oeWl1flyrdG1NAtZt
1583vgAphhidLdz+NPGq7fNpzsQcPGR4CIPQ7aesSFAsjqsCAwEAAaN1MHMwHQYDVR0O
1584BBYEFLWaUPO6N7efGiuoS9i3DVYcUwn0MEQGA1UdIwQ9MDuAFLWaUPO6N7efGiuo
1585S9i3DVYcUwn0oRikFjAUMRIwEAYDVQQDEwlsb2NhbGhvc3SCCQCKvOGtkPzr5TAM
1586BgNVHRMEBTADAQH/MA0GCSqGSIb3DQEBBQUAA4GBAMK5whPjLNQK1Ivvk88oqJqq
15874f889OwikGP0eUhOBhbFlsZs+jq5YZC2UzHz+evzKBlgAP1u4lP/cB85CnjvWqM+
15881c/lywFHQ6HOdDeQ1L72tSYMrNOG4XNmLn0h7rx6GoTU7dcFRfseahBCq8mv0IDt
1589IRbTpvlHWPjsSvHz0ZOH
1590-----END CERTIFICATE-----"""
1591
Vinay Sajip7367d082011-05-02 13:17:27 +01001592 def setUp(self):
1593 """Set up an HTTP server to receive log messages, and a HTTPHandler
1594 pointing to that server's address and port."""
1595 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001596 self.handled = threading.Event()
1597
Vinay Sajip7367d082011-05-02 13:17:27 +01001598 def handle_request(self, request):
Vinay Sajip0372e102011-05-05 12:59:14 +01001599 self.command = request.command
Vinay Sajip7367d082011-05-02 13:17:27 +01001600 self.log_data = urlparse(request.path)
Vinay Sajip0372e102011-05-05 12:59:14 +01001601 if self.command == 'POST':
1602 try:
1603 rlen = int(request.headers['Content-Length'])
1604 self.post_data = request.rfile.read(rlen)
1605 except:
1606 self.post_data = None
Vinay Sajip7367d082011-05-02 13:17:27 +01001607 request.send_response(200)
Vinay Sajip463ac512011-05-10 09:10:08 +01001608 request.end_headers()
Vinay Sajip7367d082011-05-02 13:17:27 +01001609 self.handled.set()
1610
1611 def test_output(self):
Vinay Sajipf2231162011-05-09 22:05:50 +01001612 # The log message sent to the HTTPHandler is properly received.
Vinay Sajip7367d082011-05-02 13:17:27 +01001613 logger = logging.getLogger("http")
Vinay Sajip9ba87612011-05-21 11:32:15 +01001614 root_logger = self.root_logger
1615 root_logger.removeHandler(self.root_logger.handlers[0])
1616 for secure in (False, True):
1617 addr = ('localhost', 0)
1618 if secure:
Vinay Sajip39e35282011-05-21 16:46:41 +01001619 try:
1620 import ssl
1621 fd, fn = tempfile.mkstemp()
1622 os.close(fd)
1623 with open(fn, 'w') as f:
1624 f.write(self.PEMFILE)
1625 sslctx = ssl.SSLContext(ssl.PROTOCOL_SSLv23)
1626 sslctx.load_cert_chain(fn)
1627 os.unlink(fn)
1628 except ImportError:
1629 sslctx = None
Vinay Sajip0372e102011-05-05 12:59:14 +01001630 else:
Vinay Sajip9ba87612011-05-21 11:32:15 +01001631 sslctx = None
1632 self.server = server = TestHTTPServer(addr, self.handle_request,
1633 0.01, sslctx=sslctx)
1634 server.start()
1635 server.ready.wait()
1636 host = 'localhost:%d' % server.server_port
Vinay Sajip39e35282011-05-21 16:46:41 +01001637 secure_client = secure and sslctx
1638 self.h_hdlr = logging.handlers.HTTPHandler(host, '/frob',
1639 secure=secure_client)
Vinay Sajip9ba87612011-05-21 11:32:15 +01001640 self.log_data = None
1641 root_logger.addHandler(self.h_hdlr)
1642
1643 for method in ('GET', 'POST'):
1644 self.h_hdlr.method = method
1645 self.handled.clear()
1646 msg = "sp\xe4m"
1647 logger.error(msg)
1648 self.handled.wait()
1649 self.assertEqual(self.log_data.path, '/frob')
1650 self.assertEqual(self.command, method)
1651 if method == 'GET':
1652 d = parse_qs(self.log_data.query)
1653 else:
1654 d = parse_qs(self.post_data.decode('utf-8'))
1655 self.assertEqual(d['name'], ['http'])
1656 self.assertEqual(d['funcName'], ['test_output'])
1657 self.assertEqual(d['msg'], [msg])
1658
1659 self.server.stop(2.0)
1660 self.root_logger.removeHandler(self.h_hdlr)
1661 self.h_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001662
Christian Heimes180510d2008-03-03 19:15:45 +00001663class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001664
Christian Heimes180510d2008-03-03 19:15:45 +00001665 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001666
Christian Heimes180510d2008-03-03 19:15:45 +00001667 def setUp(self):
1668 """Create a dict to remember potentially destroyed objects."""
1669 BaseTest.setUp(self)
1670 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001671
Christian Heimes180510d2008-03-03 19:15:45 +00001672 def _watch_for_survival(self, *args):
1673 """Watch the given objects for survival, by creating weakrefs to
1674 them."""
1675 for obj in args:
1676 key = id(obj), repr(obj)
1677 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001678
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001679 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +00001680 """Assert that all objects watched for survival have survived."""
1681 # Trigger cycle breaking.
1682 gc.collect()
1683 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001684 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +00001685 if ref() is None:
1686 dead.append(repr_)
1687 if dead:
1688 self.fail("%d objects should have survived "
1689 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001690
Christian Heimes180510d2008-03-03 19:15:45 +00001691 def test_persistent_loggers(self):
1692 # Logger objects are persistent and retain their configuration, even
1693 # if visible references are destroyed.
1694 self.root_logger.setLevel(logging.INFO)
1695 foo = logging.getLogger("foo")
1696 self._watch_for_survival(foo)
1697 foo.setLevel(logging.DEBUG)
1698 self.root_logger.debug(self.next_message())
1699 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001700 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001701 ('foo', 'DEBUG', '2'),
1702 ])
1703 del foo
1704 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001705 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +00001706 # foo has retained its settings.
1707 bar = logging.getLogger("foo")
1708 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001709 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001710 ('foo', 'DEBUG', '2'),
1711 ('foo', 'DEBUG', '3'),
1712 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001713
Benjamin Petersonf91df042009-02-13 02:50:59 +00001714
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001715class EncodingTest(BaseTest):
1716 def test_encoding_plain_file(self):
1717 # In Python 2.x, a plain file object is treated as having no encoding.
1718 log = logging.getLogger("test")
Vinay Sajip60b4df12010-12-27 11:18:52 +00001719 fd, fn = tempfile.mkstemp(".log", "test_logging-1-")
1720 os.close(fd)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001721 # the non-ascii data we write to the log.
1722 data = "foo\x80"
1723 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001724 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001725 log.addHandler(handler)
1726 try:
1727 # write non-ascii data to the log.
1728 log.warning(data)
1729 finally:
1730 log.removeHandler(handler)
1731 handler.close()
1732 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001733 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001734 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001735 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001736 finally:
1737 f.close()
1738 finally:
1739 if os.path.isfile(fn):
1740 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001741
Benjamin Petersonf91df042009-02-13 02:50:59 +00001742 def test_encoding_cyrillic_unicode(self):
1743 log = logging.getLogger("test")
1744 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
1745 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
1746 #Ensure it's written in a Cyrillic encoding
1747 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +00001748 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +00001749 stream = io.BytesIO()
1750 writer = writer_class(stream, 'strict')
1751 handler = logging.StreamHandler(writer)
1752 log.addHandler(handler)
1753 try:
1754 log.warning(message)
1755 finally:
1756 log.removeHandler(handler)
1757 handler.close()
1758 # check we wrote exactly those bytes, ignoring trailing \n etc
1759 s = stream.getvalue()
1760 #Compare against what the data should be when encoded in CP-1251
1761 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
1762
1763
Georg Brandlf9734072008-12-07 15:30:06 +00001764class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +00001765
Georg Brandlf9734072008-12-07 15:30:06 +00001766 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +00001767 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +00001768 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001769 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001770 warnings.filterwarnings("always", category=UserWarning)
1771 stream = io.StringIO()
1772 h = logging.StreamHandler(stream)
1773 logger = logging.getLogger("py.warnings")
1774 logger.addHandler(h)
1775 warnings.warn("I'm warning you...")
1776 logger.removeHandler(h)
1777 s = stream.getvalue()
1778 h.close()
1779 self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0)
Georg Brandlf9734072008-12-07 15:30:06 +00001780
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001781 #See if an explicit file uses the original implementation
1782 a_file = io.StringIO()
1783 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
1784 a_file, "Dummy line")
1785 s = a_file.getvalue()
1786 a_file.close()
1787 self.assertEqual(s,
1788 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
1789
1790 def test_warnings_no_handlers(self):
1791 with warnings.catch_warnings():
1792 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001793 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001794
1795 # confirm our assumption: no loggers are set
1796 logger = logging.getLogger("py.warnings")
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001797 self.assertEqual(logger.handlers, [])
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001798
1799 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001800 self.assertEqual(len(logger.handlers), 1)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001801 self.assertIsInstance(logger.handlers[0], logging.NullHandler)
Georg Brandlf9734072008-12-07 15:30:06 +00001802
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001803
1804def formatFunc(format, datefmt=None):
1805 return logging.Formatter(format, datefmt)
1806
1807def handlerFunc():
1808 return logging.StreamHandler()
1809
1810class CustomHandler(logging.StreamHandler):
1811 pass
1812
1813class ConfigDictTest(BaseTest):
1814
1815 """Reading logging config from a dictionary."""
1816
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001817 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001818
1819 # config0 is a standard configuration.
1820 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001821 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001822 'formatters': {
1823 'form1' : {
1824 'format' : '%(levelname)s ++ %(message)s',
1825 },
1826 },
1827 'handlers' : {
1828 'hand1' : {
1829 'class' : 'logging.StreamHandler',
1830 'formatter' : 'form1',
1831 'level' : 'NOTSET',
1832 'stream' : 'ext://sys.stdout',
1833 },
1834 },
1835 'root' : {
1836 'level' : 'WARNING',
1837 'handlers' : ['hand1'],
1838 },
1839 }
1840
1841 # config1 adds a little to the standard configuration.
1842 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001843 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001844 'formatters': {
1845 'form1' : {
1846 'format' : '%(levelname)s ++ %(message)s',
1847 },
1848 },
1849 'handlers' : {
1850 'hand1' : {
1851 'class' : 'logging.StreamHandler',
1852 'formatter' : 'form1',
1853 'level' : 'NOTSET',
1854 'stream' : 'ext://sys.stdout',
1855 },
1856 },
1857 'loggers' : {
1858 'compiler.parser' : {
1859 'level' : 'DEBUG',
1860 'handlers' : ['hand1'],
1861 },
1862 },
1863 'root' : {
1864 'level' : 'WARNING',
1865 },
1866 }
1867
Vinay Sajip9f9991c2011-03-07 18:02:57 +00001868 # config1a moves the handler to the root. Used with config8a
1869 config1a = {
1870 'version': 1,
1871 'formatters': {
1872 'form1' : {
1873 'format' : '%(levelname)s ++ %(message)s',
1874 },
1875 },
1876 'handlers' : {
1877 'hand1' : {
1878 'class' : 'logging.StreamHandler',
1879 'formatter' : 'form1',
1880 'level' : 'NOTSET',
1881 'stream' : 'ext://sys.stdout',
1882 },
1883 },
1884 'loggers' : {
1885 'compiler.parser' : {
1886 'level' : 'DEBUG',
1887 },
1888 },
1889 'root' : {
1890 'level' : 'WARNING',
1891 'handlers' : ['hand1'],
1892 },
1893 }
1894
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001895 # config2 has a subtle configuration error that should be reported
1896 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001897 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001898 'formatters': {
1899 'form1' : {
1900 'format' : '%(levelname)s ++ %(message)s',
1901 },
1902 },
1903 'handlers' : {
1904 'hand1' : {
1905 'class' : 'logging.StreamHandler',
1906 'formatter' : 'form1',
1907 'level' : 'NOTSET',
1908 'stream' : 'ext://sys.stdbout',
1909 },
1910 },
1911 'loggers' : {
1912 'compiler.parser' : {
1913 'level' : 'DEBUG',
1914 'handlers' : ['hand1'],
1915 },
1916 },
1917 'root' : {
1918 'level' : 'WARNING',
1919 },
1920 }
1921
1922 #As config1 but with a misspelt level on a handler
1923 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001924 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001925 'formatters': {
1926 'form1' : {
1927 'format' : '%(levelname)s ++ %(message)s',
1928 },
1929 },
1930 'handlers' : {
1931 'hand1' : {
1932 'class' : 'logging.StreamHandler',
1933 'formatter' : 'form1',
1934 'level' : 'NTOSET',
1935 'stream' : 'ext://sys.stdout',
1936 },
1937 },
1938 'loggers' : {
1939 'compiler.parser' : {
1940 'level' : 'DEBUG',
1941 'handlers' : ['hand1'],
1942 },
1943 },
1944 'root' : {
1945 'level' : 'WARNING',
1946 },
1947 }
1948
1949
1950 #As config1 but with a misspelt level on a logger
1951 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001952 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001953 'formatters': {
1954 'form1' : {
1955 'format' : '%(levelname)s ++ %(message)s',
1956 },
1957 },
1958 'handlers' : {
1959 'hand1' : {
1960 'class' : 'logging.StreamHandler',
1961 'formatter' : 'form1',
1962 'level' : 'NOTSET',
1963 'stream' : 'ext://sys.stdout',
1964 },
1965 },
1966 'loggers' : {
1967 'compiler.parser' : {
1968 'level' : 'DEBUG',
1969 'handlers' : ['hand1'],
1970 },
1971 },
1972 'root' : {
1973 'level' : 'WRANING',
1974 },
1975 }
1976
1977 # config3 has a less subtle configuration error
1978 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001979 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001980 'formatters': {
1981 'form1' : {
1982 'format' : '%(levelname)s ++ %(message)s',
1983 },
1984 },
1985 'handlers' : {
1986 'hand1' : {
1987 'class' : 'logging.StreamHandler',
1988 'formatter' : 'misspelled_name',
1989 'level' : 'NOTSET',
1990 'stream' : 'ext://sys.stdout',
1991 },
1992 },
1993 'loggers' : {
1994 'compiler.parser' : {
1995 'level' : 'DEBUG',
1996 'handlers' : ['hand1'],
1997 },
1998 },
1999 'root' : {
2000 'level' : 'WARNING',
2001 },
2002 }
2003
2004 # config4 specifies a custom formatter class to be loaded
2005 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002006 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002007 'formatters': {
2008 'form1' : {
2009 '()' : __name__ + '.ExceptionFormatter',
2010 'format' : '%(levelname)s:%(name)s:%(message)s',
2011 },
2012 },
2013 'handlers' : {
2014 'hand1' : {
2015 'class' : 'logging.StreamHandler',
2016 'formatter' : 'form1',
2017 'level' : 'NOTSET',
2018 'stream' : 'ext://sys.stdout',
2019 },
2020 },
2021 'root' : {
2022 'level' : 'NOTSET',
2023 'handlers' : ['hand1'],
2024 },
2025 }
2026
2027 # As config4 but using an actual callable rather than a string
2028 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002029 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002030 'formatters': {
2031 'form1' : {
2032 '()' : ExceptionFormatter,
2033 'format' : '%(levelname)s:%(name)s:%(message)s',
2034 },
2035 'form2' : {
2036 '()' : __name__ + '.formatFunc',
2037 'format' : '%(levelname)s:%(name)s:%(message)s',
2038 },
2039 'form3' : {
2040 '()' : formatFunc,
2041 'format' : '%(levelname)s:%(name)s:%(message)s',
2042 },
2043 },
2044 'handlers' : {
2045 'hand1' : {
2046 'class' : 'logging.StreamHandler',
2047 'formatter' : 'form1',
2048 'level' : 'NOTSET',
2049 'stream' : 'ext://sys.stdout',
2050 },
2051 'hand2' : {
2052 '()' : handlerFunc,
2053 },
2054 },
2055 'root' : {
2056 'level' : 'NOTSET',
2057 'handlers' : ['hand1'],
2058 },
2059 }
2060
2061 # config5 specifies a custom handler class to be loaded
2062 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002063 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002064 'formatters': {
2065 'form1' : {
2066 'format' : '%(levelname)s ++ %(message)s',
2067 },
2068 },
2069 'handlers' : {
2070 'hand1' : {
2071 'class' : __name__ + '.CustomHandler',
2072 'formatter' : 'form1',
2073 'level' : 'NOTSET',
2074 'stream' : 'ext://sys.stdout',
2075 },
2076 },
2077 'loggers' : {
2078 'compiler.parser' : {
2079 'level' : 'DEBUG',
2080 'handlers' : ['hand1'],
2081 },
2082 },
2083 'root' : {
2084 'level' : 'WARNING',
2085 },
2086 }
2087
2088 # config6 specifies a custom handler class to be loaded
2089 # but has bad arguments
2090 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002091 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002092 'formatters': {
2093 'form1' : {
2094 'format' : '%(levelname)s ++ %(message)s',
2095 },
2096 },
2097 'handlers' : {
2098 'hand1' : {
2099 'class' : __name__ + '.CustomHandler',
2100 'formatter' : 'form1',
2101 'level' : 'NOTSET',
2102 'stream' : 'ext://sys.stdout',
2103 '9' : 'invalid parameter name',
2104 },
2105 },
2106 'loggers' : {
2107 'compiler.parser' : {
2108 'level' : 'DEBUG',
2109 'handlers' : ['hand1'],
2110 },
2111 },
2112 'root' : {
2113 'level' : 'WARNING',
2114 },
2115 }
2116
2117 #config 7 does not define compiler.parser but defines compiler.lexer
2118 #so compiler.parser should be disabled after applying it
2119 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002120 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002121 'formatters': {
2122 'form1' : {
2123 'format' : '%(levelname)s ++ %(message)s',
2124 },
2125 },
2126 'handlers' : {
2127 'hand1' : {
2128 'class' : 'logging.StreamHandler',
2129 'formatter' : 'form1',
2130 'level' : 'NOTSET',
2131 'stream' : 'ext://sys.stdout',
2132 },
2133 },
2134 'loggers' : {
2135 'compiler.lexer' : {
2136 'level' : 'DEBUG',
2137 'handlers' : ['hand1'],
2138 },
2139 },
2140 'root' : {
2141 'level' : 'WARNING',
2142 },
2143 }
2144
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002145 # config8 defines both compiler and compiler.lexer
2146 # so compiler.parser should not be disabled (since
2147 # compiler is defined)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002148 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002149 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002150 'disable_existing_loggers' : False,
2151 'formatters': {
2152 'form1' : {
2153 'format' : '%(levelname)s ++ %(message)s',
2154 },
2155 },
2156 'handlers' : {
2157 'hand1' : {
2158 'class' : 'logging.StreamHandler',
2159 'formatter' : 'form1',
2160 'level' : 'NOTSET',
2161 'stream' : 'ext://sys.stdout',
2162 },
2163 },
2164 'loggers' : {
2165 'compiler' : {
2166 'level' : 'DEBUG',
2167 'handlers' : ['hand1'],
2168 },
2169 'compiler.lexer' : {
2170 },
2171 },
2172 'root' : {
2173 'level' : 'WARNING',
2174 },
2175 }
2176
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002177 # config8a disables existing loggers
2178 config8a = {
2179 'version': 1,
2180 'disable_existing_loggers' : True,
2181 'formatters': {
2182 'form1' : {
2183 'format' : '%(levelname)s ++ %(message)s',
2184 },
2185 },
2186 'handlers' : {
2187 'hand1' : {
2188 'class' : 'logging.StreamHandler',
2189 'formatter' : 'form1',
2190 'level' : 'NOTSET',
2191 'stream' : 'ext://sys.stdout',
2192 },
2193 },
2194 'loggers' : {
2195 'compiler' : {
2196 'level' : 'DEBUG',
2197 'handlers' : ['hand1'],
2198 },
2199 'compiler.lexer' : {
2200 },
2201 },
2202 'root' : {
2203 'level' : 'WARNING',
2204 },
2205 }
2206
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002207 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002208 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002209 'formatters': {
2210 'form1' : {
2211 'format' : '%(levelname)s ++ %(message)s',
2212 },
2213 },
2214 'handlers' : {
2215 'hand1' : {
2216 'class' : 'logging.StreamHandler',
2217 'formatter' : 'form1',
2218 'level' : 'WARNING',
2219 'stream' : 'ext://sys.stdout',
2220 },
2221 },
2222 'loggers' : {
2223 'compiler.parser' : {
2224 'level' : 'WARNING',
2225 'handlers' : ['hand1'],
2226 },
2227 },
2228 'root' : {
2229 'level' : 'NOTSET',
2230 },
2231 }
2232
2233 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002234 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002235 'incremental' : True,
2236 'handlers' : {
2237 'hand1' : {
2238 'level' : 'WARNING',
2239 },
2240 },
2241 'loggers' : {
2242 'compiler.parser' : {
2243 'level' : 'INFO',
2244 },
2245 },
2246 }
2247
2248 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002249 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002250 'incremental' : True,
2251 'handlers' : {
2252 'hand1' : {
2253 'level' : 'INFO',
2254 },
2255 },
2256 'loggers' : {
2257 'compiler.parser' : {
2258 'level' : 'INFO',
2259 },
2260 },
2261 }
2262
2263 #As config1 but with a filter added
2264 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002265 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002266 'formatters': {
2267 'form1' : {
2268 'format' : '%(levelname)s ++ %(message)s',
2269 },
2270 },
2271 'filters' : {
2272 'filt1' : {
2273 'name' : 'compiler.parser',
2274 },
2275 },
2276 'handlers' : {
2277 'hand1' : {
2278 'class' : 'logging.StreamHandler',
2279 'formatter' : 'form1',
2280 'level' : 'NOTSET',
2281 'stream' : 'ext://sys.stdout',
2282 'filters' : ['filt1'],
2283 },
2284 },
2285 'loggers' : {
2286 'compiler.parser' : {
2287 'level' : 'DEBUG',
2288 'filters' : ['filt1'],
2289 },
2290 },
2291 'root' : {
2292 'level' : 'WARNING',
2293 'handlers' : ['hand1'],
2294 },
2295 }
2296
2297 #As config1 but using cfg:// references
2298 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002299 'version': 1,
2300 'true_formatters': {
2301 'form1' : {
2302 'format' : '%(levelname)s ++ %(message)s',
2303 },
2304 },
2305 'handler_configs': {
2306 'hand1' : {
2307 'class' : 'logging.StreamHandler',
2308 'formatter' : 'form1',
2309 'level' : 'NOTSET',
2310 'stream' : 'ext://sys.stdout',
2311 },
2312 },
2313 'formatters' : 'cfg://true_formatters',
2314 'handlers' : {
2315 'hand1' : 'cfg://handler_configs[hand1]',
2316 },
2317 'loggers' : {
2318 'compiler.parser' : {
2319 'level' : 'DEBUG',
2320 'handlers' : ['hand1'],
2321 },
2322 },
2323 'root' : {
2324 'level' : 'WARNING',
2325 },
2326 }
2327
2328 #As config11 but missing the version key
2329 config12 = {
2330 'true_formatters': {
2331 'form1' : {
2332 'format' : '%(levelname)s ++ %(message)s',
2333 },
2334 },
2335 'handler_configs': {
2336 'hand1' : {
2337 'class' : 'logging.StreamHandler',
2338 'formatter' : 'form1',
2339 'level' : 'NOTSET',
2340 'stream' : 'ext://sys.stdout',
2341 },
2342 },
2343 'formatters' : 'cfg://true_formatters',
2344 'handlers' : {
2345 'hand1' : 'cfg://handler_configs[hand1]',
2346 },
2347 'loggers' : {
2348 'compiler.parser' : {
2349 'level' : 'DEBUG',
2350 'handlers' : ['hand1'],
2351 },
2352 },
2353 'root' : {
2354 'level' : 'WARNING',
2355 },
2356 }
2357
2358 #As config11 but using an unsupported version
2359 config13 = {
2360 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002361 'true_formatters': {
2362 'form1' : {
2363 'format' : '%(levelname)s ++ %(message)s',
2364 },
2365 },
2366 'handler_configs': {
2367 'hand1' : {
2368 'class' : 'logging.StreamHandler',
2369 'formatter' : 'form1',
2370 'level' : 'NOTSET',
2371 'stream' : 'ext://sys.stdout',
2372 },
2373 },
2374 'formatters' : 'cfg://true_formatters',
2375 'handlers' : {
2376 'hand1' : 'cfg://handler_configs[hand1]',
2377 },
2378 'loggers' : {
2379 'compiler.parser' : {
2380 'level' : 'DEBUG',
2381 'handlers' : ['hand1'],
2382 },
2383 },
2384 'root' : {
2385 'level' : 'WARNING',
2386 },
2387 }
2388
2389 def apply_config(self, conf):
2390 logging.config.dictConfig(conf)
2391
2392 def test_config0_ok(self):
2393 # A simple config which overrides the default settings.
2394 with captured_stdout() as output:
2395 self.apply_config(self.config0)
2396 logger = logging.getLogger()
2397 # Won't output anything
2398 logger.info(self.next_message())
2399 # Outputs a message
2400 logger.error(self.next_message())
2401 self.assert_log_lines([
2402 ('ERROR', '2'),
2403 ], stream=output)
2404 # Original logger output is empty.
2405 self.assert_log_lines([])
2406
2407 def test_config1_ok(self, config=config1):
2408 # A config defining a sub-parser as well.
2409 with captured_stdout() as output:
2410 self.apply_config(config)
2411 logger = logging.getLogger("compiler.parser")
2412 # Both will output a message
2413 logger.info(self.next_message())
2414 logger.error(self.next_message())
2415 self.assert_log_lines([
2416 ('INFO', '1'),
2417 ('ERROR', '2'),
2418 ], stream=output)
2419 # Original logger output is empty.
2420 self.assert_log_lines([])
2421
2422 def test_config2_failure(self):
2423 # A simple config which overrides the default settings.
2424 self.assertRaises(Exception, self.apply_config, self.config2)
2425
2426 def test_config2a_failure(self):
2427 # A simple config which overrides the default settings.
2428 self.assertRaises(Exception, self.apply_config, self.config2a)
2429
2430 def test_config2b_failure(self):
2431 # A simple config which overrides the default settings.
2432 self.assertRaises(Exception, self.apply_config, self.config2b)
2433
2434 def test_config3_failure(self):
2435 # A simple config which overrides the default settings.
2436 self.assertRaises(Exception, self.apply_config, self.config3)
2437
2438 def test_config4_ok(self):
2439 # A config specifying a custom formatter class.
2440 with captured_stdout() as output:
2441 self.apply_config(self.config4)
2442 #logger = logging.getLogger()
2443 try:
2444 raise RuntimeError()
2445 except RuntimeError:
2446 logging.exception("just testing")
2447 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002448 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002449 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2450 # Original logger output is empty
2451 self.assert_log_lines([])
2452
2453 def test_config4a_ok(self):
2454 # A config specifying a custom formatter class.
2455 with captured_stdout() as output:
2456 self.apply_config(self.config4a)
2457 #logger = logging.getLogger()
2458 try:
2459 raise RuntimeError()
2460 except RuntimeError:
2461 logging.exception("just testing")
2462 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002463 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002464 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2465 # Original logger output is empty
2466 self.assert_log_lines([])
2467
2468 def test_config5_ok(self):
2469 self.test_config1_ok(config=self.config5)
2470
2471 def test_config6_failure(self):
2472 self.assertRaises(Exception, self.apply_config, self.config6)
2473
2474 def test_config7_ok(self):
2475 with captured_stdout() as output:
2476 self.apply_config(self.config1)
2477 logger = logging.getLogger("compiler.parser")
2478 # Both will output a message
2479 logger.info(self.next_message())
2480 logger.error(self.next_message())
2481 self.assert_log_lines([
2482 ('INFO', '1'),
2483 ('ERROR', '2'),
2484 ], stream=output)
2485 # Original logger output is empty.
2486 self.assert_log_lines([])
2487 with captured_stdout() as output:
2488 self.apply_config(self.config7)
2489 logger = logging.getLogger("compiler.parser")
2490 self.assertTrue(logger.disabled)
2491 logger = logging.getLogger("compiler.lexer")
2492 # Both will output a message
2493 logger.info(self.next_message())
2494 logger.error(self.next_message())
2495 self.assert_log_lines([
2496 ('INFO', '3'),
2497 ('ERROR', '4'),
2498 ], stream=output)
2499 # Original logger output is empty.
2500 self.assert_log_lines([])
2501
2502 #Same as test_config_7_ok but don't disable old loggers.
2503 def test_config_8_ok(self):
2504 with captured_stdout() as output:
2505 self.apply_config(self.config1)
2506 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002507 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002508 logger.info(self.next_message())
2509 logger.error(self.next_message())
2510 self.assert_log_lines([
2511 ('INFO', '1'),
2512 ('ERROR', '2'),
2513 ], stream=output)
2514 # Original logger output is empty.
2515 self.assert_log_lines([])
2516 with captured_stdout() as output:
2517 self.apply_config(self.config8)
2518 logger = logging.getLogger("compiler.parser")
2519 self.assertFalse(logger.disabled)
2520 # Both will output a message
2521 logger.info(self.next_message())
2522 logger.error(self.next_message())
2523 logger = logging.getLogger("compiler.lexer")
2524 # Both will output a message
2525 logger.info(self.next_message())
2526 logger.error(self.next_message())
2527 self.assert_log_lines([
2528 ('INFO', '3'),
2529 ('ERROR', '4'),
2530 ('INFO', '5'),
2531 ('ERROR', '6'),
2532 ], stream=output)
2533 # Original logger output is empty.
2534 self.assert_log_lines([])
2535
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002536 def test_config_8a_ok(self):
2537 with captured_stdout() as output:
2538 self.apply_config(self.config1a)
2539 logger = logging.getLogger("compiler.parser")
2540 # See issue #11424. compiler-hyphenated sorts
2541 # between compiler and compiler.xyz and this
2542 # was preventing compiler.xyz from being included
2543 # in the child loggers of compiler because of an
2544 # overzealous loop termination condition.
2545 hyphenated = logging.getLogger('compiler-hyphenated')
2546 # All will output a message
2547 logger.info(self.next_message())
2548 logger.error(self.next_message())
2549 hyphenated.critical(self.next_message())
2550 self.assert_log_lines([
2551 ('INFO', '1'),
2552 ('ERROR', '2'),
2553 ('CRITICAL', '3'),
2554 ], stream=output)
2555 # Original logger output is empty.
2556 self.assert_log_lines([])
2557 with captured_stdout() as output:
2558 self.apply_config(self.config8a)
2559 logger = logging.getLogger("compiler.parser")
2560 self.assertFalse(logger.disabled)
2561 # Both will output a message
2562 logger.info(self.next_message())
2563 logger.error(self.next_message())
2564 logger = logging.getLogger("compiler.lexer")
2565 # Both will output a message
2566 logger.info(self.next_message())
2567 logger.error(self.next_message())
2568 # Will not appear
2569 hyphenated.critical(self.next_message())
2570 self.assert_log_lines([
2571 ('INFO', '4'),
2572 ('ERROR', '5'),
2573 ('INFO', '6'),
2574 ('ERROR', '7'),
2575 ], stream=output)
2576 # Original logger output is empty.
2577 self.assert_log_lines([])
2578
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002579 def test_config_9_ok(self):
2580 with captured_stdout() as output:
2581 self.apply_config(self.config9)
2582 logger = logging.getLogger("compiler.parser")
2583 #Nothing will be output since both handler and logger are set to WARNING
2584 logger.info(self.next_message())
2585 self.assert_log_lines([], stream=output)
2586 self.apply_config(self.config9a)
2587 #Nothing will be output since both handler is still set to WARNING
2588 logger.info(self.next_message())
2589 self.assert_log_lines([], stream=output)
2590 self.apply_config(self.config9b)
2591 #Message should now be output
2592 logger.info(self.next_message())
2593 self.assert_log_lines([
2594 ('INFO', '3'),
2595 ], stream=output)
2596
2597 def test_config_10_ok(self):
2598 with captured_stdout() as output:
2599 self.apply_config(self.config10)
2600 logger = logging.getLogger("compiler.parser")
2601 logger.warning(self.next_message())
2602 logger = logging.getLogger('compiler')
2603 #Not output, because filtered
2604 logger.warning(self.next_message())
2605 logger = logging.getLogger('compiler.lexer')
2606 #Not output, because filtered
2607 logger.warning(self.next_message())
2608 logger = logging.getLogger("compiler.parser.codegen")
2609 #Output, as not filtered
2610 logger.error(self.next_message())
2611 self.assert_log_lines([
2612 ('WARNING', '1'),
2613 ('ERROR', '4'),
2614 ], stream=output)
2615
2616 def test_config11_ok(self):
2617 self.test_config1_ok(self.config11)
2618
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002619 def test_config12_failure(self):
2620 self.assertRaises(Exception, self.apply_config, self.config12)
2621
2622 def test_config13_failure(self):
2623 self.assertRaises(Exception, self.apply_config, self.config13)
2624
Victor Stinner45df8202010-04-28 22:31:17 +00002625 @unittest.skipUnless(threading, 'listen() needs threading to work')
Vinay Sajip4ded5512012-10-02 15:56:16 +01002626 def setup_via_listener(self, text, verify=None):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002627 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00002628 # Ask for a randomly assigned port (by using port 0)
Vinay Sajip4ded5512012-10-02 15:56:16 +01002629 t = logging.config.listen(0, verify)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002630 t.start()
2631 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00002632 # Now get the port allocated
2633 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002634 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002635 try:
2636 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
2637 sock.settimeout(2.0)
2638 sock.connect(('localhost', port))
2639
2640 slen = struct.pack('>L', len(text))
2641 s = slen + text
2642 sentsofar = 0
2643 left = len(s)
2644 while left > 0:
2645 sent = sock.send(s[sentsofar:])
2646 sentsofar += sent
2647 left -= sent
2648 sock.close()
2649 finally:
2650 t.ready.wait(2.0)
2651 logging.config.stopListening()
2652 t.join(2.0)
2653
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002654 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002655 def test_listen_config_10_ok(self):
2656 with captured_stdout() as output:
2657 self.setup_via_listener(json.dumps(self.config10))
2658 logger = logging.getLogger("compiler.parser")
2659 logger.warning(self.next_message())
2660 logger = logging.getLogger('compiler')
2661 #Not output, because filtered
2662 logger.warning(self.next_message())
2663 logger = logging.getLogger('compiler.lexer')
2664 #Not output, because filtered
2665 logger.warning(self.next_message())
2666 logger = logging.getLogger("compiler.parser.codegen")
2667 #Output, as not filtered
2668 logger.error(self.next_message())
2669 self.assert_log_lines([
2670 ('WARNING', '1'),
2671 ('ERROR', '4'),
2672 ], stream=output)
2673
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002674 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002675 def test_listen_config_1_ok(self):
2676 with captured_stdout() as output:
2677 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
2678 logger = logging.getLogger("compiler.parser")
2679 # Both will output a message
2680 logger.info(self.next_message())
2681 logger.error(self.next_message())
2682 self.assert_log_lines([
2683 ('INFO', '1'),
2684 ('ERROR', '2'),
2685 ], stream=output)
2686 # Original logger output is empty.
2687 self.assert_log_lines([])
2688
Vinay Sajip4ded5512012-10-02 15:56:16 +01002689 @unittest.skipUnless(threading, 'Threading required for this test.')
2690 def test_listen_verify(self):
2691
2692 def verify_fail(stuff):
2693 return None
2694
2695 def verify_reverse(stuff):
2696 return stuff[::-1]
2697
2698 logger = logging.getLogger("compiler.parser")
2699 to_send = textwrap.dedent(ConfigFileTest.config1)
2700 # First, specify a verification function that will fail.
2701 # We expect to see no output, since our configuration
2702 # never took effect.
2703 with captured_stdout() as output:
2704 self.setup_via_listener(to_send, verify_fail)
2705 # Both will output a message
2706 logger.info(self.next_message())
2707 logger.error(self.next_message())
2708 self.assert_log_lines([], stream=output)
2709 # Original logger output has the stuff we logged.
2710 self.assert_log_lines([
2711 ('INFO', '1'),
2712 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002713 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002714
2715 # Now, perform no verification. Our configuration
2716 # should take effect.
2717
2718 with captured_stdout() as output:
2719 self.setup_via_listener(to_send) # no verify callable specified
2720 logger = logging.getLogger("compiler.parser")
2721 # Both will output a message
2722 logger.info(self.next_message())
2723 logger.error(self.next_message())
2724 self.assert_log_lines([
2725 ('INFO', '3'),
2726 ('ERROR', '4'),
2727 ], stream=output)
2728 # Original logger output still has the stuff we logged before.
2729 self.assert_log_lines([
2730 ('INFO', '1'),
2731 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002732 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002733
2734 # Now, perform verification which transforms the bytes.
2735
2736 with captured_stdout() as output:
2737 self.setup_via_listener(to_send[::-1], verify_reverse)
2738 logger = logging.getLogger("compiler.parser")
2739 # Both will output a message
2740 logger.info(self.next_message())
2741 logger.error(self.next_message())
2742 self.assert_log_lines([
2743 ('INFO', '5'),
2744 ('ERROR', '6'),
2745 ], stream=output)
2746 # Original logger output still has the stuff we logged before.
2747 self.assert_log_lines([
2748 ('INFO', '1'),
2749 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002750 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002751
Vinay Sajip373baef2011-04-26 20:05:24 +01002752 def test_baseconfig(self):
2753 d = {
2754 'atuple': (1, 2, 3),
2755 'alist': ['a', 'b', 'c'],
2756 'adict': {'d': 'e', 'f': 3 },
2757 'nest1': ('g', ('h', 'i'), 'j'),
2758 'nest2': ['k', ['l', 'm'], 'n'],
2759 'nest3': ['o', 'cfg://alist', 'p'],
2760 }
2761 bc = logging.config.BaseConfigurator(d)
2762 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
2763 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
2764 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
2765 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
2766 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
2767 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
2768 v = bc.convert('cfg://nest3')
2769 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
2770 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
2771 self.assertRaises(ValueError, bc.convert, 'cfg://!')
2772 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002773
2774class ManagerTest(BaseTest):
2775 def test_manager_loggerclass(self):
2776 logged = []
2777
2778 class MyLogger(logging.Logger):
2779 def _log(self, level, msg, args, exc_info=None, extra=None):
2780 logged.append(msg)
2781
2782 man = logging.Manager(None)
2783 self.assertRaises(TypeError, man.setLoggerClass, int)
2784 man.setLoggerClass(MyLogger)
2785 logger = man.getLogger('test')
2786 logger.warning('should appear in logged')
2787 logging.warning('should not appear in logged')
2788
2789 self.assertEqual(logged, ['should appear in logged'])
2790
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002791 def test_set_log_record_factory(self):
2792 man = logging.Manager(None)
2793 expected = object()
2794 man.setLogRecordFactory(expected)
2795 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002796
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002797class ChildLoggerTest(BaseTest):
2798 def test_child_loggers(self):
2799 r = logging.getLogger()
2800 l1 = logging.getLogger('abc')
2801 l2 = logging.getLogger('def.ghi')
2802 c1 = r.getChild('xyz')
2803 c2 = r.getChild('uvw.xyz')
2804 self.assertTrue(c1 is logging.getLogger('xyz'))
2805 self.assertTrue(c2 is logging.getLogger('uvw.xyz'))
2806 c1 = l1.getChild('def')
2807 c2 = c1.getChild('ghi')
2808 c3 = l1.getChild('def.ghi')
2809 self.assertTrue(c1 is logging.getLogger('abc.def'))
2810 self.assertTrue(c2 is logging.getLogger('abc.def.ghi'))
2811 self.assertTrue(c2 is c3)
2812
2813
Vinay Sajip6fac8172010-10-19 20:44:14 +00002814class DerivedLogRecord(logging.LogRecord):
2815 pass
2816
Vinay Sajip61561522010-12-03 11:50:38 +00002817class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00002818
2819 def setUp(self):
2820 class CheckingFilter(logging.Filter):
2821 def __init__(self, cls):
2822 self.cls = cls
2823
2824 def filter(self, record):
2825 t = type(record)
2826 if t is not self.cls:
2827 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
2828 self.cls)
2829 raise TypeError(msg)
2830 return True
2831
2832 BaseTest.setUp(self)
2833 self.filter = CheckingFilter(DerivedLogRecord)
2834 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00002835 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00002836
2837 def tearDown(self):
2838 self.root_logger.removeFilter(self.filter)
2839 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00002840 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002841
2842 def test_logrecord_class(self):
2843 self.assertRaises(TypeError, self.root_logger.warning,
2844 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00002845 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002846 self.root_logger.error(self.next_message())
2847 self.assert_log_lines([
2848 ('root', 'ERROR', '2'),
2849 ])
2850
2851
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002852class QueueHandlerTest(BaseTest):
2853 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002854 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002855
2856 def setUp(self):
2857 BaseTest.setUp(self)
2858 self.queue = queue.Queue(-1)
2859 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
2860 self.que_logger = logging.getLogger('que')
2861 self.que_logger.propagate = False
2862 self.que_logger.setLevel(logging.WARNING)
2863 self.que_logger.addHandler(self.que_hdlr)
2864
2865 def tearDown(self):
2866 self.que_hdlr.close()
2867 BaseTest.tearDown(self)
2868
2869 def test_queue_handler(self):
2870 self.que_logger.debug(self.next_message())
2871 self.assertRaises(queue.Empty, self.queue.get_nowait)
2872 self.que_logger.info(self.next_message())
2873 self.assertRaises(queue.Empty, self.queue.get_nowait)
2874 msg = self.next_message()
2875 self.que_logger.warning(msg)
2876 data = self.queue.get_nowait()
2877 self.assertTrue(isinstance(data, logging.LogRecord))
2878 self.assertEqual(data.name, self.que_logger.name)
2879 self.assertEqual((data.msg, data.args), (msg, None))
2880
Victor Stinnercafa2ef2011-05-02 16:11:28 +02002881 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
2882 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01002883 def test_queue_listener(self):
2884 handler = TestHandler(Matcher())
2885 listener = logging.handlers.QueueListener(self.queue, handler)
2886 listener.start()
2887 try:
2888 self.que_logger.warning(self.next_message())
2889 self.que_logger.error(self.next_message())
2890 self.que_logger.critical(self.next_message())
2891 finally:
2892 listener.stop()
2893 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
2894 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
2895 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
2896
Vinay Sajip37eb3382011-04-26 20:26:41 +01002897ZERO = datetime.timedelta(0)
2898
2899class UTC(datetime.tzinfo):
2900 def utcoffset(self, dt):
2901 return ZERO
2902
2903 dst = utcoffset
2904
2905 def tzname(self, dt):
2906 return 'UTC'
2907
2908utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01002909
Vinay Sajipa39c5712010-10-25 13:57:39 +00002910class FormatterTest(unittest.TestCase):
2911 def setUp(self):
2912 self.common = {
2913 'name': 'formatter.test',
2914 'level': logging.DEBUG,
2915 'pathname': os.path.join('path', 'to', 'dummy.ext'),
2916 'lineno': 42,
2917 'exc_info': None,
2918 'func': None,
2919 'msg': 'Message with %d %s',
2920 'args': (2, 'placeholders'),
2921 }
2922 self.variants = {
2923 }
2924
2925 def get_record(self, name=None):
2926 result = dict(self.common)
2927 if name is not None:
2928 result.update(self.variants[name])
2929 return logging.makeLogRecord(result)
2930
2931 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002932 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002933 r = self.get_record()
2934 f = logging.Formatter('${%(message)s}')
2935 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
2936 f = logging.Formatter('%(random)s')
2937 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002938 self.assertFalse(f.usesTime())
2939 f = logging.Formatter('%(asctime)s')
2940 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002941 f = logging.Formatter('%(asctime)-15s')
2942 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002943 f = logging.Formatter('asctime')
2944 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002945
2946 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002947 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002948 r = self.get_record()
2949 f = logging.Formatter('$%{message}%$', style='{')
2950 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2951 f = logging.Formatter('{random}', style='{')
2952 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002953 self.assertFalse(f.usesTime())
2954 f = logging.Formatter('{asctime}', style='{')
2955 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002956 f = logging.Formatter('{asctime!s:15}', style='{')
2957 self.assertTrue(f.usesTime())
2958 f = logging.Formatter('{asctime:15}', style='{')
2959 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002960 f = logging.Formatter('asctime', style='{')
2961 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002962
2963 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00002964 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00002965 r = self.get_record()
2966 f = logging.Formatter('$message', style='$')
2967 self.assertEqual(f.format(r), 'Message with 2 placeholders')
2968 f = logging.Formatter('$$%${message}%$$', style='$')
2969 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
2970 f = logging.Formatter('${random}', style='$')
2971 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002972 self.assertFalse(f.usesTime())
2973 f = logging.Formatter('${asctime}', style='$')
2974 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00002975 f = logging.Formatter('${asctime', style='$')
2976 self.assertFalse(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00002977 f = logging.Formatter('$asctime', style='$')
2978 self.assertTrue(f.usesTime())
2979 f = logging.Formatter('asctime', style='$')
2980 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00002981
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002982 def test_invalid_style(self):
2983 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
2984
Vinay Sajip86a96ce2011-04-27 08:30:30 +01002985 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002986 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01002987 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
2988 # We use None to indicate we want the local timezone
2989 # We're essentially converting a UTC time to local time
2990 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002991 r.msecs = 123
2992 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01002993 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01002994 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
2995 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01002996 f.format(r)
2997 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
2998
2999class TestBufferingFormatter(logging.BufferingFormatter):
3000 def formatHeader(self, records):
3001 return '[(%d)' % len(records)
3002
3003 def formatFooter(self, records):
3004 return '(%d)]' % len(records)
3005
3006class BufferingFormatterTest(unittest.TestCase):
3007 def setUp(self):
3008 self.records = [
3009 logging.makeLogRecord({'msg': 'one'}),
3010 logging.makeLogRecord({'msg': 'two'}),
3011 ]
3012
3013 def test_default(self):
3014 f = logging.BufferingFormatter()
3015 self.assertEqual('', f.format([]))
3016 self.assertEqual('onetwo', f.format(self.records))
3017
3018 def test_custom(self):
3019 f = TestBufferingFormatter()
3020 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
3021 lf = logging.Formatter('<%(message)s>')
3022 f = TestBufferingFormatter(lf)
3023 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003024
3025class ExceptionTest(BaseTest):
3026 def test_formatting(self):
3027 r = self.root_logger
3028 h = RecordingHandler()
3029 r.addHandler(h)
3030 try:
3031 raise RuntimeError('deliberate mistake')
3032 except:
3033 logging.exception('failed', stack_info=True)
3034 r.removeHandler(h)
3035 h.close()
3036 r = h.records[0]
3037 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
3038 'call last):\n'))
3039 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
3040 'deliberate mistake'))
3041 self.assertTrue(r.stack_info.startswith('Stack (most recent '
3042 'call last):\n'))
3043 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
3044 'stack_info=True)'))
3045
3046
Vinay Sajip5a27d402010-12-10 11:42:57 +00003047class LastResortTest(BaseTest):
3048 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003049 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00003050 root = self.root_logger
3051 root.removeHandler(self.root_hdlr)
3052 old_stderr = sys.stderr
3053 old_lastresort = logging.lastResort
3054 old_raise_exceptions = logging.raiseExceptions
3055 try:
3056 sys.stderr = sio = io.StringIO()
Vinay Sajip8188f582011-07-25 19:58:13 +01003057 root.debug('This should not appear')
3058 self.assertEqual(sio.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00003059 root.warning('This is your final chance!')
3060 self.assertEqual(sio.getvalue(), 'This is your final chance!\n')
3061 #No handlers and no last resort, so 'No handlers' message
3062 logging.lastResort = None
3063 sys.stderr = sio = io.StringIO()
3064 root.warning('This is your final chance!')
3065 self.assertEqual(sio.getvalue(), 'No handlers could be found for logger "root"\n')
3066 # 'No handlers' message only printed once
3067 sys.stderr = sio = io.StringIO()
3068 root.warning('This is your final chance!')
3069 self.assertEqual(sio.getvalue(), '')
3070 root.manager.emittedNoHandlerWarning = False
3071 #If raiseExceptions is False, no message is printed
3072 logging.raiseExceptions = False
3073 sys.stderr = sio = io.StringIO()
3074 root.warning('This is your final chance!')
3075 self.assertEqual(sio.getvalue(), '')
3076 finally:
3077 sys.stderr = old_stderr
3078 root.addHandler(self.root_hdlr)
3079 logging.lastResort = old_lastresort
3080 logging.raiseExceptions = old_raise_exceptions
3081
3082
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003083class FakeHandler:
3084
3085 def __init__(self, identifier, called):
3086 for method in ('acquire', 'flush', 'close', 'release'):
3087 setattr(self, method, self.record_call(identifier, method, called))
3088
3089 def record_call(self, identifier, method_name, called):
3090 def inner():
3091 called.append('{} - {}'.format(identifier, method_name))
3092 return inner
3093
3094
3095class RecordingHandler(logging.NullHandler):
3096
3097 def __init__(self, *args, **kwargs):
3098 super(RecordingHandler, self).__init__(*args, **kwargs)
3099 self.records = []
3100
3101 def handle(self, record):
3102 """Keep track of all the emitted records."""
3103 self.records.append(record)
3104
3105
3106class ShutdownTest(BaseTest):
3107
Vinay Sajip5e66b162011-04-20 15:41:14 +01003108 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003109
3110 def setUp(self):
3111 super(ShutdownTest, self).setUp()
3112 self.called = []
3113
3114 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003115 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003116
3117 def raise_error(self, error):
3118 def inner():
3119 raise error()
3120 return inner
3121
3122 def test_no_failure(self):
3123 # create some fake handlers
3124 handler0 = FakeHandler(0, self.called)
3125 handler1 = FakeHandler(1, self.called)
3126 handler2 = FakeHandler(2, self.called)
3127
3128 # create live weakref to those handlers
3129 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
3130
3131 logging.shutdown(handlerList=list(handlers))
3132
3133 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
3134 '1 - acquire', '1 - flush', '1 - close', '1 - release',
3135 '0 - acquire', '0 - flush', '0 - close', '0 - release']
3136 self.assertEqual(expected, self.called)
3137
3138 def _test_with_failure_in_method(self, method, error):
3139 handler = FakeHandler(0, self.called)
3140 setattr(handler, method, self.raise_error(error))
3141 handlers = [logging.weakref.ref(handler)]
3142
3143 logging.shutdown(handlerList=list(handlers))
3144
3145 self.assertEqual('0 - release', self.called[-1])
3146
3147 def test_with_ioerror_in_acquire(self):
3148 self._test_with_failure_in_method('acquire', IOError)
3149
3150 def test_with_ioerror_in_flush(self):
3151 self._test_with_failure_in_method('flush', IOError)
3152
3153 def test_with_ioerror_in_close(self):
3154 self._test_with_failure_in_method('close', IOError)
3155
3156 def test_with_valueerror_in_acquire(self):
3157 self._test_with_failure_in_method('acquire', ValueError)
3158
3159 def test_with_valueerror_in_flush(self):
3160 self._test_with_failure_in_method('flush', ValueError)
3161
3162 def test_with_valueerror_in_close(self):
3163 self._test_with_failure_in_method('close', ValueError)
3164
3165 def test_with_other_error_in_acquire_without_raise(self):
3166 logging.raiseExceptions = False
3167 self._test_with_failure_in_method('acquire', IndexError)
3168
3169 def test_with_other_error_in_flush_without_raise(self):
3170 logging.raiseExceptions = False
3171 self._test_with_failure_in_method('flush', IndexError)
3172
3173 def test_with_other_error_in_close_without_raise(self):
3174 logging.raiseExceptions = False
3175 self._test_with_failure_in_method('close', IndexError)
3176
3177 def test_with_other_error_in_acquire_with_raise(self):
3178 logging.raiseExceptions = True
3179 self.assertRaises(IndexError, self._test_with_failure_in_method,
3180 'acquire', IndexError)
3181
3182 def test_with_other_error_in_flush_with_raise(self):
3183 logging.raiseExceptions = True
3184 self.assertRaises(IndexError, self._test_with_failure_in_method,
3185 'flush', IndexError)
3186
3187 def test_with_other_error_in_close_with_raise(self):
3188 logging.raiseExceptions = True
3189 self.assertRaises(IndexError, self._test_with_failure_in_method,
3190 'close', IndexError)
3191
3192
3193class ModuleLevelMiscTest(BaseTest):
3194
Vinay Sajip5e66b162011-04-20 15:41:14 +01003195 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003196
3197 def test_disable(self):
3198 old_disable = logging.root.manager.disable
3199 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003200 self.assertEqual(old_disable, 0)
3201 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003202
3203 logging.disable(83)
3204 self.assertEqual(logging.root.manager.disable, 83)
3205
3206 def _test_log(self, method, level=None):
3207 called = []
3208 patch(self, logging, 'basicConfig',
Vinay Sajip00bdbe12011-04-22 00:17:46 +01003209 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003210
3211 recording = RecordingHandler()
3212 logging.root.addHandler(recording)
3213
3214 log_method = getattr(logging, method)
3215 if level is not None:
3216 log_method(level, "test me: %r", recording)
3217 else:
3218 log_method("test me: %r", recording)
3219
3220 self.assertEqual(len(recording.records), 1)
3221 record = recording.records[0]
3222 self.assertEqual(record.getMessage(), "test me: %r" % recording)
3223
3224 expected_level = level if level is not None else getattr(logging, method.upper())
3225 self.assertEqual(record.levelno, expected_level)
3226
3227 # basicConfig was not called!
3228 self.assertEqual(called, [])
3229
3230 def test_log(self):
3231 self._test_log('log', logging.ERROR)
3232
3233 def test_debug(self):
3234 self._test_log('debug')
3235
3236 def test_info(self):
3237 self._test_log('info')
3238
3239 def test_warning(self):
3240 self._test_log('warning')
3241
3242 def test_error(self):
3243 self._test_log('error')
3244
3245 def test_critical(self):
3246 self._test_log('critical')
3247
3248 def test_set_logger_class(self):
3249 self.assertRaises(TypeError, logging.setLoggerClass, object)
3250
3251 class MyLogger(logging.Logger):
3252 pass
3253
3254 logging.setLoggerClass(MyLogger)
3255 self.assertEqual(logging.getLoggerClass(), MyLogger)
3256
3257 logging.setLoggerClass(logging.Logger)
3258 self.assertEqual(logging.getLoggerClass(), logging.Logger)
3259
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003260class LogRecordTest(BaseTest):
3261 def test_str_rep(self):
3262 r = logging.makeLogRecord({})
3263 s = str(r)
3264 self.assertTrue(s.startswith('<LogRecord: '))
3265 self.assertTrue(s.endswith('>'))
3266
3267 def test_dict_arg(self):
3268 h = RecordingHandler()
3269 r = logging.getLogger()
3270 r.addHandler(h)
3271 d = {'less' : 'more' }
3272 logging.warning('less is %(less)s', d)
3273 self.assertIs(h.records[0].args, d)
3274 self.assertEqual(h.records[0].message, 'less is more')
3275 r.removeHandler(h)
3276 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003277
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003278 def test_multiprocessing(self):
3279 r = logging.makeLogRecord({})
3280 self.assertEqual(r.processName, 'MainProcess')
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003281 try:
3282 import multiprocessing as mp
3283 r = logging.makeLogRecord({})
3284 self.assertEqual(r.processName, mp.current_process().name)
3285 except ImportError:
3286 pass
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003287
3288 def test_optional(self):
3289 r = logging.makeLogRecord({})
3290 NOT_NONE = self.assertIsNotNone
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003291 if threading:
3292 NOT_NONE(r.thread)
3293 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003294 NOT_NONE(r.process)
3295 NOT_NONE(r.processName)
3296 log_threads = logging.logThreads
3297 log_processes = logging.logProcesses
3298 log_multiprocessing = logging.logMultiprocessing
3299 try:
3300 logging.logThreads = False
3301 logging.logProcesses = False
3302 logging.logMultiprocessing = False
3303 r = logging.makeLogRecord({})
3304 NONE = self.assertIsNone
3305 NONE(r.thread)
3306 NONE(r.threadName)
3307 NONE(r.process)
3308 NONE(r.processName)
3309 finally:
3310 logging.logThreads = log_threads
3311 logging.logProcesses = log_processes
3312 logging.logMultiprocessing = log_multiprocessing
3313
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003314class BasicConfigTest(unittest.TestCase):
3315
Vinay Sajip95bf5042011-04-20 11:50:56 +01003316 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003317
3318 def setUp(self):
3319 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01003320 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01003321 self.saved_handlers = logging._handlers.copy()
3322 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003323 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003324 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003325 logging.root.handlers = []
3326
3327 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01003328 for h in logging.root.handlers[:]:
3329 logging.root.removeHandler(h)
3330 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003331 super(BasicConfigTest, self).tearDown()
3332
Vinay Sajip3def7e02011-04-20 10:58:06 +01003333 def cleanup(self):
3334 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01003335 logging._handlers.clear()
3336 logging._handlers.update(self.saved_handlers)
3337 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003338 logging.root.level = self.original_logging_level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003339
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003340 def test_no_kwargs(self):
3341 logging.basicConfig()
3342
3343 # handler defaults to a StreamHandler to sys.stderr
3344 self.assertEqual(len(logging.root.handlers), 1)
3345 handler = logging.root.handlers[0]
3346 self.assertIsInstance(handler, logging.StreamHandler)
3347 self.assertEqual(handler.stream, sys.stderr)
3348
3349 formatter = handler.formatter
3350 # format defaults to logging.BASIC_FORMAT
3351 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
3352 # datefmt defaults to None
3353 self.assertIsNone(formatter.datefmt)
3354 # style defaults to %
3355 self.assertIsInstance(formatter._style, logging.PercentStyle)
3356
Florent Xiclunae41f0de2011-11-11 19:39:25 +01003357 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01003358 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003359
3360 def test_filename(self):
3361 logging.basicConfig(filename='test.log')
3362
3363 self.assertEqual(len(logging.root.handlers), 1)
3364 handler = logging.root.handlers[0]
3365 self.assertIsInstance(handler, logging.FileHandler)
3366
3367 expected = logging.FileHandler('test.log', 'a')
3368 self.addCleanup(expected.close)
3369 self.assertEqual(handler.stream.mode, expected.stream.mode)
3370 self.assertEqual(handler.stream.name, expected.stream.name)
3371
3372 def test_filemode(self):
3373 logging.basicConfig(filename='test.log', filemode='wb')
3374
3375 handler = logging.root.handlers[0]
3376 expected = logging.FileHandler('test.log', 'wb')
3377 self.addCleanup(expected.close)
3378 self.assertEqual(handler.stream.mode, expected.stream.mode)
3379
3380 def test_stream(self):
3381 stream = io.StringIO()
3382 self.addCleanup(stream.close)
3383 logging.basicConfig(stream=stream)
3384
3385 self.assertEqual(len(logging.root.handlers), 1)
3386 handler = logging.root.handlers[0]
3387 self.assertIsInstance(handler, logging.StreamHandler)
3388 self.assertEqual(handler.stream, stream)
3389
3390 def test_format(self):
3391 logging.basicConfig(format='foo')
3392
3393 formatter = logging.root.handlers[0].formatter
3394 self.assertEqual(formatter._style._fmt, 'foo')
3395
3396 def test_datefmt(self):
3397 logging.basicConfig(datefmt='bar')
3398
3399 formatter = logging.root.handlers[0].formatter
3400 self.assertEqual(formatter.datefmt, 'bar')
3401
3402 def test_style(self):
3403 logging.basicConfig(style='$')
3404
3405 formatter = logging.root.handlers[0].formatter
3406 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
3407
3408 def test_level(self):
3409 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003410 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003411
3412 logging.basicConfig(level=57)
3413 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003414 # Test that second call has no effect
3415 logging.basicConfig(level=58)
3416 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003417
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003418 def test_incompatible(self):
3419 assertRaises = self.assertRaises
3420 handlers = [logging.StreamHandler()]
3421 stream = sys.stderr
3422 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3423 stream=stream)
3424 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3425 handlers=handlers)
3426 assertRaises(ValueError, logging.basicConfig, stream=stream,
3427 handlers=handlers)
3428
3429 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003430 handlers = [
3431 logging.StreamHandler(),
3432 logging.StreamHandler(sys.stdout),
3433 logging.StreamHandler(),
3434 ]
3435 f = logging.Formatter()
3436 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003437 logging.basicConfig(handlers=handlers)
3438 self.assertIs(handlers[0], logging.root.handlers[0])
3439 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003440 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003441 self.assertIsNotNone(handlers[0].formatter)
3442 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003443 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003444 self.assertIs(handlers[0].formatter, handlers[1].formatter)
3445
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003446 def _test_log(self, method, level=None):
3447 # logging.root has no handlers so basicConfig should be called
3448 called = []
3449
3450 old_basic_config = logging.basicConfig
3451 def my_basic_config(*a, **kw):
3452 old_basic_config()
3453 old_level = logging.root.level
3454 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003455 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003456 called.append((a, kw))
3457
3458 patch(self, logging, 'basicConfig', my_basic_config)
3459
3460 log_method = getattr(logging, method)
3461 if level is not None:
3462 log_method(level, "test me")
3463 else:
3464 log_method("test me")
3465
3466 # basicConfig was called with no arguments
3467 self.assertEqual(called, [((), {})])
3468
3469 def test_log(self):
3470 self._test_log('log', logging.WARNING)
3471
3472 def test_debug(self):
3473 self._test_log('debug')
3474
3475 def test_info(self):
3476 self._test_log('info')
3477
3478 def test_warning(self):
3479 self._test_log('warning')
3480
3481 def test_error(self):
3482 self._test_log('error')
3483
3484 def test_critical(self):
3485 self._test_log('critical')
3486
3487
3488class LoggerAdapterTest(unittest.TestCase):
3489
3490 def setUp(self):
3491 super(LoggerAdapterTest, self).setUp()
3492 old_handler_list = logging._handlerList[:]
3493
3494 self.recording = RecordingHandler()
3495 self.logger = logging.root
3496 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003497 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003498 self.addCleanup(self.recording.close)
3499
3500 def cleanup():
3501 logging._handlerList[:] = old_handler_list
3502
3503 self.addCleanup(cleanup)
3504 self.addCleanup(logging.shutdown)
3505 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
3506
3507 def test_exception(self):
3508 msg = 'testing exception: %r'
3509 exc = None
3510 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003511 1 / 0
3512 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003513 exc = e
3514 self.adapter.exception(msg, self.recording)
3515
3516 self.assertEqual(len(self.recording.records), 1)
3517 record = self.recording.records[0]
3518 self.assertEqual(record.levelno, logging.ERROR)
3519 self.assertEqual(record.msg, msg)
3520 self.assertEqual(record.args, (self.recording,))
3521 self.assertEqual(record.exc_info,
3522 (exc.__class__, exc, exc.__traceback__))
3523
3524 def test_critical(self):
3525 msg = 'critical test! %r'
3526 self.adapter.critical(msg, self.recording)
3527
3528 self.assertEqual(len(self.recording.records), 1)
3529 record = self.recording.records[0]
3530 self.assertEqual(record.levelno, logging.CRITICAL)
3531 self.assertEqual(record.msg, msg)
3532 self.assertEqual(record.args, (self.recording,))
3533
3534 def test_is_enabled_for(self):
3535 old_disable = self.adapter.logger.manager.disable
3536 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003537 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
3538 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003539 self.assertFalse(self.adapter.isEnabledFor(32))
3540
3541 def test_has_handlers(self):
3542 self.assertTrue(self.adapter.hasHandlers())
3543
3544 for handler in self.logger.handlers:
3545 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003546
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003547 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003548 self.assertFalse(self.adapter.hasHandlers())
3549
3550
3551class LoggerTest(BaseTest):
3552
3553 def setUp(self):
3554 super(LoggerTest, self).setUp()
3555 self.recording = RecordingHandler()
3556 self.logger = logging.Logger(name='blah')
3557 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003558 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003559 self.addCleanup(self.recording.close)
3560 self.addCleanup(logging.shutdown)
3561
3562 def test_set_invalid_level(self):
3563 self.assertRaises(TypeError, self.logger.setLevel, object())
3564
3565 def test_exception(self):
3566 msg = 'testing exception: %r'
3567 exc = None
3568 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003569 1 / 0
3570 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003571 exc = e
3572 self.logger.exception(msg, self.recording)
3573
3574 self.assertEqual(len(self.recording.records), 1)
3575 record = self.recording.records[0]
3576 self.assertEqual(record.levelno, logging.ERROR)
3577 self.assertEqual(record.msg, msg)
3578 self.assertEqual(record.args, (self.recording,))
3579 self.assertEqual(record.exc_info,
3580 (exc.__class__, exc, exc.__traceback__))
3581
3582 def test_log_invalid_level_with_raise(self):
3583 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003584 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003585
3586 logging.raiseExceptions = True
3587 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
3588
3589 def test_log_invalid_level_no_raise(self):
3590 old_raise = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003591 self.addCleanup(setattr, logging, 'raiseExecptions', old_raise)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003592
3593 logging.raiseExceptions = False
3594 self.logger.log('10', 'test message') # no exception happens
3595
3596 def test_find_caller_with_stack_info(self):
3597 called = []
3598 patch(self, logging.traceback, 'print_stack',
3599 lambda f, file: called.append(file.getvalue()))
3600
3601 self.logger.findCaller(stack_info=True)
3602
3603 self.assertEqual(len(called), 1)
3604 self.assertEqual('Stack (most recent call last):\n', called[0])
3605
3606 def test_make_record_with_extra_overwrite(self):
3607 name = 'my record'
3608 level = 13
3609 fn = lno = msg = args = exc_info = func = sinfo = None
3610 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
3611 exc_info, func, sinfo)
3612
3613 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
3614 extra = {key: 'some value'}
3615 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
3616 fn, lno, msg, args, exc_info,
3617 extra=extra, sinfo=sinfo)
3618
3619 def test_make_record_with_extra_no_overwrite(self):
3620 name = 'my record'
3621 level = 13
3622 fn = lno = msg = args = exc_info = func = sinfo = None
3623 extra = {'valid_key': 'some value'}
3624 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
3625 exc_info, extra=extra, sinfo=sinfo)
3626 self.assertIn('valid_key', result.__dict__)
3627
3628 def test_has_handlers(self):
3629 self.assertTrue(self.logger.hasHandlers())
3630
3631 for handler in self.logger.handlers:
3632 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003633 self.assertFalse(self.logger.hasHandlers())
3634
3635 def test_has_handlers_no_propagate(self):
3636 child_logger = logging.getLogger('blah.child')
3637 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003638 self.assertFalse(child_logger.hasHandlers())
3639
3640 def test_is_enabled_for(self):
3641 old_disable = self.logger.manager.disable
3642 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003643 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003644 self.assertFalse(self.logger.isEnabledFor(22))
3645
Florent Xicluna5252f9f2011-11-07 19:43:05 +01003646 def test_root_logger_aliases(self):
3647 root = logging.getLogger()
3648 self.assertIs(root, logging.root)
3649 self.assertIs(root, logging.getLogger(None))
3650 self.assertIs(root, logging.getLogger(''))
3651 self.assertIs(root, logging.getLogger('foo').root)
3652 self.assertIs(root, logging.getLogger('foo.bar').root)
3653 self.assertIs(root, logging.getLogger('foo').parent)
3654
3655 self.assertIsNot(root, logging.getLogger('\0'))
3656 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
3657
3658 def test_invalid_names(self):
3659 self.assertRaises(TypeError, logging.getLogger, any)
3660 self.assertRaises(TypeError, logging.getLogger, b'foo')
3661
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003662
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003663class BaseFileTest(BaseTest):
3664 "Base class for handler tests that write log files"
3665
3666 def setUp(self):
3667 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003668 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
3669 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003670 self.rmfiles = []
3671
3672 def tearDown(self):
3673 for fn in self.rmfiles:
3674 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003675 if os.path.exists(self.fn):
3676 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00003677 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003678
3679 def assertLogFile(self, filename):
3680 "Assert a log file is there and register it for deletion"
3681 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01003682 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003683 self.rmfiles.append(filename)
3684
3685
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003686class FileHandlerTest(BaseFileTest):
3687 def test_delay(self):
3688 os.unlink(self.fn)
3689 fh = logging.FileHandler(self.fn, delay=True)
3690 self.assertIsNone(fh.stream)
3691 self.assertFalse(os.path.exists(self.fn))
3692 fh.handle(logging.makeLogRecord({}))
3693 self.assertIsNotNone(fh.stream)
3694 self.assertTrue(os.path.exists(self.fn))
3695 fh.close()
3696
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003697class RotatingFileHandlerTest(BaseFileTest):
3698 def next_rec(self):
3699 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
3700 self.next_message(), None, None, None)
3701
3702 def test_should_not_rollover(self):
3703 # If maxbytes is zero rollover never occurs
3704 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
3705 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00003706 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003707
3708 def test_should_rollover(self):
3709 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
3710 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00003711 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003712
3713 def test_file_created(self):
3714 # checks that the file is created and assumes it was created
3715 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003716 rh = logging.handlers.RotatingFileHandler(self.fn)
3717 rh.emit(self.next_rec())
3718 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00003719 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003720
3721 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00003722 def namer(name):
3723 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003724 rh = logging.handlers.RotatingFileHandler(
3725 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003726 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003727 rh.emit(self.next_rec())
3728 self.assertLogFile(self.fn)
3729 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003730 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003731 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003732 self.assertLogFile(namer(self.fn + ".2"))
3733 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
3734 rh.close()
3735
Eric V. Smith851cad72012-03-11 22:46:04 -07003736 @requires_zlib
Vinay Sajip23b94d02012-01-04 12:02:26 +00003737 def test_rotator(self):
3738 def namer(name):
3739 return name + ".gz"
3740
3741 def rotator(source, dest):
3742 with open(source, "rb") as sf:
3743 data = sf.read()
3744 compressed = zlib.compress(data, 9)
3745 with open(dest, "wb") as df:
3746 df.write(compressed)
3747 os.remove(source)
3748
3749 rh = logging.handlers.RotatingFileHandler(
3750 self.fn, backupCount=2, maxBytes=1)
3751 rh.rotator = rotator
3752 rh.namer = namer
3753 m1 = self.next_rec()
3754 rh.emit(m1)
3755 self.assertLogFile(self.fn)
3756 m2 = self.next_rec()
3757 rh.emit(m2)
3758 fn = namer(self.fn + ".1")
3759 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003760 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00003761 with open(fn, "rb") as f:
3762 compressed = f.read()
3763 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003764 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003765 rh.emit(self.next_rec())
3766 fn = namer(self.fn + ".2")
3767 self.assertLogFile(fn)
3768 with open(fn, "rb") as f:
3769 compressed = f.read()
3770 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003771 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003772 rh.emit(self.next_rec())
3773 fn = namer(self.fn + ".2")
3774 with open(fn, "rb") as f:
3775 compressed = f.read()
3776 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003777 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003778 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00003779 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003780
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003781class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01003782 # other test methods added below
3783 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01003784 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
3785 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00003786 fmt = logging.Formatter('%(asctime)s %(message)s')
3787 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003788 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003789 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01003790 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003791 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00003792 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003793 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01003794 fh.close()
3795 # At this point, we should have a recent rotated file which we
3796 # can test for the existence of. However, in practice, on some
3797 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01003798 # in time to go to look for the log file. So, we go back a fair
3799 # bit, and stop as soon as we see a rotated file. In theory this
3800 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01003801 found = False
3802 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01003803 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01003804 for secs in range(GO_BACK):
3805 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01003806 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
3807 found = os.path.exists(fn)
3808 if found:
3809 self.rmfiles.append(fn)
3810 break
Vinay Sajip672c5812011-05-13 07:09:40 +01003811 msg = 'No rotated files found, went back %d seconds' % GO_BACK
3812 if not found:
3813 #print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01003814 dn, fn = os.path.split(self.fn)
3815 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02003816 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
3817 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00003818 for f in files:
3819 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00003820 path = os.path.join(dn, f)
3821 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00003822 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01003823 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003824
Vinay Sajip0372e102011-05-05 12:59:14 +01003825 def test_invalid(self):
3826 assertRaises = self.assertRaises
3827 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003828 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003829 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003830 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003831 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003832 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003833
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003834def secs(**kw):
3835 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
3836
3837for when, exp in (('S', 1),
3838 ('M', 60),
3839 ('H', 60 * 60),
3840 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00003841 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003842 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00003843 ('W0', secs(days=4, hours=24)),
3844 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003845 def test_compute_rollover(self, when=when, exp=exp):
3846 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00003847 self.fn, when=when, interval=1, backupCount=0, utc=True)
3848 currentTime = 0.0
3849 actual = rh.computeRollover(currentTime)
3850 if exp != actual:
3851 # Failures occur on some systems for MIDNIGHT and W0.
3852 # Print detailed calculation for MIDNIGHT so we can try to see
3853 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00003854 if when == 'MIDNIGHT':
3855 try:
3856 if rh.utc:
3857 t = time.gmtime(currentTime)
3858 else:
3859 t = time.localtime(currentTime)
3860 currentHour = t[3]
3861 currentMinute = t[4]
3862 currentSecond = t[5]
3863 # r is the number of seconds left between now and midnight
3864 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
3865 currentMinute) * 60 +
3866 currentSecond)
3867 result = currentTime + r
3868 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
3869 print('currentHour: %s' % currentHour, file=sys.stderr)
3870 print('currentMinute: %s' % currentMinute, file=sys.stderr)
3871 print('currentSecond: %s' % currentSecond, file=sys.stderr)
3872 print('r: %s' % r, file=sys.stderr)
3873 print('result: %s' % result, file=sys.stderr)
3874 except Exception:
3875 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
3876 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00003877 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003878 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
3879
Vinay Sajip60ccd822011-05-09 17:32:09 +01003880
3881@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil required for this test.')
3882class NTEventLogHandlerTest(BaseTest):
3883 def test_basic(self):
3884 logtype = 'Application'
3885 elh = win32evtlog.OpenEventLog(None, logtype)
3886 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
3887 h = logging.handlers.NTEventLogHandler('test_logging')
3888 r = logging.makeLogRecord({'msg': 'Test Log Message'})
3889 h.handle(r)
3890 h.close()
3891 # Now see if the event is recorded
3892 self.assertTrue(num_recs < win32evtlog.GetNumberOfEventLogRecords(elh))
3893 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
3894 win32evtlog.EVENTLOG_SEQUENTIAL_READ
3895 found = False
3896 GO_BACK = 100
3897 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
3898 for e in events:
3899 if e.SourceName != 'test_logging':
3900 continue
3901 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
3902 if msg != 'Test Log Message\r\n':
3903 continue
3904 found = True
3905 break
3906 msg = 'Record not found in event log, went back %d records' % GO_BACK
3907 self.assertTrue(found, msg=msg)
3908
Christian Heimes180510d2008-03-03 19:15:45 +00003909# Set the locale to the platform-dependent default. I have no idea
3910# why the test does this, but in any case we save the current locale
3911# first and restore it at the end.
3912@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00003913def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +00003914 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003915 CustomLevelsAndFiltersTest, HandlerTest, MemoryHandlerTest,
Vinay Sajip7367d082011-05-02 13:17:27 +01003916 ConfigFileTest, SocketHandlerTest, DatagramHandlerTest,
3917 MemoryTest, EncodingTest, WarningsTest, ConfigDictTest,
3918 ManagerTest, FormatterTest, BufferingFormatterTest,
3919 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
3920 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest,
3921 BasicConfigTest, LoggerAdapterTest, LoggerTest,
3922 SMTPHandlerTest, FileHandlerTest, RotatingFileHandlerTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003923 LastResortTest, LogRecordTest, ExceptionTest,
Vinay Sajip60ccd822011-05-09 17:32:09 +01003924 SysLogHandlerTest, HTTPHandlerTest, NTEventLogHandlerTest,
Vinay Sajip89807a52011-02-26 16:06:02 +00003925 TimedRotatingFileHandlerTest
Vinay Sajipbc85d842010-09-17 23:35:29 +00003926 )
Jeremy Hylton096d9862003-07-18 03:19:20 +00003927
Christian Heimes180510d2008-03-03 19:15:45 +00003928if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00003929 test_main()