tcp_syslog.rb

require 'socket'
require 'syslog'
require 'logger'
require 'hoptoad_notifier'

# TcpSyslog is used are a dead-simple replacement for
# syslog ruby libs. None of them is able to send logs
# to a remote server, and even less in TCP.
#
# Example:
#
# For rails (2.X) :
#
#   config.logger = TcpSyslog.new(host => 'localhost')
#
# For more info about Syslog protocol, please refer to the RFC:
# http://www.faqs.org/rfcs/rfc3164.html
#
# Parts taken from SyslogLogger gem and ActiveSupport
#
class TcpSyslog < ActiveSupport::BufferedLogger
  include Logger::Severity

  # From 'man syslog.h':
  # LOG_EMERG   A panic condition was reported to all processes.
  # LOG_ALERT   A condition that should be corrected immediately.
  # LOG_CRIT    A critical condition.
  # LOG_ERR     An error message.
  # LOG_WARNING A warning message.
  # LOG_NOTICE  A condition requiring special handling.
  # LOG_INFO    A general information message.
  # LOG_DEBUG   A message useful for debugging programs.

  # From logger rdoc:
  # FATAL:  an unhandleable error that results in a program crash
  # ERROR:  a handleable error condition
  # WARN:   a warning
  # INFO:   generic (useful) information about system operation
  # DEBUG:  low-level information for developers

  # Maps Logger warning types to syslog(3) warning types.
  LOGGER_MAP = {
    :unknown => Syslog::LOG_ALERT,
    :fatal   => Syslog::LOG_CRIT,
    :error   => Syslog::LOG_ERR,
    :warn    => Syslog::LOG_WARNING,
    :info    => Syslog::LOG_INFO,
    :debug   => Syslog::LOG_DEBUG
  }

  # Maps Logger log levels to their values so we can silence.
  LOGGER_LEVEL_MAP = {}

  LOGGER_MAP.each_key do |key|
    LOGGER_LEVEL_MAP[key] = Logger.const_get key.to_s.upcase
  end

  # Maps Logger log level values to syslog log levels.
  LEVEL_LOGGER_MAP = {}

  LOGGER_LEVEL_MAP.invert.each do |level, severity|
    LEVEL_LOGGER_MAP[level] = LOGGER_MAP[severity]
  end

  MAX_BUFFER_SIZE = 1000

  # Builds a methods for level +meth+.
  for severity in Logger::Severity.constants
    class_eval <<-EOT, __FILE__, __LINE__
    def #{severity.downcase}(message = nil, progname = nil, &block)  # def debug(message = nil, progname = nil, &block)
      add(#{severity}, message, progname, &block)                    #   add(DEBUG, message, &block)
    end                                                              # end
    #
    def #{severity.downcase}?                                        # def debug?
      #{severity} >= @level                                          #   DEBUG >= @level
    end                                                              # end
    EOT
  end

  # Usage :
  # * +options+ : A hash with the following options
  # ** +host+ : defaults to 'localhost'
  # ** +port+ : defaults to '514'
  # ** +facility+ : defaults to user
  # ** +progname+ : defaults to 'rails'
  # ** +auto_flushing+ : number of messages to buffer before flushing
  #
  def initialize(options = {})
    @level = LOGGER_LEVEL_MAP[options[:level]] || Logger::DEBUG
    @host = options[:host] || 'localhost'
    @port = options[:port] = '514'
    @facility = options[:facility] || Syslog::LOG_USER
    @progname = options[:progname] || 'rails'
    @buffer = {}
    @socket = {}
    @auto_flushing = options[:auto_flushing] || 1
    @local_ip = local_ip
    return if defined? SYSLOG
    self.class.const_set :SYSLOG, true
  end


  # Log level for Logger compatibility.
  attr_reader :host, :port, :facility, :auto_flushing, :progname
  # Check ActiveSupport::BufferedLogger for other attributes

  # Almost duplicates Logger#add.
  def add(severity, message, progname = nil, &block)
    severity ||= Logger::UNKNOWN
    return if @level > severity
    message = clean(message || block.call)
    buffer << {:severity => severity, :body => clean(message)}
    auto_flush
    message
  end

  # In Logger, this dumps the raw message; the closest equivalent
  # would be Logger::UNKNOWN
  def <<(message)
    add(Logger::UNKNOWN, message)
  end

  def close
    flush
    socket.close
  end

  # Flush buffered logs to Syslog
  def flush
    buffer.each do |message|
      log(message[:severity], message[:body])
    end
    clear_buffer
  end

  def socket
    @socket[Thread.current] ||= TCPSocket.new(@host, @port)
  end

  protected

  # Clean up messages so they're nice and pretty.
  def clean(message)
    message = message.to_s.dup
    message.strip!
    message.gsub!(/%/, '%%') # syslog(3) freaks on % (printf)
    message.gsub!(/\e\[[^m]*m/, '') # remove useless ansi color codes
    return message
  end

  # Returns current ip
  # (taken from http://coderrr.wordpress.com/2008/05/28/get-your-local-ip-address/)
  def local_ip
    orig, Socket.do_not_reverse_lookup = Socket.do_not_reverse_lookup, true  # turn off reverse DNS resolution temporarily

    UDPSocket.open do |s|
      s.connect '64.233.187.99', 1
      s.addr.last
    end
  ensure
    Socket.do_not_reverse_lookup = orig
  end

  # Log the message to syslog
  # This method is private, use the +add+ method instead
  def log(severity, msg)
    begin
      if @progname.length + msg.length > 996 # see RFC, max size for a message is 1024 bytes
        msg.scan(/.{#{996 - @progname.length}}/).each do |chunck|
          write_on_socket(severity, chunck)
        end
      else
        write_on_socket(severity, msg)
      end
    rescue Errno::ECONNREFUSED, Errno::EPIPE => e
      HoptoadNotifier.notify e # can't log, how would we know ??
    end
  end

  # actually write on the tcp socket
  def write_on_socket(severity, msg)
    socket.write("<#{@facility + LEVEL_LOGGER_MAP[severity]}>#{Time.now.strftime("%b %e %H:%M:%S")} #{@local_ip} [#{@progname}]: #{msg}\n")
  end
end

tcp_syslog_benchmark.rb

#!/usr/bin/env ruby
require 'benchmark'
require 'rubygems'
require 'active_support'
require 'lib/tcp_syslog'

logger_tcp = TcpSyslog.new
logger_file = ActiveSupport::BufferedLogger.new("/tmp/logfile")

Benchmark.bm do |b| 
  b.report("File") do
    100.times { logger_file.info("benchmark") }
  end 

  b.report("TCP") do
    100.times { logger_tcp.info("benchmark") }
  end 

  logger_file.auto_flushing = 20
  b.report("File (buffer = 20)") do
    100.times { logger_file.info("benchmark") }
  end 

  logger_tcp.auto_flushing = 20
  b.report("TCP (buffer = 20)") do
    100.times { logger_tcp.info("benchmark") }
  end 
end

# => 
#      user     system      total        real
# File  0.000000   0.010000   0.010000 (  0.002294)
# TCP  0.010000   0.000000   0.010000 (  0.011050)
# File (buffer = 20)  0.000000   0.000000   0.000000 (  0.000841)
# TCP (buffer = 20)  0.000000   0.000000   0.000000 (  0.009806)

tcp_syslog_test.rb

# Using test-unit, should and RR for tests

require 'test_helper.rb'
require 'syslog'

class TcpSyslogTest < ActiveSupport::TestCase

  context "A TcpSyslogger" do
    setup do
      @logger = TcpSyslog.new
    end

    should "have set defaults correctly" do
      assert_equal 'localhost', @logger.host
      assert_equal '514', @logger.port
      assert_equal Syslog::LOG_USER, @logger.facility
      assert_equal 'rails', @logger.progname
      assert_equal 1, @logger.auto_flushing
      assert_equal Logger::DEBUG, @logger.level
    end

    should "have defined debug, info, warn, error, fatal methods" do
      assert @logger.respond_to?(:debug)
      assert @logger.respond_to?(:info)
      assert @logger.respond_to?(:warn)
      assert @logger.respond_to?(:error)
      assert @logger.respond_to?(:fatal)
    end

    context "on add message" do
      setup do
        message = "This message to be sent to syslog"
        mock.proxy(@logger).flush
        mock.proxy(@logger).log(Logger::INFO, message)
        mock.proxy(@logger).write_on_socket(Logger::INFO, message)
        @logger.add(Logger::INFO, message)
      end

      should "have sent the message to syslog" do
        RR.verify
      end
    end
  end

  context "A TcpSyslogger with auto_flushing set to 2" do
    setup do
      @logger = TcpSyslog.new(:auto_flushing => 2)
    end

    should "have set auto_flushing to 2" do
      assert_equal 2, @logger.auto_flushing
    end

    context "when adding a message" do
      setup do
        message = "info message"
        dont_allow(@logger).write_on_socket(Logger::INFO, message)
        @logger.info(message)
      end

      should "not send the message to syslog now" do
        RR.verify
      end

      context "and adding another message" do
        setup do
          message2 = "info message 2"
          RR.reset
          mock.proxy(@logger).write_on_socket(Logger::INFO, anything).twice
          @logger.info(message2)
        end

        should "have sent the messages to syslog" do
          RR.verify
        end
      end
    end
  end
end