audio: Improve and enable trace logging for scanner

mopidy/audio/scan.py

@@ -2,11 +2,12 @@ from __future__ import (
     absolute_import, division, print_function, unicode_literals)
 
 import collections
+import logging
 import time
 
 from mopidy import exceptions
 from mopidy.audio import tags as tags_lib, utils
-from mopidy.internal import encoding
+from mopidy.internal import encoding, log
 from mopidy.internal.gi import Gst, GstPbutils
 
 # GST_ELEMENT_FACTORY_LIST:
@@ -23,6 +24,12 @@ _SELECT_EXPOSE = 1
 _Result = collections.namedtuple(
     'Result', ('uri', 'tags', 'duration', 'seekable', 'mime', 'playable'))
 
+logger = logging.getLogger(__name__)
+
+
+def _trace(*args, **kwargs):
+    logger.log(log.TRACE_LOG_LEVEL, *args, **kwargs)
+
 
 # TODO: replace with a scan(uri, timeout=1000, proxy_config=None)?
 class Scanner(object):
@@ -200,31 +207,35 @@ def _process(pipeline, timeout_ms):
     timeout = timeout_ms
     start = int(time.time() * 1000)
     while timeout > 0:
-        message = bus.timed_pop_filtered(timeout * Gst.MSECOND, types)
-
-        if message is None:
+        msg = bus.timed_pop_filtered(timeout * Gst.MSECOND, types)
+        if msg is None:
             break
-        elif message.type == Gst.MessageType.ELEMENT:
-            if GstPbutils.is_missing_plugin_message(message):
-                missing_message = message
-        elif message.type == Gst.MessageType.APPLICATION:
-            if message.get_structure().get_name() == 'have-type':
-                mime = message.get_structure().get_value('caps').get_name()
+
+        if logger.isEnabledFor(log.TRACE_LOG_LEVEL) and msg.get_structure():
+            _trace('element %s: %s', msg.src.get_name(),
+                   msg.get_structure().to_string())
+
+        if msg.type == Gst.MessageType.ELEMENT:
+            if GstPbutils.is_missing_plugin_message(msg):
+                missing_message = msg
+        elif msg.type == Gst.MessageType.APPLICATION:
+            if msg.get_structure().get_name() == 'have-type':
+                mime = msg.get_structure().get_value('caps').get_name()
                 if mime and (
                         mime.startswith('text/') or mime == 'application/xml'):
                     return tags, mime, have_audio, duration
-            elif message.get_structure().get_name() == 'have-audio':
+            elif msg.get_structure().get_name() == 'have-audio':
                 have_audio = True
-        elif message.type == Gst.MessageType.ERROR:
-            error = encoding.locale_decode(message.parse_error()[0])
+        elif msg.type == Gst.MessageType.ERROR:
+            error = encoding.locale_decode(msg.parse_error()[0])
             if missing_message and not mime:
                 caps = missing_message.get_structure().get_value('detail')
                 mime = caps.get_structure(0).get_name()
                 return tags, mime, have_audio, duration
             raise exceptions.ScannerError(error)
-        elif message.type == Gst.MessageType.EOS:
+        elif msg.type == Gst.MessageType.EOS:
             return tags, mime, have_audio, duration
-        elif message.type == Gst.MessageType.ASYNC_DONE:
+        elif msg.type == Gst.MessageType.ASYNC_DONE:
             success, duration = _query_duration(pipeline)
             if tags and success:
                 return tags, mime, have_audio, duration
@@ -233,16 +244,17 @@ def _process(pipeline, timeout_ms):
             # after pre-roll. We get around this by starting to play the track
             # and then waiting for a duration change.
             # https://bugzilla.gnome.org/show_bug.cgi?id=763553
+            logger.debug('Using workaround for duration missing before play.')
             result = pipeline.set_state(Gst.State.PLAYING)
             if result == Gst.StateChangeReturn.FAILURE:
                 return tags, mime, have_audio, duration
 
-        elif message.type == Gst.MessageType.DURATION_CHANGED:
+        elif msg.type == Gst.MessageType.DURATION_CHANGED:
             # duration will be read after ASYNC_DONE received; for now
             # just give it a non-None value to flag that we have a duration:
             duration = 0
-        elif message.type == Gst.MessageType.TAG:
-            taglist = message.parse_tag()
+        elif msg.type == Gst.MessageType.TAG:
+            taglist = msg.parse_tag()
             # Note that this will only keep the last tag.
             tags.update(tags_lib.convert_taglist(taglist))
 
@@ -262,6 +274,9 @@ if __name__ == '__main__':
 
     from mopidy.internal import path
 
+    logging.basicConfig(format='%(asctime)-15s %(levelname)s %(message)s',
+                        level=log.TRACE_LOG_LEVEL)
+
     scanner = Scanner(5000)
     for uri in sys.argv[1:]:
         if not Gst.uri_is_valid(uri):