frozen_chromite/lib/operation.py

# -*- coding: utf-8 -*-
# Copyright (c) 2011 The Chromium OS Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.

"""Operation, including output and progress display

This module implements the concept of an operation, which has regular progress
updates, verbose text display and perhaps some errors.
"""

from __future__ import division
from __future__ import print_function

import collections
import contextlib
import fcntl
import multiprocessing
import os
import pty
import re
import struct
import sys
import termios

from six.moves import queue as Queue

from autotest_lib.utils.frozen_chromite.lib import cros_logging as logging
from autotest_lib.utils.frozen_chromite.lib import osutils
from autotest_lib.utils.frozen_chromite.lib import parallel
from autotest_lib.utils.frozen_chromite.lib.terminal import Color
from autotest_lib.utils.frozen_chromite.utils import outcap


# Define filenames for captured stdout and stderr.
STDOUT_FILE = 'stdout'
STDERR_FILE = 'stderr'

_TerminalSize = collections.namedtuple('_TerminalSize', ('lines', 'columns'))


class _BackgroundTaskComplete(object):
  """Sentinal object to indicate that the background task is complete."""


class ProgressBarOperation(object):
  """Wrapper around long running functions to show progress.

  This class is intended to capture the output of a long running fuction, parse
  the output, and display a progress bar.

  To display a progress bar for a function foo with argument foo_args, this is
  the usage case:
    1) Create a class that inherits from ProgressBarOperation (e.g.
    FooTypeOperation. In this class, override the ParseOutput method to parse
    the output of foo.
    2) op = operation.FooTypeOperation()
       op.Run(foo, foo_args)
  """

  # Subtract 10 characters from the width of the terminal because these are used
  # to display the percentage as well as other spaces.
  _PROGRESS_BAR_BORDER_SIZE = 10

  # By default, update the progress bar every 100 ms.
  _PROGRESS_BAR_UPDATE_INTERVAL = 0.1

  def __init__(self):
    self._queue = multiprocessing.Queue()
    self._stderr = None
    self._stdout = None
    self._stdout_path = None
    self._stderr_path = None
    self._progress_bar_displayed = False
    self._isatty = os.isatty(sys.stdout.fileno())

  def _GetTerminalSize(self, fd=pty.STDOUT_FILENO):
    """Return a terminal size object for |fd|.

    Note: Replace with os.terminal_size() in python3.3.
    """
    winsize = struct.pack('HHHH', 0, 0, 0, 0)
    data = fcntl.ioctl(fd, termios.TIOCGWINSZ, winsize)
    winsize = struct.unpack('HHHH', data)
    return _TerminalSize(int(winsize[0]), int(winsize[1]))

  def ProgressBar(self, progress):
    """This method creates and displays a progress bar.

    If not in a terminal, we do not display a progress bar.

    Args:
      progress: a float between 0 and 1 that represents the fraction of the
        current progress.
    """
    if not self._isatty:
      return
    self._progress_bar_displayed = True
    progress = max(0.0, min(1.0, progress))
    width = max(1, self._GetTerminalSize().columns -
                self._PROGRESS_BAR_BORDER_SIZE)
    block = int(width * progress)
    shaded = '#' * block
    unshaded = '-' * (width - block)
    text = '\r [%s%s] %d%%' % (shaded, unshaded, progress * 100)
    sys.stdout.write(text)
    sys.stdout.flush()

  def OpenStdoutStderr(self):
    """Open the stdout and stderr streams."""
    if self._stdout is None and self._stderr is None:
      self._stdout = open(self._stdout_path, 'r')
      self._stderr = open(self._stderr_path, 'r')

  def Cleanup(self):
    """Method to cleanup progress bar.

    If progress bar has been printed, then we make sure it displays 100% before
    exiting.
    """
    if self._progress_bar_displayed:
      self.ProgressBar(1)
      sys.stdout.write('\n')
      sys.stdout.flush()

  def ParseOutput(self, output=None):
    """Method to parse output and update progress bar.

    This method should be overridden to read and parse the lines in _stdout and
    _stderr.

    One example use of this method could be to detect 'foo' in stdout and
    increment the progress bar every time foo is seen.

    def ParseOutput(self):
      stdout = self._stdout.read()
      if 'foo' in stdout:
        # Increment progress bar.

    Args:
      output: Pass in output to parse instead of reading from self._stdout and
        self._stderr.
    """
    raise NotImplementedError('Subclass must override this method.')

  # TODO(ralphnathan): Deprecate this function and use parallel._BackgroundTask
  # instead (brbug.com/863)
  def WaitUntilComplete(self, update_period):
    """Return True if running background task has completed."""
    try:
      x = self._queue.get(timeout=update_period)
      if isinstance(x, _BackgroundTaskComplete):
        return True
    except Queue.Empty:
      return False

  def CaptureOutputInBackground(self, func, *args, **kwargs):
    """Launch func in background and capture its output.

    Args:
      func: Function to execute in the background and whose output is to be
        captured.
      log_level: Logging level to run the func at. By default, it runs at log
        level info.
    """
    log_level = kwargs.pop('log_level', logging.INFO)
    restore_log_level = logging.getLogger().getEffectiveLevel()
    logging.getLogger().setLevel(log_level)
    try:
      with outcap.OutputCapturer(
          stdout_path=self._stdout_path, stderr_path=self._stderr_path,
          quiet_fail=False):
        func(*args, **kwargs)
    finally:
      self._queue.put(_BackgroundTaskComplete())
      logging.getLogger().setLevel(restore_log_level)

  # TODO (ralphnathan): Store PID of spawned process.
  def Run(self, func, *args, **kwargs):
    """Run func, parse its output, and update the progress bar.

    Args:
      func: Function to execute in the background and whose output is to be
        captured.
      update_period: Optional argument to specify the period that output should
        be read.
      log_level: Logging level to run the func at. By default, it runs at log
        level info.
    """
    update_period = kwargs.pop('update_period',
                               self._PROGRESS_BAR_UPDATE_INTERVAL)

    # If we are not running in a terminal device, do not display the progress
    # bar.
    if not self._isatty:
      log_level = kwargs.pop('log_level', logging.INFO)
      restore_log_level = logging.getLogger().getEffectiveLevel()
      logging.getLogger().setLevel(log_level)
      try:
        func(*args, **kwargs)
      finally:
        logging.getLogger().setLevel(restore_log_level)
      return

    with osutils.TempDir() as tempdir:
      self._stdout_path = os.path.join(tempdir, STDOUT_FILE)
      self._stderr_path = os.path.join(tempdir, STDERR_FILE)
      osutils.Touch(self._stdout_path)
      osutils.Touch(self._stderr_path)
      try:
        with parallel.BackgroundTaskRunner(
            self.CaptureOutputInBackground, func, *args, **kwargs) as queue:
          queue.put([])
          self.OpenStdoutStderr()
          while True:
            self.ParseOutput()
            if self.WaitUntilComplete(update_period):
              break
        # Before we exit, parse the output again to update progress bar.
        self.ParseOutput()
        # Final sanity check to update the progress bar to 100% if it was used
        # by ParseOutput
        self.Cleanup()
      except:
        # Add a blank line before the logging message so the message isn't
        # touching the progress bar.
        sys.stdout.write('\n')
        logging.error('Oops. Something went wrong.')
        # Raise the exception so it can be caught again.
        raise


class ParallelEmergeOperation(ProgressBarOperation):
  """ProgressBarOperation specific for scripts/parallel_emerge.py."""

  def __init__(self):
    super(ParallelEmergeOperation, self).__init__()
    self._total = None
    self._completed = 0
    self._printed_no_packages = False
    self._events = ['Fetched ', 'Completed ']
    self._msg = None

  def _GetTotal(self, output):
    """Get total packages by looking for Total: digits packages."""
    match = re.search(r'Total: (\d+) packages', output)
    return int(match.group(1)) if match else None

  def SetProgressBarMessage(self, msg):
    """Message to be shown before the progress bar is displayed with 0%.

       The message is not displayed if the progress bar is not going to be
       displayed.
    """
    self._msg = msg

  def ParseOutput(self, output=None):
    """Parse the output of emerge to determine how to update progress bar.

    1) Figure out how many packages exist. If the total number of packages to be
    built is zero, then we do not display the progress bar.
    2) Whenever a package is downloaded or built, 'Fetched' and 'Completed' are
    printed respectively. By counting counting 'Fetched's and 'Completed's, we
    can determine how much to update the progress bar by.

    Args:
      output: Pass in output to parse instead of reading from self._stdout and
        self._stderr.

    Returns:
      A fraction between 0 and 1 indicating the level of the progress bar. If
      the progress bar isn't displayed, then the return value is -1.
    """
    if output is None:
      stdout = self._stdout.read()
      stderr = self._stderr.read()
      output = stdout + stderr

    if self._total is None:
      temp = self._GetTotal(output)
      if temp is not None:
        self._total = temp * len(self._events)
        if self._msg is not None:
          logging.notice(self._msg)

    for event in self._events:
      self._completed += output.count(event)

    if not self._printed_no_packages and self._total == 0:
      logging.notice('No packages to build.')
      self._printed_no_packages = True

    if self._total:
      progress = self._completed / self._total
      self.ProgressBar(progress)
      return progress
    else:
      return -1


# TODO(sjg): When !isatty(), keep stdout and stderr separate so they can be
# redirected separately
# TODO(sjg): Add proper docs to this fileno
# TODO(sjg): Handle stdin wait in quite mode, rather than silently stalling

class Operation(object):
  """Class which controls stdio and progress of an operation in progress.

  This class is created to handle stdio for a running subprocess. It filters
  it looking for errors and progress information. Optionally it can output the
  stderr and stdout to the terminal, but it is normally supressed.

  Progress information is garnered from the subprocess output based on
  knowledge of the legacy scripts, but at some point will move over to using
  real progress information reported through new python methods which will
  replace the scripts.

  Each operation has a name, and this class handles displaying this name
  as it reports progress.

  Operation Objects
  =================

  verbose: True / False
    In verbose mode all output from subprocesses is displayed, otherwise
    this output is normally supressed, unless we think it indicates an error.

  progress: True / False
    The output from subprocesses can be analysed in a very basic manner to
    try to present progress information to the user.

  explicit_verbose: True / False
    False if we are not just using default verbosity. In that case we allow
    verbosity to be enabled on request, since the user has not explicitly
    disabled it. This is used by commands that the user issues with the
    expectation that output would ordinarily be visible.
  """

  def __init__(self, name, color=None):
    """Create a new operation.

    Args:
      name: Operation name in a form to be displayed for the user.
      color: Determines policy for sending color to stdout; see terminal.Color
        for details on interpretation on the value.
    """
    self._name = name   # Operation name.
    self.verbose = False   # True to echo subprocess output.
    self.progress = True   # True to report progress of the operation
    self._column = 0    # Current output column (always 0 unless verbose).
    self._update_len = 0    # Length of last progress update message.
    self._line = ''   # text of current line, so far
    self.explicit_verbose = False

    self._color = Color(enabled=color)

    # -1 = no newline pending
    #  n = newline pending, and line length of last line was n
    self._pending_nl = -1

    # the type of the last stream to emit data on the current lines
    # can be sys.stdout, sys.stderr (both from the subprocess), or None
    # for our own mesages
    self._cur_stream = None

    self._error_count = 0   # number of error lines we have reported

  def __del__(self):
    """Object is about to be destroyed, so finish out output cleanly."""
    self.FinishOutput()

  def FinishOutput(self):
    """Finish off any pending output.

    This finishes any output line currently in progress and resets the color
    back to normal.
    """
    self._FinishLine(self.verbose, final=True)
    if self._column and self.verbose:
      print(self._color.Stop())
      self._column = 0

  def WereErrorsDetected(self):
    """Returns whether any errors have been detected.

    Returns:
      True if any errors have been detected in subprocess output so far.
      False otherwise
    """
    return self._error_count > 0

  def SetName(self, name):
    """Set the name of the operation as displayed to the user.

    Args:
      name: Operation name.
    """
    self._name = name

  def _FilterOutputForErrors(self, line, print_error):
    """Filter a line of output to look for and display errors.

    This uses a few regular expression searches to spot common error reports
    from subprocesses. A count of these is kept so we know how many occurred.
    Optionally they are displayed in red on the terminal.

    Args:
      line: the output line to filter, as a string.
      print_error: True to print the error, False to just record it.
    """
    bad_things = ['Cannot GET', 'ERROR', '!!!', 'FAILED']
    for bad_thing in bad_things:
      if re.search(bad_thing, line, flags=re.IGNORECASE):
        self._error_count += 1
        if print_error:
          print(self._color.Color(self._color.RED, line))
          break

  def _FilterOutputForProgress(self, line):
    """Filter a line of output to look for and dispay progress information.

    This uses a simple regular expression search to spot progress information
    coming from subprocesses. This is sent to the _Progress() method.

    Args:
      line: the output line to filter, as a string.
    """
    match = re.match(r'Pending (\d+).*Total (\d+)', line)
    if match:
      pending = int(match.group(1))
      total = int(match.group(2))
      self._Progress(total - pending, total)

  def _Progress(self, upto, total):
    """Record and optionally display progress information.

    Args:
      upto: which step we are up to in the operation (integer, from 0).
      total: total number of steps in operation,
    """
    if total > 0:
      update_str = '%s...%d%% (%d of %d)' % (self._name,
                                             upto * 100 // total, upto, total)
      if self.progress:
        # Finish the current line, print progress, and remember its length.
        self._FinishLine(self.verbose)

        # Sometimes the progress string shrinks and in this case we need to
        # blank out the characters at the end of the line that will not be
        # overwritten by the new line
        pad = max(self._update_len - len(update_str), 0)
        sys.stdout.write(update_str + (' ' * pad) + '\r')
        self._update_len = len(update_str)

  def _FinishLine(self, display, final=False):
    """Finish off the current line and prepare to start a new one.

    If a new line is pending from the previous line, then this will be output,
    along with a color reset if needed.

    We also handle removing progress messages from the output. This is done
    using a carriage return character, following by spaces.

    Args:
      display: True to display output, False to suppress it
      final: True if this is the final output before we exit, in which case
          we must clean up any remaining progress message by overwriting
          it with spaces, then carriage return
    """
    if display:
      if self._pending_nl != -1:
        # If out last output line was shorter than the progress info
        # add spaces.
        if self._pending_nl < self._update_len:
          print(' ' * (self._update_len - self._pending_nl), end='')

        # Output the newline, and reset our counter.
        sys.stdout.write(self._color.Stop())
        print()

    # If this is the last thing that this operation will print, we need to
    # close things off. So if there is some text on the current line but not
    # enough to overwrite all the progress information we have sent, add some
    # more spaces.
    if final and self._update_len:
      print(' ' * self._update_len, '\r', end='')

    self._pending_nl = -1

  def _CheckStreamAndColor(self, stream, display):
    """Check that we're writing to the same stream as last call.  No?  New line.

    If starting a new line, set the color correctly:
      stdout  Magenta
      stderr  Red
      other   White / no colors

    Args:
      stream: The stream we're going to write to.
      display: True to display it on terms, False to suppress it.
    """
    if self._column > 0 and stream != self._cur_stream:
      self._FinishLine(display)
      if display:
        print(self._color.Stop())

      self._column = 0
      self._line = ''

    # Use colors for child output.
    if self._column == 0:
      self._FinishLine(display)
      if display:
        color = None
        if stream == sys.stdout:
          color = self._color.MAGENTA
        elif stream == sys.stderr:
          color = self._color.RED
        if color:
          sys.stdout.write(self._color.Start(color))

      self._cur_stream = stream

  def _Out(self, stream, text, display, newline=False, do_output_filter=True):
    """Output some text received from a child, or generated internally.

    This method is the guts of the Operation class since it understands how to
    convert a series of output requests on different streams into something
    coherent for the user.

    If the stream has changed, then a new line is started even if we were
    still halfway through the previous line. This prevents stdout and stderr
    becoming mixed up quite so badly.

    We use color to indicate lines which are stdout and stderr. If the output
    received from the child has color codes in it already, we pass these
    through, so our colors can be overridden. If output is redirected then we
    do not add color by default. Note that nothing stops the child from adding
    it, but since we present ourselves as a terminal to the child, one might
    hope that the child will not generate color.

    If display is False, then we will not actually send this text to the
    terminal. This is uses when verbose is required to be False.

    Args:
      stream: stream on which the text was received:
        sys.stdout    - received on stdout
        sys.stderr    - received on stderr
        None          - generated by us / internally
      text: text to output
      display: True to display it on terms, False to suppress it
      newline: True to start a new line after this text, False to put the next
        lot of output immediately after this.
      do_output_filter: True to look through output for errors and progress.
    """
    self._CheckStreamAndColor(stream, display)

    # Output what we have, and remember what column we are up to.
    if display:
      sys.stdout.write(text)
      self._column += len(text)
      # If a newline is required, remember to output it later.
      if newline:
        self._pending_nl = self._column
        self._column = 0

    self._line += text

    # If we now have a whole line, check it for errors and progress.
    if newline:
      if do_output_filter:
        self._FilterOutputForErrors(self._line, print_error=not display)
        self._FilterOutputForProgress(self._line)
      self._line = ''

  def Output(self, stream, data):
    r"""Handle the output of a block of text from the subprocess.

    All subprocess output should be sent through this method. It is split into
    lines which are processed separately using the _Out() method.

    Args:
      stream: Which file the output come in on:
        sys.stdout: stdout
        sys.stderr: stderr
        None: Our own internal output
      data: Output data as a big string, potentially containing many lines of
        text. Each line should end with \r\n. There is no requirement to send
        whole lines - this method happily handles fragments and tries to
        present then to the user as early as possible

    #TODO(sjg): Just use a list as the input parameter to avoid the split.
    """
    # We cannot use splitlines() here as we need this exact behavior
    lines = data.split('\r\n')

    # Output each full line, with a \n after it.
    for line in lines[:-1]:
      self._Out(stream, line, display=self.verbose, newline=True)

    # If we have a partial line at the end, output what we have.
    # We will continue it later.
    if lines[-1]:
      self._Out(stream, lines[-1], display=self.verbose)

    # Flush so that the terminal will receive partial line output (now!)
    sys.stdout.flush()

  def Outline(self, line):
    r"""Output a line of text to the display.

    This outputs text generated internally, such as a warning message or error
    summary. It ensures that our message plays nicely with child output if
    any.

    Args:
      line: text to output (without \n on the end)
    """
    self._Out(None, line, display=True, newline=True)
    self._FinishLine(display=True)

  def Info(self, line):
    r"""Output a line of information text to the display in verbose mode.

    Args:
      line: text to output (without \n on the end)
    """
    self._Out(None, self._color.Color(self._color.BLUE, line),
              display=self.verbose, newline=True, do_output_filter=False)
    self._FinishLine(display=True)

  def Notice(self, line):
    r"""Output a line of notification text to the display.

    Args:
      line: text to output (without \n on the end)
    """
    self._Out(None, self._color.Color(self._color.GREEN, line),
              display=True, newline=True, do_output_filter=False)
    self._FinishLine(display=True)

  def Warning(self, line):
    r"""Output a line of warning text to the display.

    Args:
      line: text to output (without \n on the end)
    """
    self._Out(None, self._color.Color(self._color.YELLOW, line),
              display=True, newline=True, do_output_filter=False)
    self._FinishLine(display=True)

  def Error(self, line):
    r"""Output a line of error text to the display.

    Args:
      line: text to output (without \n on the end)
    """
    self._Out(None, self._color.Color(self._color.RED, line),
              display=True, newline=True, do_output_filter=False)
    self._FinishLine(display=True)

  def Die(self, line):
    r"""Output a line of error text to the display and die.

    Args:
      line: text to output (without \n on the end)
    """
    self.Error(line)
    sys.exit(1)

  @contextlib.contextmanager
  def RequestVerbose(self, request):
    """Perform something in verbose mode if the user hasn't disallowed it

    This is intended to be used with something like:

      with oper.RequestVerbose(True):
        ... do some things that generate output

    Args:
      request: True to request verbose mode if available, False to do nothing.
    """
    old_verbose = self.verbose
    if request and not self.explicit_verbose:
      self.verbose = True
    try:
      yield
    finally:
      self.verbose = old_verbose