blob: 3b671ce2ab370914fd782c5d0f976ad478eddc37 [file] [log] [blame]
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001# Copyright 2001-2017 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 Sajip1e6499c2017-01-09 16:54:12 +000019Copyright (C) 2001-2017 Vinay Sajip. All Rights Reserved.
Neal Norwitzb4a2df02003-01-02 14:56:39 +000020"""
21
Christian Heimes180510d2008-03-03 19:15:45 +000022import logging
23import logging.handlers
24import logging.config
Christian Heimes18c66892008-02-17 13:31:39 +000025
Benjamin Petersonf91df042009-02-13 02:50:59 +000026import codecs
Vinay Sajipcf9e2f22012-10-09 09:06:03 +010027import configparser
Vinay Sajip19ec67a2010-09-17 18:57:36 +000028import datetime
Vinay Sajipdb8f4632016-09-08 01:37:03 +010029import pathlib
Christian Heimes180510d2008-03-03 19:15:45 +000030import pickle
31import io
32import gc
Vinay Sajipdb81c4c2010-02-25 23:13:06 +000033import json
Christian Heimes180510d2008-03-03 19:15:45 +000034import os
Vinay Sajip8552d1f2010-09-14 09:34:09 +000035import queue
Vinay Sajip66b8b082012-04-24 23:25:30 +010036import random
Christian Heimes180510d2008-03-03 19:15:45 +000037import re
Miss Islington (bot)3b699932018-10-07 00:09:59 -070038import signal
Christian Heimes180510d2008-03-03 19:15:45 +000039import socket
Christian Heimes180510d2008-03-03 19:15:45 +000040import struct
41import sys
42import tempfile
Miss Islington (bot)6a7a9f12019-03-18 07:22:41 -070043from test.support.script_helper import assert_python_ok, assert_python_failure
Vinay Sajip1feedb42014-05-31 08:19:12 +010044from test import support
Christian Heimes180510d2008-03-03 19:15:45 +000045import textwrap
Antoine Pitroua6a4dc82017-09-07 18:56:24 +020046import threading
Vinay Sajip37eb3382011-04-26 20:26:41 +010047import time
Christian Heimes180510d2008-03-03 19:15:45 +000048import unittest
Georg Brandlf9734072008-12-07 15:30:06 +000049import warnings
Christian Heimes180510d2008-03-03 19:15:45 +000050import weakref
Antoine Pitroua6a4dc82017-09-07 18:56:24 +020051
52import asyncore
53from http.server import HTTPServer, BaseHTTPRequestHandler
54import smtpd
55from urllib.parse import urlparse, parse_qs
56from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
57 ThreadingTCPServer, StreamRequestHandler)
58
Vinay Sajip60ccd822011-05-09 17:32:09 +010059try:
Vinay Sajip223349c2015-10-01 20:37:54 +010060 import win32evtlog, win32evtlogutil, pywintypes
Vinay Sajip60ccd822011-05-09 17:32:09 +010061except ImportError:
Vinay Sajip223349c2015-10-01 20:37:54 +010062 win32evtlog = win32evtlogutil = pywintypes = None
63
Eric V. Smith851cad72012-03-11 22:46:04 -070064try:
65 import zlib
66except ImportError:
67 pass
Christian Heimes18c66892008-02-17 13:31:39 +000068
Christian Heimes180510d2008-03-03 19:15:45 +000069class BaseTest(unittest.TestCase):
70
71 """Base class for logging tests."""
72
73 log_format = "%(name)s -> %(levelname)s: %(message)s"
Ezio Melotti3ffd29b2012-10-02 19:45:00 +030074 expected_log_pat = r"^([\w.]+) -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +000075 message_num = 0
76
77 def setUp(self):
78 """Setup the default logging stream to an internal StringIO instance,
79 so that we can examine log output as we want."""
Victor Stinner69669602017-08-18 23:47:54 +020080 self._threading_key = support.threading_setup()
81
Christian Heimes180510d2008-03-03 19:15:45 +000082 logger_dict = logging.getLogger().manager.loggerDict
Christian Heimes18c66892008-02-17 13:31:39 +000083 logging._acquireLock()
84 try:
Christian Heimes180510d2008-03-03 19:15:45 +000085 self.saved_handlers = logging._handlers.copy()
86 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000087 self.saved_loggers = saved_loggers = logger_dict.copy()
Vinay Sajip3b84eae2013-05-25 03:20:34 -070088 self.saved_name_to_level = logging._nameToLevel.copy()
89 self.saved_level_to_name = logging._levelToName.copy()
Vinay Sajip7b60f4e2010-12-27 14:31:52 +000090 self.logger_states = logger_states = {}
91 for name in saved_loggers:
92 logger_states[name] = getattr(saved_loggers[name],
93 'disabled', None)
Christian Heimes18c66892008-02-17 13:31:39 +000094 finally:
95 logging._releaseLock()
96
Florent Xicluna5252f9f2011-11-07 19:43:05 +010097 # Set two unused loggers
Vinay Sajipb4a08092010-09-20 09:55:00 +000098 self.logger1 = logging.getLogger("\xab\xd7\xbb")
99 self.logger2 = logging.getLogger("\u013f\u00d6\u0047")
Benjamin Peterson22005fc2010-04-11 16:25:06 +0000100
Christian Heimes180510d2008-03-03 19:15:45 +0000101 self.root_logger = logging.getLogger("")
102 self.original_logging_level = self.root_logger.getEffectiveLevel()
103
104 self.stream = io.StringIO()
105 self.root_logger.setLevel(logging.DEBUG)
106 self.root_hdlr = logging.StreamHandler(self.stream)
107 self.root_formatter = logging.Formatter(self.log_format)
108 self.root_hdlr.setFormatter(self.root_formatter)
Vinay Sajip7b0e86e2010-12-30 23:26:50 +0000109 if self.logger1.hasHandlers():
110 hlist = self.logger1.handlers + self.root_logger.handlers
111 raise AssertionError('Unexpected handlers: %s' % hlist)
112 if self.logger2.hasHandlers():
113 hlist = self.logger2.handlers + self.root_logger.handlers
114 raise AssertionError('Unexpected handlers: %s' % hlist)
Christian Heimes180510d2008-03-03 19:15:45 +0000115 self.root_logger.addHandler(self.root_hdlr)
Vinay Sajipb4a08092010-09-20 09:55:00 +0000116 self.assertTrue(self.logger1.hasHandlers())
117 self.assertTrue(self.logger2.hasHandlers())
Christian Heimes180510d2008-03-03 19:15:45 +0000118
119 def tearDown(self):
120 """Remove our logging stream, and restore the original logging
121 level."""
122 self.stream.close()
123 self.root_logger.removeHandler(self.root_hdlr)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +0000124 while self.root_logger.handlers:
125 h = self.root_logger.handlers[0]
126 self.root_logger.removeHandler(h)
127 h.close()
Christian Heimes180510d2008-03-03 19:15:45 +0000128 self.root_logger.setLevel(self.original_logging_level)
129 logging._acquireLock()
130 try:
Vinay Sajip3b84eae2013-05-25 03:20:34 -0700131 logging._levelToName.clear()
132 logging._levelToName.update(self.saved_level_to_name)
133 logging._nameToLevel.clear()
134 logging._nameToLevel.update(self.saved_name_to_level)
Christian Heimes180510d2008-03-03 19:15:45 +0000135 logging._handlers.clear()
136 logging._handlers.update(self.saved_handlers)
137 logging._handlerList[:] = self.saved_handler_list
Avram Lubkin78c18a92017-07-30 05:36:33 -0400138 manager = logging.getLogger().manager
139 manager.disable = 0
140 loggerDict = manager.loggerDict
Christian Heimes180510d2008-03-03 19:15:45 +0000141 loggerDict.clear()
142 loggerDict.update(self.saved_loggers)
Vinay Sajip7b60f4e2010-12-27 14:31:52 +0000143 logger_states = self.logger_states
144 for name in self.logger_states:
145 if logger_states[name] is not None:
146 self.saved_loggers[name].disabled = logger_states[name]
Christian Heimes180510d2008-03-03 19:15:45 +0000147 finally:
148 logging._releaseLock()
149
Victor Stinner69669602017-08-18 23:47:54 +0200150 self.doCleanups()
151 support.threading_cleanup(*self._threading_key)
152
Vinay Sajip4ded5512012-10-02 15:56:16 +0100153 def assert_log_lines(self, expected_values, stream=None, pat=None):
Christian Heimes180510d2008-03-03 19:15:45 +0000154 """Match the collected log lines against the regular expression
155 self.expected_log_pat, and compare the extracted group values to
156 the expected_values list of tuples."""
157 stream = stream or self.stream
Vinay Sajip4ded5512012-10-02 15:56:16 +0100158 pat = re.compile(pat or self.expected_log_pat)
Serhiy Storchaka50254c52013-08-29 11:35:43 +0300159 actual_lines = stream.getvalue().splitlines()
Vinay Sajip5056c8c2011-06-05 09:31:34 +0100160 self.assertEqual(len(actual_lines), len(expected_values))
Christian Heimes180510d2008-03-03 19:15:45 +0000161 for actual, expected in zip(actual_lines, expected_values):
162 match = pat.search(actual)
163 if not match:
164 self.fail("Log line does not match expected pattern:\n" +
165 actual)
Ezio Melottib3aedd42010-11-20 19:04:17 +0000166 self.assertEqual(tuple(match.groups()), expected)
Christian Heimes180510d2008-03-03 19:15:45 +0000167 s = stream.read()
168 if s:
169 self.fail("Remaining output at end of log stream:\n" + s)
170
171 def next_message(self):
172 """Generate a message consisting solely of an auto-incrementing
173 integer."""
174 self.message_num += 1
175 return "%d" % self.message_num
176
177
178class BuiltinLevelsTest(BaseTest):
179 """Test builtin levels and their inheritance."""
180
181 def test_flat(self):
Mike53f7a7c2017-12-14 14:04:53 +0300182 # Logging levels in a flat logger namespace.
Christian Heimes180510d2008-03-03 19:15:45 +0000183 m = self.next_message
184
185 ERR = logging.getLogger("ERR")
186 ERR.setLevel(logging.ERROR)
Vinay Sajipc84f0162010-09-21 11:25:39 +0000187 INF = logging.LoggerAdapter(logging.getLogger("INF"), {})
Christian Heimes180510d2008-03-03 19:15:45 +0000188 INF.setLevel(logging.INFO)
189 DEB = logging.getLogger("DEB")
190 DEB.setLevel(logging.DEBUG)
191
192 # These should log.
193 ERR.log(logging.CRITICAL, m())
194 ERR.error(m())
195
196 INF.log(logging.CRITICAL, m())
197 INF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100198 INF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000199 INF.info(m())
200
201 DEB.log(logging.CRITICAL, m())
202 DEB.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100203 DEB.warning(m())
204 DEB.info(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000205 DEB.debug(m())
206
207 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100208 ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000209 ERR.info(m())
210 ERR.debug(m())
211
212 INF.debug(m())
213
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000214 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000215 ('ERR', 'CRITICAL', '1'),
216 ('ERR', 'ERROR', '2'),
217 ('INF', 'CRITICAL', '3'),
218 ('INF', 'ERROR', '4'),
219 ('INF', 'WARNING', '5'),
220 ('INF', 'INFO', '6'),
221 ('DEB', 'CRITICAL', '7'),
222 ('DEB', 'ERROR', '8'),
223 ('DEB', 'WARNING', '9'),
224 ('DEB', 'INFO', '10'),
225 ('DEB', 'DEBUG', '11'),
226 ])
227
228 def test_nested_explicit(self):
229 # Logging levels in a nested namespace, all explicitly set.
230 m = self.next_message
231
232 INF = logging.getLogger("INF")
233 INF.setLevel(logging.INFO)
234 INF_ERR = logging.getLogger("INF.ERR")
235 INF_ERR.setLevel(logging.ERROR)
236
237 # These should log.
238 INF_ERR.log(logging.CRITICAL, m())
239 INF_ERR.error(m())
240
241 # These should not log.
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100242 INF_ERR.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000243 INF_ERR.info(m())
244 INF_ERR.debug(m())
245
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000246 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000247 ('INF.ERR', 'CRITICAL', '1'),
248 ('INF.ERR', 'ERROR', '2'),
249 ])
250
251 def test_nested_inherited(self):
Mike53f7a7c2017-12-14 14:04:53 +0300252 # Logging levels in a nested namespace, inherited from parent loggers.
Christian Heimes180510d2008-03-03 19:15:45 +0000253 m = self.next_message
254
255 INF = logging.getLogger("INF")
256 INF.setLevel(logging.INFO)
257 INF_ERR = logging.getLogger("INF.ERR")
258 INF_ERR.setLevel(logging.ERROR)
259 INF_UNDEF = logging.getLogger("INF.UNDEF")
260 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
261 UNDEF = logging.getLogger("UNDEF")
262
263 # These should log.
264 INF_UNDEF.log(logging.CRITICAL, m())
265 INF_UNDEF.error(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100266 INF_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000267 INF_UNDEF.info(m())
268 INF_ERR_UNDEF.log(logging.CRITICAL, m())
269 INF_ERR_UNDEF.error(m())
270
271 # These should not log.
272 INF_UNDEF.debug(m())
Vinay Sajipb9e46e92011-10-26 13:17:20 +0100273 INF_ERR_UNDEF.warning(m())
Christian Heimes180510d2008-03-03 19:15:45 +0000274 INF_ERR_UNDEF.info(m())
275 INF_ERR_UNDEF.debug(m())
276
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000277 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000278 ('INF.UNDEF', 'CRITICAL', '1'),
279 ('INF.UNDEF', 'ERROR', '2'),
280 ('INF.UNDEF', 'WARNING', '3'),
281 ('INF.UNDEF', 'INFO', '4'),
282 ('INF.ERR.UNDEF', 'CRITICAL', '5'),
283 ('INF.ERR.UNDEF', 'ERROR', '6'),
284 ])
285
286 def test_nested_with_virtual_parent(self):
287 # Logging levels when some parent does not exist yet.
288 m = self.next_message
289
290 INF = logging.getLogger("INF")
291 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
292 CHILD = logging.getLogger("INF.BADPARENT")
293 INF.setLevel(logging.INFO)
294
295 # These should log.
296 GRANDCHILD.log(logging.FATAL, m())
297 GRANDCHILD.info(m())
298 CHILD.log(logging.FATAL, m())
299 CHILD.info(m())
300
301 # These should not log.
302 GRANDCHILD.debug(m())
303 CHILD.debug(m())
304
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000305 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000306 ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'),
307 ('INF.BADPARENT.UNDEF', 'INFO', '2'),
308 ('INF.BADPARENT', 'CRITICAL', '3'),
309 ('INF.BADPARENT', 'INFO', '4'),
310 ])
311
Vinay Sajipd1d4fbf2014-09-11 23:06:09 +0100312 def test_regression_22386(self):
313 """See issue #22386 for more information."""
314 self.assertEqual(logging.getLevelName('INFO'), logging.INFO)
315 self.assertEqual(logging.getLevelName(logging.INFO), 'INFO')
Christian Heimes180510d2008-03-03 19:15:45 +0000316
Vinay Sajip8b866d52017-01-11 06:57:55 +0000317 def test_regression_29220(self):
318 """See issue #29220 for more information."""
319 logging.addLevelName(logging.INFO, '')
320 self.addCleanup(logging.addLevelName, logging.INFO, 'INFO')
321 self.assertEqual(logging.getLevelName(logging.INFO), '')
322
Vinay Sajipdb8f4632016-09-08 01:37:03 +0100323 def test_issue27935(self):
324 fatal = logging.getLevelName('FATAL')
325 self.assertEqual(fatal, logging.FATAL)
326
Vinay Sajip924aaae2017-01-11 17:35:36 +0000327 def test_regression_29220(self):
328 """See issue #29220 for more information."""
329 logging.addLevelName(logging.INFO, '')
330 self.addCleanup(logging.addLevelName, logging.INFO, 'INFO')
331 self.assertEqual(logging.getLevelName(logging.INFO), '')
332 self.assertEqual(logging.getLevelName(logging.NOTSET), 'NOTSET')
333 self.assertEqual(logging.getLevelName('NOTSET'), logging.NOTSET)
334
Christian Heimes180510d2008-03-03 19:15:45 +0000335class BasicFilterTest(BaseTest):
336
337 """Test the bundled Filter class."""
338
339 def test_filter(self):
340 # Only messages satisfying the specified criteria pass through the
341 # filter.
342 filter_ = logging.Filter("spam.eggs")
343 handler = self.root_logger.handlers[0]
344 try:
345 handler.addFilter(filter_)
346 spam = logging.getLogger("spam")
347 spam_eggs = logging.getLogger("spam.eggs")
348 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
349 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
350
351 spam.info(self.next_message())
352 spam_eggs.info(self.next_message()) # Good.
353 spam_eggs_fish.info(self.next_message()) # Good.
354 spam_bakedbeans.info(self.next_message())
355
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000356 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000357 ('spam.eggs', 'INFO', '2'),
358 ('spam.eggs.fish', 'INFO', '3'),
359 ])
360 finally:
361 handler.removeFilter(filter_)
362
Vinay Sajip6dbed2e2010-10-19 20:53:01 +0000363 def test_callable_filter(self):
364 # Only messages satisfying the specified criteria pass through the
365 # filter.
366
367 def filterfunc(record):
368 parts = record.name.split('.')
369 prefix = '.'.join(parts[:2])
370 return prefix == 'spam.eggs'
371
372 handler = self.root_logger.handlers[0]
373 try:
374 handler.addFilter(filterfunc)
375 spam = logging.getLogger("spam")
376 spam_eggs = logging.getLogger("spam.eggs")
377 spam_eggs_fish = logging.getLogger("spam.eggs.fish")
378 spam_bakedbeans = logging.getLogger("spam.bakedbeans")
379
380 spam.info(self.next_message())
381 spam_eggs.info(self.next_message()) # Good.
382 spam_eggs_fish.info(self.next_message()) # Good.
383 spam_bakedbeans.info(self.next_message())
384
385 self.assert_log_lines([
386 ('spam.eggs', 'INFO', '2'),
387 ('spam.eggs.fish', 'INFO', '3'),
388 ])
389 finally:
390 handler.removeFilter(filterfunc)
391
Vinay Sajip985ef872011-04-26 19:34:04 +0100392 def test_empty_filter(self):
393 f = logging.Filter()
394 r = logging.makeLogRecord({'name': 'spam.eggs'})
395 self.assertTrue(f.filter(r))
Christian Heimes180510d2008-03-03 19:15:45 +0000396
397#
398# First, we define our levels. There can be as many as you want - the only
399# limitations are that they should be integers, the lowest should be > 0 and
400# larger values mean less information being logged. If you need specific
401# level values which do not fit into these limitations, you can use a
402# mapping dictionary to convert between your application levels and the
403# logging system.
404#
405SILENT = 120
406TACITURN = 119
407TERSE = 118
408EFFUSIVE = 117
409SOCIABLE = 116
410VERBOSE = 115
411TALKATIVE = 114
412GARRULOUS = 113
413CHATTERBOX = 112
414BORING = 111
415
416LEVEL_RANGE = range(BORING, SILENT + 1)
417
418#
419# Next, we define names for our levels. You don't need to do this - in which
420# case the system will use "Level n" to denote the text for the level.
421#
422my_logging_levels = {
423 SILENT : 'Silent',
424 TACITURN : 'Taciturn',
425 TERSE : 'Terse',
426 EFFUSIVE : 'Effusive',
427 SOCIABLE : 'Sociable',
428 VERBOSE : 'Verbose',
429 TALKATIVE : 'Talkative',
430 GARRULOUS : 'Garrulous',
431 CHATTERBOX : 'Chatterbox',
432 BORING : 'Boring',
433}
434
435class GarrulousFilter(logging.Filter):
436
437 """A filter which blocks garrulous messages."""
438
439 def filter(self, record):
440 return record.levelno != GARRULOUS
441
442class VerySpecificFilter(logging.Filter):
443
444 """A filter which blocks sociable and taciturn messages."""
445
446 def filter(self, record):
447 return record.levelno not in [SOCIABLE, TACITURN]
448
449
450class CustomLevelsAndFiltersTest(BaseTest):
451
452 """Test various filtering possibilities with custom logging levels."""
453
454 # Skip the logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +0300455 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +0000456
457 def setUp(self):
458 BaseTest.setUp(self)
Benjamin Peterson9451a1c2010-03-13 22:30:34 +0000459 for k, v in my_logging_levels.items():
Christian Heimes180510d2008-03-03 19:15:45 +0000460 logging.addLevelName(k, v)
461
462 def log_at_all_levels(self, logger):
463 for lvl in LEVEL_RANGE:
464 logger.log(lvl, self.next_message())
465
466 def test_logger_filter(self):
467 # Filter at logger level.
468 self.root_logger.setLevel(VERBOSE)
469 # Levels >= 'Verbose' are good.
470 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000471 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000472 ('Verbose', '5'),
473 ('Sociable', '6'),
474 ('Effusive', '7'),
475 ('Terse', '8'),
476 ('Taciturn', '9'),
477 ('Silent', '10'),
478 ])
479
480 def test_handler_filter(self):
481 # Filter at handler level.
482 self.root_logger.handlers[0].setLevel(SOCIABLE)
483 try:
484 # Levels >= 'Sociable' are good.
485 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000486 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +0000487 ('Sociable', '6'),
488 ('Effusive', '7'),
489 ('Terse', '8'),
490 ('Taciturn', '9'),
491 ('Silent', '10'),
492 ])
493 finally:
494 self.root_logger.handlers[0].setLevel(logging.NOTSET)
495
496 def test_specific_filters(self):
497 # Set a specific filter object on the handler, and then add another
498 # filter object on the logger itself.
499 handler = self.root_logger.handlers[0]
500 specific_filter = None
501 garr = GarrulousFilter()
502 handler.addFilter(garr)
503 try:
504 self.log_at_all_levels(self.root_logger)
505 first_lines = [
506 # Notice how 'Garrulous' is missing
507 ('Boring', '1'),
508 ('Chatterbox', '2'),
509 ('Talkative', '4'),
510 ('Verbose', '5'),
511 ('Sociable', '6'),
512 ('Effusive', '7'),
513 ('Terse', '8'),
514 ('Taciturn', '9'),
515 ('Silent', '10'),
516 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000517 self.assert_log_lines(first_lines)
Christian Heimes180510d2008-03-03 19:15:45 +0000518
519 specific_filter = VerySpecificFilter()
520 self.root_logger.addFilter(specific_filter)
521 self.log_at_all_levels(self.root_logger)
Benjamin Peterson77108eb2009-07-01 00:43:10 +0000522 self.assert_log_lines(first_lines + [
Christian Heimes180510d2008-03-03 19:15:45 +0000523 # Not only 'Garrulous' is still missing, but also 'Sociable'
524 # and 'Taciturn'
525 ('Boring', '11'),
526 ('Chatterbox', '12'),
527 ('Talkative', '14'),
528 ('Verbose', '15'),
529 ('Effusive', '17'),
530 ('Terse', '18'),
531 ('Silent', '20'),
532 ])
533 finally:
534 if specific_filter:
535 self.root_logger.removeFilter(specific_filter)
536 handler.removeFilter(garr)
537
538
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100539class HandlerTest(BaseTest):
540 def test_name(self):
541 h = logging.Handler()
542 h.name = 'generic'
543 self.assertEqual(h.name, 'generic')
544 h.name = 'anothergeneric'
545 self.assertEqual(h.name, 'anothergeneric')
546 self.assertRaises(NotImplementedError, h.emit, None)
547
Vinay Sajip5a35b062011-04-27 11:31:14 +0100548 def test_builtin_handlers(self):
549 # We can't actually *use* too many handlers in the tests,
550 # but we can try instantiating them with various options
Victor Stinnere6747472011-08-21 00:39:18 +0200551 if sys.platform in ('linux', 'darwin'):
Vinay Sajip5a35b062011-04-27 11:31:14 +0100552 for existing in (True, False):
553 fd, fn = tempfile.mkstemp()
554 os.close(fd)
555 if not existing:
556 os.unlink(fn)
557 h = logging.handlers.WatchedFileHandler(fn, delay=True)
558 if existing:
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100559 dev, ino = h.dev, h.ino
Vinay Sajipa5798de2012-04-24 23:33:33 +0100560 self.assertEqual(dev, -1)
561 self.assertEqual(ino, -1)
Vinay Sajip7fe1d512011-04-28 12:04:58 +0100562 r = logging.makeLogRecord({'msg': 'Test'})
563 h.handle(r)
564 # Now remove the file.
565 os.unlink(fn)
566 self.assertFalse(os.path.exists(fn))
567 # The next call should recreate the file.
568 h.handle(r)
569 self.assertTrue(os.path.exists(fn))
Vinay Sajip5a35b062011-04-27 11:31:14 +0100570 else:
571 self.assertEqual(h.dev, -1)
572 self.assertEqual(h.ino, -1)
573 h.close()
574 if existing:
575 os.unlink(fn)
576 if sys.platform == 'darwin':
Vinay Sajip6bba65c2011-04-27 14:31:55 +0100577 sockname = '/var/run/syslog'
Vinay Sajip5a35b062011-04-27 11:31:14 +0100578 else:
579 sockname = '/dev/log'
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100580 try:
581 h = logging.handlers.SysLogHandler(sockname)
582 self.assertEqual(h.facility, h.LOG_USER)
583 self.assertTrue(h.unixsocket)
584 h.close()
Andrew Svetlov0832af62012-12-18 23:10:48 +0200585 except OSError: # syslogd might not be available
Vinay Sajipdbeb2742011-04-27 14:18:06 +0100586 pass
Vinay Sajip5a35b062011-04-27 11:31:14 +0100587 for method in ('GET', 'POST', 'PUT'):
588 if method == 'PUT':
589 self.assertRaises(ValueError, logging.handlers.HTTPHandler,
590 'localhost', '/log', method)
591 else:
592 h = logging.handlers.HTTPHandler('localhost', '/log', method)
593 h.close()
594 h = logging.handlers.BufferingHandler(0)
595 r = logging.makeLogRecord({})
596 self.assertTrue(h.shouldFlush(r))
597 h.close()
598 h = logging.handlers.BufferingHandler(1)
599 self.assertFalse(h.shouldFlush(r))
600 h.close()
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100601
Vinay Sajipdb8f4632016-09-08 01:37:03 +0100602 def test_path_objects(self):
603 """
604 Test that Path objects are accepted as filename arguments to handlers.
605
606 See Issue #27493.
607 """
608 fd, fn = tempfile.mkstemp()
609 os.close(fd)
610 os.unlink(fn)
611 pfn = pathlib.Path(fn)
612 cases = (
613 (logging.FileHandler, (pfn, 'w')),
614 (logging.handlers.RotatingFileHandler, (pfn, 'a')),
615 (logging.handlers.TimedRotatingFileHandler, (pfn, 'h')),
616 )
617 if sys.platform in ('linux', 'darwin'):
618 cases += ((logging.handlers.WatchedFileHandler, (pfn, 'w')),)
619 for cls, args in cases:
620 h = cls(*args)
621 self.assertTrue(os.path.exists(fn))
622 h.close()
623 os.unlink(fn)
624
Vinay Sajip5e86eed2012-05-29 22:48:10 +0100625 @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.')
Vinay Sajipa5798de2012-04-24 23:33:33 +0100626 def test_race(self):
627 # Issue #14632 refers.
628 def remove_loop(fname, tries):
629 for _ in range(tries):
630 try:
631 os.unlink(fname)
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000632 self.deletion_time = time.time()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100633 except OSError:
634 pass
635 time.sleep(0.004 * random.randint(0, 4))
636
Vinay Sajipc94871a2012-04-25 10:51:35 +0100637 del_count = 500
638 log_count = 500
Vinay Sajipa5798de2012-04-24 23:33:33 +0100639
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000640 self.handle_time = None
641 self.deletion_time = None
642
Vinay Sajipa5798de2012-04-24 23:33:33 +0100643 for delay in (False, True):
Vinay Sajipc94871a2012-04-25 10:51:35 +0100644 fd, fn = tempfile.mkstemp('.log', 'test_logging-3-')
645 os.close(fd)
646 remover = threading.Thread(target=remove_loop, args=(fn, del_count))
647 remover.daemon = True
648 remover.start()
Vinay Sajipa5798de2012-04-24 23:33:33 +0100649 h = logging.handlers.WatchedFileHandler(fn, delay=delay)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100650 f = logging.Formatter('%(asctime)s: %(levelname)s: %(message)s')
651 h.setFormatter(f)
Vinay Sajipc94871a2012-04-25 10:51:35 +0100652 try:
653 for _ in range(log_count):
654 time.sleep(0.005)
655 r = logging.makeLogRecord({'msg': 'testing' })
Vinay Sajipdc96ca22013-12-03 12:31:23 +0000656 try:
657 self.handle_time = time.time()
658 h.handle(r)
659 except Exception:
660 print('Deleted at %s, '
661 'opened at %s' % (self.deletion_time,
662 self.handle_time))
663 raise
Vinay Sajipc94871a2012-04-25 10:51:35 +0100664 finally:
Vinay Sajipc94871a2012-04-25 10:51:35 +0100665 remover.join()
Vinay Sajipac20f462012-05-03 12:09:38 +0100666 h.close()
Vinay Sajipc94871a2012-04-25 10:51:35 +0100667 if os.path.exists(fn):
668 os.unlink(fn)
Vinay Sajipa5798de2012-04-24 23:33:33 +0100669
Miss Islington (bot)3b699932018-10-07 00:09:59 -0700670 # The implementation relies on os.register_at_fork existing, but we test
671 # based on os.fork existing because that is what users and this test use.
672 # This helps ensure that when fork exists (the important concept) that the
673 # register_at_fork mechanism is also present and used.
674 @unittest.skipIf(not hasattr(os, 'fork'), 'Test requires os.fork().')
675 def test_post_fork_child_no_deadlock(self):
676 """Ensure forked child logging locks are not held; bpo-6721."""
677 refed_h = logging.Handler()
678 refed_h.name = 'because we need at least one for this test'
679 self.assertGreater(len(logging._handlers), 0)
680
681 locks_held__ready_to_fork = threading.Event()
682 fork_happened__release_locks_and_end_thread = threading.Event()
683
684 def lock_holder_thread_fn():
685 logging._acquireLock()
686 try:
687 refed_h.acquire()
688 try:
689 # Tell the main thread to do the fork.
690 locks_held__ready_to_fork.set()
691
692 # If the deadlock bug exists, the fork will happen
693 # without dealing with the locks we hold, deadlocking
694 # the child.
695
696 # Wait for a successful fork or an unreasonable amount of
697 # time before releasing our locks. To avoid a timing based
698 # test we'd need communication from os.fork() as to when it
699 # has actually happened. Given this is a regression test
700 # for a fixed issue, potentially less reliably detecting
701 # regression via timing is acceptable for simplicity.
702 # The test will always take at least this long. :(
703 fork_happened__release_locks_and_end_thread.wait(0.5)
704 finally:
705 refed_h.release()
706 finally:
707 logging._releaseLock()
708
709 lock_holder_thread = threading.Thread(
710 target=lock_holder_thread_fn,
711 name='test_post_fork_child_no_deadlock lock holder')
712 lock_holder_thread.start()
713
714 locks_held__ready_to_fork.wait()
715 pid = os.fork()
716 if pid == 0: # Child.
717 logging.error(r'Child process did not deadlock. \o/')
718 os._exit(0)
719 else: # Parent.
720 fork_happened__release_locks_and_end_thread.set()
721 lock_holder_thread.join()
722 start_time = time.monotonic()
723 while True:
724 waited_pid, status = os.waitpid(pid, os.WNOHANG)
725 if waited_pid == pid:
726 break # child process exited.
727 if time.monotonic() - start_time > 7:
728 break # so long? implies child deadlock.
729 time.sleep(0.05)
730 if waited_pid != pid:
731 os.kill(pid, signal.SIGKILL)
732 waited_pid, status = os.waitpid(pid, 0)
733 self.fail("child process deadlocked.")
734 self.assertEqual(status, 0, msg="child process error")
735
Vinay Sajipa5798de2012-04-24 23:33:33 +0100736
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100737class BadStream(object):
738 def write(self, data):
739 raise RuntimeError('deliberate mistake')
740
741class TestStreamHandler(logging.StreamHandler):
742 def handleError(self, record):
743 self.error_record = record
744
745class StreamHandlerTest(BaseTest):
746 def test_error_handling(self):
747 h = TestStreamHandler(BadStream())
748 r = logging.makeLogRecord({})
749 old_raise = logging.raiseExceptions
Vinay Sajip1feedb42014-05-31 08:19:12 +0100750
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100751 try:
752 h.handle(r)
753 self.assertIs(h.error_record, r)
Vinay Sajip1feedb42014-05-31 08:19:12 +0100754
Vinay Sajip985ef872011-04-26 19:34:04 +0100755 h = logging.StreamHandler(BadStream())
Vinay Sajip1feedb42014-05-31 08:19:12 +0100756 with support.captured_stderr() as stderr:
757 h.handle(r)
758 msg = '\nRuntimeError: deliberate mistake\n'
759 self.assertIn(msg, stderr.getvalue())
760
Vinay Sajip985ef872011-04-26 19:34:04 +0100761 logging.raiseExceptions = False
Vinay Sajip1feedb42014-05-31 08:19:12 +0100762 with support.captured_stderr() as stderr:
763 h.handle(r)
764 self.assertEqual('', stderr.getvalue())
Vinay Sajip26fe4b72011-04-26 18:43:05 +0100765 finally:
766 logging.raiseExceptions = old_raise
767
Vinay Sajip2543f502017-07-30 10:41:45 +0100768 def test_stream_setting(self):
769 """
770 Test setting the handler's stream
771 """
772 h = logging.StreamHandler()
773 stream = io.StringIO()
774 old = h.setStream(stream)
775 self.assertIs(old, sys.stderr)
776 actual = h.setStream(old)
777 self.assertIs(actual, stream)
778 # test that setting to existing value returns None
779 actual = h.setStream(old)
780 self.assertIsNone(actual)
781
Vinay Sajip7367d082011-05-02 13:17:27 +0100782# -- The following section could be moved into a server_helper.py module
783# -- if it proves to be of wider utility than just test_logging
Vinay Sajipa463d252011-04-30 21:52:48 +0100784
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200785class TestSMTPServer(smtpd.SMTPServer):
786 """
787 This class implements a test SMTP server.
Vinay Sajipa463d252011-04-30 21:52:48 +0100788
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200789 :param addr: A (host, port) tuple which the server listens on.
790 You can specify a port value of zero: the server's
791 *port* attribute will hold the actual port number
792 used, which can be used in client connections.
793 :param handler: A callable which will be called to process
794 incoming messages. The handler will be passed
795 the client address tuple, who the message is from,
796 a list of recipients and the message data.
797 :param poll_interval: The interval, in seconds, used in the underlying
798 :func:`select` or :func:`poll` call by
799 :func:`asyncore.loop`.
800 :param sockmap: A dictionary which will be used to hold
801 :class:`asyncore.dispatcher` instances used by
802 :func:`asyncore.loop`. This avoids changing the
803 :mod:`asyncore` module's global state.
804 """
805
806 def __init__(self, addr, handler, poll_interval, sockmap):
807 smtpd.SMTPServer.__init__(self, addr, None, map=sockmap,
808 decode_data=True)
809 self.port = self.socket.getsockname()[1]
810 self._handler = handler
811 self._thread = None
812 self.poll_interval = poll_interval
813
814 def process_message(self, peer, mailfrom, rcpttos, data):
815 """
816 Delegates to the handler passed in to the server's constructor.
817
818 Typically, this will be a test case method.
819 :param peer: The client (host, port) tuple.
820 :param mailfrom: The address of the sender.
821 :param rcpttos: The addresses of the recipients.
822 :param data: The message.
823 """
824 self._handler(peer, mailfrom, rcpttos, data)
825
826 def start(self):
827 """
828 Start the server running on a separate daemon thread.
829 """
830 self._thread = t = threading.Thread(target=self.serve_forever,
831 args=(self.poll_interval,))
832 t.setDaemon(True)
833 t.start()
834
835 def serve_forever(self, poll_interval):
836 """
837 Run the :mod:`asyncore` loop until normal termination
838 conditions arise.
Vinay Sajip314b92b2011-05-02 14:31:16 +0100839 :param poll_interval: The interval, in seconds, used in the underlying
840 :func:`select` or :func:`poll` call by
841 :func:`asyncore.loop`.
842 """
Victor Stinner13ff2452018-01-22 18:32:50 +0100843 asyncore.loop(poll_interval, map=self._map)
Vinay Sajipce7c9782011-05-17 07:15:53 +0100844
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200845 def stop(self, timeout=None):
846 """
847 Stop the thread by closing the server instance.
848 Wait for the server thread to terminate.
Vinay Sajipa463d252011-04-30 21:52:48 +0100849
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200850 :param timeout: How long to wait for the server thread
851 to terminate.
852 """
853 self.close()
Victor Stinnerb9b69002017-09-14 14:40:56 -0700854 support.join_thread(self._thread, timeout)
855 self._thread = None
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200856 asyncore.close_all(map=self._map, ignore_all=True)
Vinay Sajipa463d252011-04-30 21:52:48 +0100857
Vinay Sajip7367d082011-05-02 13:17:27 +0100858
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200859class ControlMixin(object):
860 """
861 This mixin is used to start a server on a separate thread, and
862 shut it down programmatically. Request handling is simplified - instead
863 of needing to derive a suitable RequestHandler subclass, you just
864 provide a callable which will be passed each received request to be
865 processed.
Vinay Sajip7367d082011-05-02 13:17:27 +0100866
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200867 :param handler: A handler callable which will be called with a
868 single parameter - the request - in order to
869 process the request. This handler is called on the
870 server thread, effectively meaning that requests are
871 processed serially. While not quite Web scale ;-),
872 this should be fine for testing applications.
873 :param poll_interval: The polling interval in seconds.
874 """
875 def __init__(self, handler, poll_interval):
876 self._thread = None
877 self.poll_interval = poll_interval
878 self._handler = handler
879 self.ready = threading.Event()
Vinay Sajip7367d082011-05-02 13:17:27 +0100880
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200881 def start(self):
882 """
883 Create a daemon thread to run the server, and start it.
884 """
885 self._thread = t = threading.Thread(target=self.serve_forever,
886 args=(self.poll_interval,))
887 t.setDaemon(True)
888 t.start()
Vinay Sajip7367d082011-05-02 13:17:27 +0100889
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200890 def serve_forever(self, poll_interval):
891 """
892 Run the server. Set the ready flag before entering the
893 service loop.
894 """
895 self.ready.set()
896 super(ControlMixin, self).serve_forever(poll_interval)
897
898 def stop(self, timeout=None):
899 """
900 Tell the server thread to stop, and wait for it to do so.
901
902 :param timeout: How long to wait for the server thread
903 to terminate.
904 """
905 self.shutdown()
906 if self._thread is not None:
Victor Stinnerb9b69002017-09-14 14:40:56 -0700907 support.join_thread(self._thread, timeout)
Vinay Sajip7367d082011-05-02 13:17:27 +0100908 self._thread = None
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200909 self.server_close()
910 self.ready.clear()
Vinay Sajip7367d082011-05-02 13:17:27 +0100911
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200912class TestHTTPServer(ControlMixin, HTTPServer):
913 """
914 An HTTP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100915
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200916 :param addr: A tuple with the IP address and port to listen on.
917 :param handler: A handler callable which will be called with a
918 single parameter - the request - in order to
919 process the request.
920 :param poll_interval: The polling interval in seconds.
921 :param log: Pass ``True`` to enable log messages.
922 """
923 def __init__(self, addr, handler, poll_interval=0.5,
924 log=False, sslctx=None):
925 class DelegatingHTTPRequestHandler(BaseHTTPRequestHandler):
926 def __getattr__(self, name, default=None):
927 if name.startswith('do_'):
928 return self.process_request
929 raise AttributeError(name)
Vinay Sajip7367d082011-05-02 13:17:27 +0100930
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200931 def process_request(self):
932 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +0100933
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200934 def log_message(self, format, *args):
935 if log:
936 super(DelegatingHTTPRequestHandler,
937 self).log_message(format, *args)
938 HTTPServer.__init__(self, addr, DelegatingHTTPRequestHandler)
939 ControlMixin.__init__(self, handler, poll_interval)
940 self.sslctx = sslctx
Vinay Sajip7367d082011-05-02 13:17:27 +0100941
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200942 def get_request(self):
943 try:
944 sock, addr = self.socket.accept()
945 if self.sslctx:
946 sock = self.sslctx.wrap_socket(sock, server_side=True)
947 except OSError as e:
948 # socket errors are silenced by the caller, print them here
949 sys.stderr.write("Got an error:\n%s\n" % e)
950 raise
951 return sock, addr
Vinay Sajip7367d082011-05-02 13:17:27 +0100952
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200953class TestTCPServer(ControlMixin, ThreadingTCPServer):
954 """
955 A TCP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100956
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200957 :param addr: A tuple with the IP address and port to listen on.
958 :param handler: A handler callable which will be called with a single
959 parameter - the request - in order to process the request.
960 :param poll_interval: The polling interval in seconds.
961 :bind_and_activate: If True (the default), binds the server and starts it
962 listening. If False, you need to call
963 :meth:`server_bind` and :meth:`server_activate` at
964 some later time before calling :meth:`start`, so that
965 the server will set up the socket and listen on it.
966 """
Vinay Sajip7367d082011-05-02 13:17:27 +0100967
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200968 allow_reuse_address = True
Vinay Sajip7367d082011-05-02 13:17:27 +0100969
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200970 def __init__(self, addr, handler, poll_interval=0.5,
971 bind_and_activate=True):
972 class DelegatingTCPRequestHandler(StreamRequestHandler):
Vinay Sajip7367d082011-05-02 13:17:27 +0100973
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200974 def handle(self):
975 self.server._handler(self)
976 ThreadingTCPServer.__init__(self, addr, DelegatingTCPRequestHandler,
977 bind_and_activate)
978 ControlMixin.__init__(self, handler, poll_interval)
Vinay Sajip32565b62011-05-21 00:34:51 +0100979
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200980 def server_bind(self):
981 super(TestTCPServer, self).server_bind()
982 self.port = self.socket.getsockname()[1]
Vinay Sajip7367d082011-05-02 13:17:27 +0100983
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200984class TestUDPServer(ControlMixin, ThreadingUDPServer):
985 """
986 A UDP server which is controllable using :class:`ControlMixin`.
Vinay Sajip7367d082011-05-02 13:17:27 +0100987
Antoine Pitroua6a4dc82017-09-07 18:56:24 +0200988 :param addr: A tuple with the IP address and port to listen on.
989 :param handler: A handler callable which will be called with a
990 single parameter - the request - in order to
991 process the request.
992 :param poll_interval: The polling interval for shutdown requests,
993 in seconds.
994 :bind_and_activate: If True (the default), binds the server and
995 starts it listening. If False, you need to
996 call :meth:`server_bind` and
997 :meth:`server_activate` at some later time
998 before calling :meth:`start`, so that the server will
999 set up the socket and listen on it.
1000 """
1001 def __init__(self, addr, handler, poll_interval=0.5,
1002 bind_and_activate=True):
1003 class DelegatingUDPRequestHandler(DatagramRequestHandler):
Vinay Sajip7367d082011-05-02 13:17:27 +01001004
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001005 def handle(self):
1006 self.server._handler(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001007
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001008 def finish(self):
1009 data = self.wfile.getvalue()
1010 if data:
1011 try:
1012 super(DelegatingUDPRequestHandler, self).finish()
1013 except OSError:
1014 if not self.server._closed:
1015 raise
Vinay Sajipce7c9782011-05-17 07:15:53 +01001016
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001017 ThreadingUDPServer.__init__(self, addr,
1018 DelegatingUDPRequestHandler,
1019 bind_and_activate)
1020 ControlMixin.__init__(self, handler, poll_interval)
1021 self._closed = False
Vinay Sajipce7c9782011-05-17 07:15:53 +01001022
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001023 def server_bind(self):
1024 super(TestUDPServer, self).server_bind()
1025 self.port = self.socket.getsockname()[1]
Vinay Sajipce7c9782011-05-17 07:15:53 +01001026
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001027 def server_close(self):
1028 super(TestUDPServer, self).server_close()
1029 self._closed = True
Vinay Sajipce7c9782011-05-17 07:15:53 +01001030
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001031if hasattr(socket, "AF_UNIX"):
1032 class TestUnixStreamServer(TestTCPServer):
1033 address_family = socket.AF_UNIX
Vinay Sajipce7c9782011-05-17 07:15:53 +01001034
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001035 class TestUnixDatagramServer(TestUDPServer):
1036 address_family = socket.AF_UNIX
Vinay Sajip5421f352013-09-27 18:18:28 +01001037
Vinay Sajip7367d082011-05-02 13:17:27 +01001038# - end of server_helper section
Vinay Sajipa463d252011-04-30 21:52:48 +01001039
1040class SMTPHandlerTest(BaseTest):
Miss Islington (bot)0a1db322018-07-11 06:56:45 -07001041 # bpo-14314, bpo-19665, bpo-34092: don't wait forever, timeout of 1 minute
1042 TIMEOUT = 60.0
Victor Stinner4bcfa3a2017-04-25 00:41:36 +02001043
Vinay Sajipa463d252011-04-30 21:52:48 +01001044 def test_basic(self):
Vinay Sajip7367d082011-05-02 13:17:27 +01001045 sockmap = {}
Ned Deily1e012e62015-01-17 16:57:19 -08001046 server = TestSMTPServer((support.HOST, 0), self.process_message, 0.001,
Vinay Sajip7367d082011-05-02 13:17:27 +01001047 sockmap)
1048 server.start()
Ned Deily1e012e62015-01-17 16:57:19 -08001049 addr = (support.HOST, server.port)
Vinay Sajip827f5d32013-12-03 11:28:55 +00001050 h = logging.handlers.SMTPHandler(addr, 'me', 'you', 'Log',
1051 timeout=self.TIMEOUT)
Vinay Sajipa463d252011-04-30 21:52:48 +01001052 self.assertEqual(h.toaddrs, ['you'])
1053 self.messages = []
Vinay Sajip277640a2015-10-17 16:13:10 +01001054 r = logging.makeLogRecord({'msg': 'Hello \u2713'})
Vinay Sajip7367d082011-05-02 13:17:27 +01001055 self.handled = threading.Event()
Vinay Sajipa463d252011-04-30 21:52:48 +01001056 h.handle(r)
Miss Islington (bot)0a1db322018-07-11 06:56:45 -07001057 self.handled.wait(self.TIMEOUT)
Vinay Sajipa463d252011-04-30 21:52:48 +01001058 server.stop()
Vinay Sajip17160fd2012-03-15 12:02:08 +00001059 self.assertTrue(self.handled.is_set())
Vinay Sajipa463d252011-04-30 21:52:48 +01001060 self.assertEqual(len(self.messages), 1)
1061 peer, mailfrom, rcpttos, data = self.messages[0]
1062 self.assertEqual(mailfrom, 'me')
1063 self.assertEqual(rcpttos, ['you'])
Vinay Sajip5056c8c2011-06-05 09:31:34 +01001064 self.assertIn('\nSubject: Log\n', data)
Vinay Sajip277640a2015-10-17 16:13:10 +01001065 self.assertTrue(data.endswith('\n\nHello \u2713'))
Vinay Sajipa463d252011-04-30 21:52:48 +01001066 h.close()
1067
1068 def process_message(self, *args):
1069 self.messages.append(args)
Vinay Sajip7367d082011-05-02 13:17:27 +01001070 self.handled.set()
Vinay Sajipa463d252011-04-30 21:52:48 +01001071
Christian Heimes180510d2008-03-03 19:15:45 +00001072class MemoryHandlerTest(BaseTest):
1073
1074 """Tests for the MemoryHandler."""
1075
1076 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001077 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001078
1079 def setUp(self):
1080 BaseTest.setUp(self)
1081 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
Vinay Sajipdb8f4632016-09-08 01:37:03 +01001082 self.root_hdlr)
Christian Heimes180510d2008-03-03 19:15:45 +00001083 self.mem_logger = logging.getLogger('mem')
1084 self.mem_logger.propagate = 0
1085 self.mem_logger.addHandler(self.mem_hdlr)
1086
1087 def tearDown(self):
1088 self.mem_hdlr.close()
Benjamin Peterson2a691a82008-03-31 01:51:45 +00001089 BaseTest.tearDown(self)
Christian Heimes180510d2008-03-03 19:15:45 +00001090
1091 def test_flush(self):
1092 # The memory handler flushes to its target handler based on specific
1093 # criteria (message count and message level).
1094 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001095 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001096 self.mem_logger.info(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001097 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001098 # This will flush because the level is >= logging.WARNING
Vinay Sajipb9e46e92011-10-26 13:17:20 +01001099 self.mem_logger.warning(self.next_message())
Christian Heimes180510d2008-03-03 19:15:45 +00001100 lines = [
1101 ('DEBUG', '1'),
1102 ('INFO', '2'),
1103 ('WARNING', '3'),
1104 ]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001105 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001106 for n in (4, 14):
1107 for i in range(9):
1108 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001109 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001110 # This will flush because it's the 10th message since the last
1111 # flush.
1112 self.mem_logger.debug(self.next_message())
1113 lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)]
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001114 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001115
1116 self.mem_logger.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001117 self.assert_log_lines(lines)
Christian Heimes180510d2008-03-03 19:15:45 +00001118
Vinay Sajipdb8f4632016-09-08 01:37:03 +01001119 def test_flush_on_close(self):
1120 """
1121 Test that the flush-on-close configuration works as expected.
1122 """
1123 self.mem_logger.debug(self.next_message())
1124 self.assert_log_lines([])
1125 self.mem_logger.info(self.next_message())
1126 self.assert_log_lines([])
1127 self.mem_logger.removeHandler(self.mem_hdlr)
1128 # Default behaviour is to flush on close. Check that it happens.
1129 self.mem_hdlr.close()
1130 lines = [
1131 ('DEBUG', '1'),
1132 ('INFO', '2'),
1133 ]
1134 self.assert_log_lines(lines)
1135 # Now configure for flushing not to be done on close.
1136 self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING,
1137 self.root_hdlr,
1138 False)
1139 self.mem_logger.addHandler(self.mem_hdlr)
1140 self.mem_logger.debug(self.next_message())
1141 self.assert_log_lines(lines) # no change
1142 self.mem_logger.info(self.next_message())
1143 self.assert_log_lines(lines) # no change
1144 self.mem_logger.removeHandler(self.mem_hdlr)
1145 self.mem_hdlr.close()
1146 # assert that no new lines have been added
1147 self.assert_log_lines(lines) # no change
1148
Christian Heimes180510d2008-03-03 19:15:45 +00001149
1150class ExceptionFormatter(logging.Formatter):
1151 """A special exception formatter."""
1152 def formatException(self, ei):
1153 return "Got a [%s]" % ei[0].__name__
1154
1155
1156class ConfigFileTest(BaseTest):
1157
1158 """Reading logging config from a .ini-style config file."""
1159
Miss Islington (bot)6f49afc2018-07-02 02:35:09 -07001160 check_no_resource_warning = support.check_no_resource_warning
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03001161 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Christian Heimes180510d2008-03-03 19:15:45 +00001162
1163 # config0 is a standard configuration.
1164 config0 = """
1165 [loggers]
1166 keys=root
1167
1168 [handlers]
1169 keys=hand1
1170
1171 [formatters]
1172 keys=form1
1173
1174 [logger_root]
1175 level=WARNING
1176 handlers=hand1
1177
1178 [handler_hand1]
1179 class=StreamHandler
1180 level=NOTSET
1181 formatter=form1
1182 args=(sys.stdout,)
1183
1184 [formatter_form1]
1185 format=%(levelname)s ++ %(message)s
1186 datefmt=
1187 """
1188
1189 # config1 adds a little to the standard configuration.
1190 config1 = """
1191 [loggers]
1192 keys=root,parser
1193
1194 [handlers]
1195 keys=hand1
1196
1197 [formatters]
1198 keys=form1
1199
1200 [logger_root]
1201 level=WARNING
1202 handlers=
1203
1204 [logger_parser]
1205 level=DEBUG
1206 handlers=hand1
1207 propagate=1
1208 qualname=compiler.parser
1209
1210 [handler_hand1]
1211 class=StreamHandler
1212 level=NOTSET
1213 formatter=form1
1214 args=(sys.stdout,)
1215
1216 [formatter_form1]
1217 format=%(levelname)s ++ %(message)s
1218 datefmt=
1219 """
1220
Vinay Sajip3f84b072011-03-07 17:49:33 +00001221 # config1a moves the handler to the root.
1222 config1a = """
1223 [loggers]
1224 keys=root,parser
1225
1226 [handlers]
1227 keys=hand1
1228
1229 [formatters]
1230 keys=form1
1231
1232 [logger_root]
1233 level=WARNING
1234 handlers=hand1
1235
1236 [logger_parser]
1237 level=DEBUG
1238 handlers=
1239 propagate=1
1240 qualname=compiler.parser
1241
1242 [handler_hand1]
1243 class=StreamHandler
1244 level=NOTSET
1245 formatter=form1
1246 args=(sys.stdout,)
1247
1248 [formatter_form1]
1249 format=%(levelname)s ++ %(message)s
1250 datefmt=
1251 """
1252
Christian Heimes180510d2008-03-03 19:15:45 +00001253 # config2 has a subtle configuration error that should be reported
1254 config2 = config1.replace("sys.stdout", "sys.stbout")
1255
1256 # config3 has a less subtle configuration error
1257 config3 = config1.replace("formatter=form1", "formatter=misspelled_name")
1258
1259 # config4 specifies a custom formatter class to be loaded
1260 config4 = """
1261 [loggers]
1262 keys=root
1263
1264 [handlers]
1265 keys=hand1
1266
1267 [formatters]
1268 keys=form1
1269
1270 [logger_root]
1271 level=NOTSET
1272 handlers=hand1
1273
1274 [handler_hand1]
1275 class=StreamHandler
1276 level=NOTSET
1277 formatter=form1
1278 args=(sys.stdout,)
1279
1280 [formatter_form1]
1281 class=""" + __name__ + """.ExceptionFormatter
1282 format=%(levelname)s:%(name)s:%(message)s
1283 datefmt=
1284 """
1285
Georg Brandl3dbca812008-07-23 16:10:53 +00001286 # config5 specifies a custom handler class to be loaded
1287 config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler')
1288
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001289 # config6 uses ', ' delimiters in the handlers and formatters sections
1290 config6 = """
1291 [loggers]
1292 keys=root,parser
1293
1294 [handlers]
1295 keys=hand1, hand2
1296
1297 [formatters]
1298 keys=form1, form2
1299
1300 [logger_root]
1301 level=WARNING
1302 handlers=
1303
1304 [logger_parser]
1305 level=DEBUG
1306 handlers=hand1
1307 propagate=1
1308 qualname=compiler.parser
1309
1310 [handler_hand1]
1311 class=StreamHandler
1312 level=NOTSET
1313 formatter=form1
1314 args=(sys.stdout,)
1315
1316 [handler_hand2]
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001317 class=StreamHandler
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001318 level=NOTSET
1319 formatter=form1
Benjamin Peterson9aa42992008-09-10 21:57:34 +00001320 args=(sys.stderr,)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001321
1322 [formatter_form1]
1323 format=%(levelname)s ++ %(message)s
1324 datefmt=
1325
1326 [formatter_form2]
1327 format=%(message)s
1328 datefmt=
1329 """
1330
Preston Landers6ea56d22017-08-02 15:44:28 -05001331 # config7 adds a compiler logger, and uses kwargs instead of args.
Vinay Sajip3f84b072011-03-07 17:49:33 +00001332 config7 = """
1333 [loggers]
1334 keys=root,parser,compiler
1335
1336 [handlers]
1337 keys=hand1
1338
1339 [formatters]
1340 keys=form1
1341
1342 [logger_root]
1343 level=WARNING
1344 handlers=hand1
1345
1346 [logger_compiler]
1347 level=DEBUG
1348 handlers=
1349 propagate=1
1350 qualname=compiler
1351
1352 [logger_parser]
1353 level=DEBUG
1354 handlers=
1355 propagate=1
1356 qualname=compiler.parser
1357
1358 [handler_hand1]
1359 class=StreamHandler
1360 level=NOTSET
1361 formatter=form1
Preston Landers6ea56d22017-08-02 15:44:28 -05001362 kwargs={'stream': sys.stdout,}
Vinay Sajip3f84b072011-03-07 17:49:33 +00001363
1364 [formatter_form1]
1365 format=%(levelname)s ++ %(message)s
1366 datefmt=
1367 """
1368
Miss Islington (bot)6f49afc2018-07-02 02:35:09 -07001369 # config 8, check for resource warning
1370 config8 = r"""
1371 [loggers]
1372 keys=root
1373
1374 [handlers]
1375 keys=file
1376
1377 [formatters]
1378 keys=
1379
1380 [logger_root]
1381 level=DEBUG
1382 handlers=file
1383
1384 [handler_file]
1385 class=FileHandler
1386 level=DEBUG
1387 args=("{tempfile}",)
1388 """
1389
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001390 disable_test = """
1391 [loggers]
1392 keys=root
1393
1394 [handlers]
1395 keys=screen
1396
1397 [formatters]
1398 keys=
1399
1400 [logger_root]
1401 level=DEBUG
1402 handlers=screen
1403
1404 [handler_screen]
1405 level=DEBUG
1406 class=StreamHandler
1407 args=(sys.stdout,)
1408 formatter=
1409 """
1410
1411 def apply_config(self, conf, **kwargs):
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00001412 file = io.StringIO(textwrap.dedent(conf))
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001413 logging.config.fileConfig(file, **kwargs)
Christian Heimes180510d2008-03-03 19:15:45 +00001414
1415 def test_config0_ok(self):
1416 # A simple config file which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001417 with support.captured_stdout() as output:
Christian Heimes180510d2008-03-03 19:15:45 +00001418 self.apply_config(self.config0)
1419 logger = logging.getLogger()
1420 # Won't output anything
1421 logger.info(self.next_message())
1422 # Outputs a message
1423 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001424 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001425 ('ERROR', '2'),
1426 ], stream=output)
1427 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001428 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001429
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001430 def test_config0_using_cp_ok(self):
1431 # A simple config file which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001432 with support.captured_stdout() as output:
Vinay Sajipcf9e2f22012-10-09 09:06:03 +01001433 file = io.StringIO(textwrap.dedent(self.config0))
1434 cp = configparser.ConfigParser()
1435 cp.read_file(file)
1436 logging.config.fileConfig(cp)
1437 logger = logging.getLogger()
1438 # Won't output anything
1439 logger.info(self.next_message())
1440 # Outputs a message
1441 logger.error(self.next_message())
1442 self.assert_log_lines([
1443 ('ERROR', '2'),
1444 ], stream=output)
1445 # Original logger output is empty.
1446 self.assert_log_lines([])
1447
Georg Brandl3dbca812008-07-23 16:10:53 +00001448 def test_config1_ok(self, config=config1):
Christian Heimes180510d2008-03-03 19:15:45 +00001449 # A config file defining a sub-parser as well.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001450 with support.captured_stdout() as output:
Georg Brandl3dbca812008-07-23 16:10:53 +00001451 self.apply_config(config)
Christian Heimes180510d2008-03-03 19:15:45 +00001452 logger = logging.getLogger("compiler.parser")
1453 # Both will output a message
1454 logger.info(self.next_message())
1455 logger.error(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001456 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00001457 ('INFO', '1'),
1458 ('ERROR', '2'),
1459 ], stream=output)
1460 # Original logger output is empty.
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001461 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001462
1463 def test_config2_failure(self):
1464 # A simple config file which overrides the default settings.
1465 self.assertRaises(Exception, self.apply_config, self.config2)
1466
1467 def test_config3_failure(self):
1468 # A simple config file which overrides the default settings.
1469 self.assertRaises(Exception, self.apply_config, self.config3)
1470
1471 def test_config4_ok(self):
1472 # A config file specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01001473 with support.captured_stdout() as output:
Christian Heimes180510d2008-03-03 19:15:45 +00001474 self.apply_config(self.config4)
1475 logger = logging.getLogger()
1476 try:
1477 raise RuntimeError()
1478 except RuntimeError:
1479 logging.exception("just testing")
1480 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00001481 self.assertEqual(output.getvalue(),
Christian Heimes180510d2008-03-03 19:15:45 +00001482 "ERROR:root:just testing\nGot a [RuntimeError]\n")
1483 # Original logger output is empty
Benjamin Peterson77108eb2009-07-01 00:43:10 +00001484 self.assert_log_lines([])
Christian Heimes180510d2008-03-03 19:15:45 +00001485
Georg Brandl3dbca812008-07-23 16:10:53 +00001486 def test_config5_ok(self):
1487 self.test_config1_ok(config=self.config5)
Christian Heimes180510d2008-03-03 19:15:45 +00001488
Benjamin Petersonae5360b2008-09-08 23:05:23 +00001489 def test_config6_ok(self):
1490 self.test_config1_ok(config=self.config6)
1491
Vinay Sajip3f84b072011-03-07 17:49:33 +00001492 def test_config7_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01001493 with support.captured_stdout() as output:
Vinay Sajip3f84b072011-03-07 17:49:33 +00001494 self.apply_config(self.config1a)
1495 logger = logging.getLogger("compiler.parser")
1496 # See issue #11424. compiler-hyphenated sorts
1497 # between compiler and compiler.xyz and this
1498 # was preventing compiler.xyz from being included
1499 # in the child loggers of compiler because of an
1500 # overzealous loop termination condition.
1501 hyphenated = logging.getLogger('compiler-hyphenated')
1502 # All will output a message
1503 logger.info(self.next_message())
1504 logger.error(self.next_message())
1505 hyphenated.critical(self.next_message())
1506 self.assert_log_lines([
1507 ('INFO', '1'),
1508 ('ERROR', '2'),
1509 ('CRITICAL', '3'),
1510 ], stream=output)
1511 # Original logger output is empty.
1512 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01001513 with support.captured_stdout() as output:
Vinay Sajip3f84b072011-03-07 17:49:33 +00001514 self.apply_config(self.config7)
1515 logger = logging.getLogger("compiler.parser")
1516 self.assertFalse(logger.disabled)
1517 # Both will output a message
1518 logger.info(self.next_message())
1519 logger.error(self.next_message())
1520 logger = logging.getLogger("compiler.lexer")
1521 # Both will output a message
1522 logger.info(self.next_message())
1523 logger.error(self.next_message())
1524 # Will not appear
1525 hyphenated.critical(self.next_message())
1526 self.assert_log_lines([
1527 ('INFO', '4'),
1528 ('ERROR', '5'),
1529 ('INFO', '6'),
1530 ('ERROR', '7'),
1531 ], stream=output)
1532 # Original logger output is empty.
1533 self.assert_log_lines([])
1534
Miss Islington (bot)6f49afc2018-07-02 02:35:09 -07001535 def test_config8_ok(self):
1536
1537 def cleanup(h1, fn):
1538 h1.close()
1539 os.remove(fn)
1540
1541 with self.check_no_resource_warning():
1542 fd, fn = tempfile.mkstemp(".log", "test_logging-X-")
1543 os.close(fd)
1544
1545 # Replace single backslash with double backslash in windows
1546 # to avoid unicode error during string formatting
1547 if os.name == "nt":
1548 fn = fn.replace("\\", "\\\\")
1549
1550 config8 = self.config8.format(tempfile=fn)
1551
1552 self.apply_config(config8)
1553 self.apply_config(config8)
1554
1555 handler = logging.root.handlers[0]
1556 self.addCleanup(cleanup, handler, fn)
1557
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001558 def test_logger_disabling(self):
1559 self.apply_config(self.disable_test)
Antoine Pitrou04d4d6a2013-09-14 21:16:39 +02001560 logger = logging.getLogger('some_pristine_logger')
Vinay Sajip68b4cc82013-03-23 11:18:45 +00001561 self.assertFalse(logger.disabled)
1562 self.apply_config(self.disable_test)
1563 self.assertTrue(logger.disabled)
1564 self.apply_config(self.disable_test, disable_existing_loggers=False)
1565 self.assertFalse(logger.disabled)
1566
Miss Islington (bot)f44203d2018-06-08 07:01:56 -07001567 def test_defaults_do_no_interpolation(self):
1568 """bpo-33802 defaults should not get interpolated"""
1569 ini = textwrap.dedent("""
1570 [formatters]
1571 keys=default
1572
1573 [formatter_default]
1574
1575 [handlers]
1576 keys=console
1577
1578 [handler_console]
1579 class=logging.StreamHandler
1580 args=tuple()
1581
1582 [loggers]
1583 keys=root
1584
1585 [logger_root]
1586 formatter=default
1587 handlers=console
1588 """).strip()
1589 fd, fn = tempfile.mkstemp(prefix='test_logging_', suffix='.ini')
1590 try:
1591 os.write(fd, ini.encode('ascii'))
1592 os.close(fd)
1593 logging.config.fileConfig(
1594 fn,
1595 defaults=dict(
1596 version=1,
1597 disable_existing_loggers=False,
1598 formatters={
1599 "generic": {
1600 "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s",
1601 "datefmt": "[%Y-%m-%d %H:%M:%S %z]",
1602 "class": "logging.Formatter"
1603 },
1604 },
1605 )
1606 )
1607 finally:
1608 os.unlink(fn)
1609
Guido van Rossum2a1d5162003-01-21 21:05:22 +00001610
Christian Heimes180510d2008-03-03 19:15:45 +00001611class SocketHandlerTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001612
Christian Heimes180510d2008-03-03 19:15:45 +00001613 """Test for SocketHandler objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001614
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001615 server_class = TestTCPServer
1616 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001617
Christian Heimes180510d2008-03-03 19:15:45 +00001618 def setUp(self):
1619 """Set up a TCP server to receive log messages, and a SocketHandler
1620 pointing to that server's address and port."""
1621 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001622 # Issue #29177: deal with errors that happen during setup
1623 self.server = self.sock_hdlr = self.server_exception = None
1624 try:
1625 self.server = server = self.server_class(self.address,
1626 self.handle_socket, 0.01)
1627 server.start()
1628 # Uncomment next line to test error recovery in setUp()
1629 # raise OSError('dummy error raised')
1630 except OSError as e:
1631 self.server_exception = e
1632 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001633 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001634 hcls = logging.handlers.SocketHandler
1635 if isinstance(server.server_address, tuple):
1636 self.sock_hdlr = hcls('localhost', server.port)
1637 else:
1638 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001639 self.log_output = ''
Christian Heimes180510d2008-03-03 19:15:45 +00001640 self.root_logger.removeHandler(self.root_logger.handlers[0])
1641 self.root_logger.addHandler(self.sock_hdlr)
Vinay Sajip7367d082011-05-02 13:17:27 +01001642 self.handled = threading.Semaphore(0)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001643
Christian Heimes180510d2008-03-03 19:15:45 +00001644 def tearDown(self):
1645 """Shutdown the TCP server."""
1646 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001647 if self.sock_hdlr:
1648 self.root_logger.removeHandler(self.sock_hdlr)
1649 self.sock_hdlr.close()
Victor Stinnerb8f41632017-09-13 01:47:22 -07001650 if self.server:
1651 self.server.stop(2.0)
Christian Heimes180510d2008-03-03 19:15:45 +00001652 finally:
1653 BaseTest.tearDown(self)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001654
Vinay Sajip7367d082011-05-02 13:17:27 +01001655 def handle_socket(self, request):
1656 conn = request.connection
1657 while True:
1658 chunk = conn.recv(4)
1659 if len(chunk) < 4:
1660 break
1661 slen = struct.unpack(">L", chunk)[0]
1662 chunk = conn.recv(slen)
1663 while len(chunk) < slen:
1664 chunk = chunk + conn.recv(slen - len(chunk))
1665 obj = pickle.loads(chunk)
1666 record = logging.makeLogRecord(obj)
1667 self.log_output += record.msg + '\n'
1668 self.handled.release()
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001669
Christian Heimes180510d2008-03-03 19:15:45 +00001670 def test_output(self):
1671 # The log message sent to the SocketHandler is properly received.
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001672 if self.server_exception:
1673 self.skipTest(self.server_exception)
Christian Heimes180510d2008-03-03 19:15:45 +00001674 logger = logging.getLogger("tcp")
1675 logger.error("spam")
Vinay Sajip7367d082011-05-02 13:17:27 +01001676 self.handled.acquire()
Christian Heimes180510d2008-03-03 19:15:45 +00001677 logger.debug("eggs")
Vinay Sajip7367d082011-05-02 13:17:27 +01001678 self.handled.acquire()
1679 self.assertEqual(self.log_output, "spam\neggs\n")
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001680
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001681 def test_noserver(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001682 if self.server_exception:
1683 self.skipTest(self.server_exception)
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001684 # Avoid timing-related failures due to SocketHandler's own hard-wired
1685 # one-second timeout on socket.create_connection() (issue #16264).
1686 self.sock_hdlr.retryStart = 2.5
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001687 # Kill the server
Vinay Sajip7367d082011-05-02 13:17:27 +01001688 self.server.stop(2.0)
Antoine Pitrouda201fa2012-10-21 17:18:27 +02001689 # The logging call should try to connect, which should fail
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001690 try:
1691 raise RuntimeError('Deliberate mistake')
1692 except RuntimeError:
1693 self.root_logger.exception('Never sent')
1694 self.root_logger.error('Never sent, either')
1695 now = time.time()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02001696 self.assertGreater(self.sock_hdlr.retryTime, now)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01001697 time.sleep(self.sock_hdlr.retryTime - now + 0.001)
1698 self.root_logger.error('Nor this')
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001699
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001700def _get_temp_domain_socket():
1701 fd, fn = tempfile.mkstemp(prefix='test_logging_', suffix='.sock')
1702 os.close(fd)
1703 # just need a name - file can't be present, or we'll get an
1704 # 'address already in use' error.
1705 os.remove(fn)
1706 return fn
Vinay Sajip7367d082011-05-02 13:17:27 +01001707
Victor Stinnerec5a8602014-06-02 14:41:51 +02001708@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001709class UnixSocketHandlerTest(SocketHandlerTest):
1710
1711 """Test for SocketHandler with unix sockets."""
1712
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001713 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001714 server_class = TestUnixStreamServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001715
1716 def setUp(self):
1717 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001718 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001719 SocketHandlerTest.setUp(self)
1720
1721 def tearDown(self):
1722 SocketHandlerTest.tearDown(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001723 support.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001724
Vinay Sajip7367d082011-05-02 13:17:27 +01001725class DatagramHandlerTest(BaseTest):
1726
1727 """Test for DatagramHandler."""
1728
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001729 server_class = TestUDPServer
1730 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001731
Vinay Sajip7367d082011-05-02 13:17:27 +01001732 def setUp(self):
1733 """Set up a UDP server to receive log messages, and a DatagramHandler
1734 pointing to that server's address and port."""
1735 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001736 # Issue #29177: deal with errors that happen during setup
1737 self.server = self.sock_hdlr = self.server_exception = None
1738 try:
1739 self.server = server = self.server_class(self.address,
1740 self.handle_datagram, 0.01)
1741 server.start()
1742 # Uncomment next line to test error recovery in setUp()
1743 # raise OSError('dummy error raised')
1744 except OSError as e:
1745 self.server_exception = e
1746 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001747 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001748 hcls = logging.handlers.DatagramHandler
1749 if isinstance(server.server_address, tuple):
1750 self.sock_hdlr = hcls('localhost', server.port)
1751 else:
1752 self.sock_hdlr = hcls(server.server_address, None)
Vinay Sajip7367d082011-05-02 13:17:27 +01001753 self.log_output = ''
1754 self.root_logger.removeHandler(self.root_logger.handlers[0])
1755 self.root_logger.addHandler(self.sock_hdlr)
1756 self.handled = threading.Event()
1757
1758 def tearDown(self):
1759 """Shutdown the UDP server."""
1760 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001761 if self.server:
1762 self.server.stop(2.0)
1763 if self.sock_hdlr:
1764 self.root_logger.removeHandler(self.sock_hdlr)
1765 self.sock_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001766 finally:
1767 BaseTest.tearDown(self)
1768
1769 def handle_datagram(self, request):
1770 slen = struct.pack('>L', 0) # length of prefix
1771 packet = request.packet[len(slen):]
1772 obj = pickle.loads(packet)
1773 record = logging.makeLogRecord(obj)
1774 self.log_output += record.msg + '\n'
1775 self.handled.set()
1776
1777 def test_output(self):
1778 # The log message sent to the DatagramHandler is properly received.
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001779 if self.server_exception:
1780 self.skipTest(self.server_exception)
Vinay Sajip7367d082011-05-02 13:17:27 +01001781 logger = logging.getLogger("udp")
1782 logger.error("spam")
1783 self.handled.wait()
Vinay Sajip714b8dc2011-05-02 14:43:00 +01001784 self.handled.clear()
1785 logger.error("eggs")
1786 self.handled.wait()
1787 self.assertEqual(self.log_output, "spam\neggs\n")
Vinay Sajip7367d082011-05-02 13:17:27 +01001788
Victor Stinnerec5a8602014-06-02 14:41:51 +02001789@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001790class UnixDatagramHandlerTest(DatagramHandlerTest):
1791
1792 """Test for DatagramHandler using Unix sockets."""
1793
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001794 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001795 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001796
1797 def setUp(self):
1798 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001799 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001800 DatagramHandlerTest.setUp(self)
1801
1802 def tearDown(self):
1803 DatagramHandlerTest.tearDown(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001804 support.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001805
Vinay Sajip7367d082011-05-02 13:17:27 +01001806class SysLogHandlerTest(BaseTest):
1807
1808 """Test for SysLogHandler using UDP."""
1809
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001810 server_class = TestUDPServer
1811 address = ('localhost', 0)
Vinay Sajip5421f352013-09-27 18:18:28 +01001812
Vinay Sajip7367d082011-05-02 13:17:27 +01001813 def setUp(self):
1814 """Set up a UDP server to receive log messages, and a SysLogHandler
1815 pointing to that server's address and port."""
1816 BaseTest.setUp(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001817 # Issue #29177: deal with errors that happen during setup
1818 self.server = self.sl_hdlr = self.server_exception = None
1819 try:
1820 self.server = server = self.server_class(self.address,
1821 self.handle_datagram, 0.01)
1822 server.start()
1823 # Uncomment next line to test error recovery in setUp()
1824 # raise OSError('dummy error raised')
1825 except OSError as e:
1826 self.server_exception = e
1827 return
Vinay Sajip7367d082011-05-02 13:17:27 +01001828 server.ready.wait()
Vinay Sajip5421f352013-09-27 18:18:28 +01001829 hcls = logging.handlers.SysLogHandler
1830 if isinstance(server.server_address, tuple):
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001831 self.sl_hdlr = hcls((server.server_address[0], server.port))
Vinay Sajip5421f352013-09-27 18:18:28 +01001832 else:
1833 self.sl_hdlr = hcls(server.server_address)
Vinay Sajip7367d082011-05-02 13:17:27 +01001834 self.log_output = ''
1835 self.root_logger.removeHandler(self.root_logger.handlers[0])
1836 self.root_logger.addHandler(self.sl_hdlr)
1837 self.handled = threading.Event()
1838
1839 def tearDown(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001840 """Shutdown the server."""
Vinay Sajip7367d082011-05-02 13:17:27 +01001841 try:
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001842 if self.server:
1843 self.server.stop(2.0)
1844 if self.sl_hdlr:
1845 self.root_logger.removeHandler(self.sl_hdlr)
1846 self.sl_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001847 finally:
1848 BaseTest.tearDown(self)
1849
1850 def handle_datagram(self, request):
1851 self.log_output = request.packet
1852 self.handled.set()
1853
1854 def test_output(self):
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001855 if self.server_exception:
1856 self.skipTest(self.server_exception)
Vinay Sajip7367d082011-05-02 13:17:27 +01001857 # The log message sent to the SysLogHandler is properly received.
1858 logger = logging.getLogger("slh")
1859 logger.error("sp\xe4m")
1860 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001861 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
Vinay Sajip8dd8d582011-06-09 16:55:23 +01001862 self.handled.clear()
1863 self.sl_hdlr.append_nul = False
1864 logger.error("sp\xe4m")
1865 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001866 self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m')
Vinay Sajip2353e352011-06-27 15:40:06 +01001867 self.handled.clear()
1868 self.sl_hdlr.ident = "h\xe4m-"
1869 logger.error("sp\xe4m")
1870 self.handled.wait()
Vinay Sajip7706d9a2012-04-16 16:22:38 +01001871 self.assertEqual(self.log_output, b'<11>h\xc3\xa4m-sp\xc3\xa4m')
Vinay Sajip7367d082011-05-02 13:17:27 +01001872
Victor Stinnerec5a8602014-06-02 14:41:51 +02001873@unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
Vinay Sajip5421f352013-09-27 18:18:28 +01001874class UnixSysLogHandlerTest(SysLogHandlerTest):
1875
1876 """Test for SysLogHandler with Unix sockets."""
1877
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02001878 if hasattr(socket, "AF_UNIX"):
Vinay Sajipcb2c4fe2013-09-27 19:08:24 +01001879 server_class = TestUnixDatagramServer
Vinay Sajip5421f352013-09-27 18:18:28 +01001880
1881 def setUp(self):
1882 # override the definition in the base class
Vinay Sajipf6cdffe2013-09-27 18:41:12 +01001883 self.address = _get_temp_domain_socket()
Vinay Sajip5421f352013-09-27 18:18:28 +01001884 SysLogHandlerTest.setUp(self)
1885
1886 def tearDown(self):
1887 SysLogHandlerTest.tearDown(self)
Vinay Sajip1e6499c2017-01-09 16:54:12 +00001888 support.unlink(self.address)
Vinay Sajip5421f352013-09-27 18:18:28 +01001889
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001890@unittest.skipUnless(support.IPV6_ENABLED,
1891 'IPv6 support required for this test.')
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08001892class IPv6SysLogHandlerTest(SysLogHandlerTest):
1893
1894 """Test for SysLogHandler with IPv6 host."""
1895
1896 server_class = TestUDPServer
1897 address = ('::1', 0)
1898
1899 def setUp(self):
1900 self.server_class.address_family = socket.AF_INET6
1901 super(IPv6SysLogHandlerTest, self).setUp()
1902
1903 def tearDown(self):
1904 self.server_class.address_family = socket.AF_INET
1905 super(IPv6SysLogHandlerTest, self).tearDown()
1906
Vinay Sajip7367d082011-05-02 13:17:27 +01001907class HTTPHandlerTest(BaseTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01001908 """Test for HTTPHandler."""
1909
1910 def setUp(self):
1911 """Set up an HTTP server to receive log messages, and a HTTPHandler
1912 pointing to that server's address and port."""
1913 BaseTest.setUp(self)
Vinay Sajip7367d082011-05-02 13:17:27 +01001914 self.handled = threading.Event()
1915
Vinay Sajip7367d082011-05-02 13:17:27 +01001916 def handle_request(self, request):
Vinay Sajip0372e102011-05-05 12:59:14 +01001917 self.command = request.command
Vinay Sajip7367d082011-05-02 13:17:27 +01001918 self.log_data = urlparse(request.path)
Vinay Sajip0372e102011-05-05 12:59:14 +01001919 if self.command == 'POST':
1920 try:
1921 rlen = int(request.headers['Content-Length'])
1922 self.post_data = request.rfile.read(rlen)
1923 except:
1924 self.post_data = None
Vinay Sajip7367d082011-05-02 13:17:27 +01001925 request.send_response(200)
Vinay Sajip463ac512011-05-10 09:10:08 +01001926 request.end_headers()
Vinay Sajip7367d082011-05-02 13:17:27 +01001927 self.handled.set()
1928
1929 def test_output(self):
Vinay Sajipf2231162011-05-09 22:05:50 +01001930 # The log message sent to the HTTPHandler is properly received.
Vinay Sajip7367d082011-05-02 13:17:27 +01001931 logger = logging.getLogger("http")
Vinay Sajip9ba87612011-05-21 11:32:15 +01001932 root_logger = self.root_logger
1933 root_logger.removeHandler(self.root_logger.handlers[0])
1934 for secure in (False, True):
1935 addr = ('localhost', 0)
1936 if secure:
Vinay Sajip39e35282011-05-21 16:46:41 +01001937 try:
1938 import ssl
Vinay Sajip39e35282011-05-21 16:46:41 +01001939 except ImportError:
1940 sslctx = None
Benjamin Peterson4ffb0752014-11-03 14:29:33 -05001941 else:
1942 here = os.path.dirname(__file__)
1943 localhost_cert = os.path.join(here, "keycert.pem")
Christian Heimesa170fa12017-09-15 20:27:30 +02001944 sslctx = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
Benjamin Peterson4ffb0752014-11-03 14:29:33 -05001945 sslctx.load_cert_chain(localhost_cert)
Benjamin Peterson43052a12014-11-23 20:36:44 -06001946
1947 context = ssl.create_default_context(cafile=localhost_cert)
Vinay Sajip0372e102011-05-05 12:59:14 +01001948 else:
Vinay Sajip9ba87612011-05-21 11:32:15 +01001949 sslctx = None
Benjamin Peterson43052a12014-11-23 20:36:44 -06001950 context = None
Vinay Sajip9ba87612011-05-21 11:32:15 +01001951 self.server = server = TestHTTPServer(addr, self.handle_request,
1952 0.01, sslctx=sslctx)
1953 server.start()
1954 server.ready.wait()
1955 host = 'localhost:%d' % server.server_port
Vinay Sajip39e35282011-05-21 16:46:41 +01001956 secure_client = secure and sslctx
1957 self.h_hdlr = logging.handlers.HTTPHandler(host, '/frob',
Benjamin Peterson43052a12014-11-23 20:36:44 -06001958 secure=secure_client,
Vinay Sajip1bf197e2016-06-07 21:19:55 +01001959 context=context,
1960 credentials=('foo', 'bar'))
Vinay Sajip9ba87612011-05-21 11:32:15 +01001961 self.log_data = None
1962 root_logger.addHandler(self.h_hdlr)
1963
1964 for method in ('GET', 'POST'):
1965 self.h_hdlr.method = method
1966 self.handled.clear()
1967 msg = "sp\xe4m"
1968 logger.error(msg)
1969 self.handled.wait()
1970 self.assertEqual(self.log_data.path, '/frob')
1971 self.assertEqual(self.command, method)
1972 if method == 'GET':
1973 d = parse_qs(self.log_data.query)
1974 else:
1975 d = parse_qs(self.post_data.decode('utf-8'))
1976 self.assertEqual(d['name'], ['http'])
1977 self.assertEqual(d['funcName'], ['test_output'])
1978 self.assertEqual(d['msg'], [msg])
1979
1980 self.server.stop(2.0)
1981 self.root_logger.removeHandler(self.h_hdlr)
1982 self.h_hdlr.close()
Vinay Sajip7367d082011-05-02 13:17:27 +01001983
Christian Heimes180510d2008-03-03 19:15:45 +00001984class MemoryTest(BaseTest):
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001985
Christian Heimes180510d2008-03-03 19:15:45 +00001986 """Test memory persistence of logger objects."""
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001987
Christian Heimes180510d2008-03-03 19:15:45 +00001988 def setUp(self):
1989 """Create a dict to remember potentially destroyed objects."""
1990 BaseTest.setUp(self)
1991 self._survivors = {}
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001992
Christian Heimes180510d2008-03-03 19:15:45 +00001993 def _watch_for_survival(self, *args):
1994 """Watch the given objects for survival, by creating weakrefs to
1995 them."""
1996 for obj in args:
1997 key = id(obj), repr(obj)
1998 self._survivors[key] = weakref.ref(obj)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00001999
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002000 def _assertTruesurvival(self):
Christian Heimes180510d2008-03-03 19:15:45 +00002001 """Assert that all objects watched for survival have survived."""
2002 # Trigger cycle breaking.
2003 gc.collect()
2004 dead = []
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002005 for (id_, repr_), ref in self._survivors.items():
Christian Heimes180510d2008-03-03 19:15:45 +00002006 if ref() is None:
2007 dead.append(repr_)
2008 if dead:
2009 self.fail("%d objects should have survived "
2010 "but have been destroyed: %s" % (len(dead), ", ".join(dead)))
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002011
Christian Heimes180510d2008-03-03 19:15:45 +00002012 def test_persistent_loggers(self):
2013 # Logger objects are persistent and retain their configuration, even
2014 # if visible references are destroyed.
2015 self.root_logger.setLevel(logging.INFO)
2016 foo = logging.getLogger("foo")
2017 self._watch_for_survival(foo)
2018 foo.setLevel(logging.DEBUG)
2019 self.root_logger.debug(self.next_message())
2020 foo.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00002021 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00002022 ('foo', 'DEBUG', '2'),
2023 ])
2024 del foo
2025 # foo has survived.
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002026 self._assertTruesurvival()
Christian Heimes180510d2008-03-03 19:15:45 +00002027 # foo has retained its settings.
2028 bar = logging.getLogger("foo")
2029 bar.debug(self.next_message())
Benjamin Peterson77108eb2009-07-01 00:43:10 +00002030 self.assert_log_lines([
Christian Heimes180510d2008-03-03 19:15:45 +00002031 ('foo', 'DEBUG', '2'),
2032 ('foo', 'DEBUG', '3'),
2033 ])
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002034
Benjamin Petersonf91df042009-02-13 02:50:59 +00002035
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002036class EncodingTest(BaseTest):
2037 def test_encoding_plain_file(self):
2038 # In Python 2.x, a plain file object is treated as having no encoding.
2039 log = logging.getLogger("test")
Vinay Sajip60b4df12010-12-27 11:18:52 +00002040 fd, fn = tempfile.mkstemp(".log", "test_logging-1-")
2041 os.close(fd)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002042 # the non-ascii data we write to the log.
2043 data = "foo\x80"
2044 try:
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002045 handler = logging.FileHandler(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002046 log.addHandler(handler)
2047 try:
2048 # write non-ascii data to the log.
2049 log.warning(data)
2050 finally:
2051 log.removeHandler(handler)
2052 handler.close()
2053 # check we wrote exactly those bytes, ignoring trailing \n etc
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002054 f = open(fn, encoding="utf-8")
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002055 try:
Benjamin Petersonc9c0f202009-06-30 23:06:06 +00002056 self.assertEqual(f.read().rstrip(), data)
Benjamin Petersonae5360b2008-09-08 23:05:23 +00002057 finally:
2058 f.close()
2059 finally:
2060 if os.path.isfile(fn):
2061 os.remove(fn)
Neal Norwitzb4a2df02003-01-02 14:56:39 +00002062
Benjamin Petersonf91df042009-02-13 02:50:59 +00002063 def test_encoding_cyrillic_unicode(self):
2064 log = logging.getLogger("test")
Mike53f7a7c2017-12-14 14:04:53 +03002065 # Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye)
Benjamin Petersonf91df042009-02-13 02:50:59 +00002066 message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f'
Mike53f7a7c2017-12-14 14:04:53 +03002067 # Ensure it's written in a Cyrillic encoding
Benjamin Petersonf91df042009-02-13 02:50:59 +00002068 writer_class = codecs.getwriter('cp1251')
Benjamin Peterson25c95f12009-05-08 20:42:26 +00002069 writer_class.encoding = 'cp1251'
Benjamin Petersonf91df042009-02-13 02:50:59 +00002070 stream = io.BytesIO()
2071 writer = writer_class(stream, 'strict')
2072 handler = logging.StreamHandler(writer)
2073 log.addHandler(handler)
2074 try:
2075 log.warning(message)
2076 finally:
2077 log.removeHandler(handler)
2078 handler.close()
2079 # check we wrote exactly those bytes, ignoring trailing \n etc
2080 s = stream.getvalue()
Mike53f7a7c2017-12-14 14:04:53 +03002081 # Compare against what the data should be when encoded in CP-1251
Benjamin Petersonf91df042009-02-13 02:50:59 +00002082 self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n')
2083
2084
Georg Brandlf9734072008-12-07 15:30:06 +00002085class WarningsTest(BaseTest):
Brett Cannondf8709d2009-04-01 20:01:47 +00002086
Georg Brandlf9734072008-12-07 15:30:06 +00002087 def test_warnings(self):
Brett Cannondf8709d2009-04-01 20:01:47 +00002088 with warnings.catch_warnings():
Brett Cannon5b9082a2009-04-05 18:57:32 +00002089 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002090 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002091 warnings.filterwarnings("always", category=UserWarning)
2092 stream = io.StringIO()
2093 h = logging.StreamHandler(stream)
2094 logger = logging.getLogger("py.warnings")
2095 logger.addHandler(h)
2096 warnings.warn("I'm warning you...")
2097 logger.removeHandler(h)
2098 s = stream.getvalue()
2099 h.close()
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02002100 self.assertGreater(s.find("UserWarning: I'm warning you...\n"), 0)
Georg Brandlf9734072008-12-07 15:30:06 +00002101
Mike53f7a7c2017-12-14 14:04:53 +03002102 # See if an explicit file uses the original implementation
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002103 a_file = io.StringIO()
2104 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42,
2105 a_file, "Dummy line")
2106 s = a_file.getvalue()
2107 a_file.close()
2108 self.assertEqual(s,
2109 "dummy.py:42: UserWarning: Explicit\n Dummy line\n")
2110
2111 def test_warnings_no_handlers(self):
2112 with warnings.catch_warnings():
2113 logging.captureWarnings(True)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002114 self.addCleanup(logging.captureWarnings, False)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002115
2116 # confirm our assumption: no loggers are set
2117 logger = logging.getLogger("py.warnings")
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002118 self.assertEqual(logger.handlers, [])
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002119
2120 warnings.showwarning("Explicit", UserWarning, "dummy.py", 42)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01002121 self.assertEqual(len(logger.handlers), 1)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01002122 self.assertIsInstance(logger.handlers[0], logging.NullHandler)
Georg Brandlf9734072008-12-07 15:30:06 +00002123
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002124
2125def formatFunc(format, datefmt=None):
2126 return logging.Formatter(format, datefmt)
2127
2128def handlerFunc():
2129 return logging.StreamHandler()
2130
2131class CustomHandler(logging.StreamHandler):
2132 pass
2133
2134class ConfigDictTest(BaseTest):
2135
2136 """Reading logging config from a dictionary."""
2137
Miss Islington (bot)6f49afc2018-07-02 02:35:09 -07002138 check_no_resource_warning = support.check_no_resource_warning
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03002139 expected_log_pat = r"^(\w+) \+\+ (\w+)$"
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002140
2141 # config0 is a standard configuration.
2142 config0 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002143 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002144 'formatters': {
2145 'form1' : {
2146 'format' : '%(levelname)s ++ %(message)s',
2147 },
2148 },
2149 'handlers' : {
2150 'hand1' : {
2151 'class' : 'logging.StreamHandler',
2152 'formatter' : 'form1',
2153 'level' : 'NOTSET',
2154 'stream' : 'ext://sys.stdout',
2155 },
2156 },
2157 'root' : {
2158 'level' : 'WARNING',
2159 'handlers' : ['hand1'],
2160 },
2161 }
2162
2163 # config1 adds a little to the standard configuration.
2164 config1 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002165 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002166 'formatters': {
2167 'form1' : {
2168 'format' : '%(levelname)s ++ %(message)s',
2169 },
2170 },
2171 'handlers' : {
2172 'hand1' : {
2173 'class' : 'logging.StreamHandler',
2174 'formatter' : 'form1',
2175 'level' : 'NOTSET',
2176 'stream' : 'ext://sys.stdout',
2177 },
2178 },
2179 'loggers' : {
2180 'compiler.parser' : {
2181 'level' : 'DEBUG',
2182 'handlers' : ['hand1'],
2183 },
2184 },
2185 'root' : {
2186 'level' : 'WARNING',
2187 },
2188 }
2189
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002190 # config1a moves the handler to the root. Used with config8a
2191 config1a = {
2192 'version': 1,
2193 'formatters': {
2194 'form1' : {
2195 'format' : '%(levelname)s ++ %(message)s',
2196 },
2197 },
2198 'handlers' : {
2199 'hand1' : {
2200 'class' : 'logging.StreamHandler',
2201 'formatter' : 'form1',
2202 'level' : 'NOTSET',
2203 'stream' : 'ext://sys.stdout',
2204 },
2205 },
2206 'loggers' : {
2207 'compiler.parser' : {
2208 'level' : 'DEBUG',
2209 },
2210 },
2211 'root' : {
2212 'level' : 'WARNING',
2213 'handlers' : ['hand1'],
2214 },
2215 }
2216
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002217 # config2 has a subtle configuration error that should be reported
2218 config2 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002219 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002220 'formatters': {
2221 'form1' : {
2222 'format' : '%(levelname)s ++ %(message)s',
2223 },
2224 },
2225 'handlers' : {
2226 'hand1' : {
2227 'class' : 'logging.StreamHandler',
2228 'formatter' : 'form1',
2229 'level' : 'NOTSET',
2230 'stream' : 'ext://sys.stdbout',
2231 },
2232 },
2233 'loggers' : {
2234 'compiler.parser' : {
2235 'level' : 'DEBUG',
2236 'handlers' : ['hand1'],
2237 },
2238 },
2239 'root' : {
2240 'level' : 'WARNING',
2241 },
2242 }
2243
Mike53f7a7c2017-12-14 14:04:53 +03002244 # As config1 but with a misspelt level on a handler
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002245 config2a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002246 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002247 'formatters': {
2248 'form1' : {
2249 'format' : '%(levelname)s ++ %(message)s',
2250 },
2251 },
2252 'handlers' : {
2253 'hand1' : {
2254 'class' : 'logging.StreamHandler',
2255 'formatter' : 'form1',
2256 'level' : 'NTOSET',
2257 'stream' : 'ext://sys.stdout',
2258 },
2259 },
2260 'loggers' : {
2261 'compiler.parser' : {
2262 'level' : 'DEBUG',
2263 'handlers' : ['hand1'],
2264 },
2265 },
2266 'root' : {
2267 'level' : 'WARNING',
2268 },
2269 }
2270
2271
Mike53f7a7c2017-12-14 14:04:53 +03002272 # As config1 but with a misspelt level on a logger
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002273 config2b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002274 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002275 'formatters': {
2276 'form1' : {
2277 'format' : '%(levelname)s ++ %(message)s',
2278 },
2279 },
2280 'handlers' : {
2281 'hand1' : {
2282 'class' : 'logging.StreamHandler',
2283 'formatter' : 'form1',
2284 'level' : 'NOTSET',
2285 'stream' : 'ext://sys.stdout',
2286 },
2287 },
2288 'loggers' : {
2289 'compiler.parser' : {
2290 'level' : 'DEBUG',
2291 'handlers' : ['hand1'],
2292 },
2293 },
2294 'root' : {
2295 'level' : 'WRANING',
2296 },
2297 }
2298
2299 # config3 has a less subtle configuration error
2300 config3 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002301 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002302 'formatters': {
2303 'form1' : {
2304 'format' : '%(levelname)s ++ %(message)s',
2305 },
2306 },
2307 'handlers' : {
2308 'hand1' : {
2309 'class' : 'logging.StreamHandler',
2310 'formatter' : 'misspelled_name',
2311 'level' : 'NOTSET',
2312 'stream' : 'ext://sys.stdout',
2313 },
2314 },
2315 'loggers' : {
2316 'compiler.parser' : {
2317 'level' : 'DEBUG',
2318 'handlers' : ['hand1'],
2319 },
2320 },
2321 'root' : {
2322 'level' : 'WARNING',
2323 },
2324 }
2325
2326 # config4 specifies a custom formatter class to be loaded
2327 config4 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002328 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002329 'formatters': {
2330 'form1' : {
2331 '()' : __name__ + '.ExceptionFormatter',
2332 'format' : '%(levelname)s:%(name)s:%(message)s',
2333 },
2334 },
2335 'handlers' : {
2336 'hand1' : {
2337 'class' : 'logging.StreamHandler',
2338 'formatter' : 'form1',
2339 'level' : 'NOTSET',
2340 'stream' : 'ext://sys.stdout',
2341 },
2342 },
2343 'root' : {
2344 'level' : 'NOTSET',
2345 'handlers' : ['hand1'],
2346 },
2347 }
2348
2349 # As config4 but using an actual callable rather than a string
2350 config4a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002351 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002352 'formatters': {
2353 'form1' : {
2354 '()' : ExceptionFormatter,
2355 'format' : '%(levelname)s:%(name)s:%(message)s',
2356 },
2357 'form2' : {
2358 '()' : __name__ + '.formatFunc',
2359 'format' : '%(levelname)s:%(name)s:%(message)s',
2360 },
2361 'form3' : {
2362 '()' : formatFunc,
2363 'format' : '%(levelname)s:%(name)s:%(message)s',
2364 },
2365 },
2366 'handlers' : {
2367 'hand1' : {
2368 'class' : 'logging.StreamHandler',
2369 'formatter' : 'form1',
2370 'level' : 'NOTSET',
2371 'stream' : 'ext://sys.stdout',
2372 },
2373 'hand2' : {
2374 '()' : handlerFunc,
2375 },
2376 },
2377 'root' : {
2378 'level' : 'NOTSET',
2379 'handlers' : ['hand1'],
2380 },
2381 }
2382
2383 # config5 specifies a custom handler class to be loaded
2384 config5 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002385 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002386 'formatters': {
2387 'form1' : {
2388 'format' : '%(levelname)s ++ %(message)s',
2389 },
2390 },
2391 'handlers' : {
2392 'hand1' : {
2393 'class' : __name__ + '.CustomHandler',
2394 'formatter' : 'form1',
2395 'level' : 'NOTSET',
2396 'stream' : 'ext://sys.stdout',
2397 },
2398 },
2399 'loggers' : {
2400 'compiler.parser' : {
2401 'level' : 'DEBUG',
2402 'handlers' : ['hand1'],
2403 },
2404 },
2405 'root' : {
2406 'level' : 'WARNING',
2407 },
2408 }
2409
2410 # config6 specifies a custom handler class to be loaded
2411 # but has bad arguments
2412 config6 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002413 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002414 'formatters': {
2415 'form1' : {
2416 'format' : '%(levelname)s ++ %(message)s',
2417 },
2418 },
2419 'handlers' : {
2420 'hand1' : {
2421 'class' : __name__ + '.CustomHandler',
2422 'formatter' : 'form1',
2423 'level' : 'NOTSET',
2424 'stream' : 'ext://sys.stdout',
2425 '9' : 'invalid parameter name',
2426 },
2427 },
2428 'loggers' : {
2429 'compiler.parser' : {
2430 'level' : 'DEBUG',
2431 'handlers' : ['hand1'],
2432 },
2433 },
2434 'root' : {
2435 'level' : 'WARNING',
2436 },
2437 }
2438
Mike53f7a7c2017-12-14 14:04:53 +03002439 # config 7 does not define compiler.parser but defines compiler.lexer
2440 # so compiler.parser should be disabled after applying it
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002441 config7 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002442 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002443 'formatters': {
2444 'form1' : {
2445 'format' : '%(levelname)s ++ %(message)s',
2446 },
2447 },
2448 'handlers' : {
2449 'hand1' : {
2450 'class' : 'logging.StreamHandler',
2451 'formatter' : 'form1',
2452 'level' : 'NOTSET',
2453 'stream' : 'ext://sys.stdout',
2454 },
2455 },
2456 'loggers' : {
2457 'compiler.lexer' : {
2458 'level' : 'DEBUG',
2459 'handlers' : ['hand1'],
2460 },
2461 },
2462 'root' : {
2463 'level' : 'WARNING',
2464 },
2465 }
2466
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002467 # config8 defines both compiler and compiler.lexer
2468 # so compiler.parser should not be disabled (since
2469 # compiler is defined)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002470 config8 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002471 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002472 'disable_existing_loggers' : False,
2473 'formatters': {
2474 'form1' : {
2475 'format' : '%(levelname)s ++ %(message)s',
2476 },
2477 },
2478 'handlers' : {
2479 'hand1' : {
2480 'class' : 'logging.StreamHandler',
2481 'formatter' : 'form1',
2482 'level' : 'NOTSET',
2483 'stream' : 'ext://sys.stdout',
2484 },
2485 },
2486 'loggers' : {
2487 'compiler' : {
2488 'level' : 'DEBUG',
2489 'handlers' : ['hand1'],
2490 },
2491 'compiler.lexer' : {
2492 },
2493 },
2494 'root' : {
2495 'level' : 'WARNING',
2496 },
2497 }
2498
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002499 # config8a disables existing loggers
2500 config8a = {
2501 'version': 1,
2502 'disable_existing_loggers' : True,
2503 'formatters': {
2504 'form1' : {
2505 'format' : '%(levelname)s ++ %(message)s',
2506 },
2507 },
2508 'handlers' : {
2509 'hand1' : {
2510 'class' : 'logging.StreamHandler',
2511 'formatter' : 'form1',
2512 'level' : 'NOTSET',
2513 'stream' : 'ext://sys.stdout',
2514 },
2515 },
2516 'loggers' : {
2517 'compiler' : {
2518 'level' : 'DEBUG',
2519 'handlers' : ['hand1'],
2520 },
2521 'compiler.lexer' : {
2522 },
2523 },
2524 'root' : {
2525 'level' : 'WARNING',
2526 },
2527 }
2528
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002529 config9 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002530 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002531 'formatters': {
2532 'form1' : {
2533 'format' : '%(levelname)s ++ %(message)s',
2534 },
2535 },
2536 'handlers' : {
2537 'hand1' : {
2538 'class' : 'logging.StreamHandler',
2539 'formatter' : 'form1',
2540 'level' : 'WARNING',
2541 'stream' : 'ext://sys.stdout',
2542 },
2543 },
2544 'loggers' : {
2545 'compiler.parser' : {
2546 'level' : 'WARNING',
2547 'handlers' : ['hand1'],
2548 },
2549 },
2550 'root' : {
2551 'level' : 'NOTSET',
2552 },
2553 }
2554
2555 config9a = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002556 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002557 'incremental' : True,
2558 'handlers' : {
2559 'hand1' : {
2560 'level' : 'WARNING',
2561 },
2562 },
2563 'loggers' : {
2564 'compiler.parser' : {
2565 'level' : 'INFO',
2566 },
2567 },
2568 }
2569
2570 config9b = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002571 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002572 'incremental' : True,
2573 'handlers' : {
2574 'hand1' : {
2575 'level' : 'INFO',
2576 },
2577 },
2578 'loggers' : {
2579 'compiler.parser' : {
2580 'level' : 'INFO',
2581 },
2582 },
2583 }
2584
Mike53f7a7c2017-12-14 14:04:53 +03002585 # As config1 but with a filter added
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002586 config10 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002587 'version': 1,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002588 'formatters': {
2589 'form1' : {
2590 'format' : '%(levelname)s ++ %(message)s',
2591 },
2592 },
2593 'filters' : {
2594 'filt1' : {
2595 'name' : 'compiler.parser',
2596 },
2597 },
2598 'handlers' : {
2599 'hand1' : {
2600 'class' : 'logging.StreamHandler',
2601 'formatter' : 'form1',
2602 'level' : 'NOTSET',
2603 'stream' : 'ext://sys.stdout',
2604 'filters' : ['filt1'],
2605 },
2606 },
2607 'loggers' : {
2608 'compiler.parser' : {
2609 'level' : 'DEBUG',
2610 'filters' : ['filt1'],
2611 },
2612 },
2613 'root' : {
2614 'level' : 'WARNING',
2615 'handlers' : ['hand1'],
2616 },
2617 }
2618
Mike53f7a7c2017-12-14 14:04:53 +03002619 # As config1 but using cfg:// references
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002620 config11 = {
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002621 'version': 1,
2622 'true_formatters': {
2623 'form1' : {
2624 'format' : '%(levelname)s ++ %(message)s',
2625 },
2626 },
2627 'handler_configs': {
2628 'hand1' : {
2629 'class' : 'logging.StreamHandler',
2630 'formatter' : 'form1',
2631 'level' : 'NOTSET',
2632 'stream' : 'ext://sys.stdout',
2633 },
2634 },
2635 'formatters' : 'cfg://true_formatters',
2636 'handlers' : {
2637 'hand1' : 'cfg://handler_configs[hand1]',
2638 },
2639 'loggers' : {
2640 'compiler.parser' : {
2641 'level' : 'DEBUG',
2642 'handlers' : ['hand1'],
2643 },
2644 },
2645 'root' : {
2646 'level' : 'WARNING',
2647 },
2648 }
2649
Mike53f7a7c2017-12-14 14:04:53 +03002650 # As config11 but missing the version key
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002651 config12 = {
2652 'true_formatters': {
2653 'form1' : {
2654 'format' : '%(levelname)s ++ %(message)s',
2655 },
2656 },
2657 'handler_configs': {
2658 'hand1' : {
2659 'class' : 'logging.StreamHandler',
2660 'formatter' : 'form1',
2661 'level' : 'NOTSET',
2662 'stream' : 'ext://sys.stdout',
2663 },
2664 },
2665 'formatters' : 'cfg://true_formatters',
2666 'handlers' : {
2667 'hand1' : 'cfg://handler_configs[hand1]',
2668 },
2669 'loggers' : {
2670 'compiler.parser' : {
2671 'level' : 'DEBUG',
2672 'handlers' : ['hand1'],
2673 },
2674 },
2675 'root' : {
2676 'level' : 'WARNING',
2677 },
2678 }
2679
Mike53f7a7c2017-12-14 14:04:53 +03002680 # As config11 but using an unsupported version
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002681 config13 = {
2682 'version': 2,
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002683 'true_formatters': {
2684 'form1' : {
2685 'format' : '%(levelname)s ++ %(message)s',
2686 },
2687 },
2688 'handler_configs': {
2689 'hand1' : {
2690 'class' : 'logging.StreamHandler',
2691 'formatter' : 'form1',
2692 'level' : 'NOTSET',
2693 'stream' : 'ext://sys.stdout',
2694 },
2695 },
2696 'formatters' : 'cfg://true_formatters',
2697 'handlers' : {
2698 'hand1' : 'cfg://handler_configs[hand1]',
2699 },
2700 'loggers' : {
2701 'compiler.parser' : {
2702 'level' : 'DEBUG',
2703 'handlers' : ['hand1'],
2704 },
2705 },
2706 'root' : {
2707 'level' : 'WARNING',
2708 },
2709 }
2710
Vinay Sajip8d270232012-11-15 14:20:18 +00002711 # As config0, but with properties
2712 config14 = {
2713 'version': 1,
2714 'formatters': {
2715 'form1' : {
2716 'format' : '%(levelname)s ++ %(message)s',
2717 },
2718 },
2719 'handlers' : {
2720 'hand1' : {
2721 'class' : 'logging.StreamHandler',
2722 'formatter' : 'form1',
2723 'level' : 'NOTSET',
2724 'stream' : 'ext://sys.stdout',
2725 '.': {
2726 'foo': 'bar',
2727 'terminator': '!\n',
2728 }
2729 },
2730 },
2731 'root' : {
2732 'level' : 'WARNING',
2733 'handlers' : ['hand1'],
2734 },
2735 }
2736
Vinay Sajip3f885b52013-03-22 15:19:54 +00002737 out_of_order = {
2738 "version": 1,
2739 "formatters": {
2740 "mySimpleFormatter": {
Vinay Sajip28421c62013-03-29 17:56:54 +00002741 "format": "%(asctime)s (%(name)s) %(levelname)s: %(message)s",
2742 "style": "$"
Vinay Sajip3f885b52013-03-22 15:19:54 +00002743 }
2744 },
2745 "handlers": {
2746 "fileGlobal": {
2747 "class": "logging.StreamHandler",
2748 "level": "DEBUG",
2749 "formatter": "mySimpleFormatter"
2750 },
2751 "bufferGlobal": {
2752 "class": "logging.handlers.MemoryHandler",
2753 "capacity": 5,
2754 "formatter": "mySimpleFormatter",
2755 "target": "fileGlobal",
2756 "level": "DEBUG"
2757 }
2758 },
2759 "loggers": {
2760 "mymodule": {
2761 "level": "DEBUG",
2762 "handlers": ["bufferGlobal"],
2763 "propagate": "true"
2764 }
2765 }
2766 }
2767
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002768 def apply_config(self, conf):
2769 logging.config.dictConfig(conf)
2770
2771 def test_config0_ok(self):
2772 # A simple config which overrides the default settings.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002773 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002774 self.apply_config(self.config0)
2775 logger = logging.getLogger()
2776 # Won't output anything
2777 logger.info(self.next_message())
2778 # Outputs a message
2779 logger.error(self.next_message())
2780 self.assert_log_lines([
2781 ('ERROR', '2'),
2782 ], stream=output)
2783 # Original logger output is empty.
2784 self.assert_log_lines([])
2785
2786 def test_config1_ok(self, config=config1):
2787 # A config defining a sub-parser as well.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002788 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002789 self.apply_config(config)
2790 logger = logging.getLogger("compiler.parser")
2791 # Both will output a message
2792 logger.info(self.next_message())
2793 logger.error(self.next_message())
2794 self.assert_log_lines([
2795 ('INFO', '1'),
2796 ('ERROR', '2'),
2797 ], stream=output)
2798 # Original logger output is empty.
2799 self.assert_log_lines([])
2800
2801 def test_config2_failure(self):
2802 # A simple config which overrides the default settings.
2803 self.assertRaises(Exception, self.apply_config, self.config2)
2804
2805 def test_config2a_failure(self):
2806 # A simple config which overrides the default settings.
2807 self.assertRaises(Exception, self.apply_config, self.config2a)
2808
2809 def test_config2b_failure(self):
2810 # A simple config which overrides the default settings.
2811 self.assertRaises(Exception, self.apply_config, self.config2b)
2812
2813 def test_config3_failure(self):
2814 # A simple config which overrides the default settings.
2815 self.assertRaises(Exception, self.apply_config, self.config3)
2816
2817 def test_config4_ok(self):
2818 # A config specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002819 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002820 self.apply_config(self.config4)
2821 #logger = logging.getLogger()
2822 try:
2823 raise RuntimeError()
2824 except RuntimeError:
2825 logging.exception("just testing")
2826 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002827 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002828 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2829 # Original logger output is empty
2830 self.assert_log_lines([])
2831
2832 def test_config4a_ok(self):
2833 # A config specifying a custom formatter class.
Vinay Sajip1feedb42014-05-31 08:19:12 +01002834 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002835 self.apply_config(self.config4a)
2836 #logger = logging.getLogger()
2837 try:
2838 raise RuntimeError()
2839 except RuntimeError:
2840 logging.exception("just testing")
2841 sys.stdout.seek(0)
Ezio Melottib3aedd42010-11-20 19:04:17 +00002842 self.assertEqual(output.getvalue(),
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002843 "ERROR:root:just testing\nGot a [RuntimeError]\n")
2844 # Original logger output is empty
2845 self.assert_log_lines([])
2846
2847 def test_config5_ok(self):
2848 self.test_config1_ok(config=self.config5)
2849
2850 def test_config6_failure(self):
2851 self.assertRaises(Exception, self.apply_config, self.config6)
2852
2853 def test_config7_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01002854 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002855 self.apply_config(self.config1)
2856 logger = logging.getLogger("compiler.parser")
2857 # Both will output a message
2858 logger.info(self.next_message())
2859 logger.error(self.next_message())
2860 self.assert_log_lines([
2861 ('INFO', '1'),
2862 ('ERROR', '2'),
2863 ], stream=output)
2864 # Original logger output is empty.
2865 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01002866 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002867 self.apply_config(self.config7)
2868 logger = logging.getLogger("compiler.parser")
2869 self.assertTrue(logger.disabled)
2870 logger = logging.getLogger("compiler.lexer")
2871 # Both will output a message
2872 logger.info(self.next_message())
2873 logger.error(self.next_message())
2874 self.assert_log_lines([
2875 ('INFO', '3'),
2876 ('ERROR', '4'),
2877 ], stream=output)
2878 # Original logger output is empty.
2879 self.assert_log_lines([])
2880
Mike53f7a7c2017-12-14 14:04:53 +03002881 # Same as test_config_7_ok but don't disable old loggers.
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002882 def test_config_8_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01002883 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002884 self.apply_config(self.config1)
2885 logger = logging.getLogger("compiler.parser")
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002886 # All will output a message
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002887 logger.info(self.next_message())
2888 logger.error(self.next_message())
2889 self.assert_log_lines([
2890 ('INFO', '1'),
2891 ('ERROR', '2'),
2892 ], stream=output)
2893 # Original logger output is empty.
2894 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01002895 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002896 self.apply_config(self.config8)
2897 logger = logging.getLogger("compiler.parser")
2898 self.assertFalse(logger.disabled)
2899 # Both will output a message
2900 logger.info(self.next_message())
2901 logger.error(self.next_message())
2902 logger = logging.getLogger("compiler.lexer")
2903 # Both will output a message
2904 logger.info(self.next_message())
2905 logger.error(self.next_message())
2906 self.assert_log_lines([
2907 ('INFO', '3'),
2908 ('ERROR', '4'),
2909 ('INFO', '5'),
2910 ('ERROR', '6'),
2911 ], stream=output)
2912 # Original logger output is empty.
2913 self.assert_log_lines([])
2914
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002915 def test_config_8a_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01002916 with support.captured_stdout() as output:
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002917 self.apply_config(self.config1a)
2918 logger = logging.getLogger("compiler.parser")
2919 # See issue #11424. compiler-hyphenated sorts
2920 # between compiler and compiler.xyz and this
2921 # was preventing compiler.xyz from being included
2922 # in the child loggers of compiler because of an
2923 # overzealous loop termination condition.
2924 hyphenated = logging.getLogger('compiler-hyphenated')
2925 # All will output a message
2926 logger.info(self.next_message())
2927 logger.error(self.next_message())
2928 hyphenated.critical(self.next_message())
2929 self.assert_log_lines([
2930 ('INFO', '1'),
2931 ('ERROR', '2'),
2932 ('CRITICAL', '3'),
2933 ], stream=output)
2934 # Original logger output is empty.
2935 self.assert_log_lines([])
Vinay Sajip1feedb42014-05-31 08:19:12 +01002936 with support.captured_stdout() as output:
Vinay Sajip9f9991c2011-03-07 18:02:57 +00002937 self.apply_config(self.config8a)
2938 logger = logging.getLogger("compiler.parser")
2939 self.assertFalse(logger.disabled)
2940 # Both will output a message
2941 logger.info(self.next_message())
2942 logger.error(self.next_message())
2943 logger = logging.getLogger("compiler.lexer")
2944 # Both will output a message
2945 logger.info(self.next_message())
2946 logger.error(self.next_message())
2947 # Will not appear
2948 hyphenated.critical(self.next_message())
2949 self.assert_log_lines([
2950 ('INFO', '4'),
2951 ('ERROR', '5'),
2952 ('INFO', '6'),
2953 ('ERROR', '7'),
2954 ], stream=output)
2955 # Original logger output is empty.
2956 self.assert_log_lines([])
2957
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002958 def test_config_9_ok(self):
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(self.config9)
2961 logger = logging.getLogger("compiler.parser")
Mike53f7a7c2017-12-14 14:04:53 +03002962 # Nothing will be output since both handler and logger are set to WARNING
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002963 logger.info(self.next_message())
2964 self.assert_log_lines([], stream=output)
2965 self.apply_config(self.config9a)
Mike53f7a7c2017-12-14 14:04:53 +03002966 # Nothing will be output since handler is still set to WARNING
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002967 logger.info(self.next_message())
2968 self.assert_log_lines([], stream=output)
2969 self.apply_config(self.config9b)
Mike53f7a7c2017-12-14 14:04:53 +03002970 # Message should now be output
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002971 logger.info(self.next_message())
2972 self.assert_log_lines([
2973 ('INFO', '3'),
2974 ], stream=output)
2975
2976 def test_config_10_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01002977 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002978 self.apply_config(self.config10)
2979 logger = logging.getLogger("compiler.parser")
2980 logger.warning(self.next_message())
2981 logger = logging.getLogger('compiler')
Mike53f7a7c2017-12-14 14:04:53 +03002982 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002983 logger.warning(self.next_message())
2984 logger = logging.getLogger('compiler.lexer')
Mike53f7a7c2017-12-14 14:04:53 +03002985 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002986 logger.warning(self.next_message())
2987 logger = logging.getLogger("compiler.parser.codegen")
Mike53f7a7c2017-12-14 14:04:53 +03002988 # Output, as not filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00002989 logger.error(self.next_message())
2990 self.assert_log_lines([
2991 ('WARNING', '1'),
2992 ('ERROR', '4'),
2993 ], stream=output)
2994
2995 def test_config11_ok(self):
2996 self.test_config1_ok(self.config11)
2997
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00002998 def test_config12_failure(self):
2999 self.assertRaises(Exception, self.apply_config, self.config12)
3000
3001 def test_config13_failure(self):
3002 self.assertRaises(Exception, self.apply_config, self.config13)
3003
Vinay Sajip8d270232012-11-15 14:20:18 +00003004 def test_config14_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003005 with support.captured_stdout() as output:
Vinay Sajip8d270232012-11-15 14:20:18 +00003006 self.apply_config(self.config14)
3007 h = logging._handlers['hand1']
3008 self.assertEqual(h.foo, 'bar')
3009 self.assertEqual(h.terminator, '!\n')
3010 logging.warning('Exclamation')
3011 self.assertTrue(output.getvalue().endswith('Exclamation!\n'))
3012
Miss Islington (bot)6f49afc2018-07-02 02:35:09 -07003013 def test_config15_ok(self):
3014
3015 def cleanup(h1, fn):
3016 h1.close()
3017 os.remove(fn)
3018
3019 with self.check_no_resource_warning():
3020 fd, fn = tempfile.mkstemp(".log", "test_logging-X-")
3021 os.close(fd)
3022
3023 config = {
3024 "version": 1,
3025 "handlers": {
3026 "file": {
3027 "class": "logging.FileHandler",
3028 "filename": fn
3029 }
3030 },
3031 "root": {
3032 "handlers": ["file"]
3033 }
3034 }
3035
3036 self.apply_config(config)
3037 self.apply_config(config)
3038
3039 handler = logging.root.handlers[0]
3040 self.addCleanup(cleanup, handler, fn)
3041
Vinay Sajip4ded5512012-10-02 15:56:16 +01003042 def setup_via_listener(self, text, verify=None):
Benjamin Peterson9451a1c2010-03-13 22:30:34 +00003043 text = text.encode("utf-8")
Florent Xiclunadc692742010-08-15 20:16:27 +00003044 # Ask for a randomly assigned port (by using port 0)
Vinay Sajip4ded5512012-10-02 15:56:16 +01003045 t = logging.config.listen(0, verify)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003046 t.start()
3047 t.ready.wait()
Benjamin Petersona82addb2010-06-27 20:54:28 +00003048 # Now get the port allocated
3049 port = t.port
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003050 t.ready.clear()
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003051 try:
3052 sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
3053 sock.settimeout(2.0)
3054 sock.connect(('localhost', port))
3055
3056 slen = struct.pack('>L', len(text))
3057 s = slen + text
3058 sentsofar = 0
3059 left = len(s)
3060 while left > 0:
3061 sent = sock.send(s[sentsofar:])
3062 sentsofar += sent
3063 left -= sent
3064 sock.close()
3065 finally:
3066 t.ready.wait(2.0)
3067 logging.config.stopListening()
Victor Stinnerb9b69002017-09-14 14:40:56 -07003068 support.join_thread(t, 2.0)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003069
3070 def test_listen_config_10_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003071 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003072 self.setup_via_listener(json.dumps(self.config10))
3073 logger = logging.getLogger("compiler.parser")
3074 logger.warning(self.next_message())
3075 logger = logging.getLogger('compiler')
Mike53f7a7c2017-12-14 14:04:53 +03003076 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003077 logger.warning(self.next_message())
3078 logger = logging.getLogger('compiler.lexer')
Mike53f7a7c2017-12-14 14:04:53 +03003079 # Not output, because filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003080 logger.warning(self.next_message())
3081 logger = logging.getLogger("compiler.parser.codegen")
Mike53f7a7c2017-12-14 14:04:53 +03003082 # Output, as not filtered
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003083 logger.error(self.next_message())
3084 self.assert_log_lines([
3085 ('WARNING', '1'),
3086 ('ERROR', '4'),
3087 ], stream=output)
3088
3089 def test_listen_config_1_ok(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003090 with support.captured_stdout() as output:
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003091 self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1))
3092 logger = logging.getLogger("compiler.parser")
3093 # Both will output a message
3094 logger.info(self.next_message())
3095 logger.error(self.next_message())
3096 self.assert_log_lines([
3097 ('INFO', '1'),
3098 ('ERROR', '2'),
3099 ], stream=output)
3100 # Original logger output is empty.
3101 self.assert_log_lines([])
3102
Vinay Sajip4ded5512012-10-02 15:56:16 +01003103 def test_listen_verify(self):
3104
3105 def verify_fail(stuff):
3106 return None
3107
3108 def verify_reverse(stuff):
3109 return stuff[::-1]
3110
3111 logger = logging.getLogger("compiler.parser")
3112 to_send = textwrap.dedent(ConfigFileTest.config1)
3113 # First, specify a verification function that will fail.
3114 # We expect to see no output, since our configuration
3115 # never took effect.
Vinay Sajip1feedb42014-05-31 08:19:12 +01003116 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003117 self.setup_via_listener(to_send, verify_fail)
3118 # Both will output a message
3119 logger.info(self.next_message())
3120 logger.error(self.next_message())
3121 self.assert_log_lines([], stream=output)
3122 # Original logger output has the stuff we logged.
3123 self.assert_log_lines([
3124 ('INFO', '1'),
3125 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003126 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003127
3128 # Now, perform no verification. Our configuration
3129 # should take effect.
3130
Vinay Sajip1feedb42014-05-31 08:19:12 +01003131 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003132 self.setup_via_listener(to_send) # no verify callable specified
3133 logger = logging.getLogger("compiler.parser")
3134 # Both will output a message
3135 logger.info(self.next_message())
3136 logger.error(self.next_message())
3137 self.assert_log_lines([
3138 ('INFO', '3'),
3139 ('ERROR', '4'),
3140 ], stream=output)
3141 # Original logger output still has the stuff we logged before.
3142 self.assert_log_lines([
3143 ('INFO', '1'),
3144 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003145 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003146
3147 # Now, perform verification which transforms the bytes.
3148
Vinay Sajip1feedb42014-05-31 08:19:12 +01003149 with support.captured_stdout() as output:
Vinay Sajip4ded5512012-10-02 15:56:16 +01003150 self.setup_via_listener(to_send[::-1], verify_reverse)
3151 logger = logging.getLogger("compiler.parser")
3152 # Both will output a message
3153 logger.info(self.next_message())
3154 logger.error(self.next_message())
3155 self.assert_log_lines([
3156 ('INFO', '5'),
3157 ('ERROR', '6'),
3158 ], stream=output)
3159 # Original logger output still has the stuff we logged before.
3160 self.assert_log_lines([
3161 ('INFO', '1'),
3162 ('ERROR', '2'),
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003163 ], pat=r"^[\w.]+ -> (\w+): (\d+)$")
Vinay Sajip4ded5512012-10-02 15:56:16 +01003164
Vinay Sajip3f885b52013-03-22 15:19:54 +00003165 def test_out_of_order(self):
3166 self.apply_config(self.out_of_order)
3167 handler = logging.getLogger('mymodule').handlers[0]
3168 self.assertIsInstance(handler.target, logging.Handler)
Vinay Sajip28421c62013-03-29 17:56:54 +00003169 self.assertIsInstance(handler.formatter._style,
3170 logging.StringTemplateStyle)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003171
Vinay Sajip373baef2011-04-26 20:05:24 +01003172 def test_baseconfig(self):
3173 d = {
3174 'atuple': (1, 2, 3),
3175 'alist': ['a', 'b', 'c'],
3176 'adict': {'d': 'e', 'f': 3 },
3177 'nest1': ('g', ('h', 'i'), 'j'),
3178 'nest2': ['k', ['l', 'm'], 'n'],
3179 'nest3': ['o', 'cfg://alist', 'p'],
3180 }
3181 bc = logging.config.BaseConfigurator(d)
3182 self.assertEqual(bc.convert('cfg://atuple[1]'), 2)
3183 self.assertEqual(bc.convert('cfg://alist[1]'), 'b')
3184 self.assertEqual(bc.convert('cfg://nest1[1][0]'), 'h')
3185 self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm')
3186 self.assertEqual(bc.convert('cfg://adict.d'), 'e')
3187 self.assertEqual(bc.convert('cfg://adict[f]'), 3)
3188 v = bc.convert('cfg://nest3')
3189 self.assertEqual(v.pop(1), ['a', 'b', 'c'])
3190 self.assertRaises(KeyError, bc.convert, 'cfg://nosuch')
3191 self.assertRaises(ValueError, bc.convert, 'cfg://!')
3192 self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]')
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003193
3194class ManagerTest(BaseTest):
3195 def test_manager_loggerclass(self):
3196 logged = []
3197
3198 class MyLogger(logging.Logger):
3199 def _log(self, level, msg, args, exc_info=None, extra=None):
3200 logged.append(msg)
3201
3202 man = logging.Manager(None)
3203 self.assertRaises(TypeError, man.setLoggerClass, int)
3204 man.setLoggerClass(MyLogger)
3205 logger = man.getLogger('test')
3206 logger.warning('should appear in logged')
3207 logging.warning('should not appear in logged')
3208
3209 self.assertEqual(logged, ['should appear in logged'])
3210
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003211 def test_set_log_record_factory(self):
3212 man = logging.Manager(None)
3213 expected = object()
3214 man.setLogRecordFactory(expected)
3215 self.assertEqual(man.logRecordFactory, expected)
Vinay Sajipdb81c4c2010-02-25 23:13:06 +00003216
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003217class ChildLoggerTest(BaseTest):
3218 def test_child_loggers(self):
3219 r = logging.getLogger()
3220 l1 = logging.getLogger('abc')
3221 l2 = logging.getLogger('def.ghi')
3222 c1 = r.getChild('xyz')
3223 c2 = r.getChild('uvw.xyz')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02003224 self.assertIs(c1, logging.getLogger('xyz'))
3225 self.assertIs(c2, logging.getLogger('uvw.xyz'))
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003226 c1 = l1.getChild('def')
3227 c2 = c1.getChild('ghi')
3228 c3 = l1.getChild('def.ghi')
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02003229 self.assertIs(c1, logging.getLogger('abc.def'))
3230 self.assertIs(c2, logging.getLogger('abc.def.ghi'))
3231 self.assertIs(c2, c3)
Benjamin Peterson22005fc2010-04-11 16:25:06 +00003232
3233
Vinay Sajip6fac8172010-10-19 20:44:14 +00003234class DerivedLogRecord(logging.LogRecord):
3235 pass
3236
Vinay Sajip61561522010-12-03 11:50:38 +00003237class LogRecordFactoryTest(BaseTest):
Vinay Sajip6fac8172010-10-19 20:44:14 +00003238
3239 def setUp(self):
3240 class CheckingFilter(logging.Filter):
3241 def __init__(self, cls):
3242 self.cls = cls
3243
3244 def filter(self, record):
3245 t = type(record)
3246 if t is not self.cls:
3247 msg = 'Unexpected LogRecord type %s, expected %s' % (t,
3248 self.cls)
3249 raise TypeError(msg)
3250 return True
3251
3252 BaseTest.setUp(self)
3253 self.filter = CheckingFilter(DerivedLogRecord)
3254 self.root_logger.addFilter(self.filter)
Vinay Sajip61561522010-12-03 11:50:38 +00003255 self.orig_factory = logging.getLogRecordFactory()
Vinay Sajip6fac8172010-10-19 20:44:14 +00003256
3257 def tearDown(self):
3258 self.root_logger.removeFilter(self.filter)
3259 BaseTest.tearDown(self)
Vinay Sajip61561522010-12-03 11:50:38 +00003260 logging.setLogRecordFactory(self.orig_factory)
Vinay Sajip6fac8172010-10-19 20:44:14 +00003261
3262 def test_logrecord_class(self):
3263 self.assertRaises(TypeError, self.root_logger.warning,
3264 self.next_message())
Vinay Sajip61561522010-12-03 11:50:38 +00003265 logging.setLogRecordFactory(DerivedLogRecord)
Vinay Sajip6fac8172010-10-19 20:44:14 +00003266 self.root_logger.error(self.next_message())
3267 self.assert_log_lines([
3268 ('root', 'ERROR', '2'),
3269 ])
3270
3271
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003272class QueueHandlerTest(BaseTest):
3273 # Do not bother with a logger name group.
Ezio Melotti3ffd29b2012-10-02 19:45:00 +03003274 expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$"
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003275
3276 def setUp(self):
3277 BaseTest.setUp(self)
3278 self.queue = queue.Queue(-1)
3279 self.que_hdlr = logging.handlers.QueueHandler(self.queue)
favlladfe3442017-08-01 20:12:26 +02003280 self.name = 'que'
Vinay Sajip8552d1f2010-09-14 09:34:09 +00003281 self.que_logger = logging.getLogger('que')
3282 self.que_logger.propagate = False
3283 self.que_logger.setLevel(logging.WARNING)
3284 self.que_logger.addHandler(self.que_hdlr)
3285
3286 def tearDown(self):
3287 self.que_hdlr.close()
3288 BaseTest.tearDown(self)
3289
3290 def test_queue_handler(self):
3291 self.que_logger.debug(self.next_message())
3292 self.assertRaises(queue.Empty, self.queue.get_nowait)
3293 self.que_logger.info(self.next_message())
3294 self.assertRaises(queue.Empty, self.queue.get_nowait)
3295 msg = self.next_message()
3296 self.que_logger.warning(msg)
3297 data = self.queue.get_nowait()
3298 self.assertTrue(isinstance(data, logging.LogRecord))
3299 self.assertEqual(data.name, self.que_logger.name)
3300 self.assertEqual((data.msg, data.args), (msg, None))
3301
favlladfe3442017-08-01 20:12:26 +02003302 def test_formatting(self):
3303 msg = self.next_message()
3304 levelname = logging.getLevelName(logging.WARNING)
3305 log_format_str = '{name} -> {levelname}: {message}'
3306 formatted_msg = log_format_str.format(name=self.name,
3307 levelname=levelname, message=msg)
3308 formatter = logging.Formatter(self.log_format)
3309 self.que_hdlr.setFormatter(formatter)
3310 self.que_logger.warning(msg)
3311 log_record = self.queue.get_nowait()
3312 self.assertEqual(formatted_msg, log_record.msg)
3313 self.assertEqual(formatted_msg, log_record.message)
3314
Victor Stinnercafa2ef2011-05-02 16:11:28 +02003315 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3316 'logging.handlers.QueueListener required for this test')
Vinay Sajipe723e962011-04-15 22:27:17 +01003317 def test_queue_listener(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003318 handler = support.TestHandler(support.Matcher())
Vinay Sajipe723e962011-04-15 22:27:17 +01003319 listener = logging.handlers.QueueListener(self.queue, handler)
3320 listener.start()
3321 try:
3322 self.que_logger.warning(self.next_message())
3323 self.que_logger.error(self.next_message())
3324 self.que_logger.critical(self.next_message())
3325 finally:
3326 listener.stop()
3327 self.assertTrue(handler.matches(levelno=logging.WARNING, message='1'))
3328 self.assertTrue(handler.matches(levelno=logging.ERROR, message='2'))
3329 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3'))
Vinay Sajip365701a2015-02-09 19:49:00 +00003330 handler.close()
3331
3332 # Now test with respect_handler_level set
3333
3334 handler = support.TestHandler(support.Matcher())
3335 handler.setLevel(logging.CRITICAL)
3336 listener = logging.handlers.QueueListener(self.queue, handler,
3337 respect_handler_level=True)
3338 listener.start()
3339 try:
3340 self.que_logger.warning(self.next_message())
3341 self.que_logger.error(self.next_message())
3342 self.que_logger.critical(self.next_message())
3343 finally:
3344 listener.stop()
3345 self.assertFalse(handler.matches(levelno=logging.WARNING, message='4'))
3346 self.assertFalse(handler.matches(levelno=logging.ERROR, message='5'))
3347 self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='6'))
Miss Islington (bot)1a218932018-10-06 21:33:37 -07003348 handler.close()
3349
3350 @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'),
3351 'logging.handlers.QueueListener required for this test')
3352 def test_queue_listener_with_StreamHandler(self):
3353 # Test that traceback only appends once (bpo-34334).
3354 listener = logging.handlers.QueueListener(self.queue, self.root_hdlr)
3355 listener.start()
3356 try:
3357 1 / 0
3358 except ZeroDivisionError as e:
3359 exc = e
3360 self.que_logger.exception(self.next_message(), exc_info=exc)
3361 listener.stop()
3362 self.assertEqual(self.stream.getvalue().strip().count('Traceback'), 1)
Vinay Sajip365701a2015-02-09 19:49:00 +00003363
Vinay Sajipd61910c2016-09-08 01:13:39 +01003364if hasattr(logging.handlers, 'QueueListener'):
3365 import multiprocessing
3366 from unittest.mock import patch
3367
3368 class QueueListenerTest(BaseTest):
3369 """
3370 Tests based on patch submitted for issue #27930. Ensure that
3371 QueueListener handles all log messages.
3372 """
3373
3374 repeat = 20
3375
3376 @staticmethod
3377 def setup_and_log(log_queue, ident):
3378 """
3379 Creates a logger with a QueueHandler that logs to a queue read by a
3380 QueueListener. Starts the listener, logs five messages, and stops
3381 the listener.
3382 """
3383 logger = logging.getLogger('test_logger_with_id_%s' % ident)
3384 logger.setLevel(logging.DEBUG)
3385 handler = logging.handlers.QueueHandler(log_queue)
3386 logger.addHandler(handler)
3387 listener = logging.handlers.QueueListener(log_queue)
3388 listener.start()
3389
3390 logger.info('one')
3391 logger.info('two')
3392 logger.info('three')
3393 logger.info('four')
3394 logger.info('five')
3395
3396 listener.stop()
3397 logger.removeHandler(handler)
3398 handler.close()
3399
3400 @patch.object(logging.handlers.QueueListener, 'handle')
3401 def test_handle_called_with_queue_queue(self, mock_handle):
3402 for i in range(self.repeat):
3403 log_queue = queue.Queue()
3404 self.setup_and_log(log_queue, '%s_%s' % (self.id(), i))
3405 self.assertEqual(mock_handle.call_count, 5 * self.repeat,
3406 'correct number of handled log messages')
3407
3408 @patch.object(logging.handlers.QueueListener, 'handle')
3409 def test_handle_called_with_mp_queue(self, mock_handle):
xdegayebf2b65e2017-12-01 08:08:49 +01003410 # Issue 28668: The multiprocessing (mp) module is not functional
3411 # when the mp.synchronize module cannot be imported.
3412 support.import_module('multiprocessing.synchronize')
Vinay Sajipd61910c2016-09-08 01:13:39 +01003413 for i in range(self.repeat):
3414 log_queue = multiprocessing.Queue()
3415 self.setup_and_log(log_queue, '%s_%s' % (self.id(), i))
Victor Stinner8ca2f2f2017-04-26 15:56:25 +02003416 log_queue.close()
3417 log_queue.join_thread()
Vinay Sajipd61910c2016-09-08 01:13:39 +01003418 self.assertEqual(mock_handle.call_count, 5 * self.repeat,
3419 'correct number of handled log messages')
3420
3421 @staticmethod
3422 def get_all_from_queue(log_queue):
3423 try:
3424 while True:
3425 yield log_queue.get_nowait()
3426 except queue.Empty:
3427 return []
3428
3429 def test_no_messages_in_queue_after_stop(self):
3430 """
3431 Five messages are logged then the QueueListener is stopped. This
3432 test then gets everything off the queue. Failure of this test
3433 indicates that messages were not registered on the queue until
3434 _after_ the QueueListener stopped.
3435 """
xdegayebf2b65e2017-12-01 08:08:49 +01003436 # Issue 28668: The multiprocessing (mp) module is not functional
3437 # when the mp.synchronize module cannot be imported.
3438 support.import_module('multiprocessing.synchronize')
Vinay Sajipd61910c2016-09-08 01:13:39 +01003439 for i in range(self.repeat):
3440 queue = multiprocessing.Queue()
3441 self.setup_and_log(queue, '%s_%s' %(self.id(), i))
3442 # time.sleep(1)
3443 items = list(self.get_all_from_queue(queue))
Victor Stinner8ca2f2f2017-04-26 15:56:25 +02003444 queue.close()
3445 queue.join_thread()
3446
Vinay Sajipd61910c2016-09-08 01:13:39 +01003447 expected = [[], [logging.handlers.QueueListener._sentinel]]
3448 self.assertIn(items, expected,
3449 'Found unexpected messages in queue: %s' % (
3450 [m.msg if isinstance(m, logging.LogRecord)
3451 else m for m in items]))
3452
Vinay Sajipe723e962011-04-15 22:27:17 +01003453
Vinay Sajip37eb3382011-04-26 20:26:41 +01003454ZERO = datetime.timedelta(0)
3455
3456class UTC(datetime.tzinfo):
3457 def utcoffset(self, dt):
3458 return ZERO
3459
3460 dst = utcoffset
3461
3462 def tzname(self, dt):
3463 return 'UTC'
3464
3465utc = UTC()
Vinay Sajipe723e962011-04-15 22:27:17 +01003466
Vinay Sajipa39c5712010-10-25 13:57:39 +00003467class FormatterTest(unittest.TestCase):
3468 def setUp(self):
3469 self.common = {
3470 'name': 'formatter.test',
3471 'level': logging.DEBUG,
3472 'pathname': os.path.join('path', 'to', 'dummy.ext'),
3473 'lineno': 42,
3474 'exc_info': None,
3475 'func': None,
3476 'msg': 'Message with %d %s',
3477 'args': (2, 'placeholders'),
3478 }
3479 self.variants = {
3480 }
3481
3482 def get_record(self, name=None):
3483 result = dict(self.common)
3484 if name is not None:
3485 result.update(self.variants[name])
3486 return logging.makeLogRecord(result)
3487
3488 def test_percent(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003489 # Test %-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003490 r = self.get_record()
3491 f = logging.Formatter('${%(message)s}')
3492 self.assertEqual(f.format(r), '${Message with 2 placeholders}')
3493 f = logging.Formatter('%(random)s')
3494 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003495 self.assertFalse(f.usesTime())
3496 f = logging.Formatter('%(asctime)s')
3497 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003498 f = logging.Formatter('%(asctime)-15s')
3499 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003500 f = logging.Formatter('asctime')
3501 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003502
3503 def test_braces(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003504 # Test {}-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003505 r = self.get_record()
3506 f = logging.Formatter('$%{message}%$', style='{')
3507 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3508 f = logging.Formatter('{random}', style='{')
3509 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003510 self.assertFalse(f.usesTime())
3511 f = logging.Formatter('{asctime}', style='{')
3512 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003513 f = logging.Formatter('{asctime!s:15}', style='{')
3514 self.assertTrue(f.usesTime())
3515 f = logging.Formatter('{asctime:15}', style='{')
3516 self.assertTrue(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003517 f = logging.Formatter('asctime', style='{')
3518 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003519
3520 def test_dollars(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003521 # Test $-formatting
Vinay Sajipa39c5712010-10-25 13:57:39 +00003522 r = self.get_record()
3523 f = logging.Formatter('$message', style='$')
3524 self.assertEqual(f.format(r), 'Message with 2 placeholders')
3525 f = logging.Formatter('$$%${message}%$$', style='$')
3526 self.assertEqual(f.format(r), '$%Message with 2 placeholders%$')
3527 f = logging.Formatter('${random}', style='$')
3528 self.assertRaises(KeyError, f.format, r)
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003529 self.assertFalse(f.usesTime())
3530 f = logging.Formatter('${asctime}', style='$')
3531 self.assertTrue(f.usesTime())
Vinay Sajip89807a52011-02-26 16:06:02 +00003532 f = logging.Formatter('${asctime', style='$')
3533 self.assertFalse(f.usesTime())
Vinay Sajip6a65c5d2010-10-26 13:16:11 +00003534 f = logging.Formatter('$asctime', style='$')
3535 self.assertTrue(f.usesTime())
3536 f = logging.Formatter('asctime', style='$')
3537 self.assertFalse(f.usesTime())
Vinay Sajipa39c5712010-10-25 13:57:39 +00003538
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003539 def test_invalid_style(self):
3540 self.assertRaises(ValueError, logging.Formatter, None, None, 'x')
3541
Vinay Sajip86a96ce2011-04-27 08:30:30 +01003542 def test_time(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003543 r = self.get_record()
Vinay Sajiped1f7c82012-07-03 21:36:36 +01003544 dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
3545 # We use None to indicate we want the local timezone
3546 # We're essentially converting a UTC time to local time
3547 r.created = time.mktime(dt.astimezone(None).timetuple())
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003548 r.msecs = 123
3549 f = logging.Formatter('%(asctime)s %(message)s')
Vinay Sajip37eb3382011-04-26 20:26:41 +01003550 f.converter = time.gmtime
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003551 self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
3552 self.assertEqual(f.formatTime(r, '%Y:%d'), '1993:21')
Vinay Sajip985ef872011-04-26 19:34:04 +01003553 f.format(r)
3554 self.assertEqual(r.asctime, '1993-04-21 08:03:00,123')
3555
3556class TestBufferingFormatter(logging.BufferingFormatter):
3557 def formatHeader(self, records):
3558 return '[(%d)' % len(records)
3559
3560 def formatFooter(self, records):
3561 return '(%d)]' % len(records)
3562
3563class BufferingFormatterTest(unittest.TestCase):
3564 def setUp(self):
3565 self.records = [
3566 logging.makeLogRecord({'msg': 'one'}),
3567 logging.makeLogRecord({'msg': 'two'}),
3568 ]
3569
3570 def test_default(self):
3571 f = logging.BufferingFormatter()
3572 self.assertEqual('', f.format([]))
3573 self.assertEqual('onetwo', f.format(self.records))
3574
3575 def test_custom(self):
3576 f = TestBufferingFormatter()
3577 self.assertEqual('[(2)onetwo(2)]', f.format(self.records))
3578 lf = logging.Formatter('<%(message)s>')
3579 f = TestBufferingFormatter(lf)
3580 self.assertEqual('[(2)<one><two>(2)]', f.format(self.records))
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003581
3582class ExceptionTest(BaseTest):
3583 def test_formatting(self):
3584 r = self.root_logger
3585 h = RecordingHandler()
3586 r.addHandler(h)
3587 try:
3588 raise RuntimeError('deliberate mistake')
3589 except:
3590 logging.exception('failed', stack_info=True)
3591 r.removeHandler(h)
3592 h.close()
3593 r = h.records[0]
3594 self.assertTrue(r.exc_text.startswith('Traceback (most recent '
3595 'call last):\n'))
3596 self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
3597 'deliberate mistake'))
3598 self.assertTrue(r.stack_info.startswith('Stack (most recent '
3599 'call last):\n'))
3600 self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
3601 'stack_info=True)'))
3602
3603
Vinay Sajip5a27d402010-12-10 11:42:57 +00003604class LastResortTest(BaseTest):
3605 def test_last_resort(self):
Vinay Sajip60b4df12010-12-27 11:18:52 +00003606 # Test the last resort handler
Vinay Sajip5a27d402010-12-10 11:42:57 +00003607 root = self.root_logger
3608 root.removeHandler(self.root_hdlr)
Vinay Sajip5a27d402010-12-10 11:42:57 +00003609 old_lastresort = logging.lastResort
3610 old_raise_exceptions = logging.raiseExceptions
Vinay Sajip1feedb42014-05-31 08:19:12 +01003611
Vinay Sajip5a27d402010-12-10 11:42:57 +00003612 try:
Vinay Sajip1feedb42014-05-31 08:19:12 +01003613 with support.captured_stderr() as stderr:
3614 root.debug('This should not appear')
3615 self.assertEqual(stderr.getvalue(), '')
3616 root.warning('Final chance!')
3617 self.assertEqual(stderr.getvalue(), 'Final chance!\n')
3618
3619 # No handlers and no last resort, so 'No handlers' message
Vinay Sajip5a27d402010-12-10 11:42:57 +00003620 logging.lastResort = None
Vinay Sajip1feedb42014-05-31 08:19:12 +01003621 with support.captured_stderr() as stderr:
3622 root.warning('Final chance!')
3623 msg = 'No handlers could be found for logger "root"\n'
3624 self.assertEqual(stderr.getvalue(), msg)
3625
Vinay Sajip5a27d402010-12-10 11:42:57 +00003626 # 'No handlers' message only printed once
Vinay Sajip1feedb42014-05-31 08:19:12 +01003627 with support.captured_stderr() as stderr:
3628 root.warning('Final chance!')
3629 self.assertEqual(stderr.getvalue(), '')
3630
3631 # If raiseExceptions is False, no message is printed
Vinay Sajip5a27d402010-12-10 11:42:57 +00003632 root.manager.emittedNoHandlerWarning = False
Vinay Sajip5a27d402010-12-10 11:42:57 +00003633 logging.raiseExceptions = False
Vinay Sajip1feedb42014-05-31 08:19:12 +01003634 with support.captured_stderr() as stderr:
3635 root.warning('Final chance!')
3636 self.assertEqual(stderr.getvalue(), '')
Vinay Sajip5a27d402010-12-10 11:42:57 +00003637 finally:
Vinay Sajip5a27d402010-12-10 11:42:57 +00003638 root.addHandler(self.root_hdlr)
3639 logging.lastResort = old_lastresort
3640 logging.raiseExceptions = old_raise_exceptions
3641
3642
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003643class FakeHandler:
3644
3645 def __init__(self, identifier, called):
3646 for method in ('acquire', 'flush', 'close', 'release'):
3647 setattr(self, method, self.record_call(identifier, method, called))
3648
3649 def record_call(self, identifier, method_name, called):
3650 def inner():
3651 called.append('{} - {}'.format(identifier, method_name))
3652 return inner
3653
3654
3655class RecordingHandler(logging.NullHandler):
3656
3657 def __init__(self, *args, **kwargs):
3658 super(RecordingHandler, self).__init__(*args, **kwargs)
3659 self.records = []
3660
3661 def handle(self, record):
3662 """Keep track of all the emitted records."""
3663 self.records.append(record)
3664
3665
3666class ShutdownTest(BaseTest):
3667
Vinay Sajip5e66b162011-04-20 15:41:14 +01003668 """Test suite for the shutdown method."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003669
3670 def setUp(self):
3671 super(ShutdownTest, self).setUp()
3672 self.called = []
3673
3674 raise_exceptions = logging.raiseExceptions
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003675 self.addCleanup(setattr, logging, 'raiseExceptions', raise_exceptions)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003676
3677 def raise_error(self, error):
3678 def inner():
3679 raise error()
3680 return inner
3681
3682 def test_no_failure(self):
3683 # create some fake handlers
3684 handler0 = FakeHandler(0, self.called)
3685 handler1 = FakeHandler(1, self.called)
3686 handler2 = FakeHandler(2, self.called)
3687
3688 # create live weakref to those handlers
3689 handlers = map(logging.weakref.ref, [handler0, handler1, handler2])
3690
3691 logging.shutdown(handlerList=list(handlers))
3692
3693 expected = ['2 - acquire', '2 - flush', '2 - close', '2 - release',
3694 '1 - acquire', '1 - flush', '1 - close', '1 - release',
3695 '0 - acquire', '0 - flush', '0 - close', '0 - release']
3696 self.assertEqual(expected, self.called)
3697
3698 def _test_with_failure_in_method(self, method, error):
3699 handler = FakeHandler(0, self.called)
3700 setattr(handler, method, self.raise_error(error))
3701 handlers = [logging.weakref.ref(handler)]
3702
3703 logging.shutdown(handlerList=list(handlers))
3704
3705 self.assertEqual('0 - release', self.called[-1])
3706
3707 def test_with_ioerror_in_acquire(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02003708 self._test_with_failure_in_method('acquire', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003709
3710 def test_with_ioerror_in_flush(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02003711 self._test_with_failure_in_method('flush', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003712
3713 def test_with_ioerror_in_close(self):
Andrew Svetlovf7a17b42012-12-25 16:47:37 +02003714 self._test_with_failure_in_method('close', OSError)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003715
3716 def test_with_valueerror_in_acquire(self):
3717 self._test_with_failure_in_method('acquire', ValueError)
3718
3719 def test_with_valueerror_in_flush(self):
3720 self._test_with_failure_in_method('flush', ValueError)
3721
3722 def test_with_valueerror_in_close(self):
3723 self._test_with_failure_in_method('close', ValueError)
3724
3725 def test_with_other_error_in_acquire_without_raise(self):
3726 logging.raiseExceptions = False
3727 self._test_with_failure_in_method('acquire', IndexError)
3728
3729 def test_with_other_error_in_flush_without_raise(self):
3730 logging.raiseExceptions = False
3731 self._test_with_failure_in_method('flush', IndexError)
3732
3733 def test_with_other_error_in_close_without_raise(self):
3734 logging.raiseExceptions = False
3735 self._test_with_failure_in_method('close', IndexError)
3736
3737 def test_with_other_error_in_acquire_with_raise(self):
3738 logging.raiseExceptions = True
3739 self.assertRaises(IndexError, self._test_with_failure_in_method,
3740 'acquire', IndexError)
3741
3742 def test_with_other_error_in_flush_with_raise(self):
3743 logging.raiseExceptions = True
3744 self.assertRaises(IndexError, self._test_with_failure_in_method,
3745 'flush', IndexError)
3746
3747 def test_with_other_error_in_close_with_raise(self):
3748 logging.raiseExceptions = True
3749 self.assertRaises(IndexError, self._test_with_failure_in_method,
3750 'close', IndexError)
3751
3752
3753class ModuleLevelMiscTest(BaseTest):
3754
Vinay Sajip5e66b162011-04-20 15:41:14 +01003755 """Test suite for some module level methods."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003756
3757 def test_disable(self):
3758 old_disable = logging.root.manager.disable
3759 # confirm our assumptions are correct
Vinay Sajip5056c8c2011-06-05 09:31:34 +01003760 self.assertEqual(old_disable, 0)
3761 self.addCleanup(logging.disable, old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003762
3763 logging.disable(83)
3764 self.assertEqual(logging.root.manager.disable, 83)
3765
Vinay Sajipd489ac92016-12-31 11:40:11 +00003766 # test the default value introduced in 3.7
3767 # (Issue #28524)
3768 logging.disable()
3769 self.assertEqual(logging.root.manager.disable, logging.CRITICAL)
3770
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003771 def _test_log(self, method, level=None):
3772 called = []
Vinay Sajip1feedb42014-05-31 08:19:12 +01003773 support.patch(self, logging, 'basicConfig',
3774 lambda *a, **kw: called.append((a, kw)))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003775
3776 recording = RecordingHandler()
3777 logging.root.addHandler(recording)
3778
3779 log_method = getattr(logging, method)
3780 if level is not None:
3781 log_method(level, "test me: %r", recording)
3782 else:
3783 log_method("test me: %r", recording)
3784
3785 self.assertEqual(len(recording.records), 1)
3786 record = recording.records[0]
3787 self.assertEqual(record.getMessage(), "test me: %r" % recording)
3788
3789 expected_level = level if level is not None else getattr(logging, method.upper())
3790 self.assertEqual(record.levelno, expected_level)
3791
3792 # basicConfig was not called!
3793 self.assertEqual(called, [])
3794
3795 def test_log(self):
3796 self._test_log('log', logging.ERROR)
3797
3798 def test_debug(self):
3799 self._test_log('debug')
3800
3801 def test_info(self):
3802 self._test_log('info')
3803
3804 def test_warning(self):
3805 self._test_log('warning')
3806
3807 def test_error(self):
3808 self._test_log('error')
3809
3810 def test_critical(self):
3811 self._test_log('critical')
3812
3813 def test_set_logger_class(self):
3814 self.assertRaises(TypeError, logging.setLoggerClass, object)
3815
3816 class MyLogger(logging.Logger):
3817 pass
3818
3819 logging.setLoggerClass(MyLogger)
3820 self.assertEqual(logging.getLoggerClass(), MyLogger)
3821
3822 logging.setLoggerClass(logging.Logger)
3823 self.assertEqual(logging.getLoggerClass(), logging.Logger)
3824
Serhiy Storchakaa7930372016-07-03 22:27:26 +03003825 @support.requires_type_collecting
Antoine Pitrou712cb732013-12-21 15:51:54 +01003826 def test_logging_at_shutdown(self):
3827 # Issue #20037
3828 code = """if 1:
3829 import logging
3830
3831 class A:
3832 def __del__(self):
3833 try:
3834 raise ValueError("some error")
3835 except Exception:
3836 logging.exception("exception in __del__")
3837
3838 a = A()"""
3839 rc, out, err = assert_python_ok("-c", code)
3840 err = err.decode()
3841 self.assertIn("exception in __del__", err)
3842 self.assertIn("ValueError: some error", err)
3843
Miss Islington (bot)6a7a9f12019-03-18 07:22:41 -07003844 def test_recursion_error(self):
3845 # Issue 36272
3846 code = """if 1:
3847 import logging
3848
3849 def rec():
3850 logging.error("foo")
3851 rec()
3852
3853 rec()"""
3854 rc, out, err = assert_python_failure("-c", code)
3855 err = err.decode()
3856 self.assertNotIn("Cannot recover from stack overflow.", err)
3857 self.assertEqual(rc, 1)
3858
Antoine Pitrou712cb732013-12-21 15:51:54 +01003859
Vinay Sajip26fe4b72011-04-26 18:43:05 +01003860class LogRecordTest(BaseTest):
3861 def test_str_rep(self):
3862 r = logging.makeLogRecord({})
3863 s = str(r)
3864 self.assertTrue(s.startswith('<LogRecord: '))
3865 self.assertTrue(s.endswith('>'))
3866
3867 def test_dict_arg(self):
3868 h = RecordingHandler()
3869 r = logging.getLogger()
3870 r.addHandler(h)
3871 d = {'less' : 'more' }
3872 logging.warning('less is %(less)s', d)
3873 self.assertIs(h.records[0].args, d)
3874 self.assertEqual(h.records[0].message, 'less is more')
3875 r.removeHandler(h)
3876 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003877
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003878 def test_multiprocessing(self):
3879 r = logging.makeLogRecord({})
3880 self.assertEqual(r.processName, 'MainProcess')
Vinay Sajipbd3d5cf2011-05-17 07:41:18 +01003881 try:
3882 import multiprocessing as mp
3883 r = logging.makeLogRecord({})
3884 self.assertEqual(r.processName, mp.current_process().name)
3885 except ImportError:
3886 pass
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003887
3888 def test_optional(self):
3889 r = logging.makeLogRecord({})
3890 NOT_NONE = self.assertIsNotNone
Antoine Pitroua6a4dc82017-09-07 18:56:24 +02003891 NOT_NONE(r.thread)
3892 NOT_NONE(r.threadName)
Vinay Sajip7fe1d512011-04-28 12:04:58 +01003893 NOT_NONE(r.process)
3894 NOT_NONE(r.processName)
3895 log_threads = logging.logThreads
3896 log_processes = logging.logProcesses
3897 log_multiprocessing = logging.logMultiprocessing
3898 try:
3899 logging.logThreads = False
3900 logging.logProcesses = False
3901 logging.logMultiprocessing = False
3902 r = logging.makeLogRecord({})
3903 NONE = self.assertIsNone
3904 NONE(r.thread)
3905 NONE(r.threadName)
3906 NONE(r.process)
3907 NONE(r.processName)
3908 finally:
3909 logging.logThreads = log_threads
3910 logging.logProcesses = log_processes
3911 logging.logMultiprocessing = log_multiprocessing
3912
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003913class BasicConfigTest(unittest.TestCase):
3914
Vinay Sajip95bf5042011-04-20 11:50:56 +01003915 """Test suite for logging.basicConfig."""
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003916
3917 def setUp(self):
3918 super(BasicConfigTest, self).setUp()
Vinay Sajip3def7e02011-04-20 10:58:06 +01003919 self.handlers = logging.root.handlers
Vinay Sajip95bf5042011-04-20 11:50:56 +01003920 self.saved_handlers = logging._handlers.copy()
3921 self.saved_handler_list = logging._handlerList[:]
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003922 self.original_logging_level = logging.root.level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003923 self.addCleanup(self.cleanup)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003924 logging.root.handlers = []
3925
3926 def tearDown(self):
Vinay Sajip3def7e02011-04-20 10:58:06 +01003927 for h in logging.root.handlers[:]:
3928 logging.root.removeHandler(h)
3929 h.close()
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003930 super(BasicConfigTest, self).tearDown()
3931
Vinay Sajip3def7e02011-04-20 10:58:06 +01003932 def cleanup(self):
3933 setattr(logging.root, 'handlers', self.handlers)
Vinay Sajip95bf5042011-04-20 11:50:56 +01003934 logging._handlers.clear()
3935 logging._handlers.update(self.saved_handlers)
3936 logging._handlerList[:] = self.saved_handler_list
Vinay Sajip1e42f9e2011-04-20 12:20:44 +01003937 logging.root.level = self.original_logging_level
Vinay Sajip3def7e02011-04-20 10:58:06 +01003938
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003939 def test_no_kwargs(self):
3940 logging.basicConfig()
3941
3942 # handler defaults to a StreamHandler to sys.stderr
3943 self.assertEqual(len(logging.root.handlers), 1)
3944 handler = logging.root.handlers[0]
3945 self.assertIsInstance(handler, logging.StreamHandler)
3946 self.assertEqual(handler.stream, sys.stderr)
3947
3948 formatter = handler.formatter
3949 # format defaults to logging.BASIC_FORMAT
3950 self.assertEqual(formatter._style._fmt, logging.BASIC_FORMAT)
3951 # datefmt defaults to None
3952 self.assertIsNone(formatter.datefmt)
3953 # style defaults to %
3954 self.assertIsInstance(formatter._style, logging.PercentStyle)
3955
Florent Xiclunae41f0de2011-11-11 19:39:25 +01003956 # level is not explicitly set
Vinay Sajip5b9eecf2011-04-20 12:50:42 +01003957 self.assertEqual(logging.root.level, self.original_logging_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003958
Vinay Sajip1fd12022014-01-13 21:59:56 +00003959 def test_strformatstyle(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003960 with support.captured_stdout() as output:
Vinay Sajip1fd12022014-01-13 21:59:56 +00003961 logging.basicConfig(stream=sys.stdout, style="{")
3962 logging.error("Log an error")
3963 sys.stdout.seek(0)
3964 self.assertEqual(output.getvalue().strip(),
3965 "ERROR:root:Log an error")
3966
3967 def test_stringtemplatestyle(self):
Vinay Sajip1feedb42014-05-31 08:19:12 +01003968 with support.captured_stdout() as output:
Vinay Sajip1fd12022014-01-13 21:59:56 +00003969 logging.basicConfig(stream=sys.stdout, style="$")
3970 logging.error("Log an error")
3971 sys.stdout.seek(0)
3972 self.assertEqual(output.getvalue().strip(),
3973 "ERROR:root:Log an error")
3974
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003975 def test_filename(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00003976
3977 def cleanup(h1, h2, fn):
3978 h1.close()
3979 h2.close()
3980 os.remove(fn)
3981
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003982 logging.basicConfig(filename='test.log')
3983
3984 self.assertEqual(len(logging.root.handlers), 1)
3985 handler = logging.root.handlers[0]
3986 self.assertIsInstance(handler, logging.FileHandler)
3987
3988 expected = logging.FileHandler('test.log', 'a')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003989 self.assertEqual(handler.stream.mode, expected.stream.mode)
3990 self.assertEqual(handler.stream.name, expected.stream.name)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00003991 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01003992
3993 def test_filemode(self):
Vinay Sajipbecf5c62013-03-08 09:50:57 +00003994
3995 def cleanup(h1, h2, fn):
3996 h1.close()
3997 h2.close()
3998 os.remove(fn)
3999
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004000 logging.basicConfig(filename='test.log', filemode='wb')
4001
4002 handler = logging.root.handlers[0]
4003 expected = logging.FileHandler('test.log', 'wb')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004004 self.assertEqual(handler.stream.mode, expected.stream.mode)
Vinay Sajipbecf5c62013-03-08 09:50:57 +00004005 self.addCleanup(cleanup, handler, expected, 'test.log')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004006
4007 def test_stream(self):
4008 stream = io.StringIO()
4009 self.addCleanup(stream.close)
4010 logging.basicConfig(stream=stream)
4011
4012 self.assertEqual(len(logging.root.handlers), 1)
4013 handler = logging.root.handlers[0]
4014 self.assertIsInstance(handler, logging.StreamHandler)
4015 self.assertEqual(handler.stream, stream)
4016
4017 def test_format(self):
4018 logging.basicConfig(format='foo')
4019
4020 formatter = logging.root.handlers[0].formatter
4021 self.assertEqual(formatter._style._fmt, 'foo')
4022
4023 def test_datefmt(self):
4024 logging.basicConfig(datefmt='bar')
4025
4026 formatter = logging.root.handlers[0].formatter
4027 self.assertEqual(formatter.datefmt, 'bar')
4028
4029 def test_style(self):
4030 logging.basicConfig(style='$')
4031
4032 formatter = logging.root.handlers[0].formatter
4033 self.assertIsInstance(formatter._style, logging.StringTemplateStyle)
4034
4035 def test_level(self):
4036 old_level = logging.root.level
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004037 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004038
4039 logging.basicConfig(level=57)
4040 self.assertEqual(logging.root.level, 57)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004041 # Test that second call has no effect
4042 logging.basicConfig(level=58)
4043 self.assertEqual(logging.root.level, 57)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004044
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004045 def test_incompatible(self):
4046 assertRaises = self.assertRaises
4047 handlers = [logging.StreamHandler()]
4048 stream = sys.stderr
4049 assertRaises(ValueError, logging.basicConfig, filename='test.log',
4050 stream=stream)
4051 assertRaises(ValueError, logging.basicConfig, filename='test.log',
4052 handlers=handlers)
4053 assertRaises(ValueError, logging.basicConfig, stream=stream,
4054 handlers=handlers)
Vinay Sajipd55436a2015-03-18 08:47:58 +00004055 # Issue 23207: test for invalid kwargs
4056 assertRaises(ValueError, logging.basicConfig, loglevel=logging.INFO)
4057 # Should pop both filename and filemode even if filename is None
4058 logging.basicConfig(filename=None, filemode='a')
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004059
4060 def test_handlers(self):
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004061 handlers = [
4062 logging.StreamHandler(),
4063 logging.StreamHandler(sys.stdout),
4064 logging.StreamHandler(),
4065 ]
4066 f = logging.Formatter()
4067 handlers[2].setFormatter(f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004068 logging.basicConfig(handlers=handlers)
4069 self.assertIs(handlers[0], logging.root.handlers[0])
4070 self.assertIs(handlers[1], logging.root.handlers[1])
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004071 self.assertIs(handlers[2], logging.root.handlers[2])
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004072 self.assertIsNotNone(handlers[0].formatter)
4073 self.assertIsNotNone(handlers[1].formatter)
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004074 self.assertIs(handlers[2].formatter, f)
Vinay Sajip4a0a31d2011-04-11 08:42:07 +01004075 self.assertIs(handlers[0].formatter, handlers[1].formatter)
4076
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004077 def _test_log(self, method, level=None):
4078 # logging.root has no handlers so basicConfig should be called
4079 called = []
4080
4081 old_basic_config = logging.basicConfig
4082 def my_basic_config(*a, **kw):
4083 old_basic_config()
4084 old_level = logging.root.level
4085 logging.root.setLevel(100) # avoid having messages in stderr
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004086 self.addCleanup(logging.root.setLevel, old_level)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004087 called.append((a, kw))
4088
Vinay Sajip1feedb42014-05-31 08:19:12 +01004089 support.patch(self, logging, 'basicConfig', my_basic_config)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004090
4091 log_method = getattr(logging, method)
4092 if level is not None:
4093 log_method(level, "test me")
4094 else:
4095 log_method("test me")
4096
4097 # basicConfig was called with no arguments
4098 self.assertEqual(called, [((), {})])
4099
4100 def test_log(self):
4101 self._test_log('log', logging.WARNING)
4102
4103 def test_debug(self):
4104 self._test_log('debug')
4105
4106 def test_info(self):
4107 self._test_log('info')
4108
4109 def test_warning(self):
4110 self._test_log('warning')
4111
4112 def test_error(self):
4113 self._test_log('error')
4114
4115 def test_critical(self):
4116 self._test_log('critical')
4117
4118
4119class LoggerAdapterTest(unittest.TestCase):
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004120 def setUp(self):
4121 super(LoggerAdapterTest, self).setUp()
4122 old_handler_list = logging._handlerList[:]
4123
4124 self.recording = RecordingHandler()
4125 self.logger = logging.root
4126 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004127 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004128 self.addCleanup(self.recording.close)
4129
4130 def cleanup():
4131 logging._handlerList[:] = old_handler_list
4132
4133 self.addCleanup(cleanup)
4134 self.addCleanup(logging.shutdown)
4135 self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
4136
4137 def test_exception(self):
4138 msg = 'testing exception: %r'
4139 exc = None
4140 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004141 1 / 0
4142 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004143 exc = e
4144 self.adapter.exception(msg, self.recording)
4145
4146 self.assertEqual(len(self.recording.records), 1)
4147 record = self.recording.records[0]
4148 self.assertEqual(record.levelno, logging.ERROR)
4149 self.assertEqual(record.msg, msg)
4150 self.assertEqual(record.args, (self.recording,))
4151 self.assertEqual(record.exc_info,
4152 (exc.__class__, exc, exc.__traceback__))
4153
Vinay Sajip02a8f9e2014-09-14 21:29:11 +01004154 def test_exception_excinfo(self):
4155 try:
4156 1 / 0
4157 except ZeroDivisionError as e:
4158 exc = e
4159
4160 self.adapter.exception('exc_info test', exc_info=exc)
4161
4162 self.assertEqual(len(self.recording.records), 1)
4163 record = self.recording.records[0]
4164 self.assertEqual(record.exc_info,
4165 (exc.__class__, exc, exc.__traceback__))
4166
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004167 def test_critical(self):
4168 msg = 'critical test! %r'
4169 self.adapter.critical(msg, self.recording)
4170
4171 self.assertEqual(len(self.recording.records), 1)
4172 record = self.recording.records[0]
4173 self.assertEqual(record.levelno, logging.CRITICAL)
4174 self.assertEqual(record.msg, msg)
4175 self.assertEqual(record.args, (self.recording,))
4176
4177 def test_is_enabled_for(self):
4178 old_disable = self.adapter.logger.manager.disable
4179 self.adapter.logger.manager.disable = 33
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004180 self.addCleanup(setattr, self.adapter.logger.manager, 'disable',
4181 old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004182 self.assertFalse(self.adapter.isEnabledFor(32))
4183
4184 def test_has_handlers(self):
4185 self.assertTrue(self.adapter.hasHandlers())
4186
4187 for handler in self.logger.handlers:
4188 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004189
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004190 self.assertFalse(self.logger.hasHandlers())
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004191 self.assertFalse(self.adapter.hasHandlers())
4192
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004193 def test_nested(self):
Łukasz Langace9e6252017-10-19 10:24:55 -07004194 class Adapter(logging.LoggerAdapter):
4195 prefix = 'Adapter'
4196
4197 def process(self, msg, kwargs):
4198 return f"{self.prefix} {msg}", kwargs
4199
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004200 msg = 'Adapters can be nested, yo.'
Łukasz Langace9e6252017-10-19 10:24:55 -07004201 adapter = Adapter(logger=self.logger, extra=None)
4202 adapter_adapter = Adapter(logger=adapter, extra=None)
4203 adapter_adapter.prefix = 'AdapterAdapter'
4204 self.assertEqual(repr(adapter), repr(adapter_adapter))
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004205 adapter_adapter.log(logging.CRITICAL, msg, self.recording)
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004206 self.assertEqual(len(self.recording.records), 1)
4207 record = self.recording.records[0]
4208 self.assertEqual(record.levelno, logging.CRITICAL)
Łukasz Langace9e6252017-10-19 10:24:55 -07004209 self.assertEqual(record.msg, f"Adapter AdapterAdapter {msg}")
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004210 self.assertEqual(record.args, (self.recording,))
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004211 orig_manager = adapter_adapter.manager
Łukasz Langace9e6252017-10-19 10:24:55 -07004212 self.assertIs(adapter.manager, orig_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004213 self.assertIs(self.logger.manager, orig_manager)
4214 temp_manager = object()
4215 try:
4216 adapter_adapter.manager = temp_manager
4217 self.assertIs(adapter_adapter.manager, temp_manager)
Łukasz Langace9e6252017-10-19 10:24:55 -07004218 self.assertIs(adapter.manager, temp_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004219 self.assertIs(self.logger.manager, temp_manager)
4220 finally:
4221 adapter_adapter.manager = orig_manager
4222 self.assertIs(adapter_adapter.manager, orig_manager)
Łukasz Langace9e6252017-10-19 10:24:55 -07004223 self.assertIs(adapter.manager, orig_manager)
Łukasz Langa0b6a1182017-10-18 17:28:51 -07004224 self.assertIs(self.logger.manager, orig_manager)
Łukasz Langa1bbd4822017-09-14 11:34:47 -04004225
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004226
4227class LoggerTest(BaseTest):
4228
4229 def setUp(self):
4230 super(LoggerTest, self).setUp()
4231 self.recording = RecordingHandler()
4232 self.logger = logging.Logger(name='blah')
4233 self.logger.addHandler(self.recording)
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004234 self.addCleanup(self.logger.removeHandler, self.recording)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004235 self.addCleanup(self.recording.close)
4236 self.addCleanup(logging.shutdown)
4237
4238 def test_set_invalid_level(self):
4239 self.assertRaises(TypeError, self.logger.setLevel, object())
4240
4241 def test_exception(self):
4242 msg = 'testing exception: %r'
4243 exc = None
4244 try:
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004245 1 / 0
4246 except ZeroDivisionError as e:
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004247 exc = e
4248 self.logger.exception(msg, self.recording)
4249
4250 self.assertEqual(len(self.recording.records), 1)
4251 record = self.recording.records[0]
4252 self.assertEqual(record.levelno, logging.ERROR)
4253 self.assertEqual(record.msg, msg)
4254 self.assertEqual(record.args, (self.recording,))
4255 self.assertEqual(record.exc_info,
4256 (exc.__class__, exc, exc.__traceback__))
4257
4258 def test_log_invalid_level_with_raise(self):
Serhiy Storchaka296b3472015-07-21 22:40:18 +03004259 with support.swap_attr(logging, 'raiseExceptions', True):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03004260 self.assertRaises(TypeError, self.logger.log, '10', 'test message')
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004261
4262 def test_log_invalid_level_no_raise(self):
Serhiy Storchaka296b3472015-07-21 22:40:18 +03004263 with support.swap_attr(logging, 'raiseExceptions', False):
Serhiy Storchaka750eae12015-07-21 22:39:26 +03004264 self.logger.log('10', 'test message') # no exception happens
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004265
4266 def test_find_caller_with_stack_info(self):
4267 called = []
Vinay Sajip1feedb42014-05-31 08:19:12 +01004268 support.patch(self, logging.traceback, 'print_stack',
4269 lambda f, file: called.append(file.getvalue()))
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004270
4271 self.logger.findCaller(stack_info=True)
4272
4273 self.assertEqual(len(called), 1)
4274 self.assertEqual('Stack (most recent call last):\n', called[0])
4275
4276 def test_make_record_with_extra_overwrite(self):
4277 name = 'my record'
4278 level = 13
4279 fn = lno = msg = args = exc_info = func = sinfo = None
4280 rv = logging._logRecordFactory(name, level, fn, lno, msg, args,
4281 exc_info, func, sinfo)
4282
4283 for key in ('message', 'asctime') + tuple(rv.__dict__.keys()):
4284 extra = {key: 'some value'}
4285 self.assertRaises(KeyError, self.logger.makeRecord, name, level,
4286 fn, lno, msg, args, exc_info,
4287 extra=extra, sinfo=sinfo)
4288
4289 def test_make_record_with_extra_no_overwrite(self):
4290 name = 'my record'
4291 level = 13
4292 fn = lno = msg = args = exc_info = func = sinfo = None
4293 extra = {'valid_key': 'some value'}
4294 result = self.logger.makeRecord(name, level, fn, lno, msg, args,
4295 exc_info, extra=extra, sinfo=sinfo)
4296 self.assertIn('valid_key', result.__dict__)
4297
4298 def test_has_handlers(self):
4299 self.assertTrue(self.logger.hasHandlers())
4300
4301 for handler in self.logger.handlers:
4302 self.logger.removeHandler(handler)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004303 self.assertFalse(self.logger.hasHandlers())
4304
4305 def test_has_handlers_no_propagate(self):
4306 child_logger = logging.getLogger('blah.child')
4307 child_logger.propagate = False
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004308 self.assertFalse(child_logger.hasHandlers())
4309
4310 def test_is_enabled_for(self):
4311 old_disable = self.logger.manager.disable
4312 self.logger.manager.disable = 23
Vinay Sajip5056c8c2011-06-05 09:31:34 +01004313 self.addCleanup(setattr, self.logger.manager, 'disable', old_disable)
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004314 self.assertFalse(self.logger.isEnabledFor(22))
4315
Florent Xicluna5252f9f2011-11-07 19:43:05 +01004316 def test_root_logger_aliases(self):
4317 root = logging.getLogger()
4318 self.assertIs(root, logging.root)
4319 self.assertIs(root, logging.getLogger(None))
4320 self.assertIs(root, logging.getLogger(''))
4321 self.assertIs(root, logging.getLogger('foo').root)
4322 self.assertIs(root, logging.getLogger('foo.bar').root)
4323 self.assertIs(root, logging.getLogger('foo').parent)
4324
4325 self.assertIsNot(root, logging.getLogger('\0'))
4326 self.assertIsNot(root, logging.getLogger('foo.bar').parent)
4327
4328 def test_invalid_names(self):
4329 self.assertRaises(TypeError, logging.getLogger, any)
4330 self.assertRaises(TypeError, logging.getLogger, b'foo')
4331
Vinay Sajip6260d9f2017-06-06 16:34:29 +01004332 def test_pickling(self):
4333 for proto in range(pickle.HIGHEST_PROTOCOL + 1):
4334 for name in ('', 'root', 'foo', 'foo.bar', 'baz.bar'):
4335 logger = logging.getLogger(name)
4336 s = pickle.dumps(logger, proto)
4337 unpickled = pickle.loads(s)
4338 self.assertIs(unpickled, logger)
4339
Avram Lubkin78c18a92017-07-30 05:36:33 -04004340 def test_caching(self):
4341 root = self.root_logger
4342 logger1 = logging.getLogger("abc")
4343 logger2 = logging.getLogger("abc.def")
4344
4345 # Set root logger level and ensure cache is empty
4346 root.setLevel(logging.ERROR)
4347 self.assertEqual(logger2.getEffectiveLevel(), logging.ERROR)
4348 self.assertEqual(logger2._cache, {})
4349
4350 # Ensure cache is populated and calls are consistent
4351 self.assertTrue(logger2.isEnabledFor(logging.ERROR))
4352 self.assertFalse(logger2.isEnabledFor(logging.DEBUG))
4353 self.assertEqual(logger2._cache, {logging.ERROR: True, logging.DEBUG: False})
4354 self.assertEqual(root._cache, {})
4355 self.assertTrue(logger2.isEnabledFor(logging.ERROR))
4356
4357 # Ensure root cache gets populated
4358 self.assertEqual(root._cache, {})
4359 self.assertTrue(root.isEnabledFor(logging.ERROR))
4360 self.assertEqual(root._cache, {logging.ERROR: True})
4361
4362 # Set parent logger level and ensure caches are emptied
4363 logger1.setLevel(logging.CRITICAL)
4364 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
4365 self.assertEqual(logger2._cache, {})
4366
4367 # Ensure logger2 uses parent logger's effective level
4368 self.assertFalse(logger2.isEnabledFor(logging.ERROR))
4369
4370 # Set level to NOTSET and ensure caches are empty
4371 logger2.setLevel(logging.NOTSET)
4372 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
4373 self.assertEqual(logger2._cache, {})
4374 self.assertEqual(logger1._cache, {})
4375 self.assertEqual(root._cache, {})
4376
4377 # Verify logger2 follows parent and not root
4378 self.assertFalse(logger2.isEnabledFor(logging.ERROR))
4379 self.assertTrue(logger2.isEnabledFor(logging.CRITICAL))
4380 self.assertFalse(logger1.isEnabledFor(logging.ERROR))
4381 self.assertTrue(logger1.isEnabledFor(logging.CRITICAL))
4382 self.assertTrue(root.isEnabledFor(logging.ERROR))
4383
4384 # Disable logging in manager and ensure caches are clear
4385 logging.disable()
4386 self.assertEqual(logger2.getEffectiveLevel(), logging.CRITICAL)
4387 self.assertEqual(logger2._cache, {})
4388 self.assertEqual(logger1._cache, {})
4389 self.assertEqual(root._cache, {})
4390
4391 # Ensure no loggers are enabled
4392 self.assertFalse(logger1.isEnabledFor(logging.CRITICAL))
4393 self.assertFalse(logger2.isEnabledFor(logging.CRITICAL))
4394 self.assertFalse(root.isEnabledFor(logging.CRITICAL))
4395
Vinay Sajipe6c1eb92011-03-29 17:20:34 +01004396
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004397class BaseFileTest(BaseTest):
4398 "Base class for handler tests that write log files"
4399
4400 def setUp(self):
4401 BaseTest.setUp(self)
Vinay Sajip60b4df12010-12-27 11:18:52 +00004402 fd, self.fn = tempfile.mkstemp(".log", "test_logging-2-")
4403 os.close(fd)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004404 self.rmfiles = []
4405
4406 def tearDown(self):
4407 for fn in self.rmfiles:
4408 os.unlink(fn)
Vinay Sajip60b4df12010-12-27 11:18:52 +00004409 if os.path.exists(self.fn):
4410 os.unlink(self.fn)
Hirokazu Yamamoto2cdacd72010-09-18 03:54:32 +00004411 BaseTest.tearDown(self)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004412
4413 def assertLogFile(self, filename):
4414 "Assert a log file is there and register it for deletion"
4415 self.assertTrue(os.path.exists(filename),
Vinay Sajip7367d082011-05-02 13:17:27 +01004416 msg="Log file %r does not exist" % filename)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004417 self.rmfiles.append(filename)
4418
4419
Vinay Sajip26fe4b72011-04-26 18:43:05 +01004420class FileHandlerTest(BaseFileTest):
4421 def test_delay(self):
4422 os.unlink(self.fn)
4423 fh = logging.FileHandler(self.fn, delay=True)
4424 self.assertIsNone(fh.stream)
4425 self.assertFalse(os.path.exists(self.fn))
4426 fh.handle(logging.makeLogRecord({}))
4427 self.assertIsNotNone(fh.stream)
4428 self.assertTrue(os.path.exists(self.fn))
4429 fh.close()
4430
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004431class RotatingFileHandlerTest(BaseFileTest):
4432 def next_rec(self):
4433 return logging.LogRecord('n', logging.DEBUG, 'p', 1,
4434 self.next_message(), None, None, None)
4435
4436 def test_should_not_rollover(self):
4437 # If maxbytes is zero rollover never occurs
4438 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=0)
4439 self.assertFalse(rh.shouldRollover(None))
Vinay Sajipb046b802010-10-30 09:50:18 +00004440 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004441
4442 def test_should_rollover(self):
4443 rh = logging.handlers.RotatingFileHandler(self.fn, maxBytes=1)
4444 self.assertTrue(rh.shouldRollover(self.next_rec()))
Vinay Sajipb046b802010-10-30 09:50:18 +00004445 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004446
4447 def test_file_created(self):
4448 # checks that the file is created and assumes it was created
4449 # by us
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004450 rh = logging.handlers.RotatingFileHandler(self.fn)
4451 rh.emit(self.next_rec())
4452 self.assertLogFile(self.fn)
Vinay Sajipb046b802010-10-30 09:50:18 +00004453 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004454
4455 def test_rollover_filenames(self):
Vinay Sajip23b94d02012-01-04 12:02:26 +00004456 def namer(name):
4457 return name + ".test"
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004458 rh = logging.handlers.RotatingFileHandler(
4459 self.fn, backupCount=2, maxBytes=1)
Vinay Sajip23b94d02012-01-04 12:02:26 +00004460 rh.namer = namer
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004461 rh.emit(self.next_rec())
4462 self.assertLogFile(self.fn)
4463 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00004464 self.assertLogFile(namer(self.fn + ".1"))
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004465 rh.emit(self.next_rec())
Vinay Sajip23b94d02012-01-04 12:02:26 +00004466 self.assertLogFile(namer(self.fn + ".2"))
4467 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
4468 rh.close()
4469
Vinay Sajip1feedb42014-05-31 08:19:12 +01004470 @support.requires_zlib
Vinay Sajip23b94d02012-01-04 12:02:26 +00004471 def test_rotator(self):
4472 def namer(name):
4473 return name + ".gz"
4474
4475 def rotator(source, dest):
4476 with open(source, "rb") as sf:
4477 data = sf.read()
4478 compressed = zlib.compress(data, 9)
4479 with open(dest, "wb") as df:
4480 df.write(compressed)
4481 os.remove(source)
4482
4483 rh = logging.handlers.RotatingFileHandler(
4484 self.fn, backupCount=2, maxBytes=1)
4485 rh.rotator = rotator
4486 rh.namer = namer
4487 m1 = self.next_rec()
4488 rh.emit(m1)
4489 self.assertLogFile(self.fn)
4490 m2 = self.next_rec()
4491 rh.emit(m2)
4492 fn = namer(self.fn + ".1")
4493 self.assertLogFile(fn)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00004494 newline = os.linesep
Vinay Sajip23b94d02012-01-04 12:02:26 +00004495 with open(fn, "rb") as f:
4496 compressed = f.read()
4497 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00004498 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00004499 rh.emit(self.next_rec())
4500 fn = namer(self.fn + ".2")
4501 self.assertLogFile(fn)
4502 with open(fn, "rb") as f:
4503 compressed = f.read()
4504 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00004505 self.assertEqual(data.decode("ascii"), m1.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00004506 rh.emit(self.next_rec())
4507 fn = namer(self.fn + ".2")
4508 with open(fn, "rb") as f:
4509 compressed = f.read()
4510 data = zlib.decompress(compressed)
Vinay Sajip2c94cdd2012-01-07 23:26:17 +00004511 self.assertEqual(data.decode("ascii"), m2.msg + newline)
Vinay Sajip23b94d02012-01-04 12:02:26 +00004512 self.assertFalse(os.path.exists(namer(self.fn + ".3")))
Vinay Sajipb046b802010-10-30 09:50:18 +00004513 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004514
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004515class TimedRotatingFileHandlerTest(BaseFileTest):
Vinay Sajip7367d082011-05-02 13:17:27 +01004516 # other test methods added below
4517 def test_rollover(self):
Vinay Sajip0372e102011-05-05 12:59:14 +01004518 fh = logging.handlers.TimedRotatingFileHandler(self.fn, 'S',
4519 backupCount=1)
Vinay Sajipb6f66702012-03-05 09:43:47 +00004520 fmt = logging.Formatter('%(asctime)s %(message)s')
4521 fh.setFormatter(fmt)
Vinay Sajip8d217c62012-03-05 12:45:51 +00004522 r1 = logging.makeLogRecord({'msg': 'testing - initial'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00004523 fh.emit(r1)
Vinay Sajipfd285022011-05-07 17:01:22 +01004524 self.assertLogFile(self.fn)
Vinay Sajip8d217c62012-03-05 12:45:51 +00004525 time.sleep(1.1) # a little over a second ...
Vinay Sajipb2fcd3a2012-03-05 20:02:53 +00004526 r2 = logging.makeLogRecord({'msg': 'testing - after delay'})
Vinay Sajip8d217c62012-03-05 12:45:51 +00004527 fh.emit(r2)
Vinay Sajipfd285022011-05-07 17:01:22 +01004528 fh.close()
4529 # At this point, we should have a recent rotated file which we
4530 # can test for the existence of. However, in practice, on some
4531 # machines which run really slowly, we don't know how far back
Vinay Sajip672c5812011-05-13 07:09:40 +01004532 # in time to go to look for the log file. So, we go back a fair
4533 # bit, and stop as soon as we see a rotated file. In theory this
4534 # could of course still fail, but the chances are lower.
Vinay Sajipfd285022011-05-07 17:01:22 +01004535 found = False
4536 now = datetime.datetime.now()
Vinay Sajip252048c2011-05-13 16:41:57 +01004537 GO_BACK = 5 * 60 # seconds
Vinay Sajip672c5812011-05-13 07:09:40 +01004538 for secs in range(GO_BACK):
4539 prev = now - datetime.timedelta(seconds=secs)
Vinay Sajipfd285022011-05-07 17:01:22 +01004540 fn = self.fn + prev.strftime(".%Y-%m-%d_%H-%M-%S")
4541 found = os.path.exists(fn)
4542 if found:
4543 self.rmfiles.append(fn)
4544 break
Vinay Sajip672c5812011-05-13 07:09:40 +01004545 msg = 'No rotated files found, went back %d seconds' % GO_BACK
4546 if not found:
Mike53f7a7c2017-12-14 14:04:53 +03004547 # print additional diagnostics
Vinay Sajipa171f9c2011-05-13 14:45:08 +01004548 dn, fn = os.path.split(self.fn)
4549 files = [f for f in os.listdir(dn) if f.startswith(fn)]
Victor Stinner949c8902011-05-23 01:16:44 +02004550 print('Test time: %s' % now.strftime("%Y-%m-%d %H-%M-%S"), file=sys.stderr)
4551 print('The only matching files are: %s' % files, file=sys.stderr)
Vinay Sajip19b1d502012-02-28 19:02:43 +00004552 for f in files:
4553 print('Contents of %s:' % f)
Vinay Sajipd263d182012-03-03 16:20:37 +00004554 path = os.path.join(dn, f)
4555 with open(path, 'r') as tf:
Vinay Sajip19b1d502012-02-28 19:02:43 +00004556 print(tf.read())
Vinay Sajipfd285022011-05-07 17:01:22 +01004557 self.assertTrue(found, msg=msg)
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004558
Vinay Sajip0372e102011-05-05 12:59:14 +01004559 def test_invalid(self):
4560 assertRaises = self.assertRaises
4561 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01004562 self.fn, 'X', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01004563 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01004564 self.fn, 'W', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01004565 assertRaises(ValueError, logging.handlers.TimedRotatingFileHandler,
Vinay Sajipfd285022011-05-07 17:01:22 +01004566 self.fn, 'W7', delay=True)
Vinay Sajip0372e102011-05-05 12:59:14 +01004567
Vinay Sajipa7130792013-04-12 17:04:23 +01004568 def test_compute_rollover_daily_attime(self):
4569 currentTime = 0
4570 atTime = datetime.time(12, 0, 0)
4571 rh = logging.handlers.TimedRotatingFileHandler(
4572 self.fn, when='MIDNIGHT', interval=1, backupCount=0, utc=True,
4573 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01004574 try:
4575 actual = rh.computeRollover(currentTime)
4576 self.assertEqual(actual, currentTime + 12 * 60 * 60)
Vinay Sajipa7130792013-04-12 17:04:23 +01004577
Vinay Sajipd86ac962013-04-14 12:20:46 +01004578 actual = rh.computeRollover(currentTime + 13 * 60 * 60)
4579 self.assertEqual(actual, currentTime + 36 * 60 * 60)
4580 finally:
4581 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01004582
Vinay Sajip10e8c492013-05-18 10:19:54 -07004583 #@unittest.skipIf(True, 'Temporarily skipped while failures investigated.')
Vinay Sajipa7130792013-04-12 17:04:23 +01004584 def test_compute_rollover_weekly_attime(self):
Vinay Sajipd86ac962013-04-14 12:20:46 +01004585 currentTime = int(time.time())
4586 today = currentTime - currentTime % 86400
4587
Vinay Sajipa7130792013-04-12 17:04:23 +01004588 atTime = datetime.time(12, 0, 0)
4589
Vinay Sajip10e8c492013-05-18 10:19:54 -07004590 wday = time.gmtime(today).tm_wday
Vinay Sajipa7130792013-04-12 17:04:23 +01004591 for day in range(7):
4592 rh = logging.handlers.TimedRotatingFileHandler(
4593 self.fn, when='W%d' % day, interval=1, backupCount=0, utc=True,
4594 atTime=atTime)
Vinay Sajipd86ac962013-04-14 12:20:46 +01004595 try:
4596 if wday > day:
4597 # The rollover day has already passed this week, so we
4598 # go over into next week
4599 expected = (7 - wday + day)
4600 else:
4601 expected = (day - wday)
4602 # At this point expected is in days from now, convert to seconds
4603 expected *= 24 * 60 * 60
4604 # Add in the rollover time
4605 expected += 12 * 60 * 60
4606 # Add in adjustment for today
4607 expected += today
Vinay Sajip66940a12013-04-15 11:59:35 +01004608 actual = rh.computeRollover(today)
4609 if actual != expected:
4610 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01004611 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01004612 self.assertEqual(actual, expected)
4613 if day == wday:
4614 # goes into following week
4615 expected += 7 * 24 * 60 * 60
Vinay Sajip8b4c7192013-04-14 12:25:25 +01004616 actual = rh.computeRollover(today + 13 * 60 * 60)
Vinay Sajip66940a12013-04-15 11:59:35 +01004617 if actual != expected:
4618 print('failed in timezone: %d' % time.timezone)
Vinay Sajipcaf9eb82013-05-12 00:04:58 +01004619 print('local vars: %s' % locals())
Vinay Sajipd86ac962013-04-14 12:20:46 +01004620 self.assertEqual(actual, expected)
4621 finally:
4622 rh.close()
Vinay Sajipa7130792013-04-12 17:04:23 +01004623
4624
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004625def secs(**kw):
4626 return datetime.timedelta(**kw) // datetime.timedelta(seconds=1)
4627
4628for when, exp in (('S', 1),
4629 ('M', 60),
4630 ('H', 60 * 60),
4631 ('D', 60 * 60 * 24),
Vinay Sajiped0473c2011-02-26 15:35:38 +00004632 ('MIDNIGHT', 60 * 60 * 24),
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004633 # current time (epoch start) is a Thursday, W0 means Monday
Vinay Sajiped0473c2011-02-26 15:35:38 +00004634 ('W0', secs(days=4, hours=24)),
4635 ):
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004636 def test_compute_rollover(self, when=when, exp=exp):
4637 rh = logging.handlers.TimedRotatingFileHandler(
Vinay Sajiped0473c2011-02-26 15:35:38 +00004638 self.fn, when=when, interval=1, backupCount=0, utc=True)
4639 currentTime = 0.0
4640 actual = rh.computeRollover(currentTime)
4641 if exp != actual:
4642 # Failures occur on some systems for MIDNIGHT and W0.
4643 # Print detailed calculation for MIDNIGHT so we can try to see
4644 # what's going on
Vinay Sajiped0473c2011-02-26 15:35:38 +00004645 if when == 'MIDNIGHT':
4646 try:
4647 if rh.utc:
4648 t = time.gmtime(currentTime)
4649 else:
4650 t = time.localtime(currentTime)
4651 currentHour = t[3]
4652 currentMinute = t[4]
4653 currentSecond = t[5]
4654 # r is the number of seconds left between now and midnight
4655 r = logging.handlers._MIDNIGHT - ((currentHour * 60 +
4656 currentMinute) * 60 +
4657 currentSecond)
4658 result = currentTime + r
4659 print('t: %s (%s)' % (t, rh.utc), file=sys.stderr)
4660 print('currentHour: %s' % currentHour, file=sys.stderr)
4661 print('currentMinute: %s' % currentMinute, file=sys.stderr)
4662 print('currentSecond: %s' % currentSecond, file=sys.stderr)
4663 print('r: %s' % r, file=sys.stderr)
4664 print('result: %s' % result, file=sys.stderr)
4665 except Exception:
4666 print('exception in diagnostic code: %s' % sys.exc_info()[1], file=sys.stderr)
4667 self.assertEqual(exp, actual)
Vinay Sajipb046b802010-10-30 09:50:18 +00004668 rh.close()
Vinay Sajip19ec67a2010-09-17 18:57:36 +00004669 setattr(TimedRotatingFileHandlerTest, "test_compute_rollover_%s" % when, test_compute_rollover)
4670
Vinay Sajip60ccd822011-05-09 17:32:09 +01004671
Vinay Sajip223349c2015-10-01 20:37:54 +01004672@unittest.skipUnless(win32evtlog, 'win32evtlog/win32evtlogutil/pywintypes required for this test.')
Vinay Sajip60ccd822011-05-09 17:32:09 +01004673class NTEventLogHandlerTest(BaseTest):
4674 def test_basic(self):
4675 logtype = 'Application'
4676 elh = win32evtlog.OpenEventLog(None, logtype)
4677 num_recs = win32evtlog.GetNumberOfEventLogRecords(elh)
Vinay Sajip223349c2015-10-01 20:37:54 +01004678
4679 try:
4680 h = logging.handlers.NTEventLogHandler('test_logging')
4681 except pywintypes.error as e:
Zachary Ware22226c52015-10-06 15:22:13 -05004682 if e.winerror == 5: # access denied
Vinay Sajip223349c2015-10-01 20:37:54 +01004683 raise unittest.SkipTest('Insufficient privileges to run test')
Zachary Ware106ddf02015-10-06 15:28:43 -05004684 raise
Vinay Sajip223349c2015-10-01 20:37:54 +01004685
Vinay Sajip60ccd822011-05-09 17:32:09 +01004686 r = logging.makeLogRecord({'msg': 'Test Log Message'})
4687 h.handle(r)
4688 h.close()
4689 # Now see if the event is recorded
Giampaolo Rodola'284529d2012-10-17 13:24:27 +02004690 self.assertLess(num_recs, win32evtlog.GetNumberOfEventLogRecords(elh))
Vinay Sajip60ccd822011-05-09 17:32:09 +01004691 flags = win32evtlog.EVENTLOG_BACKWARDS_READ | \
4692 win32evtlog.EVENTLOG_SEQUENTIAL_READ
4693 found = False
4694 GO_BACK = 100
4695 events = win32evtlog.ReadEventLog(elh, flags, GO_BACK)
4696 for e in events:
4697 if e.SourceName != 'test_logging':
4698 continue
4699 msg = win32evtlogutil.SafeFormatMessage(e, logtype)
4700 if msg != 'Test Log Message\r\n':
4701 continue
4702 found = True
4703 break
4704 msg = 'Record not found in event log, went back %d records' % GO_BACK
4705 self.assertTrue(found, msg=msg)
4706
Vinay Sajipdb8f4632016-09-08 01:37:03 +01004707
4708class MiscTestCase(unittest.TestCase):
4709 def test__all__(self):
4710 blacklist = {'logThreads', 'logMultiprocessing',
4711 'logProcesses', 'currentframe',
4712 'PercentStyle', 'StrFormatStyle', 'StringTemplateStyle',
4713 'Filterer', 'PlaceHolder', 'Manager', 'RootLogger',
Martin Panter94332cb2016-10-20 05:10:44 +00004714 'root', 'threading'}
Vinay Sajipdb8f4632016-09-08 01:37:03 +01004715 support.check__all__(self, logging, blacklist=blacklist)
4716
4717
Christian Heimes180510d2008-03-03 19:15:45 +00004718# Set the locale to the platform-dependent default. I have no idea
4719# why the test does this, but in any case we save the current locale
4720# first and restore it at the end.
Vinay Sajip1feedb42014-05-31 08:19:12 +01004721@support.run_with_locale('LC_ALL', '')
Tim Peters36f7e932003-07-23 00:05:07 +00004722def test_main():
Vinay Sajipd61910c2016-09-08 01:13:39 +01004723 tests = [
Vinay Sajip1feedb42014-05-31 08:19:12 +01004724 BuiltinLevelsTest, BasicFilterTest, CustomLevelsAndFiltersTest,
4725 HandlerTest, MemoryHandlerTest, ConfigFileTest, SocketHandlerTest,
4726 DatagramHandlerTest, MemoryTest, EncodingTest, WarningsTest,
4727 ConfigDictTest, ManagerTest, FormatterTest, BufferingFormatterTest,
4728 StreamHandlerTest, LogRecordFactoryTest, ChildLoggerTest,
4729 QueueHandlerTest, ShutdownTest, ModuleLevelMiscTest, BasicConfigTest,
4730 LoggerAdapterTest, LoggerTest, SMTPHandlerTest, FileHandlerTest,
4731 RotatingFileHandlerTest, LastResortTest, LogRecordTest,
Xiang Zhang0b4b57d2017-06-01 21:11:56 +08004732 ExceptionTest, SysLogHandlerTest, IPv6SysLogHandlerTest, HTTPHandlerTest,
Vinay Sajip1feedb42014-05-31 08:19:12 +01004733 NTEventLogHandlerTest, TimedRotatingFileHandlerTest,
Vinay Sajipd61910c2016-09-08 01:13:39 +01004734 UnixSocketHandlerTest, UnixDatagramHandlerTest, UnixSysLogHandlerTest,
Vinay Sajipdb8f4632016-09-08 01:37:03 +01004735 MiscTestCase
Vinay Sajipd61910c2016-09-08 01:13:39 +01004736 ]
4737 if hasattr(logging.handlers, 'QueueListener'):
4738 tests.append(QueueListenerTest)
4739 support.run_unittest(*tests)
Jeremy Hylton096d9862003-07-18 03:19:20 +00004740
Christian Heimes180510d2008-03-03 19:15:45 +00004741if __name__ == "__main__":
Neal Norwitzb4a2df02003-01-02 14:56:39 +00004742 test_main()