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