Action On Log

Problem this snippet solves:

Perl script that runs as a daemon to watch a log file (like tail in the background), and runs a command when a certain message is found. Smart enough to keep working when log files get rotated, etc. Very handy when you need to run a command to start gathering debugging data or recover from failure that is indicated by a log message.

How to use this snippet:

Note that when the script is first started it sends SIGHUP to syslogd (or syslog-ng if present) which causes the daemons to reload their configuration files and flush their log buffers. This is needed in case the message you want to find is currently being suppressed by "last message repeated XX times".

The script is configured by editing the first 3 variables at the top of the script that specify the log file to watch via $LOG_FILE, log message to look for via $LOG_MESSAGE, and the action to take via $ACTION (i.e. command to run).

The $LOG_MESSAGE to match is a regular expression matched against each new line in the log file like this:

if (/$LOG_MESSAGE/)

So if you specify a simple $LOG_MESSAGE like this: $LOG_MESSAGE = "test string";

This would match so long as any part of the log line contained "test string". So "foobar test string asdf" would still match "test string".

There are 2 additional (optional) configuration parameters after the first 3 that specify how often to check if the log file has been rotated via $IDLE_TIMER, and how many lines to read when re-opening a log file that has been rotated via $MAX_ROTATED_LINES.

The script can be tested like so:

1. Determine which facility/severity messages are sent to /var/log/messages based on your syslog.conf or syslog-ng.conf. In my case, uucp.notice goes there.

2. Start the script with default settings:

   • perl action_on_log.pl

3. The default action is to append a string to a file named "/var/tmp/mylog.txt", so first cat this file and make sure it's empty:

   • cat /var/tmp/mylog.txt

4. Now send the log messages the script is checking for:

   • logger -p uucp.notice "foo watchdog bar"

5. Repeat step #3 -- this time you'll see that the file exists and contains the expected message.

You can stop the daemon like so:

kill $(cat /var/run/action_on_log.pid)

OS Support

Older versions of this script have been tested against a fairly wide variety of unix-like platforms with great success, including BSDi 3.x, FreeBSD 4.x, Linux (2.4.x-era and current 2.6.x-era distros). Some have reported success running this script directly on BIG-IP 4.x and 9.x, though obviously F5 wouldn't support doing so.

(Modify $LOG_FILE, $LOG_MESSAGE, and $ACTION as appropriate, and optionally $IDLE_TIMER, and $MAX_ROTATE_LINES)

Code :

#!/usr/bin/perl
## VERSION v0.5

use warnings;
use strict;


################
# script settings
######

my $LOG_FILE           = "/var/log/messages";
my $LOG_MESSAGE        = "watchdog";
my $ACTION             = "echo log message found >> /var/tmp/mylog.txt";


# misc
my $IDLE_TIMER         = 5;    # if ! receiving log entries, how long before checking if log is rotated
my $MAX_ROTATED_LINES  = 500;  # max lines to read from file we're re-reading because it's been rotated
my $DEBUG              = 0;    # 0/1

####################################################
# END OF THINGS THAT SHOULD BE CONFIGURED
####################################################



########
# set defaults
###
my($PID_FILE);

$LOG_FILE                  ||= "/var/log/messages";
$LOG_MESSAGE               ||= "FAILED";
$IDLE_TIMER                ||= 5;
$PID_FILE                  ||= "/var/run/action_on_log.pid";
$DEBUG                     ||= 0;

######
# misc global variable declaration
##########

my($TAIL_CHILD_PID, $TAIL_OUTPUT_PIPE);
my($CURRENT_SIZE, $CURRENT_INODE, $LAST_SIZE, $LAST_INODE);

$CURRENT_SIZE = $CURRENT_INODE = 0;
$LAST_SIZE = $LAST_INODE = -1;

$|++;


###########
# functions
#######


# exit function that does does necessary child handling

sub finish () {
        if (defined $TAIL_CHILD_PID && $TAIL_CHILD_PID != 0) {

                $DEBUG && print "INTERRUPT: sending SIGINT and SIGTERM to: $TAIL_CHILD_PID\n";
                kill(2, $TAIL_CHILD_PID);
                sleep(1);
                kill(15, $TAIL_CHILD_PID);
                waitpid($TAIL_CHILD_PID, 0);
        }
        $DEBUG && print "INTERRUPT: unlink pidfile and exit\n";

        unlink($PID_FILE);
        exit(0);
}

$SIG{INT}  = sub { finish(); };


# simple sub to send SIGHUP to syslogd

sub restart_syslogd () {
        if (-f "/var/run/syslog.pid") {
                open(PIDFILE, ";
        chomp;

        kill(1, ($_));

        1;
}


sub fork_to_background ($) {
        my $cmd = shift();

        my $pid = fork();

        if ($pid == 0) {
                exec($cmd) || die "exec() failed: $!\n";
        } else {
                return($pid);
        }
}


sub popen_read ($) {
        my $cmd   = shift();
        my $child;

        $DEBUG && print "Background: \"$cmd\"\n";

        pipe(READLOG, WRITELOG);
        select(READLOG); $|++; select(WRITELOG); $|++; select(STDOUT);

        ## dup STDOUT and STDERR
        open(T_STDOUT, ">&STDOUT");
        open(T_STDERR, ">&STDERR");

        ## redir STDOUT to pipe for child
        open(STDOUT, ">&WRITELOG");
        open(STDERR, ">&WRITELOG");

        $child = fork_to_background($cmd);

        ## close STDOUT and STDERR inherited by child
        close(STDOUT); close(STDERR);

        ## re-open STDOUT as normal for this process and close dup
        open(STDOUT, ">&T_STDOUT"); close(T_STDOUT);
        open(STDERR, ">&T_STDERR"); close(T_STDERR);

        return($child, \*READLOG);
}


sub open_log ($$) {
        my $LOG_FILE = shift();
        my $lines    = shift();

        if (defined($TAIL_OUTPUT_PIPE) &&
                        defined(fileno($TAIL_OUTPUT_PIPE)) &&
                        $TAIL_CHILD_PID != 0) {
                $DEBUG && print "Killing tail child pid $TAIL_CHILD_PID before closing LOG\n";
                kill(15, $TAIL_CHILD_PID);
                waitpid($TAIL_CHILD_PID, 0);
                $TAIL_CHILD_PID = 0;

                $DEBUG && print "Closing LOG\n";
                close($TAIL_OUTPUT_PIPE);
        }

        if (! -f $LOG_FILE) {
                $DEBUG && print "Log file \"$LOG_FILE\" not found\n";
                $TAIL_OUTPUT_PIPE = undef;
                return 0;
        }

        $DEBUG && print "Opening \"$LOG_FILE\"\n";
        ($TAIL_CHILD_PID, $TAIL_OUTPUT_PIPE) = popen_read("tail -n $lines -f $LOG_FILE");

        1;
}


## check to see if log is rotated, returns true if rotated

sub is_rotated ($) {
        my $LOG_FILE = shift();

        $DEBUG && print "enter is_rotated()\n";

        ($CURRENT_INODE, $CURRENT_SIZE) = (stat($LOG_FILE))[1,7];

        if (!defined $CURRENT_INODE || !defined $CURRENT_SIZE) {
                $CURRENT_INODE = 0;
                $CURRENT_SIZE  = 0;
        }

        if (($LAST_SIZE > 0) && ($LAST_SIZE > $CURRENT_SIZE)) {
                $DEBUG && print "File is smaller.  File must have been rotated\n";
                ($LAST_INODE, $LAST_SIZE) = ($CURRENT_INODE, $CURRENT_SIZE);
                open_log($LOG_FILE, $MAX_ROTATED_LINES);
                return(1);

        } elsif (($LAST_INODE > 0) && ($LAST_INODE != $CURRENT_INODE)) {
                $DEBUG && print "Inode changed.  File must have been rotated\n";
                ($LAST_INODE, $LAST_SIZE) = ($CURRENT_INODE, $CURRENT_SIZE);
                open_log($LOG_FILE, $MAX_ROTATED_LINES);
                return(1);
        } elsif ($LAST_INODE == 0 && $LAST_SIZE == 0) {
                $DEBUG && print "Size and inode were 0 last time.  File must have been removed\n";
                ($LAST_INODE, $LAST_SIZE) = ($CURRENT_INODE, $CURRENT_SIZE);
                open_log($LOG_FILE, $MAX_ROTATED_LINES);
                return(1);
        }

        ($LAST_INODE, $LAST_SIZE) = ($CURRENT_INODE, $CURRENT_SIZE);

        0;
}




###########
# MAIN
########

####### DAEMONIZE #############
chdir("/");
exit unless (fork() == 0);


# kill old self, write pid file
if (-f $PID_FILE) {
        open(PIDFILE, "<$PID_FILE");
        kill(15, );
        close(PIDFILE);
}

open(PIDFILE, ">$PID_FILE");
syswrite(PIDFILE, $$);
close(PIDFILE);



## set handler for SIGTERM (regular kill)
$SIG{TERM} = sub { finish(); };


################
# watch log-based trigger
####################

print "\nWaiting for \"$LOG_MESSAGE\" in \"$LOG_FILE\".  Will run:\n\"$ACTION\"\n";

# creates global $TAIL_OUTPUT_PIPE filehandle of $LOG_FILE
open_log($LOG_FILE, 0);

# flush syslogd's buffers (avoid never getting the message due to "last message repeated....")
restart_syslogd();

LOOP:
# tail -f the log and wait for message
while (1) {
        if (!defined($TAIL_OUTPUT_PIPE) || !defined(fileno($TAIL_OUTPUT_PIPE)) ) {
                # this suggests the file was removed while we were using it...
                sleep($IDLE_TIMER);
                is_rotated($LOG_FILE);
                next;
        }

        eval {
                $SIG{ALRM} = sub { die("ALRM\n"); };

                alarm($IDLE_TIMER);
                $_ = readline($TAIL_OUTPUT_PIPE);
                alarm(0);
        };

        if ($@) {
                # this only occurs if we're idle for $IDLE_TIMER seconds because no new log entries are occuring

                $@ = undef;
                is_rotated($LOG_FILE);

                next;
        }

        chop();
        $DEBUG && print "in LOG reading loop, current line: \"$_\"\n";

        if (/$LOG_MESSAGE/) {
                $DEBUG && print "Current line matches: \"$LOG_MESSAGE\"\n";
                last;
        }

        $DEBUG && print "no match, next\n";
}

## log message found: DO SOMETHING
system($ACTION);
goto LOOP;


# kill all children; doesn't return
finish();

0;