When the Logs Aren't Right

by J. Edward Durrett

When working in the real world things are not always they way they should be. For example, it is a best practice
to have all machines on a network synced to the same time source. Then, when investigating a problem or incident
the information in the logs across multiple machines can help in establishing a time line. For a variety of reasons,
including skipping the step of ensuring that times of synced, two machines could have different times. This
isn’t the end of the world as it is possible to adjust the time in the logs. Here is one such method.

First, we need to know the difference in time between the two machines. To do this, we first need to get the
time in seconds since the start of the epoch (1970-01-01 UTC). On most *NIX systems, something like this will
work:

 
date -j -f "%a %b %d %T %Z %Y" "`date`" "+%s"


Then, subtract the difference between the two time stamps. This will be the offset variable used in the script
further down on this page. The log I am going to change is a DNS query log, which looks like this:

 
18-Aug-2017 17:59:11.438 queries: info: client @0x 192.168.xx.xx#51039 (dns.xxx.xxx.xxx.xxx): query:
xxx.xxx.xxxxxxx.xxx IN SOA -E(0) (192.168.xx.xx)


The date in the logs has nanoseconds (the last 3 numbers in the times tamp), but the version of date on *BSD and
OSX doesn’t support that. So, to get the date down to the second, the script below ignores the nanoseconds.
GNU date does support nanoseconds with the %N format code. This script looks at every line, converts the time
stamp to seconds, adds the offset (basic math reminder, to subtract just make the offset a negative number),
converts the time back to the original format and writes a new line with the new time stamp to a new log file:

 
#!/bin/sh

OFFSET= #time difference in seconds
OLD_LOG= #log file with the incorrect time
NEW_LOG= #file to write with adjusted times

cat $OLD_LOG | while read LINE ; do
OLD_DATE=`echo $LINE | cut -d . -f1 | awk '{print$1" "$2}'`
OLD_DATE=`date -j -f "%d-%b-%Y %H:%M:%S" "$OLD_DATE" "+%s"`
OLD_DATE=$(($OLD_DATE + $OFFSET))
OLD_DATE=`date -j -f "%s" "$OLD_DATE" "+%d-%b-%Y %H:%M:%S"`
echo $LINE | sed -e 's/'"$OLD_DATE"'/'"$OLD_DATE"'/g' >> $NEW_LOG
done


For different time stamp formats in different logs, modifying the format string of date is necessary for the
script to work properly. Of course, the script could first read the format and, through a series of conditionals
determine which format string to use, but this script works good enough for my purposes today.

Often in the course of a day I come across something unexpected. There usually is a solution, often very simple
like the one above. Of course the time should be fixed on the machines so they are in sync, but an improperly
timed machine need not be an obstacle in performing log analyses.







Copyright (c) 2019, Jason Edward Durrett - All content on this site, unless otherwise noted, is subject to this license.

Please contact me if any errors, such as erroneous / misleading content or missing / incomplete attribution, are found.