Bug 421662 - Elisa does not release PowerManagement inhibitions on exit if it's playing when exited
Summary: Elisa does not release PowerManagement inhibitions on exit if it's playing wh...
Status: RESOLVED WORKSFORME
Alias: None
Product: Elisa
Classification: Applications
Component: general (show other bugs)
Version: 20.04.1
Platform: Gentoo Packages Linux
: NOR normal
Target Milestone: ---
Assignee: Matthieu Gallien
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-05-17 06:07 UTC by Gabriel Marcano
Modified: 2020-12-19 04:35 UTC (History)
2 users (show)

See Also:
Latest Commit:
Version Fixed In:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Gabriel Marcano 2020-05-17 06:07:34 UTC
SUMMARY

Elisa does not release the inhibition it places on org.freedesktop.PowerManagement.Inhibit while it's playing if it's exited while it is playing.

STEPS TO REPRODUCE
1. Launch Elisa
2. Play music through Elisa
3. Exit Elisa without pausing the music

OBSERVED RESULT

dbus-send --session --dest=org.kde.Solid.PowerManagement.PolicyAgent --type=method_call --print-reply /org/kde/Solid/PowerManagement/PolicyAgent org.kde.Solid.PowerManagement.PolicyAgent.ListInhibitions

Shows that there is still elisa's inhibition.

dbus-send --session --dest=org.freedesktop.PowerManagement.Inhibit --type=method_call --print-reply /org/freedesktop/PowerManagement/Inhibit org.freedesktop.PowerManagement.Inhibit.HasInhibit

returns true.

EXPECTED RESULT

For there to be no inhibitions from elisa.

SOFTWARE/OS VERSIONS
Linux/KDE Plasma: Gentoo, Plasma
(available in About System)
KDE Plasma Version: 5.18.5
KDE Frameworks Version: 5.70.0
Qt Version: 5.14.2

ADDITIONAL INFORMATION

I'll check out of curiosity on my end, but it should be possible to fix this by adding something to the PowerManagementInterface destructor, specifically to send a blocking message to the session bus if Elisa is still inhibiting during destruction.
Comment 1 Gabriel Marcano 2020-05-17 08:04:37 UTC
I've been able to hack something on my end, by making QDBusInterface objects and using them to send a synchronous message to release the active Inhibit cookie.

I'm still a little uneasy, as I'm afraid of a collision between a pending async job and the destructor (I don't know how all of these threads work together). Ideally, I think, it would be a good idea to make sure all pending async tasks are done, and then prevent them from starting once the destructor is going.

There's also the added problem of what happens if Elisa is forcibly killed by a signal... this would leave the Inhibit in place, still.

I would share what I have hacked together, but I'm under contract to not share any code I write while employed at my current employer without explicit permission from them (yay USA /s).
Comment 2 Nate Graham 2020-06-10 20:46:52 UTC
Cannot reproduce with the latest version of Elisa. Can you try to reproduce with the git master version?
Comment 3 Gabriel Marcano 2020-06-10 22:59:33 UTC
I'll take a look tonight to see if I can reproduce it. I'm curious to see how it's being handled now, if you can't reproduce the problem.
Comment 4 Gabriel Marcano 2020-06-11 01:50:04 UTC
Yes, I can still reproduce the problem. I re-built elisa with commit 1f400cf32e434479a0b35e19e34a9081e2bd78cc.

$ dbus-send --session --dest=org.kde.Solid.PowerManagement.PolicyAgent --type=method_call --print-reply /org/kde/Solid/PowerManagement/PolicyAgent org.kde.Solid.PowerManagement.PolicyAgent.ListInhibitions
method return time=1591840161.651687 sender=:1.31 -> destination=:1.310 serial=2274 reply_serial=2
   array [
      struct {
         string "elisa"
         string "Playing Music"
      }
   ]
$ ps -ef | grep elisa
gabriel   4181 22395  0 21:49 pts/8    00:00:00 grep --colour=auto elisa
$
Comment 5 Gabriel Marcano 2020-06-11 02:29:25 UTC
Interesting. Looks like a race condition.

Here's a quick screen capture I did with OBS (so it's also inhibiting): https://i.imgur.com/wtmo7pC.mp4

Let me know if you can't access that video for some reason.

In short, I show two terminals, with me launching the compiled elisa, and the other one showing the output of me querying powerdevil for active inhibitions using watch with a 1 second interval.

Elisa began playing back something from the beginning, which I paused after I saw the elisa inhibition show up (about 5 seconds AFTER playing begun). Pausing it caused it to be dropped fairly quickly. Pressing play again, I waited another 5 seconds until the inhibition came up again. I then paused the player again, and saw the inhibition disappear again. For the final test, I clicked play and quickly pressed X to exit the application, before the elisa inhibitor showed up. Like clockwork, it showed up 5 seconds after I pressed play, even though the player had already exited.
Comment 6 Gabriel Marcano 2020-06-13 22:14:41 UTC
Interesting. It looks like I wasn't hallucinating about the 5 seconds:https://github.com/KDE/powerdevil/blob/master/daemon/powerdevilpolicyagent.cpp#L509

PowerDevil is the thing that is implementing the inhibitor. It itself has a 5 second delay before actually recording the inhibition.
Comment 7 Nate Graham 2020-06-14 03:04:03 UTC
Worth a bug on Powerdevil, for sure.

Is there anything actionable here for Elisa?
Comment 8 Gabriel Marcano 2020-06-14 03:56:12 UTC
Here's the PowerDevil commit that introduced the delay: https://github.com/KDE/powerdevil/commit/eca79138c15575f6f523a8680919b407f84da2e2

It's a conscious decision by the powerdevil developers. As far as I can tell, even though powerdevil takes 5 seconds to post an inhibit request, they DO track if they receive an uninhibit request before those 5 seconds are up (https://github.com/KDE/powerdevil/blob/master/daemon/powerdevilpolicyagent.cpp#L599). As far as I can tell powerdevil returns a cookie immediately, so elisa should receive one before the inhibit is officially posted.

In other words, for some reason elisa isn't sending a request when it should to uninhibit. I "fixed" this problem by doing synchronous dbus commands on the destructor (not ideal, because of possible exceptions? Maybe? Not sure, haven't looked to see how dangerous calling dbus related classes in the destructor is), making sure that if we have a cookie, to send a message to uninhibit.

I could do a bit more digging to make sure https://github.com/KDE/elisa/blob/master/src/audiowrapper_qtmultimedia.cpp#L194 is being fired when we're exiting, and that elisa is actually requesting for the power manager to be uninhibited.
Comment 9 Gabriel Marcano 2020-06-18 03:21:45 UTC
So, playing an mp3, AudioWrapper::playerStateSignalChanges doesn't fire when exiting the application (https://github.com/KDE/elisa/blob/aecd9917a45d6c8e3c698490ab5404baacefdcf1/src/audiowrapper_libvlc.cpp#L335). I would wager that it should. Without this being called, we don't make a call to uninhibit.

That said, I'm looking through the powerdevil code right now. Something, seemingly not elisa (I set a breakpoint in the function where we set the inhibition, this does not fire on exit), is causing the inhibition to go away when elisa shuts down, only if the inhibition has posted by the time elisa exits.
Comment 10 Gabriel Marcano 2020-06-18 05:01:14 UTC
I've opened a new bug report for Powerdevil: bug 423131

Even with that bug in place, I still think elisa should try to uninhibit during a regular application exit. I think it's fair to not bother with corner cases such as crashing and receiving an unhandled signal.
Comment 11 Gabriel Marcano 2020-06-18 07:35:07 UTC
In terms of what could be done by elise, I'm not too sure as I'm not familiar with the entire codebase, but maybe we could install a custom handler for "file_quit" that somehow  tells the AudioWrapper to stop playing before killing the application? That should get the underlying code of AudioWrapper to call setPreventSleep (at least both implementations of the AudioWrapper interface do this).
Comment 12 Matthieu Gallien 2020-06-18 07:47:22 UTC
(In reply to Gabriel Marcano from comment #11)
> In terms of what could be done by elise, I'm not too sure as I'm not
> familiar with the entire codebase, but maybe we could install a custom
> handler for "file_quit" that somehow  tells the AudioWrapper to stop playing
> before killing the application? That should get the underlying code of
> AudioWrapper to call setPreventSleep (at least both implementations of the
> AudioWrapper interface do this).

Thanks for your work on this subject.

If you want, you can try to provide a fix for it by using invent.kde.org Gitlab KDE instance. We will make sure to provide you help to get this integrated.

The possibly easiest way is to get this done from a slot connected to void QCoreApplication::aboutToQuit() signal.

We are already saving the window geometry in this way (src/qml/ElisaMainWindow.qml:61).
Comment 13 Gabriel Marcano 2020-06-18 08:10:08 UTC
I'd love to take a stab, but I can't do it for the next month and a half, as my employer limits what code I can contribute (intellectual property assignment clause in contract). I'm actually leaving for grad school in August, so I should be able to get around to trying this out around then, if no one has figured this out.

Once bug 423131 is fixed, arguably the importance of this bug should drop to minor, as powerdevil should be handling elisa exiting itself. I'd argue we still should have elisa emit an Uninhibit request even if in theory powerdevil will do it.

I don't know if Gnome's session implementation is similar or not to Plasma's, so I don't know if they handle undoing all inhibits of applications that exit automatically.
Comment 14 Matthieu Gallien 2020-06-18 08:13:30 UTC
(In reply to Gabriel Marcano from comment #13)
> I'd love to take a stab, but I can't do it for the next month and a half, as
> my employer limits what code I can contribute (intellectual property
> assignment clause in contract). I'm actually leaving for grad school in
> August, so I should be able to get around to trying this out around then, if
> no one has figured this out.
> 
> Once bug 423131 is fixed, arguably the importance of this bug should drop to
> minor, as powerdevil should be handling elisa exiting itself. I'd argue we
> still should have elisa emit an Uninhibit request even if in theory
> powerdevil will do it.
> 
> I don't know if Gnome's session implementation is similar or not to
> Plasma's, so I don't know if they handle undoing all inhibits of
> applications that exit automatically.

Thanks for your work so far. This is really a good contribution.

I will try to have a look at solving the Elisa problem as soon as I finish integrating the few MR I am working on. That should be in few weeks.

I still have Gnome on my laptop. I should be able to test again and see what happen.
Comment 15 Gabriel Marcano 2020-06-18 15:05:17 UTC
I've been doing some reading to understand what's going on. At least with the libvlc audiowrapper, it does look like at some point something is causing the AudioWrapper::stop() slot to be called, which is good. The problem is this slot isn't what causes the inhibition management to happen-- it instead sends a stop command to libvlc. The vlc_callback function is called, and we queue the method that will actually update the inhibit status (audiowrapper_libvcl.cppp:360):
    QMetaObject::invokeMethod(this, [this, newStatus]() {Q_EMIT statusChanged(newStatus);}, Qt::QueuedConnection);

The problem is that this queued method might never run (and it seems to never run) if it is queued right as the application is ending (my guess is the main loop is no longer servicing events at that point).
Comment 16 Bug Janitor Service 2020-11-18 21:48:17 UTC
A possibly relevant merge request was started @ https://invent.kde.org/multimedia/elisa/-/merge_requests/192
Comment 17 Matthieu Gallien 2020-11-18 21:58:37 UTC
I cannot reproduce this.

I suspect this is because powerdevil is able to handle the application disappearance even when an inhibition exists. That would be logic because in case of a crash, you obviously do not want the inhibition to outlive the crashed application.

I have confirmed that the proposed patch allow to get the uninhibition request to be emitted. I have used Bustle.

Are you still able to reproduce that bug ?
Comment 18 Nate Graham 2020-11-18 22:47:01 UTC
Git commit 468eaa7e9d0614884971326cfbc1caacdde904b7 by Nate Graham, on behalf of Matthieu Gallien.
Committed on 18/11/2020 at 22:46.
Pushed by ngraham into branch 'release/20.12'.

prevent crash by stopping play before freeing libvlc resources

also release the inhibition on power state management
Related: bug 424891

M  +4    -0    src/audiowrapper_libvlc.cpp
M  +3    -1    src/audiowrapper_qtmultimedia.cpp

https://invent.kde.org/multimedia/elisa/commit/468eaa7e9d0614884971326cfbc1caacdde904b7
Comment 19 Gabriel Marcano 2020-11-19 00:44:07 UTC
I can check later today (or sometime this week? Being back in school is consuming my life), but I suspect part of the reason you won't be able to reproduce it (if your commit didn't fix it) is if you updated PowerDevil since I last posted a comment, they fixed a bug related to this that I also found (https://bugs.kde.org/show_bug.cgi?id=423131). As that particular bug is fixed, I would expect this Elisa bug to be swept under the metaphorical rug by PowerDevil if it doesn't send an inhibition request before quitting.
Comment 20 Bug Janitor Service 2020-12-04 04:34:18 UTC
Dear Bug Submitter,

This bug has been in NEEDSINFO status with no change for at least
15 days. Please provide the requested information as soon as
possible and set the bug status as REPORTED. Due to regular bug
tracker maintenance, if the bug is still in NEEDSINFO status with
no change in 30 days the bug will be closed as RESOLVED > WORKSFORME
due to lack of needed information.

For more information about our bug triaging procedures please read the
wiki located here:
https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

If you have already provided the requested information, please
mark the bug as REPORTED so that the KDE team knows that the bug is
ready to be confirmed.

Thank you for helping us make KDE software even better for everyone!
Comment 21 Bug Janitor Service 2020-12-19 04:35:48 UTC
This bug has been in NEEDSINFO status with no change for at least
30 days. The bug is now closed as RESOLVED > WORKSFORME
due to lack of needed information.

For more information about our bug triaging procedures please read the
wiki located here:
https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

Thank you for helping us make KDE software even better for everyone!