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 |
Harald Welte | 2720534 | 2017-06-03 09:51:45 +0200 | [diff] [blame] | 8 | # it under the terms of the GNU General Public License as |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 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 |
Harald Welte | 2720534 | 2017-06-03 09:51:45 +0200 | [diff] [blame] | 15 | # GNU General Public License for more details. |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 16 | # |
Harald Welte | 2720534 | 2017-06-03 09:51:45 +0200 | [diff] [blame] | 17 | # You should have received a copy of the GNU General Public License |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 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 |
Pau Espin Pedrol | 0d8deec | 2017-06-23 11:43:38 +0200 | [diff] [blame] | 26 | from datetime import datetime # we need this for strftime as the one from time doesn't carry microsecond info |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 27 | from inspect import getframeinfo, stack |
| 28 | |
Neels Hofmeyr | 2694a9d | 2017-04-27 19:48:09 +0200 | [diff] [blame] | 29 | from .util import is_dict |
| 30 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 31 | L_ERR = 30 |
| 32 | L_LOG = 20 |
| 33 | L_DBG = 10 |
| 34 | L_TRACEBACK = 'TRACEBACK' |
| 35 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 36 | LEVEL_STRS = { |
| 37 | 'err': L_ERR, |
| 38 | 'log': L_LOG, |
| 39 | 'dbg': L_DBG, |
| 40 | } |
| 41 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 42 | C_NET = 'net' |
| 43 | C_RUN = 'run' |
| 44 | C_TST = 'tst' |
| 45 | C_CNF = 'cnf' |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 46 | C_BUS = 'bus' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 47 | C_DEFAULT = '---' |
| 48 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 49 | LOG_CTX_VAR = '_log_ctx_' |
| 50 | |
| 51 | def dbg(*messages, _origin=None, _category=None, _src=None, **named_items): |
| 52 | '''Log on debug level. See also log()''' |
| 53 | _log(messages, named_items, origin=_origin, category=_category, level=L_DBG, src=_src) |
| 54 | |
| 55 | def log(*messages, _origin=None, _category=None, _level=L_LOG, _src=None, **named_items): |
| 56 | '''Log a message. The origin, an Origin class instance, is normally |
| 57 | determined by stack magic, only pass _origin to override. The category is |
| 58 | taken from the origin. _src is normally an integer indicating how many |
| 59 | levels up the stack sits the interesting source file to log about, can also |
| 60 | be a string. The log message is composed of all *messages and |
| 61 | **named_items, for example: |
| 62 | log('frobnicate:', thing, key=current_key, prop=erty) |
| 63 | ''' |
| 64 | _log(messages, named_items, origin=_origin, category=_category, level=_level, src=_src) |
| 65 | |
| 66 | def err(*messages, _origin=None, _category=None, _src=None, **named_items): |
| 67 | '''Log on error level. See also log()''' |
| 68 | _log(messages, named_items, origin=_origin, category=_category, level=L_ERR, src=_src) |
| 69 | |
| 70 | def _log(messages=[], named_items={}, origin=None, category=None, level=L_LOG, src=None): |
| 71 | if origin is None: |
| 72 | origin = Origin.find_on_stack() |
| 73 | if category is None and isinstance(origin, Origin): |
| 74 | category = origin._log_category |
| 75 | if src is None: |
| 76 | # two levels up |
| 77 | src = 2 |
| 78 | if isinstance(src, int): |
| 79 | src = get_src_from_caller(src + 1) |
| 80 | for target in LogTarget.all_targets: |
| 81 | target.log(origin, category, level, src, messages, named_items) |
| 82 | |
| 83 | |
Pau Espin Pedrol | 0d8deec | 2017-06-23 11:43:38 +0200 | [diff] [blame] | 84 | LONG_DATEFMT = '%Y-%m-%d_%H:%M:%S.%f' |
| 85 | DATEFMT = '%H:%M:%S.%f' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 86 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 87 | # may be overridden by regression tests |
| 88 | get_process_id = lambda: '%d-%d' % (os.getpid(), time.time()) |
| 89 | |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 90 | class Error(Exception): |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 91 | def __init__(self, *messages, **named_items): |
| 92 | super().__init__(compose_message(messages, named_items)) |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 93 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 94 | class LogTarget: |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 95 | all_targets = [] |
| 96 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 97 | do_log_time = None |
| 98 | do_log_category = None |
| 99 | do_log_level = None |
| 100 | do_log_origin = None |
Neels Hofmeyr | 9576f5f | 2017-05-24 18:31:01 +0200 | [diff] [blame] | 101 | do_log_all_origins_on_levels = None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 102 | do_log_traceback = None |
| 103 | do_log_src = None |
| 104 | origin_width = None |
| 105 | origin_fmt = None |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 106 | all_levels = None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 107 | |
| 108 | # redirected by logging test |
Pau Espin Pedrol | 0d8deec | 2017-06-23 11:43:38 +0200 | [diff] [blame] | 109 | get_time_str = lambda self: datetime.now().strftime(self.log_time_fmt) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 110 | |
| 111 | # sink that gets each complete logging line |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 112 | log_write_func = None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 113 | |
| 114 | category_levels = None |
| 115 | |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 116 | def __init__(self, log_write_func=None): |
| 117 | if log_write_func is None: |
| 118 | log_write_func = sys.__stdout__.write |
| 119 | self.log_write_func = log_write_func |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 120 | self.category_levels = {} |
| 121 | self.style() |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 122 | LogTarget.all_targets.append(self) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 123 | |
Neels Hofmeyr | fd7b9d0 | 2017-05-05 19:51:40 +0200 | [diff] [blame] | 124 | def remove(self): |
| 125 | LogTarget.all_targets.remove(self) |
| 126 | |
Neels Hofmeyr | 9576f5f | 2017-05-24 18:31:01 +0200 | [diff] [blame] | 127 | def style(self, time=True, time_fmt=DATEFMT, category=True, level=True, origin=True, origin_width=32, src=True, trace=False, all_origins_on_levels=(L_ERR, L_LOG, L_DBG, L_TRACEBACK)): |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 128 | ''' |
| 129 | set all logging format aspects, to defaults if not passed: |
| 130 | time: log timestamps; |
| 131 | time_fmt: format of timestamps; |
| 132 | category: print the logging category (three letters); |
| 133 | level: print the logging level, unless it is L_LOG; |
| 134 | origin: print which object(s) the message originated from; |
| 135 | origin_width: fill up the origin string with whitespace to this witdh; |
| 136 | src: log the source file and line number the log comes from; |
| 137 | trace: on exceptions, log the full stack trace; |
Neels Hofmeyr | 9576f5f | 2017-05-24 18:31:01 +0200 | [diff] [blame] | 138 | all_origins_on_levels: pass a tuple of logging levels that should have a full trace of origins |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 139 | ''' |
| 140 | self.log_time_fmt = time_fmt |
| 141 | self.do_log_time = bool(time) |
| 142 | if not self.log_time_fmt: |
| 143 | self.do_log_time = False |
| 144 | self.do_log_category = bool(category) |
| 145 | self.do_log_level = bool(level) |
| 146 | self.do_log_origin = bool(origin) |
| 147 | self.origin_width = int(origin_width) |
| 148 | self.origin_fmt = '{:>%ds}' % self.origin_width |
| 149 | self.do_log_src = src |
| 150 | self.do_log_traceback = trace |
Neels Hofmeyr | 9576f5f | 2017-05-24 18:31:01 +0200 | [diff] [blame] | 151 | self.do_log_all_origins_on_levels = tuple(all_origins_on_levels or []) |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame] | 152 | return self |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 153 | |
Neels Hofmeyr | 9576f5f | 2017-05-24 18:31:01 +0200 | [diff] [blame] | 154 | def style_change(self, time=None, time_fmt=None, category=None, level=None, origin=None, origin_width=None, src=None, trace=None, all_origins_on_levels=None): |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 155 | 'modify only the given aspects of the logging format' |
| 156 | self.style( |
| 157 | time=(time if time is not None else self.do_log_time), |
| 158 | time_fmt=(time_fmt if time_fmt is not None else self.log_time_fmt), |
| 159 | category=(category if category is not None else self.do_log_category), |
| 160 | level=(level if level is not None else self.do_log_level), |
| 161 | origin=(origin if origin is not None else self.do_log_origin), |
| 162 | origin_width=(origin_width if origin_width is not None else self.origin_width), |
| 163 | src=(src if src is not None else self.do_log_src), |
| 164 | trace=(trace if trace is not None else self.do_log_traceback), |
Neels Hofmeyr | 9576f5f | 2017-05-24 18:31:01 +0200 | [diff] [blame] | 165 | all_origins_on_levels=(all_origins_on_levels if all_origins_on_levels is not None else self.do_log_all_origins_on_levels), |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 166 | ) |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame] | 167 | return self |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 168 | |
| 169 | def set_level(self, category, level): |
| 170 | 'set global logging log.L_* level for a given log.C_* category' |
| 171 | self.category_levels[category] = level |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame] | 172 | return self |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 173 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 174 | def set_all_levels(self, level): |
| 175 | self.all_levels = level |
Neels Hofmeyr | 1a2177c | 2017-05-06 23:58:46 +0200 | [diff] [blame] | 176 | return self |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 177 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 178 | def is_enabled(self, category, level): |
| 179 | if level == L_TRACEBACK: |
| 180 | return self.do_log_traceback |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 181 | if self.all_levels is not None: |
| 182 | is_level = self.all_levels |
| 183 | else: |
| 184 | is_level = self.category_levels.get(category) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 185 | if is_level is None: |
| 186 | is_level = L_LOG |
| 187 | if level < is_level: |
| 188 | return False |
| 189 | return True |
| 190 | |
| 191 | def log(self, origin, category, level, src, messages, named_items): |
| 192 | if category and len(category) != 3: |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 193 | self.log_write_func('WARNING: INVALID LOGGING CATEGORY %r\n' % category) |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 194 | 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] | 195 | |
| 196 | if not category: |
| 197 | category = C_DEFAULT |
| 198 | if not self.is_enabled(category, level): |
| 199 | return |
| 200 | |
| 201 | log_pre = [] |
| 202 | if self.do_log_time: |
| 203 | log_pre.append(self.get_time_str()) |
| 204 | |
| 205 | if self.do_log_category: |
| 206 | log_pre.append(category) |
| 207 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 208 | deeper_origins = '' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 209 | if self.do_log_origin: |
| 210 | if origin is None: |
| 211 | name = '-' |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 212 | elif isinstance(origin, Origin): |
| 213 | name = origin.name() |
| 214 | # only log ancestry when there is more than one |
| 215 | if origin._parent is not None: |
| 216 | deeper_origins = origin.ancestry_str() |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 217 | elif isinstance(origin, str): |
| 218 | name = origin or None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 219 | if not name: |
| 220 | name = str(origin.__class__.__name__) |
| 221 | log_pre.append(self.origin_fmt.format(name)) |
| 222 | |
| 223 | if self.do_log_level and level != L_LOG: |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 224 | loglevel = '%s: ' % (level_str(level) or ('loglevel=' + str(level))) |
| 225 | else: |
| 226 | loglevel = '' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 227 | |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 228 | log_line = [compose_message(messages, named_items)] |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 229 | |
Neels Hofmeyr | 9576f5f | 2017-05-24 18:31:01 +0200 | [diff] [blame] | 230 | if deeper_origins and (level in self.do_log_all_origins_on_levels): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 231 | log_line.append(' [%s]' % deeper_origins) |
| 232 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 233 | if self.do_log_src and src: |
| 234 | log_line.append(' [%s]' % str(src)) |
| 235 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 236 | log_str = '%s%s%s%s' % (' '.join(log_pre), |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 237 | ': ' if log_pre else '', |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 238 | loglevel, |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 239 | ' '.join(log_line)) |
| 240 | |
Neels Hofmeyr | 5356d0a | 2017-04-10 03:45:30 +0200 | [diff] [blame] | 241 | if not log_str.endswith('\n'): |
| 242 | log_str = log_str + '\n' |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 243 | self.log_write_func(log_str) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 244 | |
Neels Hofmeyr | 6ccda11 | 2017-06-06 19:41:17 +0200 | [diff] [blame] | 245 | def large_separator(self, *msgs, sublevel=1, space_above=True): |
| 246 | sublevel = max(1, min(3, sublevel)) |
Your Name | 44af341 | 2017-04-13 03:11:59 +0200 | [diff] [blame] | 247 | msg = ' '.join(msgs) |
Neels Hofmeyr | 6ccda11 | 2017-06-06 19:41:17 +0200 | [diff] [blame] | 248 | sep = '-' * int(23 * (5 - sublevel)) |
Your Name | 44af341 | 2017-04-13 03:11:59 +0200 | [diff] [blame] | 249 | if not msg: |
Neels Hofmeyr | 6ccda11 | 2017-06-06 19:41:17 +0200 | [diff] [blame] | 250 | msg = sep |
| 251 | lines = [sep, msg, sep, ''] |
| 252 | if space_above: |
| 253 | lines.insert(0, '') |
| 254 | self.log_write_func('\n'.join(lines)) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 255 | |
| 256 | def level_str(level): |
| 257 | if level == L_TRACEBACK: |
| 258 | return L_TRACEBACK |
| 259 | if level <= L_DBG: |
| 260 | return 'DBG' |
| 261 | if level <= L_LOG: |
| 262 | return 'LOG' |
| 263 | return 'ERR' |
| 264 | |
| 265 | def _log_all_targets(origin, category, level, src, messages, named_items=None): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 266 | if origin is None: |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 267 | origin = Origin.find_on_stack() |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 268 | if isinstance(src, int): |
| 269 | src = get_src_from_caller(src + 1) |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 270 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 271 | target.log(origin, category, level, src, messages, named_items) |
| 272 | |
Neels Hofmeyr | 6ccda11 | 2017-06-06 19:41:17 +0200 | [diff] [blame] | 273 | def large_separator(*msgs, sublevel=1, space_above=True): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 274 | for target in LogTarget.all_targets: |
Neels Hofmeyr | 6ccda11 | 2017-06-06 19:41:17 +0200 | [diff] [blame] | 275 | target.large_separator(*msgs, sublevel=sublevel, space_above=space_above) |
Your Name | 44af341 | 2017-04-13 03:11:59 +0200 | [diff] [blame] | 276 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 277 | def get_src_from_caller(levels_up=1): |
| 278 | caller = getframeinfo(stack()[levels_up][0]) |
| 279 | return '%s:%d' % (os.path.basename(caller.filename), caller.lineno) |
| 280 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 281 | def get_src_from_exc_info(exc_info=None, levels_up=1): |
| 282 | if exc_info is None: |
| 283 | exc_info = sys.exc_info() |
| 284 | ftb = traceback.extract_tb(exc_info[2]) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 285 | f,l,m,c = ftb[-levels_up] |
| 286 | f = os.path.basename(f) |
| 287 | return '%s:%s: %s' % (f, l, c) |
| 288 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 289 | def get_line_for_src(src_path): |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 290 | '''find a given source file on the stack and return the line number for |
| 291 | that file. (Used to indicate the position in a test script.)''' |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 292 | etype, exception, tb = sys.exc_info() |
| 293 | if tb: |
| 294 | ftb = traceback.extract_tb(tb) |
| 295 | for f,l,m,c in ftb: |
| 296 | if f.endswith(src_path): |
| 297 | return l |
| 298 | |
| 299 | for frame in stack(): |
| 300 | caller = getframeinfo(frame[0]) |
| 301 | if caller.filename.endswith(src_path): |
| 302 | return caller.lineno |
| 303 | return None |
| 304 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 305 | def ctx(*name_items, **detail_items): |
| 306 | '''Store log context in the current frame. This string will appear as |
| 307 | origin information for exceptions thrown within the calling scope.''' |
| 308 | if not name_items and not detail_items: |
| 309 | ctx_obj(None) |
| 310 | if not detail_items and len(name_items) == 1 and isinstance(name_items[0], Origin): |
| 311 | ctx_obj(name_items[0]) |
| 312 | else: |
| 313 | ctx_obj(compose_message(name_items, detail_items)) |
| 314 | |
| 315 | def ctx_obj(origin_or_str): |
| 316 | f = sys._getframe(2) |
| 317 | if origin_or_str is None: |
| 318 | f.f_locals.pop(LOG_CTX_VAR, None) |
| 319 | else: |
| 320 | f.f_locals[LOG_CTX_VAR] = origin_or_str |
| 321 | |
| 322 | class OriginLoopError(Error): |
| 323 | pass |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 324 | |
| 325 | class Origin: |
| 326 | ''' |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 327 | Base class for all classes that want to appear in the log. |
| 328 | It is a simple named marker to find in the stack frames. |
| 329 | This depends on the object instance named 'self' in each member class. |
| 330 | |
| 331 | In addition, it provides a logging category and a globally unique ID for |
| 332 | each instance. |
| 333 | |
| 334 | Each child class *must* call super().__init__(category, name), to allow |
| 335 | noting its parent origins. |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 336 | ''' |
| 337 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 338 | _global_id = None |
| 339 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 340 | _name = None |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 341 | _origin_id = None |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 342 | _log_category = None |
| 343 | _parent = None |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 344 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 345 | @staticmethod |
| 346 | def find_on_stack(except_obj=None, f=None): |
| 347 | if f is None: |
| 348 | f = sys._getframe(2) |
| 349 | log_ctx_obj = None |
| 350 | origin = None |
| 351 | while f is not None: |
| 352 | l = f.f_locals |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 353 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 354 | # if there is a log_ctx in the scope, add it, pointing to the next |
| 355 | # actual Origin class in the stack |
| 356 | log_ctx = l.get(LOG_CTX_VAR) |
| 357 | if log_ctx: |
| 358 | if isinstance(log_ctx, Origin): |
| 359 | new_log_ctx_obj = log_ctx |
| 360 | else: |
| 361 | new_log_ctx_obj = Origin(None, log_ctx, find_parent=False) |
| 362 | if log_ctx_obj is None: |
| 363 | log_ctx_obj = new_log_ctx_obj |
| 364 | else: |
| 365 | log_ctx_obj.highest_ancestor()._set_parent(new_log_ctx_obj) |
| 366 | |
| 367 | obj = l.get('self') |
| 368 | if obj and isinstance(obj, Origin) and (except_obj is not obj): |
| 369 | origin = obj |
| 370 | break |
| 371 | f = f.f_back |
| 372 | |
| 373 | if (origin is not None) and (log_ctx_obj is not None): |
| 374 | log_ctx_obj.highest_ancestor()._set_parent(origin) |
| 375 | p = log_ctx_obj |
| 376 | while p: |
| 377 | p._set_log_category(origin._log_category) |
| 378 | p = p._parent |
| 379 | if log_ctx_obj is not None: |
| 380 | return log_ctx_obj |
| 381 | # may return None |
| 382 | return origin |
| 383 | |
| 384 | @staticmethod |
| 385 | def find_in_exc_info(exc_info): |
| 386 | tb = exc_info[2] |
| 387 | # get last tb ... I hope that's right |
| 388 | while tb.tb_next: |
| 389 | tb = tb.tb_next |
| 390 | return Origin.find_on_stack(f=tb.tb_frame) |
| 391 | |
| 392 | def __init__(self, category, *name_items, find_parent=True, **detail_items): |
| 393 | self._set_log_category(category) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 394 | self.set_name(*name_items, **detail_items) |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 395 | if find_parent: |
| 396 | self._set_parent(Origin.find_on_stack(except_obj=self)) |
| 397 | |
| 398 | def _set_parent(self, parent): |
| 399 | # make sure to avoid loops |
| 400 | p = parent |
| 401 | while p: |
| 402 | if p is self: |
| 403 | raise OriginLoopError('Origin parent loop') |
| 404 | p = p._parent |
| 405 | self._parent = parent |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 406 | |
| 407 | def set_name(self, *name_items, **detail_items): |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 408 | '''Change the origin's name for log output; rather use the constructor. |
| 409 | This function can be used to change the name in case naming info |
| 410 | becomes available only after class creation (like a pid)''' |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 411 | if name_items: |
| 412 | name = '-'.join([str(i) for i in name_items]) |
| 413 | elif not detail_items: |
| 414 | name = self.__class__.__name__ |
| 415 | else: |
| 416 | name = '' |
| 417 | if detail_items: |
| 418 | details = '(%s)' % (', '.join([("%s=%r" % (k,v)) |
| 419 | for k,v in sorted(detail_items.items())])) |
| 420 | else: |
| 421 | details = '' |
| 422 | self._name = name + details |
| 423 | |
| 424 | def name(self): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 425 | return self._name or self.__class__.__name__ |
| 426 | |
| 427 | __str__ = name |
| 428 | __repr__ = name |
| 429 | |
| 430 | def origin_id(self): |
| 431 | if not self._origin_id: |
| 432 | if not Origin._global_id: |
| 433 | Origin._global_id = get_process_id() |
| 434 | self._origin_id = '%s-%s' % (self.name(), Origin._global_id) |
| 435 | return self._origin_id |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 436 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 437 | def _set_log_category(self, category): |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 438 | self._log_category = category |
| 439 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 440 | def redirect_stdout(self): |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 441 | return contextlib.redirect_stdout(SafeRedirectStdout(self)) |
| 442 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 443 | def ancestry(self): |
| 444 | origins = [] |
| 445 | n = 10 |
| 446 | origin = self |
| 447 | while origin: |
| 448 | origins.insert(0, origin) |
| 449 | origin = origin._parent |
| 450 | n -= 1 |
| 451 | if n < 0: |
| 452 | break |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 453 | return origins |
| 454 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 455 | def ancestry_str(self): |
| 456 | return '↪'.join([o.name() for o in self.ancestry()]) |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 457 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 458 | def highest_ancestor(self): |
| 459 | if self._parent: |
| 460 | return self._parent.highest_ancestor() |
| 461 | return self |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 462 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 463 | def log(self, *messages, _src=3, **named_items): |
| 464 | '''same as log.log() but passes this object to skip looking up an origin''' |
| 465 | log(*messages, _origin=self, _src=_src, **named_items) |
| 466 | |
| 467 | def dbg(self, *messages, _src=3, **named_items): |
| 468 | '''same as log.dbg() but passes this object to skip looking up an origin''' |
| 469 | dbg(*messages, _origin=self, _src=_src, **named_items) |
| 470 | |
| 471 | def err(self, *messages, _src=3, **named_items): |
| 472 | '''same as log.err() but passes this object to skip looking up an origin''' |
| 473 | err(*messages, _origin=self, _src=_src, **named_items) |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 474 | |
| 475 | class SafeRedirectStdout: |
| 476 | ''' |
| 477 | To be able to use 'print' in test scripts, this is used to redirect stdout |
| 478 | to a test class' log() function. However, it turns out doing that breaks |
| 479 | python debugger sessions -- it uses extended features of stdout, and will |
| 480 | fail dismally if it finds this wrapper in sys.stdout. Luckily, overriding |
| 481 | __getattr__() to return the original sys.__stdout__ attributes for anything |
| 482 | else than write() makes the debugger session work nicely again! |
| 483 | ''' |
| 484 | _log_line_buf = None |
| 485 | |
| 486 | def __init__(self, origin): |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 487 | self.origin = origin |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 488 | |
| 489 | def write(self, message): |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 490 | lines = message.splitlines() |
| 491 | if not lines: |
| 492 | return |
| 493 | if self._log_line_buf: |
| 494 | lines[0] = self._log_line_buf + lines[0] |
| 495 | self._log_line_buf = None |
| 496 | if not message.endswith('\n'): |
| 497 | self._log_line_buf = lines[-1] |
| 498 | lines = lines[:-1] |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 499 | for line in lines: |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 500 | _log(messages=(line,), |
| 501 | origin=self.origin, level=L_LOG, src=2) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 502 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 503 | def __getattr__(self, name): |
| 504 | return sys.__stdout__.__getattribute__(name) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 505 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 506 | def trace(exc_info=None, origin=None): |
| 507 | if exc_info is None: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 508 | exc_info = sys.exc_info() |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 509 | if origin is None: |
| 510 | origin = Origin.find_in_exc_info(exc_info) |
| 511 | _log(messages=traceback.format_exception(*exc_info), |
| 512 | origin=origin, level=L_TRACEBACK) |
| 513 | |
| 514 | def log_exn(): |
| 515 | exc_info = sys.exc_info() |
| 516 | origin = Origin.find_in_exc_info(exc_info) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 517 | |
| 518 | etype, exception, tb = exc_info |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 519 | if hasattr(exception, 'msg'): |
| 520 | msg = exception.msg |
| 521 | else: |
| 522 | msg = str(exception) |
| 523 | |
Neels Hofmeyr | 1a7a3f0 | 2017-06-10 01:18:27 +0200 | [diff] [blame] | 524 | trace(exc_info, origin=origin) |
| 525 | _log(messages=('%s:' % str(etype.__name__), msg), |
| 526 | origin=origin, level=L_ERR, src=get_src_from_exc_info(exc_info)) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 527 | |
| 528 | |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 529 | def set_all_levels(level): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 530 | for target in LogTarget.all_targets: |
Neels Hofmeyr | 3531a19 | 2017-03-28 14:30:28 +0200 | [diff] [blame] | 531 | target.set_all_levels(level) |
| 532 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 533 | def set_level(category, level): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 534 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 535 | target.set_level(category, level) |
| 536 | |
| 537 | def style(**kwargs): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 538 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 539 | target.style(**kwargs) |
| 540 | |
| 541 | def style_change(**kwargs): |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 542 | for target in LogTarget.all_targets: |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 543 | target.style_change(**kwargs) |
| 544 | |
| 545 | class TestsTarget(LogTarget): |
| 546 | 'LogTarget producing deterministic results for regression tests' |
Neels Hofmeyr | f816688 | 2017-05-05 19:48:35 +0200 | [diff] [blame] | 547 | def __init__(self, log_write_func=None): |
| 548 | super().__init__(log_write_func) |
Neels Hofmeyr | 532126a | 2017-05-05 19:51:40 +0200 | [diff] [blame] | 549 | self.style(time=False, src=False, origin_width=0) |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 550 | |
Neels Hofmeyr | 8f4f174 | 2017-05-07 00:00:14 +0200 | [diff] [blame] | 551 | class FileLogTarget(LogTarget): |
| 552 | 'LogTarget to log to a file system path' |
| 553 | log_file = None |
| 554 | |
| 555 | def __init__(self, log_path): |
| 556 | atexit.register(self.at_exit) |
| 557 | self.path = log_path |
| 558 | self.log_file = open(log_path, 'a') |
| 559 | super().__init__(self.write_to_log_and_flush) |
| 560 | |
| 561 | def remove(self): |
| 562 | super().remove() |
| 563 | self.log_file.close() |
| 564 | self.log_file = None |
| 565 | |
| 566 | def write_to_log_and_flush(self, msg): |
| 567 | self.log_file.write(msg) |
| 568 | self.log_file.flush() |
| 569 | |
| 570 | def at_exit(self): |
| 571 | if self.log_file is not None: |
| 572 | self.log_file.flush() |
| 573 | self.log_file.close() |
| 574 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 575 | def run_logging_exceptions(func, *func_args, return_on_failure=None, **func_kwargs): |
| 576 | try: |
| 577 | return func(*func_args, **func_kwargs) |
| 578 | except: |
| 579 | log_exn() |
| 580 | return return_on_failure |
| 581 | |
Neels Hofmeyr | 2694a9d | 2017-04-27 19:48:09 +0200 | [diff] [blame] | 582 | def _compose_named_items(item): |
| 583 | 'make sure dicts are output sorted, for test expectations' |
| 584 | if is_dict(item): |
| 585 | return '{%s}' % (', '.join( |
| 586 | ['%s=%s' % (k, _compose_named_items(v)) |
| 587 | for k,v in sorted(item.items())])) |
| 588 | return repr(item) |
| 589 | |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 590 | def compose_message(messages, named_items): |
| 591 | msgs = [str(m) for m in messages] |
| 592 | |
| 593 | if named_items: |
| 594 | # unfortunately needs to be sorted to get deterministic results |
Neels Hofmeyr | 2694a9d | 2017-04-27 19:48:09 +0200 | [diff] [blame] | 595 | msgs.append(_compose_named_items(named_items)) |
Neels Hofmeyr | 85eb324 | 2017-04-09 22:01:16 +0200 | [diff] [blame] | 596 | |
| 597 | return ' '.join(msgs) |
| 598 | |
Neels Hofmeyr | dae3d3c | 2017-03-28 12:16:58 +0200 | [diff] [blame] | 599 | # vim: expandtab tabstop=4 shiftwidth=4 |