1"""logging facilities 2 3The way to use this is as follows: 4 5* each module declares its own logger, using: 6 7 from .logger import create_logger 8 logger = create_logger() 9 10* then each module uses logger.info/warning/debug/etc according to the 11 level it believes is appropriate: 12 13 logger.debug('debugging info for developers or power users') 14 logger.info('normal, informational output') 15 logger.warning('warn about a non-fatal error or sth else') 16 logger.error('a fatal error') 17 18 ... and so on. see the `logging documentation 19 <https://docs.python.org/3/howto/logging.html#when-to-use-logging>`_ 20 for more information 21 22* console interaction happens on stderr, that includes interactive 23 reporting functions like `help`, `info` and `list` 24 25* ...except ``input()`` is special, because we can't control the 26 stream it is using, unfortunately. we assume that it won't clutter 27 stdout, because interaction would be broken then anyways 28 29* what is output on INFO level is additionally controlled by commandline 30 flags 31""" 32 33import inspect 34import json 35import logging 36import logging.config 37import logging.handlers # needed for handlers defined there being configurable in logging.conf file 38import os 39import warnings 40 41configured = False 42 43# use something like this to ignore warnings: 44# warnings.filterwarnings('ignore', r'... regex for warning message to ignore ...') 45 46 47def _log_warning(message, category, filename, lineno, file=None, line=None): 48 # for warnings, we just want to use the logging system, not stderr or other files 49 msg = "{0}:{1}: {2}: {3}".format(filename, lineno, category.__name__, message) 50 logger = create_logger(__name__) 51 # Note: the warning will look like coming from here, 52 # but msg contains info about where it really comes from 53 logger.warning(msg) 54 55 56def setup_logging(stream=None, conf_fname=None, env_var='BORG_LOGGING_CONF', level='info', is_serve=False, json=False): 57 """setup logging module according to the arguments provided 58 59 if conf_fname is given (or the config file name can be determined via 60 the env_var, if given): load this logging configuration. 61 62 otherwise, set up a stream handler logger on stderr (by default, if no 63 stream is provided). 64 65 if is_serve == True, we configure a special log format as expected by 66 the borg client log message interceptor. 67 """ 68 global configured 69 err_msg = None 70 if env_var: 71 conf_fname = os.environ.get(env_var, conf_fname) 72 if conf_fname: 73 try: 74 conf_fname = os.path.abspath(conf_fname) 75 # we open the conf file here to be able to give a reasonable 76 # error message in case of failure (if we give the filename to 77 # fileConfig(), it silently ignores unreadable files and gives 78 # unhelpful error msgs like "No section: 'formatters'"): 79 with open(conf_fname) as f: 80 logging.config.fileConfig(f) 81 configured = True 82 logger = logging.getLogger(__name__) 83 borg_logger = logging.getLogger('borg') 84 borg_logger.json = json 85 logger.debug('using logging configuration read from "{0}"'.format(conf_fname)) 86 warnings.showwarning = _log_warning 87 return None 88 except Exception as err: # XXX be more precise 89 err_msg = str(err) 90 # if we did not / not successfully load a logging configuration, fallback to this: 91 logger = logging.getLogger('') 92 handler = logging.StreamHandler(stream) 93 if is_serve and not json: 94 fmt = '$LOG %(levelname)s %(name)s Remote: %(message)s' 95 else: 96 fmt = '%(message)s' 97 formatter = JsonFormatter(fmt) if json else logging.Formatter(fmt) 98 handler.setFormatter(formatter) 99 borg_logger = logging.getLogger('borg') 100 borg_logger.formatter = formatter 101 borg_logger.json = json 102 if configured and logger.handlers: 103 # The RepositoryServer can call setup_logging a second time to adjust the output 104 # mode from text-ish is_serve to json is_serve. 105 # Thus, remove the previously installed handler, if any. 106 logger.handlers[0].close() 107 logger.handlers.clear() 108 logger.addHandler(handler) 109 logger.setLevel(level.upper()) 110 configured = True 111 logger = logging.getLogger(__name__) 112 if err_msg: 113 logger.warning('setup_logging for "{0}" failed with "{1}".'.format(conf_fname, err_msg)) 114 logger.debug('using builtin fallback logging configuration') 115 warnings.showwarning = _log_warning 116 return handler 117 118 119def find_parent_module(): 120 """find the name of the first module calling this module 121 122 if we cannot find it, we return the current module's name 123 (__name__) instead. 124 """ 125 try: 126 frame = inspect.currentframe().f_back 127 module = inspect.getmodule(frame) 128 while module is None or module.__name__ == __name__: 129 frame = frame.f_back 130 module = inspect.getmodule(frame) 131 return module.__name__ 132 except AttributeError: 133 # somehow we failed to find our module 134 # return the logger module name by default 135 return __name__ 136 137 138def create_logger(name=None): 139 """lazily create a Logger object with the proper path, which is returned by 140 find_parent_module() by default, or is provided via the commandline 141 142 this is really a shortcut for: 143 144 logger = logging.getLogger(__name__) 145 146 we use it to avoid errors and provide a more standard API. 147 148 We must create the logger lazily, because this is usually called from 149 module level (and thus executed at import time - BEFORE setup_logging() 150 was called). By doing it lazily we can do the setup first, we just have to 151 be careful not to call any logger methods before the setup_logging() call. 152 If you try, you'll get an exception. 153 """ 154 class LazyLogger: 155 def __init__(self, name=None): 156 self.__name = name or find_parent_module() 157 self.__real_logger = None 158 159 @property 160 def __logger(self): 161 if self.__real_logger is None: 162 if not configured: 163 raise Exception("tried to call a logger before setup_logging() was called") 164 self.__real_logger = logging.getLogger(self.__name) 165 if self.__name.startswith('borg.debug.') and self.__real_logger.level == logging.NOTSET: 166 self.__real_logger.setLevel('WARNING') 167 return self.__real_logger 168 169 def getChild(self, suffix): 170 return LazyLogger(self.__name + '.' + suffix) 171 172 def setLevel(self, *args, **kw): 173 return self.__logger.setLevel(*args, **kw) 174 175 def log(self, *args, **kw): 176 if 'msgid' in kw: 177 kw.setdefault('extra', {})['msgid'] = kw.pop('msgid') 178 return self.__logger.log(*args, **kw) 179 180 def exception(self, *args, **kw): 181 if 'msgid' in kw: 182 kw.setdefault('extra', {})['msgid'] = kw.pop('msgid') 183 return self.__logger.exception(*args, **kw) 184 185 def debug(self, *args, **kw): 186 if 'msgid' in kw: 187 kw.setdefault('extra', {})['msgid'] = kw.pop('msgid') 188 return self.__logger.debug(*args, **kw) 189 190 def info(self, *args, **kw): 191 if 'msgid' in kw: 192 kw.setdefault('extra', {})['msgid'] = kw.pop('msgid') 193 return self.__logger.info(*args, **kw) 194 195 def warning(self, *args, **kw): 196 if 'msgid' in kw: 197 kw.setdefault('extra', {})['msgid'] = kw.pop('msgid') 198 return self.__logger.warning(*args, **kw) 199 200 def error(self, *args, **kw): 201 if 'msgid' in kw: 202 kw.setdefault('extra', {})['msgid'] = kw.pop('msgid') 203 return self.__logger.error(*args, **kw) 204 205 def critical(self, *args, **kw): 206 if 'msgid' in kw: 207 kw.setdefault('extra', {})['msgid'] = kw.pop('msgid') 208 return self.__logger.critical(*args, **kw) 209 210 return LazyLogger(name) 211 212 213class JsonFormatter(logging.Formatter): 214 RECORD_ATTRIBUTES = ( 215 'levelname', 216 'name', 217 'message', 218 # msgid is an attribute we made up in Borg to expose a non-changing handle for log messages 219 'msgid', 220 ) 221 222 # Other attributes that are not very useful but do exist: 223 # processName, process, relativeCreated, stack_info, thread, threadName 224 # msg == message 225 # *args* are the unformatted arguments passed to the logger function, not useful now, 226 # become useful if sanitized properly (must be JSON serializable) in the code + 227 # fixed message IDs are assigned. 228 # exc_info, exc_text are generally uninteresting because the message will have that 229 230 def format(self, record): 231 super().format(record) 232 data = { 233 'type': 'log_message', 234 'time': record.created, 235 'message': '', 236 'levelname': 'CRITICAL', 237 } 238 for attr in self.RECORD_ATTRIBUTES: 239 value = getattr(record, attr, None) 240 if value: 241 data[attr] = value 242 return json.dumps(data) 243