[systemd-devel] systemd tries to terminate a process that seems to have exited

Tue May 10 05:44:27 UTC 2022

The one that produces the messages is 249.11 (that is running in a
docker container):

https://packages.ubuntu.com/jammy/systemd

The one running on the host is 215-17 (Debian 8).

> But it sounds like systemd issue in one specific version you are using.

On hosts with newer Debians the issue doesn't manifest itself (the
systemd version inside docker remains the same). I'm trying to figure
out what exactly is happening on Debian 8. If not a systemd issue...
The things that come to mind are: a) the process is waiting to release
some resources after exit() or return from main(), b) something PAM-
or dbus-related, c) some threads that don't let it exit. Not a C
programmer to know if those are possible (if something can not let a
process terminate after exit() or return from main()).

On Tue, May 10, 2022 at 8:09 AM Andrei Borzenkov <arvidjaar at gmail.com> wrote:
>
> On 09.05.2022 23:43, Yuri Kanivetsky wrote:
> > Hi Andrei,
> >
> > Thanks for the suggestion. It becomes more verbose, but it still seems
> > like `systemd` fails to notice that `gnome-keyring` exited:
> >
>
> Probably
>
> ...
>
> >
> > The child exits:
> >
> >     May 09 17:52:47 cb6d1c84f84e gnome-keyring-daemon[314]: -- main:
> > return 0, gkd-main.c:1210
> >     May 09 17:52:47 cb6d1c84f84e gnome-keyring-d[314]: -- main: return
> > 0, gkd-main.c:1210
> >     May 09 17:52:47 cb6d1c84f84e systemd[106]: Child 314
> > (gnome-keyring-d) died (code=exited, status=0/SUCCESS)
> >     May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
> > Child 314 belongs to gnome-keyring.service.
> >     May 09 17:52:47 cb6d1c84f84e systemd[106]: Received SIGCHLD from
> > PID 314 (n/a).
>
> What I miss is "cgroup is empty" message. For comparison:
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: Received SIGCHLD from
> PID 73346 (sleep).
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: Child 73346 (sleep)
> died (code=exited, status=0/SUCCESS)
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: oneshot.service: Child
> 73346 belongs to oneshot.service.
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: oneshot.service:
> Control group is empty.
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: oneshot.service:
> Succeeded.
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: oneshot.service:
> Service will not restart (restart setting)
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: oneshot.service:
> Changed stop-sigterm -> dead
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: oneshot.service: Job
> 986 oneshot.service/start finished, result=done
>
> May 10 07:56:16 bor-Latitude-E5450 systemd[1593]: Finished test oneshot
> forking service.
>
>
> You never mentioned your systemd version so it is hard to say anything.
> But it sounds like systemd issue in one specific version you are using.
>
> >
> > The org.freedesktop.secrets service is activated:
> >
> >     May 09 17:52:47 cb6d1c84f84e dbus-daemon[124]: [session uid=1000
> > pid=124] Activating service name='org.freedesktop.secrets' requested
> > by ':1.16' (uid=1000 pid=243 comm="/usr/libexec/xdg-desktop-portal ")
> >     May 09 17:52:47 cb6d1c84f84e gnome-keyring-d[348]: -- main: gkd-main.c:1046
> >     May 09 17:52:47 cb6d1c84f84e org.freedesktop.secrets[348]:
> > gnome-keyring-daemon: no process capabilities, insecure memory might
> > get used
> >     May 09 17:52:47 cb6d1c84f84e gnome-keyring-daemon[348]: couldn't
> > access control socket: /run/user/1000/keyring/control: No such file or
> > directory
> >     May 09 17:52:47 cb6d1c84f84e gnome-keyring-d[348]: couldn't access
> > control socket: /run/user/1000/keyring/control: No such file or
> > directory
> >     May 09 17:52:47 cb6d1c84f84e dbus-daemon[124]: [session uid=1000
> > pid=124] Successfully activated service 'org.freedesktop.secrets'
> >
> > The gnome-keyring service times out:
> >
> >     May 09 17:54:17 cb6d1c84f84e systemd[106]: gnome-keyring.service:
> > State 'stop-sigterm' timed out. Killing.
> >     May 09 17:54:17 cb6d1c84f84e systemd[106]: gnome-keyring.service:
> > Failed with result 'timeout'.
> >     May 09 17:54:17 cb6d1c84f84e systemd[106]: gnome-keyring.service:
> > Service will not restart (restart setting)
> >     May 09 17:54:17 cb6d1c84f84e systemd[106]: gnome-keyring.service:
> > Changed stop-sigterm -> failed
> >     May 09 17:54:17 cb6d1c84f84e systemd[106]: gnome-keyring.service:
> > Job 167 gnome-keyring.service/start finished, result=failed
> >     May 09 17:54:17 cb6d1c84f84e systemd[106]: Failed to start Start
> > gnome-keyring for the Secrets Service, and PKCS #11.
> >     May 09 17:54:17 cb6d1c84f84e systemd[106]: gnome-keyring.service:
> > Unit entered failed state.
> >
> > More info here:
> >
> > https://gist.github.com/x-yuri/b12e8178a621372a4aa62c60693af37b#file-b-journal-gnome-keyring-gist-md
> >
> > Do you know any reason a process can remain alive after exit() or
> > return from main()? Any threads started by PAM or anything
> > dbus-related (wild guesses on my part)? Anything else I can check?
> >
> > Regards,
> > Yuri
> >
> > On Thu, May 5, 2022 at 8:19 AM Andrei Borzenkov <arvidjaar at gmail.com> wrote:
> >>
> >> On 05.05.2022 04:41, Yuri Kanivetsky wrote:
> >>> Hi,
> >>>
> >>> This might be not a systemd issue. But the behavior is weird, and I'm not sure.
> >>>
> >>> I'm trying to run GNOME in a docker container. And gnome-keyring fails to start:
> >>>
> >>> https://gist.github.com/x-yuri/c3c715ea6355633de4546ae957a66410
> >>>
> >>> I added debug statements, and in the log I see:
> >>>
> >>>     May 02 05:09:02 ab6aaba04124 systemd[109]: Starting Start
> >>> gnome-keyring for the Secrets Service, and PKCS #11...
> >>>     May 02 05:09:02 ab6aaba04124 gnome-keyring-d[309]: -- main: 1046
> >>>     May 02 05:09:02 ab6aaba04124 gnome-keyring-daemon[309]:
> >>> gnome-keyring-daemon: no process capabilities, insecure memory might
> >>> get used
> >>>     May 02 05:09:02 ab6aaba04124 gnome-keyring-daemon[309]: --
> >>> fork_and_print_environment: fork(), parent, 653
> >>>     May 02 05:09:02 ab6aaba04124 gnome-keyring-daemon[321]: --
> >>> fork_and_print_environment: fork(), child, 684
> >>>     May 02 05:09:02 ab6aaba04124 gnome-keyring-daemon[321]: couldn't
> >>> access control socket: /run/user/1000/keyring/control: No such file or
> >>> directory
> >>>     May 02 05:09:02 ab6aaba04124 gnome-keyring-daemon[309]: --
> >>> fork_and_print_environment: exit(0), 680
> >>>     May 02 05:09:02 ab6aaba04124 gnome-keyring-daemon[321]: -- main:
> >>> return 0, 1210
> >>>     May 02 05:10:32 ab6aaba04124 systemd[109]: gnome-keyring.service:
> >>> State 'stop-sigterm' timed out. Killing.
> >>>     May 02 05:10:32 ab6aaba04124 systemd[109]: gnome-keyring.service:
> >>> Failed with result 'timeout'.
> >>>     May 02 05:10:32 ab6aaba04124 systemd[109]: Failed to start Start
> >>> gnome-keyring for the Secrets Service, and PKCS #11.
> >>>
> >> ...
> >>>
> >>> I can only reproduce it on Debian 8. Which kind of makes it
> >>> unimportant. But the behavior is so weird (either gnome-keyring is
> >>> blocked in/after exit(), or systemd tries to kill a process that
> >>> exited), that I can't help but think about what is really going on
> >>> there.
> >>>
> >>
> >>
> >> So run systemd user instance with debug level logging to see which
> >> process are still left.
>