#!/usr/bin/env python -tt
# -*- coding: utf-8 -*-

###
###  pygster
###
###  Tails a log and applies a log parser (that knows what to do with specific)
###  types of entries in the log, then reports metrics to Graphite.
###
###  Usage:
###
###    $ pygster [options] parser logfile
###
###  Help:
###
###    $ pygster -h


import fcntl
import logging.handlers
import math
import optparse
import os
import re
import socket
import stat
import sys
import time
import traceback

pygster_directory = os.path.dirname(os.path.dirname(os.path.realpath(__file__)))
sys.path.append(pygster_directory)

import pygtail

# Local dependencies
from pygster.pygster_helper import PygsterParsingException, LockingError


# Globals
log_dir = os.path.join(pygster_directory, "log")
state_dir = os.path.join(pygster_directory, "run")

script_start_time = time.time()


# Command-line options and parsing.
cmdline = optparse.OptionParser(usage="usage: %prog [options] parser logfile",
    description="Tail a log file and filter each line to generate metrics that can be sent to common monitoring packages.")
cmdline.add_option('--metric-prefix', '-p', action='store',
                    help='Add prefix to all published metrics. This is for people that may multiple instances of same service on same host.',
                    default='')
cmdline.add_option('--metric-suffix', '-x', action='store',
                    help='Add suffix to all published metrics. This is for people that may add suffix at the end of their metrics.',
                    default=None)
cmdline.add_option('--parser-help', action='store_true',
                    help='Print usage and options for the selected parser')
cmdline.add_option('--parser-options', action='store',
                    help='Options to pass to the pygster parser such as "-o VALUE --option2 VALUE". These are parser-specific and passed directly to the parser.')
cmdline.add_option('--graphite-host', action='store',
                    help='Hostname and port for Graphite collector, e.g. graphite.example.com:2003')
cmdline.add_option('--statsd-host', action='store',
                    help='Hostname and port for statsd collector, e.g. statsd.example.com:8125')
cmdline.add_option('--state-dir', '-s', action='store', default=state_dir,
                    help='Where to store the logtail state file.  Default location %s' % state_dir)
cmdline.add_option('--log-dir', '-l', action='store', default=log_dir,
                    help='Where to store the pygster logfile.  Default location %s' % log_dir)
cmdline.add_option('--output', '-o', action='append',
                   choices=('graphite', 'stdout', 'statsd'),
                   help="Where to send metrics (can specify multiple times). Choices are 'graphite', 'statsd', or 'stdout'.")
cmdline.add_option('--stdout-separator', action='store', default=".", dest="stdout_separator",
                    help='Seperator between prefix/suffix and name for stdout. Default is \"%default\".')
cmdline.add_option('--dry-run', '-d', action='store_true', default=False,
                    help='Parse the log file but send stats to standard output.')
cmdline.add_option('--debug', '-D', action='store_true', default=False,
                    help='Provide more verbose logging for debugging.')
options, arguments = cmdline.parse_args()

if options.parser_help:
    options.parser_options = '-h'

if not len(arguments) == 2:
    cmdline.print_help()
    cmdline.error("Supply at least two arguments: parser and logfile.")
if not options.output:
    cmdline.print_help()
    cmdline.error(
        "Supply where the data should be sent with -o (or --output).")
if 'graphite' in options.output and not options.graphite_host:
    cmdline.print_help()
    cmdline.error(
        "You must supply --graphite-host when using "
        "'graphite' as an output type."
    )

class_name = arguments[0]
if class_name.find('.') == -1:
    # If it's a single name, find it in the base pygster package
    class_name = 'pygster.parsers.%s.%s' % (class_name, class_name)
log_file = arguments[1]
state_dir = options.state_dir
log_dir = options.log_dir


# Logging infrastructure for use throughout the script.
# Uses appending log file, rotated at 100 MB, keeping 5.
if not os.path.isdir(log_dir):
    os.mkdir(log_dir)

logger = logging.getLogger('pygster')
formatter = logging.Formatter('%(asctime)s %(levelname)-8s %(message)s')
hdlr = logging.handlers.RotatingFileHandler(
    '%s/pygster.log' % log_dir, 'a', 100 * 1024 * 1024, 5)
hdlr.setFormatter(formatter)
logger.addHandler(hdlr)
logger.setLevel(logging.INFO)

if options.debug:
    logger.setLevel(logging.DEBUG)


def submit_stats(parser, duration, options):
    logger.debug("submit_stats() options.output=%s" % options.output)
    metrics = parser.get_state(duration)

    if 'graphite' in options.output:
        submit_graphite(metrics, options)
    if 'stdout' in options.output:
        submit_stdout(metrics, options)
    if 'statsd' in options.output:
        submit_statsd(metrics, options)


def submit_stdout(metrics, options):
    for metric in metrics:
        if options.metric_prefix:
            metric.name = options.metric_prefix + options.stdout_separator + metric.name
        if options.metric_suffix:
            metric.name = metric.name + options.stdout_separator + options.metric_suffix
        print "%s %s %s" %(metric.timestamp, metric.name, metric.value)


def submit_graphite(metrics, options):
    if not re.match("^[\w\.\-]+\:\d+$", options.graphite_host):
        raise Exception, "Invalid host:port found for Graphite: '%s'" % options.graphite_host

    if not options.dry_run:
        host = options.graphite_host.split(':')
        s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
        s.connect((host[0], int(host[1])))

    try:
        for metric in metrics:

            if options.metric_prefix:
                metric.name = options.metric_prefix + "." + metric.name
            if options.metric_suffix:
                metric.name = metric.name + "." + options.metric_suffix

            metric_string = "%s %s %s" % (metric.name, metric.value, metric.timestamp)
            logger.debug("Submitting Graphite metric: %s" % metric_string)

            if not options.dry_run:
                s.sendall("%s\n" % metric_string)
            else:
                print "%s %s" % (options.graphite_host, metric_string)
    finally:
        if not options.dry_run:
            s.close()

def submit_statsd(metrics, addr):
    if not options.dry_run:
        host = options.statsd_host.split(':')

    for metric in metrics:
        if (options.metric_prefix != ""):
            metric.name = options.metric_prefix + '.' + metric.name
        if (options.metric_suffix is not None):
            metric.name = metric.name + '.' + options.metric_suffix
        metric_string = "%s:%s|%s" % (metric.name, metric.value, metric.metric_type)
        logger.debug("Submitting statsd metric: %s" % metric_string)

        if not options.dry_run:
            udp_sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
            udp_sock.sendto(metric_string, (host[0], int(host[1])))
        else:
            print "%s %s" % (options.statsd_host, metric_string)


def start_locking(lockfile_name):
    """Acquire a lock via a provided lockfile filename."""
    if os.path.exists(lockfile_name):
        raise LockingError('Lock file already exists.')

    f = open(lockfile_name, 'w')

    try:
        fcntl.flock(f, fcntl.LOCK_EX | fcntl.LOCK_NB)
        f.write(str(os.getpid()))
    except IOError, ex:
        # Would be better to also check the pid in the lock file and remove the
        # lock file if that pid no longer exists in the process table.
        logger.exception(ex)
        raise LockingError("Cannot acquire pygster lock (%s)", lockfile_name)

    logger.debug('Locking successful.')
    return f


def end_locking(lockfile_fd, lockfile_name):
    """ Release a lock via a provided file descriptor. """
    try:
        fcntl.flock(lockfile_fd, fcntl.LOCK_UN | fcntl.LOCK_NB)
    except IOError, e:
        raise LockingError("Cannot release pygster lock (%s)" % lockfile_name)

    try:
        os.unlink(lockfile_name)
    except OSError, e:
        raise LockingError("Cannot unlink %s" % lockfile_name)

    logger.debug("Unlocking successful")
    return


def main():

    dirsafe_logfile = log_file.replace('/', '-')
    logtail_state_file = os.path.join(state_dir, '%s%s.state' % (class_name, dirsafe_logfile))
    logtail_lock_file  = os.path.join(state_dir, '%s%s.lock' % (class_name, dirsafe_logfile))

    logger.info("Executing parser %s on logfile %s", class_name, log_file)
    logger.debug("Using state file %s", logtail_state_file)

    # Import and instantiate the class from the module passed in.
    module_name, parser_name = class_name.rsplit('.', 1)
    module = __import__(module_name, globals(), locals(), [parser_name])
    parser = getattr(module, parser_name)(option_string=options.parser_options)

    # Check for lock file so we don't run multiple copies of the same parser
    # simultaneuosly. This will happen if the log parsing takes more time than
    # the cron period, which is likely on first run if the logfile is huge.
    try:
        lockfile = start_locking(logtail_lock_file)
    except LockingError, e:
        logger.warning("Failed to get lock. Is another instance of pygster running?")
        sys.exit(1)

    # Get input to parse.
    try:

        # Read the age of the state file to see how long it's been since we last
        # ran. Replace the state file if it has gone missing. While we are her,
        # touch the state file to reset the time in case logtail doesn't
        # find any new lines (and thus won't update the statefile).
        try:
            state_file_age = os.stat(logtail_state_file)[stat.ST_MTIME]

            # Calculate now() - state file age to determine check duration.
            duration = math.floor(time.time()) - math.floor(state_file_age)
            logger.debug("Setting duration to %s seconds.", duration)

        except OSError, e:
            logger.info('Writing new state file and exiting. (Was either first run, or state file went missing.)')
            input = pygtail.Pygtail(log_file, logtail_state_file)
            # XXX: calling internal method
            input._update_offset_file()
            del input
            end_locking(lockfile, logtail_lock_file)
            sys.exit(0)

        input = pygtail.Pygtail(
            log_file, logtail_state_file, copytruncate=True)

    except SystemExit, e:
        raise e

    except Exception, e:
        logger.error('Failed to tail file to get log data.')
        logger.exception(e)
        end_locking(lockfile, logtail_lock_file)
        raise e

    # Parse each line from input, then send all stats to their collectors.
    try:
        for line in input:
            try:
                parser.parse_line(line)
            except PygsterParsingException, e:
                # This should only catch recoverable exceptions (of which there
                # aren't any at the moment).
                logger.exception(e)

        submit_stats(parser, duration, options)

    except Exception, e:
        logger.exception(e)
        end_locking(lockfile, logtail_lock_file)
        raise e

    # Log the execution time
    exec_time = round(time.time() - script_start_time, 1)
    logger.info("Total execution time: %s seconds.", exec_time)

    # Set mtime and atime for the state file to the startup time of the script
    # so that the cron interval is not thrown off by parsing a large number of
    # log entries.
    os.utime(logtail_state_file, (math.floor(script_start_time), math.floor(script_start_time)))

    end_locking(lockfile, logtail_lock_file)

    # try and remove the lockfile one last time, but it's a valid state that it's already been removed.
    try:
        end_locking(lockfile, logtail_lock_file)
    except Exception, e:
        pass


if __name__ == '__main__':
    sys.exit(main())
