Apprise is doing I/O inside the event loop

[raman325]

The problem

HA is reporting that apprise is doing I/O inside the event loop

Environment

• Home Assistant Core release with the issue: 0.115.0
• Last working Home Assistant Core release (if known): 0.114.4
• Operating environment (OS/Container/Supervised/Core): Container
• Integration causing this issue: apprise
• Link to integration documentation on our website: https://www.home-assistant.io/integrations/apprise/

Traceback/Error logs

Logger: homeassistant.util.async_
Source: util/async_.py:105
First occurred: 1:43:27 PM (1 occurrences)
Last logged: 1:43:27 PM

Detected I/O inside the event loop. This is causing stability issues. Please report issue for apprise doing I/O at homeassistant/components/apprise/notify.py, line 71: self.apprise.notify(body=message, title=title, tag=targets)

Additional information

I can submit a fix for this, just wanted to report it as an FYI See below thread

[probot-home-assistant]

apprise documentation
apprise source
_{^{(message by IssueLinks)}}

[probot-home-assistant]

Hey there @caronc, mind taking a look at this issue as its been labeled with an integration (apprise) you are listed as a codeowner for? Thanks!
_{^{(message by CodeOwnersMention)}}

[caronc]

@raman325,

The later versions of Apprise (starting at v0.8.7) adapted asyncio so i could send all of the notifications asyncronously. This makes a world of difference to older versions. Do you think this might be causing a problem? You can disable the async and fall back to the old way if you think that might be necessary?

[raman325]

so is Apprise.notify now an async function?

[caronc]

so is Apprise.notify now an async function?

Not specifically Apprise.notify(), no, but it collects all of notifications under the hood and makes use of async calls. if async is enabled (which is is by default for Python 3 users in Apprise) it calls this block of code.

But i made the async reference a switch, so it can be turned off if require.

Edit: I mean I'm leveraging the same thign HomeAssistant is though with asyncio and handling multiple tasks at once. Does this mean that all plugins/adapters to HomeAssistant can't use asyncio going forward? Is there a graceful way it can still be left on? It drastically improves the performance of Apprise (especially when you need to notify more then 1 endpoint.

[raman325]

I think the problem here is we are going async -> sync -> async. Is there a way to go straight to the async call?

[raman325]

actually @bdraco pointed out in Discord that at some point, your async code is calling urllib, which is synchronous, hence the upstream detection

[raman325]

make that requests. You should be using aiohttp or another async http library to make your outbound requests. That will eliminate the warning

[caronc]

I think the problem here is we are going async -> sync -> async. Is there a way to go straight to the async call?

Unfortunately the sync call gathers all of the services to notify and then fires them all off in their own async task. The async logic exists elsewhere because it was the only way I could get Python 2.7 users (for backwards compatibility) not to fail. Perhaps i could write async notify task and call it directly (it in-turn would still fork more async processes). So you'd get: async -> async -> async. Would this be satisfactory?

You should be using aiohttp or another async http library to make your outbound requests.

I wasn't aware that requests would cause issues with asyncio; thank you for bringing that info to me. I guess switching to aiohttp would really break the backwards compatibility 😲 I'll need to think about this. Maybe the next version should just flat out drop support for Python 2.7 since it's being dropped by pip anyway in Jan of 2021.

[caronc]

For now, I can do a pull request to just flat out disable all asyncio so you go from async -> sync if you want?

Basically the following code in homeassistant/components/apprise/notify.py needs to change from this:

def get_service(hass, config, discovery_info=None):
    """Get the Apprise notification service."""

    # Create our object
    a_obj = apprise.Apprise()

to this:

def get_service(hass, config, discovery_info=None):
    """Get the Apprise notification service."""

    # Create our asset object
    asset = apprise.AppriseAsset(async_mode=False)

    # Create our object
    a_obj = apprise.Apprise(asset=asset)

[raman325]

For point 1, I am not sure if this would resolve this warning. I think the core issue is point 2.

I am not the best person to advise you on the changes here, my async knowledge is pretty cursory. And the notification service isn't broken, it's just firing this warning on every notification. If you need some help, you may want to try the #devs_core channel in the HA discord, there are people much more capable than I that watch that channel and may be able to help.

[caronc]

Just a side note, there are a lot of Apprise services that don't use requests either. Some just use binary protocols such as Growl Notification Transport Protocol (GNTP), Extensible Messaging and Presence Protocol (XMPP), etc. So there are no asynio wrappers for these guys even if i fully converted to aiohttp for just the HTTP requests.

What specifically becomes unstable with Home Assistant with async -> sync -> async anyhow? Just curious (for my own information)?

[bdraco]

Just a side note, there are a lot of Apprise services that don't use requests either. Some just use binary protocols such as Growl Notification Transport Protocol (GNTP), Extensible Messaging and Presence Protocol (XMPP), etc. So there are no asynio wrappers for these guys even if i fully converted to aiohttp` for just the HTTP requests.

What specifically becomes unstable with Home Assistant with async -> sync -> async anyhow? Just curious (for my own information)?

The sync code is running in the event loop which means that everything has to wait until while data is being read or written on the socket.

[raman325]

I just tested your proposed fix and the warning still fires 😞

[caronc]

The sync code is running in the event loop which means that everything has to wait until while data is being read or written on the socket.

Thanks @bdraco for your reply. But since the code stack resides inside the first async call, can it still all be aborted if you had to? I mean at the lowest level you could still call Task.cancel() if you didn't want to wait any longer? Thoughts?

I just tested your proposed fix and the warning still fires 😞

That sucks, you should be bypassing all of the async code with that flag set. Or i have a bug i need to address.

[raman325]

There is indeed a bug I think.

https://github.com/caronc/apprise/blob/784e073eea64d2ee37cc52e7a2391bce35b05720/apprise/Apprise.py#L328
Shouldn't that be self.asset.async_mode rather than server.asset.async_mode?

[bdraco]

The sync code is running in the event loop which means that everything has to wait until while data is being read or written on the socket.

Thanks @bdraco for your reply. But since the code stack resides inside the first async call, can it still all be aborted if you had to? I mean at the lowest level you could still call Task.cancel() if you didn't want to wait any longer? Thoughts?

It is going to tie up the event loop since there is no code that returns control to the loop while the I/O is happening. If you ran each task in the executor, it would workaround the issue for now.

I just tested your proposed fix and the warning still fires 😞

That sucks, you should be bypassing all of the async code with that flag set. Or i have a bug i need to address.

[caronc]

Shouldn't that be self.asset.async_mode rather than server.asset.async_mode?

@raman325, No that part is good... async is assigned to each server instance as they're created. I was probably over thinking this feature when i did it. But basically i started it off with that level of granularity (async at a per server being notified basis). Effectively you can have it so some servers run with async while others queue. I'll dig into this for sure though; thanks for poking around already! I'll add a unit test for this very thing if it isn't there already. Once you initialize the global AppriseAsset with the flag set though, it gets passed down into each service unless otherwise over-ridden (which definitely doesn't happen in the Home Assistant code block). You have to go out of your way to do this.

It is going to tie up the event loop since there is no code that returns control to the loop while the I/O is happening. If you ran each task in the executor, it would workaround the issue for now.

@bdraco, fair enough and thank you for all you feedback!

[raman325]

FWIW when I had async_mode set to False, it was still entering the async block. When I changed that line to reference self.asset.async_mode instead, it skipped the block and the error stopped firing, so something about the implementation doesn't match what you intended. Either way I think I've information overloaded you at this point so will let you figure it out 😄

[caronc]

Something else must be causing the issue because for sure the async_mode switch is definitely working. It absolutely will not reference any of the async calls when set. I'm open to any more advice, i'll gladly change some of the code base to help this issue/warning you guys are having that you want to clear up. 🙂

Keep me posted.

[raman325]

Here's what I did:

1. Add the following statement under here: https://github.com/caronc/apprise/blob/master/apprise/Apprise.py#L399
   logger.error("I am doing async") and install the local version of apprise for HA to use.
2. Made change suggested in Apprise is doing I/O inside the event loop #40184 (comment)
3. Ran HomeAssistant and called the notify.apprise service and check the logs.

I get both the "I am doing async" message as well as the I/O inside event loop warning.

I saw your linked PR and the test does seem to indicate that async_mode is getting passed down appropriately, so I'm not sure why what I am getting is different from your tests. Does it matter that I am using Slack as the notifier?

[caronc]

Does it matter that I am using Slack as the notifier?

It shouldn't matter, no. They're all inherited from the same plugin base at the end of the day. Can you share your testing steps that you're doing? I am taking a guess at something like...:

git clone git@github.com:home-assistant/core.git
pushd core
pip install -r requirements_test_all.txt
py.test -k apprise

[raman325]

1. Cloned core
2. Created and activated a venv
3. Ran setup/script in the core repository so that I could run hass off the local repository.
4. Updated the get_service call as suggested above.
5. Cloned apprise
6. Added logging statement.
7. pip install -I <path/to/apprise> in my venv so that is now what HomeAssistant is using
8. Ran hass after configuring apprise
9. Called service
10. Got statement I added in 6 + I/O error

[caronc]

@raman325,

thank you for the detailed explanation as to how your doing this! 👍

I tried to do things your way and i might have done something wrong, but this worked:

# Repository

git clone git@github.com:caronc/core.git home-assistant.core
cd home-assistant.core

# virtualenv
python3 -m venv .
. ./bin/activate

# requirements
pip install -r requirements_all.txt -r requirements_test_all.txt
# Some missed, but required components:
pip install requests-mock asynctest pytest-sanic sanic

# Then i ran the unit tests and got all green lights:
# I did this after applying the change we discussed.
py.test tests/components/apprise/test_notify.py

I'm not sure if I'm missing the key element being tested here, but i was at least able to run the unit tests. I created PR #40213, but it's not identifying anything new that hasn't already been discussed here (or you haven't already tried).

[raman325]

I tried running the tests without the change and they also pass. It appears running the tests does not trigger the check because I can't even find a log message of that warning. I did a sanity check and tried #40213 (but running hass instead of running tests) and still got the error...

This article talks a lot about the different modes and how to call synchronous functions within async and vice versa: https://www.aeracode.org/2018/02/19/python-async-simplified/

In the sync from async section, they reference the sync_to_async function in asgiref.sync. FWIW I tried it and it eliminated the error. You can see my changes here: caronc/apprise@master...raman325:sync_from_async

Not sure if it's worth it to add another dependency, but it's an option for you

[raman325]

And here's one using asyncio's run_in_executor that doesn't require any additional dependencies but appears to resolve the issue as well (also shamelessly stolen from that article): caronc/apprise@master...raman325:sync_from_async_2

[caronc]

Thanks for all your research and testing. I'm a bit against pulling in an entire library used for websockets just to use https://github.com/django/asgiref/blob/master/asgiref/sync.py; specifically this block of code. I wonder if the author would mind de-coupling into it's own library or if i should just throw it in my utils function. sync_to_async() looks like a wrapper someone might want to use if they didn't write the target calling function they need to be asynchronous (and need to make it so it could be awaited on under the conditions they vetted for blocks). Thus, based on the article you shared though, I don't think it fixes the problem at hand (it only masks it from Home Assistant warnings/alarms burying the same sync blocks from within). Calls to time.sleep() will still be called under the hood blocking the event loop. Thanks by the way for sharing that article! It really taught me a lot. 👍 🙂

Even if i were to drop all support for requests and change it over to aiohttp I'd still only address 90% of the notification services Apprise offers. I'd need to think of ways to convert the other methods over that no doubt block under the hood too.

I think the best thing is for us to just switch Apprise back to sync for now; I'm really confused why the switch isn't working at this time for you when i can't make it not work over here. 😕

[raman325]

🤷🏾‍♂️

[raman325]

FYI @caronc I am still getting this error (I am on 0.115.5 so your change is applied in my installation)