2

We have a systemd service unit that starts a third-party agent; call it "service c". The service unit functions correctly -- at least, as far as I can tell! After a patching cycle, systemd starts this service unit (as expected) but then it turns around and stops the service unit about two seconds after it successfully started it. I have every reason to believe that the service started successfully the first time. When I log in after the reboot, I can see that the service is indeed not running; at that point, I can start the service unit manually (systemctl start service-c) and it starts the service as expected.

I would like to find out why systemd thinks it should be stopping the service unit. What can I configure or enable to determine why systemd took the "stop" action?

I am aware of the systemd LogLevel option and have already set it to "debug", up from the default of "info".

A similar idea is to set Environment=SYSTEMD_LOG_LEVEL=debug in the service unit file, but I don't particularly need the service debugged, but rather systemd itself.

The service unit configuration is:

# /etc/systemd/system/service-c.service
[Unit]
Description=service c
After=network-online.target local-fs.target

[Service]
Type=forking
ExecStart=/local-path/start.service-c
ExecStop=/local-path/stop.service-c
Restart=on-failure

[Install]
WantedBy=multi-user.target

... and the evidence is:

$ systemctl status service-c
● service-c.service - service c
   Loaded: loaded (/etc/systemd/system/service-c.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Wed 2021-04-07 17:49:30 EDT; 14h ago
  Process: 3162 ExecStop=/local-path/stop.service-c (code=exited, status=0/SUCCESS)
  Process: 1319 ExecStart=/local-path/start.service-c (code=exited, status=0/SUCCESS)
 Main PID: 1478 (code=exited, status=0/SUCCESS)

/local-path is an obfuscated version of a local directory on the system.

Since this has been an ongoing issue, after the last reboot I instrumented the "stop" wrapper script to log the process parent tree (using pstree -a -A -l -p -s $$)); that log file shows:

04/07/2021 17:49:19  stop.service-c:  
systemd,1 --switched-root --system --deserialize 22
  `-stop.service-c,3162 /local-path/stop.service-c
      `-pstree,3178 -a -A -l -p -s 3162

... where PID 3162 corresponds to systemd's invocation of the stop script. This looks to me like systemd is calling the ExecStop for the service.

systemd stops this service about two seconds after it has finished starting; the agent's log file has these timestamps:

04/07/2021 17:49:12  start.service-c:  Starting agent
04/07/2021 17:49:17  start.service-c:  startup success
04/07/2021 17:49:19  stop.service-c:  Executing from /agent/home as user

... ending in ...

04/07/2021 17:49:30  stop.service-c:  Finished with RC=0

... which corresponds to systemd's 17:49:30 timestamp for being "dead".

The "Restart=on-failure" directive would restart the service, but systemd tells me that the service started successfully:

Apr 07 17:49:10 hostname systemd[1]: Starting service c...
Apr 07 17:49:17 hostname systemd[1]: Started service c.

Since the service started cleanly, and since there's no attempt made by systemd to restart the service, I don't think the Restart parameter is coming into play.

Perhaps interesting, there's no corresponding "Stopping service c..." log from journalctl (as there is when I manually stop the service), yet evidence points to systemd calling the ExecStop.

I am currently running systemd 219.

11
  • Read man journalctl. You can extract log entries for service-c, systemd, ...
    – waltinator
    Apr 8, 2021 at 17:47
  • @waltinator - I've checked the journalctl logs and there's no explanation for why systemd thinks it should be stopping the service, only that it is. The journal logs for the service show that it's being started and stopped in correlation with systemd's view. The pertinent journalctl logs are in the question.
    – Jeff Schaller
    Apr 8, 2021 at 17:48
  • I don't know if it's useful, but I just noticed a lack of a "Stopping service c..." message in the journal. I've edited the question with that information.
    – Jeff Schaller
    Apr 8, 2021 at 18:02
  • Seems like an odd path: ExecStart=/local-path/start.service-c. Is there directory with the path /local-path? Apr 9, 2021 at 6:39
  • 1
    @JeffSchaller Careful that as a safety measure ExecStop is run when the main process exits regularly too. So to me all (including the lack of stopping msg) seems normal behavior for when a service ends spontaneously. Perhaps after the patch now your ExecStart command "double-fork(2)"s and the first fork, the one that counts for systemd, exits 0 by its own accord. As to why it would rather stay up when you start it manually I wouldn't know. Maybe at boot time something's missing for your agent, but that "something" comes up later on before you get a chance to start the service manually?
    – LL3
    Apr 9, 2021 at 18:52

1 Answer 1

2

I would like to find out why systemd thinks it should be stopping the service unit. What can I configure or enable to determine why systemd took the "stop" action?

In order to see the live-state of a service you can:

  • Use a systemd-cgls -l <service-cgroup-path> command: there you will see all the services's processes as they are at that moment. The service's cgroup path can be retrieved with systemctl show -p ControlGroup <service-name> command. In more recent versions of systemd (not in v219) you may also use the convenient -u <service-name> option of systemd-cgls in place of the service's cgroup path
  • For detailed insight you may use the very verbose systemctl show <service-name> command: this will give loads of info regarding the service state as known by systemd, and from that info you can try to infer in more detail what is happening

To investigate the "suspect stop" case, it is correct to add those commands as ExecStop commands. You can simply add them at the beginning of your own stop.service-c script (if it is indeed a script).

Or alternatively you can add them as additional ExecStop commands on their own before your stop.service-c command, as in:

[Service]
Type=forking
ExecStart=/local-path/start.service-c
ExecStop=-/bin/sh -c 'systemd-cgls -l -u %n && systemctl show %n'
ExecStop=/local-path/stop.service-c
Restart=on-failure

Note that the %n specifier is correctly handled by systemd also when it occurs within quoted strings.

Alternatively you can also:

[Service]
Type=forking
ExecStart=/local-path/start.service-c
ExecStop=-/usr/bin/systemd-cgls -l -u %n
ExecStop=-/bin/systemctl show %n
ExecStop=/local-path/stop.service-c
Restart=on-failure

Note also the - prefixing the commands so as to ignore their exit status, just in case they failed for unfathomable reasons.

Naturally you might also use them as ExecStartPost commands, so as to ponder the live-state immediately after the service is considered "successfully started" by systemd. (again make to ignore their exit status or systemd will tear down the entire service if they fail).

With regard to systemd-cgls's output run as ExecStop command, you should note whether the MainPID process still shows up at that time: if it does show up, then it proves that ExecStop really has been performed autonomously by systemd as you suggest. Else (if the MainPID process is not present in systemd-cgls's output at "stop" time) it means that ExecStop has been run as a result of the MainPID process exiting on its own accord. (See further below for additional reasoning). You might also want to pay attention to the PID numbers of the service's processes together with the PID numbers of the (now dead) ExecStart command to try and infer what fork(2)-ing has been going on since the service start and all along, because that is very relevant for a type=forking service in order to assess whether it is well-behaved. (See further below for additional reasoning).

With regard to systemctl show's output run as ExecStop command , I would say that the most relevant properties to pay attention to in your particular case are:

  • MainPID: reads 0 if the service's main process has exited on its own accord, else reads the service's main process's PID if it is still alive and thus is indeed being stopped by systemd
  • ExecMainExitTimestamp: reads the exit time in date format if the service's main process has exited on its own accord, else does not read at all if the process is still alive and thus is indeed being stopped by systemd
  • ExecMainExitTimestampMonotonic: as above but reads in Linux's monotonic clock and reads 0 if the process is still alive
  • ExecMainCode: this corresponds to the code= string in systemctl status1, only it reports the decimal value of the CLD_* symbols instead of their translations into english words: according to Linux's current values for CLD_* symbols (which is an enum starting from 1), the ExecMainCode field reads 0 if the process is still alive and thus is indeed about to be stopped by systemd, else reads 1 if the process has already _exit(2)-ed on its own accord, 2 if it has been kill(2)-ed (in this use case clearly not by systemd), and so on

Note however that the above fields do not correspond to the service's current state if systemd was unable to detect the service's main process at the time of service start. (see below for explanations). They would rather correspond to the most recent run for which systemd was able to accomplish the detection fully.


Further insights

In your reasoning I can see two key points that worth extra clarification:

type=forking services

type=forking services are particularly tricky for systemd, especially when using GuessMainPID=yes (the default, therefore what you're currently using for your agent). For these service types the ExecStart command is expected to fork(2) itself once and then exit while its forked process is expected to live long and prosper as the MainPID of the service. Else:

  1. If such forked process rather forks again and then exits as well, delegating to its own "secondly" forked process(es) the responsibility to function as the actual service, GuessMainPID simply loses track and systemd simply believes the service has finished regularly and spontaneously, and thus accomplishes the duty of cleaning everything (i.e. run ExecStop etc.) but without logging the Stopping service... message because, as far as systemd is concerned, it only reacted to the service's deliberate exit
  2. If instead the ExecStart original process fork(2)s twice (or more) before exiting, then GuessMainPID surrenders and systemd restrains from tearing everything down when the ExecStart original process finally exits. This is a better case because the service's actual processes survive, but it is not yet ideal because then systemd won't keep full track of events either, thus leading to e.g. inconsistent/incomplete journal logs at the least.

ExecStop execution

The ExecStop commands are run also when the MainPID process exits successfully on its own accord, as long as the main process had also started successfully (which is your case at hand). I understand that it seems counterintuitive but that is simply normal behavior by systemd: it simply deems a service's ExecStop command the preferred way to clean after that service, prior to resort to (by default, see systemd.kill(5)) sending a SIGTERM first and possibly a SIGKILL afterwards.

It doesn't say it so explicitly anywhere in the systemd.service(5) manpage, but it can be inferred by a few bits and pieces of documentation, especially those regarding the environment variables available to the Exec* commands. See the $SERVICE_RESULT, $EXIT_CODE and $EXIT_STATUS variables as to what values they can take, what semantic significance they have, and the fact that they are made available precisely to the ExecStop as well as the ExecStopPost commands.

Apart from non-explicit (or personal interpretation of the) documentation, let's look at the sources that perform that behavior. Taken from v219, here is service_sigchld_event() invoking service_enter_running() on an event referring to a child that is known to be in "running" state, and then the latter function invoking the service_enter_stop() "stopping" action in all cases except for when RemainAfterExit=yes or type=dbus or the service's main process has not been detected (see type=forking explanation above) or the control-group is not healthy.

As to why the systemd people decided to do so I wouldn't know as I am not a systemd developer, but I can see the usefulness of this behavior so as to give to all still alive-yet-"unknown" processes of a service their chance to be notified about their imminent termination in the nicest possible way, before getting a harsh SIGTERM and SIGKILL as per systemd's last resort as it proceeds to close the whole control-group. This measure is particularly useful precisely for type=forking services because those are the most difficult for systemd to track down correctly, as explained in the type= paragraph of systemd.service(5), and because systemd tries to clean after legacy/lazy/poorly-implemented services that don't close gracefully before exiting.

HTH


1. code= followed by a word representing the "exit reason" of the process: whether it exited or has been killed or trapped or even dumped; in practice: literally a word translating the various CLD_* values valid for the siginfo_t.si_code field as described in sigaction(2)

4
  • This is helpful information; thank you! I'm going to instrument the unit file with the ExecStop and ExecStartPost suggestions. Hopefully that answers the question at-hand. I have trouble believing that systemd silently stopped the service with no (logging) mention of "Stopping service-c...", but that certainly seems to be the evidence at this point. I will dig into the source code to see if that's a possibility.
    – Jeff Schaller
    Apr 12, 2021 at 18:01
  • @JeffSchaller I didn't want to be too bold in the answer but I'm rather convinced that it's the other way around, as I had also hinted in my comment to your question: systemd ran ExecStop as a consequence of the MainPID process exiting spontaneously. IOW systemd did not stop the service, but it ran ExecStop simply for "after-exit", extra-cleaning, purposes as per its normal (yet under-documented) behavior. In those cases systemd does not log any "Stopping.." message. Please feel free to edit my answer if you see fit to make anything clearer (I'm also not native english speaker)
    – LL3
    Apr 12, 2021 at 18:24
  • I'm happy to be wrong! :) I just wanted to get some evidence to make the situation clearer. I like your theory that the MainPID exited cleanly, causing systemd to call ExecStop; I haven't seen this agent (or its wrapper script) do such a thing, but perhaps there's something else going on.
    – Jeff Schaller
    Apr 12, 2021 at 18:39
  • @JeffSchaller Certainly! It's absolutely fair wishing to have more insight on the live situation so as to see it actually happening. Besides, I can't be totally sure either, because the thing that if you start the service manually then it stays up defies my theory completely.
    – LL3
    Apr 12, 2021 at 18:50

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.