fix: rescue Rack::Multipart::MultipartPartLimitError and let Sinatra handle it (#161)

* fix: rescue MultipartPartLimitError and let Sinatra handle it.

* Add an integration test for show_exceptions:true/false cases

* refactor: dry up tests and fix lint issues

---------

Co-authored-by: David Winter <[email protected]>

Author: tiegz

lib/sensible_logging/middlewares/request_logger.rb

@@ -28,5 +28,9 @@ def call(env) # rubocop:disable Metrics/AbcSize
 
   def filter_params(req)
     req.params.reject { |x| @filtered_params.include?(x) }
+  rescue Rack::Multipart::MultipartPartLimitError
+    # Let Sinatra handle multipart limit error.
+    # Don't log the params because we don't have them in this case.
+    {}
   end
 end

spec/integration/sensible_logger_spec.rb

@@ -16,6 +16,10 @@ class App < Sinatra::Base
     exclude_params: ['two']
   )
 
+  error(Rack::Multipart::MultipartPartLimitError) do
+    halt(413, "You've exceeded the multipart part limit.")
+  end
+
   get '/hello' do
     logger.tagged('todo') do |logger|
       logger.debug('test')
@@ -28,10 +32,38 @@ class App < Sinatra::Base
 describe 'Sensible Logging integrated with Sinatra' do # rubocop:disable RSpec/DescribeClass
   it 'request returns 200' do
     env = Rack::MockRequest.env_for('http://www.blah.google.co.uk/hello')
-
     app = App.new
+
     response = app.call(env)
 
     expect(response[0]).to eq(200)
   end
+
+  context 'when encountering multipart error' do
+    let(:env) do
+      data = invalid_multipart_body
+
+      Rack::MockRequest.env_for('http://www.blah.google.co.uk/hello', {
+                                  'CONTENT_TYPE' => 'multipart/form-data; boundary=myboundary',
+                                  'CONTENT_LENGTH' => data.bytesize,
+                                  input: StringIO.new(data)
+                                })
+    end
+
+    it 'does not rescue error when show_exceptions is enabled' do
+      app = App.new
+      app.settings.show_exceptions = true
+
+      expect { app.call(env) }.to raise_error(Rack::Multipart::MultipartPartLimitError)
+    end
+
+    it 'does rescue error when show_exceptions is disabled' do
+      app = App.new
+      app.settings.show_exceptions = false
+
+      response = app.call(env)
+
+      expect(response[0]).to eq(413)
+    end
+  end
 end

spec/middlewares/request_logger_spec.rb

@@ -7,7 +7,10 @@
   let(:logger) { instance_double(Logger) }
 
   before do
-    allow(Time).to receive(:now).and_return(1, 2)
+    allow(Time).to receive(:now).and_return(
+      Time.new(2022, 12, 19, 0, 0, 0),
+      Time.new(2022, 12, 19, 0, 0, 1)
+    )
     allow(logger).to receive(:info)
   end
 
@@ -21,7 +24,7 @@
 
     described_class.new(app).call(env)
 
-    expect(logger).to have_received(:info).with('method=GET path=/test client=n/a status=200 duration=1')
+    expect(logger).to have_received(:info).with('method=GET path=/test client=n/a status=200 duration=1.0')
   end
 
   it 'logs the request with REMOTE_ADDR' do
@@ -30,7 +33,7 @@
 
     described_class.new(app).call(env)
 
-    expect(logger).to have_received(:info).with('method=GET path=/test client=123.456.789.123 status=200 duration=1')
+    expect(logger).to have_received(:info).with('method=GET path=/test client=123.456.789.123 status=200 duration=1.0')
   end
 
   it 'logs the request with X_FORWARDED_FOR' do
@@ -39,7 +42,7 @@
 
     described_class.new(app).call(env)
 
-    expect(logger).to have_received(:info).with('method=GET path=/test client=123.456.789.123 status=200 duration=1')
+    expect(logger).to have_received(:info).with('method=GET path=/test client=123.456.789.123 status=200 duration=1.0')
   end
 
   it 'logs the request with no params if not GET' do
@@ -48,6 +51,19 @@
 
     described_class.new(app).call(env)
 
-    expect(logger).to have_received(:info).with('method=POST path=/test client=n/a status=200 duration=1')
+    expect(logger).to have_received(:info).with('method=POST path=/test client=n/a status=200 duration=1.0')
+  end
+
+  it 'rescues request with no params if Rack::Multipart::MultipartPartLimitError is raised' do # rubocop:disable RSpec/ExampleLength
+    data = invalid_multipart_body
+    env = Rack::MockRequest.env_for('http://localhost/test', {
+                                      'CONTENT_TYPE' => 'multipart/form-data; boundary=myboundary',
+                                      'CONTENT_LENGTH' => data.bytesize,
+                                      input: StringIO.new(data)
+                                    })
+    env['logger'] = logger
+    described_class.new(app).call(env)
+
+    expect(logger).to have_received(:info).with('method=GET path=/test client=n/a status=200 duration=1.0')
   end
 end

spec/spec_helper.rb

@@ -10,3 +10,14 @@
 require_relative '../lib/sensible_logging/helpers/subdomain_parser'
 
 ENV['RACK_ENV'] = 'test'
+
+# A multipart form that exceeds rack's multipart form limit.
+def invalid_multipart_body
+  # rubocop:disable Style/StringConcatenation
+  # rubocop:disable Layout/LineLength
+  Rack::Utils.multipart_part_limit.times.map do
+    "--myboundary\r\ncontent-type: text/plain\r\ncontent-disposition: attachment; name=#{SecureRandom.hex(10)}; filename=#{SecureRandom.hex(10)}\r\n\r\ncontents\r\n"
+  end.join("\r\n") + "--myboundary--\r"
+  # rubocop:enable Layout/LineLength
+  # rubocop:enable Style/StringConcatenation
+end