Script day: output the tail of a log based on time

As system administrators we often want to list the last few lines from a log file in order to track problems and see system reports. The UNIX command tail is very useful for that purpose and lets you display an arbitrary number of lines from the bottom of any file.

But often this is not really what you want – an administrator might want to see what happens in the last X minutes and the common practice to do this is to run tail with a guessed number of lines, see if you get what you want and if its not enough increase the number and try again.

Here’s another approach that works well if the log file you want to trace has time stamps for its lines – use UNIX date command to format the earliest time stamp you want to see and then filter on that.

For example, to list the last 10 minutes of logs from an Apache log file, one can use this command:


# grep "$(date -d "10 minutes ago" +"%d/%b/%Y:%H:%M:%S")" -A 999999 /var/log/httpd/access_log

Here we take advantage of the fact that date is very user friendly about interpreting date definitions to format an easy to understand relative time stamp – You can use almost any plain English time definition to tell date what time you need1. After formatting a time stamp according to your log convention ( “%d/%b/%Y:%H:%M:%S” is for Apache’s access log time stamp. Syslog logs or other logs will need different format specifications), we use grep to find a line that matches and show as many lines after that as we need (hopefully all of them – choose a -A large enough for your purposes).

The one major caveat of this approach is that it relies on your log to have at least one message every second, otherwise the exact second that date computed may not have a corresponding message in the log and then grep will not find it and will not output anything. Working around that problem is not that simple though – we’d have to read every line in the log, actually parse the time stamp in the log and compare it to the time stamp we provide and if the log time stamp is later – only then display the line. grep is useless for this because it can’t do any comparison other then comparing texts to check that they are identical.

My solution for this is to use date again to parse the date format in the log file (maybe with some modifications so date won’t get too confused) and then simply compare epoch time values:


# cat /var/log/httpd/balancer-access_log | (
date=$(date -d "10 minutes ago" +"%s")
while read line; do
[ "$(date -d"$(echo $line | cut -d']' -f1 | sed -e 's/.*\[//;s/\// /g;s/:/ /;')" +"%s")" -ge "$date" ] && echo $line
done)

What I do here is to pipe the log file through a while read loop – this will read each line into the $line variable, consuming all the log lines until the end of the file is reached. Each line is then put through some sed to extract the time stamp in a way that date will like it (again – the code above works for Apache access logs. Other log types may need more or less massaging to get at a parsable time values, but either way a different code will be needed). We then put the time stamp through date and use the format code +"%s" to get an epoch time stamp and compare it to the epoch time stamp we generated at the beginning from our “free language” time specification. If the parsed time value is greater (or equal) then we display the line.

The one major disadvantage of giving up on grep is the performance that will be orders of magnitude worse when you actually have to do some processing of data :-).

  1. for example, compare date -d "12:45 monday" +"%d/%b/%Y:%H:%M:%S" and date -d "12:45 last monday" +"%d/%b/%Y:%H:%M:%S" []

7 Responses to “Script day: output the tail of a log based on time”

  1. jphoglund:

    This is exactly what I need and far more elegant solution than I’d ever be able to produce. Thank you!

    //JP

  2. Coger los últimos 10 minutos del log de apache « El Hombre que Reventó de Información:

    […] http://geek.co.il/wp/2010/04/08/script-day-output-the-tail-of-a-log-based-on-time Like this:LikeBe the first to like this […]

  3. Zak:

    Just omit the seconds from the format of the output of date, then you’d only need a hit in that minute, not second.

  4. Henry:

    Thanks for sharing. Here is my take on how to minimize execution time if it miss the exact second. It should take less than 1 sec.

    https://github.com/bbhenry/check_mk_local/blob/master/check_http_code_counter

  5. Nagarajan:

    Hi this doesn’t work in solaris. date -d .. there is no option -d in solaris. How can I use this similar one in solaris. I am looking to get last 10 days of accesslog informations.

    Thanks
    Naga

  6. Oded:

    Solaris’ built-in date utility is very primitive and does not support many of the things I use `date` for. In the past when I had a need for more modern facilities, I used to install `coreutils` from sunfreeware.com.

    Unfortunately they recently changed their policy and no longer offer free (gratis) downloads of GNU open source tools. I have no knowledge of an alternative solution, but if you do find one – it would be great if you can post it here so that other people can also get help 🙂

  7. Chris Sciumbata:

    After banging my head against the wall and having issues with a space in the date/time string where I was setting in an external variable to try and achieve the same thing, I was lucky to have found this post. Thanks much for this elegant solution and saving me a ton of time tonight. I’m sure this will be in my log parsing utility belt from now on.

    Cheers!

    Chris S.

Leave a Reply