Merge pull request #638 from jodal/feature/advanced-log-levels

Support advanced log levels with -vv and -vvv

docs/changelog.rst

@@ -42,6 +42,15 @@ v0.18.0 (UNRELEASED)
 
   Imports from the old locations still works, but are deprecated.
 
+**Commands**
+
+- Reduce amount of logging from dependencies when using :option:`mopidy -v`.
+  (Fixes: :issue:`593`)
+
+- Add support for additional logging verbosity levels with ``mopidy -vv`` and
+  ``mopidy -vvv`` which increases the amount of logging from dependencies.
+  (Fixes: :issue:`593`)
+
 **Configuration**
 
 - The default for the :option:`mopidy --config` option has been updated to

docs/troubleshooting.rst

@@ -25,8 +25,8 @@ mailing list or when reporting an issue, somewhat longer text dumps are
 accepted, but large logs should still be shared through a pastebin.
 
 
-Effective configuration
-=======================
+Show effective configuration
+============================
 
 The command ``mopidy config`` will print your full effective
 configuration the way Mopidy sees it after all defaults and all config files
@@ -35,8 +35,8 @@ passwords are masked out, so the output of the command should be safe to share
 with others for debugging.
 
 
-Installed dependencies
-======================
+Show installed dependencies
+===========================
 
 The command ``mopidy deps`` will list the paths to and versions of
 any dependency Mopidy or the extensions might need to work. This is very useful
@@ -48,11 +48,16 @@ your system.
 Debug logging
 =============
 
-If you run :option:`mopidy -v`, Mopidy will output debug log to stdout. If you
-run :option:`mopidy --save-debug-log`, it will save the debug log to the file
-``mopidy.log`` in the directory you ran the command from.
+If you run :option:`mopidy -v` or ``mopidy -vv`` or ``mopidy -vvv`` Mopidy will
+print more and more debug log to stdout. All three options will give you debug
+level output from Mopidy and extensions, while ``-vv`` and ``-vvv`` will give
+you more log output from their dependencies as well.
 
-If you want to turn on more or less logging for some component, see the
+If you run :option:`mopidy --save-debug-log`, it will save the log equivalent
+with ``-vvv`` to the file ``mopidy.log`` in the directory you ran the command
+from.
+
+If you want to reduce the logging for some component, see the
 docs for the :confval:`loglevels/*` config section.
 
 

mopidy/__main__.py

@@ -70,7 +70,8 @@ def main():
         if args.verbosity_level:
             verbosity_level += args.verbosity_level
 
-        log.setup_logging(config, verbosity_level, args.save_debug_log)
+        log.setup_logging(
+            config, installed_extensions, verbosity_level, args.save_debug_log)
 
         enabled_extensions = []
         for extension in installed_extensions:

mopidy/commands.py

@@ -241,7 +241,7 @@ class RootCommand(Command):
         self.add_argument(
             '-v', '--verbose',
             action='count', dest='verbosity_level', default=0,
-            help='more output (debug level)')
+            help='more output (repeat up to 3 times for even more)')
         self.add_argument(
             '--save-debug-log',
             action='store_true', dest='save_debug_log',

mopidy/config/default.conf

@@ -4,10 +4,6 @@ debug_format = %(levelname)-8s %(asctime)s [%(process)d:%(threadName)s] %(name)s
 debug_file = mopidy.log
 config_file =
 
-[loglevels]
-pykka = info
-requests = warning
-
 [audio]
 mixer = software
 mixer_track =

mopidy/utils/log.py

@@ -31,12 +31,13 @@ def bootstrap_delayed_logging():
     root.addHandler(_delayed_handler)
 
 
-def setup_logging(config, verbosity_level, save_debug_log):
-    setup_console_logging(config, verbosity_level)
+def setup_logging(config, extensions, verbosity_level, save_debug_log):
     setup_log_levels(config)
 
+    setup_console_logging(config, extensions, verbosity_level)
+
     if save_debug_log:
-        setup_debug_logging_to_file(config)
+        setup_debug_logging_to_file(config, extensions)
 
     logging.captureWarnings(True)
 
@@ -51,29 +52,55 @@ def setup_log_levels(config):
         logging.getLogger(name).setLevel(level)
 
 
-def setup_console_logging(config, verbosity_level):
-    if verbosity_level < 0:
-        log_level = logging.WARNING
+LOG_LEVELS = {
+    -1: dict(root=logging.ERROR, mopidy=logging.WARNING),
+    0: dict(root=logging.ERROR, mopidy=logging.INFO),
+    1: dict(root=logging.WARNING, mopidy=logging.DEBUG),
+    2: dict(root=logging.INFO, mopidy=logging.DEBUG),
+    3: dict(root=logging.DEBUG, mopidy=logging.DEBUG),
+}
+
+
+def setup_console_logging(config, extensions, verbosity_level):
+    if verbosity_level < min(LOG_LEVELS.keys()):
+        verbosity_level = min(LOG_LEVELS.keys())
+    if verbosity_level > max(LOG_LEVELS.keys()):
+        verbosity_level = max(LOG_LEVELS.keys())
+
+    if verbosity_level < 1:
         log_format = config['logging']['console_format']
-    elif verbosity_level >= 1:
-        log_level = logging.DEBUG
-        log_format = config['logging']['debug_format']
     else:
-        log_level = logging.INFO
-        log_format = config['logging']['console_format']
+        log_format = config['logging']['debug_format']
     formatter = logging.Formatter(log_format)
-    handler = logging.StreamHandler()
-    handler.setFormatter(formatter)
-    handler.setLevel(log_level)
-    root = logging.getLogger('')
-    root.addHandler(handler)
+
+    root_handler = logging.StreamHandler()
+    root_handler.setFormatter(formatter)
+    root_handler.setLevel(LOG_LEVELS[verbosity_level]['root'])
+    logging.getLogger('').addHandler(root_handler)
+
+    mopidy_handler = logging.StreamHandler()
+    mopidy_handler.setFormatter(formatter)
+    mopidy_handler.setLevel(LOG_LEVELS[verbosity_level]['mopidy'])
+    add_mopidy_handler(extensions, mopidy_handler)
 
 
-def setup_debug_logging_to_file(config):
+def setup_debug_logging_to_file(config, extensions):
     formatter = logging.Formatter(config['logging']['debug_format'])
     handler = logging.handlers.RotatingFileHandler(
         config['logging']['debug_file'], maxBytes=10485760, backupCount=3)
     handler.setFormatter(formatter)
-    handler.setLevel(logging.DEBUG)
-    root = logging.getLogger('')
-    root.addHandler(handler)
+
+    logging.getLogger('').addHandler(handler)
+
+    # We must add our handler explicitly, since the mopidy* handlers don't
+    # propagate to the root handler.
+    add_mopidy_handler(extensions, handler)
+
+
+def add_mopidy_handler(extensions, handler):
+    names = ['mopidy_%s' % ext.ext_name for ext in extensions]
+    names.append('mopidy')
+    for name in names:
+        logger = logging.getLogger(name)
+        logger.propagate = False
+        logger.addHandler(handler)