launchpad-reviewers team mailing list archive

[Stuart Bishop <stuart.bishop@xxxxxxxxxxxxx>]

Stuart Bishop has proposed merging lp:~stub/launchpad/trivial into lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  Bug #951401 in Launchpad itself: "parse-ppa-apache-logs failing (missing files)"
  https://bugs.launchpad.net/launchpad/+bug/951401

For more details, see:
https://code.launchpad.net/~stub/launchpad/trivial/+merge/129401

= Summary =

There may still be improvements to make to full-update.py, but we have reached the point where we cannot identify bottlenecks without switching to millisecond precision timestamps in its output.

== Proposed fix ==

Add --ms and --no-ms options to all scripts using the standard logging system, giving everything the ability to turn on millisecond precision timestamps.

Turn the option on by default for full-update.py to make ops procedures less cumbersome.

== Pre-implementation notes ==

== LOC Rationale ==

I am a golden god.

== Implementation details ==

== Tests ==

== Demo and Q/A ==


= Launchpad lint =

Checking for conflicts and issues in changed files.

Linting changed files:
  lib/lp/services/scripts/logger.py
  database/schema/full-update.py

./database/schema/full-update.py
       7: '_pythonpath' imported but unused
-- 
https://code.launchpad.net/~stub/launchpad/trivial/+merge/129401
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~stub/launchpad/trivial into lp:launchpad.

=== modified file 'database/schema/full-update.py'
--- database/schema/full-update.py	2012-09-28 06:15:58 +0000
+++ database/schema/full-update.py	2012-10-12 11:57:33 +0000
@@ -87,7 +87,7 @@
         '--dbuser', dest='dbuser', default='postgres', metavar='USERNAME',
         help='Connect as USERNAME to databases')
 
-    logger_options(parser)
+    logger_options(parser, milliseconds=True)
     (options, args) = parser.parse_args()
     if args:
         parser.error("Too many arguments")

=== modified file 'lib/lp/services/scripts/logger.py'
--- lib/lp/services/scripts/logger.py	2011-12-30 02:24:09 +0000
+++ lib/lp/services/scripts/logger.py	2012-10-12 11:57:33 +0000
@@ -98,15 +98,13 @@
 class LaunchpadFormatter(Formatter):
     """logging.Formatter encoding our preferred output format."""
 
-    def __init__(self, fmt=None, datefmt=None):
+    def __init__(self, fmt=None, datefmt="%Y-%m-%d %H:%M:%S"):
         if fmt is None:
             if config.isTestRunner():
                 # Don't output timestamps in the test environment
                 fmt = '%(levelname)-7s %(message)s'
             else:
                 fmt = '%(asctime)s %(levelname)-7s %(message)s'
-        if datefmt is None:
-            datefmt = "%Y-%m-%d %H:%M:%S"
         logging.Formatter.__init__(self, fmt, datefmt)
         # Output should be UTC.
         self.converter = time.gmtime
@@ -232,12 +230,14 @@
     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.
+def logger_options(parser, default=logging.INFO, milliseconds=False):
+    """Add the --verbose, --quiet & --ms options to an optparse.OptionParser.
 
     The requested loglevel will end up in the option's loglevel attribute.
     Note that loglevel is not clamped to any particular range.
 
+    The milliseconds parameter specifies the default for the --ms option.
+
     >>> from optparse import OptionParser
     >>> parser = OptionParser()
     >>> logger_options(parser)
@@ -327,8 +327,27 @@
         help="Send log messages to FILE. LVL is one of %s" % debug_levels)
     parser.set_default('log_file_level', None)
 
+    def milliseconds_cb(option, opt_str, value, parser):
+        if opt_str == "--ms":
+            value = True
+        else:
+            value = False
+        parser.values.milliseconds = value
+        log._log = _logger(
+            parser.values.loglevel, out_stream=sys.stderr, milliseconds=value)
+
+    parser.add_option(
+        "--ms", action="callback", default=milliseconds,
+        dest="milliseconds", callback=milliseconds_cb,
+        help="Include milliseconds in log output timestamps")
+    parser.add_option(
+        "--no-ms", action="callback", default=milliseconds,
+        dest="milliseconds", callback=milliseconds_cb,
+        help="Include milliseconds in log output timestamps")
+
     # Set the global log
-    log._log = _logger(default, out_stream=sys.stderr)
+    log._log = _logger(
+        default, out_stream=sys.stderr, milliseconds=milliseconds)
 
 
 def logger(options=None, name=None):
@@ -359,7 +378,8 @@
 
     return _logger(
         options.loglevel, out_stream=sys.stderr, name=name,
-        log_file=log_file, log_file_level=log_file_level)
+        log_file=log_file, log_file_level=log_file_level,
+        milliseconds=options.milliseconds)
 
 
 def reset_root_logger():
@@ -375,7 +395,7 @@
 
 def _logger(
     level, out_stream, name=None,
-    log_file=None, log_file_level=logging.DEBUG):
+    log_file=None, log_file_level=logging.DEBUG, milliseconds=False):
     """Create the actual logger instance, logging at the given level
 
     if name is None, it will get args[0] without the extension (e.g. gina).
@@ -403,7 +423,12 @@
     # logs.
     root_logger.setLevel(0)
     hdlr.setLevel(level)
-    formatter = LibrarianFormatter()
+    if milliseconds:
+        # Python default datefmt includes milliseconds.
+        formatter = LibrarianFormatter(datefmt=None)
+    else:
+        # Launchpad default datefmt does not include milliseconds.
+        formatter = LibrarianFormatter()
     hdlr.setFormatter(formatter)
     root_logger.addHandler(hdlr)