import quincy beta 17.1.0

[ceph.git] / ceph / src / ceph-volume / ceph_volume / process.py

from fcntl import fcntl, F_GETFL, F_SETFL
from os import O_NONBLOCK, read, path
import subprocess
from select import select
from ceph_volume import terminal
from ceph_volume.util import as_bytes
from ceph_volume.util.system import which, run_host_cmd, host_rootfs

import logging

logger = logging.getLogger(__name__)


def log_output(descriptor, message, terminal_logging, logfile_logging):
    """
    log output to both the logger and the terminal if terminal_logging is
    enabled
    """
    if not message:
        return
    message = message.strip()
    line = '%s %s' % (descriptor, message)
    if terminal_logging:
        getattr(terminal, descriptor)(message)
    if logfile_logging:
        logger.info(line)


def log_descriptors(reads, process, terminal_logging):
    """
    Helper to send output to the terminal while polling the subprocess
    """
    # these fcntl are set to O_NONBLOCK for the filedescriptors coming from
    # subprocess so that the logging does not block. Without these a prompt in
    # a subprocess output would hang and nothing would get printed. Note how
    # these are just set when logging subprocess, not globally.
    stdout_flags = fcntl(process.stdout, F_GETFL) # get current p.stdout flags
    stderr_flags = fcntl(process.stderr, F_GETFL) # get current p.stderr flags
    fcntl(process.stdout, F_SETFL, stdout_flags | O_NONBLOCK)
    fcntl(process.stderr, F_SETFL, stderr_flags | O_NONBLOCK)
    descriptor_names = {
        process.stdout.fileno(): 'stdout',
        process.stderr.fileno(): 'stderr'
    }
    for descriptor in reads:
        descriptor_name = descriptor_names[descriptor]
        try:
            message = read(descriptor, 1024)
            if not isinstance(message, str):
                message = message.decode('utf-8')
            log_output(descriptor_name, message, terminal_logging, True)
        except (IOError, OSError):
            # nothing else to log
            pass


def obfuscate(command_, on=None):
    """
    Certain commands that are useful to log might contain information that
    should be replaced by '*' like when creating OSDs and the keyrings are
    being passed, which should not be logged.

    :param on: A string (will match a flag) or an integer (will match an index)

    If matching on a flag (when ``on`` is a string) it will obfuscate on the
    value for that flag. That is a command like ['ls', '-l', '/'] that calls
    `obfuscate(command, on='-l')` will obfustace '/' which is the value for
    `-l`.

    The reason for `on` to allow either a string or an integer, altering
    behavior for both is because it is easier for ``run`` and ``call`` to just
    pop a value to obfuscate (vs. allowing an index or a flag)
    """
    command = command_[:]
    msg = "Running command: %s" % ' '.join(command)
    if on in [None, False]:
        return msg

    if isinstance(on, int):
        index = on

    else:
        try:
            index = command.index(on) + 1
        except ValueError:
            # if the flag just doesn't exist then it doesn't matter just return
            # the base msg
            return msg

    try:
        command[index] = '*' * len(command[index])
    except IndexError: # the index was completely out of range
        return msg

    return "Running command: %s" % ' '.join(command)


def run(command, run_on_host=False, **kw):
    """
    A real-time-logging implementation of a remote subprocess.Popen call where
    a command is just executed on the remote end and no other handling is done.

    :param command: The command to pass in to the remote subprocess.Popen as a list
    :param stop_on_error: If a nonzero exit status is return, it raises a ``RuntimeError``
    :param fail_msg: If a nonzero exit status is returned this message will be included in the log
    """
    executable = which(command.pop(0), run_on_host)
    command.insert(0, executable)
    if run_on_host and path.isdir(host_rootfs):
        command = run_host_cmd + command
    stop_on_error = kw.pop('stop_on_error', True)
    command_msg = obfuscate(command, kw.pop('obfuscate', None))
    fail_msg = kw.pop('fail_msg', None)
    logger.info(command_msg)
    terminal.write(command_msg)
    terminal_logging = kw.pop('terminal_logging', True)

    process = subprocess.Popen(
        command,
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        close_fds=True,
        **kw
    )

    while True:
        reads, _, _ = select(
            [process.stdout.fileno(), process.stderr.fileno()],
            [], []
        )
        log_descriptors(reads, process, terminal_logging)

        if process.poll() is not None:
            # ensure we do not have anything pending in stdout or stderr
            log_descriptors(reads, process, terminal_logging)

            break

    returncode = process.wait()
    if returncode != 0:
        msg = "command returned non-zero exit status: %s" % returncode
        if fail_msg:
            logger.warning(fail_msg)
            if terminal_logging:
                terminal.warning(fail_msg)
        if stop_on_error:
            raise RuntimeError(msg)
        else:
            if terminal_logging:
                terminal.warning(msg)
            logger.warning(msg)


def call(command, run_on_host=False, **kw):
    """
    Similar to ``subprocess.Popen`` with the following changes:

    * returns stdout, stderr, and exit code (vs. just the exit code)
    * logs the full contents of stderr and stdout (separately) to the file log

    By default, no terminal output is given, not even the command that is going
    to run.

    Useful when system calls are needed to act on output, and that same output
    shouldn't get displayed on the terminal.

    Optionally, the command can be displayed on the terminal and the log file,
    and log file output can be turned off. This is useful to prevent sensitive
    output going to stderr/stdout and being captured on a log file.

    :param terminal_verbose: Log command output to terminal, defaults to False, and
                             it is forcefully set to True if a return code is non-zero
    :param logfile_verbose: Log stderr/stdout output to log file. Defaults to True
    :param verbose_on_failure: On a non-zero exit status, it will forcefully set logging ON for
                               the terminal. Defaults to True
    """
    executable = which(command.pop(0), run_on_host)
    command.insert(0, executable)
    if run_on_host and path.isdir(host_rootfs):
        command = run_host_cmd + command
    terminal_verbose = kw.pop('terminal_verbose', False)
    logfile_verbose = kw.pop('logfile_verbose', True)
    verbose_on_failure = kw.pop('verbose_on_failure', True)
    show_command = kw.pop('show_command', False)
    command_msg = "Running command: %s" % ' '.join(command)
    stdin = kw.pop('stdin', None)
    logger.info(command_msg)
    if show_command:
        terminal.write(command_msg)

    process = subprocess.Popen(
        command,
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        stdin=subprocess.PIPE,
        close_fds=True,
        **kw
    )

    if stdin:
        stdout_stream, stderr_stream = process.communicate(as_bytes(stdin))
    else:
        stdout_stream = process.stdout.read()
        stderr_stream = process.stderr.read()
    returncode = process.wait()
    if not isinstance(stdout_stream, str):
        stdout_stream = stdout_stream.decode('utf-8')
    if not isinstance(stderr_stream, str):
        stderr_stream = stderr_stream.decode('utf-8')
    stdout = stdout_stream.splitlines()
    stderr = stderr_stream.splitlines()

    if returncode != 0:
        # set to true so that we can log the stderr/stdout that callers would
        # do anyway as long as verbose_on_failure is set (defaults to True)
        if verbose_on_failure:
            terminal_verbose = True
        # logfiles aren't disruptive visually, unlike the terminal, so this
        # should always be on when there is a failure
        logfile_verbose = True

    # the following can get a messed up order in the log if the system call
    # returns output with both stderr and stdout intermingled. This separates
    # that.
    for line in stdout:
        log_output('stdout', line, terminal_verbose, logfile_verbose)
    for line in stderr:
        log_output('stderr', line, terminal_verbose, logfile_verbose)
    return stdout, stderr, returncode