zulip/zerver/logging_handlers.py

# System documented in https://zulip.readthedocs.io/en/latest/subsystems/logging.html

import logging
import platform
import os
import subprocess
import traceback
from typing import Any, Dict, Optional

from django.conf import settings
from django.http import HttpRequest
from django.views.debug import get_exception_reporter_filter

from zerver.lib.logging_util import find_log_caller_module
from zerver.lib.queue import queue_json_publish
from version import ZULIP_VERSION

def try_git_describe() -> Optional[str]:
    try:  # nocoverage
        return subprocess.check_output(
            ['git', 'describe', '--tags', '--match=[0-9]*', '--always', '--dirty', '--long'],
            stderr=subprocess.PIPE,
            cwd=os.path.join(os.path.dirname(__file__), '..'),
        ).strip().decode('utf-8')
    except Exception:  # nocoverage
        return None

def add_deployment_metadata(report: Dict[str, Any]) -> None:
    report['git_described'] = try_git_describe()
    report['zulip_version_const'] = ZULIP_VERSION

    version_path = os.path.join(os.path.dirname(__file__), '../version')
    if os.path.exists(version_path):
        with open(version_path) as f:  # nocoverage
            report['zulip_version_file'] = f.read().strip()

def add_request_metadata(report: Dict[str, Any], request: HttpRequest) -> None:
    report['has_request'] = True

    report['path'] = request.path
    report['method'] = request.method
    report['remote_addr'] = request.META.get('REMOTE_ADDR', None),
    report['query_string'] = request.META.get('QUERY_STRING', None),
    report['server_name'] = request.META.get('SERVER_NAME', None),
    try:
        from django.contrib.auth.models import AnonymousUser
        user_profile = request.user
        if isinstance(user_profile, AnonymousUser):
            user_full_name = None
            user_email = None
        else:
            user_full_name = user_profile.full_name
            user_email = user_profile.email
    except Exception:
        # Unexpected exceptions here should be handled gracefully
        traceback.print_exc()
        user_full_name = None
        user_email = None
    report['user_email'] = user_email
    report['user_full_name'] = user_full_name

    exception_filter = get_exception_reporter_filter(request)
    try:
        report['data'] = exception_filter.get_post_parameters(request) \
            if request.method == 'POST' else request.GET
    except Exception:
        # exception_filter.get_post_parameters will throw
        # RequestDataTooBig if there's a really big file uploaded
        report['data'] = {}

    try:
        report['host'] = request.get_host().split(':')[0]
    except Exception:
        # request.get_host() will throw a DisallowedHost
        # exception if the host is invalid
        report['host'] = platform.node()

class AdminNotifyHandler(logging.Handler):
    """An logging handler that sends the log/exception to the queue to be
       turned into an email and/or a Zulip message for the server admins.
    """

    # adapted in part from django/utils/log.py

    def __init__(self) -> None:
        logging.Handler.__init__(self)

    def emit(self, record: logging.LogRecord) -> None:
        report = {}  # type: Dict[str, Any]

        # This parameter determines whether Zulip should attempt to
        # send Zulip messages containing the error report.  If there's
        # syntax that makes the markdown processor throw an exception,
        # we really don't want to send that syntax into a new Zulip
        # message in exception handler (that's the stuff of which
        # recursive exception loops are made).
        #
        # We initialize is_bugdown_rendering_exception to `True` to
        # prevent the infinite loop of zulip messages by ERROR_BOT if
        # the outer try block here throws an exception before we have
        # a chance to check the exception for whether it comes from
        # bugdown.
        is_bugdown_rendering_exception = True

        try:
            report['node'] = platform.node()
            report['host'] = platform.node()

            add_deployment_metadata(report)

            if record.exc_info:
                stack_trace = ''.join(traceback.format_exception(*record.exc_info))
                message = str(record.exc_info[1])
                is_bugdown_rendering_exception = record.msg.startswith('Exception in Markdown parser')
            else:
                stack_trace = 'No stack trace available'
                message = record.getMessage()
                if '\n' in message:
                    # Some exception code paths in queue processors
                    # seem to result in super-long messages
                    stack_trace = message
                    message = message.split('\n')[0]
                is_bugdown_rendering_exception = False
            report['stack_trace'] = stack_trace
            report['message'] = message

            report['logger_name'] = record.name
            report['log_module'] = find_log_caller_module(record)
            report['log_lineno'] = record.lineno

            if hasattr(record, "request"):
                add_request_metadata(report, record.request)  # type: ignore[attr-defined]  # record.request is added dynamically

        except Exception:
            report['message'] = "Exception in preparing exception report!"
            logging.warning(report['message'], exc_info=True)
            report['stack_trace'] = "See /var/log/zulip/errors.log"

        if settings.DEBUG_ERROR_REPORTING:  # nocoverage
            logging.warning("Reporting an error to admins...")
            logging.warning("Reporting an error to admins: {} {} {} {} {}" .format(
                record.levelname, report['logger_name'], report['log_module'],
                report['message'], report['stack_trace']))

        try:
            if settings.STAGING_ERROR_NOTIFICATIONS:
                # On staging, process the report directly so it can happen inside this
                # try/except to prevent looping
                from zerver.lib.error_notify import notify_server_error
                notify_server_error(report, is_bugdown_rendering_exception)
            else:
                queue_json_publish('error_reports', dict(
                    type = "server",
                    report = report,
                ))
        except Exception:
            # If this breaks, complain loudly but don't pass the traceback up the stream
            # However, we *don't* want to use logging.exception since that could trigger a loop.
            logging.warning("Reporting an exception triggered an exception!", exc_info=True)