diff --git a/Gemfile b/Gemfile index 2ca61bf..79fa0a4 100644 --- a/Gemfile +++ b/Gemfile @@ -4,12 +4,9 @@ source "https://rubygems.org" gemspec group :test do - gem 'growl' - gem 'guard' - gem 'guard-rspec' - gem 'rails', "~> #{ENV["RAILS_VERSION"] || "3.2.0"}" - gem 'rb-fsevent', '~> 0.9' - gem 'rcov', :platforms => :mri_18 - gem 'redis', :require => false - gem 'simplecov', :platforms => :mri_19, :require => false + gem 'pry-nav' + gem 'rails' + gem 'timecop' + + gem 'syslog' end diff --git a/Guardfile b/Guardfile deleted file mode 100644 index 4dda56e..0000000 --- a/Guardfile +++ /dev/null @@ -1,10 +0,0 @@ -# A sample Guardfile -# More info at https://github.com/guard/guard#readme -interactor :simple - -guard 'rspec', :version => 2 do - watch(%r{^spec/.+_spec\.rb$}) - watch(%r{^lib/(.+)\.rb$}) { |m| "spec/lib/#{m[1]}_spec.rb" } - watch('spec/spec_helper.rb') { "spec" } -end - diff --git a/LICENSE.md b/LICENSE.md new file mode 100644 index 0000000..f0209c9 --- /dev/null +++ b/LICENSE.md @@ -0,0 +1,21 @@ +The MIT License (MIT) + +Copyright (c) 2014 Shadab Ahmed + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +SOFTWARE. diff --git a/README.md b/README.md index 91f6e38..7a26d7d 100644 --- a/README.md +++ b/README.md @@ -1,28 +1,22 @@ -# Logstasher [![Gem Version](https://badge.fury.io/rb/logstasher.png)](http://badge.fury.io/rb/logstasher) [![Build Status](https://secure.travis-ci.org/shadabahmed/logstasher.png)](https://secure.travis-ci.org/shadabahmed/logstasher) -### Awesome Logging for Rails !! +# Logstasher -This gem is heavily inspired from [lograge](https://github.com/roidrage/lograge), but it's focused on one thing and one thing only. That's making your logs awesome like this: +**Awesome Logging for Rails** -[![Awesome Logs](http://i.imgur.com/zZXWQNp.png)](http://i.imgur.com/zZXWQNp.png) +## History -How it's done ? +This is a fork of +[shadabahmed/logstasher](https://github.com/shadabahmed/logstasher). It has +been updated to use the [latest event +schema](https://logstash.jira.com/browse/LOGSTASH-675) and customized to better +fit the needs of MoneyDesktop--though it is still generally useful. It is not +backward compatible with its progenitor. -By, using these awesome tools: -* [Logstash](http://logstash.net) - Store and index your logs -* [Kibana](http://kibana.org/) - for awesome visualization. This is optional though, and you can use any other visualizer +## Purpose -To know how to setup these tools - visit my [blog](http://shadabahmed.com/blog/2013/04/30/logstasher-for-awesome-rails-logging) +This gem makes it easy to generate logstash compatible logs for your rails app. -## About logstasher - -This gem purely focuses on how to generate logstash compatible logs i.e. *logstash json event format*, without any overhead. Infact, logstasher logs to a separate log file named `logstash_.log`. -The reason for this separation: - * To have a pure json log file - * Prevent any logger messages(e.g. info) getting into our pure json logs - -Before **logstasher** : - -``` +A request that looks like this in your `production.log`: +```text Started GET "/login" for 10.109.10.135 at 2013-04-30 08:59:01 -0400 Processing by SessionsController#new as HTML Rendered sessions/new.html.haml within layouts/application (4.3ms) @@ -34,68 +28,70 @@ Processing by SessionsController#new as HTML Completed 200 OK in 532ms (Views: 62.4ms | ActiveRecord: 0.0ms | ND API: 0.0ms) ``` -After **logstasher**: - -``` -{"@source":"unknown","@tags":["request"],"@fields":{"method":"GET","path":"/","format":"html","controller":"file_servers" +Will look like this in your `logstash_production.log`: +```json +{"tags":["request"],"method":"GET","path":"/","format":"html","controller":"file_servers" ,"action":"index","status":200,"duration":28.34,"view":25.96,"db":0.88,"ip":"127.0.0.1","route":"file_servers#index", "parameters":"","ndapi_time":null,"uuid":"e81ecd178ed3b591099f4d489760dfb6","user":"shadab_ahmed@abc.com", -"site":"internal"},"@timestamp":"2013-04-30T13:00:46.354500+00:00"} +"site":"internal","@timestamp":"2013-04-30T13:00:46.354500+00:00","@version":"1"} ``` -By default, the older format rails request logs are disabled, though you can enable them. +From there, it's trivial to forward them to your logstash indexer. You can even +use the included redis log device to send the logs directly to a redis broker +instead. ## Installation In your Gemfile: - gem 'logstasher' + gem 'md-logstasher' ### Configure your `.rb` e.g. `development.rb` # Enable the logstasher logs for the current environment config.logstasher.enabled = true - # This line is optional if you do not want to suppress app logs in your .log - config.logstasher.suppress_app_log = false + # Optionally silience the standard logging to .log + config.logstasher.silence_standard_logging = true + +## Logging params -## Logging params hash +By default, Logstasher will add params as a JSON encoded string. To disable, +add the following to your `.rb` -Logstasher can be configured to log the contents of the params hash. When enabled, the contents of the params hash (minus the ActionController internal params) -will be added to the log as a deep hash. This can cause conflicts within the Elasticsearch mappings though, so should be enabled with care. Conflicts will occur -if different actions (or even different applications logging to the same Elasticsearch cluster) use the same params key, but with a different data type (e.g. a -string vs. a hash). This can lead to lost log entries. Enabling this can also significantly increase the size of the Elasticsearch indexes. + # Disable logging of request parameters + config.logstasher.include_parameters = false -To enable this, add the following to your `.rb` +If you want the parameters to be sent unserialized, so they are indexed and +searchable individually in elasticsearch, skip the serialization step. + + # Log parameters individually + config.logstasher.serialize_parameters = false - # Enable logging of controller params - config.logstasher.log_controller_parameters = true ## Adding custom fields to the log -Since some fields are very specific to your application for e.g. *user_name*, so it is left upto you, to add them. Here's how to add those fields to the logs: +Since some fields are very specific to your application, e.g., *user_name*, +it is left upto you to add them. Here's how to do it: # Create a file - config/initializers/logstasher.rb if LogStasher.enabled - LogStasher.add_custom_fields do |fields| - # This block is run in application_controller context, - # so you have access to all controller methods + LogStasher.append_fields do |fields| + # This block is run within the context of the controller handling the + # request, so you have access to all its methods and instance variables fields[:user] = current_user && current_user.mail fields[:site] = request.path =~ /^\/api/ ? 'api' : 'user' - - # If you are using custom instrumentation, just add it to logstasher custom fields - LogStasher.custom_fields << :myapi_runtime end end ## Versions -All versions require Rails 3.0.x and higher and Ruby 1.9.2+. Tested on Rails 4 and Ruby 2.0 +All versions require Rails 3.0.x and higher and Ruby 1.9.2+. Tested on Rails 4 +and Ruby 2.0 ## Development - Run tests - `rake` - - Generate test coverage report - `rake coverage`. Coverage report path - coverage/index.html ## Copyright -Copyright (c) 2013 Shadab Ahmed, released under the MIT license +Copyright (c) 2014 Shadab Ahmed, released under the MIT license diff --git a/Rakefile b/Rakefile index 9566fe8..190f0b8 100644 --- a/Rakefile +++ b/Rakefile @@ -1,21 +1,17 @@ -require "bundler/gem_tasks" +require 'bundler/gem_tasks' require 'rspec/core/rake_task' -# Add default task. When you type just rake command this would run. Travis CI runs this. Making this run spec desc 'Default: run specs.' task :default => :spec -# Defining spec task for running spec desc "Run specs" RSpec::Core::RakeTask.new('spec') do |spec| - # Pattern filr for spec files to run. This is default btw. spec.pattern = "./spec/**/*_spec.rb" end -# Run the rdoc task to generate rdocs for this gem require 'rdoc/task' RDoc::Task.new do |rdoc| - require "logstasher/version" + require 'logstasher/version' version = LogStasher::VERSION rdoc.rdoc_dir = 'rdoc' @@ -23,20 +19,3 @@ RDoc::Task.new do |rdoc| rdoc.rdoc_files.include('README*') rdoc.rdoc_files.include('lib/**/*.rb') end - -# Code coverage tasks. Different for Ruby 1.8 vs 1.9 -if RUBY_VERSION =~ /^1\.8/ - # Ruby 1.8 uses rcov for code coverage - RSpec::Core::RakeTask.new(:coverage) do |spec| - spec.pattern = 'spec/**/*_spec.rb' - spec.rcov = true - spec.rcov_opts = %w{--exclude pkg\/,spec\/,features\/} - end -else - # Ruby 1.9+ using simplecov. Note: Simplecov config defined in spec_helper - desc "Code coverage detail" - task :coverage do - ENV['COVERAGE'] = "true" - Rake::Task['spec'].execute - end -end \ No newline at end of file diff --git a/lib/logstasher.rb b/lib/logstasher.rb index ffbb166..192da02 100644 --- a/lib/logstasher.rb +++ b/lib/logstasher.rb @@ -1,104 +1,133 @@ -require 'logstasher/version' -require 'logstasher/log_subscriber' -require 'active_support/core_ext/module/attribute_accessors' -require 'active_support/core_ext/string/inflections' -require 'active_support/ordered_options' +require 'logger' +require 'logstash-event' module LogStasher - extend self - attr_accessor :logger, :enabled, :log_controller_parameters - - def remove_existing_log_subscriptions - ActiveSupport::LogSubscriber.log_subscribers.each do |subscriber| - case subscriber - when ActionView::LogSubscriber - unsubscribe(:action_view, subscriber) - when ActionController::LogSubscriber - unsubscribe(:action_controller, subscriber) + class << self + attr_reader :append_fields_callback + attr_writer :enabled + attr_writer :include_parameters + attr_writer :serialize_parameters + attr_writer :silence_standard_logging + attr_accessor :metadata + attr_accessor :default_device + + def load_from_config(config) + ::LogStasher.logger = ::Logger.new("/dev/null") + + config.each do |key,value| + key = key.to_s + case key + when 'metadata' + ::LogStasher.metadata = value + when 'device' + ::LogStasher.default_device = ::LogStasher::Device.factory(value) + ::LogStasher.logger = ::Logger.new(::LogStasher.default_device) + when 'include_parameters' + ::LogStasher.include_parameters = value + when 'serialize_parameters' + ::LogStasher.serialize_parameters = value + when 'silence_standard_logging' + ::LogStasher.silence_standard_logging = value + end end end - end - def unsubscribe(component, subscriber) - events = subscriber.public_methods(false).reject{ |method| method.to_s == 'call' } - events.each do |event| - ActiveSupport::Notifications.notifier.listeners_for("#{event}.#{component}").each do |listener| - if listener.instance_variable_get('@delegate') == subscriber - ActiveSupport::Notifications.unsubscribe listener - end + def append_fields(&block) + @append_fields_callback = block + end + + def dry_validation_contract=(contract) + if contract && !contract.is_a?(::Dry::Validation::Contract) + raise ArgumentError, "Expected a Dry::Validation::Contract, got #{contract.class}" end + @dry_validation_contract = contract end - end - def add_default_fields_to_payload(payload, request) - payload[:ip] = request.remote_ip - payload[:route] = "#{request.params[:controller]}##{request.params[:action]}" - self.custom_fields += [:ip, :route] - if self.log_controller_parameters - payload[:parameters] = payload[:params].except(*ActionController::LogSubscriber::INTERNAL_PARAMS) - self.custom_fields += [:parameters] + def dry_validation_contract + @dry_validation_contract end - end - def add_custom_fields(&block) - ActionController::Metal.send(:define_method, :logtasher_add_custom_fields_to_payload, &block) - ActionController::Base.send(:define_method, :logtasher_add_custom_fields_to_payload, &block) - end + def enabled? + if @enabled.nil? + @enabled = false + end - def setup(app) - app.config.action_dispatch.rack_cache[:verbose] = false if app.config.action_dispatch.rack_cache - # Path instrumentation class to insert our hook - require 'logstasher/rails_ext/action_controller/metal/instrumentation' - require 'logstash-event' - self.suppress_app_logs(app) - LogStasher::RequestLogSubscriber.attach_to :action_controller - self.logger = app.config.logstasher.logger || new_logger("#{Rails.root}/log/logstash_#{Rails.env}.log") - self.logger.level = app.config.logstasher.log_level || Logger::WARN - self.enabled = true - self.log_controller_parameters = !! app.config.logstasher.log_controller_parameters - end + @enabled + end - def suppress_app_logs(app) - if configured_to_suppress_app_logs?(app) - require 'logstasher/rails_ext/rack/logger' - LogStasher.remove_existing_log_subscriptions + def include_parameters? + if @include_parameters.nil? + @include_parameters = true + end + + @include_parameters end - end - def configured_to_suppress_app_logs?(app) - # This supports both spellings: "suppress_app_log" and "supress_app_log" - !!(app.config.logstasher.suppress_app_log.nil? ? app.config.logstasher.supress_app_log : app.config.logstasher.suppress_app_log) - end + def serialize_parameters? + if @serialize_parameters.nil? + @serialize_parameters = true + end - def custom_fields - Thread.current[:logstasher_custom_fields] ||= [] - end + @serialize_parameters + end - def custom_fields=(val) - Thread.current[:logstasher_custom_fields] = val - end + def initialize_logger(device = $stdout, level = ::Logger::INFO) + ::Logger.new(device).tap do |new_logger| + new_logger.level = level + end + end + def log_as_json(payload, as_logstash_event: false) + payload = payload.dup + + # Merge in metadata if configured. This supports a Hash and a fully formed + # LogStash::Event. + if !metadata.empty? + payload.merge!(:metadata => metadata) if payload.is_a?(::Hash) + payload.append(:metadata => metadata) if payload.is_a?(::LogStash::Event) + end - def log(severity, msg) - if self.logger && self.logger.send("#{severity}?") - event = LogStash::Event.new('@fields' => {:message => msg, :level => severity},'@tags' => ['log']) - self.logger.send severity, event.to_json + # Wrap the hash in a logstash event if the caller wishes for a specific + # formatting applied to the hash. This is used by log subscriber, for + # example. + payload = ::LogStash::Event.new(payload) if as_logstash_event + + # Validate payload if a dry_validation_contract is configured + payload = validate_payload(payload) if dry_validation_contract + + logger << payload.to_json + $INPUT_RECORD_SEPARATOR + end + + def logger + @logger ||= initialize_logger + end + + def logger=(log) + @logger = log end - end - %w( fatal error warn info debug unknown ).each do |severity| - eval <<-EOM, nil, __FILE__, __LINE__ + 1 - def #{severity}(msg) - self.log(:#{severity}, msg) + def silence_standard_logging? + if @silence_standard_logging.nil? + @silence_standard_logging = false end - EOM - end + + @silence_standard_logging + end private - def new_logger(path) - FileUtils.touch path # prevent autocreate messages in log - Logger.new path + def validate_payload(payload) + return payload unless payload.is_a?(::LogStash::Event) || payload.is_a?(::Hash) + + formatted_payload = ::JSON.parse(payload.to_json).deep_symbolize_keys + validation_results = dry_validation_contract.call(formatted_payload) + validation_metadata = { + dry_validation_success: validation_results.success?, + dry_validation_errors: validation_results.errors.to_h.to_json + } + + formatted_payload.deep_merge(validation_results.to_h).merge(validation_metadata) + end end end diff --git a/lib/logstasher/context_wrapper.rb b/lib/logstasher/context_wrapper.rb new file mode 100644 index 0000000..1fe64ac --- /dev/null +++ b/lib/logstasher/context_wrapper.rb @@ -0,0 +1,14 @@ +module LogStasher + module ContextWrapper + def process_action(*) + Thread.current[:logstasher_context] = { + :controller => self, + :request => request + } + + super + ensure + Thread.current[:logstasher_context] = nil + end + end +end diff --git a/lib/logstasher/device.rb b/lib/logstasher/device.rb new file mode 100644 index 0000000..117ad3f --- /dev/null +++ b/lib/logstasher/device.rb @@ -0,0 +1,32 @@ +module LogStasher + module Device + def self.factory(config) + config = stringify_keys(config) + type = config.delete('type') or fail ArgumentError, 'No "type" given' + + case type + when 'redis', :redis then + require 'logstasher/device/redis' + ::LogStasher::Device::Redis.new(config) + when "syslog", :syslog then + require 'logstasher/device/syslog' + ::LogStasher::Device::Syslog.new(config) + when "udp", :udp then + require 'logstasher/device/udp' + ::LogStasher::Device::UDP.new(config) + when "stdout", :stdout then + $stdout + else + fail ArgumentError, "Unknown type: #{type}" + end + end + + def stringify_keys(hash) + hash.inject({}) do |stringified_hash, (key, value)| + stringified_hash[key.to_s] = value + stringified_hash + end + end + module_function :stringify_keys + end +end diff --git a/lib/logstasher/device/redis.rb b/lib/logstasher/device/redis.rb index eb6d5ce..7187cb6 100644 --- a/lib/logstasher/device/redis.rb +++ b/lib/logstasher/device/redis.rb @@ -1,23 +1,26 @@ +require 'logstasher/device' require 'redis' module LogStasher module Device class Redis + include ::LogStasher::Device attr_reader :options, :redis def initialize(options = {}) - @options = default_options.merge(options) + @options = default_options.merge(stringify_keys(options)) + validate_options configure_redis end def data_type - options[:data_type] + options['data_type'] end def key - options[:key] + options['key'] end def redis_options @@ -51,12 +54,12 @@ def configure_redis end def default_options - { key: 'logstash', data_type: 'list' } + { 'key' => 'logstash', 'data_type' => 'list' } end def validate_options - unless ['list', 'channel'].include?(options[:data_type]) - fail 'Expected :data_type to be either "list" or "channel"' + unless ['list', 'channel'].include?(options['data_type']) + fail RuntimeError, 'Expected data_type to be either "list" or "channel"' end end end diff --git a/lib/logstasher/device/syslog.rb b/lib/logstasher/device/syslog.rb new file mode 100644 index 0000000..539eb76 --- /dev/null +++ b/lib/logstasher/device/syslog.rb @@ -0,0 +1,93 @@ +# inspired by [lumberjack](https://github.com/bdurand/lumberjack_syslog_device) + +require 'logstasher/device' +require 'syslog' + +module LogStasher + module Device + class Syslog + include ::LogStasher::Device + + attr_reader :options + + def initialize(options = {}) + raw_options = default_options.merge(stringify_keys(options)) + + @options = parse_options(raw_options) + open_syslog + end + + def close + ::Syslog.close rescue nil + end + + def closed? + !::Syslog.opened? + end + + def facility + options['facility'] + end + + def flags + options['flags'] + end + + def identity + options['identity'] + end + + def priority + options['priority'] + end + + def write(log) + fail ::RuntimeError, 'Syslog has been closed.' if closed? + fail ::RuntimeError, 'Syslog re-configured unexpectedly.' if syslog_config_changed? + + ::Syslog.log(priority, '%s', log) + end + + private + + def default_options + { + 'identity' => 'logstasher', + 'facility' => ::Syslog::LOG_LOCAL0, + 'priority' => ::Syslog::LOG_INFO, + 'flags' => ::Syslog::LOG_PID | ::Syslog::LOG_CONS, + } + end + + def open_syslog + if ::Syslog.opened? + ::Syslog.reopen(identity, flags, facility) + else + ::Syslog.open(identity, flags, facility) + end + end + + def parse_option(value) + case value + when ::String + ::Syslog.const_get(value.to_s) + when ::Array + value.reduce(0) { |all, current| all |= parse_option(current) } + else + value + end + end + + def parse_options(options) + options['facility'] = parse_option(options['facility']) + options['priority'] = parse_option(options['priority']) + options['flags'] = parse_option(options['flags']) + options + end + + def syslog_config_changed? + ::Syslog.ident != identity || ::Syslog.options != flags || ::Syslog.facility != facility + end + end + end +end diff --git a/lib/logstasher/device/udp.rb b/lib/logstasher/device/udp.rb new file mode 100644 index 0000000..16f1ef1 --- /dev/null +++ b/lib/logstasher/device/udp.rb @@ -0,0 +1,40 @@ +# simple UDP logger + +require 'logstasher/device' +require 'socket' + + +module LogStasher + module Device + class UDP + include ::LogStasher::Device + + attr_reader :options, :socket + + def initialize(options = {}) + @options = default_options.merge(stringify_keys(options)) + @socket = UDPSocket.new + end + + def close + @socket.close + end + + def write(log) + @socket.send(log, 0, options['hostname'], options['port']) + end + + private + + def default_options + { + 'hostname' => '127.0.0.1', + 'port' => 31459, + } + end + end + end +end + + + diff --git a/lib/logstasher/log_subscriber.rb b/lib/logstasher/log_subscriber.rb index 362c06d..0c422f1 100644 --- a/lib/logstasher/log_subscriber.rb +++ b/lib/logstasher/log_subscriber.rb @@ -1,42 +1,76 @@ -require 'active_support/core_ext/class/attribute' +require 'action_controller/log_subscriber' require 'active_support/log_subscriber' +require 'active_support/core_ext/hash/except' +require 'json' +require 'logstash/event' + +# active_support monkeypatches Hash#to_json with a version that does not encode +# time correctly for LogStash. Using JSON.generate bypasses the monkeypatch. +class LogStash::Event + def to_json + return JSON.generate(@data) + end +end module LogStasher - class RequestLogSubscriber < ActiveSupport::LogSubscriber + class LogSubscriber < ::ActiveSupport::LogSubscriber + + INTERNAL_PARAMS = ::ActionController::LogSubscriber::INTERNAL_PARAMS + def process_action(event) payload = event.payload + tags = extract_tags(payload) + fields = extract_request(payload) + fields.merge! extract_status(payload) + fields.merge! runtimes(event) + fields.merge! location + fields.merge! extract_exception(payload) + fields.merge! extract_parameters(payload) + fields.merge! appended_fields - data = extract_request(payload) - data.merge! extract_status(payload) - data.merge! runtimes(event) - data.merge! location(event) - data.merge! extract_exception(payload) - data.merge! extract_custom_fields(payload) - - tags = ['request'] - tags.push('exception') if payload[:exception] - event = LogStash::Event.new('@fields' => data, '@tags' => tags) - LogStasher.logger << event.to_json + "\n" + LogStasher.log_as_json(fields.merge('tags' => tags), :as_logstash_event => true) end def redirect_to(event) - Thread.current[:logstasher_location] = event.payload[:location] + Thread.current[:logstasher_context][:location] = event.payload[:location] end private + def appended_fields + callback = ::LogStasher.append_fields_callback + {}.tap do |fields| + controller.instance_exec(fields, &callback) if callback + end + end + + def controller + Thread.current[:logstasher_context][:controller] + end + def extract_request(payload) { - :method => payload[:method], - :path => extract_path(payload), - :format => extract_format(payload), - :controller => payload[:params]['controller'], - :action => payload[:params]['action'] + :action => payload[:action], + :controller => payload[:controller], + :format => extract_format(payload), + :ip => request.remote_ip, + :request_id => request.env["action_dispatch.request_id"], + :method => payload[:method], + :path => extract_path(payload), + :route => "#{payload[:controller]}##{payload[:action]}" } end - def extract_path(payload) - payload[:path].split("?").first + # Monkey patching to enable exception logging + def extract_exception(payload) + if payload[:exception] + exception, message = payload[:exception] + status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception) + message = "#{exception}\n#{message}\n#{($!.backtrace.join("\n"))}" + { :status => status, :error => message } + else + {} + end end def extract_format(payload) @@ -47,6 +81,23 @@ def extract_format(payload) end end + def extract_parameters(payload) + if LogStasher.include_parameters? + external_params = payload[:params].except(*INTERNAL_PARAMS) + if LogStasher.serialize_parameters? + { :params => JSON.generate(external_params) } + else + { :params => external_params } + end + else + {} + end + end + + def extract_path(payload) + payload[:path].split("?").first + end + def extract_status(payload) if payload[:status] { :status => payload[:status].to_i } @@ -55,42 +106,37 @@ def extract_status(payload) end end - def runtimes(event) - { - :duration => event.duration, - :view => event.payload[:view_runtime], - :db => event.payload[:db_runtime] - }.inject({}) do |runtimes, (name, runtime)| - runtimes[name] = runtime.to_f.round(2) if runtime - runtimes - end + def extract_tags(payload) + tags = ['request'] + tags.push('exception') if payload[:exception] + tags end - def location(event) - if location = Thread.current[:logstasher_location] - Thread.current[:logstasher_location] = nil + def location + location = Thread.current[:logstasher_context][:location] + + if location { :location => location } else {} end end - # Monkey patching to enable exception logging - def extract_exception(payload) - if payload[:exception] - exception, message = payload[:exception] - status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception) - message = "#{exception}\n#{message}\n#{($!.backtrace.join("\n"))}" - { :status => status, :error => message } - else - {} - end + def request + Thread.current[:logstasher_context][:request] end - def extract_custom_fields(payload) - custom_fields = (!LogStasher.custom_fields.empty? && payload.extract!(*LogStasher.custom_fields)) || {} - LogStasher.custom_fields.clear - custom_fields + def runtimes(event) + { + :total => event.duration, + :view => event.payload[:view_runtime], + :db => event.payload[:db_runtime] + }.inject({:runtime => {}}) do |runtimes, (name, runtime)| + runtimes[:runtime][name] = runtime.to_f.round(2) if runtime + runtimes + end end end end + +::LogStasher::LogSubscriber.attach_to :action_controller diff --git a/lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb b/lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb deleted file mode 100644 index 598f943..0000000 --- a/lib/logstasher/rails_ext/action_controller/metal/instrumentation.rb +++ /dev/null @@ -1,33 +0,0 @@ -module ActionController - module Instrumentation - def process_action(*args) - raw_payload = { - :controller => self.class.name, - :action => self.action_name, - :params => request.filtered_parameters, - :format => request.format.try(:ref), - :method => request.method, - :path => (request.fullpath rescue "unknown") - } - - LogStasher.add_default_fields_to_payload(raw_payload, request) - if self.respond_to?(:logtasher_add_custom_fields_to_payload) - before_keys = raw_payload.keys.clone - logtasher_add_custom_fields_to_payload(raw_payload) - after_keys = raw_payload.keys - # Store all extra keys added to payload hash in payload itself. This is a thread safe way - LogStasher.custom_fields += after_keys - before_keys - end - - ActiveSupport::Notifications.instrument("start_processing.action_controller", raw_payload.dup) - - ActiveSupport::Notifications.instrument("process_action.action_controller", raw_payload) do |payload| - result = super - payload[:status] = response.status - append_info_to_payload(payload) - result - end - end - - end -end \ No newline at end of file diff --git a/lib/logstasher/rails_ext/rack/logger.rb b/lib/logstasher/rails_ext/rack/logger.rb deleted file mode 100644 index 846ea74..0000000 --- a/lib/logstasher/rails_ext/rack/logger.rb +++ /dev/null @@ -1,24 +0,0 @@ -require 'rails/rack/logger' - -module Rails - module Rack - # Overwrites defaults of Rails::Rack::Logger that cause - # unnecessary logging. - # This effectively removes the log lines from the log - # that say: - # Started GET / for 192.168.2.1... - class Logger - # Overwrites Rails 3.2 code that logs new requests - def call_app(*args) - env = args.last - @app.call(env) - ensure - ActiveSupport::LogSubscriber.flush_all! - end - - # Overwrites Rails 3.0/3.1 code that logs new requests - def before_dispatch(env) - end - end - end -end diff --git a/lib/logstasher/railtie.rb b/lib/logstasher/railtie.rb index 911ab2f..8c85684 100644 --- a/lib/logstasher/railtie.rb +++ b/lib/logstasher/railtie.rb @@ -1,14 +1,65 @@ -require 'rails/railtie' -require 'action_view/log_subscriber' -require 'action_controller/log_subscriber' - module LogStasher - class Railtie < Rails::Railtie - config.logstasher = ActiveSupport::OrderedOptions.new + class Railtie < ::Rails::Railtie + config.logstasher = ::ActiveSupport::OrderedOptions.new config.logstasher.enabled = false + config.logstasher.include_parameters = true + config.logstasher.serialize_parameters = true + config.logstasher.silence_standard_logging = false + config.logstasher.silence_creation_message = true + config.logstasher.logger = nil + config.logstasher.log_level = ::Logger::INFO + config.logstasher.dry_validation_contract = nil + + config.logstasher.metadata = {} + config.before_initialize do + options = config.logstasher + + ::LogStasher.enabled = options.enabled + ::LogStasher.include_parameters = options.include_parameters + ::LogStasher.serialize_parameters = options.serialize_parameters + ::LogStasher.silence_standard_logging = options.silence_standard_logging + ::LogStasher.logger = options.logger || default_logger + ::LogStasher.logger.level = options.log_level + ::LogStasher.metadata = options.metadata + ::LogStasher.dry_validation_contract = options.dry_validation_contract + end + + initializer 'logstasher.load' do + if ::LogStasher.enabled? + ::ActiveSupport.on_load(:action_controller) do + require 'logstasher/log_subscriber' + require 'logstasher/context_wrapper' + + include ::LogStasher::ContextWrapper + end + end + end + + config.after_initialize do + if ::LogStasher.enabled? && ::LogStasher.silence_standard_logging? + require 'logstasher/silent_logger' + + ::Rails::Rack::Logger.send(:include, ::LogStasher::SilentLogger) + + ::ActiveSupport::LogSubscriber.log_subscribers.each do |subscriber| + if subscriber.is_a?(::ActiveSupport::LogSubscriber) + subscriber.class.send(:include, ::LogStasher::SilentLogger) + end + end + end + end + + def default_logger + unless @default_logger + path = ::Rails.root.join('log', "logstash_#{::Rails.env}.log") + if config.logstasher.silence_creation_message + ::FileUtils.touch(path) # prevent autocreate messages in log + end + + @default_logger = ::Logger.new(path) + end - initializer :logstasher, :before => :load_config_initializers do |app| - LogStasher.setup(app) if app.config.logstasher.enabled + @default_logger end end end diff --git a/lib/logstasher/silent_logger.rb b/lib/logstasher/silent_logger.rb new file mode 100644 index 0000000..fee7526 --- /dev/null +++ b/lib/logstasher/silent_logger.rb @@ -0,0 +1,16 @@ +module LogStasher + module SilentLogger + def self.included(klass) + klass.class_eval do + def logger + unless @logstasher_silent_logger + @logstasher_silent_logger = ::Logger.new('/dev/null') + @logstasher_silent_logger.level = ::Logger::UNKNOWN + end + + @logstasher_silent_logger + end + end + end + end +end diff --git a/lib/logstasher/version.rb b/lib/logstasher/version.rb index 91c1ff9..b5091ee 100644 --- a/lib/logstasher/version.rb +++ b/lib/logstasher/version.rb @@ -1,3 +1,3 @@ module LogStasher - VERSION = "0.4.9" + VERSION = "1.9.3" end diff --git a/lib/md-logstasher.rb b/lib/md-logstasher.rb new file mode 100644 index 0000000..e57a270 --- /dev/null +++ b/lib/md-logstasher.rb @@ -0,0 +1 @@ +require 'logstasher' \ No newline at end of file diff --git a/log/logstash_development.log b/log/logstash_development.log new file mode 100644 index 0000000..e69de29 diff --git a/log/logstash_test.log b/log/logstash_test.log new file mode 100644 index 0000000..e69de29 diff --git a/log/test.log b/log/test.log new file mode 100644 index 0000000..e69de29 diff --git a/logstasher.gemspec b/logstasher.gemspec index 2f463f2..100cf39 100644 --- a/logstasher.gemspec +++ b/logstasher.gemspec @@ -3,24 +3,24 @@ $:.push File.expand_path("../lib", __FILE__) require "logstasher/version" Gem::Specification.new do |s| - s.name = "logstasher" + s.name = "md-logstasher" s.version = LogStasher::VERSION - s.authors = ["Shadab Ahmed"] - s.email = ["shadab.ansari@gmail.com"] - s.homepage = "https://github.com/shadabahmed/logstasher" + s.authors = ["Devin Christensen"] + s.email = ["devin.christensen@moneydesktop.com"] + s.homepage = "https://github.com/moneydesktop/logstasher" s.summary = %q{Awesome rails logs} s.description = %q{Awesome rails logs} - - s.rubyforge_project = "logstasher" + s.license = 'MIT' s.files = `git ls-files`.split("\n") s.test_files = `git ls-files -- {test,spec,features}/*`.split("\n") s.executables = `git ls-files -- bin/*`.split("\n").map{ |f| File.basename(f) } s.require_paths = ["lib"] - s.add_runtime_dependency "logstash-event", ["~> 1.1.0"] - # specify any dependencies here; for example: + s.add_runtime_dependency "logstash-event", "~> 1.2" + s.add_runtime_dependency "dry-validation", ">= 1.11.0" + + s.add_development_dependency "redis" s.add_development_dependency "rspec" - s.add_development_dependency("bundler", [">= 1.0.0"]) - s.add_development_dependency("rails", [">= 3.0"]) + s.add_development_dependency "bundler", ">= 1.0.0" end diff --git a/spec/lib/logstasher/device/redis_spec.rb b/spec/lib/logstasher/device/redis_spec.rb index 59ca325..a0b0a50 100644 --- a/spec/lib/logstasher/device/redis_spec.rb +++ b/spec/lib/logstasher/device/redis_spec.rb @@ -7,51 +7,51 @@ let(:redis_mock) { double('Redis') } let(:default_options) {{ - key: 'logstash', - data_type: 'list' + 'key' => 'logstash', + 'data_type' => 'list' }} it 'has default options' do device = LogStasher::Device::Redis.new - device.options.should eq(default_options) + expect(device.options).to eq(default_options) end it 'creates a redis instance' do - ::Redis.should_receive(:new).with({}) + expect(::Redis).to receive(:new).with({}) LogStasher::Device::Redis.new() end it 'assumes unknown options are for redis' do - ::Redis.should_receive(:new).with(hash_including(db: '0')) + expect(::Redis).to receive(:new).with(hash_including('db' => '0')) device = LogStasher::Device::Redis.new(db: '0') - device.redis_options.should eq(db: '0') + expect(device.redis_options).to eq('db' => '0') end it 'has a key' do device = LogStasher::Device::Redis.new(key: 'the_key') - device.key.should eq 'the_key' + expect(device.key).to eq 'the_key' end it 'has a data_type' do device = LogStasher::Device::Redis.new(data_type: 'channel') - device.data_type.should eq 'channel' + expect(device.data_type).to eq 'channel' end it 'does not allow unsupported data types' do expect { device = LogStasher::Device::Redis.new(data_type: 'blargh') - }.to raise_error() + }.to raise_error(::RuntimeError) end it 'quits the redis connection on #close' do device = LogStasher::Device::Redis.new - device.redis.should_receive(:quit) + expect(device.redis).to receive(:quit) device.close end it 'works as a logger device' do device = LogStasher::Device::Redis.new - device.should_receive(:write).with('blargh') + expect(device).to receive(:write).with('blargh') logger = Logger.new(device) logger << 'blargh' end @@ -59,19 +59,19 @@ describe '#write' do it "rpushes logs onto a list" do device = LogStasher::Device::Redis.new(data_type: 'list') - device.redis.should_receive(:rpush).with('logstash', 'the log') + expect(device.redis).to receive(:rpush).with('logstash', 'the log') device.write('the log') end it "rpushes logs onto a custom key" do device = LogStasher::Device::Redis.new(data_type: 'list', key: 'custom') - device.redis.should_receive(:rpush).with('custom', 'the log') + expect(device.redis).to receive(:rpush).with('custom', 'the log') device.write('the log') end it "publishes logs onto a channel" do device = LogStasher::Device::Redis.new(data_type: 'channel', key: 'custom') - device.redis.should_receive(:publish).with('custom', 'the log') + expect(device.redis).to receive(:publish).with('custom', 'the log') device.write('the log') end end diff --git a/spec/lib/logstasher/device/syslog_spec.rb b/spec/lib/logstasher/device/syslog_spec.rb new file mode 100644 index 0000000..c69b707 --- /dev/null +++ b/spec/lib/logstasher/device/syslog_spec.rb @@ -0,0 +1,126 @@ +require 'spec_helper' + +require 'logstasher/device/syslog' + +describe LogStasher::Device::Syslog do + + let(:default_options) {{ + 'identity' => 'logstasher', + 'facility' => ::Syslog::LOG_LOCAL0, + 'priority' => ::Syslog::LOG_INFO, + 'flags' => ::Syslog::LOG_PID | ::Syslog::LOG_CONS + }} + + before { allow(::Syslog).to receive(:log) } + + around do |example| + ::Syslog.close rescue nil + example.run + ::Syslog.close rescue nil + end + + it 'has default options' do + device = LogStasher::Device::Syslog.new + expect(device.options).to eq(default_options) + end + + it 'has an identity' do + device = LogStasher::Device::Syslog.new(:identity => 'rspec') + expect(device.identity).to eq 'rspec' + end + + it 'has a facility' do + device = LogStasher::Device::Syslog.new(:facility => ::Syslog::LOG_USER) + expect(device.facility).to eq ::Syslog::LOG_USER + end + + it 'accepts facility as a string' do + device = LogStasher::Device::Syslog.new(:facility => 'LOG_LOCAL7') + expect(device.facility).to eq ::Syslog::LOG_LOCAL7 + end + + it 'has a priority' do + device = LogStasher::Device::Syslog.new(:priority => ::Syslog::LOG_CRIT) + expect(device.priority).to eq ::Syslog::LOG_CRIT + end + + it 'accepts priority as a string' do + device = LogStasher::Device::Syslog.new(:priority => 'LOG_AUTH') + expect(device.priority).to eq ::Syslog::LOG_AUTH + end + + it 'has flags' do + device = LogStasher::Device::Syslog.new(:flags => ::Syslog::LOG_NOWAIT) + expect(device.flags).to eq ::Syslog::LOG_NOWAIT + end + + it 'accepts flags as a string' do + device = LogStasher::Device::Syslog.new(:flags => 'LOG_NDELAY') + expect(device.flags).to eq ::Syslog::LOG_NDELAY + end + + it 'accepts flags as an array of strings' do + device = LogStasher::Device::Syslog.new(:flags => ['LOG_NOWAIT', 'LOG_ODELAY']) + expect(device.flags).to eq(::Syslog::LOG_NOWAIT | ::Syslog::LOG_ODELAY) + end + + it 'opens syslog when it is closed' do + expect(::Syslog).to receive(:open).with( + default_options['identity'], + default_options['flags'], + default_options['facility'], + ) + + LogStasher::Device::Syslog.new + end + + it 're-opens syslog when it is already opened' do + ::Syslog.open('temp', ::Syslog::LOG_NDELAY, ::Syslog::LOG_AUTH) + + expect(::Syslog).to receive(:reopen).with( + default_options['identity'], + default_options['flags'], + default_options['facility'], + ) + + LogStasher::Device::Syslog.new + end + + describe '#write' do + subject { LogStasher::Device::Syslog.new } + + it 'fails when the syslog config is out of sync' do + subject + ::Syslog.reopen('temp', ::Syslog::LOG_NDELAY, ::Syslog::LOG_AUTH) + expect { + subject.write('a log') + }.to raise_error(::RuntimeError, 'Syslog re-configured unexpectedly.') + end + + it 'writes the log to syslog' do + expect(::Syslog).to receive(:log).with(subject.priority, '%s', 'a log') + subject.write('a log') + end + + it 'fails when the device is closed' do + subject.close + expect { + subject.write('a log') + }.to raise_error(::RuntimeError, 'Syslog has been closed.') + end + end + + describe '#close' do + subject { LogStasher::Device::Syslog.new } + + it 'closes the device' do + subject.close + expect(subject).to be_closed + end + + it 'closes syslog' do + expect(::Syslog).to receive(:close) + subject.close + end + end +end diff --git a/spec/lib/logstasher/device/udp_spec.rb b/spec/lib/logstasher/device/udp_spec.rb new file mode 100644 index 0000000..deb65b8 --- /dev/null +++ b/spec/lib/logstasher/device/udp_spec.rb @@ -0,0 +1,37 @@ +require 'spec_helper' + +require 'logstasher/device/udp' + +describe LogStasher::Device::UDP do + + let(:default_options) {{ + 'hostname' => '127.0.0.1', + 'port' => 31459 + }} + + it 'has default options' do + device = LogStasher::Device::UDP.new + expect(device.options).to eq(default_options) + end + + it 'closes the udp socket on #close' do + device = LogStasher::Device::UDP.new + expect(device.socket).to receive(:close) + device.close + end + + it 'works as a logger device' do + device = LogStasher::Device::UDP.new + expect(device).to receive(:write).with('foo') + logger = Logger.new(device) + logger << 'foo' + end + + describe '#write' do + subject { LogStasher::Device::UDP.new } + it 'writes the log to the the socket' do + expect(subject.socket).to receive(:send).with('a log', 0, default_options['hostname'], default_options['port']) + subject.write('a log') + end + end +end diff --git a/spec/lib/logstasher/device_spec.rb b/spec/lib/logstasher/device_spec.rb new file mode 100644 index 0000000..7225c21 --- /dev/null +++ b/spec/lib/logstasher/device_spec.rb @@ -0,0 +1,72 @@ +require "spec_helper" + +require "logstasher/device" +require "logstasher/device/redis" +require "logstasher/device/syslog" +require "logstasher/device/udp" + +describe LogStasher::Device do + describe ".factory" do + it "expects a type" do + expect { + ::LogStasher::Device.factory(:no => "type given") + }.to raise_error(ArgumentError, 'No "type" given') + end + + it "forwards configuration options to the device" do + expect(::LogStasher::Device::Redis).to receive(:new).with( + {'options' => "other", 'than' => "type"} + ) + ::LogStasher::Device.factory( + 'type' => 'redis', 'options' => 'other', :than => "type" + ) + end + + it "accepts symbolized configuration keys" do + expect(::LogStasher::Device::Redis).to receive(:new).with( + {'options' => "other", 'than' => "type"} + ) + ::LogStasher::Device.factory( + :type => "redis", :options => "other", :than => "type" + ) + end + + it "can create redis devices" do + expect( + ::LogStasher::Device + ).to receive(:require).with("logstasher/device/redis") + + device = ::LogStasher::Device.factory(:type => "redis") + expect(device).to be_a_kind_of(::LogStasher::Device::Redis) + end + + it "can create syslog devices" do + expect( + ::LogStasher::Device + ).to receive(:require).with("logstasher/device/syslog") + + device = ::LogStasher::Device.factory(:type => "syslog") + expect(device).to be_a_kind_of(::LogStasher::Device::Syslog) + end + + it "can create udp devices" do + expect( + ::LogStasher::Device + ).to receive(:require).with("logstasher/device/udp") + + device = ::LogStasher::Device.factory(:type => "udp") + expect(device).to be_a_kind_of(::LogStasher::Device::UDP) + end + + it "can create stdout devices" do + device = ::LogStasher::Device.factory(:type => "stdout") + expect(device).to eq $stdout + end + + it "fails to create unknown devices" do + expect { + ::LogStasher::Device.factory(:type => "unknown") + }.to raise_error(ArgumentError, "Unknown type: unknown") + end + end +end diff --git a/spec/lib/logstasher/log_subscriber_spec.rb b/spec/lib/logstasher/log_subscriber_spec.rb index f73fa4f..455b0c2 100644 --- a/spec/lib/logstasher/log_subscriber_spec.rb +++ b/spec/lib/logstasher/log_subscriber_spec.rb @@ -1,190 +1,179 @@ require 'spec_helper' +require 'securerandom' -describe LogStasher::RequestLogSubscriber do - let(:log_output) {StringIO.new} - let(:logger) { - logger = Logger.new(log_output) - logger.formatter = ->(_, _, _, msg) { - msg - } - def log_output.json - JSON.parse! self.string - end - logger - } - before do - LogStasher.logger = logger - LogStasher.log_controller_parameters = true - LogStasher.custom_fields = [] +require 'logstasher/log_subscriber' + +class MockController + def user_id + @user_id ||= SecureRandom.hex(16) end - after do - LogStasher.log_controller_parameters = false +end + +class MockRequest + attr_accessor :env + + def initialize + @env = { 'action_dispatch.request_id' => 1 } end - let(:subscriber) {LogStasher::RequestLogSubscriber.new} - let(:event) { - ActiveSupport::Notifications::Event.new( - 'process_action.action_controller', Time.now, Time.now, 2, { - status: 200, format: 'application/json', method: 'GET', path: '/home?foo=bar', params: { - :controller => 'home', :action => 'index', 'foo' => 'bar' - }.with_indifferent_access, db_runtime: 0.02, view_runtime: 0.01 - } - ) - } - - let(:redirect) { - ActiveSupport::Notifications::Event.new( - 'redirect_to.action_controller', Time.now, Time.now, 1, location: 'http://example.com', status: 302 - ) - } - - describe '.process_action' do - let!(:request_subscriber) { @request_subscriber ||= LogStasher::RequestLogSubscriber.new() } - let(:payload) { {} } - let(:event) { double(:payload => payload) } - let(:logger) { double } - let(:json) { "{\"@source\":\"unknown\",\"@tags\":[\"request\"],\"@fields\":{\"request\":true,\"status\":true,\"runtimes\":true,\"location\":true,\"exception\":true,\"custom\":true},\"@timestamp\":\"timestamp\"}\n" } - before do - LogStasher.stub(:logger => logger) - LogStash::Time.stub(:now => 'timestamp') - end - it 'calls all extractors and outputs the json' do - request_subscriber.should_receive(:extract_request).with(payload).and_return({:request => true}) - request_subscriber.should_receive(:extract_status).with(payload).and_return({:status => true}) - request_subscriber.should_receive(:runtimes).with(event).and_return({:runtimes => true}) - request_subscriber.should_receive(:location).with(event).and_return({:location => true}) - request_subscriber.should_receive(:extract_exception).with(payload).and_return({:exception => true}) - request_subscriber.should_receive(:extract_custom_fields).with(payload).and_return({:custom => true}) - LogStasher.logger.should_receive(:<<).with(json) - request_subscriber.process_action(event) - end + def remote_ip + '127.0.0.1' end +end - describe 'logstasher output' do +describe LogStasher::LogSubscriber do + subject { described_class.new } - it "should contain request tag" do - subscriber.process_action(event) - log_output.json['@tags'].should include 'request' - end + let(:logger) { ::Logger.new('/dev/null') } - it "should contain HTTP method" do - subscriber.process_action(event) - log_output.json['@fields']['method'].should == 'GET' - end + let(:mock_controller) { MockController.new } + let(:mock_request) { MockRequest.new } + let(:context) {{ :controller => mock_controller, :request => mock_request }} - it "should include the path in the log output" do - subscriber.process_action(event) - log_output.json['@fields']['path'].should == '/home' - end + around do |example| + backup_logger = LogStasher.logger + LogStasher.logger = logger + LogStasher.append_fields { } + Thread.current[:logstasher_context] = context + Timecop.freeze { example.run } + Thread.current[:logstasher_context] = nil + LogStasher.logger = backup_logger + end - it "should include the format in the log output" do - subscriber.process_action(event) - log_output.json['@fields']['format'].should == 'application/json' - end + describe '#process_action' do + let(:timestamp) { ::Time.new.utc.iso8601(3) } + let(:duration) { 12.4 } + let(:json_params) { JSON.dump(payload[:params]) } + let(:payload) {{ + :controller => 'users', + :action => 'show', + :params => { 'foo' => 'bar' }, + :format => 'text/plain', + :method => 'method', + :path => '/users/1', + :status => 200 + }} + let(:data) { { "namespace" => "test", "appversion" => "v1" } } + + let(:event) { double(:payload => payload, :duration => duration) } + + before { ::LogStasher.metadata = data } + after { ::LogStasher.metadata = {} } + + it 'logs the event in logstash format' do + expect(logger).to receive(:<<) do |json| + expect(JSON.parse(json)).to eq({ + '@timestamp' => timestamp, + '@version' => '1', + 'tags' => ['request'], + 'action' => payload[:action], + 'controller' => payload[:controller], + 'format' => payload[:format], + 'params' => json_params, + 'ip' => mock_request.remote_ip, + 'method' => payload[:method], + 'path' => payload[:path], + 'route' => "#{payload[:controller]}##{payload[:action]}", + 'status' => payload[:status], + 'runtime' => { 'total' => duration }, + 'request_id' => 1, + 'metadata' => data + }) + end - it "should include the status code" do - subscriber.process_action(event) - log_output.json['@fields']['status'].should == 200 + subject.process_action(event) end - it "should include the controller" do - subscriber.process_action(event) - log_output.json['@fields']['controller'].should == 'home' - end + it 'appends fields to the log' do + ::LogStasher.append_fields do |fields| + fields['user_id'] = user_id + fields['other'] = 'stuff' + end - it "should include the action" do - subscriber.process_action(event) - log_output.json['@fields']['action'].should == 'index' - end + expect(logger).to receive(:<<) do |json| + fields = JSON.parse(json) + expect(fields['user_id']).to eq mock_controller.user_id + expect(fields['other']).to eq 'stuff' + end - it "should include the view rendering time" do - subscriber.process_action(event) - log_output.json['@fields']['view'].should == 0.01 + subject.process_action(event) end - it "should include the database rendering time" do - subscriber.process_action(event) - log_output.json['@fields']['db'].should == 0.02 - end + it 'can be configured to remove parameters from the log' do + allow(::LogStasher).to receive(:include_parameters?).and_return(false) - it "should add a valid status when an exception occurred" do - begin - raise AbstractController::ActionNotFound.new('Could not find an action') - # working this in rescue to get access to $! variable - rescue - event.payload[:status] = nil - event.payload[:exception] = ['AbstractController::ActionNotFound', 'Route not found'] - subscriber.process_action(event) - log_output.json['@fields']['status'].should >= 400 - log_output.json['@fields']['error'].should =~ /AbstractController::ActionNotFound.*Route not found.*logstasher\/spec\/lib\/logstasher\/log_subscriber_spec\.rb/m - log_output.json['@tags'].should include 'request' - log_output.json['@tags'].should include 'exception' + expect(logger).to receive(:<<) do |json| + expect(JSON.parse(json)['params']).to be_nil end - end - it "should return an unknown status when no status or exception is found" do - event.payload[:status] = nil - event.payload[:exception] = nil - subscriber.process_action(event) - log_output.json['@fields']['status'].should == 0 + subject.process_action(event) end - describe "with a redirect" do - before do - Thread.current[:logstasher_location] = "http://www.example.com" - end + it 'can be configured to skip parameter serialization' do + expect(::LogStasher).to receive(:serialize_parameters?).and_return(false) - it "should add the location to the log line" do - subscriber.process_action(event) - log_output.json['@fields']['location'].should == 'http://www.example.com' + expect(logger).to receive(:<<) do |json| + expect(JSON.parse(json)['params']).to eq payload[:params] end - it "should remove the thread local variable" do - subscriber.process_action(event) - Thread.current[:logstasher_location].should == nil - end + subject.process_action(event) end - it "should not include a location by default" do - subscriber.process_action(event) - log_output.json['@fields']['location'].should be_nil - end - end + it 'includes redirect location in the log' do + redirect_event = double(:payload => {:location => 'new/location'}) + subject.redirect_to(redirect_event) - describe "with append_custom_params block specified" do - let(:request) { double(:remote_ip => '10.0.0.1')} - it "should add default custom data to the output" do - request.stub(:params => event.payload[:params]) - LogStasher.add_default_fields_to_payload(event.payload, request) - subscriber.process_action(event) - log_output.json['@fields']['ip'].should == '10.0.0.1' - log_output.json['@fields']['route'].should == 'home#index' - log_output.json['@fields']['parameters'].should == {'foo' => 'bar'} + expect(logger).to receive(:<<) do |json| + expect(JSON.parse(json)['location']).to eq 'new/location' + end + + subject.process_action(event) end - end - describe "with append_custom_params block specified" do - before do - LogStasher.stub(:add_custom_fields) do |&block| - @block = block - end - LogStasher.add_custom_fields do |payload| - payload[:user] = 'user' + it 'includes runtimes in the log' do + payload.merge!({ + :view_runtime => 3.3, + :db_runtime => 2.1 + }) + + expect(logger).to receive(:<<) do |json| + runtime = JSON.parse(json)['runtime'] + expect(runtime['view']).to eq 3.3 + expect(runtime['db']).to eq 2.1 end - LogStasher.custom_fields += [:user] + + subject.process_action(event) end - it "should add the custom data to the output" do - @block.call(event.payload) - subscriber.process_action(event) - log_output.json['@fields']['user'].should == 'user' + it 'includes exception info in the log' do + begin + fail RuntimeError, 'it no work' + rescue + # Test inside the rescue block so $! is properly set + payload.merge!({ + :exception => ['RuntimeError', 'it no work'] + }) + + expect(logger).to receive(:<<) do |json| + log = JSON.parse(json) + expect(log['error']).to match /^RuntimeError\nit no work\n.+/m + expect(log['status']).to eq 500 + expect(log['tags']).to include('exception') + end + + subject.process_action(event) + end end end - describe "when processing a redirect" do - it "should store the location in a thread local variable" do - subscriber.redirect_to(redirect) - Thread.current[:logstasher_location].should == "http://example.com" + describe '#redirect_to' do + let(:location) { "users/#{SecureRandom.hex(16)}" } + let(:payload) {{ :location => location }} + let(:event) { double(:payload => payload) } + + it 'copies the location into the thread local logstasher context' do + subject.redirect_to(event) + expect(Thread.current[:logstasher_context][:location]).to eq location end end end diff --git a/spec/lib/logstasher/logstasher_spec.rb b/spec/lib/logstasher/logstasher_spec.rb new file mode 100644 index 0000000..60bdd15 --- /dev/null +++ b/spec/lib/logstasher/logstasher_spec.rb @@ -0,0 +1,278 @@ +require "spec_helper" +require "dry-validation" + +describe ::LogStasher do + before(:each) do + # Reset state before each test + ::LogStasher.metadata = {} + ::LogStasher.dry_validation_contract = nil + end + describe "#log_as_json" do + it "calls the logger with the payload" do + expect(::LogStasher.logger).to receive(:<<) do |json| + expect(::JSON.parse(json)).to eq("yolo" => "brolo") + end + + ::LogStasher.log_as_json({"yolo" => "brolo"}) + end + + context "with event" do + it "calls logger with a logstash event" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + + expect(payload["@timestamp"]).to_not be_nil + expect(payload["@version"]).to eq("1") + expect(payload["yolo"]).to eq("brolo") + end + + ::LogStasher.log_as_json({"yolo" => "brolo"}, :as_logstash_event => true) + end + end + + context "with metadata" do + before { ::LogStasher.metadata = { :namespace => :cooldude } } + after { ::LogStasher.metadata = {} } + + it "calls logger with the metadata" do + expect(::LogStasher.logger).to receive(:<<) do |json| + expect(::JSON.parse(json)).to eq("yolo" => "brolo", "metadata" => { "namespace" => "cooldude" }) + end + + ::LogStasher.log_as_json({"yolo" => "brolo"}) + end + + it "merges metadata for LogStash::Event types" do + expect(::LogStasher.logger).to receive(:<<) do |json| + expect(::JSON.parse(json)).to match(a_hash_including("yolo" => "brolo", "metadata" => { "namespace" => "cooldude" })) + end + + ::LogStasher.log_as_json(::LogStash::Event.new("yolo" => "brolo")) + end + + it "does not merge metadata on an array" do + expect(::LogStasher.logger).to receive(:<<) do |json| + expect(::JSON.parse(json)).to eq([{ "yolo" => "brolo" }]) + end + + ::LogStasher.log_as_json([{"yolo" => "brolo"}]) + end + end + + context "with dry validation contract" do + let(:validation_contract) do + Types = Dry.Types() + Class.new(Dry::Validation::Contract) do + schema do + required(:yolo).filled(:string) + optional(:yolo_coercible).maybe(Types::Coercible::String) + end + end.new + end + + before do + ::LogStasher.metadata = { :namespace => :cooldude } + ::LogStasher.dry_validation_contract = validation_contract + end + + after do + ::LogStasher.metadata = {} + ::LogStasher.dry_validation_contract = nil + end + + it "validates LogStash::Event payload and appends validation metadata on success" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + expect(payload["dry_validation_errors"]).to eq("{}") + expect(payload["dry_validation_success"]).to be true + expect(payload["yolo"]).to eq("brolo") + expect(payload["metadata"]["namespace"]).to eq("cooldude") + end + + ::LogStasher.log_as_json(::LogStash::Event.new("yolo" => "brolo")) + end + + it "validates LogStash::Event payload and appends validation metadata on failure" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + expect(payload["dry_validation_errors"]).to eq("{\"yolo\":[\"must be a string\"]}") + expect(payload["dry_validation_success"]).to be false + expect(payload["yolo"]).to eq(123) + expect(payload["metadata"]["namespace"]).to eq("cooldude") + end + + ::LogStasher.log_as_json(::LogStash::Event.new("yolo" => 123)) + end + + it "validates hash payload and merges validation metadata on success" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + expect(payload["dry_validation_errors"]).to eq("{}") + expect(payload["dry_validation_success"]).to be true + expect(payload["yolo"]).to eq("brolo") + expect(payload["metadata"]["namespace"]).to eq("cooldude") + end + + ::LogStasher.log_as_json({"yolo" => "brolo"}) + end + + it "validates hash payload and merges validation metadata on failure" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + expect(payload["dry_validation_errors"]).to eq("{\"yolo\":[\"must be a string\"]}") + expect(payload["dry_validation_success"]).to be false + expect(payload["yolo"]).to eq(123) + expect(payload["metadata"]["namespace"]).to eq("cooldude") + end + + ::LogStasher.log_as_json({"yolo" => 123}) + end + + it "does not validate array payloads" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + expect(payload).to eq([{ "yolo" => "brolo" }]) + end + + ::LogStasher.log_as_json([{"yolo" => "brolo"}]) + end + + it "formats the payload correctly for the contract call" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + expect(payload["dry_validation_errors"]).to eq("{}") + expect(payload["dry_validation_success"]).to be true + expect(payload["yolo"]).to eq("brolo") + expect(payload["metadata"]["namespace"]).to eq("cooldude") + end + + ::LogStasher.log_as_json(::LogStash::Event.new("yolo" => :brolo)) + end + + it "logs coerced types" do + expect(::LogStasher.logger).to receive(:<<) do |json| + payload = ::JSON.parse(json) + expect(payload["yolo_coercible"]).to eq("123") + end + + ::LogStasher.log_as_json(::LogStash::Event.new("yolo_coercible" => 123)) + end + end + end + + describe "#dry_validation_contract=" do + it "accepts a valid Dry::Validation::Contract" do + contract = Class.new(Dry::Validation::Contract) do + params do + required(:test).filled(:string) + end + end.new + + expect { ::LogStasher.dry_validation_contract = contract }.not_to raise_error + expect(::LogStasher.dry_validation_contract).to eq(contract) + end + + it "accepts nil" do + expect { ::LogStasher.dry_validation_contract = nil }.not_to raise_error + expect(::LogStasher.dry_validation_contract).to be_nil + end + + it "raises ArgumentError for non-Contract objects" do + expect { ::LogStasher.dry_validation_contract = "not a contract" }.to raise_error( + ArgumentError, "Expected a Dry::Validation::Contract, got String" + ) + end + end + + describe "#dry_validation_contract" do + it "returns the stored contract" do + contract = double("contract") + ::LogStasher.instance_variable_set(:@dry_validation_contract, contract) + expect(::LogStasher.dry_validation_contract).to eq(contract) + end + + it "returns nil when no contract is set" do + ::LogStasher.instance_variable_set(:@dry_validation_contract, nil) + expect(::LogStasher.dry_validation_contract).to be_nil + end + end + + describe "#load_from_config" do + before(:each) do + ::LogStasher.metadata = {} + ::LogStasher.serialize_parameters = true + ::LogStasher.silence_standard_logging = false + end + + it "loads with multiple config keys" do + config = { + metadata: { + namespace: 'kirby', + logged_via: 'logstasher', + }, + device: { + type: 'stdout' + } + } + + ::LogStasher.load_from_config(config) + expect(::LogStasher.metadata).to eq({:namespace => 'kirby', :logged_via => 'logstasher'}) + expect(::LogStasher.default_device).to eq(STDOUT) + end + + it "loads metadata" do + config = { + metadata: { + namespace: 'kirby', + logged_via: 'logstasher', + } + } + + ::LogStasher.load_from_config(config) + expect(::LogStasher.metadata).to eq({:namespace => 'kirby', :logged_via => 'logstasher'}) + end + + it "loads parameters" do + config = { + include_parameters: false, + serialize_parameters: false, + silence_standard_logging: true, + silence_creation_message: false + } + + ::LogStasher.load_from_config(config) + expect(::LogStasher.instance_variable_get(:@include_parameters)).to be false + expect(::LogStasher.instance_variable_get(:@serialize_parameters)).to be false + expect(::LogStasher.instance_variable_get(:@silence_standard_logging)).to be true + end + + it "loads with a stdout device" do + config = { + metadata: { + namespace: 'kirby', + logged_via: 'logstasher', + } + } + + ::LogStasher.load_from_config(config) + expect(::LogStasher.metadata).to eq({:namespace => 'kirby', :logged_via => 'logstasher'}) + end + + it "loads with a syslog device" do + config = { + device: + { + type: 'syslog', + identity: 'logstasher', + facility: 'LOG_LOCAL1', + priority: 'LOG_INFO', + flags: ['LOG_PID', 'LOG_CONS'] + } + } + ::LogStasher.load_from_config(config) + expect(::LogStasher.metadata).to eq({}) + expect(::LogStasher.default_device).to be_a ::LogStasher::Device::Syslog + end + end + +end diff --git a/spec/lib/logstasher/railtie_spec.rb b/spec/lib/logstasher/railtie_spec.rb new file mode 100644 index 0000000..1636c6a --- /dev/null +++ b/spec/lib/logstasher/railtie_spec.rb @@ -0,0 +1,143 @@ +require 'spec_helper' + +require 'action_controller/railtie' +require 'action_controller/log_subscriber' +require 'action_view/railtie' +require 'action_view/log_subscriber' + +require 'logstasher/context_wrapper' +require 'logstasher/log_subscriber' +require 'logstasher/railtie' +require 'logstasher/silent_logger' + +ENV['RAILS_ENV'] = 'test' + +class ::LogStasher::RailtieApp < ::Rails::Application +end + +describe ::LogStasher::Railtie do + let(:config) { described_class.config.logstasher } + + describe 'logstasher should touch log file to prevent creation message by default' do + it 'should configure LogStasher' do + expect(::FileUtils).to receive(:touch) + ActiveSupport.run_load_hooks(:before_initialize) + end + end + + describe 'logstasher should NOT touch log file if silence disabled' do + before { config.silence_creation_message = false } + after { config.silence_creation_message = true } + + it 'should configure LogStasher' do + expect(::FileUtils).not_to receive(:touch) + ActiveSupport.run_load_hooks(:before_initialize) + end + end + + + describe 'logstasher.configure' do + it 'should configure LogStasher' do + config.logger = ::Logger.new('/dev/null') + config.log_level = "log_level" + config.enabled = "enabled" + config.include_parameters = "include_parameters" + config.serialize_parameters = "serialize_parameters" + config.silence_standard_logging = "silence_standard_logging" + config.dry_validation_contract = "dry_validation_contract" + + expect(::LogStasher).to receive(:enabled=).with("enabled") + expect(::LogStasher).to receive(:include_parameters=).with("include_parameters") + expect(::LogStasher).to receive(:serialize_parameters=).with("serialize_parameters") + expect(::LogStasher).to receive(:silence_standard_logging=).with("silence_standard_logging") + expect(::LogStasher).to receive(:dry_validation_contract=).with("dry_validation_contract") + expect(::LogStasher).to receive(:logger=).with(config.logger).and_call_original + expect(config.logger).to receive(:level=).with("log_level") + + ActiveSupport.run_load_hooks(:before_initialize) + end + end + + describe 'logstasher.load' do + subject do + described_class.instance.initializers.find do |initializer| + initializer.name == 'logstasher.load' + end + end + + context 'when logstasher is disabled' do + it 'does nothing' do + expect(::ActiveSupport).not_to receive(:on_load) + + subject.run + end + end + + context 'when logstasher is enabled' do + before { allow(::LogStasher).to receive(:enabled?) { true } } + + it 'should load LogStasher into ActionController' do + expect(::ActionController).to receive(:require).with('logstasher/log_subscriber') + expect(::ActionController).to receive(:require).with('logstasher/context_wrapper') + expect(::ActionController).to receive(:include).with(::LogStasher::ContextWrapper) + + subject.run + ::ActiveSupport.run_load_hooks(:action_controller, ::ActionController) + end + end + end + + describe 'config.after_initialize' do + context 'when logstasher is enabled' do + before { allow(::LogStasher).to receive(:enabled?) { true } } + + context 'and silence_standard_logging is enabled' do + before { allow(::LogStasher).to receive(:silence_standard_logging?) { true } } + + it 'should not silence standard logging' do + expect(::ActionController::LogSubscriber).to receive(:include).with(::LogStasher::SilentLogger) + expect(::ActionView::LogSubscriber).to receive(:include).with(::LogStasher::SilentLogger) + expect(::Rails::Rack::Logger).to receive(:include).with(::LogStasher::SilentLogger) + ::ActiveSupport.run_load_hooks(:after_initialize, ::LogStasher::RailtieApp) + end + end + + context 'and silence_standard_logging is disabled' do + before { allow(::LogStasher).to receive(:silence_standard_logging?) { false } } + + it 'should not silence standard logging' do + expect(::ActionController).not_to receive(:include).with(::LogStasher::SilentLogger) + expect(::ActionView).not_to receive(:include).with(::LogStasher::SilentLogger) + expect(::Rails::Rack::Logger).not_to receive(:include).with(::LogStasher::SilentLogger) + ::ActiveSupport.run_load_hooks(:after_initialize, ::LogStasher::RailtieApp) + end + end + end + + context 'when logstasher is disabled' do + before { allow(::LogStasher).to receive(:enabled?) { false } } + + context 'and silence_standard_logging is enabled' do + before { allow(::LogStasher).to receive(:silence_standard_logging?) { true } } + + it 'should not silence standard logging' do + expect(::ActionController::LogSubscriber).not_to receive(:include).with(::LogStasher::SilentLogger) + expect(::ActionView::LogSubscriber).not_to receive(:include).with(::LogStasher::SilentLogger) + expect(::Rails::Rack::Logger).not_to receive(:include).with(::LogStasher::SilentLogger) + ::ActiveSupport.run_load_hooks(:after_initialize, ::LogStasher::RailtieApp) + end + end + + context 'and silence_standard_logging is disabled' do + before { allow(::LogStasher).to receive(:silence_standard_logging?) { false } } + + it 'should not silence standard logging' do + expect(::ActionController).not_to receive(:include).with(::LogStasher::SilentLogger) + expect(::ActionView).not_to receive(:include).with(::LogStasher::SilentLogger) + expect(::Rails::Rack::Logger).not_to receive(:include).with(::LogStasher::SilentLogger) + ::ActiveSupport.run_load_hooks(:after_initialize, ::LogStasher::RailtieApp) + end + end + end + end +end diff --git a/spec/lib/logstasher_spec.rb b/spec/lib/logstasher_spec.rb index bc3c1c7..4e0d583 100644 --- a/spec/lib/logstasher_spec.rb +++ b/spec/lib/logstasher_spec.rb @@ -1,154 +1,18 @@ require 'spec_helper' describe LogStasher do - describe "when removing Rails' log subscribers" do - after do - ActionController::LogSubscriber.attach_to :action_controller - ActionView::LogSubscriber.attach_to :action_view - end - - it "should remove subscribers for controller events" do - expect { - LogStasher.remove_existing_log_subscriptions - }.to change { - ActiveSupport::Notifications.notifier.listeners_for('process_action.action_controller') - } - end - - it "should remove subscribers for all events" do - expect { - LogStasher.remove_existing_log_subscriptions - }.to change { - ActiveSupport::Notifications.notifier.listeners_for('render_template.action_view') - } - end - - it "shouldn't remove subscribers that aren't from Rails" do - blk = -> {} - ActiveSupport::Notifications.subscribe("process_action.action_controller", &blk) - LogStasher.remove_existing_log_subscriptions - listeners = ActiveSupport::Notifications.notifier.listeners_for('process_action.action_controller') - listeners.size.should > 0 - end + it 'has a version' do + expect(::LogStasher::VERSION).not_to be_nil end - describe '.appened_default_info_to_payload' do - let(:params) { {'a' => '1', 'b' => 2, 'action' => 'action', 'controller' => 'test'}.with_indifferent_access } - let(:payload) { {:params => params} } - let(:request) { double(:params => params, :remote_ip => '10.0.0.1')} - after do - LogStasher.custom_fields = [] - LogStasher.log_controller_parameters = false - end - it 'appends default parameters to payload' do - LogStasher.log_controller_parameters = true - LogStasher.custom_fields = [] - LogStasher.add_default_fields_to_payload(payload, request) - payload[:ip].should == '10.0.0.1' - payload[:route].should == 'test#action' - payload[:parameters].should == {'a' => '1', 'b' => 2} - LogStasher.custom_fields.should == [:ip, :route, :parameters] - end - - it 'does not include parameters when not configured to' do - LogStasher.custom_fields = [] - LogStasher.add_default_fields_to_payload(payload, request) - payload.should_not have_key(:parameters) - LogStasher.custom_fields.should == [:ip, :route] - end + it 'has a logger' do + expect(::LogStasher.logger).to be_a_kind_of(::Logger) end - describe '.append_custom_params' do - let(:block) { ->{} } - it 'defines a method in ActionController::Base' do - ActionController::Base.should_receive(:send).with(:define_method, :logtasher_add_custom_fields_to_payload, &block) - LogStasher.add_custom_fields(&block) - end - end - - describe '.setup' do - let(:logger) { double } - let(:logstasher_config) { double(:logger => logger,:log_level => 'warn',:log_controller_parameters => nil) } - let(:config) { double(:logstasher => logstasher_config) } - let(:app) { double(:config => config) } - before do - config.stub(:action_dispatch => double(:rack_cache => false)) - end - it 'defines a method in ActionController::Base' do - LogStasher.should_receive(:require).with('logstasher/rails_ext/action_controller/metal/instrumentation') - LogStasher.should_receive(:require).with('logstash-event') - LogStasher.should_receive(:suppress_app_logs).with(app) - LogStasher::RequestLogSubscriber.should_receive(:attach_to).with(:action_controller) - logger.should_receive(:level=).with('warn') - LogStasher.setup(app) - LogStasher.enabled.should be_true - LogStasher.custom_fields.should == [] - LogStasher.log_controller_parameters.should == false - end - end - - describe '.suppress_app_logs' do - let(:logstasher_config){ double(:logstasher => double(:suppress_app_log => true))} - let(:app){ double(:config => logstasher_config)} - it 'removes existing subscription if enabled' do - LogStasher.should_receive(:require).with('logstasher/rails_ext/rack/logger') - LogStasher.should_receive(:remove_existing_log_subscriptions) - LogStasher.suppress_app_logs(app) - end - - context 'when disabled' do - let(:logstasher_config){ double(:logstasher => double(:suppress_app_log => false)) } - it 'does not remove existing subscription' do - LogStasher.should_not_receive(:remove_existing_log_subscriptions) - LogStasher.suppress_app_logs(app) - end - - describe "backward compatibility" do - context 'with spelling "supress_app_log"' do - let(:logstasher_config){ double(:logstasher => double(:suppress_app_log => nil, :supress_app_log => false)) } - it 'does not remove existing subscription' do - LogStasher.should_not_receive(:remove_existing_log_subscriptions) - LogStasher.suppress_app_logs(app) - end - end - end - end - end - - describe '.appended_params' do - it 'returns the stored var in current thread' do - Thread.current[:logstasher_custom_fields] = :test - LogStasher.custom_fields.should == :test - end - end - - describe '.appended_params=' do - it 'returns the stored var in current thread' do - LogStasher.custom_fields = :test - Thread.current[:logstasher_custom_fields].should == :test - end - end - - describe '.log' do - let(:logger) { double() } - before do - LogStasher.logger = logger - LogStash::Time.stub(:now => 'timestamp') - end - it 'adds to log with specified level' do - logger.should_receive(:send).with('warn?').and_return(true) - logger.should_receive(:send).with('warn',"{\"@source\":\"unknown\",\"@tags\":[\"log\"],\"@fields\":{\"message\":\"WARNING\",\"level\":\"warn\"},\"@timestamp\":\"timestamp\"}") - LogStasher.log('warn', 'WARNING') - end - end + it 'stores a callback for appending fields' do + callback = proc { |fields| fail 'Did not expect this to run' } - %w( fatal error warn info debug unknown ).each do |severity| - describe ".#{severity}" do - let(:message) { "This is a #{severity} message" } - it 'should log with specified level' do - LogStasher.should_receive(:log).with(severity.to_sym, message) - LogStasher.send(severity, message ) - end - end + ::LogStasher.append_fields(&callback) + expect(::LogStasher.append_fields_callback).to be callback end end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb index 1556eb6..89a8439 100644 --- a/spec/spec_helper.rb +++ b/spec/spec_helper.rb @@ -1,50 +1,15 @@ # Notice there is a .rspec file in the root folder. It defines rspec arguments -# Ruby 1.9 uses simplecov. The ENV['COVERAGE'] is set when rake coverage is run in ruby 1.9 -if ENV['COVERAGE'] - require 'simplecov' - SimpleCov.start do - # Remove the spec folder from coverage. By default all code files are included. For more config options see - # https://github.com/colszowka/simplecov - add_filter File.expand_path('../../spec', __FILE__) - end -end - -# Modify load path so you can require 'ogstasher directly. +# Modify load path so you can require logstasher directly. $LOAD_PATH.unshift(File.expand_path('../../lib', __FILE__)) require 'rubygems' -# Loads bundler setup tasks. Now if I run spec without installing gems then it would say gem not installed and -# do bundle install instead of ugly load error on require. require 'bundler/setup' -# This will require me all the gems automatically for the groups. If I do only .setup then I will have to require gems -# manually. Note that you have still have to require some gems if they are part of bigger gem like ActiveRecord which is -# part of Rails. You can say :require => false in gemfile to always use explicit requiring -Bundler.require(:default, :test) - -# Set Rails environment as test -ENV['RAILS_ENV'] = 'test' +Bundler.require(:default, :development, :test) -require 'action_pack' -require 'action_controller' require 'logstasher' -require 'active_support/notifications' -require 'active_support/core_ext/string' -require 'active_support/log_subscriber' -require 'action_controller/log_subscriber' -require 'action_view/log_subscriber' -require 'active_support/core_ext/hash/except' -require 'active_support/core_ext/hash/indifferent_access' -require 'active_support/core_ext/hash/slice' -require 'active_support/core_ext/string' -require 'active_support/core_ext/time/zones' -require 'abstract_controller/base' -require 'logger' -require 'logstash-event' RSpec.configure do |config| - config.treat_symbols_as_metadata_keys_with_true_values = true config.run_all_when_everything_filtered = true - config.filter_run :focus end