Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1 | #!/usr/bin/env python |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 2 | # |
Benjamin Peterson | 46a9900 | 2010-01-09 18:45:30 +0000 | [diff] [blame] | 3 | # Copyright 2001-2010 by Vinay Sajip. All Rights Reserved. |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 4 | # |
| 5 | # Permission to use, copy, modify, and distribute this software and its |
| 6 | # documentation for any purpose and without fee is hereby granted, |
| 7 | # provided that the above copyright notice appear in all copies and that |
| 8 | # both that copyright notice and this permission notice appear in |
| 9 | # supporting documentation, and that the name of Vinay Sajip |
| 10 | # not be used in advertising or publicity pertaining to distribution |
| 11 | # of the software without specific, written prior permission. |
| 12 | # VINAY SAJIP DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE, INCLUDING |
| 13 | # ALL IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL |
| 14 | # VINAY SAJIP BE LIABLE FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR |
| 15 | # ANY DAMAGES WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER |
| 16 | # IN AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT |
| 17 | # OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. |
| 18 | |
| 19 | """Test harness for the logging module. Run all tests. |
| 20 | |
Benjamin Peterson | 46a9900 | 2010-01-09 18:45:30 +0000 | [diff] [blame] | 21 | Copyright (C) 2001-2010 Vinay Sajip. All Rights Reserved. |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 22 | """ |
| 23 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 24 | import logging |
| 25 | import logging.handlers |
| 26 | import logging.config |
Christian Heimes | 18c6689 | 2008-02-17 13:31:39 +0000 | [diff] [blame] | 27 | |
Benjamin Peterson | f91df04 | 2009-02-13 02:50:59 +0000 | [diff] [blame] | 28 | import codecs |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 29 | import pickle |
| 30 | import io |
| 31 | import gc |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 32 | import json |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 33 | import os |
| 34 | import re |
Guido van Rossum | 2a1d516 | 2003-01-21 21:05:22 +0000 | [diff] [blame] | 35 | import select |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 36 | import socket |
Alexandre Vassalotti | ce26195 | 2008-05-12 02:31:37 +0000 | [diff] [blame] | 37 | from socketserver import ThreadingTCPServer, StreamRequestHandler |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 38 | import struct |
| 39 | import sys |
| 40 | import tempfile |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 41 | from test.support import captured_stdout, run_with_locale, run_unittest,\ |
| 42 | find_unused_port |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 43 | import textwrap |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 44 | import unittest |
Georg Brandl | f973407 | 2008-12-07 15:30:06 +0000 | [diff] [blame] | 45 | import warnings |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 46 | import weakref |
Victor Stinner | 45df820 | 2010-04-28 22:31:17 +0000 | [diff] [blame] | 47 | try: |
| 48 | import threading |
| 49 | except ImportError: |
| 50 | threading = None |
Christian Heimes | 18c6689 | 2008-02-17 13:31:39 +0000 | [diff] [blame] | 51 | |
| 52 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 53 | class BaseTest(unittest.TestCase): |
| 54 | |
| 55 | """Base class for logging tests.""" |
| 56 | |
| 57 | log_format = "%(name)s -> %(levelname)s: %(message)s" |
| 58 | expected_log_pat = r"^([\w.]+) -> ([\w]+): ([\d]+)$" |
| 59 | message_num = 0 |
| 60 | |
| 61 | def setUp(self): |
| 62 | """Setup the default logging stream to an internal StringIO instance, |
| 63 | so that we can examine log output as we want.""" |
| 64 | logger_dict = logging.getLogger().manager.loggerDict |
Christian Heimes | 18c6689 | 2008-02-17 13:31:39 +0000 | [diff] [blame] | 65 | logging._acquireLock() |
| 66 | try: |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 67 | self.saved_handlers = logging._handlers.copy() |
| 68 | self.saved_handler_list = logging._handlerList[:] |
| 69 | self.saved_loggers = logger_dict.copy() |
| 70 | self.saved_level_names = logging._levelNames.copy() |
Christian Heimes | 18c6689 | 2008-02-17 13:31:39 +0000 | [diff] [blame] | 71 | finally: |
| 72 | logging._releaseLock() |
| 73 | |
Benjamin Peterson | 22005fc | 2010-04-11 16:25:06 +0000 | [diff] [blame] | 74 | # Set two unused loggers: one non-ASCII and one Unicode. |
| 75 | # This is to test correct operation when sorting existing |
| 76 | # loggers in the configuration code. See issue 8201. |
| 77 | logging.getLogger("\xab\xd7\xbb") |
| 78 | logging.getLogger("\u013f\u00d6\u0047") |
| 79 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 80 | self.root_logger = logging.getLogger("") |
| 81 | self.original_logging_level = self.root_logger.getEffectiveLevel() |
| 82 | |
| 83 | self.stream = io.StringIO() |
| 84 | self.root_logger.setLevel(logging.DEBUG) |
| 85 | self.root_hdlr = logging.StreamHandler(self.stream) |
| 86 | self.root_formatter = logging.Formatter(self.log_format) |
| 87 | self.root_hdlr.setFormatter(self.root_formatter) |
| 88 | self.root_logger.addHandler(self.root_hdlr) |
| 89 | |
| 90 | def tearDown(self): |
| 91 | """Remove our logging stream, and restore the original logging |
| 92 | level.""" |
| 93 | self.stream.close() |
| 94 | self.root_logger.removeHandler(self.root_hdlr) |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 95 | while self.root_logger.handlers: |
| 96 | h = self.root_logger.handlers[0] |
| 97 | self.root_logger.removeHandler(h) |
| 98 | h.close() |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 99 | self.root_logger.setLevel(self.original_logging_level) |
| 100 | logging._acquireLock() |
| 101 | try: |
| 102 | logging._levelNames.clear() |
| 103 | logging._levelNames.update(self.saved_level_names) |
| 104 | logging._handlers.clear() |
| 105 | logging._handlers.update(self.saved_handlers) |
| 106 | logging._handlerList[:] = self.saved_handler_list |
| 107 | loggerDict = logging.getLogger().manager.loggerDict |
| 108 | loggerDict.clear() |
| 109 | loggerDict.update(self.saved_loggers) |
| 110 | finally: |
| 111 | logging._releaseLock() |
| 112 | |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 113 | def assert_log_lines(self, expected_values, stream=None): |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 114 | """Match the collected log lines against the regular expression |
| 115 | self.expected_log_pat, and compare the extracted group values to |
| 116 | the expected_values list of tuples.""" |
| 117 | stream = stream or self.stream |
| 118 | pat = re.compile(self.expected_log_pat) |
| 119 | try: |
| 120 | stream.reset() |
| 121 | actual_lines = stream.readlines() |
| 122 | except AttributeError: |
| 123 | # StringIO.StringIO lacks a reset() method. |
| 124 | actual_lines = stream.getvalue().splitlines() |
| 125 | self.assertEquals(len(actual_lines), len(expected_values)) |
| 126 | for actual, expected in zip(actual_lines, expected_values): |
| 127 | match = pat.search(actual) |
| 128 | if not match: |
| 129 | self.fail("Log line does not match expected pattern:\n" + |
| 130 | actual) |
| 131 | self.assertEquals(tuple(match.groups()), expected) |
| 132 | s = stream.read() |
| 133 | if s: |
| 134 | self.fail("Remaining output at end of log stream:\n" + s) |
| 135 | |
| 136 | def next_message(self): |
| 137 | """Generate a message consisting solely of an auto-incrementing |
| 138 | integer.""" |
| 139 | self.message_num += 1 |
| 140 | return "%d" % self.message_num |
| 141 | |
| 142 | |
| 143 | class BuiltinLevelsTest(BaseTest): |
| 144 | """Test builtin levels and their inheritance.""" |
| 145 | |
| 146 | def test_flat(self): |
| 147 | #Logging levels in a flat logger namespace. |
| 148 | m = self.next_message |
| 149 | |
| 150 | ERR = logging.getLogger("ERR") |
| 151 | ERR.setLevel(logging.ERROR) |
| 152 | INF = logging.getLogger("INF") |
| 153 | INF.setLevel(logging.INFO) |
| 154 | DEB = logging.getLogger("DEB") |
| 155 | DEB.setLevel(logging.DEBUG) |
| 156 | |
| 157 | # These should log. |
| 158 | ERR.log(logging.CRITICAL, m()) |
| 159 | ERR.error(m()) |
| 160 | |
| 161 | INF.log(logging.CRITICAL, m()) |
| 162 | INF.error(m()) |
| 163 | INF.warn(m()) |
| 164 | INF.info(m()) |
| 165 | |
| 166 | DEB.log(logging.CRITICAL, m()) |
| 167 | DEB.error(m()) |
| 168 | DEB.warn (m()) |
| 169 | DEB.info (m()) |
| 170 | DEB.debug(m()) |
| 171 | |
| 172 | # These should not log. |
| 173 | ERR.warn(m()) |
| 174 | ERR.info(m()) |
| 175 | ERR.debug(m()) |
| 176 | |
| 177 | INF.debug(m()) |
| 178 | |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 179 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 180 | ('ERR', 'CRITICAL', '1'), |
| 181 | ('ERR', 'ERROR', '2'), |
| 182 | ('INF', 'CRITICAL', '3'), |
| 183 | ('INF', 'ERROR', '4'), |
| 184 | ('INF', 'WARNING', '5'), |
| 185 | ('INF', 'INFO', '6'), |
| 186 | ('DEB', 'CRITICAL', '7'), |
| 187 | ('DEB', 'ERROR', '8'), |
| 188 | ('DEB', 'WARNING', '9'), |
| 189 | ('DEB', 'INFO', '10'), |
| 190 | ('DEB', 'DEBUG', '11'), |
| 191 | ]) |
| 192 | |
| 193 | def test_nested_explicit(self): |
| 194 | # Logging levels in a nested namespace, all explicitly set. |
| 195 | m = self.next_message |
| 196 | |
| 197 | INF = logging.getLogger("INF") |
| 198 | INF.setLevel(logging.INFO) |
| 199 | INF_ERR = logging.getLogger("INF.ERR") |
| 200 | INF_ERR.setLevel(logging.ERROR) |
| 201 | |
| 202 | # These should log. |
| 203 | INF_ERR.log(logging.CRITICAL, m()) |
| 204 | INF_ERR.error(m()) |
| 205 | |
| 206 | # These should not log. |
| 207 | INF_ERR.warn(m()) |
| 208 | INF_ERR.info(m()) |
| 209 | INF_ERR.debug(m()) |
| 210 | |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 211 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 212 | ('INF.ERR', 'CRITICAL', '1'), |
| 213 | ('INF.ERR', 'ERROR', '2'), |
| 214 | ]) |
| 215 | |
| 216 | def test_nested_inherited(self): |
| 217 | #Logging levels in a nested namespace, inherited from parent loggers. |
| 218 | m = self.next_message |
| 219 | |
| 220 | INF = logging.getLogger("INF") |
| 221 | INF.setLevel(logging.INFO) |
| 222 | INF_ERR = logging.getLogger("INF.ERR") |
| 223 | INF_ERR.setLevel(logging.ERROR) |
| 224 | INF_UNDEF = logging.getLogger("INF.UNDEF") |
| 225 | INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF") |
| 226 | UNDEF = logging.getLogger("UNDEF") |
| 227 | |
| 228 | # These should log. |
| 229 | INF_UNDEF.log(logging.CRITICAL, m()) |
| 230 | INF_UNDEF.error(m()) |
| 231 | INF_UNDEF.warn(m()) |
| 232 | INF_UNDEF.info(m()) |
| 233 | INF_ERR_UNDEF.log(logging.CRITICAL, m()) |
| 234 | INF_ERR_UNDEF.error(m()) |
| 235 | |
| 236 | # These should not log. |
| 237 | INF_UNDEF.debug(m()) |
| 238 | INF_ERR_UNDEF.warn(m()) |
| 239 | INF_ERR_UNDEF.info(m()) |
| 240 | INF_ERR_UNDEF.debug(m()) |
| 241 | |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 242 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 243 | ('INF.UNDEF', 'CRITICAL', '1'), |
| 244 | ('INF.UNDEF', 'ERROR', '2'), |
| 245 | ('INF.UNDEF', 'WARNING', '3'), |
| 246 | ('INF.UNDEF', 'INFO', '4'), |
| 247 | ('INF.ERR.UNDEF', 'CRITICAL', '5'), |
| 248 | ('INF.ERR.UNDEF', 'ERROR', '6'), |
| 249 | ]) |
| 250 | |
| 251 | def test_nested_with_virtual_parent(self): |
| 252 | # Logging levels when some parent does not exist yet. |
| 253 | m = self.next_message |
| 254 | |
| 255 | INF = logging.getLogger("INF") |
| 256 | GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF") |
| 257 | CHILD = logging.getLogger("INF.BADPARENT") |
| 258 | INF.setLevel(logging.INFO) |
| 259 | |
| 260 | # These should log. |
| 261 | GRANDCHILD.log(logging.FATAL, m()) |
| 262 | GRANDCHILD.info(m()) |
| 263 | CHILD.log(logging.FATAL, m()) |
| 264 | CHILD.info(m()) |
| 265 | |
| 266 | # These should not log. |
| 267 | GRANDCHILD.debug(m()) |
| 268 | CHILD.debug(m()) |
| 269 | |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 270 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 271 | ('INF.BADPARENT.UNDEF', 'CRITICAL', '1'), |
| 272 | ('INF.BADPARENT.UNDEF', 'INFO', '2'), |
| 273 | ('INF.BADPARENT', 'CRITICAL', '3'), |
| 274 | ('INF.BADPARENT', 'INFO', '4'), |
| 275 | ]) |
| 276 | |
| 277 | |
| 278 | class BasicFilterTest(BaseTest): |
| 279 | |
| 280 | """Test the bundled Filter class.""" |
| 281 | |
| 282 | def test_filter(self): |
| 283 | # Only messages satisfying the specified criteria pass through the |
| 284 | # filter. |
| 285 | filter_ = logging.Filter("spam.eggs") |
| 286 | handler = self.root_logger.handlers[0] |
| 287 | try: |
| 288 | handler.addFilter(filter_) |
| 289 | spam = logging.getLogger("spam") |
| 290 | spam_eggs = logging.getLogger("spam.eggs") |
| 291 | spam_eggs_fish = logging.getLogger("spam.eggs.fish") |
| 292 | spam_bakedbeans = logging.getLogger("spam.bakedbeans") |
| 293 | |
| 294 | spam.info(self.next_message()) |
| 295 | spam_eggs.info(self.next_message()) # Good. |
| 296 | spam_eggs_fish.info(self.next_message()) # Good. |
| 297 | spam_bakedbeans.info(self.next_message()) |
| 298 | |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 299 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 300 | ('spam.eggs', 'INFO', '2'), |
| 301 | ('spam.eggs.fish', 'INFO', '3'), |
| 302 | ]) |
| 303 | finally: |
| 304 | handler.removeFilter(filter_) |
| 305 | |
| 306 | |
| 307 | # |
| 308 | # First, we define our levels. There can be as many as you want - the only |
| 309 | # limitations are that they should be integers, the lowest should be > 0 and |
| 310 | # larger values mean less information being logged. If you need specific |
| 311 | # level values which do not fit into these limitations, you can use a |
| 312 | # mapping dictionary to convert between your application levels and the |
| 313 | # logging system. |
| 314 | # |
| 315 | SILENT = 120 |
| 316 | TACITURN = 119 |
| 317 | TERSE = 118 |
| 318 | EFFUSIVE = 117 |
| 319 | SOCIABLE = 116 |
| 320 | VERBOSE = 115 |
| 321 | TALKATIVE = 114 |
| 322 | GARRULOUS = 113 |
| 323 | CHATTERBOX = 112 |
| 324 | BORING = 111 |
| 325 | |
| 326 | LEVEL_RANGE = range(BORING, SILENT + 1) |
| 327 | |
| 328 | # |
| 329 | # Next, we define names for our levels. You don't need to do this - in which |
| 330 | # case the system will use "Level n" to denote the text for the level. |
| 331 | # |
| 332 | my_logging_levels = { |
| 333 | SILENT : 'Silent', |
| 334 | TACITURN : 'Taciturn', |
| 335 | TERSE : 'Terse', |
| 336 | EFFUSIVE : 'Effusive', |
| 337 | SOCIABLE : 'Sociable', |
| 338 | VERBOSE : 'Verbose', |
| 339 | TALKATIVE : 'Talkative', |
| 340 | GARRULOUS : 'Garrulous', |
| 341 | CHATTERBOX : 'Chatterbox', |
| 342 | BORING : 'Boring', |
| 343 | } |
| 344 | |
| 345 | class GarrulousFilter(logging.Filter): |
| 346 | |
| 347 | """A filter which blocks garrulous messages.""" |
| 348 | |
| 349 | def filter(self, record): |
| 350 | return record.levelno != GARRULOUS |
| 351 | |
| 352 | class VerySpecificFilter(logging.Filter): |
| 353 | |
| 354 | """A filter which blocks sociable and taciturn messages.""" |
| 355 | |
| 356 | def filter(self, record): |
| 357 | return record.levelno not in [SOCIABLE, TACITURN] |
| 358 | |
| 359 | |
| 360 | class CustomLevelsAndFiltersTest(BaseTest): |
| 361 | |
| 362 | """Test various filtering possibilities with custom logging levels.""" |
| 363 | |
| 364 | # Skip the logger name group. |
| 365 | expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$" |
| 366 | |
| 367 | def setUp(self): |
| 368 | BaseTest.setUp(self) |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 369 | for k, v in my_logging_levels.items(): |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 370 | logging.addLevelName(k, v) |
| 371 | |
| 372 | def log_at_all_levels(self, logger): |
| 373 | for lvl in LEVEL_RANGE: |
| 374 | logger.log(lvl, self.next_message()) |
| 375 | |
| 376 | def test_logger_filter(self): |
| 377 | # Filter at logger level. |
| 378 | self.root_logger.setLevel(VERBOSE) |
| 379 | # Levels >= 'Verbose' are good. |
| 380 | self.log_at_all_levels(self.root_logger) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 381 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 382 | ('Verbose', '5'), |
| 383 | ('Sociable', '6'), |
| 384 | ('Effusive', '7'), |
| 385 | ('Terse', '8'), |
| 386 | ('Taciturn', '9'), |
| 387 | ('Silent', '10'), |
| 388 | ]) |
| 389 | |
| 390 | def test_handler_filter(self): |
| 391 | # Filter at handler level. |
| 392 | self.root_logger.handlers[0].setLevel(SOCIABLE) |
| 393 | try: |
| 394 | # Levels >= 'Sociable' are good. |
| 395 | self.log_at_all_levels(self.root_logger) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 396 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 397 | ('Sociable', '6'), |
| 398 | ('Effusive', '7'), |
| 399 | ('Terse', '8'), |
| 400 | ('Taciturn', '9'), |
| 401 | ('Silent', '10'), |
| 402 | ]) |
| 403 | finally: |
| 404 | self.root_logger.handlers[0].setLevel(logging.NOTSET) |
| 405 | |
| 406 | def test_specific_filters(self): |
| 407 | # Set a specific filter object on the handler, and then add another |
| 408 | # filter object on the logger itself. |
| 409 | handler = self.root_logger.handlers[0] |
| 410 | specific_filter = None |
| 411 | garr = GarrulousFilter() |
| 412 | handler.addFilter(garr) |
| 413 | try: |
| 414 | self.log_at_all_levels(self.root_logger) |
| 415 | first_lines = [ |
| 416 | # Notice how 'Garrulous' is missing |
| 417 | ('Boring', '1'), |
| 418 | ('Chatterbox', '2'), |
| 419 | ('Talkative', '4'), |
| 420 | ('Verbose', '5'), |
| 421 | ('Sociable', '6'), |
| 422 | ('Effusive', '7'), |
| 423 | ('Terse', '8'), |
| 424 | ('Taciturn', '9'), |
| 425 | ('Silent', '10'), |
| 426 | ] |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 427 | self.assert_log_lines(first_lines) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 428 | |
| 429 | specific_filter = VerySpecificFilter() |
| 430 | self.root_logger.addFilter(specific_filter) |
| 431 | self.log_at_all_levels(self.root_logger) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 432 | self.assert_log_lines(first_lines + [ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 433 | # Not only 'Garrulous' is still missing, but also 'Sociable' |
| 434 | # and 'Taciturn' |
| 435 | ('Boring', '11'), |
| 436 | ('Chatterbox', '12'), |
| 437 | ('Talkative', '14'), |
| 438 | ('Verbose', '15'), |
| 439 | ('Effusive', '17'), |
| 440 | ('Terse', '18'), |
| 441 | ('Silent', '20'), |
| 442 | ]) |
| 443 | finally: |
| 444 | if specific_filter: |
| 445 | self.root_logger.removeFilter(specific_filter) |
| 446 | handler.removeFilter(garr) |
| 447 | |
| 448 | |
| 449 | class MemoryHandlerTest(BaseTest): |
| 450 | |
| 451 | """Tests for the MemoryHandler.""" |
| 452 | |
| 453 | # Do not bother with a logger name group. |
| 454 | expected_log_pat = r"^[\w.]+ -> ([\w]+): ([\d]+)$" |
| 455 | |
| 456 | def setUp(self): |
| 457 | BaseTest.setUp(self) |
| 458 | self.mem_hdlr = logging.handlers.MemoryHandler(10, logging.WARNING, |
| 459 | self.root_hdlr) |
| 460 | self.mem_logger = logging.getLogger('mem') |
| 461 | self.mem_logger.propagate = 0 |
| 462 | self.mem_logger.addHandler(self.mem_hdlr) |
| 463 | |
| 464 | def tearDown(self): |
| 465 | self.mem_hdlr.close() |
Benjamin Peterson | 2a691a8 | 2008-03-31 01:51:45 +0000 | [diff] [blame] | 466 | BaseTest.tearDown(self) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 467 | |
| 468 | def test_flush(self): |
| 469 | # The memory handler flushes to its target handler based on specific |
| 470 | # criteria (message count and message level). |
| 471 | self.mem_logger.debug(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 472 | self.assert_log_lines([]) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 473 | self.mem_logger.info(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 474 | self.assert_log_lines([]) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 475 | # This will flush because the level is >= logging.WARNING |
| 476 | self.mem_logger.warn(self.next_message()) |
| 477 | lines = [ |
| 478 | ('DEBUG', '1'), |
| 479 | ('INFO', '2'), |
| 480 | ('WARNING', '3'), |
| 481 | ] |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 482 | self.assert_log_lines(lines) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 483 | for n in (4, 14): |
| 484 | for i in range(9): |
| 485 | self.mem_logger.debug(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 486 | self.assert_log_lines(lines) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 487 | # This will flush because it's the 10th message since the last |
| 488 | # flush. |
| 489 | self.mem_logger.debug(self.next_message()) |
| 490 | lines = lines + [('DEBUG', str(i)) for i in range(n, n + 10)] |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 491 | self.assert_log_lines(lines) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 492 | |
| 493 | self.mem_logger.debug(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 494 | self.assert_log_lines(lines) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 495 | |
| 496 | |
| 497 | class ExceptionFormatter(logging.Formatter): |
| 498 | """A special exception formatter.""" |
| 499 | def formatException(self, ei): |
| 500 | return "Got a [%s]" % ei[0].__name__ |
| 501 | |
| 502 | |
| 503 | class ConfigFileTest(BaseTest): |
| 504 | |
| 505 | """Reading logging config from a .ini-style config file.""" |
| 506 | |
| 507 | expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$" |
| 508 | |
| 509 | # config0 is a standard configuration. |
| 510 | config0 = """ |
| 511 | [loggers] |
| 512 | keys=root |
| 513 | |
| 514 | [handlers] |
| 515 | keys=hand1 |
| 516 | |
| 517 | [formatters] |
| 518 | keys=form1 |
| 519 | |
| 520 | [logger_root] |
| 521 | level=WARNING |
| 522 | handlers=hand1 |
| 523 | |
| 524 | [handler_hand1] |
| 525 | class=StreamHandler |
| 526 | level=NOTSET |
| 527 | formatter=form1 |
| 528 | args=(sys.stdout,) |
| 529 | |
| 530 | [formatter_form1] |
| 531 | format=%(levelname)s ++ %(message)s |
| 532 | datefmt= |
| 533 | """ |
| 534 | |
| 535 | # config1 adds a little to the standard configuration. |
| 536 | config1 = """ |
| 537 | [loggers] |
| 538 | keys=root,parser |
| 539 | |
| 540 | [handlers] |
| 541 | keys=hand1 |
| 542 | |
| 543 | [formatters] |
| 544 | keys=form1 |
| 545 | |
| 546 | [logger_root] |
| 547 | level=WARNING |
| 548 | handlers= |
| 549 | |
| 550 | [logger_parser] |
| 551 | level=DEBUG |
| 552 | handlers=hand1 |
| 553 | propagate=1 |
| 554 | qualname=compiler.parser |
| 555 | |
| 556 | [handler_hand1] |
| 557 | class=StreamHandler |
| 558 | level=NOTSET |
| 559 | formatter=form1 |
| 560 | args=(sys.stdout,) |
| 561 | |
| 562 | [formatter_form1] |
| 563 | format=%(levelname)s ++ %(message)s |
| 564 | datefmt= |
| 565 | """ |
| 566 | |
| 567 | # config2 has a subtle configuration error that should be reported |
| 568 | config2 = config1.replace("sys.stdout", "sys.stbout") |
| 569 | |
| 570 | # config3 has a less subtle configuration error |
| 571 | config3 = config1.replace("formatter=form1", "formatter=misspelled_name") |
| 572 | |
| 573 | # config4 specifies a custom formatter class to be loaded |
| 574 | config4 = """ |
| 575 | [loggers] |
| 576 | keys=root |
| 577 | |
| 578 | [handlers] |
| 579 | keys=hand1 |
| 580 | |
| 581 | [formatters] |
| 582 | keys=form1 |
| 583 | |
| 584 | [logger_root] |
| 585 | level=NOTSET |
| 586 | handlers=hand1 |
| 587 | |
| 588 | [handler_hand1] |
| 589 | class=StreamHandler |
| 590 | level=NOTSET |
| 591 | formatter=form1 |
| 592 | args=(sys.stdout,) |
| 593 | |
| 594 | [formatter_form1] |
| 595 | class=""" + __name__ + """.ExceptionFormatter |
| 596 | format=%(levelname)s:%(name)s:%(message)s |
| 597 | datefmt= |
| 598 | """ |
| 599 | |
Georg Brandl | 3dbca81 | 2008-07-23 16:10:53 +0000 | [diff] [blame] | 600 | # config5 specifies a custom handler class to be loaded |
| 601 | config5 = config1.replace('class=StreamHandler', 'class=logging.StreamHandler') |
| 602 | |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 603 | # config6 uses ', ' delimiters in the handlers and formatters sections |
| 604 | config6 = """ |
| 605 | [loggers] |
| 606 | keys=root,parser |
| 607 | |
| 608 | [handlers] |
| 609 | keys=hand1, hand2 |
| 610 | |
| 611 | [formatters] |
| 612 | keys=form1, form2 |
| 613 | |
| 614 | [logger_root] |
| 615 | level=WARNING |
| 616 | handlers= |
| 617 | |
| 618 | [logger_parser] |
| 619 | level=DEBUG |
| 620 | handlers=hand1 |
| 621 | propagate=1 |
| 622 | qualname=compiler.parser |
| 623 | |
| 624 | [handler_hand1] |
| 625 | class=StreamHandler |
| 626 | level=NOTSET |
| 627 | formatter=form1 |
| 628 | args=(sys.stdout,) |
| 629 | |
| 630 | [handler_hand2] |
Benjamin Peterson | 9aa4299 | 2008-09-10 21:57:34 +0000 | [diff] [blame] | 631 | class=StreamHandler |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 632 | level=NOTSET |
| 633 | formatter=form1 |
Benjamin Peterson | 9aa4299 | 2008-09-10 21:57:34 +0000 | [diff] [blame] | 634 | args=(sys.stderr,) |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 635 | |
| 636 | [formatter_form1] |
| 637 | format=%(levelname)s ++ %(message)s |
| 638 | datefmt= |
| 639 | |
| 640 | [formatter_form2] |
| 641 | format=%(message)s |
| 642 | datefmt= |
| 643 | """ |
| 644 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 645 | def apply_config(self, conf): |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 646 | file = io.StringIO(textwrap.dedent(conf)) |
| 647 | logging.config.fileConfig(file) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 648 | |
| 649 | def test_config0_ok(self): |
| 650 | # A simple config file which overrides the default settings. |
| 651 | with captured_stdout() as output: |
| 652 | self.apply_config(self.config0) |
| 653 | logger = logging.getLogger() |
| 654 | # Won't output anything |
| 655 | logger.info(self.next_message()) |
| 656 | # Outputs a message |
| 657 | logger.error(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 658 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 659 | ('ERROR', '2'), |
| 660 | ], stream=output) |
| 661 | # Original logger output is empty. |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 662 | self.assert_log_lines([]) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 663 | |
Georg Brandl | 3dbca81 | 2008-07-23 16:10:53 +0000 | [diff] [blame] | 664 | def test_config1_ok(self, config=config1): |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 665 | # A config file defining a sub-parser as well. |
| 666 | with captured_stdout() as output: |
Georg Brandl | 3dbca81 | 2008-07-23 16:10:53 +0000 | [diff] [blame] | 667 | self.apply_config(config) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 668 | logger = logging.getLogger("compiler.parser") |
| 669 | # Both will output a message |
| 670 | logger.info(self.next_message()) |
| 671 | logger.error(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 672 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 673 | ('INFO', '1'), |
| 674 | ('ERROR', '2'), |
| 675 | ], stream=output) |
| 676 | # Original logger output is empty. |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 677 | self.assert_log_lines([]) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 678 | |
| 679 | def test_config2_failure(self): |
| 680 | # A simple config file which overrides the default settings. |
| 681 | self.assertRaises(Exception, self.apply_config, self.config2) |
| 682 | |
| 683 | def test_config3_failure(self): |
| 684 | # A simple config file which overrides the default settings. |
| 685 | self.assertRaises(Exception, self.apply_config, self.config3) |
| 686 | |
| 687 | def test_config4_ok(self): |
| 688 | # A config file specifying a custom formatter class. |
| 689 | with captured_stdout() as output: |
| 690 | self.apply_config(self.config4) |
| 691 | logger = logging.getLogger() |
| 692 | try: |
| 693 | raise RuntimeError() |
| 694 | except RuntimeError: |
| 695 | logging.exception("just testing") |
| 696 | sys.stdout.seek(0) |
| 697 | self.assertEquals(output.getvalue(), |
| 698 | "ERROR:root:just testing\nGot a [RuntimeError]\n") |
| 699 | # Original logger output is empty |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 700 | self.assert_log_lines([]) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 701 | |
Georg Brandl | 3dbca81 | 2008-07-23 16:10:53 +0000 | [diff] [blame] | 702 | def test_config5_ok(self): |
| 703 | self.test_config1_ok(config=self.config5) |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 704 | |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 705 | def test_config6_ok(self): |
| 706 | self.test_config1_ok(config=self.config6) |
| 707 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 708 | class LogRecordStreamHandler(StreamRequestHandler): |
| 709 | |
| 710 | """Handler for a streaming logging request. It saves the log message in the |
| 711 | TCP server's 'log_output' attribute.""" |
| 712 | |
| 713 | TCP_LOG_END = "!!!END!!!" |
| 714 | |
| 715 | def handle(self): |
| 716 | """Handle multiple requests - each expected to be of 4-byte length, |
| 717 | followed by the LogRecord in pickle format. Logs the record |
| 718 | according to whatever policy is configured locally.""" |
| 719 | while True: |
| 720 | chunk = self.connection.recv(4) |
| 721 | if len(chunk) < 4: |
| 722 | break |
| 723 | slen = struct.unpack(">L", chunk)[0] |
| 724 | chunk = self.connection.recv(slen) |
| 725 | while len(chunk) < slen: |
| 726 | chunk = chunk + self.connection.recv(slen - len(chunk)) |
| 727 | obj = self.unpickle(chunk) |
| 728 | record = logging.makeLogRecord(obj) |
| 729 | self.handle_log_record(record) |
| 730 | |
| 731 | def unpickle(self, data): |
| 732 | return pickle.loads(data) |
| 733 | |
| 734 | def handle_log_record(self, record): |
| 735 | # If the end-of-messages sentinel is seen, tell the server to |
| 736 | # terminate. |
| 737 | if self.TCP_LOG_END in record.msg: |
| 738 | self.server.abort = 1 |
| 739 | return |
| 740 | self.server.log_output += record.msg + "\n" |
| 741 | |
Guido van Rossum | 376e636 | 2003-04-25 14:22:00 +0000 | [diff] [blame] | 742 | |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 743 | class LogRecordSocketReceiver(ThreadingTCPServer): |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 744 | |
| 745 | """A simple-minded TCP socket-based logging receiver suitable for test |
| 746 | purposes.""" |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 747 | |
| 748 | allow_reuse_address = 1 |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 749 | log_output = "" |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 750 | |
| 751 | def __init__(self, host='localhost', |
| 752 | port=logging.handlers.DEFAULT_TCP_LOGGING_PORT, |
| 753 | handler=LogRecordStreamHandler): |
| 754 | ThreadingTCPServer.__init__(self, (host, port), handler) |
Christian Heimes | 8640e74 | 2008-02-23 16:23:06 +0000 | [diff] [blame] | 755 | self.abort = False |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 756 | self.timeout = 0.1 |
| 757 | self.finished = threading.Event() |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 758 | |
| 759 | def serve_until_stopped(self): |
Neal Norwitz | 55cd82f | 2006-02-05 08:21:08 +0000 | [diff] [blame] | 760 | while not self.abort: |
Neal Norwitz | 5bab0f8 | 2006-03-05 02:16:12 +0000 | [diff] [blame] | 761 | rd, wr, ex = select.select([self.socket.fileno()], [], [], |
| 762 | self.timeout) |
| 763 | if rd: |
| 764 | self.handle_request() |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 765 | # Notify the main thread that we're about to exit |
| 766 | self.finished.set() |
Martin v. Löwis | f684888 | 2006-01-29 19:55:18 +0000 | [diff] [blame] | 767 | # close the listen socket |
| 768 | self.server_close() |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 769 | |
Guido van Rossum | 2a1d516 | 2003-01-21 21:05:22 +0000 | [diff] [blame] | 770 | |
Victor Stinner | 45df820 | 2010-04-28 22:31:17 +0000 | [diff] [blame] | 771 | @unittest.skipUnless(threading, 'Threading required for this test.') |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 772 | class SocketHandlerTest(BaseTest): |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 773 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 774 | """Test for SocketHandler objects.""" |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 775 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 776 | def setUp(self): |
| 777 | """Set up a TCP server to receive log messages, and a SocketHandler |
| 778 | pointing to that server's address and port.""" |
| 779 | BaseTest.setUp(self) |
| 780 | self.tcpserver = LogRecordSocketReceiver(port=0) |
| 781 | self.port = self.tcpserver.socket.getsockname()[1] |
| 782 | self.threads = [ |
| 783 | threading.Thread(target=self.tcpserver.serve_until_stopped)] |
| 784 | for thread in self.threads: |
| 785 | thread.start() |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 786 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 787 | self.sock_hdlr = logging.handlers.SocketHandler('localhost', self.port) |
| 788 | self.sock_hdlr.setFormatter(self.root_formatter) |
| 789 | self.root_logger.removeHandler(self.root_logger.handlers[0]) |
| 790 | self.root_logger.addHandler(self.sock_hdlr) |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 791 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 792 | def tearDown(self): |
| 793 | """Shutdown the TCP server.""" |
| 794 | try: |
| 795 | self.tcpserver.abort = True |
| 796 | del self.tcpserver |
| 797 | self.root_logger.removeHandler(self.sock_hdlr) |
| 798 | self.sock_hdlr.close() |
| 799 | for thread in self.threads: |
| 800 | thread.join(2.0) |
| 801 | finally: |
| 802 | BaseTest.tearDown(self) |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 803 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 804 | def get_output(self): |
| 805 | """Get the log output as received by the TCP server.""" |
| 806 | # Signal the TCP receiver and wait for it to terminate. |
| 807 | self.root_logger.critical(LogRecordStreamHandler.TCP_LOG_END) |
| 808 | self.tcpserver.finished.wait(2.0) |
| 809 | return self.tcpserver.log_output |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 810 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 811 | def test_output(self): |
| 812 | # The log message sent to the SocketHandler is properly received. |
| 813 | logger = logging.getLogger("tcp") |
| 814 | logger.error("spam") |
| 815 | logger.debug("eggs") |
| 816 | self.assertEquals(self.get_output(), "spam\neggs\n") |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 817 | |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 818 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 819 | class MemoryTest(BaseTest): |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 820 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 821 | """Test memory persistence of logger objects.""" |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 822 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 823 | def setUp(self): |
| 824 | """Create a dict to remember potentially destroyed objects.""" |
| 825 | BaseTest.setUp(self) |
| 826 | self._survivors = {} |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 827 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 828 | def _watch_for_survival(self, *args): |
| 829 | """Watch the given objects for survival, by creating weakrefs to |
| 830 | them.""" |
| 831 | for obj in args: |
| 832 | key = id(obj), repr(obj) |
| 833 | self._survivors[key] = weakref.ref(obj) |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 834 | |
Benjamin Peterson | c9c0f20 | 2009-06-30 23:06:06 +0000 | [diff] [blame] | 835 | def _assertTruesurvival(self): |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 836 | """Assert that all objects watched for survival have survived.""" |
| 837 | # Trigger cycle breaking. |
| 838 | gc.collect() |
| 839 | dead = [] |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 840 | for (id_, repr_), ref in self._survivors.items(): |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 841 | if ref() is None: |
| 842 | dead.append(repr_) |
| 843 | if dead: |
| 844 | self.fail("%d objects should have survived " |
| 845 | "but have been destroyed: %s" % (len(dead), ", ".join(dead))) |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 846 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 847 | def test_persistent_loggers(self): |
| 848 | # Logger objects are persistent and retain their configuration, even |
| 849 | # if visible references are destroyed. |
| 850 | self.root_logger.setLevel(logging.INFO) |
| 851 | foo = logging.getLogger("foo") |
| 852 | self._watch_for_survival(foo) |
| 853 | foo.setLevel(logging.DEBUG) |
| 854 | self.root_logger.debug(self.next_message()) |
| 855 | foo.debug(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 856 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 857 | ('foo', 'DEBUG', '2'), |
| 858 | ]) |
| 859 | del foo |
| 860 | # foo has survived. |
Benjamin Peterson | c9c0f20 | 2009-06-30 23:06:06 +0000 | [diff] [blame] | 861 | self._assertTruesurvival() |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 862 | # foo has retained its settings. |
| 863 | bar = logging.getLogger("foo") |
| 864 | bar.debug(self.next_message()) |
Benjamin Peterson | 77108eb | 2009-07-01 00:43:10 +0000 | [diff] [blame] | 865 | self.assert_log_lines([ |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 866 | ('foo', 'DEBUG', '2'), |
| 867 | ('foo', 'DEBUG', '3'), |
| 868 | ]) |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 869 | |
Benjamin Peterson | f91df04 | 2009-02-13 02:50:59 +0000 | [diff] [blame] | 870 | |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 871 | class EncodingTest(BaseTest): |
| 872 | def test_encoding_plain_file(self): |
| 873 | # In Python 2.x, a plain file object is treated as having no encoding. |
| 874 | log = logging.getLogger("test") |
| 875 | fn = tempfile.mktemp(".log") |
| 876 | # the non-ascii data we write to the log. |
| 877 | data = "foo\x80" |
| 878 | try: |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 879 | handler = logging.FileHandler(fn, encoding="utf-8") |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 880 | log.addHandler(handler) |
| 881 | try: |
| 882 | # write non-ascii data to the log. |
| 883 | log.warning(data) |
| 884 | finally: |
| 885 | log.removeHandler(handler) |
| 886 | handler.close() |
| 887 | # check we wrote exactly those bytes, ignoring trailing \n etc |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 888 | f = open(fn, encoding="utf-8") |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 889 | try: |
Benjamin Peterson | c9c0f20 | 2009-06-30 23:06:06 +0000 | [diff] [blame] | 890 | self.assertEqual(f.read().rstrip(), data) |
Benjamin Peterson | ae5360b | 2008-09-08 23:05:23 +0000 | [diff] [blame] | 891 | finally: |
| 892 | f.close() |
| 893 | finally: |
| 894 | if os.path.isfile(fn): |
| 895 | os.remove(fn) |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 896 | |
Benjamin Peterson | f91df04 | 2009-02-13 02:50:59 +0000 | [diff] [blame] | 897 | def test_encoding_cyrillic_unicode(self): |
| 898 | log = logging.getLogger("test") |
| 899 | #Get a message in Unicode: Do svidanya in Cyrillic (meaning goodbye) |
| 900 | message = '\u0434\u043e \u0441\u0432\u0438\u0434\u0430\u043d\u0438\u044f' |
| 901 | #Ensure it's written in a Cyrillic encoding |
| 902 | writer_class = codecs.getwriter('cp1251') |
Benjamin Peterson | 25c95f1 | 2009-05-08 20:42:26 +0000 | [diff] [blame] | 903 | writer_class.encoding = 'cp1251' |
Benjamin Peterson | f91df04 | 2009-02-13 02:50:59 +0000 | [diff] [blame] | 904 | stream = io.BytesIO() |
| 905 | writer = writer_class(stream, 'strict') |
| 906 | handler = logging.StreamHandler(writer) |
| 907 | log.addHandler(handler) |
| 908 | try: |
| 909 | log.warning(message) |
| 910 | finally: |
| 911 | log.removeHandler(handler) |
| 912 | handler.close() |
| 913 | # check we wrote exactly those bytes, ignoring trailing \n etc |
| 914 | s = stream.getvalue() |
| 915 | #Compare against what the data should be when encoded in CP-1251 |
| 916 | self.assertEqual(s, b'\xe4\xee \xf1\xe2\xe8\xe4\xe0\xed\xe8\xff\n') |
| 917 | |
| 918 | |
Georg Brandl | f973407 | 2008-12-07 15:30:06 +0000 | [diff] [blame] | 919 | class WarningsTest(BaseTest): |
Brett Cannon | df8709d | 2009-04-01 20:01:47 +0000 | [diff] [blame] | 920 | |
Georg Brandl | f973407 | 2008-12-07 15:30:06 +0000 | [diff] [blame] | 921 | def test_warnings(self): |
Brett Cannon | df8709d | 2009-04-01 20:01:47 +0000 | [diff] [blame] | 922 | with warnings.catch_warnings(): |
Brett Cannon | 5b9082a | 2009-04-05 18:57:32 +0000 | [diff] [blame] | 923 | logging.captureWarnings(True) |
Brett Cannon | df8709d | 2009-04-01 20:01:47 +0000 | [diff] [blame] | 924 | try: |
Brett Cannon | 5b9082a | 2009-04-05 18:57:32 +0000 | [diff] [blame] | 925 | warnings.filterwarnings("always", category=UserWarning) |
Brett Cannon | df8709d | 2009-04-01 20:01:47 +0000 | [diff] [blame] | 926 | file = io.StringIO() |
| 927 | h = logging.StreamHandler(file) |
| 928 | logger = logging.getLogger("py.warnings") |
| 929 | logger.addHandler(h) |
| 930 | warnings.warn("I'm warning you...") |
| 931 | logger.removeHandler(h) |
| 932 | s = file.getvalue() |
| 933 | h.close() |
| 934 | self.assertTrue(s.find("UserWarning: I'm warning you...\n") > 0) |
Georg Brandl | f973407 | 2008-12-07 15:30:06 +0000 | [diff] [blame] | 935 | |
Brett Cannon | df8709d | 2009-04-01 20:01:47 +0000 | [diff] [blame] | 936 | #See if an explicit file uses the original implementation |
| 937 | file = io.StringIO() |
| 938 | warnings.showwarning("Explicit", UserWarning, "dummy.py", 42, |
| 939 | file, "Dummy line") |
| 940 | s = file.getvalue() |
| 941 | file.close() |
| 942 | self.assertEqual(s, |
| 943 | "dummy.py:42: UserWarning: Explicit\n Dummy line\n") |
| 944 | finally: |
| 945 | logging.captureWarnings(False) |
Georg Brandl | f973407 | 2008-12-07 15:30:06 +0000 | [diff] [blame] | 946 | |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 947 | |
| 948 | def formatFunc(format, datefmt=None): |
| 949 | return logging.Formatter(format, datefmt) |
| 950 | |
| 951 | def handlerFunc(): |
| 952 | return logging.StreamHandler() |
| 953 | |
| 954 | class CustomHandler(logging.StreamHandler): |
| 955 | pass |
| 956 | |
| 957 | class ConfigDictTest(BaseTest): |
| 958 | |
| 959 | """Reading logging config from a dictionary.""" |
| 960 | |
| 961 | expected_log_pat = r"^([\w]+) \+\+ ([\w]+)$" |
| 962 | |
| 963 | # config0 is a standard configuration. |
| 964 | config0 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 965 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 966 | 'formatters': { |
| 967 | 'form1' : { |
| 968 | 'format' : '%(levelname)s ++ %(message)s', |
| 969 | }, |
| 970 | }, |
| 971 | 'handlers' : { |
| 972 | 'hand1' : { |
| 973 | 'class' : 'logging.StreamHandler', |
| 974 | 'formatter' : 'form1', |
| 975 | 'level' : 'NOTSET', |
| 976 | 'stream' : 'ext://sys.stdout', |
| 977 | }, |
| 978 | }, |
| 979 | 'root' : { |
| 980 | 'level' : 'WARNING', |
| 981 | 'handlers' : ['hand1'], |
| 982 | }, |
| 983 | } |
| 984 | |
| 985 | # config1 adds a little to the standard configuration. |
| 986 | config1 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 987 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 988 | 'formatters': { |
| 989 | 'form1' : { |
| 990 | 'format' : '%(levelname)s ++ %(message)s', |
| 991 | }, |
| 992 | }, |
| 993 | 'handlers' : { |
| 994 | 'hand1' : { |
| 995 | 'class' : 'logging.StreamHandler', |
| 996 | 'formatter' : 'form1', |
| 997 | 'level' : 'NOTSET', |
| 998 | 'stream' : 'ext://sys.stdout', |
| 999 | }, |
| 1000 | }, |
| 1001 | 'loggers' : { |
| 1002 | 'compiler.parser' : { |
| 1003 | 'level' : 'DEBUG', |
| 1004 | 'handlers' : ['hand1'], |
| 1005 | }, |
| 1006 | }, |
| 1007 | 'root' : { |
| 1008 | 'level' : 'WARNING', |
| 1009 | }, |
| 1010 | } |
| 1011 | |
| 1012 | # config2 has a subtle configuration error that should be reported |
| 1013 | config2 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1014 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1015 | 'formatters': { |
| 1016 | 'form1' : { |
| 1017 | 'format' : '%(levelname)s ++ %(message)s', |
| 1018 | }, |
| 1019 | }, |
| 1020 | 'handlers' : { |
| 1021 | 'hand1' : { |
| 1022 | 'class' : 'logging.StreamHandler', |
| 1023 | 'formatter' : 'form1', |
| 1024 | 'level' : 'NOTSET', |
| 1025 | 'stream' : 'ext://sys.stdbout', |
| 1026 | }, |
| 1027 | }, |
| 1028 | 'loggers' : { |
| 1029 | 'compiler.parser' : { |
| 1030 | 'level' : 'DEBUG', |
| 1031 | 'handlers' : ['hand1'], |
| 1032 | }, |
| 1033 | }, |
| 1034 | 'root' : { |
| 1035 | 'level' : 'WARNING', |
| 1036 | }, |
| 1037 | } |
| 1038 | |
| 1039 | #As config1 but with a misspelt level on a handler |
| 1040 | config2a = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1041 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1042 | 'formatters': { |
| 1043 | 'form1' : { |
| 1044 | 'format' : '%(levelname)s ++ %(message)s', |
| 1045 | }, |
| 1046 | }, |
| 1047 | 'handlers' : { |
| 1048 | 'hand1' : { |
| 1049 | 'class' : 'logging.StreamHandler', |
| 1050 | 'formatter' : 'form1', |
| 1051 | 'level' : 'NTOSET', |
| 1052 | 'stream' : 'ext://sys.stdout', |
| 1053 | }, |
| 1054 | }, |
| 1055 | 'loggers' : { |
| 1056 | 'compiler.parser' : { |
| 1057 | 'level' : 'DEBUG', |
| 1058 | 'handlers' : ['hand1'], |
| 1059 | }, |
| 1060 | }, |
| 1061 | 'root' : { |
| 1062 | 'level' : 'WARNING', |
| 1063 | }, |
| 1064 | } |
| 1065 | |
| 1066 | |
| 1067 | #As config1 but with a misspelt level on a logger |
| 1068 | config2b = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1069 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1070 | 'formatters': { |
| 1071 | 'form1' : { |
| 1072 | 'format' : '%(levelname)s ++ %(message)s', |
| 1073 | }, |
| 1074 | }, |
| 1075 | 'handlers' : { |
| 1076 | 'hand1' : { |
| 1077 | 'class' : 'logging.StreamHandler', |
| 1078 | 'formatter' : 'form1', |
| 1079 | 'level' : 'NOTSET', |
| 1080 | 'stream' : 'ext://sys.stdout', |
| 1081 | }, |
| 1082 | }, |
| 1083 | 'loggers' : { |
| 1084 | 'compiler.parser' : { |
| 1085 | 'level' : 'DEBUG', |
| 1086 | 'handlers' : ['hand1'], |
| 1087 | }, |
| 1088 | }, |
| 1089 | 'root' : { |
| 1090 | 'level' : 'WRANING', |
| 1091 | }, |
| 1092 | } |
| 1093 | |
| 1094 | # config3 has a less subtle configuration error |
| 1095 | config3 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1096 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1097 | 'formatters': { |
| 1098 | 'form1' : { |
| 1099 | 'format' : '%(levelname)s ++ %(message)s', |
| 1100 | }, |
| 1101 | }, |
| 1102 | 'handlers' : { |
| 1103 | 'hand1' : { |
| 1104 | 'class' : 'logging.StreamHandler', |
| 1105 | 'formatter' : 'misspelled_name', |
| 1106 | 'level' : 'NOTSET', |
| 1107 | 'stream' : 'ext://sys.stdout', |
| 1108 | }, |
| 1109 | }, |
| 1110 | 'loggers' : { |
| 1111 | 'compiler.parser' : { |
| 1112 | 'level' : 'DEBUG', |
| 1113 | 'handlers' : ['hand1'], |
| 1114 | }, |
| 1115 | }, |
| 1116 | 'root' : { |
| 1117 | 'level' : 'WARNING', |
| 1118 | }, |
| 1119 | } |
| 1120 | |
| 1121 | # config4 specifies a custom formatter class to be loaded |
| 1122 | config4 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1123 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1124 | 'formatters': { |
| 1125 | 'form1' : { |
| 1126 | '()' : __name__ + '.ExceptionFormatter', |
| 1127 | 'format' : '%(levelname)s:%(name)s:%(message)s', |
| 1128 | }, |
| 1129 | }, |
| 1130 | 'handlers' : { |
| 1131 | 'hand1' : { |
| 1132 | 'class' : 'logging.StreamHandler', |
| 1133 | 'formatter' : 'form1', |
| 1134 | 'level' : 'NOTSET', |
| 1135 | 'stream' : 'ext://sys.stdout', |
| 1136 | }, |
| 1137 | }, |
| 1138 | 'root' : { |
| 1139 | 'level' : 'NOTSET', |
| 1140 | 'handlers' : ['hand1'], |
| 1141 | }, |
| 1142 | } |
| 1143 | |
| 1144 | # As config4 but using an actual callable rather than a string |
| 1145 | config4a = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1146 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1147 | 'formatters': { |
| 1148 | 'form1' : { |
| 1149 | '()' : ExceptionFormatter, |
| 1150 | 'format' : '%(levelname)s:%(name)s:%(message)s', |
| 1151 | }, |
| 1152 | 'form2' : { |
| 1153 | '()' : __name__ + '.formatFunc', |
| 1154 | 'format' : '%(levelname)s:%(name)s:%(message)s', |
| 1155 | }, |
| 1156 | 'form3' : { |
| 1157 | '()' : formatFunc, |
| 1158 | 'format' : '%(levelname)s:%(name)s:%(message)s', |
| 1159 | }, |
| 1160 | }, |
| 1161 | 'handlers' : { |
| 1162 | 'hand1' : { |
| 1163 | 'class' : 'logging.StreamHandler', |
| 1164 | 'formatter' : 'form1', |
| 1165 | 'level' : 'NOTSET', |
| 1166 | 'stream' : 'ext://sys.stdout', |
| 1167 | }, |
| 1168 | 'hand2' : { |
| 1169 | '()' : handlerFunc, |
| 1170 | }, |
| 1171 | }, |
| 1172 | 'root' : { |
| 1173 | 'level' : 'NOTSET', |
| 1174 | 'handlers' : ['hand1'], |
| 1175 | }, |
| 1176 | } |
| 1177 | |
| 1178 | # config5 specifies a custom handler class to be loaded |
| 1179 | config5 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1180 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1181 | 'formatters': { |
| 1182 | 'form1' : { |
| 1183 | 'format' : '%(levelname)s ++ %(message)s', |
| 1184 | }, |
| 1185 | }, |
| 1186 | 'handlers' : { |
| 1187 | 'hand1' : { |
| 1188 | 'class' : __name__ + '.CustomHandler', |
| 1189 | 'formatter' : 'form1', |
| 1190 | 'level' : 'NOTSET', |
| 1191 | 'stream' : 'ext://sys.stdout', |
| 1192 | }, |
| 1193 | }, |
| 1194 | 'loggers' : { |
| 1195 | 'compiler.parser' : { |
| 1196 | 'level' : 'DEBUG', |
| 1197 | 'handlers' : ['hand1'], |
| 1198 | }, |
| 1199 | }, |
| 1200 | 'root' : { |
| 1201 | 'level' : 'WARNING', |
| 1202 | }, |
| 1203 | } |
| 1204 | |
| 1205 | # config6 specifies a custom handler class to be loaded |
| 1206 | # but has bad arguments |
| 1207 | config6 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1208 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1209 | 'formatters': { |
| 1210 | 'form1' : { |
| 1211 | 'format' : '%(levelname)s ++ %(message)s', |
| 1212 | }, |
| 1213 | }, |
| 1214 | 'handlers' : { |
| 1215 | 'hand1' : { |
| 1216 | 'class' : __name__ + '.CustomHandler', |
| 1217 | 'formatter' : 'form1', |
| 1218 | 'level' : 'NOTSET', |
| 1219 | 'stream' : 'ext://sys.stdout', |
| 1220 | '9' : 'invalid parameter name', |
| 1221 | }, |
| 1222 | }, |
| 1223 | 'loggers' : { |
| 1224 | 'compiler.parser' : { |
| 1225 | 'level' : 'DEBUG', |
| 1226 | 'handlers' : ['hand1'], |
| 1227 | }, |
| 1228 | }, |
| 1229 | 'root' : { |
| 1230 | 'level' : 'WARNING', |
| 1231 | }, |
| 1232 | } |
| 1233 | |
| 1234 | #config 7 does not define compiler.parser but defines compiler.lexer |
| 1235 | #so compiler.parser should be disabled after applying it |
| 1236 | config7 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1237 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1238 | 'formatters': { |
| 1239 | 'form1' : { |
| 1240 | 'format' : '%(levelname)s ++ %(message)s', |
| 1241 | }, |
| 1242 | }, |
| 1243 | 'handlers' : { |
| 1244 | 'hand1' : { |
| 1245 | 'class' : 'logging.StreamHandler', |
| 1246 | 'formatter' : 'form1', |
| 1247 | 'level' : 'NOTSET', |
| 1248 | 'stream' : 'ext://sys.stdout', |
| 1249 | }, |
| 1250 | }, |
| 1251 | 'loggers' : { |
| 1252 | 'compiler.lexer' : { |
| 1253 | 'level' : 'DEBUG', |
| 1254 | 'handlers' : ['hand1'], |
| 1255 | }, |
| 1256 | }, |
| 1257 | 'root' : { |
| 1258 | 'level' : 'WARNING', |
| 1259 | }, |
| 1260 | } |
| 1261 | |
| 1262 | config8 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1263 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1264 | 'disable_existing_loggers' : False, |
| 1265 | 'formatters': { |
| 1266 | 'form1' : { |
| 1267 | 'format' : '%(levelname)s ++ %(message)s', |
| 1268 | }, |
| 1269 | }, |
| 1270 | 'handlers' : { |
| 1271 | 'hand1' : { |
| 1272 | 'class' : 'logging.StreamHandler', |
| 1273 | 'formatter' : 'form1', |
| 1274 | 'level' : 'NOTSET', |
| 1275 | 'stream' : 'ext://sys.stdout', |
| 1276 | }, |
| 1277 | }, |
| 1278 | 'loggers' : { |
| 1279 | 'compiler' : { |
| 1280 | 'level' : 'DEBUG', |
| 1281 | 'handlers' : ['hand1'], |
| 1282 | }, |
| 1283 | 'compiler.lexer' : { |
| 1284 | }, |
| 1285 | }, |
| 1286 | 'root' : { |
| 1287 | 'level' : 'WARNING', |
| 1288 | }, |
| 1289 | } |
| 1290 | |
| 1291 | config9 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1292 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1293 | 'formatters': { |
| 1294 | 'form1' : { |
| 1295 | 'format' : '%(levelname)s ++ %(message)s', |
| 1296 | }, |
| 1297 | }, |
| 1298 | 'handlers' : { |
| 1299 | 'hand1' : { |
| 1300 | 'class' : 'logging.StreamHandler', |
| 1301 | 'formatter' : 'form1', |
| 1302 | 'level' : 'WARNING', |
| 1303 | 'stream' : 'ext://sys.stdout', |
| 1304 | }, |
| 1305 | }, |
| 1306 | 'loggers' : { |
| 1307 | 'compiler.parser' : { |
| 1308 | 'level' : 'WARNING', |
| 1309 | 'handlers' : ['hand1'], |
| 1310 | }, |
| 1311 | }, |
| 1312 | 'root' : { |
| 1313 | 'level' : 'NOTSET', |
| 1314 | }, |
| 1315 | } |
| 1316 | |
| 1317 | config9a = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1318 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1319 | 'incremental' : True, |
| 1320 | 'handlers' : { |
| 1321 | 'hand1' : { |
| 1322 | 'level' : 'WARNING', |
| 1323 | }, |
| 1324 | }, |
| 1325 | 'loggers' : { |
| 1326 | 'compiler.parser' : { |
| 1327 | 'level' : 'INFO', |
| 1328 | }, |
| 1329 | }, |
| 1330 | } |
| 1331 | |
| 1332 | config9b = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1333 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1334 | 'incremental' : True, |
| 1335 | 'handlers' : { |
| 1336 | 'hand1' : { |
| 1337 | 'level' : 'INFO', |
| 1338 | }, |
| 1339 | }, |
| 1340 | 'loggers' : { |
| 1341 | 'compiler.parser' : { |
| 1342 | 'level' : 'INFO', |
| 1343 | }, |
| 1344 | }, |
| 1345 | } |
| 1346 | |
| 1347 | #As config1 but with a filter added |
| 1348 | config10 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1349 | 'version': 1, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1350 | 'formatters': { |
| 1351 | 'form1' : { |
| 1352 | 'format' : '%(levelname)s ++ %(message)s', |
| 1353 | }, |
| 1354 | }, |
| 1355 | 'filters' : { |
| 1356 | 'filt1' : { |
| 1357 | 'name' : 'compiler.parser', |
| 1358 | }, |
| 1359 | }, |
| 1360 | 'handlers' : { |
| 1361 | 'hand1' : { |
| 1362 | 'class' : 'logging.StreamHandler', |
| 1363 | 'formatter' : 'form1', |
| 1364 | 'level' : 'NOTSET', |
| 1365 | 'stream' : 'ext://sys.stdout', |
| 1366 | 'filters' : ['filt1'], |
| 1367 | }, |
| 1368 | }, |
| 1369 | 'loggers' : { |
| 1370 | 'compiler.parser' : { |
| 1371 | 'level' : 'DEBUG', |
| 1372 | 'filters' : ['filt1'], |
| 1373 | }, |
| 1374 | }, |
| 1375 | 'root' : { |
| 1376 | 'level' : 'WARNING', |
| 1377 | 'handlers' : ['hand1'], |
| 1378 | }, |
| 1379 | } |
| 1380 | |
| 1381 | #As config1 but using cfg:// references |
| 1382 | config11 = { |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1383 | 'version': 1, |
| 1384 | 'true_formatters': { |
| 1385 | 'form1' : { |
| 1386 | 'format' : '%(levelname)s ++ %(message)s', |
| 1387 | }, |
| 1388 | }, |
| 1389 | 'handler_configs': { |
| 1390 | 'hand1' : { |
| 1391 | 'class' : 'logging.StreamHandler', |
| 1392 | 'formatter' : 'form1', |
| 1393 | 'level' : 'NOTSET', |
| 1394 | 'stream' : 'ext://sys.stdout', |
| 1395 | }, |
| 1396 | }, |
| 1397 | 'formatters' : 'cfg://true_formatters', |
| 1398 | 'handlers' : { |
| 1399 | 'hand1' : 'cfg://handler_configs[hand1]', |
| 1400 | }, |
| 1401 | 'loggers' : { |
| 1402 | 'compiler.parser' : { |
| 1403 | 'level' : 'DEBUG', |
| 1404 | 'handlers' : ['hand1'], |
| 1405 | }, |
| 1406 | }, |
| 1407 | 'root' : { |
| 1408 | 'level' : 'WARNING', |
| 1409 | }, |
| 1410 | } |
| 1411 | |
| 1412 | #As config11 but missing the version key |
| 1413 | config12 = { |
| 1414 | 'true_formatters': { |
| 1415 | 'form1' : { |
| 1416 | 'format' : '%(levelname)s ++ %(message)s', |
| 1417 | }, |
| 1418 | }, |
| 1419 | 'handler_configs': { |
| 1420 | 'hand1' : { |
| 1421 | 'class' : 'logging.StreamHandler', |
| 1422 | 'formatter' : 'form1', |
| 1423 | 'level' : 'NOTSET', |
| 1424 | 'stream' : 'ext://sys.stdout', |
| 1425 | }, |
| 1426 | }, |
| 1427 | 'formatters' : 'cfg://true_formatters', |
| 1428 | 'handlers' : { |
| 1429 | 'hand1' : 'cfg://handler_configs[hand1]', |
| 1430 | }, |
| 1431 | 'loggers' : { |
| 1432 | 'compiler.parser' : { |
| 1433 | 'level' : 'DEBUG', |
| 1434 | 'handlers' : ['hand1'], |
| 1435 | }, |
| 1436 | }, |
| 1437 | 'root' : { |
| 1438 | 'level' : 'WARNING', |
| 1439 | }, |
| 1440 | } |
| 1441 | |
| 1442 | #As config11 but using an unsupported version |
| 1443 | config13 = { |
| 1444 | 'version': 2, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1445 | 'true_formatters': { |
| 1446 | 'form1' : { |
| 1447 | 'format' : '%(levelname)s ++ %(message)s', |
| 1448 | }, |
| 1449 | }, |
| 1450 | 'handler_configs': { |
| 1451 | 'hand1' : { |
| 1452 | 'class' : 'logging.StreamHandler', |
| 1453 | 'formatter' : 'form1', |
| 1454 | 'level' : 'NOTSET', |
| 1455 | 'stream' : 'ext://sys.stdout', |
| 1456 | }, |
| 1457 | }, |
| 1458 | 'formatters' : 'cfg://true_formatters', |
| 1459 | 'handlers' : { |
| 1460 | 'hand1' : 'cfg://handler_configs[hand1]', |
| 1461 | }, |
| 1462 | 'loggers' : { |
| 1463 | 'compiler.parser' : { |
| 1464 | 'level' : 'DEBUG', |
| 1465 | 'handlers' : ['hand1'], |
| 1466 | }, |
| 1467 | }, |
| 1468 | 'root' : { |
| 1469 | 'level' : 'WARNING', |
| 1470 | }, |
| 1471 | } |
| 1472 | |
| 1473 | def apply_config(self, conf): |
| 1474 | logging.config.dictConfig(conf) |
| 1475 | |
| 1476 | def test_config0_ok(self): |
| 1477 | # A simple config which overrides the default settings. |
| 1478 | with captured_stdout() as output: |
| 1479 | self.apply_config(self.config0) |
| 1480 | logger = logging.getLogger() |
| 1481 | # Won't output anything |
| 1482 | logger.info(self.next_message()) |
| 1483 | # Outputs a message |
| 1484 | logger.error(self.next_message()) |
| 1485 | self.assert_log_lines([ |
| 1486 | ('ERROR', '2'), |
| 1487 | ], stream=output) |
| 1488 | # Original logger output is empty. |
| 1489 | self.assert_log_lines([]) |
| 1490 | |
| 1491 | def test_config1_ok(self, config=config1): |
| 1492 | # A config defining a sub-parser as well. |
| 1493 | with captured_stdout() as output: |
| 1494 | self.apply_config(config) |
| 1495 | logger = logging.getLogger("compiler.parser") |
| 1496 | # Both will output a message |
| 1497 | logger.info(self.next_message()) |
| 1498 | logger.error(self.next_message()) |
| 1499 | self.assert_log_lines([ |
| 1500 | ('INFO', '1'), |
| 1501 | ('ERROR', '2'), |
| 1502 | ], stream=output) |
| 1503 | # Original logger output is empty. |
| 1504 | self.assert_log_lines([]) |
| 1505 | |
| 1506 | def test_config2_failure(self): |
| 1507 | # A simple config which overrides the default settings. |
| 1508 | self.assertRaises(Exception, self.apply_config, self.config2) |
| 1509 | |
| 1510 | def test_config2a_failure(self): |
| 1511 | # A simple config which overrides the default settings. |
| 1512 | self.assertRaises(Exception, self.apply_config, self.config2a) |
| 1513 | |
| 1514 | def test_config2b_failure(self): |
| 1515 | # A simple config which overrides the default settings. |
| 1516 | self.assertRaises(Exception, self.apply_config, self.config2b) |
| 1517 | |
| 1518 | def test_config3_failure(self): |
| 1519 | # A simple config which overrides the default settings. |
| 1520 | self.assertRaises(Exception, self.apply_config, self.config3) |
| 1521 | |
| 1522 | def test_config4_ok(self): |
| 1523 | # A config specifying a custom formatter class. |
| 1524 | with captured_stdout() as output: |
| 1525 | self.apply_config(self.config4) |
| 1526 | #logger = logging.getLogger() |
| 1527 | try: |
| 1528 | raise RuntimeError() |
| 1529 | except RuntimeError: |
| 1530 | logging.exception("just testing") |
| 1531 | sys.stdout.seek(0) |
| 1532 | self.assertEquals(output.getvalue(), |
| 1533 | "ERROR:root:just testing\nGot a [RuntimeError]\n") |
| 1534 | # Original logger output is empty |
| 1535 | self.assert_log_lines([]) |
| 1536 | |
| 1537 | def test_config4a_ok(self): |
| 1538 | # A config specifying a custom formatter class. |
| 1539 | with captured_stdout() as output: |
| 1540 | self.apply_config(self.config4a) |
| 1541 | #logger = logging.getLogger() |
| 1542 | try: |
| 1543 | raise RuntimeError() |
| 1544 | except RuntimeError: |
| 1545 | logging.exception("just testing") |
| 1546 | sys.stdout.seek(0) |
| 1547 | self.assertEquals(output.getvalue(), |
| 1548 | "ERROR:root:just testing\nGot a [RuntimeError]\n") |
| 1549 | # Original logger output is empty |
| 1550 | self.assert_log_lines([]) |
| 1551 | |
| 1552 | def test_config5_ok(self): |
| 1553 | self.test_config1_ok(config=self.config5) |
| 1554 | |
| 1555 | def test_config6_failure(self): |
| 1556 | self.assertRaises(Exception, self.apply_config, self.config6) |
| 1557 | |
| 1558 | def test_config7_ok(self): |
| 1559 | with captured_stdout() as output: |
| 1560 | self.apply_config(self.config1) |
| 1561 | logger = logging.getLogger("compiler.parser") |
| 1562 | # Both will output a message |
| 1563 | logger.info(self.next_message()) |
| 1564 | logger.error(self.next_message()) |
| 1565 | self.assert_log_lines([ |
| 1566 | ('INFO', '1'), |
| 1567 | ('ERROR', '2'), |
| 1568 | ], stream=output) |
| 1569 | # Original logger output is empty. |
| 1570 | self.assert_log_lines([]) |
| 1571 | with captured_stdout() as output: |
| 1572 | self.apply_config(self.config7) |
| 1573 | logger = logging.getLogger("compiler.parser") |
| 1574 | self.assertTrue(logger.disabled) |
| 1575 | logger = logging.getLogger("compiler.lexer") |
| 1576 | # Both will output a message |
| 1577 | logger.info(self.next_message()) |
| 1578 | logger.error(self.next_message()) |
| 1579 | self.assert_log_lines([ |
| 1580 | ('INFO', '3'), |
| 1581 | ('ERROR', '4'), |
| 1582 | ], stream=output) |
| 1583 | # Original logger output is empty. |
| 1584 | self.assert_log_lines([]) |
| 1585 | |
| 1586 | #Same as test_config_7_ok but don't disable old loggers. |
| 1587 | def test_config_8_ok(self): |
| 1588 | with captured_stdout() as output: |
| 1589 | self.apply_config(self.config1) |
| 1590 | logger = logging.getLogger("compiler.parser") |
| 1591 | # Both will output a message |
| 1592 | logger.info(self.next_message()) |
| 1593 | logger.error(self.next_message()) |
| 1594 | self.assert_log_lines([ |
| 1595 | ('INFO', '1'), |
| 1596 | ('ERROR', '2'), |
| 1597 | ], stream=output) |
| 1598 | # Original logger output is empty. |
| 1599 | self.assert_log_lines([]) |
| 1600 | with captured_stdout() as output: |
| 1601 | self.apply_config(self.config8) |
| 1602 | logger = logging.getLogger("compiler.parser") |
| 1603 | self.assertFalse(logger.disabled) |
| 1604 | # Both will output a message |
| 1605 | logger.info(self.next_message()) |
| 1606 | logger.error(self.next_message()) |
| 1607 | logger = logging.getLogger("compiler.lexer") |
| 1608 | # Both will output a message |
| 1609 | logger.info(self.next_message()) |
| 1610 | logger.error(self.next_message()) |
| 1611 | self.assert_log_lines([ |
| 1612 | ('INFO', '3'), |
| 1613 | ('ERROR', '4'), |
| 1614 | ('INFO', '5'), |
| 1615 | ('ERROR', '6'), |
| 1616 | ], stream=output) |
| 1617 | # Original logger output is empty. |
| 1618 | self.assert_log_lines([]) |
| 1619 | |
| 1620 | def test_config_9_ok(self): |
| 1621 | with captured_stdout() as output: |
| 1622 | self.apply_config(self.config9) |
| 1623 | logger = logging.getLogger("compiler.parser") |
| 1624 | #Nothing will be output since both handler and logger are set to WARNING |
| 1625 | logger.info(self.next_message()) |
| 1626 | self.assert_log_lines([], stream=output) |
| 1627 | self.apply_config(self.config9a) |
| 1628 | #Nothing will be output since both handler is still set to WARNING |
| 1629 | logger.info(self.next_message()) |
| 1630 | self.assert_log_lines([], stream=output) |
| 1631 | self.apply_config(self.config9b) |
| 1632 | #Message should now be output |
| 1633 | logger.info(self.next_message()) |
| 1634 | self.assert_log_lines([ |
| 1635 | ('INFO', '3'), |
| 1636 | ], stream=output) |
| 1637 | |
| 1638 | def test_config_10_ok(self): |
| 1639 | with captured_stdout() as output: |
| 1640 | self.apply_config(self.config10) |
| 1641 | logger = logging.getLogger("compiler.parser") |
| 1642 | logger.warning(self.next_message()) |
| 1643 | logger = logging.getLogger('compiler') |
| 1644 | #Not output, because filtered |
| 1645 | logger.warning(self.next_message()) |
| 1646 | logger = logging.getLogger('compiler.lexer') |
| 1647 | #Not output, because filtered |
| 1648 | logger.warning(self.next_message()) |
| 1649 | logger = logging.getLogger("compiler.parser.codegen") |
| 1650 | #Output, as not filtered |
| 1651 | logger.error(self.next_message()) |
| 1652 | self.assert_log_lines([ |
| 1653 | ('WARNING', '1'), |
| 1654 | ('ERROR', '4'), |
| 1655 | ], stream=output) |
| 1656 | |
| 1657 | def test_config11_ok(self): |
| 1658 | self.test_config1_ok(self.config11) |
| 1659 | |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1660 | def test_config12_failure(self): |
| 1661 | self.assertRaises(Exception, self.apply_config, self.config12) |
| 1662 | |
| 1663 | def test_config13_failure(self): |
| 1664 | self.assertRaises(Exception, self.apply_config, self.config13) |
| 1665 | |
Victor Stinner | 45df820 | 2010-04-28 22:31:17 +0000 | [diff] [blame] | 1666 | @unittest.skipUnless(threading, 'listen() needs threading to work') |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1667 | def setup_via_listener(self, text): |
Benjamin Peterson | 9451a1c | 2010-03-13 22:30:34 +0000 | [diff] [blame] | 1668 | text = text.encode("utf-8") |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1669 | port = find_unused_port() |
| 1670 | t = logging.config.listen(port) |
| 1671 | t.start() |
| 1672 | t.ready.wait() |
Benjamin Peterson | a82addb | 2010-06-27 20:54:28 +0000 | [diff] [blame] | 1673 | # Now get the port allocated |
| 1674 | port = t.port |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1675 | t.ready.clear() |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1676 | try: |
| 1677 | sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM) |
| 1678 | sock.settimeout(2.0) |
| 1679 | sock.connect(('localhost', port)) |
| 1680 | |
| 1681 | slen = struct.pack('>L', len(text)) |
| 1682 | s = slen + text |
| 1683 | sentsofar = 0 |
| 1684 | left = len(s) |
| 1685 | while left > 0: |
| 1686 | sent = sock.send(s[sentsofar:]) |
| 1687 | sentsofar += sent |
| 1688 | left -= sent |
| 1689 | sock.close() |
| 1690 | finally: |
| 1691 | t.ready.wait(2.0) |
| 1692 | logging.config.stopListening() |
| 1693 | t.join(2.0) |
| 1694 | |
| 1695 | def test_listen_config_10_ok(self): |
| 1696 | with captured_stdout() as output: |
| 1697 | self.setup_via_listener(json.dumps(self.config10)) |
| 1698 | logger = logging.getLogger("compiler.parser") |
| 1699 | logger.warning(self.next_message()) |
| 1700 | logger = logging.getLogger('compiler') |
| 1701 | #Not output, because filtered |
| 1702 | logger.warning(self.next_message()) |
| 1703 | logger = logging.getLogger('compiler.lexer') |
| 1704 | #Not output, because filtered |
| 1705 | logger.warning(self.next_message()) |
| 1706 | logger = logging.getLogger("compiler.parser.codegen") |
| 1707 | #Output, as not filtered |
| 1708 | logger.error(self.next_message()) |
| 1709 | self.assert_log_lines([ |
| 1710 | ('WARNING', '1'), |
| 1711 | ('ERROR', '4'), |
| 1712 | ], stream=output) |
| 1713 | |
| 1714 | def test_listen_config_1_ok(self): |
| 1715 | with captured_stdout() as output: |
| 1716 | self.setup_via_listener(textwrap.dedent(ConfigFileTest.config1)) |
| 1717 | logger = logging.getLogger("compiler.parser") |
| 1718 | # Both will output a message |
| 1719 | logger.info(self.next_message()) |
| 1720 | logger.error(self.next_message()) |
| 1721 | self.assert_log_lines([ |
| 1722 | ('INFO', '1'), |
| 1723 | ('ERROR', '2'), |
| 1724 | ], stream=output) |
| 1725 | # Original logger output is empty. |
| 1726 | self.assert_log_lines([]) |
| 1727 | |
| 1728 | |
| 1729 | class ManagerTest(BaseTest): |
| 1730 | def test_manager_loggerclass(self): |
| 1731 | logged = [] |
| 1732 | |
| 1733 | class MyLogger(logging.Logger): |
| 1734 | def _log(self, level, msg, args, exc_info=None, extra=None): |
| 1735 | logged.append(msg) |
| 1736 | |
| 1737 | man = logging.Manager(None) |
| 1738 | self.assertRaises(TypeError, man.setLoggerClass, int) |
| 1739 | man.setLoggerClass(MyLogger) |
| 1740 | logger = man.getLogger('test') |
| 1741 | logger.warning('should appear in logged') |
| 1742 | logging.warning('should not appear in logged') |
| 1743 | |
| 1744 | self.assertEqual(logged, ['should appear in logged']) |
| 1745 | |
| 1746 | |
Benjamin Peterson | 22005fc | 2010-04-11 16:25:06 +0000 | [diff] [blame] | 1747 | class ChildLoggerTest(BaseTest): |
| 1748 | def test_child_loggers(self): |
| 1749 | r = logging.getLogger() |
| 1750 | l1 = logging.getLogger('abc') |
| 1751 | l2 = logging.getLogger('def.ghi') |
| 1752 | c1 = r.getChild('xyz') |
| 1753 | c2 = r.getChild('uvw.xyz') |
| 1754 | self.assertTrue(c1 is logging.getLogger('xyz')) |
| 1755 | self.assertTrue(c2 is logging.getLogger('uvw.xyz')) |
| 1756 | c1 = l1.getChild('def') |
| 1757 | c2 = c1.getChild('ghi') |
| 1758 | c3 = l1.getChild('def.ghi') |
| 1759 | self.assertTrue(c1 is logging.getLogger('abc.def')) |
| 1760 | self.assertTrue(c2 is logging.getLogger('abc.def.ghi')) |
| 1761 | self.assertTrue(c2 is c3) |
| 1762 | |
| 1763 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 1764 | # Set the locale to the platform-dependent default. I have no idea |
| 1765 | # why the test does this, but in any case we save the current locale |
| 1766 | # first and restore it at the end. |
| 1767 | @run_with_locale('LC_ALL', '') |
Tim Peters | 36f7e93 | 2003-07-23 00:05:07 +0000 | [diff] [blame] | 1768 | def test_main(): |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 1769 | run_unittest(BuiltinLevelsTest, BasicFilterTest, |
Vinay Sajip | db81c4c | 2010-02-25 23:13:06 +0000 | [diff] [blame] | 1770 | CustomLevelsAndFiltersTest, MemoryHandlerTest, |
| 1771 | ConfigFileTest, SocketHandlerTest, MemoryTest, |
Benjamin Peterson | 22005fc | 2010-04-11 16:25:06 +0000 | [diff] [blame] | 1772 | EncodingTest, WarningsTest, ConfigDictTest, ManagerTest, |
| 1773 | ChildLoggerTest) |
Jeremy Hylton | 096d986 | 2003-07-18 03:19:20 +0000 | [diff] [blame] | 1774 | |
Christian Heimes | 180510d | 2008-03-03 19:15:45 +0000 | [diff] [blame] | 1775 | if __name__ == "__main__": |
Neal Norwitz | b4a2df0 | 2003-01-02 14:56:39 +0000 | [diff] [blame] | 1776 | test_main() |