diff --git a/.gitignore b/.gitignore index dd7765e..84994fd 100644 --- a/.gitignore +++ b/.gitignore @@ -1,4 +1,5 @@ .bundle .rvmrc Gemfile.lock -*.gem \ No newline at end of file +*.gem +.DS_Store \ No newline at end of file diff --git a/Gemfile b/Gemfile index b82c8ec..f6a560f 100644 --- a/Gemfile +++ b/Gemfile @@ -1,6 +1,3 @@ source :rubygems -gem "mocha" -gem "activesupport" -gem "redgreen" -gem "bunny" \ No newline at end of file +gemspec \ No newline at end of file diff --git a/Readme.rdoc b/Readme.rdoc index 7f80960..6fec905 100644 --- a/Readme.rdoc +++ b/Readme.rdoc @@ -7,18 +7,18 @@ A ruby logger class that logs to an {AMQP}[http://www.amqp.org/] exchange in add By default the logs are routed to the host, exchange and key specified in DEFAULT_OPTIONS. You can change the configuration when creating the logger object by specifying an argument hash: - require 'amqp_logging' + require 'amqp_logging' - logging_config = { :routing_key => "applogging", - :host => AppConfig.amqp_logging.host, - :exchange => AppConfig.amqp_logging.exchange } + logging_config = { :routing_key => "applogging", + :host => AppConfig.amqp_logging.host, + :exchange => AppConfig.amqp_logging.exchange } - logger = AMQPLogging::Logger.new(config.log_path, logging_config) - config.logger = logger - + logger = AMQPLogging::Logger.new(config.log_path, logging_config) + config.logger = logger + With Rails 3 you will need to modify this a bit, as config.log_path no longer has the desired effect: - config.logger = AMQPLogging::Logger.new(config.paths.log.to_a.first, logging_config) + config.logger = AMQPLogging::Logger.new(config.paths.log.to_a.first, logging_config) ==Routing Keys @@ -27,18 +27,63 @@ receives the logline as the first argument and returns the routing key. Example: - # You can use a lambda or whatever responds to #call as the routing key generator - AMQPRoutingKeyGenerator = lambda do |logline| - if logline =~ /(?:engine\[([^\]]*)\])\: (Completed in|Processing|Session ID)?/ - key = "logs.app.#{$1}" - key << ".statistics" unless $2.nil? - else - key = "logs.app.system" - end - key - end - - AMQPLogging::Logger.new($stdout, :routing_key => AMQPRoutingKeyGenerator) + # You can use a lambda or whatever responds to #call as the routing key generator + AMQPRoutingKeyGenerator = lambda do |logline| + if logline =~ /(?:engine\[([^\]]*)\])\: (Completed in|Processing|Session ID)?/ + key = "logs.app.#{$1}" + key << ".statistics" unless $2.nil? + else + key = "logs.app.system" + end + key + end + + AMQPLogging::Logger.new($stdout, :routing_key => AMQPRoutingKeyGenerator) + +==Buffered JSON Logging + +You can also use the BufferedJSONLogger which will buffer all the loglines of a request and +send one JSON string after dispatching and handling the request has taken place. +This will happen right after the dispatcher has passed the request to the controller and the +controller has finished processing the request. All before, after and around filters +will have run, and even if the filter chain was halted, the logger will be flushed correctly. + +The output will basically look like the following example: + + { + "page":"FooController#index", // Controller and action + "severity":1, // the highest severity over all logged lines + "lines":[ // the list of loglines in the format 'severity', 'timestamp', 'logline' + [1,"02.11.2010T17:49:42.475422","Processing FooController#index (for 127.0.0.1 at 2010-11-02 17:49:42) [GET]"] + [1,"02.11.2010T17:49:42.477404","Completed in 2ms (View: 0, DB: 0) | 200 OK [http://localhost/foo]"] + ], + "process":24785, // the process id + "host":"pc-pfriederich" // the hostname + "custom_field_1":"foobar" // whatever custom fields you add + "benchmarks": { // another custom field, for example added by timebandits (http://http://github.com/skaes/time_bandits) + "sql_queries":197, + "total":2120, + "gc_time":22.4, + "memcache_hits":4 + } + } + +The BufferedJSONLogger is especially usefull when you plan to process the logs afterwards. +Let's say you have 20 or more application servers which all log via AMQP, and you want to have some +aggregated processing of the logs, request wise, it would be a pain in the ass to identify which logline +belongs to which request. You can also add all kinds of data to the JSON object that will get logged in +the end, so you don't have to figure that out afterwards by regexp parsing the loglines. +For most users, this feature won't be that interesting I guess. + +If you want to use the Buffered logger, require 'amqp_logging/buffered_json_logger/rails' in your environment.rb +and set the logger to an instance of AMQPLogging::BufferedJSONLogger.new. That's all. + + require 'amqp_logging/buffered_json_logger/rails' + + Rails::Initializer.run do |config| + logger = AMQPLogging::BufferedJSONLogger.new(config.log_path) + config.logger = logger + # ...whatever ==License diff --git a/amqp_logging.gemspec b/amqp_logging.gemspec index a91676d..840fdaf 100644 --- a/amqp_logging.gemspec +++ b/amqp_logging.gemspec @@ -23,5 +23,7 @@ Gem::Specification.new do |s| s.specification_version = 3 s.add_runtime_dependency("bunny", [">= 0.6.0"]) s.add_runtime_dependency("activesupport", [">= 2.3.0"]) + s.add_runtime_dependency("json", [">= 1.4.0"]) s.add_development_dependency("mocha", [">= 0"]) + s.add_development_dependency("redgreen", [">= 0"]) end diff --git a/lib/amqp_logging.rb b/lib/amqp_logging.rb old mode 100644 new mode 100755 index 793294e..26b06c7 --- a/lib/amqp_logging.rb +++ b/lib/amqp_logging.rb @@ -7,7 +7,9 @@ end module AMQPLogging + autoload :BufferedJSONLogger, 'amqp_logging/buffered_json_logger' end +require 'logger' require 'amqp_logging/logger' require 'amqp_logging/log_device' diff --git a/lib/amqp_logging/buffered_json_logger.rb b/lib/amqp_logging/buffered_json_logger.rb new file mode 100644 index 0000000..a446271 --- /dev/null +++ b/lib/amqp_logging/buffered_json_logger.rb @@ -0,0 +1,71 @@ +require 'json' + + +# in der rails app +module AMQPLogging + module SimpleFormatter + def self.call(severity, time, progname, msg) + msg + end + end + + class BufferedJSONLogger < Logger + attr_reader :buffer + attr_reader :fields + + def initialize(logdev, *args) + super + @default_formatter = SimpleFormatter + @default_fields = { + :host => Socket.gethostname.split('.').first, + :process => Process.pid + } + @fields = {} + @buffer = [] + end + + def add_field(name, value) + @fields[name] = value + end + + def add_fields(extra_fields) + @fields.merge!(extra_fields) + end + + def add(severity, message = nil, progname = nil, &block) + severity ||= UNKNOWN + if severity < @level + return true + end + progname ||= @progname + if message.nil? + if block_given? + message = yield + else + message = progname + progname = @progname + end + end + t = Time.now + formatted_message = format_message(format_severity(severity), t, progname, message).strip + @buffer << [severity, t.strftime("%d.%m.%YT%H:%M:%S.#{t.usec}"), formatted_message] + true + end + + def flush + @logdev.write(format_json) + @buffer = [] + @fields = {} + true + end + + private + def format_json + @default_fields.merge({ + :lines => @buffer.reverse, + :severity => @buffer.map {|l| l[0]}.max + }).merge(@fields).to_json + "\n" + end + + end +end \ No newline at end of file diff --git a/lib/amqp_logging/buffered_json_logger/rails.rb b/lib/amqp_logging/buffered_json_logger/rails.rb new file mode 100644 index 0000000..fbec1f1 --- /dev/null +++ b/lib/amqp_logging/buffered_json_logger/rails.rb @@ -0,0 +1,15 @@ +require 'amqp_logging' +require 'amqp_logging/buffered_json_logger/rails/after_dispatch_callback_handler' + + +ActionController::Dispatcher.after_dispatch do |dispatcher| + AMQPLogging::Rails::AfterDispatchCallbackHandler.run(dispatcher) +end + +class ActionController::Base + def log_processing_for_request_id_with_json_logger_preparation + logger.add_field :page, "#{self.class.name}\##{action_name}" + log_processing_for_request_id_without_json_logger_preparation + end + alias_method_chain :log_processing_for_request_id, :json_logger_preparation +end \ No newline at end of file diff --git a/lib/amqp_logging/buffered_json_logger/rails/after_dispatch_callback_handler.rb b/lib/amqp_logging/buffered_json_logger/rails/after_dispatch_callback_handler.rb new file mode 100644 index 0000000..db7fcdb --- /dev/null +++ b/lib/amqp_logging/buffered_json_logger/rails/after_dispatch_callback_handler.rb @@ -0,0 +1,27 @@ +module AMQPLogging + module Rails + class AfterDispatchCallbackHandler + def self.run(dispatcher) + env = dispatcher.instance_variable_get(:@env) + response = env["action_controller.rescue.response"] + request = env["action_controller.rescue.request"] + request_headers = request.headers.dup + request_headers.each do |k, v| + case v + when String, Fixnum, Numeric + else + request_headers[k] = "#<#{v.class.name}>" + end + end + + ActionController::Base.logger.add_fields({ + :env => RAILS_ENV, + :response_code => response.status, + :request_params => request.request_parameters, + :request_headers => request_headers, + :response_headers => response.headers + }) + end + end + end +end \ No newline at end of file diff --git a/test/buffered_logger_test.rb b/test/buffered_logger_test.rb new file mode 100644 index 0000000..37d2d95 --- /dev/null +++ b/test/buffered_logger_test.rb @@ -0,0 +1,73 @@ +require File.dirname(__FILE__) + '/test_helper.rb' + +module AMQPLogging + class TheBufferedJSONLoggerTest < Test::Unit::TestCase + def setup + @output = StringIO.new + @logger = BufferedJSONLogger.new(@output) + end + + test "should have all the convenience log methods of a regular logger" do + ::Logger::Severity.constants.map(&:downcase).each do |logmethod| + assert_nothing_raised do + @logger.send(logmethod, "foo") + end + end + end + + test "should not write the logs immediately" do + assert_equal "", @output.string + @logger.debug "foo" + assert_equal "", @output.string + end + + test "should write to the log when flush is called eventually" do + assert_equal "", @output.string + @logger.debug "foo" + @logger.flush + assert_match /foo/, @output.string + end + + test "should empty the buffer when flush is called" do + @logger.debug "foo" + @logger.flush + assert_equal [], @logger.buffer + end + end + + class BufferedLoggerJSONOutputTest < Test::Unit::TestCase + def setup + @output = StringIO.new + @logger = BufferedJSONLogger.new(@output) + @logger.debug "foo" + @logger.warn "bar" + @logger.info "baz" + @logger.flush + @json = JSON.parse(@output.string) + end + + test "should have the loglines in a array called lines" do + assert @json["lines"].instance_of?(Array) + assert_equal 3, @json["lines"].size + end + + test "should have each logline with severity, a timestamp and the message" do + severity, timestamp, message = @json["lines"][2] + assert_equal Logger::DEBUG, severity + assert_nothing_raised { Time.parse(timestamp) } + assert_equal "foo", message + end + + test "should have a field with the highest severity" do + assert_equal Logger::WARN, @json["severity"] + end + + test "should have a field with the process id" do + assert_equal Process.pid, @json["process"] + end + + test "should have a field with the hostname" do + assert_equal Socket.gethostname.split('.').first, @json["host"] + end + end +end \ No newline at end of file