source: trunk/essentials/dev-lang/python/Lib/test/test_logging.py@ 3226

Last change on this file since 3226 was 3225, checked in by bird, 19 years ago

Python 2.5
File size: 20.5 KB
Line 
1#!/usr/bin/env python
2#
3# Copyright 2001-2004 by Vinay Sajip. All Rights Reserved.
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# This file is part of the Python logging distribution. See
20# http://www.red-dove.com/python_logging.html
21#
22"""Test harness for the logging module. Run all tests.
23
24Copyright (C) 2001-2002 Vinay Sajip. All Rights Reserved.
25"""
26
27import select
28import os, sys, string, struct, types, cPickle, cStringIO
29import socket, tempfile, threading, time
30import logging, logging.handlers, logging.config
31from test.test_support import run_with_locale
32
33BANNER = "-- %-10s %-6s ---------------------------------------------------\n"
34
35FINISH_UP = "Finish up, it's closing time. Messages should bear numbers 0 through 24."
36
37#----------------------------------------------------------------------------
38# Log receiver
39#----------------------------------------------------------------------------
40
41TIMEOUT = 10
42
43from SocketServer import ThreadingTCPServer, StreamRequestHandler
44
45class LogRecordStreamHandler(StreamRequestHandler):
46 """
47 Handler for a streaming logging request. It basically logs the record
48 using whatever logging policy is configured locally.
49 """
50
51 def handle(self):
52 """
53 Handle multiple requests - each expected to be a 4-byte length,
54 followed by the LogRecord in pickle format. Logs the record
55 according to whatever policy is configured locally.
56 """
57 while 1:
58 try:
59 chunk = self.connection.recv(4)
60 if len(chunk) < 4:
61 break
62 slen = struct.unpack(">L", chunk)[0]
63 chunk = self.connection.recv(slen)
64 while len(chunk) < slen:
65 chunk = chunk + self.connection.recv(slen - len(chunk))
66 obj = self.unPickle(chunk)
67 record = logging.makeLogRecord(obj)
68 self.handleLogRecord(record)
69 except:
70 raise
71
72 def unPickle(self, data):
73 return cPickle.loads(data)
74
75 def handleLogRecord(self, record):
76 logname = "logrecv.tcp." + record.name
77 #If the end-of-messages sentinel is seen, tell the server to terminate
78 if record.msg == FINISH_UP:
79 self.server.abort = 1
80 record.msg = record.msg + " (via " + logname + ")"
81 logger = logging.getLogger(logname)
82 logger.handle(record)
83
84# The server sets socketDataProcessed when it's done.
85socketDataProcessed = threading.Event()
86
87class LogRecordSocketReceiver(ThreadingTCPServer):
88 """
89 A simple-minded TCP socket-based logging receiver suitable for test
90 purposes.
91 """
92
93 allow_reuse_address = 1
94
95 def __init__(self, host='localhost',
96 port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
97 handler=LogRecordStreamHandler):
98 ThreadingTCPServer.__init__(self, (host, port), handler)
99 self.abort = 0
100 self.timeout = 1
101
102 def serve_until_stopped(self):
103 while not self.abort:
104 rd, wr, ex = select.select([self.socket.fileno()], [], [],
105 self.timeout)
106 if rd:
107 self.handle_request()
108 #notify the main thread that we're about to exit
109 socketDataProcessed.set()
110 # close the listen socket
111 self.server_close()
112
113 def process_request(self, request, client_address):
114 #import threading
115 t = threading.Thread(target = self.finish_request,
116 args = (request, client_address))
117 t.start()
118
119def runTCP(tcpserver):
120 tcpserver.serve_until_stopped()
121
122#----------------------------------------------------------------------------
123# Test 0
124#----------------------------------------------------------------------------
125
126msgcount = 0
127
128def nextmessage():
129 global msgcount
130 rv = "Message %d" % msgcount
131 msgcount = msgcount + 1
132 return rv
133
134def test0():
135 ERR = logging.getLogger("ERR")
136 ERR.setLevel(logging.ERROR)
137 INF = logging.getLogger("INF")
138 INF.setLevel(logging.INFO)
139 INF_ERR = logging.getLogger("INF.ERR")
140 INF_ERR.setLevel(logging.ERROR)
141 DEB = logging.getLogger("DEB")
142 DEB.setLevel(logging.DEBUG)
143
144 INF_UNDEF = logging.getLogger("INF.UNDEF")
145 INF_ERR_UNDEF = logging.getLogger("INF.ERR.UNDEF")
146 UNDEF = logging.getLogger("UNDEF")
147
148 GRANDCHILD = logging.getLogger("INF.BADPARENT.UNDEF")
149 CHILD = logging.getLogger("INF.BADPARENT")
150
151 #These should log
152 ERR.log(logging.FATAL, nextmessage())
153 ERR.error(nextmessage())
154
155 INF.log(logging.FATAL, nextmessage())
156 INF.error(nextmessage())
157 INF.warn(nextmessage())
158 INF.info(nextmessage())
159
160 INF_UNDEF.log(logging.FATAL, nextmessage())
161 INF_UNDEF.error(nextmessage())
162 INF_UNDEF.warn (nextmessage())
163 INF_UNDEF.info (nextmessage())
164
165 INF_ERR.log(logging.FATAL, nextmessage())
166 INF_ERR.error(nextmessage())
167
168 INF_ERR_UNDEF.log(logging.FATAL, nextmessage())
169 INF_ERR_UNDEF.error(nextmessage())
170
171 DEB.log(logging.FATAL, nextmessage())
172 DEB.error(nextmessage())
173 DEB.warn (nextmessage())
174 DEB.info (nextmessage())
175 DEB.debug(nextmessage())
176
177 UNDEF.log(logging.FATAL, nextmessage())
178 UNDEF.error(nextmessage())
179 UNDEF.warn (nextmessage())
180 UNDEF.info (nextmessage())
181
182 GRANDCHILD.log(logging.FATAL, nextmessage())
183 CHILD.log(logging.FATAL, nextmessage())
184
185 #These should not log
186 ERR.warn(nextmessage())
187 ERR.info(nextmessage())
188 ERR.debug(nextmessage())
189
190 INF.debug(nextmessage())
191 INF_UNDEF.debug(nextmessage())
192
193 INF_ERR.warn(nextmessage())
194 INF_ERR.info(nextmessage())
195 INF_ERR.debug(nextmessage())
196 INF_ERR_UNDEF.warn(nextmessage())
197 INF_ERR_UNDEF.info(nextmessage())
198 INF_ERR_UNDEF.debug(nextmessage())
199
200 INF.info(FINISH_UP)
201
202#----------------------------------------------------------------------------
203# Test 1
204#----------------------------------------------------------------------------
205
206#
207# First, we define our levels. There can be as many as you want - the only
208# limitations are that they should be integers, the lowest should be > 0 and
209# larger values mean less information being logged. If you need specific
210# level values which do not fit into these limitations, you can use a
211# mapping dictionary to convert between your application levels and the
212# logging system.
213#
214SILENT = 10
215TACITURN = 9
216TERSE = 8
217EFFUSIVE = 7
218SOCIABLE = 6
219VERBOSE = 5
220TALKATIVE = 4
221GARRULOUS = 3
222CHATTERBOX = 2
223BORING = 1
224
225LEVEL_RANGE = range(BORING, SILENT + 1)
226
227#
228# Next, we define names for our levels. You don't need to do this - in which
229# case the system will use "Level n" to denote the text for the level.
230#
231my_logging_levels = {
232 SILENT : 'Silent',
233 TACITURN : 'Taciturn',
234 TERSE : 'Terse',
235 EFFUSIVE : 'Effusive',
236 SOCIABLE : 'Sociable',
237 VERBOSE : 'Verbose',
238 TALKATIVE : 'Talkative',
239 GARRULOUS : 'Garrulous',
240 CHATTERBOX : 'Chatterbox',
241 BORING : 'Boring',
242}
243
244#
245# Now, to demonstrate filtering: suppose for some perverse reason we only
246# want to print out all except GARRULOUS messages. Let's create a filter for
247# this purpose...
248#
249class SpecificLevelFilter(logging.Filter):
250 def __init__(self, lvl):
251 self.level = lvl
252
253 def filter(self, record):
254 return self.level != record.levelno
255
256class GarrulousFilter(SpecificLevelFilter):
257 def __init__(self):
258 SpecificLevelFilter.__init__(self, GARRULOUS)
259
260#
261# Now, let's demonstrate filtering at the logger. This time, use a filter
262# which excludes SOCIABLE and TACITURN messages. Note that GARRULOUS events
263# are still excluded.
264#
265class VerySpecificFilter(logging.Filter):
266 def filter(self, record):
267 return record.levelno not in [SOCIABLE, TACITURN]
268
269def message(s):
270 sys.stdout.write("%s\n" % s)
271
272SHOULD1 = "This should only be seen at the '%s' logging level (or lower)"
273
274def test1():
275#
276# Now, tell the logging system to associate names with our levels.
277#
278 for lvl in my_logging_levels.keys():
279 logging.addLevelName(lvl, my_logging_levels[lvl])
280
281#
282# Now, define a test function which logs an event at each of our levels.
283#
284
285 def doLog(log):
286 for lvl in LEVEL_RANGE:
287 log.log(lvl, SHOULD1, logging.getLevelName(lvl))
288
289 log = logging.getLogger("")
290 hdlr = log.handlers[0]
291#
292# Set the logging level to each different value and call the utility
293# function to log events.
294# In the output, you should see that each time round the loop, the number of
295# logging events which are actually output decreases.
296#
297 for lvl in LEVEL_RANGE:
298 message("-- setting logging level to '%s' -----" %
299 logging.getLevelName(lvl))
300 log.setLevel(lvl)
301 doLog(log)
302 #
303 # Now, we demonstrate level filtering at the handler level. Tell the
304 # handler defined above to filter at level 'SOCIABLE', and repeat the
305 # above loop. Compare the output from the two runs.
306 #
307 hdlr.setLevel(SOCIABLE)
308 message("-- Filtering at handler level to SOCIABLE --")
309 for lvl in LEVEL_RANGE:
310 message("-- setting logging level to '%s' -----" %
311 logging.getLevelName(lvl))
312 log.setLevel(lvl)
313 doLog(log)
314
315 hdlr.setLevel(0) #turn off level filtering at the handler
316
317 garr = GarrulousFilter()
318 hdlr.addFilter(garr)
319 message("-- Filtering using GARRULOUS filter --")
320 for lvl in LEVEL_RANGE:
321 message("-- setting logging level to '%s' -----" %
322 logging.getLevelName(lvl))
323 log.setLevel(lvl)
324 doLog(log)
325 spec = VerySpecificFilter()
326 log.addFilter(spec)
327 message("-- Filtering using specific filter for SOCIABLE, TACITURN --")
328 for lvl in LEVEL_RANGE:
329 message("-- setting logging level to '%s' -----" %
330 logging.getLevelName(lvl))
331 log.setLevel(lvl)
332 doLog(log)
333
334 log.removeFilter(spec)
335 hdlr.removeFilter(garr)
336 #Undo the one level which clashes...for regression tests
337 logging.addLevelName(logging.DEBUG, "DEBUG")
338
339#----------------------------------------------------------------------------
340# Test 2
341#----------------------------------------------------------------------------
342
343MSG = "-- logging %d at INFO, messages should be seen every 10 events --"
344def test2():
345 logger = logging.getLogger("")
346 sh = logger.handlers[0]
347 sh.close()
348 logger.removeHandler(sh)
349 mh = logging.handlers.MemoryHandler(10,logging.WARNING, sh)
350 logger.setLevel(logging.DEBUG)
351 logger.addHandler(mh)
352 message("-- logging at DEBUG, nothing should be seen yet --")
353 logger.debug("Debug message")
354 message("-- logging at INFO, nothing should be seen yet --")
355 logger.info("Info message")
356 message("-- logging at WARNING, 3 messages should be seen --")
357 logger.warn("Warn message")
358 for i in xrange(102):
359 message(MSG % i)
360 logger.info("Info index = %d", i)
361 mh.close()
362 logger.removeHandler(mh)
363 logger.addHandler(sh)
364
365#----------------------------------------------------------------------------
366# Test 3
367#----------------------------------------------------------------------------
368
369FILTER = "a.b"
370
371def doLog3():
372 logging.getLogger("a").info("Info 1")
373 logging.getLogger("a.b").info("Info 2")
374 logging.getLogger("a.c").info("Info 3")
375 logging.getLogger("a.b.c").info("Info 4")
376 logging.getLogger("a.b.c.d").info("Info 5")
377 logging.getLogger("a.bb.c").info("Info 6")
378 logging.getLogger("b").info("Info 7")
379 logging.getLogger("b.a").info("Info 8")
380 logging.getLogger("c.a.b").info("Info 9")
381 logging.getLogger("a.bb").info("Info 10")
382
383def test3():
384 root = logging.getLogger()
385 root.setLevel(logging.DEBUG)
386 hand = root.handlers[0]
387 message("Unfiltered...")
388 doLog3()
389 message("Filtered with '%s'..." % FILTER)
390 filt = logging.Filter(FILTER)
391 hand.addFilter(filt)
392 doLog3()
393 hand.removeFilter(filt)
394
395#----------------------------------------------------------------------------
396# Test 4
397#----------------------------------------------------------------------------
398
399# config0 is a standard configuration.
400config0 = """
401[loggers]
402keys=root
403
404[handlers]
405keys=hand1
406
407[formatters]
408keys=form1
409
410[logger_root]
411level=NOTSET
412handlers=hand1
413
414[handler_hand1]
415class=StreamHandler
416level=NOTSET
417formatter=form1
418args=(sys.stdout,)
419
420[formatter_form1]
421format=%(levelname)s:%(name)s:%(message)s
422datefmt=
423"""
424
425# config1 adds a little to the standard configuration.
426config1 = """
427[loggers]
428keys=root,parser
429
430[handlers]
431keys=hand1
432
433[formatters]
434keys=form1
435
436[logger_root]
437level=NOTSET
438handlers=hand1
439
440[logger_parser]
441level=DEBUG
442handlers=hand1
443propagate=1
444qualname=compiler.parser
445
446[handler_hand1]
447class=StreamHandler
448level=NOTSET
449formatter=form1
450args=(sys.stdout,)
451
452[formatter_form1]
453format=%(levelname)s:%(name)s:%(message)s
454datefmt=
455"""
456
457# config2 has a subtle configuration error that should be reported
458config2 = string.replace(config1, "sys.stdout", "sys.stbout")
459
460# config3 has a less subtle configuration error
461config3 = string.replace(
462 config1, "formatter=form1", "formatter=misspelled_name")
463
464def test4():
465 for i in range(4):
466 conf = globals()['config%d' % i]
467 sys.stdout.write('config%d: ' % i)
468 loggerDict = logging.getLogger().manager.loggerDict
469 logging._acquireLock()
470 try:
471 saved_handlers = logging._handlers.copy()
472 saved_handler_list = logging._handlerList[:]
473 saved_loggers = loggerDict.copy()
474 finally:
475 logging._releaseLock()
476 try:
477 fn = tempfile.mktemp(".ini")
478 f = open(fn, "w")
479 f.write(conf)
480 f.close()
481 try:
482 logging.config.fileConfig(fn)
483 #call again to make sure cleanup is correct
484 logging.config.fileConfig(fn)
485 except:
486 t = sys.exc_info()[0]
487 message(str(t))
488 else:
489 message('ok.')
490 os.remove(fn)
491 finally:
492 logging._acquireLock()
493 try:
494 logging._handlers.clear()
495 logging._handlers.update(saved_handlers)
496 logging._handlerList[:] = saved_handler_list
497 loggerDict = logging.getLogger().manager.loggerDict
498 loggerDict.clear()
499 loggerDict.update(saved_loggers)
500 finally:
501 logging._releaseLock()
502
503#----------------------------------------------------------------------------
504# Test 5
505#----------------------------------------------------------------------------
506
507test5_config = """
508[loggers]
509keys=root
510
511[handlers]
512keys=hand1
513
514[formatters]
515keys=form1
516
517[logger_root]
518level=NOTSET
519handlers=hand1
520
521[handler_hand1]
522class=StreamHandler
523level=NOTSET
524formatter=form1
525args=(sys.stdout,)
526
527[formatter_form1]
528class=test.test_logging.FriendlyFormatter
529format=%(levelname)s:%(name)s:%(message)s
530datefmt=
531"""
532
533class FriendlyFormatter (logging.Formatter):
534 def formatException(self, ei):
535 return "%s... Don't panic!" % str(ei[0])
536
537
538def test5():
539 loggerDict = logging.getLogger().manager.loggerDict
540 logging._acquireLock()
541 try:
542 saved_handlers = logging._handlers.copy()
543 saved_handler_list = logging._handlerList[:]
544 saved_loggers = loggerDict.copy()
545 finally:
546 logging._releaseLock()
547 try:
548 fn = tempfile.mktemp(".ini")
549 f = open(fn, "w")
550 f.write(test5_config)
551 f.close()
552 logging.config.fileConfig(fn)
553 try:
554 raise KeyError
555 except KeyError:
556 logging.exception("just testing")
557 os.remove(fn)
558 finally:
559 logging._acquireLock()
560 try:
561 logging._handlers.clear()
562 logging._handlers.update(saved_handlers)
563 logging._handlerList[:] = saved_handler_list
564 loggerDict = logging.getLogger().manager.loggerDict
565 loggerDict.clear()
566 loggerDict.update(saved_loggers)
567 finally:
568 logging._releaseLock()
569
570
571#----------------------------------------------------------------------------
572# Test Harness
573#----------------------------------------------------------------------------
574def banner(nm, typ):
575 sep = BANNER % (nm, typ)
576 sys.stdout.write(sep)
577 sys.stdout.flush()
578
579def test_main_inner():
580 rootLogger = logging.getLogger("")
581 rootLogger.setLevel(logging.DEBUG)
582 hdlr = logging.StreamHandler(sys.stdout)
583 fmt = logging.Formatter(logging.BASIC_FORMAT)
584 hdlr.setFormatter(fmt)
585 rootLogger.addHandler(hdlr)
586
587 # Find an unused port number
588 port = logging.handlers.DEFAULT_TCP_LOGGING_PORT
589 while port < logging.handlers.DEFAULT_TCP_LOGGING_PORT+100:
590 try:
591 tcpserver = LogRecordSocketReceiver(port=port)
592 except socket.error:
593 port += 1
594 else:
595 break
596 else:
597 raise ImportError, "Could not find unused port"
598
599
600 #Set up a handler such that all events are sent via a socket to the log
601 #receiver (logrecv).
602 #The handler will only be added to the rootLogger for some of the tests
603 shdlr = logging.handlers.SocketHandler('localhost', port)
604
605 #Configure the logger for logrecv so events do not propagate beyond it.
606 #The sockLogger output is buffered in memory until the end of the test,
607 #and printed at the end.
608 sockOut = cStringIO.StringIO()
609 sockLogger = logging.getLogger("logrecv")
610 sockLogger.setLevel(logging.DEBUG)
611 sockhdlr = logging.StreamHandler(sockOut)
612 sockhdlr.setFormatter(logging.Formatter(
613 "%(name)s -> %(levelname)s: %(message)s"))
614 sockLogger.addHandler(sockhdlr)
615 sockLogger.propagate = 0
616
617 #Set up servers
618 threads = []
619 #sys.stdout.write("About to start TCP server...\n")
620 threads.append(threading.Thread(target=runTCP, args=(tcpserver,)))
621
622 for thread in threads:
623 thread.start()
624 try:
625 banner("log_test0", "begin")
626
627 rootLogger.addHandler(shdlr)
628 test0()
629 # XXX(nnorwitz): Try to fix timing related test failures.
630 # This sleep gives us some extra time to read messages.
631 # The test generally only fails on Solaris without this sleep.
632 time.sleep(2.0)
633 shdlr.close()
634 rootLogger.removeHandler(shdlr)
635
636 banner("log_test0", "end")
637
638 for t in range(1,6):
639 banner("log_test%d" % t, "begin")
640 globals()['test%d' % t]()
641 banner("log_test%d" % t, "end")
642
643 finally:
644 #wait for TCP receiver to terminate
645 socketDataProcessed.wait()
646 # ensure the server dies
647 tcpserver.abort = 1
648 for thread in threads:
649 thread.join(2.0)
650 banner("logrecv output", "begin")
651 sys.stdout.write(sockOut.getvalue())
652 sockOut.close()
653 sockLogger.removeHandler(sockhdlr)
654 sockhdlr.close()
655 banner("logrecv output", "end")
656 sys.stdout.flush()
657 try:
658 hdlr.close()
659 except:
660 pass
661 rootLogger.removeHandler(hdlr)
662
663# Set the locale to the platform-dependent default. I have no idea
664# why the test does this, but in any case we save the current locale
665# first and restore it at the end.
666@run_with_locale('LC_ALL', '')
667def test_main():
668 # Save and restore the original root logger level across the tests.
669 # Otherwise, e.g., if any test using cookielib runs after test_logging,
670 # cookielib's debug-level logger tries to log messages, leading to
671 # confusing:
672 # No handlers could be found for logger "cookielib"
673 # output while the tests are running.
674 root_logger = logging.getLogger("")
675 original_logging_level = root_logger.getEffectiveLevel()
676 try:
677 test_main_inner()
678 finally:
679 root_logger.setLevel(original_logging_level)
680
681if __name__ == "__main__":
682 sys.stdout.write("test_logging\n")
683 test_main()
Note: See TracBrowser for help on using the repository browser.