home *** CD-ROM | disk | FTP | other *** search
/ H4CK3R 14 / hacker14.iso / programacao / pythonwin / python.exe / TEST_LOGGING.PY < prev    next >
Encoding:
Python Source  |  2003-07-23  |  16.2 KB  |  492 lines
  1. #!/usr/bin/env python
  2. #
  3. # Copyright 2001-2002 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.  
  24. Copyright (C) 2001-2002 Vinay Sajip. All Rights Reserved.
  25. """
  26.  
  27. import select
  28. import os, sys, string, struct, types, cPickle, cStringIO
  29. import socket, threading, time
  30. import logging, logging.handlers, logging.config
  31.  
  32. BANNER = "-- %-10s %-6s ---------------------------------------------------\n"
  33.  
  34. FINISH_UP = "Finish up, it's closing time. Messages should bear numbers 0 through 24."
  35.  
  36. #----------------------------------------------------------------------------
  37. # Log receiver
  38. #----------------------------------------------------------------------------
  39.  
  40. TIMEOUT         = 10
  41.  
  42. from SocketServer import ThreadingTCPServer, StreamRequestHandler
  43.  
  44. class LogRecordStreamHandler(StreamRequestHandler):
  45.     """
  46.     Handler for a streaming logging request. It basically logs the record
  47.     using whatever logging policy is configured locally.
  48.     """
  49.  
  50.     def handle(self):
  51.         """
  52.         Handle multiple requests - each expected to be a 4-byte length,
  53.         followed by the LogRecord in pickle format. Logs the record
  54.         according to whatever policy is configured locally.
  55.         """
  56.         while 1:
  57.             try:
  58.                 chunk = self.connection.recv(4)
  59.                 if len(chunk) < 4:
  60.                     break
  61.                 slen = struct.unpack(">L", chunk)[0]
  62.                 chunk = self.connection.recv(slen)
  63.                 while len(chunk) < slen:
  64.                     chunk = chunk + self.connection.recv(slen - len(chunk))
  65.                 obj = self.unPickle(chunk)
  66.                 record = logging.makeLogRecord(obj)
  67.                 self.handleLogRecord(record)
  68.             except:
  69.                 raise
  70.  
  71.     def unPickle(self, data):
  72.         return cPickle.loads(data)
  73.  
  74.     def handleLogRecord(self, record):
  75.         logname = "logrecv.tcp." + record.name
  76.         #If the end-of-messages sentinel is seen, tell the server to terminate
  77.         if record.msg == FINISH_UP:
  78.             self.server.abort = 1
  79.         record.msg = record.msg + " (via " + logname + ")"
  80.         logger = logging.getLogger(logname)
  81.         logger.handle(record)
  82.  
  83. # The server sets socketDataProcessed when it's done.
  84. socketDataProcessed = threading.Event()
  85.  
  86. class LogRecordSocketReceiver(ThreadingTCPServer):
  87.     """
  88.     A simple-minded TCP socket-based logging receiver suitable for test
  89.     purposes.
  90.     """
  91.  
  92.     allow_reuse_address = 1
  93.  
  94.     def __init__(self, host='localhost',
  95.                              port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
  96.                      handler=LogRecordStreamHandler):
  97.         ThreadingTCPServer.__init__(self, (host, port), handler)
  98.         self.abort = 0
  99.         self.timeout = 1
  100.  
  101.     def serve_until_stopped(self):
  102.         abort = 0
  103.         while not abort:
  104.             rd, wr, ex = select.select([self.socket.fileno()],
  105.                                        [], [],
  106.                                        self.timeout)
  107.             if rd:
  108.                 self.handle_request()
  109.             abort = self.abort
  110.         #notify the main thread that we're about to exit
  111.         socketDataProcessed.set()
  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.  
  119. def runTCP(tcpserver):
  120.     tcpserver.serve_until_stopped()
  121.  
  122. #----------------------------------------------------------------------------
  123. # Test 0
  124. #----------------------------------------------------------------------------
  125.  
  126. msgcount = 0
  127.  
  128. def nextmessage():
  129.     global msgcount
  130.     rv = "Message %d" % msgcount
  131.     msgcount = msgcount + 1
  132.     return rv
  133.  
  134. def 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. #
  214. SILENT      = 10
  215. TACITURN    = 9
  216. TERSE       = 8
  217. EFFUSIVE    = 7
  218. SOCIABLE    = 6
  219. VERBOSE     = 5
  220. TALKATIVE   = 4
  221. GARRULOUS   = 3
  222. CHATTERBOX  = 2
  223. BORING      = 1
  224.  
  225. LEVEL_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. #
  231. my_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. #
  249. class 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.  
  256. class 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. #
  265. class VerySpecificFilter(logging.Filter):
  266.     def filter(self, record):
  267.         return record.levelno not in [SOCIABLE, TACITURN]
  268.  
  269. def message(s):
  270.     sys.stdout.write("%s\n" % s)
  271.  
  272. SHOULD1 = "This should only be seen at the '%s' logging level (or lower)"
  273.  
  274. def 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.  
  343. MSG = "-- logging %d at INFO, messages should be seen every 10 events --"
  344. def 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.  
  369. FILTER = "a.b"
  370.  
  371. def 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.  
  383. def 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 Harness
  397. #----------------------------------------------------------------------------
  398. def banner(nm, typ):
  399.     sep = BANNER % (nm, typ)
  400.     sys.stdout.write(sep)
  401.     sys.stdout.flush()
  402.  
  403. def test_main_inner():
  404.     rootLogger = logging.getLogger("")
  405.     rootLogger.setLevel(logging.DEBUG)
  406.     hdlr = logging.StreamHandler(sys.stdout)
  407.     fmt = logging.Formatter(logging.BASIC_FORMAT)
  408.     hdlr.setFormatter(fmt)
  409.     rootLogger.addHandler(hdlr)
  410.  
  411.     #Set up a handler such that all events are sent via a socket to the log
  412.     #receiver (logrecv).
  413.     #The handler will only be added to the rootLogger for some of the tests
  414.     hdlr = logging.handlers.SocketHandler('localhost',
  415.                                    logging.handlers.DEFAULT_TCP_LOGGING_PORT)
  416.  
  417.     #Configure the logger for logrecv so events do not propagate beyond it.
  418.     #The sockLogger output is buffered in memory until the end of the test,
  419.     #and printed at the end.
  420.     sockOut = cStringIO.StringIO()
  421.     sockLogger = logging.getLogger("logrecv")
  422.     sockLogger.setLevel(logging.DEBUG)
  423.     sockhdlr = logging.StreamHandler(sockOut)
  424.     sockhdlr.setFormatter(logging.Formatter(
  425.                                    "%(name)s -> %(levelname)s: %(message)s"))
  426.     sockLogger.addHandler(sockhdlr)
  427.     sockLogger.propagate = 0
  428.  
  429.     #Set up servers
  430.     threads = []
  431.     tcpserver = LogRecordSocketReceiver()
  432.     #sys.stdout.write("About to start TCP server...\n")
  433.     threads.append(threading.Thread(target=runTCP, args=(tcpserver,)))
  434.  
  435.     for thread in threads:
  436.         thread.start()
  437.     try:
  438.         banner("log_test0", "begin")
  439.  
  440.         rootLogger.addHandler(hdlr)
  441.         test0()
  442.         hdlr.close()
  443.         rootLogger.removeHandler(hdlr)
  444.  
  445.         banner("log_test0", "end")
  446.  
  447.         banner("log_test1", "begin")
  448.         test1()
  449.         banner("log_test1", "end")
  450.  
  451.         banner("log_test2", "begin")
  452.         test2()
  453.         banner("log_test2", "end")
  454.  
  455.         banner("log_test3", "begin")
  456.         test3()
  457.         banner("log_test3", "end")
  458.  
  459.     finally:
  460.         #wait for TCP receiver to terminate
  461.         socketDataProcessed.wait()
  462.         for thread in threads:
  463.             thread.join()
  464.         banner("logrecv output", "begin")
  465.         sys.stdout.write(sockOut.getvalue())
  466.         sockOut.close()
  467.         banner("logrecv output", "end")
  468.         sys.stdout.flush()
  469.  
  470. def test_main():
  471.     import locale
  472.     # Set the locale to the platform-dependent default.  I have no idea
  473.     # why the test does this, but in any case we save the current locale
  474.     # first so we can restore it at the end.
  475.     try:
  476.         original_locale = locale.setlocale(locale.LC_ALL)
  477.         locale.setlocale(locale.LC_ALL, '')
  478.     except (ValueError, locale.Error):
  479.         # this happens on a Solaris box which only supports "C" locale
  480.         # or a Mac OS X box which supports very little locale stuff at all
  481.         original_locale = None
  482.  
  483.     try:
  484.         test_main_inner()
  485.     finally:
  486.         if original_locale is not None:
  487.             locale.setlocale(locale.LC_ALL, original_locale)
  488.  
  489. if __name__ == "__main__":
  490.     sys.stdout.write("test_logging\n")
  491.     test_main()
  492.