RuntimeError: This event loop is already running

[blueyed]

I am seeing a RuntimeError: This event loop is already running when using
`log.exception from deoplete-jedi's server.

This appears to be caused by DeopleteLogFilter.filter using
self.vim.call('deoplete#util#print_error', record.getMessage(), record.name).

Full traceback (the code in deoplete-jedi (from the first exception) is new ):

[deoplete.jedi.client] Caught BrokenPipeError(32, 'Broken pipe') during handling completions
Exception in thread Thread-5:
Traceback (most recent call last):
  File "/home/user/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py", line 560, in completions
    stream_write(self._server.stdin, args)
  File "/home/user/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py", line 109, in stream_write
    pipe.flush()
BrokenPipeError: [Errno 32] Broken pipe

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/home/user/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/worker.py", line 34, in completion_work
    filename, options)
  File "/home/user/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py", line 563, in completions
    log.exception('Caught %r during handling completions', exc)
  File "/usr/lib/python3.6/logging/__init__.py", line 1341, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1335, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1442, in _log
    self.handle(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1452, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 1514, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 859, in handle
    rv = self.filter(record)
  File "/usr/lib/python3.6/logging/__init__.py", line 718, in filter
    result = f.filter(record)
  File "/home/user/.vim/plugged/deoplete.nvim/rplugin/python3/deoplete/logger.py", line 144, in filter
    record.name)
  File "/usr/lib/python3.6/site-packages/neovim/api/nvim.py", line 254, in call
    return self.request('nvim_call_function', name, args, **kwargs)
  File "/usr/lib/python3.6/site-packages/neovim/api/nvim.py", line 140, in request
    res = self._session.request(name, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/session.py", line 91, in request
    v = self._blocking_request(method, args)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/session.py", line 169, in _blocking_request
    self._enqueue_notification)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/async_session.py", line 66, in run
    self._msgpack_stream.run(self._on_message)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/msgpack_stream.py", line 44, in run
    self.loop.run(self._on_data)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/event_loop/base.py", line 143, in run
    self._run()
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/event_loop/asyncio.py", line 112, in _run
    self._loop.run_forever()
  File "/usr/lib/python3.6/asyncio/base_events.py", line 409, in run_forever
    raise RuntimeError('This event loop is already running')
RuntimeError: This event loop is already running

Another instance:

[deoplete.jedi.client] Caught BrokenPipeError(32, 'Broken pipe') during handling completions
[deoplete] Traceback (most recent call last):
  File "/home/user/.vim/plugged/deoplete.nvim/rplugin/python3/deoplete/child.py", line 236, in _gather_results
    ctx['candidates'] = source.gather_candidates(ctx)
  File "/home/user/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/profiler.py", line 39, in wrapper
    ret = func(self, *args, **kwargs)
  File "/home/user/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi.py", line 201, in gather_candidates
    cache_key, extra_modules = cache.cache_context(buf.name, context, src,
  File "/usr/lib/python3.6/site-packages/neovim/api/buffer.py", line 116, in name
    return self.request('nvim_buf_get_name')
  File "/usr/lib/python3.6/site-packages/neovim/api/common.py", line 44, in request
    return self._session.request(name, self, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/neovim/api/nvim.py", line 140, in request
    res = self._session.request(name, *args, **kwargs)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/session.py", line 91, in request
    v = self._blocking_request(method, args)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/session.py", line 169, in _blocking_request
    self._enqueue_notification)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/async_session.py", line 66, in run
    self._msgpack_stream.run(self._on_message)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/msgpack_stream.py", line 44, in run
    self.loop.run(self._on_data)
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/event_loop/base.py", line 143, in run
    self._run()
  File "/usr/lib/python3.6/site-packages/neovim/msgpack_rpc/event_loop/asyncio.py", line 112, in _run
    self._loop.run_forever()
  File "/usr/lib/python3.6/asyncio/base_events.py", line 409, in run_forever
    raise RuntimeError('This event loop is already running')
RuntimeError: This event loop is already running
Error from jedi: RuntimeError('This event loop is already running',).  Use :messages / see above for error details.

Code in cpython: https://github.com/python/cpython/blob/20d68dfcc07bd389ce2ea7b0773c44d97ebeb68d/Lib/asyncio/base_events.py#L507-L508

It appears to be a race, since is_running() only looks at the thread_id, and
not _stopping (which is what stop() sets).

Events:

2018-04-24 18:29:59.639905 asyncio: loop: <_UnixSelectorEventLoop running=False closed=False debug=False> (140257753452784) (pid: 13763)
logging.callHandlers: handle: <LogRecord: deoplete.jedi.client, 40, /home/daniel/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py, 563, "Caught %r during handling completions">: Caught BrokenPipeError(32, 'Broken pipe') during handling completions
2018-04-24 18:29:59.641060 logger: <LogRecord: deoplete.jedi.client, 40, /home/daniel/.vim/plugged/deoplete-jedi/rplugin/python3/deoplete/sources/deoplete_jedi/server.py, 563, "Caught %r during handling completions">: Caught BrokenPipeError(32, 'Broken pipe') during handling completions
2018-04-24 18:29:59.641272 asyncio: stopping (pid: 13763)
2018-04-24 18:29:59.641933 asyncio: loop: <_UnixSelectorEventLoop running=True closed=False debug=False> (140257753452784) (pid: 13763)

So neovim stops the loop ("stopping"), but then calls self._loop.run_forever again, since the internal is_running is false, but run_forever will then raise the RuntimeError.

I've tried using self.loop._loop.is_running directly/alone, but then the greenlet parent might be None:

  File "/home/user/.vim/plugged/deoplete.nvim/rplugin/python3/deoplete/logger.py", line 148, in filter
    record.name)
  File "…/Vcs/neovim-python-client/neovim/api/nvim.py", line 252, in call
    return self.request('nvim_call_function', name, args, **kwargs)
  File "…/Vcs/neovim-python-client/neovim/api/nvim.py", line 140, in request
    res = self._session.request(name, *args, **kwargs)
  File "…/Vcs/neovim-python-client/neovim/msgpack_rpc/session.py", line 90, in request
    v = self._yielding_request(method, args)
  File "…/Vcs/neovim-python-client/neovim/msgpack_rpc/session.py", line 157, in _yielding_request
    return parent.switch()
AttributeError: 'NoneType' object has no attribute 'switch'

[blueyed]

Sorry, I've meant to file it with neovim-python-client: neovim/pynvim#326

[Shougo]

OK