New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

IndexError and KeyError in extensions logged with wrong level (or logger) #741

Closed
tamland opened this Issue Jun 3, 2014 · 8 comments

Comments

3 participants
@tamland
Contributor

tamland commented Jun 3, 2014

I'm extending LibraryProvider and have loglevels for the extension set to debug, all others to default. If Exception is raised in e.g. find_exact the stack trace is printed to the mopidy log, as expected. If IndexError or KeyError is raised nothing is printed. Basically, those exceptions are logged by pykka as debug. Took me a good 20min to realize that;) I would expect any errors originating from an extension to at least be logged when level for that extension is debug.

Here's the logs:

DEBUG   [pykka] Exception returned from Core (urn:uuid:163b5192-d4fb-42a8-a126-2c96084da103) to caller:
Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 200, in _actor_loop
    response = self._handle_receive(message)
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 294, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/home/thomas/src/mopidy/mopidy/core/library.py", line 116, in find_exact
    return [result for result in pykka.get_all(futures) if result]
  File "build/bdist.linux-x86_64/egg/pykka/future.py", line 330, in get_all
    return [future.get(timeout=timeout) for future in futures]
  File "build/bdist.linux-x86_64/egg/pykka/future.py", line 299, in get
    exec('raise exc_info[0], exc_info[1], exc_info[2]')
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 200, in _actor_loop
    response = self._handle_receive(message)
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 294, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/home/thomas/src/mopidy-banshee/mopidy_banshee/__init__.py", line 66, in find_exact
    raise IndexError()
ERROR   [pykka] Unhandled exception in MpdSession (urn:uuid:3d746239-db5d-4ae2-8740-5eed67c70d11):
Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 200, in _actor_loop
    response = self._handle_receive(message)
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 303, in _handle_receive
    return self.on_receive(message)
  File "/home/thomas/src/mopidy/mopidy/utils/network.py", line 366, in on_receive
    self.on_line_received(line)
  File "/home/thomas/src/mopidy/mopidy/mpd/session.py", line 33, in on_line_received
    response = self.dispatcher.handle_request(line)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 46, in handle_request
    return self._call_next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 67, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 75, in _catch_mpd_ack_errors_filter
    return self._call_next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 67, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 85, in _authenticate_filter
    return self._call_next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 67, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 104, in _command_list_filter
    response = self._call_next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 67, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 133, in _idle_filter
    response = self._call_next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 67, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 146, in _add_ok_filter
    response = self._call_next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 67, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 158, in _call_handler_filter
    response = self._format_response(self._call_handler(request))
  File "/home/thomas/src/mopidy/mopidy/mpd/dispatcher.py", line 167, in _call_handler
    return protocol.commands.call(tokens, context=self.context)
  File "/home/thomas/src/mopidy/mopidy/mpd/protocol/__init__.py", line 171, in call
    return self.handlers[tokens[0]](context, *tokens[1:])
  File "/home/thomas/src/mopidy/mopidy/mpd/protocol/__init__.py", line 140, in validate
    return func(*args, **kwargs)
  File "/home/thomas/src/mopidy/mopidy/mpd/protocol/music_db.py", line 269, in list_
    return _list_artist(context, query)
  File "/home/thomas/src/mopidy/mopidy/mpd/protocol/music_db.py", line 286, in _list_artist
    results = context.core.library.find_exact(**query).get()
  File "build/bdist.linux-x86_64/egg/pykka/future.py", line 299, in get
    exec('raise exc_info[0], exc_info[1], exc_info[2]')
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 200, in _actor_loop
    response = self._handle_receive(message)
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 294, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/home/thomas/src/mopidy/mopidy/core/library.py", line 116, in find_exact
    return [result for result in pykka.get_all(futures) if result]
  File "build/bdist.linux-x86_64/egg/pykka/future.py", line 330, in get_all
    return [future.get(timeout=timeout) for future in futures]
  File "build/bdist.linux-x86_64/egg/pykka/future.py", line 299, in get
    exec('raise exc_info[0], exc_info[1], exc_info[2]')
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 200, in _actor_loop
    response = self._handle_receive(message)
  File "build/bdist.linux-x86_64/egg/pykka/actor.py", line 294, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/home/thomas/src/mopidy-banshee/mopidy_banshee/__init__.py", line 66, in find_exact
    raise Exception()

@tamland tamland changed the title from `IndexError` and `KeyError` in extensions logged with wrong level (or logger) to IndexError and KeyError in extensions logged with wrong level (or logger) Jun 3, 2014

@jodal

This comment has been minimized.

Member

jodal commented Jun 3, 2014

This has really nothing to do with Mopidy and everything to do with Pykka.

If actor A tells actor B to do something, and actor B raises an exception, there is no place to send the exception for proper error handling, since actor A isn't expecting a reply. Thus Pykka logs the exception at error level. This is the "Unhandled exception in B" message you see.

If actor A asks actor B to do something, and actor B raises an exception, it is returned through the future to actor A. If actor A calls get() on the future, the exception will be reraised in actor A and it will continue up the stack in actor A. The traceback will contain stack frames from both actor B and A. Now, in case actor A asked but didn't care about the answer, Pykka logs the exception at debug level with the text "Exception returned from B..." so that it will still leave some traces to help with debugging.

The right solution is to either just tell actor B to do something, or ask and actually get() the resulting future.

@jodal jodal added the question label Jun 3, 2014

@jodal jodal self-assigned this Jun 3, 2014

@jodal

This comment has been minimized.

Member

jodal commented Jun 3, 2014

As for which loggers to use, Pykka knows absolutely nothing about the loggers used by Mopidy or Mopidy extensions. To get an error into your extension's log, you'll need to ask, get, and log if you get an exception. Example:

# In actor A
try:
  result = actor_b.ask({'msg': 'foo'}).get()
except FooException:
  logger.exception('Actor B raised the Foo exception')

If you use actor proxies, as most of Mopidy does, think of method calls and attribute reads as equivalent to ask() as they will always return some value, while attribute setting is equivalent to tell() since there is no useful return value.

@tamland

This comment has been minimized.

Contributor

tamland commented Jun 4, 2014

Yeah but why is Index and KeyError special?

I think you may have misunderstood what I'm doing here. The only actor I have is the one from the example backend. As far as I know I'm not communicating with any actors, but mopidy is. So to use the solution you propose, isn't that something that must be implemented in mopidy?

@jodal

This comment has been minimized.

Member

jodal commented Jun 4, 2014

As far as I remember, there's nothing special with IndexError and KeyError in Pykka. Pykka only differentiates between BaseException and Exception:
https://github.com/jodal/pykka/blob/develop/pykka/actor.py#L184-L221

As you can see from https://docs.python.org/2/library/exceptions.html#exception-hierarchy, both are a superclass of IndexError and KeyError, with BaseException at the root of the class hierarchy.

@jodal

This comment has been minimized.

Member

jodal commented Jun 4, 2014

Ok, I think I see what you're doing now, and it seems odd that the exceptions works differently. I'll have to try this myself.

On a side note, I guess we should create a "bad" backend which returns garbage results/raises exceptions on every backend call, and make the Mopidy core handle this better.

@jodal jodal added bug and removed question labels Jun 4, 2014

@tamland

This comment has been minimized.

Contributor

tamland commented Jun 4, 2014

That's what I'm getting at;) I see LookupError (which is superclass of exactly IndexError and KeyError) being translated here https://github.com/mopidy/mopidy/blob/develop/mopidy/mpd/dispatcher.py#L172 Relevant?

@jodal

This comment has been minimized.

Member

jodal commented Jun 4, 2014

That may be relevant. I'll have to look into this later.

jodal referenced this issue Jun 20, 2014

mpd: Remove old exception handling.
This is a leftover from the old dispatcher code that was missed in the
refactor. The call() will never raise a LookupError for missing commands.

adamcik added a commit that referenced this issue Jun 20, 2014

@adamcik

This comment has been minimized.

Member

adamcik commented Jun 20, 2014

Fixed in 6b76652

@adamcik adamcik closed this Jun 20, 2014

@jodal jodal assigned adamcik and unassigned jodal Jun 20, 2014

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment