From 4578c4f0e1659daab8d25c79d1f466ae9838d8c7 Mon Sep 17 00:00:00 2001 From: Bruno Cauet Date: Tue, 10 Feb 2015 15:30:15 +0100 Subject: [PATCH 1/6] 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__) From 327b62b6103771bd19465f10a6d4f0412c2b9f1c Mon Sep 17 00:00:00 2001 From: Bruno Cauet Date: Tue, 10 Feb 2015 16:55:06 +0100 Subject: [PATCH 2/6] Improve logging management for plugins: fixes Delete the remaining usages of BeetsPlugin.listen(). Since BeetsPlugin.listeners are wrapped by a loglevel-setting function, we cannot easily check their unicity anymore. BeetsPlugin._raw_listeners set holds the raw listeners. Legacy plugins that did not handle enough arguments in their listenings functions may break: dedicated code is now deleted for it would not work with the decorated listeners. Tests got fixed. Some modifications were done empirically: if it passes then it's okay. --- beets/plugins.py | 19 ++++++++++--------- beetsplug/chroma.py | 2 +- beetsplug/fromfilename.py | 5 +++-- beetsplug/permissions.py | 5 +++-- test/test_plugins.py | 17 +++++++---------- 5 files changed, 24 insertions(+), 24 deletions(-) diff --git a/beets/plugins.py b/beets/plugins.py index b7d4c9445..58d9bc0ee 100755 --- a/beets/plugins.py +++ b/beets/plugins.py @@ -18,7 +18,6 @@ from __future__ import (division, absolute_import, print_function, unicode_literals) import traceback -import inspect import re from collections import defaultdict from functools import wraps @@ -180,17 +179,21 @@ class BeetsPlugin(object): mediafile.MediaFile.add_field(name, descriptor) library.Item._media_fields.add(name) + _raw_listeners = None listeners = None def register_listener(self, event, func): """Add a function as a listener for the specified event. """ - func = self._set_log_level(logging.WARNING, func) + wrapped_func = self._set_log_level(logging.WARNING, func) - if self.listeners is None: - self.listeners = defaultdict(list) - if func not in self.listeners[event]: - self.listeners[event].append(func) + cls = self.__class__ + if cls.listeners is None or cls._raw_listeners is None: + cls._raw_listeners = defaultdict(list) + cls.listeners = defaultdict(list) + if func not in cls._raw_listeners[event]: + cls._raw_listeners[event].append(func) + cls.listeners[event].append(wrapped_func) template_funcs = None template_fields = None @@ -440,9 +443,7 @@ def send(event, **arguments): results = [] for handler in event_handlers()[event]: # Don't break legacy plugins if we want to pass more arguments - argspec = inspect.getargspec(handler).args - args = dict((k, v) for k, v in arguments.items() if k in argspec) - result = handler(**args) + result = handler(**arguments) if result is not None: results.append(result) return results diff --git a/beetsplug/chroma.py b/beetsplug/chroma.py index 928f90479..8a83c0002 100644 --- a/beetsplug/chroma.py +++ b/beetsplug/chroma.py @@ -136,6 +136,7 @@ class AcoustidPlugin(plugins.BeetsPlugin): if self.config['auto']: self.register_listener('import_task_start', self.fingerprint_task) + self.register_listener('import_task_apply', apply_acoustid_metadata) def fingerprint_task(self, task, session): return fingerprint_task(self._log, task, session) @@ -211,7 +212,6 @@ def fingerprint_task(log, task, session): acoustid_match(log, item.path) -@AcoustidPlugin.listen('import_task_apply') def apply_acoustid_metadata(task, session): """Apply Acoustid metadata (fingerprint and ID) to the task's items. """ diff --git a/beetsplug/fromfilename.py b/beetsplug/fromfilename.py index 169c02ff6..dc040a0a2 100644 --- a/beetsplug/fromfilename.py +++ b/beetsplug/fromfilename.py @@ -140,10 +140,11 @@ def apply_matches(d): # Plugin structure and hook into import process. class FromFilenamePlugin(plugins.BeetsPlugin): - pass + def __init__(self): + super(FromFilenamePlugin, self).__init__() + self.register_listener('import_task_start', filename_task) -@FromFilenamePlugin.listen('import_task_start') def filename_task(task, session): """Examine each item in the task to see if we can extract a title from the filename. Try to match all filenames to a number of diff --git a/beetsplug/permissions.py b/beetsplug/permissions.py index 256f09e52..5068c2a0a 100644 --- a/beetsplug/permissions.py +++ b/beetsplug/permissions.py @@ -37,9 +37,10 @@ class Permissions(BeetsPlugin): u'file': 644 }) + self.register_listener('item_imported', permissions) + self.register_listener('album_imported', permissions) + -@Permissions.listen('item_imported') -@Permissions.listen('album_imported') def permissions(lib, item=None, album=None): """Running the permission fixer. """ diff --git a/test/test_plugins.py b/test/test_plugins.py index d46c5bd5d..c9c5be502 100644 --- a/test/test_plugins.py +++ b/test/test_plugins.py @@ -35,6 +35,7 @@ class TestHelper(helper.TestHelper): def setup_plugin_loader(self): # FIXME the mocking code is horrific, but this is the lowest and # earliest level of the plugin mechanism we can hook into. + self.load_plugins() self._plugin_loader_patch = patch('beets.plugins.load_plugins') self._plugin_classes = set() load_plugins = self._plugin_loader_patch.start() @@ -95,7 +96,7 @@ class ItemWriteTest(unittest.TestCase, TestHelper): class EventListenerPlugin(plugins.BeetsPlugin): pass - self.event_listener_plugin = EventListenerPlugin + self.event_listener_plugin = EventListenerPlugin() self.register_plugin(EventListenerPlugin) def tearDown(self): @@ -298,19 +299,15 @@ class ListenersTest(unittest.TestCase, TestHelper): pass d = DummyPlugin() - self.assertEqual(DummyPlugin.listeners['cli_exit'], [d.dummy]) + self.assertEqual(DummyPlugin._raw_listeners['cli_exit'], [d.dummy]) d2 = DummyPlugin() - DummyPlugin.register_listener('cli_exit', d.dummy) - self.assertEqual(DummyPlugin.listeners['cli_exit'], + self.assertEqual(DummyPlugin._raw_listeners['cli_exit'], [d.dummy, d2.dummy]) - @DummyPlugin.listen('cli_exit') - def dummy(lib): - pass - - self.assertEqual(DummyPlugin.listeners['cli_exit'], - [d.dummy, d2.dummy, dummy]) + d.register_listener('cli_exit', d2.dummy) + self.assertEqual(DummyPlugin._raw_listeners['cli_exit'], + [d.dummy, d2.dummy]) def suite(): From f1e13cf886a23a3b933a5f39163b32c44bdda5e6 Mon Sep 17 00:00:00 2001 From: Bruno Cauet Date: Tue, 10 Feb 2015 17:13:15 +0100 Subject: [PATCH 3/6] Offer verbose and very verbose modes 'verbose' is now an int and not a boolean. '-v' is level 1, '-vv' level 2. In the configuration it can be set with 'verbose: 1' or 'verbose: 2'. Improve #1244: auditing current log levels of plugins remains. --- beets/config_default.yaml | 2 +- beets/plugins.py | 5 ++--- beets/ui/__init__.py | 4 ++-- test/helper.py | 2 +- test/test_logging.py | 38 +++++++++++++++++++++++++++----------- test/test_spotify.py | 2 +- 6 files changed, 34 insertions(+), 19 deletions(-) diff --git a/beets/config_default.yaml b/beets/config_default.yaml index c448585d9..b98ffbfc6 100644 --- a/beets/config_default.yaml +++ b/beets/config_default.yaml @@ -43,7 +43,7 @@ pluginpath: [] threaded: yes timeout: 5.0 per_disc_numbering: no -verbose: no +verbose: 0 terminal_encoding: utf8 original_date: no id3v23: no diff --git a/beets/plugins.py b/beets/plugins.py index 58d9bc0ee..9235883d0 100755 --- a/beets/plugins.py +++ b/beets/plugins.py @@ -112,9 +112,8 @@ class BeetsPlugin(object): def wrapper(*args, **kwargs): assert self._log.level == logging.NOTSET - log_level = base_log_level - if beets.config['verbose'].get(bool): - log_level -= 10 + verbosity = beets.config['verbose'].get(int) + log_level = max(logging.DEBUG, base_log_level - 10 * verbosity) self._log.setLevel(log_level) try: diff --git a/beets/ui/__init__.py b/beets/ui/__init__.py index 02a7a9478..e041db95e 100644 --- a/beets/ui/__init__.py +++ b/beets/ui/__init__.py @@ -858,7 +858,7 @@ def _configure(options): config.set_args(options) # Configure the logger. - if config['verbose'].get(bool): + if config['verbose'].get(int): log.setLevel(logging.DEBUG) else: log.setLevel(logging.INFO) @@ -917,7 +917,7 @@ def _raw_main(args, lib=None): help='library database file to use') parser.add_option('-d', '--directory', dest='directory', help="destination music directory") - parser.add_option('-v', '--verbose', dest='verbose', action='store_true', + parser.add_option('-v', '--verbose', dest='verbose', action='count', help='print debugging information') parser.add_option('-c', '--config', dest='config', help='path to configuration file') diff --git a/test/helper.py b/test/helper.py index e929eecff..8d0dbf8a6 100644 --- a/test/helper.py +++ b/test/helper.py @@ -167,7 +167,7 @@ class TestHelper(object): self.config.read() self.config['plugins'] = [] - self.config['verbose'] = True + self.config['verbose'] = 1 self.config['ui']['color'] = False self.config['threaded'] = False diff --git a/test/test_logging.py b/test/test_logging.py index bc8ade0aa..a4e2cfbe7 100644 --- a/test/test_logging.py +++ b/test/test_logging.py @@ -78,37 +78,45 @@ class LoggingLevelTest(unittest.TestCase, helper.TestHelper): sys.modules.pop('beetsplug.dummy') def test_command_logging(self): - self.config['verbose'] = False + self.config['verbose'] = 0 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) + for level in (1, 2): + self.config['verbose'] = level + 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 + self.config['verbose'] = 0 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 + self.config['verbose'] = 1 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) + self.config['verbose'] = 2 + with helper.capture_log() as logs: + plugins.send('dummy_event') + self.assertIn('dummy: warning listener', logs) + self.assertIn('dummy: info listener', logs) + self.assertIn('dummy: debug listener', logs) + def test_import_stage_logging(self): - self.config['verbose'] = False + self.config['verbose'] = 0 with helper.capture_log() as logs: importer = self.create_importer() importer.run() @@ -116,7 +124,7 @@ class LoggingLevelTest(unittest.TestCase, helper.TestHelper): self.assertNotIn('dummy: info import_stage', logs) self.assertNotIn('dummy: debug import_stage', logs) - self.config['verbose'] = True + self.config['verbose'] = 1 with helper.capture_log() as logs: importer = self.create_importer() importer.run() @@ -124,6 +132,14 @@ class LoggingLevelTest(unittest.TestCase, helper.TestHelper): self.assertIn('dummy: info import_stage', logs) self.assertNotIn('dummy: debug import_stage', logs) + self.config['verbose'] = 2 + 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.assertIn('dummy: debug import_stage', logs) + def suite(): return unittest.TestLoader().loadTestsFromName(__name__) diff --git a/test/test_spotify.py b/test/test_spotify.py index 3d4d75bde..3025163bb 100644 --- a/test/test_spotify.py +++ b/test/test_spotify.py @@ -17,7 +17,7 @@ class ArgumentsMock(object): def __init__(self, mode, show_failures): self.mode = mode self.show_failures = show_failures - self.verbose = True + self.verbose = 1 def _params(url): From a014750e2dba00386c300cc62e06898bf591c472 Mon Sep 17 00:00:00 2001 From: Bruno Cauet Date: Tue, 10 Feb 2015 17:26:56 +0100 Subject: [PATCH 4/6] Update docs: mention multi-level logging If you think what I wrote suck, it's because it does. --- docs/changelog.rst | 7 ++++++- docs/dev/plugins.rst | 27 +++++++++++++++++---------- docs/reference/cli.rst | 2 +- 3 files changed, 24 insertions(+), 12 deletions(-) diff --git a/docs/changelog.rst b/docs/changelog.rst index 81493428c..b8bdc15cc 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -6,6 +6,9 @@ Changelog Features: +* Verbosity is now an integer in the configuration since multiple levels are + supported (like e.g. apt-get). On the CLI one can stack verbose flags (i.e. + `-vv`). :bug:`1244` * The summary shown to compare duplicate albums during import now displays the old and new filesizes. :bug:`1291` * The colors used are now configurable via the new config option ``colors``, @@ -106,7 +109,9 @@ For developers: * The logging system in beets has been overhauled. Plugins now each have their own logger, which helps by automatically adjusting the verbosity level in - import mode and by prefixing the plugin's name. Also, logging calls can (and + import mode and by prefixing the plugin's name. Logging levels are + dynamically set when a plugin is called, depending on how it is called + (import stage, event or direct command). Finally, logging calls can (and should!) use modern ``{}``-style string formatting lazily. See :ref:`plugin-logging` in the plugin API docs. * A new ``import_task_created`` event lets you manipulate import tasks diff --git a/docs/dev/plugins.rst b/docs/dev/plugins.rst index 97da193f0..f448b5dfa 100644 --- a/docs/dev/plugins.rst +++ b/docs/dev/plugins.rst @@ -480,14 +480,21 @@ str.format-style string formatting. So you can write logging calls like this:: .. _PEP 3101: https://www.python.org/dev/peps/pep-3101/ .. _standard Python logging module: https://docs.python.org/2/library/logging.html -The per-plugin loggers have two convenient features: +When beets is in verbose mode, plugin messages are prefixed with the plugin +name to make them easier to see. + +What messages will be logged depends on the logging level and the action +performed: + +* On import stages and event, the default is ``WARNING`` messages. +* On direct actions, the default is ``INFO`` and ``WARNING`` message. + +The verbosity can be increased with ``--verbose`` flags: each flags lowers the +level by a notch. + +This addresses a common pattern where plugins need to use the same code for a +command and an import stage, but the command needs to print more messages than +the import stage. (For example, you'll want to log "found lyrics for this song" +when you're run explicitly as a command, but you don't want to noisily +interrupt the importer interface when running automatically.) -* When beets is in verbose mode, messages are prefixed with the plugin name to - make them easier to see. -* Messages at the ``INFO`` logging level are hidden when the plugin is running - in an importer stage (see above). This addresses a common pattern where - plugins need to use the same code for a command and an import stage, but the - command needs to print more messages than the import stage. (For example, - you'll want to log "found lyrics for this song" when you're run explicitly - as a command, but you don't want to noisily interrupt the importer interface - when running automatically.) diff --git a/docs/reference/cli.rst b/docs/reference/cli.rst index e569c073c..f889be678 100644 --- a/docs/reference/cli.rst +++ b/docs/reference/cli.rst @@ -369,7 +369,7 @@ import ...``. * ``-l LIBPATH``: specify the library database file to use. * ``-d DIRECTORY``: specify the library root directory. * ``-v``: verbose mode; prints out a deluge of debugging information. Please use - this flag when reporting bugs. + this flag when reporting bugs. It can be stacked twice. * ``-c FILE``: read a specified YAML :doc:`configuration file `. Beets also uses the ``BEETSDIR`` environment variable to look for From 5a1f499c6413a054fb53a527a61dca92f6032b00 Mon Sep 17 00:00:00 2001 From: Bruno Cauet Date: Wed, 11 Feb 2015 09:06:13 +0100 Subject: [PATCH 5/6] Discogs plugin: fix event listener params Also delete related deprecated comment. --- beets/plugins.py | 1 - beetsplug/discogs.py | 2 +- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/beets/plugins.py b/beets/plugins.py index 9235883d0..59aa9763c 100755 --- a/beets/plugins.py +++ b/beets/plugins.py @@ -441,7 +441,6 @@ def send(event, **arguments): log.debug(u'Sending event: {0}', event) results = [] for handler in event_handlers()[event]: - # Don't break legacy plugins if we want to pass more arguments result = handler(**arguments) if result is not None: results.append(result) diff --git a/beetsplug/discogs.py b/beetsplug/discogs.py index 267041bcc..a8b02f349 100644 --- a/beetsplug/discogs.py +++ b/beetsplug/discogs.py @@ -58,7 +58,7 @@ class DiscogsPlugin(BeetsPlugin): self.discogs_client = None self.register_listener('import_begin', self.setup) - def setup(self): + def setup(self, session): """Create the `discogs_client` field. Authenticate if necessary. """ c_key = self.config['apikey'].get(unicode) From 06cc5346f243e49f599208f62086bbd82523f050 Mon Sep 17 00:00:00 2001 From: Bruno Cauet Date: Wed, 11 Feb 2015 09:11:34 +0100 Subject: [PATCH 6/6] Make less assumptions on plugin log levels --- beets/plugins.py | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/beets/plugins.py b/beets/plugins.py index 59aa9763c..bee4d9f32 100755 --- a/beets/plugins.py +++ b/beets/plugins.py @@ -105,13 +105,15 @@ class BeetsPlugin(object): def _set_log_level(self, base_log_level, func): """Wrap `func` to temporarily set this plugin's logger level to - `base_log_level` + config options (and restore it to NOTSET after the - function returns). + `base_log_level` + config options (and restore it to its previous + value after the function returns). + + Note that that value may not be NOTSET, e.g. if a plugin import stage + triggers an event that is listened this very same plugin """ @wraps(func) def wrapper(*args, **kwargs): - assert self._log.level == logging.NOTSET - + old_log_level = self._log.level verbosity = beets.config['verbose'].get(int) log_level = max(logging.DEBUG, base_log_level - 10 * verbosity) self._log.setLevel(log_level) @@ -119,7 +121,7 @@ class BeetsPlugin(object): try: return func(*args, **kwargs) finally: - self._log.setLevel(logging.NOTSET) + self._log.setLevel(old_log_level) return wrapper def queries(self):