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

@@ -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):
-            if not any(isinstance(f, PluginLogFilter)
+            self._log.addFilter(PluginLogFilter(self))
-                       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).
+        `base_log_level` + config options (and restore it to NOTSET 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.
         """
         @wraps(func)
         def wrapper(*args, **kwargs):
-            if not beets.config['verbose']:
+            assert self._log.level == logging.NOTSET
-                old_log_level = self._log.level
+
-                self._log.setLevel(log_level)
+            log_level = base_log_level
-            result = func(*args, **kwargs)
+            if beets.config['verbose'].get(bool):
-            if not beets.config['verbose']:
+                log_level -= 10
-                self._log.setLevel(old_log_level)
+            self._log.setLevel(log_level)
-            return result
+
+            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(self, event, func):
-    def register_listener(cls, event, func):
+        """Add a function as a listener for the specified event.
-        """Add a function as a listener for the specified event. (An
-        imperative alternative to the @listen decorator.)
         """
-        if cls.listeners is None:
+        func = self._set_log_level(logging.WARNING, func)
-            cls.listeners = defaultdict(list)
-        if func not in cls.listeners[event]:
-            cls.listeners[event].append(func)
 
-    @classmethod
+        if self.listeners is None:
-    def listen(cls, event):
+            self.listeners = defaultdict(list)
-        """Decorator that adds a function as an event handler for the
+        if func not in self.listeners[event]:
-        specified event (as a string). The parameters passed to function
+            self.listeners[event].append(func)
-        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
 
     template_funcs = None
     template_fields = None

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__)