Proc, #519: Rework error-exc msgs & log thread-pumps errors

+ No WindowsError exception.
+ Add `test_exc.py` for unicode issues.
+ Single-arg for decoding-streams in pump-func.

9 files changed, 240 insertions, 57 deletions

diff --git a/git/cmd.py b/git/cmd.py
index feb16e30..20da96bd 100644
--- a/git/cmd.py
+++ b/git/cmd.py
@@ -45,6 +45,7 @@ from git.compat import (
 )
 import io
 from _io import UnsupportedOperation
+from git.exc import CommandError
 
 execute_kwargs = set(('istream', 'with_keep_cwd', 'with_extended_output',
                       'with_exceptions', 'as_process', 'stdout_as_string',
@@ -56,9 +57,6 @@ log.addHandler(logging.NullHandler())
 
 __all__ = ('Git',)
 
-if is_win:
-    WindowsError = OSError  # @ReservedAssignment
-
 if PY3:
     _bchr = bchr
 else:
@@ -73,17 +71,23 @@ else:
 # Documentation
 ## @{
 
-def handle_process_output(process, stdout_handler, stderr_handler, finalizer,
-                          decode_stdout=True, decode_stderr=True):
+def handle_process_output(process, stdout_handler, stderr_handler, finalizer, decode_streams=True):
     """Registers for notifications to lean that process output is ready to read, and dispatches lines to
     the respective line handlers. We are able to handle carriage returns in case progress is sent by that
     mean. For performance reasons, we only apply this to stderr.
     This function returns once the finalizer returns
+
     :return: result of finalizer
     :param process: subprocess.Popen instance
     :param stdout_handler: f(stdout_line_string), or None
     :param stderr_hanlder: f(stderr_line_string), or None
-    :param finalizer: f(proc) - wait for proc to finish"""
+    :param finalizer: f(proc) - wait for proc to finish
+    :param decode_streams:
+        Assume stdout/stderr streams are binary and decode them vefore pushing \
+        their contents to handlers.
+        Set it to False if `universal_newline == True` (then streams are in text-mode)
+        or if decoding must happen later (i.e. for Diffs).
+    """
 
     def _parse_lines_from_buffer(buf):
         line = b''
@@ -156,18 +160,29 @@ def handle_process_output(process, stdout_handler, stderr_handler, finalizer,
         # Oh ... probably we are on windows. or TC mockap provided for streams.
         # Anyhow, select.select() can only handle sockets, we have files
         # The only reliable way to do this now is to use threads and wait for both to finish
-        def _handle_lines(fd, handler, decode):
-            for line in fd:
-                if handler:
-                    if decode:
-                        line = line.decode(defenc)
-                    handler(line)
-
+        def pump_stream(cmdline, name, stream, is_decode, handler):
+            try:
+                for line in stream:
+                    if handler:
+                        if is_decode:
+                            line = line.decode(defenc)
+                        handler(line)
+            except Exception as ex:
+                log.error("Pumping %r of cmd(%s) failed due to: %r", name, cmdline, ex)
+                raise CommandError(['<%s-pump>' % name] + cmdline, ex)
+            finally:
+                stream.close()
+
+        cmdline = getattr(process, 'args', '')  # PY3+ only
+        if not isinstance(cmdline, (tuple, list)):
+            cmdline = cmdline.split()
         threads = []
-        for fd, handler, decode in zip((process.stdout, process.stderr),
-                                       (stdout_handler, stderr_handler),
-                                       (decode_stdout, decode_stderr),):
-            t = threading.Thread(target=_handle_lines, args=(fd, handler, decode))
+        for name, stream, handler in (
+            ('stdout', process.stdout, stdout_handler),
+            ('stderr', process.stderr, stderr_handler),
+        ):
+            t = threading.Thread(target=pump_stream,
+                                 args=(cmdline, name, stream, decode_streams, handler))
             t.setDaemon(True)
             t.start()
             threads.append(t)
@@ -177,8 +192,8 @@ def handle_process_output(process, stdout_handler, stderr_handler, finalizer,
     else:
             # poll is preferred, as select is limited to file handles up to 1024 ... . This could otherwise be
             # an issue for us, as it matters how many handles our own process has
-            fdmap = {outfn: (stdout_handler, [b''], decode_stdout),
-                     errfn: (stderr_handler, [b''], decode_stderr)}
+            fdmap = {outfn: (stdout_handler, [b''], decode_streams),
+                     errfn: (stderr_handler, [b''], decode_streams)}
 
             READ_ONLY = select.POLLIN | select.POLLPRI | select.POLLHUP | select.POLLERR  # @UndefinedVariable
             CLOSED = select.POLLHUP | select.POLLERR                                      # @UndefinedVariable
@@ -334,7 +349,8 @@ class Git(LazyMixin):
             try:
                 proc.terminate()
                 proc.wait()    # ensure process goes away
-            except (OSError, WindowsError):
+            except OSError as ex:
+                log.info("Ignored error after process has dies: %r", ex)
                 pass  # ignore error when process already died
             except AttributeError:
                 # try windows
@@ -638,12 +654,12 @@ class Git(LazyMixin):
         env.update(self._environment)
 
         if is_win:
-            cmd_not_found_exception = WindowsError
+            cmd_not_found_exception = OSError
             if kill_after_timeout:
-                raise GitCommandError('"kill_after_timeout" feature is not supported on Windows.')
+                raise GitCommandError(command, '"kill_after_timeout" feature is not supported on Windows.')
         else:
             if sys.version_info[0] > 2:
-                cmd_not_found_exception = FileNotFoundError  # NOQA # this is defined, but flake8 doesn't know
+                cmd_not_found_exception = FileNotFoundError  # NOQA # exists, flake8 unknown @UndefinedVariable
             else:
                 cmd_not_found_exception = OSError
         # end handle
@@ -663,7 +679,7 @@ class Git(LazyMixin):
                          **subprocess_kwargs
                          )
         except cmd_not_found_exception as err:
-            raise GitCommandNotFound('%s: %s' % (command[0], err))
+            raise GitCommandNotFound(command, err)
 
         if as_process:
             return self.AutoInterrupt(proc, command)
diff --git a/git/diff.py b/git/diff.py
index 54804c45..35c7ff86 100644
--- a/git/diff.py
+++ b/git/diff.py
@@ -407,7 +407,7 @@ class Diff(object):
 
         ## FIXME: Here SLURPING raw, need to re-phrase header-regexes linewise.
         text = []
-        handle_process_output(proc, text.append, None, finalize_process, decode_stdout=False)
+        handle_process_output(proc, text.append, None, finalize_process, decode_streams=False)
 
         # for now, we have to bake the stream
         text = b''.join(text)
@@ -499,6 +499,6 @@ class Diff(object):
                         new_file, deleted_file, rename_from, rename_to, '', change_type)
             index.append(diff)
 
-        handle_process_output(proc, handle_diff_line, None, finalize_process, decode_stdout=False)
+        handle_process_output(proc, handle_diff_line, None, finalize_process, decode_streams=False)
 
         return index
diff --git a/git/exc.py b/git/exc.py
index 37712d11..6c9cde34 100644
--- a/git/exc.py
+++ b/git/exc.py
@@ -6,7 +6,7 @@
 """ Module containing all exceptions thrown througout the git package, """
 
 from gitdb.exc import *     # NOQA
-from git.compat import UnicodeMixin, safe_decode
+from git.compat import UnicodeMixin, safe_decode, string_types
 
 
 class InvalidGitRepositoryError(Exception):
@@ -21,25 +21,56 @@ class NoSuchPathError(OSError):
     """ Thrown if a path could not be access by the system. """
 
 
-class GitCommandNotFound(Exception):
+class CommandError(UnicodeMixin, Exception):
+    """Base class for exceptions thrown at every stage of `Popen()` execution.
+
+    :param command:
+        A non-empty list of argv comprising the command-line.
+    """
+
+    #: A unicode print-format with 2 `%s for `<cmdline>` and the rest,
+    #:  e.g.
+    #:     u"'%s' failed%s"
+    _msg = u"Cmd('%s') failed%s"
+
+    def __init__(self, command, status=None, stderr=None, stdout=None):
+        assert isinstance(command, (tuple, list)), command
+        self.command = command
+        self.status = status
+        if status:
+            if isinstance(status, Exception):
+                status = u"%s('%s')" % (type(status).__name__, safe_decode(str(status)))
+            else:
+                try:
+                    status = u'exit code(%s)' % int(status)
+                except:
+                    s = safe_decode(str(status))
+                    status = u"'%s'" % s if isinstance(status, string_types) else s
+
+        self._cmd = safe_decode(command[0])
+        self._cmdline = u' '.join(safe_decode(i) for i in command)
+        self._cause = status and u" due to: %s" % status or "!"
+        self.stdout = stdout and u"\n  stdout: '%s'" % safe_decode(stdout) or ''
+        self.stderr = stderr and u"\n  stderr: '%s'" % safe_decode(stderr) or ''
+
+    def __unicode__(self):
+        return (self._msg + "\n  cmdline: %s%s%s") % (
+            self._cmd, self._cause, self._cmdline, self.stdout, self.stderr)
+
+
+class GitCommandNotFound(CommandError):
     """Thrown if we cannot find the `git` executable in the PATH or at the path given by
     the GIT_PYTHON_GIT_EXECUTABLE environment variable"""
-    pass
+    def __init__(self, command, cause):
+        super(GitCommandNotFound, self).__init__(command, cause)
+        self._msg = u"Cmd('%s') not found%s"
 
 
-class GitCommandError(UnicodeMixin, Exception):
+class GitCommandError(CommandError):
     """ Thrown if execution of the git command fails with non-zero status code. """
 
     def __init__(self, command, status, stderr=None, stdout=None):
-        self.stderr = stderr
-        self.stdout = stdout
-        self.status = status
-        self.command = command
-
-    def __unicode__(self):
-        cmdline = u' '.join(safe_decode(i) for i in self.command)
-        return (u"'%s' returned with exit code %s\n  stdout: '%s'\n  stderr: '%s'"
-                % (cmdline, self.status, safe_decode(self.stdout), safe_decode(self.stderr)))
+        super(GitCommandError, self).__init__(command, status, stderr, stdout)
 
 
 class CheckoutError(Exception):
@@ -76,20 +107,13 @@ class UnmergedEntriesError(CacheError):
     entries in the cache"""
 
 
-class HookExecutionError(UnicodeMixin, Exception):
+class HookExecutionError(CommandError):
     """Thrown if a hook exits with a non-zero exit code. It provides access to the exit code and the string returned
     via standard output"""
 
-    def __init__(self, command, status, stdout=None, stderr=None):
-        self.command = command
-        self.status = status
-        self.stdout = stdout
-        self.stderr = stderr
-
-    def __unicode__(self):
-        cmdline = u' '.join(safe_decode(i) for i in self.command)
-        return (u"'%s' hook failed with %r\n  stdout: '%s'\n  stderr: '%s'"
-                % (cmdline, self.status, safe_decode(self.stdout), safe_decode(self.stderr)))
+    def __init__(self, command, status, stderr=None, stdout=None):
+        super(HookExecutionError, self).__init__(command, status, stderr, stdout)
+        self._msg = u"Hook('%s') failed%s"
 
 
 class RepositoryDirtyError(Exception):
diff --git a/git/index/base.py b/git/index/base.py
index 6656d940..d7d9fc3a 100644
--- a/git/index/base.py
+++ b/git/index/base.py
@@ -1091,6 +1091,7 @@ class IndexFile(LazyMixin, diff.Diffable, Serializable):
             kwargs['as_process'] = True
             kwargs['istream'] = subprocess.PIPE
             proc = self.repo.git.checkout_index(args, **kwargs)
+            # FIXME: Reading from GIL!
             make_exc = lambda: GitCommandError(("git-checkout-index",) + tuple(args), 128, proc.stderr.read())
             checked_out_files = list()
 
diff --git a/git/remote.py b/git/remote.py
index 07f5b432..58238991 100644
--- a/git/remote.py
+++ b/git/remote.py
@@ -681,8 +681,7 @@ class Remote(LazyMixin, Iterable):
         # END for each line
 
         try:
-            handle_process_output(proc, stdout_handler, progress_handler, finalize_process,
-                                  decode_stdout=False, decode_stderr=False)
+            handle_process_output(proc, stdout_handler, progress_handler, finalize_process, decode_streams=False)
         except Exception:
             if len(output) == 0:
                 raise
diff --git a/git/test/test_exc.py b/git/test/test_exc.py
new file mode 100644
index 00000000..7e6b023e
--- /dev/null
+++ b/git/test/test_exc.py
@@ -0,0 +1,142 @@
+# -*- coding: utf-8 -*-
+# test_exc.py
+# Copyright (C) 2008, 2009, 2016 Michael Trier (mtrier@gmail.com) and contributors
+#
+# This module is part of GitPython and is released under
+# the BSD License: http://www.opensource.org/licenses/bsd-license.php
+
+
+import re
+
+import ddt
+from git.exc import (
+    CommandError,
+    GitCommandNotFound,
+    GitCommandError,
+    HookExecutionError,
+)
+from git.test.lib import TestBase
+
+import itertools as itt
+
+
+_cmd_argvs = (
+    ('cmd', ),
+    ('θνιψοδε', ),
+    ('θνιψοδε', 'normal', 'argvs'),
+    ('cmd', 'ελληνικα', 'args'),
+    ('θνιψοδε', 'κι', 'αλλα', 'strange', 'args'),
+    ('θνιψοδε', 'κι', 'αλλα', 'non-unicode', 'args'),
+)
+_causes_n_substrings = (
+    (None,                      None),                          # noqa: E241
+    (7,                         "exit code(7)"),                           # noqa: E241
+    ('Some string',             "'Some string'"),               # noqa: E241
+    ('παλιο string',            "'παλιο string'"),              # noqa: E241
+    (Exception("An exc."),      "Exception('An exc.')"),        # noqa: E241
+    (Exception("Κακια exc."),   "Exception('Κακια exc.')"),     # noqa: E241
+    (object(),                  "<object object at "),         # noqa: E241
+)
+
+_streams_n_substrings = (None, 'steram', 'ομορφο stream', )
+
+
+@ddt.ddt
+class TExc(TestBase):
+
+    @ddt.data(*list(itt.product(_cmd_argvs, _causes_n_substrings, _streams_n_substrings)))
+    def test_CommandError_unicode(self, case):
+        argv, (cause, subs), stream = case
+        cls = CommandError
+        c = cls(argv, cause)
+        s = str(c)
+
+        self.assertIsNotNone(c._msg)
+        self.assertIn('  cmdline: ', s)
+
+        for a in argv:
+            self.assertIn(a, s)
+
+        if not cause:
+            self.assertIn("failed!", s)
+        else:
+            self.assertIn(" failed due to:", s)
+
+            if subs is not None:
+                # Substrings (must) already contain opening `'`.
+                subs = "(?<!')%s(?!')" % re.escape(subs)
+                self.assertRegexpMatches(s, subs)
+
+        if not stream:
+            c = cls(argv, cause)
+            s = str(c)
+            self.assertNotIn("  stdout:", s)
+            self.assertNotIn("  stderr:", s)
+        else:
+            c = cls(argv, cause, stream)
+            s = str(c)
+            self.assertIn("  stderr:", s)
+            self.assertIn(stream, s)
+
+            c = cls(argv, cause, None, stream)
+            s = str(c)
+            self.assertIn("  stdout:", s)
+            self.assertIn(stream, s)
+
+            c = cls(argv, cause, stream, stream + 'no2')
+            s = str(c)
+            self.assertIn("  stderr:", s)
+            self.assertIn(stream, s)
+            self.assertIn("  stdout:", s)
+            self.assertIn(stream + 'no2', s)
+
+    @ddt.data(
+        (['cmd1'], None),
+        (['cmd1'], "some cause"),
+        (['cmd1'], Exception()),
+    )
+    def test_GitCommandNotFound(self, init_args):
+        argv, cause = init_args
+        c = GitCommandNotFound(argv, cause)
+        s = str(c)
+
+        self.assertIn(argv[0], s)
+        if cause:
+            self.assertIn(' not found due to: ', s)
+            self.assertIn(str(cause), s)
+        else:
+            self.assertIn(' not found!', s)
+
+    @ddt.data(
+        (['cmd1'], None),
+        (['cmd1'], "some cause"),
+        (['cmd1'], Exception()),
+    )
+    def test_GitCommandError(self, init_args):
+        argv, cause = init_args
+        c = GitCommandError(argv, cause)
+        s = str(c)
+
+        self.assertIn(argv[0], s)
+        if cause:
+            self.assertIn(' failed due to: ', s)
+            self.assertIn(str(cause), s)
+        else:
+            self.assertIn(' failed!', s)
+
+    @ddt.data(
+        (['cmd1'], None),
+        (['cmd1'], "some cause"),
+        (['cmd1'], Exception()),
+    )
+    def test_HookExecutionError(self, init_args):
+        argv, cause = init_args
+        c = HookExecutionError(argv, cause)
+        s = str(c)
+
+        self.assertIn(argv[0], s)
+        if cause:
+            self.assertTrue(s.startswith('Hook('), s)
+            self.assertIn(str(cause), s)
+        else:
+            self.assertIn(' failed!', s)
diff --git a/git/test/test_git.py b/git/test/test_git.py
index a676d7f7..8a0242e6 100644
--- a/git/test/test_git.py
+++ b/git/test/test_git.py
@@ -27,6 +27,7 @@ from git import (
 from git.test.lib import with_rw_directory
 
 from git.compat import PY3, is_darwin
+from git.util import finalize_process
 
 try:
     from unittest import mock
@@ -233,7 +234,8 @@ class TestGit(TestBase):
         def counter_stderr(line):
             count[2] += 1
 
-        proc = subprocess.Popen([sys.executable, fixture_path('cat_file.py'), str(fixture_path('issue-301_stderr'))],
+        cmdline = [sys.executable, fixture_path('cat_file.py'), str(fixture_path('issue-301_stderr'))]
+        proc = subprocess.Popen(cmdline,
                                 stdin=None,
                                 stdout=subprocess.PIPE,
                                 stderr=subprocess.PIPE,
@@ -241,7 +243,7 @@ class TestGit(TestBase):
                                 creationflags=cmd.PROC_CREATIONFLAGS,
                                 )
 
-        handle_process_output(proc, counter_stdout, counter_stderr, lambda proc: proc.wait())
+        handle_process_output(proc, counter_stdout, counter_stderr, finalize_process)
 
         self.assertEqual(count[1], line_count)
         self.assertEqual(count[2], line_count)
diff --git a/git/test/test_index.py b/git/test/test_index.py
index c78890ae..08d6491d 100644
--- a/git/test/test_index.py
+++ b/git/test/test_index.py
@@ -730,7 +730,7 @@ class TestIndex(TestBase):
                 index.commit("This should fail")
             except HookExecutionError as err:
                 if is_win:
-                    self.assertIsInstance(err.status, WindowsError)
+                    self.assertIsInstance(err.status, OSError)
                     self.assertEqual(err.command, hp)
                     self.assertIsNone(err.stdout)
                     self.assertIsNone(err.stderr)
diff --git a/git/test/test_util.py b/git/test/test_util.py
index 9fc159df..eae9fbc7 100644
--- a/git/test/test_util.py
+++ b/git/test/test_util.py
@@ -90,10 +90,9 @@ class TestUtils(TestBase):
         wait_lock = BlockingLockFile(my_file, 0.05, wait_time)
         self.failUnlessRaises(IOError, wait_lock._obtain_lock)
         elapsed = time.time() - start
-        # More extra time costs, but...
         extra_time = 0.2
         if is_win:
-            extra_time *= 4
+            extra_time *= 6  # NOTE: Indeterministic failures here...
         self.assertLess(elapsed, wait_time + 0.02)
 
     def test_user_id(self):