Merge pull request #169 from bfredl/asyncerr

better handling of exceptions in async contexts

Author: bfredl

neovim/__init__.py

@@ -16,7 +16,7 @@
 __all__ = ('tcp_session', 'socket_session', 'stdio_session', 'child_session',
            'start_host', 'autocmd', 'command', 'encoding', 'function',
            'plugin', 'rpc_export', 'Host', 'DecodeHook', 'Nvim',
-           'SessionHook', 'shutdown_hook', 'attach')
+           'SessionHook', 'shutdown_hook', 'attach', 'setup_logging')
 
 
 def start_host(session=None):
@@ -43,23 +43,8 @@ def start_host(session=None):
     if not plugins:
         sys.exit('must specify at least one plugin as argument')
 
-    logger = logging.getLogger(__name__)
-    if 'NVIM_PYTHON_LOG_FILE' in os.environ:
-        logfile = (os.environ['NVIM_PYTHON_LOG_FILE'].strip() +
-                   '_' + str(os.getpid()))
-        handler = logging.FileHandler(logfile, 'w')
-        handler.formatter = logging.Formatter(
-            '%(asctime)s [%(levelname)s @ '
-            '%(filename)s:%(funcName)s:%(lineno)s] %(process)s - %(message)s')
-        logging.root.addHandler(handler)
-        level = logging.INFO
-        if 'NVIM_PYTHON_LOG_LEVEL' in os.environ:
-            l = getattr(logging,
-                        os.environ['NVIM_PYTHON_LOG_LEVEL'].strip(),
-                        level)
-            if isinstance(l, int):
-                level = l
-        logger.setLevel(level)
+    setup_logging()
+
     if not session:
         session = stdio_session()
     host = Host(Nvim.from_session(session))
@@ -95,6 +80,27 @@ def attach(session_type, address=None, port=None, path=None, argv=None):
     return Nvim.from_session(session)
 
 
+def setup_logging():
+    """Setup logging according to environment variables."""
+    logger = logging.getLogger(__name__)
+    if 'NVIM_PYTHON_LOG_FILE' in os.environ:
+        logfile = (os.environ['NVIM_PYTHON_LOG_FILE'].strip() +
+                   '_' + str(os.getpid()))
+        handler = logging.FileHandler(logfile, 'w')
+        handler.formatter = logging.Formatter(
+            '%(asctime)s [%(levelname)s @ '
+            '%(filename)s:%(funcName)s:%(lineno)s] %(process)s - %(message)s')
+        logging.root.addHandler(handler)
+        level = logging.INFO
+        if 'NVIM_PYTHON_LOG_LEVEL' in os.environ:
+            l = getattr(logging,
+                        os.environ['NVIM_PYTHON_LOG_LEVEL'].strip(),
+                        level)
+            if isinstance(l, int):
+                level = l
+        logger.setLevel(level)
+
+
 # Required for python 2.6
 class NullHandler(logging.Handler):
     def emit(self, record):

neovim/api/nvim.py

@@ -2,6 +2,8 @@
 import functools
 import os
 
+from traceback import format_exc, format_stack
+
 from msgpack import ExtType
 
 from .buffer import Buffer
@@ -204,9 +206,9 @@ def out_write(self, msg):
         """Print `msg` as a normal message."""
         return self._session.request('vim_out_write', msg)
 
-    def err_write(self, msg):
+    def err_write(self, msg, async=False):
         """Print `msg` as an error message."""
-        return self._session.request('vim_err_write', msg)
+        return self._session.request('vim_err_write', msg, async=async)
 
     def quit(self, quit_command='qa!'):
         """Send a quit command to Nvim.
@@ -226,6 +228,29 @@ def new_highlight_source(self):
         """Return new src_id for use with Buffer.add_highlight."""
         return self.current.buffer.add_highlight("", 0, src_id=0)
 
+    def async_call(self, fn, *args, **kwargs):
+        """Schedule `fn` to be called by the event loop soon.
+
+        This function is thread-safe, and is the only way code not
+        on the main thread could interact with nvim api objects.
+
+        This function can also be called in a synchronous
+        event handler, just before it returns, to defer execution
+        that shouldn't block neovim.
+        """
+        call_point = ''.join(format_stack(None, 5)[:-1])
+
+        def handler():
+            try:
+                fn(*args, **kwargs)
+            except Exception as err:
+                msg = ("error caught while executing async callback:\n"
+                       "{!r}\n{}\n \nthe call was requested at\n{}"
+                       .format(err, format_exc(5), call_point))
+                self.err_write(msg, async=True)
+                raise
+        self._session.threadsafe_call(handler)
+
 
 class Current(object):
 

neovim/msgpack_rpc/session.py

@@ -31,7 +31,11 @@ def __init__(self, async_session):
     def threadsafe_call(self, fn, *args, **kwargs):
         """Wrapper around `AsyncSession.threadsafe_call`."""
         def handler():
-            fn(*args, **kwargs)
+            try:
+                fn(*args, **kwargs)
+            except Exception:
+                warn("error caught while excecuting async callback\n%s\n",
+                     format_exc())
 
         def greenlet_wrapper():
             gr = greenlet.greenlet(handler)
@@ -197,6 +201,7 @@ def handler():
             except Exception:
                 warn("error caught while processing notification '%s %s': %s",
                      name, args, format_exc())
+
             debug('greenlet %s is now dying...', gr)
 
         gr = greenlet.greenlet(handler)

neovim/plugin/host.py

@@ -6,10 +6,11 @@
 import os
 import os.path
 
+from traceback import format_exc
+
 from ..api import DecodeHook
 from ..compat import IS_PYTHON3, find_module
 
-
 __all__ = ('Host')
 
 logger = logging.getLogger(__name__)
@@ -76,7 +77,13 @@ def _on_notification(self, name, args):
             return
 
         debug('calling notification handler for "%s", args: "%s"', name, args)
-        handler(*args)
+        try:
+            handler(*args)
+        except Exception as err:
+            msg = ("error caught in async handler '{} {}':\n{!r}\n{}"
+                   .format(name, args, err, format_exc(5)))
+            self.nvim.err_write(msg, async=True)
+            raise
 
     def _load(self, plugins):
         for path in plugins:

test/test_common.py

@@ -6,6 +6,7 @@
 
 from nose.tools import eq_ as eq
 
+neovim.setup_logging()
 
 if 'NVIM_CHILD_ARGV' in os.environ:
     vim = neovim.attach('child', argv=json.loads(os.environ['NVIM_CHILD_ARGV']))
@@ -17,7 +18,6 @@
     # with Python2
     vim = vim.with_hook(neovim.DecodeHook())
 
-
 cleanup_func = ''':function BeforeEachTest()
   set all&
   redir => groups

test/test_concurrency.py

@@ -9,3 +9,11 @@ def test_interrupt_from_another_thread():
     timer = Timer(0.5, lambda: session.threadsafe_call(lambda: session.stop()))
     timer.start()
     eq(vim.session.next_message(), None)
+
+
+@with_setup(setup=cleanup)
+def test_exception_in_threadsafe_call():
+    # an exception in a threadsafe_call shouldn't crash the entire host
+    vim.session.threadsafe_call(lambda: [vim.eval("3"), undefined_variable])
+    vim.session.threadsafe_call(lambda: vim.session.stop())
+    vim.session.run(None, None)