python asyncio logger not logging aiohttp errors

Question

Here is a python script that includes an async class which awaits a task and starts a background loop at initialization:

import asyncio, aiohttp, logging

logging.basicConfig(level=logging.DEBUG, filename='test.log', filemode='w')


class Client:

    async def _async_init(self):
        self.session = aiohttp.ClientSession()
        self.bg_task = asyncio.create_task(self._background_task())
        await self.make_request()
        logging.debug('async client initialized.')
        return self

    async def make_request(self):
        async with self.session.get('https://google.com') as response:
            self.info = await response.text()

    async def _background_task(self):
        while True:
            await asyncio.sleep(1000)


async def main():
    client = await Client()._async_init()
    # Intentionally leaving the aiohttp client session unclosed...
    # ...to log the 'unclosed client session' error.

asyncio.run(main())

Output (not desired):

# test.log

DEBUG:asyncio:Using proactor: IocpProactor
DEBUG:root:async client initialized.

What I want is to log certain asyncio errors to the test.log file. These errors normally get printed out to the terminal if I don't use any logging. These errors are also logged on program exit since they are logged for unclosed client session and unclosed connector situations.

I figured that if I remove the background task from the class:

# These lines are removed from the class

...
# self.bg_task = asyncio.create_task(self._background_task())
...
# async def _background_loop(self):
#     while True:
#         await asyncio.sleep(1000)
...

Output (desired):

# test.log

DEBUG:asyncio:Using proactor: IocpProactor
DEBUG:root:async client initialized.
ERROR:asyncio:Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x000002043315D6D0>
ERROR:asyncio:Unclosed connector
connections: ['[(<aiohttp.client_proto.ResponseHandler object at 0x000002043312B230>, 44091.562)]', '[(<aiohttp.client_proto.ResponseHandler object at 0x000002043312B7E0>, 44092.468)]']
connector: <aiohttp.connector.TCPConnector object at 0x000002043315D710>

The question is, how can I get this output while also keeping the background task in the class?

It might be useful to note that I checked the aiohttp and asyncio sources. I saw that aiohttp calls asyncio's call_exception_handler to log these errors and they are logged inside this method in asyncio library with a simple logger.error(). asyncio's logger has no configurations made other than it's name.

Why asyncio's exception handler is not called(?) due to my background task is beyond my understanding so it'd also be helpful to know if someone explains that part.

UpTheIrons · Answer 1 · 2023-03-31T09:53:26.640

Edit: Currently this solution is not working. I am using Python 3.11 but not sure if I was using an older version when I posted this. Besides, after further reading, I came to acknowledge that suppressing the asyncio.CancelledError like this is not good practice and is discouraged in the Python docs. I removed the try/except blocks from my background task and use them in my coroutines only if I really have a good reason to catch the errors. (eg. logging or other exception handling) Here's another SO question that helped me.

Answer before edit:

I realized that I had to kill or await all asyncio tasks before the event loop closes to make this work. I'm not sure why this is the case, but the idea worked.

Since my background task goes on forever, I need to kill (cancel) it instead of awaiting it. Calling task.cancel() is not enough to kill a task, it just makes a cancellation request by throwing asyncio.CancelledError exception into the task coroutine. This answer is useful to learn more about task creation and termination.

Tasks automatically get cancelled when the event loop closes (throws asyncio.CancelledError into the task) therefore we need to finish this cancellation that the event loop starts. We can also call task.cancel() manually but here I'm logging for user mistakes so any kind of manual cancellation/termination doesn't fit the case.

Maybe not the best but my solution is catching the asyncio.CancelledError exception to ensure that the cancellation is done, by changing the _background_task function such as:

...
async def _background_task(self):
    try:
        while True:
            await asyncio.sleep(1000)
    except asyncio.CancelledError:
        pass  # catch the exception that the event loop throws
...

After finally running the script, the desired errors are successfully logged:

# test.log

DEBUG:asyncio:Using proactor: IocpProactor
DEBUG:root:async client initialized.
ERROR:asyncio:Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x000001187C9F9C90>
ERROR:asyncio:Unclosed connector
connections: ['[(<aiohttp.client_proto.ResponseHandler object at 0x000001187C9C7690>, 24429.703)]', '[(<aiohttp.client_proto.ResponseHandler object at 0x000001187C9C7C40>, 24430.015)]']
connector: <aiohttp.connector.TCPConnector object at 0x000001187C9F9CD0>

python asyncio logger not logging aiohttp errors

1 Answers1