Bug 1257516 - Make the ConfigureOutputHandler keep some debug messages to print out when an error occurs. r?ted draft
authorMike Hommey <mh+mozilla@glandium.org>
Fri, 25 Mar 2016 20:00:09 +0900
changeset 344697 b3af64933052e4f61c878e467101c65901d2f71f
parent 344696 6ed8521425345d88a64dfea34ccf399a07d69803
child 344698 edfc845531ba258ccbde22c993786e2b8fe35a11
push id13908
push userbmo:mh+mozilla@glandium.org
push dateFri, 25 Mar 2016 11:36:41 +0000
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,27 +43,36 @@ 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 following 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 = False
 
     @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
@@ -78,30 +89,57 @@ class ConfigureOutputHandler(logging.Han
                         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
+                    isinstance(self._keep_if_debug, bool)):
+                if self._keep_if_debug:
+                    self._debug.append(record)
+                return
             else:
+                if record.levelno >= logging.ERROR and len(self._debug):
+                    self._keep_if_debug = '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 = True
+
                 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 = True
+        yield
+        self._keep_if_debug = False
+        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)