blob: b17f5e5f54864737f58d8c13df07de5bd1110da5 [file] [log] [blame]
Vinay Sajip3f885b52013-03-22 15:19:54 +00001# Copyright 2001-2013 by Vinay Sajip. All Rights Reserved.
Christian Heimes180510d2008-03-03 19:15:45 +00002#
3# Permission to use, copy, modify, and distribute this software and its
4# documentation for any purpose and without fee is hereby granted,
5# provided that the above copyright notice appear in all copies and that
6# both that copyright notice and this permission notice appear in
7# supporting documentation, and that the name of Vinay Sajip
8# not be used in advertising or publicity pertaining to distribution
9# of the software without specific, written prior permission.
10# VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING
11# ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
12# VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR
13# ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER
14# IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT
15# OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
16
17"""Test harness for the logging module. Run all tests.
18
Vinay Sajip3f885b52013-03-22 15:19:54 +000019Copyright (C) 2001-2013 Vinay Sajip. All Rights Reserved.
Neal Norwitzb4a2df02003-01-02 14:56:39 +000020"""
21
Christian Heimes180510d2008-03-03 19:15:45 +000022import logging
23import logging.handlers
24import logging.config
Christian Heimes18c66892008-02-17 13:31:39 +000025
Benjamin Petersonf91df042009-02-13 02:50:59 +000026import codecs
Vinay Sajipcf9e2f22012-10-09 09:06:03 +010027import configparser
Vinay Sajip19ec67a2010-09-17 18:57:36 +000028import datetime
Christian Heimes180510d2008-03-03 19:15:45 +000029import pickle
30import io
31import gc
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000032import json
Christian Heimes180510d2008-03-03 19:15:45 +000033import os
Vinay Sajip8552d1f2010-09-14 09:34:09 +000034import queue
Vinay Sajip66b8b082012-04-24 23:25:30 +010035import random
Christian Heimes180510d2008-03-03 19:15:45 +000036import re
Guido van Rossum2a1d5162003-01-21 21:05:22 +000037import select
Christian Heimes180510d2008-03-03 19:15:45 +000038import socket
Christian Heimes180510d2008-03-03 19:15:45 +000039import struct
40import sys
41import tempfile
Antoine Pitrou712cb732013-12-21 15:51:54 +010042from test.script_helper import assert_python_ok
Eric V. Smith851cad72012-03-11 22:46:04 -070043from test.support import (captured_stdout, run_with_locale, run_unittest,
Serhiy Storchaka750eae12015-07-21 22:39:26 +030044 patch, requires_zlib, TestHandler, Matcher, HOST,
45 swap_attr)
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,
Vinay Sajip5421f352013-09-27 18:18:28 +010062 ThreadingTCPServer, StreamRequestHandler,
63 ThreadingUnixStreamServer,
64 ThreadingUnixDatagramServer)
Victor Stinner45df8202010-04-28 22:31:17 +000065except ImportError:
66 threading = None
Vinay Sajip60ccd822011-05-09 17:32:09 +010067try:
Vinay Sajip223349c2015-10-01 20:37:54 +010068 import win32evtlog, win32evtlogutil, pywintypes
Vinay Sajip60ccd822011-05-09 17:32:09 +010069except ImportError:
Vinay Sajip223349c2015-10-01 20:37:54 +010070 win32evtlog = win32evtlogutil = pywintypes = None
71
Eric V. Smith851cad72012-03-11 22:46:04 -070072try:
73 import zlib
74except ImportError:
75 pass
Christian Heimes18c66892008-02-17 13:31:39 +000076
Christian Heimes180510d2008-03-03 19:15:45 +000077class BaseTest(unittest.TestCase):
78
79 """Base class for logging tests."""
80
81 log_format = "%(name)s -> %(levelname)s: %(message)s"
Ezio Melotti3ffd29b2012-10-02 19:45:00 +030082 expected_log_pat = r"^([\w.]+) -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +000083 message_num = 0
84
85 def setUp(self):
86 """Setup the default logging stream to an internal StringIO instance,
87 so that we can examine log output as we want."""
88 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000089 logging._acquireLock()
90 try:
Christian Heimes180510d2008-03-03 19:15:45 +000091 self.saved_handlers = logging._handlers.copy()
92 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000093 self.saved_loggers = saved_loggers = logger_dict.copy()
Vinay Sajip3b84eae2013-05-25 03:20:34 -070094 self.saved_name_to_level = logging._nameToLevel.copy()
95 self.saved_level_to_name = logging._levelToName.copy()
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000096 self.logger_states = logger_states = {}
97 for name in saved_loggers:
98 logger_states[name] = getattr(saved_loggers[name],
99 'disabled', None)
Christian Heimes18c66892008-02-17 13:31:39 +0000100 finally:
101 logging._releaseLock()
102
Florent Xicluna5252f9f2011-11-07 19:43:05 +0100103 # Set two unused loggers
Vinay Sajipb4a08092010-09-20 09:55:00 +0000104 self.logger1 = logging.getLogger("\xab\xd7\xbb")
105 self.logger2 = logging.getLogger("\u013f\u00d6\u0047")
Benjamin Peterson22005fc2010-04-11 16:25:06 +0000106
Christian Heimes180510d2008-03-03 19:15:45 +0000107 self.root_logger = logging.getLogger("")
108 self.original_logging_level = self.root_logger.getEffectiveLevel()
109
110 self.stream = io.StringIO()
111 self.root_logger.setLevel(logging.DEBUG)
112 self.root_hdlr = logging.StreamHandler(self.stream)
113 self.root_formatter = logging.Formatter(self.log_format)
114 self.root_hdlr.setFormatter(self.root_formatter)
Vinay Sajip7b0e86e2010-12-30 23:26:50 +0000115 if self.logger1.hasHandlers():
116 hlist = self.logger1.handlers + self.root_logger.handlers
117 raise AssertionError('Unexpected handlers: %s' % hlist)
118 if self.logger2.hasHandlers():
119 hlist = self.logger2.handlers + self.root_logger.handlers
120 raise AssertionError('Unexpected handlers: %s' % hlist)
Christian Heimes180510d2008-03-03 19:15:45 +0000121 self.root_logger.addHandler(self.root_hdlr)
Vinay Sajipb4a08092010-09-20 09:55:00 +0000122 self.assertTrue(self.logger1.hasHandlers())
123 self.assertTrue(self.logger2.hasHandlers())
Christian Heimes180510d2008-03-03 19:15:45 +0000124
125 def tearDown(self):
126 """Remove our logging stream, and restore the original logging
127 level."""
128 self.stream.close()
129 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000130 while self.root_logger.handlers:
131 h = self.root_logger.handlers[0]
132 self.root_logger.removeHandler(h)
133 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +0000134 self.root_logger.setLevel(self.original_logging_level)
135 logging._acquireLock()
136 try:
Vinay Sajip3b84eae2013-05-25 03:20:34 -0700137 logging._levelToName.clear()
138 logging._levelToName.update(self.saved_level_to_name)
139 logging._nameToLevel.clear()
140 logging._nameToLevel.update(self.saved_name_to_level)
Christian Heimes180510d2008-03-03 19:15:45 +0000141 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)
Serhiy Storchaka50254c52013-08-29 11:35:43 +0300160 actual_lines = stream.getvalue().splitlines()
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100161 self.assertEqual(len(actual_lines), len(expected_values))
Christian Heimes180510d2008-03-03 19:15:45 +0000162 for actual, expected in zip(actual_lines, expected_values):
163 match = pat.search(actual)
164 if not match:
165 self.fail("Log line does not match expected pattern:\n" +
166 actual)
Ezio Melottib3aedd42010-11-20 19:04:17 +0000167 self.assertEqual(tuple(match.groups()), expected)
Christian Heimes180510d2008-03-03 19:15:45 +0000168 s = stream.read()
169 if s:
170 self.fail("Remaining output at end of log stream:\n" + s)
171
172 def next_message(self):
173 """Generate a message consisting solely of an auto-incrementing
174 integer."""
175 self.message_num += 1
176 return "%d" % self.message_num
177
178
179class BuiltinLevelsTest(BaseTest):
180 """Test builtin levels and their inheritance."""
181
182 def test_flat(self):
183 #Logging levels in a flat logger namespace.
184 m = self.next_message
185
186 ERR = logging.getLogger("ERR")
187 ERR.setLevel(logging.ERROR)
Vinay Sajipc84f0162010-09-21 11:25:39 +0000188 INF = logging.LoggerAdapter(logging.getLogger("INF"), {})
Christian Heimes180510d2008-03-03 19:15:45 +0000189 INF.setLevel(logging.INFO)
190 DEB = logging.getLogger("DEB")
191 DEB.setLevel(logging.DEBUG)
192
193 # These should log.
194 ERR.log(logging.CRITICAL, m())
195 ERR.error(m())
196
197 INF.log(logging.CRITICAL, m())
198 INF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100199 INF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000200 INF.info(m())
201
202 DEB.log(logging.CRITICAL, m())
203 DEB.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100204 DEB.warning(m())
205 DEB.info(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000206 DEB.debug(m())
207
208 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100209 ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000210 ERR.info(m())
211 ERR.debug(m())
212
213 INF.debug(m())
214
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000215 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000216 ('ERR', 'CRITICAL', '1'),
217 ('ERR', 'ERROR', '2'),
218 ('INF', 'CRITICAL', '3'),
219 ('INF', 'ERROR', '4'),
220 ('INF', 'WARNING', '5'),
221 ('INF', 'INFO', '6'),
222 ('DEB', 'CRITICAL', '7'),
223 ('DEB', 'ERROR', '8'),
224 ('DEB', 'WARNING', '9'),
225 ('DEB', 'INFO', '10'),
226 ('DEB', 'DEBUG', '11'),
227 ])
228
229 def test_nested_explicit(self):
230 # Logging levels in a nested namespace, all explicitly set.
231 m = self.next_message
232
233 INF = logging.getLogger("INF")
234 INF.setLevel(logging.INFO)
235 INF_ERR = logging.getLogger("INF.ERR")
236 INF_ERR.setLevel(logging.ERROR)
237
238 # These should log.
239 INF_ERR.log(logging.CRITICAL, m())
240 INF_ERR.error(m())
241
242 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100243 INF_ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000244 INF_ERR.info(m())
245 INF_ERR.debug(m())
246
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000247 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000248 ('INF.ERR', 'CRITICAL', '1'),
249 ('INF.ERR', 'ERROR', '2'),
250 ])
251
252 def test_nested_inherited(self):
253 #Logging levels in a nested namespace, inherited from parent loggers.
254 m = self.next_message
255
256 INF = logging.getLogger("INF")
257 INF.setLevel(logging.INFO)
258 INF_ERR = logging.getLogger("INF.ERR")
259 INF_ERR.setLevel(logging.ERROR)
260 INF_UNDEF = logging.getLogger("INF.UNDEF")
261 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
262 UNDEF = logging.getLogger("UNDEF")
263
264 # These should log.
265 INF_UNDEF.log(logging.CRITICAL, m())
266 INF_UNDEF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100267 INF_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000268 INF_UNDEF.info(m())
269 INF_ERR_UNDEF.log(logging.CRITICAL, m())
270 INF_ERR_UNDEF.error(m())
271
272 # These should not log.
273 INF_UNDEF.debug(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100274 INF_ERR_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000275 INF_ERR_UNDEF.info(m())
276 INF_ERR_UNDEF.debug(m())
277
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000278 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000279 ('INF.UNDEF', 'CRITICAL', '1'),
280 ('INF.UNDEF', 'ERROR', '2'),
281 ('INF.UNDEF', 'WARNING', '3'),
282 ('INF.UNDEF', 'INFO', '4'),
283 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
284 ('INF.ERR.UNDEF', 'ERROR', '6'),
285 ])
286
287 def test_nested_with_virtual_parent(self):
288 # Logging levels when some parent does not exist yet.
289 m = self.next_message
290
291 INF = logging.getLogger("INF")
292 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
293 CHILD = logging.getLogger("INF.BADPARENT")
294 INF.setLevel(logging.INFO)
295
296 # These should log.
297 GRANDCHILD.log(logging.FATAL, m())
298 GRANDCHILD.info(m())
299 CHILD.log(logging.FATAL, m())
300 CHILD.info(m())
301
302 # These should not log.
303 GRANDCHILD.debug(m())
304 CHILD.debug(m())
305
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000306 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000307 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
308 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
309 ('INF.BADPARENT', 'CRITICAL', '3'),
310 ('INF.BADPARENT', 'INFO', '4'),
311 ])
312
Vinay Sajipd1d4fbf2014-09-11 23:06:09 +0100313 def test_regression_22386(self):
314 """See issue #22386 for more information."""
315 self.assertEqual(logging.getLevelName('INFO'), logging.INFO)
316 self.assertEqual(logging.getLevelName(logging.INFO), 'INFO')
Christian Heimes180510d2008-03-03 19:15:45 +0000317
318class BasicFilterTest(BaseTest):
319
320 """Test the bundled Filter class."""
321
322 def test_filter(self):
323 # Only messages satisfying the specified criteria pass through the
324 # filter.
325 filter_ = logging.Filter("spam.eggs")
326 handler = self.root_logger.handlers[0]
327 try:
328 handler.addFilter(filter_)
329 spam = logging.getLogger("spam")
330 spam_eggs = logging.getLogger("spam.eggs")
331 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
332 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
333
334 spam.info(self.next_message())
335 spam_eggs.info(self.next_message()) # Good.
336 spam_eggs_fish.info(self.next_message()) # Good.
337 spam_bakedbeans.info(self.next_message())
338
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000339 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000340 ('spam.eggs', 'INFO', '2'),
341 ('spam.eggs.fish', 'INFO', '3'),
342 ])
343 finally:
344 handler.removeFilter(filter_)
345
Vinay Sajip6dbed2e2010-10-19 20:53:01 +0000346 def test_callable_filter(self):
347 # Only messages satisfying the specified criteria pass through the
348 # filter.
349
350 def filterfunc(record):
351 parts = record.name.split('.')
352 prefix = '.'.join(parts[:2])
353 return prefix == 'spam.eggs'
354
355 handler = self.root_logger.handlers[0]
356 try:
357 handler.addFilter(filterfunc)
358 spam = logging.getLogger("spam")
359 spam_eggs = logging.getLogger("spam.eggs")
360 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
361 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
362
363 spam.info(self.next_message())
364 spam_eggs.info(self.next_message()) # Good.
365 spam_eggs_fish.info(self.next_message()) # Good.
366 spam_bakedbeans.info(self.next_message())
367
368 self.assert_log_lines([
369 ('spam.eggs', 'INFO', '2'),
370 ('spam.eggs.fish', 'INFO', '3'),
371 ])
372 finally:
373 handler.removeFilter(filterfunc)
374
Vinay Sajip985ef872011-04-26 19:34:04 +0100375 def test_empty_filter(self):
376 f = logging.Filter()
377 r = logging.makeLogRecord({'name': 'spam.eggs'})
378 self.assertTrue(f.filter(r))
Christian Heimes180510d2008-03-03 19:15:45 +0000379
380#
381# First, we define our levels. There can be as many as you want - the only
382# limitations are that they should be integers, the lowest should be > 0 and
383# larger values mean less information being logged. If you need specific
384# level values which do not fit into these limitations, you can use a
385# mapping dictionary to convert between your application levels and the
386# logging system.
387#
388SILENT = 120
389TACITURN = 119
390TERSE = 118
391EFFUSIVE = 117
392SOCIABLE = 116
393VERBOSE = 115
394TALKATIVE = 114
395GARRULOUS = 113
396CHATTERBOX = 112
397BORING = 111
398
399LEVEL_RANGE = range(BORING, SILENT + 1)
400
401#
402# Next, we define names for our levels. You don't need to do this - in which
403# case the system will use "Level n" to denote the text for the level.
404#
405my_logging_levels = {
406 SILENT : 'Silent',
407 TACITURN : 'Taciturn',
408 TERSE : 'Terse',
409 EFFUSIVE : 'Effusive',
410 SOCIABLE : 'Sociable',
411 VERBOSE : 'Verbose',
412 TALKATIVE : 'Talkative',
413 GARRULOUS : 'Garrulous',
414 CHATTERBOX : 'Chatterbox',
415 BORING : 'Boring',
416}
417
418class GarrulousFilter(logging.Filter):
419
420 """A filter which blocks garrulous messages."""
421
422 def filter(self, record):
423 return record.levelno != GARRULOUS
424
425class VerySpecificFilter(logging.Filter):
426
427 """A filter which blocks sociable and taciturn messages."""
428
429 def filter(self, record):
430 return record.levelno not in [SOCIABLE, TACITURN]
431
432
433class CustomLevelsAndFiltersTest(BaseTest):
434
435 """Test various filtering possibilities with custom logging levels."""
436
437 # Skip the logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +0300438 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +0000439
440 def setUp(self):
441 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000442 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000443 logging.addLevelName(k, v)
444
445 def log_at_all_levels(self, logger):
446 for lvl in LEVEL_RANGE:
447 logger.log(lvl, self.next_message())
448
449 def test_logger_filter(self):
450 # Filter at logger level.
451 self.root_logger.setLevel(VERBOSE)
452 # Levels >= 'Verbose' are good.
453 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000454 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000455 ('Verbose', '5'),
456 ('Sociable', '6'),
457 ('Effusive', '7'),
458 ('Terse', '8'),
459 ('Taciturn', '9'),
460 ('Silent', '10'),
461 ])
462
463 def test_handler_filter(self):
464 # Filter at handler level.
465 self.root_logger.handlers[0].setLevel(SOCIABLE)
466 try:
467 # Levels >= 'Sociable' are good.
468 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000469 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000470 ('Sociable', '6'),
471 ('Effusive', '7'),
472 ('Terse', '8'),
473 ('Taciturn', '9'),
474 ('Silent', '10'),
475 ])
476 finally:
477 self.root_logger.handlers[0].setLevel(logging.NOTSET)
478
479 def test_specific_filters(self):
480 # Set a specific filter object on the handler, and then add another
481 # filter object on the logger itself.
482 handler = self.root_logger.handlers[0]
483 specific_filter = None
484 garr = GarrulousFilter()
485 handler.addFilter(garr)
486 try:
487 self.log_at_all_levels(self.root_logger)
488 first_lines = [
489 # Notice how 'Garrulous' is missing
490 ('Boring', '1'),
491 ('Chatterbox', '2'),
492 ('Talkative', '4'),
493 ('Verbose', '5'),
494 ('Sociable', '6'),
495 ('Effusive', '7'),
496 ('Terse', '8'),
497 ('Taciturn', '9'),
498 ('Silent', '10'),
499 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000500 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000501
502 specific_filter = VerySpecificFilter()
503 self.root_logger.addFilter(specific_filter)
504 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000505 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000506 # Not only 'Garrulous' is still missing, but also 'Sociable'
507 # and 'Taciturn'
508 ('Boring', '11'),
509 ('Chatterbox', '12'),
510 ('Talkative', '14'),
511 ('Verbose', '15'),
512 ('Effusive', '17'),
513 ('Terse', '18'),
514 ('Silent', '20'),
515 ])
516 finally:
517 if specific_filter:
518 self.root_logger.removeFilter(specific_filter)
519 handler.removeFilter(garr)
520
521
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100522class HandlerTest(BaseTest):
523 def test_name(self):
524 h = logging.Handler()
525 h.name = 'generic'
526 self.assertEqual(h.name, 'generic')
527 h.name = 'anothergeneric'
528 self.assertEqual(h.name, 'anothergeneric')
529 self.assertRaises(NotImplementedError, h.emit, None)
530
Vinay Sajip5a35b062011-04-27 11:31:14 +0100531 def test_builtin_handlers(self):
532 # We can't actually *use* too many handlers in the tests,
533 # but we can try instantiating them with various options
Victor Stinnere6747472011-08-21 00:39:18 +0200534 if sys.platform in ('linux', 'darwin'):
Vinay Sajip5a35b062011-04-27 11:31:14 +0100535 for existing in (True, False):
536 fd, fn = tempfile.mkstemp()
537 os.close(fd)
538 if not existing:
539 os.unlink(fn)
540 h = logging.handlers.WatchedFileHandler(fn, delay=True)
541 if existing:
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100542 dev, ino = h.dev, h.ino
Vinay Sajipa5798de2012-04-24 23:33:33 +0100543 self.assertEqual(dev, -1)
544 self.assertEqual(ino, -1)
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100545 r = logging.makeLogRecord({'msg': 'Test'})
546 h.handle(r)
547 # Now remove the file.
548 os.unlink(fn)
549 self.assertFalse(os.path.exists(fn))
550 # The next call should recreate the file.
551 h.handle(r)
552 self.assertTrue(os.path.exists(fn))
Vinay Sajip5a35b062011-04-27 11:31:14 +0100553 else:
554 self.assertEqual(h.dev, -1)
555 self.assertEqual(h.ino, -1)
556 h.close()
557 if existing:
558 os.unlink(fn)
559 if sys.platform == 'darwin':
Vinay Sajip6bba65c2011-04-27 14:31:55 +0100560 sockname = '/var/run/syslog'
Vinay Sajip5a35b062011-04-27 11:31:14 +0100561 else:
562 sockname = '/dev/log'
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100563 try:
564 h = logging.handlers.SysLogHandler(sockname)
565 self.assertEqual(h.facility, h.LOG_USER)
566 self.assertTrue(h.unixsocket)
567 h.close()
Andrew Svetlov0832af62012-12-18 23:10:48 +0200568 except OSError: # syslogd might not be available
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100569 pass
Vinay Sajip5a35b062011-04-27 11:31:14 +0100570 for method in ('GET', 'POST', 'PUT'):
571 if method == 'PUT':
572 self.assertRaises(ValueError, logging.handlers.HTTPHandler,
573 'localhost', '/log', method)
574 else:
575 h = logging.handlers.HTTPHandler('localhost', '/log', method)
576 h.close()
577 h = logging.handlers.BufferingHandler(0)
578 r = logging.makeLogRecord({})
579 self.assertTrue(h.shouldFlush(r))
580 h.close()
581 h = logging.handlers.BufferingHandler(1)
582 self.assertFalse(h.shouldFlush(r))
583 h.close()
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100584
Vinay Sajip5e86eed2012-05-29 22:48:10 +0100585 @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.')
Vinay Sajipa5798de2012-04-24 23:33:33 +0100586 @unittest.skipUnless(threading, 'Threading required for this test.')
587 def test_race(self):
588 # Issue #14632 refers.
589 def remove_loop(fname, tries):
590 for _ in range(tries):
591 try:
592 os.unlink(fname)
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000593 self.deletion_time = time.time()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100594 except OSError:
595 pass
596 time.sleep(0.004 * random.randint(0, 4))
597
Vinay Sajipc94871a2012-04-25 10:51:35 +0100598 del_count = 500
599 log_count = 500
Vinay Sajipa5798de2012-04-24 23:33:33 +0100600
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000601 self.handle_time = None
602 self.deletion_time = None
603
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' })
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000617 try:
618 self.handle_time = time.time()
619 h.handle(r)
620 except Exception:
621 print('Deleted at %s, '
622 'opened at %s' % (self.deletion_time,
623 self.handle_time))
624 raise
Vinay Sajipc94871a2012-04-25 10:51:35 +0100625 finally:
Vinay Sajipc94871a2012-04-25 10:51:35 +0100626 remover.join()
Vinay Sajipac20f462012-05-03 12:09:38 +0100627 h.close()
Vinay Sajipc94871a2012-04-25 10:51:35 +0100628 if os.path.exists(fn):
629 os.unlink(fn)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100630
631
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100632class BadStream(object):
633 def write(self, data):
634 raise RuntimeError('deliberate mistake')
635
636class TestStreamHandler(logging.StreamHandler):
637 def handleError(self, record):
638 self.error_record = record
639
640class StreamHandlerTest(BaseTest):
641 def test_error_handling(self):
642 h = TestStreamHandler(BadStream())
643 r = logging.makeLogRecord({})
644 old_raise = logging.raiseExceptions
Vinay Sajip985ef872011-04-26 19:34:04 +0100645 old_stderr = sys.stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100646 try:
647 h.handle(r)
648 self.assertIs(h.error_record, r)
Vinay Sajip985ef872011-04-26 19:34:04 +0100649 h = logging.StreamHandler(BadStream())
650 sys.stderr = sio = io.StringIO()
651 h.handle(r)
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100652 self.assertIn('\nRuntimeError: deliberate mistake\n',
653 sio.getvalue())
Vinay Sajip985ef872011-04-26 19:34:04 +0100654 logging.raiseExceptions = False
655 sys.stderr = sio = io.StringIO()
656 h.handle(r)
657 self.assertEqual('', sio.getvalue())
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100658 finally:
659 logging.raiseExceptions = old_raise
Vinay Sajip985ef872011-04-26 19:34:04 +0100660 sys.stderr = old_stderr
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100661
Vinay Sajip7367d082011-05-02 13:17:27 +0100662# -- The following section could be moved into a server_helper.py module
663# -- if it proves to be of wider utility than just test_logging
Vinay Sajipa463d252011-04-30 21:52:48 +0100664
Vinay Sajipce7c9782011-05-17 07:15:53 +0100665if threading:
Vinay Sajipce7c9782011-05-17 07:15:53 +0100666 class TestSMTPServer(smtpd.SMTPServer):
Vinay Sajip314b92b2011-05-02 14:31:16 +0100667 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100668 This class implements a test SMTP server.
Vinay Sajipa463d252011-04-30 21:52:48 +0100669
Vinay Sajipce7c9782011-05-17 07:15:53 +0100670 :param addr: A (host, port) tuple which the server listens on.
671 You can specify a port value of zero: the server's
672 *port* attribute will hold the actual port number
673 used, which can be used in client connections.
674 :param handler: A callable which will be called to process
675 incoming messages. The handler will be passed
676 the client address tuple, who the message is from,
677 a list of recipients and the message data.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100678 :param poll_interval: The interval, in seconds, used in the underlying
679 :func:`select` or :func:`poll` call by
680 :func:`asyncore.loop`.
Vinay Sajipce7c9782011-05-17 07:15:53 +0100681 :param sockmap: A dictionary which will be used to hold
682 :class:`asyncore.dispatcher` instances used by
683 :func:`asyncore.loop`. This avoids changing the
684 :mod:`asyncore` module's global state.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100685 """
Vinay Sajipce7c9782011-05-17 07:15:53 +0100686
687 def __init__(self, addr, handler, poll_interval, sockmap):
Vinay Sajip30298b42013-06-07 15:21:41 +0100688 smtpd.SMTPServer.__init__(self, addr, None, map=sockmap)
689 self.port = self.socket.getsockname()[1]
Vinay Sajipce7c9782011-05-17 07:15:53 +0100690 self._handler = handler
691 self._thread = None
692 self.poll_interval = poll_interval
Vinay Sajipa463d252011-04-30 21:52:48 +0100693
Vinay Sajipce7c9782011-05-17 07:15:53 +0100694 def process_message(self, peer, mailfrom, rcpttos, data):
695 """
696 Delegates to the handler passed in to the server's constructor.
Vinay Sajipa463d252011-04-30 21:52:48 +0100697
Vinay Sajipce7c9782011-05-17 07:15:53 +0100698 Typically, this will be a test case method.
699 :param peer: The client (host, port) tuple.
700 :param mailfrom: The address of the sender.
701 :param rcpttos: The addresses of the recipients.
702 :param data: The message.
703 """
704 self._handler(peer, mailfrom, rcpttos, data)
Vinay Sajip7367d082011-05-02 13:17:27 +0100705
Vinay Sajipce7c9782011-05-17 07:15:53 +0100706 def start(self):
707 """
708 Start the server running on a separate daemon thread.
709 """
710 self._thread = t = threading.Thread(target=self.serve_forever,
711 args=(self.poll_interval,))
712 t.setDaemon(True)
713 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100714
Vinay Sajipce7c9782011-05-17 07:15:53 +0100715 def serve_forever(self, poll_interval):
716 """
717 Run the :mod:`asyncore` loop until normal termination
718 conditions arise.
719 :param poll_interval: The interval, in seconds, used in the underlying
720 :func:`select` or :func:`poll` call by
721 :func:`asyncore.loop`.
722 """
723 try:
Vinay Sajip30298b42013-06-07 15:21:41 +0100724 asyncore.loop(poll_interval, map=self._map)
Andrew Svetlov6d8a1222012-12-17 22:23:46 +0200725 except OSError:
Vinay Sajipce7c9782011-05-17 07:15:53 +0100726 # On FreeBSD 8, closing the server repeatably
727 # raises this error. We swallow it if the
728 # server has been closed.
729 if self.connected or self.accepting:
730 raise
Vinay Sajip7367d082011-05-02 13:17:27 +0100731
Vinay Sajipce7c9782011-05-17 07:15:53 +0100732 def stop(self, timeout=None):
733 """
734 Stop the thread by closing the server instance.
735 Wait for the server thread to terminate.
Vinay Sajip7367d082011-05-02 13:17:27 +0100736
Vinay Sajipce7c9782011-05-17 07:15:53 +0100737 :param timeout: How long to wait for the server thread
738 to terminate.
739 """
740 self.close()
Vinay Sajip7367d082011-05-02 13:17:27 +0100741 self._thread.join(timeout)
742 self._thread = None
Vinay Sajip7367d082011-05-02 13:17:27 +0100743
Vinay Sajipce7c9782011-05-17 07:15:53 +0100744 class ControlMixin(object):
745 """
746 This mixin is used to start a server on a separate thread, and
747 shut it down programmatically. Request handling is simplified - instead
748 of needing to derive a suitable RequestHandler subclass, you just
749 provide a callable which will be passed each received request to be
750 processed.
Vinay Sajip7367d082011-05-02 13:17:27 +0100751
Vinay Sajipce7c9782011-05-17 07:15:53 +0100752 :param handler: A handler callable which will be called with a
753 single parameter - the request - in order to
754 process the request. This handler is called on the
755 server thread, effectively meaning that requests are
756 processed serially. While not quite Web scale ;-),
757 this should be fine for testing applications.
758 :param poll_interval: The polling interval in seconds.
759 """
760 def __init__(self, handler, poll_interval):
761 self._thread = None
762 self.poll_interval = poll_interval
763 self._handler = handler
764 self.ready = threading.Event()
Vinay Sajip7367d082011-05-02 13:17:27 +0100765
Vinay Sajipce7c9782011-05-17 07:15:53 +0100766 def start(self):
767 """
768 Create a daemon thread to run the server, and start it.
769 """
770 self._thread = t = threading.Thread(target=self.serve_forever,
771 args=(self.poll_interval,))
772 t.setDaemon(True)
773 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100774
Vinay Sajipce7c9782011-05-17 07:15:53 +0100775 def serve_forever(self, poll_interval):
776 """
777 Run the server. Set the ready flag before entering the
778 service loop.
779 """
780 self.ready.set()
781 super(ControlMixin, self).serve_forever(poll_interval)
Vinay Sajip7367d082011-05-02 13:17:27 +0100782
Vinay Sajipce7c9782011-05-17 07:15:53 +0100783 def stop(self, timeout=None):
784 """
785 Tell the server thread to stop, and wait for it to do so.
Vinay Sajip7367d082011-05-02 13:17:27 +0100786
Vinay Sajipce7c9782011-05-17 07:15:53 +0100787 :param timeout: How long to wait for the server thread
788 to terminate.
789 """
790 self.shutdown()
791 if self._thread is not None:
792 self._thread.join(timeout)
793 self._thread = None
794 self.server_close()
795 self.ready.clear()
Vinay Sajip7367d082011-05-02 13:17:27 +0100796
Vinay Sajipce7c9782011-05-17 07:15:53 +0100797 class TestHTTPServer(ControlMixin, HTTPServer):
798 """
799 An HTTP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100800
Vinay Sajipce7c9782011-05-17 07:15:53 +0100801 :param addr: A tuple with the IP address and port to listen on.
802 :param handler: A handler callable which will be called with a
803 single parameter - the request - in order to
804 process the request.
805 :param poll_interval: The polling interval in seconds.
806 :param log: Pass ``True`` to enable log messages.
807 """
Vinay Sajip32565b62011-05-21 00:34:51 +0100808 def __init__(self, addr, handler, poll_interval=0.5,
809 log=False, sslctx=None):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100810 class DelegatingHTTPRequestHandler(BaseHTTPRequestHandler):
811 def __getattr__(self, name, default=None):
812 if name.startswith('do_'):
813 return self.process_request
814 raise AttributeError(name)
Vinay Sajip7367d082011-05-02 13:17:27 +0100815
Vinay Sajipce7c9782011-05-17 07:15:53 +0100816 def process_request(self):
817 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +0100818
Vinay Sajipce7c9782011-05-17 07:15:53 +0100819 def log_message(self, format, *args):
820 if log:
821 super(DelegatingHTTPRequestHandler,
822 self).log_message(format, *args)
823 HTTPServer.__init__(self, addr, DelegatingHTTPRequestHandler)
824 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajip32565b62011-05-21 00:34:51 +0100825 self.sslctx = sslctx
826
827 def get_request(self):
828 try:
829 sock, addr = self.socket.accept()
830 if self.sslctx:
831 sock = self.sslctx.wrap_socket(sock, server_side=True)
Andrew Svetlov0832af62012-12-18 23:10:48 +0200832 except OSError as e:
Vinay Sajip32565b62011-05-21 00:34:51 +0100833 # socket errors are silenced by the caller, print them here
834 sys.stderr.write("Got an error:\n%s\n" % e)
835 raise
836 return sock, addr
Vinay Sajip7367d082011-05-02 13:17:27 +0100837
Vinay Sajipce7c9782011-05-17 07:15:53 +0100838 class TestTCPServer(ControlMixin, ThreadingTCPServer):
839 """
840 A TCP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100841
Vinay Sajipce7c9782011-05-17 07:15:53 +0100842 :param addr: A tuple with the IP address and port to listen on.
843 :param handler: A handler callable which will be called with a single
844 parameter - the request - in order to process the request.
845 :param poll_interval: The polling interval in seconds.
846 :bind_and_activate: If True (the default), binds the server and starts it
847 listening. If False, you need to call
848 :meth:`server_bind` and :meth:`server_activate` at
849 some later time before calling :meth:`start`, so that
850 the server will set up the socket and listen on it.
851 """
Vinay Sajip7367d082011-05-02 13:17:27 +0100852
Vinay Sajipce7c9782011-05-17 07:15:53 +0100853 allow_reuse_address = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100854
Vinay Sajipce7c9782011-05-17 07:15:53 +0100855 def __init__(self, addr, handler, poll_interval=0.5,
856 bind_and_activate=True):
857 class DelegatingTCPRequestHandler(StreamRequestHandler):
858
859 def handle(self):
860 self.server._handler(self)
861 ThreadingTCPServer.__init__(self, addr, DelegatingTCPRequestHandler,
862 bind_and_activate)
863 ControlMixin.__init__(self, handler, poll_interval)
864
865 def server_bind(self):
866 super(TestTCPServer, self).server_bind()
867 self.port = self.socket.getsockname()[1]
868
869 class TestUDPServer(ControlMixin, ThreadingUDPServer):
870 """
871 A UDP server which is controllable using :class:`ControlMixin`.
872
873 :param addr: A tuple with the IP address and port to listen on.
874 :param handler: A handler callable which will be called with a
875 single parameter - the request - in order to
876 process the request.
877 :param poll_interval: The polling interval for shutdown requests,
878 in seconds.
879 :bind_and_activate: If True (the default), binds the server and
880 starts it listening. If False, you need to
881 call :meth:`server_bind` and
882 :meth:`server_activate` at some later time
883 before calling :meth:`start`, so that the server will
884 set up the socket and listen on it.
885 """
Vinay Sajip3ef12292011-05-23 23:00:42 +0100886 def __init__(self, addr, handler, poll_interval=0.5,
887 bind_and_activate=True):
Vinay Sajipce7c9782011-05-17 07:15:53 +0100888 class DelegatingUDPRequestHandler(DatagramRequestHandler):
889
890 def handle(self):
891 self.server._handler(self)
Vinay Sajipba980db2011-05-23 21:37:54 +0100892
893 def finish(self):
894 data = self.wfile.getvalue()
Vinay Sajip3ef12292011-05-23 23:00:42 +0100895 if data:
896 try:
897 super(DelegatingUDPRequestHandler, self).finish()
Andrew Svetlov0832af62012-12-18 23:10:48 +0200898 except OSError:
Vinay Sajip3ef12292011-05-23 23:00:42 +0100899 if not self.server._closed:
900 raise
Vinay Sajipba980db2011-05-23 21:37:54 +0100901
Vinay Sajip3ef12292011-05-23 23:00:42 +0100902 ThreadingUDPServer.__init__(self, addr,
903 DelegatingUDPRequestHandler,
Vinay Sajipce7c9782011-05-17 07:15:53 +0100904 bind_and_activate)
905 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajipba980db2011-05-23 21:37:54 +0100906 self._closed = False
Vinay Sajipce7c9782011-05-17 07:15:53 +0100907
908 def server_bind(self):
909 super(TestUDPServer, self).server_bind()
910 self.port = self.socket.getsockname()[1]
Vinay Sajip7367d082011-05-02 13:17:27 +0100911
Vinay Sajipba980db2011-05-23 21:37:54 +0100912 def server_close(self):
913 super(TestUDPServer, self).server_close()
914 self._closed = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100915
Victor Stinnerec5a8602014-06-02 14:41:51 +0200916 if hasattr(socket, "AF_UNIX"):
917 class TestUnixStreamServer(TestTCPServer):
918 address_family = socket.AF_UNIX
919
920 class TestUnixDatagramServer(TestUDPServer):
921 address_family = socket.AF_UNIX
Vinay Sajip5421f352013-09-27 18:18:28 +0100922
Vinay Sajip7367d082011-05-02 13:17:27 +0100923# - end of server_helper section
Vinay Sajipa463d252011-04-30 21:52:48 +0100924
Vinay Sajipce7c9782011-05-17 07:15:53 +0100925@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipa463d252011-04-30 21:52:48 +0100926class SMTPHandlerTest(BaseTest):
Vinay Sajip827f5d32013-12-03 11:28:55 +0000927 TIMEOUT = 8.0
Vinay Sajipa463d252011-04-30 21:52:48 +0100928 def test_basic(self):
Vinay Sajip7367d082011-05-02 13:17:27 +0100929 sockmap = {}
Ned Deily3bbb37e2015-01-17 17:31:13 -0800930 server = TestSMTPServer((HOST, 0), self.process_message, 0.001,
Vinay Sajip7367d082011-05-02 13:17:27 +0100931 sockmap)
932 server.start()
Ned Deily3bbb37e2015-01-17 17:31:13 -0800933 addr = (HOST, server.port)
Vinay Sajip827f5d32013-12-03 11:28:55 +0000934 h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log',
935 timeout=self.TIMEOUT)
Vinay Sajipa463d252011-04-30 21:52:48 +0100936 self.assertEqual(h.toaddrs, ['you'])
937 self.messages = []
Vinay Sajip277640a2015-10-17 16:13:10 +0100938 r = logging.makeLogRecord({'msg': 'Hello \u2713'})
Vinay Sajip7367d082011-05-02 13:17:27 +0100939 self.handled = threading.Event()
Vinay Sajipa463d252011-04-30 21:52:48 +0100940 h.handle(r)
Vinay Sajip827f5d32013-12-03 11:28:55 +0000941 self.handled.wait(self.TIMEOUT) # 14314: don't wait forever
Vinay Sajipa463d252011-04-30 21:52:48 +0100942 server.stop()
Vinay Sajip17160fd2012-03-15 12:02:08 +0000943 self.assertTrue(self.handled.is_set())
Vinay Sajipa463d252011-04-30 21:52:48 +0100944 self.assertEqual(len(self.messages), 1)
945 peer, mailfrom, rcpttos, data = self.messages[0]
946 self.assertEqual(mailfrom, 'me')
947 self.assertEqual(rcpttos, ['you'])
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100948 self.assertIn('\nSubject: Log\n', data)
Vinay Sajip277640a2015-10-17 16:13:10 +0100949 self.assertTrue(data.endswith('\n\nHello \u2713'))
Vinay Sajipa463d252011-04-30 21:52:48 +0100950 h.close()
951
952 def process_message(self, *args):
953 self.messages.append(args)
Vinay Sajip7367d082011-05-02 13:17:27 +0100954 self.handled.set()
Vinay Sajipa463d252011-04-30 21:52:48 +0100955
Christian Heimes180510d2008-03-03 19:15:45 +0000956class MemoryHandlerTest(BaseTest):
957
958 """Tests for the MemoryHandler."""
959
960 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +0300961 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +0000962
963 def setUp(self):
964 BaseTest.setUp(self)
965 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
966 self.root_hdlr)
967 self.mem_logger = logging.getLogger('mem')
968 self.mem_logger.propagate = 0
969 self.mem_logger.addHandler(self.mem_hdlr)
970
971 def tearDown(self):
972 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +0000973 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +0000974
975 def test_flush(self):
976 # The memory handler flushes to its target handler based on specific
977 # criteria (message count and message level).
978 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000979 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000980 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000981 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +0000982 # This will flush because the level is >= logging.WARNING
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100983 self.mem_logger.warning(self.next_message())
Christian Heimes180510d2008-03-03 19:15:45 +0000984 lines = [
985 ('DEBUG', '1'),
986 ('INFO', '2'),
987 ('WARNING', '3'),
988 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000989 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000990 for n in (4, 14):
991 for i in range(9):
992 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000993 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000994 # This will flush because it's the 10th message since the last
995 # flush.
996 self.mem_logger.debug(self.next_message())
997 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000998 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000999
1000 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001001 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001002
1003
1004class ExceptionFormatter(logging.Formatter):
1005 """A special exception formatter."""
1006 def formatException(self, ei):
1007 return "Got a [%s]" % ei[0].__name__
1008
1009
1010class ConfigFileTest(BaseTest):
1011
1012 """Reading logging config from a .ini-style config file."""
1013
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001014 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001015
1016 # config0 is a standard configuration.
1017 config0 = """
1018 [loggers]
1019 keys=root
1020
1021 [handlers]
1022 keys=hand1
1023
1024 [formatters]
1025 keys=form1
1026
1027 [logger_root]
1028 level=WARNING
1029 handlers=hand1
1030
1031 [handler_hand1]
1032 class=StreamHandler
1033 level=NOTSET
1034 formatter=form1
1035 args=(sys.stdout,)
1036
1037 [formatter_form1]
1038 format=%(levelname)s ++ %(message)s
1039 datefmt=
1040 """
1041
1042 # config1 adds a little to the standard configuration.
1043 config1 = """
1044 [loggers]
1045 keys=root,parser
1046
1047 [handlers]
1048 keys=hand1
1049
1050 [formatters]
1051 keys=form1
1052
1053 [logger_root]
1054 level=WARNING
1055 handlers=
1056
1057 [logger_parser]
1058 level=DEBUG
1059 handlers=hand1
1060 propagate=1
1061 qualname=compiler.parser
1062
1063 [handler_hand1]
1064 class=StreamHandler
1065 level=NOTSET
1066 formatter=form1
1067 args=(sys.stdout,)
1068
1069 [formatter_form1]
1070 format=%(levelname)s ++ %(message)s
1071 datefmt=
1072 """
1073
Vinay Sajip3f84b072011-03-07 17:49:33 +00001074 # config1a moves the handler to the root.
1075 config1a = """
1076 [loggers]
1077 keys=root,parser
1078
1079 [handlers]
1080 keys=hand1
1081
1082 [formatters]
1083 keys=form1
1084
1085 [logger_root]
1086 level=WARNING
1087 handlers=hand1
1088
1089 [logger_parser]
1090 level=DEBUG
1091 handlers=
1092 propagate=1
1093 qualname=compiler.parser
1094
1095 [handler_hand1]
1096 class=StreamHandler
1097 level=NOTSET
1098 formatter=form1
1099 args=(sys.stdout,)
1100
1101 [formatter_form1]
1102 format=%(levelname)s ++ %(message)s
1103 datefmt=
1104 """
1105
Christian Heimes180510d2008-03-03 19:15:45 +00001106 # config2 has a subtle configuration error that should be reported
1107 config2 = config1.replace("sys.stdout", "sys.stbout")
1108
1109 # config3 has a less subtle configuration error
1110 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
1111
1112 # config4 specifies a custom formatter class to be loaded
1113 config4 = """
1114 [loggers]
1115 keys=root
1116
1117 [handlers]
1118 keys=hand1
1119
1120 [formatters]
1121 keys=form1
1122
1123 [logger_root]
1124 level=NOTSET
1125 handlers=hand1
1126
1127 [handler_hand1]
1128 class=StreamHandler
1129 level=NOTSET
1130 formatter=form1
1131 args=(sys.stdout,)
1132
1133 [formatter_form1]
1134 class=""" + __name__ + """.ExceptionFormatter
1135 format=%(levelname)s:%(name)s:%(message)s
1136 datefmt=
1137 """
1138
Georg Brandl3dbca812008-07-23 16:10:53 +00001139 # config5 specifies a custom handler class to be loaded
1140 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
1141
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001142 # config6 uses ', ' delimiters in the handlers and formatters sections
1143 config6 = """
1144 [loggers]
1145 keys=root,parser
1146
1147 [handlers]
1148 keys=hand1, hand2
1149
1150 [formatters]
1151 keys=form1, form2
1152
1153 [logger_root]
1154 level=WARNING
1155 handlers=
1156
1157 [logger_parser]
1158 level=DEBUG
1159 handlers=hand1
1160 propagate=1
1161 qualname=compiler.parser
1162
1163 [handler_hand1]
1164 class=StreamHandler
1165 level=NOTSET
1166 formatter=form1
1167 args=(sys.stdout,)
1168
1169 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001170 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001171 level=NOTSET
1172 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001173 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001174
1175 [formatter_form1]
1176 format=%(levelname)s ++ %(message)s
1177 datefmt=
1178
1179 [formatter_form2]
1180 format=%(message)s
1181 datefmt=
1182 """
1183
Vinay Sajip3f84b072011-03-07 17:49:33 +00001184 # config7 adds a compiler logger.
1185 config7 = """
1186 [loggers]
1187 keys=root,parser,compiler
1188
1189 [handlers]
1190 keys=hand1
1191
1192 [formatters]
1193 keys=form1
1194
1195 [logger_root]
1196 level=WARNING
1197 handlers=hand1
1198
1199 [logger_compiler]
1200 level=DEBUG
1201 handlers=
1202 propagate=1
1203 qualname=compiler
1204
1205 [logger_parser]
1206 level=DEBUG
1207 handlers=
1208 propagate=1
1209 qualname=compiler.parser
1210
1211 [handler_hand1]
1212 class=StreamHandler
1213 level=NOTSET
1214 formatter=form1
1215 args=(sys.stdout,)
1216
1217 [formatter_form1]
1218 format=%(levelname)s ++ %(message)s
1219 datefmt=
1220 """
1221
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001222 disable_test = """
1223 [loggers]
1224 keys=root
1225
1226 [handlers]
1227 keys=screen
1228
1229 [formatters]
1230 keys=
1231
1232 [logger_root]
1233 level=DEBUG
1234 handlers=screen
1235
1236 [handler_screen]
1237 level=DEBUG
1238 class=StreamHandler
1239 args=(sys.stdout,)
1240 formatter=
1241 """
1242
1243 def apply_config(self, conf, **kwargs):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001244 file = io.StringIO(textwrap.dedent(conf))
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001245 logging.config.fileConfig(file, **kwargs)
Christian Heimes180510d2008-03-03 19:15:45 +00001246
1247 def test_config0_ok(self):
1248 # A simple config file which overrides the default settings.
1249 with captured_stdout() as output:
1250 self.apply_config(self.config0)
1251 logger = logging.getLogger()
1252 # Won't output anything
1253 logger.info(self.next_message())
1254 # Outputs a message
1255 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001256 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001257 ('ERROR', '2'),
1258 ], stream=output)
1259 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001260 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001261
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001262 def test_config0_using_cp_ok(self):
1263 # A simple config file which overrides the default settings.
1264 with captured_stdout() as output:
1265 file = io.StringIO(textwrap.dedent(self.config0))
1266 cp = configparser.ConfigParser()
1267 cp.read_file(file)
1268 logging.config.fileConfig(cp)
1269 logger = logging.getLogger()
1270 # Won't output anything
1271 logger.info(self.next_message())
1272 # Outputs a message
1273 logger.error(self.next_message())
1274 self.assert_log_lines([
1275 ('ERROR', '2'),
1276 ], stream=output)
1277 # Original logger output is empty.
1278 self.assert_log_lines([])
1279
Georg Brandl3dbca812008-07-23 16:10:53 +00001280 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +00001281 # A config file defining a sub-parser as well.
1282 with captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +00001283 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +00001284 logger = logging.getLogger("compiler.parser")
1285 # Both will output a message
1286 logger.info(self.next_message())
1287 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001288 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001289 ('INFO', '1'),
1290 ('ERROR', '2'),
1291 ], stream=output)
1292 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001293 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001294
1295 def test_config2_failure(self):
1296 # A simple config file which overrides the default settings.
1297 self.assertRaises(Exception, self.apply_config, self.config2)
1298
1299 def test_config3_failure(self):
1300 # A simple config file which overrides the default settings.
1301 self.assertRaises(Exception, self.apply_config, self.config3)
1302
1303 def test_config4_ok(self):
1304 # A config file specifying a custom formatter class.
1305 with captured_stdout() as output:
1306 self.apply_config(self.config4)
1307 logger = logging.getLogger()
1308 try:
1309 raise RuntimeError()
1310 except RuntimeError:
1311 logging.exception("just testing")
1312 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00001313 self.assertEqual(output.getvalue(),
Christian Heimes180510d2008-03-03 19:15:45 +00001314 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1315 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001316 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001317
Georg Brandl3dbca812008-07-23 16:10:53 +00001318 def test_config5_ok(self):
1319 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +00001320
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001321 def test_config6_ok(self):
1322 self.test_config1_ok(config=self.config6)
1323
Vinay Sajip3f84b072011-03-07 17:49:33 +00001324 def test_config7_ok(self):
1325 with captured_stdout() as output:
1326 self.apply_config(self.config1a)
1327 logger = logging.getLogger("compiler.parser")
1328 # See issue #11424. compiler-hyphenated sorts
1329 # between compiler and compiler.xyz and this
1330 # was preventing compiler.xyz from being included
1331 # in the child loggers of compiler because of an
1332 # overzealous loop termination condition.
1333 hyphenated = logging.getLogger('compiler-hyphenated')
1334 # All will output a message
1335 logger.info(self.next_message())
1336 logger.error(self.next_message())
1337 hyphenated.critical(self.next_message())
1338 self.assert_log_lines([
1339 ('INFO', '1'),
1340 ('ERROR', '2'),
1341 ('CRITICAL', '3'),
1342 ], stream=output)
1343 # Original logger output is empty.
1344 self.assert_log_lines([])
1345 with captured_stdout() as output:
1346 self.apply_config(self.config7)
1347 logger = logging.getLogger("compiler.parser")
1348 self.assertFalse(logger.disabled)
1349 # Both will output a message
1350 logger.info(self.next_message())
1351 logger.error(self.next_message())
1352 logger = logging.getLogger("compiler.lexer")
1353 # Both will output a message
1354 logger.info(self.next_message())
1355 logger.error(self.next_message())
1356 # Will not appear
1357 hyphenated.critical(self.next_message())
1358 self.assert_log_lines([
1359 ('INFO', '4'),
1360 ('ERROR', '5'),
1361 ('INFO', '6'),
1362 ('ERROR', '7'),
1363 ], stream=output)
1364 # Original logger output is empty.
1365 self.assert_log_lines([])
1366
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001367 def test_logger_disabling(self):
1368 self.apply_config(self.disable_test)
Antoine Pitrou04d4d6a2013-09-14 21:16:39 +02001369 logger = logging.getLogger('some_pristine_logger')
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001370 self.assertFalse(logger.disabled)
1371 self.apply_config(self.disable_test)
1372 self.assertTrue(logger.disabled)
1373 self.apply_config(self.disable_test, disable_existing_loggers=False)
1374 self.assertFalse(logger.disabled)
1375
Guido van Rossum2a1d5162003-01-21 21:05:22 +00001376
Victor Stinner45df8202010-04-28 22:31:17 +00001377@unittest.skipUnless(threading, 'Threading required for this test.')
Christian Heimes180510d2008-03-03 19:15:45 +00001378class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001379
Christian Heimes180510d2008-03-03 19:15:45 +00001380 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001381
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001382 if threading:
1383 server_class = TestTCPServer
1384 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001385
Christian Heimes180510d2008-03-03 19:15:45 +00001386 def setUp(self):
1387 """Set up a TCP server to receive log messages, and a SocketHandler
1388 pointing to that server's address and port."""
1389 BaseTest.setUp(self)
Vinay Sajip5421f352013-09-27 18:18:28 +01001390 self.server = server = self.server_class(self.address,
1391 self.handle_socket, 0.01)
Vinay Sajip7367d082011-05-02 13:17:27 +01001392 server.start()
1393 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001394 hcls = logging.handlers.SocketHandler
1395 if isinstance(server.server_address, tuple):
1396 self.sock_hdlr = hcls('localhost', server.port)
1397 else:
1398 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001399 self.log_output = ''
Christian Heimes180510d2008-03-03 19:15:45 +00001400 self.root_logger.removeHandler(self.root_logger.handlers[0])
1401 self.root_logger.addHandler(self.sock_hdlr)
Vinay Sajip7367d082011-05-02 13:17:27 +01001402 self.handled = threading.Semaphore(0)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001403
Christian Heimes180510d2008-03-03 19:15:45 +00001404 def tearDown(self):
1405 """Shutdown the TCP server."""
1406 try:
Vinay Sajip7367d082011-05-02 13:17:27 +01001407 self.server.stop(2.0)
Christian Heimes180510d2008-03-03 19:15:45 +00001408 self.root_logger.removeHandler(self.sock_hdlr)
1409 self.sock_hdlr.close()
Christian Heimes180510d2008-03-03 19:15:45 +00001410 finally:
1411 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001412
Vinay Sajip7367d082011-05-02 13:17:27 +01001413 def handle_socket(self, request):
1414 conn = request.connection
1415 while True:
1416 chunk = conn.recv(4)
1417 if len(chunk) < 4:
1418 break
1419 slen = struct.unpack(">L", chunk)[0]
1420 chunk = conn.recv(slen)
1421 while len(chunk) < slen:
1422 chunk = chunk + conn.recv(slen - len(chunk))
1423 obj = pickle.loads(chunk)
1424 record = logging.makeLogRecord(obj)
1425 self.log_output += record.msg + '\n'
1426 self.handled.release()
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001427
Christian Heimes180510d2008-03-03 19:15:45 +00001428 def test_output(self):
1429 # The log message sent to the SocketHandler is properly received.
1430 logger = logging.getLogger("tcp")
1431 logger.error("spam")
Vinay Sajip7367d082011-05-02 13:17:27 +01001432 self.handled.acquire()
Christian Heimes180510d2008-03-03 19:15:45 +00001433 logger.debug("eggs")
Vinay Sajip7367d082011-05-02 13:17:27 +01001434 self.handled.acquire()
1435 self.assertEqual(self.log_output, "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001436
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001437 def test_noserver(self):
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001438 # Avoid timing-related failures due to SocketHandler's own hard-wired
1439 # one-second timeout on socket.create_connection() (issue #16264).
1440 self.sock_hdlr.retryStart = 2.5
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001441 # Kill the server
Vinay Sajip7367d082011-05-02 13:17:27 +01001442 self.server.stop(2.0)
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001443 # The logging call should try to connect, which should fail
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001444 try:
1445 raise RuntimeError('Deliberate mistake')
1446 except RuntimeError:
1447 self.root_logger.exception('Never sent')
1448 self.root_logger.error('Never sent, either')
1449 now = time.time()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02001450 self.assertGreater(self.sock_hdlr.retryTime, now)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001451 time.sleep(self.sock_hdlr.retryTime - now + 0.001)
1452 self.root_logger.error('Nor this')
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001453
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001454def _get_temp_domain_socket():
1455 fd, fn = tempfile.mkstemp(prefix='test_logging_', suffix='.sock')
1456 os.close(fd)
1457 # just need a name - file can't be present, or we'll get an
1458 # 'address already in use' error.
1459 os.remove(fn)
1460 return fn
Vinay Sajip7367d082011-05-02 13:17:27 +01001461
Victor Stinnerec5a8602014-06-02 14:41:51 +02001462@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip7367d082011-05-02 13:17:27 +01001463@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajip5421f352013-09-27 18:18:28 +01001464class UnixSocketHandlerTest(SocketHandlerTest):
1465
1466 """Test for SocketHandler with unix sockets."""
1467
Victor Stinnerec5a8602014-06-02 14:41:51 +02001468 if threading and hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001469 server_class = TestUnixStreamServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001470
1471 def setUp(self):
1472 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001473 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001474 SocketHandlerTest.setUp(self)
1475
1476 def tearDown(self):
1477 SocketHandlerTest.tearDown(self)
1478 os.remove(self.address)
1479
1480@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajip7367d082011-05-02 13:17:27 +01001481class DatagramHandlerTest(BaseTest):
1482
1483 """Test for DatagramHandler."""
1484
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001485 if threading:
1486 server_class = TestUDPServer
1487 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001488
Vinay Sajip7367d082011-05-02 13:17:27 +01001489 def setUp(self):
1490 """Set up a UDP server to receive log messages, and a DatagramHandler
1491 pointing to that server's address and port."""
1492 BaseTest.setUp(self)
Vinay Sajip5421f352013-09-27 18:18:28 +01001493 self.server = server = self.server_class(self.address,
1494 self.handle_datagram, 0.01)
Vinay Sajip7367d082011-05-02 13:17:27 +01001495 server.start()
1496 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001497 hcls = logging.handlers.DatagramHandler
1498 if isinstance(server.server_address, tuple):
1499 self.sock_hdlr = hcls('localhost', server.port)
1500 else:
1501 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001502 self.log_output = ''
1503 self.root_logger.removeHandler(self.root_logger.handlers[0])
1504 self.root_logger.addHandler(self.sock_hdlr)
1505 self.handled = threading.Event()
1506
1507 def tearDown(self):
1508 """Shutdown the UDP server."""
1509 try:
1510 self.server.stop(2.0)
1511 self.root_logger.removeHandler(self.sock_hdlr)
1512 self.sock_hdlr.close()
1513 finally:
1514 BaseTest.tearDown(self)
1515
1516 def handle_datagram(self, request):
1517 slen = struct.pack('>L', 0) # length of prefix
1518 packet = request.packet[len(slen):]
1519 obj = pickle.loads(packet)
1520 record = logging.makeLogRecord(obj)
1521 self.log_output += record.msg + '\n'
1522 self.handled.set()
1523
1524 def test_output(self):
1525 # The log message sent to the DatagramHandler is properly received.
1526 logger = logging.getLogger("udp")
1527 logger.error("spam")
1528 self.handled.wait()
Vinay Sajip714b8dc2011-05-02 14:43:00 +01001529 self.handled.clear()
1530 logger.error("eggs")
1531 self.handled.wait()
1532 self.assertEqual(self.log_output, "spam\neggs\n")
Vinay Sajip7367d082011-05-02 13:17:27 +01001533
Victor Stinnerec5a8602014-06-02 14:41:51 +02001534@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip7367d082011-05-02 13:17:27 +01001535@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajip5421f352013-09-27 18:18:28 +01001536class UnixDatagramHandlerTest(DatagramHandlerTest):
1537
1538 """Test for DatagramHandler using Unix sockets."""
1539
Victor Stinnerec5a8602014-06-02 14:41:51 +02001540 if threading and hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001541 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001542
1543 def setUp(self):
1544 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001545 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001546 DatagramHandlerTest.setUp(self)
1547
1548 def tearDown(self):
1549 DatagramHandlerTest.tearDown(self)
1550 os.remove(self.address)
1551
1552@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajip7367d082011-05-02 13:17:27 +01001553class SysLogHandlerTest(BaseTest):
1554
1555 """Test for SysLogHandler using UDP."""
1556
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001557 if threading:
1558 server_class = TestUDPServer
1559 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001560
Vinay Sajip7367d082011-05-02 13:17:27 +01001561 def setUp(self):
1562 """Set up a UDP server to receive log messages, and a SysLogHandler
1563 pointing to that server's address and port."""
1564 BaseTest.setUp(self)
Vinay Sajip5421f352013-09-27 18:18:28 +01001565 self.server = server = self.server_class(self.address,
1566 self.handle_datagram, 0.01)
Vinay Sajip7367d082011-05-02 13:17:27 +01001567 server.start()
1568 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001569 hcls = logging.handlers.SysLogHandler
1570 if isinstance(server.server_address, tuple):
1571 self.sl_hdlr = hcls(('localhost', server.port))
1572 else:
1573 self.sl_hdlr = hcls(server.server_address)
Vinay Sajip7367d082011-05-02 13:17:27 +01001574 self.log_output = ''
1575 self.root_logger.removeHandler(self.root_logger.handlers[0])
1576 self.root_logger.addHandler(self.sl_hdlr)
1577 self.handled = threading.Event()
1578
1579 def tearDown(self):
1580 """Shutdown the UDP server."""
1581 try:
1582 self.server.stop(2.0)
1583 self.root_logger.removeHandler(self.sl_hdlr)
1584 self.sl_hdlr.close()
1585 finally:
1586 BaseTest.tearDown(self)
1587
1588 def handle_datagram(self, request):
1589 self.log_output = request.packet
1590 self.handled.set()
1591
1592 def test_output(self):
1593 # The log message sent to the SysLogHandler is properly received.
1594 logger = logging.getLogger("slh")
1595 logger.error("sp\xe4m")
1596 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001597 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001598 self.handled.clear()
1599 self.sl_hdlr.append_nul = False
1600 logger.error("sp\xe4m")
1601 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001602 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m')
Vinay Sajip2353e352011-06-27 15:40:06 +01001603 self.handled.clear()
1604 self.sl_hdlr.ident = "h\xe4m-"
1605 logger.error("sp\xe4m")
1606 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001607 self.assertEqual(self.log_output, b'<11>h\xc3\xa4m-sp\xc3\xa4m')
Vinay Sajip7367d082011-05-02 13:17:27 +01001608
Victor Stinnerec5a8602014-06-02 14:41:51 +02001609@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip7367d082011-05-02 13:17:27 +01001610@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajip5421f352013-09-27 18:18:28 +01001611class UnixSysLogHandlerTest(SysLogHandlerTest):
1612
1613 """Test for SysLogHandler with Unix sockets."""
1614
Victor Stinnerec5a8602014-06-02 14:41:51 +02001615 if threading and hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001616 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001617
1618 def setUp(self):
1619 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001620 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001621 SysLogHandlerTest.setUp(self)
1622
1623 def tearDown(self):
1624 SysLogHandlerTest.tearDown(self)
1625 os.remove(self.address)
1626
Vinay Sajip5421f352013-09-27 18:18:28 +01001627@unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajip7367d082011-05-02 13:17:27 +01001628class HTTPHandlerTest(BaseTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01001629 """Test for HTTPHandler."""
1630
1631 def setUp(self):
1632 """Set up an HTTP server to receive log messages, and a HTTPHandler
1633 pointing to that server's address and port."""
1634 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001635 self.handled = threading.Event()
1636
Vinay Sajip7367d082011-05-02 13:17:27 +01001637 def handle_request(self, request):
Vinay Sajip0372e102011-05-05 12:59:14 +01001638 self.command = request.command
Vinay Sajip7367d082011-05-02 13:17:27 +01001639 self.log_data = urlparse(request.path)
Vinay Sajip0372e102011-05-05 12:59:14 +01001640 if self.command == 'POST':
1641 try:
1642 rlen = int(request.headers['Content-Length'])
1643 self.post_data = request.rfile.read(rlen)
1644 except:
1645 self.post_data = None
Vinay Sajip7367d082011-05-02 13:17:27 +01001646 request.send_response(200)
Vinay Sajip463ac512011-05-10 09:10:08 +01001647 request.end_headers()
Vinay Sajip7367d082011-05-02 13:17:27 +01001648 self.handled.set()
1649
1650 def test_output(self):
Vinay Sajipf2231162011-05-09 22:05:50 +01001651 # The log message sent to the HTTPHandler is properly received.
Vinay Sajip7367d082011-05-02 13:17:27 +01001652 logger = logging.getLogger("http")
Vinay Sajip9ba87612011-05-21 11:32:15 +01001653 root_logger = self.root_logger
1654 root_logger.removeHandler(self.root_logger.handlers[0])
1655 for secure in (False, True):
1656 addr = ('localhost', 0)
1657 if secure:
Vinay Sajip39e35282011-05-21 16:46:41 +01001658 try:
1659 import ssl
Vinay Sajip39e35282011-05-21 16:46:41 +01001660 except ImportError:
1661 sslctx = None
Benjamin Peterson4ffb0752014-11-03 14:29:33 -05001662 else:
1663 here = os.path.dirname(__file__)
1664 localhost_cert = os.path.join(here, "keycert.pem")
1665 sslctx = ssl.SSLContext(ssl.PROTOCOL_SSLv23)
1666 sslctx.load_cert_chain(localhost_cert)
Benjamin Peterson43052a12014-11-23 20:36:44 -06001667
1668 context = ssl.create_default_context(cafile=localhost_cert)
Vinay Sajip0372e102011-05-05 12:59:14 +01001669 else:
Vinay Sajip9ba87612011-05-21 11:32:15 +01001670 sslctx = None
Benjamin Peterson43052a12014-11-23 20:36:44 -06001671 context = None
Vinay Sajip9ba87612011-05-21 11:32:15 +01001672 self.server = server = TestHTTPServer(addr, self.handle_request,
1673 0.01, sslctx=sslctx)
1674 server.start()
1675 server.ready.wait()
1676 host = 'localhost:%d' % server.server_port
Vinay Sajip39e35282011-05-21 16:46:41 +01001677 secure_client = secure and sslctx
1678 self.h_hdlr = logging.handlers.HTTPHandler(host, '/frob',
Benjamin Peterson43052a12014-11-23 20:36:44 -06001679 secure=secure_client,
1680 context=context)
Vinay Sajip9ba87612011-05-21 11:32:15 +01001681 self.log_data = None
1682 root_logger.addHandler(self.h_hdlr)
1683
1684 for method in ('GET', 'POST'):
1685 self.h_hdlr.method = method
1686 self.handled.clear()
1687 msg = "sp\xe4m"
1688 logger.error(msg)
1689 self.handled.wait()
1690 self.assertEqual(self.log_data.path, '/frob')
1691 self.assertEqual(self.command, method)
1692 if method == 'GET':
1693 d = parse_qs(self.log_data.query)
1694 else:
1695 d = parse_qs(self.post_data.decode('utf-8'))
1696 self.assertEqual(d['name'], ['http'])
1697 self.assertEqual(d['funcName'], ['test_output'])
1698 self.assertEqual(d['msg'], [msg])
1699
1700 self.server.stop(2.0)
1701 self.root_logger.removeHandler(self.h_hdlr)
1702 self.h_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001703
Christian Heimes180510d2008-03-03 19:15:45 +00001704class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001705
Christian Heimes180510d2008-03-03 19:15:45 +00001706 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001707
Christian Heimes180510d2008-03-03 19:15:45 +00001708 def setUp(self):
1709 """Create a dict to remember potentially destroyed objects."""
1710 BaseTest.setUp(self)
1711 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001712
Christian Heimes180510d2008-03-03 19:15:45 +00001713 def _watch_for_survival(self, *args):
1714 """Watch the given objects for survival, by creating weakrefs to
1715 them."""
1716 for obj in args:
1717 key = id(obj), repr(obj)
1718 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001719
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001720 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +00001721 """Assert that all objects watched for survival have survived."""
1722 # Trigger cycle breaking.
1723 gc.collect()
1724 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001725 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +00001726 if ref() is None:
1727 dead.append(repr_)
1728 if dead:
1729 self.fail("%d objects should have survived "
1730 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001731
Christian Heimes180510d2008-03-03 19:15:45 +00001732 def test_persistent_loggers(self):
1733 # Logger objects are persistent and retain their configuration, even
1734 # if visible references are destroyed.
1735 self.root_logger.setLevel(logging.INFO)
1736 foo = logging.getLogger("foo")
1737 self._watch_for_survival(foo)
1738 foo.setLevel(logging.DEBUG)
1739 self.root_logger.debug(self.next_message())
1740 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001741 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001742 ('foo', 'DEBUG', '2'),
1743 ])
1744 del foo
1745 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001746 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +00001747 # foo has retained its settings.
1748 bar = logging.getLogger("foo")
1749 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001750 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001751 ('foo', 'DEBUG', '2'),
1752 ('foo', 'DEBUG', '3'),
1753 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001754
Benjamin Petersonf91df042009-02-13 02:50:59 +00001755
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001756class EncodingTest(BaseTest):
1757 def test_encoding_plain_file(self):
1758 # In Python 2.x, a plain file object is treated as having no encoding.
1759 log = logging.getLogger("test")
Vinay Sajip60b4df12010-12-27 11:18:52 +00001760 fd, fn = tempfile.mkstemp(".log", "test_logging-1-")
1761 os.close(fd)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001762 # the non-ascii data we write to the log.
1763 data = "foo\x80"
1764 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001765 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001766 log.addHandler(handler)
1767 try:
1768 # write non-ascii data to the log.
1769 log.warning(data)
1770 finally:
1771 log.removeHandler(handler)
1772 handler.close()
1773 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001774 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001775 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00001776 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001777 finally:
1778 f.close()
1779 finally:
1780 if os.path.isfile(fn):
1781 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001782
Benjamin Petersonf91df042009-02-13 02:50:59 +00001783 def test_encoding_cyrillic_unicode(self):
1784 log = logging.getLogger("test")
1785 #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
1786 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
1787 #Ensure it's written in a Cyrillic encoding
1788 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +00001789 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +00001790 stream = io.BytesIO()
1791 writer = writer_class(stream, 'strict')
1792 handler = logging.StreamHandler(writer)
1793 log.addHandler(handler)
1794 try:
1795 log.warning(message)
1796 finally:
1797 log.removeHandler(handler)
1798 handler.close()
1799 # check we wrote exactly those bytes, ignoring trailing \n etc
1800 s = stream.getvalue()
1801 #Compare against what the data should be when encoded in CP-1251
1802 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
1803
1804
Georg Brandlf9734072008-12-07 15:30:06 +00001805class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +00001806
Georg Brandlf9734072008-12-07 15:30:06 +00001807 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +00001808 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +00001809 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001810 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001811 warnings.filterwarnings("always", category=UserWarning)
1812 stream = io.StringIO()
1813 h = logging.StreamHandler(stream)
1814 logger = logging.getLogger("py.warnings")
1815 logger.addHandler(h)
1816 warnings.warn("I'm warning you...")
1817 logger.removeHandler(h)
1818 s = stream.getvalue()
1819 h.close()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02001820 self.assertGreater(s.find("UserWarning: I'm warning you...\n"), 0)
Georg Brandlf9734072008-12-07 15:30:06 +00001821
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001822 #See if an explicit file uses the original implementation
1823 a_file = io.StringIO()
1824 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
1825 a_file, "Dummy line")
1826 s = a_file.getvalue()
1827 a_file.close()
1828 self.assertEqual(s,
1829 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
1830
1831 def test_warnings_no_handlers(self):
1832 with warnings.catch_warnings():
1833 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001834 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001835
1836 # confirm our assumption: no loggers are set
1837 logger = logging.getLogger("py.warnings")
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001838 self.assertEqual(logger.handlers, [])
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001839
1840 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001841 self.assertEqual(len(logger.handlers), 1)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01001842 self.assertIsInstance(logger.handlers[0], logging.NullHandler)
Georg Brandlf9734072008-12-07 15:30:06 +00001843
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001844
1845def formatFunc(format, datefmt=None):
1846 return logging.Formatter(format, datefmt)
1847
1848def handlerFunc():
1849 return logging.StreamHandler()
1850
1851class CustomHandler(logging.StreamHandler):
1852 pass
1853
1854class ConfigDictTest(BaseTest):
1855
1856 """Reading logging config from a dictionary."""
1857
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001858 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001859
1860 # config0 is a standard configuration.
1861 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001862 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001863 'formatters': {
1864 'form1' : {
1865 'format' : '%(levelname)s ++ %(message)s',
1866 },
1867 },
1868 'handlers' : {
1869 'hand1' : {
1870 'class' : 'logging.StreamHandler',
1871 'formatter' : 'form1',
1872 'level' : 'NOTSET',
1873 'stream' : 'ext://sys.stdout',
1874 },
1875 },
1876 'root' : {
1877 'level' : 'WARNING',
1878 'handlers' : ['hand1'],
1879 },
1880 }
1881
1882 # config1 adds a little to the standard configuration.
1883 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001884 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001885 'formatters': {
1886 'form1' : {
1887 'format' : '%(levelname)s ++ %(message)s',
1888 },
1889 },
1890 'handlers' : {
1891 'hand1' : {
1892 'class' : 'logging.StreamHandler',
1893 'formatter' : 'form1',
1894 'level' : 'NOTSET',
1895 'stream' : 'ext://sys.stdout',
1896 },
1897 },
1898 'loggers' : {
1899 'compiler.parser' : {
1900 'level' : 'DEBUG',
1901 'handlers' : ['hand1'],
1902 },
1903 },
1904 'root' : {
1905 'level' : 'WARNING',
1906 },
1907 }
1908
Vinay Sajip9f9991c2011-03-07 18:02:57 +00001909 # config1a moves the handler to the root. Used with config8a
1910 config1a = {
1911 'version': 1,
1912 'formatters': {
1913 'form1' : {
1914 'format' : '%(levelname)s ++ %(message)s',
1915 },
1916 },
1917 'handlers' : {
1918 'hand1' : {
1919 'class' : 'logging.StreamHandler',
1920 'formatter' : 'form1',
1921 'level' : 'NOTSET',
1922 'stream' : 'ext://sys.stdout',
1923 },
1924 },
1925 'loggers' : {
1926 'compiler.parser' : {
1927 'level' : 'DEBUG',
1928 },
1929 },
1930 'root' : {
1931 'level' : 'WARNING',
1932 'handlers' : ['hand1'],
1933 },
1934 }
1935
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001936 # config2 has a subtle configuration error that should be reported
1937 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001938 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001939 'formatters': {
1940 'form1' : {
1941 'format' : '%(levelname)s ++ %(message)s',
1942 },
1943 },
1944 'handlers' : {
1945 'hand1' : {
1946 'class' : 'logging.StreamHandler',
1947 'formatter' : 'form1',
1948 'level' : 'NOTSET',
1949 'stream' : 'ext://sys.stdbout',
1950 },
1951 },
1952 'loggers' : {
1953 'compiler.parser' : {
1954 'level' : 'DEBUG',
1955 'handlers' : ['hand1'],
1956 },
1957 },
1958 'root' : {
1959 'level' : 'WARNING',
1960 },
1961 }
1962
1963 #As config1 but with a misspelt level on a handler
1964 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001965 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001966 'formatters': {
1967 'form1' : {
1968 'format' : '%(levelname)s ++ %(message)s',
1969 },
1970 },
1971 'handlers' : {
1972 'hand1' : {
1973 'class' : 'logging.StreamHandler',
1974 'formatter' : 'form1',
1975 'level' : 'NTOSET',
1976 'stream' : 'ext://sys.stdout',
1977 },
1978 },
1979 'loggers' : {
1980 'compiler.parser' : {
1981 'level' : 'DEBUG',
1982 'handlers' : ['hand1'],
1983 },
1984 },
1985 'root' : {
1986 'level' : 'WARNING',
1987 },
1988 }
1989
1990
1991 #As config1 but with a misspelt level on a logger
1992 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00001993 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001994 'formatters': {
1995 'form1' : {
1996 'format' : '%(levelname)s ++ %(message)s',
1997 },
1998 },
1999 'handlers' : {
2000 'hand1' : {
2001 'class' : 'logging.StreamHandler',
2002 'formatter' : 'form1',
2003 'level' : 'NOTSET',
2004 'stream' : 'ext://sys.stdout',
2005 },
2006 },
2007 'loggers' : {
2008 'compiler.parser' : {
2009 'level' : 'DEBUG',
2010 'handlers' : ['hand1'],
2011 },
2012 },
2013 'root' : {
2014 'level' : 'WRANING',
2015 },
2016 }
2017
2018 # config3 has a less subtle configuration error
2019 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002020 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002021 'formatters': {
2022 'form1' : {
2023 'format' : '%(levelname)s ++ %(message)s',
2024 },
2025 },
2026 'handlers' : {
2027 'hand1' : {
2028 'class' : 'logging.StreamHandler',
2029 'formatter' : 'misspelled_name',
2030 'level' : 'NOTSET',
2031 'stream' : 'ext://sys.stdout',
2032 },
2033 },
2034 'loggers' : {
2035 'compiler.parser' : {
2036 'level' : 'DEBUG',
2037 'handlers' : ['hand1'],
2038 },
2039 },
2040 'root' : {
2041 'level' : 'WARNING',
2042 },
2043 }
2044
2045 # config4 specifies a custom formatter class to be loaded
2046 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002047 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002048 'formatters': {
2049 'form1' : {
2050 '()' : __name__ + '.ExceptionFormatter',
2051 'format' : '%(levelname)s:%(name)s:%(message)s',
2052 },
2053 },
2054 'handlers' : {
2055 'hand1' : {
2056 'class' : 'logging.StreamHandler',
2057 'formatter' : 'form1',
2058 'level' : 'NOTSET',
2059 'stream' : 'ext://sys.stdout',
2060 },
2061 },
2062 'root' : {
2063 'level' : 'NOTSET',
2064 'handlers' : ['hand1'],
2065 },
2066 }
2067
2068 # As config4 but using an actual callable rather than a string
2069 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002070 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002071 'formatters': {
2072 'form1' : {
2073 '()' : ExceptionFormatter,
2074 'format' : '%(levelname)s:%(name)s:%(message)s',
2075 },
2076 'form2' : {
2077 '()' : __name__ + '.formatFunc',
2078 'format' : '%(levelname)s:%(name)s:%(message)s',
2079 },
2080 'form3' : {
2081 '()' : formatFunc,
2082 'format' : '%(levelname)s:%(name)s:%(message)s',
2083 },
2084 },
2085 'handlers' : {
2086 'hand1' : {
2087 'class' : 'logging.StreamHandler',
2088 'formatter' : 'form1',
2089 'level' : 'NOTSET',
2090 'stream' : 'ext://sys.stdout',
2091 },
2092 'hand2' : {
2093 '()' : handlerFunc,
2094 },
2095 },
2096 'root' : {
2097 'level' : 'NOTSET',
2098 'handlers' : ['hand1'],
2099 },
2100 }
2101
2102 # config5 specifies a custom handler class to be loaded
2103 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002104 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002105 'formatters': {
2106 'form1' : {
2107 'format' : '%(levelname)s ++ %(message)s',
2108 },
2109 },
2110 'handlers' : {
2111 'hand1' : {
2112 'class' : __name__ + '.CustomHandler',
2113 'formatter' : 'form1',
2114 'level' : 'NOTSET',
2115 'stream' : 'ext://sys.stdout',
2116 },
2117 },
2118 'loggers' : {
2119 'compiler.parser' : {
2120 'level' : 'DEBUG',
2121 'handlers' : ['hand1'],
2122 },
2123 },
2124 'root' : {
2125 'level' : 'WARNING',
2126 },
2127 }
2128
2129 # config6 specifies a custom handler class to be loaded
2130 # but has bad arguments
2131 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002132 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002133 'formatters': {
2134 'form1' : {
2135 'format' : '%(levelname)s ++ %(message)s',
2136 },
2137 },
2138 'handlers' : {
2139 'hand1' : {
2140 'class' : __name__ + '.CustomHandler',
2141 'formatter' : 'form1',
2142 'level' : 'NOTSET',
2143 'stream' : 'ext://sys.stdout',
2144 '9' : 'invalid parameter name',
2145 },
2146 },
2147 'loggers' : {
2148 'compiler.parser' : {
2149 'level' : 'DEBUG',
2150 'handlers' : ['hand1'],
2151 },
2152 },
2153 'root' : {
2154 'level' : 'WARNING',
2155 },
2156 }
2157
2158 #config 7 does not define compiler.parser but defines compiler.lexer
2159 #so compiler.parser should be disabled after applying it
2160 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002161 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002162 'formatters': {
2163 'form1' : {
2164 'format' : '%(levelname)s ++ %(message)s',
2165 },
2166 },
2167 'handlers' : {
2168 'hand1' : {
2169 'class' : 'logging.StreamHandler',
2170 'formatter' : 'form1',
2171 'level' : 'NOTSET',
2172 'stream' : 'ext://sys.stdout',
2173 },
2174 },
2175 'loggers' : {
2176 'compiler.lexer' : {
2177 'level' : 'DEBUG',
2178 'handlers' : ['hand1'],
2179 },
2180 },
2181 'root' : {
2182 'level' : 'WARNING',
2183 },
2184 }
2185
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002186 # config8 defines both compiler and compiler.lexer
2187 # so compiler.parser should not be disabled (since
2188 # compiler is defined)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002189 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002190 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002191 'disable_existing_loggers' : False,
2192 'formatters': {
2193 'form1' : {
2194 'format' : '%(levelname)s ++ %(message)s',
2195 },
2196 },
2197 'handlers' : {
2198 'hand1' : {
2199 'class' : 'logging.StreamHandler',
2200 'formatter' : 'form1',
2201 'level' : 'NOTSET',
2202 'stream' : 'ext://sys.stdout',
2203 },
2204 },
2205 'loggers' : {
2206 'compiler' : {
2207 'level' : 'DEBUG',
2208 'handlers' : ['hand1'],
2209 },
2210 'compiler.lexer' : {
2211 },
2212 },
2213 'root' : {
2214 'level' : 'WARNING',
2215 },
2216 }
2217
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002218 # config8a disables existing loggers
2219 config8a = {
2220 'version': 1,
2221 'disable_existing_loggers' : True,
2222 'formatters': {
2223 'form1' : {
2224 'format' : '%(levelname)s ++ %(message)s',
2225 },
2226 },
2227 'handlers' : {
2228 'hand1' : {
2229 'class' : 'logging.StreamHandler',
2230 'formatter' : 'form1',
2231 'level' : 'NOTSET',
2232 'stream' : 'ext://sys.stdout',
2233 },
2234 },
2235 'loggers' : {
2236 'compiler' : {
2237 'level' : 'DEBUG',
2238 'handlers' : ['hand1'],
2239 },
2240 'compiler.lexer' : {
2241 },
2242 },
2243 'root' : {
2244 'level' : 'WARNING',
2245 },
2246 }
2247
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002248 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002249 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002250 'formatters': {
2251 'form1' : {
2252 'format' : '%(levelname)s ++ %(message)s',
2253 },
2254 },
2255 'handlers' : {
2256 'hand1' : {
2257 'class' : 'logging.StreamHandler',
2258 'formatter' : 'form1',
2259 'level' : 'WARNING',
2260 'stream' : 'ext://sys.stdout',
2261 },
2262 },
2263 'loggers' : {
2264 'compiler.parser' : {
2265 'level' : 'WARNING',
2266 'handlers' : ['hand1'],
2267 },
2268 },
2269 'root' : {
2270 'level' : 'NOTSET',
2271 },
2272 }
2273
2274 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002275 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002276 'incremental' : True,
2277 'handlers' : {
2278 'hand1' : {
2279 'level' : 'WARNING',
2280 },
2281 },
2282 'loggers' : {
2283 'compiler.parser' : {
2284 'level' : 'INFO',
2285 },
2286 },
2287 }
2288
2289 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002290 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002291 'incremental' : True,
2292 'handlers' : {
2293 'hand1' : {
2294 'level' : 'INFO',
2295 },
2296 },
2297 'loggers' : {
2298 'compiler.parser' : {
2299 'level' : 'INFO',
2300 },
2301 },
2302 }
2303
2304 #As config1 but with a filter added
2305 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002306 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002307 'formatters': {
2308 'form1' : {
2309 'format' : '%(levelname)s ++ %(message)s',
2310 },
2311 },
2312 'filters' : {
2313 'filt1' : {
2314 'name' : 'compiler.parser',
2315 },
2316 },
2317 'handlers' : {
2318 'hand1' : {
2319 'class' : 'logging.StreamHandler',
2320 'formatter' : 'form1',
2321 'level' : 'NOTSET',
2322 'stream' : 'ext://sys.stdout',
2323 'filters' : ['filt1'],
2324 },
2325 },
2326 'loggers' : {
2327 'compiler.parser' : {
2328 'level' : 'DEBUG',
2329 'filters' : ['filt1'],
2330 },
2331 },
2332 'root' : {
2333 'level' : 'WARNING',
2334 'handlers' : ['hand1'],
2335 },
2336 }
2337
2338 #As config1 but using cfg:// references
2339 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002340 'version': 1,
2341 'true_formatters': {
2342 'form1' : {
2343 'format' : '%(levelname)s ++ %(message)s',
2344 },
2345 },
2346 'handler_configs': {
2347 'hand1' : {
2348 'class' : 'logging.StreamHandler',
2349 'formatter' : 'form1',
2350 'level' : 'NOTSET',
2351 'stream' : 'ext://sys.stdout',
2352 },
2353 },
2354 'formatters' : 'cfg://true_formatters',
2355 'handlers' : {
2356 'hand1' : 'cfg://handler_configs[hand1]',
2357 },
2358 'loggers' : {
2359 'compiler.parser' : {
2360 'level' : 'DEBUG',
2361 'handlers' : ['hand1'],
2362 },
2363 },
2364 'root' : {
2365 'level' : 'WARNING',
2366 },
2367 }
2368
2369 #As config11 but missing the version key
2370 config12 = {
2371 'true_formatters': {
2372 'form1' : {
2373 'format' : '%(levelname)s ++ %(message)s',
2374 },
2375 },
2376 'handler_configs': {
2377 'hand1' : {
2378 'class' : 'logging.StreamHandler',
2379 'formatter' : 'form1',
2380 'level' : 'NOTSET',
2381 'stream' : 'ext://sys.stdout',
2382 },
2383 },
2384 'formatters' : 'cfg://true_formatters',
2385 'handlers' : {
2386 'hand1' : 'cfg://handler_configs[hand1]',
2387 },
2388 'loggers' : {
2389 'compiler.parser' : {
2390 'level' : 'DEBUG',
2391 'handlers' : ['hand1'],
2392 },
2393 },
2394 'root' : {
2395 'level' : 'WARNING',
2396 },
2397 }
2398
2399 #As config11 but using an unsupported version
2400 config13 = {
2401 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002402 'true_formatters': {
2403 'form1' : {
2404 'format' : '%(levelname)s ++ %(message)s',
2405 },
2406 },
2407 'handler_configs': {
2408 'hand1' : {
2409 'class' : 'logging.StreamHandler',
2410 'formatter' : 'form1',
2411 'level' : 'NOTSET',
2412 'stream' : 'ext://sys.stdout',
2413 },
2414 },
2415 'formatters' : 'cfg://true_formatters',
2416 'handlers' : {
2417 'hand1' : 'cfg://handler_configs[hand1]',
2418 },
2419 'loggers' : {
2420 'compiler.parser' : {
2421 'level' : 'DEBUG',
2422 'handlers' : ['hand1'],
2423 },
2424 },
2425 'root' : {
2426 'level' : 'WARNING',
2427 },
2428 }
2429
Vinay Sajip8d270232012-11-15 14:20:18 +00002430 # As config0, but with properties
2431 config14 = {
2432 'version': 1,
2433 'formatters': {
2434 'form1' : {
2435 'format' : '%(levelname)s ++ %(message)s',
2436 },
2437 },
2438 'handlers' : {
2439 'hand1' : {
2440 'class' : 'logging.StreamHandler',
2441 'formatter' : 'form1',
2442 'level' : 'NOTSET',
2443 'stream' : 'ext://sys.stdout',
2444 '.': {
2445 'foo': 'bar',
2446 'terminator': '!\n',
2447 }
2448 },
2449 },
2450 'root' : {
2451 'level' : 'WARNING',
2452 'handlers' : ['hand1'],
2453 },
2454 }
2455
Vinay Sajip3f885b52013-03-22 15:19:54 +00002456 out_of_order = {
2457 "version": 1,
2458 "formatters": {
2459 "mySimpleFormatter": {
Vinay Sajip28421c62013-03-29 17:56:54 +00002460 "format": "%(asctime)s (%(name)s) %(levelname)s: %(message)s",
2461 "style": "$"
Vinay Sajip3f885b52013-03-22 15:19:54 +00002462 }
2463 },
2464 "handlers": {
2465 "fileGlobal": {
2466 "class": "logging.StreamHandler",
2467 "level": "DEBUG",
2468 "formatter": "mySimpleFormatter"
2469 },
2470 "bufferGlobal": {
2471 "class": "logging.handlers.MemoryHandler",
2472 "capacity": 5,
2473 "formatter": "mySimpleFormatter",
2474 "target": "fileGlobal",
2475 "level": "DEBUG"
2476 }
2477 },
2478 "loggers": {
2479 "mymodule": {
2480 "level": "DEBUG",
2481 "handlers": ["bufferGlobal"],
2482 "propagate": "true"
2483 }
2484 }
2485 }
2486
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002487 def apply_config(self, conf):
2488 logging.config.dictConfig(conf)
2489
2490 def test_config0_ok(self):
2491 # A simple config which overrides the default settings.
2492 with captured_stdout() as output:
2493 self.apply_config(self.config0)
2494 logger = logging.getLogger()
2495 # Won't output anything
2496 logger.info(self.next_message())
2497 # Outputs a message
2498 logger.error(self.next_message())
2499 self.assert_log_lines([
2500 ('ERROR', '2'),
2501 ], stream=output)
2502 # Original logger output is empty.
2503 self.assert_log_lines([])
2504
2505 def test_config1_ok(self, config=config1):
2506 # A config defining a sub-parser as well.
2507 with captured_stdout() as output:
2508 self.apply_config(config)
2509 logger = logging.getLogger("compiler.parser")
2510 # Both will output a message
2511 logger.info(self.next_message())
2512 logger.error(self.next_message())
2513 self.assert_log_lines([
2514 ('INFO', '1'),
2515 ('ERROR', '2'),
2516 ], stream=output)
2517 # Original logger output is empty.
2518 self.assert_log_lines([])
2519
2520 def test_config2_failure(self):
2521 # A simple config which overrides the default settings.
2522 self.assertRaises(Exception, self.apply_config, self.config2)
2523
2524 def test_config2a_failure(self):
2525 # A simple config which overrides the default settings.
2526 self.assertRaises(Exception, self.apply_config, self.config2a)
2527
2528 def test_config2b_failure(self):
2529 # A simple config which overrides the default settings.
2530 self.assertRaises(Exception, self.apply_config, self.config2b)
2531
2532 def test_config3_failure(self):
2533 # A simple config which overrides the default settings.
2534 self.assertRaises(Exception, self.apply_config, self.config3)
2535
2536 def test_config4_ok(self):
2537 # A config specifying a custom formatter class.
2538 with captured_stdout() as output:
2539 self.apply_config(self.config4)
2540 #logger = logging.getLogger()
2541 try:
2542 raise RuntimeError()
2543 except RuntimeError:
2544 logging.exception("just testing")
2545 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002546 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002547 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2548 # Original logger output is empty
2549 self.assert_log_lines([])
2550
2551 def test_config4a_ok(self):
2552 # A config specifying a custom formatter class.
2553 with captured_stdout() as output:
2554 self.apply_config(self.config4a)
2555 #logger = logging.getLogger()
2556 try:
2557 raise RuntimeError()
2558 except RuntimeError:
2559 logging.exception("just testing")
2560 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002561 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002562 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2563 # Original logger output is empty
2564 self.assert_log_lines([])
2565
2566 def test_config5_ok(self):
2567 self.test_config1_ok(config=self.config5)
2568
2569 def test_config6_failure(self):
2570 self.assertRaises(Exception, self.apply_config, self.config6)
2571
2572 def test_config7_ok(self):
2573 with captured_stdout() as output:
2574 self.apply_config(self.config1)
2575 logger = logging.getLogger("compiler.parser")
2576 # Both will output a message
2577 logger.info(self.next_message())
2578 logger.error(self.next_message())
2579 self.assert_log_lines([
2580 ('INFO', '1'),
2581 ('ERROR', '2'),
2582 ], stream=output)
2583 # Original logger output is empty.
2584 self.assert_log_lines([])
2585 with captured_stdout() as output:
2586 self.apply_config(self.config7)
2587 logger = logging.getLogger("compiler.parser")
2588 self.assertTrue(logger.disabled)
2589 logger = logging.getLogger("compiler.lexer")
2590 # Both will output a message
2591 logger.info(self.next_message())
2592 logger.error(self.next_message())
2593 self.assert_log_lines([
2594 ('INFO', '3'),
2595 ('ERROR', '4'),
2596 ], stream=output)
2597 # Original logger output is empty.
2598 self.assert_log_lines([])
2599
2600 #Same as test_config_7_ok but don't disable old loggers.
2601 def test_config_8_ok(self):
2602 with captured_stdout() as output:
2603 self.apply_config(self.config1)
2604 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002605 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002606 logger.info(self.next_message())
2607 logger.error(self.next_message())
2608 self.assert_log_lines([
2609 ('INFO', '1'),
2610 ('ERROR', '2'),
2611 ], stream=output)
2612 # Original logger output is empty.
2613 self.assert_log_lines([])
2614 with captured_stdout() as output:
2615 self.apply_config(self.config8)
2616 logger = logging.getLogger("compiler.parser")
2617 self.assertFalse(logger.disabled)
2618 # Both will output a message
2619 logger.info(self.next_message())
2620 logger.error(self.next_message())
2621 logger = logging.getLogger("compiler.lexer")
2622 # Both will output a message
2623 logger.info(self.next_message())
2624 logger.error(self.next_message())
2625 self.assert_log_lines([
2626 ('INFO', '3'),
2627 ('ERROR', '4'),
2628 ('INFO', '5'),
2629 ('ERROR', '6'),
2630 ], stream=output)
2631 # Original logger output is empty.
2632 self.assert_log_lines([])
2633
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002634 def test_config_8a_ok(self):
2635 with captured_stdout() as output:
2636 self.apply_config(self.config1a)
2637 logger = logging.getLogger("compiler.parser")
2638 # See issue #11424. compiler-hyphenated sorts
2639 # between compiler and compiler.xyz and this
2640 # was preventing compiler.xyz from being included
2641 # in the child loggers of compiler because of an
2642 # overzealous loop termination condition.
2643 hyphenated = logging.getLogger('compiler-hyphenated')
2644 # All will output a message
2645 logger.info(self.next_message())
2646 logger.error(self.next_message())
2647 hyphenated.critical(self.next_message())
2648 self.assert_log_lines([
2649 ('INFO', '1'),
2650 ('ERROR', '2'),
2651 ('CRITICAL', '3'),
2652 ], stream=output)
2653 # Original logger output is empty.
2654 self.assert_log_lines([])
2655 with captured_stdout() as output:
2656 self.apply_config(self.config8a)
2657 logger = logging.getLogger("compiler.parser")
2658 self.assertFalse(logger.disabled)
2659 # Both will output a message
2660 logger.info(self.next_message())
2661 logger.error(self.next_message())
2662 logger = logging.getLogger("compiler.lexer")
2663 # Both will output a message
2664 logger.info(self.next_message())
2665 logger.error(self.next_message())
2666 # Will not appear
2667 hyphenated.critical(self.next_message())
2668 self.assert_log_lines([
2669 ('INFO', '4'),
2670 ('ERROR', '5'),
2671 ('INFO', '6'),
2672 ('ERROR', '7'),
2673 ], stream=output)
2674 # Original logger output is empty.
2675 self.assert_log_lines([])
2676
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002677 def test_config_9_ok(self):
2678 with captured_stdout() as output:
2679 self.apply_config(self.config9)
2680 logger = logging.getLogger("compiler.parser")
2681 #Nothing will be output since both handler and logger are set to WARNING
2682 logger.info(self.next_message())
2683 self.assert_log_lines([], stream=output)
2684 self.apply_config(self.config9a)
2685 #Nothing will be output since both handler is still set to WARNING
2686 logger.info(self.next_message())
2687 self.assert_log_lines([], stream=output)
2688 self.apply_config(self.config9b)
2689 #Message should now be output
2690 logger.info(self.next_message())
2691 self.assert_log_lines([
2692 ('INFO', '3'),
2693 ], stream=output)
2694
2695 def test_config_10_ok(self):
2696 with captured_stdout() as output:
2697 self.apply_config(self.config10)
2698 logger = logging.getLogger("compiler.parser")
2699 logger.warning(self.next_message())
2700 logger = logging.getLogger('compiler')
2701 #Not output, because filtered
2702 logger.warning(self.next_message())
2703 logger = logging.getLogger('compiler.lexer')
2704 #Not output, because filtered
2705 logger.warning(self.next_message())
2706 logger = logging.getLogger("compiler.parser.codegen")
2707 #Output, as not filtered
2708 logger.error(self.next_message())
2709 self.assert_log_lines([
2710 ('WARNING', '1'),
2711 ('ERROR', '4'),
2712 ], stream=output)
2713
2714 def test_config11_ok(self):
2715 self.test_config1_ok(self.config11)
2716
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002717 def test_config12_failure(self):
2718 self.assertRaises(Exception, self.apply_config, self.config12)
2719
2720 def test_config13_failure(self):
2721 self.assertRaises(Exception, self.apply_config, self.config13)
2722
Vinay Sajip8d270232012-11-15 14:20:18 +00002723 def test_config14_ok(self):
2724 with captured_stdout() as output:
2725 self.apply_config(self.config14)
2726 h = logging._handlers['hand1']
2727 self.assertEqual(h.foo, 'bar')
2728 self.assertEqual(h.terminator, '!\n')
2729 logging.warning('Exclamation')
2730 self.assertTrue(output.getvalue().endswith('Exclamation!\n'))
2731
Victor Stinner45df8202010-04-28 22:31:17 +00002732 @unittest.skipUnless(threading, 'listen() needs threading to work')
Vinay Sajip4ded5512012-10-02 15:56:16 +01002733 def setup_via_listener(self, text, verify=None):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002734 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00002735 # Ask for a randomly assigned port (by using port 0)
Vinay Sajip4ded5512012-10-02 15:56:16 +01002736 t = logging.config.listen(0, verify)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002737 t.start()
2738 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00002739 # Now get the port allocated
2740 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002741 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002742 try:
2743 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
2744 sock.settimeout(2.0)
2745 sock.connect(('localhost', port))
2746
2747 slen = struct.pack('>L', len(text))
2748 s = slen + text
2749 sentsofar = 0
2750 left = len(s)
2751 while left > 0:
2752 sent = sock.send(s[sentsofar:])
2753 sentsofar += sent
2754 left -= sent
2755 sock.close()
2756 finally:
2757 t.ready.wait(2.0)
2758 logging.config.stopListening()
2759 t.join(2.0)
2760
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002761 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002762 def test_listen_config_10_ok(self):
2763 with captured_stdout() as output:
2764 self.setup_via_listener(json.dumps(self.config10))
2765 logger = logging.getLogger("compiler.parser")
2766 logger.warning(self.next_message())
2767 logger = logging.getLogger('compiler')
2768 #Not output, because filtered
2769 logger.warning(self.next_message())
2770 logger = logging.getLogger('compiler.lexer')
2771 #Not output, because filtered
2772 logger.warning(self.next_message())
2773 logger = logging.getLogger("compiler.parser.codegen")
2774 #Output, as not filtered
2775 logger.error(self.next_message())
2776 self.assert_log_lines([
2777 ('WARNING', '1'),
2778 ('ERROR', '4'),
2779 ], stream=output)
2780
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01002781 @unittest.skipUnless(threading, 'Threading required for this test.')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002782 def test_listen_config_1_ok(self):
2783 with captured_stdout() as output:
2784 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
2785 logger = logging.getLogger("compiler.parser")
2786 # Both will output a message
2787 logger.info(self.next_message())
2788 logger.error(self.next_message())
2789 self.assert_log_lines([
2790 ('INFO', '1'),
2791 ('ERROR', '2'),
2792 ], stream=output)
2793 # Original logger output is empty.
2794 self.assert_log_lines([])
2795
Vinay Sajip4ded5512012-10-02 15:56:16 +01002796 @unittest.skipUnless(threading, 'Threading required for this test.')
2797 def test_listen_verify(self):
2798
2799 def verify_fail(stuff):
2800 return None
2801
2802 def verify_reverse(stuff):
2803 return stuff[::-1]
2804
2805 logger = logging.getLogger("compiler.parser")
2806 to_send = textwrap.dedent(ConfigFileTest.config1)
2807 # First, specify a verification function that will fail.
2808 # We expect to see no output, since our configuration
2809 # never took effect.
2810 with captured_stdout() as output:
2811 self.setup_via_listener(to_send, verify_fail)
2812 # Both will output a message
2813 logger.info(self.next_message())
2814 logger.error(self.next_message())
2815 self.assert_log_lines([], stream=output)
2816 # Original logger output has the stuff we logged.
2817 self.assert_log_lines([
2818 ('INFO', '1'),
2819 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002820 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002821
2822 # Now, perform no verification. Our configuration
2823 # should take effect.
2824
2825 with captured_stdout() as output:
2826 self.setup_via_listener(to_send) # no verify callable specified
2827 logger = logging.getLogger("compiler.parser")
2828 # Both will output a message
2829 logger.info(self.next_message())
2830 logger.error(self.next_message())
2831 self.assert_log_lines([
2832 ('INFO', '3'),
2833 ('ERROR', '4'),
2834 ], stream=output)
2835 # Original logger output still has the stuff we logged before.
2836 self.assert_log_lines([
2837 ('INFO', '1'),
2838 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002839 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002840
2841 # Now, perform verification which transforms the bytes.
2842
2843 with captured_stdout() as output:
2844 self.setup_via_listener(to_send[::-1], verify_reverse)
2845 logger = logging.getLogger("compiler.parser")
2846 # Both will output a message
2847 logger.info(self.next_message())
2848 logger.error(self.next_message())
2849 self.assert_log_lines([
2850 ('INFO', '5'),
2851 ('ERROR', '6'),
2852 ], stream=output)
2853 # Original logger output still has the stuff we logged before.
2854 self.assert_log_lines([
2855 ('INFO', '1'),
2856 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002857 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01002858
Vinay Sajip3f885b52013-03-22 15:19:54 +00002859 def test_out_of_order(self):
2860 self.apply_config(self.out_of_order)
2861 handler = logging.getLogger('mymodule').handlers[0]
2862 self.assertIsInstance(handler.target, logging.Handler)
Vinay Sajip28421c62013-03-29 17:56:54 +00002863 self.assertIsInstance(handler.formatter._style,
2864 logging.StringTemplateStyle)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002865
Vinay Sajip373baef2011-04-26 20:05:24 +01002866 def test_baseconfig(self):
2867 d = {
2868 'atuple': (1, 2, 3),
2869 'alist': ['a', 'b', 'c'],
2870 'adict': {'d': 'e', 'f': 3 },
2871 'nest1': ('g', ('h', 'i'), 'j'),
2872 'nest2': ['k', ['l', 'm'], 'n'],
2873 'nest3': ['o', 'cfg://alist', 'p'],
2874 }
2875 bc = logging.config.BaseConfigurator(d)
2876 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
2877 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
2878 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
2879 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
2880 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
2881 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
2882 v = bc.convert('cfg://nest3')
2883 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
2884 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
2885 self.assertRaises(ValueError, bc.convert, 'cfg://!')
2886 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002887
2888class ManagerTest(BaseTest):
2889 def test_manager_loggerclass(self):
2890 logged = []
2891
2892 class MyLogger(logging.Logger):
2893 def _log(self, level, msg, args, exc_info=None, extra=None):
2894 logged.append(msg)
2895
2896 man = logging.Manager(None)
2897 self.assertRaises(TypeError, man.setLoggerClass, int)
2898 man.setLoggerClass(MyLogger)
2899 logger = man.getLogger('test')
2900 logger.warning('should appear in logged')
2901 logging.warning('should not appear in logged')
2902
2903 self.assertEqual(logged, ['should appear in logged'])
2904
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002905 def test_set_log_record_factory(self):
2906 man = logging.Manager(None)
2907 expected = object()
2908 man.setLogRecordFactory(expected)
2909 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002910
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002911class ChildLoggerTest(BaseTest):
2912 def test_child_loggers(self):
2913 r = logging.getLogger()
2914 l1 = logging.getLogger('abc')
2915 l2 = logging.getLogger('def.ghi')
2916 c1 = r.getChild('xyz')
2917 c2 = r.getChild('uvw.xyz')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02002918 self.assertIs(c1, logging.getLogger('xyz'))
2919 self.assertIs(c2, logging.getLogger('uvw.xyz'))
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002920 c1 = l1.getChild('def')
2921 c2 = c1.getChild('ghi')
2922 c3 = l1.getChild('def.ghi')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02002923 self.assertIs(c1, logging.getLogger('abc.def'))
2924 self.assertIs(c2, logging.getLogger('abc.def.ghi'))
2925 self.assertIs(c2, c3)
Benjamin Peterson22005fc2010-04-11 16:25:06 +00002926
2927
Vinay Sajip6fac8172010-10-19 20:44:14 +00002928class DerivedLogRecord(logging.LogRecord):
2929 pass
2930
Vinay Sajip61561522010-12-03 11:50:38 +00002931class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00002932
2933 def setUp(self):
2934 class CheckingFilter(logging.Filter):
2935 def __init__(self, cls):
2936 self.cls = cls
2937
2938 def filter(self, record):
2939 t = type(record)
2940 if t is not self.cls:
2941 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
2942 self.cls)
2943 raise TypeError(msg)
2944 return True
2945
2946 BaseTest.setUp(self)
2947 self.filter = CheckingFilter(DerivedLogRecord)
2948 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00002949 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00002950
2951 def tearDown(self):
2952 self.root_logger.removeFilter(self.filter)
2953 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00002954 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002955
2956 def test_logrecord_class(self):
2957 self.assertRaises(TypeError, self.root_logger.warning,
2958 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00002959 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00002960 self.root_logger.error(self.next_message())
2961 self.assert_log_lines([
2962 ('root', 'ERROR', '2'),
2963 ])
2964
2965
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002966class QueueHandlerTest(BaseTest):
2967 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002968 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Vinay Sajip8552d1f2010-09-14 09:34:09 +00002969
2970 def setUp(self):
2971 BaseTest.setUp(self)
2972 self.queue = queue.Queue(-1)
2973 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
2974 self.que_logger = logging.getLogger('que')
2975 self.que_logger.propagate = False
2976 self.que_logger.setLevel(logging.WARNING)
2977 self.que_logger.addHandler(self.que_hdlr)
2978
2979 def tearDown(self):
2980 self.que_hdlr.close()
2981 BaseTest.tearDown(self)
2982
2983 def test_queue_handler(self):
2984 self.que_logger.debug(self.next_message())
2985 self.assertRaises(queue.Empty, self.queue.get_nowait)
2986 self.que_logger.info(self.next_message())
2987 self.assertRaises(queue.Empty, self.queue.get_nowait)
2988 msg = self.next_message()
2989 self.que_logger.warning(msg)
2990 data = self.queue.get_nowait()
2991 self.assertTrue(isinstance(data, logging.LogRecord))
2992 self.assertEqual(data.name, self.que_logger.name)
2993 self.assertEqual((data.msg, data.args), (msg, None))
2994
Victor Stinnercafa2ef2011-05-02 16:11:28 +02002995 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
2996 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01002997 def test_queue_listener(self):
2998 handler = TestHandler(Matcher())
2999 listener = logging.handlers.QueueListener(self.queue, handler)
3000 listener.start()
3001 try:
3002 self.que_logger.warning(self.next_message())
3003 self.que_logger.error(self.next_message())
3004 self.que_logger.critical(self.next_message())
3005 finally:
3006 listener.stop()
3007 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
3008 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
3009 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
3010
Vinay Sajip37eb3382011-04-26 20:26:41 +01003011ZERO = datetime.timedelta(0)
3012
3013class UTC(datetime.tzinfo):
3014 def utcoffset(self, dt):
3015 return ZERO
3016
3017 dst = utcoffset
3018
3019 def tzname(self, dt):
3020 return 'UTC'
3021
3022utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01003023
Vinay Sajipa39c5712010-10-25 13:57:39 +00003024class FormatterTest(unittest.TestCase):
3025 def setUp(self):
3026 self.common = {
3027 'name': 'formatter.test',
3028 'level': logging.DEBUG,
3029 'pathname': os.path.join('path', 'to', 'dummy.ext'),
3030 'lineno': 42,
3031 'exc_info': None,
3032 'func': None,
3033 'msg': 'Message with %d %s',
3034 'args': (2, 'placeholders'),
3035 }
3036 self.variants = {
3037 }
3038
3039 def get_record(self, name=None):
3040 result = dict(self.common)
3041 if name is not None:
3042 result.update(self.variants[name])
3043 return logging.makeLogRecord(result)
3044
3045 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003046 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003047 r = self.get_record()
3048 f = logging.Formatter('${%(message)s}')
3049 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
3050 f = logging.Formatter('%(random)s')
3051 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003052 self.assertFalse(f.usesTime())
3053 f = logging.Formatter('%(asctime)s')
3054 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003055 f = logging.Formatter('%(asctime)-15s')
3056 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003057 f = logging.Formatter('asctime')
3058 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003059
3060 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003061 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003062 r = self.get_record()
3063 f = logging.Formatter('$%{message}%$', style='{')
3064 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3065 f = logging.Formatter('{random}', style='{')
3066 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003067 self.assertFalse(f.usesTime())
3068 f = logging.Formatter('{asctime}', style='{')
3069 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003070 f = logging.Formatter('{asctime!s:15}', style='{')
3071 self.assertTrue(f.usesTime())
3072 f = logging.Formatter('{asctime:15}', style='{')
3073 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003074 f = logging.Formatter('asctime', style='{')
3075 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003076
3077 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003078 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003079 r = self.get_record()
3080 f = logging.Formatter('$message', style='$')
3081 self.assertEqual(f.format(r), 'Message with 2 placeholders')
3082 f = logging.Formatter('$$%${message}%$$', style='$')
3083 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3084 f = logging.Formatter('${random}', style='$')
3085 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003086 self.assertFalse(f.usesTime())
3087 f = logging.Formatter('${asctime}', style='$')
3088 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003089 f = logging.Formatter('${asctime', style='$')
3090 self.assertFalse(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003091 f = logging.Formatter('$asctime', style='$')
3092 self.assertTrue(f.usesTime())
3093 f = logging.Formatter('asctime', style='$')
3094 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003095
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003096 def test_invalid_style(self):
3097 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
3098
Vinay Sajip86a96ce2011-04-27 08:30:30 +01003099 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003100 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01003101 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
3102 # We use None to indicate we want the local timezone
3103 # We're essentially converting a UTC time to local time
3104 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003105 r.msecs = 123
3106 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01003107 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003108 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
3109 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01003110 f.format(r)
3111 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
3112
3113class TestBufferingFormatter(logging.BufferingFormatter):
3114 def formatHeader(self, records):
3115 return '[(%d)' % len(records)
3116
3117 def formatFooter(self, records):
3118 return '(%d)]' % len(records)
3119
3120class BufferingFormatterTest(unittest.TestCase):
3121 def setUp(self):
3122 self.records = [
3123 logging.makeLogRecord({'msg': 'one'}),
3124 logging.makeLogRecord({'msg': 'two'}),
3125 ]
3126
3127 def test_default(self):
3128 f = logging.BufferingFormatter()
3129 self.assertEqual('', f.format([]))
3130 self.assertEqual('onetwo', f.format(self.records))
3131
3132 def test_custom(self):
3133 f = TestBufferingFormatter()
3134 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
3135 lf = logging.Formatter('<%(message)s>')
3136 f = TestBufferingFormatter(lf)
3137 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003138
3139class ExceptionTest(BaseTest):
3140 def test_formatting(self):
3141 r = self.root_logger
3142 h = RecordingHandler()
3143 r.addHandler(h)
3144 try:
3145 raise RuntimeError('deliberate mistake')
3146 except:
3147 logging.exception('failed', stack_info=True)
3148 r.removeHandler(h)
3149 h.close()
3150 r = h.records[0]
3151 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
3152 'call last):\n'))
3153 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
3154 'deliberate mistake'))
3155 self.assertTrue(r.stack_info.startswith('Stack (most recent '
3156 'call last):\n'))
3157 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
3158 'stack_info=True)'))
3159
3160
Vinay Sajip5a27d402010-12-10 11:42:57 +00003161class LastResortTest(BaseTest):
3162 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003163 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00003164 root = self.root_logger
3165 root.removeHandler(self.root_hdlr)
3166 old_stderr = sys.stderr
3167 old_lastresort = logging.lastResort
3168 old_raise_exceptions = logging.raiseExceptions
3169 try:
3170 sys.stderr = sio = io.StringIO()
Vinay Sajip8188f582011-07-25 19:58:13 +01003171 root.debug('This should not appear')
3172 self.assertEqual(sio.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00003173 root.warning('This is your final chance!')
3174 self.assertEqual(sio.getvalue(), 'This is your final chance!\n')
3175 #No handlers and no last resort, so 'No handlers' message
3176 logging.lastResort = None
3177 sys.stderr = sio = io.StringIO()
3178 root.warning('This is your final chance!')
3179 self.assertEqual(sio.getvalue(), 'No handlers could be found for logger "root"\n')
3180 # 'No handlers' message only printed once
3181 sys.stderr = sio = io.StringIO()
3182 root.warning('This is your final chance!')
3183 self.assertEqual(sio.getvalue(), '')
3184 root.manager.emittedNoHandlerWarning = False
3185 #If raiseExceptions is False, no message is printed
3186 logging.raiseExceptions = False
3187 sys.stderr = sio = io.StringIO()
3188 root.warning('This is your final chance!')
3189 self.assertEqual(sio.getvalue(), '')
3190 finally:
3191 sys.stderr = old_stderr
3192 root.addHandler(self.root_hdlr)
3193 logging.lastResort = old_lastresort
3194 logging.raiseExceptions = old_raise_exceptions
3195
3196
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003197class FakeHandler:
3198
3199 def __init__(self, identifier, called):
3200 for method in ('acquire', 'flush', 'close', 'release'):
3201 setattr(self, method, self.record_call(identifier, method, called))
3202
3203 def record_call(self, identifier, method_name, called):
3204 def inner():
3205 called.append('{} - {}'.format(identifier, method_name))
3206 return inner
3207
3208
3209class RecordingHandler(logging.NullHandler):
3210
3211 def __init__(self, *args, **kwargs):
3212 super(RecordingHandler, self).__init__(*args, **kwargs)
3213 self.records = []
3214
3215 def handle(self, record):
3216 """Keep track of all the emitted records."""
3217 self.records.append(record)
3218
3219
3220class ShutdownTest(BaseTest):
3221
Vinay Sajip5e66b162011-04-20 15:41:14 +01003222 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003223
3224 def setUp(self):
3225 super(ShutdownTest, self).setUp()
3226 self.called = []
3227
3228 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003229 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003230
3231 def raise_error(self, error):
3232 def inner():
3233 raise error()
3234 return inner
3235
3236 def test_no_failure(self):
3237 # create some fake handlers
3238 handler0 = FakeHandler(0, self.called)
3239 handler1 = FakeHandler(1, self.called)
3240 handler2 = FakeHandler(2, self.called)
3241
3242 # create live weakref to those handlers
3243 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
3244
3245 logging.shutdown(handlerList=list(handlers))
3246
3247 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
3248 '1 - acquire', '1 - flush', '1 - close', '1 - release',
3249 '0 - acquire', '0 - flush', '0 - close', '0 - release']
3250 self.assertEqual(expected, self.called)
3251
3252 def _test_with_failure_in_method(self, method, error):
3253 handler = FakeHandler(0, self.called)
3254 setattr(handler, method, self.raise_error(error))
3255 handlers = [logging.weakref.ref(handler)]
3256
3257 logging.shutdown(handlerList=list(handlers))
3258
3259 self.assertEqual('0 - release', self.called[-1])
3260
3261 def test_with_ioerror_in_acquire(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02003262 self._test_with_failure_in_method('acquire', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003263
3264 def test_with_ioerror_in_flush(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02003265 self._test_with_failure_in_method('flush', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003266
3267 def test_with_ioerror_in_close(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02003268 self._test_with_failure_in_method('close', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003269
3270 def test_with_valueerror_in_acquire(self):
3271 self._test_with_failure_in_method('acquire', ValueError)
3272
3273 def test_with_valueerror_in_flush(self):
3274 self._test_with_failure_in_method('flush', ValueError)
3275
3276 def test_with_valueerror_in_close(self):
3277 self._test_with_failure_in_method('close', ValueError)
3278
3279 def test_with_other_error_in_acquire_without_raise(self):
3280 logging.raiseExceptions = False
3281 self._test_with_failure_in_method('acquire', IndexError)
3282
3283 def test_with_other_error_in_flush_without_raise(self):
3284 logging.raiseExceptions = False
3285 self._test_with_failure_in_method('flush', IndexError)
3286
3287 def test_with_other_error_in_close_without_raise(self):
3288 logging.raiseExceptions = False
3289 self._test_with_failure_in_method('close', IndexError)
3290
3291 def test_with_other_error_in_acquire_with_raise(self):
3292 logging.raiseExceptions = True
3293 self.assertRaises(IndexError, self._test_with_failure_in_method,
3294 'acquire', IndexError)
3295
3296 def test_with_other_error_in_flush_with_raise(self):
3297 logging.raiseExceptions = True
3298 self.assertRaises(IndexError, self._test_with_failure_in_method,
3299 'flush', IndexError)
3300
3301 def test_with_other_error_in_close_with_raise(self):
3302 logging.raiseExceptions = True
3303 self.assertRaises(IndexError, self._test_with_failure_in_method,
3304 'close', IndexError)
3305
3306
3307class ModuleLevelMiscTest(BaseTest):
3308
Vinay Sajip5e66b162011-04-20 15:41:14 +01003309 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003310
3311 def test_disable(self):
3312 old_disable = logging.root.manager.disable
3313 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003314 self.assertEqual(old_disable, 0)
3315 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003316
3317 logging.disable(83)
3318 self.assertEqual(logging.root.manager.disable, 83)
3319
3320 def _test_log(self, method, level=None):
3321 called = []
3322 patch(self, logging, 'basicConfig',
Vinay Sajip00bdbe12011-04-22 00:17:46 +01003323 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003324
3325 recording = RecordingHandler()
3326 logging.root.addHandler(recording)
3327
3328 log_method = getattr(logging, method)
3329 if level is not None:
3330 log_method(level, "test me: %r", recording)
3331 else:
3332 log_method("test me: %r", recording)
3333
3334 self.assertEqual(len(recording.records), 1)
3335 record = recording.records[0]
3336 self.assertEqual(record.getMessage(), "test me: %r" % recording)
3337
3338 expected_level = level if level is not None else getattr(logging, method.upper())
3339 self.assertEqual(record.levelno, expected_level)
3340
3341 # basicConfig was not called!
3342 self.assertEqual(called, [])
3343
3344 def test_log(self):
3345 self._test_log('log', logging.ERROR)
3346
3347 def test_debug(self):
3348 self._test_log('debug')
3349
3350 def test_info(self):
3351 self._test_log('info')
3352
3353 def test_warning(self):
3354 self._test_log('warning')
3355
3356 def test_error(self):
3357 self._test_log('error')
3358
3359 def test_critical(self):
3360 self._test_log('critical')
3361
3362 def test_set_logger_class(self):
3363 self.assertRaises(TypeError, logging.setLoggerClass, object)
3364
3365 class MyLogger(logging.Logger):
3366 pass
3367
3368 logging.setLoggerClass(MyLogger)
3369 self.assertEqual(logging.getLoggerClass(), MyLogger)
3370
3371 logging.setLoggerClass(logging.Logger)
3372 self.assertEqual(logging.getLoggerClass(), logging.Logger)
3373
Antoine Pitrou712cb732013-12-21 15:51:54 +01003374 def test_logging_at_shutdown(self):
3375 # Issue #20037
3376 code = """if 1:
3377 import logging
3378
3379 class A:
3380 def __del__(self):
3381 try:
3382 raise ValueError("some error")
3383 except Exception:
3384 logging.exception("exception in __del__")
3385
3386 a = A()"""
3387 rc, out, err = assert_python_ok("-c", code)
3388 err = err.decode()
3389 self.assertIn("exception in __del__", err)
3390 self.assertIn("ValueError: some error", err)
3391
3392
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003393class LogRecordTest(BaseTest):
3394 def test_str_rep(self):
3395 r = logging.makeLogRecord({})
3396 s = str(r)
3397 self.assertTrue(s.startswith('<LogRecord: '))
3398 self.assertTrue(s.endswith('>'))
3399
3400 def test_dict_arg(self):
3401 h = RecordingHandler()
3402 r = logging.getLogger()
3403 r.addHandler(h)
3404 d = {'less' : 'more' }
3405 logging.warning('less is %(less)s', d)
3406 self.assertIs(h.records[0].args, d)
3407 self.assertEqual(h.records[0].message, 'less is more')
3408 r.removeHandler(h)
3409 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003410
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003411 def test_multiprocessing(self):
3412 r = logging.makeLogRecord({})
3413 self.assertEqual(r.processName, 'MainProcess')
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003414 try:
3415 import multiprocessing as mp
3416 r = logging.makeLogRecord({})
3417 self.assertEqual(r.processName, mp.current_process().name)
3418 except ImportError:
3419 pass
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003420
3421 def test_optional(self):
3422 r = logging.makeLogRecord({})
3423 NOT_NONE = self.assertIsNotNone
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003424 if threading:
3425 NOT_NONE(r.thread)
3426 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003427 NOT_NONE(r.process)
3428 NOT_NONE(r.processName)
3429 log_threads = logging.logThreads
3430 log_processes = logging.logProcesses
3431 log_multiprocessing = logging.logMultiprocessing
3432 try:
3433 logging.logThreads = False
3434 logging.logProcesses = False
3435 logging.logMultiprocessing = False
3436 r = logging.makeLogRecord({})
3437 NONE = self.assertIsNone
3438 NONE(r.thread)
3439 NONE(r.threadName)
3440 NONE(r.process)
3441 NONE(r.processName)
3442 finally:
3443 logging.logThreads = log_threads
3444 logging.logProcesses = log_processes
3445 logging.logMultiprocessing = log_multiprocessing
3446
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003447class BasicConfigTest(unittest.TestCase):
3448
Vinay Sajip95bf5042011-04-20 11:50:56 +01003449 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003450
3451 def setUp(self):
3452 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01003453 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01003454 self.saved_handlers = logging._handlers.copy()
3455 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003456 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003457 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003458 logging.root.handlers = []
3459
3460 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01003461 for h in logging.root.handlers[:]:
3462 logging.root.removeHandler(h)
3463 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003464 super(BasicConfigTest, self).tearDown()
3465
Vinay Sajip3def7e02011-04-20 10:58:06 +01003466 def cleanup(self):
3467 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01003468 logging._handlers.clear()
3469 logging._handlers.update(self.saved_handlers)
3470 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003471 logging.root.level = self.original_logging_level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003472
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003473 def test_no_kwargs(self):
3474 logging.basicConfig()
3475
3476 # handler defaults to a StreamHandler to sys.stderr
3477 self.assertEqual(len(logging.root.handlers), 1)
3478 handler = logging.root.handlers[0]
3479 self.assertIsInstance(handler, logging.StreamHandler)
3480 self.assertEqual(handler.stream, sys.stderr)
3481
3482 formatter = handler.formatter
3483 # format defaults to logging.BASIC_FORMAT
3484 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
3485 # datefmt defaults to None
3486 self.assertIsNone(formatter.datefmt)
3487 # style defaults to %
3488 self.assertIsInstance(formatter._style, logging.PercentStyle)
3489
Florent Xiclunae41f0de2011-11-11 19:39:25 +01003490 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01003491 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003492
Vinay Sajip1fd12022014-01-13 21:59:56 +00003493 def test_strformatstyle(self):
3494 with captured_stdout() as output:
3495 logging.basicConfig(stream=sys.stdout, style="{")
3496 logging.error("Log an error")
3497 sys.stdout.seek(0)
3498 self.assertEqual(output.getvalue().strip(),
3499 "ERROR:root:Log an error")
3500
3501 def test_stringtemplatestyle(self):
3502 with captured_stdout() as output:
3503 logging.basicConfig(stream=sys.stdout, style="$")
3504 logging.error("Log an error")
3505 sys.stdout.seek(0)
3506 self.assertEqual(output.getvalue().strip(),
3507 "ERROR:root:Log an error")
3508
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003509 def test_filename(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00003510
3511 def cleanup(h1, h2, fn):
3512 h1.close()
3513 h2.close()
3514 os.remove(fn)
3515
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003516 logging.basicConfig(filename='test.log')
3517
3518 self.assertEqual(len(logging.root.handlers), 1)
3519 handler = logging.root.handlers[0]
3520 self.assertIsInstance(handler, logging.FileHandler)
3521
3522 expected = logging.FileHandler('test.log', 'a')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003523 self.assertEqual(handler.stream.mode, expected.stream.mode)
3524 self.assertEqual(handler.stream.name, expected.stream.name)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00003525 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003526
3527 def test_filemode(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00003528
3529 def cleanup(h1, h2, fn):
3530 h1.close()
3531 h2.close()
3532 os.remove(fn)
3533
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003534 logging.basicConfig(filename='test.log', filemode='wb')
3535
3536 handler = logging.root.handlers[0]
3537 expected = logging.FileHandler('test.log', 'wb')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003538 self.assertEqual(handler.stream.mode, expected.stream.mode)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00003539 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003540
3541 def test_stream(self):
3542 stream = io.StringIO()
3543 self.addCleanup(stream.close)
3544 logging.basicConfig(stream=stream)
3545
3546 self.assertEqual(len(logging.root.handlers), 1)
3547 handler = logging.root.handlers[0]
3548 self.assertIsInstance(handler, logging.StreamHandler)
3549 self.assertEqual(handler.stream, stream)
3550
3551 def test_format(self):
3552 logging.basicConfig(format='foo')
3553
3554 formatter = logging.root.handlers[0].formatter
3555 self.assertEqual(formatter._style._fmt, 'foo')
3556
3557 def test_datefmt(self):
3558 logging.basicConfig(datefmt='bar')
3559
3560 formatter = logging.root.handlers[0].formatter
3561 self.assertEqual(formatter.datefmt, 'bar')
3562
3563 def test_style(self):
3564 logging.basicConfig(style='$')
3565
3566 formatter = logging.root.handlers[0].formatter
3567 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
3568
3569 def test_level(self):
3570 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003571 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003572
3573 logging.basicConfig(level=57)
3574 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003575 # Test that second call has no effect
3576 logging.basicConfig(level=58)
3577 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003578
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003579 def test_incompatible(self):
3580 assertRaises = self.assertRaises
3581 handlers = [logging.StreamHandler()]
3582 stream = sys.stderr
3583 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3584 stream=stream)
3585 assertRaises(ValueError, logging.basicConfig, filename='test.log',
3586 handlers=handlers)
3587 assertRaises(ValueError, logging.basicConfig, stream=stream,
3588 handlers=handlers)
Vinay Sajipd55436a2015-03-18 08:47:58 +00003589 # Issue 23207: test for invalid kwargs
3590 assertRaises(ValueError, logging.basicConfig, loglevel=logging.INFO)
3591 # Should pop both filename and filemode even if filename is None
3592 logging.basicConfig(filename=None, filemode='a')
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003593
3594 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003595 handlers = [
3596 logging.StreamHandler(),
3597 logging.StreamHandler(sys.stdout),
3598 logging.StreamHandler(),
3599 ]
3600 f = logging.Formatter()
3601 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003602 logging.basicConfig(handlers=handlers)
3603 self.assertIs(handlers[0], logging.root.handlers[0])
3604 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003605 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003606 self.assertIsNotNone(handlers[0].formatter)
3607 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003608 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01003609 self.assertIs(handlers[0].formatter, handlers[1].formatter)
3610
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003611 def _test_log(self, method, level=None):
3612 # logging.root has no handlers so basicConfig should be called
3613 called = []
3614
3615 old_basic_config = logging.basicConfig
3616 def my_basic_config(*a, **kw):
3617 old_basic_config()
3618 old_level = logging.root.level
3619 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003620 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003621 called.append((a, kw))
3622
3623 patch(self, logging, 'basicConfig', my_basic_config)
3624
3625 log_method = getattr(logging, method)
3626 if level is not None:
3627 log_method(level, "test me")
3628 else:
3629 log_method("test me")
3630
3631 # basicConfig was called with no arguments
3632 self.assertEqual(called, [((), {})])
3633
3634 def test_log(self):
3635 self._test_log('log', logging.WARNING)
3636
3637 def test_debug(self):
3638 self._test_log('debug')
3639
3640 def test_info(self):
3641 self._test_log('info')
3642
3643 def test_warning(self):
3644 self._test_log('warning')
3645
3646 def test_error(self):
3647 self._test_log('error')
3648
3649 def test_critical(self):
3650 self._test_log('critical')
3651
3652
3653class LoggerAdapterTest(unittest.TestCase):
3654
3655 def setUp(self):
3656 super(LoggerAdapterTest, self).setUp()
3657 old_handler_list = logging._handlerList[:]
3658
3659 self.recording = RecordingHandler()
3660 self.logger = logging.root
3661 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003662 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003663 self.addCleanup(self.recording.close)
3664
3665 def cleanup():
3666 logging._handlerList[:] = old_handler_list
3667
3668 self.addCleanup(cleanup)
3669 self.addCleanup(logging.shutdown)
3670 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
3671
3672 def test_exception(self):
3673 msg = 'testing exception: %r'
3674 exc = None
3675 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003676 1 / 0
3677 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003678 exc = e
3679 self.adapter.exception(msg, self.recording)
3680
3681 self.assertEqual(len(self.recording.records), 1)
3682 record = self.recording.records[0]
3683 self.assertEqual(record.levelno, logging.ERROR)
3684 self.assertEqual(record.msg, msg)
3685 self.assertEqual(record.args, (self.recording,))
3686 self.assertEqual(record.exc_info,
3687 (exc.__class__, exc, exc.__traceback__))
3688
3689 def test_critical(self):
3690 msg = 'critical test! %r'
3691 self.adapter.critical(msg, self.recording)
3692
3693 self.assertEqual(len(self.recording.records), 1)
3694 record = self.recording.records[0]
3695 self.assertEqual(record.levelno, logging.CRITICAL)
3696 self.assertEqual(record.msg, msg)
3697 self.assertEqual(record.args, (self.recording,))
3698
3699 def test_is_enabled_for(self):
3700 old_disable = self.adapter.logger.manager.disable
3701 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003702 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
3703 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003704 self.assertFalse(self.adapter.isEnabledFor(32))
3705
3706 def test_has_handlers(self):
3707 self.assertTrue(self.adapter.hasHandlers())
3708
3709 for handler in self.logger.handlers:
3710 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003711
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003712 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003713 self.assertFalse(self.adapter.hasHandlers())
3714
3715
3716class LoggerTest(BaseTest):
3717
3718 def setUp(self):
3719 super(LoggerTest, self).setUp()
3720 self.recording = RecordingHandler()
3721 self.logger = logging.Logger(name='blah')
3722 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003723 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003724 self.addCleanup(self.recording.close)
3725 self.addCleanup(logging.shutdown)
3726
3727 def test_set_invalid_level(self):
3728 self.assertRaises(TypeError, self.logger.setLevel, object())
3729
3730 def test_exception(self):
3731 msg = 'testing exception: %r'
3732 exc = None
3733 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003734 1 / 0
3735 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003736 exc = e
3737 self.logger.exception(msg, self.recording)
3738
3739 self.assertEqual(len(self.recording.records), 1)
3740 record = self.recording.records[0]
3741 self.assertEqual(record.levelno, logging.ERROR)
3742 self.assertEqual(record.msg, msg)
3743 self.assertEqual(record.args, (self.recording,))
3744 self.assertEqual(record.exc_info,
3745 (exc.__class__, exc, exc.__traceback__))
3746
3747 def test_log_invalid_level_with_raise(self):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03003748 with swap_attr(logging, 'raiseExceptions', True):
3749 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003750
3751 def test_log_invalid_level_no_raise(self):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03003752 with swap_attr(logging, 'raiseExceptions', False):
3753 self.logger.log('10', 'test message') # no exception happens
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003754
3755 def test_find_caller_with_stack_info(self):
3756 called = []
3757 patch(self, logging.traceback, 'print_stack',
3758 lambda f, file: called.append(file.getvalue()))
3759
3760 self.logger.findCaller(stack_info=True)
3761
3762 self.assertEqual(len(called), 1)
3763 self.assertEqual('Stack (most recent call last):\n', called[0])
3764
3765 def test_make_record_with_extra_overwrite(self):
3766 name = 'my record'
3767 level = 13
3768 fn = lno = msg = args = exc_info = func = sinfo = None
3769 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
3770 exc_info, func, sinfo)
3771
3772 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
3773 extra = {key: 'some value'}
3774 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
3775 fn, lno, msg, args, exc_info,
3776 extra=extra, sinfo=sinfo)
3777
3778 def test_make_record_with_extra_no_overwrite(self):
3779 name = 'my record'
3780 level = 13
3781 fn = lno = msg = args = exc_info = func = sinfo = None
3782 extra = {'valid_key': 'some value'}
3783 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
3784 exc_info, extra=extra, sinfo=sinfo)
3785 self.assertIn('valid_key', result.__dict__)
3786
3787 def test_has_handlers(self):
3788 self.assertTrue(self.logger.hasHandlers())
3789
3790 for handler in self.logger.handlers:
3791 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003792 self.assertFalse(self.logger.hasHandlers())
3793
3794 def test_has_handlers_no_propagate(self):
3795 child_logger = logging.getLogger('blah.child')
3796 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003797 self.assertFalse(child_logger.hasHandlers())
3798
3799 def test_is_enabled_for(self):
3800 old_disable = self.logger.manager.disable
3801 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003802 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003803 self.assertFalse(self.logger.isEnabledFor(22))
3804
Florent Xicluna5252f9f2011-11-07 19:43:05 +01003805 def test_root_logger_aliases(self):
3806 root = logging.getLogger()
3807 self.assertIs(root, logging.root)
3808 self.assertIs(root, logging.getLogger(None))
3809 self.assertIs(root, logging.getLogger(''))
3810 self.assertIs(root, logging.getLogger('foo').root)
3811 self.assertIs(root, logging.getLogger('foo.bar').root)
3812 self.assertIs(root, logging.getLogger('foo').parent)
3813
3814 self.assertIsNot(root, logging.getLogger('\0'))
3815 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
3816
3817 def test_invalid_names(self):
3818 self.assertRaises(TypeError, logging.getLogger, any)
3819 self.assertRaises(TypeError, logging.getLogger, b'foo')
3820
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003821
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003822class BaseFileTest(BaseTest):
3823 "Base class for handler tests that write log files"
3824
3825 def setUp(self):
3826 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003827 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
3828 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003829 self.rmfiles = []
3830
3831 def tearDown(self):
3832 for fn in self.rmfiles:
3833 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00003834 if os.path.exists(self.fn):
3835 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00003836 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003837
3838 def assertLogFile(self, filename):
3839 "Assert a log file is there and register it for deletion"
3840 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01003841 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003842 self.rmfiles.append(filename)
3843
3844
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003845class FileHandlerTest(BaseFileTest):
3846 def test_delay(self):
3847 os.unlink(self.fn)
3848 fh = logging.FileHandler(self.fn, delay=True)
3849 self.assertIsNone(fh.stream)
3850 self.assertFalse(os.path.exists(self.fn))
3851 fh.handle(logging.makeLogRecord({}))
3852 self.assertIsNotNone(fh.stream)
3853 self.assertTrue(os.path.exists(self.fn))
3854 fh.close()
3855
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003856class RotatingFileHandlerTest(BaseFileTest):
3857 def next_rec(self):
3858 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
3859 self.next_message(), None, None, None)
3860
3861 def test_should_not_rollover(self):
3862 # If maxbytes is zero rollover never occurs
3863 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
3864 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00003865 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003866
3867 def test_should_rollover(self):
3868 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
3869 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00003870 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003871
3872 def test_file_created(self):
3873 # checks that the file is created and assumes it was created
3874 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003875 rh = logging.handlers.RotatingFileHandler(self.fn)
3876 rh.emit(self.next_rec())
3877 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00003878 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003879
3880 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00003881 def namer(name):
3882 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003883 rh = logging.handlers.RotatingFileHandler(
3884 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003885 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003886 rh.emit(self.next_rec())
3887 self.assertLogFile(self.fn)
3888 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003889 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003890 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00003891 self.assertLogFile(namer(self.fn + ".2"))
3892 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
3893 rh.close()
3894
Eric V. Smith851cad72012-03-11 22:46:04 -07003895 @requires_zlib
Vinay Sajip23b94d02012-01-04 12:02:26 +00003896 def test_rotator(self):
3897 def namer(name):
3898 return name + ".gz"
3899
3900 def rotator(source, dest):
3901 with open(source, "rb") as sf:
3902 data = sf.read()
3903 compressed = zlib.compress(data, 9)
3904 with open(dest, "wb") as df:
3905 df.write(compressed)
3906 os.remove(source)
3907
3908 rh = logging.handlers.RotatingFileHandler(
3909 self.fn, backupCount=2, maxBytes=1)
3910 rh.rotator = rotator
3911 rh.namer = namer
3912 m1 = self.next_rec()
3913 rh.emit(m1)
3914 self.assertLogFile(self.fn)
3915 m2 = self.next_rec()
3916 rh.emit(m2)
3917 fn = namer(self.fn + ".1")
3918 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003919 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00003920 with open(fn, "rb") as f:
3921 compressed = f.read()
3922 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003923 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003924 rh.emit(self.next_rec())
3925 fn = namer(self.fn + ".2")
3926 self.assertLogFile(fn)
3927 with open(fn, "rb") as f:
3928 compressed = f.read()
3929 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003930 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003931 rh.emit(self.next_rec())
3932 fn = namer(self.fn + ".2")
3933 with open(fn, "rb") as f:
3934 compressed = f.read()
3935 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00003936 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00003937 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00003938 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003939
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003940class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01003941 # other test methods added below
3942 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01003943 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
3944 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00003945 fmt = logging.Formatter('%(asctime)s %(message)s')
3946 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003947 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003948 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01003949 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00003950 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00003951 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00003952 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01003953 fh.close()
3954 # At this point, we should have a recent rotated file which we
3955 # can test for the existence of. However, in practice, on some
3956 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01003957 # in time to go to look for the log file. So, we go back a fair
3958 # bit, and stop as soon as we see a rotated file. In theory this
3959 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01003960 found = False
3961 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01003962 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01003963 for secs in range(GO_BACK):
3964 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01003965 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
3966 found = os.path.exists(fn)
3967 if found:
3968 self.rmfiles.append(fn)
3969 break
Vinay Sajip672c5812011-05-13 07:09:40 +01003970 msg = 'No rotated files found, went back %d seconds' % GO_BACK
3971 if not found:
3972 #print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01003973 dn, fn = os.path.split(self.fn)
3974 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02003975 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
3976 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00003977 for f in files:
3978 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00003979 path = os.path.join(dn, f)
3980 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00003981 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01003982 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00003983
Vinay Sajip0372e102011-05-05 12:59:14 +01003984 def test_invalid(self):
3985 assertRaises = self.assertRaises
3986 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003987 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003988 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003989 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003990 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01003991 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01003992
Vinay Sajipa7130792013-04-12 17:04:23 +01003993 def test_compute_rollover_daily_attime(self):
3994 currentTime = 0
3995 atTime = datetime.time(12, 0, 0)
3996 rh = logging.handlers.TimedRotatingFileHandler(
3997 self.fn, when='MIDNIGHT', interval=1, backupCount=0, utc=True,
3998 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01003999 try:
4000 actual = rh.computeRollover(currentTime)
4001 self.assertEqual(actual, currentTime + 12 * 60 * 60)
Vinay Sajipa7130792013-04-12 17:04:23 +01004002
Vinay Sajipd86ac962013-04-14 12:20:46 +01004003 actual = rh.computeRollover(currentTime + 13 * 60 * 60)
4004 self.assertEqual(actual, currentTime + 36 * 60 * 60)
4005 finally:
4006 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01004007
Vinay Sajip10e8c492013-05-18 10:19:54 -07004008 #@unittest.skipIf(True, 'Temporarily skipped while failures investigated.')
Vinay Sajipa7130792013-04-12 17:04:23 +01004009 def test_compute_rollover_weekly_attime(self):
Vinay Sajipd86ac962013-04-14 12:20:46 +01004010 currentTime = int(time.time())
4011 today = currentTime - currentTime % 86400
4012
Vinay Sajipa7130792013-04-12 17:04:23 +01004013 atTime = datetime.time(12, 0, 0)
4014
Vinay Sajip10e8c492013-05-18 10:19:54 -07004015 wday = time.gmtime(today).tm_wday
Vinay Sajipa7130792013-04-12 17:04:23 +01004016 for day in range(7):
4017 rh = logging.handlers.TimedRotatingFileHandler(
4018 self.fn, when='W%d' % day, interval=1, backupCount=0, utc=True,
4019 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01004020 try:
4021 if wday > day:
4022 # The rollover day has already passed this week, so we
4023 # go over into next week
4024 expected = (7 - wday + day)
4025 else:
4026 expected = (day - wday)
4027 # At this point expected is in days from now, convert to seconds
4028 expected *= 24 * 60 * 60
4029 # Add in the rollover time
4030 expected += 12 * 60 * 60
4031 # Add in adjustment for today
4032 expected += today
Vinay Sajip66940a12013-04-15 11:59:35 +01004033 actual = rh.computeRollover(today)
4034 if actual != expected:
4035 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01004036 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01004037 self.assertEqual(actual, expected)
4038 if day == wday:
4039 # goes into following week
4040 expected += 7 * 24 * 60 * 60
Vinay Sajip8b4c7192013-04-14 12:25:25 +01004041 actual = rh.computeRollover(today + 13 * 60 * 60)
Vinay Sajip66940a12013-04-15 11:59:35 +01004042 if actual != expected:
4043 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01004044 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01004045 self.assertEqual(actual, expected)
4046 finally:
4047 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01004048
4049
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004050def secs(**kw):
4051 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
4052
4053for when, exp in (('S', 1),
4054 ('M', 60),
4055 ('H', 60 * 60),
4056 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00004057 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004058 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00004059 ('W0', secs(days=4, hours=24)),
4060 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004061 def test_compute_rollover(self, when=when, exp=exp):
4062 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00004063 self.fn, when=when, interval=1, backupCount=0, utc=True)
4064 currentTime = 0.0
4065 actual = rh.computeRollover(currentTime)
4066 if exp != actual:
4067 # Failures occur on some systems for MIDNIGHT and W0.
4068 # Print detailed calculation for MIDNIGHT so we can try to see
4069 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00004070 if when == 'MIDNIGHT':
4071 try:
4072 if rh.utc:
4073 t = time.gmtime(currentTime)
4074 else:
4075 t = time.localtime(currentTime)
4076 currentHour = t[3]
4077 currentMinute = t[4]
4078 currentSecond = t[5]
4079 # r is the number of seconds left between now and midnight
4080 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
4081 currentMinute) * 60 +
4082 currentSecond)
4083 result = currentTime + r
4084 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
4085 print('currentHour: %s' % currentHour, file=sys.stderr)
4086 print('currentMinute: %s' % currentMinute, file=sys.stderr)
4087 print('currentSecond: %s' % currentSecond, file=sys.stderr)
4088 print('r: %s' % r, file=sys.stderr)
4089 print('result: %s' % result, file=sys.stderr)
4090 except Exception:
4091 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
4092 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00004093 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004094 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
4095
Vinay Sajip60ccd822011-05-09 17:32:09 +01004096
Vinay Sajip223349c2015-10-01 20:37:54 +01004097@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil/pywintypes required for this test.')
Vinay Sajip60ccd822011-05-09 17:32:09 +01004098class NTEventLogHandlerTest(BaseTest):
4099 def test_basic(self):
4100 logtype = 'Application'
4101 elh = win32evtlog.OpenEventLog(None, logtype)
4102 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
Vinay Sajip223349c2015-10-01 20:37:54 +01004103
4104 try:
4105 h = logging.handlers.NTEventLogHandler('test_logging')
4106 except pywintypes.error as e:
Zachary Ware22226c52015-10-06 15:22:13 -05004107 if e.winerror == 5: # access denied
Vinay Sajip223349c2015-10-01 20:37:54 +01004108 raise unittest.SkipTest('Insufficient privileges to run test')
Zachary Ware106ddf02015-10-06 15:28:43 -05004109 raise
Vinay Sajip223349c2015-10-01 20:37:54 +01004110
Vinay Sajip60ccd822011-05-09 17:32:09 +01004111 r = logging.makeLogRecord({'msg': 'Test Log Message'})
4112 h.handle(r)
4113 h.close()
4114 # Now see if the event is recorded
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02004115 self.assertLess(num_recs, win32evtlog.GetNumberOfEventLogRecords(elh))
Vinay Sajip60ccd822011-05-09 17:32:09 +01004116 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
4117 win32evtlog.EVENTLOG_SEQUENTIAL_READ
4118 found = False
4119 GO_BACK = 100
4120 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
4121 for e in events:
4122 if e.SourceName != 'test_logging':
4123 continue
4124 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
4125 if msg != 'Test Log Message\r\n':
4126 continue
4127 found = True
4128 break
4129 msg = 'Record not found in event log, went back %d records' % GO_BACK
4130 self.assertTrue(found, msg=msg)
4131
Christian Heimes180510d2008-03-03 19:15:45 +00004132# Set the locale to the platform-dependent default. I have no idea
4133# why the test does this, but in any case we save the current locale
4134# first and restore it at the end.
4135@run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00004136def test_main():
Christian Heimes180510d2008-03-03 19:15:45 +00004137 run_unittest(BuiltinLevelsTest, BasicFilterTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004138 CustomLevelsAndFiltersTest, HandlerTest, MemoryHandlerTest,
Vinay Sajip7367d082011-05-02 13:17:27 +01004139 ConfigFileTest, SocketHandlerTest, DatagramHandlerTest,
4140 MemoryTest, EncodingTest, WarningsTest, ConfigDictTest,
4141 ManagerTest, FormatterTest, BufferingFormatterTest,
4142 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
4143 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest,
4144 BasicConfigTest, LoggerAdapterTest, LoggerTest,
4145 SMTPHandlerTest, FileHandlerTest, RotatingFileHandlerTest,
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004146 LastResortTest, LogRecordTest, ExceptionTest,
Vinay Sajip60ccd822011-05-09 17:32:09 +01004147 SysLogHandlerTest, HTTPHandlerTest, NTEventLogHandlerTest,
Vinay Sajip5421f352013-09-27 18:18:28 +01004148 TimedRotatingFileHandlerTest, UnixSocketHandlerTest,
4149 UnixDatagramHandlerTest, UnixSysLogHandlerTest
Vinay Sajipbc85d842010-09-17 23:35:29 +00004150 )
Jeremy Hylton096d9862003-07-18 03:19:20 +00004151
Christian Heimes180510d2008-03-03 19:15:45 +00004152if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00004153 test_main()