util.check_output: when debug logging, dump output immediately

asv/console.py

@@ -275,15 +275,20 @@ def _stream_formatter(self, record):
  rest = parts[1]
 
  indent = self._indent + 1
+ continued = getattr(record, 'continued', False)
 
  if self._total:
  progress_msg = '[{0:6.02f}%] '.format(
  (float(self._count) / self._total) * 100.0)
- color_print(progress_msg, end='')
+ if not continued:
+ color_print(progress_msg, end='')
  indent += len(progress_msg)
 
- color_print('·' * self._indent, end='')
- color_print(' ', end='')
+ if not continued:
+ color_print('·' * self._indent, end='')
+ color_print(' ', end='')
+ else:
+ color_print(' ' * indent, end='')
 
  if hasattr(record, 'color'):
  color = record.color
@@ -380,10 +385,16 @@ def set_level(self, level):
  def is_debug_enabled(self):
  return self._logger.getEffectiveLevel() <= logging.DEBUG
 
- def _message(self, routine, message, reserve_space=False, color=None):
+ def _message(self, routine, message, reserve_space=False, color=None,
+ continued=False):
  kwargs = {}
+ extra = {}
  if color is not None:
- kwargs['extra'] = dict(color=color)
+ extra['color'] = color
+ if continued:
+ extra['continued'] = True
+ if extra:
+ kwargs['extra'] = extra
 
  if reserve_space:
  max_width = max(16, util.get_terminal_width() - 33)

asv/util.py

@@ -369,6 +369,38 @@ def check_call(args, valid_return_codes=(0,), timeout=600, dots=True,
  cwd=cwd)
 
 
+class DebugLogBuffer(object):
+ def __init__(self, log):
+ self.buf = []
+ self.first = True
+ self.linebreak_re = re.compile(b'.*\n')
+ self.log = log
+
+ def __call__(self, c):
+ if c is None:
+ text = b"".join(self.buf)
+ del self.buf[:]
+ elif b'\n' in c:
+ m = self.linebreak_re.match(c)
+ j = m.end()
+ self.buf.append(c[:j])
+ text = b"".join(self.buf)
+ self.buf[:] = [c[j:]]
+ else:
+ self.buf.append(c)
+ return
+
+ text = text.decode('utf-8', 'replace')
+ if text.endswith('\n'):
+ text = text[:-1]
+
+ if text:
+ if self.first:
+ self.log.debug('OUTPUT -------->', continued=True)
+ self.first = False
+ self.log.debug(text, continued=True)
+
+
 def check_output(args, valid_return_codes=(0,), timeout=600, dots=True,
  display_error=True, shell=False, return_stderr=False,
  env=None, cwd=None, redirect_stderr=False, return_popen=False):
@@ -486,6 +518,11 @@ def _fix_env(s):
  stderr_chunks = []
  is_timeout = False
 
+ if log.is_debug_enabled():
+ debug_log = DebugLogBuffer(log)
+ else:
+ debug_log = lambda c: None
+
  if WIN:
  start_time = [time.time()]
  was_timeout = [False]
@@ -497,6 +534,7 @@ def stdout_reader_run():
  break
  start_time[0] = time.time()
  stdout_chunks.append(c)
+ debug_log(c)
 
  def stderr_reader_run():
  while True:
@@ -505,6 +543,7 @@ def stderr_reader_run():
  break
  start_time[0] = time.time()
  stderr_chunks.append(c)
+ debug_log(c)
 
  def watcher_run():
  while proc.returncode is None:
@@ -579,6 +618,7 @@ def sig_forward(signum, frame):
  for f in rlist:
  output = os.read(f, PIPE_BUF)
  fds[f].append(output)
+ debug_log(output)
  if dots and time.time() - last_dot_time > 0.5:
  if dots is True:
  log.dot()
@@ -621,6 +661,8 @@ def sig_forward(signum, frame):
  if not redirect_stderr:
  proc.stderr.close()
 
+ debug_log(None)
+
  stdout = b''.join(stdout_chunks)
  stderr = b''.join(stderr_chunks)
 
@@ -635,13 +677,12 @@ def sig_forward(signum, frame):
  if valid_return_codes is not None and retcode not in valid_return_codes:
  header = 'Error running {0}'.format(' '.join(args))
  if display_error:
- log.error(get_content(header))
- else:
  if log.is_debug_enabled():
- log.debug(get_content(header))
+ # Output was already printed
+ log.error(header)
+ else:
+ log.error(get_content(header))
  raise ProcessError(args, retcode, stdout, stderr)
- elif log.is_debug_enabled():
- log.debug(get_content())
 
  if return_stderr:
  return (stdout, stderr, retcode)