# This Source Code Form is subject to the terms of the Mozilla Public
# License, v. 2.0. If a copy of the MPL was not distributed with this
# file, You can obtain one at http://mozilla.org/MPL/2.0/.

from __future__ import unicode_literals

from multiprocessing import current_process
from threading import current_thread, Lock
import json
import sys
import time
import traceback

from logtypes import Unicode, TestId, Status, SubStatus, Dict, List, Int, Any
from logtypes import log_action, convertor_registry

"""Structured Logging for recording test results.

Allowed actions, and subfields:
  suite_start
      tests  - List of test names

  suite_end

  test_start
      test - ID for the test
      path - Relative path to test (optional)

  test_end
      test - ID for the test
      status [PASS | FAIL | OK | ERROR |
              TIMEOUT | CRASH | ASSERT | SKIP] - test status
      expected [As for status] - Status that the test was expected to get,
                                 or absent if the test got the expected status
      extra - Dictionary of harness-specific extra information e.g. debug info

  test_status
      test - ID for the test
      subtest - Name of the subtest
      status [PASS | FAIL | TIMEOUT | NOTRUN | SKIP] - test status
      expected [As for status] - Status that the subtest was expected to get,
                                 or absent if the subtest got the expected status

  process_output
      process - PID of the process
      command - Command line of the process
      data - Output data from the process

  log
      level [CRITICAL | ERROR | WARNING |
             INFO | DEBUG] - level of the logging message
      message - Message to log

Subfields for all messages:
      action - the action type of the current message
      time - the timestamp in ms since the epoch of the log message
      thread - name for the thread emitting the message
      pid - id of the python process in which the logger is running
      source - name for the source emitting the message
      component - name of the subcomponent emitting the message
"""

_default_logger_name = None

def get_default_logger(component=None):
    """Gets the default logger if available, optionally tagged with component
    name. Will return None if not yet set

    :param component: The component name to tag log messages with
    """
    global _default_logger_name

    if not _default_logger_name:
        return None

    return StructuredLogger(_default_logger_name, component=component)

def set_default_logger(default_logger):
    """Sets the default logger to logger.

    It can then be retrieved with :py:func:`get_default_logger`

    Note that :py:func:`~mozlog.commandline.setup_logging` will
    set a default logger for you, so there should be no need to call this
    function if you're using setting up logging that way (recommended).

    :param default_logger: The logger to set to default.
    """
    global _default_logger_name

    _default_logger_name = default_logger.name

log_levels = dict((k.upper(), v) for v, k in
                  enumerate(["critical", "error", "warning", "info", "debug"]))

def log_actions():
    """Returns the set of actions implemented by mozlog."""
    return set(convertor_registry.keys())

class LoggerState(object):
    def __init__(self):
        self.handlers = []
        self.running_tests = set()
        self.suite_started = False
        self.component_states = {}

class ComponentState(object):
    def __init__(self):
        self.filter_ = None

class StructuredLogger(object):
    _lock = Lock()
    _logger_states = {}
    """Create a structured logger with the given name

    :param name: The name of the logger.
    :param component: A subcomponent that the logger belongs to (typically a library name)
    """

    def __init__(self, name, component=None):
        self.name = name
        self.component = component

        with self._lock:
            if name not in self._logger_states:
                self._logger_states[name] = LoggerState()

            if component not in self._logger_states[name].component_states:
                self._logger_states[name].component_states[component] = ComponentState()

        self._state = self._logger_states[name]
        self._component_state = self._state.component_states[component]

    def add_handler(self, handler):
        """Add a handler to the current logger"""
        self._state.handlers.append(handler)

    def remove_handler(self, handler):
        """Remove a handler from the current logger"""
        self._state.handlers.remove(handler)

    def send_message(self, topic, command, *args):
        """Send a message to each handler configured for this logger. This
        part of the api is useful to those users requiring dynamic control
        of a handler's behavior.

        :param topic: The name used by handlers to subscribe to a message.
        :param command: The name of the command to issue.
        :param args: Any arguments known to the target for specialized
                     behavior.
        """
        rv = []
        for handler in self._state.handlers:
            if hasattr(handler, "handle_message"):
                rv += handler.handle_message(topic, command, *args)
        return rv

    @property
    def handlers(self):
        """A list of handlers that will be called when a
        message is logged from this logger"""
        return self._state.handlers

    @property
    def component_filter(self):
        return self._component_state.filter_

    @component_filter.setter
    def component_filter(self, value):
        self._component_state.filter_ = value

    def log_raw(self, raw_data):
        if "action" not in raw_data:
            raise ValueError

        action = raw_data["action"]
        converted_data = convertor_registry[action].convert_known(**raw_data)
        for k, v in raw_data.iteritems():
            if k not in converted_data:
                converted_data[k] = v

        data = self._make_log_data(action, converted_data)

        if action in ("test_status", "test_end"):
            if (data["expected"] == data["status"] or
                data["status"] == "SKIP" or
                "expected" not in raw_data):
                del data["expected"]

        if not self._ensure_suite_state(action, data):
            return

        self._handle_log(data)

    def _log_data(self, action, data=None):
        if data is None:
            data = {}

        log_data = self._make_log_data(action, data)
        self._handle_log(log_data)

    def _handle_log(self, data):
        with self._lock:
            if self.component_filter:
                data = self.component_filter(data)
                if data is None:
                    return

            for handler in self.handlers:
                handler(data)

    def _make_log_data(self, action, data):
        all_data = {"action": action,
                    "time": int(time.time() * 1000),
                    "thread": current_thread().name,
                    "pid": current_process().pid,
                    "source": self.name}
        if self.component:
            all_data['component'] = self.component
        all_data.update(data)
        return all_data

    def _ensure_suite_state(self, action, data):
        if action == 'suite_start':
            if self._state.suite_started:
                self.error("Got second suite_start message before suite_end. " +
                           "Logged with data: {}".format(json.dumps(data)))
                return False
            self._state.suite_started = True
        elif action == 'suite_end':
            if not self._state.suite_started:
                self.error("Got suite_end message before suite_start. " +
                           "Logged with data: {}".format(json.dumps(data)))
                return False
            self._state.suite_started = False
        return True

    @log_action(List("tests", Unicode),
                Dict("run_info", default=None, optional=True),
                Dict("version_info", default=None, optional=True),
                Dict("device_info", default=None, optional=True))
    def suite_start(self, data):
        """Log a suite_start message

        :param list tests: Test identifiers that will be run in the suite.
        :param dict run_info: Optional information typically provided by mozinfo.
        :param dict version_info: Optional target application version information provided by mozversion.
        :param dict device_info: Optional target device information provided by mozdevice.
        """
        if not self._ensure_suite_state('suite_start', data):
            return

        self._log_data("suite_start", data)

    @log_action()
    def suite_end(self, data):
        """Log a suite_end message"""
        if not self._ensure_suite_state('suite_end', data):
            return

        self._log_data("suite_end")

    @log_action(TestId("test"),
                Unicode("path", default=None, optional=True))
    def test_start(self, data):
        """Log a test_start message

        :param test: Identifier of the test that will run.
        :param path: Path to test relative to some base (typically the root of
                     the source tree).
        """
        if not self._state.suite_started:
            self.error("Got test_start message before suite_start for test %s" %
                       data["test"])
            return
        if data["test"] in self._state.running_tests:
            self.error("test_start for %s logged while in progress." %
                       data["test"])
            return
        self._state.running_tests.add(data["test"])
        self._log_data("test_start", data)

    @log_action(TestId("test"),
                Unicode("subtest"),
                SubStatus("status"),
                SubStatus("expected", default="PASS"),
                Unicode("message", default=None, optional=True),
                Unicode("stack", default=None, optional=True),
                Dict("extra", default=None, optional=True))
    def test_status(self, data):
        """
        Log a test_status message indicating a subtest result. Tests that
        do not have subtests are not expected to produce test_status messages.

        :param test: Identifier of the test that produced the result.
        :param subtest: Name of the subtest.
        :param status: Status string indicating the subtest result
        :param expected: Status string indicating the expected subtest result.
        :param message: String containing a message associated with the result.
        :param stack: a stack trace encountered during test execution.
        :param extra: suite-specific data associated with the test result.
        """

        if (data["expected"] == data["status"] or
            data["status"] == "SKIP"):
            del data["expected"]

        if data["test"] not in self._state.running_tests:
            self.error("test_status for %s logged while not in progress. "
                       "Logged with data: %s" % (data["test"], json.dumps(data)))
            return

        self._log_data("test_status", data)

    @log_action(TestId("test"),
                Status("status"),
                Status("expected", default="OK"),
                Unicode("message", default=None, optional=True),
                Unicode("stack", default=None, optional=True),
                Dict("extra", default=None, optional=True))
    def test_end(self, data):
        """
        Log a test_end message indicating that a test completed. For tests
        with subtests this indicates whether the overall test completed without
        errors. For tests without subtests this indicates the test result
        directly.

        :param test: Identifier of the test that produced the result.
        :param status: Status string indicating the test result
        :param expected: Status string indicating the expected test result.
        :param message: String containing a message associated with the result.
        :param stack: a stack trace encountered during test execution.
        :param extra: suite-specific data associated with the test result.
        """

        if (data["expected"] == data["status"] or
             data["status"] == "SKIP"):
            del data["expected"]

        if data["test"] not in self._state.running_tests:
            self.error("test_end for %s logged while not in progress. "
                       "Logged with data: %s" % (data["test"], json.dumps(data)))
        else:
            self._state.running_tests.remove(data["test"])
            self._log_data("test_end", data)

    @log_action(Unicode("process"),
                Unicode("data"),
                Unicode("command", default=None, optional=True))
    def process_output(self, data):
        """Log output from a managed process.

        :param process: A unique identifier for the process producing the output
                        (typically the pid)
        :param data: The output to log
        :param command: A string representing the full command line used to start
                        the process.
        """
        self._log_data("process_output", data)

    @log_action(Unicode("process", default=None),
                Unicode("signature", default="[Unknown]"),
                TestId("test", default=None, optional=True),
                Unicode("minidump_path", default=None, optional=True),
                Unicode("minidump_extra", default=None, optional=True),
                Int("stackwalk_retcode", default=None, optional=True),
                Unicode("stackwalk_stdout", default=None, optional=True),
                Unicode("stackwalk_stderr", default=None, optional=True),
                List("stackwalk_errors", Unicode, default=None))
    def crash(self, data):
        if data["stackwalk_errors"] is None:
            data["stackwalk_errors"] = []

        self._log_data("crash", data)

    @log_action(Unicode("primary", default=None),
                List("secondary", Unicode, default=None))
    def valgrind_error(self, data):
        self._log_data("valgrind_error", data)

    @log_action(Unicode("process"),
                Unicode("command", default=None, optional=True))
    def process_start(self, data):
        """Log start event of a process.

        :param process: A unique identifier for the process producing the
                        output (typically the pid)
        :param command: A string representing the full command line used to
                        start the process.
        """
        self._log_data("process_start", data)

    @log_action(Unicode("process"),
                Int("exitcode"),
                Unicode("command", default=None, optional=True))
    def process_exit(self, data):
        """Log exit event of a process.

        :param process: A unique identifier for the process producing the
                        output (typically the pid)
        :param exitcode: the exit code
        :param command: A string representing the full command line used to
                        start the process.
        """
        self._log_data("process_exit", data)


def _log_func(level_name):
    @log_action(Unicode("message"),
                Any("exc_info", default=False))
    def log(self, data):
        exc_info = data.pop("exc_info", None)
        if exc_info:
            if not isinstance(exc_info, tuple):
                exc_info = sys.exc_info()
            if exc_info != (None, None, None):
                bt = traceback.format_exception(*exc_info)
                data["stack"] = u"\n".join(bt)

        data["level"] = level_name
        self._log_data("log", data)

    log.__doc__ = """Log a message with level %s

:param message: The string message to log
:param exc_info: Either a boolean indicating whether to include a traceback
                 derived from sys.exc_info() or a three-item tuple in the
                 same format as sys.exc_info() containing exception information
                 to log.
""" % level_name
    log.__name__ = str(level_name).lower()
    return log


# Create all the methods on StructuredLog for debug levels
for level_name in log_levels:
    setattr(StructuredLogger, level_name.lower(), _log_func(level_name))


class StructuredLogFileLike(object):
    """Wrapper for file-like objects to redirect writes to logger
    instead. Each call to `write` becomes a single log entry of type `log`.

    When using this it is important that the callees i.e. the logging
    handlers do not themselves try to write to the wrapped file as this
    will cause infinite recursion.

    :param logger: `StructuredLogger` to which to redirect the file write operations.
    :param level: log level to use for each write.
    :param prefix: String prefix to prepend to each log entry.
    """
    def __init__(self, logger, level="info", prefix=None):
        self.logger = logger
        self.log_func = getattr(self.logger, level)
        self.prefix = prefix

    def write(self, data):
        if data.endswith("\n"):
            data = data[:-1]
        if data.endswith("\r"):
            data = data[:-1]
        if self.prefix is not None:
            data = "%s: %s" % (self.prefix, data)
        self.log_func(data)

    def flush(self):
        pass