Re: systemd killing processes on monitor wakeup?

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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@autostart.service: Child 3928538 belongs to app-yakuake@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@xxxxxxxxx> 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@xxxxxxxxx> 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, 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@xxxxxxxxx> 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@xxxxxxxxx> 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@xxxxxxxxx> 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


[Index of Archives]     [LARTC]     [Bugtraq]     [Yosemite Forum]     [Photo]

  Powered by Linux