Merge pull request #1320 from brunal/multiple-logging-levels

Multiple logging levels

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

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
@@ -84,10 +83,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 +103,25 @@ 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 its previous
+        value 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.
+        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):
-            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']:
+            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)
+
+            try:
+                return func(*args, **kwargs)
+            finally:
                 self._log.setLevel(old_log_level)
-            return result
         return wrapper
 
     def queries(self):
@@ -181,36 +180,21 @@ class BeetsPlugin(object):
         mediafile.MediaFile.add_field(name, descriptor)
         library.Item._media_fields.add(name)
 
+    _raw_listeners = None
     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:
+        wrapped_func = self._set_log_level(logging.WARNING, 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.listeners[event]:
-            cls.listeners[event].append(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 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
@@ -459,10 +443,7 @@ 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
-        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

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

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.
     """

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)

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

beetsplug/permissions.py

@@ -48,9 +48,10 @@ class Permissions(BeetsPlugin):
             u'dir': 755
         })
 
+        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.
     """

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``,
@@ -112,7 +115,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

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

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 <config>`.
 
 Beets also uses the ``BEETSDIR`` environment variable to look for

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
 

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,106 @@ 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'] = 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)
+
+        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'] = 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'] = 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'] = 0
+        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'] = 1
+        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)
+
+        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__)
 

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():

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