client/common_lib/logging_manager.py

"""
Autotest has some surprisingly complicated logging behaviour.

Managers allow you to define logging contexts, which define a set of rules on
how to handle stdout/stderr.  The niceness that you get by going through the
logging_manager for this is that you can push/pop these contexts.  So if you
wish to temporarily change how logging works, this gives you that mechanism.

Most of this file is actually setting up for a confusing
fork-for-a-logging-subprocess ordeal that's better explained as

                                           normal python logging
                                                     ^
                                                     |
                      +--------+                     |
                      |AUTOSERV|                 +---+---+
                      |        +------stdout---->+LOGGING|
                      | fork() |                 +---+---+
                      ++------++                     ^
                       |      |                      |
              +--------+      +--------+           stdout
              |                        |             |
    +---------+--------+      +--------+---------+   |
    |     AUTOSERV     |      |     AUTOSERV     |   |
    |                  |      |                  |   |
    ++----------------++      ++----------------++   |
    ||      test      ||      ||      test      ||   |
    ||                ||      ||                ||---+
    ||logging.info('')||      ||logging.info('')||
    |------------------|      |------------------|
    +------------------+      +------------------+

Each top-level box is a process.  When autoserv starts up, it'll fork off a
logging subprocess, and set its stdout/stderr fd's to the subprocess's stdin.
When we fork to create the processes that will run the test code, they inherit
this.  As do any processes they themselves fork and exec (such as shelling out
to some command).  This isn't the nicest, as it involves closing and dup'ing
over stdout/stderr, but it does make sure that the whole process tree logs to
python logging in a very consistent way.
"""


import fcntl, logging, os, signal, sys, time, warnings

# primary public APIs

def configure_logging(logging_config, **kwargs):
    """
    Configure the logging module using the specific configuration object, which
    should be an instance of logging_config.LoggingConfig (usually of a
    subclass).  Any keyword args will be passed to the object's
    configure_logging() method.

    Every entry point should call this method at application startup.
    """
    LoggingManager.logging_config_object = logging_config
    logging_config.configure_logging(**kwargs)


def get_logging_manager(manage_stdout_and_stderr=False, redirect_fds=False):
    """
    Create a LoggingManager that's managing sys.stdout and sys.stderr.

    Every entry point that wants to capture stdout/stderr and/or use
    LoggingManager to manage a stack of destinations should call this method
    at application startup.
    """
    if redirect_fds:
        manager = FdRedirectionLoggingManager()
    else:
        manager = LoggingManager()
    if manage_stdout_and_stderr:
        manager.manage_stdout()
        manager.manage_stderr()
    return manager


# implementation follows

logger = logging.getLogger()


def _current_handlers():
    return set(logger.handlers)


_caller_code_to_skip_in_logging_stack = set()


def do_not_report_as_logging_caller(func):
    """Decorator to annotate functions we will tell logging not to log."""
    # These are not the droids you are looking for.
    # You may go about your business.
    _caller_code_to_skip_in_logging_stack.add(func.func_code)
    return func


# Copied from Python 2.4 logging/__init__.py Logger.findCaller and enhanced.
# The logging code remains the same and compatible with this monkey patching
# through at least Python version 2.6.2.
def _logging_manager_aware_logger__find_caller(unused):
    """
    Find the stack frame of the caller so that we can note the source
    file name, line number and function name.
    """
    f = sys._getframe(2).f_back
    rv = "(unknown file)", 0, "(unknown function)"
    while hasattr(f, "f_code"):
        co = f.f_code
        filename = os.path.normcase(co.co_filename)
        if filename == logging._srcfile:
            f = f.f_back
            continue
        ### START additional code.
        if co in _caller_code_to_skip_in_logging_stack:
            f = f.f_back
            continue
        ### END additional code.
        rv = (filename, f.f_lineno, co.co_name)
        break
    return rv


if sys.version_info[:2] > (2, 7):
    warnings.warn('This module has not been reviewed for Python %s' %
                  sys.version)


# Monkey patch our way around logging's design...
_original_logger__find_caller = logging.Logger.findCaller
logging.Logger.findCaller = _logging_manager_aware_logger__find_caller


class LoggingFile(object):
    """
    File-like object that will receive messages pass them to the logging
    infrastructure in an appropriate way.
    """

    # This object is used to replace stdout and stderr, but doesn't expose
    # the same interface as a file object. To work around the most troublesome
    # part of the API, |fileno()|, we need to be able to provide a fake fd that
    # can pass basic checks.
    _fake_fds = os.pipe()

    def __init__(self, prefix='', level=logging.DEBUG):
        """
        @param prefix - The prefix for each line logged by this object.
        """
        self._prefix = prefix
        self._level = level
        self._buffer = []


    @do_not_report_as_logging_caller
    def write(self, data):
        """"
        Writes data only if it constitutes a whole line. If it's not the case,
        store it in a buffer and wait until we have a complete line.
        @param data - Raw data (a string) that will be processed.
        """
        # splitlines() discards a trailing blank line, so use split() instead
        data_lines = data.split('\n')
        if len(data_lines) > 1:
            self._buffer.append(data_lines[0])
            self._flush_buffer()
        for line in data_lines[1:-1]:
            self._log_line(line)
        if data_lines[-1]:
            self._buffer.append(data_lines[-1])


    @do_not_report_as_logging_caller
    def _log_line(self, line):
        """
        Passes lines of output to the logging module.
        """
        logging.log(self._level, self._prefix + line)


    @do_not_report_as_logging_caller
    def _flush_buffer(self):
        if self._buffer:
            self._log_line(''.join(self._buffer))
            self._buffer = []


    @do_not_report_as_logging_caller
    def flush(self):
        self._flush_buffer()


    @do_not_report_as_logging_caller
    def isatty(self):
        return False


    @do_not_report_as_logging_caller
    def fileno(self):
        # We return the read end of the pipe here becauase if we return the
        # write end, one can make the reasonable assumption that writing to the
        # fd is the same as stdout.write(). As we aren't reading from the other
        # end of the pipe, writing to this fd should be an error.
        return self._fake_fds[0]


class _StreamManager(object):
    """
    Redirects all output for some output stream (normally stdout or stderr) to
    the logging module by replacing the file objects with a new LoggingFile
    that calls logging.log().
    """
    def __init__(self, stream, level, stream_setter):
        """
        @param stream: stream object to manage
        @param level: level at which data written to the stream will be logged
        @param stream_setter: function accepting a stream object that will
                replace the given stream in its original location.
        """
        self._stream = stream
        self._level = level
        self._stream_setter = stream_setter
        self._logging_stream = None


    def _replace_with_logger(self):
        self._logging_stream = LoggingFile(level=self._level)
        self._stream_setter(self._logging_stream)


    def _restore_stream(self):
        self._stream_setter(self._stream)


    def flush(self):
        self._logging_stream.flush()


    def start_logging(self):
        """Start directing the stream to the logging module."""
        self._replace_with_logger()


    def stop_logging(self):
        """Restore the stream to its original settings."""
        self._restore_stream()


    def on_push_context(self, context):
        """
        Called when the logging manager is about to push a new context onto the
        stack and has changed logging settings.  The StreamHandler can modify
        the context to be saved before returning.
        """
        pass


    def on_restore_context(self, context):
        """
        Called when the logging manager is restoring a previous context.
        """
        pass



class LoggingManager(object):
    """
    Manages a stack of logging configurations, allowing clients to conveniently
    add and remove logging destinations.  Also keeps a list of StreamManagers
    to easily direct streams into the logging module.
    """

    STREAM_MANAGER_CLASS = _StreamManager

    logging_config_object = None

    def __init__(self):
        """
        This class should not ordinarily be constructed directly (other than in
        tests).  Use the module-global factory method get_logging_manager()
        instead.
        """
        if self.logging_config_object is None:
            raise RuntimeError('You must call configure_logging() before this')

        # _context_stack holds a stack of context dicts.  Each context dict
        # contains:
        # * old_handlers: list of registered logging Handlers
        # contexts may also be extended by _StreamHandlers
        self._context_stack = []
        self._streams = []
        self._started = False


    def manage_stream(self, stream, level, stream_setter):
        """
        Tells this manager to manage the given stream.  All data written to the
        stream will be directed to the logging module instead.  Must be called
        before start_logging().

        @param stream: stream to manage
        @param level: level to log data written to this stream
        @param stream_setter: function to set the stream to a new object
        """
        if self._started:
            raise RuntimeError('You must call this before start_logging()')
        self._streams.append(self.STREAM_MANAGER_CLASS(stream, level,
                                                       stream_setter))


    def _sys_stream_setter(self, stream_name):
        assert stream_name in ('stdout', 'stderr'), stream_name
        def set_stream(file_object):
            setattr(sys, stream_name, file_object)
        return set_stream


    def manage_stdout(self):
        self.manage_stream(sys.stdout, logging.INFO,
                           self._sys_stream_setter('stdout'))


    def manage_stderr(self):
        self.manage_stream(sys.stderr, self.logging_config_object.stderr_level,
                           self._sys_stream_setter('stderr'))


    def start_logging(self):
        """
        Begin capturing output to the logging module.
        """
        for stream_manager in self._streams:
            stream_manager.start_logging()
        self._started = True


    def stop_logging(self):
        """
        Restore output to its original state.
        """
        while self._context_stack:
            self._pop_context()

        for stream_manager in self._streams:
            stream_manager.stop_logging()

        self._started = False


    def _clear_all_handlers(self):
        for handler in _current_handlers():
            logger.removeHandler(handler)


    def _get_context(self):
        return {'old_handlers': _current_handlers()}


    def _push_context(self, context):
        for stream_manager in self._streams:
            stream_manager.on_push_context(context)
        self._context_stack.append(context)


    def _flush_all_streams(self):
        for stream_manager in self._streams:
            stream_manager.flush()


    def _add_log_handlers(self, add_handlers_fn):
        """
        Modify the logging module's registered handlers and push a new context
        onto the stack.
        @param add_handlers_fn: function to modify the registered logging
        handlers. Accepts a context dictionary which may be modified.
        """
        self._flush_all_streams()
        context = self._get_context()

        add_handlers_fn(context)

        self._push_context(context)


    class _TaggingFormatter(logging.Formatter):
        """
        Delegates to a given formatter, but prefixes each line of output with a
        tag.
        """
        def __init__(self, base_formatter, tag):
            self.base_formatter = base_formatter
            prefix = tag + ' : '
            self._fmt = base_formatter._fmt.replace('%(message)s',
                                                    prefix + '%(message)s')
            self.datefmt = base_formatter.datefmt


    def _add_tagging_formatter(self, tag):
        for handler in _current_handlers():
            tagging_formatter = self._TaggingFormatter(handler.formatter, tag)
            handler.setFormatter(tagging_formatter)


    def _do_redirect(self, stream=None, filename=None, level=None,
                     clear_other_handlers=False):
        """
        @param clear_other_handlers - if true, clear out all other logging
        handlers.
        """
        assert bool(stream) != bool(filename) # xor
        if not self._started:
            raise RuntimeError('You must call start_logging() before this')

        def add_handler(context):
            if clear_other_handlers:
                self._clear_all_handlers()

            if stream:
                handler = self.logging_config_object.add_stream_handler(stream)
            else:
                handler = self.logging_config_object.add_file_handler(filename)

            if level:
                handler.setLevel(level)

        self._add_log_handlers(add_handler)


    def redirect(self, filename):
        """Redirect output to the specified file"""
        self._do_redirect(filename=filename, clear_other_handlers=True)


    def redirect_to_stream(self, stream):
        """Redirect output to the given stream"""
        self._do_redirect(stream=stream, clear_other_handlers=True)


    def tee_redirect(self, filename, level=None):
        """Tee output to the specified file"""
        self._do_redirect(filename=filename, level=level)


    def tee_redirect_to_stream(self, stream):
        """Tee output to the given stream"""
        self._do_redirect(stream=stream)


    def tee_redirect_debug_dir(self, debug_dir, log_name=None, tag=None):
        """
        Tee output to a full new set of debug logs in the given directory.
        """
        def add_handlers(context):
            if tag:
                self._add_tagging_formatter(tag)
                context['tag_added'] = True
            self.logging_config_object.add_debug_file_handlers(
                    debug_dir, log_name=log_name)
        self._add_log_handlers(add_handlers)


    def _restore_context(self, context):
        for stream_handler in self._streams:
            stream_handler.on_restore_context(context)

        # restore logging handlers
        old_handlers = context['old_handlers']
        for handler in _current_handlers() - old_handlers:
            handler.close()
        self._clear_all_handlers()
        for handler in old_handlers:
            logger.addHandler(handler)

        if 'tag_added' in context:
            for handler in _current_handlers():
                tagging_formatter = handler.formatter
                handler.setFormatter(tagging_formatter.base_formatter)


    def _pop_context(self):
        self._flush_all_streams()
        context = self._context_stack.pop()
        self._restore_context(context)


    def undo_redirect(self):
        """
        Undo the last redirection (that hasn't yet been undone).

        If any subprocesses have been launched since the redirection was
        performed, they must have ended by the time this is called.  Otherwise,
        this will hang waiting for the logging subprocess to end.
        """
        if not self._context_stack:
            raise RuntimeError('No redirects to undo')
        self._pop_context()


    def restore(self):
        """
        Same as undo_redirect().  For backwards compatibility with
        fd_stack.
        """
        self.undo_redirect()


class _FdRedirectionStreamManager(_StreamManager):
    """
    Like StreamManager, but also captures output from subprocesses by modifying
    the underlying file descriptors.

    For the underlying file descriptors, we spawn a subprocess that writes all
    input to the logging module, and we point the FD to that subprocess.  As a
    result, every time we redirect output we need to spawn a new subprocess to
    pick up the new logging settings (without disturbing any existing processes
    using the old logging subprocess).

    If, one day, we could get all code using utils.run() and friends to launch
    subprocesses, we'd no longer need to handle raw FD output, and we could
    get rid of all this business with subprocesses.  Another option would be
    to capture all stray output to a single, separate destination.
    """

    WAITPID_TIMEOUT_S = 5
    WAITPID_SAMPLE_TIME_S = 0.1

    def __init__(self, stream, level, stream_setter):
        if not hasattr(stream, 'fileno'):
            # with fake, in-process file objects, subprocess output won't be
            # captured. this should never happen in normal use, since the
            # factory methods will only pass sys.stdout and sys.stderr.
            raise ValueError("FdRedirectionLoggingManager won't work with "
                             "streams that aren't backed by file "
                             "descriptors")

        super(_FdRedirectionStreamManager, self).__init__(stream, level,
                                                          stream_setter)
        self._fd = stream.fileno()
        self._fd_copy_stream = None


    def _point_stream_handlers_to_copy(self):
        """
        point logging StreamHandlers that point to this stream to a safe
        copy of the underlying FD. otherwise, StreamHandler output will go
        to the logging subprocess, effectively getting doubly logged.
        """
        fd_copy = os.dup(self._fd)
        self._fd_copy_stream = os.fdopen(fd_copy, 'w')
        self._redirect_logging_stream_handlers(self._stream,
                                               self._fd_copy_stream)


    def _restore_stream_handlers(self):
        """ point logging StreamHandlers back to the original FD """
        self._redirect_logging_stream_handlers(self._fd_copy_stream,
                                               self._stream)
        self._fd_copy_stream.close()


    def _redirect_logging_stream_handlers(self, old_stream, new_stream):
        """
        Redirect all configured logging StreamHandlers pointing to
        old_stream to point to new_stream instead.
        """
        for handler in _current_handlers():
            points_to_stream = (isinstance(handler, logging.StreamHandler) and
                                hasattr(handler.stream, 'fileno') and
                                handler.stream.fileno() == old_stream.fileno())
            if points_to_stream:
                logger.removeHandler(handler)
                handler.close() # doesn't close the stream, just the handler

                new_handler = logging.StreamHandler(new_stream)
                new_handler.setLevel(handler.level)
                new_handler.setFormatter(handler.formatter)
                for log_filter in handler.filters:
                    new_handler.addFilter(log_filter)
                logger.addHandler(new_handler)


    def start_logging(self):
        super(_FdRedirectionStreamManager, self).start_logging()
        self._point_stream_handlers_to_copy()


    def stop_logging(self):
        super(_FdRedirectionStreamManager, self).stop_logging()
        self._restore_stream_handlers()


    def _spawn_logging_subprocess(self):
        """
        Spawn a subprocess to log all input to the logging module with the
        current settings, and direct output to it.
        """
        read_end, write_end = os.pipe()
        pid = os.fork()
        if pid: # parent
            os.close(read_end)
            os.dup2(write_end, self._fd) # point FD to the subprocess
            os.close(write_end)
            fd_flags = fcntl.fcntl(self._fd, fcntl.F_GETFD)
            fcntl.fcntl(self._fd, fcntl.F_SETFD,
                        fd_flags | fcntl.FD_CLOEXEC)
            return pid
        else: # child
            try:
                os.close(write_end)
                # ensure this subprocess doesn't hold any pipes to others
                os.close(1)
                os.close(2)
                self._run_logging_subprocess(read_end) # never returns
            except:
                # don't let exceptions in the child escape
                try:
                    logging.exception('Logging subprocess died:')
                finally:
                    os._exit(1)


    def _run_logging_subprocess(self, read_fd):
        """
        Always run from a subprocess.  Read from read_fd and write to the
        logging module until EOF.
        """
        # A SIGTERM will be issued by the main process if it believes this
        # subprocess to the stuck. In that case, simply exit with status 1.
        # See below for pending TODO on how to remove this.
        signal.signal(signal.SIGTERM, lambda signum, stack: os._exit(1))
        input_file = os.fdopen(read_fd, 'r')
        for line in iter(input_file.readline, ''):
            logging.log(self._level, line.rstrip('\n'))
        logging.debug('Logging subprocess finished')
        os._exit(0)


    def _context_id(self):
        return '%s_context' % id(self)


    def on_push_context(self, context):
        # adds a context dict for this stream, $id_context, with the following:
        # * old_fd: FD holding a copy of the managed FD before launching a new
        #   subprocess.
        # * child_pid: PID of the logging subprocess launched
        fd_copy = os.dup(self._fd)
        child_pid = self._spawn_logging_subprocess()
        my_context = {'old_fd': fd_copy, 'child_pid': child_pid}
        context[self._context_id()] = my_context


    def on_restore_context(self, context):
        my_context = context[self._context_id()]

        # shut down subprocess
        child_pid = my_context['child_pid']
        try:
            os.close(self._fd)
            # TODO(crbug.com/970115): remove this work-around in favor of
            # a clean waitpid(child_pid, 0) once the issue described in the
            # bug is root caused and resolved.
            end = time.time() + self.WAITPID_TIMEOUT_S
            while time.time() < end:
                if os.waitpid(child_pid, os.WNOHANG) != (0, 0):
                    break
                time.sleep(self.WAITPID_SAMPLE_TIME_S)
            else:
                # After timeout the process still hasn't finished. Send a
                # SIGTERM as it's likely stuck.
                os.kill(child_pid, signal.SIGTERM)
                logging.exception('Ended up killing logging subprocess at %s.',
                                  child_pid)
        except OSError:
            logging.exception('Failed to cleanly shutdown logging subprocess:')

        # restore previous FD
        old_fd = my_context['old_fd']
        os.dup2(old_fd, self._fd)
        os.close(old_fd)


class FdRedirectionLoggingManager(LoggingManager):
    """
    A simple extension of LoggingManager to use FdRedirectionStreamManagers,
    so that managed streams have their underlying FDs redirected.
    """

    STREAM_MANAGER_CLASS = _FdRedirectionStreamManager

    def start_logging(self):
        super(FdRedirectionLoggingManager, self).start_logging()
        # spawn the initial logging subprocess
        self._push_context(self._get_context())


    def undo_redirect(self):
        # len == 1 would mean only start_logging() had been called (but no
        # redirects had occurred)
        if len(self._context_stack) < 2:
            raise RuntimeError('No redirects to undo')
        super(FdRedirectionLoggingManager, self).undo_redirect()