Redirect stdout/stderr through the logging system.
authorDavid Anderson <david.jc.anderson@gmail.com>
Fri, 13 Mar 2009 23:12:43 +0000
changeset 1846 ac30e04bcbba
parent 1845 2651cb3979db
child 1847 15ad1ee02dc5
Redirect stdout/stderr through the logging system. This change also causes the uncaptured output of subprocesses to be routed to the logging system for recording in the session transcript.
scripts/release/log.py
scripts/release/release.py
scripts/release/util.py
--- a/scripts/release/log.py	Fri Mar 13 23:12:40 2009 +0000
+++ b/scripts/release/log.py	Fri Mar 13 23:12:43 2009 +0000
@@ -26,10 +26,31 @@
     ]
 
 import logging
+import sys
 
 import util
 
 
+# A logging level that is even lower than DEBUG. We use this level to
+# log to file only, when we need to replay something output by
+# bypassing the logging system.
+_TERMINAL_ECHO = 5
+
+
+# Pull in the functions from the logging module, for ease of use
+debug = logging.debug
+info = logging.info
+error = logging.error
+raw = debug  # Used for logging raw output like subprocess stdout data.
+
+
+# Save the actual out/err streams before init() replaces them. Users
+# of the logging system can use these files if they need to bypass the
+# logging system for some reason.
+stdout = sys.stdout
+stderr = sys.stderr
+
+
 class _ColorizingFormatter(logging.Formatter):
   """A logging formatter that colorizes based on log levels."""
 
@@ -51,6 +72,35 @@
     return util.decolorize(logging.Formatter.format(self, record))
 
 
+class FileLikeLogger(object):
+  """A file-like object that logs anything written to it."""
+
+  def __init__(self):
+    self._buffer = []
+
+  def _getBuffer(self):
+    data, self._buffer = ''.join(self._buffer), []
+    return data
+
+  def close(self):
+    self.flush()
+
+  def flush(self):
+    raw(self._getBuffer())
+
+  def write(self, str):
+    lines = str.split('\n')
+    self.writelines(lines[0:-1])
+    self._buffer.append(lines[-1])
+
+  def writelines(self, lines):
+    if not lines:
+      return
+    lines[0] = self._getBuffer() + lines[0]
+    for line in lines:
+      raw(line)
+
+
 def init(logfile=None):
   """Initialize the logging subsystem.
 
@@ -59,7 +109,7 @@
   """
 
   root = logging.getLogger('')
-  root.setLevel(logging.DEBUG)
+  root.setLevel(_TERMINAL_ECHO)
 
   console = logging.StreamHandler()
   console.setLevel(logging.DEBUG)
@@ -68,11 +118,27 @@
 
   if logfile:
     transcript = logging.FileHandler(logfile, 'w')
-    transcript.setLevel(logging.DEBUG)
+    transcript.setLevel(_TERMINAL_ECHO)
     transcript.setFormatter(_DecolorizingFormatter())
     root.addHandler(transcript)
 
+  # Redirect sys.stdout and sys.stderr to logging streams. This will
+  # force everything that is output in this process, even through
+  # 'print', to go to both the console and the transcript (if active).
+  sys.stdout = FileLikeLogger()
+  sys.stderr = FileLikeLogger()
 
-debug = logging.debug
-info = logging.info
-error = logging.error
+
+def terminal_echo(text, *args, **kwargs):
+  """Echo a message written manually to the terminal.
+
+  This function should be used when you want to echo into the logging
+  system something that you manually wrote to the real
+  stdout/stderr.
+
+  For example, when asking the user for input, you would output the
+  raw prompt to the terminal manually, read the user's response, and
+  then echo both the prompt and the answer back into the logging
+  system for recording.
+  """
+  logging.log(_TERMINAL_ECHO, text, *args, **kwargs)
--- a/scripts/release/release.py	Fri Mar 13 23:12:40 2009 +0000
+++ b/scripts/release/release.py	Fri Mar 13 23:12:43 2009 +0000
@@ -46,6 +46,7 @@
 import re
 import subprocess
 import sys
+import threading
 
 import error
 import log
@@ -83,6 +84,20 @@
   """An error occured while accessing a file."""
 
 
+def getString(prompt):
+  """Prompt for and return a string."""
+  prompt += ' '
+  log.stdout.write(prompt)
+  log.stdout.flush()
+
+  response = sys.stdin.readline()
+  log.terminal_echo(prompt + response.strip())
+  if not response:
+    raise AbortedByUser('Aborted by ctrl+D')
+
+  return response.strip()
+
+
 def confirm(prompt, default=False):
   """Ask a yes/no question and return the answer.
 
@@ -97,14 +112,11 @@
     True if the user answered affirmatively, False otherwise.
   """
   if default:
-    question = prompt + ' [Yn] '
+    question = prompt + ' [Yn]'
   else:
-    question = prompt + ' [yN] '
+    question = prompt + ' [yN]'
   while True:
-    try:
-      answer = raw_input(question).strip().lower()
-    except EOFError:
-      raise AbortedByUser('Aborted by ctrl+D')
+    answer = getString(question)
     if not answer:
       return default
     elif answer in ('y', 'yes'):
@@ -115,14 +127,6 @@
       log.error('Please answer yes or no.')
 
 
-def getString(prompt):
-  """Prompt for and return a string."""
-  try:
-    return raw_input(prompt + ' ').strip()
-  except EOFError:
-    raise AbortedByUser('Aborted by ctrl+D')
-
-
 def getNumber(prompt):
   """Prompt for and return a number.
 
--- a/scripts/release/util.py	Fri Mar 13 23:12:40 2009 +0000
+++ b/scripts/release/util.py	Fri Mar 13 23:12:43 2009 +0000
@@ -27,9 +27,15 @@
 
 import os.path
 import re
+try:
+  import cStringIO as StringIO
+except ImportError:
+  import StringIO
 import subprocess
+import threading
 
 import error
+import log
 
 
 class Error(error.Error):
@@ -129,7 +135,26 @@
     return os.path.exists(self.path(path))
 
 
-def run(argv, cwd=None, capture=False, split_capture=True, stdin=''):
+class _PipeAdapter(threading.Thread):
+  """A thread that connects one file-like object to another"""
+  def __init__(self, pipe, logfile):
+    threading.Thread.__init__(self)
+    self.pipe, self.logfile = pipe, logfile
+    self.setDaemon(True)
+    self.start()
+
+  def run(self):
+    try:
+      while True:
+        data = self.pipe.read(512)  # Small to retain interactivity
+        if not data:
+          return
+        self.logfile.write(data)
+    except (EOFError, OSError):
+      pass
+
+
+def run(argv, cwd=None, capture=False, split_capture=True, stdin=None):
   """Run the given command and optionally return its output.
 
   Note that if you set capture=True, the command's output is
@@ -156,19 +181,46 @@
     SubprocessFailed: The subprocess exited with a non-zero exit
             code.
   """
-  print colorize('# ' + ' '.join(argv), WHITE, bold=True)
+  log.debug(colorize('# ' + ' '.join(argv), WHITE, bold=True))
 
   process = subprocess.Popen(argv,
                              shell=False,
                              cwd=cwd,
-                             stdin=subprocess.PIPE,
-                             stdout=(subprocess.PIPE if capture else None),
-                             stderr=None)
-  output, _ = process.communicate(input=stdin)
+                             stdin=(subprocess.PIPE if stdin else None),
+                             stdout=subprocess.PIPE,
+                             stderr=subprocess.PIPE)
+
+  # Spin up threads to capture stdout and stderr. Depending on the
+  # value of the capture parameter, stdout is pushed either into the
+  # log or into a string for processing. stderr always goes
+  # into the log.
+  #
+  # Threads are necessary because all of writing to stdin, reading
+  # from stdout and reading from stderr must all happen
+  # simultaneously. Otherwise, there is a risk that one of the pipes
+  # will fill up, causing the subprocess and us to deadlock. So,
+  # threads are used to keep the pipes safely flowing.
+  stdout = StringIO.StringIO() if capture else log.FileLikeLogger()
+  out_adapter = _PipeAdapter(process.stdout, stdout)
+  err_adapter = _PipeAdapter(process.stderr, log.FileLikeLogger())
+  if stdin:
+    process.stdin.write(stdin)
+
+  out_adapter.join()
+  err_adapter.join()
+  process.wait()
+
   if process.returncode != 0:
-    raise SubprocessFailed('Process %s failed with output: %s' %
-                           (argv[0], output))
-  if output is not None and split_capture:
-    return output.strip().split('\n')
-  else:
-    return output
+    if capture:
+      raise SubprocessFailed('Process %s failed with output: %s' %
+                             (argv[0], stdout.getvalue()))
+    else:
+      raise SubprocessFailed('Process %s failed' % argv[0])
+
+  if capture:
+    out = stdout.getvalue()
+    stdout.close()
+
+    if split_capture:
+      out = out.strip().split('\n')
+    return out