-Modified logging formatter

-Modified logging configuration names, all of them prefixed with "log_"
-Modified Xfrout unittest, add log in __init__() method
-Using mkstemp in logging unittest


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

src/bin/xfrout/tests/xfrout_test.py

@@ -75,7 +75,8 @@ class TestXfroutSession(unittest.TestCase):
 
     def setUp(self):
         request = MySocket(socket.AF_INET,socket.SOCK_STREAM)
-        self.xfrsess = MyXfroutSession(request, None, None)
+        self.log = isc.log.NSLogger('xfrout', '',  severity = 'critical', log_to_console = False )
+        self.xfrsess = MyXfroutSession(request, None, None, self.log)
         self.xfrsess.server = Dbserver()
         self.mdata = b'\xd6=\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x07example\x03com\x00\x00\xfc\x00\x01'
         self.sock = MySocket(socket.AF_INET,socket.SOCK_STREAM)
@@ -238,10 +239,6 @@ class TestXfroutSession(unittest.TestCase):
         reply_msg = self.sock.read_msg()
         self.assertEqual(reply_msg.get_rr_count(section.ANSWER()), 2)
 
-        # set event
-        self.xfrsess.server._shutdown_event.set()
-        self.assertRaises(XfroutException, self.xfrsess._reply_xfrout_query, self.getmsg(), self.sock, "example.com.")
-
 class MyUnixSockServer(UnixSockServer):
     def __init__(self):
         self._lock = threading.Lock()
@@ -249,6 +246,7 @@ class MyUnixSockServer(UnixSockServer):
         self._shutdown_event = threading.Event()
         self._db_file = "initdb.file"
         self._max_transfers_out = 10
+        self._log = isc.log.NSLogger('xfrout', '', severity = 'critical', log_to_console = False )
 
 class TestUnixSockServer(unittest.TestCase):
     def setUp(self):

src/bin/xfrout/xfrout.py.in

@@ -50,10 +50,6 @@ UNIX_SOCKET_FILE = "@@LOCALSTATEDIR@@/auth_xfrout_conn"
 MAX_TRANSFERS_OUT = 10
 VERBOSE_MODE = False
 
-
-class XfroutException(Exception): pass
-
-
 class XfroutSession(BaseRequestHandler):
     def __init__(self, request, client_address, server, log):
         BaseRequestHandler.__init__(self, request, client_address, server)
@@ -62,7 +58,7 @@ class XfroutSession(BaseRequestHandler):
     def handle(self):
         fd = recv_fd(self.request.fileno())
         if fd < 0:
-            raise XfroutException("failed to receive the FD for XFR connection")
+            self._log.log_message("error", "Failed to receive the FD for XFR connection")
         data_len = self.request.recv(2)
         msg_len = struct.unpack('!H', data_len)[0]
         msgdata = self.request.recv(msg_len)
@@ -74,9 +70,6 @@ class XfroutSession(BaseRequestHandler):
 
         sock.close()
 
-    def setLogger(self, logger):
-        self._log = logger
-
     def _parse_query_message(self, mdata):
         ''' parse query message to [socket,message]'''
         #TODO, need to add parseHeader() in case the message header is invalid 
@@ -251,7 +244,7 @@ class XfroutSession(BaseRequestHandler):
         # the message length to know if the rrset has been added sucessfully.
         for rr_data in sqlite3_ds.get_zone_datas(zone_name, self.server.get_db_file()):
             if  self.server._shutdown_event.is_set(): # Check if xfrout is shutdown
-                raise XfroutException("shutdown!")
+                self._log.log_message("error", "shutdown!")
 
             if rr_type(rr_data[5]) == rr_type.SOA(): #ignore soa record
                 continue
@@ -270,9 +263,6 @@ class XfroutSession(BaseRequestHandler):
 
         self._send_message_with_last_soa(msg, sock, rrset_soa)
 
-    def log_msg(self, msg):
-        print('[b10-xfrout] ', msg)
-   
 
 class UnixSockServer(ThreadingUnixStreamServer):
     '''The unix domain socket server which accept xfr query sent from auth server.'''
@@ -280,8 +270,8 @@ class UnixSockServer(ThreadingUnixStreamServer):
     def __init__(self, sock_file, handle_class, shutdown_event, config_data, log):
         try:
             os.unlink(sock_file)
-        except:
-            pass
+        except Exception as e:
+            self._log.log_message("error", str(e))
  
         self._sock_file = sock_file
         ThreadingUnixStreamServer.__init__(self, sock_file, handle_class)
@@ -296,12 +286,11 @@ class UnixSockServer(ThreadingUnixStreamServer):
         self.RequestHandlerClass(request, client_address, self, self._log)
 
     def shutdown(self):
-        self._log.log_message('warning', 'Xfrout process is shutting down!')
         ThreadingUnixStreamServer.shutdown(self)
         try:
             os.unlink(self._sock_file)
-        except:
-            self._log.log_message('error', 'OS unlink sock file exception while shutting down')
+        except Exception as e:
+            self._log.log_message("error", str(e))
 
     def update_config_data(self, new_config):
         '''Apply the new config setting of xfrout module. '''
@@ -356,8 +345,8 @@ class XfroutServer:
         self._config_data = self._cc.get_full_config()
         self._cc.start()
         self._log = isc.log.NSLogger(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._config_data.get('log_severity'), self._config_data.get('log_versions'),
+                                self._config_data.get('log_max_bytes'), True)
         self._start_xfr_query_listener()
 
 

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

@@ -24,22 +24,22 @@
          "item_name": "log_file",
     	 "item_type": "string",
          "item_optional": False,
-         "item_default": '@@LOCALSTATEDIR@@/Xfrout.log'
+         "item_default": '@@LOCALSTATEDIR@@/@PACKAGE@/log/Xfrout.log'
        },
        {
-         "item_name": "severity",
+         "item_name": "log_severity",
     	 "item_type": "string",
          "item_optional": False,
     	 "item_default": "debug"
        },
        {
-         "item_name": "versions",
+         "item_name": "log_versions",
     	 "item_type": "integer",
          "item_optional": False,
     	 "item_default": 5
        },
        {
-         "item_name": "max_bytes",
+         "item_name": "log_max_bytes",
     	 "item_type": "integer",
          "item_optional": False,
     	 "item_default": 1048576

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

@@ -31,13 +31,18 @@ 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: %(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")
 
 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,
                                                 backupCount, encoding, delay)
 
@@ -202,15 +207,15 @@ class NSLogger(logging.getLoggerClass()):
          if(log_file_str):
             self._log_file = log_file_str
          
-         severity_str = config_data.get('severity')
+         severity_str = config_data.get('log_severity')
          if(severity_str):
              self._severity = severity_str
 
-         versions_str = config_data.get('versions')
+         versions_str = config_data.get('log_versions')
          if(versions_str):
              self._versions = int(versions_str)
 
-         max_bytes_str = config_data.get('max_bytes')
+         max_bytes_str = config_data.get('log_max_bytes')
          if(max_bytes_str):
              self._max_bytes = int(max_bytes_str)
 

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

@@ -2,42 +2,45 @@ from isc.log.log import *
 import unittest
 import os
 import sys
-
-FILE_LOG1 = '/tmp/b10_file1.log'
-FILE_LOG2 = '/tmp/b10_file2.log'
-FILE_LOG3 = '/tmp/ZZZZ/b10_file2.log'
-
-FILE_STREAM_LOG1 = '/tmp/b10_file_stream1.log'
-FILE_STREAM_LOG2 = '/tmp/b10_file_stream2.log'
-FILE_STREAM_LOG3 = '/tmp/b10_file_stream2.log'
+import tempfile
 
 
 class TestRotateFileHandler(unittest.TestCase):
 
     def setUp(self):
-        self.handler = NSFileLogHandler(filename = FILE_LOG1, maxBytes = 1024, backupCount = 5)
+        self.FILE_LOG1 = tempfile.mkstemp()
+        self.FILE_LOG2 = tempfile.mkstemp()
+        self.FILE_LOG3 = tempfile.mkstemp()
+        self.handler = NSFileLogHandler(filename = self.FILE_LOG1[1], maxBytes = 1024, backupCount = 5)
 
     def test_shouldRollover(self):
-        if(os.path.exists(FILE_LOG1)):
-            os.remove(FILE_LOG1)
+        if(os.path.exists(self.FILE_LOG1[1])):
+            os.remove(self.FILE_LOG1[1])
         record = logging.LogRecord(None, None, "", 0, "rotate file handler", (), None, None)
         self.handler.shouldRollover(record)
-        self.assertTrue(os.path.exists(FILE_LOG1))
+        self.assertTrue(os.path.exists(self.FILE_LOG1[1]))
 
     def test_update_config(self):
-        self.handler.update_config(FILE_LOG2, 3, 512)
-        self.assertEqual(self.handler.baseFilename, FILE_LOG2)
+        self.handler.update_config(self.FILE_LOG2[1], 3, 512)
+        self.assertEqual(self.handler.baseFilename, self.FILE_LOG2[1])
         self.assertEqual(self.handler.maxBytes, 512)
         self.assertEqual(self.handler.backupCount, 3)
 
-        dir = os.path.split(FILE_LOG3)                                        
-        if not os.path.exists(dir[0]):
-            self.handler.update_config(FILE_LOG3, 4, 1024)
-            self.assertEqual(self.handler.baseFilename, FILE_LOG2)
+        dir = os.path.split(self.FILE_LOG3[1])                                        
+        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[1])
             self.assertEqual(self.handler.maxBytes, 1024)
             self.assertEqual(self.handler.backupCount, 4)
 
     def tearDown(self):
+        os.close(self.FILE_LOG1[0])
+        os.close(self.FILE_LOG2[0])
+        os.unlink(self.FILE_LOG1[1])
+        os.unlink(self.FILE_LOG2[1])
         self.handler.flush()
         self.handler.close()
 
@@ -45,7 +48,10 @@ class TestRotateFileHandler(unittest.TestCase):
 class TestLogging(unittest.TestCase):
     
     def setUp(self):
-        self.file_stream_logger = NSLogger('File_Stream_Logger', FILE_STREAM_LOG1,
+        self.FILE_STREAM_LOG1 = tempfile.mkstemp()
+        self.FILE_STREAM_LOG2 = tempfile.mkstemp()
+        self.FILE_STREAM_LOG3 = tempfile.mkstemp()
+        self.file_stream_logger = NSLogger('File_Stream_Logger', self.FILE_STREAM_LOG1[1],
                                            'debug', 5, 1024, True)
         self.syslog_logger = NSLogger('SysLogger', '', 'info', 5, 1024, False)
     
@@ -84,11 +90,11 @@ class TestLogging(unittest.TestCase):
         ret = self.syslog_logger._file_handler in self.syslog_logger.handlers
         self.assertFalse(ret)
 
-        self.syslog_logger._add_rotate_handler(FILE_STREAM_LOG1, 5, 1024)
+        self.syslog_logger._add_rotate_handler(self.FILE_STREAM_LOG1[1], 5, 1024)
         ret = self.syslog_logger._file_handler in self.syslog_logger.handlers
         self.assertTrue(ret)
 
-    def test_add__stream_handler(self):
+    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)
 
@@ -105,7 +111,7 @@ class TestLogging(unittest.TestCase):
         self.assertTrue(ret)
 
     def test_update_rotate_handler(self):
-        self.file_stream_logger._update_rotate_handler(FILE_STREAM_LOG2, 4, 1024)
+        self.file_stream_logger._update_rotate_handler(self.FILE_STREAM_LOG2[1], 4, 1024)
         ret = self.file_stream_logger._file_handler in self.file_stream_logger.handlers
         self.assertTrue(ret)
 
@@ -113,33 +119,38 @@ class TestLogging(unittest.TestCase):
         ret = self.file_stream_logger._file_handler in self.file_stream_logger.handlers
         self.assertFalse(ret)
 
-        self.file_stream_logger._update_rotate_handler(FILE_STREAM_LOG1, 4, 1024)
+        self.file_stream_logger._update_rotate_handler(self.FILE_STREAM_LOG1[1], 4, 1024)
         ret = self.file_stream_logger._file_handler in self.file_stream_logger.handlers
         self.assertTrue(ret)
 
     def test_update_config(self):
-        update_config = {'log_file' : FILE_STREAM_LOG1,
-                         'severity' : 'error',
-                         'versions' : 4,
-                         'max_bytes' : 1024}
+        update_config = {'log_file' : self.FILE_STREAM_LOG1[1],
+                         'log_severity' : 'error',
+                         'log_versions' : 4,
+                         'log_max_bytes' : 1024}
         self.file_stream_logger.update_config(update_config)
         logLevel = LEVELS.get('error', logging.NOTSET)
         self.assertEqual(self.file_stream_logger.getEffectiveLevel(), logLevel)
 
     def test_log_message(self):
-        update_config = {'log_file' : FILE_STREAM_LOG3,
-                         'severity' : 'critical',
-                         'versions' : 4,
-                         'max_bytes' : 1024}
+        update_config = {'log_file' : self.FILE_STREAM_LOG3[1],
+                         'log_severity' : 'critical',
+                         'log_versions' : 4,
+                         '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')
-        self.assertFalse(os.path.exists(FILE_STREAM_LOG3))
+        self.assertTrue(os.path.exists(self.FILE_STREAM_LOG3[1]))
     
     def tearDown(self):
-        pass
+        os.close(self.FILE_STREAM_LOG1[0])
+        os.unlink(self.FILE_STREAM_LOG1[1])
+        os.close(self.FILE_STREAM_LOG2[0])
+        os.unlink(self.FILE_STREAM_LOG2[1])
+        os.close(self.FILE_STREAM_LOG3[0])
+        os.unlink(self.FILE_STREAM_LOG3[1])
 
 if __name__ == '__main__':
     unittest.main()