From 42623fb48f4c92d7a9004772bb93b6ed86e11334 Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Fri, 7 Feb 2014 08:46:47 +0100 Subject: [PATCH 01/11] zeroconf: Move all logging to debug level --- mopidy/http/actor.py | 7 ++++--- mopidy/mpd/actor.py | 7 ++++--- mopidy/zeroconf.py | 2 +- 3 files changed, 9 insertions(+), 7 deletions(-) diff --git a/mopidy/http/actor.py b/mopidy/http/actor.py index e7b5cb66..c5787fec 100644 --- a/mopidy/http/actor.py +++ b/mopidy/http/actor.py @@ -100,10 +100,11 @@ class HttpFrontend(pykka.ThreadingActor, CoreListener): host=self.hostname, port=self.port) if self.zeroconf_service.publish(): - logger.info('Registered HTTP with Zeroconf as "%s"', - self.zeroconf_service.name) + logger.debug( + 'Registered HTTP with Zeroconf as "%s"', + self.zeroconf_service.name) else: - logger.info('Registering HTTP with Zeroconf failed.') + logger.debug('Registering HTTP with Zeroconf failed.') def on_stop(self): if self.zeroconf_service: diff --git a/mopidy/mpd/actor.py b/mopidy/mpd/actor.py index 20417a4d..684b4968 100644 --- a/mopidy/mpd/actor.py +++ b/mopidy/mpd/actor.py @@ -48,10 +48,11 @@ class MpdFrontend(pykka.ThreadingActor, CoreListener): host=self.hostname, port=self.port) if self.zeroconf_service.publish(): - logger.info('Registered MPD with Zeroconf as "%s"', - self.zeroconf_service.name) + logger.debug( + 'Registered MPD with Zeroconf as "%s"', + self.zeroconf_service.name) else: - logger.info('Registering MPD with Zeroconf failed.') + logger.debug('Registering MPD with Zeroconf failed.') def on_stop(self): if self.zeroconf_service: diff --git a/mopidy/zeroconf.py b/mopidy/zeroconf.py index e95b1792..1111975f 100644 --- a/mopidy/zeroconf.py +++ b/mopidy/zeroconf.py @@ -63,7 +63,7 @@ class Zeroconf(object): """ if _is_loopback_address(self.host): - logger.info( + logger.debug( 'Zeroconf publish on loopback interface is not supported.') return False From f0878ff2874dde4aec0bf29c5487ee2dde6ca718 Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Fri, 7 Feb 2014 20:09:57 +0100 Subject: [PATCH 02/11] http: Catch socket errors when handling websockets (fixes #571) (cherry picked from commit 94fe38ff09d048153585713180d317378db1f6cc) --- mopidy/http/ws.py | 30 +++++++++++++++++++++++++----- 1 file changed, 25 insertions(+), 5 deletions(-) diff --git a/mopidy/http/ws.py b/mopidy/http/ws.py index 4d7aa9a2..286e97e6 100644 --- a/mopidy/http/ws.py +++ b/mopidy/http/ws.py @@ -1,14 +1,14 @@ from __future__ import unicode_literals import logging +import socket import cherrypy -from ws4py.websocket import WebSocket +import ws4py.websocket from mopidy import core, models from mopidy.utils import jsonrpc - logger = logging.getLogger(__name__) @@ -43,7 +43,28 @@ class WebSocketResource(object): cherrypy.request.ws_handler.jsonrpc = self.jsonrpc -class WebSocketHandler(WebSocket): +class _WebSocket(ws4py.websocket.WebSocket): + """Sub-class ws4py WebSocket with better error handling.""" + + def send(self, *args, **kwargs): + try: + super(_WebSocket, self).send(*args, **kwargs) + return True + except socket.error as e: + logger.warning('Send message failed: %s', e) + # This isn't really correct, but its the only way to break of out + # the loop in run and trick ws4py into cleaning up. + self.client_terminated = self.server_terminated = True + return False + + def close(self, *args, **kwargs): + try: + super(_WebSocket, self).close(*args, **kwargs) + except socket.error as e: + logger.warning('Closing WebSocket failed: %s', e) + + +class WebSocketHandler(_WebSocket): def opened(self): remote = cherrypy.request.remote logger.debug( @@ -66,8 +87,7 @@ class WebSocketHandler(WebSocket): remote.ip, remote.port, request) response = self.jsonrpc.handle_json(request) - if response: - self.send(response) + if response and self.send(response): logger.debug( 'Sent WebSocket message to %s:%d: %r', remote.ip, remote.port, response) From f96eb1d4f73ad858026f2ef60523a7a2ee41e2d1 Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Fri, 7 Feb 2014 20:31:36 +0100 Subject: [PATCH 03/11] docs: Update changelog --- docs/changelog.rst | 3 +++ 1 file changed, 3 insertions(+) diff --git a/docs/changelog.rst b/docs/changelog.rst index 5e28f82a..21e729fd 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -10,6 +10,9 @@ v0.18.2 (UNRELEASED) Bug fix release. +- Fix a crash in the server side WebSocket handler caused by connection + problems with clients. (Fixes: :issue:`571`) + - Fix the ``time_position`` field of the ``track_playback_ended`` event, which has been always 0 since v0.18.0. This made scrobbles by Mopidy-Scrobbler not be persisted by Last.fm, because Mopidy reported that you listened to 0 From 99cc11bcae434e8f59ed019a1bf712334bc267d0 Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Fri, 7 Feb 2014 20:14:53 +0100 Subject: [PATCH 04/11] local: Make clear command mesages more clear (cherry picked from commit 812f018d5923829cad0a7bcfcea3cb428bf95f18) --- mopidy/local/commands.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/mopidy/local/commands.py b/mopidy/local/commands.py index 85939b43..c30b1ada 100644 --- a/mopidy/local/commands.py +++ b/mopidy/local/commands.py @@ -37,17 +37,17 @@ class ClearCommand(commands.Command): def run(self, args, config): library = _get_library(args, config) - prompt = 'Are you sure you want to clear the library? [y/N] ' + prompt = '\nAre you sure you want to clear the library? [y/N] ' if raw_input(prompt).lower() != 'y': - logging.info('Clearing library aborted.') + print 'Clearing library aborted.' return 0 if library.clear(): - logging.info('Library succesfully cleared.') + print 'Library succesfully cleared.' return 0 - logging.warning('Unable to clear library.') + print 'Unable to clear library.' return 1 From b8aab6086488e0ed1bdd8081821915ce5e416111 Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Fri, 7 Feb 2014 20:32:19 +0100 Subject: [PATCH 05/11] local: Fix typo (cherry picked from commit 884c1b9803d024f1d1615ad10ce4bdc30e9d8e41) --- mopidy/local/commands.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mopidy/local/commands.py b/mopidy/local/commands.py index c30b1ada..885ea946 100644 --- a/mopidy/local/commands.py +++ b/mopidy/local/commands.py @@ -44,7 +44,7 @@ class ClearCommand(commands.Command): return 0 if library.clear(): - print 'Library succesfully cleared.' + print 'Library successfully cleared.' return 0 print 'Unable to clear library.' From 01bc7a0a2c81226f3dc902c2889836a0c7c050b8 Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Fri, 7 Feb 2014 20:33:34 +0100 Subject: [PATCH 06/11] local: Use print() function (cherry picked from commit d0a305a8e2208d1188c4013328a64d5d7f17de9c) --- mopidy/local/commands.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/mopidy/local/commands.py b/mopidy/local/commands.py index 885ea946..fb8f5368 100644 --- a/mopidy/local/commands.py +++ b/mopidy/local/commands.py @@ -1,4 +1,4 @@ -from __future__ import unicode_literals +from __future__ import print_function, unicode_literals import logging import os @@ -40,14 +40,14 @@ class ClearCommand(commands.Command): prompt = '\nAre you sure you want to clear the library? [y/N] ' if raw_input(prompt).lower() != 'y': - print 'Clearing library aborted.' + print('Clearing library aborted.') return 0 if library.clear(): - print 'Library successfully cleared.' + print('Library successfully cleared.') return 0 - print 'Unable to clear library.' + print('Unable to clear library.') return 1 From e255afb97fe4e635d21d611cf9d5b35cd03c315b Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Sat, 15 Feb 2014 00:18:24 +0100 Subject: [PATCH 07/11] config: Make keyring log messages explain more ...as a lot of users see debug-level errors from the keyring code and think they explain some larger issue. These are currently *always* red herrings as there is no command for setting configuration values in the keyring yet. Fixes #681 --- mopidy/config/keyring.py | 24 +++++++++++++++--------- 1 file changed, 15 insertions(+), 9 deletions(-) diff --git a/mopidy/config/keyring.py b/mopidy/config/keyring.py index 6800d2c4..4d251f52 100644 --- a/mopidy/config/keyring.py +++ b/mopidy/config/keyring.py @@ -19,20 +19,25 @@ else: EMPTY_STRING = '' +FETCH_ERROR = ( + 'Fetching passwords from your keyring failed. Any passwords ' + 'stored in the keyring will not be available.') + + def fetch(): if not dbus: - logger.debug('Fetching from keyring failed: dbus not installed.') + logger.debug('%s (dbus not installed)', FETCH_ERROR) return [] try: bus = dbus.SessionBus() except dbus.exceptions.DBusException as e: - logger.debug('Fetching from keyring failed: %s', e) + logger.debug('%s (%s)', FETCH_ERROR, e) return [] if not bus.name_has_owner('org.freedesktop.secrets'): logger.debug( - 'Fetching from keyring failed: secrets service not running.') + '%s (org.freedesktop.secrets service not running)', FETCH_ERROR) return [] service = _service(bus) @@ -47,7 +52,7 @@ def fetch(): items, prompt = service.Unlock(locked) if prompt != '/': _prompt(bus, prompt).Dismiss() - logger.debug('Fetching from keyring failed: keyring is locked.') + logger.debug('%s (Keyring is locked)', FETCH_ERROR) return [] result = [] @@ -65,19 +70,20 @@ def set(section, key, value): Indicates if storage failed or succeeded. """ if not dbus: - logger.debug('Saving %s/%s to keyring failed: dbus not installed.', + logger.debug('Saving %s/%s to keyring failed. (dbus not installed)', section, key) return False try: bus = dbus.SessionBus() except dbus.exceptions.DBusException as e: - logger.debug('Saving %s/%s to keyring failed: %s', section, key, e) + logger.debug('Saving %s/%s to keyring failed. (%s)', section, key, e) return False if not bus.name_has_owner('org.freedesktop.secrets'): logger.debug( - 'Saving %s/%s to keyring failed: secrets service not running.', + 'Saving %s/%s to keyring failed. ' + '(org.freedesktop.secrets service not running)', section, key) return False @@ -101,14 +107,14 @@ def set(section, key, value): item, prompt = collection.CreateItem(properties, secret, True) except dbus.exceptions.DBusException as e: # TODO: catch IsLocked errors etc. - logger.debug('Saving %s/%s to keyring failed: %s', section, key, e) + logger.debug('Saving %s/%s to keyring failed. (%s)', section, key, e) return False if prompt == '/': return True _prompt(bus, prompt).Dismiss() - logger.debug('Saving secret %s/%s failed: Keyring is locked', + logger.debug('Saving secret %s/%s failed. (Keyring is locked)', section, key) return False From 01bef27a4ecf4597d7715b74e0ee744ac5d7a851 Mon Sep 17 00:00:00 2001 From: Thomas Adamcik Date: Sun, 16 Feb 2014 18:29:57 +0100 Subject: [PATCH 08/11] config/ext: Automatically disable extensions with bad config Ensures config errors on extensions don't block mopidy startup. Also improves error messages for config problems. (cherry picked from commit 684bfcf301c7f945308894ca54bc02be627d4d16) --- mopidy/__main__.py | 68 ++++++++++++++++++++++++++++++++++------------ 1 file changed, 51 insertions(+), 17 deletions(-) diff --git a/mopidy/__main__.py b/mopidy/__main__.py index 05394bc2..b447e77d 100644 --- a/mopidy/__main__.py +++ b/mopidy/__main__.py @@ -74,20 +74,28 @@ def main(): log.setup_logging(config, verbosity_level, args.save_debug_log) - enabled_extensions = [] + extensions = { + 'validate': [], 'config': [], 'disabled': [], 'enabled': []} for extension in installed_extensions: if not ext.validate_extension(extension): config[extension.ext_name] = {'enabled': False} config_errors[extension.ext_name] = { 'enabled': 'extension disabled by self check.'} + extensions['validate'].append(extension) elif not config[extension.ext_name]['enabled']: config[extension.ext_name] = {'enabled': False} config_errors[extension.ext_name] = { 'enabled': 'extension disabled by user config.'} + extensions['disabled'].append(extension) + elif config_errors.get(extension.ext_name): + config[extension.ext_name]['enabled'] = False + config_errors[extension.ext_name]['enabled'] = ( + 'extension disabled due to config errors.') + extensions['config'].append(extension) else: - enabled_extensions.append(extension) + extensions['enabled'].append(extension) - log_extension_info(installed_extensions, enabled_extensions) + log_extension_info(installed_extensions, extensions['enabled']) # Config and deps commands are simply special cased for now. if args.command == config_cmd: @@ -96,22 +104,22 @@ def main(): elif args.command == deps_cmd: return args.command.run() - # Remove errors for extensions that are not enabled: - for extension in installed_extensions: - if extension not in enabled_extensions: - config_errors.pop(extension.ext_name, None) - check_config_errors(config_errors) + check_config_errors(config, config_errors, extensions) + + if not extensions['enabled']: + logger.error('No extension enabled, exiting...') + sys.exit(1) # Read-only config from here on, please. proxied_config = config_lib.Proxy(config) - if args.extension and args.extension not in enabled_extensions: + if args.extension and args.extension not in extensions['enabled']: logger.error( 'Unable to run command provided by disabled extension %s', args.extension.ext_name) return 1 - for extension in enabled_extensions: + for extension in extensions['enabled']: extension.setup(registry) # Anything that wants to exit after this point must use @@ -173,13 +181,39 @@ def log_extension_info(all_extensions, enabled_extensions): 'Disabled extensions: %s', ', '.join(disabled_names) or 'none') -def check_config_errors(errors): - if not errors: - return - for section in errors: - for key, msg in errors[section].items(): - logger.error('Config value %s/%s %s', section, key, msg) - sys.exit(1) +def check_config_errors(config, errors, extensions): + fatal_errors = [] + extension_names = {} + all_extension_names = set() + + for state in extensions: + extension_names[state] = set(e.ext_name for e in extensions[state]) + all_extension_names.update(extension_names[state]) + + for section in sorted(errors): + if not errors[section]: + continue + + if section not in all_extension_names: + logger.warning('Found fatal %s configuration errors:', section) + fatal_errors.append(section) + elif section in extension_names['config']: + del errors[section]['enabled'] + logger.warning('Found %s configuration errors, the extension ' + 'has been automatically disabled:', section) + else: + continue + + for field, msg in errors[section].items(): + logger.warning(' %s/%s %s', section, field, msg) + + if extensions['config']: + logger.warning('Please fix the extension configuration errors or ' + 'disable the extensions to silence these messages.') + + if fatal_errors: + logger.error('Please fix fatal configuration errors, exiting...') + sys.exit(1) if __name__ == '__main__': From 61200b24f0f1e4414e7cc80ef070b1e8b1e34c55 Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Sun, 16 Feb 2014 18:52:05 +0100 Subject: [PATCH 09/11] docs: Update changelog --- docs/changelog.rst | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/docs/changelog.rst b/docs/changelog.rst index 21e729fd..b46ad695 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -10,6 +10,10 @@ v0.18.2 (UNRELEASED) Bug fix release. +- We now log warnings for wrongly configured extensions, and clearly label them + in :option:`mopidy config`, but does no longer stop Mopidy from starting + because of misconfigured extensions. (Fixes: :issue:`682`) + - Fix a crash in the server side WebSocket handler caused by connection problems with clients. (Fixes: :issue:`571`) From fa15e7a2640e6c13647e7905f3ddbb805deed6c2 Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Sun, 16 Feb 2014 21:24:57 +0100 Subject: [PATCH 10/11] Bump version number to 0.18.2 --- mopidy/__init__.py | 2 +- tests/test_version.py | 5 +++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/mopidy/__init__.py b/mopidy/__init__.py index 1367a219..95b296b3 100644 --- a/mopidy/__init__.py +++ b/mopidy/__init__.py @@ -21,4 +21,4 @@ if (isinstance(pykka.__version__, basestring) warnings.filterwarnings('ignore', 'could not open display') -__version__ = '0.18.1' +__version__ = '0.18.2' diff --git a/tests/test_version.py b/tests/test_version.py index 23c93f01..737a21f3 100644 --- a/tests/test_version.py +++ b/tests/test_version.py @@ -43,5 +43,6 @@ class VersionTest(unittest.TestCase): self.assertLess(SV('0.15.0'), SV('0.16.0')) self.assertLess(SV('0.16.0'), SV('0.17.0')) self.assertLess(SV('0.17.0'), SV('0.18.0')) - self.assertLess(SV('0.18.0'), SV(__version__)) - self.assertLess(SV(__version__), SV('0.18.2')) + self.assertLess(SV('0.18.0'), SV('0.18.1')) + self.assertLess(SV('0.18.1'), SV(__version__)) + self.assertLess(SV(__version__), SV('0.18.3')) From d18e1aafe43c5edd7b4151a3614618ba8d9ed489 Mon Sep 17 00:00:00 2001 From: Stein Magnus Jodal Date: Sun, 16 Feb 2014 21:25:23 +0100 Subject: [PATCH 11/11] docs: Update changelog for v0.18.2 --- docs/changelog.rst | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/changelog.rst b/docs/changelog.rst index b46ad695..08cd9a77 100644 --- a/docs/changelog.rst +++ b/docs/changelog.rst @@ -5,7 +5,7 @@ Changelog This changelog is used to track all major changes to Mopidy. -v0.18.2 (UNRELEASED) +v0.18.2 (2014-02-16) ==================== Bug fix release. @@ -15,7 +15,7 @@ Bug fix release. because of misconfigured extensions. (Fixes: :issue:`682`) - Fix a crash in the server side WebSocket handler caused by connection - problems with clients. (Fixes: :issue:`571`) + problems with clients. (Fixes: :issue:`428`, :issue:`571`) - Fix the ``time_position`` field of the ``track_playback_ended`` event, which has been always 0 since v0.18.0. This made scrobbles by Mopidy-Scrobbler not