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)