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