From 4578c4f0e1659daab8d25c79d1f466ae9838d8c7 Mon Sep 17 00:00:00 2001 From: Bruno Cauet Date: Tue, 10 Feb 2015 15:30:15 +0100 Subject: [PATCH] Improve logging management for plugins Listeners get logging level modulations, like import_stages already did. Add extensive tests: - explicit plugin commands are logged like core beets (INFO or DEBUG) - import stages are more silent - event listeners are like import stages Delete @BeetsPlugin.listen decorator since listeners need plugin instance context to set its logging level. Improve #1244. Next is multiple verbosity levels. --- beets/plugins.py | 66 ++++++++++++--------------------- test/test_logging.py | 88 ++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 111 insertions(+), 43 deletions(-) diff --git a/beets/plugins.py b/beets/plugins.py index bd285da2d..b7d4c9445 100755 --- a/beets/plugins.py +++ b/beets/plugins.py @@ -84,10 +84,8 @@ class BeetsPlugin(object): self._log = log.getChild(self.name) self._log.setLevel(logging.NOTSET) # Use `beets` logger level. - if beets.config['verbose']: - if not any(isinstance(f, PluginLogFilter) - for f in self._log.filters): - self._log.addFilter(PluginLogFilter(self)) + if not any(isinstance(f, PluginLogFilter) for f in self._log.filters): + self._log.addFilter(PluginLogFilter(self)) def commands(self): """Should return a list of beets.ui.Subcommand objects for @@ -106,23 +104,24 @@ class BeetsPlugin(object): return [self._set_log_level(logging.WARNING, import_stage) for import_stage in self.import_stages] - def _set_log_level(self, log_level, func): + def _set_log_level(self, base_log_level, func): """Wrap `func` to temporarily set this plugin's logger level to - `log_level` (and restore it after the function returns). - - The level is *not* adjusted when beets is in verbose - mode---i.e., the plugin logger continues to delegate to the base - beets logger. + `base_log_level` + config options (and restore it to NOTSET after the + function returns). """ @wraps(func) def wrapper(*args, **kwargs): - if not beets.config['verbose']: - old_log_level = self._log.level - self._log.setLevel(log_level) - result = func(*args, **kwargs) - if not beets.config['verbose']: - self._log.setLevel(old_log_level) - return result + assert self._log.level == logging.NOTSET + + log_level = base_log_level + if beets.config['verbose'].get(bool): + log_level -= 10 + self._log.setLevel(log_level) + + try: + return func(*args, **kwargs) + finally: + self._log.setLevel(logging.NOTSET) return wrapper def queries(self): @@ -183,34 +182,15 @@ class BeetsPlugin(object): listeners = None - @classmethod - def register_listener(cls, event, func): - """Add a function as a listener for the specified event. (An - imperative alternative to the @listen decorator.) + def register_listener(self, event, func): + """Add a function as a listener for the specified event. """ - if cls.listeners is None: - cls.listeners = defaultdict(list) - if func not in cls.listeners[event]: - cls.listeners[event].append(func) + func = self._set_log_level(logging.WARNING, func) - @classmethod - def listen(cls, event): - """Decorator that adds a function as an event handler for the - specified event (as a string). The parameters passed to function - will vary depending on what event occurred. - - The function should respond to named parameters. - function(**kwargs) will trap all arguments in a dictionary. - Example: - - >>> @MyPlugin.listen("imported") - >>> def importListener(**kwargs): - ... pass - """ - def helper(func): - cls.register_listener(event, func) - return func - return helper + if self.listeners is None: + self.listeners = defaultdict(list) + if func not in self.listeners[event]: + self.listeners[event].append(func) template_funcs = None template_fields = None diff --git a/test/test_logging.py b/test/test_logging.py index 864fd021a..bc8ade0aa 100644 --- a/test/test_logging.py +++ b/test/test_logging.py @@ -2,11 +2,15 @@ from __future__ import (division, absolute_import, print_function, unicode_literals) +import sys import logging as log from StringIO import StringIO import beets.logging as blog +from beets import plugins, ui +import beetsplug from test._common import unittest, TestCase +from test import helper class LoggingTest(TestCase): @@ -37,6 +41,90 @@ class LoggingTest(TestCase): self.assertTrue(stream.getvalue(), "foo oof baz") +class LoggingLevelTest(unittest.TestCase, helper.TestHelper): + class DummyModule(object): + class DummyPlugin(plugins.BeetsPlugin): + def __init__(self): + plugins.BeetsPlugin.__init__(self, 'dummy') + self.import_stages = [self.import_stage] + self.register_listener('dummy_event', self.listener) + + def log_all(self, name): + self._log.debug('debug ' + name) + self._log.info('info ' + name) + self._log.warning('warning ' + name) + + def commands(self): + cmd = ui.Subcommand('dummy') + cmd.func = lambda _, __, ___: self.log_all('cmd') + return (cmd,) + + def import_stage(self, session, task): + self.log_all('import_stage') + + def listener(self): + self.log_all('listener') + + def setUp(self): + sys.modules['beetsplug.dummy'] = self.DummyModule + beetsplug.dummy = self.DummyModule + self.setup_beets() + self.load_plugins('dummy') + + def tearDown(self): + self.unload_plugins() + self.teardown_beets() + del beetsplug.dummy + sys.modules.pop('beetsplug.dummy') + + def test_command_logging(self): + self.config['verbose'] = False + with helper.capture_log() as logs: + self.run_command('dummy') + self.assertIn('dummy: warning cmd', logs) + self.assertIn('dummy: info cmd', logs) + self.assertNotIn('dummy: debug cmd', logs) + + self.config['verbose'] = True + with helper.capture_log() as logs: + self.run_command('dummy') + self.assertIn('dummy: warning cmd', logs) + self.assertIn('dummy: info cmd', logs) + self.assertIn('dummy: debug cmd', logs) + + def test_listener_logging(self): + self.config['verbose'] = False + with helper.capture_log() as logs: + plugins.send('dummy_event') + self.assertIn('dummy: warning listener', logs) + self.assertNotIn('dummy: info listener', logs) + self.assertNotIn('dummy: debug listener', logs) + + self.config['verbose'] = True + with helper.capture_log() as logs: + plugins.send('dummy_event') + self.assertIn('dummy: warning listener', logs) + self.assertIn('dummy: info listener', logs) + self.assertNotIn('dummy: debug listener', logs) + + def test_import_stage_logging(self): + self.config['verbose'] = False + with helper.capture_log() as logs: + importer = self.create_importer() + importer.run() + self.assertIn('dummy: warning import_stage', logs) + self.assertNotIn('dummy: info import_stage', logs) + self.assertNotIn('dummy: debug import_stage', logs) + + self.config['verbose'] = True + with helper.capture_log() as logs: + importer = self.create_importer() + importer.run() + self.assertIn('dummy: warning import_stage', logs) + self.assertIn('dummy: info import_stage', logs) + self.assertNotIn('dummy: debug import_stage', logs) + + def suite(): return unittest.TestLoader().loadTestsFromName(__name__)