reformat run-webkit-tests --driver-logging output to show ctrl chars.

Tools/Scripts/webkitpy/layout_tests/port/server_process.py

 # Copyright (C) 2010 Google Inc. All rights reserved.
 #
 # Redistribution and use in source and binary forms, with or without
 # modification, are permitted provided that the following conditions are
 # met:
 #
 #     * Redistributions of source code must retain the above copyright
 # notice, this list of conditions and the following disclaimer.
 #     * Redistributions in binary form must reproduce the above
 # copyright notice, this list of conditions and the following disclaimer
@@ skipping 12 matching lines @@
 # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
 # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
 # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 """Package that implements the ServerProcess wrapper class"""
 
 import errno
 import logging
+import re
 import signal
 import sys
 import time
 
 # Note that although win32 python does provide an implementation of
 # the win32 select API, it only works on sockets, and not on the named pipes
 # used by subprocess, so we have to use the native APIs directly.
 _quote_cmd = None
 
 if sys.platform == 'win32':
     import msvcrt
     import win32pipe
     import win32file
     import subprocess
     _quote_cmd = subprocess.list2cmdline
 else:
     import fcntl
     import os
     import pipes
     import select
     _quote_cmd = lambda cmdline: ' '.join(pipes.quote(arg) for arg in cmdline)
 
 from webkitpy.common.system.executive import ScriptError
 
 
 _log = logging.getLogger(__name__)
 
 
+_trailing_spaces_re = re.compile('(.*[^ ])?( +)$')
+
+
+def quote_data(data):
+    txt = repr(data).replace('\\n', '\\n\n')[1:-1]
+    lines = []
+    for l in txt.splitlines():
+        m = _trailing_spaces_re.match(l)
+        if m:
+            l = m.group(1) + m.group(2).replace(' ', '\x20')
+        lines.append(l)
+    return lines
+
 class ServerProcess(object):
     """This class provides a wrapper around a subprocess that
     implements a simple request/response usage model. The primary benefit
     is that reading responses takes a deadline, so that we don't ever block
     indefinitely. The class also handles transparently restarting processes
     as necessary to keep issuing commands."""
 
     def __init__(self, port_obj, name, cmd, env=None, universal_newlines=False, treat_no_data_as_crash=False,
                  logging=False):
         self._port = port_obj
@@ skipping 43 matching lines @@
     def _start(self):
         if self._proc:
             raise ValueError("%s already running" % self._name)
         self._reset()
         # close_fds is a workaround for http://bugs.python.org/issue2320
         close_fds = not self._host.platform.is_win()
         if self._logging:
             env_str = ''
             if self._env:
                 env_str += '\n'.join("%s=%s" % (k, v) for k, v in self._env.items()) + '\n'
-            _log.info('CMD: """\n%s%s\n"""', env_str, _quote_cmd(self._cmd))
+            _log.info('CMD: \n%s%s\n', env_str, _quote_cmd(self._cmd))
         self._proc = self._host.executive.popen(self._cmd, stdin=self._host.executive.PIPE,
             stdout=self._host.executive.PIPE,
             stderr=self._host.executive.PIPE,
             close_fds=close_fds,
             env=self._env,
             universal_newlines=self._universal_newlines)
         self._pid = self._proc.pid
         fd = self._proc.stdout.fileno()
         if not self._use_win32_apis:
             fl = fcntl.fcntl(fd, fcntl.F_GETFL)
@@ skipping 20 matching lines @@
         if self._proc:
             return self._proc.poll()
         return None
 
     def write(self, bytes):
         """Write a request to the subprocess. The subprocess is (re-)start()'ed
         if is not already running."""
         if not self._proc:
             self._start()
         try:
-            if self._logging:
-                _log.info(' IN: """%s"""', bytes)
+            self._log_data(' IN', bytes)
             self._proc.stdin.write(bytes)
         except IOError, e:
             self.stop(0.0)
             # stop() calls _reset(), so we have to set crashed to True after calling stop().
             self._crashed = True
 
     def _pop_stdout_line_if_ready(self):
         index_after_newline = self._output.find('\n') + 1
         if index_after_newline > 0:
             return self._pop_output_bytes(index_after_newline)
@@ skipping 40 matching lines @@
             return None
 
         return self._read(deadline, retrieve_bytes_from_stdout_buffer)
 
     def _log(self, message):
         # This is a bit of a hack, but we first log a blank line to avoid
         # messing up the master process's output.
         _log.info('')
         _log.info(message)
 
+    def _log_data(self, prefix, data):
+        if self._logging and data and len(data):
+            for line in quote_data(data):
+                _log.info('%s: %s', prefix, line)
+
     def _handle_timeout(self):
         self.timed_out = True
         self._port.sample_process(self._name, self._proc.pid)
 
     def _split_string_after_index(self, string, index):
         return string[:index], string[index:]
 
     def _pop_output_bytes(self, bytes_count):
         output, self._output = self._split_string_after_index(self._output, bytes_count)
         return output
@@ skipping 23 matching lines @@
         try:
             # Note that we may get no data during read() even though
             # select says we got something; see the select() man page
             # on linux. I don't know if this happens on Mac OS and
             # other Unixen as well, but we don't bother special-casing
             # Linux because it's relatively harmless either way.
             if out_fd in read_fds:
                 data = self._proc.stdout.read()
                 if not data and not stopping and (self._treat_no_data_as_crash or self._proc.poll()):
                     self._crashed = True
-                if self._logging and len(data):
-                    _log.info('OUT: """%s"""', data)
+                self._log_data('OUT', data)
                 self._output += data
 
             if err_fd in read_fds:
                 data = self._proc.stderr.read()
                 if not data and not stopping and (self._treat_no_data_as_crash or self._proc.poll()):
                     self._crashed = True
-                if self._logging and len(data):
-                    _log.info('ERR: """%s"""', data)
+                self._log_data('ERR', data)
                 self._error += data
         except IOError, e:
             # We can ignore the IOErrors because we will detect if the subporcess crashed
             # the next time through the loop in _read()
             pass
 
     def _wait_for_data_and_update_buffers_using_win32_apis(self, deadline):
         # See http://code.activestate.com/recipes/440554-module-to-allow-asynchronous-subprocess-use-on-win/
         # and http://docs.activestate.com/activepython/2.6/pywin32/modules.html
         # for documentation on all of these win32-specific modules.
         now = time.time()
         out_fh = msvcrt.get_osfhandle(self._proc.stdout.fileno())
         err_fh = msvcrt.get_osfhandle(self._proc.stderr.fileno())
         while (self._proc.poll() is None) and (now < deadline):
             output = self._non_blocking_read_win32(out_fh)
+            self._log_data('OUT', output)
             error = self._non_blocking_read_win32(err_fh)
+            self._log_data('ERR', error)
             if output or error:
                 if output:
                     self._output += output
                 if error:
                     self._error += error
                 return
             time.sleep(0.01)
             now = time.time()
         return
 
@@ skipping 39 matching lines @@
         if not self._proc:
             self._start()
 
     def stop(self, timeout_secs=3.0):
         if not self._proc:
             return (None, None)
 
         now = time.time()
         if self._proc.stdin:
             if self._logging:
-                _log.info(' IN: """^D"""')
+                _log.info(' IN: ^D')
             self._proc.stdin.close()
             self._proc.stdin = None
         killed = False
         if timeout_secs:
             deadline = now + timeout_secs
             while self._proc.poll() is None and time.time() < deadline:
                 time.sleep(0.01)
             if self._proc.poll() is None:
                 _log.warning('stopping %s(pid %d) timed out, killing it' % (self._name, self._proc.pid))
 
@@ skipping 21 matching lines @@
             self._proc.wait()
 
     def replace_outputs(self, stdout, stderr):
         assert self._proc
         if stdout:
             self._proc.stdout.close()
             self._proc.stdout = stdout
         if stderr:
             self._proc.stderr.close()
             self._proc.stderr = stderr