Repository: sphinx-gallery/sphinx-gallery

Issue:
option to control verbosity
The newer version of sphinx-gallery does not anymore print the output from the executed examples on the console. This can be problematic when some of the examples are slightly longer as Circle CI times out if there is no output for 5 minutes. 

This is what I've been facing for [autoreject](https://github.com/autoreject/autoreject/pull/82) where some of the examples are on the longer side. Granted this is not ideal and I'm working on improving the build timing, but I feel this is orthogonal to the issue of verbosity. I prefer to see the output as it also makes debugging easier.

I'm posting the issue as @larsoner mentioned he had some ideas to solve it which could be discussed here.

Thanks a ton!

Discussion:
lesteve: Thanks a lot for the PR. It would be great to add tests. Minimal effort would be just to add unit tests for the LoggingTee.
choldgraf: (changes look good but approve when travis is happy)
larsoner: @jasmainak can you see if this fixes your slow-example problem (autoreject I think)?
jasmainak: okay I'm giving it a try. Thanks for the PR!
jasmainak: umm ... it doesn't seem to be working for me. See: https://github.com/autoreject/autoreject/pull/89. The circle CI output is timing out and doesn't seem to be verbose
jasmainak: okay everything works for me if I use `SPHINXOPTS=-v` and this PR. Thanks!
lesteve: It looks like there are some timeouts in the mayavi build. I have no clue why, any ideas?

lesteve: Some tweaks to work around weird errors but now everything seems fine. Will merge this one, thanks a lot @QuLogic!

Patch:
diff --git a/CHANGES.rst b/CHANGES.rst
index 93ef73b..1028a11 100644
--- a/CHANGES.rst
+++ b/CHANGES.rst
@@ -20,6 +20,11 @@ Bug Fixes
   <https://github.com/sphinx-gallery/sphinx-gallery/pull/311>`_ for more
   details.
 
+* In verbose mode, example output is printed to the console during execution of
+  the example, rather than only at the end. See `#301
+  <https://github.com/sphinx-gallery/sphinx-gallery/issues/301>`_ for a use
+  case where it matters.
+
 Developer changes
 '''''''''''''''''
 
diff --git a/sphinx_gallery/gen_rst.py b/sphinx_gallery/gen_rst.py
index b8aa1c8..29d32d7 100644
--- a/sphinx_gallery/gen_rst.py
+++ b/sphinx_gallery/gen_rst.py
@@ -95,6 +95,48 @@ logger = sphinx_compatibility.getLogger('sphinx-gallery')
 ###############################################################################
 
 
+class LoggingTee(object):
+    """A tee object to redirect streams to the logger"""
+
+    def __init__(self, output_file, logger, src_filename):
+        self.output_file = output_file
+        self.logger = logger
+        self.src_filename = src_filename
+        self.first_write = True
+        self.logger_buffer = ''
+
+    def write(self, data):
+        self.output_file.write(data)
+
+        if self.first_write:
+            self.logger.verbose('Output from %s', self.src_filename,
+                                color='brown')
+            self.first_write = False
+
+        data = self.logger_buffer + data
+        lines = data.splitlines()
+        if data and data[-1] not in '\r\n':
+            # Wait to write last line if it's incomplete. It will write next
+            # time or when the LoggingTee is flushed.
+            self.logger_buffer = lines[-1]
+            lines = lines[:-1]
+        else:
+            self.logger_buffer = ''
+
+        for line in lines:
+            self.logger.verbose('%s', line)
+
+    def flush(self):
+        self.output_file.flush()
+        if self.logger_buffer:
+            self.logger.verbose('%s', self.logger_buffer)
+            self.logger_buffer = ''
+
+    # When called from a local terminal seaborn needs it in Python3
+    def isatty(self):
+        return self.output_file.isatty()
+
+
 class MixedEncodingStringIO(StringIO):
     """Helper when both ASCII and unicode strings will be written"""
 
@@ -478,7 +520,7 @@ def execute_code_block(compiler, src_file, code_block, lineno, example_globals,
 
     my_stdout = MixedEncodingStringIO()
     os.chdir(os.path.dirname(src_file))
-    sys.stdout = my_stdout
+    sys.stdout = LoggingTee(my_stdout, logger, src_file)
 
     try:
         dont_inherit = 1
@@ -491,6 +533,7 @@ def execute_code_block(compiler, src_file, code_block, lineno, example_globals,
         exec(compiler(code_ast, src_file, 'exec'), example_globals)
         time_elapsed = time() - t_start
     except Exception:
+        sys.stdout.flush()
         sys.stdout = orig_stdout
         except_rst = handle_exception(sys.exc_info(), src_file, block_vars,
                                       gallery_conf)
@@ -503,14 +546,13 @@ def execute_code_block(compiler, src_file, code_block, lineno, example_globals,
         code_output = u"\n{0}\n\n\n\n".format(except_rst)
 
     else:
+        sys.stdout.flush()
         sys.stdout = orig_stdout
         os.chdir(cwd)
 
         my_stdout = my_stdout.getvalue().strip().expandtabs()
         if my_stdout:
             stdout = CODE_OUTPUT.format(indent(my_stdout, u' ' * 4))
-            logger.verbose('Output from %s', src_file, color='brown')
-            logger.verbose(my_stdout)
         else:
             stdout = ''
         images_rst, fig_num = save_figures(block_vars['image_path'],


Test patch:
diff --git a/sphinx_gallery/tests/test_gen_rst.py b/sphinx_gallery/tests/test_gen_rst.py
index f5a517f..10cf519 100644
--- a/sphinx_gallery/tests/test_gen_rst.py
+++ b/sphinx_gallery/tests/test_gen_rst.py
@@ -9,11 +9,14 @@ from __future__ import (division, absolute_import, print_function,
 import ast
 import codecs
 import copy
+import io
 import tempfile
 import re
 import os
 import shutil
 import zipfile
+import sys
+
 import pytest
 
 import sphinx_gallery.gen_rst as sg
@@ -321,6 +324,65 @@ def test_figure_rst():
     assert fig_num == 1
 
 
+class TestLoggingTee:
+    def setup(self):
+        self.output_file = io.StringIO()
+        self.src_filename = 'source file name'
+        self.tee = sg.LoggingTee(self.output_file, sg.logger,
+                                 self.src_filename)
+
+    def test_full_line(self, log_collector):
+        # A full line is output immediately.
+        self.tee.write('Output\n')
+        self.tee.flush()
+        assert self.output_file.getvalue() == 'Output\n'
+        assert len(log_collector.calls['verbose']) == 2
+        assert self.src_filename in log_collector.calls['verbose'][0].args
+        assert 'Output' in log_collector.calls['verbose'][1].args
+
+    def test_incomplete_line_with_flush(self, log_collector):
+        # An incomplete line ...
+        self.tee.write('Output')
+        assert self.output_file.getvalue() == 'Output'
+        assert len(log_collector.calls['verbose']) == 1
+        assert self.src_filename in log_collector.calls['verbose'][0].args
+
+        # ... should appear when flushed.
+        self.tee.flush()
+        assert len(log_collector.calls['verbose']) == 2
+        assert 'Output' in log_collector.calls['verbose'][1].args
+
+    def test_incomplete_line_with_more_output(self, log_collector):
+        # An incomplete line ...
+        self.tee.write('Output')
+        assert self.output_file.getvalue() == 'Output'
+        assert len(log_collector.calls['verbose']) == 1
+        assert self.src_filename in log_collector.calls['verbose'][0].args
+
+        # ... should appear when more data is written.
+        self.tee.write('\nMore output\n')
+        assert self.output_file.getvalue() == 'Output\nMore output\n'
+        assert len(log_collector.calls['verbose']) == 3
+        assert 'Output' in log_collector.calls['verbose'][1].args
+        assert 'More output' in log_collector.calls['verbose'][2].args
+
+    def test_multi_line(self, log_collector):
+        self.tee.write('first line\rsecond line\nthird line')
+        assert (self.output_file.getvalue() ==
+                'first line\rsecond line\nthird line')
+        verbose_calls = log_collector.calls['verbose']
+        assert len(verbose_calls) == 3
+        assert self.src_filename in verbose_calls[0].args
+        assert 'first line' in verbose_calls[1].args
+        assert 'second line' in verbose_calls[2].args
+        assert self.tee.logger_buffer == 'third line'
+
+    def test_isatty(self, monkeypatch):
+        assert not self.tee.isatty()
+
+        monkeypatch.setattr(self.tee.output_file, 'isatty', lambda: True)
+        assert self.tee.isatty()
+
 # TODO: test that broken thumbnail does appear when needed
 # TODO: test that examples are not executed twice
 # TODO: test that examples are executed after a no-plot and produce