2

I am trying to calculate time taken by reboot on SUSE linux systems (SLES11 and SLES12 systems) as follows:

reboot_time = end_time - start_time

where
    start_time is "time at which reboot command is triggered"
    end_time   is "time at which system is ready after booting process, finishing up startup and userspace programs" OR "time when login is prompted soon after reboot"

I am able to know start_time. But not able to know time end_time for SLES11 systems (init.d SysV version). For SLES12 (systemd initialization), systemd-analyze was giving required information, but I am not able to figure out a reliable way for init.d systems. Is there any similar alternative on a SysV init system or SLES11 that could give me the time spent on booting (starting kernel, finish running startup programs and complete userspace initialization)?

Pranav
  • 1,653
  • 2
  • 11
  • 9

3 Answers3

1

You might get (non second precise) last shutdown date with the following command

last -x | egrep "shutdown|reboot" | head -1 | awk '{print $5" "$7" "$6" "$8}'

last -x can give you system boot / reboot & shutdown times, and all system boot logs since system creation. The problem is that is does not show years, and has only minute resolution.

last reads various log binary log files (/var/log/wtmp utmp and btmp) You can use utmpdump utility to get shutdown & reboot timestamps with more precise timestamps

utmpdump /var/log/wtmp | egrep "shutdown|reboot" | awk -F '[' '{print $9}' | sed 's/ ]//g'

Ultimatively, you can get the elapsed time from shutdown to reboot with the following (horribly long) one liner:

echo "System $(hostname) took $(($(date -d "$(LC_ALL=C utmpdump /var/log/wtmp 2>/dev/null| grep "reboot" | grep -Eo '[[:alpha:]]{3} [[:alpha:]]{3} [[:digit:]]{2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2} [[:digit:]]{4}|[[:digit:]]{4}-[[:digit:]]{2}-[[:digit:]]{2}T[[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}' | tail -1)" "+%s") - $(date -d "$(LC_ALL=C utmpdump /var/log/wtmp 2>/dev/null| grep "shutdown" | grep -Eo '[[:alpha:]]{3} [[:alpha:]]{3} [[:digit:]]{2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2} [[:digit:]]{4}|[[:digit:]]{4}-[[:digit:]]{2}-[[:digit:]]{2}T[[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}' | tail -1)" "+%s"))) to reboot"

Explanation:

  • LC_ALL=C makes the output of the following commands unlocalized
  • utmpdump /var/log/wtmp 2>/dev/null will list all events, while 2>/dev/null will redirect errors and unwanted output.
  • grep "reboot" or grep "shutdown" will filter utmpdump output to show only reboot or shutdown events
  • '[[:alpha:]]{3} [[:alpha:]]{3} [[:digit:]]{2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2} [[:digit:]]{4}' is a regex to capture non localized date strings that look like "Fri Aug 02 00:01:27 2019", these are used on CentOS
  • '[[:digit:]]{4}-[[:digit:]]{2}-[[:digit:]]{2}T[[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}' is a regex to capture ISO 8601 date strings that look like "2021-08-17T10:11:03", these are used on Debian
  • date -d "datestring" converts the date into an epoch
  • $(command) is the output of the command
  • $((x - y)) is for mathematical operations (eg substract two epochs)

You can also play with the output of utmpdump to retrieve login timestamps. Be aware that shutdown/reboot cycle is different from shutdown/system boot cycle, hence the commands have to be adapted to your usage. Also be aware that any forceful system resets will not be included in the logs, hence giving bogus values.

Orsiris de Jong
  • 2,819
  • 1
  • 26
  • 48
  • Thanks a lot for your response. I tried to rely on `last` command (or wtmp file) earlier, but that command/file does not seem to give proper results on few systems. I saw empty output on few systems even when system was rebooted. Also `reboot` time shown in wtmp/last is not considering time taken to start startup daemons and services. – Pranav Sep 01 '21 at 04:56
  • Have you looked at my other answer ? – Orsiris de Jong Sep 01 '21 at 09:06
  • Have you checked whether you have /var/log/wtmp, btmp or utmp files ? Is there maybe some other info you could get with the help of utmpdump ? Also, my asnwer supposes some particular date formats with regexes. I have adapted them to work on Debian and Redhat alikes. You might have to tweak the regex to work with SLES date formats. Can you maybe pastebin some utmpdump output ? – Orsiris de Jong Sep 02 '21 at 09:41
  • On test systems I can see the wtmp and utmp files. But wasn't able to see btmp file even after failed login attempts. Based on my observation on init.d systems, I could see login screen appearing only after initiating all the startup programs. So I am planning to get the time at which login screen appeared for the first time. Looks like utmp gives us required login time for different ttys; but does not store time/pids for failed attempts. I am worried about systems that miss wtmp or utmp files. Can I use `ps -p -o lstart=`? Or Is `utmpdump /var/run/utmp` much better? – Pranav Sep 02 '21 at 12:10
  • `utmpdump /var/run/utmp` output: https://pastebin.com/rM7xZ90Q – Pranav Sep 02 '21 at 12:18
  • Your initial question was about reboot times, not failed logins. That's a job for /var/log/secure or whatever security logs you have. I don't have btmp on my systems too, but utmp contains reboot and shutdown times, hence you have your results. – Orsiris de Jong Sep 02 '21 at 12:55
  • Sorry I dint keep track of bounty time. I started one more bounty and will reward this answer with bounty as soon as it becomes available. – Pranav Sep 02 '21 at 13:18
  • Thank you. Is your problem sorted out ? You can filter "shutdown", "reboot", "system boot" and "login" times in wtmp file. This should give you everything you need. The file you pasted uses a date format that is compatible with the above regex. You should be all set. – Orsiris de Jong Sep 03 '21 at 08:11
  • Yeah, I used python to parse wtmp file. In case wtmp file do not exist (or utmpdump fails for some reason), script would try to get process start time of agetty and mingetty processes. Is there any alternative to get time at which linux welcome screen first appeared after last reboot? – Pranav Sep 03 '21 at 17:54
  • Getting tty service start time seems fair enough to me. You might want to add an answer by posting your python script. – Orsiris de Jong Sep 05 '21 at 12:14
0

Maybe a bit hacky, but you might just add a script that gets executed at last, ie /etc/init.d/K99WriteShutdownTime (where K means shutdown script, and the higher the number, the later it gets executed).

The script could contain somthing like

#!/usr/bin/env bash

timestamp_logfile="/var/log/shutdown_timestamp"
date +"%s" > "$timestamp_logfile"

You can then have another script ie /etc/init.d/S99WriteGetTime like

#!/usr/bin/env bash

timestamp_logfile="/var/log/shutdown_timestamp"
boot_time_logfile="/var/log/boot_time.log"

if [ -f "$logfile" ]; then
   boot_timestamp=$(date +"%s")
   shutdown_timestamp=$(cat "$timestamp_logfile")
   delta=$((boot_timestamp - shutdown_timestamp))
   echo "$(date +"%Y-%m-%d %H:%M:%S"): It took $delta seconds to boot $(hostname)" >> boot_time_logfile
else
   echo "$(date +"%Y-%m-%d %H:%M:%S"): No prior shutdown time detected. Cannot compute boot time" >> boot_time_logfile
fi
Orsiris de Jong
  • 2,819
  • 1
  • 26
  • 48
  • I think you are asking to place the script in `/etc/init.d/rc3.d/` (runlevel 3) or `/etc/init.d/rc5.d/` (runlevel 5) path instead of `/etc/init.d`? Anyways, we will not have write access on customer systems to add new statup and kill script. So I am looking for commands without having to add new scripts. – Pranav Sep 02 '21 at 09:11
  • Wow, without write access you won't have much options. Put these scripts in whatever runlevel you're booting. – Orsiris de Jong Sep 02 '21 at 09:41
0

On init systems (like SLES11), login prompt will be displayed to user only after initiating all the startup programs. So we can rely on getting login prompt time from wtmp file (as suggested by user "Orsiris de Jong").

Below is the python script to get login prompt time after last reboot.

#!/usr/bin/env python3
import subprocess
import re
from datetime import datetime
from typing import List


class UnableToFindLoginTimeError(Exception):
    pass


class UnexpectedCommandException(Exception):
    pass


class CommandResult:
    def __init__(self, command, stdout, stderr, exit_code):
        self.command = command
        self.stdout = stdout
        self.stderr = stderr
        self.exit_code = exit_code

    def validate(self, check_stderr=True, check_exit_code=True):
        if (check_stderr and self.stderr) or (check_exit_code and self.exit_code != 0):
            raise UnexpectedCommandException('Unexpected command result')


def run_command(command, timeout=600):
    completed_process = subprocess.run(
        command,
        encoding='utf-8',
        timeout=timeout,
        stdout=subprocess.PIPE,
        stderr=subprocess.PIPE,
        shell=True,
        errors='ignore',
    )
    command_result = CommandResult(
        stdout=completed_process.stdout.strip(),
        stderr=completed_process.stderr.strip(),
        exit_code=completed_process.returncode,
        command=command,
    )
    return command_result


def _extract_data_in_square_brackets(row: str) -> List[str]:
    """
    Extract data within square brackets from a string.

    Example:
    '[One] [Two ] [Three   ] [Wed Aug 25 09:21:59 2021 UTC]'
    returns
    ['One', 'Two', 'Three', 'Wed Aug 25 09:21:59 2021 UTC']
    """
    regex = r'\[(.*?)\]'
    columns_list = re.findall(regex, row)
    return [item.strip() for item in columns_list]


def convert_datetime_string_to_epoch(datetime_str: str) -> int:
    """
    Run following command to automatically parse datetime string (in any valid format) into epoch:
    # date -d '{datetime_str}' +%s

    Note: The Unix epoch is the number of seconds that have elapsed since January 1, 1970 (midnight UTC/GMT).
    At any point of time, epoch will be same throughout all time zones.

    Example: epoch for "Fri Sep  3 11:08:09 UTC 2021" will be 1630667289.
    """
    command_result = run_command(f"date -d '{datetime_str}' +%s")
    command_result.validate()
    epoch = round(float(command_result.stdout.strip()))
    return epoch


def get_login_time_from_wtmp() -> datetime:
    """
    Read through /var/log/wtmp binary file using utmpdump
    and find least LOGIN time after last reboot.

    wtmp gives historical data of utmp (gives information about user logins, logouts, system boot etc.).
    In case of failed logins, we see multiple entries for same tty in the output.
    In such case, we get first occurred entry after last reboot since that is when
    startup processes have been completed and welcome screen appeared.

    Sample:
    -------
    Output:
    [2] [00000] [~~  ] [reboot  ] [~           ] [3.10.0-957.12.2.el7.x86_64] [0.0.0.0        ] [Mon Aug 16 06:21:06 2021 UTC]
    [6] [01828] [tty1] [LOGIN   ] [tty1        ] [                    ] [0.0.0.0        ] [Mon Aug 16 06:21:26 2021 UTC]
    [2] [00000] [~~  ] [reboot  ] [~           ] [3.10.0-957.12.2.el7.x86_64] [0.0.0.0        ] [Wed Aug 25 09:21:34 2021 UTC]
    [6] [01815] [tty1] [LOGIN   ] [tty1        ] [                    ] [0.0.0.0        ] [Wed Aug 25 09:21:59 2021 UTC]

    Returns: "Wed Aug 25 09:21:59 2021 UTC" as datetime object
    """
    command_result = run_command(f'utmpdump /var/log/wtmp | grep -e reboot -e LOGIN')
    command_result.validate(check_stderr=False)
    output = command_result.stdout
    list_of_login_epochs = []
    # read output in reverse order
    for line in output.splitlines()[::-1]:
        if 'reboot' in line:
            # exit loop since we dont require data before last reboot
            break
        items = _extract_data_in_square_brackets(line)
        if 'LOGIN' in items:
            login_time_str = items[-1].strip()
            epoch = convert_datetime_string_to_epoch(login_time_str)
            list_of_login_epochs.append(epoch)

    if not list_of_login_epochs:
        raise UnableToFindLoginTimeError()

    # collect least login time out of all since we need time at which login was prompted first.
    least_epoch = min(list_of_login_epochs)
    login_datetime_object = datetime.utcfromtimestamp(round(least_epoch))
    return login_datetime_object


if __name__ == '__main__':
    print(
        f'Login screen was displayed to user after last reboot at {get_login_time_from_wtmp()} UTC'
    )
Pranav
  • 1,653
  • 2
  • 11
  • 9