Notification subprocess can cause hangups to become unresponsive

[CyanBlob]

Hey there! I've just recently started using Hangups, and it's great so far except for one problem: My inputs will pretty frequently start being queued instead of processed. I can't tell for sure what the trigger is, but it's either when the other user is typing, or while hangups is downloading the messages. This can be especially frustrating if the other person is sending a lot of messages.

Has anybody else experienced this? Does anybody have any idea of what I should look for when diagnosing this?

Thanks!

[tdryer]

Sounds like something is blocking the IO loop. What operating system and hardware are you using? Is the CPU under high load when the issue occurs?

[CyanBlob]

I'm running Ubuntu 17.10 in a VM with 10GB memory and 4 CPU threads (i3-6100T) allocated to it. I'm running i3 and basically only terminals running vim and SSH sessions and Firefox, so the load is typically pretty light. The issue seems to happen pretty consistently. Do incoming messages block the IO loop, or are they handled on a separate thread?

[tdryer]

Network requests are asynchronous, so they shouldn't be blocking the IO loop.

Try running hangups in asyncio debug mode:

PYTHONASYNCIODEBUG=1 hangups

While checking the logs for any messages from asyncio:

tail -f ~/.cache/hangups/log/hangups.log | grep asyncio

[CyanBlob]

Thanks for the suggestion. Here's a sample from the log: 2018-04-11 07:50:17,548 - asyncio - WARNING - Executing <Handle <TaskWakeupMethWrapper object at 0x7f6d8cb4d7f8>(<Future finis...events.py:275>) created at /usr/lib/python3.6/asyncio/tasks.py:318> took 28.078 seconds 2018-04-11 07:51:40,362 - asyncio - WARNING - Executing <Handle <TaskWakeupMethWrapper object at 0x7f6d9286ce28>(<Future finis...events.py:275>) created at /usr/lib/python3.6/asyncio/tasks.py:318> took 28.054 seconds

Do you have any idea what could be causing the async call to take so long? I don't really know any Python, but I'd be glad to look into it if you point me in the right direction

[tdryer]

Those logs indicate that that IO loop is blocked for 28 seconds. Is that the length of delay you've experienced? Is the hangups process idle during that time, or is it using 100% of a CPU core? If you run hangups with debug logs enabled (hangups -d), what is the last log before it hangs?

[CyanBlob]

Here is the log, trimmed to the point where I receive the log. Interestingly, when tailing the log, I see the message show in the log at about the same time as it comes in on my phone, but hangups then hangs for 28 seconds before displaying the message. Hangups does not max-out a core while hanging.
hangups.log

[CyanBlob]

Looking closer at the log, it seems that hangups tries to create a notification, but fails: 2018-04-16 10:29:33,023 - hangups.ui.notifier - INFO - Creating notification with command: ['gdbus', 'call', '--session', '--dest', 'org.freedesktop.Notifications', '--object-path', '/org/freedesktop/Notifications', '--method', 'org.freedesktop.Notifications.Notify', 'hangups', '0', '', 'Candace Vanover', 'tough love baby\xa0', '[]', '{}', ' -1'] 2018-04-16 10:30:01,060 - hangups.ui.notifier - INFO - Notification command failed: Command '['gdbus', 'call', '--session', '--dest', 'org.freedesktop.Notifications', '--object-path', '/org/freedesktop/Notifications', '--method', 'org.freedesktop.Notifications.Notify', 'hangups', '0', '', 'Candace Vanover', 'tough love baby\xa0', '[]', '{}', ' -1']' returned non-zero exit status 1. 2018-04-16 10:30:01,061 - hangups.ui.notifier - INFO - Failed to parse notification command result: 'NoneType' object has no attribute 'groups' 2018-04-16 10:30:01,062 - hangups.event - DEBUG - Fired Event('Conversation.on_event') 2018-04-16 10:30:01,063 - hangups.client - DEBUG - Received StateUpdate:
Testing notifications with notify-send --icon=gtk-info Test "This is a test" also hung for a while, so I installed dunst to handle notifications, and now all is good with hangups! Thanks for the debugging help. I'll close this, but maybe it'd be worth considering adding something to the README about notification daemons!

[tdryer]

Great! You can also specify --notification-type none to disable notifications.

I'll re-purpose this issue for making the notification code asynchronous to prevent this from happening.