#!/usr/libexec/isilon/isi_hangdump

# Script to obtain a dump when the file locks are about to time out

import errno
import getopt
import glob
import os
import os.path as path
import select
import shutil
import signal
import sys
import syslog
import subprocess
import time
import traceback
import re
import gzip

import isi.misc as misc
import isi.app.daemon as daemon
import isi.hw.hal as hal
from isi.app.lib.process import madvise, MADV_PROTECT
from isi.app.lib.procs import get_cmd_output

# try to stat this to see if a shared lock can be acquired
TESTFILE = "/ifs"
# file where all stacks will be printed before panic
DUMPFILE = "/var/crash/isi_hangdump_latest.log"
# beginning of filename dump copied to
SAVED_DUMP_PREFIX = "/var/crash/isi_hangdump_"
# end of filename dump copied to
SAVED_DUMP_SUFFIX = ".log"
# file permissions for the latest dump file
FILE_FLAGS = os.O_RDWR | os.O_CREAT | os.O_APPEND

# percentage of the timeout period to wait before considering a panic imminent
DEBUG_PERCENT_TIMEOUT   = .5 # 50% in debug builds
RELEASE_PERCENT_TIMEOUT = .3 # 30% in release builds

# seconds between pings
PING_DELAY = 5
# the maximum number of dumps to leave in the destination folder
MAX_OLD_DUMPS = 10

# the maximum memory to be allocated by the misc library
MAXSIZE = 33554432

# The minimum time between dumps.
MIN_REPEAT_DUMP = 60 * 10

SPACER = "===============================================================\n"
# sysctl used to find the timeout period
ROOTLOCK_TIMEOUT             = 'debug.ufs_rootlock_timeout_secs'

# format to print date/time in
TIME_FMT = "%04d_%02d_%02d_%02d_%02d_%02d"

# command to run cluster wide to send dump signal
CLUSTER_TRIGGER_CMD = 'isi_for_array -x0`hostname | tr - "\n" | tail -1` \'killall -HUP isi_hangdump\''

# sysctlbyname doesn't take * as an argument so define sysctls here
SYSCTLS = [
# necessary sysctls for lock visualization
# this should always be gathered first since it is the most useful
# information and none of these sysctls are guaranteed not to panic
'efs.rbm.array_id',
'efs.lin.lock.probe.num_active',
'efs.rbm.running_handlers',
'efs.rbm.batch.initiators',
'efs.rbm.batch.participants',
'efs.rbm.dev_msg_ring_pos_initial',
'efs.rbm.devices',
'efs.gmp.current_info',
'efs.journal.buf_waiters',
'efs.lin.lock.initiator.active_entries',
'efs.mds.block_lock.initiator.active_entries',
'efs.advlock.initiator.active_entries',
'efs.ref.initiator.active_entries',
'efs.bam.datalock.initiator.active_entries',
'efs.bam.av.lk.initiator.active_entries',
'efs.quota.cache.initiator.active_entries',
'kern.proc.all_stacks',
# other possibly useful data
'efs.gmp.shared_merge_lock_owners',
'efs.txn.initiators',
'efs.txn.participants',
'efs.txn.coordinators',
'efs.lin.lock.deadlocks_detected',
'efs.lin.lock.coordinator.active_entries',
'efs.lin.lock.initiator.lazy_queue_size',
'efs.lin.lock.initiator.lazy_queue_goal',
'efs.lin.lock.initiator.max_probes',
'efs.lin.lock.probe.stats.result_stats',
'efs.lin.lock.probe.stats.deepest_deadlock',
'efs.lin.lock.probe.stats.deepest_non_deadlock',
'efs.mds.block_lock.coordinator.entries',
'efs.mds.block_lock.coordinator.active_entries',
'efs.mds.block_lock.initiator.lazy_queue_size',
'efs.mds.block_lock.initiator.lazy_queue_goal',
'efs.ref.coordinator.active_entries',
'efs.ref.initiator.lazy_queue_size',
'efs.ref.initiator.lazy_queue_goal',
'efs.bam.datalock.coordinator.active_entries',
'efs.bam.datalock.initiator.lazy_queue_size',
'efs.bam.datalock.initiator.lazy_queue_goal',
'efs.bam.av.lk.coordinator.active_entries',
'efs.quota.cache.coordinator.active_entries',
'efs.quota.cache.initiator.lazy_queue_size',
'efs.quota.cache.initiator.lazy_queue_goal',
'efs.dexitcode_ring',
'efs.bam.coalescer.coalescers',
'efs.bam.coalescer_stats',
'vfs.bufdebug',
'vm.uma_zalloc_pigs',
'kern.malloc_pigs',
'kern.mbaudit',
]

# File descriptor of the hangdump log file always held open.
fd = -1

# Reasons for dumping
REASON_HUP = "Received HUP" 
REASON_PING_TIMEOUT = "Ping timeout"
REASON_LOCK_TIMEOUT = "Lock timeout"

def write_and_log(fd, msg):
    os.write(fd, msg + "\n")
    syslog.syslog(syslog.LOG_NOTICE, msg)

# Dump debug info to the dump file.
def dump(fd, reason, elapsed=0):
    cmd_out_stderr = None
    try:
        if reason != REASON_HUP:
            # Send a clusterwide signal from a separate process
            syslog.syslog(syslog.LOG_NOTICE, "Triggering clusterwide hangdump.")
            try:
                childp = subprocess.Popen(CLUSTER_TRIGGER_CMD, shell=True,
                                          stdout = subprocess.PIPE,
                                          stderr = subprocess.STDOUT,
                                          close_fds = True)
                cmd_out_stderr = childp.stdout
            except OSError as e:
                syslog.syslog(syslog.LOG_ERR, "Popen failed: %d %s"
                              % (e.errno, e.strerror))
		if hasattr(e, 'child_traceback') and e.child_traceback:
                    syslog.syslog(syslog.LOG_ERR, "Child traceback: %s"
                                  % e.child_traceback)
        timestamp = int(time.time())
        write_and_log(fd, "LOCK TIMEOUT AT %d UTC" % timestamp)
        write_and_log(fd, "Hangdump timeout after %d seconds: %s" %
                      (elapsed, reason))
        if reason != REASON_HUP:
            write_and_log(fd, "Initiating hangdump...")
        os.write(fd, SPACER)

        for ctl in SYSCTLS:
            try:
                output = misc.sysctlbyname(ctl, MAXSIZE)
                os.write(fd, "%s: " % ctl)
                if isinstance(output, int):
                    os.write(fd, "%d\n" % output)
                elif isinstance(output, float):
                    os.write(fd, "%f\n" % output)
                else:
                    os.write(fd, "%s\n" % output)
            except misc.error, e:
            	#Ignore this sysctl because it may not exist in this kernel.
                os.write(fd, "%s sysctl invalid, ignored\n" % ctl)
            os.write(fd, SPACER)

        write_and_log(fd, "END OF DUMP AT %d UTC\n" % timestamp)
        os.fsync(fd)
        # Now signal across the cluster
        if reason != REASON_HUP:
            syslog.syslog(syslog.LOG_NOTICE, "Triggering clusterwide hangdump.")
            os.system(CLUSTER_TRIGGER_CMD)
    finally:
        if cmd_out_stderr is not None:
            try:
                line = cmd_out_stderr.readline()
                if line:
                    syslog.syslog(syslog.LOG_NOTICE,
                                  "Clusterwide trigger output:")
                    syslog.syslog(syslog.LOG_NOTICE, line)
                for line in cmd_out_stderr:
                    syslog.syslog(syslog.LOG_NOTICE, line)
            except EnvironmentError as e:
                if e.errno != errno.EINTR:
                     syslog.syslog(syslog.LOG_ERR,
                                   "Dump thread failed to send signal: %d (%s)" %
                                   (e.errno, e.strerror))
            cmd_out_stderr.close()

def dump_handle_hup(sig, stack):
    # This may not be atomicish enough, but it is the best I can do now.
    global fd
    global dump_time
    now = misc.monotime()
    
    if (now - dump_time) > MIN_REPEAT_DUMP:
        dump_time = now
        dump(fd, REASON_HUP)
        os.close(fd)
        fd = open_dumpfile()



# The thread that dumps debug state on several conditions:
#   1) the ping thread stops responding indicating a vnode deadlock
#   2) a signal is received indicating the user wants the state dumped
#   3) a signal is received indicating that a dump thread on another node
#      saw event 1 or 2 and sent a signal over isi_for_array.
def dump_thread(r, w, timeout):
    global fd
    global dump_time
    # We start the dump time as negative so that it can dump in the first
    # 10 minutes of boot.  (monotime is implemented as uptime.)
    dump_time = -MIN_REPEAT_DUMP
    expect_good = True
    # Protect from the OOM killer
    madvise(MADV_PROTECT)

    # Set up a signal listener for user signals in case of a user triggered
    # dump or cluster wide dump.
    signal.signal(signal.SIGHUP, dump_handle_hup)

    # Set the dump thread 
    os.close(w)
    lastPing = misc.monotime()
    ping = ""
    # Listen for the ping proc.
    while (True):
        try:
            i, o, e = select.select([r], [], [], timeout)
        except select.error, (error, errstr):
            # Ignore EINTR, as HUP could have generated it while we
            # were in a syscall. Just restart in that case.
            if error == errno.EINTR:
                continue
            else:
                raise

        if (i != []):
            ping = os.read(r, 1)
            if len(ping) == 0:
                syslog.syslog(syslog.LOG_NOTICE, "Dump thread lost contact with"
                        " ping thread.  Closing dump thread.")
                os.close(fd)
                sys.exit(0)
        else:
            ping = ""

        reason = None
        now = misc.monotime()
        elapsed = now - lastPing
        if (ping):
            lastPing = now
        elif (elapsed > timeout):
            reason = REASON_PING_TIMEOUT

        if (ping == "d"):
            reason = REASON_LOCK_TIMEOUT
        
        if reason:
            # Dump locally first since dump to ensure local information
            # is gathered.  Then do a more unreliable cluster wide
            # dump.
            if (now - dump_time) > MIN_REPEAT_DUMP and expect_good:
                dump_time = now
                dump(fd, reason, elapsed)
                os.close(fd)
                # After we dump, we open a new dumpfile.  It is perfectly
                # possible this will hang.  But thats OK as we would only 
                # want to do another dump if we had at some point
                # somehow returned to a good state.
                fd = open_dumpfile()
        expect_good = reason is None

# Periodically stat a directory in the filesystem to ensure there is no
# vnode deadlock.  Note this behavior does not necessarily behave as desired
# if the filesystem supports shared locks and stat does not grab an exclusive
# lock.
#
# Periodically check to see if there are any lin lock or mds block lock local
# waiters that have been waiting for too long as well.
#
# This doesn't register a HUP handler so this should be unaffected when that
# signal is sent cluster wide.
def ping_thread(r, w, timeout):
    # HUPs are for the dump process.
    signal.signal(signal.SIGHUP, signal.SIG_IGN)
    os.close(r)

    gmp_infos_dump_threshold = 50

    while (True):
        ping = "p"

        # Check that /ifs isn't deadlocked.
        try:
            if misc.ifs_ready():
                os.stat(TESTFILE)
        except EnvironmentError as e:
            # Don't error out since we're specifically looking for a hang,
            # and this could just be something simple like a loss of quorum.
            # Do log the error though...
            syslog.syslog(syslog.LOG_ERR,
                    "Ping thread failed to stat %s, error: %d (%s)" %
                    (TESTFILE, e.errno, e.strerror))

        # Check that no lin lock and mds block lock local waiters have been
        # waiting for too long
        for name in ('efs.lin.lock.initiator.oldest_waiter',
                'efs.mds.block_lock.initiator.oldest_waiter'):
            try:
                oldest_waiter = misc.sysctlbyname(name)
                match = re.search(r"started = \d+\.\d+ \((\d+\.\d+) "
                                  "seconds ago\)", oldest_waiter)

                if match and float(match.group(1)) > timeout:
                    ping = "d"
                    syslog.syslog(syslog.LOG_NOTICE,
                            "Lock timeout: %s from %s" % (match.group(1), 
                            name))
            except misc.error as e:
                syslog.syslog(syslog.LOG_ERR,
                        "sysctlbyname failed on %s:%s" % (name, str(e)))

        # The braces are needed to force python to view the
        # single string as a tuple. Without them, the for loop
        # tries to iterate over the characters in the string.
        for name in (['efs.gmp.rtxn_time_since_checkpoint']):
            try:
                msec = misc.sysctlbyname(name)
                if msec / 1000 > timeout:
                    ping = "d"
                    syslog.syslog(syslog.LOG_NOTICE,
                            "Stall timeout: %s" % (name))
            except misc.error as e:
                syslog.syslog(syslog.LOG_ERR,
                        "sysctlbyname failed on %s:%s" % (name, str(e)))

        try:
            ninfos = misc.sysctlbyname('efs.gmp.num_infos')
            if ninfos >= gmp_infos_dump_threshold:
                ping = "d"
                gmp_infos_dump_threshold = gmp_infos_dump_threshold + 50
            elif ninfos < 10:
                gmp_infos_dump_threshold = 50
        except misc.error as e:
                syslog.syslog(syslog.LOG_ERR,
                    "sysctlbyname failed on efs.gmp.num_infos:%s" % (str(e)))

	# Check for long j_getblk requests
        if not hal.isAcceleratorClass() and misc.ifs_mounted():
            for name in (['efs.journal.oldest_buf_waiter']):
                try:
                    oldest_waiter = misc.sysctlbyname(name)
                    match = re.search(r"waiting (\d+\.\d+) seconds",
                            oldest_waiter)
                    if match and float(match.group(1)) > timeout:
                        ping = "d"
                        syslog.syslog(syslog.LOG_NOTICE,
                                "Buf timeout: %s from %s" % (match.group(1), 
                                name))
                except misc.error as e:
                    syslog.syslog(syslog.LOG_ERR,
                            "sysctlbyname failed on %s:%s" % (name, str(e)))

        try:
            os.write(w, ping)
        except OSError as e:
            if e.errno == errno.EPIPE:
                syslog.syslog(syslog.LOG_NOTICE, "Ping thread lost contact with"
                        " dump thread.  Closing ping thread.")
                sys.exit(0)
            else:
                raise
        time.sleep(PING_DELAY)
        
def open_dumpfile():
    try:
        fd = os.open(DUMPFILE, FILE_FLAGS)
    except IOError, e:
        syslog.syslog(syslog.LOG_ERR, "%s failed opening %s, error: %d (%s)" 
              % (prog, DUMPFILE, e.errno, e.strerror))
        sys.exit(1)

    # check if we need to save old dump
    old_file_contents = os.read(fd, 512)
    if (old_file_contents != ""):
        fd2 = os.dup(fd)
        f = os.fdopen(fd2)
        f.seek(0)
        line = f.readline()

        # If a valid dump was stored, save it to another file.
        if (line.startswith("LOCK TIMEOUT AT ") and line.endswith(" UTC\n")):
            line = line.replace("LOCK TIMEOUT AT ", "")
            line = line.replace(" UTC\n", "")
            now = time.localtime(int(line))
            timestamp = TIME_FMT % (now.tm_year, now.tm_mon, now.tm_mday, \
                                    now.tm_hour, now.tm_min, now.tm_sec)
            new_file = SAVED_DUMP_PREFIX + "%s" % timestamp + SAVED_DUMP_SUFFIX
            try:
                f_out = gzip.open(new_file + ".gz", 'wb')
                f.seek(0)
                f_out.writelines(f)
                f_out.close()
            except:
                shutil.copy(DUMPFILE, new_file)

        f.close()

        # If the file was valid, truncate whats left, if not valid, truncate
        # without copying.
        os.ftruncate(fd, 0)

        # Limit the number of dumped files to MAX_OLD_DUMPS.
        old_dumps = glob.glob(SAVED_DUMP_PREFIX + "*")
        if (len(old_dumps) > MAX_OLD_DUMPS):
            old_dumps.sort()
            os.unlink(old_dumps[0])
    return fd

def main():
    global fd
    prog = path.basename(sys.argv[0])

    syslog.openlog("isi_hangdump")

    # Protect from the OOM killer
    madvise(MADV_PROTECT)

    # Ensure the timeout period can be determined, otherwise this is all
    # useless.
    try:
        ufs_timeout = float(misc.sysctlbyname(ROOTLOCK_TIMEOUT))
    except misc.error as e:
        syslog.syslog(syslog.LOG_ERR, "%s failed calling %s, "
                "error: %d (%s)" % (prog, ROOTLOCK_TIMEOUT, e.errno, 
                e.strerror))
        sys.exit(1)

    if (len(sys.argv) == 3):
        ufs_timeout = float(sys.argv[2])

    # open the file before a deadlock to avoid blocking on it
    
    fd = open_dumpfile()
    if misc.osbuild().count("DEBUG") > 0:
        timeout = DEBUG_PERCENT_TIMEOUT * ufs_timeout
    else:
        timeout = RELEASE_PERCENT_TIMEOUT * ufs_timeout

    try:
        # Make a ping thread to stat / and a dump thread to print debug info
        # if it doesn't hear from the ping
        r, w = os.pipe()
        pid = os.fork()
    except OSError, e:
        syslog.syslog(syslog.LOG_ERR, "%s failed pipe or fork call, "
                "error: %d (%s)" % (prog, e.errno, e.strerror))
        sys.exit(1)

    try:
        if pid == 0:
            threadname = "Dump"
            dump_thread(r, w, timeout)
        else:
            threadname = "Ping"
            ping_thread(r, w, timeout)
               
    except Exception:
        syslog.syslog(syslog.LOG_ERR, "%s thread died unexpectedly:"
                % threadname)
        syslog.syslog(syslog.LOG_ERR, traceback.format_exc())
        sys.exit(1)


if __name__ == '__main__':
    try:
        daemon.startstop()
        main()
    except Exception:
        syslog.syslog(syslog.LOG_ERR, traceback.format_exc())
        sys.exit(1)

