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

from django.utils.timezone import now as timezone_now
from django.utils.timezone import utc as timezone_utc

import hashlib
import logging
import threading
import traceback
from typing import Optional, Tuple
from datetime import datetime, timedelta
from django.conf import settings
from django.core.cache import cache
from logging import Logger

class _RateLimitFilter:
    """This class is designed to rate-limit Django error reporting
    notifications so that it won't send thousands of emails if the
    database or cache is completely down.  It uses a remote shared
    cache (shared by all Django processes) for its default behavior
    (so that the deduplication is global, not per-process), and a
    local in-process cache for when it can't access the remote cache.

    This is critical code because it is called every time
    `logging.error` or `logging.exception` (or an exception) happens
    in the codebase.

    Adapted from https://djangosnippets.org/snippets/2242/.

    """
    last_error = datetime.min.replace(tzinfo=timezone_utc)
    # This thread-local variable is used to detect recursive
    # exceptions during exception handling (primarily intended for
    # when accessing the shared cache throws an exception).
    handling_exception = threading.local()
    should_reset_handling_exception = False

    def can_use_remote_cache(self) -> Tuple[bool, bool]:
        if getattr(self.handling_exception, 'value', False):
            # If we're processing an exception that occurred
            # while handling an exception, this almost
            # certainly was because interacting with the
            # remote cache is failing (e.g. because the cache
            # is down).  Fall back to tracking duplicate
            # exceptions in memory without the remote shared cache.
            return False, False

        # Now we test if the remote cache is accessible.
        #
        # This code path can only be reached if we are not potentially
        # handling a recursive exception, so here we set
        # self.handling_exception (in case the cache access we're
        # about to do triggers a `logging.error` or exception that
        # might recurse into this filter class), and actually record
        # that this is the main exception handler thread.
        try:
            self.handling_exception.value = True
            cache.set('RLF_TEST_KEY', 1, 1)
            return cache.get('RLF_TEST_KEY') == 1, True
        except Exception:
            return False, True

    def filter(self, record: logging.LogRecord) -> bool:
        # When the original filter() call finishes executing, it's
        # going to change handling_exception.value to False. The
        # local variable below tracks whether the *current*,
        # potentially recursive, filter() call is allowed to touch
        # that value (only the original will find this to be True
        # at the end of its execution)
        should_reset_handling_exception = False
        try:
            # Track duplicate errors
            duplicate = False
            rate = getattr(settings, '%s_LIMIT' % (self.__class__.__name__.upper(),),
                           600)  # seconds

            if rate > 0:
                (use_cache, should_reset_handling_exception) = self.can_use_remote_cache()
                if use_cache:
                    if record.exc_info is not None:
                        tb = '\n'.join(traceback.format_exception(*record.exc_info))
                    else:
                        tb = str(record)
                    key = self.__class__.__name__.upper() + hashlib.sha1(tb.encode()).hexdigest()
                    duplicate = cache.get(key) == 1
                    if not duplicate:
                        cache.set(key, 1, rate)
                else:
                    min_date = timezone_now() - timedelta(seconds=rate)
                    duplicate = (self.last_error >= min_date)
                    if not duplicate:
                        self.last_error = timezone_now()

            return not duplicate
        finally:
            if should_reset_handling_exception:
                self.handling_exception.value = False

class ZulipLimiter(_RateLimitFilter):
    pass

class EmailLimiter(_RateLimitFilter):
    pass

class ReturnTrue(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        return True

class ReturnEnabled(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        return settings.LOGGING_ENABLED

class RequireReallyDeployed(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        from django.conf import settings
        return settings.PRODUCTION

def skip_200_and_304(record: logging.LogRecord) -> bool:
    # Apparently, `status_code` is added by Django and is not an actual
    # attribute of LogRecord; as a result, mypy throws an error if we
    # access the `status_code` attribute directly.
    if getattr(record, 'status_code') in [200, 304]:
        return False

    return True

def skip_site_packages_logs(record: logging.LogRecord) -> bool:
    # This skips the log records that are generated from libraries
    # installed in site packages.
    # Workaround for https://code.djangoproject.com/ticket/26886
    if 'site-packages' in record.pathname:
        return False
    return True

def find_log_caller_module(record: logging.LogRecord) -> Optional[str]:
    '''Find the module name corresponding to where this record was logged.

    Sadly `record.module` is just the innermost component of the full
    module name, so we have to go reconstruct this ourselves.
    '''
    # Repeat a search similar to that in logging.Logger.findCaller.
    # The logging call should still be on the stack somewhere; search until
    # we find something in the same source file, and that should give the
    # right module name.
    f = logging.currentframe()
    while True:
        if f.f_code.co_filename == record.pathname:
            return f.f_globals.get('__name__')
        if f.f_back is None:
            return None
        f = f.f_back

logger_nicknames = {
    'root': '',  # This one is more like undoing a nickname.
    'zulip.requests': 'zr',  # Super common.
}

def find_log_origin(record: logging.LogRecord) -> str:
    logger_name = logger_nicknames.get(record.name, record.name)

    if settings.LOGGING_SHOW_MODULE:
        module_name = find_log_caller_module(record)
        if module_name == logger_name or module_name == record.name:
            # Abbreviate a bit.
            pass
        else:
            logger_name = '{}/{}'.format(logger_name, module_name or '?')

    if settings.RUNNING_INSIDE_TORNADO:
        # In multi-sharded Tornado, it's often valuable to have which shard is
        # responsible for the request in the logs.
        from zerver.tornado.ioloop_logging import logging_data
        shard = logging_data.get('port', 'unknown')
        logger_name = "{}:{}".format(logger_name, shard)

    return logger_name

log_level_abbrevs = {
    'DEBUG':    'DEBG',
    'INFO':     'INFO',
    'WARNING':  'WARN',
    'ERROR':    'ERR',
    'CRITICAL': 'CRIT',
}

def abbrev_log_levelname(levelname: str) -> str:
    # It's unlikely someone will set a custom log level with a custom name,
    # but it's an option, so we shouldn't crash if someone does.
    return log_level_abbrevs.get(levelname, levelname[:4])

class ZulipFormatter(logging.Formatter):
    # Used in the base implementation.  Default uses `,`.
    default_msec_format = '%s.%03d'

    def __init__(self) -> None:
        super().__init__(fmt=self._compute_fmt())

    def _compute_fmt(self) -> str:
        pieces = ['%(asctime)s', '%(zulip_level_abbrev)-4s']
        if settings.LOGGING_SHOW_PID:
            pieces.append('pid:%(process)d')
        pieces.extend(['[%(zulip_origin)s]', '%(message)s'])
        return ' '.join(pieces)

    def format(self, record: logging.LogRecord) -> str:
        if not getattr(record, 'zulip_decorated', False):
            # The `setattr` calls put this logic explicitly outside the bounds of the
            # type system; otherwise mypy would complain LogRecord lacks these attributes.
            setattr(record, 'zulip_level_abbrev', abbrev_log_levelname(record.levelname))
            setattr(record, 'zulip_origin', find_log_origin(record))
            setattr(record, 'zulip_decorated', True)
        return super().format(record)

def log_to_file(logger: Logger,
                filename: str,
                log_format: str="%(asctime)s %(levelname)-8s %(message)s",
                ) -> None:
    """Note: `filename` should be declared in zproject/settings.py with zulip_path."""
    formatter = logging.Formatter(log_format)
    handler = logging.FileHandler(filename)
    handler.setFormatter(formatter)
    logger.addHandler(handler)

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

from django.utils.timezone import now as timezone_now
from django.utils.timezone import utc as timezone_utc

import hashlib
import logging
import threading
import traceback
from typing import Optional, Tuple
from datetime import datetime, timedelta
from django.conf import settings
from django.core.cache import cache
from logging import Logger

class _RateLimitFilter:
    """This class is designed to rate-limit Django error reporting
    notifications so that it won't send thousands of emails if the
    database or cache is completely down.  It uses a remote shared
    cache (shared by all Django processes) for its default behavior
    (so that the deduplication is global, not per-process), and a
    local in-process cache for when it can't access the remote cache.

    This is critical code because it is called every time
    `logging.error` or `logging.exception` (or an exception) happens
    in the codebase.

    Adapted from https://djangosnippets.org/snippets/2242/.

    """
    last_error = datetime.min.replace(tzinfo=timezone_utc)
    # This thread-local variable is used to detect recursive
    # exceptions during exception handling (primarily intended for
    # when accessing the shared cache throws an exception).
    handling_exception = threading.local()
    should_reset_handling_exception = False

    def can_use_remote_cache(self) -> Tuple[bool, bool]:
        if getattr(self.handling_exception, 'value', False):
            # If we're processing an exception that occurred
            # while handling an exception, this almost
            # certainly was because interacting with the
            # remote cache is failing (e.g. because the cache
            # is down).  Fall back to tracking duplicate
            # exceptions in memory without the remote shared cache.
            return False, False

        # Now we test if the remote cache is accessible.
        #
        # This code path can only be reached if we are not potentially
        # handling a recursive exception, so here we set
        # self.handling_exception (in case the cache access we're
        # about to do triggers a `logging.error` or exception that
        # might recurse into this filter class), and actually record
        # that this is the main exception handler thread.
        try:
            self.handling_exception.value = True
            cache.set('RLF_TEST_KEY', 1, 1)
            return cache.get('RLF_TEST_KEY') == 1, True
        except Exception:
            return False, True

    def filter(self, record: logging.LogRecord) -> bool:
        # When the original filter() call finishes executing, it's
        # going to change handling_exception.value to False. The
        # local variable below tracks whether the *current*,
        # potentially recursive, filter() call is allowed to touch
        # that value (only the original will find this to be True
        # at the end of its execution)
        should_reset_handling_exception = False
        try:
            # Track duplicate errors
            duplicate = False
            rate = getattr(settings, '%s_LIMIT' % (self.__class__.__name__.upper(),),
                           600)  # seconds

            if rate > 0:
                (use_cache, should_reset_handling_exception) = self.can_use_remote_cache()
                if use_cache:
                    if record.exc_info is not None:
                        tb = '\n'.join(traceback.format_exception(*record.exc_info))
                    else:
                        tb = str(record)
                    key = self.__class__.__name__.upper() + hashlib.sha1(tb.encode()).hexdigest()
                    duplicate = cache.get(key) == 1
                    if not duplicate:
                        cache.set(key, 1, rate)
                else:
                    min_date = timezone_now() - timedelta(seconds=rate)
                    duplicate = (self.last_error >= min_date)
                    if not duplicate:
                        self.last_error = timezone_now()

            return not duplicate
        finally:
            if should_reset_handling_exception:
                self.handling_exception.value = False

class ZulipLimiter(_RateLimitFilter):
    pass

class EmailLimiter(_RateLimitFilter):
    pass

class ReturnTrue(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        return True

class ReturnEnabled(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        return settings.LOGGING_ENABLED

class RequireReallyDeployed(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        from django.conf import settings
        return settings.PRODUCTION

def skip_200_and_304(record: logging.LogRecord) -> bool:
    # Apparently, `status_code` is added by Django and is not an actual
    # attribute of LogRecord; as a result, mypy throws an error if we
    # access the `status_code` attribute directly.
    if getattr(record, 'status_code', None) in [200, 304]:
        return False

    return True

def skip_site_packages_logs(record: logging.LogRecord) -> bool:
    # This skips the log records that are generated from libraries
    # installed in site packages.
    # Workaround for https://code.djangoproject.com/ticket/26886
    if 'site-packages' in record.pathname:
        return False
    return True

def find_log_caller_module(record: logging.LogRecord) -> Optional[str]:
    '''Find the module name corresponding to where this record was logged.

    Sadly `record.module` is just the innermost component of the full
    module name, so we have to go reconstruct this ourselves.
    '''
    # Repeat a search similar to that in logging.Logger.findCaller.
    # The logging call should still be on the stack somewhere; search until
    # we find something in the same source file, and that should give the
    # right module name.
    f = logging.currentframe()
    while f is not None:
        if f.f_code.co_filename == record.pathname:
            return f.f_globals.get('__name__')
        f = f.f_back
    return None  # type: ignore # required because of previous ignore on f

logger_nicknames = {
    'root': '',  # This one is more like undoing a nickname.
    'zulip.requests': 'zr',  # Super common.
}

def find_log_origin(record: logging.LogRecord) -> str:
    logger_name = logger_nicknames.get(record.name, record.name)

    if settings.LOGGING_SHOW_MODULE:
        module_name = find_log_caller_module(record)
        if module_name == logger_name or module_name == record.name:
            # Abbreviate a bit.
            pass
        else:
            logger_name = '{}/{}'.format(logger_name, module_name or '?')

    if settings.RUNNING_INSIDE_TORNADO:
        # In multi-sharded Tornado, it's often valuable to have which shard is
        # responsible for the request in the logs.
        from zerver.tornado.ioloop_logging import logging_data
        shard = logging_data.get('port', 'unknown')
        logger_name = "{}:{}".format(logger_name, shard)

    return logger_name

log_level_abbrevs = {
    'DEBUG':    'DEBG',
    'INFO':     'INFO',
    'WARNING':  'WARN',
    'ERROR':    'ERR',
    'CRITICAL': 'CRIT',
}

def abbrev_log_levelname(levelname: str) -> str:
    # It's unlikely someone will set a custom log level with a custom name,
    # but it's an option, so we shouldn't crash if someone does.
    return log_level_abbrevs.get(levelname, levelname[:4])

class ZulipFormatter(logging.Formatter):
    # Used in the base implementation.  Default uses `,`.
    default_msec_format = '%s.%03d'

    def __init__(self) -> None:
        super().__init__(fmt=self._compute_fmt())

    def _compute_fmt(self) -> str:
        pieces = ['%(asctime)s', '%(zulip_level_abbrev)-4s']
        if settings.LOGGING_SHOW_PID:
            pieces.append('pid:%(process)d')
        pieces.extend(['[%(zulip_origin)s]', '%(message)s'])
        return ' '.join(pieces)

    def format(self, record: logging.LogRecord) -> str:
        if not getattr(record, 'zulip_decorated', False):
            # The `setattr` calls put this logic explicitly outside the bounds of the
            # type system; otherwise mypy would complain LogRecord lacks these attributes.
            setattr(record, 'zulip_level_abbrev', abbrev_log_levelname(record.levelname))
            setattr(record, 'zulip_origin', find_log_origin(record))
            setattr(record, 'zulip_decorated', True)
        return super().format(record)

def log_to_file(logger: Logger,
                filename: str,
                log_format: str="%(asctime)s %(levelname)-8s %(message)s",
                ) -> None:
    """Note: `filename` should be declared in zproject/settings.py with zulip_path."""
    formatter = logging.Formatter(log_format)
    handler = logging.FileHandler(filename)
    handler.setFormatter(formatter)
    logger.addHandler(handler)

zerver/lib/logging_util.py
diff --git a/zerver/lib/logging_util.py b/zerver/lib/logging_util.py
index 6f5bf023873ac..43c9030ebb10a 100644
--- a/zerver/lib/logging_util.py
+++ b/zerver/lib/logging_util.py
@@ -119,7 +119,7 @@ def skip_200_and_304(record: logging.LogRecord) -> bool:
     # Apparently, `status_code` is added by Django and is not an actual
     # attribute of LogRecord; as a result, mypy throws an error if we
     # access the `status_code` attribute directly.
-    if getattr(record, 'status_code') in [200, 304]:
+    if getattr(record, 'status_code', None) in [200, 304]:
         return False
 
     return True

AttributeError: 'LogRecord' object has no attribute 'status_code'
I have a development environment with the latest Git version. After performing many requests, I get blocked because of rate limiting. Then, the following error is logged in the console:

```
----------------------------------------
Exception happened during processing of request from ('127.0.0.1', 56444)
2020-04-16 11:35:49.159 INFO [zr] 127.0.0.1       POST    429  65ms (mem: 57ms/4) (+start: 24ms) /json/messages (10@zulip via website)
2020-04-16 11:35:49.160 INFO [zr] status=429, data=b'{"result":"error","msg":"API usage exceeded rate limit","retry-after":2.6131470203}\n', uid=10@zulip
2020-04-16 11:35:49.162 INFO [zr] 127.0.0.1       POST    429  11ms (mem: 7ms/2) /json/messages (10@zulip via website)
2020-04-16 11:35:49.162 WARN [django.server] "POST /json/messages HTTP/1.1" 429 84
2020-04-16 11:35:49.173 INFO [zr] status=429, data=b'{"result":"error","msg":"API usage exceeded rate limit","retry-after":2.6109778881}\n', uid=10@zulip
2020-04-16 11:35:49.179 INFO [zr] 127.0.0.1       POST    429  20ms (+start: 51ms) /json/messages (10@zulip via website)
2020-04-16 11:35:49.182 WARN [django.server] "POST /json/messages HTTP/1.1" 429 84
2020-04-16 11:35:49.195 INFO [zr] status=429, data=b'{"result":"error","msg":"API usage exceeded rate limit","retry-after":2.5940015316}\n', uid=10@zulip
Traceback (most recent call last):
  File "/usr/lib/python3.7/socketserver.py", line 650, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python3.7/socketserver.py", line 360, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python3.7/socketserver.py", line 720, in __init__
    self.handle()
  File "/srv/zulip-py3-venv/lib/python3.7/site-packages/django/core/servers/basehttp.py", line 171, in handle
    self.handle_one_request()
  File "/srv/zulip-py3-venv/lib/python3.7/site-packages/django/core/servers/basehttp.py", line 187, in handle_one_request
    if not self.parse_request():  # An error code has been sent, just exit
  File "/usr/lib/python3.7/http/server.py", line 322, in parse_request
    "Bad request syntax (%r)" % requestline)
  File "/usr/lib/python3.7/http/server.py", line 456, in send_error
    self.log_error("code %d, message %s", code, message)
  File "/usr/lib/python3.7/http/server.py", line 558, in log_error
    self.log_message(format, *args)
  File "/srv/zulip-py3-venv/lib/python3.7/site-packages/django/core/servers/basehttp.py", line 154, in log_message
    level(format, *args, extra=extra)
  File "/usr/lib/python3.7/logging/__init__.py", line 1383, in info
    self._log(INFO, msg, args, **kwargs)
  File "/usr/lib/python3.7/logging/__init__.py", line 1519, in _log
    self.handle(record)
  File "/usr/lib/python3.7/logging/__init__.py", line 1528, in handle
    if (not self.disabled) and self.filter(record):
  File "/usr/lib/python3.7/logging/__init__.py", line 762, in filter
    result = f.filter(record)
  File "/srv/zulip-py3-venv/lib/python3.7/site-packages/django/utils/log.py", line 147, in filter
    if self.callback(record):
  File "/home/sjoerd/zulip/zerver/lib/logging_util.py", line 122, in skip_200_and_304
    if getattr(record, 'status_code') in [200, 304]:
AttributeError: 'LogRecord' object has no attribute 'status_code'
----------------------------------------
```

Normally, [http.server logs request, status code, size](https://github.com/python/cpython/blob/master/Lib/http/server.py#L544-L545), and [Django extracts the status code from that](https://github.com/django/django/blob/master/django/core/servers/basehttp.py#L144-L157). However, [on errors http.server logs code and message](https://github.com/python/cpython/blob/master/Lib/http/server.py#L457) and Django doesn't extract the status code.

Parsing arguments to log messages seems pretty fragile to me, so maybe it's better to accept that there isn't always a status code on a log record. Making `getattr` default to `None` in [`skip_200_and_304`](https://github.com/zulip/zulip/blob/master/zerver/lib/logging_util.py#L122) is probably the best option.


