[systemd-devel] systemd killing processes on monitor wakeup?
Raman Gupta
rocketraman at gmail.com
Sat Jan 29 22:06:48 UTC 2022
Here are the logs at debug level when plasmashell is not running via
systemd, but instead as an independent process:
Jan 29 16:59:53 edison systemd[2551]: Got message type=signal
sender=org.freedesktop.DBus destination=n/a path=/org/freedesktop/DBus
interface=org.freedesktop.DBus member=NameOwnerChanged cookie=4294967295
reply_cookie=0 signature=sss error-name=n/a error-message=n/a
Jan 29 16:59:53 edison systemd[2551]: plasma-ksystemstats.service: D-Bus
name org.kde.ksystemstats now owned by :1.6208
Jan 29 16:59:53 edison systemd[2551]: plasma-ksystemstats.service: Changed
start -> running
Jan 29 16:59:53 edison systemd[2551]: plasma-ksystemstats.service: Job 3360
plasma-ksystemstats.service/start finished, result=done
Jan 29 16:59:53 edison systemd[2551]: Started Track hardware statistics.
Jan 29 16:59:53 edison systemd[2551]: Sent message type=signal sender=n/a
destination=n/a
path=/org/freedesktop/systemd1/unit/plasma_2dksystemstats_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=10906 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
Jan 29 16:59:53 edison systemd[2551]: Sent message type=signal sender=n/a
destination=n/a
path=/org/freedesktop/systemd1/unit/plasma_2dksystemstats_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=10907 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
Jan 29 16:59:53 edison systemd[2551]: Sent message type=signal sender=n/a
destination=n/a path=/org/freedesktop/systemd1
interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=10908
reply_cookie=0 signature=uoss error-name=n/a error-message=n/a
Jan 29 16:59:53 edison systemd[2551]: Sent message type=method_call
sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus
interface=org.freedesktop.DBus member=RemoveMatch cookie=10909
reply_cookie=0 signature=s error-name=n/a error-message=n/a
Jan 29 16:59:53 edison systemd[2551]: Sent message type=signal sender=n/a
destination=n/a
path=/org/freedesktop/systemd1/unit/plasma_2dksystemstats_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=10910 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
Jan 29 16:59:53 edison systemd[2551]: Sent message type=signal sender=n/a
destination=n/a
path=/org/freedesktop/systemd1/unit/plasma_2dksystemstats_2eservice
interface=org.freedesktop.DBus.Properties member=PropertiesChanged
cookie=10911 reply_cookie=0 signature=sa{sv}as error-name=n/a
error-message=n/a
Jan 29 16:59:56 edison systemd-coredump[3940155]: [🡕] Process 3928538
(plasmashell) of user 1000 dumped core.
*[... plasmashell crash details elided...]*
Jan 29 16:59:56 edison systemd[2551]: Received SIGCHLD from PID 3928538
(plasmashell).
Jan 29 16:59:56 edison systemd[2551]: Child 3928538 (plasmashell) died
(code=dumped, status=11/SEGV)
Jan 29 16:59:56 edison systemd[2551]: app-yakuake at autostart.service: Child
3928538 belongs to app-yakuake at autostart.service.
*[... various other messages / dbus things but no other SIGCHLD or any
other processing things...]*
Note there is nothing related to processes dying or being killed. Is it
appropriate to create a bug for systemd now? Or is there additional
information I can collect?
Regards,
Raman
On Sat, Jan 29, 2022 at 9:20 AM Raman Gupta <rocketraman at gmail.com> wrote:
> As a another test, I left plasmashell as a child process of my terminal
> shell rather than starting it as a systemd user unit.
>
> When doing it this way, plasmashell still crashed on monitor wake-up, but
> my applications remained running.
>
> Given that, it does seem like the crash of plasmashell in combination with
> some behavior of systemd is the source of my applications being terminated
> prematurely.
>
> Regards,
> Raman
>
>
>
> On Fri, Jan 28, 2022 at 10:28 PM Raman Gupta <rocketraman at gmail.com>
> wrote:
>
>> Try to set the systemd user instance's log level to 'debug'; I'm guessing
>>> it's not that systemd kills processes directly but that something triggers
>>> a 'systemctl stop' of the session .scope that they were in.
>>
>>
>> Here are the logs at debug level with some annotations inline:
>>
>> *<wake up at 21:57:30>*
>>
>> Jan 28 21:57:34 edison plasmashell[3114743]: KCrash: Application
>> 'plasmashell' crashing...
>> Jan 28 21:57:34 edison plasmashell[3114743]: KCrash: Attempting to start
>> /usr/libexec/drkonqi
>>
>> *<This is because of https://bugs.kde.org/show_bug.cgi?id=396359
>> <https://bugs.kde.org/show_bug.cgi?id=396359>, could be related to
>> subsequent events but I'm pretty sure I've seen this same problem even when
>> Plasma doesn't crash>*
>>
>> Jan 28 21:57:34 edison systemd[2551]: Got message type=signal
>> sender=org.freedesktop.DBus destination=n/a path=/org/freedesktop/DBus
>> interface=org.freedesktop.DBus member=NameOwnerChanged cookie=4294967295
>> reply_cookie=0 signature=sss error-name=n/a error-message=n/a
>> Jan 28 21:57:34 edison systemd[2551]: plasma-plasmashell.service: D-Bus
>> name org.kde.plasmashell now not owned by anyone.
>> Jan 28 21:57:34 edison systemd[2551]: plasma-plasmashell.service: Changed
>> running -> stop-sigterm
>> Jan 28 21:57:34 edison systemd[2551]: Sent message type=signal sender=n/a
>> destination=n/a
>> path=/org/freedesktop/systemd1/unit/plasma_2dplasmashell_2eservice
>> interface=org.freedesktop.DBus.Properties member=PropertiesChanged
>> cookie=10389 reply_cookie=0 signature=sa{sv}as error-name=n/a
>> error-message=n/a
>> Jan 28 21:57:34 edison systemd[2551]: Sent message type=signal sender=n/a
>> destination=n/a
>> path=/org/freedesktop/systemd1/unit/plasma_2dplasmashell_2eservice
>> interface=org.freedesktop.DBus.Properties member=PropertiesChanged
>> cookie=10390 reply_cookie=0 signature=sa{sv}as error-name=n/a
>> error-message=n/a
>> Jan 28 21:57:34 edison systemd[2551]: Received SIGCHLD from PID 3326812
>> (idea.sh).
>> Jan 28 21:57:34 edison systemd[2551]: Child 3326812 (idea.sh) died
>> (code=killed, status=15/TERM)
>>
>> *<This seems to indicate that systemd is receiving notification that IDEA
>> died. Not sure why killsnoop.py seems to think that systemd is the process
>> that sends the SIGTERM -- it's still unclear to me where IDEA is receiving
>> the SIGTERM from>*
>>
>> Jan 28 21:57:34 edison systemd[2551]: plasma-plasmashell.service: Child
>> 3326812 belongs to plasma-plasmashell.service.
>> Jan 28 21:57:34 edison systemd[2551]: Child 3114994 (kio_http_cache_)
>> died (code=killed, status=15/TERM)
>> Jan 28 21:57:34 edison systemd[2551]: plasma-plasmashell.service: Child
>> 3114994 belongs to plasma-plasmashell.service.
>> Jan 28 21:57:34 edison systemd[2551]: Child 3328167 (adb) died
>> (code=killed, status=15/TERM)
>> Jan 28 21:57:34 edison systemd[2551]: plasma-plasmashell.service: Child
>> 3328167 belongs to plasma-plasmashell.service.
>> Jan 28 21:57:34 edison systemd[2551]: Received SIGCHLD from PID 3328167
>> (n/a).
>>
>> *<bunch more processes dying similarly, plasma restarting, etc.>*
>>
>> Can't think of any events directly related to monitor wakeup that systemd
>>> would react to (unless you meant the processes die on full system suspend
>>> that usually follows). Do you have any screensaver running? Do the
>>> processes actually get killed when the monitor goes to sleep or only when
>>> it wakes up?
>>
>>
>> No screensaver, just the lock screen. It's a desktop -- it doesn't
>> hibernate. The monitors just go to sleep according to the energy settings,
>> and then they wake up when there is keyboard or mouse activity. The
>> processes get killed only at wake-up time -- not at sleep time. It's also
>> at wake up time, not at login time.
>>
>> Just as a test I killed plasmashell to see if that would cause other
>> processes to shut down (recognizing that a SIGTERM is not the same as a
>> crash). It did not. All processes remained running.
>>
>> Regards,
>> Raman
>>
>>
>>
>>
>>
>> On Fri, Jan 28, 2022 at 6:41 AM Mantas Mikulėnas <grawity at gmail.com>
>> wrote:
>>
>>> Try to set the systemd user instance's log level to 'debug'; I'm
>>> guessing it's not that systemd kills processes directly but that something
>>> triggers a 'systemctl stop' of the session .scope that they were in.
>>>
>>> Can't think of any events directly related to monitor wakeup that
>>> systemd would react to (unless you meant the processes die on full system
>>> suspend that usually follows). Do you have any screensaver running? Do the
>>> processes actually get killed when the monitor goes to sleep or only when
>>> it wakes up?
>>>
>>> On Wed, Jan 26, 2022, 15:39 Raman Gupta <rocketraman at gmail.com> wrote:
>>>
>>>> Does anyone have any tips for debugging this or getting more
>>>> information? Should I create an issue for this?
>>>>
>>>> On Sun, Jan 23, 2022 at 3:43 PM Raman Gupta <rocketraman at gmail.com>
>>>> wrote:
>>>>
>>>>> (A variation of this message was originally sent to fedora-users)
>>>>>
>>>>> I have a couple processes that have been consistently dying every time
>>>>> I wake up my monitors after the system has been idle. One is Slack Desktop
>>>>> and the other is IntelliJ IDEA.
>>>>>
>>>>> I used an eBPF program (killsnoop.py at
>>>>> https://github.com/iovisor/bcc/blob/master/tools/killsnoop.py) to
>>>>> trace where the signal to shut down these processes was coming from, and it
>>>>> appears that systemd is sending pretty much every active process signal 15
>>>>> and then 18.
>>>>>
>>>>> TIME PID COMM SIG TPID RESULT
>>>>> ... on monitor wakeup ...
>>>>> 12:16:58 2551 systemd 15 2938613 0
>>>>> 12:16:58 2551 systemd 18 2938613 0
>>>>> 12:16:58 2551 systemd 15 2938814 0
>>>>> 12:16:58 2551 systemd 18 2938814 0
>>>>> 12:16:58 2551 systemd 15 2938832 0
>>>>> 12:16:58 2551 systemd 18 2938832 0
>>>>> 12:16:58 2551 systemd 15 2938978 0
>>>>> 12:16:58 2551 systemd 18 2938978 0
>>>>> 12:16:58 2551 systemd 15 2939432 0
>>>>> 12:16:58 2551 systemd 18 2939432 0
>>>>> 12:16:58 2551 systemd 15 2939899 0
>>>>> 12:16:58 2551 systemd 18 2939899 0
>>>>> 12:16:58 2551 systemd 15 2942192 0
>>>>> 12:16:58 2551 systemd 18 2942192 0
>>>>> ...
>>>>>
>>>>> Process 2551 is the PDF of the source of the signal according to
>>>>> killsnoop, 15 and 18 are the signals being sent, and TPID is the target
>>>>> PID, which among many others, does include my dying processes. Process 2551
>>>>> is indeed systemd, specifically the user process:
>>>>>
>>>>> raman 2551 1 0 Jan07 ? 00:00:10
>>>>> /usr/lib/systemd/systemd --user
>>>>>
>>>>> This behavior is relatively new. What is going on here? I haven't
>>>>> found any other reports of this behavior anywhere else.
>>>>>
>>>>> I'm using systemd-249.9-1.fc35 on Fedora 35.
>>>>>
>>>>> Regards,
>>>>> Raman
>>>>>
>>>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20220129/3964d810/attachment-0001.htm>
More information about the systemd-devel
mailing list