Bug 2011459

Description of problem:
Tuned performs a full rollback when it hangs at shutdown

We have profiles modeled against cpu-partitioning, extended to configure cpusets (using the cgconfig service) and isolate the system early at boot using cgroups rather than using isolcpus.
 
Two of our hosts lost all their setting after a week-end reboot. What seemed to happen is that tuned hung during shutdown, and eventually systemd killed it (after exactly 50 seconds). We suspect that upon receiving the SIGTERM tuned performed a full rollback instead of merely dying without undoing non-persistent tuning. Here’s the relevant portion of the tuned log:
 
2021-07-10 22:28:53,554 INFO     tuned.plugins.plugin_bootloader: removing directory '/tmp/tmp.jPMqr1omNZ'
2021-07-10 22:28:53,632 INFO     tuned.daemon.daemon: static tuning from profile 'ms-lc' applied
2021-07-17 22:10:08,675 INFO     tuned.daemon.controller: terminating controller
2021-07-17 22:10:08,676 INFO     tuned.daemon.daemon: stopping tuning
2021-07-17 22:10:58,798 INFO     tuned.daemon.daemon: terminating Tuned, rolling back all changes
2021-07-17 22:10:58,798 INFO     tuned.plugins.plugin_bootloader: removing grub2 tuning previously added by Tuned
2021-07-17 22:10:58,800 INFO     tuned.plugins.plugin_bootloader: removing initrd image '/boot/tuned-initrd.img'
2021-07-17 22:10:58,821 INFO     tuned.plugins.plugin_script: calling script '/usr/lib/tuned/ms-lc/script.sh' with arguments '['stop', 'full_rollback']'
2021-07-17 22:11:23,991 ERROR    tuned.plugins.plugin_script: script '/usr/lib/tuned/ms-lc/script.sh' error output: 'Failed to execute operation: Connection timed out'
2021-07-17 22:11:24,056 INFO     tuned.plugins.plugin_systemd: removing 'CPUAffinity' systemd tuning previously added by Tuned
2021-07-17 22:11:24,057 CONSOLE  tuned.plugins.plugin_systemd: you may need to manualy run 'dracut -f' to update the systemd configuration in initrd image
2021-07-17 22:11:24,063 INFO     tuned.plugins.plugin_cpu: energy_perf_bias successfully set to 'normal' on cpu 'cpu14'
[...]
 
To me it’s clear that in case of a crash/unclean shutdown tuned should not do more than it do on a normal shutdown, and there is no reason for doing a full rollback.

I understand it’s normal for tuned to undo tunings on shutdown, but there are persistent tunings (ex kernel command-line) that just cannot, else you would never have them active when the host boot up, and for that reason there is a concept of “full rollback” that is only executed on profile changes. So when I restart a host those aren’t undone by design too.

The issue appears to be if for some reason tuned hangs on shutdown, and gets SIGTERM’ed by systemctl, it perform a full rollback.

So only in some cases of unclean shutdown tuned will undo the changes that are needed on the next reboot. Also I’m worried the SIGKILL could prevent rollback during profile switch (we write the active_profile file and restart tuned, and were told that it’s a supported way of setting the tuned profile…)


<snip>

I've been having a deeper look at how tuned works and think that my initial suspicion was incorrect and focusing on the script isn't likely going to go anywhere. That said, the error that the rollback is throwing when trying to do so with the script is interesting to me:  'Failed to execute operation: Connection timed out'. I've seen this before in other contexts and it looks like a systemd/DBus error to me and could be suggesting that there's an issue somewhere in the area. Normally a shutdown won't trigger a rollback and doesn't; there are a few things that we check to decide what the shutdown conditions are and whether a rollback is called for:


<snip>
        # if terminating due to profile switch
        if self._terminate_profile_switch.is_set():
            full_rollback = True
        else: 
            # with systemd it detects system shutdown and in such case it doesn't perform
            # full cleanup, if not shutting down it means that Tuned was explicitly
            # stopped by user and in such case do full cleanup, without systemd never
            # do full cleanup
            full_rollback = False
            if self._full_rollback_required():
                if self._daemon:
                    log.info("terminating Tuned, rolling back all changes")
                    full_rollback = True
...
    def _full_rollback_required(self):
        retcode, out = self._cmd.execute(["systemctl", "is-system-running"], no_errors = [0])
        if retcode < 0:
            return False
        if out[:8] == "stopping":
            return False
        retcode, out = self._cmd.execute(["systemctl", "list-jobs"], no_errors = [0])
        return re.search(r"\b(shutdown|reboot|halt|poweroff).target.*start", out) is None
</snip>


Now this is why the "interesting" message above is so to me. If there's something going on with systemd/dbus around this time and our "systemctl" calls in the daemon to decide whether we need to rollback or not don't work correctly then this could go awry. So, it could be a dbus/systemd issue and this is all fallout. I'm not certain on this, but it's plausible. I'm seeing how we could debug this as I've been unable to reproduce thus far, but need to look further.

<snip>

we've modified tuned to capture the extract RC and output of the failing commands, then we were able to reproduce the issue by faking the systemctl commands output.


There are two commands tuned may run in the _full_rollback_required method... The first is systemctl is-system-running:


Returns false if retcode < 0 or output is stopping. Observation shown that this command normally returns 0 or 1 with output stopping during a normal shutdown, else running or degraded. I'm not sure about the returncode < 0 case as I couldn't find any documentation on systemctl's returncodes, and on affected systems the command returned a RC of 0 with unknown after a 25 seconds timeout (suspected dbus timeout).


This command never returned anything to STDERR in our tests.


If tuned isn't satisfied with this first command it proceeds with the 2nd command, list-jobs. If tuned gets to that point, it only look at the output for a job matching shutdown, reboot, halt or poweroff.


Again I could not see anything about the expected RC for this command (which isn't used regardless), but on failing systems RC is 1, there is no output to STDOUT and STDERR gets:


Failed to list jobs: Connection timed out
Normally, from my observations this comment should always return something to STDOUT and never to STDERR, so the _full_rollback_required method method should probably return False if the regex doesn't match and there is anything on STDERR or nothing on STDOUT (perhaps check RC if that makes sense, again I could not find any documentation on the expected RC).
</snip>

**note: This was seen on RHEL7, but it doesn't look like this behavior would change on RHEL8 if the read on what's happening is correct so I'm raising it on the newer OS since this would be out of scope on RHEL7 at this phase**