Re: [systemd-devel] systemd killing processes on monitor wakeup?

[Raman Gupta]

>
> 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:

**

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

*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)

**

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).

**

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  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  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 
>> 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  PIDCOMM SIG  TPID   RESULT
>>> ... on monitor wakeup ...
>>> 12:16:58  2551   systemd  15   2938613 0
>>> 12:16:58  2551   syst

Re: [systemd-devel] sd_bus_process() + sd_bus_wait() is it not suitable for application?

[Lennart Poettering]

On Sa, 22.01.22 14:08, www (ouyangxua...@163.com) wrote:

> Dear all,
>
>
> When using sd_bus_process() + sd_bus_wait()  to implement the 
> application(Service), call the methods function on the service can obtain the 
> correct information.  Run a certain number of times will lead to insufficient 
> memory and memleak does occur.
>
>
> It should not be a problem with the DBUS method, because a single call does 
> not increase memory, it needs to call the method 65 ~ 70 times, and you will 
> see the memory increase. After stopping the call, the memory will not 
> decrease. It seems that it has nothing to do with the time interval when the 
> method is called.
>
>
> code implementation：
> int main()
> {
> ..
> r = sd_bus_open_system(&bus);
> ...
> r = sd_bus_add_object_vtable(bus, ..);
> ..
> r= sd_bus_request_name(bus, "xxx.xx.xx.xxx");
> ..
>
>
> for( ; ; )
> {
> r = sd_bus_process(bus, NULL);
> ...
> r = sd_bus_wait(bus, -1);
> ..
> }
> sd_bus_slot_unref(slot);
> sd_bus_unref(bus);
> }

Maybe the callback handlers you added in the vtable keep some objects
pinned?

Also note that unreffing the bus in the end is typically not enough,
if it still has messages queued. Use sd_bus_flush() + sd_bus_close()
first (or combine them in one sd_bus_flush_close_unref()).

Otherwise it might happen that messages still not flushed out at the
end remain pinned.

Lennart

--
Lennart Poettering, Berlin

Re: [systemd-devel] systemd killing processes on monitor wakeup?

[Mantas Mikulėnas]

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  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  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  PIDCOMM 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
>>
>>

Re: [systemd-devel] [EXT] Re: Q: "systemd[1]: var-tmp-AP_0x6tWaHS.mount: Succeeded."

[Mantas Mikulėnas]

On Fri, Jan 28, 2022, 11:59 Ulrich Windl 
wrote:

> >>> Mantas Mikulenas  schrieb am 28.01.2022 um 10:27 in
> Nachricht
> :
> > On Fri, Jan 28, 2022 at 10:50 AM Ulrich Windl <
> > ulrich.wi...@rz.uni-regensburg.de> wrote:
> >
> >> Hi!
> >>
> >> When upgrading SLES15 to SP3, a newer version of systemd was installed
> >> (246.16+suse.191.g3850086c65).
> >> Since then I see new journal messages like these that I cannot associate
> >> with a unit:
> >>
> >> Jan 27 09:29:30 h16 systemd[1]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
> >> Jan 27 09:29:30 h16 systemd[22591]: var-tmp-AP_0xC5KDJP.mount:
> Succeeded.
> >>
> >> Where do these messages originate from, and couldn't they be improved?
> Or
> >> is it some debug-leftover?
> >> I do not see corresponding names in /var/tmp.
> >>
> >
> > If I understand correctly, the messages indicate that the filesystem was
> > *unmounted*, and the same program which did mounting/unmounting
> immediately
> > cleaned up the mountpoint as well.
> >
> > (systemd reacts to external mounts as those also contribute to
> > dependencies.)
> >
> > If OpenSuSE has the kernel audit subsystem enabled, try using `auditctl`
> to
> > monitor a) what process executes mount-related syscalls, b) what process
> > creates directories under /var/tmp.
>
> Thanks,
>
> probably these messages are related to mounting a virtual CD, as nearby are
> these messages:
> Jan 27 09:29:29 h16 kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
> Jan 27 09:29:29 h16 kernel: ISO 9660 Extensions: RRIP_1991A
> Jan 27 09:29:30 h16 systemd[1]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
> Jan 27 09:29:30 h16 systemd[22591]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
> Jan 27 09:29:30 h16 kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
> Jan 27 09:29:30 h16 kernel: ISO 9660 Extensions: RRIP_1991A
> Jan 27 09:29:31 h16 systemd[22591]: var-tmp-AP_0x6tWaHS.mount: Succeeded.
> Jan 27 09:29:31 h16 systemd[1]: var-tmp-AP_0x6tWaHS.mount: Succeeded.
>
> Still I wonder what this is all about (systemd finding a CD, mounting it,
> just
> to find out that no-one needs it?)...
>

Why do you think systemd is finding and/or mounting it?

>

[systemd-devel] Antw: [EXT] Re: Q: "systemd[1]: var-tmp-AP_0x6tWaHS.mount: Succeeded."

[Ulrich Windl]

>>> Mantas Mikulenas  schrieb am 28.01.2022 um 10:27 in
Nachricht
:
> On Fri, Jan 28, 2022 at 10:50 AM Ulrich Windl <
> ulrich.wi...@rz.uni-regensburg.de> wrote:
> 
>> Hi!
>>
>> When upgrading SLES15 to SP3, a newer version of systemd was installed
>> (246.16+suse.191.g3850086c65).
>> Since then I see new journal messages like these that I cannot associate
>> with a unit:
>>
>> Jan 27 09:29:30 h16 systemd[1]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
>> Jan 27 09:29:30 h16 systemd[22591]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
>>
>> Where do these messages originate from, and couldn't they be improved? Or
>> is it some debug-leftover?
>> I do not see corresponding names in /var/tmp.
>>
> 
> If I understand correctly, the messages indicate that the filesystem was
> *unmounted*, and the same program which did mounting/unmounting immediately
> cleaned up the mountpoint as well.
> 
> (systemd reacts to external mounts as those also contribute to
> dependencies.)
> 
> If OpenSuSE has the kernel audit subsystem enabled, try using `auditctl` to
> monitor a) what process executes mount-related syscalls, b) what process
> creates directories under /var/tmp.

Thanks,

probably these messages are related to mounting a virtual CD, as nearby are
these messages:
Jan 27 09:29:29 h16 kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
Jan 27 09:29:29 h16 kernel: ISO 9660 Extensions: RRIP_1991A
Jan 27 09:29:30 h16 systemd[1]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
Jan 27 09:29:30 h16 systemd[22591]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
Jan 27 09:29:30 h16 kernel: ISO 9660 Extensions: Microsoft Joliet Level 3
Jan 27 09:29:30 h16 kernel: ISO 9660 Extensions: RRIP_1991A
Jan 27 09:29:31 h16 systemd[22591]: var-tmp-AP_0x6tWaHS.mount: Succeeded.
Jan 27 09:29:31 h16 systemd[1]: var-tmp-AP_0x6tWaHS.mount: Succeeded.

Still I wonder what this is all about (systemd finding a CD, mounting it, just
to find out that no-one needs it?)...

> 
> -- 
> Mantas Mikulėnas

Re: [systemd-devel] Q: "systemd[1]: var-tmp-AP_0x6tWaHS.mount: Succeeded."

[Mantas Mikulėnas]

On Fri, Jan 28, 2022 at 10:50 AM Ulrich Windl <
ulrich.wi...@rz.uni-regensburg.de> wrote:

> Hi!
>
> When upgrading SLES15 to SP3, a newer version of systemd was installed
> (246.16+suse.191.g3850086c65).
> Since then I see new journal messages like these that I cannot associate
> with a unit:
>
> Jan 27 09:29:30 h16 systemd[1]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
> Jan 27 09:29:30 h16 systemd[22591]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
>
> Where do these messages originate from, and couldn't they be improved? Or
> is it some debug-leftover?
> I do not see corresponding names in /var/tmp.
>

If I understand correctly, the messages indicate that the filesystem was
*unmounted*, and the same program which did mounting/unmounting immediately
cleaned up the mountpoint as well.

(systemd reacts to external mounts as those also contribute to
dependencies.)

If OpenSuSE has the kernel audit subsystem enabled, try using `auditctl` to
monitor a) what process executes mount-related syscalls, b) what process
creates directories under /var/tmp.

-- 
Mantas Mikulėnas

[systemd-devel] Q: "systemd[1]: var-tmp-AP_0x6tWaHS.mount: Succeeded."

[Ulrich Windl]

Hi!

When upgrading SLES15 to SP3, a newer version of systemd was installed 
(246.16+suse.191.g3850086c65).
Since then I see new journal messages like these that I cannot associate with a 
unit:

Jan 27 09:29:30 h16 systemd[1]: var-tmp-AP_0xC5KDJP.mount: Succeeded.
Jan 27 09:29:30 h16 systemd[22591]: var-tmp-AP_0xC5KDJP.mount: Succeeded.

Where do these messages originate from, and couldn't they be improved? Or is it 
some debug-leftover?
I do not see corresponding names in /var/tmp.

Regards,
Ulrich