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

@@ -39,6 +39,28 b' COLORS = {'
 }
 
 
+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
@@ -107,42 +129,6 b' class ExceptionAwareFormatter(logging.Fo'
         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)
@@ -151,20 +137,35 b' class RequestTrackingFormatter(Exception'
         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