rails_request_duration

#!/usr/bin/env ruby
pod=<<-POD

=head1 NAME
rails_request_duration - Munin plugin to monitor the minimum, average and maximum request duration.

=head1 APPLICABLE SYSTEMS
All systems that have a rails application log.

=head1 CONFIGURATION
The request-log-analyzer gem has to be intalled.
Also the script has to be able to access the rails log file and tail.
This configuration section shows the defaults of the plugin:

  [rails_request_duration]
  env.log_file '/path/to/production.log'
  user www-data
  command /usr/local/bin/ruby %c
  
Options
  env.lines 50000                             # Number of lines to tail
  env.interval 300                            # Munin interval in seconds (used for graphs and caching)
  env.log_format                              # request-log-analyzer log format (passed to '--format')
  env.request_log_analyzer '/usr/local/bin'   # Path to gem. Use this for Debian.
  env.graph_category 'App'                    # Graph Category. Defaults to App.

ln -s /usr/share/munin/plugins/rails_request_duration /etc/munin/plugins/rails_request_duration

=head1 INTERPRETATION
Three lines are graphed, showing the minimum, average and maximum request times.

=head1 MAGIC MARKERS
  #%# family=auto
  #%# capabilities=autoconf

=head1 VERSION
1.9.7

=head1 BUGS
None known

=head1 AUTHOR
Bart ten Brinke - railsdoctors.com

=head1 LICENSE
MIT

POD

# Globals
GRAPH_CATEGORY  = ENV['graph_category'] || 'App'
INTERVAL        = ENV['interval'] ? ENV['interval'].to_i : 300
NUMBER_OF_LINES = ENV['lines'] || 50000
LOG_FILE        = ENV['log_file']
LOG_FORMAT      = ENV['log_format'] ? "--format #{ENV['log_format']}" : ''
AFTER_TIME      = (Time.now - INTERVAL).strftime('%Y%m%d%H%M%S')
FLOOR_TIME      = Time.at((Time.now.to_f / INTERVAL).floor * INTERVAL)

TEMP_FOLDER     = '/tmp'
TEMP_PREFIX     = GRAPH_CATEGORY == 'App' ? 'rla' : GRAPH_CATEGORY.downcase
TEMP_FILE       = "#{TEMP_PREFIX}_#{FLOOR_TIME.to_i}.yml"
REQUEST_LOG_ANALYZER = ENV['request_log_analyzer'] || '/usr/bin/request-log-analyzer'

# Check if we can run this plugin on this system
def autoconf
  begin
    require 'rubygems'
    gem "request-log-analyzer", ">=1.1.6"
    require "yaml"
  rescue Exception => e
    puts "no (Gem not found: #{e})"
    exit 1
  end

  unless `echo "test" | tail 2>/dev/null`.include?("test")
    puts "no (tail command not found)"
    exit 1
  end
  
  puts "yes"
  exit 0
end

# Uptput the config
def config
  puts <<-CONFIG
graph_category #{GRAPH_CATEGORY}
graph_title Request time
graph_vlabel Seconds
graph_args --base 1000 -l 0
graph_info The minimum, maximum and average request times - railsdoctors.com
 
min.label min
max.label max
average.label avg
CONFIG
  exit 0
end

def fetch_or_create_yaml_file(log_file, debug = false)
  # Clean up any old temp files left in de temp folder
  Dir.new(TEMP_FOLDER).entries.each do |file_name|
    if match = file_name.match(/^#{TEMP_PREFIX}_.*\.yml/)
      if match[0] != TEMP_FILE
        puts "Removing old cache file: #{file_name}" if debug
        File.delete(TEMP_FOLDER + "/" + file_name) 
      end
    end
  end
  
  temp_file = TEMP_FOLDER + "/" + TEMP_FILE
  
  # Create temp file rla if needed
  unless File.exists?(temp_file)
    puts "Processing the last #{NUMBER_OF_LINES} lines of #{log_file} which are less then #{INTERVAL} seconds old." if debug    
    status = `tail -n #{NUMBER_OF_LINES} #{log_file} | #{REQUEST_LOG_ANALYZER} - --after #{AFTER_TIME} #{LOG_FORMAT} -b --dump #{temp_file} 2>/dev/null`

    unless $?.success?
      $stderr.puts "failed executing request-log-analyzer. Is the gem path correct?"
      exit 1
    end
  else
    puts "Processing cached YAML result #{temp_file}" if debug      
  end
  
  return temp_file
end

# Gather information
def run(log_file, debug = false)

  if log_file == "" || log_file.nil?
    $stderr.puts "Filepath unspecified. Exiting"
    exit 1  
  end

  # Initialize values
  max_value = 0
  min_value = 1.0/0.0
  cumulative = 0
  hits = 0
  
  # Walk through the
  require "yaml"
  rla = YAML::load_file( fetch_or_create_yaml_file(log_file, debug) )
  
  if rla && rla["Request duration"]
    rla["Request duration"].each do |item|
      max_value = item[1][:max] if item[1][:max] > max_value
      min_value = item[1][:min] if item[1][:min] < min_value
      hits += item[1][:hits]
      cumulative += item[1][:sum]
    end
  else
    hits = 1
    min_value = 0
  end
  
  puts "max.value #{max_value}"
  puts "min.value #{min_value}"
  puts "average.value #{cumulative / hits.to_f}"
end

# Main
if ARGV[0] == "config"
  config
elsif ARGV[0] == "autoconf"
  autoconf
elsif ARGV[0] == "debug"
  run(LOG_FILE || ARGV[1], true)
else
  run(LOG_FILE || ARGV[0])
end