#!/usr/bin/perl # =pod =head1 SUMMARY Works with multilog to analyse and summarise log entries generated by the logterse plugin. It is designed to be invoked by multilog at log-rotation time. This is specified by an argument to multilog similar to: =over 4 multilog t !/path/to/qplogsumm ./main =back When qplogsumm is invoked, each line will be echoed, meaning the stored log is unchanged, but summary information will be written to fd 5 and so stored in the 'state' file by multilog. This file is fed in on fd 4 at the beginning of the next log rotation, so running totals, etc can be maintained. =head1 State file format: One entry per line containing three fields separated by whitespace: =over 4 =item 1. Disposition (plugin) name. =item 2. tai64n timestamp recording the first time it was seen in a log. =item 3. long-term running total. =back A disposition is effectively the plugin name that called DENY or the string 'queued' for messages that made it through. A line containing a disposition name of LOGFILE_EPOCH and a timestamp for the earliest known log entry. Other derived data, such as percentages etc. can also appear in the file, commented by a # character. This will be ignored on the next intake. =head1 AUTHOR Charles Butcher =head1 VERSION This is release 1.0 =cut use strict; use POSIX qw(strftime); my $FS = "\t"; # field separator used by logterse plugin my %disp; # hash of dispositions if (open PREVIOUS, "<&4") { while () { chomp(); next if m/^#/; next if m/^\s*$/; my ($plug_name, $plug_epoch, $plug_cumulative) = split /\s+/; my $c = { epoch => $plug_epoch, cum => $plug_cumulative, curr => 0 }; $disp{$plug_name} = $c; } close PREVIOUS; } my $first_timestamp = 0; my $last_timestamp = 0; while (<>) { print; chomp; next unless m/terse plugin/; my ($timestamp_part, $log_part) = split '`'; my ($current_timestamp) = split /\s/, $timestamp_part; $first_timestamp = $current_timestamp unless $first_timestamp; $last_timestamp = $current_timestamp; my (@log_items) = split $FS, $log_part; my $disposition = $log_items[5]; next unless defined $disposition; if ($disp{$disposition}) { $disp{$disposition}->{curr} += 1; } else # a new plugin -- make a note of when it first appeared { my $c = { epoch => $current_timestamp, cum => 0, curr => 1 }; $disp{$disposition} = $c; } } # # Set overall epoch # if (!exists $disp{'LOGFILE_EPOCH'}) { my $c = { epoch => $first_timestamp, cum => 0, curr => 0}; $disp{'LOGFILE_EPOCH'} = $c; } my $current_total = 0; my $cumulative_total = 0; open HOLDOVER, ">&5" and select HOLDOVER; # # Output cumulative values for intake the next time a log is processed # for my $c (keys %disp) { $disp{$c}->{cum} += $disp{$c}->{curr}; $current_total += $disp{$c}->{curr}; $cumulative_total += $disp{$c}->{cum}; printf "%-30.30s %s %12d\n", $c, $disp{$c}->{epoch}, $disp{$c}->{cum}; } # # Output current logfile stats # my $current_elapsed = tai64diff($last_timestamp, $first_timestamp); exit 0 if ($current_elapsed == 0); printf "# # Most recent logfile # ------------------- # # Start : %s # Finish : %s # Elapsed: %s # # Total transactions : %9d # Average tx per hour: %9d ", tai64utc($first_timestamp), tai64utc($last_timestamp), seconds_to_days($current_elapsed), $current_total, $current_total / ($current_elapsed / 3600), ; # # Output cumulative log stats # my $cumulative_elapsed = tai64diff($last_timestamp, $disp{'LOGFILE_EPOCH'}->{epoch}); printf "# # Cumulative Totals # ----------------- # # Start : %s # Finish : %s # Elapsed: %s # # Total transactions : %12d # Average tx per hour: %12d ", tai64utc($disp{'LOGFILE_EPOCH'}->{epoch}), tai64utc($last_timestamp), seconds_to_days($cumulative_elapsed), $cumulative_total, $cumulative_total / ($cumulative_elapsed / 3600), ; # # Output per-plugin stats # print "# # Most Recent Logfile Cumulative Totals # Disposition (plugin) Total Avg/Day Total Avg/Day # ----------------------------------------------------------------------------\n"; my $printf_format = "# %-30.30s %6d %3d%% %8d %10d %3d%% %8d\n"; foreach my $c (sort { $disp{$b}->{curr} <=> $disp{$a}->{curr} } keys %disp) { next if ($c eq 'LOGFILE_EPOCH'); printf $printf_format, $c, $disp{$c}->{curr}, $disp{$c}->{curr} / $current_total * 100, $disp{$c}->{curr} / ($current_elapsed / 86400), $disp{$c}->{cum}, $disp{$c}->{cum} / $cumulative_total * 100, $disp{$c}->{cum} / (tai64diff($last_timestamp, $disp{$c}->{epoch}) / 86400), ; } print "# ----------------------------------------------------------------------------\n"; printf $printf_format, 'TOTALS', $current_total, 100, $current_total / ($current_elapsed / 86400), $cumulative_total, 100, $cumulative_total / ($cumulative_elapsed / 86400), ; exit 0; sub tai64utc { my ($s) = @_; # @400000003f6c7bc5253bf98c # 0123456789012345678901234 # 0 1 2 # |-------------||------| if (substr($s, 0, 2) eq '@4') { my $ts = hex(substr($s, 2, 15)); $s = strftime('%Y-%m-%d %H:%M:%S', gmtime($ts)); } return $s; } # # Return difference in seconds # sub tai64diff { my ($s1, $s2) = @_; # @400000003f6c7bc5253bf98c # 0123456789012345678901234 # 0 1 2 # |-------------||------| if (substr($s1, 0, 2) eq '@4' and substr($s2, 0, 2) eq '@4') { my $ts1 = hex(substr($s1, 2, 15)); my $ts2 = hex(substr($s2, 2, 15)); return $ts1 - $ts2; } else { return 0; } } # # Return an english phrase representing a number of seconds # sub seconds_to_days { my ($secs) = @_; my $phrase = sprintf "%d days, ", ($secs / 86400); $secs %= 86400; $phrase .= sprintf "%d hours, ", ($secs / 3600); $secs %= 3600; $phrase .= sprintf "%d mins, %d secs", ($secs / 60), ($secs % 60); }