Add logging module and unittest in lib/python/isc/log,

also add log in xfrout module for testing.
Currently, logging module supports three channels:stderr
file and syslog.




git-svn-id: svn://bind10.isc.org/svn/bind10/branches/trac176@1946 e5f2f494-b856-4b98-b285-d166d9295462

configure.ac

@@ -396,6 +396,8 @@ AC_CONFIG_FILES([Makefile
                  src/lib/python/isc/cc/tests/Makefile
                  src/lib/python/isc/config/Makefile
                  src/lib/python/isc/config/tests/Makefile
+                 src/lib/python/isc/log/Makefile
+                 src/lib/python/isc/log/tests/Makefile
                  src/lib/config/Makefile
                  src/lib/config/tests/Makefile
                  src/lib/dns/Makefile

src/bin/xfrout/xfrout.py.in

@@ -26,6 +26,7 @@ from isc.datasrc import sqlite3_ds
 from socketserver import *
 import os
 from isc.config.ccsession import *
+from isc.log.log import *
 from isc.cc import SessionError
 import socket
 from optparse import OptionParser, OptionValueError
@@ -276,7 +277,7 @@ class XfroutSession(BaseRequestHandler):
 class UnixSockServer(ThreadingUnixStreamServer):
     '''The unix domain socket server which accept xfr query sent from auth server.'''
 
-    def __init__(self, sock_file, handle_class, shutdown_event, config_data):
+    def __init__(self, sock_file, handle_class, shutdown_event, config_data, log):
         try:
             os.unlink(sock_file)
         except:
@@ -287,23 +288,30 @@ class UnixSockServer(ThreadingUnixStreamServer):
         self._lock = threading.Lock()
         self._transfers_counter = 0
         self._shutdown_event = shutdown_event
+        self._log = log
         self.update_config_data(config_data)
     
 
     def shutdown(self):
+        self._log.log_message('warning', 'Xfrout process will is shutting down')
         ThreadingUnixStreamServer.shutdown(self)
         try:
             os.unlink(self._sock_file)
         except:
-            pass
+            #pass
+            self._log.log_message('error', 'OS unlink sock file exception while shutting down')
 
     def update_config_data(self, new_config):
         '''Apply the new config setting of xfrout module. '''
 
+        self._log.log_message('info', 'update config data start')
         self._lock.acquire()
         self._max_transfers_out = new_config.get('transfers_out')
+        self._log.log_message('debug', 'max transfer out : %d', self._max_transfers_out)
         self._db_file = new_config.get('db_file')
+        self._log.log_message('debug', 'db file name : %s', self._db_file)
         self._lock.release()
+        self._log.log_message('info', 'update config data complete')
 
     def get_db_file(self):
         self._lock.acquire()
@@ -339,11 +347,15 @@ def listen_on_xfr_query(unix_socket_server):
 class XfroutServer:
     def __init__(self):
         self._unix_socket_server = None
+        self._log = None
         self._listen_sock_file = UNIX_SOCKET_FILE 
         self._shutdown_event = threading.Event()
         self._cc = isc.config.ModuleCCSession(SPECFILE_LOCATION, self.config_handler, self.command_handler)
         self._config_data = self._cc.get_full_config()
         self._cc.start()
+        self._log = isc.log.ModuleLogger(self._config_data.get('log_name'), self._config_data.get('log_file'),
+                                         self._config_data.get('severity'), self._config_data.get('versions'),
+                                         self._config_data.get('max_bytes'), True)
         self._start_xfr_query_listener()
 
 
@@ -351,7 +363,8 @@ class XfroutServer:
         '''Start a new thread to accept xfr query. '''
     
         self._unix_socket_server = UnixSockServer(self._listen_sock_file, XfroutSession, 
-                                                  self._shutdown_event, self._config_data);
+                                                  self._shutdown_event, self._config_data,
+                                                  self._log);
         listener = threading.Thread(target = listen_on_xfr_query, args = (self._unix_socket_server,))
         listener.start()
 
@@ -365,6 +378,10 @@ class XfroutServer:
                 continue
             self._config_data[key] = new_config[key]
         
+        if self._log:
+            self._log.update_config(self._config_data.get('log_file'), self._config_data.get('severity'), 
+                                    self._config_data.get('max_bytes'), self._config_data.get('versions'))
+
         if self._unix_socket_server:
             self._unix_socket_server.update_config_data(self._config_data)
 

src/bin/xfrout/xfrout.spec.pre.in

@@ -13,6 +13,36 @@
          "item_type": "string",
          "item_optional": False,
          "item_default": '@@LOCALSTATEDIR@@/@PACKAGE@/zone.sqlite3'
+       },
+       {
+         "item_name": "log_name",
+         "item_type": "string",
+         "item_optional": False,
+         "item_default": "Xfrout"
+       },
+       {
+         "item_name": "log_file",
+    	 "item_type": "string",
+         "item_optional": False,
+    	 "item_default": "/var/log/xfrout.log"
+       },
+       {
+         "item_name": "severity",
+    	 "item_type": "string",
+         "item_optional": False,
+    	 "item_default": "debug"
+       },
+       {
+         "item_name": "versions",
+    	 "item_type": "integer",
+         "item_optional": False,
+    	 "item_default": 5
+       },
+       {
+         "item_name": "max_bytes",
+    	 "item_type": "integer",
+         "item_optional": False,
+    	 "item_default": 1048576
        }
       ],
       "commands": [

src/lib/python/isc/Makefile.am

@@ -1,4 +1,4 @@
-SUBDIRS = datasrc cc config # Util
+SUBDIRS = datasrc cc config log # Util
 
 python_PYTHON = __init__.py
 

src/lib/python/isc/__init__.py

@@ -1,3 +1,4 @@
 import isc.datasrc
 import isc.cc
 import isc.config
+import isc.log

src/lib/python/isc/log/Makefile.am

@@ -0,0 +1,6 @@
+SUBDIRS = tests
+
+python_PYTHON = __init__.py log.py
+
+pythondir = $(pyexecdir)/isc/log
+

src/lib/python/isc/log/__init__.py

@@ -0,0 +1 @@
+from isc.log.log import *

src/lib/python/isc/log/log.py

@@ -0,0 +1,195 @@
+# Copyright (C) 2010  Internet Systems Consortium.
+#
+# Permission to use, copy, modify, and distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND INTERNET SYSTEMS CONSORTIUM
+# DISCLAIMS ALL WARRANTIES WITH REGARD TO THIS SOFTWARE INCLUDING ALL
+# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL
+# INTERNET SYSTEMS CONSORTIUM BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING
+# FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT,
+# NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION
+# WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+
+import os
+import syslog
+import logging
+import logging.handlers
+
+#########################################################################
+# LEVELS: logging levels mapping
+#########################################################################
+LEVELS = {'debug' : logging.DEBUG,
+       	  'info' : logging.INFO,
+          'warning' : logging.WARNING,
+          'error' : logging.ERROR,
+          'critical' : logging.CRITICAL}
+
+formatter = logging.Formatter("%(name)s: %(levelname)s: %(message)s")
+time_formatter = logging.Formatter("%(asctime)s: %(name)s: %(levelname)s: %(message)s")
+#########################################################################
+# NullHandler: define a do-nothing handler 
+#########################################################################
+class NullHandler(logging.Handler):
+    def emit(self, record):
+        pass
+
+#########################################################################
+# RotatingFileHandler: replace RotatingFileHandler with a custom handler 
+#########################################################################
+class RotatingFileHandler(logging.handlers.RotatingFileHandler):
+
+    def __init__(self, filename, mode='a', maxBytes=0, backupCount=0, encoding=None):
+        logging.handlers.RotatingFileHandler.__init__(self, filename, mode, 
+                                                      maxBytes, backupCount,
+                                                      encoding)
+    #####################################################################
+    # shouldRollover 
+    #   Rewrite RotatingFileHandler.shouldRollover. 
+    #   If the log file is deleted, a new file will be created. 
+    #####################################################################
+    def shouldRollover(self, record):
+        if self.stream is None:                 # delay was set...
+            self.stream = self._open()
+
+        dfn = self.baseFilename                 # Is log file exist?
+        if not os.path.exists(dfn):
+            self.stream.close()
+            self.stream = self._open()
+
+        if self.maxBytes > 0:                   # are we rolling over?
+            msg = "%s\n" % self.format(record)
+            self.stream.seek(0, 2)  #due to non-posix-compliant Windows feature
+            if self.stream.tell() + len(msg) >= self.maxBytes:
+                return 1
+        return 0
+
+    ######################################################################
+    # handleError 
+    #   Rewrite RotatingFileHandler.handleError.
+    #   If raiseExceptions is false, exceptions get silently ignored.
+    ######################################################################
+    def handleError(self, record):
+        pass
+
+    ######################################################################
+    # update_config
+    #   update RotatingFileHandler configuration
+    #   input:
+    #         new log file name
+    #         max backup count
+    #         predetermined log file size
+    ######################################################################
+    def update_config(self, file_name, backup_count, max_bytes):
+        self.baseFilename = file_name
+        self.maxBytes = max_bytes
+        self.backupCount = backup_count
+
+
+#########################################################################
+# SLHandler: Replace SysLogHandler with a custom handler due to python3.1
+#            SysLogHandler issue : http://bugs.python.org/issue8148
+#########################################################################
+class SLHandler(logging.Handler):    
+    def __init__(self, ident, logopt=0, facility=syslog.LOG_USER):        
+        logging.Handler.__init__(self)        
+        self.ident = ident        
+        self.logopt = logopt        
+        self.facility = facility        
+        self.mappings = {            
+                logging.DEBUG: syslog.LOG_DEBUG,            
+                logging.INFO: syslog.LOG_INFO,            
+                logging.WARNING: syslog.LOG_WARNING,            
+                logging.ERROR: syslog.LOG_ERR,            
+                logging.CRITICAL: syslog.LOG_CRIT,            
+                }   
+        
+    def encodeLevel(self, level):        
+        return self.mappings.get(level, syslog.LOG_INFO)    
+   
+    def handleError(self, record):
+        pass
+
+    def emit(self, record):        
+        syslog.openlog(self.ident, self.logopt, self.facility)        
+        msg = self.format(record)        
+        prio = self.encodeLevel(record.levelno)        
+        syslog.syslog(prio, msg)        
+        syslog.closelog()
+
+
+#########################################################################
+# ModuleLogger: rewrite logging.Logger 
+#########################################################################
+class ModuleLogger(logging.getLoggerClass()):
+    def __init__(self, log_name, log_file, 
+                 severity = 'debug', backup_count = 0, max_bytes = 0,
+                 log_to_console = True):
+        logging.Logger.__init__(self, log_name)
+
+        # Set up a specific logger with our desired output level
+        logLevel = LEVELS.get(severity, logging.NOTSET)
+        self.setLevel(logLevel)
+        
+        null_handler = NullHandler()
+        self.addHandler(null_handler)
+
+        self.rotating_handler = None
+        self.stream_handler = None
+        self.syslog_handler = None
+        self.add_rotate_handler(log_file, max_bytes, backup_count)
+        if log_to_console:
+            self.add_stream_handler()
+        else:
+            self.add_syslog_handler()
+
+    def add_rotate_handler(self, log_file, max_bytes, backup_count):
+        # If logFile was specified
+        if(log_file != 0  and log_file != ''):
+            # Add the log message handler to the logger
+            try:
+                self.rotating_handler = RotatingFileHandler(filename = log_file, maxBytes = max_bytes, 
+                                                            backupCount = backup_count)
+                # add formatter to ch
+                self.rotating_handler.setFormatter(time_formatter)
+                self.addHandler(self.rotating_handler)
+            except IOError:
+                pass
+
+    def add_stream_handler(self):
+        self.stream_handler = logging.StreamHandler()
+        self.stream_handler.setFormatter(time_formatter)
+        self.addHandler(self.stream_handler)
+
+    def add_syslog_handler(self):
+        self.syslog_handler = SLHandler('BIND10')
+        self.syslog_handler.setFormatter(formatter)
+        #set syslog handler level info
+        self.syslog_handler.setLevel(logging.INFO)
+        self.addHandler(self.syslog_handler)
+
+    def update_rotate_handler(self, log_file, max_bytes, backup_count):
+        # If logFile was specified
+        if (self.rotating_handler not in self.handlers):
+            pass
+        else:
+            if(log_file != 0 and log_file != ''):
+                self.rotating_handler.update_config(log_file, max_bytes, backup_count)
+            else:
+                self.rotating_handler.flush()
+                self.rotating_handler.close()
+                self.removeHandler(self.rotating_handler)
+
+    def update_config(self, file_name, level, max_bytes, backup_count):
+        logLevel = LEVELS.get(level, logging.NOTSET)
+        if(logLevel != self.getEffectiveLevel()):
+            self.setLevel(logLevel)
+        self.update_rotate_handler(file_name, backup_count, max_bytes)
+
+    def log_message(self, level, msg, *args, **kwargs):
+        logLevel = LEVELS.get(level, logging.NOTSET)
+        self.log(logLevel, msg, *args, **kwargs)
+
+

src/lib/python/isc/log/tests/Makefile.am

@@ -0,0 +1,12 @@
+PYTESTS = log_test.py
+EXTRA_DIST = $(PYTESTS)
+
+# later will have configure option to choose this, like: coverage run --branch
+PYCOVERAGE = $(PYTHON)
+# test using command-line arguments, so use check-local target instead of TESTS
+check-local:
+	for pytest in $(PYTESTS) ; do \
+	echo Running test: $$pytest ; \
+	env PYTHONPATH=$(abs_top_srcdir)/src/lib/python \
+	$(PYCOVERAGE) $(abs_srcdir)/$$pytest ; \
+	done

src/lib/python/isc/log/tests/log_test.py

@@ -0,0 +1,121 @@
+from isc.log.log import *
+import unittest
+import os
+
+class TestRotateFileHandler(unittest.TestCase):
+
+    def setUp(self):
+        self.handler = RotatingFileHandler('/var/log/rotate_file_handler.log', 1024, 5)
+
+    def test_shouldRollover(self):
+        if(os.path.exists('/var/log/rotate_file_handler.log')):
+            os.remove('/var/log/rotate_file_handler.log')
+        record = logging.LogRecord(None, None, "", 0, "rotate file handler", (), None, None)
+        self.handler.shouldRollover(record)
+        self.assertTrue(os.path.exists('/var/log/rotate_file_handler.log'))
+
+    def test_update_config(self):
+        self.handler.update_config('/var/log/rotate_file_handler2.log', 512, 3)
+        self.assertEqual(self.handler.baseFilename, '/var/log/rotate_file_handler2.log')
+        self.assertEqual(self.handler.maxBytes, 3)
+        self.assertEqual(self.handler.backupCount, 512)
+
+
+class TestLogging(unittest.TestCase):
+
+    def setUp(self):
+        self.file_stream_logger = ModuleLogger('File_Stream_Logger', '/var/log/FileStreamLogger.log',
+                                               'debug', 5, 1024, True)
+        self.syslog_logger = ModuleLogger('SysLogger', '', 'info', 5, 1024, False)
+
+    def test_logging_init(self):
+        self.assertNotEqual(self.file_stream_logger.rotating_handler, None)
+        self.assertNotEqual(self.file_stream_logger.stream_handler, None)
+        self.assertEqual(self.file_stream_logger.syslog_handler, None)
+
+        ret = self.file_stream_logger.rotating_handler in self.file_stream_logger.handlers
+        self.assertTrue(ret)
+        ret = self.file_stream_logger.stream_handler in self.file_stream_logger.handlers
+        self.assertTrue(ret)
+        ret = self.file_stream_logger.syslog_handler in self.file_stream_logger.handlers
+        self.assertFalse(ret)
+        logLevel = LEVELS.get('debug', logging.NOTSET)
+        self.assertEqual(self.file_stream_logger.getEffectiveLevel(), logLevel)
+
+        self.assertEqual(self.syslog_logger.rotating_handler, None)
+        self.assertEqual(self.syslog_logger.stream_handler, None)
+        self.assertNotEqual(self.syslog_logger.syslog_handler, None)
+        ret = self.syslog_logger.rotating_handler in self.syslog_logger.handlers
+        self.assertFalse(ret)
+        ret = self.syslog_logger.stream_handler in self.syslog_logger.handlers
+        self.assertFalse(ret)
+        ret = self.syslog_logger.syslog_handler in self.syslog_logger.handlers
+        self.assertTrue(ret)
+
+        logLevel = LEVELS.get('info', logging.NOTSET)
+        self.assertEqual(self.syslog_logger.getEffectiveLevel(), logLevel)
+
+    def test_add_rotate_handler(self):
+        if(self.syslog_logger.rotating_handler in self.syslog_logger.handlers):
+            self.syslog_logger.removeHandler(self.syslog_logger.rotating_handler)
+        
+        self.syslog_logger.add_rotate_handler('', 1024, 5)
+        ret = self.syslog_logger.rotating_handler in self.syslog_logger.handlers
+        self.assertFalse(ret)
+
+        self.syslog_logger.add_rotate_handler('/var/log/RotateFile.log', 1024, 5)
+        ret = self.syslog_logger.rotating_handler in self.syslog_logger.handlers
+        self.assertTrue(ret)
+
+    def test_add_stream_handler(self):
+        if(self.file_stream_logger.stream_handler in self.file_stream_logger.handlers):
+            self.file_stream_logger.removeHandler(self.file_stream_logger.stream_handler)
+
+        self.file_stream_logger.add_stream_handler()
+        ret = self.file_stream_logger.stream_handler in self.file_stream_logger.handlers
+        self.assertTrue(ret)
+
+    def test_add_syslog_handler(self):
+        if(self.syslog_logger.syslog_handler in self.syslog_logger.handlers):
+            self.syslog_logger.removeHandler(self.syslog_logger.syslog_handler)
+
+        self.syslog_logger.add_syslog_handler()
+        ret = self.syslog_logger.syslog_handler in self.syslog_logger.handlers
+        self.assertTrue(ret)
+
+    def test_update_rotate_handler(self):
+        self.file_stream_logger.update_rotate_handler('/var/log/RotateFile', 4, 1024)
+        ret = self.file_stream_logger.rotating_handler in self.file_stream_logger.handlers
+        self.assertTrue(ret)
+
+        self.file_stream_logger.update_rotate_handler('', 5, 1024)
+        ret = self.file_stream_logger.rotating_handler in self.file_stream_logger.handlers
+        self.assertFalse(ret)
+
+        self.file_stream_logger.update_rotate_handler('/var/log/RotateFile', 4, 1024)
+        ret = self.file_stream_logger.rotating_handler in self.file_stream_logger.handlers
+        self.assertFalse(ret)
+
+    def test_update_config(self):
+        self.file_stream_logger.update_config('/var/log/RotateFile','error', 4, 1024)
+        logLevel = LEVELS.get('error', logging.NOTSET)
+        self.assertEqual(self.file_stream_logger.getEffectiveLevel(), logLevel)
+
+    def test_log_message(self):
+        print ('\r')
+        #output log message to stderr and file
+        self.file_stream_logger.log_message('debug', 'Debug message')
+        self.file_stream_logger.log_message('info', 'Info message')
+        self.file_stream_logger.log_message('warning', 'Warning message')
+        self.file_stream_logger.log_message('error', 'Error message')
+        self.file_stream_logger.log_message('critical', 'Critical message')
+
+        #output log message to syslog 
+        self.syslog_logger.log_message('debug', 'Debug message')
+        self.syslog_logger.log_message('info', 'Info message')
+        self.syslog_logger.log_message('warning', 'Warning message')
+        self.syslog_logger.log_message('error', 'Error message')
+        self.syslog_logger.log_message('critical', 'Critical message')
+
+if __name__ == '__main__':
+    unittest.main()