Output flooded with EventLoop related messages

[pierreganty]

I have a Python script that is spawning thousands of short lived nvim instances.
With the latest release of pynvim (i.e. 0.5.0) the output gets flooded with the following messages:

…
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 40854 is closed
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 40855 is closed
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 40856 is closed
…

Is there a way to silence these messages ? A workaround, for the time being, is to downgrade to 0.4.3.

Thank you for your time and the new release.

Output of nvim -V1 -v

NVIM v0.10.0-dev-1157+g6e0e36bd70
Build type: RelWithDebInfo
LuaJIT 2.1.1694940244
Compilation: /Library/Developer/CommandLineTools/usr/bin/cc -O2 -g -Og -g -Wall -Wextra -ped
antic -Wno-unused-parameter -Wstrict-prototypes -std=gnu99 -Wshadow -Wconversion -Wvla -Wdou
ble-promotion -Wmissing-noreturn -Wmissing-format-attribute -Wmissing-prototypes -Wimplicit-
fallthrough -fdiagnostics-color=always -fstack-protector-strong -DUNIT_TESTING -DINCLUDE_GEN
ERATED_DECLARATIONS -DNVIM_TS_HAS_SET_MAX_START_DEPTH -I/Users/pierreganty/neovim/.deps/usr/
include/luajit-2.1 -I/opt/homebrew/opt/gettext/include -I/Users/pierreganty/neovim/.deps/usr
/include -I/Users/pierreganty/neovim/build/src/nvim/auto -I/Users/pierreganty/neovim/build/i
nclude -I/Users/pierreganty/neovim/build/cmake.config -I/Users/pierreganty/neovim/src -I/Lib
rary/Developer/CommandLineTools/SDKs/MacOSX14.0.sdk/usr/include

[wookayin]

Questions:

• Does that happen also on pynvim 0.4.3 or only on pynvim 0.5.0?
• What is your python version?
• Can you make a simple reproduction by any chance? That will be very helpful for debugging.

The warning is actually coming from ChildWatcher: https://github.com/python/cpython/blob/v3.12.0/Lib/asyncio/unix_events.py#L1333-L1334. I think there is some missing logic w.r.t the lifecycle of event loop when child processes (hence child watcher) are used. Relevant: #241 #543

[pierreganty]

1. Does not happen in 0.4.3, only in 0.5.0
2. Python 3.11.6
3. I am not able to come up with a simple reproduction and won't be able to look into it in 2023.

[wookayin]

Without a reasonable reproduction, bugfix might take a bit long. Please let us know when you've got some free cycles.

My guess is that fd4247c is the relevant difference against 0.4.3. I have a proposed fix: a PR will follow (EDIT: #556), please stay tuned.

[wookayin]

Hmm if #556 (comment) doesn't fix this, I'll need a repro to help you troubleshoot this issue. At least any traceback information will be needed.

Can you try enabling neovim logging?

$ export NVIM_PYTHON_LOG_FILE="555.log" NVIM_PYTHON_LOG_LEVEL="debug"
$ python ...<your script>...

or override asyncio's warning logger to print the detailed stacktrace information:

import functools
import logging
import asyncio.log
formatter = logging.Formatter('[%(levelname)s %(asctime)s] %(filename)s:%(lineno)d %(message)s')
ch = logging.StreamHandler()
ch.setFormatter(formatter)
asyncio.log.logger.addHandler(ch)
asyncio.log.logger.warning = functools.partial(asyncio.log.logger.warning, stack_info=True)

BTW, if you'd like to silence the warning you can do something like:

import asyncio.log
asyncio.log.logger.setLevel("ERROR")

[wookayin]

Minimal repro:

vim = pynvim.attach('child', argv=['nvim', '--embed', '--clean', '-i', 'NONE'])
vim.close()
vim = pynvim.attach('child', argv=['nvim', '--embed', '--clean', '-i', 'NONE'])
vim.close()

# Result
Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 1048 is closed