"""
Utility functions.

Includes:
    - Logging decorators
    - Logging functions log_start() and log_end()
"""
__author__ = 'Dan Gunter <dkgunter@lbl.gov>'
__date__ = '8/4/15'

from collections import deque
from datetime import datetime
import logging
import logging.config
import os
import six
import time

ENTRY_MESSAGE = '{timestamp} {func_name}.begin {kvp}'
EXIT_MESSAGE = '{timestamp} {func_name}.end {dur} {kvp}'
EVENT_MESSAGE = '{timestamp} {func_name} {kvp}'

DEFAULT_LEVEL = logging.INFO
logformat = '%(levelname)s %(message)s'

g_running_nosetests = None

def get_logger(name=''):
    global g_running_nosetests
    if not name.startswith('doekbase'):
        if name == '':
            name = 'doekbase'
        else:
            name = 'doekbase.' + name
    # If we are running in nose, nest under there so nose -v options
    # can apply to us. Cache the result of checking for nose in a global var.
    if g_running_nosetests is None:  # haven't checked yet
         g_running_nosetests = 'nose' in logging.root.manager.loggerDict
    if g_running_nosetests:
         name = 'nose.' + name
    # create logger
    logger = logging.getLogger(name)
    logger.propagate = 1
    return logger

def basic_config(level=logging.INFO):
    log = get_logger()
    log.setLevel(level)
    h = logging.StreamHandler()
    h.setFormatter(logging.Formatter(logformat))
    log.addHandler(h)
    return log

class Timer(object):
    def __init__(self):
        self._timings = []
        self._start = time.time()

    def __enter__(self):
        self._start = time.time()

    def __exit__(self, exc_type, exc_val, exc_tb):
        t = time.time()
        dt, self._start = t - self._start, t
        self._timings.append(dt)

    def pop(self):
        return self._timings.pop()

#TODO turn example below into a test
def logged(logger, log_level=logging.INFO, log_name=None, **kw):
    """Wrap a method/function in a log start/end message.

    Example usage. Given the following code::

        @logged(g_log, log_name='hello')
        def hello_world(self, what):
            sys.stderr.write("hello {} world\n". format(what))

    Then the statement ``hello_world("dumb")`` should print output like::

        2015-08-26T01:02:30.123456 hello.begin
        hello dumb world
        2015-08-26T01:02:30.654321 hello.end
    """
    def real_decorator(method, logger_name=logger.name):
        # choose name for logged event
        func_name = log_name or method.__name__
        full_name = logger_name + '.' + func_name
        # format any key/value pairs
        kvp_str = format_kvp(kw, ',') if kw else ''

        # create wrapper
        def method_wrapper(self, *args, **kwds):
            t0 = log_start(logger, full_name, level=log_level, kvp=kvp_str)
            returnval = method(self, *args, **kwds)
            log_end(logger, t0, full_name, level=log_level, kvp=kvp_str)
            return returnval
        # return wrapper
        return method_wrapper

    return real_decorator

def log_start(logger, func_name, level=None, fmt=None, kvp=None):
    t0 = time.time()
    kvp_str = format_kvp(kvp, ',') if kvp else ''
    d = dict(timestamp=format_timestamp(t0),
             func_name=func_name, kvp=kvp_str)
    fmt = fmt or ENTRY_MESSAGE
    msg = fmt.format(**d)
    if level is None:
        level = DEFAULT_LEVEL
    logger.log(level, msg)
    return t0

def log_event(logger, func_name, level=None, fmt=None, kvp=None):
    t0 = time.time()
    kvp_str = format_kvp(kvp, ',') if kvp else ''
    d = dict(timestamp=format_timestamp(t0),
             func_name=func_name, kvp=kvp_str)
    fmt = fmt or EVENT_MESSAGE
    msg = fmt.format(**d)
    if level is None:
        level = DEFAULT_LEVEL
    logger.log(level, msg)
    return t0

def log_end(logger, t0, func_name, level=None, fmt=None, status_code=0, kvp=None):
    t1 = time.time()