Skip to content

Commit

Permalink
Merge pull request #1678 from Exirel/rework-logging
Browse files Browse the repository at this point in the history 
core: Rework logging
  • Loading branch information
@dgw
dgw committed Oct 8, 2019
2 parents ac2779e + a2c2d20 commit d896391
Show file tree
Hide file tree
Showing 16 changed files with 443 additions and 304 deletions.
222 changes: 151 additions & 71 deletions sopel/bot.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,15 +10,15 @@
from ast import literal_eval
import collections
import itertools
import os
import logging
import re
import sys
import threading
import time

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
Expand All @@ -27,7 +27,7 @@

__all__ = ['Sopel', 'SopelWrapper']

LOGGER = logger.get_logger(__name__)
LOGGER = logging.getLogger(__name__)

if sys.version_info.major >= 3:
unicode = str
Expand Down Expand Up @@ -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
Expand All @@ -230,35 +251,28 @@ 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():
plugin.setup(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
Expand All @@ -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
Expand All @@ -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"""
Expand All @@ -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"""
Expand All @@ -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`
Expand All @@ -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.
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 = []

Expand Down

0 comments on commit d896391

Please sign in to comment.