1###
2# Copyright (c) 2002-2005, Jeremiah Fincher
3# All rights reserved.
4#
5# Redistribution and use in source and binary forms, with or without
6# modification, are permitted provided that the following conditions are met:
7#
8#   * Redistributions of source code must retain the above copyright notice,
9#     this list of conditions, and the following disclaimer.
10#   * Redistributions in binary form must reproduce the above copyright notice,
11#     this list of conditions, and the following disclaimer in the
12#     documentation and/or other materials provided with the distribution.
13#   * Neither the name of the author of this software nor the name of
14#     contributors to this software may be used to endorse or promote products
15#     derived from this software without specific prior written consent.
16#
17# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
18# AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
19# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
20# ARE DISCLAIMED.  IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE
21# LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
22# CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
23# SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
24# INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
25# CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
26# ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
27# POSSIBILITY OF SUCH DAMAGE.
28###
29
30import os
31import sys
32import time
33import types
34import atexit
35import logging
36import operator
37import textwrap
38import traceback
39
40from . import ansi, conf, ircutils, registry, utils
41from .utils import minisix
42
43deadlyExceptions = [KeyboardInterrupt, SystemExit]
44
45###
46# This is for testing, of course.  Mostly it just disables the firewall code
47# so exceptions can propagate.
48###
49testing = False
50
51class Formatter(logging.Formatter):
52    _fmtConf = staticmethod(lambda : conf.supybot.log.format())
53    def formatTime(self, record, datefmt=None):
54        return timestamp(record.created)
55
56    def formatException(self, exc_info):
57        (E, e, tb) = exc_info
58        for exn in deadlyExceptions:
59            if issubclass(e.__class__, exn):
60                raise
61        return logging.Formatter.formatException(self, (E, e, tb))
62
63    def format(self, record):
64        self._fmt = self._fmtConf()
65        if hasattr(self, '_style'): # Python 3
66            self._style._fmt = self._fmtConf()
67        return logging.Formatter.format(self, record)
68
69
70class PluginFormatter(Formatter):
71    _fmtConf = staticmethod(lambda : conf.supybot.log.plugins.format())
72
73
74class Logger(logging.Logger):
75    def exception(self, *args):
76        (E, e, tb) = sys.exc_info()
77        tbinfo = traceback.extract_tb(tb)
78        path = '[%s]' % '|'.join(map(operator.itemgetter(2), tbinfo))
79        eStrId = '%s:%s' % (E, path)
80        eId = hex(hash(eStrId) & 0xFFFFF)
81        logging.Logger.exception(self, *args)
82        self.error('Exception id: %s', eId)
83        self.debug('%s', utils.python.collect_extra_debug_data())
84        # The traceback should be sufficient if we want it.
85        # self.error('Exception string: %s', eStrId)
86
87    def _log(self, level, msg, args, exc_info=None, extra=None):
88        msg = format(msg, *args)
89        logging.Logger._log(self, level, msg, (), exc_info=exc_info,
90                            extra=extra)
91
92
93class StdoutStreamHandler(logging.StreamHandler):
94    def format(self, record):
95        s = logging.StreamHandler.format(self, record)
96        if record.levelname != 'ERROR' and conf.supybot.log.stdout.wrap():
97            # We check for ERROR there because otherwise, tracebacks (which are
98            # already wrapped by Python itself) wrap oddly.
99            if not isinstance(record.levelname, minisix.string_types):
100                print(record)
101                print(record.levelname)
102                print(utils.stackTrace())
103            prefixLen = len(record.levelname) + 1 # ' '
104            s = textwrap.fill(s, width=78, subsequent_indent=' '*prefixLen)
105            s.rstrip('\r\n')
106        return s
107
108    def emit(self, record):
109        if conf.supybot.log.stdout() and not conf.daemonized:
110            try:
111                logging.StreamHandler.emit(self, record)
112            except ValueError: # Raised if sys.stdout is closed.
113                self.disable()
114                error('Error logging to stdout.  Removing stdout handler.')
115                exception('Uncaught exception in StdoutStreamHandler:')
116
117    def disable(self):
118        self.setLevel(sys.maxsize) # Just in case.
119        _logger.removeHandler(self)
120        logging._acquireLock()
121        try:
122            del logging._handlers[self]
123        finally:
124            logging._releaseLock()
125
126
127class BetterFileHandler(logging.FileHandler):
128    def emit(self, record):
129        msg = self.format(record)
130        try:
131            self.stream.write(msg)
132        except (UnicodeError, TypeError):
133            try:
134                self.stream.write(msg.encode("utf8"))
135            except (UnicodeError, TypeError):
136                try:
137                    self.stream.write(msg.encode("utf8").decode('ascii', 'replace'))
138                except (UnicodeError, TypeError):
139                    self.stream.write(repr(msg))
140        self.stream.write(os.linesep)
141        try:
142            self.flush()
143        except OSError as e:
144            if e.args[0] == 28:
145                print('No space left on device, cannot flush log.')
146            else:
147                raise
148
149
150class ColorizedFormatter(Formatter):
151    # This was necessary because these variables aren't defined until later.
152    # The staticmethod is necessary because they get treated like methods.
153    _fmtConf = staticmethod(lambda : conf.supybot.log.stdout.format())
154    def formatException(self, exc_info):
155        (E, e, tb) = exc_info
156        if conf.supybot.log.stdout.colorized():
157            return ''.join([ansi.RED,
158                            Formatter.formatException(self, (E, e, tb)),
159                            ansi.RESET])
160        else:
161            return Formatter.formatException(self, (E, e, tb))
162
163    def format(self, record, *args, **kwargs):
164        if conf.supybot.log.stdout.colorized():
165            color = ''
166            if record.levelno == logging.CRITICAL:
167                color = ansi.WHITE + ansi.BOLD
168            elif record.levelno == logging.ERROR:
169                color = ansi.RED
170            elif record.levelno == logging.WARNING:
171                color = ansi.YELLOW
172            if color:
173                return ''.join([color,
174                                Formatter.format(self, record, *args, **kwargs),
175                                ansi.RESET])
176            else:
177                return Formatter.format(self, record, *args, **kwargs)
178        else:
179            return Formatter.format(self, record, *args, **kwargs)
180
181_logDir = conf.supybot.directories.log()
182if not os.path.exists(_logDir):
183    os.mkdir(_logDir, 0o755)
184
185pluginLogDir = os.path.join(_logDir, 'plugins')
186
187if not os.path.exists(pluginLogDir):
188    os.mkdir(pluginLogDir, 0o755)
189
190try:
191    messagesLogFilename = os.path.join(_logDir, 'messages.log')
192    _handler = BetterFileHandler(messagesLogFilename, encoding='utf8')
193except EnvironmentError as e:
194    raise SystemExit('Error opening messages logfile (%s).  ' \
195          'Generally, this is because you are running Supybot in a directory ' \
196          'you don\'t have permissions to add files in, or you\'re running ' \
197          'Supybot as a different user than you normally do.  The original ' \
198          'error was: %s' % (messagesLogFilename, utils.gen.exnToString(e)))
199
200# These are public.
201if sys.version_info >= (3, 8):
202    formatter = Formatter(
203            'NEVER SEEN; IF YOU SEE THIS, FILE A BUG!', validate=False)
204    pluginFormatter = PluginFormatter(
205            'NEVER SEEN; IF YOU SEE THIS, FILE A BUG!', validate=False)
206
207else:
208    formatter = Formatter(
209            'NEVER SEEN; IF YOU SEE THIS, FILE A BUG!')
210    pluginFormatter = PluginFormatter(
211            'NEVER SEEN; IF YOU SEE THIS, FILE A BUG!')
212
213# These are not.
214logging.setLoggerClass(Logger)
215_logger = logging.getLogger('supybot')
216_stdoutHandler = StdoutStreamHandler(sys.stdout)
217
218class ValidLogLevel(registry.String):
219    """Invalid log level."""
220    handler = None
221    minimumLevel = -1
222    def set(self, s):
223        s = s.upper()
224        try:
225            try:
226                level = logging._levelNames[s]
227            except AttributeError:
228                level = logging._nameToLevel[s]
229        except KeyError:
230            try:
231                level = int(s)
232            except ValueError:
233                self.error()
234        if level < self.minimumLevel:
235            self.error()
236        if self.handler is not None:
237            self.handler.setLevel(level)
238        self.setValue(level)
239
240    def __str__(self):
241        # The str() is necessary here; apparently getLevelName returns an
242        # integer on occasion.  logging--
243        level = str(logging.getLevelName(self.value))
244        if level.startswith('Level'):
245            level = level.split()[-1]
246        return level
247
248class LogLevel(ValidLogLevel):
249    """Invalid log level.  Value must be either DEBUG, INFO, WARNING,
250    ERROR, or CRITICAL."""
251    handler = _handler
252
253class StdoutLogLevel(ValidLogLevel):
254    """Invalid log level.  Value must be either DEBUG, INFO, WARNING,
255    ERROR, or CRITICAL."""
256    handler = _stdoutHandler
257
258conf.registerGroup(conf.supybot, 'log')
259conf.registerGlobalValue(conf.supybot.log, 'format',
260    registry.String('%(levelname)s %(asctime)s %(name)s %(message)s',
261    """Determines what the bot's logging format will be.  The relevant
262    documentation on the available formattings is Python's documentation on
263    its logging module."""))
264conf.registerGlobalValue(conf.supybot.log, 'level',
265    LogLevel(logging.INFO, """Determines what the minimum priority level logged
266    to file will be.  Do note that this value does not affect the level logged
267    to stdout; for that, you should set the value of supybot.log.stdout.level.
268    Valid values are DEBUG, INFO, WARNING, ERROR, and CRITICAL, in order of
269    increasing priority."""))
270conf.registerGlobalValue(conf.supybot.log, 'timestampFormat',
271    registry.String('%Y-%m-%dT%H:%M:%S', """Determines the format string for
272    timestamps in logfiles.  Refer to the Python documentation for the time
273    module to see what formats are accepted. If you set this variable to the
274    empty string, times will be logged in a simple seconds-since-epoch
275    format."""))
276
277class BooleanRequiredFalseOnWindows(registry.Boolean):
278    """Value cannot be true on Windows"""
279    def set(self, s):
280        registry.Boolean.set(self, s)
281        if self.value and os.name == 'nt':
282            self.error()
283
284conf.registerGlobalValue(conf.supybot.log, 'stdout',
285    registry.Boolean(True, """Determines whether the bot will log to
286    stdout."""))
287conf.registerGlobalValue(conf.supybot.log.stdout, 'colorized',
288    BooleanRequiredFalseOnWindows(False, """Determines whether the bot's logs
289    to stdout (if enabled) will be colorized with ANSI color."""))
290conf.registerGlobalValue(conf.supybot.log.stdout, 'wrap',
291    registry.Boolean(False, """Determines whether the bot will wrap its logs
292    when they're output to stdout."""))
293conf.registerGlobalValue(conf.supybot.log.stdout, 'format',
294    registry.String('%(levelname)s %(asctime)s %(message)s',
295    """Determines what the bot's logging format will be.  The relevant
296    documentation on the available formattings is Python's documentation on
297    its logging module."""))
298conf.registerGlobalValue(conf.supybot.log.stdout, 'level',
299    StdoutLogLevel(logging.INFO, """Determines what the minimum priority level
300    logged will be.  Valid values are DEBUG, INFO, WARNING, ERROR, and
301    CRITICAL, in order of increasing priority."""))
302
303conf.registerGroup(conf.supybot.log, 'plugins')
304conf.registerGlobalValue(conf.supybot.log.plugins, 'individualLogfiles',
305    registry.Boolean(False, """Determines whether the bot will separate plugin
306    logs into their own individual logfiles."""))
307conf.registerGlobalValue(conf.supybot.log.plugins, 'format',
308    registry.String('%(levelname)s %(asctime)s %(message)s',
309    """Determines what the bot's logging format will be.  The relevant
310    documentation on the available formattings is Python's documentation on
311    its logging module."""))
312
313
314# These just make things easier.
315debug = _logger.debug
316info = _logger.info
317warning = _logger.warning
318error = _logger.error
319critical = _logger.critical
320exception = _logger.exception
321
322# These were just begging to be replaced.
323registry.error = error
324registry.exception = exception
325
326setLevel = _logger.setLevel
327
328atexit.register(logging.shutdown)
329
330# ircutils will work without this, but it's useful.
331ircutils.debug = debug
332
333def getPluginLogger(name):
334    if not conf.supybot.log.plugins.individualLogfiles():
335        return _logger
336    log = logging.getLogger('supybot.plugins.%s' % name)
337    if not log.handlers:
338        filename = os.path.join(pluginLogDir, '%s.log' % name)
339        handler = BetterFileHandler(filename)
340        handler.setLevel(-1)
341        handler.setFormatter(pluginFormatter)
342        log.addHandler(handler)
343    if name in sys.modules:
344        log.info('Starting log for %s.', name)
345    return log
346
347def timestamp(when=None):
348    if when is None:
349        when = time.time()
350    format = conf.supybot.log.timestampFormat()
351    t = time.localtime(when)
352    if format:
353        return time.strftime(format, t)
354    else:
355        return str(int(time.mktime(t)))
356
357def firewall(f, errorHandler=None):
358    def logException(self, s=None):
359        if s is None:
360            s = 'Uncaught exception'
361        if hasattr(self, 'log'):
362            logging_function = self.log.exception
363        else:
364            logging_function = exception
365        logging_function('%s in %s.%s:', s, self.__class__.__name__, f.__name__)
366    def m(self, *args, **kwargs):
367        try:
368            return f(self, *args, **kwargs)
369        except Exception:
370            if testing:
371                raise
372            logException(self)
373            if errorHandler is not None:
374                try:
375                    return errorHandler(self, *args, **kwargs)
376                except Exception:
377                    logException(self, 'Uncaught exception in errorHandler')
378    m = utils.python.changeFunctionName(m, f.__name__, f.__doc__)
379    return m
380
381class MetaFirewall(type):
382    def __new__(cls, name, bases, classdict):
383        firewalled = {}
384        for base in bases:
385            if hasattr(base, '__firewalled__'):
386                cls.updateFirewalled(firewalled, base.__firewalled__)
387        cls.updateFirewalled(firewalled, classdict.get('__firewalled__', []))
388        for (attr, errorHandler) in firewalled.items():
389            if attr in classdict:
390                classdict[attr] = firewall(classdict[attr], errorHandler)
391        return super(MetaFirewall, cls).__new__(cls, name, bases, classdict)
392
393    def getErrorHandler(cls, dictOrTuple, name):
394        if isinstance(dictOrTuple, dict):
395            return dictOrTuple[name]
396        else:
397            return None
398    getErrorHandler = classmethod(getErrorHandler)
399
400    def updateFirewalled(cls, firewalled, __firewalled__):
401        for attr in __firewalled__:
402            firewalled[attr] = cls.getErrorHandler(__firewalled__, attr)
403    updateFirewalled = classmethod(updateFirewalled)
404Firewalled = MetaFirewall('Firewalled', (), {})
405
406
407class PluginLogFilter(logging.Filter):
408    def filter(self, record):
409        if conf.supybot.log.plugins.individualLogfiles():
410            if record.name.startswith('supybot.plugins'):
411                return False
412        return True
413
414_handler.setFormatter(formatter)
415_handler.addFilter(PluginLogFilter())
416
417_handler.setLevel(conf.supybot.log.level())
418_logger.addHandler(_handler)
419_logger.setLevel(-1)
420
421if sys.version_info >= (3, 8):
422    _stdoutFormatter = ColorizedFormatter(
423            'IF YOU SEE THIS, FILE A BUG!', validate=False)
424else:
425    _stdoutFormatter = ColorizedFormatter(
426            'IF YOU SEE THIS, FILE A BUG!')
427_stdoutHandler.setFormatter(_stdoutFormatter)
428_stdoutHandler.setLevel(conf.supybot.log.stdout.level())
429if not conf.daemonized:
430    _logger.addHandler(_stdoutHandler)
431
432
433# vim:set shiftwidth=4 softtabstop=4 expandtab textwidth=79:
434
435