path: root/buildscripts/resmokelib/hang_analyzer/dumper.py

"""Tools to dump debug info for each OS."""

import itertools
import logging
import os
import sys
import tempfile
from abc import ABCMeta, abstractmethod
from collections import namedtuple
from distutils import spawn  # pylint: disable=no-name-in-module

from buildscripts.resmokelib.hang_analyzer.process import call, callo, find_program
from buildscripts.resmokelib.hang_analyzer.process_list import Pinfo

Dumpers = namedtuple('Dumpers', ['dbg', 'jstack'])


def get_dumpers(root_logger: logging.Logger, dbg_output: str):
    """
    Return OS-appropriate dumpers.

    :param root_logger: Top-level logger
    :param dbg_output: 'stdout' or 'file'
    """

    dbg = None
    jstack = None
    if sys.platform.startswith("linux"):
        dbg = GDBDumper(root_logger, dbg_output)
        jstack = JstackDumper()
    elif sys.platform == "win32" or sys.platform == "cygwin":
        dbg = WindowsDumper(root_logger, dbg_output)
        jstack = JstackWindowsDumper()
    elif sys.platform == "darwin":
        dbg = LLDBDumper(root_logger, dbg_output)
        jstack = JstackDumper()

    return Dumpers(dbg=dbg, jstack=jstack)


class Dumper(metaclass=ABCMeta):
    """
    Abstract base class for OS-specific dumpers.

    :param dbg_output: 'stdout' or 'file'
    :param root_logger: Top-level logger
    """

    def __init__(self, root_logger: logging.Logger, dbg_output: str):
        """Initialize dumper."""
        self._root_logger = root_logger
        self._dbg_output = dbg_output

    @abstractmethod
    def dump_info(  # pylint: disable=too-many-arguments,too-many-locals
            self,
            pinfo: Pinfo,
            take_dump: bool,
    ):
        """
        Perform dump for a process.

        :param pinfo: A Pinfo describing the process
        :param take_dump: Whether to take a core dump
        """
        raise NotImplementedError("dump_info must be implemented in OS-specific subclasses")

    @abstractmethod
    def get_dump_ext(self):
        """Return the dump file extension."""
        raise NotImplementedError("get_dump_ext must be implemented in OS-specific subclasses")

    @abstractmethod
    def _find_debugger(self, debugger):
        """
        Find the installed debugger.

        :param debugger: debugger executable.
        """
        raise NotImplementedError("_find_debugger must be implemented in OS-specific subclasses")

    @abstractmethod
    def _prefix(self):
        """Return the commands to set up a debugger process."""
        raise NotImplementedError("_prefix must be implemented in OS-specific subclasses")

    @abstractmethod
    def _process_specific(self, pinfo: Pinfo, take_dump: bool, logger: logging.Logger = None):
        """
        Return the commands that attach to each process, dump info and detach.

        :param pinfo: A Pinfo describing the process
        :param take_dump: Whether to take a core dump
        :param logger: Logger to output dump info to
        """
        raise NotImplementedError("_process_specific must be implemented in OS-specific subclasses")

    @abstractmethod
    def _postfix(self):
        """Return the commands to exit the debugger."""
        raise NotImplementedError("_postfix must be implemented in OS-specific subclasses")


class WindowsDumper(Dumper):
    """WindowsDumper class."""

    def _find_debugger(self, debugger):
        """Find the installed debugger."""
        # We are looking for c:\Program Files (x86)\Windows Kits\8.1\Debuggers\x64
        cdb = spawn.find_executable(debugger)
        if cdb is not None:
            return cdb
        from win32com.shell import shell, shellcon

        # Cygwin via sshd does not expose the normal environment variables
        # Use the shell api to get the variable instead
        root_dir = shell.SHGetFolderPath(0, shellcon.CSIDL_PROGRAM_FILESX86, None, 0)

        # Construct the debugger search paths in most-recent order
        debugger_paths = [os.path.join(root_dir, "Windows Kits", "10", "Debuggers", "x64")]
        for idx in reversed(range(0, 2)):
            debugger_paths.append(
                os.path.join(root_dir, "Windows Kits", "8." + str(idx), "Debuggers", "x64"))

        for dbg_path in debugger_paths:
            self._root_logger.info("Checking for debugger in %s", dbg_path)
            if os.path.exists(dbg_path):
                return os.path.join(dbg_path, debugger)

        return None

    def _prefix(self):
        """Return the commands to set up a debugger process."""
        cmds = [
            ".symfix",  # Fixup symbol path
            "!sym noisy",  # Enable noisy symbol loading
            ".symopt +0x10",  # Enable line loading (off by default in CDB, on by default in WinDBG)
            ".reload",  # Reload symbols
        ]

        return cmds

    def _process_specific(self, pinfo, take_dump, logger=None):
        """Return the commands that attach to each process, dump info and detach."""
        assert isinstance(pinfo.pidv, int)

        dump_command = ""
        if take_dump:
            # Dump to file, dump_<process name>.<pid>.mdmp
            dump_file = "dump_%s.%d.%s" % (os.path.splitext(pinfo.name)[0], pinfo.pidv,
                                           self.get_dump_ext())
            dump_command = ".dump /ma %s" % dump_file
            self._root_logger.info("Dumping core to %s", dump_file)

        cmds = [
            "!peb",  # Dump current exe, & environment variables
            "lm",  # Dump loaded modules
            dump_command,
            "!uniqstack -pn",  # Dump All unique Threads with function arguments
            "!cs -l",  # Dump all locked critical sections
            ".detach",  # Detach
        ]

        return cmds

    def _postfix(self):
        """Return the commands to exit the debugger."""
        cmds = [
            "q"  # Quit
        ]

        return cmds

    def dump_info(  # pylint: disable=too-many-arguments
            self, pinfo, take_dump):
        """Dump useful information to the console."""
        debugger = "cdb.exe"
        dbg = self._find_debugger(debugger)

        if dbg is None:
            self._root_logger.warning("Debugger %s not found, skipping dumping of %s", debugger,
                                      str(pinfo.pidv))
            return

        self._root_logger.info("Debugger %s, analyzing %s processes with PIDs %s", dbg, pinfo.name,
                               str(pinfo.pidv))

        # TODO: SERVER-48449
        for pid in pinfo.pidv:
            logger = _get_process_logger(self._dbg_output, pinfo.name, pid=pid)

            process = Pinfo(name=pinfo.name, pidv=pid)
            cmds = self._prefix() + self._process_specific(process, take_dump) + self._postfix()

            call([dbg, '-c', ";".join(cmds), '-p', str(pid)], logger)

            self._root_logger.info("Done analyzing %s process with PID %d", pinfo.name, pid)

    def get_dump_ext(self):
        """Return the dump file extension."""
        return "mdmp"


# LLDB dumper is for MacOS X
class LLDBDumper(Dumper):
    """LLDBDumper class."""

    @staticmethod
    def _find_debugger(debugger):
        """Find the installed debugger."""
        return find_program(debugger, ['/usr/bin'])

    def _prefix(self):
        pass

    def _process_specific(self, pinfo, take_dump, logger=None):
        """Return the commands that attach to each process, dump info and detach."""
        cmds = []
        dump_files = self._dump_files(pinfo)
        for pid in pinfo.pidv:
            dump_command = ""
            if take_dump:
                # Dump to file, dump_<process name>.<pid>.core
                dump_file = dump_files[pid]
                dump_command = "process save-core %s" % dump_file
                self._root_logger.info("Dumping core to %s", dump_file)

            cmds += [
                "platform shell kill -CONT %d" % pid,
                "attach -p %d" % pid,
                "target modules list",
                "thread backtrace all",
                dump_command,
                "process detach",
                "platform shell kill -STOP %d" % pid,
            ]

        return cmds

    def _postfix(self):
        """Return the commands to exit the debugger."""
        cmds = [
            "settings set interpreter.prompt-on-quit false",
            "quit",
        ]

        return cmds

    def dump_info(self, pinfo, take_dump):
        """Dump info."""
        debugger = "lldb"
        dbg = self._find_debugger(debugger)
        logger = _get_process_logger(self._dbg_output, pinfo.name)

        if dbg is None:
            self._root_logger.warning("Debugger %s not found, skipping dumping of %s", debugger,
                                      str(pinfo.pidv))
            return

        self._root_logger.info("Debugger %s, analyzing %s processes with PIDs %s", dbg, pinfo.name,
                               str(pinfo.pidv))

        lldb_version = callo([dbg, "--version"], logger)

        logger.info(lldb_version)

        # Do we have the XCode or LLVM version of lldb?
        # Old versions of lldb do not work well when taking commands via a file
        # XCode (7.2): lldb-340.4.119
        # LLVM - lldb version 3.7.0 ( revision )

        if 'version' not in lldb_version:
            # We have XCode's lldb
            lldb_version = lldb_version[lldb_version.index("lldb-"):]
            lldb_version = lldb_version.replace('lldb-', '')
            lldb_major_version = int(lldb_version[:lldb_version.index('.')])
            if lldb_major_version < 340:
                logger.warning("Debugger lldb is too old, please upgrade to XCode 7.2")
                return

        cmds = self._process_specific(pinfo, take_dump) + self._postfix()

        tf = tempfile.NamedTemporaryFile(mode='w', encoding='utf-8')

        for cmd in cmds:
            tf.write(cmd + "\n")

        tf.flush()

        # Works on in MacOS 10.9 & later
        #call([dbg] +  list( itertools.chain.from_iterable([['-o', b] for b in cmds])), logger)
        call(['cat', tf.name], logger)
        call([dbg, '--source', tf.name], logger)

        self._root_logger.info("Done analyzing %s processes with PIDs %s", pinfo.name,
                               str(pinfo.pidv))

        if take_dump:
            need_sigabrt = {}
            files = self._dump_files(pinfo)
            for pid in files:
                if not os.path.exists(files[pid]):
                    need_sigabrt[pid] = files[pid]
            if need_sigabrt:
                raise DumpError(need_sigabrt)

    def get_dump_ext(self):
        """Return the dump file extension."""
        return "core"

    def _dump_files(self, pinfo):
        """Return a dict mapping pids to core dump filenames that this dumper can create."""
        files = {}
        for pid in pinfo.pidv:
            files[pid] = "dump_%s.%d.%s" % (pinfo.name, pid, self.get_dump_ext())
        return files


# GDB dumper is for Linux
class GDBDumper(Dumper):
    """GDBDumper class."""

    def _find_debugger(self, debugger):
        """Find the installed debugger."""
        return find_program(debugger, ['/opt/mongodbtoolchain/gdb/bin', '/usr/bin'])

    def _prefix(self):
        """Return the commands to set up a debugger process."""
        script_dir = "buildscripts"
        gdb_dir = os.path.join(script_dir, "gdb")
        mongo_script = os.path.join(gdb_dir, "mongo.py")
        mongo_printers_script = os.path.join(gdb_dir, "mongo_printers.py")
        mongo_lock_script = os.path.join(gdb_dir, "mongo_lock.py")

        source_mongo = "source %s" % mongo_script
        source_mongo_printers = "source %s" % mongo_printers_script
        source_mongo_lock = "source %s" % mongo_lock_script

        cmds = [
            "set interactive-mode off",
            "set print thread-events off",  # Suppress GDB messages of threads starting/finishing.
            "set python print-stack full",
            source_mongo,
            source_mongo_printers,
            source_mongo_lock,
        ]
        return cmds

    def _process_specific(  # pylint: disable=too-many-locals
            self, pinfo, take_dump, logger=None):
        """Return the commands that attach to each process, dump info and detach."""
        mongodb_dump_locks = "mongodb-dump-locks"
        mongodb_show_locks = "mongodb-show-locks"
        mongodb_uniqstack = "mongodb-uniqstack mongodb-bt-if-active"
        mongodb_javascript_stack = "mongodb-javascript-stack"
        mongod_dump_sessions = "mongod-dump-sessions"
        mongodb_dump_mutexes = "mongodb-dump-mutexes"
        mongodb_dump_recovery_units = "mongodb-dump-recovery-units"

        cmds = []
        for pid in pinfo.pidv:
            if not logger.mongo_process_filename:
                raw_stacks_commands = []
            else:
                base, ext = os.path.splitext(logger.mongo_process_filename)
                raw_stacks_filename = "%s_%d_raw_stacks%s" % (base, pid, ext)
                raw_stacks_commands = [
                    'echo \\nWriting raw stacks to %s.\\n' % raw_stacks_filename,
                    # This sends output to log file rather than stdout until we turn logging off.
                    'set logging redirect on',
                    'set logging file ' + raw_stacks_filename,
                    'set logging on',
                    'thread apply all bt',
                    'set logging off',
                ]

            dump_command = ""
            if take_dump:
                # Dump to file, dump_<process name>.<pid>.core
                dump_file = "dump_%s.%d.%s" % (pinfo.name, pid, self.get_dump_ext())
                dump_command = "gcore %s" % dump_file
                self._root_logger.info("Dumping core to %s", dump_file)

            mongodb_waitsfor_graph = "mongodb-waitsfor-graph debugger_waitsfor_%s_%d.gv" % \
                (pinfo.name, pid)

            cmds += [
                "attach %d" % pid,
                "handle SIGSTOP ignore noprint",
                "info sharedlibrary",
                "info threads",  # Dump a simple list of commands to get the thread name
            ] + raw_stacks_commands + [
                mongodb_uniqstack,
                # Lock the scheduler, before running commands, which execute code in the attached process.
                "set scheduler-locking on",
                dump_command,
                mongodb_dump_locks,
                mongodb_show_locks,
                mongodb_waitsfor_graph,
                mongodb_javascript_stack,
                mongod_dump_sessions,
                mongodb_dump_mutexes,
                mongodb_dump_recovery_units,
                "detach",
            ]

        return cmds

    def _postfix(self):
        """Return the commands to exit the debugger."""
        cmds = ["set confirm off", "quit"]
        return cmds

    def dump_info(self, pinfo, take_dump):
        """Dump info."""
        debugger = "gdb"
        dbg = self._find_debugger(debugger)
        logger = _get_process_logger(self._dbg_output, pinfo.name)

        if dbg is None:
            self._root_logger.warning("Debugger %s not found, skipping dumping of %s", debugger,
                                      str(pinfo.pidv))
            return

        self._root_logger.info("Debugger %s, analyzing %s processes with PIDs %s", dbg, pinfo.name,
                               str(pinfo.pidv))

        call([dbg, "--version"], logger)

        cmds = self._prefix() + self._process_specific(pinfo, take_dump, logger) + self._postfix()

        call([dbg, "--quiet", "--nx"] + list(
            itertools.chain.from_iterable([['-ex', b] for b in cmds])), logger)

        self._root_logger.info("Done analyzing %s processes with PIDs %s", pinfo.name,
                               str(pinfo.pidv))

    def get_dump_ext(self):
        """Return the dump file extension."""
        return "core"

    @staticmethod
    def _find_gcore():
        """Find the installed gcore."""
        dbg = "/usr/bin/gcore"
        if os.path.exists(dbg):
            return dbg

        return None


# jstack is a JDK utility
class JstackDumper(object):
    """JstackDumper class."""

    @staticmethod
    def _find_debugger(debugger):
        """Find the installed jstack debugger."""
        return find_program(debugger, ['/usr/bin'])

    def dump_info(self, root_logger, dbg_output, pid, process_name):
        """Dump java thread stack traces to the console."""
        debugger = "jstack"
        jstack = self._find_debugger(debugger)
        logger = _get_process_logger(dbg_output, process_name, pid=pid)

        if jstack is None:
            logger.warning("Debugger %s not found, skipping dumping of %d", debugger, pid)
            return

        root_logger.info("Debugger %s, analyzing %s process with PID %d", jstack, process_name, pid)

        call([jstack, "-l", str(pid)], logger)

        root_logger.info("Done analyzing %s process with PID %d", process_name, pid)


# jstack is a JDK utility
class JstackWindowsDumper(object):
    """JstackWindowsDumper class."""

    @staticmethod
    def dump_info(root_logger, pid):
        """Dump java thread stack traces to the logger."""

        root_logger.warning("Debugger jstack not supported, skipping dumping of %d", pid)


def _get_process_logger(dbg_output, pname: str, pid: int = None):
    """Return the process logger from options specified."""
    process_logger = logging.Logger("process", level=logging.DEBUG)
    process_logger.mongo_process_filename = None

    if 'stdout' in dbg_output:
        s_handler = logging.StreamHandler(sys.stdout)
        s_handler.setFormatter(logging.Formatter(fmt="%(message)s"))
        process_logger.addHandler(s_handler)

    if 'file' in dbg_output:
        if pid:
            filename = "debugger_%s_%d.log" % (os.path.splitext(pname)[0], pid)
        else:
            filename = "debugger_%s.log" % (os.path.splitext(pname)[0])
        process_logger.mongo_process_filename = filename
        f_handler = logging.FileHandler(filename=filename, mode="w")
        f_handler.setFormatter(logging.Formatter(fmt="%(message)s"))
        process_logger.addHandler(f_handler)

    return process_logger


class DumpError(Exception):
    """
    Exception raised for errors while dumping processes.

    Tracks what cores still need to be generated.
    """

    def __init__(self, dump_pids, message=("Failed to create core dumps for some processes,"
                                           " SIGABRT will be sent as a fallback if -k is set.")):
        """Initialize error."""
        self.dump_pids = dump_pids
        self.message = message
        super().__init__(self.message)