Python 3.5 asyncio loop.stop threading problem

call_soon_threadsafe_loop_stop.log

2018-01-31 17:45:06,829 MainThread - root     I - Starting loop thread
2018-01-31 17:45:06,829 run_loop   - asyncio  D - Using selector: EpollSelector
2018-01-31 17:45:06,830 MainThread - root     I - Started loop thread
2018-01-31 17:45:06,830 run_loop   - root     I - running loop
2018-01-31 17:45:07,831 MainThread - root     I - Scheduling something in the far future
2018-01-31 17:45:07,831 run_loop   - asyncio  I - poll took 1001.507 ms: 1 events
2018-01-31 17:45:07,832 run_loop   - root     I - schedule_later: far future
2018-01-31 17:45:08,832 MainThread - root     I - Scheduling something in the near future
2018-01-31 17:45:08,833 run_loop   - asyncio  I - poll 29999.713 ms took 1000.840 ms: 1 events
2018-01-31 17:45:08,833 run_loop   - root     I - schedule_later: near future
2018-01-31 17:45:09,834 MainThread - root     I - Stopping loop
2018-01-31 17:45:09,835 run_loop   - asyncio  I - poll 9999.771 ms took 1001.083 ms: 1 events
2018-01-31 17:45:09,835 run_loop   - root     I - loop ended
2018-01-31 17:45:10,836 MainThread - root     I - Current task None in loop <_UnixSelectorEventLoop running=False closed=False debug=True> in loop thread <Thread(run_loop, stopped 139993295951616)>
2018-01-31 17:45:10,836 MainThread - root     I - 2 tasks scheduled for later execution: [<TimerHandle when=68198.796758575 info('schedule_later:called_at %s', 'near future') at /usr/lib64/python3.6/logging/__init__.py:1892 created at /home/niko/.PyCharm2017.3/config/scratches/scratch_51.py:26>, <TimerHandle when=68217.795213603 info('schedule_later:called_at %s', 'far future') at /usr/lib64/python3.6/logging/__init__.py:1892 created at /home/niko/.PyCharm2017.3/config/scratches/scratch_51.py:26>]
2018-01-31 17:45:10,837 MainThread - root     I - Waiting for loop join
2018-01-31 17:45:10,837 MainThread - root     I - loop joined
2018-01-31 17:45:10,845 MainThread - asyncio  D - Close <_UnixSelectorEventLoop running=False closed=False debug=True>

loop_stop_problem.py

import asyncio
import logging
import sys
import time
import traceback
from threading import Thread

logging.basicConfig(level=logging.DEBUG,
                    format="%(asctime)s %(threadName)-10s - %(name)-8s %(levelname).1s - %(message)s")
loop: asyncio.BaseEventLoop = None


def run_loop():
    global loop
    loop = asyncio.new_event_loop()
    loop.set_debug(True)
    try:
        logging.info("running loop")
        loop.run_forever()
    finally:
        logging.info("loop ended")


def schedule_later(delay, msg):
    logging.info("schedule_later: %s", msg)
    loop.call_at(loop.time() + delay, logging.info, "schedule_later:called_at %s", msg)


logging.info("Starting loop thread")
loop_thread = Thread(target=run_loop, name="run_loop")
loop_thread.start()
logging.info("Started loop thread")
time.sleep(1)

logging.info("Scheduling something in the far future")
loop.call_soon_threadsafe(schedule_later, 30, "far future")
time.sleep(1)

logging.info("Scheduling something in the near future")
loop.call_soon_threadsafe(schedule_later, 10, "near future")
time.sleep(1)

logging.info("Stopping loop")
loop.call_soon_threadsafe(loop.stop)
# loop.stop()

time.sleep(1)
logging.info("Current task %s in loop %s in loop thread %s", asyncio.Task.current_task(loop=loop), loop, loop_thread)
logging.info("%s tasks scheduled for later execution: %s", len(loop._scheduled), loop._scheduled)
if loop_thread.is_alive():
    logging.info("Loop thread stack: %s", "".join(traceback.format_stack(sys._current_frames()[loop_thread.ident])))

logging.info("Waiting for loop join")
loop_thread.join()
logging.info("loop joined")

threadunsafe_loop_stop.log

2018-01-31 17:43:45,560 MainThread - root     I - Starting loop thread
2018-01-31 17:43:45,561 MainThread - root     I - Started loop thread
2018-01-31 17:43:45,561 run_loop   - asyncio  D - Using selector: EpollSelector
2018-01-31 17:43:45,561 run_loop   - root     I - running loop
2018-01-31 17:43:46,561 MainThread - root     I - Scheduling something in the far future
2018-01-31 17:43:46,562 run_loop   - asyncio  I - poll took 1000.650 ms: 1 events
2018-01-31 17:43:46,562 run_loop   - root     I - schedule_later: far future
2018-01-31 17:43:47,563 MainThread - root     I - Scheduling something in the near future
2018-01-31 17:43:47,563 run_loop   - asyncio  I - poll 29999.756 ms took 1000.942 ms: 1 events
2018-01-31 17:43:47,564 run_loop   - root     I - schedule_later: near future
2018-01-31 17:43:48,564 MainThread - root     I - Stopping loop
2018-01-31 17:43:49,564 MainThread - root     I - Current task None in loop <_UnixSelectorEventLoop running=True closed=False debug=True> in loop thread <Thread(run_loop, started 140624323286784)>
2018-01-31 17:43:49,564 MainThread - root     I - 2 tasks scheduled for later execution: [<TimerHandle when=68117.527237019 info('schedule_later:called_at %s', 'near future') at /usr/lib64/python3.6/logging/__init__.py:1892 created at /home/niko/.PyCharm2017.3/config/scratches/scratch_51.py:26>, <TimerHandle when=68136.525518461 info('schedule_later:called_at %s', 'far future') at /usr/lib64/python3.6/logging/__init__.py:1892 created at /home/niko/.PyCharm2017.3/config/scratches/scratch_51.py:26>]
2018-01-31 17:43:49,569 MainThread - root     I - Loop thread stack:   File "/usr/lib64/python3.6/threading.py", line 884, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib64/python3.6/threading.py", line 916, in _bootstrap_inner
    self.run()
  File "/usr/lib64/python3.6/threading.py", line 864, in run
    self._target(*self._args, **self._kwargs)
  File "/home/niko/.PyCharm2017.3/config/scratches/scratch_51.py", line 19, in run_loop
    loop.run_forever()
  File "/usr/lib64/python3.6/asyncio/base_events.py", line 421, in run_forever
    self._run_once()
  File "/usr/lib64/python3.6/asyncio/base_events.py", line 1376, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib64/python3.6/selectors.py", line 445, in select
    fd_event_list = self._epoll.poll(timeout, max_ev)

2018-01-31 17:43:49,570 MainThread - root     I - Waiting for loop join
2018-01-31 17:43:57,573 run_loop   - asyncio  I - poll 9999.724 ms took 10009.126 ms: timeout
2018-01-31 17:43:57,573 run_loop   - root     I - schedule_later:called_at near future
2018-01-31 17:43:57,574 run_loop   - root     I - loop ended
2018-01-31 17:43:57,574 MainThread - root     I - loop joined
2018-01-31 17:43:57,581 MainThread - asyncio  D - Close <_UnixSelectorEventLoop running=False closed=False debug=True>