blob: d23fbfb4fe281b14594699de9c4ac1c224885500 [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
1167
1168 def removeTarget(self):
1169 self.mem_hdlr.setTarget(None)
1170
1171 def handle(self, msg):
1172 t = threading.Thread(target=self.removeTarget)
1173 t.daemon = True
1174 t.start()
1175
1176 target = MockRaceConditionHandler(self.mem_hdlr)
1177 self.mem_hdlr.setTarget(target)
1178
1179 for _ in range(10):
1180 time.sleep(0.005)
1181 self.mem_logger.info("not flushed")
1182 self.mem_logger.warning("flushed")
1183
Christian Heimes180510d2008-03-03 19:15:45 +00001184
1185class ExceptionFormatter(logging.Formatter):
1186 """A special exception formatter."""
1187 def formatException(self, ei):
1188 return "Got a [%s]" % ei[0].__name__
1189
1190
1191class ConfigFileTest(BaseTest):
1192
1193 """Reading logging config from a .ini-style config file."""
1194
Hai Shi3ddc6342020-06-30 21:46:06 +08001195 check_no_resource_warning = warnings_helper.check_no_resource_warning
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001196 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001197
1198 # config0 is a standard configuration.
1199 config0 = """
1200 [loggers]
1201 keys=root
1202
1203 [handlers]
1204 keys=hand1
1205
1206 [formatters]
1207 keys=form1
1208
1209 [logger_root]
1210 level=WARNING
1211 handlers=hand1
1212
1213 [handler_hand1]
1214 class=StreamHandler
1215 level=NOTSET
1216 formatter=form1
1217 args=(sys.stdout,)
1218
1219 [formatter_form1]
1220 format=%(levelname)s ++ %(message)s
1221 datefmt=
1222 """
1223
1224 # config1 adds a little to the standard configuration.
1225 config1 = """
1226 [loggers]
1227 keys=root,parser
1228
1229 [handlers]
1230 keys=hand1
1231
1232 [formatters]
1233 keys=form1
1234
1235 [logger_root]
1236 level=WARNING
1237 handlers=
1238
1239 [logger_parser]
1240 level=DEBUG
1241 handlers=hand1
1242 propagate=1
1243 qualname=compiler.parser
1244
1245 [handler_hand1]
1246 class=StreamHandler
1247 level=NOTSET
1248 formatter=form1
1249 args=(sys.stdout,)
1250
1251 [formatter_form1]
1252 format=%(levelname)s ++ %(message)s
1253 datefmt=
1254 """
1255
Vinay Sajip3f84b072011-03-07 17:49:33 +00001256 # config1a moves the handler to the root.
1257 config1a = """
1258 [loggers]
1259 keys=root,parser
1260
1261 [handlers]
1262 keys=hand1
1263
1264 [formatters]
1265 keys=form1
1266
1267 [logger_root]
1268 level=WARNING
1269 handlers=hand1
1270
1271 [logger_parser]
1272 level=DEBUG
1273 handlers=
1274 propagate=1
1275 qualname=compiler.parser
1276
1277 [handler_hand1]
1278 class=StreamHandler
1279 level=NOTSET
1280 formatter=form1
1281 args=(sys.stdout,)
1282
1283 [formatter_form1]
1284 format=%(levelname)s ++ %(message)s
1285 datefmt=
1286 """
1287
Christian Heimes180510d2008-03-03 19:15:45 +00001288 # config2 has a subtle configuration error that should be reported
1289 config2 = config1.replace("sys.stdout", "sys.stbout")
1290
1291 # config3 has a less subtle configuration error
1292 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
1293
1294 # config4 specifies a custom formatter class to be loaded
1295 config4 = """
1296 [loggers]
1297 keys=root
1298
1299 [handlers]
1300 keys=hand1
1301
1302 [formatters]
1303 keys=form1
1304
1305 [logger_root]
1306 level=NOTSET
1307 handlers=hand1
1308
1309 [handler_hand1]
1310 class=StreamHandler
1311 level=NOTSET
1312 formatter=form1
1313 args=(sys.stdout,)
1314
1315 [formatter_form1]
1316 class=""" + __name__ + """.ExceptionFormatter
1317 format=%(levelname)s:%(name)s:%(message)s
1318 datefmt=
1319 """
1320
Georg Brandl3dbca812008-07-23 16:10:53 +00001321 # config5 specifies a custom handler class to be loaded
1322 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
1323
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001324 # config6 uses ', ' delimiters in the handlers and formatters sections
1325 config6 = """
1326 [loggers]
1327 keys=root,parser
1328
1329 [handlers]
1330 keys=hand1, hand2
1331
1332 [formatters]
1333 keys=form1, form2
1334
1335 [logger_root]
1336 level=WARNING
1337 handlers=
1338
1339 [logger_parser]
1340 level=DEBUG
1341 handlers=hand1
1342 propagate=1
1343 qualname=compiler.parser
1344
1345 [handler_hand1]
1346 class=StreamHandler
1347 level=NOTSET
1348 formatter=form1
1349 args=(sys.stdout,)
1350
1351 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001352 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001353 level=NOTSET
1354 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001355 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001356
1357 [formatter_form1]
1358 format=%(levelname)s ++ %(message)s
1359 datefmt=
1360
1361 [formatter_form2]
1362 format=%(message)s
1363 datefmt=
1364 """
1365
Preston Landers6ea56d22017-08-02 15:44:28 -05001366 # config7 adds a compiler logger, and uses kwargs instead of args.
Vinay Sajip3f84b072011-03-07 17:49:33 +00001367 config7 = """
1368 [loggers]
1369 keys=root,parser,compiler
1370
1371 [handlers]
1372 keys=hand1
1373
1374 [formatters]
1375 keys=form1
1376
1377 [logger_root]
1378 level=WARNING
1379 handlers=hand1
1380
1381 [logger_compiler]
1382 level=DEBUG
1383 handlers=
1384 propagate=1
1385 qualname=compiler
1386
1387 [logger_parser]
1388 level=DEBUG
1389 handlers=
1390 propagate=1
1391 qualname=compiler.parser
1392
1393 [handler_hand1]
1394 class=StreamHandler
1395 level=NOTSET
1396 formatter=form1
Preston Landers6ea56d22017-08-02 15:44:28 -05001397 kwargs={'stream': sys.stdout,}
Vinay Sajip3f84b072011-03-07 17:49:33 +00001398
1399 [formatter_form1]
1400 format=%(levelname)s ++ %(message)s
1401 datefmt=
1402 """
1403
Xtreak087570a2018-07-02 14:27:46 +05301404 # config 8, check for resource warning
1405 config8 = r"""
1406 [loggers]
1407 keys=root
1408
1409 [handlers]
1410 keys=file
1411
1412 [formatters]
1413 keys=
1414
1415 [logger_root]
1416 level=DEBUG
1417 handlers=file
1418
1419 [handler_file]
1420 class=FileHandler
1421 level=DEBUG
1422 args=("{tempfile}",)
1423 """
1424
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001425 disable_test = """
1426 [loggers]
1427 keys=root
1428
1429 [handlers]
1430 keys=screen
1431
1432 [formatters]
1433 keys=
1434
1435 [logger_root]
1436 level=DEBUG
1437 handlers=screen
1438
1439 [handler_screen]
1440 level=DEBUG
1441 class=StreamHandler
1442 args=(sys.stdout,)
1443 formatter=
1444 """
1445
1446 def apply_config(self, conf, **kwargs):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001447 file = io.StringIO(textwrap.dedent(conf))
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001448 logging.config.fileConfig(file, **kwargs)
Christian Heimes180510d2008-03-03 19:15:45 +00001449
1450 def test_config0_ok(self):
1451 # A simple config file which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001452 with support.captured_stdout() as output:
Christian Heimes180510d2008-03-03 19:15:45 +00001453 self.apply_config(self.config0)
1454 logger = logging.getLogger()
1455 # Won't output anything
1456 logger.info(self.next_message())
1457 # Outputs a message
1458 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001459 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001460 ('ERROR', '2'),
1461 ], stream=output)
1462 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001463 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001464
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001465 def test_config0_using_cp_ok(self):
1466 # A simple config file which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001467 with support.captured_stdout() as output:
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001468 file = io.StringIO(textwrap.dedent(self.config0))
1469 cp = configparser.ConfigParser()
1470 cp.read_file(file)
1471 logging.config.fileConfig(cp)
1472 logger = logging.getLogger()
1473 # Won't output anything
1474 logger.info(self.next_message())
1475 # Outputs a message
1476 logger.error(self.next_message())
1477 self.assert_log_lines([
1478 ('ERROR', '2'),
1479 ], stream=output)
1480 # Original logger output is empty.
1481 self.assert_log_lines([])
1482
Georg Brandl3dbca812008-07-23 16:10:53 +00001483 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +00001484 # A config file defining a sub-parser as well.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001485 with support.captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +00001486 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +00001487 logger = logging.getLogger("compiler.parser")
1488 # Both will output a message
1489 logger.info(self.next_message())
1490 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001491 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001492 ('INFO', '1'),
1493 ('ERROR', '2'),
1494 ], stream=output)
1495 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001496 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001497
1498 def test_config2_failure(self):
1499 # A simple config file which overrides the default settings.
1500 self.assertRaises(Exception, self.apply_config, self.config2)
1501
1502 def test_config3_failure(self):
1503 # A simple config file which overrides the default settings.
1504 self.assertRaises(Exception, self.apply_config, self.config3)
1505
1506 def test_config4_ok(self):
1507 # A config file specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001508 with support.captured_stdout() as output:
Christian Heimes180510d2008-03-03 19:15:45 +00001509 self.apply_config(self.config4)
1510 logger = logging.getLogger()
1511 try:
1512 raise RuntimeError()
1513 except RuntimeError:
1514 logging.exception("just testing")
1515 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00001516 self.assertEqual(output.getvalue(),
Christian Heimes180510d2008-03-03 19:15:45 +00001517 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1518 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001519 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001520
Georg Brandl3dbca812008-07-23 16:10:53 +00001521 def test_config5_ok(self):
1522 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +00001523
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001524 def test_config6_ok(self):
1525 self.test_config1_ok(config=self.config6)
1526
Vinay Sajip3f84b072011-03-07 17:49:33 +00001527 def test_config7_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01001528 with support.captured_stdout() as output:
Vinay Sajip3f84b072011-03-07 17:49:33 +00001529 self.apply_config(self.config1a)
1530 logger = logging.getLogger("compiler.parser")
1531 # See issue #11424. compiler-hyphenated sorts
1532 # between compiler and compiler.xyz and this
1533 # was preventing compiler.xyz from being included
1534 # in the child loggers of compiler because of an
1535 # overzealous loop termination condition.
1536 hyphenated = logging.getLogger('compiler-hyphenated')
1537 # All will output a message
1538 logger.info(self.next_message())
1539 logger.error(self.next_message())
1540 hyphenated.critical(self.next_message())
1541 self.assert_log_lines([
1542 ('INFO', '1'),
1543 ('ERROR', '2'),
1544 ('CRITICAL', '3'),
1545 ], stream=output)
1546 # Original logger output is empty.
1547 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01001548 with support.captured_stdout() as output:
Vinay Sajip3f84b072011-03-07 17:49:33 +00001549 self.apply_config(self.config7)
1550 logger = logging.getLogger("compiler.parser")
1551 self.assertFalse(logger.disabled)
1552 # Both will output a message
1553 logger.info(self.next_message())
1554 logger.error(self.next_message())
1555 logger = logging.getLogger("compiler.lexer")
1556 # Both will output a message
1557 logger.info(self.next_message())
1558 logger.error(self.next_message())
1559 # Will not appear
1560 hyphenated.critical(self.next_message())
1561 self.assert_log_lines([
1562 ('INFO', '4'),
1563 ('ERROR', '5'),
1564 ('INFO', '6'),
1565 ('ERROR', '7'),
1566 ], stream=output)
1567 # Original logger output is empty.
1568 self.assert_log_lines([])
1569
Xtreak087570a2018-07-02 14:27:46 +05301570 def test_config8_ok(self):
1571
1572 def cleanup(h1, fn):
1573 h1.close()
1574 os.remove(fn)
1575
1576 with self.check_no_resource_warning():
1577 fd, fn = tempfile.mkstemp(".log", "test_logging-X-")
1578 os.close(fd)
1579
1580 # Replace single backslash with double backslash in windows
1581 # to avoid unicode error during string formatting
1582 if os.name == "nt":
1583 fn = fn.replace("\\", "\\\\")
1584
1585 config8 = self.config8.format(tempfile=fn)
1586
1587 self.apply_config(config8)
1588 self.apply_config(config8)
1589
1590 handler = logging.root.handlers[0]
1591 self.addCleanup(cleanup, handler, fn)
1592
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001593 def test_logger_disabling(self):
1594 self.apply_config(self.disable_test)
Antoine Pitrou04d4d6a2013-09-14 21:16:39 +02001595 logger = logging.getLogger('some_pristine_logger')
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001596 self.assertFalse(logger.disabled)
1597 self.apply_config(self.disable_test)
1598 self.assertTrue(logger.disabled)
1599 self.apply_config(self.disable_test, disable_existing_loggers=False)
1600 self.assertFalse(logger.disabled)
1601
Lucas Cimonb15100f2019-10-31 09:06:25 +01001602 def test_config_set_handler_names(self):
1603 test_config = """
1604 [loggers]
1605 keys=root
1606
1607 [handlers]
1608 keys=hand1
1609
1610 [formatters]
1611 keys=form1
1612
1613 [logger_root]
1614 handlers=hand1
1615
1616 [handler_hand1]
1617 class=StreamHandler
1618 formatter=form1
1619
1620 [formatter_form1]
1621 format=%(levelname)s ++ %(message)s
1622 """
1623 self.apply_config(test_config)
l0rb991b02d2019-11-07 11:13:36 +01001624 self.assertEqual(logging.getLogger().handlers[0].name, 'hand1')
Lucas Cimonb15100f2019-10-31 09:06:25 +01001625
Łukasz Langa214f18e2018-06-08 04:02:48 -07001626 def test_defaults_do_no_interpolation(self):
1627 """bpo-33802 defaults should not get interpolated"""
1628 ini = textwrap.dedent("""
1629 [formatters]
1630 keys=default
1631
1632 [formatter_default]
1633
1634 [handlers]
1635 keys=console
1636
1637 [handler_console]
1638 class=logging.StreamHandler
1639 args=tuple()
1640
1641 [loggers]
1642 keys=root
1643
1644 [logger_root]
1645 formatter=default
1646 handlers=console
1647 """).strip()
1648 fd, fn = tempfile.mkstemp(prefix='test_logging_', suffix='.ini')
1649 try:
1650 os.write(fd, ini.encode('ascii'))
1651 os.close(fd)
1652 logging.config.fileConfig(
1653 fn,
1654 defaults=dict(
1655 version=1,
1656 disable_existing_loggers=False,
1657 formatters={
1658 "generic": {
1659 "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s",
1660 "datefmt": "[%Y-%m-%d %H:%M:%S %z]",
1661 "class": "logging.Formatter"
1662 },
1663 },
1664 )
1665 )
1666 finally:
1667 os.unlink(fn)
1668
Guido van Rossum2a1d5162003-01-21 21:05:22 +00001669
Christian Heimes180510d2008-03-03 19:15:45 +00001670class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001671
Christian Heimes180510d2008-03-03 19:15:45 +00001672 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001673
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001674 server_class = TestTCPServer
1675 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001676
Christian Heimes180510d2008-03-03 19:15:45 +00001677 def setUp(self):
1678 """Set up a TCP server to receive log messages, and a SocketHandler
1679 pointing to that server's address and port."""
1680 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001681 # Issue #29177: deal with errors that happen during setup
1682 self.server = self.sock_hdlr = self.server_exception = None
1683 try:
1684 self.server = server = self.server_class(self.address,
1685 self.handle_socket, 0.01)
1686 server.start()
1687 # Uncomment next line to test error recovery in setUp()
1688 # raise OSError('dummy error raised')
1689 except OSError as e:
1690 self.server_exception = e
1691 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001692 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001693 hcls = logging.handlers.SocketHandler
1694 if isinstance(server.server_address, tuple):
1695 self.sock_hdlr = hcls('localhost', server.port)
1696 else:
1697 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001698 self.log_output = ''
Christian Heimes180510d2008-03-03 19:15:45 +00001699 self.root_logger.removeHandler(self.root_logger.handlers[0])
1700 self.root_logger.addHandler(self.sock_hdlr)
Vinay Sajip7367d082011-05-02 13:17:27 +01001701 self.handled = threading.Semaphore(0)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001702
Christian Heimes180510d2008-03-03 19:15:45 +00001703 def tearDown(self):
1704 """Shutdown the TCP server."""
1705 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001706 if self.sock_hdlr:
1707 self.root_logger.removeHandler(self.sock_hdlr)
1708 self.sock_hdlr.close()
Victor Stinnerb8f41632017-09-13 01:47:22 -07001709 if self.server:
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001710 self.server.stop()
Christian Heimes180510d2008-03-03 19:15:45 +00001711 finally:
1712 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001713
Vinay Sajip7367d082011-05-02 13:17:27 +01001714 def handle_socket(self, request):
1715 conn = request.connection
1716 while True:
1717 chunk = conn.recv(4)
1718 if len(chunk) < 4:
1719 break
1720 slen = struct.unpack(">L", chunk)[0]
1721 chunk = conn.recv(slen)
1722 while len(chunk) < slen:
1723 chunk = chunk + conn.recv(slen - len(chunk))
1724 obj = pickle.loads(chunk)
1725 record = logging.makeLogRecord(obj)
1726 self.log_output += record.msg + '\n'
1727 self.handled.release()
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001728
Christian Heimes180510d2008-03-03 19:15:45 +00001729 def test_output(self):
1730 # The log message sent to the SocketHandler is properly received.
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001731 if self.server_exception:
1732 self.skipTest(self.server_exception)
Christian Heimes180510d2008-03-03 19:15:45 +00001733 logger = logging.getLogger("tcp")
1734 logger.error("spam")
Vinay Sajip7367d082011-05-02 13:17:27 +01001735 self.handled.acquire()
Christian Heimes180510d2008-03-03 19:15:45 +00001736 logger.debug("eggs")
Vinay Sajip7367d082011-05-02 13:17:27 +01001737 self.handled.acquire()
1738 self.assertEqual(self.log_output, "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001739
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001740 def test_noserver(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001741 if self.server_exception:
1742 self.skipTest(self.server_exception)
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001743 # Avoid timing-related failures due to SocketHandler's own hard-wired
1744 # one-second timeout on socket.create_connection() (issue #16264).
1745 self.sock_hdlr.retryStart = 2.5
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001746 # Kill the server
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001747 self.server.stop()
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001748 # The logging call should try to connect, which should fail
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001749 try:
1750 raise RuntimeError('Deliberate mistake')
1751 except RuntimeError:
1752 self.root_logger.exception('Never sent')
1753 self.root_logger.error('Never sent, either')
1754 now = time.time()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02001755 self.assertGreater(self.sock_hdlr.retryTime, now)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001756 time.sleep(self.sock_hdlr.retryTime - now + 0.001)
1757 self.root_logger.error('Nor this')
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001758
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001759def _get_temp_domain_socket():
1760 fd, fn = tempfile.mkstemp(prefix='test_logging_', suffix='.sock')
1761 os.close(fd)
1762 # just need a name - file can't be present, or we'll get an
1763 # 'address already in use' error.
1764 os.remove(fn)
1765 return fn
Vinay Sajip7367d082011-05-02 13:17:27 +01001766
Victor Stinnerec5a8602014-06-02 14:41:51 +02001767@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001768class UnixSocketHandlerTest(SocketHandlerTest):
1769
1770 """Test for SocketHandler with unix sockets."""
1771
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001772 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001773 server_class = TestUnixStreamServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001774
1775 def setUp(self):
1776 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001777 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001778 SocketHandlerTest.setUp(self)
1779
1780 def tearDown(self):
1781 SocketHandlerTest.tearDown(self)
Hai Shi3ddc6342020-06-30 21:46:06 +08001782 os_helper.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001783
Vinay Sajip7367d082011-05-02 13:17:27 +01001784class DatagramHandlerTest(BaseTest):
1785
1786 """Test for DatagramHandler."""
1787
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001788 server_class = TestUDPServer
1789 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001790
Vinay Sajip7367d082011-05-02 13:17:27 +01001791 def setUp(self):
1792 """Set up a UDP server to receive log messages, and a DatagramHandler
1793 pointing to that server's address and port."""
1794 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001795 # Issue #29177: deal with errors that happen during setup
1796 self.server = self.sock_hdlr = self.server_exception = None
1797 try:
1798 self.server = server = self.server_class(self.address,
1799 self.handle_datagram, 0.01)
1800 server.start()
1801 # Uncomment next line to test error recovery in setUp()
1802 # raise OSError('dummy error raised')
1803 except OSError as e:
1804 self.server_exception = e
1805 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001806 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001807 hcls = logging.handlers.DatagramHandler
1808 if isinstance(server.server_address, tuple):
1809 self.sock_hdlr = hcls('localhost', server.port)
1810 else:
1811 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001812 self.log_output = ''
1813 self.root_logger.removeHandler(self.root_logger.handlers[0])
1814 self.root_logger.addHandler(self.sock_hdlr)
1815 self.handled = threading.Event()
1816
1817 def tearDown(self):
1818 """Shutdown the UDP server."""
1819 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001820 if self.server:
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001821 self.server.stop()
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001822 if self.sock_hdlr:
1823 self.root_logger.removeHandler(self.sock_hdlr)
1824 self.sock_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001825 finally:
1826 BaseTest.tearDown(self)
1827
1828 def handle_datagram(self, request):
1829 slen = struct.pack('>L', 0) # length of prefix
1830 packet = request.packet[len(slen):]
1831 obj = pickle.loads(packet)
1832 record = logging.makeLogRecord(obj)
1833 self.log_output += record.msg + '\n'
1834 self.handled.set()
1835
1836 def test_output(self):
1837 # The log message sent to the DatagramHandler is properly received.
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001838 if self.server_exception:
1839 self.skipTest(self.server_exception)
Vinay Sajip7367d082011-05-02 13:17:27 +01001840 logger = logging.getLogger("udp")
1841 logger.error("spam")
1842 self.handled.wait()
Vinay Sajip714b8dc2011-05-02 14:43:00 +01001843 self.handled.clear()
1844 logger.error("eggs")
1845 self.handled.wait()
1846 self.assertEqual(self.log_output, "spam\neggs\n")
Vinay Sajip7367d082011-05-02 13:17:27 +01001847
Victor Stinnerec5a8602014-06-02 14:41:51 +02001848@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001849class UnixDatagramHandlerTest(DatagramHandlerTest):
1850
1851 """Test for DatagramHandler using Unix sockets."""
1852
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001853 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001854 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001855
1856 def setUp(self):
1857 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001858 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001859 DatagramHandlerTest.setUp(self)
1860
1861 def tearDown(self):
1862 DatagramHandlerTest.tearDown(self)
Hai Shi3ddc6342020-06-30 21:46:06 +08001863 os_helper.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001864
Vinay Sajip7367d082011-05-02 13:17:27 +01001865class SysLogHandlerTest(BaseTest):
1866
1867 """Test for SysLogHandler using UDP."""
1868
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001869 server_class = TestUDPServer
1870 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001871
Vinay Sajip7367d082011-05-02 13:17:27 +01001872 def setUp(self):
1873 """Set up a UDP server to receive log messages, and a SysLogHandler
1874 pointing to that server's address and port."""
1875 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001876 # Issue #29177: deal with errors that happen during setup
1877 self.server = self.sl_hdlr = self.server_exception = None
1878 try:
1879 self.server = server = self.server_class(self.address,
1880 self.handle_datagram, 0.01)
1881 server.start()
1882 # Uncomment next line to test error recovery in setUp()
1883 # raise OSError('dummy error raised')
1884 except OSError as e:
1885 self.server_exception = e
1886 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001887 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001888 hcls = logging.handlers.SysLogHandler
1889 if isinstance(server.server_address, tuple):
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001890 self.sl_hdlr = hcls((server.server_address[0], server.port))
Vinay Sajip5421f352013-09-27 18:18:28 +01001891 else:
1892 self.sl_hdlr = hcls(server.server_address)
Vinay Sajip7367d082011-05-02 13:17:27 +01001893 self.log_output = ''
1894 self.root_logger.removeHandler(self.root_logger.handlers[0])
1895 self.root_logger.addHandler(self.sl_hdlr)
1896 self.handled = threading.Event()
1897
1898 def tearDown(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001899 """Shutdown the server."""
Vinay Sajip7367d082011-05-02 13:17:27 +01001900 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001901 if self.server:
Victor Stinnerbbc8b792019-12-10 20:41:23 +01001902 self.server.stop()
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001903 if self.sl_hdlr:
1904 self.root_logger.removeHandler(self.sl_hdlr)
1905 self.sl_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001906 finally:
1907 BaseTest.tearDown(self)
1908
1909 def handle_datagram(self, request):
1910 self.log_output = request.packet
1911 self.handled.set()
1912
1913 def test_output(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001914 if self.server_exception:
1915 self.skipTest(self.server_exception)
Vinay Sajip7367d082011-05-02 13:17:27 +01001916 # The log message sent to the SysLogHandler is properly received.
1917 logger = logging.getLogger("slh")
1918 logger.error("sp\xe4m")
1919 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001920 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001921 self.handled.clear()
1922 self.sl_hdlr.append_nul = False
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')
Vinay Sajip2353e352011-06-27 15:40:06 +01001926 self.handled.clear()
1927 self.sl_hdlr.ident = "h\xe4m-"
1928 logger.error("sp\xe4m")
1929 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001930 self.assertEqual(self.log_output, b'<11>h\xc3\xa4m-sp\xc3\xa4m')
Vinay Sajip7367d082011-05-02 13:17:27 +01001931
Victor Stinnerec5a8602014-06-02 14:41:51 +02001932@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001933class UnixSysLogHandlerTest(SysLogHandlerTest):
1934
1935 """Test for SysLogHandler with Unix sockets."""
1936
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001937 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001938 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001939
1940 def setUp(self):
1941 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001942 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001943 SysLogHandlerTest.setUp(self)
1944
1945 def tearDown(self):
1946 SysLogHandlerTest.tearDown(self)
Hai Shi3ddc6342020-06-30 21:46:06 +08001947 os_helper.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001948
Serhiy Storchaka16994912020-04-25 10:06:29 +03001949@unittest.skipUnless(socket_helper.IPV6_ENABLED,
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001950 'IPv6 support required for this test.')
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001951class IPv6SysLogHandlerTest(SysLogHandlerTest):
1952
1953 """Test for SysLogHandler with IPv6 host."""
1954
1955 server_class = TestUDPServer
1956 address = ('::1', 0)
1957
1958 def setUp(self):
1959 self.server_class.address_family = socket.AF_INET6
1960 super(IPv6SysLogHandlerTest, self).setUp()
1961
1962 def tearDown(self):
1963 self.server_class.address_family = socket.AF_INET
1964 super(IPv6SysLogHandlerTest, self).tearDown()
1965
Vinay Sajip7367d082011-05-02 13:17:27 +01001966class HTTPHandlerTest(BaseTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01001967 """Test for HTTPHandler."""
1968
1969 def setUp(self):
1970 """Set up an HTTP server to receive log messages, and a HTTPHandler
1971 pointing to that server's address and port."""
1972 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001973 self.handled = threading.Event()
1974
Vinay Sajip7367d082011-05-02 13:17:27 +01001975 def handle_request(self, request):
Vinay Sajip0372e102011-05-05 12:59:14 +01001976 self.command = request.command
Vinay Sajip7367d082011-05-02 13:17:27 +01001977 self.log_data = urlparse(request.path)
Vinay Sajip0372e102011-05-05 12:59:14 +01001978 if self.command == 'POST':
1979 try:
1980 rlen = int(request.headers['Content-Length'])
1981 self.post_data = request.rfile.read(rlen)
1982 except:
1983 self.post_data = None
Vinay Sajip7367d082011-05-02 13:17:27 +01001984 request.send_response(200)
Vinay Sajip463ac512011-05-10 09:10:08 +01001985 request.end_headers()
Vinay Sajip7367d082011-05-02 13:17:27 +01001986 self.handled.set()
1987
1988 def test_output(self):
Vinay Sajipf2231162011-05-09 22:05:50 +01001989 # The log message sent to the HTTPHandler is properly received.
Vinay Sajip7367d082011-05-02 13:17:27 +01001990 logger = logging.getLogger("http")
Vinay Sajip9ba87612011-05-21 11:32:15 +01001991 root_logger = self.root_logger
1992 root_logger.removeHandler(self.root_logger.handlers[0])
1993 for secure in (False, True):
1994 addr = ('localhost', 0)
1995 if secure:
Vinay Sajip39e35282011-05-21 16:46:41 +01001996 try:
1997 import ssl
Vinay Sajip39e35282011-05-21 16:46:41 +01001998 except ImportError:
1999 sslctx = None
Benjamin Peterson4ffb0752014-11-03 14:29:33 -05002000 else:
2001 here = os.path.dirname(__file__)
2002 localhost_cert = os.path.join(here, "keycert.pem")
Christian Heimesa170fa12017-09-15 20:27:30 +02002003 sslctx = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
Benjamin Peterson4ffb0752014-11-03 14:29:33 -05002004 sslctx.load_cert_chain(localhost_cert)
Benjamin Peterson43052a12014-11-23 20:36:44 -06002005
2006 context = ssl.create_default_context(cafile=localhost_cert)
Vinay Sajip0372e102011-05-05 12:59:14 +01002007 else:
Vinay Sajip9ba87612011-05-21 11:32:15 +01002008 sslctx = None
Benjamin Peterson43052a12014-11-23 20:36:44 -06002009 context = None
Vinay Sajip9ba87612011-05-21 11:32:15 +01002010 self.server = server = TestHTTPServer(addr, self.handle_request,
2011 0.01, sslctx=sslctx)
2012 server.start()
2013 server.ready.wait()
2014 host = 'localhost:%d' % server.server_port
Vinay Sajip39e35282011-05-21 16:46:41 +01002015 secure_client = secure and sslctx
2016 self.h_hdlr = logging.handlers.HTTPHandler(host, '/frob',
Benjamin Peterson43052a12014-11-23 20:36:44 -06002017 secure=secure_client,
Vinay Sajip1bf197e2016-06-07 21:19:55 +01002018 context=context,
2019 credentials=('foo', 'bar'))
Vinay Sajip9ba87612011-05-21 11:32:15 +01002020 self.log_data = None
2021 root_logger.addHandler(self.h_hdlr)
2022
2023 for method in ('GET', 'POST'):
2024 self.h_hdlr.method = method
2025 self.handled.clear()
2026 msg = "sp\xe4m"
2027 logger.error(msg)
2028 self.handled.wait()
2029 self.assertEqual(self.log_data.path, '/frob')
2030 self.assertEqual(self.command, method)
2031 if method == 'GET':
2032 d = parse_qs(self.log_data.query)
2033 else:
2034 d = parse_qs(self.post_data.decode('utf-8'))
2035 self.assertEqual(d['name'], ['http'])
2036 self.assertEqual(d['funcName'], ['test_output'])
2037 self.assertEqual(d['msg'], [msg])
2038
Victor Stinnerbbc8b792019-12-10 20:41:23 +01002039 self.server.stop()
Vinay Sajip9ba87612011-05-21 11:32:15 +01002040 self.root_logger.removeHandler(self.h_hdlr)
2041 self.h_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01002042
Christian Heimes180510d2008-03-03 19:15:45 +00002043class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002044
Christian Heimes180510d2008-03-03 19:15:45 +00002045 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002046
Christian Heimes180510d2008-03-03 19:15:45 +00002047 def setUp(self):
2048 """Create a dict to remember potentially destroyed objects."""
2049 BaseTest.setUp(self)
2050 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002051
Christian Heimes180510d2008-03-03 19:15:45 +00002052 def _watch_for_survival(self, *args):
2053 """Watch the given objects for survival, by creating weakrefs to
2054 them."""
2055 for obj in args:
2056 key = id(obj), repr(obj)
2057 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002058
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002059 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +00002060 """Assert that all objects watched for survival have survived."""
2061 # Trigger cycle breaking.
2062 gc.collect()
2063 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002064 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +00002065 if ref() is None:
2066 dead.append(repr_)
2067 if dead:
2068 self.fail("%d objects should have survived "
2069 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002070
Christian Heimes180510d2008-03-03 19:15:45 +00002071 def test_persistent_loggers(self):
2072 # Logger objects are persistent and retain their configuration, even
2073 # if visible references are destroyed.
2074 self.root_logger.setLevel(logging.INFO)
2075 foo = logging.getLogger("foo")
2076 self._watch_for_survival(foo)
2077 foo.setLevel(logging.DEBUG)
2078 self.root_logger.debug(self.next_message())
2079 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00002080 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00002081 ('foo', 'DEBUG', '2'),
2082 ])
2083 del foo
2084 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002085 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +00002086 # foo has retained its settings.
2087 bar = logging.getLogger("foo")
2088 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00002089 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00002090 ('foo', 'DEBUG', '2'),
2091 ('foo', 'DEBUG', '3'),
2092 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002093
Benjamin Petersonf91df042009-02-13 02:50:59 +00002094
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002095class EncodingTest(BaseTest):
2096 def test_encoding_plain_file(self):
2097 # In Python 2.x, a plain file object is treated as having no encoding.
2098 log = logging.getLogger("test")
Vinay Sajip60b4df12010-12-27 11:18:52 +00002099 fd, fn = tempfile.mkstemp(".log", "test_logging-1-")
2100 os.close(fd)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002101 # the non-ascii data we write to the log.
2102 data = "foo\x80"
2103 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002104 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002105 log.addHandler(handler)
2106 try:
2107 # write non-ascii data to the log.
2108 log.warning(data)
2109 finally:
2110 log.removeHandler(handler)
2111 handler.close()
2112 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002113 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002114 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002115 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002116 finally:
2117 f.close()
2118 finally:
2119 if os.path.isfile(fn):
2120 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002121
Benjamin Petersonf91df042009-02-13 02:50:59 +00002122 def test_encoding_cyrillic_unicode(self):
2123 log = logging.getLogger("test")
Mike53f7a7c2017-12-14 14:04:53 +03002124 # Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
Benjamin Petersonf91df042009-02-13 02:50:59 +00002125 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
Mike53f7a7c2017-12-14 14:04:53 +03002126 # Ensure it's written in a Cyrillic encoding
Benjamin Petersonf91df042009-02-13 02:50:59 +00002127 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +00002128 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +00002129 stream = io.BytesIO()
2130 writer = writer_class(stream, 'strict')
2131 handler = logging.StreamHandler(writer)
2132 log.addHandler(handler)
2133 try:
2134 log.warning(message)
2135 finally:
2136 log.removeHandler(handler)
2137 handler.close()
2138 # check we wrote exactly those bytes, ignoring trailing \n etc
2139 s = stream.getvalue()
Mike53f7a7c2017-12-14 14:04:53 +03002140 # Compare against what the data should be when encoded in CP-1251
Benjamin Petersonf91df042009-02-13 02:50:59 +00002141 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
2142
2143
Georg Brandlf9734072008-12-07 15:30:06 +00002144class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +00002145
Georg Brandlf9734072008-12-07 15:30:06 +00002146 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +00002147 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +00002148 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002149 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002150 warnings.filterwarnings("always", category=UserWarning)
2151 stream = io.StringIO()
2152 h = logging.StreamHandler(stream)
2153 logger = logging.getLogger("py.warnings")
2154 logger.addHandler(h)
2155 warnings.warn("I'm warning you...")
2156 logger.removeHandler(h)
2157 s = stream.getvalue()
2158 h.close()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02002159 self.assertGreater(s.find("UserWarning: I'm warning you...\n"), 0)
Georg Brandlf9734072008-12-07 15:30:06 +00002160
Mike53f7a7c2017-12-14 14:04:53 +03002161 # See if an explicit file uses the original implementation
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002162 a_file = io.StringIO()
2163 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
2164 a_file, "Dummy line")
2165 s = a_file.getvalue()
2166 a_file.close()
2167 self.assertEqual(s,
2168 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
2169
2170 def test_warnings_no_handlers(self):
2171 with warnings.catch_warnings():
2172 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002173 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002174
2175 # confirm our assumption: no loggers are set
2176 logger = logging.getLogger("py.warnings")
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002177 self.assertEqual(logger.handlers, [])
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002178
2179 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002180 self.assertEqual(len(logger.handlers), 1)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002181 self.assertIsInstance(logger.handlers[0], logging.NullHandler)
Georg Brandlf9734072008-12-07 15:30:06 +00002182
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002183
2184def formatFunc(format, datefmt=None):
2185 return logging.Formatter(format, datefmt)
2186
BNMetrics18fb1fb2018-10-15 19:41:36 +01002187class myCustomFormatter:
2188 def __init__(self, fmt, datefmt=None):
2189 pass
2190
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002191def handlerFunc():
2192 return logging.StreamHandler()
2193
2194class CustomHandler(logging.StreamHandler):
2195 pass
2196
2197class ConfigDictTest(BaseTest):
2198
2199 """Reading logging config from a dictionary."""
2200
Hai Shi3ddc6342020-06-30 21:46:06 +08002201 check_no_resource_warning = warnings_helper.check_no_resource_warning
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002202 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002203
2204 # config0 is a standard configuration.
2205 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002206 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002207 'formatters': {
2208 'form1' : {
2209 'format' : '%(levelname)s ++ %(message)s',
2210 },
2211 },
2212 'handlers' : {
2213 'hand1' : {
2214 'class' : 'logging.StreamHandler',
2215 'formatter' : 'form1',
2216 'level' : 'NOTSET',
2217 'stream' : 'ext://sys.stdout',
2218 },
2219 },
2220 'root' : {
2221 'level' : 'WARNING',
2222 'handlers' : ['hand1'],
2223 },
2224 }
2225
2226 # config1 adds a little to the standard configuration.
2227 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002228 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002229 'formatters': {
2230 'form1' : {
2231 'format' : '%(levelname)s ++ %(message)s',
2232 },
2233 },
2234 'handlers' : {
2235 'hand1' : {
2236 'class' : 'logging.StreamHandler',
2237 'formatter' : 'form1',
2238 'level' : 'NOTSET',
2239 'stream' : 'ext://sys.stdout',
2240 },
2241 },
2242 'loggers' : {
2243 'compiler.parser' : {
2244 'level' : 'DEBUG',
2245 'handlers' : ['hand1'],
2246 },
2247 },
2248 'root' : {
2249 'level' : 'WARNING',
2250 },
2251 }
2252
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002253 # config1a moves the handler to the root. Used with config8a
2254 config1a = {
2255 'version': 1,
2256 'formatters': {
2257 'form1' : {
2258 'format' : '%(levelname)s ++ %(message)s',
2259 },
2260 },
2261 'handlers' : {
2262 'hand1' : {
2263 'class' : 'logging.StreamHandler',
2264 'formatter' : 'form1',
2265 'level' : 'NOTSET',
2266 'stream' : 'ext://sys.stdout',
2267 },
2268 },
2269 'loggers' : {
2270 'compiler.parser' : {
2271 'level' : 'DEBUG',
2272 },
2273 },
2274 'root' : {
2275 'level' : 'WARNING',
2276 'handlers' : ['hand1'],
2277 },
2278 }
2279
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002280 # config2 has a subtle configuration error that should be reported
2281 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002282 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002283 'formatters': {
2284 'form1' : {
2285 'format' : '%(levelname)s ++ %(message)s',
2286 },
2287 },
2288 'handlers' : {
2289 'hand1' : {
2290 'class' : 'logging.StreamHandler',
2291 'formatter' : 'form1',
2292 'level' : 'NOTSET',
2293 'stream' : 'ext://sys.stdbout',
2294 },
2295 },
2296 'loggers' : {
2297 'compiler.parser' : {
2298 'level' : 'DEBUG',
2299 'handlers' : ['hand1'],
2300 },
2301 },
2302 'root' : {
2303 'level' : 'WARNING',
2304 },
2305 }
2306
Mike53f7a7c2017-12-14 14:04:53 +03002307 # As config1 but with a misspelt level on a handler
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002308 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002309 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002310 'formatters': {
2311 'form1' : {
2312 'format' : '%(levelname)s ++ %(message)s',
2313 },
2314 },
2315 'handlers' : {
2316 'hand1' : {
2317 'class' : 'logging.StreamHandler',
2318 'formatter' : 'form1',
2319 'level' : 'NTOSET',
2320 'stream' : 'ext://sys.stdout',
2321 },
2322 },
2323 'loggers' : {
2324 'compiler.parser' : {
2325 'level' : 'DEBUG',
2326 'handlers' : ['hand1'],
2327 },
2328 },
2329 'root' : {
2330 'level' : 'WARNING',
2331 },
2332 }
2333
2334
Mike53f7a7c2017-12-14 14:04:53 +03002335 # As config1 but with a misspelt level on a logger
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002336 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002337 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002338 'formatters': {
2339 'form1' : {
2340 'format' : '%(levelname)s ++ %(message)s',
2341 },
2342 },
2343 'handlers' : {
2344 'hand1' : {
2345 'class' : 'logging.StreamHandler',
2346 'formatter' : 'form1',
2347 'level' : 'NOTSET',
2348 'stream' : 'ext://sys.stdout',
2349 },
2350 },
2351 'loggers' : {
2352 'compiler.parser' : {
2353 'level' : 'DEBUG',
2354 'handlers' : ['hand1'],
2355 },
2356 },
2357 'root' : {
2358 'level' : 'WRANING',
2359 },
2360 }
2361
2362 # config3 has a less subtle configuration error
2363 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002364 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002365 'formatters': {
2366 'form1' : {
2367 'format' : '%(levelname)s ++ %(message)s',
2368 },
2369 },
2370 'handlers' : {
2371 'hand1' : {
2372 'class' : 'logging.StreamHandler',
2373 'formatter' : 'misspelled_name',
2374 'level' : 'NOTSET',
2375 'stream' : 'ext://sys.stdout',
2376 },
2377 },
2378 'loggers' : {
2379 'compiler.parser' : {
2380 'level' : 'DEBUG',
2381 'handlers' : ['hand1'],
2382 },
2383 },
2384 'root' : {
2385 'level' : 'WARNING',
2386 },
2387 }
2388
2389 # config4 specifies a custom formatter class to be loaded
2390 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002391 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002392 'formatters': {
2393 'form1' : {
2394 '()' : __name__ + '.ExceptionFormatter',
2395 'format' : '%(levelname)s:%(name)s:%(message)s',
2396 },
2397 },
2398 'handlers' : {
2399 'hand1' : {
2400 'class' : 'logging.StreamHandler',
2401 'formatter' : 'form1',
2402 'level' : 'NOTSET',
2403 'stream' : 'ext://sys.stdout',
2404 },
2405 },
2406 'root' : {
2407 'level' : 'NOTSET',
2408 'handlers' : ['hand1'],
2409 },
2410 }
2411
2412 # As config4 but using an actual callable rather than a string
2413 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002414 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002415 'formatters': {
2416 'form1' : {
2417 '()' : ExceptionFormatter,
2418 'format' : '%(levelname)s:%(name)s:%(message)s',
2419 },
2420 'form2' : {
2421 '()' : __name__ + '.formatFunc',
2422 'format' : '%(levelname)s:%(name)s:%(message)s',
2423 },
2424 'form3' : {
2425 '()' : formatFunc,
2426 'format' : '%(levelname)s:%(name)s:%(message)s',
2427 },
2428 },
2429 'handlers' : {
2430 'hand1' : {
2431 'class' : 'logging.StreamHandler',
2432 'formatter' : 'form1',
2433 'level' : 'NOTSET',
2434 'stream' : 'ext://sys.stdout',
2435 },
2436 'hand2' : {
2437 '()' : handlerFunc,
2438 },
2439 },
2440 'root' : {
2441 'level' : 'NOTSET',
2442 'handlers' : ['hand1'],
2443 },
2444 }
2445
2446 # config5 specifies a custom handler class to be loaded
2447 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002448 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002449 'formatters': {
2450 'form1' : {
2451 'format' : '%(levelname)s ++ %(message)s',
2452 },
2453 },
2454 'handlers' : {
2455 'hand1' : {
2456 'class' : __name__ + '.CustomHandler',
2457 'formatter' : 'form1',
2458 'level' : 'NOTSET',
2459 'stream' : 'ext://sys.stdout',
2460 },
2461 },
2462 'loggers' : {
2463 'compiler.parser' : {
2464 'level' : 'DEBUG',
2465 'handlers' : ['hand1'],
2466 },
2467 },
2468 'root' : {
2469 'level' : 'WARNING',
2470 },
2471 }
2472
2473 # config6 specifies a custom handler class to be loaded
2474 # but has bad arguments
2475 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002476 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002477 'formatters': {
2478 'form1' : {
2479 'format' : '%(levelname)s ++ %(message)s',
2480 },
2481 },
2482 'handlers' : {
2483 'hand1' : {
2484 'class' : __name__ + '.CustomHandler',
2485 'formatter' : 'form1',
2486 'level' : 'NOTSET',
2487 'stream' : 'ext://sys.stdout',
2488 '9' : 'invalid parameter name',
2489 },
2490 },
2491 'loggers' : {
2492 'compiler.parser' : {
2493 'level' : 'DEBUG',
2494 'handlers' : ['hand1'],
2495 },
2496 },
2497 'root' : {
2498 'level' : 'WARNING',
2499 },
2500 }
2501
Mike53f7a7c2017-12-14 14:04:53 +03002502 # config 7 does not define compiler.parser but defines compiler.lexer
2503 # so compiler.parser should be disabled after applying it
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002504 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002505 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002506 'formatters': {
2507 'form1' : {
2508 'format' : '%(levelname)s ++ %(message)s',
2509 },
2510 },
2511 'handlers' : {
2512 'hand1' : {
2513 'class' : 'logging.StreamHandler',
2514 'formatter' : 'form1',
2515 'level' : 'NOTSET',
2516 'stream' : 'ext://sys.stdout',
2517 },
2518 },
2519 'loggers' : {
2520 'compiler.lexer' : {
2521 'level' : 'DEBUG',
2522 'handlers' : ['hand1'],
2523 },
2524 },
2525 'root' : {
2526 'level' : 'WARNING',
2527 },
2528 }
2529
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002530 # config8 defines both compiler and compiler.lexer
2531 # so compiler.parser should not be disabled (since
2532 # compiler is defined)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002533 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002534 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002535 'disable_existing_loggers' : False,
2536 'formatters': {
2537 'form1' : {
2538 'format' : '%(levelname)s ++ %(message)s',
2539 },
2540 },
2541 'handlers' : {
2542 'hand1' : {
2543 'class' : 'logging.StreamHandler',
2544 'formatter' : 'form1',
2545 'level' : 'NOTSET',
2546 'stream' : 'ext://sys.stdout',
2547 },
2548 },
2549 'loggers' : {
2550 'compiler' : {
2551 'level' : 'DEBUG',
2552 'handlers' : ['hand1'],
2553 },
2554 'compiler.lexer' : {
2555 },
2556 },
2557 'root' : {
2558 'level' : 'WARNING',
2559 },
2560 }
2561
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002562 # config8a disables existing loggers
2563 config8a = {
2564 'version': 1,
2565 'disable_existing_loggers' : True,
2566 'formatters': {
2567 'form1' : {
2568 'format' : '%(levelname)s ++ %(message)s',
2569 },
2570 },
2571 'handlers' : {
2572 'hand1' : {
2573 'class' : 'logging.StreamHandler',
2574 'formatter' : 'form1',
2575 'level' : 'NOTSET',
2576 'stream' : 'ext://sys.stdout',
2577 },
2578 },
2579 'loggers' : {
2580 'compiler' : {
2581 'level' : 'DEBUG',
2582 'handlers' : ['hand1'],
2583 },
2584 'compiler.lexer' : {
2585 },
2586 },
2587 'root' : {
2588 'level' : 'WARNING',
2589 },
2590 }
2591
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002592 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002593 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002594 'formatters': {
2595 'form1' : {
2596 'format' : '%(levelname)s ++ %(message)s',
2597 },
2598 },
2599 'handlers' : {
2600 'hand1' : {
2601 'class' : 'logging.StreamHandler',
2602 'formatter' : 'form1',
2603 'level' : 'WARNING',
2604 'stream' : 'ext://sys.stdout',
2605 },
2606 },
2607 'loggers' : {
2608 'compiler.parser' : {
2609 'level' : 'WARNING',
2610 'handlers' : ['hand1'],
2611 },
2612 },
2613 'root' : {
2614 'level' : 'NOTSET',
2615 },
2616 }
2617
2618 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002619 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002620 'incremental' : True,
2621 'handlers' : {
2622 'hand1' : {
2623 'level' : 'WARNING',
2624 },
2625 },
2626 'loggers' : {
2627 'compiler.parser' : {
2628 'level' : 'INFO',
2629 },
2630 },
2631 }
2632
2633 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002634 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002635 'incremental' : True,
2636 'handlers' : {
2637 'hand1' : {
2638 'level' : 'INFO',
2639 },
2640 },
2641 'loggers' : {
2642 'compiler.parser' : {
2643 'level' : 'INFO',
2644 },
2645 },
2646 }
2647
Mike53f7a7c2017-12-14 14:04:53 +03002648 # As config1 but with a filter added
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002649 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002650 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002651 'formatters': {
2652 'form1' : {
2653 'format' : '%(levelname)s ++ %(message)s',
2654 },
2655 },
2656 'filters' : {
2657 'filt1' : {
2658 'name' : 'compiler.parser',
2659 },
2660 },
2661 'handlers' : {
2662 'hand1' : {
2663 'class' : 'logging.StreamHandler',
2664 'formatter' : 'form1',
2665 'level' : 'NOTSET',
2666 'stream' : 'ext://sys.stdout',
2667 'filters' : ['filt1'],
2668 },
2669 },
2670 'loggers' : {
2671 'compiler.parser' : {
2672 'level' : 'DEBUG',
2673 'filters' : ['filt1'],
2674 },
2675 },
2676 'root' : {
2677 'level' : 'WARNING',
2678 'handlers' : ['hand1'],
2679 },
2680 }
2681
Mike53f7a7c2017-12-14 14:04:53 +03002682 # As config1 but using cfg:// references
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002683 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002684 'version': 1,
2685 'true_formatters': {
2686 'form1' : {
2687 'format' : '%(levelname)s ++ %(message)s',
2688 },
2689 },
2690 'handler_configs': {
2691 'hand1' : {
2692 'class' : 'logging.StreamHandler',
2693 'formatter' : 'form1',
2694 'level' : 'NOTSET',
2695 'stream' : 'ext://sys.stdout',
2696 },
2697 },
2698 'formatters' : 'cfg://true_formatters',
2699 'handlers' : {
2700 'hand1' : 'cfg://handler_configs[hand1]',
2701 },
2702 'loggers' : {
2703 'compiler.parser' : {
2704 'level' : 'DEBUG',
2705 'handlers' : ['hand1'],
2706 },
2707 },
2708 'root' : {
2709 'level' : 'WARNING',
2710 },
2711 }
2712
Mike53f7a7c2017-12-14 14:04:53 +03002713 # As config11 but missing the version key
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002714 config12 = {
2715 'true_formatters': {
2716 'form1' : {
2717 'format' : '%(levelname)s ++ %(message)s',
2718 },
2719 },
2720 'handler_configs': {
2721 'hand1' : {
2722 'class' : 'logging.StreamHandler',
2723 'formatter' : 'form1',
2724 'level' : 'NOTSET',
2725 'stream' : 'ext://sys.stdout',
2726 },
2727 },
2728 'formatters' : 'cfg://true_formatters',
2729 'handlers' : {
2730 'hand1' : 'cfg://handler_configs[hand1]',
2731 },
2732 'loggers' : {
2733 'compiler.parser' : {
2734 'level' : 'DEBUG',
2735 'handlers' : ['hand1'],
2736 },
2737 },
2738 'root' : {
2739 'level' : 'WARNING',
2740 },
2741 }
2742
Mike53f7a7c2017-12-14 14:04:53 +03002743 # As config11 but using an unsupported version
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002744 config13 = {
2745 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002746 'true_formatters': {
2747 'form1' : {
2748 'format' : '%(levelname)s ++ %(message)s',
2749 },
2750 },
2751 'handler_configs': {
2752 'hand1' : {
2753 'class' : 'logging.StreamHandler',
2754 'formatter' : 'form1',
2755 'level' : 'NOTSET',
2756 'stream' : 'ext://sys.stdout',
2757 },
2758 },
2759 'formatters' : 'cfg://true_formatters',
2760 'handlers' : {
2761 'hand1' : 'cfg://handler_configs[hand1]',
2762 },
2763 'loggers' : {
2764 'compiler.parser' : {
2765 'level' : 'DEBUG',
2766 'handlers' : ['hand1'],
2767 },
2768 },
2769 'root' : {
2770 'level' : 'WARNING',
2771 },
2772 }
2773
Vinay Sajip8d270232012-11-15 14:20:18 +00002774 # As config0, but with properties
2775 config14 = {
2776 'version': 1,
2777 'formatters': {
2778 'form1' : {
2779 'format' : '%(levelname)s ++ %(message)s',
2780 },
2781 },
2782 'handlers' : {
2783 'hand1' : {
2784 'class' : 'logging.StreamHandler',
2785 'formatter' : 'form1',
2786 'level' : 'NOTSET',
2787 'stream' : 'ext://sys.stdout',
2788 '.': {
2789 'foo': 'bar',
2790 'terminator': '!\n',
2791 }
2792 },
2793 },
2794 'root' : {
2795 'level' : 'WARNING',
2796 'handlers' : ['hand1'],
2797 },
2798 }
2799
Vinay Sajip3f885b52013-03-22 15:19:54 +00002800 out_of_order = {
2801 "version": 1,
2802 "formatters": {
2803 "mySimpleFormatter": {
Vinay Sajip28421c62013-03-29 17:56:54 +00002804 "format": "%(asctime)s (%(name)s) %(levelname)s: %(message)s",
2805 "style": "$"
Vinay Sajip3f885b52013-03-22 15:19:54 +00002806 }
2807 },
2808 "handlers": {
2809 "fileGlobal": {
2810 "class": "logging.StreamHandler",
2811 "level": "DEBUG",
2812 "formatter": "mySimpleFormatter"
2813 },
2814 "bufferGlobal": {
2815 "class": "logging.handlers.MemoryHandler",
2816 "capacity": 5,
2817 "formatter": "mySimpleFormatter",
2818 "target": "fileGlobal",
2819 "level": "DEBUG"
2820 }
2821 },
2822 "loggers": {
2823 "mymodule": {
2824 "level": "DEBUG",
2825 "handlers": ["bufferGlobal"],
2826 "propagate": "true"
2827 }
2828 }
2829 }
2830
BNMetrics18fb1fb2018-10-15 19:41:36 +01002831 # Configuration with custom logging.Formatter subclass as '()' key and 'validate' set to False
2832 custom_formatter_class_validate = {
2833 'version': 1,
2834 'formatters': {
2835 'form1': {
2836 '()': __name__ + '.ExceptionFormatter',
2837 'format': '%(levelname)s:%(name)s:%(message)s',
2838 'validate': False,
2839 },
2840 },
2841 'handlers' : {
2842 'hand1' : {
2843 'class': 'logging.StreamHandler',
2844 'formatter': 'form1',
2845 'level': 'NOTSET',
2846 'stream': 'ext://sys.stdout',
2847 },
2848 },
2849 "loggers": {
2850 "my_test_logger_custom_formatter": {
2851 "level": "DEBUG",
2852 "handlers": ["hand1"],
2853 "propagate": "true"
2854 }
2855 }
2856 }
2857
2858 # Configuration with custom logging.Formatter subclass as 'class' key and 'validate' set to False
2859 custom_formatter_class_validate2 = {
2860 'version': 1,
2861 'formatters': {
2862 'form1': {
2863 'class': __name__ + '.ExceptionFormatter',
2864 'format': '%(levelname)s:%(name)s:%(message)s',
2865 'validate': False,
2866 },
2867 },
2868 'handlers' : {
2869 'hand1' : {
2870 'class': 'logging.StreamHandler',
2871 'formatter': 'form1',
2872 'level': 'NOTSET',
2873 'stream': 'ext://sys.stdout',
2874 },
2875 },
2876 "loggers": {
2877 "my_test_logger_custom_formatter": {
2878 "level": "DEBUG",
2879 "handlers": ["hand1"],
2880 "propagate": "true"
2881 }
2882 }
2883 }
2884
2885 # Configuration with custom class that is not inherited from logging.Formatter
2886 custom_formatter_class_validate3 = {
2887 'version': 1,
2888 'formatters': {
2889 'form1': {
2890 'class': __name__ + '.myCustomFormatter',
2891 'format': '%(levelname)s:%(name)s:%(message)s',
2892 'validate': False,
2893 },
2894 },
2895 'handlers' : {
2896 'hand1' : {
2897 'class': 'logging.StreamHandler',
2898 'formatter': 'form1',
2899 'level': 'NOTSET',
2900 'stream': 'ext://sys.stdout',
2901 },
2902 },
2903 "loggers": {
2904 "my_test_logger_custom_formatter": {
2905 "level": "DEBUG",
2906 "handlers": ["hand1"],
2907 "propagate": "true"
2908 }
2909 }
2910 }
2911
2912 # Configuration with custom function and 'validate' set to False
2913 custom_formatter_with_function = {
2914 'version': 1,
2915 'formatters': {
2916 'form1': {
2917 '()': formatFunc,
2918 'format': '%(levelname)s:%(name)s:%(message)s',
2919 'validate': False,
2920 },
2921 },
2922 'handlers' : {
2923 'hand1' : {
2924 'class': 'logging.StreamHandler',
2925 'formatter': 'form1',
2926 'level': 'NOTSET',
2927 'stream': 'ext://sys.stdout',
2928 },
2929 },
2930 "loggers": {
2931 "my_test_logger_custom_formatter": {
2932 "level": "DEBUG",
2933 "handlers": ["hand1"],
2934 "propagate": "true"
2935 }
2936 }
2937 }
2938
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002939 def apply_config(self, conf):
2940 logging.config.dictConfig(conf)
2941
2942 def test_config0_ok(self):
2943 # A simple config which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002944 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002945 self.apply_config(self.config0)
2946 logger = logging.getLogger()
2947 # Won't output anything
2948 logger.info(self.next_message())
2949 # Outputs a message
2950 logger.error(self.next_message())
2951 self.assert_log_lines([
2952 ('ERROR', '2'),
2953 ], stream=output)
2954 # Original logger output is empty.
2955 self.assert_log_lines([])
2956
2957 def test_config1_ok(self, config=config1):
2958 # A config defining a sub-parser as well.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002959 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002960 self.apply_config(config)
2961 logger = logging.getLogger("compiler.parser")
2962 # Both will output a message
2963 logger.info(self.next_message())
2964 logger.error(self.next_message())
2965 self.assert_log_lines([
2966 ('INFO', '1'),
2967 ('ERROR', '2'),
2968 ], stream=output)
2969 # Original logger output is empty.
2970 self.assert_log_lines([])
2971
2972 def test_config2_failure(self):
2973 # A simple config which overrides the default settings.
2974 self.assertRaises(Exception, self.apply_config, self.config2)
2975
2976 def test_config2a_failure(self):
2977 # A simple config which overrides the default settings.
2978 self.assertRaises(Exception, self.apply_config, self.config2a)
2979
2980 def test_config2b_failure(self):
2981 # A simple config which overrides the default settings.
2982 self.assertRaises(Exception, self.apply_config, self.config2b)
2983
2984 def test_config3_failure(self):
2985 # A simple config which overrides the default settings.
2986 self.assertRaises(Exception, self.apply_config, self.config3)
2987
2988 def test_config4_ok(self):
2989 # A config specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002990 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002991 self.apply_config(self.config4)
2992 #logger = logging.getLogger()
2993 try:
2994 raise RuntimeError()
2995 except RuntimeError:
2996 logging.exception("just testing")
2997 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002998 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002999 "ERROR:root:just testing\nGot a [RuntimeError]\n")
3000 # Original logger output is empty
3001 self.assert_log_lines([])
3002
3003 def test_config4a_ok(self):
3004 # A config specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01003005 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003006 self.apply_config(self.config4a)
3007 #logger = logging.getLogger()
3008 try:
3009 raise RuntimeError()
3010 except RuntimeError:
3011 logging.exception("just testing")
3012 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00003013 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003014 "ERROR:root:just testing\nGot a [RuntimeError]\n")
3015 # Original logger output is empty
3016 self.assert_log_lines([])
3017
3018 def test_config5_ok(self):
3019 self.test_config1_ok(config=self.config5)
3020
3021 def test_config6_failure(self):
3022 self.assertRaises(Exception, self.apply_config, self.config6)
3023
3024 def test_config7_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003025 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003026 self.apply_config(self.config1)
3027 logger = logging.getLogger("compiler.parser")
3028 # Both will output a message
3029 logger.info(self.next_message())
3030 logger.error(self.next_message())
3031 self.assert_log_lines([
3032 ('INFO', '1'),
3033 ('ERROR', '2'),
3034 ], stream=output)
3035 # Original logger output is empty.
3036 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01003037 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003038 self.apply_config(self.config7)
3039 logger = logging.getLogger("compiler.parser")
3040 self.assertTrue(logger.disabled)
3041 logger = logging.getLogger("compiler.lexer")
3042 # Both will output a message
3043 logger.info(self.next_message())
3044 logger.error(self.next_message())
3045 self.assert_log_lines([
3046 ('INFO', '3'),
3047 ('ERROR', '4'),
3048 ], stream=output)
3049 # Original logger output is empty.
3050 self.assert_log_lines([])
3051
Mike53f7a7c2017-12-14 14:04:53 +03003052 # Same as test_config_7_ok but don't disable old loggers.
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003053 def test_config_8_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003054 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003055 self.apply_config(self.config1)
3056 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003057 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003058 logger.info(self.next_message())
3059 logger.error(self.next_message())
3060 self.assert_log_lines([
3061 ('INFO', '1'),
3062 ('ERROR', '2'),
3063 ], stream=output)
3064 # Original logger output is empty.
3065 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01003066 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003067 self.apply_config(self.config8)
3068 logger = logging.getLogger("compiler.parser")
3069 self.assertFalse(logger.disabled)
3070 # Both will output a message
3071 logger.info(self.next_message())
3072 logger.error(self.next_message())
3073 logger = logging.getLogger("compiler.lexer")
3074 # Both will output a message
3075 logger.info(self.next_message())
3076 logger.error(self.next_message())
3077 self.assert_log_lines([
3078 ('INFO', '3'),
3079 ('ERROR', '4'),
3080 ('INFO', '5'),
3081 ('ERROR', '6'),
3082 ], stream=output)
3083 # Original logger output is empty.
3084 self.assert_log_lines([])
3085
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003086 def test_config_8a_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003087 with support.captured_stdout() as output:
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003088 self.apply_config(self.config1a)
3089 logger = logging.getLogger("compiler.parser")
3090 # See issue #11424. compiler-hyphenated sorts
3091 # between compiler and compiler.xyz and this
3092 # was preventing compiler.xyz from being included
3093 # in the child loggers of compiler because of an
3094 # overzealous loop termination condition.
3095 hyphenated = logging.getLogger('compiler-hyphenated')
3096 # All will output a message
3097 logger.info(self.next_message())
3098 logger.error(self.next_message())
3099 hyphenated.critical(self.next_message())
3100 self.assert_log_lines([
3101 ('INFO', '1'),
3102 ('ERROR', '2'),
3103 ('CRITICAL', '3'),
3104 ], stream=output)
3105 # Original logger output is empty.
3106 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01003107 with support.captured_stdout() as output:
Vinay Sajip9f9991c2011-03-07 18:02:57 +00003108 self.apply_config(self.config8a)
3109 logger = logging.getLogger("compiler.parser")
3110 self.assertFalse(logger.disabled)
3111 # Both will output a message
3112 logger.info(self.next_message())
3113 logger.error(self.next_message())
3114 logger = logging.getLogger("compiler.lexer")
3115 # Both will output a message
3116 logger.info(self.next_message())
3117 logger.error(self.next_message())
3118 # Will not appear
3119 hyphenated.critical(self.next_message())
3120 self.assert_log_lines([
3121 ('INFO', '4'),
3122 ('ERROR', '5'),
3123 ('INFO', '6'),
3124 ('ERROR', '7'),
3125 ], stream=output)
3126 # Original logger output is empty.
3127 self.assert_log_lines([])
3128
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003129 def test_config_9_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003130 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003131 self.apply_config(self.config9)
3132 logger = logging.getLogger("compiler.parser")
Mike53f7a7c2017-12-14 14:04:53 +03003133 # Nothing will be output since both handler and logger are set to WARNING
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003134 logger.info(self.next_message())
3135 self.assert_log_lines([], stream=output)
3136 self.apply_config(self.config9a)
Mike53f7a7c2017-12-14 14:04:53 +03003137 # Nothing will be output since handler is still set to WARNING
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003138 logger.info(self.next_message())
3139 self.assert_log_lines([], stream=output)
3140 self.apply_config(self.config9b)
Mike53f7a7c2017-12-14 14:04:53 +03003141 # Message should now be output
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003142 logger.info(self.next_message())
3143 self.assert_log_lines([
3144 ('INFO', '3'),
3145 ], stream=output)
3146
3147 def test_config_10_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003148 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003149 self.apply_config(self.config10)
3150 logger = logging.getLogger("compiler.parser")
3151 logger.warning(self.next_message())
3152 logger = logging.getLogger('compiler')
Mike53f7a7c2017-12-14 14:04:53 +03003153 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003154 logger.warning(self.next_message())
3155 logger = logging.getLogger('compiler.lexer')
Mike53f7a7c2017-12-14 14:04:53 +03003156 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003157 logger.warning(self.next_message())
3158 logger = logging.getLogger("compiler.parser.codegen")
Mike53f7a7c2017-12-14 14:04:53 +03003159 # Output, as not filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003160 logger.error(self.next_message())
3161 self.assert_log_lines([
3162 ('WARNING', '1'),
3163 ('ERROR', '4'),
3164 ], stream=output)
3165
3166 def test_config11_ok(self):
3167 self.test_config1_ok(self.config11)
3168
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00003169 def test_config12_failure(self):
3170 self.assertRaises(Exception, self.apply_config, self.config12)
3171
3172 def test_config13_failure(self):
3173 self.assertRaises(Exception, self.apply_config, self.config13)
3174
Vinay Sajip8d270232012-11-15 14:20:18 +00003175 def test_config14_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003176 with support.captured_stdout() as output:
Vinay Sajip8d270232012-11-15 14:20:18 +00003177 self.apply_config(self.config14)
3178 h = logging._handlers['hand1']
3179 self.assertEqual(h.foo, 'bar')
3180 self.assertEqual(h.terminator, '!\n')
3181 logging.warning('Exclamation')
3182 self.assertTrue(output.getvalue().endswith('Exclamation!\n'))
3183
Xtreak087570a2018-07-02 14:27:46 +05303184 def test_config15_ok(self):
3185
3186 def cleanup(h1, fn):
3187 h1.close()
3188 os.remove(fn)
3189
3190 with self.check_no_resource_warning():
3191 fd, fn = tempfile.mkstemp(".log", "test_logging-X-")
3192 os.close(fd)
3193
3194 config = {
3195 "version": 1,
3196 "handlers": {
3197 "file": {
3198 "class": "logging.FileHandler",
3199 "filename": fn
3200 }
3201 },
3202 "root": {
3203 "handlers": ["file"]
3204 }
3205 }
3206
3207 self.apply_config(config)
3208 self.apply_config(config)
3209
3210 handler = logging.root.handlers[0]
3211 self.addCleanup(cleanup, handler, fn)
3212
Vinay Sajip4ded5512012-10-02 15:56:16 +01003213 def setup_via_listener(self, text, verify=None):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00003214 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00003215 # Ask for a randomly assigned port (by using port 0)
Vinay Sajip4ded5512012-10-02 15:56:16 +01003216 t = logging.config.listen(0, verify)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003217 t.start()
3218 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00003219 # Now get the port allocated
3220 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003221 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003222 try:
3223 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
3224 sock.settimeout(2.0)
3225 sock.connect(('localhost', port))
3226
3227 slen = struct.pack('>L', len(text))
3228 s = slen + text
3229 sentsofar = 0
3230 left = len(s)
3231 while left > 0:
3232 sent = sock.send(s[sentsofar:])
3233 sentsofar += sent
3234 left -= sent
3235 sock.close()
3236 finally:
3237 t.ready.wait(2.0)
3238 logging.config.stopListening()
Hai Shie80697d2020-05-28 06:10:27 +08003239 threading_helper.join_thread(t)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003240
3241 def test_listen_config_10_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003242 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003243 self.setup_via_listener(json.dumps(self.config10))
3244 logger = logging.getLogger("compiler.parser")
3245 logger.warning(self.next_message())
3246 logger = logging.getLogger('compiler')
Mike53f7a7c2017-12-14 14:04:53 +03003247 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003248 logger.warning(self.next_message())
3249 logger = logging.getLogger('compiler.lexer')
Mike53f7a7c2017-12-14 14:04:53 +03003250 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003251 logger.warning(self.next_message())
3252 logger = logging.getLogger("compiler.parser.codegen")
Mike53f7a7c2017-12-14 14:04:53 +03003253 # Output, as not filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003254 logger.error(self.next_message())
3255 self.assert_log_lines([
3256 ('WARNING', '1'),
3257 ('ERROR', '4'),
3258 ], stream=output)
3259
3260 def test_listen_config_1_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003261 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003262 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
3263 logger = logging.getLogger("compiler.parser")
3264 # Both will output a message
3265 logger.info(self.next_message())
3266 logger.error(self.next_message())
3267 self.assert_log_lines([
3268 ('INFO', '1'),
3269 ('ERROR', '2'),
3270 ], stream=output)
3271 # Original logger output is empty.
3272 self.assert_log_lines([])
3273
Vinay Sajip4ded5512012-10-02 15:56:16 +01003274 def test_listen_verify(self):
3275
3276 def verify_fail(stuff):
3277 return None
3278
3279 def verify_reverse(stuff):
3280 return stuff[::-1]
3281
3282 logger = logging.getLogger("compiler.parser")
3283 to_send = textwrap.dedent(ConfigFileTest.config1)
3284 # First, specify a verification function that will fail.
3285 # We expect to see no output, since our configuration
3286 # never took effect.
Vinay Sajip1feedb42014-05-31 08:19:12 +01003287 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003288 self.setup_via_listener(to_send, verify_fail)
3289 # Both will output a message
3290 logger.info(self.next_message())
3291 logger.error(self.next_message())
3292 self.assert_log_lines([], stream=output)
3293 # Original logger output has the stuff we logged.
3294 self.assert_log_lines([
3295 ('INFO', '1'),
3296 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003297 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003298
3299 # Now, perform no verification. Our configuration
3300 # should take effect.
3301
Vinay Sajip1feedb42014-05-31 08:19:12 +01003302 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003303 self.setup_via_listener(to_send) # no verify callable specified
3304 logger = logging.getLogger("compiler.parser")
3305 # Both will output a message
3306 logger.info(self.next_message())
3307 logger.error(self.next_message())
3308 self.assert_log_lines([
3309 ('INFO', '3'),
3310 ('ERROR', '4'),
3311 ], stream=output)
3312 # Original logger output still has the stuff we logged before.
3313 self.assert_log_lines([
3314 ('INFO', '1'),
3315 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003316 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003317
3318 # Now, perform verification which transforms the bytes.
3319
Vinay Sajip1feedb42014-05-31 08:19:12 +01003320 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003321 self.setup_via_listener(to_send[::-1], verify_reverse)
3322 logger = logging.getLogger("compiler.parser")
3323 # Both will output a message
3324 logger.info(self.next_message())
3325 logger.error(self.next_message())
3326 self.assert_log_lines([
3327 ('INFO', '5'),
3328 ('ERROR', '6'),
3329 ], stream=output)
3330 # Original logger output still has the stuff we logged before.
3331 self.assert_log_lines([
3332 ('INFO', '1'),
3333 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003334 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003335
Vinay Sajip3f885b52013-03-22 15:19:54 +00003336 def test_out_of_order(self):
BNMetrics18fb1fb2018-10-15 19:41:36 +01003337 self.assertRaises(ValueError, self.apply_config, self.out_of_order)
3338
3339 def test_out_of_order_with_dollar_style(self):
Pablo Galindo137b0632018-10-16 15:17:57 +01003340 config = copy.deepcopy(self.out_of_order)
BNMetrics18fb1fb2018-10-15 19:41:36 +01003341 config['formatters']['mySimpleFormatter']['format'] = "${asctime} (${name}) ${levelname}: ${message}"
3342
3343 self.apply_config(config)
Vinay Sajip3f885b52013-03-22 15:19:54 +00003344 handler = logging.getLogger('mymodule').handlers[0]
3345 self.assertIsInstance(handler.target, logging.Handler)
Vinay Sajip28421c62013-03-29 17:56:54 +00003346 self.assertIsInstance(handler.formatter._style,
3347 logging.StringTemplateStyle)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003348
BNMetrics18fb1fb2018-10-15 19:41:36 +01003349 def test_custom_formatter_class_with_validate(self):
3350 self.apply_config(self.custom_formatter_class_validate)
3351 handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0]
3352 self.assertIsInstance(handler.formatter, ExceptionFormatter)
3353
3354 def test_custom_formatter_class_with_validate2(self):
3355 self.apply_config(self.custom_formatter_class_validate2)
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_with_wrong_fmt(self):
3360 config = self.custom_formatter_class_validate.copy()
3361 config['formatters']['form1']['style'] = "$"
3362
3363 # Exception should not be raise as we have configured 'validate' to False
3364 self.apply_config(config)
3365 handler = logging.getLogger("my_test_logger_custom_formatter").handlers[0]
3366 self.assertIsInstance(handler.formatter, ExceptionFormatter)
3367
3368 def test_custom_formatter_class_with_validate3(self):
3369 self.assertRaises(ValueError, self.apply_config, self.custom_formatter_class_validate3)
3370
3371 def test_custom_formatter_function_with_validate(self):
3372 self.assertRaises(ValueError, self.apply_config, self.custom_formatter_with_function)
3373
Vinay Sajip373baef2011-04-26 20:05:24 +01003374 def test_baseconfig(self):
3375 d = {
3376 'atuple': (1, 2, 3),
3377 'alist': ['a', 'b', 'c'],
3378 'adict': {'d': 'e', 'f': 3 },
3379 'nest1': ('g', ('h', 'i'), 'j'),
3380 'nest2': ['k', ['l', 'm'], 'n'],
3381 'nest3': ['o', 'cfg://alist', 'p'],
3382 }
3383 bc = logging.config.BaseConfigurator(d)
3384 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
3385 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
3386 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
3387 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
3388 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
3389 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
3390 v = bc.convert('cfg://nest3')
3391 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
3392 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
3393 self.assertRaises(ValueError, bc.convert, 'cfg://!')
3394 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003395
Vinay Sajip46abfc12020-01-01 19:32:11 +00003396 def test_namedtuple(self):
3397 # see bpo-39142
3398 from collections import namedtuple
3399
3400 class MyHandler(logging.StreamHandler):
3401 def __init__(self, resource, *args, **kwargs):
3402 super().__init__(*args, **kwargs)
3403 self.resource: namedtuple = resource
3404
3405 def emit(self, record):
3406 record.msg += f' {self.resource.type}'
3407 return super().emit(record)
3408
3409 Resource = namedtuple('Resource', ['type', 'labels'])
3410 resource = Resource(type='my_type', labels=['a'])
3411
3412 config = {
3413 'version': 1,
3414 'handlers': {
3415 'myhandler': {
3416 '()': MyHandler,
3417 'resource': resource
3418 }
3419 },
3420 'root': {'level': 'INFO', 'handlers': ['myhandler']},
3421 }
3422 with support.captured_stderr() as stderr:
3423 self.apply_config(config)
3424 logging.info('some log')
3425 self.assertEqual(stderr.getvalue(), 'some log my_type\n')
3426
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003427class ManagerTest(BaseTest):
3428 def test_manager_loggerclass(self):
3429 logged = []
3430
3431 class MyLogger(logging.Logger):
3432 def _log(self, level, msg, args, exc_info=None, extra=None):
3433 logged.append(msg)
3434
3435 man = logging.Manager(None)
3436 self.assertRaises(TypeError, man.setLoggerClass, int)
3437 man.setLoggerClass(MyLogger)
3438 logger = man.getLogger('test')
3439 logger.warning('should appear in logged')
3440 logging.warning('should not appear in logged')
3441
3442 self.assertEqual(logged, ['should appear in logged'])
3443
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003444 def test_set_log_record_factory(self):
3445 man = logging.Manager(None)
3446 expected = object()
3447 man.setLogRecordFactory(expected)
3448 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003449
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003450class ChildLoggerTest(BaseTest):
3451 def test_child_loggers(self):
3452 r = logging.getLogger()
3453 l1 = logging.getLogger('abc')
3454 l2 = logging.getLogger('def.ghi')
3455 c1 = r.getChild('xyz')
3456 c2 = r.getChild('uvw.xyz')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02003457 self.assertIs(c1, logging.getLogger('xyz'))
3458 self.assertIs(c2, logging.getLogger('uvw.xyz'))
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003459 c1 = l1.getChild('def')
3460 c2 = c1.getChild('ghi')
3461 c3 = l1.getChild('def.ghi')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02003462 self.assertIs(c1, logging.getLogger('abc.def'))
3463 self.assertIs(c2, logging.getLogger('abc.def.ghi'))
3464 self.assertIs(c2, c3)
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003465
3466
Vinay Sajip6fac8172010-10-19 20:44:14 +00003467class DerivedLogRecord(logging.LogRecord):
3468 pass
3469
Vinay Sajip61561522010-12-03 11:50:38 +00003470class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00003471
3472 def setUp(self):
3473 class CheckingFilter(logging.Filter):
3474 def __init__(self, cls):
3475 self.cls = cls
3476
3477 def filter(self, record):
3478 t = type(record)
3479 if t is not self.cls:
3480 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
3481 self.cls)
3482 raise TypeError(msg)
3483 return True
3484
3485 BaseTest.setUp(self)
3486 self.filter = CheckingFilter(DerivedLogRecord)
3487 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00003488 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00003489
3490 def tearDown(self):
3491 self.root_logger.removeFilter(self.filter)
3492 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00003493 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00003494
3495 def test_logrecord_class(self):
3496 self.assertRaises(TypeError, self.root_logger.warning,
3497 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00003498 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00003499 self.root_logger.error(self.next_message())
3500 self.assert_log_lines([
3501 ('root', 'ERROR', '2'),
3502 ])
3503
3504
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003505class QueueHandlerTest(BaseTest):
3506 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003507 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003508
3509 def setUp(self):
3510 BaseTest.setUp(self)
3511 self.queue = queue.Queue(-1)
3512 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
favlladfe3442017-08-01 20:12:26 +02003513 self.name = 'que'
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003514 self.que_logger = logging.getLogger('que')
3515 self.que_logger.propagate = False
3516 self.que_logger.setLevel(logging.WARNING)
3517 self.que_logger.addHandler(self.que_hdlr)
3518
3519 def tearDown(self):
3520 self.que_hdlr.close()
3521 BaseTest.tearDown(self)
3522
3523 def test_queue_handler(self):
3524 self.que_logger.debug(self.next_message())
3525 self.assertRaises(queue.Empty, self.queue.get_nowait)
3526 self.que_logger.info(self.next_message())
3527 self.assertRaises(queue.Empty, self.queue.get_nowait)
3528 msg = self.next_message()
3529 self.que_logger.warning(msg)
3530 data = self.queue.get_nowait()
3531 self.assertTrue(isinstance(data, logging.LogRecord))
3532 self.assertEqual(data.name, self.que_logger.name)
3533 self.assertEqual((data.msg, data.args), (msg, None))
3534
favlladfe3442017-08-01 20:12:26 +02003535 def test_formatting(self):
3536 msg = self.next_message()
3537 levelname = logging.getLevelName(logging.WARNING)
3538 log_format_str = '{name} -> {levelname}: {message}'
3539 formatted_msg = log_format_str.format(name=self.name,
3540 levelname=levelname, message=msg)
3541 formatter = logging.Formatter(self.log_format)
3542 self.que_hdlr.setFormatter(formatter)
3543 self.que_logger.warning(msg)
3544 log_record = self.queue.get_nowait()
3545 self.assertEqual(formatted_msg, log_record.msg)
3546 self.assertEqual(formatted_msg, log_record.message)
3547
Victor Stinnercafa2ef2011-05-02 16:11:28 +02003548 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3549 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01003550 def test_queue_listener(self):
Serhiy Storchaka515fce42020-04-25 11:35:18 +03003551 handler = TestHandler(support.Matcher())
Vinay Sajipe723e962011-04-15 22:27:17 +01003552 listener = logging.handlers.QueueListener(self.queue, handler)
3553 listener.start()
3554 try:
3555 self.que_logger.warning(self.next_message())
3556 self.que_logger.error(self.next_message())
3557 self.que_logger.critical(self.next_message())
3558 finally:
3559 listener.stop()
3560 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
3561 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
3562 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
Vinay Sajip365701a2015-02-09 19:49:00 +00003563 handler.close()
3564
3565 # Now test with respect_handler_level set
3566
Serhiy Storchaka515fce42020-04-25 11:35:18 +03003567 handler = TestHandler(support.Matcher())
Vinay Sajip365701a2015-02-09 19:49:00 +00003568 handler.setLevel(logging.CRITICAL)
3569 listener = logging.handlers.QueueListener(self.queue, handler,
3570 respect_handler_level=True)
3571 listener.start()
3572 try:
3573 self.que_logger.warning(self.next_message())
3574 self.que_logger.error(self.next_message())
3575 self.que_logger.critical(self.next_message())
3576 finally:
3577 listener.stop()
3578 self.assertFalse(handler.matches(levelno=logging.WARNING, message='4'))
3579 self.assertFalse(handler.matches(levelno=logging.ERROR, message='5'))
3580 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='6'))
Cheryl Sabellad345bb42018-09-25 19:00:08 -04003581 handler.close()
3582
3583 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3584 'logging.handlers.QueueListener required for this test')
3585 def test_queue_listener_with_StreamHandler(self):
3586 # Test that traceback only appends once (bpo-34334).
3587 listener = logging.handlers.QueueListener(self.queue, self.root_hdlr)
3588 listener.start()
3589 try:
3590 1 / 0
3591 except ZeroDivisionError as e:
3592 exc = e
3593 self.que_logger.exception(self.next_message(), exc_info=exc)
3594 listener.stop()
3595 self.assertEqual(self.stream.getvalue().strip().count('Traceback'), 1)
Vinay Sajip365701a2015-02-09 19:49:00 +00003596
Xtreak2dad9602019-04-07 13:21:27 +05303597 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3598 'logging.handlers.QueueListener required for this test')
3599 def test_queue_listener_with_multiple_handlers(self):
3600 # Test that queue handler format doesn't affect other handler formats (bpo-35726).
3601 self.que_hdlr.setFormatter(self.root_formatter)
3602 self.que_logger.addHandler(self.root_hdlr)
3603
3604 listener = logging.handlers.QueueListener(self.queue, self.que_hdlr)
3605 listener.start()
3606 self.que_logger.error("error")
3607 listener.stop()
3608 self.assertEqual(self.stream.getvalue().strip(), "que -> ERROR: error")
3609
Vinay Sajipd61910c2016-09-08 01:13:39 +01003610if hasattr(logging.handlers, 'QueueListener'):
3611 import multiprocessing
3612 from unittest.mock import patch
3613
3614 class QueueListenerTest(BaseTest):
3615 """
3616 Tests based on patch submitted for issue #27930. Ensure that
3617 QueueListener handles all log messages.
3618 """
3619
3620 repeat = 20
3621
3622 @staticmethod
3623 def setup_and_log(log_queue, ident):
3624 """
3625 Creates a logger with a QueueHandler that logs to a queue read by a
3626 QueueListener. Starts the listener, logs five messages, and stops
3627 the listener.
3628 """
3629 logger = logging.getLogger('test_logger_with_id_%s' % ident)
3630 logger.setLevel(logging.DEBUG)
3631 handler = logging.handlers.QueueHandler(log_queue)
3632 logger.addHandler(handler)
3633 listener = logging.handlers.QueueListener(log_queue)
3634 listener.start()
3635
3636 logger.info('one')
3637 logger.info('two')
3638 logger.info('three')
3639 logger.info('four')
3640 logger.info('five')
3641
3642 listener.stop()
3643 logger.removeHandler(handler)
3644 handler.close()
3645
3646 @patch.object(logging.handlers.QueueListener, 'handle')
3647 def test_handle_called_with_queue_queue(self, mock_handle):
3648 for i in range(self.repeat):
3649 log_queue = queue.Queue()
3650 self.setup_and_log(log_queue, '%s_%s' % (self.id(), i))
3651 self.assertEqual(mock_handle.call_count, 5 * self.repeat,
3652 'correct number of handled log messages')
3653
3654 @patch.object(logging.handlers.QueueListener, 'handle')
3655 def test_handle_called_with_mp_queue(self, mock_handle):
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003656 # bpo-28668: The multiprocessing (mp) module is not functional
xdegayebf2b65e2017-12-01 08:08:49 +01003657 # when the mp.synchronize module cannot be imported.
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003658 support.skip_if_broken_multiprocessing_synchronize()
Vinay Sajipd61910c2016-09-08 01:13:39 +01003659 for i in range(self.repeat):
3660 log_queue = multiprocessing.Queue()
3661 self.setup_and_log(log_queue, '%s_%s' % (self.id(), i))
Victor Stinner8ca2f2f2017-04-26 15:56:25 +02003662 log_queue.close()
3663 log_queue.join_thread()
Vinay Sajipd61910c2016-09-08 01:13:39 +01003664 self.assertEqual(mock_handle.call_count, 5 * self.repeat,
3665 'correct number of handled log messages')
3666
3667 @staticmethod
3668 def get_all_from_queue(log_queue):
3669 try:
3670 while True:
3671 yield log_queue.get_nowait()
3672 except queue.Empty:
3673 return []
3674
3675 def test_no_messages_in_queue_after_stop(self):
3676 """
3677 Five messages are logged then the QueueListener is stopped. This
3678 test then gets everything off the queue. Failure of this test
3679 indicates that messages were not registered on the queue until
3680 _after_ the QueueListener stopped.
3681 """
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003682 # bpo-28668: The multiprocessing (mp) module is not functional
xdegayebf2b65e2017-12-01 08:08:49 +01003683 # when the mp.synchronize module cannot be imported.
Victor Stinnerddbeb2f2020-06-18 14:53:19 +02003684 support.skip_if_broken_multiprocessing_synchronize()
Vinay Sajipd61910c2016-09-08 01:13:39 +01003685 for i in range(self.repeat):
3686 queue = multiprocessing.Queue()
3687 self.setup_and_log(queue, '%s_%s' %(self.id(), i))
3688 # time.sleep(1)
3689 items = list(self.get_all_from_queue(queue))
Victor Stinner8ca2f2f2017-04-26 15:56:25 +02003690 queue.close()
3691 queue.join_thread()
3692
Vinay Sajipd61910c2016-09-08 01:13:39 +01003693 expected = [[], [logging.handlers.QueueListener._sentinel]]
3694 self.assertIn(items, expected,
3695 'Found unexpected messages in queue: %s' % (
3696 [m.msg if isinstance(m, logging.LogRecord)
3697 else m for m in items]))
3698
Bar Harel6b282e12019-06-01 12:19:09 +03003699 def test_calls_task_done_after_stop(self):
3700 # Issue 36813: Make sure queue.join does not deadlock.
3701 log_queue = queue.Queue()
3702 listener = logging.handlers.QueueListener(log_queue)
3703 listener.start()
3704 listener.stop()
3705 with self.assertRaises(ValueError):
3706 # Make sure all tasks are done and .join won't block.
3707 log_queue.task_done()
3708
Vinay Sajipe723e962011-04-15 22:27:17 +01003709
Vinay Sajip37eb3382011-04-26 20:26:41 +01003710ZERO = datetime.timedelta(0)
3711
3712class UTC(datetime.tzinfo):
3713 def utcoffset(self, dt):
3714 return ZERO
3715
3716 dst = utcoffset
3717
3718 def tzname(self, dt):
3719 return 'UTC'
3720
3721utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01003722
Vinay Sajipa39c5712010-10-25 13:57:39 +00003723class FormatterTest(unittest.TestCase):
3724 def setUp(self):
3725 self.common = {
3726 'name': 'formatter.test',
3727 'level': logging.DEBUG,
3728 'pathname': os.path.join('path', 'to', 'dummy.ext'),
3729 'lineno': 42,
3730 'exc_info': None,
3731 'func': None,
3732 'msg': 'Message with %d %s',
3733 'args': (2, 'placeholders'),
3734 }
3735 self.variants = {
Bar Harel8f192d12020-06-18 17:18:58 +03003736 'custom': {
3737 'custom': 1234
3738 }
Vinay Sajipa39c5712010-10-25 13:57:39 +00003739 }
3740
3741 def get_record(self, name=None):
3742 result = dict(self.common)
3743 if name is not None:
3744 result.update(self.variants[name])
3745 return logging.makeLogRecord(result)
3746
BNMetrics18fb1fb2018-10-15 19:41:36 +01003747 def assert_error_message(self, exception, message, *args, **kwargs):
3748 try:
3749 self.assertRaises(exception, *args, **kwargs)
3750 except exception as e:
3751 self.assertEqual(message, e.message)
3752
Vinay Sajipa39c5712010-10-25 13:57:39 +00003753 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003754 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003755 r = self.get_record()
3756 f = logging.Formatter('${%(message)s}')
3757 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
3758 f = logging.Formatter('%(random)s')
BNMetrics18fb1fb2018-10-15 19:41:36 +01003759 self.assertRaises(ValueError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003760 self.assertFalse(f.usesTime())
3761 f = logging.Formatter('%(asctime)s')
3762 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003763 f = logging.Formatter('%(asctime)-15s')
3764 self.assertTrue(f.usesTime())
BNMetrics18fb1fb2018-10-15 19:41:36 +01003765 f = logging.Formatter('%(asctime)#15s')
3766 self.assertTrue(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003767
3768 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003769 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003770 r = self.get_record()
3771 f = logging.Formatter('$%{message}%$', style='{')
3772 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3773 f = logging.Formatter('{random}', style='{')
BNMetrics18fb1fb2018-10-15 19:41:36 +01003774 self.assertRaises(ValueError, f.format, r)
3775 f = logging.Formatter("{message}", style='{')
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003776 self.assertFalse(f.usesTime())
3777 f = logging.Formatter('{asctime}', style='{')
3778 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003779 f = logging.Formatter('{asctime!s:15}', style='{')
3780 self.assertTrue(f.usesTime())
3781 f = logging.Formatter('{asctime:15}', style='{')
3782 self.assertTrue(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003783
3784 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003785 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003786 r = self.get_record()
BNMetrics18fb1fb2018-10-15 19:41:36 +01003787 f = logging.Formatter('${message}', style='$')
3788 self.assertEqual(f.format(r), 'Message with 2 placeholders')
Vinay Sajipa39c5712010-10-25 13:57:39 +00003789 f = logging.Formatter('$message', style='$')
3790 self.assertEqual(f.format(r), 'Message with 2 placeholders')
3791 f = logging.Formatter('$$%${message}%$$', style='$')
3792 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3793 f = logging.Formatter('${random}', style='$')
BNMetrics18fb1fb2018-10-15 19:41:36 +01003794 self.assertRaises(ValueError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003795 self.assertFalse(f.usesTime())
3796 f = logging.Formatter('${asctime}', style='$')
3797 self.assertTrue(f.usesTime())
3798 f = logging.Formatter('$asctime', style='$')
3799 self.assertTrue(f.usesTime())
BNMetrics18fb1fb2018-10-15 19:41:36 +01003800 f = logging.Formatter('${message}', style='$')
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003801 self.assertFalse(f.usesTime())
BNMetrics18fb1fb2018-10-15 19:41:36 +01003802 f = logging.Formatter('${asctime}--', style='$')
3803 self.assertTrue(f.usesTime())
3804
3805 def test_format_validate(self):
3806 # Check correct formatting
3807 # Percentage style
3808 f = logging.Formatter("%(levelname)-15s - %(message) 5s - %(process)03d - %(module) - %(asctime)*.3s")
3809 self.assertEqual(f._fmt, "%(levelname)-15s - %(message) 5s - %(process)03d - %(module) - %(asctime)*.3s")
3810 f = logging.Formatter("%(asctime)*s - %(asctime)*.3s - %(process)-34.33o")
3811 self.assertEqual(f._fmt, "%(asctime)*s - %(asctime)*.3s - %(process)-34.33o")
3812 f = logging.Formatter("%(process)#+027.23X")
3813 self.assertEqual(f._fmt, "%(process)#+027.23X")
3814 f = logging.Formatter("%(foo)#.*g")
3815 self.assertEqual(f._fmt, "%(foo)#.*g")
3816
3817 # StrFormat Style
3818 f = logging.Formatter("$%{message}%$ - {asctime!a:15} - {customfield['key']}", style="{")
3819 self.assertEqual(f._fmt, "$%{message}%$ - {asctime!a:15} - {customfield['key']}")
3820 f = logging.Formatter("{process:.2f} - {custom.f:.4f}", style="{")
3821 self.assertEqual(f._fmt, "{process:.2f} - {custom.f:.4f}")
3822 f = logging.Formatter("{customfield!s:#<30}", style="{")
3823 self.assertEqual(f._fmt, "{customfield!s:#<30}")
3824 f = logging.Formatter("{message!r}", style="{")
3825 self.assertEqual(f._fmt, "{message!r}")
3826 f = logging.Formatter("{message!s}", style="{")
3827 self.assertEqual(f._fmt, "{message!s}")
3828 f = logging.Formatter("{message!a}", style="{")
3829 self.assertEqual(f._fmt, "{message!a}")
3830 f = logging.Formatter("{process!r:4.2}", style="{")
3831 self.assertEqual(f._fmt, "{process!r:4.2}")
3832 f = logging.Formatter("{process!s:<#30,.12f}- {custom:=+#30,.1d} - {module:^30}", style="{")
3833 self.assertEqual(f._fmt, "{process!s:<#30,.12f}- {custom:=+#30,.1d} - {module:^30}")
3834 f = logging.Formatter("{process!s:{w},.{p}}", style="{")
3835 self.assertEqual(f._fmt, "{process!s:{w},.{p}}")
3836 f = logging.Formatter("{foo:12.{p}}", style="{")
3837 self.assertEqual(f._fmt, "{foo:12.{p}}")
3838 f = logging.Formatter("{foo:{w}.6}", style="{")
3839 self.assertEqual(f._fmt, "{foo:{w}.6}")
3840 f = logging.Formatter("{foo[0].bar[1].baz}", style="{")
3841 self.assertEqual(f._fmt, "{foo[0].bar[1].baz}")
3842 f = logging.Formatter("{foo[k1].bar[k2].baz}", style="{")
3843 self.assertEqual(f._fmt, "{foo[k1].bar[k2].baz}")
3844 f = logging.Formatter("{12[k1].bar[k2].baz}", style="{")
3845 self.assertEqual(f._fmt, "{12[k1].bar[k2].baz}")
3846
3847 # Dollar style
3848 f = logging.Formatter("${asctime} - $message", style="$")
3849 self.assertEqual(f._fmt, "${asctime} - $message")
3850 f = logging.Formatter("$bar $$", style="$")
3851 self.assertEqual(f._fmt, "$bar $$")
3852 f = logging.Formatter("$bar $$$$", style="$")
3853 self.assertEqual(f._fmt, "$bar $$$$") # this would print two $($$)
3854
3855 # Testing when ValueError being raised from incorrect format
3856 # Percentage Style
3857 self.assertRaises(ValueError, logging.Formatter, "%(asctime)Z")
3858 self.assertRaises(ValueError, logging.Formatter, "%(asctime)b")
3859 self.assertRaises(ValueError, logging.Formatter, "%(asctime)*")
3860 self.assertRaises(ValueError, logging.Formatter, "%(asctime)*3s")
3861 self.assertRaises(ValueError, logging.Formatter, "%(asctime)_")
3862 self.assertRaises(ValueError, logging.Formatter, '{asctime}')
3863 self.assertRaises(ValueError, logging.Formatter, '${message}')
3864 self.assertRaises(ValueError, logging.Formatter, '%(foo)#12.3*f') # with both * and decimal number as precision
3865 self.assertRaises(ValueError, logging.Formatter, '%(foo)0*.8*f')
3866
3867 # StrFormat Style
3868 # Testing failure for '-' in field name
3869 self.assert_error_message(
3870 ValueError,
3871 "invalid field name/expression: 'name-thing'",
3872 logging.Formatter, "{name-thing}", style="{"
3873 )
3874 # Testing failure for style mismatch
3875 self.assert_error_message(
3876 ValueError,
3877 "invalid format: no fields",
3878 logging.Formatter, '%(asctime)s', style='{'
3879 )
3880 # Testing failure for invalid conversion
3881 self.assert_error_message(
3882 ValueError,
3883 "invalid conversion: 'Z'"
3884 )
3885 self.assertRaises(ValueError, logging.Formatter, '{asctime!s:#30,15f}', style='{')
3886 self.assert_error_message(
3887 ValueError,
3888 "invalid format: expected ':' after conversion specifier",
3889 logging.Formatter, '{asctime!aa:15}', style='{'
3890 )
3891 # Testing failure for invalid spec
3892 self.assert_error_message(
3893 ValueError,
3894 "bad specifier: '.2ff'",
3895 logging.Formatter, '{process:.2ff}', style='{'
3896 )
3897 self.assertRaises(ValueError, logging.Formatter, '{process:.2Z}', style='{')
3898 self.assertRaises(ValueError, logging.Formatter, '{process!s:<##30,12g}', style='{')
3899 self.assertRaises(ValueError, logging.Formatter, '{process!s:<#30#,12g}', style='{')
3900 self.assertRaises(ValueError, logging.Formatter, '{process!s:{{w}},{{p}}}', style='{')
3901 # Testing failure for mismatch braces
3902 self.assert_error_message(
3903 ValueError,
3904 "invalid format: unmatched '{' in format spec",
3905 logging.Formatter, '{process', style='{'
3906 )
3907 self.assert_error_message(
3908 ValueError,
3909 "invalid format: unmatched '{' in format spec",
3910 logging.Formatter, 'process}', style='{'
3911 )
3912 self.assertRaises(ValueError, logging.Formatter, '{{foo!r:4.2}', style='{')
3913 self.assertRaises(ValueError, logging.Formatter, '{{foo!r:4.2}}', style='{')
3914 self.assertRaises(ValueError, logging.Formatter, '{foo/bar}', style='{')
3915 self.assertRaises(ValueError, logging.Formatter, '{foo:{{w}}.{{p}}}}', style='{')
3916 self.assertRaises(ValueError, logging.Formatter, '{foo!X:{{w}}.{{p}}}', style='{')
3917 self.assertRaises(ValueError, logging.Formatter, '{foo!a:random}', style='{')
3918 self.assertRaises(ValueError, logging.Formatter, '{foo!a:ran{dom}', style='{')
3919 self.assertRaises(ValueError, logging.Formatter, '{foo!a:ran{d}om}', style='{')
3920 self.assertRaises(ValueError, logging.Formatter, '{foo.!a:d}', style='{')
3921
3922 # Dollar style
3923 # Testing failure for mismatch bare $
3924 self.assert_error_message(
3925 ValueError,
3926 "invalid format: bare \'$\' not allowed",
3927 logging.Formatter, '$bar $$$', style='$'
3928 )
3929 self.assert_error_message(
3930 ValueError,
3931 "invalid format: bare \'$\' not allowed",
3932 logging.Formatter, 'bar $', style='$'
3933 )
3934 self.assert_error_message(
3935 ValueError,
3936 "invalid format: bare \'$\' not allowed",
3937 logging.Formatter, 'foo $.', style='$'
3938 )
3939 # Testing failure for mismatch style
3940 self.assert_error_message(
3941 ValueError,
3942 "invalid format: no fields",
3943 logging.Formatter, '{asctime}', style='$'
3944 )
3945 self.assertRaises(ValueError, logging.Formatter, '%(asctime)s', style='$')
3946
3947 # Testing failure for incorrect fields
3948 self.assert_error_message(
3949 ValueError,
3950 "invalid format: no fields",
3951 logging.Formatter, 'foo', style='$'
3952 )
3953 self.assertRaises(ValueError, logging.Formatter, '${asctime', style='$')
Vinay Sajipa39c5712010-10-25 13:57:39 +00003954
Bar Harel8f192d12020-06-18 17:18:58 +03003955 def test_defaults_parameter(self):
3956 fmts = ['%(custom)s %(message)s', '{custom} {message}', '$custom $message']
3957 styles = ['%', '{', '$']
3958 for fmt, style in zip(fmts, styles):
3959 f = logging.Formatter(fmt, style=style, defaults={'custom': 'Default'})
3960 r = self.get_record()
3961 self.assertEqual(f.format(r), 'Default Message with 2 placeholders')
3962 r = self.get_record("custom")
3963 self.assertEqual(f.format(r), '1234 Message with 2 placeholders')
3964
3965 # Without default
3966 f = logging.Formatter(fmt, style=style)
3967 r = self.get_record()
3968 self.assertRaises(ValueError, f.format, r)
3969
3970 # Non-existing default is ignored
3971 f = logging.Formatter(fmt, style=style, defaults={'Non-existing': 'Default'})
3972 r = self.get_record("custom")
3973 self.assertEqual(f.format(r), '1234 Message with 2 placeholders')
3974
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003975 def test_invalid_style(self):
3976 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
3977
Vinay Sajip86a96ce2011-04-27 08:30:30 +01003978 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003979 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01003980 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
3981 # We use None to indicate we want the local timezone
3982 # We're essentially converting a UTC time to local time
3983 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003984 r.msecs = 123
3985 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01003986 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003987 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
3988 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01003989 f.format(r)
3990 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
3991
Mariusz Felisiak06a35542020-04-17 18:02:47 +02003992 def test_default_msec_format_none(self):
3993 class NoMsecFormatter(logging.Formatter):
3994 default_msec_format = None
3995 default_time_format = '%d/%m/%Y %H:%M:%S'
3996
3997 r = self.get_record()
3998 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 123, utc)
3999 r.created = time.mktime(dt.astimezone(None).timetuple())
4000 f = NoMsecFormatter()
4001 f.converter = time.gmtime
4002 self.assertEqual(f.formatTime(r), '21/04/1993 08:03:00')
4003
4004
Vinay Sajip985ef872011-04-26 19:34:04 +01004005class TestBufferingFormatter(logging.BufferingFormatter):
4006 def formatHeader(self, records):
4007 return '[(%d)' % len(records)
4008
4009 def formatFooter(self, records):
4010 return '(%d)]' % len(records)
4011
4012class BufferingFormatterTest(unittest.TestCase):
4013 def setUp(self):
4014 self.records = [
4015 logging.makeLogRecord({'msg': 'one'}),
4016 logging.makeLogRecord({'msg': 'two'}),
4017 ]
4018
4019 def test_default(self):
4020 f = logging.BufferingFormatter()
4021 self.assertEqual('', f.format([]))
4022 self.assertEqual('onetwo', f.format(self.records))
4023
4024 def test_custom(self):
4025 f = TestBufferingFormatter()
4026 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
4027 lf = logging.Formatter('<%(message)s>')
4028 f = TestBufferingFormatter(lf)
4029 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004030
4031class ExceptionTest(BaseTest):
4032 def test_formatting(self):
4033 r = self.root_logger
4034 h = RecordingHandler()
4035 r.addHandler(h)
4036 try:
4037 raise RuntimeError('deliberate mistake')
4038 except:
4039 logging.exception('failed', stack_info=True)
4040 r.removeHandler(h)
4041 h.close()
4042 r = h.records[0]
4043 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
4044 'call last):\n'))
4045 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
4046 'deliberate mistake'))
4047 self.assertTrue(r.stack_info.startswith('Stack (most recent '
4048 'call last):\n'))
4049 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
4050 'stack_info=True)'))
4051
4052
Vinay Sajip5a27d402010-12-10 11:42:57 +00004053class LastResortTest(BaseTest):
4054 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00004055 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00004056 root = self.root_logger
4057 root.removeHandler(self.root_hdlr)
Vinay Sajip5a27d402010-12-10 11:42:57 +00004058 old_lastresort = logging.lastResort
4059 old_raise_exceptions = logging.raiseExceptions
Vinay Sajip1feedb42014-05-31 08:19:12 +01004060
Vinay Sajip5a27d402010-12-10 11:42:57 +00004061 try:
Vinay Sajip1feedb42014-05-31 08:19:12 +01004062 with support.captured_stderr() as stderr:
4063 root.debug('This should not appear')
4064 self.assertEqual(stderr.getvalue(), '')
4065 root.warning('Final chance!')
4066 self.assertEqual(stderr.getvalue(), 'Final chance!\n')
4067
4068 # No handlers and no last resort, so 'No handlers' message
Vinay Sajip5a27d402010-12-10 11:42:57 +00004069 logging.lastResort = None
Vinay Sajip1feedb42014-05-31 08:19:12 +01004070 with support.captured_stderr() as stderr:
4071 root.warning('Final chance!')
4072 msg = 'No handlers could be found for logger "root"\n'
4073 self.assertEqual(stderr.getvalue(), msg)
4074
Vinay Sajip5a27d402010-12-10 11:42:57 +00004075 # 'No handlers' message only printed once
Vinay Sajip1feedb42014-05-31 08:19:12 +01004076 with support.captured_stderr() as stderr:
4077 root.warning('Final chance!')
4078 self.assertEqual(stderr.getvalue(), '')
4079
4080 # If raiseExceptions is False, no message is printed
Vinay Sajip5a27d402010-12-10 11:42:57 +00004081 root.manager.emittedNoHandlerWarning = False
Vinay Sajip5a27d402010-12-10 11:42:57 +00004082 logging.raiseExceptions = False
Vinay Sajip1feedb42014-05-31 08:19:12 +01004083 with support.captured_stderr() as stderr:
4084 root.warning('Final chance!')
4085 self.assertEqual(stderr.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00004086 finally:
Vinay Sajip5a27d402010-12-10 11:42:57 +00004087 root.addHandler(self.root_hdlr)
4088 logging.lastResort = old_lastresort
4089 logging.raiseExceptions = old_raise_exceptions
4090
4091
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004092class FakeHandler:
4093
4094 def __init__(self, identifier, called):
4095 for method in ('acquire', 'flush', 'close', 'release'):
4096 setattr(self, method, self.record_call(identifier, method, called))
4097
4098 def record_call(self, identifier, method_name, called):
4099 def inner():
4100 called.append('{} - {}'.format(identifier, method_name))
4101 return inner
4102
4103
4104class RecordingHandler(logging.NullHandler):
4105
4106 def __init__(self, *args, **kwargs):
4107 super(RecordingHandler, self).__init__(*args, **kwargs)
4108 self.records = []
4109
4110 def handle(self, record):
4111 """Keep track of all the emitted records."""
4112 self.records.append(record)
4113
4114
4115class ShutdownTest(BaseTest):
4116
Vinay Sajip5e66b162011-04-20 15:41:14 +01004117 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004118
4119 def setUp(self):
4120 super(ShutdownTest, self).setUp()
4121 self.called = []
4122
4123 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004124 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004125
4126 def raise_error(self, error):
4127 def inner():
4128 raise error()
4129 return inner
4130
4131 def test_no_failure(self):
4132 # create some fake handlers
4133 handler0 = FakeHandler(0, self.called)
4134 handler1 = FakeHandler(1, self.called)
4135 handler2 = FakeHandler(2, self.called)
4136
4137 # create live weakref to those handlers
4138 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
4139
4140 logging.shutdown(handlerList=list(handlers))
4141
4142 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
4143 '1 - acquire', '1 - flush', '1 - close', '1 - release',
4144 '0 - acquire', '0 - flush', '0 - close', '0 - release']
4145 self.assertEqual(expected, self.called)
4146
4147 def _test_with_failure_in_method(self, method, error):
4148 handler = FakeHandler(0, self.called)
4149 setattr(handler, method, self.raise_error(error))
4150 handlers = [logging.weakref.ref(handler)]
4151
4152 logging.shutdown(handlerList=list(handlers))
4153
4154 self.assertEqual('0 - release', self.called[-1])
4155
4156 def test_with_ioerror_in_acquire(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02004157 self._test_with_failure_in_method('acquire', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004158
4159 def test_with_ioerror_in_flush(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02004160 self._test_with_failure_in_method('flush', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004161
4162 def test_with_ioerror_in_close(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02004163 self._test_with_failure_in_method('close', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004164
4165 def test_with_valueerror_in_acquire(self):
4166 self._test_with_failure_in_method('acquire', ValueError)
4167
4168 def test_with_valueerror_in_flush(self):
4169 self._test_with_failure_in_method('flush', ValueError)
4170
4171 def test_with_valueerror_in_close(self):
4172 self._test_with_failure_in_method('close', ValueError)
4173
4174 def test_with_other_error_in_acquire_without_raise(self):
4175 logging.raiseExceptions = False
4176 self._test_with_failure_in_method('acquire', IndexError)
4177
4178 def test_with_other_error_in_flush_without_raise(self):
4179 logging.raiseExceptions = False
4180 self._test_with_failure_in_method('flush', IndexError)
4181
4182 def test_with_other_error_in_close_without_raise(self):
4183 logging.raiseExceptions = False
4184 self._test_with_failure_in_method('close', IndexError)
4185
4186 def test_with_other_error_in_acquire_with_raise(self):
4187 logging.raiseExceptions = True
4188 self.assertRaises(IndexError, self._test_with_failure_in_method,
4189 'acquire', IndexError)
4190
4191 def test_with_other_error_in_flush_with_raise(self):
4192 logging.raiseExceptions = True
4193 self.assertRaises(IndexError, self._test_with_failure_in_method,
4194 'flush', IndexError)
4195
4196 def test_with_other_error_in_close_with_raise(self):
4197 logging.raiseExceptions = True
4198 self.assertRaises(IndexError, self._test_with_failure_in_method,
4199 'close', IndexError)
4200
4201
4202class ModuleLevelMiscTest(BaseTest):
4203
Vinay Sajip5e66b162011-04-20 15:41:14 +01004204 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004205
4206 def test_disable(self):
4207 old_disable = logging.root.manager.disable
4208 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004209 self.assertEqual(old_disable, 0)
4210 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004211
4212 logging.disable(83)
4213 self.assertEqual(logging.root.manager.disable, 83)
4214
Vinay Sajipd489ac92016-12-31 11:40:11 +00004215 # test the default value introduced in 3.7
4216 # (Issue #28524)
4217 logging.disable()
4218 self.assertEqual(logging.root.manager.disable, logging.CRITICAL)
4219
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004220 def _test_log(self, method, level=None):
4221 called = []
Vinay Sajip1feedb42014-05-31 08:19:12 +01004222 support.patch(self, logging, 'basicConfig',
4223 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004224
4225 recording = RecordingHandler()
4226 logging.root.addHandler(recording)
4227
4228 log_method = getattr(logging, method)
4229 if level is not None:
4230 log_method(level, "test me: %r", recording)
4231 else:
4232 log_method("test me: %r", recording)
4233
4234 self.assertEqual(len(recording.records), 1)
4235 record = recording.records[0]
4236 self.assertEqual(record.getMessage(), "test me: %r" % recording)
4237
4238 expected_level = level if level is not None else getattr(logging, method.upper())
4239 self.assertEqual(record.levelno, expected_level)
4240
4241 # basicConfig was not called!
4242 self.assertEqual(called, [])
4243
4244 def test_log(self):
4245 self._test_log('log', logging.ERROR)
4246
4247 def test_debug(self):
4248 self._test_log('debug')
4249
4250 def test_info(self):
4251 self._test_log('info')
4252
4253 def test_warning(self):
4254 self._test_log('warning')
4255
4256 def test_error(self):
4257 self._test_log('error')
4258
4259 def test_critical(self):
4260 self._test_log('critical')
4261
4262 def test_set_logger_class(self):
4263 self.assertRaises(TypeError, logging.setLoggerClass, object)
4264
4265 class MyLogger(logging.Logger):
4266 pass
4267
4268 logging.setLoggerClass(MyLogger)
4269 self.assertEqual(logging.getLoggerClass(), MyLogger)
4270
4271 logging.setLoggerClass(logging.Logger)
4272 self.assertEqual(logging.getLoggerClass(), logging.Logger)
4273
Vinay Sajip01500012019-06-19 11:46:53 +01004274 def test_subclass_logger_cache(self):
4275 # bpo-37258
4276 message = []
4277
4278 class MyLogger(logging.getLoggerClass()):
4279 def __init__(self, name='MyLogger', level=logging.NOTSET):
4280 super().__init__(name, level)
4281 message.append('initialized')
4282
4283 logging.setLoggerClass(MyLogger)
4284 logger = logging.getLogger('just_some_logger')
4285 self.assertEqual(message, ['initialized'])
4286 stream = io.StringIO()
4287 h = logging.StreamHandler(stream)
4288 logger.addHandler(h)
4289 try:
4290 logger.setLevel(logging.DEBUG)
4291 logger.debug("hello")
4292 self.assertEqual(stream.getvalue().strip(), "hello")
4293
4294 stream.truncate(0)
4295 stream.seek(0)
4296
4297 logger.setLevel(logging.INFO)
4298 logger.debug("hello")
4299 self.assertEqual(stream.getvalue(), "")
4300 finally:
4301 logger.removeHandler(h)
4302 h.close()
4303 logging.setLoggerClass(logging.Logger)
4304
Antoine Pitrou712cb732013-12-21 15:51:54 +01004305 def test_logging_at_shutdown(self):
4306 # Issue #20037
4307 code = """if 1:
4308 import logging
4309
4310 class A:
4311 def __del__(self):
4312 try:
4313 raise ValueError("some error")
4314 except Exception:
4315 logging.exception("exception in __del__")
4316
4317 a = A()"""
4318 rc, out, err = assert_python_ok("-c", code)
4319 err = err.decode()
4320 self.assertIn("exception in __del__", err)
4321 self.assertIn("ValueError: some error", err)
4322
Rémi Lapeyre65f64b12019-03-15 07:53:34 +01004323 def test_recursion_error(self):
4324 # Issue 36272
4325 code = """if 1:
4326 import logging
4327
4328 def rec():
4329 logging.error("foo")
4330 rec()
4331
4332 rec()"""
4333 rc, out, err = assert_python_failure("-c", code)
4334 err = err.decode()
4335 self.assertNotIn("Cannot recover from stack overflow.", err)
4336 self.assertEqual(rc, 1)
4337
Antoine Pitrou712cb732013-12-21 15:51:54 +01004338
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004339class LogRecordTest(BaseTest):
4340 def test_str_rep(self):
4341 r = logging.makeLogRecord({})
4342 s = str(r)
4343 self.assertTrue(s.startswith('<LogRecord: '))
4344 self.assertTrue(s.endswith('>'))
4345
4346 def test_dict_arg(self):
4347 h = RecordingHandler()
4348 r = logging.getLogger()
4349 r.addHandler(h)
4350 d = {'less' : 'more' }
4351 logging.warning('less is %(less)s', d)
4352 self.assertIs(h.records[0].args, d)
4353 self.assertEqual(h.records[0].message, 'less is more')
4354 r.removeHandler(h)
4355 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004356
Irit Katriel3fd69992020-09-08 20:40:04 +01004357 @staticmethod # pickled as target of child process in the following test
4358 def _extract_logrecord_process_name(key, logMultiprocessing, conn=None):
4359 prev_logMultiprocessing = logging.logMultiprocessing
4360 logging.logMultiprocessing = logMultiprocessing
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01004361 try:
4362 import multiprocessing as mp
Irit Katriel3fd69992020-09-08 20:40:04 +01004363 name = mp.current_process().name
4364
4365 r1 = logging.makeLogRecord({'msg': f'msg1_{key}'})
4366 del sys.modules['multiprocessing']
4367 r2 = logging.makeLogRecord({'msg': f'msg2_{key}'})
4368
4369 results = {'processName' : name,
4370 'r1.processName': r1.processName,
4371 'r2.processName': r2.processName,
4372 }
4373 finally:
4374 logging.logMultiprocessing = prev_logMultiprocessing
4375 if conn:
4376 conn.send(results)
4377 else:
4378 return results
4379
4380 def test_multiprocessing(self):
4381 multiprocessing_imported = 'multiprocessing' in sys.modules
4382 try:
4383 # logMultiprocessing is True by default
4384 self.assertEqual(logging.logMultiprocessing, True)
4385
4386 LOG_MULTI_PROCESSING = True
4387 # When logMultiprocessing == True:
4388 # In the main process processName = 'MainProcess'
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01004389 r = logging.makeLogRecord({})
Irit Katriel3fd69992020-09-08 20:40:04 +01004390 self.assertEqual(r.processName, 'MainProcess')
4391
4392 results = self._extract_logrecord_process_name(1, LOG_MULTI_PROCESSING)
4393 self.assertEqual('MainProcess', results['processName'])
4394 self.assertEqual('MainProcess', results['r1.processName'])
4395 self.assertEqual('MainProcess', results['r2.processName'])
4396
4397 # In other processes, processName is correct when multiprocessing in imported,
4398 # but it is (incorrectly) defaulted to 'MainProcess' otherwise (bpo-38762).
4399 import multiprocessing
4400 parent_conn, child_conn = multiprocessing.Pipe()
4401 p = multiprocessing.Process(
4402 target=self._extract_logrecord_process_name,
4403 args=(2, LOG_MULTI_PROCESSING, child_conn,)
4404 )
4405 p.start()
4406 results = parent_conn.recv()
4407 self.assertNotEqual('MainProcess', results['processName'])
4408 self.assertEqual(results['processName'], results['r1.processName'])
4409 self.assertEqual('MainProcess', results['r2.processName'])
4410 p.join()
4411
4412 finally:
4413 if multiprocessing_imported:
4414 import multiprocessing
4415
Vinay Sajip7fe1d512011-04-28 12:04:58 +01004416
4417 def test_optional(self):
4418 r = logging.makeLogRecord({})
4419 NOT_NONE = self.assertIsNotNone
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02004420 NOT_NONE(r.thread)
4421 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01004422 NOT_NONE(r.process)
4423 NOT_NONE(r.processName)
4424 log_threads = logging.logThreads
4425 log_processes = logging.logProcesses
4426 log_multiprocessing = logging.logMultiprocessing
4427 try:
4428 logging.logThreads = False
4429 logging.logProcesses = False
4430 logging.logMultiprocessing = False
4431 r = logging.makeLogRecord({})
4432 NONE = self.assertIsNone
4433 NONE(r.thread)
4434 NONE(r.threadName)
4435 NONE(r.process)
4436 NONE(r.processName)
4437 finally:
4438 logging.logThreads = log_threads
4439 logging.logProcesses = log_processes
4440 logging.logMultiprocessing = log_multiprocessing
4441
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004442class BasicConfigTest(unittest.TestCase):
4443
Vinay Sajip95bf5042011-04-20 11:50:56 +01004444 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004445
4446 def setUp(self):
4447 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01004448 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01004449 self.saved_handlers = logging._handlers.copy()
4450 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01004451 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01004452 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004453 logging.root.handlers = []
4454
4455 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01004456 for h in logging.root.handlers[:]:
4457 logging.root.removeHandler(h)
4458 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004459 super(BasicConfigTest, self).tearDown()
4460
Vinay Sajip3def7e02011-04-20 10:58:06 +01004461 def cleanup(self):
4462 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01004463 logging._handlers.clear()
4464 logging._handlers.update(self.saved_handlers)
4465 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1d094af2019-09-22 03:51:51 +01004466 logging.root.setLevel(self.original_logging_level)
Vinay Sajip3def7e02011-04-20 10:58:06 +01004467
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004468 def test_no_kwargs(self):
4469 logging.basicConfig()
4470
4471 # handler defaults to a StreamHandler to sys.stderr
4472 self.assertEqual(len(logging.root.handlers), 1)
4473 handler = logging.root.handlers[0]
4474 self.assertIsInstance(handler, logging.StreamHandler)
4475 self.assertEqual(handler.stream, sys.stderr)
4476
4477 formatter = handler.formatter
4478 # format defaults to logging.BASIC_FORMAT
4479 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
4480 # datefmt defaults to None
4481 self.assertIsNone(formatter.datefmt)
4482 # style defaults to %
4483 self.assertIsInstance(formatter._style, logging.PercentStyle)
4484
Florent Xiclunae41f0de2011-11-11 19:39:25 +01004485 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01004486 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004487
Vinay Sajip1fd12022014-01-13 21:59:56 +00004488 def test_strformatstyle(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01004489 with support.captured_stdout() as output:
Vinay Sajip1fd12022014-01-13 21:59:56 +00004490 logging.basicConfig(stream=sys.stdout, style="{")
4491 logging.error("Log an error")
4492 sys.stdout.seek(0)
4493 self.assertEqual(output.getvalue().strip(),
4494 "ERROR:root:Log an error")
4495
4496 def test_stringtemplatestyle(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01004497 with support.captured_stdout() as output:
Vinay Sajip1fd12022014-01-13 21:59:56 +00004498 logging.basicConfig(stream=sys.stdout, style="$")
4499 logging.error("Log an error")
4500 sys.stdout.seek(0)
4501 self.assertEqual(output.getvalue().strip(),
4502 "ERROR:root:Log an error")
4503
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004504 def test_filename(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004505
4506 def cleanup(h1, h2, fn):
4507 h1.close()
4508 h2.close()
4509 os.remove(fn)
4510
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004511 logging.basicConfig(filename='test.log')
4512
4513 self.assertEqual(len(logging.root.handlers), 1)
4514 handler = logging.root.handlers[0]
4515 self.assertIsInstance(handler, logging.FileHandler)
4516
4517 expected = logging.FileHandler('test.log', 'a')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004518 self.assertEqual(handler.stream.mode, expected.stream.mode)
4519 self.assertEqual(handler.stream.name, expected.stream.name)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004520 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004521
4522 def test_filemode(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004523
4524 def cleanup(h1, h2, fn):
4525 h1.close()
4526 h2.close()
4527 os.remove(fn)
4528
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004529 logging.basicConfig(filename='test.log', filemode='wb')
4530
4531 handler = logging.root.handlers[0]
4532 expected = logging.FileHandler('test.log', 'wb')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004533 self.assertEqual(handler.stream.mode, expected.stream.mode)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004534 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004535
4536 def test_stream(self):
4537 stream = io.StringIO()
4538 self.addCleanup(stream.close)
4539 logging.basicConfig(stream=stream)
4540
4541 self.assertEqual(len(logging.root.handlers), 1)
4542 handler = logging.root.handlers[0]
4543 self.assertIsInstance(handler, logging.StreamHandler)
4544 self.assertEqual(handler.stream, stream)
4545
4546 def test_format(self):
BNMetrics18fb1fb2018-10-15 19:41:36 +01004547 logging.basicConfig(format='%(asctime)s - %(message)s')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004548
4549 formatter = logging.root.handlers[0].formatter
BNMetrics18fb1fb2018-10-15 19:41:36 +01004550 self.assertEqual(formatter._style._fmt, '%(asctime)s - %(message)s')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004551
4552 def test_datefmt(self):
4553 logging.basicConfig(datefmt='bar')
4554
4555 formatter = logging.root.handlers[0].formatter
4556 self.assertEqual(formatter.datefmt, 'bar')
4557
4558 def test_style(self):
4559 logging.basicConfig(style='$')
4560
4561 formatter = logging.root.handlers[0].formatter
4562 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
4563
4564 def test_level(self):
4565 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004566 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004567
4568 logging.basicConfig(level=57)
4569 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004570 # Test that second call has no effect
4571 logging.basicConfig(level=58)
4572 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004573
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004574 def test_incompatible(self):
4575 assertRaises = self.assertRaises
4576 handlers = [logging.StreamHandler()]
4577 stream = sys.stderr
4578 assertRaises(ValueError, logging.basicConfig, filename='test.log',
BNMetrics18fb1fb2018-10-15 19:41:36 +01004579 stream=stream)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004580 assertRaises(ValueError, logging.basicConfig, filename='test.log',
BNMetrics18fb1fb2018-10-15 19:41:36 +01004581 handlers=handlers)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004582 assertRaises(ValueError, logging.basicConfig, stream=stream,
BNMetrics18fb1fb2018-10-15 19:41:36 +01004583 handlers=handlers)
Vinay Sajipd55436a2015-03-18 08:47:58 +00004584 # Issue 23207: test for invalid kwargs
4585 assertRaises(ValueError, logging.basicConfig, loglevel=logging.INFO)
4586 # Should pop both filename and filemode even if filename is None
4587 logging.basicConfig(filename=None, filemode='a')
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004588
4589 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004590 handlers = [
4591 logging.StreamHandler(),
4592 logging.StreamHandler(sys.stdout),
4593 logging.StreamHandler(),
4594 ]
4595 f = logging.Formatter()
4596 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004597 logging.basicConfig(handlers=handlers)
4598 self.assertIs(handlers[0], logging.root.handlers[0])
4599 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004600 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004601 self.assertIsNotNone(handlers[0].formatter)
4602 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004603 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004604 self.assertIs(handlers[0].formatter, handlers[1].formatter)
4605
Dong-hee Nacf67d6a2018-06-25 13:11:09 +09004606 def test_force(self):
4607 old_string_io = io.StringIO()
4608 new_string_io = io.StringIO()
4609 old_handlers = [logging.StreamHandler(old_string_io)]
4610 new_handlers = [logging.StreamHandler(new_string_io)]
4611 logging.basicConfig(level=logging.WARNING, handlers=old_handlers)
4612 logging.warning('warn')
4613 logging.info('info')
4614 logging.debug('debug')
4615 self.assertEqual(len(logging.root.handlers), 1)
4616 logging.basicConfig(level=logging.INFO, handlers=new_handlers,
4617 force=True)
4618 logging.warning('warn')
4619 logging.info('info')
4620 logging.debug('debug')
4621 self.assertEqual(len(logging.root.handlers), 1)
4622 self.assertEqual(old_string_io.getvalue().strip(),
4623 'WARNING:root:warn')
4624 self.assertEqual(new_string_io.getvalue().strip(),
4625 'WARNING:root:warn\nINFO:root:info')
4626
Vinay Sajipca7b5042019-06-17 17:40:52 +01004627 def test_encoding(self):
4628 try:
4629 encoding = 'utf-8'
4630 logging.basicConfig(filename='test.log', encoding=encoding,
4631 errors='strict',
4632 format='%(message)s', level=logging.DEBUG)
4633
4634 self.assertEqual(len(logging.root.handlers), 1)
4635 handler = logging.root.handlers[0]
4636 self.assertIsInstance(handler, logging.FileHandler)
4637 self.assertEqual(handler.encoding, encoding)
4638 logging.debug('The Øresund Bridge joins Copenhagen to Malmö')
4639 finally:
4640 handler.close()
4641 with open('test.log', encoding='utf-8') as f:
4642 data = f.read().strip()
4643 os.remove('test.log')
4644 self.assertEqual(data,
4645 'The Øresund Bridge joins Copenhagen to Malmö')
4646
4647 def test_encoding_errors(self):
4648 try:
4649 encoding = 'ascii'
4650 logging.basicConfig(filename='test.log', encoding=encoding,
4651 errors='ignore',
4652 format='%(message)s', level=logging.DEBUG)
4653
4654 self.assertEqual(len(logging.root.handlers), 1)
4655 handler = logging.root.handlers[0]
4656 self.assertIsInstance(handler, logging.FileHandler)
4657 self.assertEqual(handler.encoding, encoding)
4658 logging.debug('The Øresund Bridge joins Copenhagen to Malmö')
4659 finally:
4660 handler.close()
4661 with open('test.log', encoding='utf-8') as f:
4662 data = f.read().strip()
4663 os.remove('test.log')
4664 self.assertEqual(data, 'The resund Bridge joins Copenhagen to Malm')
4665
4666 def test_encoding_errors_default(self):
4667 try:
4668 encoding = 'ascii'
4669 logging.basicConfig(filename='test.log', encoding=encoding,
4670 format='%(message)s', level=logging.DEBUG)
4671
4672 self.assertEqual(len(logging.root.handlers), 1)
4673 handler = logging.root.handlers[0]
4674 self.assertIsInstance(handler, logging.FileHandler)
4675 self.assertEqual(handler.encoding, encoding)
4676 self.assertEqual(handler.errors, 'backslashreplace')
4677 logging.debug('😂: ☃️: The Øresund Bridge joins Copenhagen to Malmö')
4678 finally:
4679 handler.close()
4680 with open('test.log', encoding='utf-8') as f:
4681 data = f.read().strip()
4682 os.remove('test.log')
4683 self.assertEqual(data, r'\U0001f602: \u2603\ufe0f: The \xd8resund '
4684 r'Bridge joins Copenhagen to Malm\xf6')
4685
4686 def test_encoding_errors_none(self):
4687 # Specifying None should behave as 'strict'
4688 try:
4689 encoding = 'ascii'
4690 logging.basicConfig(filename='test.log', encoding=encoding,
4691 errors=None,
4692 format='%(message)s', level=logging.DEBUG)
4693
4694 self.assertEqual(len(logging.root.handlers), 1)
4695 handler = logging.root.handlers[0]
4696 self.assertIsInstance(handler, logging.FileHandler)
4697 self.assertEqual(handler.encoding, encoding)
4698 self.assertIsNone(handler.errors)
4699
4700 message = []
4701
4702 def dummy_handle_error(record):
4703 _, v, _ = sys.exc_info()
4704 message.append(str(v))
4705
4706 handler.handleError = dummy_handle_error
4707 logging.debug('The Øresund Bridge joins Copenhagen to Malmö')
4708 self.assertTrue(message)
4709 self.assertIn("'ascii' codec can't encode "
4710 "character '\\xd8' in position 4:", message[0])
4711 finally:
4712 handler.close()
4713 with open('test.log', encoding='utf-8') as f:
4714 data = f.read().strip()
4715 os.remove('test.log')
4716 # didn't write anything due to the encoding error
4717 self.assertEqual(data, r'')
4718
4719
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004720 def _test_log(self, method, level=None):
4721 # logging.root has no handlers so basicConfig should be called
4722 called = []
4723
4724 old_basic_config = logging.basicConfig
4725 def my_basic_config(*a, **kw):
4726 old_basic_config()
4727 old_level = logging.root.level
4728 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004729 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004730 called.append((a, kw))
4731
Vinay Sajip1feedb42014-05-31 08:19:12 +01004732 support.patch(self, logging, 'basicConfig', my_basic_config)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004733
4734 log_method = getattr(logging, method)
4735 if level is not None:
4736 log_method(level, "test me")
4737 else:
4738 log_method("test me")
4739
4740 # basicConfig was called with no arguments
4741 self.assertEqual(called, [((), {})])
4742
4743 def test_log(self):
4744 self._test_log('log', logging.WARNING)
4745
4746 def test_debug(self):
4747 self._test_log('debug')
4748
4749 def test_info(self):
4750 self._test_log('info')
4751
4752 def test_warning(self):
4753 self._test_log('warning')
4754
4755 def test_error(self):
4756 self._test_log('error')
4757
4758 def test_critical(self):
4759 self._test_log('critical')
4760
4761
4762class LoggerAdapterTest(unittest.TestCase):
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004763 def setUp(self):
4764 super(LoggerAdapterTest, self).setUp()
4765 old_handler_list = logging._handlerList[:]
4766
4767 self.recording = RecordingHandler()
4768 self.logger = logging.root
4769 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004770 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004771 self.addCleanup(self.recording.close)
4772
4773 def cleanup():
4774 logging._handlerList[:] = old_handler_list
4775
4776 self.addCleanup(cleanup)
4777 self.addCleanup(logging.shutdown)
4778 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
4779
4780 def test_exception(self):
4781 msg = 'testing exception: %r'
4782 exc = None
4783 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004784 1 / 0
4785 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004786 exc = e
4787 self.adapter.exception(msg, self.recording)
4788
4789 self.assertEqual(len(self.recording.records), 1)
4790 record = self.recording.records[0]
4791 self.assertEqual(record.levelno, logging.ERROR)
4792 self.assertEqual(record.msg, msg)
4793 self.assertEqual(record.args, (self.recording,))
4794 self.assertEqual(record.exc_info,
4795 (exc.__class__, exc, exc.__traceback__))
4796
Vinay Sajip02a8f9e2014-09-14 21:29:11 +01004797 def test_exception_excinfo(self):
4798 try:
4799 1 / 0
4800 except ZeroDivisionError as e:
4801 exc = e
4802
4803 self.adapter.exception('exc_info test', exc_info=exc)
4804
4805 self.assertEqual(len(self.recording.records), 1)
4806 record = self.recording.records[0]
4807 self.assertEqual(record.exc_info,
4808 (exc.__class__, exc, exc.__traceback__))
4809
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004810 def test_critical(self):
4811 msg = 'critical test! %r'
4812 self.adapter.critical(msg, self.recording)
4813
4814 self.assertEqual(len(self.recording.records), 1)
4815 record = self.recording.records[0]
4816 self.assertEqual(record.levelno, logging.CRITICAL)
4817 self.assertEqual(record.msg, msg)
4818 self.assertEqual(record.args, (self.recording,))
4819
4820 def test_is_enabled_for(self):
4821 old_disable = self.adapter.logger.manager.disable
4822 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004823 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
4824 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004825 self.assertFalse(self.adapter.isEnabledFor(32))
4826
4827 def test_has_handlers(self):
4828 self.assertTrue(self.adapter.hasHandlers())
4829
4830 for handler in self.logger.handlers:
4831 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004832
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004833 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004834 self.assertFalse(self.adapter.hasHandlers())
4835
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004836 def test_nested(self):
Łukasz Langace9e6252017-10-19 10:24:55 -07004837 class Adapter(logging.LoggerAdapter):
4838 prefix = 'Adapter'
4839
4840 def process(self, msg, kwargs):
4841 return f"{self.prefix} {msg}", kwargs
4842
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004843 msg = 'Adapters can be nested, yo.'
Łukasz Langace9e6252017-10-19 10:24:55 -07004844 adapter = Adapter(logger=self.logger, extra=None)
4845 adapter_adapter = Adapter(logger=adapter, extra=None)
4846 adapter_adapter.prefix = 'AdapterAdapter'
4847 self.assertEqual(repr(adapter), repr(adapter_adapter))
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004848 adapter_adapter.log(logging.CRITICAL, msg, self.recording)
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004849 self.assertEqual(len(self.recording.records), 1)
4850 record = self.recording.records[0]
4851 self.assertEqual(record.levelno, logging.CRITICAL)
Łukasz Langace9e6252017-10-19 10:24:55 -07004852 self.assertEqual(record.msg, f"Adapter AdapterAdapter {msg}")
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004853 self.assertEqual(record.args, (self.recording,))
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004854 orig_manager = adapter_adapter.manager
Łukasz Langace9e6252017-10-19 10:24:55 -07004855 self.assertIs(adapter.manager, orig_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004856 self.assertIs(self.logger.manager, orig_manager)
4857 temp_manager = object()
4858 try:
4859 adapter_adapter.manager = temp_manager
4860 self.assertIs(adapter_adapter.manager, temp_manager)
Łukasz Langace9e6252017-10-19 10:24:55 -07004861 self.assertIs(adapter.manager, temp_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004862 self.assertIs(self.logger.manager, temp_manager)
4863 finally:
4864 adapter_adapter.manager = orig_manager
4865 self.assertIs(adapter_adapter.manager, orig_manager)
Łukasz Langace9e6252017-10-19 10:24:55 -07004866 self.assertIs(adapter.manager, orig_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004867 self.assertIs(self.logger.manager, orig_manager)
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004868
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004869
4870class LoggerTest(BaseTest):
4871
4872 def setUp(self):
4873 super(LoggerTest, self).setUp()
4874 self.recording = RecordingHandler()
4875 self.logger = logging.Logger(name='blah')
4876 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004877 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004878 self.addCleanup(self.recording.close)
4879 self.addCleanup(logging.shutdown)
4880
4881 def test_set_invalid_level(self):
4882 self.assertRaises(TypeError, self.logger.setLevel, object())
4883
4884 def test_exception(self):
4885 msg = 'testing exception: %r'
4886 exc = None
4887 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004888 1 / 0
4889 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004890 exc = e
4891 self.logger.exception(msg, self.recording)
4892
4893 self.assertEqual(len(self.recording.records), 1)
4894 record = self.recording.records[0]
4895 self.assertEqual(record.levelno, logging.ERROR)
4896 self.assertEqual(record.msg, msg)
4897 self.assertEqual(record.args, (self.recording,))
4898 self.assertEqual(record.exc_info,
4899 (exc.__class__, exc, exc.__traceback__))
4900
4901 def test_log_invalid_level_with_raise(self):
Serhiy Storchaka296b3472015-07-21 22:40:18 +03004902 with support.swap_attr(logging, 'raiseExceptions', True):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03004903 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004904
4905 def test_log_invalid_level_no_raise(self):
Serhiy Storchaka296b3472015-07-21 22:40:18 +03004906 with support.swap_attr(logging, 'raiseExceptions', False):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03004907 self.logger.log('10', 'test message') # no exception happens
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004908
4909 def test_find_caller_with_stack_info(self):
4910 called = []
Vinay Sajip1feedb42014-05-31 08:19:12 +01004911 support.patch(self, logging.traceback, 'print_stack',
4912 lambda f, file: called.append(file.getvalue()))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004913
4914 self.logger.findCaller(stack_info=True)
4915
4916 self.assertEqual(len(called), 1)
4917 self.assertEqual('Stack (most recent call last):\n', called[0])
4918
Vinay Sajipdde9fdb2018-06-05 17:24:18 +01004919 def test_find_caller_with_stacklevel(self):
4920 the_level = 1
4921
4922 def innermost():
4923 self.logger.warning('test', stacklevel=the_level)
4924
4925 def inner():
4926 innermost()
4927
4928 def outer():
4929 inner()
4930
4931 records = self.recording.records
4932 outer()
4933 self.assertEqual(records[-1].funcName, 'innermost')
4934 lineno = records[-1].lineno
4935 the_level += 1
4936 outer()
4937 self.assertEqual(records[-1].funcName, 'inner')
4938 self.assertGreater(records[-1].lineno, lineno)
4939 lineno = records[-1].lineno
4940 the_level += 1
4941 outer()
4942 self.assertEqual(records[-1].funcName, 'outer')
4943 self.assertGreater(records[-1].lineno, lineno)
4944 lineno = records[-1].lineno
4945 the_level += 1
4946 outer()
4947 self.assertEqual(records[-1].funcName, 'test_find_caller_with_stacklevel')
4948 self.assertGreater(records[-1].lineno, lineno)
4949
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004950 def test_make_record_with_extra_overwrite(self):
4951 name = 'my record'
4952 level = 13
4953 fn = lno = msg = args = exc_info = func = sinfo = None
4954 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
4955 exc_info, func, sinfo)
4956
4957 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
4958 extra = {key: 'some value'}
4959 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
4960 fn, lno, msg, args, exc_info,
4961 extra=extra, sinfo=sinfo)
4962
4963 def test_make_record_with_extra_no_overwrite(self):
4964 name = 'my record'
4965 level = 13
4966 fn = lno = msg = args = exc_info = func = sinfo = None
4967 extra = {'valid_key': 'some value'}
4968 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
4969 exc_info, extra=extra, sinfo=sinfo)
4970 self.assertIn('valid_key', result.__dict__)
4971
4972 def test_has_handlers(self):
4973 self.assertTrue(self.logger.hasHandlers())
4974
4975 for handler in self.logger.handlers:
4976 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004977 self.assertFalse(self.logger.hasHandlers())
4978
4979 def test_has_handlers_no_propagate(self):
4980 child_logger = logging.getLogger('blah.child')
4981 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004982 self.assertFalse(child_logger.hasHandlers())
4983
4984 def test_is_enabled_for(self):
4985 old_disable = self.logger.manager.disable
4986 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004987 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004988 self.assertFalse(self.logger.isEnabledFor(22))
4989
Timo Furrer6e3ca642018-06-01 09:29:46 +02004990 def test_is_enabled_for_disabled_logger(self):
4991 old_disabled = self.logger.disabled
4992 old_disable = self.logger.manager.disable
4993
4994 self.logger.disabled = True
4995 self.logger.manager.disable = 21
4996
4997 self.addCleanup(setattr, self.logger, 'disabled', old_disabled)
4998 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
4999
5000 self.assertFalse(self.logger.isEnabledFor(22))
5001
Florent Xicluna5252f9f2011-11-07 19:43:05 +01005002 def test_root_logger_aliases(self):
5003 root = logging.getLogger()
5004 self.assertIs(root, logging.root)
5005 self.assertIs(root, logging.getLogger(None))
5006 self.assertIs(root, logging.getLogger(''))
Vinay Sajipcb65b3a2019-08-02 16:53:00 +01005007 self.assertIs(root, logging.getLogger('root'))
Florent Xicluna5252f9f2011-11-07 19:43:05 +01005008 self.assertIs(root, logging.getLogger('foo').root)
5009 self.assertIs(root, logging.getLogger('foo.bar').root)
5010 self.assertIs(root, logging.getLogger('foo').parent)
5011
5012 self.assertIsNot(root, logging.getLogger('\0'))
5013 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
5014
5015 def test_invalid_names(self):
5016 self.assertRaises(TypeError, logging.getLogger, any)
5017 self.assertRaises(TypeError, logging.getLogger, b'foo')
5018
Vinay Sajip6260d9f2017-06-06 16:34:29 +01005019 def test_pickling(self):
5020 for proto in range(pickle.HIGHEST_PROTOCOL + 1):
5021 for name in ('', 'root', 'foo', 'foo.bar', 'baz.bar'):
5022 logger = logging.getLogger(name)
5023 s = pickle.dumps(logger, proto)
5024 unpickled = pickle.loads(s)
5025 self.assertIs(unpickled, logger)
5026
Avram Lubkin78c18a92017-07-30 05:36:33 -04005027 def test_caching(self):
5028 root = self.root_logger
5029 logger1 = logging.getLogger("abc")
5030 logger2 = logging.getLogger("abc.def")
5031
5032 # Set root logger level and ensure cache is empty
5033 root.setLevel(logging.ERROR)
5034 self.assertEqual(logger2.getEffectiveLevel(), logging.ERROR)
5035 self.assertEqual(logger2._cache, {})
5036
5037 # Ensure cache is populated and calls are consistent
5038 self.assertTrue(logger2.isEnabledFor(logging.ERROR))
5039 self.assertFalse(logger2.isEnabledFor(logging.DEBUG))
5040 self.assertEqual(logger2._cache, {logging.ERROR: True, logging.DEBUG: False})
5041 self.assertEqual(root._cache, {})
5042 self.assertTrue(logger2.isEnabledFor(logging.ERROR))
5043
5044 # Ensure root cache gets populated
5045 self.assertEqual(root._cache, {})
5046 self.assertTrue(root.isEnabledFor(logging.ERROR))
5047 self.assertEqual(root._cache, {logging.ERROR: True})
5048
5049 # Set parent logger level and ensure caches are emptied
5050 logger1.setLevel(logging.CRITICAL)
5051 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
5052 self.assertEqual(logger2._cache, {})
5053
5054 # Ensure logger2 uses parent logger's effective level
5055 self.assertFalse(logger2.isEnabledFor(logging.ERROR))
5056
5057 # Set level to NOTSET and ensure caches are empty
5058 logger2.setLevel(logging.NOTSET)
5059 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
5060 self.assertEqual(logger2._cache, {})
5061 self.assertEqual(logger1._cache, {})
5062 self.assertEqual(root._cache, {})
5063
5064 # Verify logger2 follows parent and not root
5065 self.assertFalse(logger2.isEnabledFor(logging.ERROR))
5066 self.assertTrue(logger2.isEnabledFor(logging.CRITICAL))
5067 self.assertFalse(logger1.isEnabledFor(logging.ERROR))
5068 self.assertTrue(logger1.isEnabledFor(logging.CRITICAL))
5069 self.assertTrue(root.isEnabledFor(logging.ERROR))
5070
5071 # Disable logging in manager and ensure caches are clear
5072 logging.disable()
5073 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
5074 self.assertEqual(logger2._cache, {})
5075 self.assertEqual(logger1._cache, {})
5076 self.assertEqual(root._cache, {})
5077
5078 # Ensure no loggers are enabled
5079 self.assertFalse(logger1.isEnabledFor(logging.CRITICAL))
5080 self.assertFalse(logger2.isEnabledFor(logging.CRITICAL))
5081 self.assertFalse(root.isEnabledFor(logging.CRITICAL))
5082
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01005083
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005084class BaseFileTest(BaseTest):
5085 "Base class for handler tests that write log files"
5086
5087 def setUp(self):
5088 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00005089 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
5090 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005091 self.rmfiles = []
5092
5093 def tearDown(self):
5094 for fn in self.rmfiles:
5095 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00005096 if os.path.exists(self.fn):
5097 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00005098 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005099
5100 def assertLogFile(self, filename):
5101 "Assert a log file is there and register it for deletion"
5102 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01005103 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005104 self.rmfiles.append(filename)
5105
5106
Vinay Sajip26fe4b72011-04-26 18:43:05 +01005107class FileHandlerTest(BaseFileTest):
5108 def test_delay(self):
5109 os.unlink(self.fn)
5110 fh = logging.FileHandler(self.fn, delay=True)
5111 self.assertIsNone(fh.stream)
5112 self.assertFalse(os.path.exists(self.fn))
5113 fh.handle(logging.makeLogRecord({}))
5114 self.assertIsNotNone(fh.stream)
5115 self.assertTrue(os.path.exists(self.fn))
5116 fh.close()
5117
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005118class RotatingFileHandlerTest(BaseFileTest):
5119 def next_rec(self):
5120 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
5121 self.next_message(), None, None, None)
5122
5123 def test_should_not_rollover(self):
5124 # If maxbytes is zero rollover never occurs
5125 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
5126 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00005127 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005128
5129 def test_should_rollover(self):
5130 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
5131 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00005132 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005133
5134 def test_file_created(self):
5135 # checks that the file is created and assumes it was created
5136 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005137 rh = logging.handlers.RotatingFileHandler(self.fn)
5138 rh.emit(self.next_rec())
5139 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00005140 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005141
5142 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00005143 def namer(name):
5144 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005145 rh = logging.handlers.RotatingFileHandler(
5146 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005147 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005148 rh.emit(self.next_rec())
5149 self.assertLogFile(self.fn)
5150 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00005151 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005152 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00005153 self.assertLogFile(namer(self.fn + ".2"))
5154 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
5155 rh.close()
5156
l0rb519cb872019-11-06 22:21:40 +01005157 def test_namer_rotator_inheritance(self):
5158 class HandlerWithNamerAndRotator(logging.handlers.RotatingFileHandler):
5159 def namer(self, name):
5160 return name + ".test"
5161
5162 def rotator(self, source, dest):
5163 if os.path.exists(source):
5164 os.rename(source, dest + ".rotated")
5165
5166 rh = HandlerWithNamerAndRotator(
5167 self.fn, backupCount=2, maxBytes=1)
5168 self.assertEqual(rh.namer(self.fn), self.fn + ".test")
5169 rh.emit(self.next_rec())
5170 self.assertLogFile(self.fn)
5171 rh.emit(self.next_rec())
5172 self.assertLogFile(rh.namer(self.fn + ".1") + ".rotated")
5173 self.assertFalse(os.path.exists(rh.namer(self.fn + ".1")))
5174 rh.close()
5175
Hai Shia3ec3ad2020-05-19 06:02:57 +08005176 @support.requires_zlib()
Vinay Sajip23b94d02012-01-04 12:02:26 +00005177 def test_rotator(self):
5178 def namer(name):
5179 return name + ".gz"
5180
5181 def rotator(source, dest):
5182 with open(source, "rb") as sf:
5183 data = sf.read()
5184 compressed = zlib.compress(data, 9)
5185 with open(dest, "wb") as df:
5186 df.write(compressed)
5187 os.remove(source)
5188
5189 rh = logging.handlers.RotatingFileHandler(
5190 self.fn, backupCount=2, maxBytes=1)
5191 rh.rotator = rotator
5192 rh.namer = namer
5193 m1 = self.next_rec()
5194 rh.emit(m1)
5195 self.assertLogFile(self.fn)
5196 m2 = self.next_rec()
5197 rh.emit(m2)
5198 fn = namer(self.fn + ".1")
5199 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005200 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00005201 with open(fn, "rb") as f:
5202 compressed = f.read()
5203 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005204 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005205 rh.emit(self.next_rec())
5206 fn = namer(self.fn + ".2")
5207 self.assertLogFile(fn)
5208 with open(fn, "rb") as f:
5209 compressed = f.read()
5210 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005211 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005212 rh.emit(self.next_rec())
5213 fn = namer(self.fn + ".2")
5214 with open(fn, "rb") as f:
5215 compressed = f.read()
5216 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00005217 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00005218 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00005219 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005220
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005221class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01005222 # other test methods added below
5223 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01005224 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
5225 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00005226 fmt = logging.Formatter('%(asctime)s %(message)s')
5227 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00005228 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00005229 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01005230 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00005231 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00005232 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00005233 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01005234 fh.close()
5235 # At this point, we should have a recent rotated file which we
5236 # can test for the existence of. However, in practice, on some
5237 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01005238 # in time to go to look for the log file. So, we go back a fair
5239 # bit, and stop as soon as we see a rotated file. In theory this
5240 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01005241 found = False
5242 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01005243 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01005244 for secs in range(GO_BACK):
5245 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01005246 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
5247 found = os.path.exists(fn)
5248 if found:
5249 self.rmfiles.append(fn)
5250 break
Vinay Sajip672c5812011-05-13 07:09:40 +01005251 msg = 'No rotated files found, went back %d seconds' % GO_BACK
5252 if not found:
Mike53f7a7c2017-12-14 14:04:53 +03005253 # print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01005254 dn, fn = os.path.split(self.fn)
5255 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02005256 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
5257 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00005258 for f in files:
5259 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00005260 path = os.path.join(dn, f)
5261 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00005262 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01005263 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005264
Vinay Sajip0372e102011-05-05 12:59:14 +01005265 def test_invalid(self):
5266 assertRaises = self.assertRaises
5267 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01005268 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01005269 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01005270 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01005271 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01005272 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01005273
Vinay Sajipa7130792013-04-12 17:04:23 +01005274 def test_compute_rollover_daily_attime(self):
5275 currentTime = 0
5276 atTime = datetime.time(12, 0, 0)
5277 rh = logging.handlers.TimedRotatingFileHandler(
5278 self.fn, when='MIDNIGHT', interval=1, backupCount=0, utc=True,
5279 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01005280 try:
5281 actual = rh.computeRollover(currentTime)
5282 self.assertEqual(actual, currentTime + 12 * 60 * 60)
Vinay Sajipa7130792013-04-12 17:04:23 +01005283
Vinay Sajipd86ac962013-04-14 12:20:46 +01005284 actual = rh.computeRollover(currentTime + 13 * 60 * 60)
5285 self.assertEqual(actual, currentTime + 36 * 60 * 60)
5286 finally:
5287 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01005288
Vinay Sajip10e8c492013-05-18 10:19:54 -07005289 #@unittest.skipIf(True, 'Temporarily skipped while failures investigated.')
Vinay Sajipa7130792013-04-12 17:04:23 +01005290 def test_compute_rollover_weekly_attime(self):
Vinay Sajipd86ac962013-04-14 12:20:46 +01005291 currentTime = int(time.time())
5292 today = currentTime - currentTime % 86400
5293
Vinay Sajipa7130792013-04-12 17:04:23 +01005294 atTime = datetime.time(12, 0, 0)
5295
Vinay Sajip10e8c492013-05-18 10:19:54 -07005296 wday = time.gmtime(today).tm_wday
Vinay Sajipa7130792013-04-12 17:04:23 +01005297 for day in range(7):
5298 rh = logging.handlers.TimedRotatingFileHandler(
5299 self.fn, when='W%d' % day, interval=1, backupCount=0, utc=True,
5300 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01005301 try:
5302 if wday > day:
5303 # The rollover day has already passed this week, so we
5304 # go over into next week
5305 expected = (7 - wday + day)
5306 else:
5307 expected = (day - wday)
5308 # At this point expected is in days from now, convert to seconds
5309 expected *= 24 * 60 * 60
5310 # Add in the rollover time
5311 expected += 12 * 60 * 60
5312 # Add in adjustment for today
5313 expected += today
Vinay Sajip66940a12013-04-15 11:59:35 +01005314 actual = rh.computeRollover(today)
5315 if actual != expected:
5316 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01005317 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01005318 self.assertEqual(actual, expected)
5319 if day == wday:
5320 # goes into following week
5321 expected += 7 * 24 * 60 * 60
Vinay Sajip8b4c7192013-04-14 12:25:25 +01005322 actual = rh.computeRollover(today + 13 * 60 * 60)
Vinay Sajip66940a12013-04-15 11:59:35 +01005323 if actual != expected:
5324 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01005325 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01005326 self.assertEqual(actual, expected)
5327 finally:
5328 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01005329
5330
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005331def secs(**kw):
5332 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
5333
5334for when, exp in (('S', 1),
5335 ('M', 60),
5336 ('H', 60 * 60),
5337 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00005338 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005339 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00005340 ('W0', secs(days=4, hours=24)),
5341 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005342 def test_compute_rollover(self, when=when, exp=exp):
5343 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00005344 self.fn, when=when, interval=1, backupCount=0, utc=True)
5345 currentTime = 0.0
5346 actual = rh.computeRollover(currentTime)
5347 if exp != actual:
5348 # Failures occur on some systems for MIDNIGHT and W0.
5349 # Print detailed calculation for MIDNIGHT so we can try to see
5350 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00005351 if when == 'MIDNIGHT':
5352 try:
5353 if rh.utc:
5354 t = time.gmtime(currentTime)
5355 else:
5356 t = time.localtime(currentTime)
5357 currentHour = t[3]
5358 currentMinute = t[4]
5359 currentSecond = t[5]
5360 # r is the number of seconds left between now and midnight
5361 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
5362 currentMinute) * 60 +
5363 currentSecond)
5364 result = currentTime + r
5365 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
5366 print('currentHour: %s' % currentHour, file=sys.stderr)
5367 print('currentMinute: %s' % currentMinute, file=sys.stderr)
5368 print('currentSecond: %s' % currentSecond, file=sys.stderr)
5369 print('r: %s' % r, file=sys.stderr)
5370 print('result: %s' % result, file=sys.stderr)
5371 except Exception:
5372 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
5373 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00005374 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00005375 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
5376
Vinay Sajip60ccd822011-05-09 17:32:09 +01005377
Vinay Sajip223349c2015-10-01 20:37:54 +01005378@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil/pywintypes required for this test.')
Vinay Sajip60ccd822011-05-09 17:32:09 +01005379class NTEventLogHandlerTest(BaseTest):
5380 def test_basic(self):
5381 logtype = 'Application'
5382 elh = win32evtlog.OpenEventLog(None, logtype)
5383 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
Vinay Sajip223349c2015-10-01 20:37:54 +01005384
5385 try:
5386 h = logging.handlers.NTEventLogHandler('test_logging')
5387 except pywintypes.error as e:
Zachary Ware22226c52015-10-06 15:22:13 -05005388 if e.winerror == 5: # access denied
Vinay Sajip223349c2015-10-01 20:37:54 +01005389 raise unittest.SkipTest('Insufficient privileges to run test')
Zachary Ware106ddf02015-10-06 15:28:43 -05005390 raise
Vinay Sajip223349c2015-10-01 20:37:54 +01005391
Vinay Sajip60ccd822011-05-09 17:32:09 +01005392 r = logging.makeLogRecord({'msg': 'Test Log Message'})
5393 h.handle(r)
5394 h.close()
5395 # Now see if the event is recorded
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02005396 self.assertLess(num_recs, win32evtlog.GetNumberOfEventLogRecords(elh))
Vinay Sajip60ccd822011-05-09 17:32:09 +01005397 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
5398 win32evtlog.EVENTLOG_SEQUENTIAL_READ
5399 found = False
5400 GO_BACK = 100
5401 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
5402 for e in events:
5403 if e.SourceName != 'test_logging':
5404 continue
5405 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
5406 if msg != 'Test Log Message\r\n':
5407 continue
5408 found = True
5409 break
5410 msg = 'Record not found in event log, went back %d records' % GO_BACK
5411 self.assertTrue(found, msg=msg)
5412
Vinay Sajipdb8f4632016-09-08 01:37:03 +01005413
5414class MiscTestCase(unittest.TestCase):
5415 def test__all__(self):
Victor Stinnerfbf43f02020-08-17 07:20:40 +02005416 not_exported = {
5417 'logThreads', 'logMultiprocessing', 'logProcesses', 'currentframe',
5418 'PercentStyle', 'StrFormatStyle', 'StringTemplateStyle',
5419 'Filterer', 'PlaceHolder', 'Manager', 'RootLogger', 'root',
5420 'threading'}
5421 support.check__all__(self, logging, not_exported=not_exported)
Vinay Sajipdb8f4632016-09-08 01:37:03 +01005422
5423
Christian Heimes180510d2008-03-03 19:15:45 +00005424# Set the locale to the platform-dependent default. I have no idea
5425# why the test does this, but in any case we save the current locale
5426# first and restore it at the end.
Vinay Sajip1feedb42014-05-31 08:19:12 +01005427@support.run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00005428def test_main():
Vinay Sajipd61910c2016-09-08 01:13:39 +01005429 tests = [
Vinay Sajip1feedb42014-05-31 08:19:12 +01005430 BuiltinLevelsTest, BasicFilterTest, CustomLevelsAndFiltersTest,
5431 HandlerTest, MemoryHandlerTest, ConfigFileTest, SocketHandlerTest,
5432 DatagramHandlerTest, MemoryTest, EncodingTest, WarningsTest,
5433 ConfigDictTest, ManagerTest, FormatterTest, BufferingFormatterTest,
5434 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
5435 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest, BasicConfigTest,
5436 LoggerAdapterTest, LoggerTest, SMTPHandlerTest, FileHandlerTest,
5437 RotatingFileHandlerTest, LastResortTest, LogRecordTest,
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08005438 ExceptionTest, SysLogHandlerTest, IPv6SysLogHandlerTest, HTTPHandlerTest,
Vinay Sajip1feedb42014-05-31 08:19:12 +01005439 NTEventLogHandlerTest, TimedRotatingFileHandlerTest,
Vinay Sajipd61910c2016-09-08 01:13:39 +01005440 UnixSocketHandlerTest, UnixDatagramHandlerTest, UnixSysLogHandlerTest,
Vinay Sajipdb8f4632016-09-08 01:37:03 +01005441 MiscTestCase
Vinay Sajipd61910c2016-09-08 01:13:39 +01005442 ]
5443 if hasattr(logging.handlers, 'QueueListener'):
5444 tests.append(QueueListenerTest)
5445 support.run_unittest(*tests)
Jeremy Hylton096d9862003-07-18 03:19:20 +00005446
Christian Heimes180510d2008-03-03 19:15:45 +00005447if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00005448 test_main()