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.
--- 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)