asyncio: Warning message when waiting for an Event set by AbstractLoop.add_reader

[Léo El Amri]

Hello list,

During my attempt to bring asyncio support to the multiprocessing Queue,
I found warning messages when executing my code with asyncio debug
logging enabled.

It seems that awaiting for an Event will make theses messages appears
after the second attempt to wait for the Event.

Here is a code sample to test this (47 lines long):

import asyncio
import threading
import os
import io
import time
import logging
logging.basicConfig()
logging.getLogger('asyncio').setLevel(logging.DEBUG)
fd1, fd2 = os.pipe()  # (r, w)
loop = asyncio.get_event_loop()
event = asyncio.Event()
def readfd(fd, size):
    buf = io.BytesIO()
    handle = fd
    remaining = size
    while remaining > 0:
        chunk = os.read(handle, remaining)
        n = len(chunk)
        if n == 0:
            raise Exception()
        buf.write(chunk)
        remaining -= n
    return buf.getvalue()
def f():
    loop.add_reader(fd1, event.set)
    loop.run_until_complete(g())
    loop.close()
async def g():
    while True:
        await event.wait()
        msg = readfd(fd1, 4)
        event.clear()
        if msg == b'STOP':
            break
        print(msg)
if __name__ == '__main__':
    t = threading.Thread(target=f)
    t.start()
    time.sleep(1)
    os.write(fd2, b'TST1')
    time.sleep(1)
    os.write(fd2, b'TST2')
    time.sleep(1)
    os.write(fd2, b'TST3')
    time.sleep(1)
    os.write(fd2, b'STOP')
    t.join()

I get this output:

DEBUG:asyncio:Using selector: EpollSelector
DEBUG:asyncio:poll took 999.868 ms: 1 events
b'TST1'
b'TST2'
WARNING:asyncio:Executing <Handle [CUT] locks.py:261> took 1.001 seconds
INFO:asyncio:poll took 1000.411 ms: 1 events
b'TST3'
WARNING:asyncio:Executing <Handle [CUT] locks.py:261> took 1.001 seconds
DEBUG:asyncio:Close <_UnixSelectorEventLoop [CUT]>

I don't get the message, because it seems that the event is awaited
properly. I'm especially bugged, because I get this output from the
actual code I'm writing:

WARNING:asyncio:Executing <Handle [CUT] locks.py:261> took 1.000 seconds
DEBUG:asyncio:poll took 0.012 ms: 1 events

Here, it seems that "polling" went for 0.012 ms. But it should have gone
for 1000.0 ms. But in any case, it still works. However, the fact that
polling seems to "return" instantly is a strange fact.

The test code is not producing this difference. In fact, it seems that
polling is working as intended (Polling takes 1000.0 ms and Event is
awaited for 1000.0 ms). But there is still this warning...

Maybe one of you have an insight on this ?