[systemd-devel] systemctl reboot get terminated by signal 15

[Pengpeng Sun]

Hi there,

Our program executes 'systemctl reboot' in a child process to reboot Linux right after its booted, Sometimes there is no error, but sometimes the child process terminated due to received uncaught signal 15, then no reboot happened. WIFSIGNALED evaluated a non-zero value, WTERMSIG evaluated 15. Don't understand why the uncaught signal 15 happened here, could you please shed light on this, Thanks.

--
Best regards,
Pengpeng

[Lennart Poettering]

On Mo, 19.04.21 14:29, Pengpeng Sun (***@vmware.com) wrote:

> Hi there,
>
> Our program executes 'systemctl reboot' in a child process to reboot
> Linux right after its booted, Sometimes there is no error, but
> sometimes the child process terminated due to received uncaught
> signal 15, then no reboot happened. WIFSIGNALED evaluated a non-zero
> value, WTERMSIG evaluated 15. Don't understand why the uncaught
> signal 15 happened here, could you please shed light on this,
> Thanks.

15 is SIGTERM, i.e. the signal sent when a process is politely asked
to shut down. Something is terminating your process.

It could be systemd, could be something else.

To track down what it is, maybe turn on debug logging in systemd, maybe
you find the explanation there. i.e. "systemd-analyze log-level debug"
and then reproduce the issue.

ALternatively, install a signal handler for SIGTERM via sigaction, and
look into the .si_pid field of the siginfo_t you can receive in the
handler. It tells you which processes sent the SIGTERM.

Lennart

--
Lennart Poettering, Berlin

[Pengpeng Sun]

Thanks Lennart!
I reproduced the issue after set "systemd-analyze log-level debug". It turns out 'systemctl reboot' triggered before all the steps logged in 'journalctl -a'. But I did get the stderr of 'systemctl reboot', paste it as below, please check if it helps to locate the root cause.
And besides 'journalctl -a', where can I get the systemd debug logs?

stderr: Bus n/a: changing state UNSET → OPENING
Bus n/a: changing state OPENING → AUTHENTICATING
Executing dbus call org.freedesktop.systemd1.Manager StartUnit(reboot.target, replace-irreversibly)
Bus n/a: changing state AUTHENTICATING → RUNNING
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=5 reply_cookie=1 signature=o error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a

--
Best regards,
Pengpeng

On 2021/4/19, 10:37 PM, "Lennart Poettering" <***@poettering.net> wrote:

On Mo, 19.04.21 14:29, Pengpeng Sun (***@vmware.com) wrote:

> Hi there,
>
> Our program executes 'systemctl reboot' in a child process to reboot
> Linux right after its booted, Sometimes there is no error, but
> sometimes the child process terminated due to received uncaught
> signal 15, then no reboot happened. WIFSIGNALED evaluated a non-zero
> value, WTERMSIG evaluated 15. Don't understand why the uncaught
> signal 15 happened here, could you please shed light on this,
> Thanks.

15 is SIGTERM, i.e. the signal sent when a process is politely asked
to shut down. Something is terminating your process.

It could be systemd, could be something else.

To track down what it is, maybe turn on debug logging in systemd, maybe
you find the explanation there. i.e. "systemd-analyze log-level debug"
and then reproduce the issue.

ALternatively, install a signal handler for SIGTERM via sigaction, and
look into the .si_pid field of the siginfo_t you can receive in the
handler. It tells you which processes sent the SIGTERM.

Lennart

--
Lennart Poettering, Berlin

[Pengpeng Sun]

Hi Lennart,

After installed a signal handler for SIGTERM and reproduced the issue, got si_pid is 1 which is systemd.

Also paste the stderr here:
stderr: 'Bus n/a: changing state UNSET → OPENING
Bus n/a: changing state OPENING → AUTHENTICATING
Executing dbus call org.freedesktop.systemd1.Manager StartUnit(reboot.target, replace-irreversibly)
Bus n/a: changing state AUTHENTICATING → RUNNING
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=5 reply_cookie=1 signature=o error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=131 reply_cookie=2 signature=o error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/reboot_2etarget interface=org.freedesktop.DBus.Properties member=Get cookie=3 reply_cookie=0 signature=ss error-name=n/a error-message=n/a

What make systemd triggered SIGTERM when calling 'systemd reboot'?

--
Best regards,
Pengpeng

On 2021/4/21, 12:48 AM, "Pengpeng Sun" <***@vmware.com> wrote:

Thanks Lennart!
I reproduced the issue after set "systemd-analyze log-level debug". It turns out 'systemctl reboot' triggered before all the steps logged in 'journalctl -a'. But I did get the stderr of 'systemctl reboot', paste it as below, please check if it helps to locate the root cause.
And besides 'journalctl -a', where can I get the systemd debug logs?

stderr: Bus n/a: changing state UNSET → OPENING
Bus n/a: changing state OPENING → AUTHENTICATING
Executing dbus call org.freedesktop.systemd1.Manager StartUnit(reboot.target, replace-irreversibly)
Bus n/a: changing state AUTHENTICATING → RUNNING
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=5 reply_cookie=1 signature=o error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a

--
Best regards,
Pengpeng

On 2021/4/19, 10:37 PM, "Lennart Poettering" <***@poettering.net> wrote:

On Mo, 19.04.21 14:29, Pengpeng Sun (***@vmware.com) wrote:

> Hi there,
>
> Our program executes 'systemctl reboot' in a child process to reboot
> Linux right after its booted, Sometimes there is no error, but
> sometimes the child process terminated due to received uncaught
> signal 15, then no reboot happened. WIFSIGNALED evaluated a non-zero
> value, WTERMSIG evaluated 15. Don't understand why the uncaught
> signal 15 happened here, could you please shed light on this,
> Thanks.

15 is SIGTERM, i.e. the signal sent when a process is politely asked
to shut down. Something is terminating your process.

It could be systemd, could be something else.

To track down what it is, maybe turn on debug logging in systemd, maybe
you find the explanation there. i.e. "systemd-analyze log-level debug"
and then reproduce the issue.

ALternatively, install a signal handler for SIGTERM via sigaction, and
look into the .si_pid field of the siginfo_t you can receive in the
handler. It tells you which processes sent the SIGTERM.

Lennart

--
Lennart Poettering, Berlin

[Lennart Poettering]

On Di, 20.04.21 16:48, Pengpeng Sun (***@vmware.com) wrote:

> Thanks Lennart!
> I reproduced the issue after set "systemd-analyze log-level debug". It turns out 'systemctl reboot' triggered before all the steps logged in 'journalctl -a'. But I did get the stderr of 'systemctl reboot', paste it as below, please check if it helps to locate the root cause.
> And besides 'journalctl -a', where can I get the systemd debug logs?
>
> stderr: Bus n/a: changing state UNSET → OPENING
> Bus n/a: changing state OPENING → AUTHENTICATING
> Executing dbus call org.freedesktop.systemd1.Manager StartUnit(reboot.target, replace-irreversibly)
> Bus n/a: changing state AUTHENTICATING → RUNNING
> Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
> Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=5 reply_cookie=1 signature=o error-name=n/a error-message=n/a
> Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a

That looks like the debug log of systemctl on the client side? I was
more interested int the logs of systemd, i.e. of PID 1.

Lennart

--
Lennart Poettering, Berlin

[Pengpeng Sun]

Hi Lennart,

The issue reproduced at 2021-04-22T15:45:30.230Z, I ran 'sudo journalctl -b', the log began at Apr 22 15:45:48 which is later than the issue reproduced.
How can I get more early and detailed systemd log?

--
Best regards,
Pengpeng

On 2021/4/23, 4:01 PM, "Lennart Poettering" <***@poettering.net> wrote:

On Di, 20.04.21 16:48, Pengpeng Sun (***@vmware.com) wrote:

> Thanks Lennart!
> I reproduced the issue after set "systemd-analyze log-level debug". It turns out 'systemctl reboot' triggered before all the steps logged in 'journalctl -a'. But I did get the stderr of 'systemctl reboot', paste it as below, please check if it helps to locate the root cause.
> And besides 'journalctl -a', where can I get the systemd debug logs?
>
> stderr: Bus n/a: changing state UNSET → OPENING
> Bus n/a: changing state OPENING → AUTHENTICATING
> Executing dbus call org.freedesktop.systemd1.Manager StartUnit(reboot.target, replace-irreversibly)
> Bus n/a: changing state AUTHENTICATING → RUNNING
> Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=StartUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
> Got message type=method_return sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=5 reply_cookie=1 signature=o error-name=n/a error-message=n/a
> Sent message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=GetUnit cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a

That looks like the debug log of systemctl on the client side? I was
more interested int the logs of systemd, i.e. of PID 1.

Lennart

--
Lennart Poettering, Berlin

[Lennart Poettering]

On Fr, 23.04.21 14:15, Pengpeng Sun (***@vmware.com) wrote:

> Hi Lennart,
>
> The issue reproduced at 2021-04-22T15:45:30.230Z, I ran 'sudo journalctl -b', the log began at Apr 22 15:45:48 which is later than the issue reproduced.
> How can I get more early and detailed systemd log?

man 5 journald.conf

Maybe your distro didn't enable persistent storage of journald, and
thus journald uses only in-memory storage in /run, and is thus
constrained by its diminutive size?

Lennart

--
Lennart Poettering, Berlin

[Pengpeng Sun]

Forgot to mention: Here I called '/sbin/telinit 6' to reboot, '/sbin/telinit' is a softlink to '/bin/systemctl' in RHEL8.0. And the issue also reproduced if I call '/bin/systemctl reboot' directly.

--
Best regards,
Pengpeng

On 2021/4/25, 3:09 PM, "Pengpeng Sun" <***@vmware.com> wrote:

Hi Lennart,

After modify journald.conf, got systemd log when the issue reproduced. Please find it in attachment.

The issue reproduced at 2021-04-25T04:58:50, please help to review the systemd log around the same time.
[2021-04-25T04:58:50.757Z] [ debug] Command to exec : '/sbin/telinit'.
[2021-04-25T04:58:50.999Z] [ info] Sending PID: 1, UID: 0
[2021-04-25T04:58:51.101Z] [ error] Process exited abnormally after 0 sec, uncaught signal 15


--
Best regards,
Pengpeng

On 2021/4/24, 3:33 AM, "Lennart Poettering" <***@poettering.net> wrote:

On Fr, 23.04.21 14:15, Pengpeng Sun (***@vmware.com) wrote:

> Hi Lennart,
>
> The issue reproduced at 2021-04-22T15:45:30.230Z, I ran 'sudo journalctl -b', the log began at Apr 22 15:45:48 which is later than the issue reproduced.
> How can I get more early and detailed systemd log?

man 5 journald.conf

Maybe your distro didn't enable persistent storage of journald, and
thus journald uses only in-memory storage in /run, and is thus
constrained by its diminutive size?

Lennart

--
Lennart Poettering, Berlin

[Pengpeng Sun]

It seems the attachment is bigger than 500KB, so it has been cancelled.
So I copied the logs from 2021-04-25T04:58:50 to 2021-04-25T04:58:51 to a smaller attachment again.


--
Best regards,
Pengpeng

On 2021/4/25, 3:12 PM, "Pengpeng Sun" <***@vmware.com> wrote:

Forgot to mention: Here I called '/sbin/telinit 6' to reboot, '/sbin/telinit' is a softlink to '/bin/systemctl' in RHEL8.0. And the issue also reproduced if I call '/bin/systemctl reboot' directly.

--
Best regards,
Pengpeng

On 2021/4/25, 3:09 PM, "Pengpeng Sun" <***@vmware.com> wrote:

Hi Lennart,

After modify journald.conf, got systemd log when the issue reproduced. Please find it in attachment.

The issue reproduced at 2021-04-25T04:58:50, please help to review the systemd log around the same time.
[2021-04-25T04:58:50.757Z] [ debug] Command to exec : '/sbin/telinit'.
[2021-04-25T04:58:50.999Z] [ info] Sending PID: 1, UID: 0
[2021-04-25T04:58:51.101Z] [ error] Process exited abnormally after 0 sec, uncaught signal 15


--
Best regards,
Pengpeng

On 2021/4/24, 3:33 AM, "Lennart Poettering" <***@poettering.net> wrote:

On Fr, 23.04.21 14:15, Pengpeng Sun (***@vmware.com) wrote:

> Hi Lennart,
>
> The issue reproduced at 2021-04-22T15:45:30.230Z, I ran 'sudo journalctl -b', the log began at Apr 22 15:45:48 which is later than the issue reproduced.
> How can I get more early and detailed systemd log?

man 5 journald.conf

Maybe your distro didn't enable persistent storage of journald, and
thus journald uses only in-memory storage in /run, and is thus
constrained by its diminutive size?

Lennart

--
Lennart Poettering, Berlin

[Ulrich Windl]

>>> Lennart Poettering <***@poettering.net> schrieb am 23.04.2021 um 21:33
in
Nachricht <YIMhEqF2jKtF+***@gardel-login>:
> On Fr, 23.04.21 14:15, Pengpeng Sun (***@vmware.com) wrote:
>
>> Hi Lennart,
>>
>> The issue reproduced at 2021‑04‑22T15:45:30.230Z, I ran 'sudo journalctl
‑b',
> the log began at Apr 22 15:45:48 which is later than the issue reproduced.
>> How can I get more early and detailed systemd log?
>
> man 5 journald.conf
>
> Maybe your distro didn't enable persistent storage of journald, and
> thus journald uses only in‑memory storage in /run, and is thus
> constrained by its diminutive size?

In SLES it seems to be just "mkdir /var/log/journal" and restarting journald.

>
> Lennart
>
> ‑‑
> Lennart Poettering, Berlin
> _______________________________________________
> systemd‑devel mailing list
> systemd‑***@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/systemd‑devel

[Lennart Poettering]

On So, 25.04.21 07:09, Pengpeng Sun (***@vmware.com) wrote:

> Hi Lennart,
>
> After modify journald.conf, got systemd log when the issue reproduced. Please find it in attachment.

Looking at the logs there seems to be a lot missing, in particular all
the debug output of PID 1 is eventually going away.

My educated guess: you are runnning "systemctl reboot" from user
context? i.e. some script you run as part of your user sesion? If so,
when the system goes down your user session of course will be
terminated. Thus it's a race: either your session (and its associated
services) are terminated via SIGTERM first, including the systemctl
command you issued, or the systemctl is quicker and exits before it
gets killed.

The net effect is the same: before we go down we need to terminate all
processes, of course. And user processes are terminated before sytem
processes, of course.

Lennart

--
Lennart Poettering, Berlin

[Pengpeng Sun]

> > Hi Lennart,
> >
> > After modify journald.conf, got systemd log when the issue
> > reproduced. Please find it in attachment.
>
> Looking at the logs there seems to be a lot missing, in particular all
> the debug output of PID 1 is eventually going away.
>
> My educated guess: you are runnning "systemctl reboot" from user
> context? i.e. some script you run as part of your user sesion? If so,
> when the system goes down your user session of course will be
> terminated. Thus it's a race: either your session (and its associated
> services) are terminated via SIGTERM first, including the systemctl
> command you issued, or the systemctl is quicker and exits before it
> gets killed.
>

Here is where our code calls “/sbin/telinit 6” to reboot Linux.
https://github.com/vmware/open-vm-tools/blob/master/open-vm-tools/libDeployPkg/linuxDeployment.c#L1466
This code is executed when systemd vmtoolsd.service starts, attached the
vmtoolsd.service file.
Not seeing this issue before /sbin/telinit becomes a softlink to systemctl.

After I did a small change to let loop continue if the first /sbin/telinit fails,
then I can see only the first iteration /sbin/telinit got uncaught signal 15,
the second, the third iterations /sbin/telinit exit code is 0, no errors.
It seems our session is not terminated when SIGTERM received,
or systemctl is quicker and exits, but how could the latter iterations got
no errors.
> The net effect is the same: before we go down we need to terminate all
> processes, of course. And user processes are terminated before sytem
> processes, of course.



>
> Lennart
>
> --
> Lennart Poettering, Berlin

[Lennart Poettering]

On Do, 29.04.21 16:55, Pengpeng Sun (***@vmware.com) wrote:

> > > Hi Lennart,
> > >
> > > After modify journald.conf, got systemd log when the issue
> > > reproduced. Please find it in attachment.
> >
> > Looking at the logs there seems to be a lot missing, in particular all
> > the debug output of PID 1 is eventually going away.
> >
> > My educated guess: you are runnning "systemctl reboot" from user
> > context? i.e. some script you run as part of your user sesion? If so,
> > when the system goes down your user session of course will be
> > terminated. Thus it's a race: either your session (and its associated
> > services) are terminated via SIGTERM first, including the systemctl
> > command you issued, or the systemctl is quicker and exits before it
> > gets killed.
> >
>
> Here is where our code calls “/sbin/telinit 6” to reboot Linux.
> https://github.com/vmware/open-vm-tools/blob/master/open-vm-tools/libDeployPkg/linuxDeployment.c#L1466
> This code is executed when systemd vmtoolsd.service starts, attached the
> vmtoolsd.service file.
> Not seeing this issue before /sbin/telinit becomes a softlink to
> systemctl.

vmtoolsd.service is probably asked to shutdown because of the system
shutdown, and the forked off /sbin/telinit is part of that service, so
it gets terminated too?

Lennart

--
Lennart Poettering, Berlin

[Pengpeng Sun]

> > > > Hi Lennart,
> > > >
> > > > After modify journald.conf, got systemd log when the issue
> > > > reproduced. Please find it in attachment.
> > >
> > > Looking at the logs there seems to be a lot missing, in particular all
> > > the debug output of PID 1 is eventually going away.
> > >
> > > My educated guess: you are runnning "systemctl reboot" from user
> > > context? i.e. some script you run as part of your user sesion? If so,
> > > when the system goes down your user session of course will be
> > > terminated. Thus it's a race: either your session (and its associated
> > > services) are terminated via SIGTERM first, including the systemctl
> > > command you issued, or the systemctl is quicker and exits before it
> > > gets killed.
> > >
> >
> > Here is where our code calls “/sbin/telinit 6” to reboot Linux.
> > https://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fvmware%2Fopen-vm-tools%2Fblob%2Fmaster%2Fopen-vm-tools%2FlibDeployPkg%2FlinuxDeployment.c%23L1466&amp;data=04%7C01%7Cpengpengs%40vmware.com%7C703b24bd11584d4d033d08d90b4a1ad9%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C637553235200829094%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&amp;sdata=DWWAKyPLV6dqnbJ37%2FFVqpAYapYvVC57reiYTSflFH4%3D&amp;reserved=0
> > This code is executed when systemd vmtoolsd.service starts, attached the
> > vmtoolsd.service file.
> > Not seeing this issue before /sbin/telinit becomes a softlink to
> > systemctl.
>
> vmtoolsd.service is probably asked to shutdown because of the system
> shutdown, and the forked off /sbin/telinit is part of that service, so
> it gets terminated too?

Yes, this could be the reason. The issue is system does NOT always reboot after
“uncaught signal 15” happens, while sometimes it does reboot during my local
testing. Is there a way/command to make sure system get rebooted?

[Lennart Poettering]

On Fr, 30.04.21 02:00, Pengpeng Sun (***@vmware.com) wrote:

> > > Here is where our code calls “/sbin/telinit 6” to reboot Linux.
> > > https://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fvmware%2Fopen-vm-tools%2Fblob%2Fmaster%2Fopen-vm-tools%2FlibDeployPkg%2FlinuxDeployment.c%23L1466&amp;data=04%7C01%7Cpengpengs%40vmware.com%7C703b24bd11584d4d033d08d90b4a1ad9%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C637553235200829094%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&amp;sdata=DWWAKyPLV6dqnbJ37%2FFVqpAYapYvVC57reiYTSflFH4%3D&amp;reserved=0
> > > This code is executed when systemd vmtoolsd.service starts, attached the
> > > vmtoolsd.service file.
> > > Not seeing this issue before /sbin/telinit becomes a softlink to
> > > systemctl.
> >
> > vmtoolsd.service is probably asked to shutdown because of the system
> > shutdown, and the forked off /sbin/telinit is part of that service, so
> > it gets terminated too?
>
> Yes, this could be the reason. The issue is system does NOT always reboot after
> “uncaught signal 15” happens, while sometimes it does reboot during my local
> testing. Is there a way/command to make sure system get rebooted?

Check the logs?

https://freedesktop.org/wiki/Software/systemd/Debugging/#index2h1

Lennart

--
Lennart Poettering, Berlin