filter_parameter_logging throws exception with ruby 1.9.1

"not reproducible"

Ruby: ruby 1.9.2dev (2009-08-07 trunk 24440) [x86_64-linux]

I added

@@@ Ruby

filter_parameter_logging :password, :login, :controller, :action

and test on login form:

@@@ Ruby
<% form_tag  session_path do  %>
    <p>Please log in</p>
    <p>
        <label> Username: </label>
        <%= text_field_tag 'login' %>
    </p>
    <p>
        <label> Password: </label>
        <%= password_field_tag 'password' %>
    </p>
<p><%= submit_tag "Log in" %></p>

Processing SessionsController#create (for 127.0.0.1 at 2009-08-08 09:51:15) [POST]
  Parameters: {"authenticity_token"=>"3UcGlMYa96Pp3X/Pjf3WNef990BkBLGGdANwIaZBQfc=", "login"=>"[FILTERED]", "password"=>"[FILTERED]", "commit"=>"Log in", "controller"=>"[FILTERED]", "action"=>"[FILTERED]"}

to reproduce you need to have a repeated text_filed_tag:

for example

@@@ Ruby

<%= text_field_tag 'stuff[]', 1 %> <%= text_field_tag 'stuff[]', 2 %>

I too falied to reproduce this bug with Ruby 1.9:

    <%= text_field_tag 'name[]' %>
    <%= text_field_tag 'name[]' %>

    filter_parameter_logging :name

    Parameters: {"authenticity_token"=>"...", "name"=>"[FILTERED]"}

not reproducible

okay I created a fresh rails app to reproduce the bug.

I could only reproduce it by changing from sqlite to postgresql.

here is my database.yml file:

defaults: &defaults
  adapter: postgresql
  username: testtest:
  database: bug_test
  adapter: postgresql
  username: test
  password: test
  host: localhost
  port: 5432

development:
  database: bug_development
  adapter: postgresql
  username: test
  password: test
  host: localhost
  port: 5432

oops, that should read:

test:
  database: bug_test
  adapter: postgresql
  username: test
  password: test
  host: localhost
  port: 5432

development:
  database: bug_development
  adapter: postgresql
  username: test
  password: test
  host: localhost
  port: 5432

I've managed to reproduce the same error with both sqlite3 and postgresql in an existing project (Rails 2.3.3 and Ruby 1.9.1).

I have reproduced a similar error - sqlite3, Rails 2.3.3 ruby 1.9 using a multiple choice select_tag.

= select_tag 'schedule[days][]', options_for_select([['Sunday',0],['Monday',1],['Tuesday',2],['Wednesday',3],['Thursday',4],['Friday',5],['Saturday',6]]), {:multiple => true, :size =>7, :id => "schedule_days" }

Heres the output -

/!\ FAILSAFE /!\ 2009-08-25 15:55:15 +0000 Status: 500 Internal Server Error undefined method each' for "0":String

/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `block in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:496:in `block (3 levels) in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:495:in `collect'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:495:in `block (2 levels) in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `each'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `block in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:493:in `block (2 levels) in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `each'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `block in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:1315:in `log_processing_for_parameters'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:1302:in `log_processing'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:526:in `process'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/filters.rb:606:in `process_with_filters'
/usr/local/lib/ruby/gems/1.9.1/gems/haml-2.2.2/lib/sass/plugin/rails.rb:19:in `process'
/usr/local/lib/ruby/gems/1.9.1/gems/chriseppstein-compass-0.8.9/lib/compass/app_integration/rails/action_controller.rb:7:in `process_with_compass'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/rescue.rb:65:in `call_with_exception'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/dispatcher.rb:91:in `rescue in dispatch'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/dispatcher.rb:97:in `dispatch'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/dispatcher.rb:111:in `_call'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/dispatcher.rb:82:in `block in initialize'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/head.rb:9:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/head.rb:9:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/methodoverride.rb:24:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/params_parser.rb:15:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/session/abstract_store.rb:122:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/activerecord-2.3.3/lib/active_record/query_cache.rb:29:in `block in call'
/usr/local/lib/ruby/gems/1.9.1/gems/activerecord-2.3.3/lib/active_record/connection_adapters/abstract/query_cache.rb:34:in `cache'
/usr/local/lib/ruby/gems/1.9.1/gems/activerecord-2.3.3/lib/active_record/query_cache.rb:9:in `cache'
/usr/local/lib/ruby/gems/1.9.1/gems/activerecord-2.3.3/lib/active_record/query_cache.rb:28:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/activerecord-2.3.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:361:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/reloader.rb:29:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/failsafe.rb:26:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/lock.rb:11:in `block in call'
<internal:prelude>:8:in `synchronize'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/lock.rb:11:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/dispatcher.rb:106:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rails-2.3.3/lib/rails/rack/static.rb:31:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/urlmap.rb:46:in `block in call'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/urlmap.rb:40:in `each'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/urlmap.rb:40:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rails-2.3.3/lib/rails/rack/log_tailer.rb:17:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/content_length.rb:13:in `call'
/usr/local/lib/ruby/gems/1.9.1/gems/rack-1.0.0/lib/rack/handler/webrick.rb:46:in `service'
/usr/local/lib/ruby/1.9.1/webrick/httpserver.rb:111:in `service'
/usr/local/lib/ruby/1.9.1/webrick/httpserver.rb:70:in `run'
/usr/local/lib/ruby/1.9.1/webrick/server.rb:183:in `block in start_thread'

have tried changing to

= select_tag 'schedule[days][]', options_for_select([['Sunday',"sun"],['Monday',"mon"],['Tuesday',"tues"],['Wednesday',"wed"],['Thursday',"thurs"],['Friday',"fri"],['Saturday',"sat"]]), {:multiple => true, :size =>7, :id => "schedule_days" }

still fails

Am working on it.

Not sure if this is the right way to go about it, added to the existing test cases - http://github.com/tevio/rails/blob/451389d10484cd73d8bf63c7def00dde...

Hey Steve, that's the right way. However, the commit is missing the expected result and the array of params to filter. Note that the others in the list have three elements: unfiltered, filtered, and filter keys.

I expanded the test a bit but the case you give passes on 1.9.

Hi Jeremy, thanks for looking into it.

Three elements, I see now ( on a closer look ),will expand if still required.

this is the output i got when running my test case - ruby 1.9.1 ( sorry didn't mention the .1 if that makes a difference)...

@@@ /usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/test: ruby controller/filter_params_test.rb Loaded suite controller/filter_params_test
Started
E.

Finished in 0.011309 seconds.

1) Error: test_filter_parameters(FilterParamTest):
NoMethodError: undefined method each' for "foo":String<br/>

/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `block in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:496:in `block (3 levels) in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:495:in `collect'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:495:in `block (2 levels) in filter_parameter_logging'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `each'
/usr/local/lib/ruby/gems/1.9.1/gems/actionpack-2.3.3/lib/action_controller/base.rb:489:in `block in filter_parameter_logging'
controller/filter_params_test.rb:32:in `block in test_filter_parameters'
controller/filter_params_test.rb:30:in `each'
controller/filter_params_test.rb:30:in `test_filter_parameters'
/usr/local/lib/ruby/gems/1.9.1/gems/mocha-0.9.7/lib/mocha/integration/test_unit/gem_version_201_and_above.rb:20:in `run'

2 tests, 25 assertions, 0 failures, 1 errors, 0 pendings, 0 omissions, 0 notifications

This is related to String.each no longer being available in Ruby 1.9...

To trigger the bug,

1. Use Ruby 1.9.1
   
2. add a route: map.connect '*path', :controller => 'home', :action => 'unrecognized'
   
3. try to load an unrecognised route.

I have a fix to the tests for actionpack/test/controller/filter_params_test.rb, change line 18 to:

test_hashes = [[{},{},[]],
[{'foo'=>nil},{'foo'=>nil},[]],
[{'foo'=>'bar'},{'foo'=>'bar'},[]],
[{'foo'=>'bar'},{'foo'=>'bar'},%w'food'],
[{'foo'=>'bar'},{'foo'=>'[FILTERED]'},%w'foo'],
[{'foo'=>'bar', 'bar'=>'foo'},{'foo'=>'[FILTERED]', 'bar'=>'foo'},%w'foo baz'],
[{'foo'=>'bar', 'baz'=>'foo'},{'foo'=>'[FILTERED]', 'baz'=>'[FILTERED]'},%w'foo baz'],
[{'bar'=>{'foo'=>'bar','bar'=>'foo'}},{'bar'=>{'foo'=>'[FILTERED]','bar'=>'foo'}},%w'fo'],
[{'foo'=>{'foo'=>'bar','bar'=>'foo'}},{'foo'=>'[FILTERED]'},%w'f banana'],
[{'baz'=>[{'foo'=>'baz'}]}, {'baz'=>[{'foo'=>'[FILTERED]'}]}, %w(foo)],
[{"foo"=>["bar"]}, {"foo"=>["bar"]}, []]]

This will pass on Ruby1.8 and fail on Ruby1.9

I'm sorry, the test case fails on both 1.8 and 1.9, but the test logic is correct. It is the filter_parameter logic that needs fixing.

You can check it yourself by adding the route I gave above.

I'm sorry, the test case fails on both 1.8 and 1.9, but the test logic is correct. It is the filter_parameter logic that needs fixing.

You can check it yourself by adding the route I gave above.

I'm sorry, the updated test case above fails on both ruby 1.8 and 1.9, but the test logic is correct, it is the filter_parameter logic that needs updating.

You can check it yourself by using the glob route I gave above, which crashes on ruby1.9

Updated patch. There was a bug in the previous one.