Merge ~ltrager/maas:emulate_terminal into maas:master

[Lee Trager]

Enumate a terminal when logging script output

Some applications don't properly detect that they are not being run in a
terminal and refresh output for progress bars, counters, and spinners. These
characters quickly add up making the log difficult to read. When writing output
from an application emulate a terminal so readable data is captured.

Fixes: LP: #1705792

[Newell Jensen (newell-jensen)]

How does this fix progress bars or spinners? Some progress bars are dots with a percentage as show in the bug, but some might use # signs etc. Additionally, spinners, when spinning will show hyphens '-' while the spinner is spinning between backslash-hyphen-forwardslash and so forth. Is this branch to fix all those possibilities or are we just doing it for the carriage return and backslash like you have in your code?

review: Needs Information

[Lee Trager (ltrager)]

The carriage return and back slash are how you change the output on the screen. [1] is a spinner. It writes the character, sleeps, then moves the position back one space and writes over it. \b would be used to update a counter or any other character as well. MAAS now looks for the backspace and carriage return characters and seeks back as a terminal does. So previously if you ran [1] as a test script in MAAS you would get a file containing 'Processing... ' and '|/-\\' 10 times repeated, now you just get 'Processing... '

http://paste.ubuntu.com/25143239/

[Newell Jensen (newell-jensen)]

Thanks for the clarification!

review: Approve

[MAAS Lander (maas-lander)]

LANDING
-b emulate_terminal lp:~ltrager/maas into -b master lp:~maas-committers/maas

STATUS: FAILED BUILD
LOG: http://maas-ci-jenkins.internal:8080/job/maas/job/branch-tester/133/console

[MAAS Lander (maas-lander)]

LANDING
-b emulate_terminal lp:~ltrager/maas into -b master lp:~maas-committers/maas

STATUS: FAILED BUILD
LOG: http://maas-ci-jenkins.internal:8080/job/maas/job/branch-tester/135/console

[Mike Pontillo (mpontillo)]

This is interesting.

I should hope that MAAS (and related utilities that generate logging in MAAS, such as curtin, or any test scripts) would run most commands with proper arguments for non-interactive usage, so that we can avoid this issue.

But this seems like a nice workaround for cases where that isn't true, and seems to be simple enough that it won't break our usual non-interactive logs.

One nit: I might have liked to see more comprehensive testing of edge cases, such as seeking to the beginning of a line in a case where you aren't seeking to the start of the file.

diff --git a/src/provisioningserver/refresh/maas_api_helper.py b/src/provisioningserver/refresh/maas_api_helper.py
index ca2271a..d4dd138 100644
--- a/src/provisioningserver/refresh/maas_api_helper.py
+++ b/src/provisioningserver/refresh/maas_api_helper.py
@@ -17,6 +17,7 @@ from datetime import (
 from email.utils import parsedate
 import json
 import mimetypes
+import os
 import random
 import selectors
 import socket
@@ -296,8 +297,12 @@ def capture_script_output(
         # Pad the timeout by 60 seconds to allow for cleanup.
         timeout = datetime.now() + timedelta(seconds=(timeout_seconds + 60))
 
-    with open(stdout_path, 'wb') as out, open(stderr_path, 'wb') as err:
-        with open(combined_path, 'wb') as combined:
+    # Create the file and then open it in read write mode for terminal
+    # emulation.
+    for path in (stdout_path, stderr_path, combined_path):
+        open(path, 'w').close()
+    with open(stdout_path, 'r+b') as out, open(stderr_path, 'r+b') as err:
+        with open(combined_path, 'r+b') as combined:
             with selectors.DefaultSelector() as selector:
                 selector.register(proc.stdout, selectors.EVENT_READ, out)
                 selector.register(proc.stderr, selectors.EVENT_READ, err)
@@ -342,5 +347,37 @@ def _select_script_output(selector, combined, timeout):
             if len(chunk) == 0:  # EOF
                 selector.unregister(key.fileobj)
             else:
-                key.data.write(chunk)
-                combined.write(chunk)
+                # The list comprehension is needed to get byte objects instead
+                # of their numeric value.
+                for i in [chunk[i:i + 1] for i in range(len(chunk))]:
+                    for f in [key.data, combined]:
+                        # Some applications don't properly detect that they are
+                        # not being run in a terminal and refresh output for
+                        # progress bars, counters, and spinners. These
+                        # characters quickly add up making the log difficult to
+                        # read. When writing output from an application emulate
+                        # a terminal so readable data is captured.
+                        if i == b'\b':
+                            # Backspace - Go back one space, if we can.
+                            if f.tell() != 0:
+                                f.seek(-1, os.SEEK_CUR)
+                        elif i == b'\r':
+                            # Carriage return - Seek to the beginning of the
+                            # line, as indicated by a line feed, or file.
+                            while f.tell() != 0:
+                                f.seek(-1, os.SEEK_CUR)
+                                if f.read(1) == b'\n':
+                                    # Check if line feed was found.
+                                    break
+                                else:
+                                    # The read advances the file position by
+                                    # one so seek back again.
+                                    f.seek(-1, os.SEEK_CUR)
+                        elif i == b'\n':
+                            # Line feed - Some applications do a carriage
+                            # return and then a line feed. The data on the line
+                            # should be saved, not overwritten.
+                            f.seek(0, os.SEEK_END)
+                            f.write(i)
+                        else:
+                            f.write(i)
diff --git a/src/provisioningserver/refresh/tests/test_maas_api_helper.py b/src/provisioningserver/refresh/tests/test_maas_api_helper.py
index be50262..3bf9b83 100644
--- a/src/provisioningserver/refresh/tests/test_maas_api_helper.py
+++ b/src/provisioningserver/refresh/tests/test_maas_api_helper.py
@@ -596,6 +596,24 @@ class TestCaptureScriptOutput(MAASTestCase):
         # This is a complete XML document; we've captured all output.
         self.assertThat(etree.fromstring(stdout).tag, Equals("list"))
 
+    def test__interprets_backslash(self):
+        proc = Popen(
+            'bash -c "echo -en \bmas\bas"',
+            stdout=PIPE, stderr=PIPE, shell=True)
+        self.assertThat(
+            self.capture(proc), MatchesListwise((
+                Equals(0), Equals("maas"), Equals(""), Equals("maas")
+            )))
+
+    def test__interprets_carriage_return(self):
+        proc = Popen(
+            'bash -c "echo -en foo\rmaas"',
+            stdout=PIPE, stderr=PIPE, shell=True)
+        self.assertThat(
+            self.capture(proc), MatchesListwise((
+                Equals(0), Equals("maas"), Equals(""), Equals("maas")
+            )))
+
     def test__timeout(self):
         # The timeout is padded by 60 seconds, override it so the test can
         # run quickly.