Specs and update to handle broken state of Grape Globals

Rakefile

@@ -1,2 +1,7 @@
-require "bundler/gem_tasks"
+require 'rspec/core/rake_task'
+RSpec::Core::RakeTask.new(:spec) do |spec|
+  spec.pattern = 'spec/**/*_spec.rb'
+end
 
+desc 'Run specs'
+task default: :spec

grape-middleware-logger.gemspec

@@ -1,25 +1,27 @@
 # coding: utf-8
 lib = File.expand_path('../lib', __FILE__)
 $LOAD_PATH.unshift(lib) unless $LOAD_PATH.include?(lib)
-require 'grape/middleware/logger/version'
+require 'grape/middleware/logger'
 
 Gem::Specification.new do |spec|
-  spec.name          = "grape-middleware-logger"
+  spec.name          = 'grape-middleware-logger'
   spec.version       = Grape::Middleware::Logger::VERSION
-  spec.authors       = ["Ryan Buckley"]
+  spec.platform      = Gem::Platform::RUBY
-  spec.email         = ["arebuckley@gmail.com"]
+  spec.authors       = ['Ryan Buckley']
+  spec.email         = ['arebuckley@gmail.com']
   spec.summary       = %q{Logging middleware for Grape apps}
   spec.description   = %q{Logging middleware for Grape apps, similar to what Rails offers}
-  spec.homepage      = ""
+  spec.homepage      = ''
-  spec.license       = "MIT"
+  spec.license       = 'MIT'
 
   spec.files         = `git ls-files -z`.split("\x0")
   spec.executables   = spec.files.grep(%r{^bin/}) { |f| File.basename(f) }
   spec.test_files    = spec.files.grep(%r{^(test|spec|features)/})
-  spec.require_paths = ["lib"]
+  spec.require_paths = ['lib']
 
   spec.add_dependency 'grape'
 
-  spec.add_development_dependency "bundler", "~> 1.7"
+  spec.add_development_dependency 'bundler', '~> 1.7'
-  spec.add_development_dependency "rake", "~> 10.0"
+  spec.add_development_dependency 'rake', '~> 10.0'
+  spec.add_development_dependency 'rspec', '>= 3.0'
 end

lib/grape/middleware/logger.rb

@@ -1,5 +1,5 @@
-require 'grape/middleware/logger/version'
 require 'logger'
+require 'grape/middleware/globals'
 
 module Grape
   module Middleware
@@ -9,22 +9,9 @@ module Grape
       # Overrides
       #
 
-      def before
-        @start_time = Time.now
-        super
-        logger.info ''
-        logger.info %Q(Started #{env['grape.request'].request_method} "#{env['grape.request'].path}")
-        logger.info %Q(  Parameters: #{parameters})
-      end
-
-      def after(status)
-        logger.info "Completed #{status} in #{((Time.now - @start_time) * 1000).round(2)}ms"
-        logger.info ''
-      end
-
       def call!(env)
         @env = env
-        before
+        _before
         error = catch(:error) { @app_response = @app.call(@env); nil }
         if error
           after_failure(error)
@@ -35,10 +22,23 @@ module Grape
         @app_response
       end
 
+      def after(status)
+        logger.info "Completed #{status} in #{((Time.now - @start_time) * 1000).round(2)}ms"
+        logger.info ''
+      end
+
       #
       # Helpers
       #
 
+      # @todo rename to +before+ when Grape v0.12.0 is released
+      def _before
+        @start_time = Time.now
+        logger.info ''
+        logger.info %Q(Started #{env['grape.request'].request_method} "#{env['grape.request'].path}")
+        logger.info %Q(  Parameters: #{parameters})
+      end
+
       def after_failure(error)
         logger.info %Q(  Error: #{error[:message]}) if error[:message]
         after(error[:status])
@@ -47,20 +47,18 @@ module Grape
       def parameters
         request_params = env['grape.request.params'].to_hash
         request_params.merge!(env['action_dispatch.request.request_parameters'] || {})
-        filter_params(request_params)
-      end
-
-      def filter_params(params)
         if @options[:filter]
-          @options[:filter].filter(params)
+          @options[:filter].filter(request_params)
         else
-          params
+          request_params
         end
       end
 
       def logger
-        @logger ||= @options[:logger] || Logger.new(STDOUT)
+        @logger ||= @options[:logger] || ::Logger.new(STDOUT)
       end
     end
   end
 end
+
+require 'grape/middleware/logger/version'

lib/grape/middleware/logger/version.rb

@@ -1,7 +1,7 @@
 module Grape
   module Middleware
     class Logger
-      VERSION = '0.0.1'
+      VERSION = '0.1.0'
     end
   end
 end

spec/lib/grape/middleware/logger_spec.rb

@@ -0,0 +1,132 @@
+require 'spec_helper'
+require 'grape/middleware/logger'
+
+describe Grape::Middleware::Logger do
+  let(:app) { double('app') }
+  let(:options) { { filter: ParamFilter.new, logger: Object.new } }
+
+  subject { described_class.new(app, options) }
+
+  let(:app_response) { [200, {}, 'Hello World'] }
+  let(:env) {
+    {
+      'grape.request' => OpenStruct.new(request_method: 'POST', path: '/api/1.0/users'),
+      'grape.request.params' => {
+        'id' => '101001'
+      },
+      'action_dispatch.request.request_parameters' => {
+        'name' => 'foo',
+        'password' => 'access'
+      }
+    }
+  }
+  describe '#call!' do
+    context 'when calling the app results in an error response' do
+      let(:error) { { status: 400 } }
+
+      it 'calls +after_failure+ and rethrows the error' do
+        expect(app).to receive(:call).with(env).and_throw(:error, error)
+        expect(subject).to receive(:_before)
+        expect(subject).to receive(:after_failure).with(error)
+        expect(subject).to receive(:throw).with(:error, error)
+        subject.call!(env)
+      end
+    end
+
+    context 'when there is no error' do
+      it 'calls +after+ with the correct status' do
+        expect(app).to receive(:call).with(env).and_return(app_response)
+        expect(subject).to receive(:_before)
+        expect(subject).to receive(:after).with(200)
+        subject.call!(env)
+      end
+
+      it 'returns the @app_response' do
+        expect(app).to receive(:call).with(env).and_return(app_response)
+        allow(subject).to receive(:_before)
+        allow(subject).to receive(:after)
+        expect(subject.call!(env)).to eq app_response
+      end
+    end
+
+    describe 'integration' do
+      it 'properly logs requests' do
+        expect(app).to receive(:call).with(env).and_return(app_response)
+        expect(subject.logger).to receive(:info).with('')
+        expect(subject.logger).to receive(:info).with(%Q(Started POST "/api/1.0/users"))
+        expect(subject.logger).to receive(:info).with(%Q(  Parameters: {"id"=>"101001", "name"=>"foo", "password"=>"[FILTERED]"}))
+        expect(subject.logger).to receive(:info).with(/Completed 200 in \d.\d+ms/)
+        expect(subject.logger).to receive(:info).with('')
+        subject.call!(env)
+      end
+    end
+  end
+
+  describe '#after_failure' do
+    let(:error) { { status: 403 } }
+
+    it 'calls +after+ with the :status' do
+      expect(subject).to receive(:after).with(403)
+      subject.after_failure(error)
+    end
+
+    context 'when :message is set in the error object' do
+      let(:error) { { message: 'Oops, not found' } }
+
+      it 'logs the error message' do
+        allow(subject).to receive(:after)
+        expect(subject.logger).to receive(:info).with(Regexp.new(error[:message]))
+        subject.after_failure(error)
+      end
+    end
+  end
+
+  describe '#parameters' do
+    before { subject.instance_variable_set(:@env, env) }
+
+    context 'when @options[:filter] is set' do
+      it 'calls +filter+ with the raw parameters' do
+        expect(subject.options[:filter]).to receive(:filter).with({ "id" => '101001', "name" => "foo", "password" => "access" })
+        subject.parameters
+      end
+
+      it 'returns the filtered results' do
+        expect(subject.parameters).to eq({ "id" => '101001', "name" => "foo", "password" => "[FILTERED]" })
+      end
+    end
+
+    context 'when @options[:filter] is nil' do
+      let(:options) { {} }
+
+      it 'returns the params extracted out of @env' do
+        expect(subject.parameters).to eq({ "id" => '101001', "name" => "foo", "password" => "access" })
+      end
+    end
+  end
+
+  describe '#logger' do
+    context 'when @options[:logger] is nil' do
+      let(:options) { {} }
+
+      it 'defaults to the the standard Logger' do
+        expect(subject.logger).to be_a(Logger)
+      end
+    end
+
+    context 'when @options[:logger] is set' do
+      it 'returns the logger object' do
+        expect(subject.logger).to eq options[:logger]
+      end
+    end
+  end
+
+  #
+  # Test class
+  #
+
+  ParamFilter = Class.new do
+    def filter(opts)
+      opts.each_pair { |key, val| val[0..-1] = '[FILTERED]' if key == 'password' }
+    end
+  end
+end

spec/spec_helper.rb

@@ -0,0 +1,8 @@
+$LOAD_PATH.unshift(File.dirname(__FILE__))
+$LOAD_PATH.unshift(File.join(File.dirname(__FILE__), '..', 'lib'))
+
+require 'ostruct'
+
+RSpec.configure do |config|
+  config.raise_errors_for_deprecations!
+end