blob: 7c98e19b7408fc88e442bde3939fe2f4f9771a5c [file] [log] [blame]
Vinay Sajipca7b5042019-06-17 17:40:52 +01001# Copyright 2001-2019 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 Sajipca7b5042019-06-17 17:40:52 +010019Copyright (C) 2001-2019 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
Pablo Galindo137b0632018-10-16 15:17:57 +010028import copy
Vinay Sajip19ec67a2010-09-17 18:57:36 +000029import datetime
Vinay Sajipdb8f4632016-09-08 01:37:03 +010030import pathlib
Christian Heimes180510d2008-03-03 19:15:45 +000031import pickle
32import io
33import gc
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000034import json
Christian Heimes180510d2008-03-03 19:15:45 +000035import os
Vinay Sajip8552d1f2010-09-14 09:34:09 +000036import queue
Vinay Sajip66b8b082012-04-24 23:25:30 +010037import random
Christian Heimes180510d2008-03-03 19:15:45 +000038import re
Christian Heimes180510d2008-03-03 19:15:45 +000039import socket
Christian Heimes180510d2008-03-03 19:15:45 +000040import struct
41import sys
42import tempfile
Rémi Lapeyre65f64b12019-03-15 07:53:34 +010043from test.support.script_helper import assert_python_ok, assert_python_failure
Vinay Sajip1feedb42014-05-31 08:19:12 +010044from test import support
Hai Shi3ddc6342020-06-30 21:46:06 +080045from test.support import os_helper
Serhiy Storchaka16994912020-04-25 10:06:29 +030046from test.support import socket_helper
Hai Shie80697d2020-05-28 06:10:27 +080047from test.support import threading_helper
Hai Shi3ddc6342020-06-30 21:46:06 +080048from test.support import warnings_helper
Serhiy Storchaka515fce42020-04-25 11:35:18 +030049from test.support.logging_helper import TestHandler
Christian Heimes180510d2008-03-03 19:15:45 +000050import textwrap
Antoine Pitroua6a4dc82017-09-07 18:56:24 +020051import threading
Vinay Sajip37eb3382011-04-26 20:26:41 +010052import time
Christian Heimes180510d2008-03-03 19:15:45 +000053import unittest
Georg Brandlf9734072008-12-07 15:30:06 +000054import warnings
Christian Heimes180510d2008-03-03 19:15:45 +000055import weakref
Antoine Pitroua6a4dc82017-09-07 18:56:24 +020056
57import asyncore
58from http.server import HTTPServer, BaseHTTPRequestHandler
59import smtpd
60from urllib.parse import urlparse, parse_qs
61from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
62 ThreadingTCPServer, StreamRequestHandler)
63
Vinay Sajip60ccd822011-05-09 17:32:09 +010064try:
Vinay Sajip223349c2015-10-01 20:37:54 +010065 import win32evtlog, win32evtlogutil, pywintypes
Vinay Sajip60ccd822011-05-09 17:32:09 +010066except ImportError:
Vinay Sajip223349c2015-10-01 20:37:54 +010067 win32evtlog = win32evtlogutil = pywintypes = None
68
Eric V. Smith851cad72012-03-11 22:46:04 -070069try:
70 import zlib
71except ImportError:
72 pass
Christian Heimes18c66892008-02-17 13:31:39 +000073
Christian Heimes180510d2008-03-03 19:15:45 +000074class BaseTest(unittest.TestCase):
75
76 """Base class for logging tests."""
77
78 log_format = "%(name)s -> %(levelname)s: %(message)s"
Ezio Melotti3ffd29b2012-10-02 19:45:00 +030079 expected_log_pat = r"^([\w.]+) -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +000080 message_num = 0
81
82 def setUp(self):
83 """Setup the default logging stream to an internal StringIO instance,
84 so that we can examine log output as we want."""
Hai Shie80697d2020-05-28 06:10:27 +080085 self._threading_key = threading_helper.threading_setup()
Victor Stinner69669602017-08-18 23:47:54 +020086
Christian Heimes180510d2008-03-03 19:15:45 +000087 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000088 logging._acquireLock()
89 try:
Christian Heimes180510d2008-03-03 19:15:45 +000090 self.saved_handlers = logging._handlers.copy()
91 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000092 self.saved_loggers = saved_loggers = logger_dict.copy()
Vinay Sajip3b84eae2013-05-25 03:20:34 -070093 self.saved_name_to_level = logging._nameToLevel.copy()
94 self.saved_level_to_name = logging._levelToName.copy()
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000095 self.logger_states = logger_states = {}
96 for name in saved_loggers:
97 logger_states[name] = getattr(saved_loggers[name],
98 'disabled', None)
Christian Heimes18c66892008-02-17 13:31:39 +000099 finally:
100 logging._releaseLock()
101
Florent Xicluna5252f9f2011-11-07 19:43:05 +0100102 # Set two unused loggers
Vinay Sajipb4a08092010-09-20 09:55:00 +0000103 self.logger1 = logging.getLogger("\xab\xd7\xbb")
104 self.logger2 = logging.getLogger("\u013f\u00d6\u0047")
Benjamin Peterson22005fc2010-04-11 16:25:06 +0000105
Christian Heimes180510d2008-03-03 19:15:45 +0000106 self.root_logger = logging.getLogger("")
107 self.original_logging_level = self.root_logger.getEffectiveLevel()
108
109 self.stream = io.StringIO()
110 self.root_logger.setLevel(logging.DEBUG)
111 self.root_hdlr = logging.StreamHandler(self.stream)
112 self.root_formatter = logging.Formatter(self.log_format)
113 self.root_hdlr.setFormatter(self.root_formatter)
Vinay Sajip7b0e86e2010-12-30 23:26:50 +0000114 if self.logger1.hasHandlers():
115 hlist = self.logger1.handlers + self.root_logger.handlers
116 raise AssertionError('Unexpected handlers: %s' % hlist)
117 if self.logger2.hasHandlers():
118 hlist = self.logger2.handlers + self.root_logger.handlers
119 raise AssertionError('Unexpected handlers: %s' % hlist)
Christian Heimes180510d2008-03-03 19:15:45 +0000120 self.root_logger.addHandler(self.root_hdlr)
Vinay Sajipb4a08092010-09-20 09:55:00 +0000121 self.assertTrue(self.logger1.hasHandlers())
122 self.assertTrue(self.logger2.hasHandlers())
Christian Heimes180510d2008-03-03 19:15:45 +0000123
124 def tearDown(self):
125 """Remove our logging stream, and restore the original logging
126 level."""
127 self.stream.close()
128 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000129 while self.root_logger.handlers:
130 h = self.root_logger.handlers[0]
131 self.root_logger.removeHandler(h)
132 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +0000133 self.root_logger.setLevel(self.original_logging_level)
134 logging._acquireLock()
135 try:
Vinay Sajip3b84eae2013-05-25 03:20:34 -0700136 logging._levelToName.clear()
137 logging._levelToName.update(self.saved_level_to_name)
138 logging._nameToLevel.clear()
139 logging._nameToLevel.update(self.saved_name_to_level)
Christian Heimes180510d2008-03-03 19:15:45 +0000140 logging._handlers.clear()
141 logging._handlers.update(self.saved_handlers)
142 logging._handlerList[:] = self.saved_handler_list
Avram Lubkin78c18a92017-07-30 05:36:33 -0400143 manager = logging.getLogger().manager
144 manager.disable = 0
145 loggerDict = manager.loggerDict
Christian Heimes180510d2008-03-03 19:15:45 +0000146 loggerDict.clear()
147 loggerDict.update(self.saved_loggers)
Vinay Sajip7b60f4e2010-12-27 14:31:52 +0000148 logger_states = self.logger_states
149 for name in self.logger_states:
150 if logger_states[name] is not None:
151 self.saved_loggers[name].disabled = logger_states[name]
Christian Heimes180510d2008-03-03 19:15:45 +0000152 finally:
153 logging._releaseLock()
154
Victor Stinner69669602017-08-18 23:47:54 +0200155 self.doCleanups()
Hai Shie80697d2020-05-28 06:10:27 +0800156 threading_helper.threading_cleanup(*self._threading_key)
Victor Stinner69669602017-08-18 23:47:54 +0200157
Vinay Sajip4ded5512012-10-02 15:56:16 +0100158 def assert_log_lines(self, expected_values, stream=None, pat=None):
Christian Heimes180510d2008-03-03 19:15:45 +0000159 """Match the collected log lines against the regular expression
160 self.expected_log_pat, and compare the extracted group values to
161 the expected_values list of tuples."""
162 stream = stream or self.stream
Vinay Sajip4ded5512012-10-02 15:56:16 +0100163 pat = re.compile(pat or self.expected_log_pat)
Serhiy Storchaka50254c52013-08-29 11:35:43 +0300164 actual_lines = stream.getvalue().splitlines()
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100165 self.assertEqual(len(actual_lines), len(expected_values))
Christian Heimes180510d2008-03-03 19:15:45 +0000166 for actual, expected in zip(actual_lines, expected_values):
167 match = pat.search(actual)
168 if not match:
169 self.fail("Log line does not match expected pattern:\n" +
170 actual)
Ezio Melottib3aedd42010-11-20 19:04:17 +0000171 self.assertEqual(tuple(match.groups()), expected)
Christian Heimes180510d2008-03-03 19:15:45 +0000172 s = stream.read()
173 if s:
174 self.fail("Remaining output at end of log stream:\n" + s)
175
176 def next_message(self):
177 """Generate a message consisting solely of an auto-incrementing
178 integer."""
179 self.message_num += 1
180 return "%d" % self.message_num
181
182
183class BuiltinLevelsTest(BaseTest):
184 """Test builtin levels and their inheritance."""
185
186 def test_flat(self):
Mike53f7a7c2017-12-14 14:04:53 +0300187 # Logging levels in a flat logger namespace.
Christian Heimes180510d2008-03-03 19:15:45 +0000188 m = self.next_message
189
190 ERR = logging.getLogger("ERR")
191 ERR.setLevel(logging.ERROR)
Vinay Sajipc84f0162010-09-21 11:25:39 +0000192 INF = logging.LoggerAdapter(logging.getLogger("INF"), {})
Christian Heimes180510d2008-03-03 19:15:45 +0000193 INF.setLevel(logging.INFO)
194 DEB = logging.getLogger("DEB")
195 DEB.setLevel(logging.DEBUG)
196
197 # These should log.
198 ERR.log(logging.CRITICAL, m())
199 ERR.error(m())
200
201 INF.log(logging.CRITICAL, m())
202 INF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100203 INF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000204 INF.info(m())
205
206 DEB.log(logging.CRITICAL, m())
207 DEB.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100208 DEB.warning(m())
209 DEB.info(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000210 DEB.debug(m())
211
212 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100213 ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000214 ERR.info(m())
215 ERR.debug(m())
216
217 INF.debug(m())
218
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000219 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000220 ('ERR', 'CRITICAL', '1'),
221 ('ERR', 'ERROR', '2'),
222 ('INF', 'CRITICAL', '3'),
223 ('INF', 'ERROR', '4'),
224 ('INF', 'WARNING', '5'),
225 ('INF', 'INFO', '6'),
226 ('DEB', 'CRITICAL', '7'),
227 ('DEB', 'ERROR', '8'),
228 ('DEB', 'WARNING', '9'),
229 ('DEB', 'INFO', '10'),
230 ('DEB', 'DEBUG', '11'),
231 ])
232
233 def test_nested_explicit(self):
234 # Logging levels in a nested namespace, all explicitly set.
235 m = self.next_message
236
237 INF = logging.getLogger("INF")
238 INF.setLevel(logging.INFO)
239 INF_ERR = logging.getLogger("INF.ERR")
240 INF_ERR.setLevel(logging.ERROR)
241
242 # These should log.
243 INF_ERR.log(logging.CRITICAL, m())
244 INF_ERR.error(m())
245
246 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100247 INF_ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000248 INF_ERR.info(m())
249 INF_ERR.debug(m())
250
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000251 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000252 ('INF.ERR', 'CRITICAL', '1'),
253 ('INF.ERR', 'ERROR', '2'),
254 ])
255
256 def test_nested_inherited(self):
Mike53f7a7c2017-12-14 14:04:53 +0300257 # Logging levels in a nested namespace, inherited from parent loggers.
Christian Heimes180510d2008-03-03 19:15:45 +0000258 m = self.next_message
259
260 INF = logging.getLogger("INF")
261 INF.setLevel(logging.INFO)
262 INF_ERR = logging.getLogger("INF.ERR")
263 INF_ERR.setLevel(logging.ERROR)
264 INF_UNDEF = logging.getLogger("INF.UNDEF")
265 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
266 UNDEF = logging.getLogger("UNDEF")
267
268 # These should log.
269 INF_UNDEF.log(logging.CRITICAL, m())
270 INF_UNDEF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100271 INF_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000272 INF_UNDEF.info(m())
273 INF_ERR_UNDEF.log(logging.CRITICAL, m())
274 INF_ERR_UNDEF.error(m())
275
276 # These should not log.
277 INF_UNDEF.debug(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100278 INF_ERR_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000279 INF_ERR_UNDEF.info(m())
280 INF_ERR_UNDEF.debug(m())
281
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000282 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000283 ('INF.UNDEF', 'CRITICAL', '1'),
284 ('INF.UNDEF', 'ERROR', '2'),
285 ('INF.UNDEF', 'WARNING', '3'),
286 ('INF.UNDEF', 'INFO', '4'),
287 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
288 ('INF.ERR.UNDEF', 'ERROR', '6'),
289 ])
290
291 def test_nested_with_virtual_parent(self):
292 # Logging levels when some parent does not exist yet.
293 m = self.next_message
294
295 INF = logging.getLogger("INF")
296 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
297 CHILD = logging.getLogger("INF.BADPARENT")
298 INF.setLevel(logging.INFO)
299
300 # These should log.
301 GRANDCHILD.log(logging.FATAL, m())
302 GRANDCHILD.info(m())
303 CHILD.log(logging.FATAL, m())
304 CHILD.info(m())
305
306 # These should not log.
307 GRANDCHILD.debug(m())
308 CHILD.debug(m())
309
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000310 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000311 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
312 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
313 ('INF.BADPARENT', 'CRITICAL', '3'),
314 ('INF.BADPARENT', 'INFO', '4'),
315 ])
316
Vinay Sajipd1d4fbf2014-09-11 23:06:09 +0100317 def test_regression_22386(self):
318 """See issue #22386 for more information."""
319 self.assertEqual(logging.getLevelName('INFO'), logging.INFO)
320 self.assertEqual(logging.getLevelName(logging.INFO), 'INFO')
Christian Heimes180510d2008-03-03 19:15:45 +0000321
Vinay Sajipdb8f4632016-09-08 01:37:03 +0100322 def test_issue27935(self):
323 fatal = logging.getLevelName('FATAL')
324 self.assertEqual(fatal, logging.FATAL)
325
Vinay Sajip924aaae2017-01-11 17:35:36 +0000326 def test_regression_29220(self):
327 """See issue #29220 for more information."""
328 logging.addLevelName(logging.INFO, '')
329 self.addCleanup(logging.addLevelName, logging.INFO, 'INFO')
330 self.assertEqual(logging.getLevelName(logging.INFO), '')
331 self.assertEqual(logging.getLevelName(logging.NOTSET), 'NOTSET')
332 self.assertEqual(logging.getLevelName('NOTSET'), logging.NOTSET)
333
Christian Heimes180510d2008-03-03 19:15:45 +0000334class BasicFilterTest(BaseTest):
335
336 """Test the bundled Filter class."""
337
338 def test_filter(self):
339 # Only messages satisfying the specified criteria pass through the
340 # filter.
341 filter_ = logging.Filter("spam.eggs")
342 handler = self.root_logger.handlers[0]
343 try:
344 handler.addFilter(filter_)
345 spam = logging.getLogger("spam")
346 spam_eggs = logging.getLogger("spam.eggs")
347 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
348 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
349
350 spam.info(self.next_message())
351 spam_eggs.info(self.next_message()) # Good.
352 spam_eggs_fish.info(self.next_message()) # Good.
353 spam_bakedbeans.info(self.next_message())
354
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000355 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000356 ('spam.eggs', 'INFO', '2'),
357 ('spam.eggs.fish', 'INFO', '3'),
358 ])
359 finally:
360 handler.removeFilter(filter_)
361
Vinay Sajip6dbed2e2010-10-19 20:53:01 +0000362 def test_callable_filter(self):
363 # Only messages satisfying the specified criteria pass through the
364 # filter.
365
366 def filterfunc(record):
367 parts = record.name.split('.')
368 prefix = '.'.join(parts[:2])
369 return prefix == 'spam.eggs'
370
371 handler = self.root_logger.handlers[0]
372 try:
373 handler.addFilter(filterfunc)
374 spam = logging.getLogger("spam")
375 spam_eggs = logging.getLogger("spam.eggs")
376 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
377 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
378
379 spam.info(self.next_message())
380 spam_eggs.info(self.next_message()) # Good.
381 spam_eggs_fish.info(self.next_message()) # Good.
382 spam_bakedbeans.info(self.next_message())
383
384 self.assert_log_lines([
385 ('spam.eggs', 'INFO', '2'),
386 ('spam.eggs.fish', 'INFO', '3'),
387 ])
388 finally:
389 handler.removeFilter(filterfunc)
390
Vinay Sajip985ef872011-04-26 19:34:04 +0100391 def test_empty_filter(self):
392 f = logging.Filter()
393 r = logging.makeLogRecord({'name': 'spam.eggs'})
394 self.assertTrue(f.filter(r))
Christian Heimes180510d2008-03-03 19:15:45 +0000395
396#
397# First, we define our levels. There can be as many as you want - the only
398# limitations are that they should be integers, the lowest should be > 0 and
399# larger values mean less information being logged. If you need specific
400# level values which do not fit into these limitations, you can use a
401# mapping dictionary to convert between your application levels and the
402# logging system.
403#
404SILENT = 120
405TACITURN = 119
406TERSE = 118
407EFFUSIVE = 117
408SOCIABLE = 116
409VERBOSE = 115
410TALKATIVE = 114
411GARRULOUS = 113
412CHATTERBOX = 112
413BORING = 111
414
415LEVEL_RANGE = range(BORING, SILENT + 1)
416
417#
418# Next, we define names for our levels. You don't need to do this - in which
419# case the system will use "Level n" to denote the text for the level.
420#
421my_logging_levels = {
422 SILENT : 'Silent',
423 TACITURN : 'Taciturn',
424 TERSE : 'Terse',
425 EFFUSIVE : 'Effusive',
426 SOCIABLE : 'Sociable',
427 VERBOSE : 'Verbose',
428 TALKATIVE : 'Talkative',
429 GARRULOUS : 'Garrulous',
430 CHATTERBOX : 'Chatterbox',
431 BORING : 'Boring',
432}
433
434class GarrulousFilter(logging.Filter):
435
436 """A filter which blocks garrulous messages."""
437
438 def filter(self, record):
439 return record.levelno != GARRULOUS
440
441class VerySpecificFilter(logging.Filter):
442
443 """A filter which blocks sociable and taciturn messages."""
444
445 def filter(self, record):
446 return record.levelno not in [SOCIABLE, TACITURN]
447
448
449class CustomLevelsAndFiltersTest(BaseTest):
450
451 """Test various filtering possibilities with custom logging levels."""
452
453 # Skip the logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +0300454 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +0000455
456 def setUp(self):
457 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000458 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000459 logging.addLevelName(k, v)
460
461 def log_at_all_levels(self, logger):
462 for lvl in LEVEL_RANGE:
463 logger.log(lvl, self.next_message())
464
465 def test_logger_filter(self):
466 # Filter at logger level.
467 self.root_logger.setLevel(VERBOSE)
468 # Levels >= 'Verbose' are good.
469 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000470 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000471 ('Verbose', '5'),
472 ('Sociable', '6'),
473 ('Effusive', '7'),
474 ('Terse', '8'),
475 ('Taciturn', '9'),
476 ('Silent', '10'),
477 ])
478
479 def test_handler_filter(self):
480 # Filter at handler level.
481 self.root_logger.handlers[0].setLevel(SOCIABLE)
482 try:
483 # Levels >= 'Sociable' are good.
484 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000485 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000486 ('Sociable', '6'),
487 ('Effusive', '7'),
488 ('Terse', '8'),
489 ('Taciturn', '9'),
490 ('Silent', '10'),
491 ])
492 finally:
493 self.root_logger.handlers[0].setLevel(logging.NOTSET)
494
495 def test_specific_filters(self):
496 # Set a specific filter object on the handler, and then add another
497 # filter object on the logger itself.
498 handler = self.root_logger.handlers[0]
499 specific_filter = None
500 garr = GarrulousFilter()
501 handler.addFilter(garr)
502 try:
503 self.log_at_all_levels(self.root_logger)
504 first_lines = [
505 # Notice how 'Garrulous' is missing
506 ('Boring', '1'),
507 ('Chatterbox', '2'),
508 ('Talkative', '4'),
509 ('Verbose', '5'),
510 ('Sociable', '6'),
511 ('Effusive', '7'),
512 ('Terse', '8'),
513 ('Taciturn', '9'),
514 ('Silent', '10'),
515 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000516 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000517
518 specific_filter = VerySpecificFilter()
519 self.root_logger.addFilter(specific_filter)
520 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000521 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000522 # Not only 'Garrulous' is still missing, but also 'Sociable'
523 # and 'Taciturn'
524 ('Boring', '11'),
525 ('Chatterbox', '12'),
526 ('Talkative', '14'),
527 ('Verbose', '15'),
528 ('Effusive', '17'),
529 ('Terse', '18'),
530 ('Silent', '20'),
531 ])
532 finally:
533 if specific_filter:
534 self.root_logger.removeFilter(specific_filter)
535 handler.removeFilter(garr)
536
537
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100538class HandlerTest(BaseTest):
539 def test_name(self):
540 h = logging.Handler()
541 h.name = 'generic'
542 self.assertEqual(h.name, 'generic')
543 h.name = 'anothergeneric'
544 self.assertEqual(h.name, 'anothergeneric')
545 self.assertRaises(NotImplementedError, h.emit, None)
546
Vinay Sajip5a35b062011-04-27 11:31:14 +0100547 def test_builtin_handlers(self):
548 # We can't actually *use* too many handlers in the tests,
549 # but we can try instantiating them with various options
Victor Stinnere6747472011-08-21 00:39:18 +0200550 if sys.platform in ('linux', 'darwin'):
Vinay Sajip5a35b062011-04-27 11:31:14 +0100551 for existing in (True, False):
552 fd, fn = tempfile.mkstemp()
553 os.close(fd)
554 if not existing:
555 os.unlink(fn)
556 h = logging.handlers.WatchedFileHandler(fn, delay=True)
557 if existing:
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100558 dev, ino = h.dev, h.ino
Vinay Sajipa5798de2012-04-24 23:33:33 +0100559 self.assertEqual(dev, -1)
560 self.assertEqual(ino, -1)
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100561 r = logging.makeLogRecord({'msg': 'Test'})
562 h.handle(r)
563 # Now remove the file.
564 os.unlink(fn)
565 self.assertFalse(os.path.exists(fn))
566 # The next call should recreate the file.
567 h.handle(r)
568 self.assertTrue(os.path.exists(fn))
Vinay Sajip5a35b062011-04-27 11:31:14 +0100569 else:
570 self.assertEqual(h.dev, -1)
571 self.assertEqual(h.ino, -1)
572 h.close()
573 if existing:
574 os.unlink(fn)
575 if sys.platform == 'darwin':
Vinay Sajip6bba65c2011-04-27 14:31:55 +0100576 sockname = '/var/run/syslog'
Vinay Sajip5a35b062011-04-27 11:31:14 +0100577 else:
578 sockname = '/dev/log'
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100579 try:
580 h = logging.handlers.SysLogHandler(sockname)
581 self.assertEqual(h.facility, h.LOG_USER)
582 self.assertTrue(h.unixsocket)
583 h.close()
Andrew Svetlov0832af62012-12-18 23:10:48 +0200584 except OSError: # syslogd might not be available
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100585 pass
Vinay Sajip5a35b062011-04-27 11:31:14 +0100586 for method in ('GET', 'POST', 'PUT'):
587 if method == 'PUT':
588 self.assertRaises(ValueError, logging.handlers.HTTPHandler,
589 'localhost', '/log', method)
590 else:
591 h = logging.handlers.HTTPHandler('localhost', '/log', method)
592 h.close()
593 h = logging.handlers.BufferingHandler(0)
594 r = logging.makeLogRecord({})
595 self.assertTrue(h.shouldFlush(r))
596 h.close()
597 h = logging.handlers.BufferingHandler(1)
598 self.assertFalse(h.shouldFlush(r))
599 h.close()
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100600
Vinay Sajipdb8f4632016-09-08 01:37:03 +0100601 def test_path_objects(self):
602 """
603 Test that Path objects are accepted as filename arguments to handlers.
604
605 See Issue #27493.
606 """
607 fd, fn = tempfile.mkstemp()
608 os.close(fd)
609 os.unlink(fn)
610 pfn = pathlib.Path(fn)
611 cases = (
612 (logging.FileHandler, (pfn, 'w')),
613 (logging.handlers.RotatingFileHandler, (pfn, 'a')),
614 (logging.handlers.TimedRotatingFileHandler, (pfn, 'h')),
615 )
616 if sys.platform in ('linux', 'darwin'):
617 cases += ((logging.handlers.WatchedFileHandler, (pfn, 'w')),)
618 for cls, args in cases:
619 h = cls(*args)
620 self.assertTrue(os.path.exists(fn))
621 h.close()
622 os.unlink(fn)
623
Vinay Sajip5e86eed2012-05-29 22:48:10 +0100624 @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.')
Vinay Sajipa5798de2012-04-24 23:33:33 +0100625 def test_race(self):
626 # Issue #14632 refers.
627 def remove_loop(fname, tries):
628 for _ in range(tries):
629 try:
630 os.unlink(fname)
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000631 self.deletion_time = time.time()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100632 except OSError:
633 pass
634 time.sleep(0.004 * random.randint(0, 4))
635
Vinay Sajipc94871a2012-04-25 10:51:35 +0100636 del_count = 500
637 log_count = 500
Vinay Sajipa5798de2012-04-24 23:33:33 +0100638
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000639 self.handle_time = None
640 self.deletion_time = None
641
Vinay Sajipa5798de2012-04-24 23:33:33 +0100642 for delay in (False, True):
Vinay Sajipc94871a2012-04-25 10:51:35 +0100643 fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
644 os.close(fd)
645 remover = threading.Thread(target=remove_loop, args=(fn, del_count))
646 remover.daemon = True
647 remover.start()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100648 h = logging.handlers.WatchedFileHandler(fn, delay=delay)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100649 f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
650 h.setFormatter(f)
Vinay Sajipc94871a2012-04-25 10:51:35 +0100651 try:
652 for _ in range(log_count):
653 time.sleep(0.005)
654 r = logging.makeLogRecord({'msg': 'testing' })
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000655 try:
656 self.handle_time = time.time()
657 h.handle(r)
658 except Exception:
659 print('Deleted at %s, '
660 'opened at %s' % (self.deletion_time,
661 self.handle_time))
662 raise
Vinay Sajipc94871a2012-04-25 10:51:35 +0100663 finally:
Vinay Sajipc94871a2012-04-25 10:51:35 +0100664 remover.join()
Vinay Sajipac20f462012-05-03 12:09:38 +0100665 h.close()
Vinay Sajipc94871a2012-04-25 10:51:35 +0100666 if os.path.exists(fn):
667 os.unlink(fn)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100668
Gregory P. Smith19003842018-09-13 22:08:31 -0700669 # The implementation relies on os.register_at_fork existing, but we test
670 # based on os.fork existing because that is what users and this test use.
671 # This helps ensure that when fork exists (the important concept) that the
672 # register_at_fork mechanism is also present and used.
673 @unittest.skipIf(not hasattr(os, 'fork'), 'Test requires os.fork().')
674 def test_post_fork_child_no_deadlock(self):
Gregory P. Smith64aa6d22019-05-07 12:18:20 -0400675 """Ensure child logging locks are not held; bpo-6721 & bpo-36533."""
676 class _OurHandler(logging.Handler):
677 def __init__(self):
678 super().__init__()
679 self.sub_handler = logging.StreamHandler(
680 stream=open('/dev/null', 'wt'))
681
682 def emit(self, record):
683 self.sub_handler.acquire()
684 try:
685 self.sub_handler.emit(record)
686 finally:
687 self.sub_handler.release()
688
689 self.assertEqual(len(logging._handlers), 0)
690 refed_h = _OurHandler()
Xtreak2c105382019-05-13 20:18:52 +0530691 self.addCleanup(refed_h.sub_handler.stream.close)
Gregory P. Smith19003842018-09-13 22:08:31 -0700692 refed_h.name = 'because we need at least one for this test'
693 self.assertGreater(len(logging._handlers), 0)
Gregory P. Smith64aa6d22019-05-07 12:18:20 -0400694 self.assertGreater(len(logging._at_fork_reinit_lock_weakset), 1)
695 test_logger = logging.getLogger('test_post_fork_child_no_deadlock')
696 test_logger.addHandler(refed_h)
697 test_logger.setLevel(logging.DEBUG)
Gregory P. Smith19003842018-09-13 22:08:31 -0700698
699 locks_held__ready_to_fork = threading.Event()
700 fork_happened__release_locks_and_end_thread = threading.Event()
701
702 def lock_holder_thread_fn():
703 logging._acquireLock()
704 try:
705 refed_h.acquire()
706 try:
707 # Tell the main thread to do the fork.
708 locks_held__ready_to_fork.set()
709
710 # If the deadlock bug exists, the fork will happen
711 # without dealing with the locks we hold, deadlocking
712 # the child.
713
714 # Wait for a successful fork or an unreasonable amount of
715 # time before releasing our locks. To avoid a timing based
716 # test we'd need communication from os.fork() as to when it
717 # has actually happened. Given this is a regression test
718 # for a fixed issue, potentially less reliably detecting
719 # regression via timing is acceptable for simplicity.
720 # The test will always take at least this long. :(
721 fork_happened__release_locks_and_end_thread.wait(0.5)
722 finally:
723 refed_h.release()
724 finally:
725 logging._releaseLock()
726
727 lock_holder_thread = threading.Thread(
728 target=lock_holder_thread_fn,
729 name='test_post_fork_child_no_deadlock lock holder')
730 lock_holder_thread.start()
731
732 locks_held__ready_to_fork.wait()
733 pid = os.fork()
Victor Stinner278c1e12020-03-31 20:08:12 +0200734 if pid == 0:
735 # Child process
Gregory P. Smith64aa6d22019-05-07 12:18:20 -0400736 try:
737 test_logger.info(r'Child process did not deadlock. \o/')
738 finally:
739 os._exit(0)
Victor Stinner278c1e12020-03-31 20:08:12 +0200740 else:
741 # Parent process
Gregory P. Smith64aa6d22019-05-07 12:18:20 -0400742 test_logger.info(r'Parent process returned from fork. \o/')
Gregory P. Smith19003842018-09-13 22:08:31 -0700743 fork_happened__release_locks_and_end_thread.set()
744 lock_holder_thread.join()
Victor Stinner278c1e12020-03-31 20:08:12 +0200745
746 support.wait_process(pid, exitcode=0)
Gregory P. Smith19003842018-09-13 22:08:31 -0700747
Vinay Sajipa5798de2012-04-24 23:33:33 +0100748
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100749class BadStream(object):
750 def write(self, data):
751 raise RuntimeError('deliberate mistake')
752
753class TestStreamHandler(logging.StreamHandler):
754 def handleError(self, record):
755 self.error_record = record
756
Riccardo Magliocchettica87eeb2019-05-07 23:36:39 +0200757class StreamWithIntName(object):
758 level = logging.NOTSET
759 name = 2
760
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100761class StreamHandlerTest(BaseTest):
762 def test_error_handling(self):
763 h = TestStreamHandler(BadStream())
764 r = logging.makeLogRecord({})
765 old_raise = logging.raiseExceptions
Vinay Sajip1feedb42014-05-31 08:19:12 +0100766
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100767 try:
768 h.handle(r)
769 self.assertIs(h.error_record, r)
Vinay Sajip1feedb42014-05-31 08:19:12 +0100770
Vinay Sajip985ef872011-04-26 19:34:04 +0100771 h = logging.StreamHandler(BadStream())
Vinay Sajip1feedb42014-05-31 08:19:12 +0100772 with support.captured_stderr() as stderr:
773 h.handle(r)
774 msg = '\nRuntimeError: deliberate mistake\n'
775 self.assertIn(msg, stderr.getvalue())
776
Vinay Sajip985ef872011-04-26 19:34:04 +0100777 logging.raiseExceptions = False
Vinay Sajip1feedb42014-05-31 08:19:12 +0100778 with support.captured_stderr() as stderr:
779 h.handle(r)
780 self.assertEqual('', stderr.getvalue())
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100781 finally:
782 logging.raiseExceptions = old_raise
783
Vinay Sajip2543f502017-07-30 10:41:45 +0100784 def test_stream_setting(self):
785 """
786 Test setting the handler's stream
787 """
788 h = logging.StreamHandler()
789 stream = io.StringIO()
790 old = h.setStream(stream)
791 self.assertIs(old, sys.stderr)
792 actual = h.setStream(old)
793 self.assertIs(actual, stream)
794 # test that setting to existing value returns None
795 actual = h.setStream(old)
796 self.assertIsNone(actual)
797
Riccardo Magliocchettica87eeb2019-05-07 23:36:39 +0200798 def test_can_represent_stream_with_int_name(self):
799 h = logging.StreamHandler(StreamWithIntName())
800 self.assertEqual(repr(h), '<StreamHandler 2 (NOTSET)>')
801
Vinay Sajip7367d082011-05-02 13:17:27 +0100802# -- The following section could be moved into a server_helper.py module
803# -- if it proves to be of wider utility than just test_logging
Vinay Sajipa463d252011-04-30 21:52:48 +0100804
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200805class TestSMTPServer(smtpd.SMTPServer):
806 """
807 This class implements a test SMTP server.
Vinay Sajipa463d252011-04-30 21:52:48 +0100808
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200809 :param addr: A (host, port) tuple which the server listens on.
810 You can specify a port value of zero: the server's
811 *port* attribute will hold the actual port number
812 used, which can be used in client connections.
813 :param handler: A callable which will be called to process
814 incoming messages. The handler will be passed
815 the client address tuple, who the message is from,
816 a list of recipients and the message data.
817 :param poll_interval: The interval, in seconds, used in the underlying
818 :func:`select` or :func:`poll` call by
819 :func:`asyncore.loop`.
820 :param sockmap: A dictionary which will be used to hold
821 :class:`asyncore.dispatcher` instances used by
822 :func:`asyncore.loop`. This avoids changing the
823 :mod:`asyncore` module's global state.
824 """
825
826 def __init__(self, addr, handler, poll_interval, sockmap):
827 smtpd.SMTPServer.__init__(self, addr, None, map=sockmap,
828 decode_data=True)
829 self.port = self.socket.getsockname()[1]
830 self._handler = handler
831 self._thread = None
832 self.poll_interval = poll_interval
833
834 def process_message(self, peer, mailfrom, rcpttos, data):
835 """
836 Delegates to the handler passed in to the server's constructor.
837
838 Typically, this will be a test case method.
839 :param peer: The client (host, port) tuple.
840 :param mailfrom: The address of the sender.
841 :param rcpttos: The addresses of the recipients.
842 :param data: The message.
843 """
844 self._handler(peer, mailfrom, rcpttos, data)
845
846 def start(self):
847 """
848 Start the server running on a separate daemon thread.
849 """
850 self._thread = t = threading.Thread(target=self.serve_forever,
851 args=(self.poll_interval,))
852 t.setDaemon(True)
853 t.start()
854
855 def serve_forever(self, poll_interval):
856 """
857 Run the :mod:`asyncore` loop until normal termination
858 conditions arise.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100859 :param poll_interval: The interval, in seconds, used in the underlying
860 :func:`select` or :func:`poll` call by
861 :func:`asyncore.loop`.
862 """
Victor Stinner13ff2452018-01-22 18:32:50 +0100863 asyncore.loop(poll_interval, map=self._map)
Vinay Sajipce7c9782011-05-17 07:15:53 +0100864
Victor Stinnerbbc8b792019-12-10 20:41:23 +0100865 def stop(self):
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200866 """
867 Stop the thread by closing the server instance.
868 Wait for the server thread to terminate.
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200869 """
870 self.close()
Hai Shie80697d2020-05-28 06:10:27 +0800871 threading_helper.join_thread(self._thread)
Victor Stinnerb9b69002017-09-14 14:40:56 -0700872 self._thread = None
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200873 asyncore.close_all(map=self._map, ignore_all=True)
Vinay Sajipa463d252011-04-30 21:52:48 +0100874
Vinay Sajip7367d082011-05-02 13:17:27 +0100875
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200876class ControlMixin(object):
877 """
878 This mixin is used to start a server on a separate thread, and
879 shut it down programmatically. Request handling is simplified - instead
880 of needing to derive a suitable RequestHandler subclass, you just
881 provide a callable which will be passed each received request to be
882 processed.
Vinay Sajip7367d082011-05-02 13:17:27 +0100883
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200884 :param handler: A handler callable which will be called with a
885 single parameter - the request - in order to
886 process the request. This handler is called on the
887 server thread, effectively meaning that requests are
888 processed serially. While not quite Web scale ;-),
889 this should be fine for testing applications.
890 :param poll_interval: The polling interval in seconds.
891 """
892 def __init__(self, handler, poll_interval):
893 self._thread = None
894 self.poll_interval = poll_interval
895 self._handler = handler
896 self.ready = threading.Event()
Vinay Sajip7367d082011-05-02 13:17:27 +0100897
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200898 def start(self):
899 """
900 Create a daemon thread to run the server, and start it.
901 """
902 self._thread = t = threading.Thread(target=self.serve_forever,
903 args=(self.poll_interval,))
904 t.setDaemon(True)
905 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100906
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200907 def serve_forever(self, poll_interval):
908 """
909 Run the server. Set the ready flag before entering the
910 service loop.
911 """
912 self.ready.set()
913 super(ControlMixin, self).serve_forever(poll_interval)
914
Victor Stinnerbbc8b792019-12-10 20:41:23 +0100915 def stop(self):
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200916 """
917 Tell the server thread to stop, and wait for it to do so.
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200918 """
919 self.shutdown()
920 if self._thread is not None:
Hai Shie80697d2020-05-28 06:10:27 +0800921 threading_helper.join_thread(self._thread)
Vinay Sajip7367d082011-05-02 13:17:27 +0100922 self._thread = None
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200923 self.server_close()
924 self.ready.clear()
Vinay Sajip7367d082011-05-02 13:17:27 +0100925
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200926class TestHTTPServer(ControlMixin, HTTPServer):
927 """
928 An HTTP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100929
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200930 :param addr: A tuple with the IP address and port to listen on.
931 :param handler: A handler callable which will be called with a
932 single parameter - the request - in order to
933 process the request.
934 :param poll_interval: The polling interval in seconds.
935 :param log: Pass ``True`` to enable log messages.
936 """
937 def __init__(self, addr, handler, poll_interval=0.5,
938 log=False, sslctx=None):
939 class DelegatingHTTPRequestHandler(BaseHTTPRequestHandler):
940 def __getattr__(self, name, default=None):
941 if name.startswith('do_'):
942 return self.process_request
943 raise AttributeError(name)
Vinay Sajip7367d082011-05-02 13:17:27 +0100944
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200945 def process_request(self):
946 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +0100947
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200948 def log_message(self, format, *args):
949 if log:
950 super(DelegatingHTTPRequestHandler,
951 self).log_message(format, *args)
952 HTTPServer.__init__(self, addr, DelegatingHTTPRequestHandler)
953 ControlMixin.__init__(self, handler, poll_interval)
954 self.sslctx = sslctx
Vinay Sajip7367d082011-05-02 13:17:27 +0100955
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200956 def get_request(self):
957 try:
958 sock, addr = self.socket.accept()
959 if self.sslctx:
960 sock = self.sslctx.wrap_socket(sock, server_side=True)
961 except OSError as e:
962 # socket errors are silenced by the caller, print them here
963 sys.stderr.write("Got an error:\n%s\n" % e)
964 raise
965 return sock, addr
Vinay Sajip7367d082011-05-02 13:17:27 +0100966
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200967class TestTCPServer(ControlMixin, ThreadingTCPServer):
968 """
969 A TCP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100970
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200971 :param addr: A tuple with the IP address and port to listen on.
972 :param handler: A handler callable which will be called with a single
973 parameter - the request - in order to process the request.
974 :param poll_interval: The polling interval in seconds.
975 :bind_and_activate: If True (the default), binds the server and starts it
976 listening. If False, you need to call
977 :meth:`server_bind` and :meth:`server_activate` at
978 some later time before calling :meth:`start`, so that
979 the server will set up the socket and listen on it.
980 """
Vinay Sajip7367d082011-05-02 13:17:27 +0100981
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200982 allow_reuse_address = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100983
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200984 def __init__(self, addr, handler, poll_interval=0.5,
985 bind_and_activate=True):
986 class DelegatingTCPRequestHandler(StreamRequestHandler):
Vinay Sajip7367d082011-05-02 13:17:27 +0100987
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200988 def handle(self):
989 self.server._handler(self)
990 ThreadingTCPServer.__init__(self, addr, DelegatingTCPRequestHandler,
991 bind_and_activate)
992 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajip32565b62011-05-21 00:34:51 +0100993
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200994 def server_bind(self):
995 super(TestTCPServer, self).server_bind()
996 self.port = self.socket.getsockname()[1]
Vinay Sajip7367d082011-05-02 13:17:27 +0100997
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200998class TestUDPServer(ControlMixin, ThreadingUDPServer):
999 """
1000 A UDP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +01001001
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001002 :param addr: A tuple with the IP address and port to listen on.
1003 :param handler: A handler callable which will be called with a
1004 single parameter - the request - in order to
1005 process the request.
1006 :param poll_interval: The polling interval for shutdown requests,
1007 in seconds.
1008 :bind_and_activate: If True (the default), binds the server and
1009 starts it listening. If False, you need to
1010 call :meth:`server_bind` and
1011 :meth:`server_activate` at some later time
1012 before calling :meth:`start`, so that the server will
1013 set up the socket and listen on it.
1014 """
1015 def __init__(self, addr, handler, poll_interval=0.5,
1016 bind_and_activate=True):
1017 class DelegatingUDPRequestHandler(DatagramRequestHandler):
Vinay Sajip7367d082011-05-02 13:17:27 +01001018
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001019 def handle(self):
1020 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001021
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001022 def finish(self):
1023 data = self.wfile.getvalue()
1024 if data:
1025 try:
1026 super(DelegatingUDPRequestHandler, self).finish()
1027 except OSError:
1028 if not self.server._closed:
1029 raise
Vinay Sajipce7c9782011-05-17 07:15:53 +01001030
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001031 ThreadingUDPServer.__init__(self, addr,
1032 DelegatingUDPRequestHandler,
1033 bind_and_activate)
1034 ControlMixin.__init__(self, handler, poll_interval)
1035 self._closed = False
Vinay Sajipce7c9782011-05-17 07:15:53 +01001036
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001037 def server_bind(self):
1038 super(TestUDPServer, self).server_bind()
1039 self.port = self.socket.getsockname()[1]
Vinay Sajipce7c9782011-05-17 07:15:53 +01001040
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001041 def server_close(self):
1042 super(TestUDPServer, self).server_close()
1043 self._closed = True
Vinay Sajipce7c9782011-05-17 07:15:53 +01001044
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001045if hasattr(socket, "AF_UNIX"):
1046 class TestUnixStreamServer(TestTCPServer):
1047 address_family = socket.AF_UNIX
Vinay Sajipce7c9782011-05-17 07:15:53 +01001048
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001049 class TestUnixDatagramServer(TestUDPServer):
1050 address_family = socket.AF_UNIX
Vinay Sajip5421f352013-09-27 18:18:28 +01001051
Vinay Sajip7367d082011-05-02 13:17:27 +01001052# - end of server_helper section
Vinay Sajipa463d252011-04-30 21:52:48 +01001053
1054class SMTPHandlerTest(BaseTest):
Victor Stinnerc98b0192019-12-10 21:12:26 +01001055 # bpo-14314, bpo-19665, bpo-34092: don't wait forever
1056 TIMEOUT = support.LONG_TIMEOUT
Victor Stinner4bcfa3a2017-04-25 00:41:36 +02001057
Vinay Sajipa463d252011-04-30 21:52:48 +01001058 def test_basic(self):
Vinay Sajip7367d082011-05-02 13:17:27 +01001059 sockmap = {}
Serhiy Storchaka16994912020-04-25 10:06:29 +03001060 server = TestSMTPServer((socket_helper.HOST, 0), self.process_message, 0.001,
Vinay Sajip7367d082011-05-02 13:17:27 +01001061 sockmap)
1062 server.start()
Serhiy Storchaka16994912020-04-25 10:06:29 +03001063 addr = (socket_helper.HOST, server.port)
Vinay Sajip827f5d32013-12-03 11:28:55 +00001064 h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log',
1065 timeout=self.TIMEOUT)
Vinay Sajipa463d252011-04-30 21:52:48 +01001066 self.assertEqual(h.toaddrs, ['you'])
1067 self.messages = []
Vinay Sajip277640a2015-10-17 16:13:10 +01001068 r = logging.makeLogRecord({'msg': 'Hello \u2713'})
Vinay Sajip7367d082011-05-02 13:17:27 +01001069 self.handled = threading.Event()
Vinay Sajipa463d252011-04-30 21:52:48 +01001070 h.handle(r)
Victor Stinner31b50b82018-07-11 12:35:38 +02001071 self.handled.wait(self.TIMEOUT)
Vinay Sajipa463d252011-04-30 21:52:48 +01001072 server.stop()
Vinay Sajip17160fd2012-03-15 12:02:08 +00001073 self.assertTrue(self.handled.is_set())
Vinay Sajipa463d252011-04-30 21:52:48 +01001074 self.assertEqual(len(self.messages), 1)
1075 peer, mailfrom, rcpttos, data = self.messages[0]
1076 self.assertEqual(mailfrom, 'me')
1077 self.assertEqual(rcpttos, ['you'])
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001078 self.assertIn('\nSubject: Log\n', data)
Vinay Sajip277640a2015-10-17 16:13:10 +01001079 self.assertTrue(data.endswith('\n\nHello \u2713'))
Vinay Sajipa463d252011-04-30 21:52:48 +01001080 h.close()
1081
1082 def process_message(self, *args):
1083 self.messages.append(args)
Vinay Sajip7367d082011-05-02 13:17:27 +01001084 self.handled.set()
Vinay Sajipa463d252011-04-30 21:52:48 +01001085
Christian Heimes180510d2008-03-03 19:15:45 +00001086class MemoryHandlerTest(BaseTest):
1087
1088 """Tests for the MemoryHandler."""
1089
1090 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001091 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001092
1093 def setUp(self):
1094 BaseTest.setUp(self)
1095 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
Vinay Sajipdb8f4632016-09-08 01:37:03 +01001096 self.root_hdlr)
Christian Heimes180510d2008-03-03 19:15:45 +00001097 self.mem_logger = logging.getLogger('mem')
1098 self.mem_logger.propagate = 0
1099 self.mem_logger.addHandler(self.mem_hdlr)
1100
1101 def tearDown(self):
1102 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +00001103 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +00001104
1105 def test_flush(self):
1106 # The memory handler flushes to its target handler based on specific
1107 # criteria (message count and message level).
1108 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001109 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001110 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001111 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001112 # This will flush because the level is >= logging.WARNING
Vinay Sajipb9e46e92011-10-26 13:17:20 +01001113 self.mem_logger.warning(self.next_message())
Christian Heimes180510d2008-03-03 19:15:45 +00001114 lines = [
1115 ('DEBUG', '1'),
1116 ('INFO', '2'),
1117 ('WARNING', '3'),
1118 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001119 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001120 for n in (4, 14):
1121 for i in range(9):
1122 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001123 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001124 # This will flush because it's the 10th message since the last
1125 # flush.
1126 self.mem_logger.debug(self.next_message())
1127 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001128 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001129
1130 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001131 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001132
Vinay Sajipdb8f4632016-09-08 01:37:03 +01001133 def test_flush_on_close(self):
1134 """
1135 Test that the flush-on-close configuration works as expected.
1136 """
1137 self.mem_logger.debug(self.next_message())
1138 self.assert_log_lines([])
1139 self.mem_logger.info(self.next_message())
1140 self.assert_log_lines([])
1141 self.mem_logger.removeHandler(self.mem_hdlr)
1142 # Default behaviour is to flush on close. Check that it happens.
1143 self.mem_hdlr.close()
1144 lines = [
1145 ('DEBUG', '1'),
1146 ('INFO', '2'),
1147 ]
1148 self.assert_log_lines(lines)
1149 # Now configure for flushing not to be done on close.
1150 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
1151 self.root_hdlr,
1152 False)
1153 self.mem_logger.addHandler(self.mem_hdlr)
1154 self.mem_logger.debug(self.next_message())
1155 self.assert_log_lines(lines) # no change
1156 self.mem_logger.info(self.next_message())
1157 self.assert_log_lines(lines) # no change
1158 self.mem_logger.removeHandler(self.mem_hdlr)
1159 self.mem_hdlr.close()
1160 # assert that no new lines have been added
1161 self.assert_log_lines(lines) # no change
1162
Irit Katriel2353d772020-08-16 16:10:13 +01001163 def test_race_between_set_target_and_flush(self):
1164 class MockRaceConditionHandler:
1165 def __init__(self, mem_hdlr):
1166 self.mem_hdlr = mem_hdlr
Victor Stinner13ff3962020-10-12 00:37:20 +02001167 self.threads = []
Irit Katriel2353d772020-08-16 16:10:13 +01001168
1169 def removeTarget(self):
1170 self.mem_hdlr.setTarget(None)
1171
1172 def handle(self, msg):
Victor Stinner13ff3962020-10-12 00:37:20 +02001173 thread = threading.Thread(target=self.removeTarget)
1174 self.threads.append(thread)
1175 thread.start()
Irit Katriel2353d772020-08-16 16:10:13 +01001176
1177 target = MockRaceConditionHandler(self.mem_hdlr)
Victor Stinner13ff3962020-10-12 00:37:20 +02001178 try:
1179 self.mem_hdlr.setTarget(target)
Irit Katriel2353d772020-08-16 16:10:13 +01001180
Victor Stinner13ff3962020-10-12 00:37:20 +02001181 for _ in range(10):
1182 time.sleep(0.005)
1183 self.mem_logger.info("not flushed")
1184 self.mem_logger.warning("flushed")
1185 finally:
1186 for thread in target.threads:
1187 threading_helper.join_thread(thread)
Irit Katriel2353d772020-08-16 16:10:13 +01001188
Christian Heimes180510d2008-03-03 19:15:45 +00001189
1190class ExceptionFormatter(logging.Formatter):
1191 """A special exception formatter."""
1192 def formatException(self, ei):
1193 return "Got a [%s]" % ei[0].__name__
1194
1195
1196class ConfigFileTest(BaseTest):
1197
1198 """Reading logging config from a .ini-style config file."""
1199
Hai Shi3ddc6342020-06-30 21:46:06 +08001200 check_no_resource_warning = warnings_helper.check_no_resource_warning
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001201 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001202
1203 # config0 is a standard configuration.
1204 config0 = """
1205 [loggers]
1206 keys=root
1207
1208 [handlers]
1209 keys=hand1
1210
1211 [formatters]
1212 keys=form1
1213
1214 [logger_root]
1215 level=WARNING
1216 handlers=hand1
1217
1218 [handler_hand1]
1219 class=StreamHandler
1220 level=NOTSET
1221 formatter=form1
1222 args=(sys.stdout,)
1223
1224 [formatter_form1]
1225 format=%(levelname)s ++ %(message)s
1226 datefmt=
1227 """
1228
1229 # config1 adds a little to the standard configuration.
1230 config1 = """
1231 [loggers]
1232 keys=root,parser
1233
1234 [handlers]
1235 keys=hand1
1236
1237 [formatters]
1238 keys=form1
1239
1240 [logger_root]
1241 level=WARNING
1242 handlers=
1243
1244 [logger_parser]
1245 level=DEBUG
1246 handlers=hand1
1247 propagate=1
1248 qualname=compiler.parser
1249
1250 [handler_hand1]
1251 class=StreamHandler
1252 level=NOTSET
1253 formatter=form1
1254 args=(sys.stdout,)
1255
1256 [formatter_form1]
1257 format=%(levelname)s ++ %(message)s
1258 datefmt=
1259 """
1260
Vinay Sajip3f84b072011-03-07 17:49:33 +00001261 # config1a moves the handler to the root.
1262 config1a = """
1263 [loggers]
1264 keys=root,parser
1265
1266 [handlers]
1267 keys=hand1
1268
1269 [formatters]
1270 keys=form1
1271
1272 [logger_root]
1273 level=WARNING
1274 handlers=hand1
1275
1276 [logger_parser]
1277 level=DEBUG
1278 handlers=
1279 propagate=1
1280 qualname=compiler.parser
1281
1282 [handler_hand1]
1283 class=StreamHandler
1284 level=NOTSET
1285 formatter=form1
1286 args=(sys.stdout,)
1287
1288 [formatter_form1]
1289 format=%(levelname)s ++ %(message)s
1290 datefmt=
1291 """
1292
Christian Heimes180510d2008-03-03 19:15:45 +00001293 # config2 has a subtle configuration error that should be reported
1294 config2 = config1.replace("sys.stdout", "sys.stbout")
1295
1296 # config3 has a less subtle configuration error
1297 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
1298
1299 # config4 specifies a custom formatter class to be loaded
1300 config4 = """
1301 [loggers]
1302 keys=root
1303
1304 [handlers]
1305 keys=hand1
1306
1307 [formatters]
1308 keys=form1
1309
1310 [logger_root]
1311 level=NOTSET
1312 handlers=hand1
1313
1314 [handler_hand1]
1315 class=StreamHandler
1316 level=NOTSET
1317 formatter=form1
1318 args=(sys.stdout,)
1319
1320 [formatter_form1]
1321 class=""" + __name__ + """.ExceptionFormatter
1322 format=%(levelname)s:%(name)s:%(message)s
1323 datefmt=
1324 """
1325
Georg Brandl3dbca812008-07-23 16:10:53 +00001326 # config5 specifies a custom handler class to be loaded
1327 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
1328
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001329 # config6 uses ', ' delimiters in the handlers and formatters sections
1330 config6 = """
1331 [loggers]
1332 keys=root,parser
1333
1334 [handlers]
1335 keys=hand1, hand2
1336
1337 [formatters]
1338 keys=form1, form2
1339
1340 [logger_root]
1341 level=WARNING
1342 handlers=
1343
1344 [logger_parser]
1345 level=DEBUG
1346 handlers=hand1
1347 propagate=1
1348 qualname=compiler.parser
1349
1350 [handler_hand1]
1351 class=StreamHandler
1352 level=NOTSET
1353 formatter=form1
1354 args=(sys.stdout,)
1355
1356 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001357 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001358 level=NOTSET
1359 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001360 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001361
1362 [formatter_form1]
1363 format=%(levelname)s ++ %(message)s
1364 datefmt=
1365
1366 [formatter_form2]
1367 format=%(message)s
1368 datefmt=
1369 """
1370
Preston Landers6ea56d22017-08-02 15:44:28 -05001371 # config7 adds a compiler logger, and uses kwargs instead of args.
Vinay Sajip3f84b072011-03-07 17:49:33 +00001372 config7 = """
1373 [loggers]
1374 keys=root,parser,compiler
1375
1376 [handlers]
1377 keys=hand1
1378
1379 [formatters]
1380 keys=form1
1381
1382 [logger_root]
1383 level=WARNING
1384 handlers=hand1
1385
1386 [logger_compiler]
1387 level=DEBUG
1388 handlers=
1389 propagate=1
1390 qualname=compiler
1391
1392 [logger_parser]
1393 level=DEBUG
1394 handlers=
1395 propagate=1
1396 qualname=compiler.parser
1397
1398 [handler_hand1]
1399 class=StreamHandler
1400 level=NOTSET
1401 formatter=form1
Preston Landers6ea56d22017-08-02 15:44:28 -05001402 kwargs={'stream': sys.stdout,}
Vinay Sajip3f84b072011-03-07 17:49:33 +00001403
1404 [formatter_form1]
1405 format=%(levelname)s ++ %(message)s
1406 datefmt=
1407 """
1408
Xtreak087570a2018-07-02 14:27:46 +05301409 # config 8, check for resource warning
1410 config8 = r"""
1411 [loggers]
1412 keys=root
1413
1414 [handlers]
1415 keys=file
1416
1417 [formatters]
1418 keys=
1419
1420 [logger_root]
1421 level=DEBUG
1422 handlers=file
1423
1424 [handler_file]
1425 class=FileHandler
1426 level=DEBUG
1427 args=("{tempfile}",)
1428 """
1429
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001430 disable_test = """
1431 [loggers]
1432 keys=root
1433
1434 [handlers]
1435 keys=screen
1436
1437 [formatters]
1438 keys=
1439
1440 [logger_root]
1441 level=DEBUG
1442 handlers=screen
1443
1444 [handler_screen]
1445 level=DEBUG
1446 class=StreamHandler
1447 args=(sys.stdout,)
1448 formatter=
1449 """
1450
1451 def apply_config(self, conf, **kwargs):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001452 file = io.StringIO(textwrap.dedent(conf))
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001453 logging.config.fileConfig(file, **kwargs)
Christian Heimes180510d2008-03-03 19:15:45 +00001454
1455 def test_config0_ok(self):
1456 # A simple config file which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001457 with support.captured_stdout() as output:
Christian Heimes180510d2008-03-03 19:15:45 +00001458 self.apply_config(self.config0)
1459 logger = logging.getLogger()
1460 # Won't output anything
1461 logger.info(self.next_message())
1462 # Outputs a message
1463 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001464 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001465 ('ERROR', '2'),
1466 ], stream=output)
1467 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001468 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001469
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001470 def test_config0_using_cp_ok(self):
1471 # A simple config file which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001472 with support.captured_stdout() as output:
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001473 file = io.StringIO(textwrap.dedent(self.config0))
1474 cp = configparser.ConfigParser()
1475 cp.read_file(file)
1476 logging.config.fileConfig(cp)
1477 logger = logging.getLogger()
1478 # Won't output anything
1479 logger.info(self.next_message())
1480 # Outputs a message
1481 logger.error(self.next_message())
1482 self.assert_log_lines([
1483 ('ERROR', '2'),
1484 ], stream=output)
1485 # Original logger output is empty.
1486 self.assert_log_lines([])
1487
Georg Brandl3dbca812008-07-23 16:10:53 +00001488 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +00001489 # A config file defining a sub-parser as well.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001490 with support.captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +00001491 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +00001492 logger = logging.getLogger("compiler.parser")
1493 # Both will output a message
1494 logger.info(self.next_message())
1495 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001496 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001497 ('INFO', '1'),
1498 ('ERROR', '2'),
1499 ], stream=output)
1500 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001501 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001502
1503 def test_config2_failure(self):
1504 # A simple config file which overrides the default settings.
1505 self.assertRaises(Exception, self.apply_config, self.config2)
1506
1507 def test_config3_failure(self):
1508 # A simple config file which overrides the default settings.
1509 self.assertRaises(Exception, self.apply_config, self.config3)
1510
1511 def test_config4_ok(self):
1512 # A config file specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001513 with support.captured_stdout() as output:
Christian Heimes180510d2008-03-03 19:15:45 +00001514 self.apply_config(self.config4)
1515 logger = logging.getLogger()
1516 try:
1517 raise RuntimeError()
1518 except RuntimeError:
1519 logging.exception("just testing")
1520 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00001521 self.assertEqual(output.getvalue(),
Christian Heimes180510d2008-03-03 19:15:45 +00001522 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1523 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001524 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001525
Georg Brandl3dbca812008-07-23 16:10:53 +00001526 def test_config5_ok(self):
1527 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +00001528
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001529 def test_config6_ok(self):
1530 self.test_config1_ok(config=self.config6)
1531
Vinay Sajip3f84b072011-03-07 17:49:33 +00001532 def test_config7_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01001533 with support.captured_stdout() as output:
Vinay Sajip3f84b072011-03-07 17:49:33 +00001534 self.apply_config(self.config1a)
1535 logger = logging.getLogger("compiler.parser")
1536 # See issue #11424. compiler-hyphenated sorts
1537 # between compiler and compiler.xyz and this
1538 # was preventing compiler.xyz from being included
1539 # in the child loggers of compiler because of an
1540 # overzealous loop termination condition.
1541 hyphenated = logging.getLogger('compiler-hyphenated')
1542 # All will output a message
1543 logger.info(self.next_message())
1544 logger.error(self.next_message())
1545 hyphenated.critical(self.next_message())
1546 self.assert_log_lines([
1547 ('INFO', '1'),
1548 ('ERROR', '2'),
1549 ('CRITICAL', '3'),
1550 ], stream=output)
1551 # Original logger output is empty.
1552 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01001553 with support.captured_stdout() as output:
Vinay Sajip3f84b072011-03-07 17:49:33 +00001554 self.apply_config(self.config7)
1555 logger = logging.getLogger("compiler.parser")
1556 self.assertFalse(logger.disabled)
1557 # Both will output a message
1558 logger.info(self.next_message())
1559 logger.error(self.next_message())
1560 logger = logging.getLogger("compiler.lexer")
1561 # Both will output a message
1562 logger.info(self.next_message())
1563 logger.error(self.next_message())
1564 # Will not appear
1565 hyphenated.critical(self.next_message())
1566 self.assert_log_lines([
1567 ('INFO', '4'),
1568 ('ERROR', '5'),
1569 ('INFO', '6'),
1570 ('ERROR', '7'),
1571 ], stream=output)
1572 # Original logger output is empty.
1573 self.assert_log_lines([])
1574
Xtreak087570a2018-07-02 14:27:46 +05301575 def test_config8_ok(self):
1576
1577 def cleanup(h1, fn):
1578 h1.close()
1579 os.remove(fn)
1580
1581 with self.check_no_resource_warning():
1582 fd, fn = tempfile.mkstemp(".log", "test_logging-X-")
1583 os.close(fd)
1584
1585 # Replace single backslash with double backslash in windows
1586 # to avoid unicode error during string formatting
1587 if os.name == "nt":
1588 fn = fn.replace("\\", "\\\\")
1589
1590 config8 = self.config8.format(tempfile=fn)
1591
1592 self.apply_config(config8)
1593 self.apply_config(config8)
1594
1595 handler = logging.root.handlers[0]
1596 self.addCleanup(cleanup, handler, fn)
1597
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001598 def test_logger_disabling(self):
1599 self.apply_config(self.disable_test)
Antoine Pitrou04d4d6a2013-09-14 21:16:39 +02001600 logger = logging.getLogger('some_pristine_logger')
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001601 self.assertFalse(logger.disabled)
1602 self.apply_config(self.disable_test)
1603 self.assertTrue(logger.disabled)
1604 self.apply_config(self.disable_test, disable_existing_loggers=False)
1605 self.assertFalse(logger.disabled)
1606
Lucas Cimonb15100f2019-10-31 09:06:25 +01001607 def test_config_set_handler_names(self):
1608 test_config = """
1609 [loggers]
1610 keys=root
1611
1612 [handlers]
1613 keys=hand1
1614
1615 [formatters]
1616 keys=form1
1617
1618 [logger_root]
1619 handlers=hand1
1620
1621 [handler_hand1]
1622 class=StreamHandler
1623 formatter=form1
1624
1625 [formatter_form1]
1626 format=%(levelname)s ++ %(message)s
1627 """
1628 self.apply_config(test_config)
l0rb991b02d2019-11-07 11:13:36 +01001629 self.assertEqual(logging.getLogger().handlers[0].name, 'hand1')
Lucas Cimonb15100f2019-10-31 09:06:25 +01001630
Łukasz Langa214f18e2018-06-08 04:02:48 -07001631 def test_defaults_do_no_interpolation(self):
1632 """bpo-33802 defaults should not get interpolated"""
1633 ini = textwrap.dedent("""
1634 [formatters]
1635 keys=default
1636
1637 [formatter_default]
1638
1639 [handlers]
1640 keys=console
1641
1642 [handler_console]
1643 class=logging.StreamHandler
1644 args=tuple()
1645
1646 [loggers]
1647 keys=root
1648
1649 [logger_root]
1650 formatter=default
1651 handlers=console
1652 """).strip()
1653 fd, fn = tempfile.mkstemp(prefix='test_logging_', suffix='.ini')
1654 try:
1655 os.write(fd, ini.encode('ascii'))
1656 os.close(fd)
1657 logging.config.fileConfig(
1658 fn,
1659 defaults=dict(
1660 version=1,
1661 disable_existing_loggers=False,
1662 formatters={
1663 "generic": {
1664 "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s",
1665 "datefmt": "[%Y-%m-%d %H:%M:%S %z]",
1666 "class": "logging.Formatter"
1667 },
1668 },
1669 )
1670 )
1671 finally:
1672 os.unlink(fn)
1673
Guido van Rossum2a1d5162003-01-21 21:05:22 +00001674
Christian Heimes180510d2008-03-03 19:15:45 +00001675class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001676
Christian Heimes180510d2008-03-03 19:15:45 +00001677 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001678
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001679 server_class = TestTCPServer
1680 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001681
Christian Heimes180510d2008-03-03 19:15:45 +00001682 def setUp(self):
1683 """Set up a TCP server to receive log messages, and a SocketHandler
1684 pointing to that server's address and port."""
1685 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001686 # Issue #29177: deal with errors that happen during setup
1687 self.server = self.sock_hdlr = self.server_exception = None
1688 try:
1689 self.server = server = self.server_class(self.address,
1690 self.handle_socket, 0.01)
1691 server.start()
1692 # Uncomment next line to test error recovery in setUp()
1693 # raise OSError('dummy error raised')
1694 except OSError as e:
1695 self.server_exception = e
1696 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001697 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001698 hcls = logging.handlers.SocketHandler
1699 if isinstance(server.server_address, tuple):
1700 self.sock_hdlr = hcls('localhost', server.port)
1701 else:
1702 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001703 self.log_output = ''
Christian Heimes180510d2008-03-03 19:15:45 +00001704 self.root_logger.removeHandler(self.root_logger.handlers[0])
1705 self.root_logger.addHandler(self.sock_hdlr)
Vinay Sajip7367d082011-05-02 13:17:27 +01001706 self.handled = threading.Semaphore(0)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001707
Christian Heimes180510d2008-03-03 19:15:45 +00001708 def tearDown(self):
1709 """Shutdown the TCP server."""
1710 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001711 if self.sock_hdlr:
1712 self.root_logger.removeHandler(self.sock_hdlr)
1713 self.sock_hdlr.close()
Victor Stinnerb8f41632017-09-13 01:47:22 -07001714 if self.server:
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001715 self.server.stop()
Christian Heimes180510d2008-03-03 19:15:45 +00001716 finally:
1717 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001718
Vinay Sajip7367d082011-05-02 13:17:27 +01001719 def handle_socket(self, request):
1720 conn = request.connection
1721 while True:
1722 chunk = conn.recv(4)
1723 if len(chunk) < 4:
1724 break
1725 slen = struct.unpack(">L", chunk)[0]
1726 chunk = conn.recv(slen)
1727 while len(chunk) < slen:
1728 chunk = chunk + conn.recv(slen - len(chunk))
1729 obj = pickle.loads(chunk)
1730 record = logging.makeLogRecord(obj)
1731 self.log_output += record.msg + '\n'
1732 self.handled.release()
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001733
Christian Heimes180510d2008-03-03 19:15:45 +00001734 def test_output(self):
1735 # The log message sent to the SocketHandler is properly received.
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001736 if self.server_exception:
1737 self.skipTest(self.server_exception)
Christian Heimes180510d2008-03-03 19:15:45 +00001738 logger = logging.getLogger("tcp")
1739 logger.error("spam")
Vinay Sajip7367d082011-05-02 13:17:27 +01001740 self.handled.acquire()
Christian Heimes180510d2008-03-03 19:15:45 +00001741 logger.debug("eggs")
Vinay Sajip7367d082011-05-02 13:17:27 +01001742 self.handled.acquire()
1743 self.assertEqual(self.log_output, "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001744
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001745 def test_noserver(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001746 if self.server_exception:
1747 self.skipTest(self.server_exception)
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001748 # Avoid timing-related failures due to SocketHandler's own hard-wired
1749 # one-second timeout on socket.create_connection() (issue #16264).
1750 self.sock_hdlr.retryStart = 2.5
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001751 # Kill the server
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001752 self.server.stop()
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001753 # The logging call should try to connect, which should fail
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001754 try:
1755 raise RuntimeError('Deliberate mistake')
1756 except RuntimeError:
1757 self.root_logger.exception('Never sent')
1758 self.root_logger.error('Never sent, either')
1759 now = time.time()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02001760 self.assertGreater(self.sock_hdlr.retryTime, now)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001761 time.sleep(self.sock_hdlr.retryTime - now + 0.001)
1762 self.root_logger.error('Nor this')
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001763
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001764def _get_temp_domain_socket():
1765 fd, fn = tempfile.mkstemp(prefix='test_logging_', suffix='.sock')
1766 os.close(fd)
1767 # just need a name - file can't be present, or we'll get an
1768 # 'address already in use' error.
1769 os.remove(fn)
1770 return fn
Vinay Sajip7367d082011-05-02 13:17:27 +01001771
Victor Stinnerec5a8602014-06-02 14:41:51 +02001772@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001773class UnixSocketHandlerTest(SocketHandlerTest):
1774
1775 """Test for SocketHandler with unix sockets."""
1776
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001777 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001778 server_class = TestUnixStreamServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001779
1780 def setUp(self):
1781 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001782 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001783 SocketHandlerTest.setUp(self)
1784
1785 def tearDown(self):
1786 SocketHandlerTest.tearDown(self)
Hai Shi3ddc6342020-06-30 21:46:06 +08001787 os_helper.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001788
Vinay Sajip7367d082011-05-02 13:17:27 +01001789class DatagramHandlerTest(BaseTest):
1790
1791 """Test for DatagramHandler."""
1792
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001793 server_class = TestUDPServer
1794 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001795
Vinay Sajip7367d082011-05-02 13:17:27 +01001796 def setUp(self):
1797 """Set up a UDP server to receive log messages, and a DatagramHandler
1798 pointing to that server's address and port."""
1799 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001800 # Issue #29177: deal with errors that happen during setup
1801 self.server = self.sock_hdlr = self.server_exception = None
1802 try:
1803 self.server = server = self.server_class(self.address,
1804 self.handle_datagram, 0.01)
1805 server.start()
1806 # Uncomment next line to test error recovery in setUp()
1807 # raise OSError('dummy error raised')
1808 except OSError as e:
1809 self.server_exception = e
1810 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001811 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001812 hcls = logging.handlers.DatagramHandler
1813 if isinstance(server.server_address, tuple):
1814 self.sock_hdlr = hcls('localhost', server.port)
1815 else:
1816 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001817 self.log_output = ''
1818 self.root_logger.removeHandler(self.root_logger.handlers[0])
1819 self.root_logger.addHandler(self.sock_hdlr)
1820 self.handled = threading.Event()
1821
1822 def tearDown(self):
1823 """Shutdown the UDP server."""
1824 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001825 if self.server:
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001826 self.server.stop()
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001827 if self.sock_hdlr:
1828 self.root_logger.removeHandler(self.sock_hdlr)
1829 self.sock_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001830 finally:
1831 BaseTest.tearDown(self)
1832
1833 def handle_datagram(self, request):
1834 slen = struct.pack('>L', 0) # length of prefix
1835 packet = request.packet[len(slen):]
1836 obj = pickle.loads(packet)
1837 record = logging.makeLogRecord(obj)
1838 self.log_output += record.msg + '\n'
1839 self.handled.set()
1840
1841 def test_output(self):
1842 # The log message sent to the DatagramHandler is properly received.
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001843 if self.server_exception:
1844 self.skipTest(self.server_exception)
Vinay Sajip7367d082011-05-02 13:17:27 +01001845 logger = logging.getLogger("udp")
1846 logger.error("spam")
1847 self.handled.wait()
Vinay Sajip714b8dc2011-05-02 14:43:00 +01001848 self.handled.clear()
1849 logger.error("eggs")
1850 self.handled.wait()
1851 self.assertEqual(self.log_output, "spam\neggs\n")
Vinay Sajip7367d082011-05-02 13:17:27 +01001852
Victor Stinnerec5a8602014-06-02 14:41:51 +02001853@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001854class UnixDatagramHandlerTest(DatagramHandlerTest):
1855
1856 """Test for DatagramHandler using Unix sockets."""
1857
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001858 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001859 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001860
1861 def setUp(self):
1862 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001863 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001864 DatagramHandlerTest.setUp(self)
1865
1866 def tearDown(self):
1867 DatagramHandlerTest.tearDown(self)
Hai Shi3ddc6342020-06-30 21:46:06 +08001868 os_helper.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001869
Vinay Sajip7367d082011-05-02 13:17:27 +01001870class SysLogHandlerTest(BaseTest):
1871
1872 """Test for SysLogHandler using UDP."""
1873
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001874 server_class = TestUDPServer
1875 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001876
Vinay Sajip7367d082011-05-02 13:17:27 +01001877 def setUp(self):
1878 """Set up a UDP server to receive log messages, and a SysLogHandler
1879 pointing to that server's address and port."""
1880 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001881 # Issue #29177: deal with errors that happen during setup
1882 self.server = self.sl_hdlr = self.server_exception = None
1883 try:
1884 self.server = server = self.server_class(self.address,
1885 self.handle_datagram, 0.01)
1886 server.start()
1887 # Uncomment next line to test error recovery in setUp()
1888 # raise OSError('dummy error raised')
1889 except OSError as e:
1890 self.server_exception = e
1891 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001892 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001893 hcls = logging.handlers.SysLogHandler
1894 if isinstance(server.server_address, tuple):
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001895 self.sl_hdlr = hcls((server.server_address[0], server.port))
Vinay Sajip5421f352013-09-27 18:18:28 +01001896 else:
1897 self.sl_hdlr = hcls(server.server_address)
Vinay Sajip7367d082011-05-02 13:17:27 +01001898 self.log_output = ''
1899 self.root_logger.removeHandler(self.root_logger.handlers[0])
1900 self.root_logger.addHandler(self.sl_hdlr)
1901 self.handled = threading.Event()
1902
1903 def tearDown(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001904 """Shutdown the server."""
Vinay Sajip7367d082011-05-02 13:17:27 +01001905 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001906 if self.server:
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001907 self.server.stop()
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001908 if self.sl_hdlr:
1909 self.root_logger.removeHandler(self.sl_hdlr)
1910 self.sl_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001911 finally:
1912 BaseTest.tearDown(self)
1913
1914 def handle_datagram(self, request):
1915 self.log_output = request.packet
1916 self.handled.set()
1917
1918 def test_output(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001919 if self.server_exception:
1920 self.skipTest(self.server_exception)
Vinay Sajip7367d082011-05-02 13:17:27 +01001921 # The log message sent to the SysLogHandler is properly received.
1922 logger = logging.getLogger("slh")
1923 logger.error("sp\xe4m")
1924 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001925 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001926 self.handled.clear()
1927 self.sl_hdlr.append_nul = False
1928 logger.error("sp\xe4m")
1929 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001930 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m')
Vinay Sajip2353e352011-06-27 15:40:06 +01001931 self.handled.clear()
1932 self.sl_hdlr.ident = "h\xe4m-"
1933 logger.error("sp\xe4m")
1934 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001935 self.assertEqual(self.log_output, b'<11>h\xc3\xa4m-sp\xc3\xa4m')
Vinay Sajip7367d082011-05-02 13:17:27 +01001936
Victor Stinnerec5a8602014-06-02 14:41:51 +02001937@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001938class UnixSysLogHandlerTest(SysLogHandlerTest):
1939
1940 """Test for SysLogHandler with Unix sockets."""
1941
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001942 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001943 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001944
1945 def setUp(self):
1946 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001947 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001948 SysLogHandlerTest.setUp(self)
1949
1950 def tearDown(self):
1951 SysLogHandlerTest.tearDown(self)
Hai Shi3ddc6342020-06-30 21:46:06 +08001952 os_helper.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001953
Serhiy Storchaka16994912020-04-25 10:06:29 +03001954@unittest.skipUnless(socket_helper.IPV6_ENABLED,
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001955 'IPv6 support required for this test.')
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001956class IPv6SysLogHandlerTest(SysLogHandlerTest):
1957
1958 """Test for SysLogHandler with IPv6 host."""
1959
1960 server_class = TestUDPServer
1961 address = ('::1', 0)
1962
1963 def setUp(self):
1964 self.server_class.address_family = socket.AF_INET6
1965 super(IPv6SysLogHandlerTest, self).setUp()
1966
1967 def tearDown(self):
1968 self.server_class.address_family = socket.AF_INET
1969 super(IPv6SysLogHandlerTest, self).tearDown()
1970
Vinay Sajip7367d082011-05-02 13:17:27 +01001971class HTTPHandlerTest(BaseTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01001972 """Test for HTTPHandler."""
1973
1974 def setUp(self):
1975 """Set up an HTTP server to receive log messages, and a HTTPHandler
1976 pointing to that server's address and port."""
1977 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001978 self.handled = threading.Event()
1979
Vinay Sajip7367d082011-05-02 13:17:27 +01001980 def handle_request(self, request):
Vinay Sajip0372e102011-05-05 12:59:14 +01001981 self.command = request.command
Vinay Sajip7367d082011-05-02 13:17:27 +01001982 self.log_data = urlparse(request.path)
Vinay Sajip0372e102011-05-05 12:59:14 +01001983 if self.command == 'POST':
1984 try:
1985 rlen = int(request.headers['Content-Length'])
1986 self.post_data = request.rfile.read(rlen)
1987 except:
1988 self.post_data = None
Vinay Sajip7367d082011-05-02 13:17:27 +01001989 request.send_response(200)
Vinay Sajip463ac512011-05-10 09:10:08 +01001990 request.end_headers()
Vinay Sajip7367d082011-05-02 13:17:27 +01001991 self.handled.set()
1992
1993 def test_output(self):
Vinay Sajipf2231162011-05-09 22:05:50 +01001994 # The log message sent to the HTTPHandler is properly received.
Vinay Sajip7367d082011-05-02 13:17:27 +01001995 logger = logging.getLogger("http")
Vinay Sajip9ba87612011-05-21 11:32:15 +01001996 root_logger = self.root_logger
1997 root_logger.removeHandler(self.root_logger.handlers[0])
1998 for secure in (False, True):
1999 addr = ('localhost', 0)
2000 if secure:
Vinay Sajip39e35282011-05-21 16:46:41 +01002001 try:
2002 import ssl
Vinay Sajip39e35282011-05-21 16:46:41 +01002003 except ImportError:
2004 sslctx = None
Benjamin Peterson4ffb0752014-11-03 14:29:33 -05002005 else:
2006 here = os.path.dirname(__file__)
2007 localhost_cert = os.path.join(here, "keycert.pem")
Christian Heimesa170fa12017-09-15 20:27:30 +02002008 sslctx = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
Benjamin Peterson4ffb0752014-11-03 14:29:33 -05002009 sslctx.load_cert_chain(localhost_cert)
Benjamin Peterson43052a12014-11-23 20:36:44 -06002010
2011 context = ssl.create_default_context(cafile=localhost_cert)
Vinay Sajip0372e102011-05-05 12:59:14 +01002012 else:
Vinay Sajip9ba87612011-05-21 11:32:15 +01002013 sslctx = None
Benjamin Peterson43052a12014-11-23 20:36:44 -06002014 context = None
Vinay Sajip9ba87612011-05-21 11:32:15 +01002015 self.server = server = TestHTTPServer(addr, self.handle_request,
2016 0.01, sslctx=sslctx)
2017 server.start()
2018 server.ready.wait()
2019 host = 'localhost:%d' % server.server_port
Vinay Sajip39e35282011-05-21 16:46:41 +01002020 secure_client = secure and sslctx
2021 self.h_hdlr = logging.handlers.HTTPHandler(host, '/frob',
Benjamin Peterson43052a12014-11-23 20:36:44 -06002022 secure=secure_client,
Vinay Sajip1bf197e2016-06-07 21:19:55 +01002023 context=context,
2024 credentials=('foo', 'bar'))
Vinay Sajip9ba87612011-05-21 11:32:15 +01002025 self.log_data = None
2026 root_logger.addHandler(self.h_hdlr)
2027
2028 for method in ('GET', 'POST'):
2029 self.h_hdlr.method = method
2030 self.handled.clear()
2031 msg = "sp\xe4m"
2032 logger.error(msg)
2033 self.handled.wait()
2034 self.assertEqual(self.log_data.path, '/frob')
2035 self.assertEqual(self.command, method)
2036 if method == 'GET':
2037 d = parse_qs(self.log_data.query)
2038 else:
2039 d = parse_qs(self.post_data.decode('utf-8'))
2040 self.assertEqual(d['name'], ['http'])
2041 self.assertEqual(d['funcName'], ['test_output'])
2042 self.assertEqual(d['msg'], [msg])
2043
Victor Stinnerbbc8b792019-12-10 20:41:23 +01002044 self.server.stop()
Vinay Sajip9ba87612011-05-21 11:32:15 +01002045 self.root_logger.removeHandler(self.h_hdlr)
2046 self.h_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01002047
Christian Heimes180510d2008-03-03 19:15:45 +00002048class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002049
Christian Heimes180510d2008-03-03 19:15:45 +00002050 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002051
Christian Heimes180510d2008-03-03 19:15:45 +00002052 def setUp(self):
2053 """Create a dict to remember potentially destroyed objects."""
2054 BaseTest.setUp(self)
2055 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002056
Christian Heimes180510d2008-03-03 19:15:45 +00002057 def _watch_for_survival(self, *args):
2058 """Watch the given objects for survival, by creating weakrefs to
2059 them."""
2060 for obj in args:
2061 key = id(obj), repr(obj)
2062 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002063
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002064 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +00002065 """Assert that all objects watched for survival have survived."""
2066 # Trigger cycle breaking.
2067 gc.collect()
2068 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002069 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +00002070 if ref() is None:
2071 dead.append(repr_)
2072 if dead:
2073 self.fail("%d objects should have survived "
2074 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002075
Christian Heimes180510d2008-03-03 19:15:45 +00002076 def test_persistent_loggers(self):
2077 # Logger objects are persistent and retain their configuration, even
2078 # if visible references are destroyed.
2079 self.root_logger.setLevel(logging.INFO)
2080 foo = logging.getLogger("foo")
2081 self._watch_for_survival(foo)
2082 foo.setLevel(logging.DEBUG)
2083 self.root_logger.debug(self.next_message())
2084 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00002085 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00002086 ('foo', 'DEBUG', '2'),
2087 ])
2088 del foo
2089 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002090 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +00002091 # foo has retained its settings.
2092 bar = logging.getLogger("foo")
2093 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00002094 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00002095 ('foo', 'DEBUG', '2'),
2096 ('foo', 'DEBUG', '3'),
2097 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002098
Benjamin Petersonf91df042009-02-13 02:50:59 +00002099
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002100class EncodingTest(BaseTest):
2101 def test_encoding_plain_file(self):
2102 # In Python 2.x, a plain file object is treated as having no encoding.
2103 log = logging.getLogger("test")
Vinay Sajip60b4df12010-12-27 11:18:52 +00002104 fd, fn = tempfile.mkstemp(".log", "test_logging-1-")
2105 os.close(fd)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002106 # the non-ascii data we write to the log.
2107 data = "foo\x80"
2108 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002109 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002110 log.addHandler(handler)
2111 try:
2112 # write non-ascii data to the log.
2113 log.warning(data)
2114 finally:
2115 log.removeHandler(handler)
2116 handler.close()
2117 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002118 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002119 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002120 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002121 finally:
2122 f.close()
2123 finally:
2124 if os.path.isfile(fn):
2125 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002126
Benjamin Petersonf91df042009-02-13 02:50:59 +00002127 def test_encoding_cyrillic_unicode(self):
2128 log = logging.getLogger("test")
Mike53f7a7c2017-12-14 14:04:53 +03002129 # Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
Benjamin Petersonf91df042009-02-13 02:50:59 +00002130 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
Mike53f7a7c2017-12-14 14:04:53 +03002131 # Ensure it's written in a Cyrillic encoding
Benjamin Petersonf91df042009-02-13 02:50:59 +00002132 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +00002133 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +00002134 stream = io.BytesIO()
2135 writer = writer_class(stream, 'strict')
2136 handler = logging.StreamHandler(writer)
2137 log.addHandler(handler)
2138 try:
2139 log.warning(message)
2140 finally:
2141 log.removeHandler(handler)
2142 handler.close()
2143 # check we wrote exactly those bytes, ignoring trailing \n etc
2144 s = stream.getvalue()
Mike53f7a7c2017-12-14 14:04:53 +03002145 # Compare against what the data should be when encoded in CP-1251
Benjamin Petersonf91df042009-02-13 02:50:59 +00002146 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
2147
2148
Georg Brandlf9734072008-12-07 15:30:06 +00002149class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +00002150
Georg Brandlf9734072008-12-07 15:30:06 +00002151 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +00002152 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +00002153 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002154 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002155 warnings.filterwarnings("always", category=UserWarning)
2156 stream = io.StringIO()
2157 h = logging.StreamHandler(stream)
2158 logger = logging.getLogger("py.warnings")
2159 logger.addHandler(h)
2160 warnings.warn("I'm warning you...")
2161 logger.removeHandler(h)
2162 s = stream.getvalue()
2163 h.close()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02002164 self.assertGreater(s.find("UserWarning: I'm warning you...\n"), 0)
Georg Brandlf9734072008-12-07 15:30:06 +00002165
Mike53f7a7c2017-12-14 14:04:53 +03002166 # See if an explicit file uses the original implementation
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002167 a_file = io.StringIO()
2168 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
2169 a_file, "Dummy line")
2170 s = a_file.getvalue()
2171 a_file.close()
2172 self.assertEqual(s,
2173 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
2174
2175 def test_warnings_no_handlers(self):
2176 with warnings.catch_warnings():
2177 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002178 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002179
2180 # confirm our assumption: no loggers are set
2181 logger = logging.getLogger("py.warnings")
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002182 self.assertEqual(logger.handlers, [])
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002183
2184 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002185 self.assertEqual(len(logger.handlers), 1)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002186 self.assertIsInstance(logger.handlers[0], logging.NullHandler)
Georg Brandlf9734072008-12-07 15:30:06 +00002187
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002188
2189def formatFunc(format, datefmt=None):
2190 return logging.Formatter(format, datefmt)
2191
BNMetrics18fb1fb2018-10-15 19:41:36 +01002192class myCustomFormatter:
2193 def __init__(self, fmt, datefmt=None):
2194 pass
2195
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002196def handlerFunc():
2197 return logging.StreamHandler()
2198
2199class CustomHandler(logging.StreamHandler):
2200 pass
2201
2202class ConfigDictTest(BaseTest):
2203
2204 """Reading logging config from a dictionary."""
2205
Hai Shi3ddc6342020-06-30 21:46:06 +08002206 check_no_resource_warning = warnings_helper.check_no_resource_warning
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002207 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002208
2209 # config0 is a standard configuration.
2210 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002211 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002212 'formatters': {
2213 'form1' : {
2214 'format' : '%(levelname)s ++ %(message)s',
2215 },
2216 },
2217 'handlers' : {
2218 'hand1' : {
2219 'class' : 'logging.StreamHandler',
2220 'formatter' : 'form1',
2221 'level' : 'NOTSET',
2222 'stream' : 'ext://sys.stdout',
2223 },
2224 },
2225 'root' : {
2226 'level' : 'WARNING',
2227 'handlers' : ['hand1'],
2228 },
2229 }
2230
2231 # config1 adds a little to the standard configuration.
2232 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002233 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002234 'formatters': {
2235 'form1' : {
2236 'format' : '%(levelname)s ++ %(message)s',
2237 },
2238 },
2239 'handlers' : {
2240 'hand1' : {
2241 'class' : 'logging.StreamHandler',
2242 'formatter' : 'form1',
2243 'level' : 'NOTSET',
2244 'stream' : 'ext://sys.stdout',
2245 },
2246 },
2247 'loggers' : {
2248 'compiler.parser' : {
2249 'level' : 'DEBUG',
2250 'handlers' : ['hand1'],
2251 },
2252 },
2253 'root' : {
2254 'level' : 'WARNING',
2255 },
2256 }
2257
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002258 # config1a moves the handler to the root. Used with config8a
2259 config1a = {
2260 'version': 1,
2261 'formatters': {
2262 'form1' : {
2263 'format' : '%(levelname)s ++ %(message)s',
2264 },
2265 },
2266 'handlers' : {
2267 'hand1' : {
2268 'class' : 'logging.StreamHandler',
2269 'formatter' : 'form1',
2270 'level' : 'NOTSET',
2271 'stream' : 'ext://sys.stdout',
2272 },
2273 },
2274 'loggers' : {
2275 'compiler.parser' : {
2276 'level' : 'DEBUG',
2277 },
2278 },
2279 'root' : {
2280 'level' : 'WARNING',
2281 'handlers' : ['hand1'],
2282 },
2283 }
2284
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002285 # config2 has a subtle configuration error that should be reported
2286 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002287 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002288 'formatters': {
2289 'form1' : {
2290 'format' : '%(levelname)s ++ %(message)s',
2291 },
2292 },
2293 'handlers' : {
2294 'hand1' : {
2295 'class' : 'logging.StreamHandler',
2296 'formatter' : 'form1',
2297 'level' : 'NOTSET',
2298 'stream' : 'ext://sys.stdbout',
2299 },
2300 },
2301 'loggers' : {
2302 'compiler.parser' : {
2303 'level' : 'DEBUG',
2304 'handlers' : ['hand1'],
2305 },
2306 },
2307 'root' : {
2308 'level' : 'WARNING',
2309 },
2310 }
2311
Mike53f7a7c2017-12-14 14:04:53 +03002312 # As config1 but with a misspelt level on a handler
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002313 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002314 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002315 'formatters': {
2316 'form1' : {
2317 'format' : '%(levelname)s ++ %(message)s',
2318 },
2319 },
2320 'handlers' : {
2321 'hand1' : {
2322 'class' : 'logging.StreamHandler',
2323 'formatter' : 'form1',
2324 'level' : 'NTOSET',
2325 'stream' : 'ext://sys.stdout',
2326 },
2327 },
2328 'loggers' : {
2329 'compiler.parser' : {
2330 'level' : 'DEBUG',
2331 'handlers' : ['hand1'],
2332 },
2333 },
2334 'root' : {
2335 'level' : 'WARNING',
2336 },
2337 }
2338
2339
Mike53f7a7c2017-12-14 14:04:53 +03002340 # As config1 but with a misspelt level on a logger
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002341 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002342 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002343 'formatters': {
2344 'form1' : {
2345 'format' : '%(levelname)s ++ %(message)s',
2346 },
2347 },
2348 'handlers' : {
2349 'hand1' : {
2350 'class' : 'logging.StreamHandler',
2351 'formatter' : 'form1',
2352 'level' : 'NOTSET',
2353 'stream' : 'ext://sys.stdout',
2354 },
2355 },
2356 'loggers' : {
2357 'compiler.parser' : {
2358 'level' : 'DEBUG',
2359 'handlers' : ['hand1'],
2360 },
2361 },
2362 'root' : {
2363 'level' : 'WRANING',
2364 },
2365 }
2366
2367 # config3 has a less subtle configuration error
2368 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002369 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002370 'formatters': {
2371 'form1' : {
2372 'format' : '%(levelname)s ++ %(message)s',
2373 },
2374 },
2375 'handlers' : {
2376 'hand1' : {
2377 'class' : 'logging.StreamHandler',
2378 'formatter' : 'misspelled_name',
2379 'level' : 'NOTSET',
2380 'stream' : 'ext://sys.stdout',
2381 },
2382 },
2383 'loggers' : {
2384 'compiler.parser' : {
2385 'level' : 'DEBUG',
2386 'handlers' : ['hand1'],
2387 },
2388 },
2389 'root' : {
2390 'level' : 'WARNING',
2391 },
2392 }
2393
2394 # config4 specifies a custom formatter class to be loaded
2395 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002396 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002397 'formatters': {
2398 'form1' : {
2399 '()' : __name__ + '.ExceptionFormatter',
2400 'format' : '%(levelname)s:%(name)s:%(message)s',
2401 },
2402 },
2403 'handlers' : {
2404 'hand1' : {
2405 'class' : 'logging.StreamHandler',
2406 'formatter' : 'form1',
2407 'level' : 'NOTSET',
2408 'stream' : 'ext://sys.stdout',
2409 },
2410 },
2411 'root' : {
2412 'level' : 'NOTSET',
2413 'handlers' : ['hand1'],
2414 },
2415 }
2416
2417 # As config4 but using an actual callable rather than a string
2418 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002419 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002420 'formatters': {
2421 'form1' : {
2422 '()' : ExceptionFormatter,
2423 'format' : '%(levelname)s:%(name)s:%(message)s',
2424 },
2425 'form2' : {
2426 '()' : __name__ + '.formatFunc',
2427 'format' : '%(levelname)s:%(name)s:%(message)s',
2428 },
2429 'form3' : {
2430 '()' : formatFunc,
2431 'format' : '%(levelname)s:%(name)s:%(message)s',
2432 },
2433 },
2434 'handlers' : {
2435 'hand1' : {
2436 'class' : 'logging.StreamHandler',
2437 'formatter' : 'form1',
2438 'level' : 'NOTSET',
2439 'stream' : 'ext://sys.stdout',
2440 },
2441 'hand2' : {
2442 '()' : handlerFunc,
2443 },
2444 },
2445 'root' : {
2446 'level' : 'NOTSET',
2447 'handlers' : ['hand1'],
2448 },
2449 }
2450
2451 # config5 specifies a custom handler class to be loaded
2452 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002453 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002454 'formatters': {
2455 'form1' : {
2456 'format' : '%(levelname)s ++ %(message)s',
2457 },
2458 },
2459 'handlers' : {
2460 'hand1' : {
2461 'class' : __name__ + '.CustomHandler',
2462 'formatter' : 'form1',
2463 'level' : 'NOTSET',
2464 'stream' : 'ext://sys.stdout',
2465 },
2466 },
2467 'loggers' : {
2468 'compiler.parser' : {
2469 'level' : 'DEBUG',
2470 'handlers' : ['hand1'],
2471 },
2472 },
2473 'root' : {
2474 'level' : 'WARNING',
2475 },
2476 }
2477
2478 # config6 specifies a custom handler class to be loaded
2479 # but has bad arguments
2480 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002481 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002482 'formatters': {
2483 'form1' : {
2484 'format' : '%(levelname)s ++ %(message)s',
2485 },
2486 },
2487 'handlers' : {
2488 'hand1' : {
2489 'class' : __name__ + '.CustomHandler',
2490 'formatter' : 'form1',
2491 'level' : 'NOTSET',
2492 'stream' : 'ext://sys.stdout',
2493 '9' : 'invalid parameter name',
2494 },
2495 },
2496 'loggers' : {
2497 'compiler.parser' : {
2498 'level' : 'DEBUG',
2499 'handlers' : ['hand1'],
2500 },
2501 },
2502 'root' : {
2503 'level' : 'WARNING',
2504 },
2505 }
2506
Mike53f7a7c2017-12-14 14:04:53 +03002507 # config 7 does not define compiler.parser but defines compiler.lexer
2508 # so compiler.parser should be disabled after applying it
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002509 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002510 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002511 'formatters': {
2512 'form1' : {
2513 'format' : '%(levelname)s ++ %(message)s',
2514 },
2515 },
2516 'handlers' : {
2517 'hand1' : {
2518 'class' : 'logging.StreamHandler',
2519 'formatter' : 'form1',
2520 'level' : 'NOTSET',
2521 'stream' : 'ext://sys.stdout',
2522 },
2523 },
2524 'loggers' : {
2525 'compiler.lexer' : {
2526 'level' : 'DEBUG',
2527 'handlers' : ['hand1'],
2528 },
2529 },
2530 'root' : {
2531 'level' : 'WARNING',
2532 },
2533 }
2534
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002535 # config8 defines both compiler and compiler.lexer
2536 # so compiler.parser should not be disabled (since
2537 # compiler is defined)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002538 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002539 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002540 'disable_existing_loggers' : False,
2541 'formatters': {
2542 'form1' : {
2543 'format' : '%(levelname)s ++ %(message)s',
2544 },
2545 },
2546 'handlers' : {
2547 'hand1' : {
2548 'class' : 'logging.StreamHandler',
2549 'formatter' : 'form1',
2550 'level' : 'NOTSET',
2551 'stream' : 'ext://sys.stdout',
2552 },
2553 },
2554 'loggers' : {
2555 'compiler' : {
2556 'level' : 'DEBUG',
2557 'handlers' : ['hand1'],
2558 },
2559 'compiler.lexer' : {
2560 },
2561 },
2562 'root' : {
2563 'level' : 'WARNING',
2564 },
2565 }
2566
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002567 # config8a disables existing loggers
2568 config8a = {
2569 'version': 1,
2570 'disable_existing_loggers' : True,
2571 'formatters': {
2572 'form1' : {
2573 'format' : '%(levelname)s ++ %(message)s',
2574 },
2575 },
2576 'handlers' : {
2577 'hand1' : {
2578 'class' : 'logging.StreamHandler',
2579 'formatter' : 'form1',
2580 'level' : 'NOTSET',
2581 'stream' : 'ext://sys.stdout',
2582 },
2583 },
2584 'loggers' : {
2585 'compiler' : {
2586 'level' : 'DEBUG',
2587 'handlers' : ['hand1'],
2588 },
2589 'compiler.lexer' : {
2590 },
2591 },
2592 'root' : {
2593 'level' : 'WARNING',
2594 },
2595 }
2596
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002597 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002598 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002599 'formatters': {
2600 'form1' : {
2601 'format' : '%(levelname)s ++ %(message)s',
2602 },
2603 },
2604 'handlers' : {
2605 'hand1' : {
2606 'class' : 'logging.StreamHandler',
2607 'formatter' : 'form1',
2608 'level' : 'WARNING',
2609 'stream' : 'ext://sys.stdout',
2610 },
2611 },
2612 'loggers' : {
2613 'compiler.parser' : {
2614 'level' : 'WARNING',
2615 'handlers' : ['hand1'],
2616 },
2617 },
2618 'root' : {
2619 'level' : 'NOTSET',
2620 },
2621 }
2622
2623 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002624 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002625 'incremental' : True,
2626 'handlers' : {
2627 'hand1' : {
2628 'level' : 'WARNING',
2629 },
2630 },
2631 'loggers' : {
2632 'compiler.parser' : {
2633 'level' : 'INFO',
2634 },
2635 },
2636 }
2637
2638 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002639 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002640 'incremental' : True,
2641 'handlers' : {
2642 'hand1' : {
2643 'level' : 'INFO',
2644 },
2645 },
2646 'loggers' : {
2647 'compiler.parser' : {
2648 'level' : 'INFO',
2649 },
2650 },
2651 }
2652
Mike53f7a7c2017-12-14 14:04:53 +03002653 # As config1 but with a filter added
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002654 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002655 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002656 'formatters': {
2657 'form1' : {
2658 'format' : '%(levelname)s ++ %(message)s',
2659 },
2660 },
2661 'filters' : {
2662 'filt1' : {
2663 'name' : 'compiler.parser',
2664 },
2665 },
2666 'handlers' : {
2667 'hand1' : {
2668 'class' : 'logging.StreamHandler',
2669 'formatter' : 'form1',
2670 'level' : 'NOTSET',
2671 'stream' : 'ext://sys.stdout',
2672 'filters' : ['filt1'],
2673 },
2674 },
2675 'loggers' : {
2676 'compiler.parser' : {
2677 'level' : 'DEBUG',
2678 'filters' : ['filt1'],
2679 },
2680 },
2681 'root' : {
2682 'level' : 'WARNING',
2683 'handlers' : ['hand1'],
2684 },
2685 }
2686
Mike53f7a7c2017-12-14 14:04:53 +03002687 # As config1 but using cfg:// references
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002688 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002689 'version': 1,
2690 'true_formatters': {
2691 'form1' : {
2692 'format' : '%(levelname)s ++ %(message)s',
2693 },
2694 },
2695 'handler_configs': {
2696 'hand1' : {
2697 'class' : 'logging.StreamHandler',
2698 'formatter' : 'form1',
2699 'level' : 'NOTSET',
2700 'stream' : 'ext://sys.stdout',
2701 },
2702 },
2703 'formatters' : 'cfg://true_formatters',
2704 'handlers' : {
2705 'hand1' : 'cfg://handler_configs[hand1]',
2706 },
2707 'loggers' : {
2708 'compiler.parser' : {
2709 'level' : 'DEBUG',
2710 'handlers' : ['hand1'],
2711 },
2712 },
2713 'root' : {
2714 'level' : 'WARNING',
2715 },
2716 }
2717
Mike53f7a7c2017-12-14 14:04:53 +03002718 # As config11 but missing the version key
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002719 config12 = {
2720 'true_formatters': {
2721 'form1' : {
2722 'format' : '%(levelname)s ++ %(message)s',
2723 },
2724 },
2725 'handler_configs': {
2726 'hand1' : {
2727 'class' : 'logging.StreamHandler',
2728 'formatter' : 'form1',
2729 'level' : 'NOTSET',
2730 'stream' : 'ext://sys.stdout',
2731 },
2732 },
2733 'formatters' : 'cfg://true_formatters',
2734 'handlers' : {
2735 'hand1' : 'cfg://handler_configs[hand1]',
2736 },
2737 'loggers' : {
2738 'compiler.parser' : {
2739 'level' : 'DEBUG',
2740 'handlers' : ['hand1'],
2741 },
2742 },
2743 'root' : {
2744 'level' : 'WARNING',
2745 },
2746 }
2747
Mike53f7a7c2017-12-14 14:04:53 +03002748 # As config11 but using an unsupported version
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002749 config13 = {
2750 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002751 'true_formatters': {
2752 'form1' : {
2753 'format' : '%(levelname)s ++ %(message)s',
2754 },
2755 },
2756 'handler_configs': {
2757 'hand1' : {
2758 'class' : 'logging.StreamHandler',
2759 'formatter' : 'form1',
2760 'level' : 'NOTSET',
2761 'stream' : 'ext://sys.stdout',
2762 },
2763 },
2764 'formatters' : 'cfg://true_formatters',
2765 'handlers' : {
2766 'hand1' : 'cfg://handler_configs[hand1]',
2767 },
2768 'loggers' : {
2769 'compiler.parser' : {
2770 'level' : 'DEBUG',
2771 'handlers' : ['hand1'],
2772 },
2773 },
2774 'root' : {
2775 'level' : 'WARNING',
2776 },
2777 }
2778
Vinay Sajip8d270232012-11-15 14:20:18 +00002779 # As config0, but with properties
2780 config14 = {
2781 'version': 1,
2782 'formatters': {
2783 'form1' : {
2784 'format' : '%(levelname)s ++ %(message)s',
2785 },
2786 },
2787 'handlers' : {
2788 'hand1' : {
2789 'class' : 'logging.StreamHandler',
2790 'formatter' : 'form1',
2791 'level' : 'NOTSET',
2792 'stream' : 'ext://sys.stdout',
2793 '.': {
2794 'foo': 'bar',
2795 'terminator': '!\n',
2796 }
2797 },
2798 },
2799 'root' : {
2800 'level' : 'WARNING',
2801 'handlers' : ['hand1'],
2802 },
2803 }
2804
Vinay Sajip3f885b52013-03-22 15:19:54 +00002805 out_of_order = {
2806 "version": 1,
2807 "formatters": {
2808 "mySimpleFormatter": {
Vinay Sajip28421c62013-03-29 17:56:54 +00002809 "format": "%(asctime)s (%(name)s) %(levelname)s: %(message)s",
2810 "style": "$"
Vinay Sajip3f885b52013-03-22 15:19:54 +00002811 }
2812 },
2813 "handlers": {
2814 "fileGlobal": {
2815 "class": "logging.StreamHandler",
2816 "level": "DEBUG",
2817 "formatter": "mySimpleFormatter"
2818 },
2819 "bufferGlobal": {
2820 "class": "logging.handlers.MemoryHandler",
2821 "capacity": 5,
2822 "formatter": "mySimpleFormatter",
2823 "target": "fileGlobal",
2824 "level": "DEBUG"
2825 }
2826 },
2827 "loggers": {
2828 "mymodule": {
2829 "level": "DEBUG",
2830 "handlers": ["bufferGlobal"],
2831 "propagate": "true"
2832 }
2833 }
2834 }
2835
BNMetrics18fb1fb2018-10-15 19:41:36 +01002836 # Configuration with custom logging.Formatter subclass as '()' key and 'validate' set to False
2837 custom_formatter_class_validate = {
2838 'version': 1,
2839 'formatters': {
2840 'form1': {
2841 '()': __name__ + '.ExceptionFormatter',
2842 'format': '%(levelname)s:%(name)s:%(message)s',
2843 'validate': False,
2844 },
2845 },
2846 'handlers' : {
2847 'hand1' : {
2848 'class': 'logging.StreamHandler',
2849 'formatter': 'form1',
2850 'level': 'NOTSET',
2851 'stream': 'ext://sys.stdout',
2852 },
2853 },
2854 "loggers": {
2855 "my_test_logger_custom_formatter": {
2856 "level": "DEBUG",
2857 "handlers": ["hand1"],
2858 "propagate": "true"
2859 }
2860 }
2861 }
2862
2863 # Configuration with custom logging.Formatter subclass as 'class' key and 'validate' set to False
2864 custom_formatter_class_validate2 = {
2865 'version': 1,
2866 'formatters': {
2867 'form1': {
2868 'class': __name__ + '.ExceptionFormatter',
2869 'format': '%(levelname)s:%(name)s:%(message)s',
2870 'validate': False,
2871 },
2872 },
2873 'handlers' : {
2874 'hand1' : {
2875 'class': 'logging.StreamHandler',
2876 'formatter': 'form1',
2877 'level': 'NOTSET',
2878 'stream': 'ext://sys.stdout',
2879 },
2880 },
2881 "loggers": {
2882 "my_test_logger_custom_formatter": {
2883 "level": "DEBUG",
2884 "handlers": ["hand1"],
2885 "propagate": "true"
2886 }
2887 }
2888 }
2889
2890 # Configuration with custom class that is not inherited from logging.Formatter
2891 custom_formatter_class_validate3 = {
2892 'version': 1,
2893 'formatters': {
2894 'form1': {
2895 'class': __name__ + '.myCustomFormatter',
2896 'format': '%(levelname)s:%(name)s:%(message)s',
2897 'validate': False,
2898 },
2899 },
2900 'handlers' : {
2901 'hand1' : {
2902 'class': 'logging.StreamHandler',
2903 'formatter': 'form1',
2904 'level': 'NOTSET',
2905 'stream': 'ext://sys.stdout',
2906 },
2907 },
2908 "loggers": {
2909 "my_test_logger_custom_formatter": {
2910 "level": "DEBUG",
2911 "handlers": ["hand1"],
2912 "propagate": "true"
2913 }
2914 }
2915 }
2916
2917 # Configuration with custom function and 'validate' set to False
2918 custom_formatter_with_function = {
2919 'version': 1,
2920 'formatters': {
2921 'form1': {
2922 '()': formatFunc,
2923 'format': '%(levelname)s:%(name)s:%(message)s',
2924 'validate': False,
2925 },
2926 },
2927 'handlers' : {
2928 'hand1' : {
2929 'class': 'logging.StreamHandler',
2930 'formatter': 'form1',
2931 'level': 'NOTSET',
2932 'stream': 'ext://sys.stdout',
2933 },
2934 },
2935 "loggers": {
2936 "my_test_logger_custom_formatter": {
2937 "level": "DEBUG",
2938 "handlers": ["hand1"],
2939 "propagate": "true"
2940 }
2941 }
2942 }
2943
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002944 def apply_config(self, conf):
2945 logging.config.dictConfig(conf)
2946
2947 def test_config0_ok(self):
2948 # A simple config which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002949 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002950 self.apply_config(self.config0)
2951 logger = logging.getLogger()
2952 # Won't output anything
2953 logger.info(self.next_message())
2954 # Outputs a message
2955 logger.error(self.next_message())
2956 self.assert_log_lines([
2957 ('ERROR', '2'),
2958 ], stream=output)
2959 # Original logger output is empty.
2960 self.assert_log_lines([])
2961
2962 def test_config1_ok(self, config=config1):
2963 # A config defining a sub-parser as well.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002964 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002965 self.apply_config(config)
2966 logger = logging.getLogger("compiler.parser")
2967 # Both will output a message
2968 logger.info(self.next_message())
2969 logger.error(self.next_message())
2970 self.assert_log_lines([
2971 ('INFO', '1'),
2972 ('ERROR', '2'),
2973 ], stream=output)
2974 # Original logger output is empty.
2975 self.assert_log_lines([])
2976
2977 def test_config2_failure(self):
2978 # A simple config which overrides the default settings.
2979 self.assertRaises(Exception, self.apply_config, self.config2)
2980
2981 def test_config2a_failure(self):
2982 # A simple config which overrides the default settings.
2983 self.assertRaises(Exception, self.apply_config, self.config2a)
2984
2985 def test_config2b_failure(self):
2986 # A simple config which overrides the default settings.
2987 self.assertRaises(Exception, self.apply_config, self.config2b)
2988
2989 def test_config3_failure(self):
2990 # A simple config which overrides the default settings.
2991 self.assertRaises(Exception, self.apply_config, self.config3)
2992
2993 def test_config4_ok(self):
2994 # A config specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002995 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002996 self.apply_config(self.config4)
2997 #logger = logging.getLogger()
2998 try:
2999 raise RuntimeError()
3000 except RuntimeError:
3001 logging.exception("just testing")
3002 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00003003 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003004 "ERROR:root:just testing\nGot a [RuntimeError]\n")
3005 # Original logger output is empty
3006 self.assert_log_lines([])
3007
3008 def test_config4a_ok(self):
3009 # A config specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01003010 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003011 self.apply_config(self.config4a)
3012 #logger = logging.getLogger()
3013 try:
3014 raise RuntimeError()
3015 except RuntimeError:
3016 logging.exception("just testing")
3017 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00003018 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003019 "ERROR:root:just testing\nGot a [RuntimeError]\n")
3020 # Original logger output is empty
3021 self.assert_log_lines([])
3022
3023 def test_config5_ok(self):
3024 self.test_config1_ok(config=self.config5)
3025
3026 def test_config6_failure(self):
3027 self.assertRaises(Exception, self.apply_config, self.config6)
3028
3029 def test_config7_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003030 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003031 self.apply_config(self.config1)
3032 logger = logging.getLogger("compiler.parser")
3033 # Both will output a message
3034 logger.info(self.next_message())
3035 logger.error(self.next_message())
3036 self.assert_log_lines([
3037 ('INFO', '1'),
3038 ('ERROR', '2'),
3039 ], stream=output)
3040 # Original logger output is empty.
3041 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01003042 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003043 self.apply_config(self.config7)
3044 logger = logging.getLogger("compiler.parser")
3045 self.assertTrue(logger.disabled)
3046 logger = logging.getLogger("compiler.lexer")
3047 # Both will output a message
3048 logger.info(self.next_message())
3049 logger.error(self.next_message())
3050 self.assert_log_lines([
3051 ('INFO', '3'),
3052 ('ERROR', '4'),
3053 ], stream=output)
3054 # Original logger output is empty.
3055 self.assert_log_lines([])
3056
Mike53f7a7c2017-12-14 14:04:53 +03003057 # Same as test_config_7_ok but don't disable old loggers.
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003058 def test_config_8_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003059 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003060 self.apply_config(self.config1)
3061 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003062 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003063 logger.info(self.next_message())
3064 logger.error(self.next_message())
3065 self.assert_log_lines([
3066 ('INFO', '1'),
3067 ('ERROR', '2'),
3068 ], stream=output)
3069 # Original logger output is empty.
3070 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01003071 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003072 self.apply_config(self.config8)
3073 logger = logging.getLogger("compiler.parser")
3074 self.assertFalse(logger.disabled)
3075 # Both will output a message
3076 logger.info(self.next_message())
3077 logger.error(self.next_message())
3078 logger = logging.getLogger("compiler.lexer")
3079 # Both will output a message
3080 logger.info(self.next_message())
3081 logger.error(self.next_message())
3082 self.assert_log_lines([
3083 ('INFO', '3'),
3084 ('ERROR', '4'),
3085 ('INFO', '5'),
3086 ('ERROR', '6'),
3087 ], stream=output)
3088 # Original logger output is empty.
3089 self.assert_log_lines([])
3090
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003091 def test_config_8a_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003092 with support.captured_stdout() as output:
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003093 self.apply_config(self.config1a)
3094 logger = logging.getLogger("compiler.parser")
3095 # See issue #11424. compiler-hyphenated sorts
3096 # between compiler and compiler.xyz and this
3097 # was preventing compiler.xyz from being included
3098 # in the child loggers of compiler because of an
3099 # overzealous loop termination condition.
3100 hyphenated = logging.getLogger('compiler-hyphenated')
3101 # All will output a message
3102 logger.info(self.next_message())
3103 logger.error(self.next_message())
3104 hyphenated.critical(self.next_message())
3105 self.assert_log_lines([
3106 ('INFO', '1'),
3107 ('ERROR', '2'),
3108 ('CRITICAL', '3'),
3109 ], stream=output)
3110 # Original logger output is empty.
3111 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01003112 with support.captured_stdout() as output:
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003113 self.apply_config(self.config8a)
3114 logger = logging.getLogger("compiler.parser")
3115 self.assertFalse(logger.disabled)
3116 # Both will output a message
3117 logger.info(self.next_message())
3118 logger.error(self.next_message())
3119 logger = logging.getLogger("compiler.lexer")
3120 # Both will output a message
3121 logger.info(self.next_message())
3122 logger.error(self.next_message())
3123 # Will not appear
3124 hyphenated.critical(self.next_message())
3125 self.assert_log_lines([
3126 ('INFO', '4'),
3127 ('ERROR', '5'),
3128 ('INFO', '6'),
3129 ('ERROR', '7'),
3130 ], stream=output)
3131 # Original logger output is empty.
3132 self.assert_log_lines([])
3133
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003134 def test_config_9_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003135 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003136 self.apply_config(self.config9)
3137 logger = logging.getLogger("compiler.parser")
Mike53f7a7c2017-12-14 14:04:53 +03003138 # Nothing will be output since both handler and logger are set to WARNING
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003139 logger.info(self.next_message())
3140 self.assert_log_lines([], stream=output)
3141 self.apply_config(self.config9a)
Mike53f7a7c2017-12-14 14:04:53 +03003142 # Nothing will be output since handler is still set to WARNING
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003143 logger.info(self.next_message())
3144 self.assert_log_lines([], stream=output)
3145 self.apply_config(self.config9b)
Mike53f7a7c2017-12-14 14:04:53 +03003146 # Message should now be output
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003147 logger.info(self.next_message())
3148 self.assert_log_lines([
3149 ('INFO', '3'),
3150 ], stream=output)
3151
3152 def test_config_10_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003153 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003154 self.apply_config(self.config10)
3155 logger = logging.getLogger("compiler.parser")
3156 logger.warning(self.next_message())
3157 logger = logging.getLogger('compiler')
Mike53f7a7c2017-12-14 14:04:53 +03003158 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003159 logger.warning(self.next_message())
3160 logger = logging.getLogger('compiler.lexer')
Mike53f7a7c2017-12-14 14:04:53 +03003161 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003162 logger.warning(self.next_message())
3163 logger = logging.getLogger("compiler.parser.codegen")
Mike53f7a7c2017-12-14 14:04:53 +03003164 # Output, as not filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003165 logger.error(self.next_message())
3166 self.assert_log_lines([
3167 ('WARNING', '1'),
3168 ('ERROR', '4'),
3169 ], stream=output)
3170
3171 def test_config11_ok(self):
3172 self.test_config1_ok(self.config11)
3173
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00003174 def test_config12_failure(self):
3175 self.assertRaises(Exception, self.apply_config, self.config12)
3176
3177 def test_config13_failure(self):
3178 self.assertRaises(Exception, self.apply_config, self.config13)
3179
Vinay Sajip8d270232012-11-15 14:20:18 +00003180 def test_config14_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003181 with support.captured_stdout() as output:
Vinay Sajip8d270232012-11-15 14:20:18 +00003182 self.apply_config(self.config14)
3183 h = logging._handlers['hand1']
3184 self.assertEqual(h.foo, 'bar')
3185 self.assertEqual(h.terminator, '!\n')
3186 logging.warning('Exclamation')
3187 self.assertTrue(output.getvalue().endswith('Exclamation!\n'))
3188
Xtreak087570a2018-07-02 14:27:46 +05303189 def test_config15_ok(self):
3190
3191 def cleanup(h1, fn):
3192 h1.close()
3193 os.remove(fn)
3194
3195 with self.check_no_resource_warning():
3196 fd, fn = tempfile.mkstemp(".log", "test_logging-X-")
3197 os.close(fd)
3198
3199 config = {
3200 "version": 1,
3201 "handlers": {
3202 "file": {
3203 "class": "logging.FileHandler",
3204 "filename": fn
3205 }
3206 },
3207 "root": {
3208 "handlers": ["file"]
3209 }
3210 }
3211
3212 self.apply_config(config)
3213 self.apply_config(config)
3214
3215 handler = logging.root.handlers[0]
3216 self.addCleanup(cleanup, handler, fn)
3217
Vinay Sajip4ded5512012-10-02 15:56:16 +01003218 def setup_via_listener(self, text, verify=None):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00003219 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00003220 # Ask for a randomly assigned port (by using port 0)
Vinay Sajip4ded5512012-10-02 15:56:16 +01003221 t = logging.config.listen(0, verify)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003222 t.start()
3223 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00003224 # Now get the port allocated
3225 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003226 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003227 try:
3228 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
3229 sock.settimeout(2.0)
3230 sock.connect(('localhost', port))
3231
3232 slen = struct.pack('>L', len(text))
3233 s = slen + text
3234 sentsofar = 0
3235 left = len(s)
3236 while left > 0:
3237 sent = sock.send(s[sentsofar:])
3238 sentsofar += sent
3239 left -= sent
3240 sock.close()
3241 finally:
3242 t.ready.wait(2.0)
3243 logging.config.stopListening()
Hai Shie80697d2020-05-28 06:10:27 +08003244 threading_helper.join_thread(t)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003245
3246 def test_listen_config_10_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003247 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003248 self.setup_via_listener(json.dumps(self.config10))
3249 logger = logging.getLogger("compiler.parser")
3250 logger.warning(self.next_message())
3251 logger = logging.getLogger('compiler')
Mike53f7a7c2017-12-14 14:04:53 +03003252 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003253 logger.warning(self.next_message())
3254 logger = logging.getLogger('compiler.lexer')
Mike53f7a7c2017-12-14 14:04:53 +03003255 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003256 logger.warning(self.next_message())
3257 logger = logging.getLogger("compiler.parser.codegen")
Mike53f7a7c2017-12-14 14:04:53 +03003258 # Output, as not filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003259 logger.error(self.next_message())
3260 self.assert_log_lines([
3261 ('WARNING', '1'),
3262 ('ERROR', '4'),
3263 ], stream=output)
3264
3265 def test_listen_config_1_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003266 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003267 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
3268 logger = logging.getLogger("compiler.parser")
3269 # Both will output a message
3270 logger.info(self.next_message())
3271 logger.error(self.next_message())
3272 self.assert_log_lines([
3273 ('INFO', '1'),
3274 ('ERROR', '2'),
3275 ], stream=output)
3276 # Original logger output is empty.
3277 self.assert_log_lines([])
3278
Vinay Sajip4ded5512012-10-02 15:56:16 +01003279 def test_listen_verify(self):
3280
3281 def verify_fail(stuff):
3282 return None
3283
3284 def verify_reverse(stuff):
3285 return stuff[::-1]
3286
3287 logger = logging.getLogger("compiler.parser")
3288 to_send = textwrap.dedent(ConfigFileTest.config1)
3289 # First, specify a verification function that will fail.
3290 # We expect to see no output, since our configuration
3291 # never took effect.
Vinay Sajip1feedb42014-05-31 08:19:12 +01003292 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003293 self.setup_via_listener(to_send, verify_fail)
3294 # Both will output a message
3295 logger.info(self.next_message())
3296 logger.error(self.next_message())
3297 self.assert_log_lines([], stream=output)
3298 # Original logger output has the stuff we logged.
3299 self.assert_log_lines([
3300 ('INFO', '1'),
3301 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003302 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003303
3304 # Now, perform no verification. Our configuration
3305 # should take effect.
3306
Vinay Sajip1feedb42014-05-31 08:19:12 +01003307 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003308 self.setup_via_listener(to_send) # no verify callable specified
3309 logger = logging.getLogger("compiler.parser")
3310 # Both will output a message
3311 logger.info(self.next_message())
3312 logger.error(self.next_message())
3313 self.assert_log_lines([
3314 ('INFO', '3'),
3315 ('ERROR', '4'),
3316 ], stream=output)
3317 # Original logger output still has the stuff we logged before.
3318 self.assert_log_lines([
3319 ('INFO', '1'),
3320 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003321 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003322
3323 # Now, perform verification which transforms the bytes.
3324
Vinay Sajip1feedb42014-05-31 08:19:12 +01003325 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003326 self.setup_via_listener(to_send[::-1], verify_reverse)
3327 logger = logging.getLogger("compiler.parser")
3328 # Both will output a message
3329 logger.info(self.next_message())
3330 logger.error(self.next_message())
3331 self.assert_log_lines([
3332 ('INFO', '5'),
3333 ('ERROR', '6'),
3334 ], stream=output)
3335 # Original logger output still has the stuff we logged before.
3336 self.assert_log_lines([
3337 ('INFO', '1'),
3338 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003339 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003340
Vinay Sajip3f885b52013-03-22 15:19:54 +00003341 def test_out_of_order(self):
BNMetrics18fb1fb2018-10-15 19:41:36 +01003342 self.assertRaises(ValueError, self.apply_config, self.out_of_order)
3343
3344 def test_out_of_order_with_dollar_style(self):
Pablo Galindo137b0632018-10-16 15:17:57 +01003345 config = copy.deepcopy(self.out_of_order)
BNMetrics18fb1fb2018-10-15 19:41:36 +01003346 config['formatters']['mySimpleFormatter']['format'] = "${asctime} (${name}) ${levelname}: ${message}"
3347
3348 self.apply_config(config)
Vinay Sajip3f885b52013-03-22 15:19:54 +00003349 handler = logging.getLogger('mymodule').handlers[0]
3350 self.assertIsInstance(handler.target, logging.Handler)
Vinay Sajip28421c62013-03-29 17:56:54 +00003351 self.assertIsInstance(handler.formatter._style,
3352 logging.StringTemplateStyle)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003353
BNMetrics18fb1fb2018-10-15 19:41:36 +01003354 def test_custom_formatter_class_with_validate(self):
3355 self.apply_config(self.custom_formatter_class_validate)
3356 handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0]
3357 self.assertIsInstance(handler.formatter, ExceptionFormatter)
3358
3359 def test_custom_formatter_class_with_validate2(self):
3360 self.apply_config(self.custom_formatter_class_validate2)
3361 handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0]
3362 self.assertIsInstance(handler.formatter, ExceptionFormatter)
3363
3364 def test_custom_formatter_class_with_validate2_with_wrong_fmt(self):
3365 config = self.custom_formatter_class_validate.copy()
3366 config['formatters']['form1']['style'] = "$"
3367
3368 # Exception should not be raise as we have configured 'validate' to False
3369 self.apply_config(config)
3370 handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0]
3371 self.assertIsInstance(handler.formatter, ExceptionFormatter)
3372
3373 def test_custom_formatter_class_with_validate3(self):
3374 self.assertRaises(ValueError, self.apply_config, self.custom_formatter_class_validate3)
3375
3376 def test_custom_formatter_function_with_validate(self):
3377 self.assertRaises(ValueError, self.apply_config, self.custom_formatter_with_function)
3378
Vinay Sajip373baef2011-04-26 20:05:24 +01003379 def test_baseconfig(self):
3380 d = {
3381 'atuple': (1, 2, 3),
3382 'alist': ['a', 'b', 'c'],
3383 'adict': {'d': 'e', 'f': 3 },
3384 'nest1': ('g', ('h', 'i'), 'j'),
3385 'nest2': ['k', ['l', 'm'], 'n'],
3386 'nest3': ['o', 'cfg://alist', 'p'],
3387 }
3388 bc = logging.config.BaseConfigurator(d)
3389 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
3390 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
3391 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
3392 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
3393 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
3394 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
3395 v = bc.convert('cfg://nest3')
3396 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
3397 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
3398 self.assertRaises(ValueError, bc.convert, 'cfg://!')
3399 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003400
Vinay Sajip46abfc12020-01-01 19:32:11 +00003401 def test_namedtuple(self):
3402 # see bpo-39142
3403 from collections import namedtuple
3404
3405 class MyHandler(logging.StreamHandler):
3406 def __init__(self, resource, *args, **kwargs):
3407 super().__init__(*args, **kwargs)
3408 self.resource: namedtuple = resource
3409
3410 def emit(self, record):
3411 record.msg += f' {self.resource.type}'
3412 return super().emit(record)
3413
3414 Resource = namedtuple('Resource', ['type', 'labels'])
3415 resource = Resource(type='my_type', labels=['a'])
3416
3417 config = {
3418 'version': 1,
3419 'handlers': {
3420 'myhandler': {
3421 '()': MyHandler,
3422 'resource': resource
3423 }
3424 },
3425 'root': {'level': 'INFO', 'handlers': ['myhandler']},
3426 }
3427 with support.captured_stderr() as stderr:
3428 self.apply_config(config)
3429 logging.info('some log')
3430 self.assertEqual(stderr.getvalue(), 'some log my_type\n')
3431
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003432class ManagerTest(BaseTest):
3433 def test_manager_loggerclass(self):
3434 logged = []
3435
3436 class MyLogger(logging.Logger):
3437 def _log(self, level, msg, args, exc_info=None, extra=None):
3438 logged.append(msg)
3439
3440 man = logging.Manager(None)
3441 self.assertRaises(TypeError, man.setLoggerClass, int)
3442 man.setLoggerClass(MyLogger)
3443 logger = man.getLogger('test')
3444 logger.warning('should appear in logged')
3445 logging.warning('should not appear in logged')
3446
3447 self.assertEqual(logged, ['should appear in logged'])
3448
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003449 def test_set_log_record_factory(self):
3450 man = logging.Manager(None)
3451 expected = object()
3452 man.setLogRecordFactory(expected)
3453 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003454
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003455class ChildLoggerTest(BaseTest):
3456 def test_child_loggers(self):
3457 r = logging.getLogger()
3458 l1 = logging.getLogger('abc')
3459 l2 = logging.getLogger('def.ghi')
3460 c1 = r.getChild('xyz')
3461 c2 = r.getChild('uvw.xyz')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02003462 self.assertIs(c1, logging.getLogger('xyz'))
3463 self.assertIs(c2, logging.getLogger('uvw.xyz'))
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003464 c1 = l1.getChild('def')
3465 c2 = c1.getChild('ghi')
3466 c3 = l1.getChild('def.ghi')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02003467 self.assertIs(c1, logging.getLogger('abc.def'))
3468 self.assertIs(c2, logging.getLogger('abc.def.ghi'))
3469 self.assertIs(c2, c3)
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003470
3471
Vinay Sajip6fac8172010-10-19 20:44:14 +00003472class DerivedLogRecord(logging.LogRecord):
3473 pass
3474
Vinay Sajip61561522010-12-03 11:50:38 +00003475class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00003476
3477 def setUp(self):
3478 class CheckingFilter(logging.Filter):
3479 def __init__(self, cls):
3480 self.cls = cls
3481
3482 def filter(self, record):
3483 t = type(record)
3484 if t is not self.cls:
3485 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
3486 self.cls)
3487 raise TypeError(msg)
3488 return True
3489
3490 BaseTest.setUp(self)
3491 self.filter = CheckingFilter(DerivedLogRecord)
3492 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00003493 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00003494
3495 def tearDown(self):
3496 self.root_logger.removeFilter(self.filter)
3497 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00003498 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00003499
3500 def test_logrecord_class(self):
3501 self.assertRaises(TypeError, self.root_logger.warning,
3502 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00003503 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00003504 self.root_logger.error(self.next_message())
3505 self.assert_log_lines([
3506 ('root', 'ERROR', '2'),
3507 ])
3508
3509
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003510class QueueHandlerTest(BaseTest):
3511 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003512 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003513
3514 def setUp(self):
3515 BaseTest.setUp(self)
3516 self.queue = queue.Queue(-1)
3517 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
favlladfe3442017-08-01 20:12:26 +02003518 self.name = 'que'
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003519 self.que_logger = logging.getLogger('que')
3520 self.que_logger.propagate = False
3521 self.que_logger.setLevel(logging.WARNING)
3522 self.que_logger.addHandler(self.que_hdlr)
3523
3524 def tearDown(self):
3525 self.que_hdlr.close()
3526 BaseTest.tearDown(self)
3527
3528 def test_queue_handler(self):
3529 self.que_logger.debug(self.next_message())
3530 self.assertRaises(queue.Empty, self.queue.get_nowait)
3531 self.que_logger.info(self.next_message())
3532 self.assertRaises(queue.Empty, self.queue.get_nowait)
3533 msg = self.next_message()
3534 self.que_logger.warning(msg)
3535 data = self.queue.get_nowait()
3536 self.assertTrue(isinstance(data, logging.LogRecord))
3537 self.assertEqual(data.name, self.que_logger.name)
3538 self.assertEqual((data.msg, data.args), (msg, None))
3539
favlladfe3442017-08-01 20:12:26 +02003540 def test_formatting(self):
3541 msg = self.next_message()
3542 levelname = logging.getLevelName(logging.WARNING)
3543 log_format_str = '{name} -> {levelname}: {message}'
3544 formatted_msg = log_format_str.format(name=self.name,
3545 levelname=levelname, message=msg)
3546 formatter = logging.Formatter(self.log_format)
3547 self.que_hdlr.setFormatter(formatter)
3548 self.que_logger.warning(msg)
3549 log_record = self.queue.get_nowait()
3550 self.assertEqual(formatted_msg, log_record.msg)
3551 self.assertEqual(formatted_msg, log_record.message)
3552
Victor Stinnercafa2ef2011-05-02 16:11:28 +02003553 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3554 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01003555 def test_queue_listener(self):
Serhiy Storchaka515fce42020-04-25 11:35:18 +03003556 handler = TestHandler(support.Matcher())
Vinay Sajipe723e962011-04-15 22:27:17 +01003557 listener = logging.handlers.QueueListener(self.queue, handler)
3558 listener.start()
3559 try:
3560 self.que_logger.warning(self.next_message())
3561 self.que_logger.error(self.next_message())
3562 self.que_logger.critical(self.next_message())
3563 finally:
3564 listener.stop()
3565 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
3566 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
3567 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
Vinay Sajip365701a2015-02-09 19:49:00 +00003568 handler.close()
3569
3570 # Now test with respect_handler_level set
3571
Serhiy Storchaka515fce42020-04-25 11:35:18 +03003572 handler = TestHandler(support.Matcher())
Vinay Sajip365701a2015-02-09 19:49:00 +00003573 handler.setLevel(logging.CRITICAL)
3574 listener = logging.handlers.QueueListener(self.queue, handler,
3575 respect_handler_level=True)
3576 listener.start()
3577 try:
3578 self.que_logger.warning(self.next_message())
3579 self.que_logger.error(self.next_message())
3580 self.que_logger.critical(self.next_message())
3581 finally:
3582 listener.stop()
3583 self.assertFalse(handler.matches(levelno=logging.WARNING, message='4'))
3584 self.assertFalse(handler.matches(levelno=logging.ERROR, message='5'))
3585 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='6'))
Cheryl Sabellad345bb42018-09-25 19:00:08 -04003586 handler.close()
3587
3588 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3589 'logging.handlers.QueueListener required for this test')
3590 def test_queue_listener_with_StreamHandler(self):
3591 # Test that traceback only appends once (bpo-34334).
3592 listener = logging.handlers.QueueListener(self.queue, self.root_hdlr)
3593 listener.start()
3594 try:
3595 1 / 0
3596 except ZeroDivisionError as e:
3597 exc = e
3598 self.que_logger.exception(self.next_message(), exc_info=exc)
3599 listener.stop()
3600 self.assertEqual(self.stream.getvalue().strip().count('Traceback'), 1)
Vinay Sajip365701a2015-02-09 19:49:00 +00003601
Xtreak2dad9602019-04-07 13:21:27 +05303602 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3603 'logging.handlers.QueueListener required for this test')
3604 def test_queue_listener_with_multiple_handlers(self):
3605 # Test that queue handler format doesn't affect other handler formats (bpo-35726).
3606 self.que_hdlr.setFormatter(self.root_formatter)
3607 self.que_logger.addHandler(self.root_hdlr)
3608
3609 listener = logging.handlers.QueueListener(self.queue, self.que_hdlr)
3610 listener.start()
3611 self.que_logger.error("error")
3612 listener.stop()
3613 self.assertEqual(self.stream.getvalue().strip(), "que -> ERROR: error")
3614
Vinay Sajipd61910c2016-09-08 01:13:39 +01003615if hasattr(logging.handlers, 'QueueListener'):
3616 import multiprocessing
3617 from unittest.mock import patch
3618
3619 class QueueListenerTest(BaseTest):
3620 """
3621 Tests based on patch submitted for issue #27930. Ensure that
3622 QueueListener handles all log messages.
3623 """
3624
3625 repeat = 20
3626
3627 @staticmethod
3628 def setup_and_log(log_queue, ident):
3629 """
3630 Creates a logger with a QueueHandler that logs to a queue read by a
3631 QueueListener. Starts the listener, logs five messages, and stops
3632 the listener.
3633 """
3634 logger = logging.getLogger('test_logger_with_id_%s' % ident)
3635 logger.setLevel(logging.DEBUG)
3636 handler = logging.handlers.QueueHandler(log_queue)
3637 logger.addHandler(handler)
3638 listener = logging.handlers.QueueListener(log_queue)
3639 listener.start()
3640
3641 logger.info('one')
3642 logger.info('two')
3643 logger.info('three')
3644 logger.info('four')
3645 logger.info('five')
3646
3647 listener.stop()
3648 logger.removeHandler(handler)
3649 handler.close()
3650
3651 @patch.object(logging.handlers.QueueListener, 'handle')
3652 def test_handle_called_with_queue_queue(self, mock_handle):
3653 for i in range(self.repeat):
3654 log_queue = queue.Queue()
3655 self.setup_and_log(log_queue, '%s_%s' % (self.id(), i))
3656 self.assertEqual(mock_handle.call_count, 5 * self.repeat,
3657 'correct number of handled log messages')
3658
3659 @patch.object(logging.handlers.QueueListener, 'handle')
3660 def test_handle_called_with_mp_queue(self, mock_handle):
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003661 # bpo-28668: The multiprocessing (mp) module is not functional
xdegayebf2b65e2017-12-01 08:08:49 +01003662 # when the mp.synchronize module cannot be imported.
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003663 support.skip_if_broken_multiprocessing_synchronize()
Vinay Sajipd61910c2016-09-08 01:13:39 +01003664 for i in range(self.repeat):
3665 log_queue = multiprocessing.Queue()
3666 self.setup_and_log(log_queue, '%s_%s' % (self.id(), i))
Victor Stinner8ca2f2f2017-04-26 15:56:25 +02003667 log_queue.close()
3668 log_queue.join_thread()
Vinay Sajipd61910c2016-09-08 01:13:39 +01003669 self.assertEqual(mock_handle.call_count, 5 * self.repeat,
3670 'correct number of handled log messages')
3671
3672 @staticmethod
3673 def get_all_from_queue(log_queue):
3674 try:
3675 while True:
3676 yield log_queue.get_nowait()
3677 except queue.Empty:
3678 return []
3679
3680 def test_no_messages_in_queue_after_stop(self):
3681 """
3682 Five messages are logged then the QueueListener is stopped. This
3683 test then gets everything off the queue. Failure of this test
3684 indicates that messages were not registered on the queue until
3685 _after_ the QueueListener stopped.
3686 """
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003687 # bpo-28668: The multiprocessing (mp) module is not functional
xdegayebf2b65e2017-12-01 08:08:49 +01003688 # when the mp.synchronize module cannot be imported.
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003689 support.skip_if_broken_multiprocessing_synchronize()
Vinay Sajipd61910c2016-09-08 01:13:39 +01003690 for i in range(self.repeat):
3691 queue = multiprocessing.Queue()
3692 self.setup_and_log(queue, '%s_%s' %(self.id(), i))
3693 # time.sleep(1)
3694 items = list(self.get_all_from_queue(queue))
Victor Stinner8ca2f2f2017-04-26 15:56:25 +02003695 queue.close()
3696 queue.join_thread()
3697
Vinay Sajipd61910c2016-09-08 01:13:39 +01003698 expected = [[], [logging.handlers.QueueListener._sentinel]]
3699 self.assertIn(items, expected,
3700 'Found unexpected messages in queue: %s' % (
3701 [m.msg if isinstance(m, logging.LogRecord)
3702 else m for m in items]))
3703
Bar Harel6b282e12019-06-01 12:19:09 +03003704 def test_calls_task_done_after_stop(self):
3705 # Issue 36813: Make sure queue.join does not deadlock.
3706 log_queue = queue.Queue()
3707 listener = logging.handlers.QueueListener(log_queue)
3708 listener.start()
3709 listener.stop()
3710 with self.assertRaises(ValueError):
3711 # Make sure all tasks are done and .join won't block.
3712 log_queue.task_done()
3713
Vinay Sajipe723e962011-04-15 22:27:17 +01003714
Vinay Sajip37eb3382011-04-26 20:26:41 +01003715ZERO = datetime.timedelta(0)
3716
3717class UTC(datetime.tzinfo):
3718 def utcoffset(self, dt):
3719 return ZERO
3720
3721 dst = utcoffset
3722
3723 def tzname(self, dt):
3724 return 'UTC'
3725
3726utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01003727
Eric Larson9fdb76c2020-09-25 14:08:50 -04003728class AssertErrorMessage:
3729
3730 def assert_error_message(self, exception, message, *args, **kwargs):
3731 try:
3732 self.assertRaises((), *args, **kwargs)
3733 except exception as e:
3734 self.assertEqual(message, str(e))
3735
3736class FormatterTest(unittest.TestCase, AssertErrorMessage):
Vinay Sajipa39c5712010-10-25 13:57:39 +00003737 def setUp(self):
3738 self.common = {
3739 'name': 'formatter.test',
3740 'level': logging.DEBUG,
3741 'pathname': os.path.join('path', 'to', 'dummy.ext'),
3742 'lineno': 42,
3743 'exc_info': None,
3744 'func': None,
3745 'msg': 'Message with %d %s',
3746 'args': (2, 'placeholders'),
3747 }
3748 self.variants = {
Bar Harel8f192d12020-06-18 17:18:58 +03003749 'custom': {
3750 'custom': 1234
3751 }
Vinay Sajipa39c5712010-10-25 13:57:39 +00003752 }
3753
3754 def get_record(self, name=None):
3755 result = dict(self.common)
3756 if name is not None:
3757 result.update(self.variants[name])
3758 return logging.makeLogRecord(result)
3759
3760 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003761 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003762 r = self.get_record()
3763 f = logging.Formatter('${%(message)s}')
3764 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
3765 f = logging.Formatter('%(random)s')
BNMetrics18fb1fb2018-10-15 19:41:36 +01003766 self.assertRaises(ValueError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003767 self.assertFalse(f.usesTime())
3768 f = logging.Formatter('%(asctime)s')
3769 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003770 f = logging.Formatter('%(asctime)-15s')
3771 self.assertTrue(f.usesTime())
BNMetrics18fb1fb2018-10-15 19:41:36 +01003772 f = logging.Formatter('%(asctime)#15s')
3773 self.assertTrue(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003774
3775 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003776 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003777 r = self.get_record()
3778 f = logging.Formatter('$%{message}%$', style='{')
3779 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3780 f = logging.Formatter('{random}', style='{')
BNMetrics18fb1fb2018-10-15 19:41:36 +01003781 self.assertRaises(ValueError, f.format, r)
3782 f = logging.Formatter("{message}", style='{')
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003783 self.assertFalse(f.usesTime())
3784 f = logging.Formatter('{asctime}', style='{')
3785 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003786 f = logging.Formatter('{asctime!s:15}', style='{')
3787 self.assertTrue(f.usesTime())
3788 f = logging.Formatter('{asctime:15}', style='{')
3789 self.assertTrue(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003790
3791 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003792 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003793 r = self.get_record()
BNMetrics18fb1fb2018-10-15 19:41:36 +01003794 f = logging.Formatter('${message}', style='$')
3795 self.assertEqual(f.format(r), 'Message with 2 placeholders')
Vinay Sajipa39c5712010-10-25 13:57:39 +00003796 f = logging.Formatter('$message', style='$')
3797 self.assertEqual(f.format(r), 'Message with 2 placeholders')
3798 f = logging.Formatter('$$%${message}%$$', style='$')
3799 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3800 f = logging.Formatter('${random}', style='$')
BNMetrics18fb1fb2018-10-15 19:41:36 +01003801 self.assertRaises(ValueError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003802 self.assertFalse(f.usesTime())
3803 f = logging.Formatter('${asctime}', style='$')
3804 self.assertTrue(f.usesTime())
3805 f = logging.Formatter('$asctime', style='$')
3806 self.assertTrue(f.usesTime())
BNMetrics18fb1fb2018-10-15 19:41:36 +01003807 f = logging.Formatter('${message}', style='$')
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003808 self.assertFalse(f.usesTime())
BNMetrics18fb1fb2018-10-15 19:41:36 +01003809 f = logging.Formatter('${asctime}--', style='$')
3810 self.assertTrue(f.usesTime())
3811
3812 def test_format_validate(self):
3813 # Check correct formatting
3814 # Percentage style
3815 f = logging.Formatter("%(levelname)-15s - %(message) 5s - %(process)03d - %(module) - %(asctime)*.3s")
3816 self.assertEqual(f._fmt, "%(levelname)-15s - %(message) 5s - %(process)03d - %(module) - %(asctime)*.3s")
3817 f = logging.Formatter("%(asctime)*s - %(asctime)*.3s - %(process)-34.33o")
3818 self.assertEqual(f._fmt, "%(asctime)*s - %(asctime)*.3s - %(process)-34.33o")
3819 f = logging.Formatter("%(process)#+027.23X")
3820 self.assertEqual(f._fmt, "%(process)#+027.23X")
3821 f = logging.Formatter("%(foo)#.*g")
3822 self.assertEqual(f._fmt, "%(foo)#.*g")
3823
3824 # StrFormat Style
3825 f = logging.Formatter("$%{message}%$ - {asctime!a:15} - {customfield['key']}", style="{")
3826 self.assertEqual(f._fmt, "$%{message}%$ - {asctime!a:15} - {customfield['key']}")
3827 f = logging.Formatter("{process:.2f} - {custom.f:.4f}", style="{")
3828 self.assertEqual(f._fmt, "{process:.2f} - {custom.f:.4f}")
3829 f = logging.Formatter("{customfield!s:#<30}", style="{")
3830 self.assertEqual(f._fmt, "{customfield!s:#<30}")
3831 f = logging.Formatter("{message!r}", style="{")
3832 self.assertEqual(f._fmt, "{message!r}")
3833 f = logging.Formatter("{message!s}", style="{")
3834 self.assertEqual(f._fmt, "{message!s}")
3835 f = logging.Formatter("{message!a}", style="{")
3836 self.assertEqual(f._fmt, "{message!a}")
3837 f = logging.Formatter("{process!r:4.2}", style="{")
3838 self.assertEqual(f._fmt, "{process!r:4.2}")
3839 f = logging.Formatter("{process!s:<#30,.12f}- {custom:=+#30,.1d} - {module:^30}", style="{")
3840 self.assertEqual(f._fmt, "{process!s:<#30,.12f}- {custom:=+#30,.1d} - {module:^30}")
3841 f = logging.Formatter("{process!s:{w},.{p}}", style="{")
3842 self.assertEqual(f._fmt, "{process!s:{w},.{p}}")
3843 f = logging.Formatter("{foo:12.{p}}", style="{")
3844 self.assertEqual(f._fmt, "{foo:12.{p}}")
3845 f = logging.Formatter("{foo:{w}.6}", style="{")
3846 self.assertEqual(f._fmt, "{foo:{w}.6}")
3847 f = logging.Formatter("{foo[0].bar[1].baz}", style="{")
3848 self.assertEqual(f._fmt, "{foo[0].bar[1].baz}")
3849 f = logging.Formatter("{foo[k1].bar[k2].baz}", style="{")
3850 self.assertEqual(f._fmt, "{foo[k1].bar[k2].baz}")
3851 f = logging.Formatter("{12[k1].bar[k2].baz}", style="{")
3852 self.assertEqual(f._fmt, "{12[k1].bar[k2].baz}")
3853
3854 # Dollar style
3855 f = logging.Formatter("${asctime} - $message", style="$")
3856 self.assertEqual(f._fmt, "${asctime} - $message")
3857 f = logging.Formatter("$bar $$", style="$")
3858 self.assertEqual(f._fmt, "$bar $$")
3859 f = logging.Formatter("$bar $$$$", style="$")
3860 self.assertEqual(f._fmt, "$bar $$$$") # this would print two $($$)
3861
3862 # Testing when ValueError being raised from incorrect format
3863 # Percentage Style
3864 self.assertRaises(ValueError, logging.Formatter, "%(asctime)Z")
3865 self.assertRaises(ValueError, logging.Formatter, "%(asctime)b")
3866 self.assertRaises(ValueError, logging.Formatter, "%(asctime)*")
3867 self.assertRaises(ValueError, logging.Formatter, "%(asctime)*3s")
3868 self.assertRaises(ValueError, logging.Formatter, "%(asctime)_")
3869 self.assertRaises(ValueError, logging.Formatter, '{asctime}')
3870 self.assertRaises(ValueError, logging.Formatter, '${message}')
3871 self.assertRaises(ValueError, logging.Formatter, '%(foo)#12.3*f') # with both * and decimal number as precision
3872 self.assertRaises(ValueError, logging.Formatter, '%(foo)0*.8*f')
3873
3874 # StrFormat Style
3875 # Testing failure for '-' in field name
3876 self.assert_error_message(
3877 ValueError,
Eric Larson9fdb76c2020-09-25 14:08:50 -04003878 "invalid format: invalid field name/expression: 'name-thing'",
BNMetrics18fb1fb2018-10-15 19:41:36 +01003879 logging.Formatter, "{name-thing}", style="{"
3880 )
3881 # Testing failure for style mismatch
3882 self.assert_error_message(
3883 ValueError,
3884 "invalid format: no fields",
3885 logging.Formatter, '%(asctime)s', style='{'
3886 )
3887 # Testing failure for invalid conversion
3888 self.assert_error_message(
3889 ValueError,
3890 "invalid conversion: 'Z'"
3891 )
3892 self.assertRaises(ValueError, logging.Formatter, '{asctime!s:#30,15f}', style='{')
3893 self.assert_error_message(
3894 ValueError,
3895 "invalid format: expected ':' after conversion specifier",
3896 logging.Formatter, '{asctime!aa:15}', style='{'
3897 )
3898 # Testing failure for invalid spec
3899 self.assert_error_message(
3900 ValueError,
Eric Larson9fdb76c2020-09-25 14:08:50 -04003901 "invalid format: bad specifier: '.2ff'",
BNMetrics18fb1fb2018-10-15 19:41:36 +01003902 logging.Formatter, '{process:.2ff}', style='{'
3903 )
3904 self.assertRaises(ValueError, logging.Formatter, '{process:.2Z}', style='{')
3905 self.assertRaises(ValueError, logging.Formatter, '{process!s:<##30,12g}', style='{')
3906 self.assertRaises(ValueError, logging.Formatter, '{process!s:<#30#,12g}', style='{')
3907 self.assertRaises(ValueError, logging.Formatter, '{process!s:{{w}},{{p}}}', style='{')
3908 # Testing failure for mismatch braces
3909 self.assert_error_message(
3910 ValueError,
Eric Larson9fdb76c2020-09-25 14:08:50 -04003911 "invalid format: expected '}' before end of string",
BNMetrics18fb1fb2018-10-15 19:41:36 +01003912 logging.Formatter, '{process', style='{'
3913 )
3914 self.assert_error_message(
3915 ValueError,
Eric Larson9fdb76c2020-09-25 14:08:50 -04003916 "invalid format: Single '}' encountered in format string",
BNMetrics18fb1fb2018-10-15 19:41:36 +01003917 logging.Formatter, 'process}', style='{'
3918 )
3919 self.assertRaises(ValueError, logging.Formatter, '{{foo!r:4.2}', style='{')
3920 self.assertRaises(ValueError, logging.Formatter, '{{foo!r:4.2}}', style='{')
3921 self.assertRaises(ValueError, logging.Formatter, '{foo/bar}', style='{')
3922 self.assertRaises(ValueError, logging.Formatter, '{foo:{{w}}.{{p}}}}', style='{')
3923 self.assertRaises(ValueError, logging.Formatter, '{foo!X:{{w}}.{{p}}}', style='{')
3924 self.assertRaises(ValueError, logging.Formatter, '{foo!a:random}', style='{')
3925 self.assertRaises(ValueError, logging.Formatter, '{foo!a:ran{dom}', style='{')
3926 self.assertRaises(ValueError, logging.Formatter, '{foo!a:ran{d}om}', style='{')
3927 self.assertRaises(ValueError, logging.Formatter, '{foo.!a:d}', style='{')
3928
3929 # Dollar style
3930 # Testing failure for mismatch bare $
3931 self.assert_error_message(
3932 ValueError,
3933 "invalid format: bare \'$\' not allowed",
3934 logging.Formatter, '$bar $$$', style='$'
3935 )
3936 self.assert_error_message(
3937 ValueError,
3938 "invalid format: bare \'$\' not allowed",
3939 logging.Formatter, 'bar $', style='$'
3940 )
3941 self.assert_error_message(
3942 ValueError,
3943 "invalid format: bare \'$\' not allowed",
3944 logging.Formatter, 'foo $.', style='$'
3945 )
3946 # Testing failure for mismatch style
3947 self.assert_error_message(
3948 ValueError,
3949 "invalid format: no fields",
3950 logging.Formatter, '{asctime}', style='$'
3951 )
3952 self.assertRaises(ValueError, logging.Formatter, '%(asctime)s', style='$')
3953
3954 # Testing failure for incorrect fields
3955 self.assert_error_message(
3956 ValueError,
3957 "invalid format: no fields",
3958 logging.Formatter, 'foo', style='$'
3959 )
3960 self.assertRaises(ValueError, logging.Formatter, '${asctime', style='$')
Vinay Sajipa39c5712010-10-25 13:57:39 +00003961
Bar Harel8f192d12020-06-18 17:18:58 +03003962 def test_defaults_parameter(self):
3963 fmts = ['%(custom)s %(message)s', '{custom} {message}', '$custom $message']
3964 styles = ['%', '{', '$']
3965 for fmt, style in zip(fmts, styles):
3966 f = logging.Formatter(fmt, style=style, defaults={'custom': 'Default'})
3967 r = self.get_record()
3968 self.assertEqual(f.format(r), 'Default Message with 2 placeholders')
3969 r = self.get_record("custom")
3970 self.assertEqual(f.format(r), '1234 Message with 2 placeholders')
3971
3972 # Without default
3973 f = logging.Formatter(fmt, style=style)
3974 r = self.get_record()
3975 self.assertRaises(ValueError, f.format, r)
3976
3977 # Non-existing default is ignored
3978 f = logging.Formatter(fmt, style=style, defaults={'Non-existing': 'Default'})
3979 r = self.get_record("custom")
3980 self.assertEqual(f.format(r), '1234 Message with 2 placeholders')
3981
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003982 def test_invalid_style(self):
3983 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
3984
Vinay Sajip86a96ce2011-04-27 08:30:30 +01003985 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003986 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01003987 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
3988 # We use None to indicate we want the local timezone
3989 # We're essentially converting a UTC time to local time
3990 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003991 r.msecs = 123
3992 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01003993 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003994 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
3995 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01003996 f.format(r)
3997 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
3998
Mariusz Felisiak06a35542020-04-17 18:02:47 +02003999 def test_default_msec_format_none(self):
4000 class NoMsecFormatter(logging.Formatter):
4001 default_msec_format = None
4002 default_time_format = '%d/%m/%Y %H:%M:%S'
4003
4004 r = self.get_record()
4005 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 123, utc)
4006 r.created = time.mktime(dt.astimezone(None).timetuple())
4007 f = NoMsecFormatter()
4008 f.converter = time.gmtime
4009 self.assertEqual(f.formatTime(r), '21/04/1993 08:03:00')
4010
4011
Vinay Sajip985ef872011-04-26 19:34:04 +01004012class TestBufferingFormatter(logging.BufferingFormatter):
4013 def formatHeader(self, records):
4014 return '[(%d)' % len(records)
4015
4016 def formatFooter(self, records):
4017 return '(%d)]' % len(records)
4018
4019class BufferingFormatterTest(unittest.TestCase):
4020 def setUp(self):
4021 self.records = [
4022 logging.makeLogRecord({'msg': 'one'}),
4023 logging.makeLogRecord({'msg': 'two'}),
4024 ]
4025
4026 def test_default(self):
4027 f = logging.BufferingFormatter()
4028 self.assertEqual('', f.format([]))
4029 self.assertEqual('onetwo', f.format(self.records))
4030
4031 def test_custom(self):
4032 f = TestBufferingFormatter()
4033 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
4034 lf = logging.Formatter('<%(message)s>')
4035 f = TestBufferingFormatter(lf)
4036 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004037
4038class ExceptionTest(BaseTest):
4039 def test_formatting(self):
4040 r = self.root_logger
4041 h = RecordingHandler()
4042 r.addHandler(h)
4043 try:
4044 raise RuntimeError('deliberate mistake')
4045 except:
4046 logging.exception('failed', stack_info=True)
4047 r.removeHandler(h)
4048 h.close()
4049 r = h.records[0]
4050 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
4051 'call last):\n'))
4052 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
4053 'deliberate mistake'))
4054 self.assertTrue(r.stack_info.startswith('Stack (most recent '
4055 'call last):\n'))
4056 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
4057 'stack_info=True)'))
4058
4059
Vinay Sajip5a27d402010-12-10 11:42:57 +00004060class LastResortTest(BaseTest):
4061 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00004062 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00004063 root = self.root_logger
4064 root.removeHandler(self.root_hdlr)
Vinay Sajip5a27d402010-12-10 11:42:57 +00004065 old_lastresort = logging.lastResort
4066 old_raise_exceptions = logging.raiseExceptions
Vinay Sajip1feedb42014-05-31 08:19:12 +01004067
Vinay Sajip5a27d402010-12-10 11:42:57 +00004068 try:
Vinay Sajip1feedb42014-05-31 08:19:12 +01004069 with support.captured_stderr() as stderr:
4070 root.debug('This should not appear')
4071 self.assertEqual(stderr.getvalue(), '')
4072 root.warning('Final chance!')
4073 self.assertEqual(stderr.getvalue(), 'Final chance!\n')
4074
4075 # No handlers and no last resort, so 'No handlers' message
Vinay Sajip5a27d402010-12-10 11:42:57 +00004076 logging.lastResort = None
Vinay Sajip1feedb42014-05-31 08:19:12 +01004077 with support.captured_stderr() as stderr:
4078 root.warning('Final chance!')
4079 msg = 'No handlers could be found for logger "root"\n'
4080 self.assertEqual(stderr.getvalue(), msg)
4081
Vinay Sajip5a27d402010-12-10 11:42:57 +00004082 # 'No handlers' message only printed once
Vinay Sajip1feedb42014-05-31 08:19:12 +01004083 with support.captured_stderr() as stderr:
4084 root.warning('Final chance!')
4085 self.assertEqual(stderr.getvalue(), '')
4086
4087 # If raiseExceptions is False, no message is printed
Vinay Sajip5a27d402010-12-10 11:42:57 +00004088 root.manager.emittedNoHandlerWarning = False
Vinay Sajip5a27d402010-12-10 11:42:57 +00004089 logging.raiseExceptions = False
Vinay Sajip1feedb42014-05-31 08:19:12 +01004090 with support.captured_stderr() as stderr:
4091 root.warning('Final chance!')
4092 self.assertEqual(stderr.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00004093 finally:
Vinay Sajip5a27d402010-12-10 11:42:57 +00004094 root.addHandler(self.root_hdlr)
4095 logging.lastResort = old_lastresort
4096 logging.raiseExceptions = old_raise_exceptions
4097
4098
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004099class FakeHandler:
4100
4101 def __init__(self, identifier, called):
4102 for method in ('acquire', 'flush', 'close', 'release'):
4103 setattr(self, method, self.record_call(identifier, method, called))
4104
4105 def record_call(self, identifier, method_name, called):
4106 def inner():
4107 called.append('{} - {}'.format(identifier, method_name))
4108 return inner
4109
4110
4111class RecordingHandler(logging.NullHandler):
4112
4113 def __init__(self, *args, **kwargs):
4114 super(RecordingHandler, self).__init__(*args, **kwargs)
4115 self.records = []
4116
4117 def handle(self, record):
4118 """Keep track of all the emitted records."""
4119 self.records.append(record)
4120
4121
4122class ShutdownTest(BaseTest):
4123
Vinay Sajip5e66b162011-04-20 15:41:14 +01004124 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004125
4126 def setUp(self):
4127 super(ShutdownTest, self).setUp()
4128 self.called = []
4129
4130 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004131 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004132
4133 def raise_error(self, error):
4134 def inner():
4135 raise error()
4136 return inner
4137
4138 def test_no_failure(self):
4139 # create some fake handlers
4140 handler0 = FakeHandler(0, self.called)
4141 handler1 = FakeHandler(1, self.called)
4142 handler2 = FakeHandler(2, self.called)
4143
4144 # create live weakref to those handlers
4145 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
4146
4147 logging.shutdown(handlerList=list(handlers))
4148
4149 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
4150 '1 - acquire', '1 - flush', '1 - close', '1 - release',
4151 '0 - acquire', '0 - flush', '0 - close', '0 - release']
4152 self.assertEqual(expected, self.called)
4153
4154 def _test_with_failure_in_method(self, method, error):
4155 handler = FakeHandler(0, self.called)
4156 setattr(handler, method, self.raise_error(error))
4157 handlers = [logging.weakref.ref(handler)]
4158
4159 logging.shutdown(handlerList=list(handlers))
4160
4161 self.assertEqual('0 - release', self.called[-1])
4162
4163 def test_with_ioerror_in_acquire(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02004164 self._test_with_failure_in_method('acquire', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004165
4166 def test_with_ioerror_in_flush(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02004167 self._test_with_failure_in_method('flush', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004168
4169 def test_with_ioerror_in_close(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02004170 self._test_with_failure_in_method('close', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004171
4172 def test_with_valueerror_in_acquire(self):
4173 self._test_with_failure_in_method('acquire', ValueError)
4174
4175 def test_with_valueerror_in_flush(self):
4176 self._test_with_failure_in_method('flush', ValueError)
4177
4178 def test_with_valueerror_in_close(self):
4179 self._test_with_failure_in_method('close', ValueError)
4180
4181 def test_with_other_error_in_acquire_without_raise(self):
4182 logging.raiseExceptions = False
4183 self._test_with_failure_in_method('acquire', IndexError)
4184
4185 def test_with_other_error_in_flush_without_raise(self):
4186 logging.raiseExceptions = False
4187 self._test_with_failure_in_method('flush', IndexError)
4188
4189 def test_with_other_error_in_close_without_raise(self):
4190 logging.raiseExceptions = False
4191 self._test_with_failure_in_method('close', IndexError)
4192
4193 def test_with_other_error_in_acquire_with_raise(self):
4194 logging.raiseExceptions = True
4195 self.assertRaises(IndexError, self._test_with_failure_in_method,
4196 'acquire', IndexError)
4197
4198 def test_with_other_error_in_flush_with_raise(self):
4199 logging.raiseExceptions = True
4200 self.assertRaises(IndexError, self._test_with_failure_in_method,
4201 'flush', IndexError)
4202
4203 def test_with_other_error_in_close_with_raise(self):
4204 logging.raiseExceptions = True
4205 self.assertRaises(IndexError, self._test_with_failure_in_method,
4206 'close', IndexError)
4207
4208
4209class ModuleLevelMiscTest(BaseTest):
4210
Vinay Sajip5e66b162011-04-20 15:41:14 +01004211 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004212
4213 def test_disable(self):
4214 old_disable = logging.root.manager.disable
4215 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004216 self.assertEqual(old_disable, 0)
4217 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004218
4219 logging.disable(83)
4220 self.assertEqual(logging.root.manager.disable, 83)
4221
Vinay Sajipd489ac92016-12-31 11:40:11 +00004222 # test the default value introduced in 3.7
4223 # (Issue #28524)
4224 logging.disable()
4225 self.assertEqual(logging.root.manager.disable, logging.CRITICAL)
4226
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004227 def _test_log(self, method, level=None):
4228 called = []
Vinay Sajip1feedb42014-05-31 08:19:12 +01004229 support.patch(self, logging, 'basicConfig',
4230 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004231
4232 recording = RecordingHandler()
4233 logging.root.addHandler(recording)
4234
4235 log_method = getattr(logging, method)
4236 if level is not None:
4237 log_method(level, "test me: %r", recording)
4238 else:
4239 log_method("test me: %r", recording)
4240
4241 self.assertEqual(len(recording.records), 1)
4242 record = recording.records[0]
4243 self.assertEqual(record.getMessage(), "test me: %r" % recording)
4244
4245 expected_level = level if level is not None else getattr(logging, method.upper())
4246 self.assertEqual(record.levelno, expected_level)
4247
4248 # basicConfig was not called!
4249 self.assertEqual(called, [])
4250
4251 def test_log(self):
4252 self._test_log('log', logging.ERROR)
4253
4254 def test_debug(self):
4255 self._test_log('debug')
4256
4257 def test_info(self):
4258 self._test_log('info')
4259
4260 def test_warning(self):
4261 self._test_log('warning')
4262
4263 def test_error(self):
4264 self._test_log('error')
4265
4266 def test_critical(self):
4267 self._test_log('critical')
4268
4269 def test_set_logger_class(self):
4270 self.assertRaises(TypeError, logging.setLoggerClass, object)
4271
4272 class MyLogger(logging.Logger):
4273 pass
4274
4275 logging.setLoggerClass(MyLogger)
4276 self.assertEqual(logging.getLoggerClass(), MyLogger)
4277
4278 logging.setLoggerClass(logging.Logger)
4279 self.assertEqual(logging.getLoggerClass(), logging.Logger)
4280
Vinay Sajip01500012019-06-19 11:46:53 +01004281 def test_subclass_logger_cache(self):
4282 # bpo-37258
4283 message = []
4284
4285 class MyLogger(logging.getLoggerClass()):
4286 def __init__(self, name='MyLogger', level=logging.NOTSET):
4287 super().__init__(name, level)
4288 message.append('initialized')
4289
4290 logging.setLoggerClass(MyLogger)
4291 logger = logging.getLogger('just_some_logger')
4292 self.assertEqual(message, ['initialized'])
4293 stream = io.StringIO()
4294 h = logging.StreamHandler(stream)
4295 logger.addHandler(h)
4296 try:
4297 logger.setLevel(logging.DEBUG)
4298 logger.debug("hello")
4299 self.assertEqual(stream.getvalue().strip(), "hello")
4300
4301 stream.truncate(0)
4302 stream.seek(0)
4303
4304 logger.setLevel(logging.INFO)
4305 logger.debug("hello")
4306 self.assertEqual(stream.getvalue(), "")
4307 finally:
4308 logger.removeHandler(h)
4309 h.close()
4310 logging.setLoggerClass(logging.Logger)
4311
Antoine Pitrou712cb732013-12-21 15:51:54 +01004312 def test_logging_at_shutdown(self):
4313 # Issue #20037
4314 code = """if 1:
4315 import logging
4316
4317 class A:
4318 def __del__(self):
4319 try:
4320 raise ValueError("some error")
4321 except Exception:
4322 logging.exception("exception in __del__")
4323
4324 a = A()"""
4325 rc, out, err = assert_python_ok("-c", code)
4326 err = err.decode()
4327 self.assertIn("exception in __del__", err)
4328 self.assertIn("ValueError: some error", err)
4329
Rémi Lapeyre65f64b12019-03-15 07:53:34 +01004330 def test_recursion_error(self):
4331 # Issue 36272
4332 code = """if 1:
4333 import logging
4334
4335 def rec():
4336 logging.error("foo")
4337 rec()
4338
4339 rec()"""
4340 rc, out, err = assert_python_failure("-c", code)
4341 err = err.decode()
4342 self.assertNotIn("Cannot recover from stack overflow.", err)
4343 self.assertEqual(rc, 1)
4344
Antoine Pitrou712cb732013-12-21 15:51:54 +01004345
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004346class LogRecordTest(BaseTest):
4347 def test_str_rep(self):
4348 r = logging.makeLogRecord({})
4349 s = str(r)
4350 self.assertTrue(s.startswith('<LogRecord: '))
4351 self.assertTrue(s.endswith('>'))
4352
4353 def test_dict_arg(self):
4354 h = RecordingHandler()
4355 r = logging.getLogger()
4356 r.addHandler(h)
4357 d = {'less' : 'more' }
4358 logging.warning('less is %(less)s', d)
4359 self.assertIs(h.records[0].args, d)
4360 self.assertEqual(h.records[0].message, 'less is more')
4361 r.removeHandler(h)
4362 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004363
Irit Katriel3fd69992020-09-08 20:40:04 +01004364 @staticmethod # pickled as target of child process in the following test
4365 def _extract_logrecord_process_name(key, logMultiprocessing, conn=None):
4366 prev_logMultiprocessing = logging.logMultiprocessing
4367 logging.logMultiprocessing = logMultiprocessing
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01004368 try:
4369 import multiprocessing as mp
Irit Katriel3fd69992020-09-08 20:40:04 +01004370 name = mp.current_process().name
4371
4372 r1 = logging.makeLogRecord({'msg': f'msg1_{key}'})
4373 del sys.modules['multiprocessing']
4374 r2 = logging.makeLogRecord({'msg': f'msg2_{key}'})
4375
4376 results = {'processName' : name,
4377 'r1.processName': r1.processName,
4378 'r2.processName': r2.processName,
4379 }
4380 finally:
4381 logging.logMultiprocessing = prev_logMultiprocessing
4382 if conn:
4383 conn.send(results)
4384 else:
4385 return results
4386
4387 def test_multiprocessing(self):
4388 multiprocessing_imported = 'multiprocessing' in sys.modules
4389 try:
4390 # logMultiprocessing is True by default
4391 self.assertEqual(logging.logMultiprocessing, True)
4392
4393 LOG_MULTI_PROCESSING = True
4394 # When logMultiprocessing == True:
4395 # In the main process processName = 'MainProcess'
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01004396 r = logging.makeLogRecord({})
Irit Katriel3fd69992020-09-08 20:40:04 +01004397 self.assertEqual(r.processName, 'MainProcess')
4398
4399 results = self._extract_logrecord_process_name(1, LOG_MULTI_PROCESSING)
4400 self.assertEqual('MainProcess', results['processName'])
4401 self.assertEqual('MainProcess', results['r1.processName'])
4402 self.assertEqual('MainProcess', results['r2.processName'])
4403
4404 # In other processes, processName is correct when multiprocessing in imported,
4405 # but it is (incorrectly) defaulted to 'MainProcess' otherwise (bpo-38762).
4406 import multiprocessing
4407 parent_conn, child_conn = multiprocessing.Pipe()
4408 p = multiprocessing.Process(
4409 target=self._extract_logrecord_process_name,
4410 args=(2, LOG_MULTI_PROCESSING, child_conn,)
4411 )
4412 p.start()
4413 results = parent_conn.recv()
4414 self.assertNotEqual('MainProcess', results['processName'])
4415 self.assertEqual(results['processName'], results['r1.processName'])
4416 self.assertEqual('MainProcess', results['r2.processName'])
4417 p.join()
4418
4419 finally:
4420 if multiprocessing_imported:
4421 import multiprocessing
4422
Vinay Sajip7fe1d512011-04-28 12:04:58 +01004423
4424 def test_optional(self):
4425 r = logging.makeLogRecord({})
4426 NOT_NONE = self.assertIsNotNone
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02004427 NOT_NONE(r.thread)
4428 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01004429 NOT_NONE(r.process)
4430 NOT_NONE(r.processName)
4431 log_threads = logging.logThreads
4432 log_processes = logging.logProcesses
4433 log_multiprocessing = logging.logMultiprocessing
4434 try:
4435 logging.logThreads = False
4436 logging.logProcesses = False
4437 logging.logMultiprocessing = False
4438 r = logging.makeLogRecord({})
4439 NONE = self.assertIsNone
4440 NONE(r.thread)
4441 NONE(r.threadName)
4442 NONE(r.process)
4443 NONE(r.processName)
4444 finally:
4445 logging.logThreads = log_threads
4446 logging.logProcesses = log_processes
4447 logging.logMultiprocessing = log_multiprocessing
4448
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004449class BasicConfigTest(unittest.TestCase):
4450
Vinay Sajip95bf5042011-04-20 11:50:56 +01004451 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004452
4453 def setUp(self):
4454 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01004455 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01004456 self.saved_handlers = logging._handlers.copy()
4457 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01004458 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01004459 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004460 logging.root.handlers = []
4461
4462 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01004463 for h in logging.root.handlers[:]:
4464 logging.root.removeHandler(h)
4465 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004466 super(BasicConfigTest, self).tearDown()
4467
Vinay Sajip3def7e02011-04-20 10:58:06 +01004468 def cleanup(self):
4469 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01004470 logging._handlers.clear()
4471 logging._handlers.update(self.saved_handlers)
4472 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1d094af2019-09-22 03:51:51 +01004473 logging.root.setLevel(self.original_logging_level)
Vinay Sajip3def7e02011-04-20 10:58:06 +01004474
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004475 def test_no_kwargs(self):
4476 logging.basicConfig()
4477
4478 # handler defaults to a StreamHandler to sys.stderr
4479 self.assertEqual(len(logging.root.handlers), 1)
4480 handler = logging.root.handlers[0]
4481 self.assertIsInstance(handler, logging.StreamHandler)
4482 self.assertEqual(handler.stream, sys.stderr)
4483
4484 formatter = handler.formatter
4485 # format defaults to logging.BASIC_FORMAT
4486 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
4487 # datefmt defaults to None
4488 self.assertIsNone(formatter.datefmt)
4489 # style defaults to %
4490 self.assertIsInstance(formatter._style, logging.PercentStyle)
4491
Florent Xiclunae41f0de2011-11-11 19:39:25 +01004492 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01004493 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004494
Vinay Sajip1fd12022014-01-13 21:59:56 +00004495 def test_strformatstyle(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01004496 with support.captured_stdout() as output:
Vinay Sajip1fd12022014-01-13 21:59:56 +00004497 logging.basicConfig(stream=sys.stdout, style="{")
4498 logging.error("Log an error")
4499 sys.stdout.seek(0)
4500 self.assertEqual(output.getvalue().strip(),
4501 "ERROR:root:Log an error")
4502
4503 def test_stringtemplatestyle(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01004504 with support.captured_stdout() as output:
Vinay Sajip1fd12022014-01-13 21:59:56 +00004505 logging.basicConfig(stream=sys.stdout, style="$")
4506 logging.error("Log an error")
4507 sys.stdout.seek(0)
4508 self.assertEqual(output.getvalue().strip(),
4509 "ERROR:root:Log an error")
4510
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004511 def test_filename(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004512
4513 def cleanup(h1, h2, fn):
4514 h1.close()
4515 h2.close()
4516 os.remove(fn)
4517
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004518 logging.basicConfig(filename='test.log')
4519
4520 self.assertEqual(len(logging.root.handlers), 1)
4521 handler = logging.root.handlers[0]
4522 self.assertIsInstance(handler, logging.FileHandler)
4523
4524 expected = logging.FileHandler('test.log', 'a')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004525 self.assertEqual(handler.stream.mode, expected.stream.mode)
4526 self.assertEqual(handler.stream.name, expected.stream.name)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004527 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004528
4529 def test_filemode(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004530
4531 def cleanup(h1, h2, fn):
4532 h1.close()
4533 h2.close()
4534 os.remove(fn)
4535
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004536 logging.basicConfig(filename='test.log', filemode='wb')
4537
4538 handler = logging.root.handlers[0]
4539 expected = logging.FileHandler('test.log', 'wb')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004540 self.assertEqual(handler.stream.mode, expected.stream.mode)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004541 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004542
4543 def test_stream(self):
4544 stream = io.StringIO()
4545 self.addCleanup(stream.close)
4546 logging.basicConfig(stream=stream)
4547
4548 self.assertEqual(len(logging.root.handlers), 1)
4549 handler = logging.root.handlers[0]
4550 self.assertIsInstance(handler, logging.StreamHandler)
4551 self.assertEqual(handler.stream, stream)
4552
4553 def test_format(self):
BNMetrics18fb1fb2018-10-15 19:41:36 +01004554 logging.basicConfig(format='%(asctime)s - %(message)s')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004555
4556 formatter = logging.root.handlers[0].formatter
BNMetrics18fb1fb2018-10-15 19:41:36 +01004557 self.assertEqual(formatter._style._fmt, '%(asctime)s - %(message)s')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004558
4559 def test_datefmt(self):
4560 logging.basicConfig(datefmt='bar')
4561
4562 formatter = logging.root.handlers[0].formatter
4563 self.assertEqual(formatter.datefmt, 'bar')
4564
4565 def test_style(self):
4566 logging.basicConfig(style='$')
4567
4568 formatter = logging.root.handlers[0].formatter
4569 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
4570
4571 def test_level(self):
4572 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004573 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004574
4575 logging.basicConfig(level=57)
4576 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004577 # Test that second call has no effect
4578 logging.basicConfig(level=58)
4579 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004580
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004581 def test_incompatible(self):
4582 assertRaises = self.assertRaises
4583 handlers = [logging.StreamHandler()]
4584 stream = sys.stderr
4585 assertRaises(ValueError, logging.basicConfig, filename='test.log',
BNMetrics18fb1fb2018-10-15 19:41:36 +01004586 stream=stream)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004587 assertRaises(ValueError, logging.basicConfig, filename='test.log',
BNMetrics18fb1fb2018-10-15 19:41:36 +01004588 handlers=handlers)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004589 assertRaises(ValueError, logging.basicConfig, stream=stream,
BNMetrics18fb1fb2018-10-15 19:41:36 +01004590 handlers=handlers)
Vinay Sajipd55436a2015-03-18 08:47:58 +00004591 # Issue 23207: test for invalid kwargs
4592 assertRaises(ValueError, logging.basicConfig, loglevel=logging.INFO)
4593 # Should pop both filename and filemode even if filename is None
4594 logging.basicConfig(filename=None, filemode='a')
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004595
4596 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004597 handlers = [
4598 logging.StreamHandler(),
4599 logging.StreamHandler(sys.stdout),
4600 logging.StreamHandler(),
4601 ]
4602 f = logging.Formatter()
4603 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004604 logging.basicConfig(handlers=handlers)
4605 self.assertIs(handlers[0], logging.root.handlers[0])
4606 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004607 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004608 self.assertIsNotNone(handlers[0].formatter)
4609 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004610 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004611 self.assertIs(handlers[0].formatter, handlers[1].formatter)
4612
Dong-hee Nacf67d6a2018-06-25 13:11:09 +09004613 def test_force(self):
4614 old_string_io = io.StringIO()
4615 new_string_io = io.StringIO()
4616 old_handlers = [logging.StreamHandler(old_string_io)]
4617 new_handlers = [logging.StreamHandler(new_string_io)]
4618 logging.basicConfig(level=logging.WARNING, handlers=old_handlers)
4619 logging.warning('warn')
4620 logging.info('info')
4621 logging.debug('debug')
4622 self.assertEqual(len(logging.root.handlers), 1)
4623 logging.basicConfig(level=logging.INFO, handlers=new_handlers,
4624 force=True)
4625 logging.warning('warn')
4626 logging.info('info')
4627 logging.debug('debug')
4628 self.assertEqual(len(logging.root.handlers), 1)
4629 self.assertEqual(old_string_io.getvalue().strip(),
4630 'WARNING:root:warn')
4631 self.assertEqual(new_string_io.getvalue().strip(),
4632 'WARNING:root:warn\nINFO:root:info')
4633
Vinay Sajipca7b5042019-06-17 17:40:52 +01004634 def test_encoding(self):
4635 try:
4636 encoding = 'utf-8'
4637 logging.basicConfig(filename='test.log', encoding=encoding,
4638 errors='strict',
4639 format='%(message)s', level=logging.DEBUG)
4640
4641 self.assertEqual(len(logging.root.handlers), 1)
4642 handler = logging.root.handlers[0]
4643 self.assertIsInstance(handler, logging.FileHandler)
4644 self.assertEqual(handler.encoding, encoding)
4645 logging.debug('The Øresund Bridge joins Copenhagen to Malmö')
4646 finally:
4647 handler.close()
4648 with open('test.log', encoding='utf-8') as f:
4649 data = f.read().strip()
4650 os.remove('test.log')
4651 self.assertEqual(data,
4652 'The Øresund Bridge joins Copenhagen to Malmö')
4653
4654 def test_encoding_errors(self):
4655 try:
4656 encoding = 'ascii'
4657 logging.basicConfig(filename='test.log', encoding=encoding,
4658 errors='ignore',
4659 format='%(message)s', level=logging.DEBUG)
4660
4661 self.assertEqual(len(logging.root.handlers), 1)
4662 handler = logging.root.handlers[0]
4663 self.assertIsInstance(handler, logging.FileHandler)
4664 self.assertEqual(handler.encoding, encoding)
4665 logging.debug('The Øresund Bridge joins Copenhagen to Malmö')
4666 finally:
4667 handler.close()
4668 with open('test.log', encoding='utf-8') as f:
4669 data = f.read().strip()
4670 os.remove('test.log')
4671 self.assertEqual(data, 'The resund Bridge joins Copenhagen to Malm')
4672
4673 def test_encoding_errors_default(self):
4674 try:
4675 encoding = 'ascii'
4676 logging.basicConfig(filename='test.log', encoding=encoding,
4677 format='%(message)s', level=logging.DEBUG)
4678
4679 self.assertEqual(len(logging.root.handlers), 1)
4680 handler = logging.root.handlers[0]
4681 self.assertIsInstance(handler, logging.FileHandler)
4682 self.assertEqual(handler.encoding, encoding)
4683 self.assertEqual(handler.errors, 'backslashreplace')
4684 logging.debug('😂: ☃️: The Øresund Bridge joins Copenhagen to Malmö')
4685 finally:
4686 handler.close()
4687 with open('test.log', encoding='utf-8') as f:
4688 data = f.read().strip()
4689 os.remove('test.log')
4690 self.assertEqual(data, r'\U0001f602: \u2603\ufe0f: The \xd8resund '
4691 r'Bridge joins Copenhagen to Malm\xf6')
4692
4693 def test_encoding_errors_none(self):
4694 # Specifying None should behave as 'strict'
4695 try:
4696 encoding = 'ascii'
4697 logging.basicConfig(filename='test.log', encoding=encoding,
4698 errors=None,
4699 format='%(message)s', level=logging.DEBUG)
4700
4701 self.assertEqual(len(logging.root.handlers), 1)
4702 handler = logging.root.handlers[0]
4703 self.assertIsInstance(handler, logging.FileHandler)
4704 self.assertEqual(handler.encoding, encoding)
4705 self.assertIsNone(handler.errors)
4706
4707 message = []
4708
4709 def dummy_handle_error(record):
4710 _, v, _ = sys.exc_info()
4711 message.append(str(v))
4712
4713 handler.handleError = dummy_handle_error
4714 logging.debug('The Øresund Bridge joins Copenhagen to Malmö')
4715 self.assertTrue(message)
4716 self.assertIn("'ascii' codec can't encode "
4717 "character '\\xd8' in position 4:", message[0])
4718 finally:
4719 handler.close()
4720 with open('test.log', encoding='utf-8') as f:
4721 data = f.read().strip()
4722 os.remove('test.log')
4723 # didn't write anything due to the encoding error
4724 self.assertEqual(data, r'')
4725
4726
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004727 def _test_log(self, method, level=None):
4728 # logging.root has no handlers so basicConfig should be called
4729 called = []
4730
4731 old_basic_config = logging.basicConfig
4732 def my_basic_config(*a, **kw):
4733 old_basic_config()
4734 old_level = logging.root.level
4735 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004736 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004737 called.append((a, kw))
4738
Vinay Sajip1feedb42014-05-31 08:19:12 +01004739 support.patch(self, logging, 'basicConfig', my_basic_config)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004740
4741 log_method = getattr(logging, method)
4742 if level is not None:
4743 log_method(level, "test me")
4744 else:
4745 log_method("test me")
4746
4747 # basicConfig was called with no arguments
4748 self.assertEqual(called, [((), {})])
4749
4750 def test_log(self):
4751 self._test_log('log', logging.WARNING)
4752
4753 def test_debug(self):
4754 self._test_log('debug')
4755
4756 def test_info(self):
4757 self._test_log('info')
4758
4759 def test_warning(self):
4760 self._test_log('warning')
4761
4762 def test_error(self):
4763 self._test_log('error')
4764
4765 def test_critical(self):
4766 self._test_log('critical')
4767
4768
4769class LoggerAdapterTest(unittest.TestCase):
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004770 def setUp(self):
4771 super(LoggerAdapterTest, self).setUp()
4772 old_handler_list = logging._handlerList[:]
4773
4774 self.recording = RecordingHandler()
4775 self.logger = logging.root
4776 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004777 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004778 self.addCleanup(self.recording.close)
4779
4780 def cleanup():
4781 logging._handlerList[:] = old_handler_list
4782
4783 self.addCleanup(cleanup)
4784 self.addCleanup(logging.shutdown)
4785 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
4786
4787 def test_exception(self):
4788 msg = 'testing exception: %r'
4789 exc = None
4790 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004791 1 / 0
4792 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004793 exc = e
4794 self.adapter.exception(msg, self.recording)
4795
4796 self.assertEqual(len(self.recording.records), 1)
4797 record = self.recording.records[0]
4798 self.assertEqual(record.levelno, logging.ERROR)
4799 self.assertEqual(record.msg, msg)
4800 self.assertEqual(record.args, (self.recording,))
4801 self.assertEqual(record.exc_info,
4802 (exc.__class__, exc, exc.__traceback__))
4803
Vinay Sajip02a8f9e2014-09-14 21:29:11 +01004804 def test_exception_excinfo(self):
4805 try:
4806 1 / 0
4807 except ZeroDivisionError as e:
4808 exc = e
4809
4810 self.adapter.exception('exc_info test', exc_info=exc)
4811
4812 self.assertEqual(len(self.recording.records), 1)
4813 record = self.recording.records[0]
4814 self.assertEqual(record.exc_info,
4815 (exc.__class__, exc, exc.__traceback__))
4816
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004817 def test_critical(self):
4818 msg = 'critical test! %r'
4819 self.adapter.critical(msg, self.recording)
4820
4821 self.assertEqual(len(self.recording.records), 1)
4822 record = self.recording.records[0]
4823 self.assertEqual(record.levelno, logging.CRITICAL)
4824 self.assertEqual(record.msg, msg)
4825 self.assertEqual(record.args, (self.recording,))
4826
4827 def test_is_enabled_for(self):
4828 old_disable = self.adapter.logger.manager.disable
4829 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004830 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
4831 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004832 self.assertFalse(self.adapter.isEnabledFor(32))
4833
4834 def test_has_handlers(self):
4835 self.assertTrue(self.adapter.hasHandlers())
4836
4837 for handler in self.logger.handlers:
4838 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004839
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004840 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004841 self.assertFalse(self.adapter.hasHandlers())
4842
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004843 def test_nested(self):
Łukasz Langace9e6252017-10-19 10:24:55 -07004844 class Adapter(logging.LoggerAdapter):
4845 prefix = 'Adapter'
4846
4847 def process(self, msg, kwargs):
4848 return f"{self.prefix} {msg}", kwargs
4849
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004850 msg = 'Adapters can be nested, yo.'
Łukasz Langace9e6252017-10-19 10:24:55 -07004851 adapter = Adapter(logger=self.logger, extra=None)
4852 adapter_adapter = Adapter(logger=adapter, extra=None)
4853 adapter_adapter.prefix = 'AdapterAdapter'
4854 self.assertEqual(repr(adapter), repr(adapter_adapter))
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004855 adapter_adapter.log(logging.CRITICAL, msg, self.recording)
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004856 self.assertEqual(len(self.recording.records), 1)
4857 record = self.recording.records[0]
4858 self.assertEqual(record.levelno, logging.CRITICAL)
Łukasz Langace9e6252017-10-19 10:24:55 -07004859 self.assertEqual(record.msg, f"Adapter AdapterAdapter {msg}")
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004860 self.assertEqual(record.args, (self.recording,))
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004861 orig_manager = adapter_adapter.manager
Łukasz Langace9e6252017-10-19 10:24:55 -07004862 self.assertIs(adapter.manager, orig_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004863 self.assertIs(self.logger.manager, orig_manager)
4864 temp_manager = object()
4865 try:
4866 adapter_adapter.manager = temp_manager
4867 self.assertIs(adapter_adapter.manager, temp_manager)
Łukasz Langace9e6252017-10-19 10:24:55 -07004868 self.assertIs(adapter.manager, temp_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004869 self.assertIs(self.logger.manager, temp_manager)
4870 finally:
4871 adapter_adapter.manager = orig_manager
4872 self.assertIs(adapter_adapter.manager, orig_manager)
Łukasz Langace9e6252017-10-19 10:24:55 -07004873 self.assertIs(adapter.manager, orig_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004874 self.assertIs(self.logger.manager, orig_manager)
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004875
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004876
Eric Larson9fdb76c2020-09-25 14:08:50 -04004877class LoggerTest(BaseTest, AssertErrorMessage):
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004878
4879 def setUp(self):
4880 super(LoggerTest, self).setUp()
4881 self.recording = RecordingHandler()
4882 self.logger = logging.Logger(name='blah')
4883 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004884 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004885 self.addCleanup(self.recording.close)
4886 self.addCleanup(logging.shutdown)
4887
4888 def test_set_invalid_level(self):
Eric Larson9fdb76c2020-09-25 14:08:50 -04004889 self.assert_error_message(
4890 TypeError, 'Level not an integer or a valid string: None',
4891 self.logger.setLevel, None)
4892 self.assert_error_message(
4893 TypeError, 'Level not an integer or a valid string: (0, 0)',
4894 self.logger.setLevel, (0, 0))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004895
4896 def test_exception(self):
4897 msg = 'testing exception: %r'
4898 exc = None
4899 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004900 1 / 0
4901 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004902 exc = e
4903 self.logger.exception(msg, self.recording)
4904
4905 self.assertEqual(len(self.recording.records), 1)
4906 record = self.recording.records[0]
4907 self.assertEqual(record.levelno, logging.ERROR)
4908 self.assertEqual(record.msg, msg)
4909 self.assertEqual(record.args, (self.recording,))
4910 self.assertEqual(record.exc_info,
4911 (exc.__class__, exc, exc.__traceback__))
4912
4913 def test_log_invalid_level_with_raise(self):
Serhiy Storchaka296b3472015-07-21 22:40:18 +03004914 with support.swap_attr(logging, 'raiseExceptions', True):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03004915 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004916
4917 def test_log_invalid_level_no_raise(self):
Serhiy Storchaka296b3472015-07-21 22:40:18 +03004918 with support.swap_attr(logging, 'raiseExceptions', False):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03004919 self.logger.log('10', 'test message') # no exception happens
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004920
4921 def test_find_caller_with_stack_info(self):
4922 called = []
Vinay Sajip1feedb42014-05-31 08:19:12 +01004923 support.patch(self, logging.traceback, 'print_stack',
4924 lambda f, file: called.append(file.getvalue()))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004925
4926 self.logger.findCaller(stack_info=True)
4927
4928 self.assertEqual(len(called), 1)
4929 self.assertEqual('Stack (most recent call last):\n', called[0])
4930
Vinay Sajipdde9fdb2018-06-05 17:24:18 +01004931 def test_find_caller_with_stacklevel(self):
4932 the_level = 1
4933
4934 def innermost():
4935 self.logger.warning('test', stacklevel=the_level)
4936
4937 def inner():
4938 innermost()
4939
4940 def outer():
4941 inner()
4942
4943 records = self.recording.records
4944 outer()
4945 self.assertEqual(records[-1].funcName, 'innermost')
4946 lineno = records[-1].lineno
4947 the_level += 1
4948 outer()
4949 self.assertEqual(records[-1].funcName, 'inner')
4950 self.assertGreater(records[-1].lineno, lineno)
4951 lineno = records[-1].lineno
4952 the_level += 1
4953 outer()
4954 self.assertEqual(records[-1].funcName, 'outer')
4955 self.assertGreater(records[-1].lineno, lineno)
4956 lineno = records[-1].lineno
4957 the_level += 1
4958 outer()
4959 self.assertEqual(records[-1].funcName, 'test_find_caller_with_stacklevel')
4960 self.assertGreater(records[-1].lineno, lineno)
4961
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004962 def test_make_record_with_extra_overwrite(self):
4963 name = 'my record'
4964 level = 13
4965 fn = lno = msg = args = exc_info = func = sinfo = None
4966 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
4967 exc_info, func, sinfo)
4968
4969 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
4970 extra = {key: 'some value'}
4971 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
4972 fn, lno, msg, args, exc_info,
4973 extra=extra, sinfo=sinfo)
4974
4975 def test_make_record_with_extra_no_overwrite(self):
4976 name = 'my record'
4977 level = 13
4978 fn = lno = msg = args = exc_info = func = sinfo = None
4979 extra = {'valid_key': 'some value'}
4980 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
4981 exc_info, extra=extra, sinfo=sinfo)
4982 self.assertIn('valid_key', result.__dict__)
4983
4984 def test_has_handlers(self):
4985 self.assertTrue(self.logger.hasHandlers())
4986
4987 for handler in self.logger.handlers:
4988 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004989 self.assertFalse(self.logger.hasHandlers())
4990
4991 def test_has_handlers_no_propagate(self):
4992 child_logger = logging.getLogger('blah.child')
4993 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004994 self.assertFalse(child_logger.hasHandlers())
4995
4996 def test_is_enabled_for(self):
4997 old_disable = self.logger.manager.disable
4998 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004999 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01005000 self.assertFalse(self.logger.isEnabledFor(22))
5001
Timo Furrer6e3ca642018-06-01 09:29:46 +02005002 def test_is_enabled_for_disabled_logger(self):
5003 old_disabled = self.logger.disabled
5004 old_disable = self.logger.manager.disable
5005
5006 self.logger.disabled = True
5007 self.logger.manager.disable = 21
5008
5009 self.addCleanup(setattr, self.logger, 'disabled', old_disabled)
5010 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
5011
5012 self.assertFalse(self.logger.isEnabledFor(22))
5013
Florent Xicluna5252f9f2011-11-07 19:43:05 +01005014 def test_root_logger_aliases(self):
5015 root = logging.getLogger()
5016 self.assertIs(root, logging.root)
5017 self.assertIs(root, logging.getLogger(None))
5018 self.assertIs(root, logging.getLogger(''))
Vinay Sajipcb65b3a2019-08-02 16:53:00 +01005019 self.assertIs(root, logging.getLogger('root'))
Florent Xicluna5252f9f2011-11-07 19:43:05 +01005020 self.assertIs(root, logging.getLogger('foo').root)
5021 self.assertIs(root, logging.getLogger('foo.bar').root)
5022 self.assertIs(root, logging.getLogger('foo').parent)
5023
5024 self.assertIsNot(root, logging.getLogger('\0'))
5025 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
5026
5027 def test_invalid_names(self):
5028 self.assertRaises(TypeError, logging.getLogger, any)
5029 self.assertRaises(TypeError, logging.getLogger, b'foo')
5030
Vinay Sajip6260d9f2017-06-06 16:34:29 +01005031 def test_pickling(self):
5032 for proto in range(pickle.HIGHEST_PROTOCOL + 1):
5033 for name in ('', 'root', 'foo', 'foo.bar', 'baz.bar'):
5034 logger = logging.getLogger(name)
5035 s = pickle.dumps(logger, proto)
5036 unpickled = pickle.loads(s)
5037 self.assertIs(unpickled, logger)
5038
Avram Lubkin78c18a92017-07-30 05:36:33 -04005039 def test_caching(self):
5040 root = self.root_logger
5041 logger1 = logging.getLogger("abc")
5042 logger2 = logging.getLogger("abc.def")
5043
5044 # Set root logger level and ensure cache is empty
5045 root.setLevel(logging.ERROR)
5046 self.assertEqual(logger2.getEffectiveLevel(), logging.ERROR)
5047 self.assertEqual(logger2._cache, {})
5048
5049 # Ensure cache is populated and calls are consistent
5050 self.assertTrue(logger2.isEnabledFor(logging.ERROR))
5051 self.assertFalse(logger2.isEnabledFor(logging.DEBUG))
5052 self.assertEqual(logger2._cache, {logging.ERROR: True, logging.DEBUG: False})
5053 self.assertEqual(root._cache, {})
5054 self.assertTrue(logger2.isEnabledFor(logging.ERROR))
5055
5056 # Ensure root cache gets populated
5057 self.assertEqual(root._cache, {})
5058 self.assertTrue(root.isEnabledFor(logging.ERROR))
5059 self.assertEqual(root._cache, {logging.ERROR: True})
5060
5061 # Set parent logger level and ensure caches are emptied
5062 logger1.setLevel(logging.CRITICAL)
5063 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
5064 self.assertEqual(logger2._cache, {})
5065
5066 # Ensure logger2 uses parent logger's effective level
5067 self.assertFalse(logger2.isEnabledFor(logging.ERROR))
5068
5069 # Set level to NOTSET and ensure caches are empty
5070 logger2.setLevel(logging.NOTSET)
5071 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
5072 self.assertEqual(logger2._cache, {})
5073 self.assertEqual(logger1._cache, {})
5074 self.assertEqual(root._cache, {})
5075
5076 # Verify logger2 follows parent and not root
5077 self.assertFalse(logger2.isEnabledFor(logging.ERROR))
5078 self.assertTrue(logger2.isEnabledFor(logging.CRITICAL))
5079 self.assertFalse(logger1.isEnabledFor(logging.ERROR))
5080 self.assertTrue(logger1.isEnabledFor(logging.CRITICAL))
5081 self.assertTrue(root.isEnabledFor(logging.ERROR))
5082
5083 # Disable logging in manager and ensure caches are clear
5084 logging.disable()
5085 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
5086 self.assertEqual(logger2._cache, {})
5087 self.assertEqual(logger1._cache, {})
5088 self.assertEqual(root._cache, {})
5089
5090 # Ensure no loggers are enabled
5091 self.assertFalse(logger1.isEnabledFor(logging.CRITICAL))
5092 self.assertFalse(logger2.isEnabledFor(logging.CRITICAL))
5093 self.assertFalse(root.isEnabledFor(logging.CRITICAL))
5094
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01005095
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005096class BaseFileTest(BaseTest):
5097 "Base class for handler tests that write log files"
5098
5099 def setUp(self):
5100 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00005101 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
5102 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005103 self.rmfiles = []
5104
5105 def tearDown(self):
5106 for fn in self.rmfiles:
5107 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00005108 if os.path.exists(self.fn):
5109 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00005110 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005111
5112 def assertLogFile(self, filename):
5113 "Assert a log file is there and register it for deletion"
5114 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01005115 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005116 self.rmfiles.append(filename)
5117
5118
Vinay Sajip26fe4b72011-04-26 18:43:05 +01005119class FileHandlerTest(BaseFileTest):
5120 def test_delay(self):
5121 os.unlink(self.fn)
5122 fh = logging.FileHandler(self.fn, delay=True)
5123 self.assertIsNone(fh.stream)
5124 self.assertFalse(os.path.exists(self.fn))
5125 fh.handle(logging.makeLogRecord({}))
5126 self.assertIsNotNone(fh.stream)
5127 self.assertTrue(os.path.exists(self.fn))
5128 fh.close()
5129
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005130class RotatingFileHandlerTest(BaseFileTest):
5131 def next_rec(self):
5132 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
5133 self.next_message(), None, None, None)
5134
5135 def test_should_not_rollover(self):
5136 # If maxbytes is zero rollover never occurs
5137 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
5138 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00005139 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005140
5141 def test_should_rollover(self):
5142 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
5143 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00005144 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005145
5146 def test_file_created(self):
5147 # checks that the file is created and assumes it was created
5148 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005149 rh = logging.handlers.RotatingFileHandler(self.fn)
5150 rh.emit(self.next_rec())
5151 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00005152 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005153
5154 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00005155 def namer(name):
5156 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005157 rh = logging.handlers.RotatingFileHandler(
5158 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005159 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005160 rh.emit(self.next_rec())
5161 self.assertLogFile(self.fn)
5162 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00005163 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005164 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00005165 self.assertLogFile(namer(self.fn + ".2"))
5166 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
5167 rh.close()
5168
l0rb519cb872019-11-06 22:21:40 +01005169 def test_namer_rotator_inheritance(self):
5170 class HandlerWithNamerAndRotator(logging.handlers.RotatingFileHandler):
5171 def namer(self, name):
5172 return name + ".test"
5173
5174 def rotator(self, source, dest):
5175 if os.path.exists(source):
5176 os.rename(source, dest + ".rotated")
5177
5178 rh = HandlerWithNamerAndRotator(
5179 self.fn, backupCount=2, maxBytes=1)
5180 self.assertEqual(rh.namer(self.fn), self.fn + ".test")
5181 rh.emit(self.next_rec())
5182 self.assertLogFile(self.fn)
5183 rh.emit(self.next_rec())
5184 self.assertLogFile(rh.namer(self.fn + ".1") + ".rotated")
5185 self.assertFalse(os.path.exists(rh.namer(self.fn + ".1")))
5186 rh.close()
5187
Hai Shia3ec3ad2020-05-19 06:02:57 +08005188 @support.requires_zlib()
Vinay Sajip23b94d02012-01-04 12:02:26 +00005189 def test_rotator(self):
5190 def namer(name):
5191 return name + ".gz"
5192
5193 def rotator(source, dest):
5194 with open(source, "rb") as sf:
5195 data = sf.read()
5196 compressed = zlib.compress(data, 9)
5197 with open(dest, "wb") as df:
5198 df.write(compressed)
5199 os.remove(source)
5200
5201 rh = logging.handlers.RotatingFileHandler(
5202 self.fn, backupCount=2, maxBytes=1)
5203 rh.rotator = rotator
5204 rh.namer = namer
5205 m1 = self.next_rec()
5206 rh.emit(m1)
5207 self.assertLogFile(self.fn)
5208 m2 = self.next_rec()
5209 rh.emit(m2)
5210 fn = namer(self.fn + ".1")
5211 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005212 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00005213 with open(fn, "rb") as f:
5214 compressed = f.read()
5215 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005216 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005217 rh.emit(self.next_rec())
5218 fn = namer(self.fn + ".2")
5219 self.assertLogFile(fn)
5220 with open(fn, "rb") as f:
5221 compressed = f.read()
5222 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005223 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005224 rh.emit(self.next_rec())
5225 fn = namer(self.fn + ".2")
5226 with open(fn, "rb") as f:
5227 compressed = f.read()
5228 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005229 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005230 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00005231 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005232
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005233class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01005234 # other test methods added below
5235 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01005236 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
5237 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00005238 fmt = logging.Formatter('%(asctime)s %(message)s')
5239 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00005240 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00005241 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01005242 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00005243 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00005244 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00005245 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01005246 fh.close()
5247 # At this point, we should have a recent rotated file which we
5248 # can test for the existence of. However, in practice, on some
5249 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01005250 # in time to go to look for the log file. So, we go back a fair
5251 # bit, and stop as soon as we see a rotated file. In theory this
5252 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01005253 found = False
5254 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01005255 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01005256 for secs in range(GO_BACK):
5257 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01005258 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
5259 found = os.path.exists(fn)
5260 if found:
5261 self.rmfiles.append(fn)
5262 break
Vinay Sajip672c5812011-05-13 07:09:40 +01005263 msg = 'No rotated files found, went back %d seconds' % GO_BACK
5264 if not found:
Mike53f7a7c2017-12-14 14:04:53 +03005265 # print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01005266 dn, fn = os.path.split(self.fn)
5267 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02005268 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
5269 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00005270 for f in files:
5271 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00005272 path = os.path.join(dn, f)
5273 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00005274 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01005275 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005276
Vinay Sajip0372e102011-05-05 12:59:14 +01005277 def test_invalid(self):
5278 assertRaises = self.assertRaises
5279 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01005280 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01005281 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01005282 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01005283 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01005284 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01005285
Vinay Sajipa7130792013-04-12 17:04:23 +01005286 def test_compute_rollover_daily_attime(self):
5287 currentTime = 0
5288 atTime = datetime.time(12, 0, 0)
5289 rh = logging.handlers.TimedRotatingFileHandler(
5290 self.fn, when='MIDNIGHT', interval=1, backupCount=0, utc=True,
5291 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01005292 try:
5293 actual = rh.computeRollover(currentTime)
5294 self.assertEqual(actual, currentTime + 12 * 60 * 60)
Vinay Sajipa7130792013-04-12 17:04:23 +01005295
Vinay Sajipd86ac962013-04-14 12:20:46 +01005296 actual = rh.computeRollover(currentTime + 13 * 60 * 60)
5297 self.assertEqual(actual, currentTime + 36 * 60 * 60)
5298 finally:
5299 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01005300
Vinay Sajip10e8c492013-05-18 10:19:54 -07005301 #@unittest.skipIf(True, 'Temporarily skipped while failures investigated.')
Vinay Sajipa7130792013-04-12 17:04:23 +01005302 def test_compute_rollover_weekly_attime(self):
Vinay Sajipd86ac962013-04-14 12:20:46 +01005303 currentTime = int(time.time())
5304 today = currentTime - currentTime % 86400
5305
Vinay Sajipa7130792013-04-12 17:04:23 +01005306 atTime = datetime.time(12, 0, 0)
5307
Vinay Sajip10e8c492013-05-18 10:19:54 -07005308 wday = time.gmtime(today).tm_wday
Vinay Sajipa7130792013-04-12 17:04:23 +01005309 for day in range(7):
5310 rh = logging.handlers.TimedRotatingFileHandler(
5311 self.fn, when='W%d' % day, interval=1, backupCount=0, utc=True,
5312 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01005313 try:
5314 if wday > day:
5315 # The rollover day has already passed this week, so we
5316 # go over into next week
5317 expected = (7 - wday + day)
5318 else:
5319 expected = (day - wday)
5320 # At this point expected is in days from now, convert to seconds
5321 expected *= 24 * 60 * 60
5322 # Add in the rollover time
5323 expected += 12 * 60 * 60
5324 # Add in adjustment for today
5325 expected += today
Vinay Sajip66940a12013-04-15 11:59:35 +01005326 actual = rh.computeRollover(today)
5327 if actual != expected:
5328 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01005329 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01005330 self.assertEqual(actual, expected)
5331 if day == wday:
5332 # goes into following week
5333 expected += 7 * 24 * 60 * 60
Vinay Sajip8b4c7192013-04-14 12:25:25 +01005334 actual = rh.computeRollover(today + 13 * 60 * 60)
Vinay Sajip66940a12013-04-15 11:59:35 +01005335 if actual != expected:
5336 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01005337 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01005338 self.assertEqual(actual, expected)
5339 finally:
5340 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01005341
5342
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005343def secs(**kw):
5344 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
5345
5346for when, exp in (('S', 1),
5347 ('M', 60),
5348 ('H', 60 * 60),
5349 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00005350 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005351 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00005352 ('W0', secs(days=4, hours=24)),
5353 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005354 def test_compute_rollover(self, when=when, exp=exp):
5355 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00005356 self.fn, when=when, interval=1, backupCount=0, utc=True)
5357 currentTime = 0.0
5358 actual = rh.computeRollover(currentTime)
5359 if exp != actual:
5360 # Failures occur on some systems for MIDNIGHT and W0.
5361 # Print detailed calculation for MIDNIGHT so we can try to see
5362 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00005363 if when == 'MIDNIGHT':
5364 try:
5365 if rh.utc:
5366 t = time.gmtime(currentTime)
5367 else:
5368 t = time.localtime(currentTime)
5369 currentHour = t[3]
5370 currentMinute = t[4]
5371 currentSecond = t[5]
5372 # r is the number of seconds left between now and midnight
5373 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
5374 currentMinute) * 60 +
5375 currentSecond)
5376 result = currentTime + r
5377 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
5378 print('currentHour: %s' % currentHour, file=sys.stderr)
5379 print('currentMinute: %s' % currentMinute, file=sys.stderr)
5380 print('currentSecond: %s' % currentSecond, file=sys.stderr)
5381 print('r: %s' % r, file=sys.stderr)
5382 print('result: %s' % result, file=sys.stderr)
5383 except Exception:
5384 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
5385 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00005386 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005387 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
5388
Vinay Sajip60ccd822011-05-09 17:32:09 +01005389
Vinay Sajip223349c2015-10-01 20:37:54 +01005390@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil/pywintypes required for this test.')
Vinay Sajip60ccd822011-05-09 17:32:09 +01005391class NTEventLogHandlerTest(BaseTest):
5392 def test_basic(self):
5393 logtype = 'Application'
5394 elh = win32evtlog.OpenEventLog(None, logtype)
5395 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
Vinay Sajip223349c2015-10-01 20:37:54 +01005396
5397 try:
5398 h = logging.handlers.NTEventLogHandler('test_logging')
5399 except pywintypes.error as e:
Zachary Ware22226c52015-10-06 15:22:13 -05005400 if e.winerror == 5: # access denied
Vinay Sajip223349c2015-10-01 20:37:54 +01005401 raise unittest.SkipTest('Insufficient privileges to run test')
Zachary Ware106ddf02015-10-06 15:28:43 -05005402 raise
Vinay Sajip223349c2015-10-01 20:37:54 +01005403
Vinay Sajip60ccd822011-05-09 17:32:09 +01005404 r = logging.makeLogRecord({'msg': 'Test Log Message'})
5405 h.handle(r)
5406 h.close()
5407 # Now see if the event is recorded
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02005408 self.assertLess(num_recs, win32evtlog.GetNumberOfEventLogRecords(elh))
Vinay Sajip60ccd822011-05-09 17:32:09 +01005409 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
5410 win32evtlog.EVENTLOG_SEQUENTIAL_READ
5411 found = False
5412 GO_BACK = 100
5413 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
5414 for e in events:
5415 if e.SourceName != 'test_logging':
5416 continue
5417 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
5418 if msg != 'Test Log Message\r\n':
5419 continue
5420 found = True
5421 break
5422 msg = 'Record not found in event log, went back %d records' % GO_BACK
5423 self.assertTrue(found, msg=msg)
5424
Vinay Sajipdb8f4632016-09-08 01:37:03 +01005425
5426class MiscTestCase(unittest.TestCase):
5427 def test__all__(self):
Victor Stinnerfbf43f02020-08-17 07:20:40 +02005428 not_exported = {
5429 'logThreads', 'logMultiprocessing', 'logProcesses', 'currentframe',
5430 'PercentStyle', 'StrFormatStyle', 'StringTemplateStyle',
5431 'Filterer', 'PlaceHolder', 'Manager', 'RootLogger', 'root',
5432 'threading'}
5433 support.check__all__(self, logging, not_exported=not_exported)
Vinay Sajipdb8f4632016-09-08 01:37:03 +01005434
5435
Christian Heimes180510d2008-03-03 19:15:45 +00005436# Set the locale to the platform-dependent default. I have no idea
5437# why the test does this, but in any case we save the current locale
5438# first and restore it at the end.
Vinay Sajip1feedb42014-05-31 08:19:12 +01005439@support.run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00005440def test_main():
Vinay Sajipd61910c2016-09-08 01:13:39 +01005441 tests = [
Vinay Sajip1feedb42014-05-31 08:19:12 +01005442 BuiltinLevelsTest, BasicFilterTest, CustomLevelsAndFiltersTest,
5443 HandlerTest, MemoryHandlerTest, ConfigFileTest, SocketHandlerTest,
5444 DatagramHandlerTest, MemoryTest, EncodingTest, WarningsTest,
5445 ConfigDictTest, ManagerTest, FormatterTest, BufferingFormatterTest,
5446 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
5447 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest, BasicConfigTest,
5448 LoggerAdapterTest, LoggerTest, SMTPHandlerTest, FileHandlerTest,
5449 RotatingFileHandlerTest, LastResortTest, LogRecordTest,
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08005450 ExceptionTest, SysLogHandlerTest, IPv6SysLogHandlerTest, HTTPHandlerTest,
Vinay Sajip1feedb42014-05-31 08:19:12 +01005451 NTEventLogHandlerTest, TimedRotatingFileHandlerTest,
Vinay Sajipd61910c2016-09-08 01:13:39 +01005452 UnixSocketHandlerTest, UnixDatagramHandlerTest, UnixSysLogHandlerTest,
Vinay Sajipdb8f4632016-09-08 01:37:03 +01005453 MiscTestCase
Vinay Sajipd61910c2016-09-08 01:13:39 +01005454 ]
5455 if hasattr(logging.handlers, 'QueueListener'):
5456 tests.append(QueueListenerTest)
5457 support.run_unittest(*tests)
Jeremy Hylton096d9862003-07-18 03:19:20 +00005458
Christian Heimes180510d2008-03-03 19:15:45 +00005459if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00005460 test_main()