Introduce re-openable log record handler

This patch adds a new log handler class based on the standard library's
BaseRotatingHandler. This new class allows the log file to be re-opened,
e.g. upon receiving a SIGHUP signal. The latter will be implemented in
forthcoming patches. The patch does not change the behaviour regarding
writing to /dev/console.

Quite a bit of code had to be changed to unittest the log handlers.

Signed-off-by: Michael Hanselmann <hansmi@google.com>
Reviewed-by: Iustin Pop <iustin@google.com>

Makefile.am

@@ -504,6 +504,7 @@ python_tests = \
 	test/ganeti.utils.filelock_unittest.py \
 	test/ganeti.utils.hash_unittest.py \
 	test/ganeti.utils.io_unittest.py \
+	test/ganeti.utils.log_unittest.py \
 	test/ganeti.utils.mlock_unittest.py \
 	test/ganeti.utils.nodesetup_unittest.py \
 	test/ganeti.utils.process_unittest.py \

lib/utils/log.py

@@ -28,38 +28,105 @@ import logging.handlers
 from ganeti import constants
 
 
-class LogFileHandler(logging.FileHandler):
-  """Log handler that doesn't fallback to stderr.
+class _ReopenableLogHandler(logging.handlers.BaseRotatingHandler):
+  """Log handler with ability to reopen log file on request.
 
-  When an error occurs while writing on the logfile, logging.FileHandler tries
-  to log on stderr. This doesn't work in ganeti since stderr is redirected to
-  the logfile. This class avoids failures reporting errors to /dev/console.
+  In combination with a SIGHUP handler this class can reopen the log file on
+  user request.
 
   """
-  def __init__(self, filename, mode="a", encoding=None):
-    """Open the specified file and use it as the stream for logging.
+  def __init__(self, filename):
+    """Initializes this class.
 
-    Also open /dev/console to report errors while logging.
+    @type filename: string
+    @param filename: Path to logfile
 
     """
-    logging.FileHandler.__init__(self, filename, mode, encoding)
-    self.console = open(constants.DEV_CONSOLE, "a")
+    logging.handlers.BaseRotatingHandler.__init__(self, filename, "a")
 
-  def handleError(self, record): # pylint: disable-msg=C0103
-    """Handle errors which occur during an emit() call.
+    assert self.encoding is None, "Encoding not supported for logging"
+    assert not hasattr(self, "_reopen"), "Base class has '_reopen' attribute"
 
-    Try to handle errors with FileHandler method, if it fails write to
+    self._reopen = False
+
+  def shouldRollover(self, _): # pylint: disable-msg=C0103
+    """Determine whether log file should be reopened.
+
+    """
+    return self._reopen or not self.stream
+
+  def doRollover(self): # pylint: disable-msg=C0103
+    """Reopens the log file.
+
+    """
+    if self.stream:
+      self.stream.flush()
+      self.stream.close()
+      self.stream = None
+
+    # Reopen file
+    # TODO: Handle errors?
+    self.stream = open(self.baseFilename, "a")
+
+  def RequestReopen(self):
+    """Register a request to reopen the file.
+
+    The file will be reopened before writing the next log record.
+
+    """
+    self._reopen = True
+
+
+def _LogErrorsToConsole(base):
+  """Create wrapper class writing errors to console.
+
+  This needs to be in a function for unittesting.
+
+  """
+  class wrapped(base): # pylint: disable-msg=C0103
+    """Log handler that doesn't fallback to stderr.
+
+    When an error occurs while writing on the logfile, logging.FileHandler
+    tries to log on stderr. This doesn't work in Ganeti since stderr is
+    redirected to a logfile. This class avoids failures by reporting errors to
     /dev/console.
 
     """
-    try:
-      logging.FileHandler.handleError(self, record)
-    except Exception: # pylint: disable-msg=W0703
+    def __init__(self, console, *args, **kwargs):
+      """Initializes this class.
+
+      @type console: file-like object or None
+      @param console: Open file-like object for console
+
+      """
+      base.__init__(self, *args, **kwargs)
+      assert not hasattr(self, "_console")
+      self._console = console
+
+    def handleError(self, record): # pylint: disable-msg=C0103
+      """Handle errors which occur during an emit() call.
+
+      Try to handle errors with FileHandler method, if it fails write to
+      /dev/console.
+
+      """
       try:
-        self.console.write("Cannot log message:\n%s\n" % self.format(record))
+        base.handleError(record)
       except Exception: # pylint: disable-msg=W0703
-        # Log handler tried everything it could, now just give up
-        pass
+        if self._console:
+          try:
+            # Ignore warning about "self.format", pylint: disable-msg=E1101
+            self._console.write("Cannot log message:\n%s\n" %
+                                self.format(record))
+          except Exception: # pylint: disable-msg=W0703
+            # Log handler tried everything it could, now just give up
+            pass
+
+  return wrapped
+
+
+#: Custom log handler for writing to console with a reopenable handler
+_LogHandler = _LogErrorsToConsole(_ReopenableLogHandler)
 
 
 def SetupLogging(logfile, debug=0, stderr_logging=False, program="",
@@ -138,9 +205,10 @@ def SetupLogging(logfile, debug=0, stderr_logging=False, program="",
     # exception since otherwise we could run but without any logs at all
     try:
       if console_logging:
-        logfile_handler = LogFileHandler(logfile)
+        logfile_handler = _LogHandler(open(constants.DEV_CONSOLE, "a"), logfile)
       else:
-        logfile_handler = logging.FileHandler(logfile)
+        logfile_handler = _ReopenableLogHandler(logfile)
+
       logfile_handler.setFormatter(formatter)
       if debug:
         logfile_handler.setLevel(logging.DEBUG)

test/ganeti.utils.log_unittest.py

+#!/usr/bin/python
+#
+
+# Copyright (C) 2011 Google Inc.
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful, but
+# WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
+# 02110-1301, USA.
+
+
+"""Script for testing ganeti.utils.log"""
+
+import os
+import unittest
+import logging
+import tempfile
+
+from ganeti import constants
+from ganeti import errors
+from ganeti import utils
+
+import testutils
+
+
+class TestLogHandler(unittest.TestCase):
+  def test(self):
+    tmpfile = tempfile.NamedTemporaryFile()
+
+    handler = utils.log._ReopenableLogHandler(tmpfile.name)
+    handler.setFormatter(logging.Formatter("%(asctime)s: %(message)s"))
+
+    logger = logging.Logger("TestLogger")
+    logger.addHandler(handler)
+    self.assertEqual(len(logger.handlers), 1)
+
+    logger.error("Test message ERROR")
+    logger.info("Test message INFO")
+
+    logger.removeHandler(handler)
+    self.assertFalse(logger.handlers)
+    handler.close()
+
+    self.assertEqual(len(utils.ReadFile(tmpfile.name).splitlines()), 2)
+
+  def testReopen(self):
+    tmpfile = tempfile.NamedTemporaryFile()
+    tmpfile2 = tempfile.NamedTemporaryFile()
+
+    handler = utils.log._ReopenableLogHandler(tmpfile.name)
+
+    self.assertFalse(utils.ReadFile(tmpfile.name))
+    self.assertFalse(utils.ReadFile(tmpfile2.name))
+
+    logger = logging.Logger("TestLoggerReopen")
+    logger.addHandler(handler)
+
+    for _ in range(3):
+      logger.error("Test message ERROR")
+    handler.flush()
+    self.assertEqual(len(utils.ReadFile(tmpfile.name).splitlines()), 3)
+    before_id = utils.GetFileID(tmpfile.name)
+
+    handler.RequestReopen()
+    self.assertTrue(handler._reopen)
+    self.assertTrue(utils.VerifyFileID(utils.GetFileID(tmpfile.name),
+                                       before_id))
+
+    # Rename only after requesting reopen
+    os.rename(tmpfile.name, tmpfile2.name)
+    assert not os.path.exists(tmpfile.name)
+
+    # Write another message, should reopen
+    for _ in range(4):
+      logger.info("Test message INFO")
+      self.assertFalse(utils.VerifyFileID(utils.GetFileID(tmpfile.name),
+                                          before_id))
+
+    logger.removeHandler(handler)
+    self.assertFalse(logger.handlers)
+    handler.close()
+
+    self.assertEqual(len(utils.ReadFile(tmpfile.name).splitlines()), 4)
+    self.assertEqual(len(utils.ReadFile(tmpfile2.name).splitlines()), 3)
+
+  def testConsole(self):
+    for (console, check) in [(None, False),
+                             (tempfile.NamedTemporaryFile(), True),
+                             (self._FailingFile(os.devnull), False)]:
+      # Create a handler which will fail when handling errors
+      cls = utils.log._LogErrorsToConsole(self._FailingHandler)
+
+      # Instantiate handler with file which will fail when writing,
+      # provoking a write to the console
+      handler = cls(console, self._FailingFile(os.devnull))
+
+      logger = logging.Logger("TestLogger")
+      logger.addHandler(handler)
+      self.assertEqual(len(logger.handlers), 1)
+
+      # Provoke write
+      logger.error("Test message ERROR")
+
+      # Take everything apart
+      logger.removeHandler(handler)
+      self.assertFalse(logger.handlers)
+      handler.close()
+
+      if console and check:
+        console.flush()
+
+        # Check console output
+        consout = utils.ReadFile(console.name)
+        self.assertTrue("Cannot log message" in consout)
+        self.assertTrue("Test message ERROR" in consout)
+
+  class _FailingFile(file):
+    def write(self, _):
+      raise Exception
+
+  class _FailingHandler(logging.StreamHandler):
+    def handleError(self, _):
+      raise Exception
+
+
+if __name__ == "__main__":
+  testutils.GanetiTestProgram()