##// END OF EJS Templates
logging: added json logger to send json formatted logs
super-admin -
r4789:eac1839b default
parent child Browse files
Show More
@@ -0,0 +1,236 b''
1 '''
2 This library is provided to allow standard python logging
3 to output log data as JSON formatted strings
4 '''
5 import logging
6 import json
7 import re
8 from datetime import date, datetime, time, tzinfo, timedelta
9 import traceback
10 import importlib
11
12 from inspect import istraceback
13
14 from collections import OrderedDict
15 from rhodecode.lib.logging_formatter import _inject_req_id, ExceptionAwareFormatter
16
17 ZERO = timedelta(0)
18 HOUR = timedelta(hours=1)
19
20
21 class UTC(tzinfo):
22 """UTC"""
23
24 def utcoffset(self, dt):
25 return ZERO
26
27 def tzname(self, dt):
28 return "UTC"
29
30 def dst(self, dt):
31 return ZERO
32
33 utc = UTC()
34
35
36 # skip natural LogRecord attributes
37 # http://docs.python.org/library/logging.html#logrecord-attributes
38 RESERVED_ATTRS = (
39 'args', 'asctime', 'created', 'exc_info', 'exc_text', 'filename',
40 'funcName', 'levelname', 'levelno', 'lineno', 'module',
41 'msecs', 'message', 'msg', 'name', 'pathname', 'process',
42 'processName', 'relativeCreated', 'stack_info', 'thread', 'threadName')
43
44
45 def merge_record_extra(record, target, reserved):
46 """
47 Merges extra attributes from LogRecord object into target dictionary
48
49 :param record: logging.LogRecord
50 :param target: dict to update
51 :param reserved: dict or list with reserved keys to skip
52 """
53 for key, value in record.__dict__.items():
54 # this allows to have numeric keys
55 if (key not in reserved
56 and not (hasattr(key, "startswith")
57 and key.startswith('_'))):
58 target[key] = value
59 return target
60
61
62 class JsonEncoder(json.JSONEncoder):
63 """
64 A custom encoder extending the default JSONEncoder
65 """
66
67 def default(self, obj):
68 if isinstance(obj, (date, datetime, time)):
69 return self.format_datetime_obj(obj)
70
71 elif istraceback(obj):
72 return ''.join(traceback.format_tb(obj)).strip()
73
74 elif type(obj) == Exception \
75 or isinstance(obj, Exception) \
76 or type(obj) == type:
77 return str(obj)
78
79 try:
80 return super(JsonEncoder, self).default(obj)
81
82 except TypeError:
83 try:
84 return str(obj)
85
86 except Exception:
87 return None
88
89 def format_datetime_obj(self, obj):
90 return obj.isoformat()
91
92
93 class JsonFormatter(ExceptionAwareFormatter):
94 """
95 A custom formatter to format logging records as json strings.
96 Extra values will be formatted as str() if not supported by
97 json default encoder
98 """
99
100 def __init__(self, *args, **kwargs):
101 """
102 :param json_default: a function for encoding non-standard objects
103 as outlined in http://docs.python.org/2/library/json.html
104 :param json_encoder: optional custom encoder
105 :param json_serializer: a :meth:`json.dumps`-compatible callable
106 that will be used to serialize the log record.
107 :param json_indent: an optional :meth:`json.dumps`-compatible numeric value
108 that will be used to customize the indent of the output json.
109 :param prefix: an optional string prefix added at the beginning of
110 the formatted string
111 :param json_indent: indent parameter for json.dumps
112 :param json_ensure_ascii: ensure_ascii parameter for json.dumps
113 :param reserved_attrs: an optional list of fields that will be skipped when
114 outputting json log record. Defaults to all log record attributes:
115 http://docs.python.org/library/logging.html#logrecord-attributes
116 :param timestamp: an optional string/boolean field to add a timestamp when
117 outputting the json log record. If string is passed, timestamp will be added
118 to log record using string as key. If True boolean is passed, timestamp key
119 will be "timestamp". Defaults to False/off.
120 """
121 self.json_default = self._str_to_fn(kwargs.pop("json_default", None))
122 self.json_encoder = self._str_to_fn(kwargs.pop("json_encoder", None))
123 self.json_serializer = self._str_to_fn(kwargs.pop("json_serializer", json.dumps))
124 self.json_indent = kwargs.pop("json_indent", None)
125 self.json_ensure_ascii = kwargs.pop("json_ensure_ascii", True)
126 self.prefix = kwargs.pop("prefix", "")
127 reserved_attrs = kwargs.pop("reserved_attrs", RESERVED_ATTRS)
128 self.reserved_attrs = dict(zip(reserved_attrs, reserved_attrs))
129 self.timestamp = kwargs.pop("timestamp", True)
130
131 # super(JsonFormatter, self).__init__(*args, **kwargs)
132 logging.Formatter.__init__(self, *args, **kwargs)
133 if not self.json_encoder and not self.json_default:
134 self.json_encoder = JsonEncoder
135
136 self._required_fields = self.parse()
137 self._skip_fields = dict(zip(self._required_fields,
138 self._required_fields))
139 self._skip_fields.update(self.reserved_attrs)
140
141 def _str_to_fn(self, fn_as_str):
142 """
143 If the argument is not a string, return whatever was passed in.
144 Parses a string such as package.module.function, imports the module
145 and returns the function.
146
147 :param fn_as_str: The string to parse. If not a string, return it.
148 """
149 if not isinstance(fn_as_str, str):
150 return fn_as_str
151
152 path, _, function = fn_as_str.rpartition('.')
153 module = importlib.import_module(path)
154 return getattr(module, function)
155
156 def parse(self):
157 """
158 Parses format string looking for substitutions
159
160 This method is responsible for returning a list of fields (as strings)
161 to include in all log messages.
162 """
163 standard_formatters = re.compile(r'\((.+?)\)', re.IGNORECASE)
164 return standard_formatters.findall(self._fmt)
165
166 def add_fields(self, log_record, record, message_dict):
167 """
168 Override this method to implement custom logic for adding fields.
169 """
170 for field in self._required_fields:
171 log_record[field] = record.__dict__.get(field)
172 log_record.update(message_dict)
173 merge_record_extra(record, log_record, reserved=self._skip_fields)
174
175 if self.timestamp:
176 key = self.timestamp if type(self.timestamp) == str else 'timestamp'
177 log_record[key] = datetime.fromtimestamp(record.created, tz=utc)
178
179 def process_log_record(self, log_record):
180 """
181 Override this method to implement custom logic
182 on the possibly ordered dictionary.
183 """
184 return log_record
185
186 def jsonify_log_record(self, log_record):
187 """Returns a json string of the log record."""
188 return self.json_serializer(log_record,
189 default=self.json_default,
190 cls=self.json_encoder,
191 indent=self.json_indent,
192 ensure_ascii=self.json_ensure_ascii)
193
194 def serialize_log_record(self, log_record):
195 """Returns the final representation of the log record."""
196 return "%s%s" % (self.prefix, self.jsonify_log_record(log_record))
197
198 def format(self, record):
199 """Formats a log record and serializes to json"""
200 message_dict = {}
201 # FIXME: logging.LogRecord.msg and logging.LogRecord.message in typeshed
202 # are always type of str. We shouldn't need to override that.
203 if isinstance(record.msg, dict):
204 message_dict = record.msg
205 record.message = None
206 else:
207 record.message = record.getMessage()
208 # only format time if needed
209 if "asctime" in self._required_fields:
210 record.asctime = self.formatTime(record, self.datefmt)
211
212 # Display formatted exception, but allow overriding it in the
213 # user-supplied dict.
214 if record.exc_info and not message_dict.get('exc_info'):
215 message_dict['exc_info'] = self.formatException(record.exc_info)
216 if not message_dict.get('exc_info') and record.exc_text:
217 message_dict['exc_info'] = record.exc_text
218 # Display formatted record of stack frames
219 # default format is a string returned from :func:`traceback.print_stack`
220 try:
221 if record.stack_info and not message_dict.get('stack_info'):
222 message_dict['stack_info'] = self.formatStack(record.stack_info)
223 except AttributeError:
224 # Python2.7 doesn't have stack_info.
225 pass
226
227 try:
228 log_record = OrderedDict()
229 except NameError:
230 log_record = {}
231
232 _inject_req_id(record, with_prefix=False)
233 self.add_fields(log_record, record, message_dict)
234 log_record = self.process_log_record(log_record)
235
236 return self.serialize_log_record(log_record)
@@ -1,186 +1,187 b''
1 # -*- coding: utf-8 -*-
1 # -*- coding: utf-8 -*-
2
2
3 # Copyright (C) 2010-2020 RhodeCode GmbH
3 # Copyright (C) 2010-2020 RhodeCode GmbH
4 #
4 #
5 # This program is free software: you can redistribute it and/or modify
5 # This program is free software: you can redistribute it and/or modify
6 # it under the terms of the GNU Affero General Public License, version 3
6 # it under the terms of the GNU Affero General Public License, version 3
7 # (only), as published by the Free Software Foundation.
7 # (only), as published by the Free Software Foundation.
8 #
8 #
9 # This program is distributed in the hope that it will be useful,
9 # This program is distributed in the hope that it will be useful,
10 # but WITHOUT ANY WARRANTY; without even the implied warranty of
10 # but WITHOUT ANY WARRANTY; without even the implied warranty of
11 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
11 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
12 # GNU General Public License for more details.
12 # GNU General Public License for more details.
13 #
13 #
14 # You should have received a copy of the GNU Affero General Public License
14 # You should have received a copy of the GNU Affero General Public License
15 # along with this program. If not, see <http://www.gnu.org/licenses/>.
15 # along with this program. If not, see <http://www.gnu.org/licenses/>.
16 #
16 #
17 # This program is dual-licensed. If you wish to learn more about the
17 # This program is dual-licensed. If you wish to learn more about the
18 # RhodeCode Enterprise Edition, including its added features, Support services,
18 # RhodeCode Enterprise Edition, including its added features, Support services,
19 # and proprietary license terms, please see https://rhodecode.com/licenses/
19 # and proprietary license terms, please see https://rhodecode.com/licenses/
20
20
21 import sys
21 import sys
22 import logging
22 import logging
23
23
24
24
25 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE = xrange(30, 38)
25 BLACK, RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE = xrange(30, 38)
26
26
27 # Sequences
27 # Sequences
28 RESET_SEQ = "\033[0m"
28 RESET_SEQ = "\033[0m"
29 COLOR_SEQ = "\033[0;%dm"
29 COLOR_SEQ = "\033[0;%dm"
30 BOLD_SEQ = "\033[1m"
30 BOLD_SEQ = "\033[1m"
31
31
32 COLORS = {
32 COLORS = {
33 'CRITICAL': MAGENTA,
33 'CRITICAL': MAGENTA,
34 'ERROR': RED,
34 'ERROR': RED,
35 'WARNING': CYAN,
35 'WARNING': CYAN,
36 'INFO': GREEN,
36 'INFO': GREEN,
37 'DEBUG': BLUE,
37 'DEBUG': BLUE,
38 'SQL': YELLOW
38 'SQL': YELLOW
39 }
39 }
40
40
41
41
42 def _inject_req_id(record, with_prefix=True):
43 from pyramid.threadlocal import get_current_request
44 dummy = '00000000-0000-0000-0000-000000000000'
45 req_id = None
46
47 req = get_current_request()
48 if req:
49 req_id = getattr(req, 'req_id', None)
50 if with_prefix:
51 req_id = 'req_id:%-36s' % (req_id or dummy)
52 else:
53 req_id = (req_id or dummy)
54 record.req_id = req_id
55
56
57 def _add_log_to_debug_bucket(formatted_record):
58 from pyramid.threadlocal import get_current_request
59 req = get_current_request()
60 if req:
61 req.req_id_bucket.append(formatted_record)
62
63
42 def one_space_trim(s):
64 def one_space_trim(s):
43 if s.find(" ") == -1:
65 if s.find(" ") == -1:
44 return s
66 return s
45 else:
67 else:
46 s = s.replace(' ', ' ')
68 s = s.replace(' ', ' ')
47 return one_space_trim(s)
69 return one_space_trim(s)
48
70
49
71
50 def format_sql(sql):
72 def format_sql(sql):
51 sql = sql.replace('\n', '')
73 sql = sql.replace('\n', '')
52 sql = one_space_trim(sql)
74 sql = one_space_trim(sql)
53 sql = sql\
75 sql = sql\
54 .replace(',', ',\n\t')\
76 .replace(',', ',\n\t')\
55 .replace('SELECT', '\n\tSELECT \n\t')\
77 .replace('SELECT', '\n\tSELECT \n\t')\
56 .replace('UPDATE', '\n\tUPDATE \n\t')\
78 .replace('UPDATE', '\n\tUPDATE \n\t')\
57 .replace('DELETE', '\n\tDELETE \n\t')\
79 .replace('DELETE', '\n\tDELETE \n\t')\
58 .replace('FROM', '\n\tFROM')\
80 .replace('FROM', '\n\tFROM')\
59 .replace('ORDER BY', '\n\tORDER BY')\
81 .replace('ORDER BY', '\n\tORDER BY')\
60 .replace('LIMIT', '\n\tLIMIT')\
82 .replace('LIMIT', '\n\tLIMIT')\
61 .replace('WHERE', '\n\tWHERE')\
83 .replace('WHERE', '\n\tWHERE')\
62 .replace('AND', '\n\tAND')\
84 .replace('AND', '\n\tAND')\
63 .replace('LEFT', '\n\tLEFT')\
85 .replace('LEFT', '\n\tLEFT')\
64 .replace('INNER', '\n\tINNER')\
86 .replace('INNER', '\n\tINNER')\
65 .replace('INSERT', '\n\tINSERT')\
87 .replace('INSERT', '\n\tINSERT')\
66 .replace('DELETE', '\n\tDELETE')
88 .replace('DELETE', '\n\tDELETE')
67 return sql
89 return sql
68
90
69
91
70 class ExceptionAwareFormatter(logging.Formatter):
92 class ExceptionAwareFormatter(logging.Formatter):
71 """
93 """
72 Extended logging formatter which prints out remote tracebacks.
94 Extended logging formatter which prints out remote tracebacks.
73 """
95 """
74
96
75 def formatException(self, ei):
97 def formatException(self, ei):
76 ex_type, ex_value, ex_tb = ei
98 ex_type, ex_value, ex_tb = ei
77
99
78 local_tb = logging.Formatter.formatException(self, ei)
100 local_tb = logging.Formatter.formatException(self, ei)
79 if hasattr(ex_value, '_vcs_server_traceback'):
101 if hasattr(ex_value, '_vcs_server_traceback'):
80
102
81 def formatRemoteTraceback(remote_tb_lines):
103 def formatRemoteTraceback(remote_tb_lines):
82 result = ["\n +--- This exception occured remotely on VCSServer - Remote traceback:\n\n"]
104 result = ["\n +--- This exception occured remotely on VCSServer - Remote traceback:\n\n"]
83 result.append(remote_tb_lines)
105 result.append(remote_tb_lines)
84 result.append("\n +--- End of remote traceback\n")
106 result.append("\n +--- End of remote traceback\n")
85 return result
107 return result
86
108
87 try:
109 try:
88 if ex_type is not None and ex_value is None and ex_tb is None:
110 if ex_type is not None and ex_value is None and ex_tb is None:
89 # possible old (3.x) call syntax where caller is only
111 # possible old (3.x) call syntax where caller is only
90 # providing exception object
112 # providing exception object
91 if type(ex_type) is not type:
113 if type(ex_type) is not type:
92 raise TypeError(
114 raise TypeError(
93 "invalid argument: ex_type should be an exception "
115 "invalid argument: ex_type should be an exception "
94 "type, or just supply no arguments at all")
116 "type, or just supply no arguments at all")
95 if ex_type is None and ex_tb is None:
117 if ex_type is None and ex_tb is None:
96 ex_type, ex_value, ex_tb = sys.exc_info()
118 ex_type, ex_value, ex_tb = sys.exc_info()
97
119
98 remote_tb = getattr(ex_value, "_vcs_server_traceback", None)
120 remote_tb = getattr(ex_value, "_vcs_server_traceback", None)
99
121
100 if remote_tb:
122 if remote_tb:
101 remote_tb = formatRemoteTraceback(remote_tb)
123 remote_tb = formatRemoteTraceback(remote_tb)
102 return local_tb + ''.join(remote_tb)
124 return local_tb + ''.join(remote_tb)
103 finally:
125 finally:
104 # clean up cycle to traceback, to allow proper GC
126 # clean up cycle to traceback, to allow proper GC
105 del ex_type, ex_value, ex_tb
127 del ex_type, ex_value, ex_tb
106
128
107 return local_tb
129 return local_tb
108
130
109
131
110 class ColorFormatter(ExceptionAwareFormatter):
111
112 def format(self, record):
113 """
114 Changes record's levelname to use with COLORS enum
115 """
116
117 levelname = record.levelname
118 start = COLOR_SEQ % (COLORS[levelname])
119 def_record = logging.Formatter.format(self, record)
120 end = RESET_SEQ
121
122 colored_record = ''.join([start, def_record, end])
123 return colored_record
124
125
126 def _inject_req_id(record):
127 from pyramid.threadlocal import get_current_request
128 dummy = '00000000-0000-0000-0000-000000000000'
129 req_id = None
130
131 req = get_current_request()
132 if req:
133 req_id = getattr(req, 'req_id', None)
134
135 req_id = 'req_id:%-36s' % (req_id or dummy)
136 record.req_id = req_id
137
138
139 def _add_log_to_debug_bucket(formatted_record):
140 from pyramid.threadlocal import get_current_request
141 req = get_current_request()
142 if req:
143 req.req_id_bucket.append(formatted_record)
144
145
146 class RequestTrackingFormatter(ExceptionAwareFormatter):
132 class RequestTrackingFormatter(ExceptionAwareFormatter):
147 def format(self, record):
133 def format(self, record):
148 _inject_req_id(record)
134 _inject_req_id(record)
149 def_record = logging.Formatter.format(self, record)
135 def_record = logging.Formatter.format(self, record)
150 _add_log_to_debug_bucket(def_record)
136 _add_log_to_debug_bucket(def_record)
151 return def_record
137 return def_record
152
138
153
139
154 class ColorRequestTrackingFormatter(ColorFormatter):
140 class ColorFormatter(ExceptionAwareFormatter):
155
141
156 def format(self, record):
142 def format(self, record):
157 """
143 """
158 Changes record's levelname to use with COLORS enum
144 Changes record's levelname to use with COLORS enum
159 """
145 """
160 _inject_req_id(record)
146 def_record = super(ColorFormatter, self).format(record)
147
161 levelname = record.levelname
148 levelname = record.levelname
162 start = COLOR_SEQ % (COLORS[levelname])
149 start = COLOR_SEQ % (COLORS[levelname])
163 def_record = logging.Formatter.format(self, record)
164 end = RESET_SEQ
150 end = RESET_SEQ
165
151
166 colored_record = ''.join([start, def_record, end])
152 colored_record = ''.join([start, def_record, end])
167 _add_log_to_debug_bucket(def_record)
153 return colored_record
154
155
156 class ColorRequestTrackingFormatter(RequestTrackingFormatter):
157
158 def format(self, record):
159 """
160 Changes record's levelname to use with COLORS enum
161 """
162 def_record = super(ColorRequestTrackingFormatter, self).format(record)
163
164 levelname = record.levelname
165 start = COLOR_SEQ % (COLORS[levelname])
166 end = RESET_SEQ
167
168 colored_record = ''.join([start, def_record, end])
168 return colored_record
169 return colored_record
169
170
170
171
171 class ColorFormatterSql(logging.Formatter):
172 class ColorFormatterSql(logging.Formatter):
172
173
173 def format(self, record):
174 def format(self, record):
174 """
175 """
175 Changes record's levelname to use with COLORS enum
176 Changes record's levelname to use with COLORS enum
176 """
177 """
177
178
178 start = COLOR_SEQ % (COLORS['SQL'])
179 start = COLOR_SEQ % (COLORS['SQL'])
179 def_record = format_sql(logging.Formatter.format(self, record))
180 def_record = format_sql(logging.Formatter.format(self, record))
180 end = RESET_SEQ
181 end = RESET_SEQ
181
182
182 colored_record = ''.join([start, def_record, end])
183 colored_record = ''.join([start, def_record, end])
183 return colored_record
184 return colored_record
184
185
185 # marcink: needs to stay with this name for backward .ini compatability
186 # marcink: needs to stay with this name for backward .ini compatability
186 Pyro4AwareFormatter = ExceptionAwareFormatter
187 Pyro4AwareFormatter = ExceptionAwareFormatter
General Comments 0
You need to be logged in to leave comments. Login now