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