From 9c2c3df0abdd0545c746a996a8e4f42a5e0fa0f4 Mon Sep 17 00:00:00 2001
From: Christian Heimes <cheimes@redhat.com>
Date: Fri, 16 Feb 2018 12:14:11 +0100
Subject: [PATCH] Add better CalledProcessError and run() logging

In case of an error, ipapython.ipautil.run() now raises an exception that
contains the error message of the failed command. Before the exception
only contained the command and error code.

The command is no longer collapsed into one string. The error message
and logging output contains the actual command and arguments with intact
quoting.

Example:
CalledProcessError(Command ['/usr/bin/python3', '-c', 'import sys; sys.exit(" ".join(("error", "XXXXXXXX")))'] returned non-zero exit status 1: 'error XXXXXXXX\n')

Signed-off-by: Christian Heimes <cheimes@redhat.com>
Reviewed-By: Tibor Dudlak <tdudlak@redhat.com>
---
 ipapython/ipautil.py                    | 42 ++++++++++++++++---------
 ipatests/test_ipapython/test_ipautil.py | 28 ++++++++++++++++-
 2 files changed, 54 insertions(+), 16 deletions(-)

diff --git a/ipapython/ipautil.py b/ipapython/ipautil.py
index be89cdc56..354361f6c 100644
--- a/ipapython/ipautil.py
+++ b/ipapython/ipautil.py
@@ -41,7 +41,6 @@ import grp
 from contextlib import contextmanager
 import locale
 import collections
-from subprocess import CalledProcessError
 
 from dns import resolver, reversename
 from dns.exception import DNSException
@@ -353,23 +352,34 @@ def shell_quote(string):
         return b"'" + string.replace(b"'", b"'\\''") + b"'"
 
 
-if six.PY3:
-    def _log_arg(s):
-        """Convert string or bytes to a string suitable for logging"""
-        if isinstance(s, bytes):
-            return s.decode(locale.getpreferredencoding(),
-                            errors='replace')
-        else:
-            return s
-else:
-    _log_arg = str
-
-
 class _RunResult(collections.namedtuple('_RunResult',
                                         'output error_output returncode')):
     """Result of ipautil.run"""
 
 
+class CalledProcessError(subprocess.CalledProcessError):
+    """CalledProcessError with stderr
+
+    Hold stderr of failed call and print it in repr() to simplify debugging.
+    """
+    def __init__(self, returncode, cmd, output=None, stderr=None):
+        super(CalledProcessError, self).__init__(returncode, cmd, output)
+        self.stderr = stderr
+
+    def __str__(self):
+        args = [
+            self.__class__.__name__, '('
+            'Command {!s} '.format(self.cmd),
+            'returned non-zero exit status {!r}'.format(self.returncode)
+        ]
+        if self.stderr is not None:
+            args.append(': {!r}'.format(self.stderr))
+        args.append(')')
+        return ''.join(args)
+
+    __repr__ = __str__
+
+
 def run(args, stdin=None, raiseonerr=True, nolog=(), env=None,
         capture_output=False, skip_output=False, cwd=None,
         runas=None, suplementary_groups=[],
@@ -477,7 +487,7 @@ def run(args, stdin=None, raiseonerr=True, nolog=(), env=None,
     if six.PY3 and isinstance(stdin, str):
         stdin = stdin.encode(encoding)
 
-    arg_string = nolog_replace(' '.join(_log_arg(a) for a in args), nolog)
+    arg_string = nolog_replace(repr(args), nolog)
     logger.debug('Starting external process')
     logger.debug('args=%s', arg_string)
 
@@ -558,7 +568,9 @@ def run(args, stdin=None, raiseonerr=True, nolog=(), env=None,
         error_output = None
 
     if p.returncode != 0 and raiseonerr:
-        raise CalledProcessError(p.returncode, arg_string, str(output))
+        raise CalledProcessError(
+            p.returncode, arg_string, output_log, error_log
+        )
 
     result = _RunResult(output, error_output, p.returncode)
     result.raw_output = stdout
diff --git a/ipatests/test_ipapython/test_ipautil.py b/ipatests/test_ipapython/test_ipautil.py
index 73849714d..ef70f20fe 100644
--- a/ipatests/test_ipapython/test_ipautil.py
+++ b/ipatests/test_ipapython/test_ipautil.py
@@ -21,10 +21,11 @@
 """
 Test the `ipapython/ipautil.py` module.
 """
+import sys
+import tempfile
 
 import pytest
 import six
-import tempfile
 
 from ipaplatform.paths import paths
 from ipapython import ipautil
@@ -482,3 +483,28 @@ def test_flush_sync():
     with tempfile.NamedTemporaryFile('wb+') as f:
         f.write(b'data')
         ipautil.flush_sync(f)
+
+
+def test_run_stderr():
+    args = [
+        sys.executable, '-c',
+        'import sys; sys.exit(" ".join(("error", "message")))'
+    ]
+
+    with pytest.raises(ipautil.CalledProcessError) as cm:
+        ipautil.run(args)
+
+    assert cm.value.cmd == repr(args)
+    assert cm.value.stderr == "error message\n"
+    assert "CalledProcessError(" in str(cm.value)
+    assert repr(args) in str(cm.value)
+    assert str(cm.value).endswith("'error message\\n')")
+
+    with pytest.raises(ipautil.CalledProcessError) as cm:
+        ipautil.run(args, nolog=["message"])
+
+    assert cm.value.cmd == repr(args).replace("message", "XXXXXXXX")
+    assert str(cm.value).endswith("'error XXXXXXXX\\n')")
+    assert "message" not in str(cm.value)
+    assert "message" not in str(cm.value.output)
+    assert "message" not in str(cm.value.stderr)