Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 1 | # osmo_gsm_tester: global logging |
| 2 | # |
| 3 | # Copyright (C) 2016-2017 by sysmocom - s.f.m.c. GmbH |
| 4 | # |
| 5 | # Author: Neels Hofmeyr <neels@hofmeyr.de> |
| 6 | # |
| 7 | # This program is free software: you can redistribute it and/or modify |
| 8 | # it under the terms of the GNU Affero General Public License as |
| 9 | # published by the Free Software Foundation, either version 3 of the |
| 10 | # License, or (at your option) any later version. |
| 11 | # |
| 12 | # This program is distributed in the hope that it will be useful, |
| 13 | # but WITHOUT ANY WARRANTY; without even the implied warranty of |
| 14 | # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the |
| 15 | # GNU Affero General Public License for more details. |
| 16 | # |
| 17 | # You should have received a copy of the GNU Affero General Public License |
| 18 | # along with this program. If not, see <http://www.gnu.org/licenses/>. |
| 19 | |
| 20 | import os |
| 21 | import sys |
| 22 | import time |
| 23 | import traceback |
| 24 | import contextlib |
| 25 | from inspect import getframeinfo, stack |
| 26 | |
Neels Hofmeyr | 2694a9d | 2017-04-27 19:48:09 +0200 | [diff] [blame] | 27 | from .util import is_dict |
| 28 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 29 | L_ERR = 30 |
| 30 | L_LOG = 20 |
| 31 | L_DBG = 10 |
| 32 | L_TRACEBACK = 'TRACEBACK' |
| 33 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 34 | LEVEL_STRS = { |
| 35 | 'err': L_ERR, |
| 36 | 'log': L_LOG, |
| 37 | 'dbg': L_DBG, |
| 38 | } |
| 39 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 40 | C_NET = 'net' |
| 41 | C_RUN = 'run' |
| 42 | C_TST = 'tst' |
| 43 | C_CNF = 'cnf' |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 44 | C_BUS = 'bus' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 45 | C_DEFAULT = '---' |
| 46 | |
| 47 | LONG_DATEFMT = '%Y-%m-%d_%H:%M:%S' |
| 48 | DATEFMT = '%H:%M:%S' |
| 49 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 50 | # may be overridden by regression tests |
| 51 | get_process_id = lambda: '%d-%d' % (os.getpid(), time.time()) |
| 52 | |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 53 | class Error(Exception): |
| 54 | pass |
| 55 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 56 | class LogTarget: |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 57 | all_targets = [] |
| 58 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 59 | do_log_time = None |
| 60 | do_log_category = None |
| 61 | do_log_level = None |
| 62 | do_log_origin = None |
| 63 | do_log_traceback = None |
| 64 | do_log_src = None |
| 65 | origin_width = None |
| 66 | origin_fmt = None |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 67 | all_levels = None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 68 | |
| 69 | # redirected by logging test |
| 70 | get_time_str = lambda self: time.strftime(self.log_time_fmt) |
| 71 | |
| 72 | # sink that gets each complete logging line |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 73 | log_write_func = None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 74 | |
| 75 | category_levels = None |
| 76 | |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 77 | def __init__(self, log_write_func=None): |
| 78 | if log_write_func is None: |
| 79 | log_write_func = sys.__stdout__.write |
| 80 | self.log_write_func = log_write_func |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 81 | self.category_levels = {} |
| 82 | self.style() |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 83 | LogTarget.all_targets.append(self) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 84 | |
| 85 | def style(self, time=True, time_fmt=DATEFMT, category=True, level=True, origin=True, origin_width=0, src=True, trace=False): |
| 86 | ''' |
| 87 | set all logging format aspects, to defaults if not passed: |
| 88 | time: log timestamps; |
| 89 | time_fmt: format of timestamps; |
| 90 | category: print the logging category (three letters); |
| 91 | level: print the logging level, unless it is L_LOG; |
| 92 | origin: print which object(s) the message originated from; |
| 93 | origin_width: fill up the origin string with whitespace to this witdh; |
| 94 | src: log the source file and line number the log comes from; |
| 95 | trace: on exceptions, log the full stack trace; |
| 96 | ''' |
| 97 | self.log_time_fmt = time_fmt |
| 98 | self.do_log_time = bool(time) |
| 99 | if not self.log_time_fmt: |
| 100 | self.do_log_time = False |
| 101 | self.do_log_category = bool(category) |
| 102 | self.do_log_level = bool(level) |
| 103 | self.do_log_origin = bool(origin) |
| 104 | self.origin_width = int(origin_width) |
| 105 | self.origin_fmt = '{:>%ds}' % self.origin_width |
| 106 | self.do_log_src = src |
| 107 | self.do_log_traceback = trace |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame^] | 108 | return self |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 109 | |
| 110 | def style_change(self, time=None, time_fmt=None, category=None, level=None, origin=None, origin_width=None, src=None, trace=None): |
| 111 | 'modify only the given aspects of the logging format' |
| 112 | self.style( |
| 113 | time=(time if time is not None else self.do_log_time), |
| 114 | time_fmt=(time_fmt if time_fmt is not None else self.log_time_fmt), |
| 115 | category=(category if category is not None else self.do_log_category), |
| 116 | level=(level if level is not None else self.do_log_level), |
| 117 | origin=(origin if origin is not None else self.do_log_origin), |
| 118 | origin_width=(origin_width if origin_width is not None else self.origin_width), |
| 119 | src=(src if src is not None else self.do_log_src), |
| 120 | trace=(trace if trace is not None else self.do_log_traceback), |
| 121 | ) |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame^] | 122 | return self |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 123 | |
| 124 | def set_level(self, category, level): |
| 125 | 'set global logging log.L_* level for a given log.C_* category' |
| 126 | self.category_levels[category] = level |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame^] | 127 | return self |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 128 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 129 | def set_all_levels(self, level): |
| 130 | self.all_levels = level |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame^] | 131 | return self |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 132 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 133 | def is_enabled(self, category, level): |
| 134 | if level == L_TRACEBACK: |
| 135 | return self.do_log_traceback |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 136 | if self.all_levels is not None: |
| 137 | is_level = self.all_levels |
| 138 | else: |
| 139 | is_level = self.category_levels.get(category) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 140 | if is_level is None: |
| 141 | is_level = L_LOG |
| 142 | if level < is_level: |
| 143 | return False |
| 144 | return True |
| 145 | |
| 146 | def log(self, origin, category, level, src, messages, named_items): |
| 147 | if category and len(category) != 3: |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 148 | self.log_write_func('WARNING: INVALID LOG SUBSYSTEM %r\n' % category) |
| 149 | self.log_write_func('origin=%r category=%r level=%r\n' % (origin, category, level)); |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 150 | |
| 151 | if not category: |
| 152 | category = C_DEFAULT |
| 153 | if not self.is_enabled(category, level): |
| 154 | return |
| 155 | |
| 156 | log_pre = [] |
| 157 | if self.do_log_time: |
| 158 | log_pre.append(self.get_time_str()) |
| 159 | |
| 160 | if self.do_log_category: |
| 161 | log_pre.append(category) |
| 162 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 163 | deeper_origins = '' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 164 | if self.do_log_origin: |
| 165 | if origin is None: |
| 166 | name = '-' |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 167 | elif isinstance(origin, Origins): |
| 168 | name = origin[-1] |
| 169 | if len(origin) > 1: |
| 170 | deeper_origins = str(origin) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 171 | elif isinstance(origin, str): |
| 172 | name = origin or None |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 173 | elif hasattr(origin, 'name'): |
| 174 | name = origin.name() |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 175 | if not name: |
| 176 | name = str(origin.__class__.__name__) |
| 177 | log_pre.append(self.origin_fmt.format(name)) |
| 178 | |
| 179 | if self.do_log_level and level != L_LOG: |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 180 | loglevel = '%s: ' % (level_str(level) or ('loglevel=' + str(level))) |
| 181 | else: |
| 182 | loglevel = '' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 183 | |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 184 | log_line = [compose_message(messages, named_items)] |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 185 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 186 | if deeper_origins: |
| 187 | log_line.append(' [%s]' % deeper_origins) |
| 188 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 189 | if self.do_log_src and src: |
| 190 | log_line.append(' [%s]' % str(src)) |
| 191 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 192 | log_str = '%s%s%s%s' % (' '.join(log_pre), |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 193 | ': ' if log_pre else '', |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 194 | loglevel, |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 195 | ' '.join(log_line)) |
| 196 | |
Neels Hofmeyr | 5356d0a | 2017-04-10 03:45:30 +0200 | [diff] [blame] | 197 | if not log_str.endswith('\n'): |
| 198 | log_str = log_str + '\n' |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 199 | self.log_write_func(log_str) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 200 | |
Your Name | 44af341 | 2017-04-13 03:11:59 +0200 | [diff] [blame] | 201 | def large_separator(self, *msgs): |
| 202 | msg = ' '.join(msgs) |
| 203 | if not msg: |
| 204 | msg = '------------------------------------------' |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 205 | self.log_write_func('------------------------------------------\n' |
| 206 | '%s\n' |
| 207 | '------------------------------------------\n' % msg) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 208 | |
| 209 | def level_str(level): |
| 210 | if level == L_TRACEBACK: |
| 211 | return L_TRACEBACK |
| 212 | if level <= L_DBG: |
| 213 | return 'DBG' |
| 214 | if level <= L_LOG: |
| 215 | return 'LOG' |
| 216 | return 'ERR' |
| 217 | |
| 218 | def _log_all_targets(origin, category, level, src, messages, named_items=None): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 219 | if origin is None: |
| 220 | origin = Origin._global_current_origin |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 221 | if isinstance(src, int): |
| 222 | src = get_src_from_caller(src + 1) |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 223 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 224 | target.log(origin, category, level, src, messages, named_items) |
| 225 | |
Your Name | 44af341 | 2017-04-13 03:11:59 +0200 | [diff] [blame] | 226 | def large_separator(*msgs): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 227 | for target in LogTarget.all_targets: |
Your Name | 44af341 | 2017-04-13 03:11:59 +0200 | [diff] [blame] | 228 | target.large_separator(*msgs) |
| 229 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 230 | def get_src_from_caller(levels_up=1): |
| 231 | caller = getframeinfo(stack()[levels_up][0]) |
| 232 | return '%s:%d' % (os.path.basename(caller.filename), caller.lineno) |
| 233 | |
| 234 | def get_src_from_tb(tb, levels_up=1): |
| 235 | ftb = traceback.extract_tb(tb) |
| 236 | f,l,m,c = ftb[-levels_up] |
| 237 | f = os.path.basename(f) |
| 238 | return '%s:%s: %s' % (f, l, c) |
| 239 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 240 | def get_line_for_src(src_path): |
| 241 | etype, exception, tb = sys.exc_info() |
| 242 | if tb: |
| 243 | ftb = traceback.extract_tb(tb) |
| 244 | for f,l,m,c in ftb: |
| 245 | if f.endswith(src_path): |
| 246 | return l |
| 247 | |
| 248 | for frame in stack(): |
| 249 | caller = getframeinfo(frame[0]) |
| 250 | if caller.filename.endswith(src_path): |
| 251 | return caller.lineno |
| 252 | return None |
| 253 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 254 | |
| 255 | class Origin: |
| 256 | ''' |
| 257 | Base class for all classes that want to log, |
| 258 | and to add an origin string to a code path: |
| 259 | with log.Origin('my name'): |
| 260 | raise Problem() |
| 261 | This will log 'my name' as an origin for the Problem. |
| 262 | ''' |
| 263 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 264 | _global_current_origin = None |
| 265 | _global_id = None |
| 266 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 267 | _log_category = None |
| 268 | _src = None |
| 269 | _name = None |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 270 | _origin_id = None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 271 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 272 | _parent_origin = None |
| 273 | |
| 274 | def __init__(self, *name_items, category=None, **detail_items): |
| 275 | self.set_log_category(category) |
| 276 | self.set_name(*name_items, **detail_items) |
| 277 | |
| 278 | def set_name(self, *name_items, **detail_items): |
| 279 | if name_items: |
| 280 | name = '-'.join([str(i) for i in name_items]) |
| 281 | elif not detail_items: |
| 282 | name = self.__class__.__name__ |
| 283 | else: |
| 284 | name = '' |
| 285 | if detail_items: |
| 286 | details = '(%s)' % (', '.join([("%s=%r" % (k,v)) |
| 287 | for k,v in sorted(detail_items.items())])) |
| 288 | else: |
| 289 | details = '' |
| 290 | self._name = name + details |
| 291 | |
| 292 | def name(self): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 293 | return self._name or self.__class__.__name__ |
| 294 | |
| 295 | __str__ = name |
| 296 | __repr__ = name |
| 297 | |
| 298 | def origin_id(self): |
| 299 | if not self._origin_id: |
| 300 | if not Origin._global_id: |
| 301 | Origin._global_id = get_process_id() |
| 302 | self._origin_id = '%s-%s' % (self.name(), Origin._global_id) |
| 303 | return self._origin_id |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 304 | |
| 305 | def set_log_category(self, category): |
| 306 | self._log_category = category |
| 307 | |
| 308 | def _log(self, level, messages, named_items=None, src_levels_up=3, origins=None): |
| 309 | src = self._src or src_levels_up |
| 310 | origin = origins or self.gather_origins() |
| 311 | _log_all_targets(origin, self._log_category, level, src, messages, named_items) |
| 312 | |
| 313 | def dbg(self, *messages, **named_items): |
| 314 | self._log(L_DBG, messages, named_items) |
| 315 | |
| 316 | def log(self, *messages, **named_items): |
| 317 | self._log(L_LOG, messages, named_items) |
| 318 | |
| 319 | def err(self, *messages, **named_items): |
| 320 | self._log(L_ERR, messages, named_items) |
| 321 | |
| 322 | def log_exn(self, exc_info=None): |
| 323 | log_exn(self, self._log_category, exc_info) |
| 324 | |
| 325 | def __enter__(self): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 326 | if not self.set_child_of(Origin._global_current_origin): |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 327 | return |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 328 | Origin._global_current_origin = self |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 329 | |
| 330 | def __exit__(self, *exc_info): |
| 331 | rc = None |
| 332 | if exc_info[0] is not None: |
| 333 | rc = exn_add_info(exc_info, self) |
| 334 | Origin._global_current_origin, self._parent_origin = self._parent_origin, None |
| 335 | return rc |
| 336 | |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 337 | def raise_exn(self, *messages, exn_class=Error, **named_items): |
| 338 | with self: |
| 339 | raise exn_class(compose_message(messages, named_items)) |
| 340 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 341 | def redirect_stdout(self): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 342 | return contextlib.redirect_stdout(SafeRedirectStdout(self)) |
| 343 | |
| 344 | def gather_origins(self): |
| 345 | origins = Origins() |
| 346 | origins.add(self) |
| 347 | origin = self._parent_origin |
| 348 | if origin is None and Origin._global_current_origin is not None: |
| 349 | origin = Origin._global_current_origin |
| 350 | while origin is not None: |
| 351 | origins.add(origin) |
| 352 | origin = origin._parent_origin |
| 353 | return origins |
| 354 | |
| 355 | def set_child_of(self, parent_origin): |
| 356 | # avoid loops |
| 357 | if self._parent_origin is not None: |
| 358 | return False |
| 359 | if parent_origin == self: |
| 360 | return False |
| 361 | self._parent_origin = parent_origin |
| 362 | return True |
| 363 | |
| 364 | class LineInfo(Origin): |
| 365 | def __init__(self, src_file, *name_items, **detail_items): |
| 366 | self.src_file = src_file |
| 367 | self.set_name(*name_items, **detail_items) |
| 368 | |
| 369 | def name(self): |
| 370 | l = get_line_for_src(self.src_file) |
| 371 | if l is not None: |
| 372 | return '%s:%s' % (self._name, l) |
| 373 | return super().name() |
| 374 | |
| 375 | class SafeRedirectStdout: |
| 376 | ''' |
| 377 | To be able to use 'print' in test scripts, this is used to redirect stdout |
| 378 | to a test class' log() function. However, it turns out doing that breaks |
| 379 | python debugger sessions -- it uses extended features of stdout, and will |
| 380 | fail dismally if it finds this wrapper in sys.stdout. Luckily, overriding |
| 381 | __getattr__() to return the original sys.__stdout__ attributes for anything |
| 382 | else than write() makes the debugger session work nicely again! |
| 383 | ''' |
| 384 | _log_line_buf = None |
| 385 | |
| 386 | def __init__(self, origin): |
| 387 | self._origin = origin |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 388 | |
| 389 | def write(self, message): |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 390 | lines = message.splitlines() |
| 391 | if not lines: |
| 392 | return |
| 393 | if self._log_line_buf: |
| 394 | lines[0] = self._log_line_buf + lines[0] |
| 395 | self._log_line_buf = None |
| 396 | if not message.endswith('\n'): |
| 397 | self._log_line_buf = lines[-1] |
| 398 | lines = lines[:-1] |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 399 | origins = self._origin.gather_origins() |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 400 | for line in lines: |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 401 | self._origin._log(L_LOG, (line,), origins=origins) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 402 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 403 | def __getattr__(self, name): |
| 404 | return sys.__stdout__.__getattribute__(name) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 405 | |
| 406 | |
| 407 | def dbg(origin, category, *messages, **named_items): |
| 408 | _log_all_targets(origin, category, L_DBG, 2, messages, named_items) |
| 409 | |
| 410 | def log(origin, category, *messages, **named_items): |
| 411 | _log_all_targets(origin, category, L_LOG, 2, messages, named_items) |
| 412 | |
| 413 | def err(origin, category, *messages, **named_items): |
| 414 | _log_all_targets(origin, category, L_ERR, 2, messages, named_items) |
| 415 | |
| 416 | def trace(origin, category, exc_info): |
| 417 | _log_all_targets(origin, category, L_TRACEBACK, None, |
| 418 | traceback.format_exception(*exc_info)) |
| 419 | |
| 420 | def resolve_category(origin, category): |
| 421 | if category is not None: |
| 422 | return category |
| 423 | if not hasattr(origin, '_log_category'): |
| 424 | return None |
| 425 | return origin._log_category |
| 426 | |
| 427 | def exn_add_info(exc_info, origin, category=None): |
| 428 | etype, exception, tb = exc_info |
| 429 | if not hasattr(exception, 'origins'): |
| 430 | exception.origins = Origins() |
| 431 | if not hasattr(exception, 'category'): |
| 432 | # only remember the deepest category |
| 433 | exception.category = resolve_category(origin, category) |
| 434 | if not hasattr(exception, 'src'): |
| 435 | exception.src = get_src_from_tb(tb) |
| 436 | exception.origins.add(origin) |
| 437 | return False |
| 438 | |
| 439 | |
| 440 | |
| 441 | def log_exn(origin=None, category=None, exc_info=None): |
| 442 | if not (exc_info is not None and len(exc_info) == 3): |
| 443 | exc_info = sys.exc_info() |
| 444 | if not (exc_info is not None and len(exc_info) == 3): |
| 445 | raise RuntimeError('invalid call to log_exn() -- no valid exception info') |
| 446 | |
| 447 | etype, exception, tb = exc_info |
| 448 | |
| 449 | # if there are origins recorded with the Exception, prefer that |
| 450 | if hasattr(exception, 'origins'): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 451 | origin = exception.origins |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 452 | |
| 453 | # if there is a category recorded with the Exception, prefer that |
| 454 | if hasattr(exception, 'category'): |
| 455 | category = exception.category |
| 456 | |
| 457 | if hasattr(exception, 'msg'): |
| 458 | msg = exception.msg |
| 459 | else: |
| 460 | msg = str(exception) |
| 461 | |
| 462 | if hasattr(exception, 'src'): |
| 463 | src = exception.src |
| 464 | else: |
| 465 | src = 2 |
| 466 | |
| 467 | trace(origin, category, exc_info) |
| 468 | _log_all_targets(origin, category, L_ERR, src, |
| 469 | ('%s:' % str(etype.__name__), msg)) |
| 470 | |
| 471 | |
| 472 | class Origins(list): |
| 473 | def __init__(self, origin=None): |
| 474 | if origin is not None: |
| 475 | self.add(origin) |
| 476 | def add(self, origin): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 477 | if hasattr(origin, 'name'): |
| 478 | origin_str = origin.name() |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 479 | else: |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 480 | origin_str = repr(origin) |
| 481 | if origin_str is None: |
| 482 | raise RuntimeError('origin_str is None for %r' % origin) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 483 | self.insert(0, origin_str) |
| 484 | def __str__(self): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 485 | return '↪'.join(self) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 486 | |
| 487 | |
| 488 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 489 | def set_all_levels(level): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 490 | for target in LogTarget.all_targets: |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 491 | target.set_all_levels(level) |
| 492 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 493 | def set_level(category, level): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 494 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 495 | target.set_level(category, level) |
| 496 | |
| 497 | def style(**kwargs): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 498 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 499 | target.style(**kwargs) |
| 500 | |
| 501 | def style_change(**kwargs): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 502 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 503 | target.style_change(**kwargs) |
| 504 | |
| 505 | class TestsTarget(LogTarget): |
| 506 | 'LogTarget producing deterministic results for regression tests' |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 507 | def __init__(self, log_write_func=None): |
| 508 | super().__init__(log_write_func) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 509 | self.style(time=False, src=False) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 510 | |
| 511 | def run_logging_exceptions(func, *func_args, return_on_failure=None, **func_kwargs): |
| 512 | try: |
| 513 | return func(*func_args, **func_kwargs) |
| 514 | except: |
| 515 | log_exn() |
| 516 | return return_on_failure |
| 517 | |
Neels Hofmeyr | 2694a9d | 2017-04-27 19:48:09 +0200 | [diff] [blame] | 518 | def _compose_named_items(item): |
| 519 | 'make sure dicts are output sorted, for test expectations' |
| 520 | if is_dict(item): |
| 521 | return '{%s}' % (', '.join( |
| 522 | ['%s=%s' % (k, _compose_named_items(v)) |
| 523 | for k,v in sorted(item.items())])) |
| 524 | return repr(item) |
| 525 | |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 526 | def compose_message(messages, named_items): |
| 527 | msgs = [str(m) for m in messages] |
| 528 | |
| 529 | if named_items: |
| 530 | # unfortunately needs to be sorted to get deterministic results |
Neels Hofmeyr | 2694a9d | 2017-04-27 19:48:09 +0200 | [diff] [blame] | 531 | msgs.append(_compose_named_items(named_items)) |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 532 | |
| 533 | return ' '.join(msgs) |
| 534 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 535 | # vim: expandtab tabstop=4 shiftwidth=4 |