misc: sh displays sdterr/stdout continuously

Instead of blocking until the command completes, which makes for a
better user experience when the command takes more than a second to complete.

Signed-off-by: Loic Dachary <loic@dachary.org>

diff --git a/teuthology/misc.py b/teuthology/misc.py
index 3355814d293e2b740b3d402698319e4c8d6ae05a..24132b17874e07d9b84d2b8ba5ed9ed9d391ed07 100644 (file)
--- a/teuthology/misc.py
+++ b/teuthology/misc.py
@@ -1288,27 +1288,36 @@ def sh(command, log_limit=1024):
     stdout).  If the command fails, raise an exception. The command
     and its output are logged, on success and on error.
     """
-    log.debug(command)
-    output = ''
+    log.debug(":sh: " + command)
     proc = subprocess.Popen(
         args=command,
         stdout=subprocess.PIPE,
         stderr=subprocess.STDOUT,
-        shell=True)
-    output = proc.communicate()[0]
-    if proc.returncode == 0:
-        if output.strip():
-            if len(output) > log_limit:
-                log.debug(command + " output " + str(output)[:log_limit] +
+        shell=True,
+        bufsize=1)
+    lines = []
+    truncated = False
+    with proc.stdout:
+        for line in iter(proc.stdout.readline, b''):
+            lines.append(line)
+            line = line.strip()
+            if len(line) > log_limit:
+                truncated = True
+                log.debug(str(line)[:log_limit] +
                           "... (truncated to the first " + str(log_limit) +
                           " characters)")
             else:
-                log.debug(command + " output " + str(output))
-    else:
-        log.debug(command + " failed with " + str(output))
+                log.debug(str(line))
+    output = "".join(lines)
+    if proc.wait() != 0:
+        if truncated:
+            log.error(command + " replay full stdout/stderr"
+                      " because an error occurred and some of"
+                      " it was truncated")
+            log.error(output)
         raise subprocess.CalledProcessError(
             returncode=proc.returncode,
             cmd=command,
-            output=output,
+            output=output
         )
     return output.decode('utf-8')

diff --git a/teuthology/test/test_misc.py b/teuthology/test/test_misc.py
index 0dbb094364e7d4ed49c0de7419dde23b42ba14a2..bd070e31acd3a5d1346f0da9bae2ddf8d832354f 100644 (file)
--- a/teuthology/test/test_misc.py
+++ b/teuthology/test/test_misc.py
@@ -1,9 +1,11 @@
 import argparse
+from datetime import datetime
 
 from mock import patch
 from ..orchestra import cluster
 from .. import misc
 from ..config import config
+import subprocess
 
 import pytest
 
@@ -24,11 +26,28 @@ def test_sh_truncate(caplog):
 
 
 def test_sh_fail(caplog):
-    with pytest.raises(Exception) as excinfo:
+    with pytest.raises(subprocess.CalledProcessError) as excinfo:
         misc.sh("/bin/echo -n AB ; /bin/echo C ; exit 111", 2) == "ABC\n"
     assert excinfo.value.returncode == 111
-    assert "failed with ABC" in caplog.text()
-
+    for record in caplog.records():
+        if record.levelname == 'ERROR':
+            assert ('replay full' in record.message or
+                    'ABC\n' == record.message)
+
+def test_sh_progress(caplog):
+    misc.sh("echo AB ; sleep 5 ; /bin/echo C", 2) == "ABC\n"
+    records = caplog.records()
+    assert ':sh: ' in records[0].message
+    assert 'AB' == records[1].message
+    assert 'C' == records[2].message
+    #
+    # With a sleep 5 between the first and the second message,
+    # there must be at least 2 seconds between the log record
+    # of the first message and the log record of the second one
+    #
+    t1 = datetime.strptime(records[1].asctime.split(',')[0], "%Y-%m-%d %H:%M:%S")
+    t2 = datetime.strptime(records[2].asctime.split(',')[0], "%Y-%m-%d %H:%M:%S")
+    assert (t2 - t1).total_seconds() > 2
 
 def test_wait_until_osds_up():
     ctx = argparse.Namespace()