Logging issue in jupyter kernel when logs are issued in a Thread

[mscheltienne]

Description of the problem

When running the code snippet bellow in VSCode interactive window (using ipykernel), it fails at k=1012 on both Linux and Windows, with:

--- Logging error ---
Exception in thread Thread-1016:
Traceback (most recent call last):
  File "/home/scheltie/pyvenv/mscheltienne/mne-lsl/lib/python3.11/site-packages/ipykernel/iostream.py", line 141, in _event_pipe
    event_pipe = self._local.event_pipe
                 ^^^^^^^^^^^^^^^^^^^^^^
AttributeError: '_thread._local' object has no attribute 'event_pipe'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.11/logging/__init__.py", line 1113, in emit
    stream.write(msg + self.terminator)
  File "/home/scheltie/pyvenv/mscheltienne/mne-lsl/lib/python3.11/site-packages/ipykernel/iostream.py", line 664, in write
    self._schedule_flush()
  File "/home/scheltie/pyvenv/mscheltienne/mne-lsl/lib/python3.11/site-packages/ipykernel/iostream.py", line 561, in _schedule_flush
    self.pub_thread.schedule(_schedule_in_thread)
  File "/home/scheltie/pyvenv/mscheltienne/mne-lsl/lib/python3.11/site-packages/ipykernel/iostream.py", line 267, in schedule
    self._event_pipe.send(b"")
    ^^^^^^^^^^^^^^^^
  File "/home/scheltie/pyvenv/mscheltienne/mne-lsl/lib/python3.11/site-packages/ipykernel/iostream.py", line 145, in _event_pipe
    event_pipe = ctx.socket(zmq.PUSH)
                 ^^^^^^^^^^^^^^^^^^^^
  File "/home/scheltie/pyvenv/mscheltienne/mne-lsl/lib/python3.11/site-packages/zmq/sugar/context.py", line 362, in socket
    s: ST = socket_class(  # set PYTHONTRACEMALLOC=2 to get the calling frame
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/scheltie/pyvenv/mscheltienne/mne-lsl/lib/python3.11/site-packages/zmq/sugar/socket.py", line 159, in __init__
    super().__init__(
  File "zmq/backend/cython/socket.pyx", line 332, in zmq.backend.cython.socket.Socket.__init__
zmq.error.ZMQError: Too many open files

[...]

Sane issue in MNE-LSL with a simpler logger: mne-tools/mne-lsl#260

Steps to reproduce

import threading

from mne.utils import logger

global k
k = 0


def foo():
    try:
        global k
        logger.info("test %i", k)
        k += 1
        if k == 2000:
            return
        thread = threading.Timer(0.00001, foo)
        thread.daemon = True
        thread.start()
    except Exception as error:
        raise error


thread = threading.Timer(0.00001, foo)
thread.daemon = True
thread.start()

An even simpler MWE:

import logging
import sys
import threading

global logger
logger = logging.getLogger("test")
handler = logging.StreamHandler(sys.stdout)
logger.setLevel(logging.INFO)
logger.addHandler(handler)
global k
k = 0


def foo():
    global k
    logger.info("test %i", k)
    k += 1
    if k == 1200:
        return
    thread = threading.Timer(0.00001, foo)
    thread.daemon = True
    thread.start()


thread = threading.Timer(0.00001, foo)
thread.daemon = True
thread.start()

If anyone has an idea about what I'm doing wrong in those MWE.. I'll try to see if we can prevent this in the first place.

[hoechenberger]

Not a solution, but have you considered using asyncio instead of threads?

[hoechenberger]

This works for me:

# %%
import asyncio
from mne.utils import logger

k = 0

async def foo():
    global k
    try:
        while k < 2000:
            logger.info("test %i", k)
            k += 1
            await asyncio.sleep(0.00001)
    except Exception as error:
        raise error

# Create and run the async task using the existing event loop in IPython / Jupyter
task = asyncio.create_task(foo())
await task

[mscheltienne]

Which is logic as this is now running in a single thread. I started using threading in mne-lsl and changing the structure to asyncio would be a lot of work for an unclear benefit to me. I still have no idea why this snippet is failing in interactive windows..

[mscheltienne]

But that one does work:

import logging
import sys
import threading
from concurrent.futures import ThreadPoolExecutor

global logger
logger = logging.getLogger("test")
handler = logging.StreamHandler(sys.stdout)
logger.setLevel(logging.INFO)
logger.addHandler(handler)
global k
k = 0

executor = ThreadPoolExecutor(max_workers=10)  # Limit the number of worker threads


def foo():
    global k
    logger.info("test %i", k)
    k += 1
    if k == 3000:
        return
    executor.submit(foo)  # Submit the task to the thread pool


# Start the first task
executor.submit(foo)

If I get that right, ThreadPoolExecutor is limiting the number of workers and re-using them for future tasks; while my example was spawning/destroying thread rapidly. That seems to be the issue and I don't see anything to be done on MNE's logger side to prevent this from happening. Closing..