Re: systemd tries to terminate a process that seems to have exited

[Yuri Kanivetsky <yuri.kanivetsky@xxxxxxxxx>]

Hi Andrei,

Thanks for the suggestion. It becomes more verbose, but it still seems
like `systemd` fails to notice that `gnome-keyring` exited:

    May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
Passing 0 fds to service
    May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
About to execute /usr/local/bin/gnome-keyring-daemon --start
--components pkcs11,secrets
    May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
Forked /usr/local/bin/gnome-keyring-daemon as 310
    May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
Changed dead -> start
    May 09 17:52:47 cb6d1c84f84e systemd[106]: Starting Start
gnome-keyring for the Secrets Service, and PKCS #11...
    May 09 17:52:47 cb6d1c84f84e systemd[310]: Skipping PR_SET_MM, as
we don't have privileges.
    May 09 17:52:47 cb6d1c84f84e systemd[310]: gnome-keyring.service:
Executing: /usr/local/bin/gnome-keyring-daemon --start --components
pkcs11,secrets

The main() starts:

    May 09 17:52:47 cb6d1c84f84e (g-daemon)[310]: -- main: gkd-main.c:1046

A child is forked:

    May 09 17:52:47 cb6d1c84f84e gnome-keyring-daemon[310]: --
fork_and_print_environment: fork(), parent, gkd-main.c:653
    May 09 17:52:47 cb6d1c84f84e (g-daemon)[310]: --
fork_and_print_environment: fork(), parent, gkd-main.c:653
    May 09 17:52:47 cb6d1c84f84e gnome-keyring-daemon[314]: --
fork_and_print_environment: fork(), child, gkd-main.c:684
    May 09 17:52:47 cb6d1c84f84e gnome-keyring-d[314]: --
fork_and_print_environment: fork(), child, gkd-main.c:684

    May 09 17:52:47 cb6d1c84f84e gnome-keyring-daemon[314]: couldn't
access control socket: /run/user/1000/keyring/control: No such file or
directory
    May 09 17:52:47 cb6d1c84f84e gnome-keyring-d[314]: couldn't access
control socket: /run/user/1000/keyring/control: No such file or
directory

The parent exits:

    May 09 17:52:47 cb6d1c84f84e gnome-keyring-daemon[310]: --
fork_and_print_environment: exit(0), gkd-main.c:680
    May 09 17:52:47 cb6d1c84f84e (g-daemon)[310]: --
fork_and_print_environment: exit(0), gkd-main.c:680
    May 09 17:52:47 cb6d1c84f84e systemd[106]: Received SIGCHLD from
PID 310 (gnome-keyring-d).
    May 09 17:52:47 cb6d1c84f84e systemd[106]: Child 310
(gnome-keyring-d) died (code=exited, status=0/SUCCESS)
    May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
Child 310 belongs to gnome-keyring.service.
    May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
Main process exited, code=exited, status=0/SUCCESS (success)
    May 09 17:52:47 cb6d1c84f84e systemd[106]: gnome-keyring.service:
Changed start -> stop-sigterm

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

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@xxxxxxxxx> 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.