Bug 1257516 - Make the ConfigureOutputHandler keep some debug messages to print out when an error occurs. r=ted
authorMike Hommey <mh+mozilla@glandium.org>
Fri, 25 Mar 2016 20:00:09 +0900
changeset 290978 062e0b17553ccac075a0cab36f012d9633a64665
parent 290977 e521d0d6b1bf2fe858519d98e452581953cdee6a
child 290979 9bcbc8d381e45de860c4037af1936c4fe4911030
push id19656
push usergwagner@mozilla.com
push dateMon, 04 Apr 2016 13:43:23 +0000
treeherderb2g-inbound@e99061fde28a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersted
bugs1257516
milestone48.0a1
Bug 1257516 - Make the ConfigureOutputHandler keep some debug messages to print out when an error occurs. r=ted The feature is made opt-in by using a context manager.
python/mozbuild/mozbuild/configure/__init__.py
python/mozbuild/mozbuild/configure/util.py
python/mozbuild/mozbuild/test/configure/test_util.py
--- a/python/mozbuild/mozbuild/configure/__init__.py
+++ b/python/mozbuild/mozbuild/configure/__init__.py
@@ -5,16 +5,17 @@
 from __future__ import absolute_import, print_function, unicode_literals
 
 import inspect
 import logging
 import os
 import sys
 import types
 from collections import OrderedDict
+from contextlib import contextmanager
 from functools import wraps
 from mozbuild.configure.options import (
     CommandLineHelper,
     ConflictingOptionError,
     InvalidOptionError,
     NegativeOptionValue,
     Option,
     OptionValue,
@@ -125,45 +126,48 @@ class ConfigureSandbox(dict):
 
         self._helper = CommandLineHelper(environ, argv)
 
         assert isinstance(config, dict)
         self._config = config
 
         if logger is None:
             logger = moz_logger = logging.getLogger('moz.configure')
-            logger.setLevel(logging.INFO)
+            logger.setLevel(logging.DEBUG)
             formatter = logging.Formatter('%(levelname)s: %(message)s')
             handler = ConfigureOutputHandler(stdout, stderr)
-            handler.setLevel(logging.INFO)
             handler.setFormatter(formatter)
+            queue_debug = handler.queue_debug
             logger.addHandler(handler)
 
         else:
             assert isinstance(logger, logging.Logger)
             moz_logger = None
+            @contextmanager
+            def queue_debug():
+                yield
 
-        self.log_impl = ReadOnlyNamespace(**{
-                k: getattr(logger, k)
-                for k in ('debug', 'info', 'warning', 'error')
-        })
+        log_namespace = {
+            k: getattr(logger, k)
+            for k in ('debug', 'info', 'warning', 'error')
+        }
+        log_namespace['queue_debug'] = queue_debug
+        self.log_impl = ReadOnlyNamespace(**log_namespace)
 
         self._help = None
         self._help_option = self.option_impl('--help',
                                              help='print this message')
         self._seen.add(self._help_option)
         # self._option_impl('--help') will have set this if --help was on the
         # command line.
         if self._option_values[self._help_option]:
             self._help = HelpFormatter(argv[0])
             self._help.add(self._help_option)
         elif moz_logger:
-            logger.setLevel(logging.DEBUG)
             handler = logging.FileHandler('config.log', mode='w', delay=True)
-            handler.setLevel(logging.DEBUG)
             handler.setFormatter(formatter)
             logger.addHandler(handler)
 
     def exec_file(self, path):
         '''Execute one file within the sandbox. Users of this class probably
         want to use `run` instead.'''
 
         if self._paths:
--- a/python/mozbuild/mozbuild/configure/util.py
+++ b/python/mozbuild/mozbuild/configure/util.py
@@ -3,16 +3,18 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 from __future__ import absolute_import, print_function, unicode_literals
 
 import itertools
 import logging
 import os
 import sys
+from collections import deque
+from contextlib import contextmanager
 from distutils.version import LooseVersion
 
 
 class Version(LooseVersion):
     '''A simple subclass of distutils.version.LooseVersion.
     Adds attributes for `major`, `minor`, `patch` for the first three
     version components so users can easily pull out major/minor
     versions, like:
@@ -41,67 +43,109 @@ class Version(LooseVersion):
 
 class ConfigureOutputHandler(logging.Handler):
     '''A logging handler class that sends info messages to stdout and other
     messages to stderr.
 
     Messages sent to stdout are not formatted with the attached Formatter.
     Additionally, if they end with '... ', no newline character is printed,
     making the next message printed follow the '... '.
+
+    Only messages above log level INFO (included) are logged.
+
+    Messages below that level can be kept until an ERROR message is received,
+    at which point the last `maxlen` accumulated messages below INFO are
+    printed out. This feature is only enabled under the `queue_debug` context
+    manager.
     '''
-    def __init__(self, stdout=sys.stdout, stderr=sys.stderr):
+    def __init__(self, stdout=sys.stdout, stderr=sys.stderr, maxlen=20):
         super(ConfigureOutputHandler, self).__init__()
         self._stdout, self._stderr = stdout, stderr
         try:
             fd1 = self._stdout.fileno()
             fd2 = self._stderr.fileno()
             self._same_output = self._is_same_output(fd1, fd2)
         except AttributeError:
             self._same_output = self._stdout == self._stderr
         self._stdout_waiting = None
+        self._debug = deque(maxlen=maxlen + 1)
+        self._keep_if_debug = self.THROW
 
     @staticmethod
     def _is_same_output(fd1, fd2):
         if fd1 == fd2:
             return True
         stat1 = os.fstat(fd1)
         stat2 = os.fstat(fd2)
         return stat1.st_ino == stat2.st_ino and stat1.st_dev == stat2.st_dev
 
+    # possible values for _stdout_waiting
     WAITING = 1
     INTERRUPTED = 2
 
+    # possible values for _keep_if_debug
+    THROW = 0
+    KEEP = 1
+    PRINT = 2
+
     def emit(self, record):
         try:
             if record.levelno == logging.INFO:
                 stream = self._stdout
                 msg = record.getMessage()
                 if (self._stdout_waiting == self.INTERRUPTED and
                         self._same_output):
                     msg = ' ... %s' % msg
                 self._stdout_waiting = msg.endswith('... ')
                 if msg.endswith('... '):
                     self._stdout_waiting = self.WAITING
                 else:
                     self._stdout_waiting = None
                     msg = '%s\n' % msg
+            elif (record.levelno < logging.INFO and
+                    self._keep_if_debug != self.PRINT):
+                if self._keep_if_debug == self.KEEP:
+                    self._debug.append(record)
+                return
             else:
+                if record.levelno >= logging.ERROR and len(self._debug):
+                    self._keep_if_debug = self.PRINT
+                    if len(self._debug) == self._debug.maxlen:
+                        r = self._debug.popleft()
+                        self.emit(logging.LogRecord(
+                            r.name, r.levelno, r.pathname, r.lineno,
+                            '<truncated - see config.log for full output>',
+                            (), None))
+                    while True:
+                        try:
+                            self.emit(self._debug.popleft())
+                        except IndexError:
+                            break
+                    self._keep_if_debug = self.KEEP
+
                 if self._stdout_waiting == self.WAITING and self._same_output:
                     self._stdout_waiting = self.INTERRUPTED
                     self._stdout.write('\n')
                     self._stdout.flush()
                 stream = self._stderr
                 msg = '%s\n' % self.format(record)
             stream.write(msg)
             stream.flush()
         except (KeyboardInterrupt, SystemExit):
             raise
         except:
             self.handleError(record)
 
+    @contextmanager
+    def queue_debug(self):
+        self._keep_if_debug = self.KEEP
+        yield
+        self._keep_if_debug = self.THROW
+        self._debug.clear()
+
 
 class LineIO(object):
     '''File-like class that sends each line of the written data to a callback
     (without carriage returns).
     '''
     def __init__(self, callback):
         self._callback = callback
         self._buf = ''
--- a/python/mozbuild/mozbuild/test/configure/test_util.py
+++ b/python/mozbuild/mozbuild/test/configure/test_util.py
@@ -28,42 +28,43 @@ class TestConfigureOutputHandler(unittes
         name = '%s.test_separation' % self.__class__.__name__
         logger = logging.getLogger(name)
         logger.setLevel(logging.DEBUG)
         logger.addHandler(ConfigureOutputHandler(out, err))
 
         logger.error('foo')
         logger.warning('bar')
         logger.info('baz')
+        # DEBUG level is not printed out by this handler
         logger.debug('qux')
 
         self.assertEqual(out.getvalue(), 'baz\n')
-        self.assertEqual(err.getvalue(), 'foo\nbar\nqux\n')
+        self.assertEqual(err.getvalue(), 'foo\nbar\n')
 
     def test_format(self):
         out = StringIO()
         err = StringIO()
         name = '%s.test_format' % self.__class__.__name__
         logger = logging.getLogger(name)
         logger.setLevel(logging.DEBUG)
         handler =  ConfigureOutputHandler(out, err)
         handler.setFormatter(logging.Formatter('%(levelname)s:%(message)s'))
         logger.addHandler(handler)
 
         logger.error('foo')
         logger.warning('bar')
         logger.info('baz')
+        # DEBUG level is not printed out by this handler
         logger.debug('qux')
 
         self.assertEqual(out.getvalue(), 'baz\n')
         self.assertEqual(
             err.getvalue(),
             'ERROR:foo\n'
             'WARNING:bar\n'
-            'DEBUG:qux\n'
         )
 
     def test_continuation(self):
         out = StringIO()
         name = '%s.test_continuation' % self.__class__.__name__
         logger = logging.getLogger(name)
         logger.setLevel(logging.DEBUG)
         handler =  ConfigureOutputHandler(out, out)
@@ -144,16 +145,96 @@ class TestConfigureOutputHandler(unittes
         )
 
         self.assertEqual(
             err.getvalue(),
             'WARNING:hoge\n'
             'WARNING:fuga\n'
         )
 
+    def test_queue_debug(self):
+        out = StringIO()
+        name = '%s.test_queue_debug' % self.__class__.__name__
+        logger = logging.getLogger(name)
+        logger.setLevel(logging.DEBUG)
+        handler =  ConfigureOutputHandler(out, out, maxlen=3)
+        handler.setFormatter(logging.Formatter('%(levelname)s:%(message)s'))
+        logger.addHandler(handler)
+
+        with handler.queue_debug():
+            logger.info('checking bar... ')
+            logger.debug('do foo')
+            logger.info('yes')
+            logger.info('qux')
+
+        self.assertEqual(
+            out.getvalue(),
+            'checking bar... yes\n'
+            'qux\n'
+        )
+
+        out.seek(0)
+        out.truncate()
+
+        with handler.queue_debug():
+            logger.info('checking bar... ')
+            logger.debug('do foo')
+            logger.info('no')
+            logger.error('fail')
+
+        self.assertEqual(
+            out.getvalue(),
+            'checking bar... no\n'
+            'DEBUG:do foo\n'
+            'ERROR:fail\n'
+        )
+
+        out.seek(0)
+        out.truncate()
+
+        with handler.queue_debug():
+            logger.info('checking bar... ')
+            logger.debug('do foo')
+            logger.debug('do bar')
+            logger.debug('do baz')
+            logger.info('no')
+            logger.error('fail')
+
+        self.assertEqual(
+            out.getvalue(),
+            'checking bar... no\n'
+            'DEBUG:do foo\n'
+            'DEBUG:do bar\n'
+            'DEBUG:do baz\n'
+            'ERROR:fail\n'
+        )
+
+        out.seek(0)
+        out.truncate()
+
+        with handler.queue_debug():
+            logger.info('checking bar... ')
+            logger.debug('do foo')
+            logger.debug('do bar')
+            logger.debug('do baz')
+            logger.debug('do qux')
+            logger.debug('do hoge')
+            logger.info('no')
+            logger.error('fail')
+
+        self.assertEqual(
+            out.getvalue(),
+            'checking bar... no\n'
+            'DEBUG:<truncated - see config.log for full output>\n'
+            'DEBUG:do baz\n'
+            'DEBUG:do qux\n'
+            'DEBUG:do hoge\n'
+            'ERROR:fail\n'
+        )
+
     def test_is_same_output(self):
         fd1 = sys.stderr.fileno()
         fd2 = os.dup(fd1)
         try:
             self.assertTrue(ConfigureOutputHandler._is_same_output(fd1, fd2))
         finally:
             os.close(fd2)