launchpad-reviewers team mailing list archive

["Jeroen T. Vermeulen" <jtv@xxxxxxxxxxxxx>]

Jeroen T. Vermeulen has proposed merging lp:~jtv/launchpad/bug-741585 into lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #741585 in Launchpad itself: "FakeLogger doesn't quite conform to logging API"
  https://bugs.launchpad.net/launchpad/+bug/741585

For more details, see:
https://code.launchpad.net/~jtv/launchpad/bug-741585/+merge/54674

= Summary =

This is one of those "start pulling a loose thread, end up without trousers" problems.

It started with some test noise in derived-distro work I'm doing.  Took me a long time to figure out why using DevNullLogger failed to suppress it.  Turned out that a function called process_in_batches was creating a LoopTuner without a logger, making it create its own.  Since process_in_batches takes a logger as an argument, the sensible thing to do is to pass it on to the LoopTuner.

That in turn broke some tests that rely on exact log output as captured by FakeLogger.  The sensible thing to do about that (as well as noisy output in general, since LoopTuner is now pretty stable and we don't really need to look at all its output any more) is to lower the messages' log level to DEBUG2, a custom level in our code.

Of course there's no matching "debug2" method in the standard loggers, so the robust way to pass the custom log level is to call the logger's log() method, which takes a log level as its first argument.

But that broke tests since FakeLogger.log didn't accept a log level as its first argument (or actually it passed its arguments on to FakeLogger.message, deeper down in the call stack, which doesn't accept a log level).


== Proposed fix ==

Make FakeLogger.log accept a log level as its first argument.


== Pre-implementation notes ==

Stuart agrees that debug2 is fine for the looptuner debug output.


== Implementation details ==

I regularized things a bit as well.  There is now just a single comparison to filter for the applicable log level, and text representation of a message's log level is now handled by a dict called LEVEL_PREFIXES.

The setup of that dict looks a bit weird; that's because it combines python's built-in log levels with some custom ones that Launchpad adds.  There's probably some way to get around this using a logging formatter but that seems pointlessly heavyweight.  If there's a simple, clean way to do it we can always improve on what we have now — at least the code to fix will now be in one place.


== Tests ==

{{{
./bin/test -vvc lp.registry -t logging
./bin/test -vvc -t deathrow.txt
}}}


== Demo and Q/A ==

Debug output for loop tuners will change a bit.  I don't think there's much Q/A to be done.


= Launchpad lint =

Checking for conflicts and issues in changed files.

Linting changed files:
  lib/lp/services/log/logger.py
  lib/lp/archivepublisher/utils.py
  lib/canonical/launchpad/utilities/looptuner.py

./lib/lp/archivepublisher/utils.py
     140: E302 expected 2 blank lines, found 3

That's one of those "floating comments" notices that I'm not cleaning up because it's not clear to me that it's not a valid construct separate from the one that the linter is looking for.
-- 
https://code.launchpad.net/~jtv/launchpad/bug-741585/+merge/54674
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~jtv/launchpad/bug-741585 into lp:launchpad.

=== modified file 'lib/canonical/launchpad/utilities/looptuner.py'
--- lib/canonical/launchpad/utilities/looptuner.py	2011-02-23 10:28:53 +0000
+++ lib/canonical/launchpad/utilities/looptuner.py	2011-03-24 10:32:37 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2011 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 __metaclass__ = type
@@ -25,6 +25,7 @@
     MASTER_FLAVOR,
     )
 from canonical.lazr.utils import safe_hasattr
+from lp.services.log.loglevels import DEBUG2
 
 
 class LoopTuner:
@@ -136,8 +137,10 @@
                 new_clock = self._time()
                 time_taken = new_clock - last_clock
                 last_clock = new_clock
-                self.log.debug("Iteration %d (size %.1f): %.3f seconds" %
-                            (iteration, chunk_size, time_taken))
+                self.log.log(
+                    DEBUG2,
+                    "Iteration %d (size %.1f): %.3f seconds",
+                    iteration, chunk_size, time_taken)
 
                 last_clock = self._coolDown(last_clock)
 
@@ -162,12 +165,12 @@
             total_time = last_clock - self.start_time
             average_size = total_size/max(1, iteration)
             average_speed = total_size/max(1, total_time)
-            self.log.debug(
-                "Done. %d items in %d iterations, "
-                "%.3f seconds, "
-                "average size %f (%s/s)" %
-                    (total_size, iteration, total_time, average_size,
-                    average_speed))
+            self.log.log(
+                DEBUG2,
+                "Done. %d items in %d iterations, 3f seconds, "
+                "average size %f (%s/s)",
+                total_size, iteration, total_time, average_size,
+                average_speed)
         finally:
             if safe_hasattr(self.operation, 'cleanUp'):
                 self.operation.cleanUp()

=== modified file 'lib/lp/archivepublisher/utils.py'
--- lib/lp/archivepublisher/utils.py	2011-02-17 16:58:57 +0000
+++ lib/lp/archivepublisher/utils.py	2011-03-24 10:32:37 +0000
@@ -156,8 +156,9 @@
         each batch, defaults to 10000
     """
     loop = PublishingTunableLoop(input, task, logger)
-    loop_tuner = LoopTuner(loop, goal_seconds=goal_seconds,
-                           minimum_chunk_size=minimum_chunk_size)
+    loop_tuner = LoopTuner(
+        loop, goal_seconds=goal_seconds,
+        minimum_chunk_size=minimum_chunk_size, log=logger)
     loop_tuner.run()
 
 

=== modified file 'lib/lp/services/log/logger.py'
--- lib/lp/services/log/logger.py	2010-12-22 20:46:21 +0000
+++ lib/lp/services/log/logger.py	2011-03-24 10:32:37 +0000
@@ -1,4 +1,4 @@
-# Copyright 2010 Canonical Ltd.  This software is licensed under the
+# Copyright 2011 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Simple loggers."""
@@ -11,16 +11,31 @@
     ]
 
 from StringIO import StringIO
-import logging
 import sys
 import traceback
 
+from lp.services.log import loglevels
+
+
+LEVEL_PREFIXES = dict(
+    (debug_level, "DEBUG%d" % (1 + debug_level - loglevels.DEBUG))
+    for debug_level in xrange(loglevels.DEBUG9, loglevels.DEBUG))
+
+LEVEL_PREFIXES.update({
+    None: 'log>',
+    loglevels.DEBUG: 'DEBUG',
+    loglevels.INFO: 'INFO',
+    loglevels.WARNING: 'WARNING',
+    loglevels.ERROR: 'ERROR',
+    loglevels.CRITICAL: 'CRITICAL',
+})
+
 
 class FakeLogger:
     """Emulates a proper logger, just printing everything out the given file.
     """
 
-    loglevel = logging.DEBUG
+    loglevel = loglevels.DEBUG
 
     def __init__(self, output_file=None):
         """The default output_file is sys.stdout."""
@@ -41,7 +56,10 @@
             msg %= args
         return msg
 
-    def message(self, prefix, msg, *stuff, **kw):
+    def message(self, level, msg, *stuff, **kw):
+        if level < self.loglevel:
+            return
+
         # We handle the default output file here because sys.stdout
         # might have been reassigned. Between now and when this object
         # was instantiated.
@@ -49,38 +67,35 @@
             output_file = sys.stdout
         else:
             output_file = self.output_file
+        prefix = LEVEL_PREFIXES.get(level, "%d>" % level)
         print >> output_file, prefix, self._format_message(msg, *stuff)
 
         if 'exc_info' in kw:
             traceback.print_exc(file=output_file)
 
-    def log(self, *stuff, **kw):
-        self.message('log>', *stuff, **kw)
+    def log(self, level, *stuff, **kw):
+        self.message(level, *stuff, **kw)
 
     def warning(self, *stuff, **kw):
-        if self.loglevel <= logging.WARN:
-            self.message('WARNING', *stuff, **kw)
+        self.message(loglevels.WARNING, *stuff, **kw)
 
     warn = warning
 
     def error(self, *stuff, **kw):
-        if self.loglevel <= logging.ERROR:
-            self.message('ERROR', *stuff, **kw)
+        self.message(loglevels.ERROR, *stuff, **kw)
 
     exception = error
 
     def critical(self, *stuff, **kw):
-        self.message('CRITICAL', *stuff, **kw)
+        self.message(loglevels.CRITICAL, *stuff, **kw)
 
     fatal = critical
 
     def info(self, *stuff, **kw):
-        if self.loglevel <= logging.INFO:
-            self.message('INFO', *stuff, **kw)
+        self.message(loglevels.INFO, *stuff, **kw)
 
     def debug(self, *stuff, **kw):
-        if self.loglevel <= logging.DEBUG:
-            self.message('DEBUG', *stuff, **kw)
+        self.message(loglevels.DEBUG, *stuff, **kw)
 
 
 class DevNullLogger(FakeLogger):
@@ -95,7 +110,6 @@
 
     def __init__(self):
         super(BufferLogger, self).__init__(StringIO())
-        # self.buffer = StringIO()
 
     def getLogBuffer(self):
         """Return the existing log messages."""