"""
Common narrative logging functions.


To log an event with proper metadata and formatting use 'log_event':

You can also do free-form logs, but these will be ignored by
most upstream consumers.

"""
__author__ = 'Dan Gunter <dkgunter@lbl.gov>'
__date__ = '2014-07-31'

import collections
import logging
from logging import handlers
import os
import threading
import time
# Local
from .util import kbase_env
from . import log_proxy
from .log_common import format_event

## Constants

KBASE_TMP_DIR = "/tmp"
KBASE_TMP_LOGFILE = os.path.join(KBASE_TMP_DIR, "kbase-narrative.log")

# env var with location of proxy config file
KBASE_PROXY_ENV = 'KBASE_PROXY_CONFIG'

## Internal logging

_log = logging.getLogger("tornado.application")

# WTF is going on logging
#def _logdbg(m):
#    open("/tmp/wtf", "a").write(m + "\n")

## External functions

def get_logger(name="", init=False):
    """Get a given KBase log obj.

    :param name: name (a.b.c) of the logging namespace, which may be
                 relative or absolute (starting with 'biokbase.'), or
                 empty in which case the 'biokbase' logger is returned
    :param init: If true, re-initialize the file/socket log handlers
    :return: Log object
    :rtype: LogAdapter
    """
    if init:
        reset_handlers()
    return logging.getLogger(_kbase_log_name(name))

def log_event(log, event, mapping):
    """Log an event and a mapping.

    For example::

        log_event(_log, "collision", {"who":"unstoppable force",
                  "with":"immovable object", "where":"kbase"})
    """
    msg = format_event(event, mapping)
    log.info(msg)

## Internal functions and classes

def _kbase_log_name(name):
    """Smarter name of KBase logger."""
    # no name => root
    if not name:
        return "biokbase"
    # absolute name
    if name.startswith("biokbase."):
        return name
    # relative name
    return "biokbase." + name

def _has_handler_type(log, type_):
    return any(map(lambda h: isinstance(h, type_), log.handlers))

## Custom handlers

class BufferedSocketHandler(handlers.SocketHandler):
    """Buffer up messages to a socket, sending them asynchronously.
    Starts a separate thread to pull messages off and send them.
    Ignores any messages that did not come from `log_event()`, above.
    """
    def __init__(self, *args):
        handlers.SocketHandler.__init__(self, *args)
        self._dbg = _log.isEnabledFor(logging.DEBUG)
        if self._dbg:
            _log.debug("Created SocketHandler with args = {}".format(args))
        self.buf = collections.deque([], 100)
        self.buf_lock = threading.Lock()
        # start thread to send data from buffer
        self.thr = threading.Thread(target=self.emitter)
        self.thr.daemon = True
        self._stop = False
        self.extra = {}
        self.thr.start()

    def close(self):
        if self.thr:
            self._stop = True
            self.thr.join()
            self.thr = None
        handlers.SocketHandler.close(self)

    def emitter(self):
        while not self._stop:
            try:
                self.buf_lock.acquire()
                item = self.buf.popleft()
                if not self._emit(item):
                    self.buf.appendleft(item)
                    self.buf_lock.release()
                    time.sleep(0.1)
                else:
                    self.buf_lock.release()
            except IndexError:
                self.buf_lock.release()
                time.sleep(0.1)

    def emit(self, record):
        if self._skip(record):
            return
        # stuff 'extra' from environment into record
        #_logdbg("@@ stuffing into record: {}".format(kbase_env))
        record.__dict__.update(kbase_env)
        if 'auth_token' in record.__dict__:
            del record.__dict__['auth_token']
        self.buf_lock.acquire()
        try:
            self.buf.append(record)
        finally:
            self.buf_lock.release()

    def _skip(self, record):
        """Return True if this record should not go to a socket"""
        # Do not forward records that didn't get logged through
        # kblogging.log_event
        if record.funcName != 'log_event':
            if self._dbg:
                _log.debug("Skip: funcName {} != log_event"
                           .format(record.funcName))
            return

    def _emit(self, record):