Merge lp:~jtv/launchpad/bug-814141 into lp:launchpad

[Jeroen T. Vermeulen]

[r=gmb][bug=814141] Pass loggers to LaunchpadScripts to protect global logging config.

= Summary =

When publish-ftpmaster instantiates and calls a publish-distro script object, it overrides (without restoring it afterwards!) the logging options you passed in.

As it turns out, the LaunchpadScript constructor messes with the process-global logging settings, which causes strange effects.

== Proposed fix ==

When instantiating a script object, allow the caller to pass in a logger. This doesn't really do much, exactly because loggers are global, but I do like the clarity of it and it does kill two birds with one stone:

1. It ensures a meaningful self.logger (which we'd otherwise have to look up anyway).
2. It clearly says "don't configure logging; use this instead."

Now you can run publish-ftpmaster.py with -vvv or -qqq options, and their effects on logging verbosity will apply to the main script but also to the script that it calls in turn. Previously, the first time the script instantiated another script object the log level would get reset to INFO and never recover.

== Pre-implementation notes ==

We came up with several approaches. I tried even more. Almost gave up; Julian (who requested the fix, leading me to discover the underlying problem) would have been willing to accept a hack that spewed "-v" and "-q" options to the sub-script. But that would have been unspeakable.

Stuart suggested creating a new option. At first I tried to make do with test_args, but it wasn't quite as transparent and I didn't quite get it to work. I also tried just a boolean ("initialize global logging?") but that left self.logging uninitialized.

== Implementation details ==

The options code uses callbacks to change log levels. There was a fair bit of duplication, and they took the default value straight from a variable in the surrounding function. I replaced them with a single class which I hope is cleaner.

Hopefully in the future we'll be able to quench more test noise by passing logger=DevNullLogger() to script objects in tests.

== Tests ==

Since this messes with the global log level, I didn't add any unit tests. Obviously scripts still work though. However, do run this to ensure that I haven't broken anything:

{{{
./bin/test -vvc lp.archivepublisher.tests.test_publish_ftpmaster
}}}

== Demo and Q/A ==

Run "publish-ftpmaster.py -d ubuntu -v" to see DEBUG output, which will include the output from publish-distro. Or replace the -v with -q to get less output from both publish-ftpmaster and publish-distro.

You may need to “rm -rf /var/tmp/archive/ubuntu*” before the script will work well.

= Launchpad lint =

Checking for conflicts and issues in changed files.

Linting changed files:
  lib/canonical/launchpad/scripts/__init__.py
  lib/lp/services/scripts/base.py
  lib/canonical/launchpad/scripts/logger.py
  lib/lp/archivepublisher/scripts/publish_ftpmaster.py
  lib/lp/archivepublisher/scripts/generate_contents_files.py

[Graham Binns (gmb)]

review: Approve (code)

=== modified file 'lib/canonical/launchpad/scripts/__init__.py'
--- lib/canonical/launchpad/scripts/__init__.py	2011-02-18 18:16:50 +0000
+++ lib/canonical/launchpad/scripts/__init__.py	2011-07-26 13:56:51 +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).
 
 """Library functions for use in all scripts.
@@ -8,6 +8,7 @@
 
 __all__ = [
     'db_options',
+    'dummy_logger_options',
     'execute_zcml_for_scripts',
     'log',
     'logger',
@@ -31,6 +32,7 @@
 from canonical.config import config
 # these are intentional re-exports, apparently, used by *many* files.
 from canonical.launchpad.scripts.logger import (
+    dummy_logger_options,
     log,
     logger,
     logger_options,
@@ -126,8 +128,8 @@
 
     dbname and dbhost are also propagated to config.database.dbname and
     config.database.dbhost. dbname, dbhost and dbuser are also propagated to
-    lp.get_dbname(), lp.dbhost and lp.dbuser. This ensures that all systems will
-    be using the requested connection details.
+    lp.get_dbname(), lp.dbhost and lp.dbuser. This ensures that all systems
+    will be using the requested connection details.
 
     To test, we first need to store the current values so we can reset them
     later.
@@ -170,7 +172,8 @@
 
     parser.add_option(
             "-d", "--dbname", action="callback", callback=dbname_callback,
-            type="string", dest="dbname", default=config.database.rw_main_master,
+            type="string", dest="dbname",
+            default=config.database.rw_main_master,
             help="PostgreSQL database to connect to."
             )
 

=== modified file 'lib/canonical/launchpad/scripts/logger.py'
--- lib/canonical/launchpad/scripts/logger.py	2011-06-30 11:28:59 +0000
+++ lib/canonical/launchpad/scripts/logger.py	2011-07-26 13:56:51 +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).
 
 # pylint: disable-msg=W0702
@@ -23,6 +23,7 @@
     'DEBUG7',
     'DEBUG8',
     'DEBUG9',
+    'dummy_logger_options',
     'LaunchpadFormatter',
     'log',
     'logger',
@@ -112,7 +113,8 @@
         if datefmt is None:
             datefmt = "%Y-%m-%d %H:%M:%S"
         logging.Formatter.__init__(self, fmt, datefmt)
-        self.converter = time.gmtime # Output should be UTC
+        # Output should be UTC.
+        self.converter = time.gmtime
 
 
 class LibrarianFormatter(LaunchpadFormatter):
@@ -168,6 +170,73 @@
                     LaunchpadFormatter.formatException(self, sys.exc_info()))
 
 
+class LogLevelNudger:
+    """Callable to adjust the global log level.
+
+    Use instances as callbacks for `optparse`.
+    """
+
+    def __init__(self, default, increment=True):
+        """Initialize nudger to increment or decrement log level.
+
+        :param default: Default starting level.
+        :param increment: Whether to increase the log level (as when
+            handling the --verbose option).  If not, will decrease
+            instead (as with the --quiet option).
+        """
+        self.default = default
+        self.increment = increment
+
+    def getIncrement(self, current_level):
+        """Figure out how much to increment the log level.
+
+        Increment is negative when decreasing log level, of course.
+        """
+        if self.increment:
+            if current_level < 10:
+                return 1
+            else:
+                return 10
+        else:
+            if current_level <= 10:
+                return -1
+            else:
+                return -10
+
+    def __call__(self, option, opt_str, value, parser):
+        """Callback for `optparse` to handle --verbose or --quiet option."""
+        current_level = getattr(parser.values, 'loglevel', self.default)
+        increment = self.getIncrement(current_level)
+        parser.values.loglevel = current_level + increment
+        parser.values.verbose = (parser.values.loglevel < self.default)
+        # Reset the global log.
+        log._log = _logger(parser.values.loglevel, out_stream=sys.stderr)
+
+
+def define_verbosity_options(parser, default, verbose_callback,
+                             quiet_callback):
+    """Define the -v and -q options on `parser`."""
+    # Only one of these specifies dest and default.  That's because
+    # that's enough to make the parser create the option value; there's
+    # no need for the other option to specify them as well.
+    parser.add_option(
+        "-v", "--verbose", dest="loglevel", default=default,
+        action="callback", callback=verbose_callback,
+        help="Increase stderr verbosity. May be specified multiple times.")
+    parser.add_option(
+        "-q", "--quiet", action="callback", callback=quiet_callback,
+        help="Decrease stderr verbosity. May be specified multiple times.")
+
+
+def do_nothing(*args, **kwargs):
+    """Do absolutely nothing."""
+
+
+def dummy_logger_options(parser):
+    """Add dummy --verbose and --quiet options to `parser`."""
+    define_verbosity_options(parser, None, do_nothing, do_nothing)
+
+
 def logger_options(parser, default=logging.INFO):
     """Add the --verbose and --quiet options to an optparse.OptionParser.
 
@@ -219,35 +288,9 @@
     # Undocumented use of the optparse module
     parser.defaults['verbose'] = False
 
-    def inc_loglevel(option, opt_str, value, parser):
-        current_level = getattr(parser.values, 'loglevel', default)
-        if current_level < 10:
-            inc = 1
-        else:
-            inc = 10
-        parser.values.loglevel = current_level + inc
-        parser.values.verbose = (parser.values.loglevel < default)
-        # Reset the global log.
-        log._log = _logger(parser.values.loglevel, out_stream=sys.stderr)
-
-    def dec_loglevel(option, opt_str, value, parser):
-        current_level = getattr(parser.values, 'loglevel', default)
-        if current_level <= 10:
-            dec = 1
-        else:
-            dec = 10
-        parser.values.loglevel = current_level - dec
-        parser.values.verbose = (parser.values.loglevel < default)
-        # Reset the global log.
-        log._log = _logger(parser.values.loglevel, out_stream=sys.stderr)
-
-    parser.add_option(
-        "-v", "--verbose", dest="loglevel", default=default,
-        action="callback", callback=dec_loglevel,
-        help="Increase stderr verbosity. May be specified multiple times.")
-    parser.add_option(
-        "-q", "--quiet", action="callback", callback=inc_loglevel,
-        help="Decrease stderr verbosity. May be specified multiple times.")
+    define_verbosity_options(
+        parser, default,
+        LogLevelNudger(default, False), LogLevelNudger(default, True))
 
     debug_levels = ', '.join([
         v for k, v in sorted(logging._levelNames.items(), reverse=True)

=== modified file 'lib/lp/archivepublisher/scripts/generate_contents_files.py'
--- lib/lp/archivepublisher/scripts/generate_contents_files.py	2011-07-26 12:07:33 +0000
+++ lib/lp/archivepublisher/scripts/generate_contents_files.py	2011-07-26 13:56:51 +0000
@@ -156,8 +156,7 @@
         if options is not None:
             args += options
         args.append(request)
-        query_distro = LpQueryDistro(test_args=args)
-        query_distro.logger = self.logger
+        query_distro = LpQueryDistro(test_args=args, logger=self.logger)
         query_distro.txn = self.txn
         receiver = StoreArgument()
         query_distro.runAction(presenter=receiver)

=== modified file 'lib/lp/archivepublisher/scripts/publish_ftpmaster.py'
--- lib/lp/archivepublisher/scripts/publish_ftpmaster.py	2011-07-18 21:50:38 +0000
+++ lib/lp/archivepublisher/scripts/publish_ftpmaster.py	2011-07-26 13:56:51 +0000
@@ -285,16 +285,17 @@
         """Run the process-accepted script."""
         self.logger.debug(
             "Processing the accepted queue into the publishing records...")
-        script = ProcessAccepted(test_args=[self.distribution.name])
+        script = ProcessAccepted(
+            test_args=[self.distribution.name], logger=self.logger)
         script.txn = self.txn
-        script.logger = self.logger
         script.main()
 
     def getDirtySuites(self):
         """Return list of suites that have packages pending publication."""
         self.logger.debug("Querying which suites are pending publication...")
         query_distro = LpQueryDistro(
-            test_args=['-d', self.distribution.name, "pending_suites"])
+            test_args=['-d', self.distribution.name, "pending_suites"],
+            logger=self.logger)
         receiver = StoreArgument()
         query_distro.runAction(presenter=receiver)
         return receiver.argument.split()
@@ -362,7 +363,8 @@
             args +
             sum([['-s', suite] for suite in suites], []))
 
-        publish_distro = PublishDistro(test_args=arguments)
+        publish_distro = PublishDistro(
+            test_args=arguments, logger=self.logger)
         publish_distro.logger = self.logger
         publish_distro.txn = self.txn
         publish_distro.main()

=== modified file 'lib/lp/services/scripts/base.py'
--- lib/lp/services/scripts/base.py	2011-04-18 15:40:02 +0000
+++ lib/lp/services/scripts/base.py	2011-07-26 13:56:51 +0000
@@ -148,7 +148,7 @@
     # State for the log_unhandled_exceptions decorator.
     _log_unhandled_exceptions_level = 0
 
-    def __init__(self, name=None, dbuser=None, test_args=None):
+    def __init__(self, name=None, dbuser=None, test_args=None, logger=None):
         """Construct new LaunchpadScript.
 
         Name is a short name for this script; it will be used to
@@ -159,6 +159,9 @@
 
         Specify test_args when you want to override sys.argv.  This is
         useful in test scripts.
+
+        :param logger: Use this logger, instead of initializing global
+            logging.
         """
         if name is None:
             self._name = self.__class__.__name__.lower()
@@ -166,6 +169,7 @@
             self._name = name
 
         self._dbuser = dbuser
+        self.logger = logger
 
         # The construction of the option parser is a bit roundabout, but
         # at least it's isolated here. First we build the parser, then
@@ -178,11 +182,16 @@
             description = self.description
         self.parser = OptionParser(usage=self.usage,
                                    description=description)
-        scripts.logger_options(self.parser, default=self.loglevel)
-        self.parser.add_option(
-            '--profile', dest='profile', metavar='FILE', help=(
-                    "Run the script under the profiler and save the "
-                    "profiling stats in FILE."))
+
+        if logger is None:
+            scripts.logger_options(self.parser, default=self.loglevel)
+            self.parser.add_option(
+                '--profile', dest='profile', metavar='FILE', help=(
+                        "Run the script under the profiler and save the "
+                        "profiling stats in FILE."))
+        else:
+            scripts.dummy_logger_options(self.parser)
+
         self.add_my_options()
         self.options, self.args = self.parser.parse_args(args=test_args)
 
@@ -191,7 +200,8 @@
         self.handle_options()
 
     def handle_options(self):
-        self.logger = scripts.logger(self.options, self.name)
+        if self.logger is None:
+            self.logger = scripts.logger(self.options, self.name)
 
     @property
     def name(self):
@@ -369,8 +379,9 @@
 class LaunchpadCronScript(LaunchpadScript):
     """Logs successful script runs in the database."""
 
-    def __init__(self, name=None, dbuser=None, test_args=None):
-        super(LaunchpadCronScript, self).__init__(name, dbuser, test_args)
+    def __init__(self, name=None, dbuser=None, test_args=None, logger=None):
+        super(LaunchpadCronScript, self).__init__(
+            name, dbuser, test_args=test_args, logger=logger)
 
         # self.name is used instead of the name argument, since it may have
         # have been overridden by command-line parameters or by