merged trac #267: python log shouldn't die with OSError

git-svn-id: svn://bind10.isc.org/svn/bind10/trunk@3137 e5f2f494-b856-4b98-b285-d166d9295462

ChangeLog

@@ -1,3 +1,7 @@
+  103.	[bug]		jerry
+	lib/python/isc/log: Fixed an issue with python logging,
+	python log shouldn't die with OSError.(Trac #267, r3137)
+				   
   102.	[build]		jinmei
 	Disable threads in ASIO to minimize build time dependency.
 	(Trac #345, r3100)
@@ -89,8 +93,8 @@ bind10-devel-20100917 released on September 17, 2010
 	zone axfr/ixfr finishing, the server will notify its slaves.
 	(Trac #289, svn r2737)
 
-  86.   [func]		jerry
-    	bin/zonemgr: Added zone manager module. The zone manager is one 
+  86.	[func]		jerry
+	bin/zonemgr: Added zone manager module. The zone manager is one 
 	of the co-operating processes of BIND10, which keeps track of 
 	timers and other information necessary for BIND10 to act as a 
 	slave. (Trac #215, svn r2737)

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

@@ -19,6 +19,7 @@ Copyright (C) 2010  Internet Systems Consortium.
 To use, simply 'import isc.log.log' and log away!
 """
 import os
+import sys
 import syslog
 import logging
 import logging.handlers
@@ -31,47 +32,73 @@ LEVELS = {'debug' : logging.DEBUG,
           'error' : logging.ERROR,
           'critical' : logging.CRITICAL}
 
-
 FORMATTER = logging.Formatter("%(name)s: %(levelname)s: %(message)s")
 TIME_FORMATTER = logging.Formatter("%(asctime)s.%(msecs)03d %(name)s: %(levelname)s: %(message)s",
                                    "%d-%b-%Y %H:%M:%S")
 
+def log_err(err_type, err_msg):
+    sys.stderr.write(err_type + ": " + "%s.\n" % str(err_msg)[str(err_msg).find(']')+1:])
+
+
 class NSFileLogHandler(logging.handlers.RotatingFileHandler):
     """RotatingFileHandler: replace RotatingFileHandler with a custom handler"""
 
     def __init__(self, filename, mode='a', maxBytes=0, backupCount=0, encoding=None, delay=0):
-        dir = os.path.split(filename)
-        if not (os.path.exists(dir[0])):
-            os.makedirs(dir[0])
-        super(NSFileLogHandler, self).__init__(filename, mode, maxBytes,
+        abs_file_name = self._get_abs_file_path(filename)
+        """Create log directory beforehand, because the underlying logging framework won't 
+        create non-exsiting log directory on writing logs.
+        """
+        if not (os.path.exists(os.path.dirname(abs_file_name))):
+            os.makedirs(os.path.dirname(abs_file_name))
+        super(NSFileLogHandler, self).__init__(abs_file_name, mode, maxBytes,
                                                 backupCount, encoding, delay)
 
+    def handleError(self, record):
+        """Overwrite handleError to provide more user-friendly error messages"""
+        if logging.raiseExceptions:
+            ei = sys.exc_info()
+            if (ei[1]):
+                sys.stderr.write("[b10-logging] : " + str(ei[1]))
+
+    def _get_abs_file_path(self, file_name):
+        """ Get absolute file path"""
+        # For a bare filename, log_dir will be set the current directory.
+        if not os.path.dirname(file_name):
+            abs_file_dir = os.getcwd()
+        else:
+            abs_file_dir = os.path.abspath(os.path.dirname(file_name))
+        abs_file_name = os.path.join(abs_file_dir, os.path.basename(file_name))
+        return abs_file_name
+
     def shouldRollover(self, record):
         """Rewrite RotatingFileHandler.shouldRollover. 
        
         If the log file is deleted at runtime, a new file will be created.
         """
-        dfn = self.baseFilename                 
+        dfn = self.baseFilename
         if (self.stream) and (not os.path.exists(dfn)): #Does log file exist?
-            self.stream.close()
-            dir = os.path.split(dfn)
-            if not (os.path.exists(dir[0])): #Does log subdirectory exist?
-                os.makedirs(dir[0])
+            self.stream = None
+            """ Log directory may be deleted while bind10 running or updated with a
+             non-existing directory. Need to create log directory beforehand, because
+             the underlying logging framework won't create non-exsiting log directory
+             on writing logs.
+             """
+            if not (os.path.exists(os.path.dirname(dfn))): #Does log subdirectory exist?
+                os.makedirs(os.path.dirname(dfn))
             self.stream = self._open()
         return super(NSFileLogHandler, self).shouldRollover(record)
     
     def update_config(self, file_name, backup_count, max_bytes):
         """Update RotatingFileHandler configuration.
+        Changes will be picked up in the next call to shouldRollover().
 
-        If the file path does not exist, we will use the old log file.
         input:
             log file name
             max backup count
             predetermined log file size
         """
-        dir = os.path.split(file_name)
-        if (os.path.exists(dir[0])):
-            self.baseFilename = file_name
+        abs_file_name = self._get_abs_file_path(file_name)
+        self.baseFilename = abs_file_name 
         self.maxBytes = max_bytes
         self.backupCount = backup_count
 
@@ -162,8 +189,9 @@ class NSLogger(logging.getLoggerClass()):
             try:
                 self._file_handler = NSFileLogHandler(filename = log_file,
                                           maxBytes = max_bytes, backupCount = backup_count)
-            except IOError:
+            except (IOError, OSError) as e:
                 self._file_handler = None
+                log_err("[b10-logging] Add file handler fail", str(e))
                 return
             self._file_handler.setFormatter(TIME_FORMATTER)
             self.addHandler(self._file_handler)
@@ -244,6 +272,9 @@ class NSLogger(logging.getLoggerClass()):
         logger.log_message('info', "We have a %s", "mysterious problem").
         """
         logLevel = LEVELS.get(level, logging.NOTSET)
-        self.log(logLevel, msg, *args, **kwargs)
+        try:
+            self.log(logLevel, msg, *args, **kwargs)
+        except (TypeError, KeyError) as e:
+            sys.stderr.write("[b10-logging] Log message fail %s\n" % (str(e)))
 
 

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

@@ -20,6 +20,7 @@
 from isc.log.log import *
 import unittest
 import os
+import sys
 import tempfile
 
 
@@ -46,21 +47,48 @@ class TestRotateFileHandler(unittest.TestCase):
         self.handler.shouldRollover(record)
         self.assertTrue(os.path.exists(self.FILE_LOG1.name))
 
+    def test_get_absolute_file_path(self):
+        abs_file_name = self.handler._get_abs_file_path(self.FILE_LOG1.name)
+        self.assertEqual(abs_file_name, self.FILE_LOG1.name)
+        # test bare filename
+        file_name1 = "bind10.py"
+        abs_file_name = self.handler._get_abs_file_path(file_name1)
+        self.assertEqual(abs_file_name, os.path.join(os.getcwd(), file_name1))
+        # test relative path 
+        file_name2 = "./bind10.py"
+        abs_file_name = self.handler._get_abs_file_path(file_name2)
+        self.assertEqual(abs_file_name, os.path.join(os.getcwd(), os.path.basename(file_name2)))
+         
     def test_update_config(self):
         self.handler.update_config(self.FILE_LOG2.name, 3, 512)
         self.assertEqual(self.handler.baseFilename, self.FILE_LOG2.name)
         self.assertEqual(self.handler.maxBytes, 512)
         self.assertEqual(self.handler.backupCount, 3)
 
-        dir = os.path.split(self.FILE_LOG3.name)                                        
-        path = dir[0] + "path_not_exists"
-        update_file = os.path.join(path, dir[1])
-
-        if not os.path.exists(path):
-            self.handler.update_config(update_file, 4, 1024)
-            self.assertEqual(self.handler.baseFilename, self.FILE_LOG2.name)
-            self.assertEqual(self.handler.maxBytes, 1024)
-            self.assertEqual(self.handler.backupCount, 4)
+        # check the existence of new log file.
+        # emit() will call shouldRollover() to update the log file
+        if(os.path.exists(self.FILE_LOG2.name)):
+            os.remove(self.FILE_LOG2.name)
+        record = logging.LogRecord(None, None, "", 0, "rotate file handler", (), None, None)
+        self.handler.emit(record)
+        self.assertTrue(os.path.exists(self.FILE_LOG2.name))
+
+    def test_handle_Error(self):
+        if(os.path.exists(self.FILE_LOG3.name)):
+            os.remove(self.FILE_LOG3.name)
+        # redirect error message to file
+        savederr = sys.stderr
+        errfd = open(self.FILE_LOG3.name, 'w+')
+        sys.stderr = errfd
+        record = logging.LogRecord(None, None, "", 0, "record message", (), None, None)
+        try:
+            raise ValueError("ValueError")
+        except ValueError:
+            self.handler.handleError(record)
+
+        self.assertEqual("[b10-logging] : ValueError", errfd.read())
+        sys.stderr = savederr
+        errfd.close()
 
     def tearDown(self):
         self.handler.flush()
@@ -78,50 +106,46 @@ class TestSysLogHandler(unittest.TestCase):
         self.assertEqual(sysLevel, syslog.LOG_ERR)
 
     def test_emit(self):
-        record = logging.LogRecord(None, None, "", 0, "syslog handler", (), None, None)
+        syslog_message = "bind10 syslog testing"
+        record = logging.LogRecord(None, None, "", 0, syslog_message, (), None, None)
         self.handler.emit(record)
 
-
 class TestLogging(unittest.TestCase):
     
     def setUp(self):
-        self.FILE_STREAM_LOG1= tempfile.NamedTemporaryFile(mode='w',
+        self.FILE_STREAM_LOG1 = tempfile.NamedTemporaryFile(mode='w',
                                                       prefix="b10",
                                                       delete=True)
-        self.FILE_STREAM_LOG2= tempfile.NamedTemporaryFile(mode='w',
+        self.FILE_STREAM_LOG2 = tempfile.NamedTemporaryFile(mode='w',
                                                       prefix="b10",
                                                       delete=True)
-        self.FILE_STREAM_LOG3= tempfile.NamedTemporaryFile(mode='w',
+        self.FILE_STREAM_LOG3 = tempfile.NamedTemporaryFile(mode='w',
                                                       prefix="b10",
                                                       delete=True)
         self.file_stream_logger = NSLogger('File_Stream_Logger',
                                            self.FILE_STREAM_LOG1.name,
                                            'debug', 5, 1024, True)
         self.syslog_logger = NSLogger('SysLogger', '', 'info', 5, 1024, False)
+        self.stderr_bak = sys.stderr
+        sys.stderr = open(os.devnull, 'w')
     
     def test_logging_init(self):
         self.assertNotEqual(self.file_stream_logger._file_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._file_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)
+        self.assertIn(self.file_stream_logger._file_handler, self.file_stream_logger.handlers)
+        self.assertIn(self.file_stream_logger._stream_handler, self.file_stream_logger.handlers)
+        self.assertNotIn(self.file_stream_logger._syslog_handler, self.file_stream_logger.handlers)
         logLevel = LEVELS.get('debug', logging.NOTSET)
         self.assertEqual(self.file_stream_logger.getEffectiveLevel(), logLevel)
 
         self.assertEqual(self.syslog_logger._file_handler, None)
         self.assertEqual(self.syslog_logger._stream_handler, None)
         self.assertNotEqual(self.syslog_logger._syslog_handler, None)
-        ret = self.syslog_logger._file_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)
+        self.assertNotIn(self.syslog_logger._file_handler, self.syslog_logger.handlers)
+        self.assertNotIn(self.syslog_logger._stream_handler, self.syslog_logger.handlers)
+        self.assertIn(self.syslog_logger._syslog_handler, self.syslog_logger.handlers)
 
         logLevel = LEVELS.get('info', logging.NOTSET)
         self.assertEqual(self.syslog_logger.getEffectiveLevel(), logLevel)
@@ -131,41 +155,52 @@ class TestLogging(unittest.TestCase):
             self.syslog_logger.removeHandler(self.syslog_logger._file_handler)
         
         self.syslog_logger._add_rotate_handler('', 5, 1024)
-        ret = self.syslog_logger._file_handler in self.syslog_logger.handlers
-        self.assertFalse(ret)
+        self.assertNotIn(self.syslog_logger._file_handler, self.syslog_logger.handlers)
 
         self.syslog_logger._add_rotate_handler(self.FILE_STREAM_LOG1.name, 5, 1024)
-        ret = self.syslog_logger._file_handler in self.syslog_logger.handlers
-        self.assertTrue(ret)
+        self.assertIn(self.syslog_logger._file_handler, self.syslog_logger.handlers)
+
+        # test IOError exception
+        self.syslog_logger.removeHandler(self.syslog_logger._file_handler)
+        log_file = self.FILE_STREAM_LOG1.name + '/logfile'
+        self.syslog_logger._add_rotate_handler(log_file, 5, 1024)
+        self.assertNotIn(self.syslog_logger._file_handler, self.syslog_logger.handlers)
 
     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)
+        self.assertIn(self.file_stream_logger._stream_handler, self.file_stream_logger.handlers)
 
     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)
+        self.assertIn(self.syslog_logger._syslog_handler, self.syslog_logger.handlers)
 
     def test_update_rotate_handler(self):
         self.file_stream_logger._update_rotate_handler(self.FILE_STREAM_LOG2.name, 4, 1024)
-        ret = self.file_stream_logger._file_handler in self.file_stream_logger.handlers
-        self.assertTrue(ret)
+        self.assertIn(self.file_stream_logger._file_handler, self.file_stream_logger.handlers)
 
         self.file_stream_logger._update_rotate_handler('', 5, 1024)
-        ret = self.file_stream_logger._file_handler in self.file_stream_logger.handlers
-        self.assertFalse(ret)
+        self.assertNotIn(self.file_stream_logger._file_handler, self.file_stream_logger.handlers)
 
         self.file_stream_logger._update_rotate_handler(self.FILE_STREAM_LOG1.name, 4, 1024)
-        ret = self.file_stream_logger._file_handler in self.file_stream_logger.handlers
-        self.assertTrue(ret)
+        self.assertIn(self.file_stream_logger._file_handler, self.file_stream_logger.handlers)
+
+    def test_get_config(self):
+        config_data = {'log_file' : self.FILE_STREAM_LOG1.name,
+                       'log_severity' : 'critical',
+                       'log_versions' : 4,
+                       'log_max_bytes' : 1024}
+        self.file_stream_logger._get_config(config_data)
+        self.assertEqual(self.file_stream_logger._log_file, self.FILE_STREAM_LOG1.name)
+        self.assertEqual(self.file_stream_logger._severity, 'critical')
+        self.assertEqual(self.file_stream_logger._versions, 4)
+        self.assertEqual(self.file_stream_logger._max_bytes, 1024)
+
 
     def test_update_config(self):
         update_config = {'log_file' : self.FILE_STREAM_LOG1.name,
@@ -183,15 +218,20 @@ class TestLogging(unittest.TestCase):
                          'log_max_bytes' : 1024}
         self.file_stream_logger.update_config(update_config)
         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')
+        #test non-exist log level
+        self.assertRaises(None, self.file_stream_logger.log_message('not-exist', 'not exist message'))
+        #test log_message KeyError exception
+        self.assertRaises(None, self.file_stream_logger.log_message('critical', 'critical message', extra=['message', 'asctime']))
         self.assertTrue(os.path.exists(self.FILE_STREAM_LOG3.name))
     
     def tearDown(self):
         self.FILE_STREAM_LOG1.close()
         self.FILE_STREAM_LOG2.close()
         self.FILE_STREAM_LOG3.close()
+        sys.stderr.flush();
+        sys.stderr = self.stderr_bak
 
 if __name__ == '__main__':
     unittest.main()