diff --git a/sopel/bot.py b/sopel/bot.py index cb2bc604d3..f15bd6d218 100644 --- a/sopel/bot.py +++ b/sopel/bot.py @@ -10,7 +10,7 @@ from ast import literal_eval import collections import itertools -import os +import logging import re import sys import threading @@ -18,7 +18,7 @@ from sopel import irc, logger, plugins, tools from sopel.db import SopelDB -from sopel.tools import stderr, Identifier, deprecated +from sopel.tools import Identifier, deprecated import sopel.tools.jobs from sopel.trigger import Trigger from sopel.module import NOLIMIT @@ -27,7 +27,7 @@ __all__ = ['Sopel', 'SopelWrapper'] -LOGGER = logger.get_logger(__name__) +LOGGER = logging.getLogger(__name__) if sys.version_info.major >= 3: unicode = str @@ -211,14 +211,35 @@ def setup(self): self.scheduler.start() def setup_logging(self): - logger.setup_logging(self) + logger.setup_logging(self.config) + base_level = self.config.core.logging_level or 'INFO' + base_format = self.config.core.logging_format + base_datefmt = self.config.core.logging_datefmt + + # configure channel logging if required by configuration + if self.config.core.logging_channel: + channel_level = self.config.core.logging_channel_level or base_level + channel_format = self.config.core.logging_channel_format or base_format + channel_datefmt = self.config.core.logging_channel_datefmt or base_datefmt + channel_params = {} + if channel_format: + channel_params['fmt'] = channel_format + if channel_datefmt: + channel_params['datefmt'] = channel_datefmt + formatter = logger.ChannelOutputFormatter(**channel_params) + handler = logger.IrcLoggingHandler(self, channel_level) + handler.setFormatter(formatter) + + # set channel handler to `sopel` logger + LOGGER = logging.getLogger('sopel') + LOGGER.addHandler(handler) def setup_plugins(self): load_success = 0 load_error = 0 load_disabled = 0 - stderr("Loading plugins...") + LOGGER.info('Loading plugins...') usable_plugins = plugins.get_usable_plugins(self.config) for name, info in usable_plugins.items(): plugin, is_enabled = info @@ -230,10 +251,7 @@ def setup_plugins(self): plugin.load() except Exception as e: load_error = load_error + 1 - filename, lineno = tools.get_raising_file_and_line() - rel_path = os.path.relpath(filename, os.path.dirname(__file__)) - raising_stmt = "%s:%d" % (rel_path, lineno) - stderr("Error loading %s: %s (%s)" % (name, e, raising_stmt)) + LOGGER.exception('Error loading %s: %s', name, e) else: try: if plugin.has_setup(): @@ -241,24 +259,20 @@ def setup_plugins(self): plugin.register(self) except Exception as e: load_error = load_error + 1 - filename, lineno = tools.get_raising_file_and_line() - rel_path = os.path.relpath( - filename, os.path.dirname(__file__) - ) - raising_stmt = "%s:%d" % (rel_path, lineno) - stderr("Error in %s setup procedure: %s (%s)" - % (name, e, raising_stmt)) + LOGGER.exception('Error in %s setup: %s', name, e) else: load_success = load_success + 1 - print('Loaded: %s' % name) + LOGGER.info('Plugin loaded: %s', name) total = sum([load_success, load_error, load_disabled]) if total and load_success: - stderr('Registered %d modules' % (load_success - 1)) - stderr('%d modules failed to load' % load_error) - stderr('%d modules disabled' % load_disabled) + LOGGER.info( + 'Registered %d plugins, %d failed, %d disabled', + (load_success - 1), + load_error, + load_disabled) else: - stderr("Warning: Couldn't load any modules") + LOGGER.warning("Warning: Couldn't load any plugins") def reload_plugin(self, name): """Reload a plugin @@ -276,12 +290,12 @@ def reload_plugin(self, name): # tear down plugin.shutdown(self) plugin.unregister(self) - print('Unloaded: %s' % name) + LOGGER.info('Unloaded plugin %s', name) # reload & setup plugin.reload() plugin.setup(self) plugin.register(self) - print('Reloaded: %s' % name) + LOGGER.info('Reloaded plugin %s', name) def reload_plugins(self): """Reload all plugins @@ -295,14 +309,14 @@ def reload_plugins(self): for name, plugin in registered: plugin.shutdown(self) plugin.unregister(self) - print('Unloaded: %s' % name) + LOGGER.info('Unloaded plugin %s', name) # reload & setup all plugins for name, plugin in registered: plugin.reload() plugin.setup(self) plugin.register(self) - print('Reloaded: %s' % name) + LOGGER.info('Reloaded plugin %s', name) def add_plugin(self, plugin, callables, jobs, shutdowns, urls): """Add a loaded plugin to the bot's registry""" @@ -315,24 +329,21 @@ def remove_plugin(self, plugin, callables, jobs, shutdowns, urls): if not self.has_plugin(name): raise plugins.exceptions.PluginNotRegistered(name) - try: - # remove commands, jobs, and shutdown functions - for func in itertools.chain(callables, jobs, shutdowns): - self.unregister(func) - - # remove URL callback handlers - if "url_callbacks" in self.memory: - for func in urls: - regexes = func.url_regex - for regex in regexes: - if func == self.memory['url_callbacks'].get(regex): - self.unregister_url_callback(regex) - except: # noqa - # TODO: consider logging? - raise # re-raised - else: - # remove plugin from registry - del self._plugins[name] + # remove commands, jobs, and shutdown functions + for func in itertools.chain(callables, jobs, shutdowns): + self.unregister(func) + + # remove URL callback handlers + if "url_callbacks" in self.memory: + for func in urls: + regexes = func.url_regex + for regex in regexes: + if func == self.memory['url_callbacks'].get(regex): + self.unregister_url_callback(regex) + LOGGER.debug('URL Callback unregistered: %r', regex) + + # remove plugin from registry + del self._plugins[name] def has_plugin(self, name): """Tell if the bot has registered this plugin by its name""" @@ -345,22 +356,29 @@ def unregister(self, obj): :type obj: :term:`object` """ if not callable(obj): + LOGGER.warning('Cannot unregister obj %r: not a callable', obj) return + callable_name = getattr(obj, "__name__", 'UNKNOWN') + if hasattr(obj, 'rule'): # commands and intents have it added for rule in obj.rule: callb_list = self._callables[obj.priority][rule] if obj in callb_list: callb_list.remove(obj) + LOGGER.debug( + 'Rule callable "%s" unregistered', + callable_name, + rule.pattern) + if hasattr(obj, 'interval'): self.scheduler.remove_callable_job(obj) - if ( - getattr(obj, "__name__", None) == "shutdown" and - obj in self.shutdown_methods - ): + LOGGER.debug('Job callable removed: %s', callable_name) + + if callable_name == "shutdown" and obj in self.shutdown_methods: self.shutdown_methods.remove(obj) def register(self, callables, jobs, shutdowns, urls): - """Register a callable. + """Register rules, jobs, shutdown methods, and URL callbacks. :param callables: an iterable of callables to register :type callables: :term:`iterable` @@ -370,32 +388,98 @@ def register(self, callables, jobs, shutdowns, urls): :type shutdowns: :term:`iterable` :param urls: an iterable of functions to call when matched against a URL :type urls: :term:`iterable` + + The ``callables`` argument contains a list of "callable objects", i.e. + objects for which :func:`callable` will return ``True``. They can be: + + * a callable with rules (will match triggers with a regex pattern) + * a callable without rules (will match any triggers, such as events) + * a callable with commands + * a callable with nick commands + + It is possible to have a callable with rules, commands, and nick + commands configured. It should not be possible to have a callable with + commands or nick commands but without rules. Callables without rules + are usually event handlers. """ # Append module's shutdown function to the bot's list of functions to # call on shutdown self.shutdown_methods += shutdowns + match_any = re.compile('.*') for callbl in callables: - if hasattr(callbl, 'rule'): - for rule in callbl.rule: + callable_name = getattr(callbl, "__name__", 'UNKNOWN') + rules = getattr(callbl, 'rule', []) + commands = getattr(callbl, 'commands', []) + nick_commands = getattr(callbl, 'nickname_commands', []) + events = getattr(callbl, 'event', []) + is_rule_only = rules and not commands and not nick_commands + + if rules: + for rule in rules: self._callables[callbl.priority][rule].append(callbl) + if is_rule_only: + # Command & Nick Command are logged later: + # here we log rule only callable + LOGGER.debug( + 'Rule callable "%s" registered for "%s"', + callable_name, + rule.pattern) + if commands: + LOGGER.debug( + 'Command callable "%s" registered for "%s"', + callable_name, + '|'.join(commands)) + if nick_commands: + LOGGER.debug( + 'Nick command callable "%s" registered for "%s"', + callable_name, + '|'.join(nick_commands)) + if events: + LOGGER.debug( + 'Event callable "%s" registered for "%s"', + callable_name, + '|'.join(events)) else: - self._callables[callbl.priority][re.compile('.*')].append(callbl) - if hasattr(callbl, 'commands'): + self._callables[callbl.priority][match_any].append(callbl) + if events: + LOGGER.debug( + 'Event callable "%s" registered ' + 'with "match any" rule for "%s"', + callable_name, + '|'.join(events)) + else: + LOGGER.debug( + 'Rule callable "%s" registered with "match any" rule', + callable_name) + + if commands: module_name = callbl.__module__.rsplit('.', 1)[-1] # TODO doc and make decorator for this. Not sure if this is how # it should work yet, so not making it public for 6.0. category = getattr(callbl, 'category', module_name) - self._command_groups[category].append(callbl.commands[0]) + self._command_groups[category].append(commands[0]) + for command, docs in callbl._docs.items(): self.doc[command] = docs + for func in jobs: for interval in func.interval: job = sopel.tools.jobs.Job(interval, func) self.scheduler.add_job(job) + callable_name = getattr(func, "__name__", 'UNKNOWN') + LOGGER.debug( + 'Job added "%s", will run every %d seconds', + callable_name, + interval) for func in urls: for regex in func.url_regex: self.register_url_callback(regex, func) + callable_name = getattr(func, "__name__", 'UNKNOWN') + LOGGER.debug( + 'URL Callback added "%s" for URL pattern "%s"', + callable_name, + regex) def part(self, channel, msg=None): """Leave a channel. @@ -647,9 +731,9 @@ def call(self, func, sopel, trigger): try: exit_code = func(sopel, trigger) - except Exception: # TODO: Be specific + except Exception as error: # TODO: Be specific exit_code = None - self.error(trigger) + self.error(trigger, exception=error) if exit_code != NOLIMIT: self._times[nick][func] = current_time @@ -763,36 +847,32 @@ def _nick_blocked(self, nick): def _shutdown(self): # Stop Job Scheduler - stderr('Stopping the Job Scheduler.') + LOGGER.info('Stopping the Job Scheduler.') self.scheduler.stop() try: self.scheduler.join(timeout=15) except RuntimeError: - stderr('Unable to stop the Job Scheduler.') + LOGGER.exception('Unable to stop the Job Scheduler.') else: - stderr('Job Scheduler stopped.') + LOGGER.info('Job Scheduler stopped.') self.scheduler.clear_jobs() # Shutdown plugins - stderr( - 'Calling shutdown for %d modules.' % (len(self.shutdown_methods),) - ) + LOGGER.info( + 'Calling shutdown for %d modules.', len(self.shutdown_methods)) + for shutdown_method in self.shutdown_methods: try: - stderr( - "calling %s.%s" % ( - shutdown_method.__module__, shutdown_method.__name__, - ) - ) + LOGGER.debug( + 'Calling %s.%s', + shutdown_method.__module__, + shutdown_method.__name__) shutdown_method(self) except Exception as e: - stderr( - "Error calling shutdown method for module %s:%s" % ( - shutdown_method.__module__, e - ) - ) + LOGGER.exception('Error calling shutdown method: %s', e) + # Avoid calling shutdown methods if we already have. self.shutdown_methods = [] diff --git a/sopel/cli/run.py b/sopel/cli/run.py index e96e992b2a..fa9ab3de34 100755 --- a/sopel/cli/run.py +++ b/sopel/cli/run.py @@ -11,14 +11,14 @@ from __future__ import unicode_literals, absolute_import, print_function, division import argparse +import logging import os import platform import signal import sys import time -import traceback -from sopel import bot, config, tools, __version__ +from sopel import bot, config, logger, tools, __version__ from . import utils if sys.version_info < (2, 7): @@ -30,6 +30,8 @@ tools.stderr('Error: When running on Python 3, Python 3.3 is required.') sys.exit(1) +LOGGER = logging.getLogger(__name__) + ERR_CODE = 1 """Error code: program exited with an error""" ERR_CODE_NO_RESTART = 2 @@ -49,10 +51,10 @@ def run(settings, pid_file, daemon=False): def signal_handler(sig, frame): if sig == signal.SIGUSR1 or sig == signal.SIGTERM or sig == signal.SIGINT: - tools.stderr('Got quit signal, shutting down.') + LOGGER.warning('Got quit signal, shutting down.') p.quit('Closing') elif sig == signal.SIGUSR2 or sig == signal.SIGILL: - tools.stderr('Got restart signal.') + LOGGER.warning('Got restart signal, shutting down and restarting.') p.restart('Restarting') # Define empty variable `p` for bot @@ -73,20 +75,26 @@ def signal_handler(sig, frame): if hasattr(signal, 'SIGILL'): signal.signal(signal.SIGILL, signal_handler) p.setup() + except KeyboardInterrupt: + break + except Exception: + # In that case, there is nothing we can do. + # If the bot can't setup itself, then it won't run. + # This is a critical case scenario, where the user should have + # direct access to the exception traceback right in the console. + # Besides, we can't know if logging has been set up or not, so + # we can't rely on that here. + tools.stderr('Unexpected error in bot setup') + raise + + try: p.run(settings.core.host, int(settings.core.port)) except KeyboardInterrupt: break - except Exception: # TODO: Be specific - trace = traceback.format_exc() - try: - tools.stderr(trace) - except Exception: # TODO: Be specific - pass - logfile = open(os.path.join(settings.core.logdir, settings.basename + '.exceptions.log'), 'a') - logfile.write('Critical exception in core') - logfile.write(trace) - logfile.write('----------------------------------------\n\n') - logfile.close() + except Exception: + err_log = logging.getLogger('sopel.exceptions') + err_log.exception('Critical exception in core') + err_log.error('----------------------------------------') # TODO: This should be handled by command_start # All we should need here is a return value, but replacing the # os._exit() call below (at the end) broke ^C. @@ -101,8 +109,7 @@ def signal_handler(sig, frame): return -1 if p.hasquit: break - tools.stderr( - 'Warning: Disconnected. Reconnecting in %s seconds...' % delay) + LOGGER.warning('Disconnected. Reconnecting in %s seconds...', delay) time.sleep(delay) # TODO: This should be handled by command_start # All we should need here is a return value, but making this @@ -393,10 +400,7 @@ def command_start(opts): tools.stderr('Bot is not configured, can\'t start') return ERR_CODE_NO_RESTART - # Step Two: Manage logfile, stdout and stderr - utils.redirect_outputs(config_module, opts.quiet) - - # Step Three: Handle process-lifecycle options and manage the PID file + # Step Two: Handle process-lifecycle options and manage the PID file pid_dir = config_module.core.pid_dir pid_file_path = get_pid_filename(opts, pid_dir) pid = get_running_pid(pid_file_path) @@ -416,10 +420,10 @@ def command_start(opts): with open(pid_file_path, 'w') as pid_file: pid_file.write(str(os.getpid())) - # Step Four: Run Sopel + # Step Three: Run Sopel ret = run(config_module, pid_file_path) - # Step Five: Shutdown Clean-Up + # Step Four: Shutdown Clean-Up os.unlink(pid_file_path) if ret == -1: @@ -452,8 +456,8 @@ def command_stop(opts): tools.stderr('Sopel is not configured, can\'t stop') return ERR_CODE - # Redirect Outputs - utils.redirect_outputs(settings, opts.quiet) + # Configure logging + logger.setup_logging(settings) # Get Sopel's PID filename = get_pid_filename(opts, settings.core.pid_dir) @@ -491,8 +495,8 @@ def command_restart(opts): tools.stderr('Sopel is not configured, can\'t stop') return ERR_CODE - # Redirect Outputs - utils.redirect_outputs(settings, opts.quiet) + # Configure logging + logger.setup_logging(settings) # Get Sopel's PID filename = get_pid_filename(opts, settings.core.pid_dir) @@ -579,10 +583,7 @@ def command_legacy(opts): tools.stderr('Bot is not configured, can\'t start') return ERR_CODE_NO_RESTART - # Step Three: Manage logfile, stdout and stderr - utils.redirect_outputs(config_module, opts.quiet) - - # Step Four: Handle process-lifecycle options and manage the PID file + # Step Three: Handle process-lifecycle options and manage the PID file pid_dir = config_module.core.pid_dir pid_file_path = get_pid_filename(opts, pid_dir) old_pid = get_running_pid(pid_file_path) @@ -636,7 +637,7 @@ def command_legacy(opts): with open(pid_file_path, 'w') as pid_file: pid_file.write(str(os.getpid())) - # Step Five: Initialize and run Sopel + # Step Four: Initialize and run Sopel ret = run(config_module, pid_file_path) os.unlink(pid_file_path) if ret == -1: diff --git a/sopel/cli/utils.py b/sopel/cli/utils.py index 30566b0d9b..10702ee5e4 100644 --- a/sopel/cli/utils.py +++ b/sopel/cli/utils.py @@ -2,6 +2,7 @@ from __future__ import unicode_literals, absolute_import, print_function, division import inspect +import logging import os import sys @@ -22,6 +23,7 @@ 'red', ] +LOGGER = logging.getLogger(__name__) RESET = '\033[0m' RED = '\033[31m' @@ -160,10 +162,7 @@ def _plugins_wizard(settings): try: _plugin_wizard(settings, plugin) except Exception as e: - filename, lineno = tools.get_raising_file_and_line() - rel_path = os.path.relpath(filename, os.path.dirname(__file__)) - raising_stmt = "%s:%d" % (rel_path, lineno) - tools.stderr("Error loading %s: %s (%s)" % (name, e, raising_stmt)) + LOGGER.exception('Error loading %s: %s', name, e) def _plugin_wizard(settings, plugin): @@ -338,6 +337,9 @@ def load_settings(options): return config.Config(filename) +@tools.deprecated(reason='Obsoleted by modernized logging.', + version='7.0', + removed_in='8.0') def redirect_outputs(settings, is_quiet=False): """Redirect ``sys``'s outputs using Sopel's settings. @@ -346,8 +348,15 @@ def redirect_outputs(settings, is_quiet=False): :param bool is_quiet: Optional, set to True to make Sopel's outputs quiet Both ``sys.stderr`` and ``sys.stdout`` are redirected to a logfile. + + .. deprecated:: 7.0 + + Sopel now uses the built-in logging system for its output, and this + function is now deprecated. + """ - logfile = os.path.os.path.join(settings.core.logdir, settings.basename + '.stdio.log') + logfile = os.path.os.path.join( + settings.core.logdir, settings.basename + '.stdio.log') sys.stderr = tools.OutputRedirect(logfile, True, is_quiet) sys.stdout = tools.OutputRedirect(logfile, False, is_quiet) diff --git a/sopel/config/core_section.py b/sopel/config/core_section.py index 08da383e29..977dcbed6f 100644 --- a/sopel/config/core_section.py +++ b/sopel/config/core_section.py @@ -261,10 +261,10 @@ def homedir(self): logging_level = ChoiceAttribute('logging_level', ['CRITICAL', 'ERROR', 'WARNING', 'INFO', 'DEBUG'], - 'WARNING') + 'INFO') """The lowest severity of logs to display. - If not specified, this defaults to ``WARNING``. + If not specified, this defaults to ``INFO``. """ modes = ValidatedAttribute('modes', default='B') diff --git a/sopel/coretasks.py b/sopel/coretasks.py index 33542b0e1c..86516e3a90 100644 --- a/sopel/coretasks.py +++ b/sopel/coretasks.py @@ -12,6 +12,7 @@ # Licensed under the Eiffel Forum License 2. from __future__ import unicode_literals, absolute_import, print_function, division +import logging from random import randint import datetime import re @@ -24,12 +25,11 @@ from sopel.tools import Identifier, iteritems, events from sopel.tools.target import User, Channel import base64 -from sopel.logger import get_logger if sys.version_info.major >= 3: unicode = str -LOGGER = get_logger(__name__) +LOGGER = logging.getLogger(__name__) batched_caps = {} who_reqs = {} # Keeps track of reqs coming from this module, rather than others @@ -216,8 +216,8 @@ def track_modes(bot, trigger): if len(trigger.args) < 3: # We need at least [channel, mode, nickname] to do anything useful # MODE messages with fewer args won't help us - LOGGER.info("Received an apparently useless MODE message: {}" - .format(trigger.raw)) + LOGGER.debug("Received an apparently useless MODE message: {}" + .format(trigger.raw)) return # Our old MODE parsing code checked if any of the args was empty. # Somewhere around here would be a good place to re-implement that if it's diff --git a/sopel/irc.py b/sopel/irc.py index 1cd3c630cc..40bbcc1c5c 100644 --- a/sopel/irc.py +++ b/sopel/irc.py @@ -16,10 +16,8 @@ import asyncore import asynchat import os -import codecs -import traceback -from sopel.logger import get_logger -from sopel.tools import stderr, Identifier +import logging +from sopel.tools import Identifier from sopel.trigger import PreTrigger try: import ssl @@ -42,7 +40,7 @@ __all__ = ['Bot'] -LOGGER = get_logger(__name__) +LOGGER = logging.getLogger(__name__) class Bot(asynchat.async_chat): @@ -97,22 +95,8 @@ def log_raw(self, line, prefix): """Log raw line to the raw log.""" if not self.config.core.log_raw: return - if not os.path.isdir(self.config.core.logdir): - try: - os.mkdir(self.config.core.logdir) - except Exception as e: - stderr('There was a problem creating the logs directory.') - stderr('%s %s' % (str(e.__class__), str(e))) - stderr('Please fix this and then run Sopel again.') - os._exit(1) - f = codecs.open(os.path.join(self.config.core.logdir, self.config.basename + '.raw.log'), - 'a', encoding='utf-8') - f.write(prefix + unicode(time.time()) + "\t") - temp = line.replace('\n', '') - - f.write(temp) - f.write("\n") - f.close() + logger = logging.getLogger('sopel.raw') + logger.info('\t'.join([prefix, line.strip()])) def safe(self, string): """Remove newlines from a string.""" @@ -189,11 +173,11 @@ def run(self, host, port=6667): try: self.initiate_connect(host, port) except socket.error as e: - stderr('Connection error: %s' % e) + LOGGER.exception('Connection error: %s', e) self.handle_close() def initiate_connect(self, host, port): - stderr('Connecting to %s:%s...' % (host, port)) + LOGGER.info('Connecting to %s:%s...', host, port) source_address = ((self.config.core.bind_host, 0) if self.config.core.bind_host else None) self.set_socket(socket.create_connection((host, port), @@ -202,13 +186,14 @@ def initiate_connect(self, host, port): self.send = self._ssl_send self.recv = self._ssl_recv elif not has_ssl and self.config.core.use_ssl: - stderr('SSL is not avilable on your system, attempting connection ' - 'without it') + LOGGER.warning( + 'SSL is not available on your system; ' + 'attempting connection without it') self.connect((host, port)) try: asyncore.loop() except KeyboardInterrupt: - print('KeyboardInterrupt') + LOGGER.warning('KeyboardInterrupt') self.quit('KeyboardInterrupt') def restart(self, message): @@ -235,14 +220,16 @@ def handle_close(self): if hasattr(self, '_shutdown'): self._shutdown() - stderr('Closed!') # This will eventually call asyncore dispatchers close method, which # will release the main thread. This should be called last to avoid # race conditions. if self.socket: + LOGGER.debug('Closing socket') self.close() + LOGGER.info('Closed!') + def handle_connect(self): """ Connect to IRC server, handle TLS and authenticate @@ -279,7 +266,6 @@ def handle_connect(self): pass if not has_matched: # everything is broken - stderr("Invalid certificate, hostname mismatch!") LOGGER.error("invalid certificate, no hostname matches") if hasattr(self.config.core, 'pid_file_path'): os.unlink(self.config.core.pid_file_path) @@ -300,7 +286,7 @@ def handle_connect(self): self.write(('USER', self.user, '+iw', self.nick), self.name) # maintain connection - stderr('Connected.') + LOGGER.info('Connected.') self.last_ping_time = datetime.now() timeout_check_thread = threading.Thread(target=self._timeout_check) timeout_check_thread.daemon = True @@ -332,7 +318,10 @@ def _get_cnames(self, domain): def _timeout_check(self): while self.connected or self.connecting: if (datetime.now() - self.last_ping_time).seconds > int(self.config.core.timeout): - stderr('Ping timeout reached after %s seconds, closing connection' % self.config.core.timeout) + LOGGER.warning( + 'Ping timeout reached after %s seconds; ' + 'closing connection', + self.config.core.timeout) self.handle_close() break else: @@ -419,7 +408,7 @@ def found_terminator(self): if self.hasquit: self.close_when_done() elif pretrigger.event == '433': - stderr('Nickname already in use!') + LOGGER.error('Nickname already in use!') self.handle_close() self.dispatch(pretrigger) @@ -427,75 +416,47 @@ def found_terminator(self): def dispatch(self, pretrigger): pass - def error(self, trigger=None): + def error(self, trigger=None, exception=None): """Called internally when a module causes an error.""" - try: - trace = traceback.format_exc() - if sys.version_info.major < 3: - trace = trace.decode('utf-8', errors='xmlcharrefreplace') - stderr(trace) - try: - lines = list(reversed(trace.splitlines())) - report = [lines[0].strip()] - for line in lines: - line = line.strip() - if line.startswith('File "'): - report.append(line[0].lower() + line[1:]) - break - else: - report.append('source unknown') - - signature = '%s (%s)' % (report[0], report[1]) - # TODO: make not hardcoded - log_filename = os.path.join(self.config.core.logdir, self.config.basename + '.exceptions.log') - with codecs.open(log_filename, 'a', encoding='utf-8') as logfile: - logfile.write('Signature: %s\n' % signature) - if trigger: - logfile.write('from {} at {}. Message was: {}\n'.format( - trigger.nick, str(datetime.now()), trigger.group(0))) - logfile.write(trace) - logfile.write( - '----------------------------------------\n\n' - ) - except Exception as e: - stderr("Could not save full traceback!") - LOGGER.error("Could not save traceback from %s to file: %s", trigger.sender, str(e)) - - if trigger and self.config.core.reply_errors and trigger.sender is not None: - self.say(signature, trigger.sender) - if trigger: - LOGGER.error('Exception from {}: {} ({})'.format(trigger.sender, str(signature), trigger.raw)) - except Exception as e: - if trigger and self.config.core.reply_errors and trigger.sender is not None: - self.say("Got an error.", trigger.sender) - if trigger: - LOGGER.error('Exception from {}: {} ({})'.format(trigger.sender, str(e), trigger.raw)) + message = 'Unexpected error' + if exception: + message = '{} ({})'.format(message, exception) + + if trigger: + message = '{} from {} at {}. Message was: {}'.format( + message, trigger.nick, str(datetime.now()), trigger.group(0) + ) + + LOGGER.exception(message) + + if trigger and self.config.core.reply_errors and trigger.sender is not None: + self.say(message, trigger.sender) def handle_error(self): """Handle any uncaptured error in the core. - Overrides asyncore's handle_error. - + This method is an override of :meth:`asyncore.dispatcher.handle_error`, + the :class:`asynchat.async_chat` being a subclass of + :class:`asyncore.dispatcher`. """ - trace = traceback.format_exc() - stderr(trace) - LOGGER.error('Fatal error in core, please review exception log') - # TODO: make not hardcoded - logfile = codecs.open( - os.path.join(self.config.core.logdir, self.config.basename + '.exceptions.log'), - 'a', - encoding='utf-8' + LOGGER.error('Fatal error in core; please review exception log.') + + err_log = logging.getLogger('sopel.exceptions') + err_log.error( + 'Fatal error in core; handle_error() was called.\n' + 'Last raw line was: %s\n' + 'Buffer:\n%s\n', + self.raw, self.buffer ) - logfile.write('Fatal error in core, handle_error() was called\n') - logfile.write('last raw line was %s' % self.raw) - logfile.write(trace) - logfile.write('Buffer:\n') - logfile.write(self.buffer) - logfile.write('----------------------------------------\n\n') - logfile.close() + err_log.exception('Fatal error traceback') + err_log.error('----------------------------------------') + if self.error_count > 10: + # quit if too many errors if (datetime.now() - self.last_error_timestamp).seconds < 5: - stderr("Too many errors, can't continue") + LOGGER.error("Too many errors; can't continue") os._exit(1) + # TODO: should we reset error_count? + self.last_error_timestamp = datetime.now() self.error_count = self.error_count + 1 diff --git a/sopel/logger.py b/sopel/logger.py index f7cc1cec67..59a1ad6754 100644 --- a/sopel/logger.py +++ b/sopel/logger.py @@ -2,6 +2,10 @@ from __future__ import unicode_literals, absolute_import, print_function, division import logging +import os +from logging.config import dictConfig + +from sopel import tools class IrcLoggingHandler(logging.Handler): @@ -30,40 +34,108 @@ def formatException(self, exc_info): return ' - ' + repr(exc_info[1]) -def setup_logging(bot): - base_level = bot.config.core.logging_level or 'WARNING' - base_format = bot.config.core.logging_format - base_datefmt = bot.config.core.logging_datefmt - base_params = {'level': base_level} - if base_format: - base_params['format'] = base_format - if base_datefmt: - base_params['datefmt'] = base_datefmt - logging.basicConfig(**base_params) - logger = logging.getLogger('sopel') - if bot.config.core.logging_channel: - channel_level = bot.config.core.logging_channel_level or base_level - channel_format = bot.config.core.logging_channel_format or base_format - channel_datefmt = bot.config.core.logging_channel_datefmt or base_datefmt - channel_params = {} - if channel_format: - channel_params['fmt'] = channel_format - if channel_datefmt: - channel_params['datefmt'] = channel_datefmt - formatter = ChannelOutputFormatter(**channel_params) - handler = IrcLoggingHandler(bot, channel_level) - handler.setFormatter(formatter) - logger.addHandler(handler) +def setup_logging(settings): + log_directory = settings.core.logdir + base_level = settings.core.logging_level or 'WARNING' + base_format = settings.core.logging_format + base_datefmt = settings.core.logging_datefmt + + logging_config = { + 'version': 1, + 'formatters': { + 'sopel': { + 'format': base_format, + 'datefmt': base_datefmt, + }, + 'raw': { + 'format': '%(asctime)s %(message)s', + 'datefmt': base_datefmt, + }, + }, + 'loggers': { + # all purpose, sopel root logger + 'sopel': { + 'level': base_level, + 'handlers': ['console', 'logfile', 'errorfile'], + }, + # raw IRC log + 'sopel.raw': { + 'level': 'DEBUG', + 'propagate': False, + 'handlers': ['raw'], + }, + # asynchat exception logger + 'sopel.exceptions': { + 'level': 'INFO', + 'propagate': False, + 'handlers': ['exceptionfile'], + }, + }, + 'handlers': { + # output on stderr + 'console': { + 'level': 'DEBUG', + 'class': 'logging.StreamHandler', + 'formatter': 'sopel', + }, + # generic purpose log file + 'logfile': { + 'level': 'DEBUG', + 'class': 'logging.handlers.TimedRotatingFileHandler', + 'filename': os.path.join( + log_directory, settings.basename + '.sopel.log'), + 'when': 'midnight', + 'formatter': 'sopel', + }, + # catched error log file + 'errorfile': { + 'level': 'ERROR', + 'class': 'logging.handlers.TimedRotatingFileHandler', + 'filename': os.path.join( + log_directory, settings.basename + '.error.log'), + 'when': 'midnight', + 'formatter': 'sopel', + }, + # uncaught error file + 'exceptionfile': { + 'level': 'ERROR', + 'class': 'logging.handlers.TimedRotatingFileHandler', + 'filename': os.path.join( + log_directory, settings.basename + '.exceptions.log'), + 'when': 'midnight', + 'formatter': 'sopel', + }, + # raw IRC log file + 'raw': { + 'level': 'DEBUG', + 'class': 'logging.handlers.TimedRotatingFileHandler', + 'filename': os.path.join( + log_directory, settings.basename + '.raw.log'), + 'when': 'midnight', + 'formatter': 'raw', + }, + }, + } + dictConfig(logging_config) def get_logger(name=None): """Return a logger for a module, if the name is given. - This is equivalent to `logging.getLogger('sopel.modules.' + name)` when - name is given, and `logging.getLogger('sopel')` when it is not. The latter - case is intended for use in Sopel's core; modules should call - `get_logger(__name__)` to get a logger.""" - if name: - return logging.getLogger('sopel.modules.' + name) - else: + .. deprecated:: 7.0 + + Use ``logging.getLogger(__name__)`` in Sopel's code instead, and + :func:`sopel.tools.get_logger` for external plugins. + + This will warn a deprecation warning in Sopel 8.0 then removed in 9.0. + + """ + if not name: return logging.getLogger('sopel') + + parts = name.strip().split('.') + if len(parts) > 1 or parts[0] in ['sopel', 'sopel_modules']: + return logging.getLogger(name) + + # assume it's a plugin name, as intended by the original get_logger + return tools.get_logger(name) diff --git a/sopel/modules/bugzilla.py b/sopel/modules/bugzilla.py index dbddce375c..9b6fa5e791 100644 --- a/sopel/modules/bugzilla.py +++ b/sopel/modules/bugzilla.py @@ -8,18 +8,18 @@ """ from __future__ import unicode_literals, absolute_import, print_function, division +import logging import re import requests import xmltodict from sopel.config.types import StaticSection, ListAttribute -from sopel.logger import get_logger from sopel.module import rule regex = None -LOGGER = get_logger(__name__) +LOGGER = logging.getLogger(__name__) class BugzillaSection(StaticSection): diff --git a/sopel/modules/currency.py b/sopel/modules/currency.py index 80eb903148..4ca1d383f5 100644 --- a/sopel/modules/currency.py +++ b/sopel/modules/currency.py @@ -9,13 +9,13 @@ """ from __future__ import unicode_literals, absolute_import, print_function, division +import logging import re import time import requests from sopel.config.types import StaticSection, ValidatedAttribute -from sopel.logger import get_logger from sopel.module import commands, example, NOLIMIT, rule @@ -28,7 +28,7 @@ \s+(?:in|as|of|to)\s+ # preposition (([a-zA-Z]{3}$)|([a-zA-Z]{3})\s)+$ # one or more 3-letter currency code ''', re.VERBOSE) -LOGGER = get_logger(__name__) +LOGGER = logging.getLogger(__name__) UNSUPPORTED_CURRENCY = "Sorry, {} isn't currently supported." UNRECOGNIZED_INPUT = "Sorry, I didn't understand the input." diff --git a/sopel/modules/help.py b/sopel/modules/help.py index eac82804fb..853dffb425 100644 --- a/sopel/modules/help.py +++ b/sopel/modules/help.py @@ -14,19 +14,19 @@ import re import collections +import logging import socket import textwrap import requests from sopel.config.types import ChoiceAttribute, ValidatedAttribute, StaticSection -from sopel.logger import get_logger from sopel.module import commands, rule, example, priority from sopel.tools import SopelMemory SETTING_CACHE_NAMESPACE = 'help-setting-cache' # Set top-level memory key name -LOGGER = get_logger(__name__) +LOGGER = logging.getLogger(__name__) # Settings that should require the help listing to be regenerated, or # re-POSTed to paste, if they are changed during runtime. diff --git a/sopel/modules/ip.py b/sopel/modules/ip.py index 6ad24397b2..7f6ef9b580 100644 --- a/sopel/modules/ip.py +++ b/sopel/modules/ip.py @@ -10,6 +10,7 @@ from __future__ import unicode_literals, absolute_import, print_function, division +import logging import os import socket import tarfile @@ -17,7 +18,6 @@ import geoip2.database from sopel.config.types import FilenameAttribute, StaticSection -from sopel.logger import get_logger from sopel.module import commands, example urlretrieve = None @@ -33,7 +33,7 @@ pass -LOGGER = get_logger(__name__) +LOGGER = logging.getLogger(__name__) class GeoipSection(StaticSection): @@ -78,8 +78,8 @@ def _find_geoip_db(bot): return config.ip.GeoIP_db_path else: LOGGER.warning( - 'GeoIP path configured but DB not found in configured path' - ) + 'GeoIP path configured but DB not found in configured path') + if (os.path.isfile(os.path.join(config.core.homedir, 'GeoLite2-City.mmdb')) and os.path.isfile(os.path.join(config.core.homedir, 'GeoLite2-ASN.mmdb'))): return config.core.homedir @@ -87,13 +87,14 @@ def _find_geoip_db(bot): os.path.isfile(os.path.join('/usr/share/GeoIP', 'GeoLite2-ASN.mmdb'))): return '/usr/share/GeoIP' elif urlretrieve: - LOGGER.warning('Downloading GeoIP database') + LOGGER.info('Downloading GeoIP database') bot.say('Downloading GeoIP database, please wait...') geolite_urls = [ 'https://geolite.maxmind.com/download/geoip/database/GeoLite2-City.tar.gz', 'https://geolite.maxmind.com/download/geoip/database/GeoLite2-ASN.tar.gz' ] for url in geolite_urls: + LOGGER.debug('GeoIP Source URL: %s', url) full_path = os.path.join(config.core.homedir, url.split("/")[-1]) urlretrieve(url, full_path) _decompress(full_path, config.core.homedir) diff --git a/sopel/modules/ipython.py b/sopel/modules/ipython.py index 51fb266c2f..461d5ffe11 100644 --- a/sopel/modules/ipython.py +++ b/sopel/modules/ipython.py @@ -13,28 +13,11 @@ import sopel import sopel.module -if sys.version_info.major >= 3: - # Backup stderr/stdout wrappers - old_stdout = sys.stdout - old_stderr = sys.stderr - - # IPython wants actual stderr and stdout. In Python 2, it only needed that - # when actually starting the console, but in Python 3 it seems to need that - # on import as well - sys.stdout = sys.__stdout__ - sys.stderr = sys.__stderr__ -try: - import IPython - if hasattr(IPython, 'terminal'): - from IPython.terminal.embed import InteractiveShellEmbed - else: - from IPython.frontend.terminal.embed import InteractiveShellEmbed -finally: - if sys.version_info.major >= 3: - # Restore stderr/stdout wrappers - sys.stdout = old_stdout - sys.stderr = old_stderr - +import IPython +if hasattr(IPython, 'terminal'): + from IPython.terminal.embed import InteractiveShellEmbed +else: + from IPython.frontend.terminal.embed import InteractiveShellEmbed console = None diff --git a/sopel/modules/reload.py b/sopel/modules/reload.py index 5264328831..3ab4553f24 100644 --- a/sopel/modules/reload.py +++ b/sopel/modules/reload.py @@ -8,11 +8,14 @@ """ from __future__ import unicode_literals, absolute_import, print_function, division -import os +import logging import subprocess import sopel.module -from sopel import plugins, tools +from sopel import plugins + + +LOGGER = logging.getLogger(__name__) def _load(bot, plugin): @@ -23,11 +26,7 @@ def _load(bot, plugin): plugin.setup(bot) plugin.register(bot) except Exception as e: - filename, lineno = tools.get_raising_file_and_line() - rel_path = os.path.relpath(filename, os.path.dirname(__file__)) - raising_stmt = "%s:%d" % (rel_path, lineno) - tools.stderr( - "Error loading %s: %s (%s)" % (plugin.name, e, raising_stmt)) + LOGGER.exception('Error loading %s: %s', plugin.name, e) raise diff --git a/sopel/modules/safety.py b/sopel/modules/safety.py index 06aaadfd4e..aafdcebaa6 100644 --- a/sopel/modules/safety.py +++ b/sopel/modules/safety.py @@ -8,16 +8,16 @@ """ from __future__ import unicode_literals, absolute_import, print_function, division -import sys -import time +import logging import os.path import re +import sys +import time import requests from sopel.config.types import StaticSection, ValidatedAttribute, ListAttribute from sopel.formatting import color, bold -from sopel.logger import get_logger from sopel.module import OP import sopel.tools @@ -38,7 +38,7 @@ from urlparse import urlparse -LOGGER = get_logger(__name__) +LOGGER = logging.getLogger(__name__) vt_base_api_url = 'https://www.virustotal.com/vtapi/v2/url/' malware_domains = set() @@ -108,8 +108,9 @@ def shutdown(bot): def _download_malwaredomains_db(path): - print('Downloading malwaredomains db...') - urlretrieve('https://mirror1.malwaredomains.com/files/justdomains', path) + url = 'https://mirror1.malwaredomains.com/files/justdomains' + LOGGER.info('Downloading malwaredomains db from %s', url) + urlretrieve(url, path) @sopel.module.rule(r'(?u).*(https?://\S+).*') diff --git a/sopel/tools/__init__.py b/sopel/tools/__init__.py index ef2e863e11..970458412c 100644 --- a/sopel/tools/__init__.py +++ b/sopel/tools/__init__.py @@ -16,6 +16,7 @@ import codecs import functools +import logging import os import re import sys @@ -55,21 +56,6 @@ def get_input(prompt): return raw_input(prompt).decode('utf8') -def get_raising_file_and_line(tb=None): - """Get the file and line number where an exception happened. - - :param tb: the traceback (uses the most recent exception if not given) - :return: a tuple of the filename and line number - :rtype: (str, int) - """ - if not tb: - tb = sys.exc_info()[2] - - filename, lineno, _context, _line = traceback.extract_tb(tb)[-1] - - return filename, lineno - - def compile_rule(nick, pattern, alias_nicks): """Compile a rule regex and fill in nickname placeholders. @@ -498,9 +484,9 @@ def flush(self): # These seems to trace back to when we thought we needed a try/except on prints, -# because it looked like that was why we were having problems. We'll drop it in -# 4.0^H^H^H5.0^H^H^H6.0^H^H^Hsome version when someone can be bothered. -@deprecated +# because it looked like that was why we were having problems. +# We'll drop it in Sopel 8.0 because it has been here for far too long already. +@deprecated('Use `print()` instead of sopel.tools.stdout', removed_in='8.0') def stdout(string): print(string) @@ -549,6 +535,30 @@ def get_hostmask_regex(mask): return re.compile(mask + '$', re.I) +def get_logger(plugin_name): + """Return a logger for a plugin. + + :param str plugin_name: name of the plugin + :return: the logger for the given plugin + + This:: + + from sopel import plugins + LOGGER = plugins.get_logger('my_custom_plugin') + + is equivalent to this:: + + import logging + LOGGER = logging.getLogger('sopel.externals.my_custom_plugin') + + Internally, Sopel configures logging for the ``sopel`` namespace, so + external plugins can't benefit from it with ``logging.getLogger(__name__)`` + as they won't be in the same namespace. This function uses the + ``plugin_name`` with a prefix inside this namespace. + """ + return logging.getLogger('sopel.externals.%s' % plugin_name) + + class SopelMemory(dict): """A simple thread-safe ``dict`` implementation. @@ -643,3 +653,25 @@ def contains(self, key): operator, you should be. """ return self.__contains__(key) + + +@deprecated(version='7.0', removed_in='8.0') +def get_raising_file_and_line(tb=None): + """Get the file and line number where an exception happened. + + :param tb: the traceback (uses the most recent exception if not given) + :return: a tuple of the filename and line number + :rtype: (str, int) + + .. deprecated:: 7.0 + + Use Python's built-in logging system, with the ``logger.exception`` + method. This method makes sure to log the exception with the traceback + and the relevant information (filename, line number, etc.). + """ + if not tb: + tb = sys.exc_info()[2] + + filename, lineno, _context, _line = traceback.extract_tb(tb)[-1] + + return filename, lineno diff --git a/sopel/tools/jobs.py b/sopel/tools/jobs.py index 690ee5fce8..8df62eca3b 100644 --- a/sopel/tools/jobs.py +++ b/sopel/tools/jobs.py @@ -82,12 +82,12 @@ def run(self): except KeyboardInterrupt: # Do not block on KeyboardInterrupt raise - except Exception: # TODO: Be specific + except Exception as error: # TODO: Be specific # Modules exceptions are caught earlier, so this is a bit # more serious. Options are to either stop the main thread # or continue this thread and hope that it won't happen # again. - self.bot.error() + self.bot.error(exception=error) # Sleep a bit to guard against busy-looping and filling # the log with useless error messages. time.sleep(10.0) # seconds @@ -115,8 +115,8 @@ def _call(self, func): except KeyboardInterrupt: # Do not block on KeyboardInterrupt raise - except Exception: # TODO: Be specific - self.bot.error() + except Exception as error: # TODO: Be specific + self.bot.error(exception=error) class Job(object):