Skip to content
May 11, 2013 / gus3

When was that? Examining syslog timestamps

One convenient Linux kernel feature is an uptime stamp in each kernel log entry. This stamp is independent of the clock time, so small or large jumps in the clock have no bearing on the reported time for each entry.

Normally, the log files in /var/log/ will include a human-readable local time stamp before the log entry, but these files are readable only by the root user. Another possibility is that the logs are routed to another system for storage. This practice would also include restricting “dmesg” to the root user; the following won’t be useful in this case.

The basic math is simple. We have the current uptime in /proc/uptime, and the current Unix epoch time from date +’%s’, so the only input remaining is the desired offset time. For example, my dmesg output contains the following, generated when I inserted an SD card:

[151119.144389] sd 6:0:0:0: [sdc] No Caching mode page present

The offset time is 151,119 seconds after booting. So, if I type the following:

logtime 151119

I get something like the following:

151119 seconds after boot was about Tue May  7 20:49:48 EDT 2013.

It says “about” because shell scripts don’t run at breakneck speed. Under high system load, a script may take a few seconds just to load. Still, this gives an idea of the date and time, and from that you may remember what you were doing to generate that log entry.

Here is the script:

#!/bin/sh -e
# Bourne shell script to convert uptime from dmesg
# entry to a human-readable version.
# This script is in the public domain, as
# all interpreted scripts should be.

if [ "$#" != "1" ] ; then
# no time, or too many args
echo "Usage: `/usr/bin/basename $0` time-offset-integer"
exit 1
elif [ "`echo $1 | /usr/bin/sed 's/[0-9]//g'`" != "" ] ; then
# non-digit characters present
echo "Usage: `/usr/bin/basename $0` time-offset-integer"
exit 1
fi

# Now
N=`/usr/bin/date +'%s'`
# Uptime (the '$1' isn't interpreted by Bash,
# thanks to single quotes)
U=`FS="." /usr/bin/awk '{print $1;}' < /proc/uptime | \
/usr/bin/sed 's/[^0-9].*//'`
# $1 in Seconds
TS=`/usr/bin/expr $N - $U + $1`
# Boot time + $1 in the local format
T=`/usr/bin/date --date="@$TS"`

echo "$1 seconds after boot was about $T."

Three points about the above code:

  • The script assumes the system time is properly set. On systems with a hardware clock, this is automatic. Without a hardware clock, the system time defaults to the start of the Unix epoch, unless a startup script sets it somehow. Otherwise, the boot time is calculated as midnight, January 1, 1970 Greenwich Mean Time, probably not what you want.
  • The “-e” parameter on the first line says to exit immediately at the first error.
  • The use of `expr…` rather than $((…)) improves compatibility with other Bourne-derived shells, or earlier versions of Bash, but `expr` incurs time to fork/exec.
About these ads

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: