# This file is part of Radicale - CalDAV and CardDAV server
# Copyright © 2011-2017 Guillaume Ayoub
# Copyright © 2017-2023 Unrud <unrud@outlook.com>
# Copyright © 2024-2026 Peter Bieringer <pb@bieringer.de>
#
# This library is free software: you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# This library is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with Radicale.  If not, see <http://www.gnu.org/licenses/>.

"""
Functions to set up Python's logging facility for Radicale's WSGI application.

Log messages are sent to the first available target of:

  - Error stream specified by the WSGI server in "wsgi.errors"
  - ``sys.stderr``

"""

import contextlib
import io
import ipaddress
import logging
import os
import re
import socket
import struct
import sys
import threading
import time
from functools import partial, partialmethod
from typing import (TYPE_CHECKING, Any, Callable, ClassVar, Dict, Iterator,
                    Mapping, Optional, Tuple, Union, cast)

from radicale import types

LOGGER_NAME: str = "radicale"
LOGGER_FORMATS: Mapping[str, str] = {
    "verbose": "[%(asctime)s] [%(ident)s] [%(levelname)s] %(message)s",
    "journal": "[%(ident)s] [%(levelname)s] %(message)s",
}
DATE_FORMAT: str = "%Y-%m-%d %H:%M:%S %z"

LOG_CONDITION_TOKEN: dict = {"method": "str",
                             "path": "str",
                             "useragent": "str",
                             "host": "ipaddress",
                             "login": "str",
                             "status": "int",
                             }
LOG_CONDITION_CONDITION: list = ["match", "value"]
LOG_CONDITION_MATCH_STR: list = ["startswith", "endswith", "equal", "re", "==", "="]
LOG_CONDITION_MATCH_INT: list = ["=", ">", "<", "<=", ">=", "equal", "==", "<>", "!="]
LOG_CONDITION_MATCH_IPADDRESS: list = ["==", "equal", "=", "<>", "!="]
LOG_CONDITION_MATCH_IPNETWORK: list = ["included", "excluded", "incl", "excl"]

LOG_LEVEL_OPTIONS: list = ["trace", "debug", "info", "notice", "warning", "error", "critical", "alert"]

LOG_LEVEL_TRACE: int = 5
LOG_LEVEL_NOTICE: int = 25
LOG_LEVEL_ALERT: int = 55

logging.addLevelName(LOG_LEVEL_TRACE, "TRACE")
logging.addLevelName(LOG_LEVEL_NOTICE, "NOTICE")
logging.addLevelName(LOG_LEVEL_ALERT, "ALERT")

setattr(logging, "TRACE", LOG_LEVEL_TRACE)
setattr(logging, "NOTICE", LOG_LEVEL_NOTICE)
setattr(logging, "ALERT", LOG_LEVEL_ALERT)

logging.__all__ += ['TRACE', 'NOTICE', 'ALERT']

setattr(logging, "trace", partial(logging.log, LOG_LEVEL_TRACE))
setattr(logging, "notice", partial(logging.log, LOG_LEVEL_NOTICE))
setattr(logging, "alert", partial(logging.log, LOG_LEVEL_ALERT))

setattr(logging.getLoggerClass(), "trace", partialmethod(logging.Logger.log, LOG_LEVEL_TRACE))
setattr(logging.getLoggerClass(), "notice", partialmethod(logging.Logger.log, LOG_LEVEL_NOTICE))
setattr(logging.getLoggerClass(), "alert", partialmethod(logging.Logger.log, LOG_LEVEL_ALERT))


class RadicaleLogger(logging.Logger):
    if TYPE_CHECKING:
        pass
        # reuse similar types
        trace = logging.Logger.debug
        notice = logging.Logger.info
        alert = logging.Logger.critical
    else:
        def trace(self, msg, *args, **kwargs):
            if self.isEnabledFor(LOG_LEVEL_TRACE):
                self._log(LOG_LEVEL_TRACE, msg, args, **kwargs)

        def notice(self, msg, *args, **kwargs):
            if self.isEnabledFor(LOG_LEVEL_NOTICE):
                self._log(LOG_LEVEL_NOTICE, msg, args, **kwargs)

        def alert(self, msg, *args, **kwargs):
            if self.isEnabledFor(LOG_LEVEL_ALERT):
                self._log(LOG_LEVEL_ALERT, msg, args, **kwargs)


logger = cast(RadicaleLogger, logging.getLogger(LOGGER_NAME))


class RemoveTracebackFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.exc_info = None
        return True


class PassTRACETOKENFilter(logging.Filter):
    def __init__(self, trace_filter: str):
        super().__init__()
        self.trace_filter = trace_filter

    def filter(self, record: logging.LogRecord) -> bool:
        if record.levelno == LOG_LEVEL_TRACE:
            if record.msg.startswith(self.trace_filter):
                return True
            else:
                return False
        else:
            return True


REMOVE_TRACEBACK_FILTER: logging.Filter = RemoveTracebackFilter()


class IdentLogRecordFactory:
    """LogRecordFactory that adds ``ident`` attribute."""

    def __init__(self, upstream_factory: Callable[..., logging.LogRecord]
                 ) -> None:
        self._upstream_factory = upstream_factory

    def __call__(self, *args: Any, **kwargs: Any) -> logging.LogRecord:
        record = self._upstream_factory(*args, **kwargs)
        ident = ("%d" % record.process if record.process is not None
                 else record.processName or "unknown")
        tid = None
        if record.thread is not None:
            if record.thread != threading.main_thread().ident:
                ident += "/%s" % (record.threadName or "unknown")
            if (sys.version_info >= (3, 8) and
                    record.thread == threading.get_ident()):
                try:
                    tid = threading.get_native_id()
                except AttributeError:
                    # so far function not existing e.g. on SunOS
                    # see also https://docs.python.org/3/library/threading.html#threading.get_native_id
                    tid = None

        record.ident = ident  # type:ignore[attr-defined]
        record.tid = tid  # type:ignore[attr-defined]
        return record


class ThreadedStreamHandler(logging.Handler):
    """Sends logging output to the stream registered for the current thread or
       ``sys.stderr`` when no stream was registered."""

    terminator: ClassVar[str] = "\n"

    _streams: Dict[int, types.ErrorStream]
    _journal_stream_id: Optional[Tuple[int, int]]
    _journal_socket: Optional[socket.socket]
    _journal_socket_failed: bool
    _formatters: Mapping[str, logging.Formatter]
    _formatter: Optional[logging.Formatter]

    def __init__(self, format_name: Optional[str] = None) -> None:
        super().__init__()
        self._streams = {}
        self._journal_stream_id = None
        with contextlib.suppress(TypeError, ValueError):
            dev, inode = os.environ.get("JOURNAL_STREAM", "").split(":", 1)
            self._journal_stream_id = (int(dev), int(inode))
        self._journal_socket = None
        self._journal_socket_failed = False
        self._formatters = {name: logging.Formatter(fmt, DATE_FORMAT)
                            for name, fmt in LOGGER_FORMATS.items()}
        self._formatter = (self._formatters[format_name]
                           if format_name is not None else None)

    def _get_formatter(self, default_format_name: str) -> logging.Formatter:
        return self._formatter or self._formatters[default_format_name]

    def _detect_journal(self, stream: types.ErrorStream) -> bool:
        if not self._journal_stream_id or not isinstance(stream, io.IOBase):
            return False
        try:
            stat = os.fstat(stream.fileno())
        except OSError:
            return False
        return self._journal_stream_id == (stat.st_dev, stat.st_ino)

    @staticmethod
    def _encode_journal(data: Mapping[str, Optional[Union[str, int]]]
                        ) -> bytes:
        msg = b""
        for key, value in data.items():
            if value is None:
                continue
            keyb = key.encode()
            valueb = str(value).encode()
            if b"\n" in valueb:
                msg += (keyb + b"\n" +
                        struct.pack("<Q", len(valueb)) + valueb + b"\n")
            else:
                msg += keyb + b"=" + valueb + b"\n"
        return msg

    def _try_emit_journal(self, record: logging.LogRecord) -> bool:
        if not self._journal_socket:
            # Try to connect to systemd journal socket
            if self._journal_socket_failed or not hasattr(socket, "AF_UNIX"):
                return False
            journal_socket = None
            try:
                journal_socket = socket.socket(
                    socket.AF_UNIX, socket.SOCK_DGRAM)
                journal_socket.connect("/run/systemd/journal/socket")
            except OSError as e:
                self._journal_socket_failed = True
                if journal_socket:
                    journal_socket.close()
                # Log after setting `_journal_socket_failed` to prevent loop!
                logger.error("Failed to connect to systemd journal: %s",
                             e, exc_info=True)
                return False
            self._journal_socket = journal_socket

        priority = {"TRACE": 7,
                    "DEBUG": 7,
                    "INFO": 6,
                    "NOTICE": 5,
                    "WARNING": 4,
                    "ERROR": 3,
                    "CRITICAL": 2,
                    "ALERT": 1}.get(record.levelname, 4)
        timestamp = time.strftime("%Y-%m-%dT%H:%M:%S.%%03dZ",
                                  time.gmtime(record.created)) % record.msecs
        data = {"PRIORITY": priority,
                "TID": cast(Optional[int], getattr(record, "tid", None)),
                "SYSLOG_IDENTIFIER": record.name,
                "SYSLOG_FACILITY": 1,
                "SYSLOG_PID": record.process,
                "SYSLOG_TIMESTAMP": timestamp,
                "CODE_FILE": record.pathname,
                "CODE_LINE": record.lineno,
                "CODE_FUNC": record.funcName,
                "MESSAGE": self._get_formatter("journal").format(record)}
        self._journal_socket.sendall(self._encode_journal(data))
        return True

    def emit(self, record: logging.LogRecord) -> None:
        try:
            stream = self._streams.get(threading.get_ident(), sys.stderr)
            if self._detect_journal(stream) and self._try_emit_journal(record):
                return
            msg = self._get_formatter("verbose").format(record)
            stream.write(msg + self.terminator)
            stream.flush()
        except Exception:
            self.handleError(record)

    @types.contextmanager
    def register_stream(self, stream: types.ErrorStream) -> Iterator[None]:
        """Register stream for logging output of the current thread."""
        key = threading.get_ident()
        self._streams[key] = stream
        try:
            yield
        finally:
            del self._streams[key]


@types.contextmanager
def register_stream(stream: types.ErrorStream) -> Iterator[None]:
    """Register stream for logging output of the current thread."""
    yield


def setup() -> None:
    """Set global logging up."""
    global register_stream
    format_name = os.environ.get("RADICALE_LOG_FORMAT") or None
    sane_format_name = format_name if format_name in LOGGER_FORMATS else None
    handler = ThreadedStreamHandler(sane_format_name)
    logging.basicConfig(handlers=[handler])
    register_stream = handler.register_stream
    log_record_factory = IdentLogRecordFactory(logging.getLogRecordFactory())
    logging.setLogRecordFactory(log_record_factory)
    set_level(logging.INFO, True)
    if format_name != sane_format_name:
        logger.error("Invalid RADICALE_LOG_FORMAT: %r", format_name)


logger_display_backtrace_disabled: bool = False
logger_display_backtrace_enabled: bool = False


def set_level(level: Union[int, str], backtrace_on_debug: bool, trace_filter: str = "") -> None:
    """Set logging level for global logger."""
    global logger_display_backtrace_disabled
    global logger_display_backtrace_enabled
    if isinstance(level, str):
        level = getattr(logging, level.upper())
        assert isinstance(level, int)
    logger.setLevel(level)
    logger.log(level, "Logging level set to: %r", logging.getLevelName(level))
    if level > logging.DEBUG:
        if logger_display_backtrace_disabled is False:
            logger.info("Logging of backtrace is disabled in this loglevel")
            logger_display_backtrace_disabled = True
        logger.addFilter(REMOVE_TRACEBACK_FILTER)
    else:
        if not backtrace_on_debug:
            if logger_display_backtrace_disabled is False:
                logger.debug("Logging of backtrace is disabled by option in this loglevel")
                logger_display_backtrace_disabled = True
            logger.addFilter(REMOVE_TRACEBACK_FILTER)
        else:
            if logger_display_backtrace_enabled is False:
                logger.debug("Logging of backtrace is enabled by option in this loglevel")
                logger_display_backtrace_enabled = True
            logger.removeFilter(REMOVE_TRACEBACK_FILTER)
    if level < logging.DEBUG:
        if trace_filter != "":
            logger.trace("Logging messages on 'trace' level enabled but filtered by prefix: %r", trace_filter)
            logger.addFilter(PassTRACETOKENFilter(trace_filter))
        else:
            logger.trace("Logging messages on 'trace' level enabled")


def log_conditional(name: str, condition: dict, value: dict) -> bool:
    logger.trace("log/conditional/%s/CHECK : condition=%r value=%r", name, condition, value)
    # "and" combination
    condition_active = False
    for token in condition:
        condition_active = True
        if LOG_CONDITION_TOKEN[token] == "str":
            logger.trace("log/conditional/%s/%s/string/CHECK  : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token])
            if condition[token]["match"] in ["equal", "==", "="]:
                if not condition[token]["value"] == value[token]:
                    return False
            elif condition[token]["match"] in ["startswith"]:
                if not value[token].startswith(condition[token]["value"]):
                    return False
            elif condition[token]["match"] in ["endswith"]:
                if not value[token].endswith(condition[token]["value"]):
                    return False
            elif condition[token]["match"] in ["re"]:
                if not re.search(condition[token]["value"], value[token]):
                    return False
            logger.trace("log/conditional/%s/%s/string/PASSED : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token])

        elif LOG_CONDITION_TOKEN[token] == "int":
            condition[token]["value"] = int(condition[token]["value"])
            logger.trace("log/conditional/%s/%s/integer/CHECK  : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token])
            if condition[token]["match"] in ["equal", "==", "="]:
                if not condition[token]["value"] == value[token]:
                    return False
            elif condition[token]["match"] in ["<"]:
                if not condition[token]["value"] < value[token]:
                    return False
            elif condition[token]["match"] in ["<="]:
                if not condition[token]["value"] <= value[token]:
                    return False
            elif condition[token]["match"] in [">"]:
                if not condition[token]["value"] > value[token]:
                    return False
            elif condition[token]["match"] in [">="]:
                if not condition[token]["value"] >= value[token]:
                    return False
            elif condition[token]["match"] in ["<>", "!="]:
                if not condition[token]["value"] != value[token]:
                    return False
            logger.trace("log/conditional/%s/%s/integer/PASSED : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token])

        elif LOG_CONDITION_TOKEN[token] == "ipaddress":
            logger.trace("log/conditional/%s/%s/ip/CHECK  : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token])
            # simple IP address check
            if condition[token]["match"] in ["equal", "==", "="]:
                if not condition[token]["value"] == value[token]:
                    return False
            elif condition[token]["match"] in ["<>", "!="]:
                if not condition[token]["value"] != value[token]:
                    return False
            elif condition[token]["match"] in ["included", "incl", "excluded", "excl"]:
                if condition[token]["match"] in ["included", "incl"]:
                    if value[token] == "unknown":
                        return False
                    else:
                        ip_net = ipaddress.ip_network(value[token])
                        ip = ipaddress.ip_network(condition[token]["value"])
                        if type(ip_net) is ipaddress.IPv4Network and type(ip) is ipaddress.IPv4Network:
                            if not ip_net.subnet_of(ip):
                                return False
                        elif type(ip_net) is ipaddress.IPv6Network and type(ip) is ipaddress.IPv6Network:
                            if not ip_net.subnet_of(ip):
                                return False
                        else:
                            return False
                elif condition[token]["match"] in ["excluded", "excl"]:
                    if value[token] != "unknown":
                        ip_net = ipaddress.ip_network(value[token])
                        if type(ip_net) is ipaddress.IPv4Network and type(ip) is ipaddress.IPv4Network:
                            if ip_net.subnet_of(ip):
                                return False
                        elif type(ip_net) is ipaddress.IPv6Network and type(ip) is ipaddress.IPv6Network:
                            if ip_net.subnet_of(ip):
                                return False
                logger.trace("log/conditional/%s/%s/ip/PASSED : %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token])
            else:
                logger.trace("log/conditional/%s/%s/ip/SKIPPED: %r %s %r", name, token, condition[token]["value"], condition[token]["match"], value[token])

    # only return 'True' if at least one condition was found
    logger.trace("log/conditional/%s/PASSED: condition=%r value=%r", name, condition, value)
    return condition_active