logging: added json logger to send json formatted logs

rhodecode/lib/_vendor/jsonlogger/__init__.py

@@ -0,0 +1,236 b''
+'''
+This library is provided to allow standard python logging
+to output log data as JSON formatted strings
+'''
+import logging
+import json
+import re
+from datetime import date, datetime, time, tzinfo, timedelta
+import traceback
+import importlib
+
+from inspect import istraceback
+
+from collections import OrderedDict
+from rhodecode.lib.logging_formatter import _inject_req_id, ExceptionAwareFormatter
+
+ZERO = timedelta(0)
+HOUR = timedelta(hours=1)
+
+
+class UTC(tzinfo):
+    """UTC"""
+
+    def utcoffset(self, dt):
+        return ZERO
+
+    def tzname(self, dt):
+        return "UTC"
+
+    def dst(self, dt):
+        return ZERO
+
+utc = UTC()
+
+
+# skip natural LogRecord attributes
+# http://docs.python.org/library/logging.html#logrecord-attributes
+RESERVED_ATTRS = (
+    'args', 'asctime', 'created', 'exc_info', 'exc_text', 'filename',
+    'funcName', 'levelname', 'levelno', 'lineno', 'module',
+    'msecs', 'message', 'msg', 'name', 'pathname', 'process',
+    'processName', 'relativeCreated', 'stack_info', 'thread', 'threadName')
+
+
+def merge_record_extra(record, target, reserved):
+    """
+    Merges extra attributes from LogRecord object into target dictionary
+
+    :param record: logging.LogRecord
+    :param target: dict to update
+    :param reserved: dict or list with reserved keys to skip
+    """
+    for key, value in record.__dict__.items():
+        # this allows to have numeric keys
+        if (key not in reserved
+            and not (hasattr(key, "startswith")
+                     and key.startswith('_'))):
+            target[key] = value
+    return target
+
+
+class JsonEncoder(json.JSONEncoder):
+    """
+    A custom encoder extending the default JSONEncoder
+    """
+
+    def default(self, obj):
+        if isinstance(obj, (date, datetime, time)):
+            return self.format_datetime_obj(obj)
+
+        elif istraceback(obj):
+            return ''.join(traceback.format_tb(obj)).strip()
+
+        elif type(obj) == Exception \
+                or isinstance(obj, Exception) \
+                or type(obj) == type:
+            return str(obj)
+
+        try:
+            return super(JsonEncoder, self).default(obj)
+
+        except TypeError:
+            try:
+                return str(obj)
+
+            except Exception:
+                return None
+
+    def format_datetime_obj(self, obj):
+        return obj.isoformat()
+
+
+class JsonFormatter(ExceptionAwareFormatter):
+    """
+    A custom formatter to format logging records as json strings.
+    Extra values will be formatted as str() if not supported by
+    json default encoder
+    """
+
+    def __init__(self, *args, **kwargs):
+        """
+        :param json_default: a function for encoding non-standard objects
+            as outlined in http://docs.python.org/2/library/json.html
+        :param json_encoder: optional custom encoder
+        :param json_serializer: a :meth:`json.dumps`-compatible callable
+            that will be used to serialize the log record.
+        :param json_indent: an optional :meth:`json.dumps`-compatible numeric value
+            that will be used to customize the indent of the output json.
+        :param prefix: an optional string prefix added at the beginning of
+            the formatted string
+        :param json_indent: indent parameter for json.dumps
+        :param json_ensure_ascii: ensure_ascii parameter for json.dumps
+        :param reserved_attrs: an optional list of fields that will be skipped when
+            outputting json log record. Defaults to all log record attributes:
+            http://docs.python.org/library/logging.html#logrecord-attributes
+        :param timestamp: an optional string/boolean field to add a timestamp when
+            outputting the json log record. If string is passed, timestamp will be added
+            to log record using string as key. If True boolean is passed, timestamp key
+            will be "timestamp". Defaults to False/off.
+        """
+        self.json_default = self._str_to_fn(kwargs.pop("json_default", None))
+        self.json_encoder = self._str_to_fn(kwargs.pop("json_encoder", None))
+        self.json_serializer = self._str_to_fn(kwargs.pop("json_serializer", json.dumps))
+        self.json_indent = kwargs.pop("json_indent", None)
+        self.json_ensure_ascii = kwargs.pop("json_ensure_ascii", True)
+        self.prefix = kwargs.pop("prefix", "")
+        reserved_attrs = kwargs.pop("reserved_attrs", RESERVED_ATTRS)
+        self.reserved_attrs = dict(zip(reserved_attrs, reserved_attrs))
+        self.timestamp = kwargs.pop("timestamp", True)
+
+        # super(JsonFormatter, self).__init__(*args, **kwargs)
+        logging.Formatter.__init__(self, *args, **kwargs)
+        if not self.json_encoder and not self.json_default:
+            self.json_encoder = JsonEncoder
+
+        self._required_fields = self.parse()
+        self._skip_fields = dict(zip(self._required_fields,
+                                     self._required_fields))
+        self._skip_fields.update(self.reserved_attrs)
+
+    def _str_to_fn(self, fn_as_str):
+        """
+        If the argument is not a string, return whatever was passed in.
+        Parses a string such as package.module.function, imports the module
+        and returns the function.
+
+        :param fn_as_str: The string to parse. If not a string, return it.
+        """
+        if not isinstance(fn_as_str, str):
+            return fn_as_str
+
+        path, _, function = fn_as_str.rpartition('.')
+        module = importlib.import_module(path)
+        return getattr(module, function)
+
+    def parse(self):
+        """
+        Parses format string looking for substitutions
+
+        This method is responsible for returning a list of fields (as strings)
+        to include in all log messages.
+        """
+        standard_formatters = re.compile(r'\((.+?)\)', re.IGNORECASE)
+        return standard_formatters.findall(self._fmt)
+
+    def add_fields(self, log_record, record, message_dict):
+        """
+        Override this method to implement custom logic for adding fields.
+        """
+        for field in self._required_fields:
+            log_record[field] = record.__dict__.get(field)
+        log_record.update(message_dict)
+        merge_record_extra(record, log_record, reserved=self._skip_fields)
+
+        if self.timestamp:
+            key = self.timestamp if type(self.timestamp) == str else 'timestamp'
+            log_record[key] = datetime.fromtimestamp(record.created, tz=utc)
+
+    def process_log_record(self, log_record):
+        """
+        Override this method to implement custom logic
+        on the possibly ordered dictionary.
+        """
+        return log_record
+
+    def jsonify_log_record(self, log_record):
+        """Returns a json string of the log record."""
+        return self.json_serializer(log_record,
+                                    default=self.json_default,
+                                    cls=self.json_encoder,
+                                    indent=self.json_indent,
+                                    ensure_ascii=self.json_ensure_ascii)
+
+    def serialize_log_record(self, log_record):
+        """Returns the final representation of the log record."""
+        return "%s%s" % (self.prefix, self.jsonify_log_record(log_record))
+
+    def format(self, record):
+        """Formats a log record and serializes to json"""
+        message_dict = {}
+        # FIXME: logging.LogRecord.msg and logging.LogRecord.message in typeshed
+        #        are always type of str. We shouldn't need to override that.
+        if isinstance(record.msg, dict):
+            message_dict = record.msg
+            record.message = None
+        else:
+            record.message = record.getMessage()
+        # only format time if needed
+        if "asctime" in self._required_fields:
+            record.asctime = self.formatTime(record, self.datefmt)
+
+        # Display formatted exception, but allow overriding it in the
+        # user-supplied dict.
+        if record.exc_info and not message_dict.get('exc_info'):
+            message_dict['exc_info'] = self.formatException(record.exc_info)
+        if not message_dict.get('exc_info') and record.exc_text:
+            message_dict['exc_info'] = record.exc_text
+        # Display formatted record of stack frames
+        # default format is a string returned from :func:`traceback.print_stack`
+        try:
+            if record.stack_info and not message_dict.get('stack_info'):
+                message_dict['stack_info'] = self.formatStack(record.stack_info)
+        except AttributeError:
+            # Python2.7 doesn't have stack_info.
+            pass
+
+        try:
+            log_record = OrderedDict()
+        except NameError:
+            log_record = {}
+
+        _inject_req_id(record, with_prefix=False)
+        self.add_fields(log_record, record, message_dict)
+        log_record = self.process_log_record(log_record)
+
+        return self.serialize_log_record(log_record)

rhodecode/lib/logging_formatter.py

@@ -1,186 +1,187 b''
 # -*- coding: utf-8 -*-
 
 # Copyright (C) 2010-2020 RhodeCode GmbH
 #
 # This program is free software: you can redistribute it and/or modify
 # it under the terms of the GNU Affero General Public License, version 3
 # (only), as published by the Free Software Foundation.
 #
 # This program 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 Affero General Public License
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 #
 # This program is dual-licensed. If you wish to learn more about the
 # RhodeCode Enterprise Edition, including its added features, Support services,
 # and proprietary license terms, please see https://rhodecode.com/licenses/
 
 import sys
 import logging
 
 
 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE = xrange(30, 38)
 
 # Sequences
 RESET_SEQ = "\033[0m"
 COLOR_SEQ = "\033[0;%dm"
 BOLD_SEQ = "\033[1m"
 
 COLORS = {
     'CRITICAL': MAGENTA,
     'ERROR': RED,
     'WARNING': CYAN,
     'INFO': GREEN,
     'DEBUG': BLUE,
     'SQL': YELLOW
 }
 
 
+def _inject_req_id(record, with_prefix=True):
+    from pyramid.threadlocal import get_current_request
+    dummy = '00000000-0000-0000-0000-000000000000'
+    req_id = None
+
+    req = get_current_request()
+    if req:
+        req_id = getattr(req, 'req_id', None)
+    if with_prefix:
+        req_id = 'req_id:%-36s' % (req_id or dummy)
+    else:
+        req_id = (req_id or dummy)
+    record.req_id = req_id
+
+
+def _add_log_to_debug_bucket(formatted_record):
+    from pyramid.threadlocal import get_current_request
+    req = get_current_request()
+    if req:
+        req.req_id_bucket.append(formatted_record)
+
+
 def one_space_trim(s):
     if s.find("  ") == -1:
         return s
     else:
         s = s.replace('  ', ' ')
         return one_space_trim(s)
 
 
 def format_sql(sql):
     sql = sql.replace('\n', '')
     sql = one_space_trim(sql)
     sql = sql\
         .replace(',', ',\n\t')\
         .replace('SELECT', '\n\tSELECT \n\t')\
         .replace('UPDATE', '\n\tUPDATE \n\t')\
         .replace('DELETE', '\n\tDELETE \n\t')\
         .replace('FROM', '\n\tFROM')\
         .replace('ORDER BY', '\n\tORDER BY')\
         .replace('LIMIT', '\n\tLIMIT')\
         .replace('WHERE', '\n\tWHERE')\
         .replace('AND', '\n\tAND')\
         .replace('LEFT', '\n\tLEFT')\
         .replace('INNER', '\n\tINNER')\
         .replace('INSERT', '\n\tINSERT')\
         .replace('DELETE', '\n\tDELETE')
     return sql
 
 
 class ExceptionAwareFormatter(logging.Formatter):
     """
     Extended logging formatter which prints out remote tracebacks.
     """
 
     def formatException(self, ei):
         ex_type, ex_value, ex_tb = ei
 
         local_tb = logging.Formatter.formatException(self, ei)
         if hasattr(ex_value, '_vcs_server_traceback'):
 
             def formatRemoteTraceback(remote_tb_lines):
                 result = ["\n +--- This exception occured remotely on VCSServer - Remote traceback:\n\n"]
                 result.append(remote_tb_lines)
                 result.append("\n +--- End of remote traceback\n")
                 return result
 
             try:
                 if ex_type is not None and ex_value is None and ex_tb is None:
                     # possible old (3.x) call syntax where caller is only
                     # providing exception object
                     if type(ex_type) is not type:
                         raise TypeError(
                             "invalid argument: ex_type should be an exception "
                             "type, or just supply no arguments at all")
                 if ex_type is None and ex_tb is None:
                     ex_type, ex_value, ex_tb = sys.exc_info()
 
                 remote_tb = getattr(ex_value, "_vcs_server_traceback", None)
 
                 if remote_tb:
                     remote_tb = formatRemoteTraceback(remote_tb)
                     return local_tb + ''.join(remote_tb)
             finally:
                 # clean up cycle to traceback, to allow proper GC
                 del ex_type, ex_value, ex_tb
 
         return local_tb
 
 
-class ColorFormatter(ExceptionAwareFormatter):
-
-    def format(self, record):
-        """
-        Changes record's levelname to use with COLORS enum
-        """
-
-        levelname = record.levelname
-        start = COLOR_SEQ % (COLORS[levelname])
-        def_record = logging.Formatter.format(self, record)
-        end = RESET_SEQ
-
-        colored_record = ''.join([start, def_record, end])
-        return colored_record
-
-
-def _inject_req_id(record):
-    from pyramid.threadlocal import get_current_request
-    dummy = '00000000-0000-0000-0000-000000000000'
-    req_id = None
-
-    req = get_current_request()
-    if req:
-        req_id = getattr(req, 'req_id', None)
-
-    req_id = 'req_id:%-36s' % (req_id or dummy)
-    record.req_id = req_id
-
-
-def _add_log_to_debug_bucket(formatted_record):
-    from pyramid.threadlocal import get_current_request
-    req = get_current_request()
-    if req:
-        req.req_id_bucket.append(formatted_record)
-
-
 class RequestTrackingFormatter(ExceptionAwareFormatter):
     def format(self, record):
         _inject_req_id(record)
         def_record = logging.Formatter.format(self, record)
         _add_log_to_debug_bucket(def_record)
         return def_record
 
 
-class ColorRequestTrackingFormatter(ColorFormatter):
+class ColorFormatter(ExceptionAwareFormatter):
 
     def format(self, record):
         """
         Changes record's levelname to use with COLORS enum
         """
-        _inject_req_id(record)
+        def_record = super(ColorFormatter, self).format(record)
+
         levelname = record.levelname
         start = COLOR_SEQ % (COLORS[levelname])
-        def_record = logging.Formatter.format(self, record)
         end = RESET_SEQ
 
         colored_record = ''.join([start, def_record, end])
-        _add_log_to_debug_bucket(def_record)
+        return colored_record
+
+
+class ColorRequestTrackingFormatter(RequestTrackingFormatter):
+
+    def format(self, record):
+        """
+        Changes record's levelname to use with COLORS enum
+        """
+        def_record = super(ColorRequestTrackingFormatter, self).format(record)
+
+        levelname = record.levelname
+        start = COLOR_SEQ % (COLORS[levelname])
+        end = RESET_SEQ
+
+        colored_record = ''.join([start, def_record, end])
         return colored_record
 
 
 class ColorFormatterSql(logging.Formatter):
 
     def format(self, record):
         """
         Changes record's levelname to use with COLORS enum
         """
 
         start = COLOR_SEQ % (COLORS['SQL'])
         def_record = format_sql(logging.Formatter.format(self, record))
         end = RESET_SEQ
 
         colored_record = ''.join([start, def_record, end])
         return colored_record
 
 # marcink: needs to stay with this name for backward .ini compatability
 Pyro4AwareFormatter = ExceptionAwareFormatter