How can I know system boot time on SLES11 systems?

Question

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

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

Answer 2

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

Answer 3

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