search

reidmorrison / rails_semantic_logger

Rails Semantic Logger replaces the Rails default logger with Semantic Logger
https://logger.rocketjob.io/rails
Apache License 2.0
330 stars 117 forks source link

Ruby 2.6.0's Enumerable#filter conflicts with configuration option #84

Closed codebycliff closed 5 years ago

codebycliff commented 5 years ago

Environment

12:20:41 web.1     | 2019-01-09 12:20:41.452740 W [48989:70113932075040 base.rb:284] Rails -- Rails Error: Unable to access log file. Please ensure that /Users/cliff/Code/shiftdsm/navigate-rails/log/development.log exists and is chmod 0666. The log level has been raised to WARN and the output directed to STDERR until the problem is fixed. -- Exception: RuntimeError: :filter must be a Regexp or Proc
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/semantic_logger-4.3.1/lib/semantic_logger/base.rb:284:in `initialize'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/semantic_logger-4.3.1/lib/semantic_logger/subscriber.rb:103:in `initialize'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/semantic_logger-4.3.1/lib/semantic_logger/appender/file.rb:71:in `initialize'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/semantic_logger-4.3.1/lib/semantic_logger/appender.rb:69:in `new'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/semantic_logger-4.3.1/lib/semantic_logger/appender.rb:69:in `build'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/semantic_logger-4.3.1/lib/semantic_logger/appender.rb:48:in `factory'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/semantic_logger-4.3.1/lib/semantic_logger/semantic_logger.rb:156:in `add_appender'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/rails_semantic_logger-4.3.3/lib/rails_semantic_logger/engine.rb:149:in `block in <class:Engine>'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/railties-5.2.2/lib/rails/initializable.rb:32:in `instance_exec'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/railties-5.2.2/lib/rails/initializable.rb:32:in `run'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/railties-5.2.2/lib/rails/initializable.rb:61:in `block in run_initializers'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:228:in `block in tsort_each'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:422:in `block (2 levels) in each_strongly_connected_component_from'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:431:in `each_strongly_connected_component_from'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:421:in `block in each_strongly_connected_component_from'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/railties-5.2.2/lib/rails/initializable.rb:50:in `each'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/railties-5.2.2/lib/rails/initializable.rb:50:in `tsort_each_child'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:415:in `call'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:415:in `each_strongly_connected_component_from'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:349:in `block in each_strongly_connected_component'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:347:in `each'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:347:in `call'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:347:in `each_strongly_connected_component'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:226:in `tsort_each'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/tsort.rb:205:in `tsort_each'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/railties-5.2.2/lib/rails/initializable.rb:60:in `run_initializers'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/railties-5.2.2/lib/rails/application.rb:361:in `initialize!'
12:20:41 web.1     | /Users/cliff/Code/shiftdsm/navigate-rails/config/environment.rb:5:in `<top (required)>'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/rubygems/core_ext/kernel_require.rb:54:in `require'
12:20:41 web.1     | /Users/cliff/.rvm/rubies/ruby-2.6.0/lib/ruby/2.6.0/rubygems/core_ext/kernel_require.rb:54:in `require'
12:20:41 web.1     | config.ru:4:in `block in <main>'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/rack-2.0.6/lib/rack/builder.rb:55:in `instance_eval'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/rack-2.0.6/lib/rack/builder.rb:55:in `initialize'
12:20:41 web.1     | config.ru:in `new'
12:20:41 web.1     | config.ru:in `<main>'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/rack-2.0.6/lib/rack/builder.rb:49:in `eval'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/rack-2.0.6/lib/rack/builder.rb:49:in `new_from_string'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/rack-2.0.6/lib/rack/builder.rb:40:in `parse_file'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/puma-3.12.0/lib/puma/configuration.rb:318:in `load_rackup'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/puma-3.12.0/lib/puma/configuration.rb:243:in `app'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/puma-3.12.0/lib/puma/runner.rb:145:in `load_and_bind'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/puma-3.12.0/lib/puma/single.rb:96:in `run'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/puma-3.12.0/lib/puma/launcher.rb:184:in `run'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/puma-3.12.0/lib/puma/cli.rb:78:in `run'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/gems/puma-3.12.0/bin/puma:10:in `<top (required)>'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/bin/puma:23:in `load'
12:20:41 web.1     | /Users/cliff/.rvm/gems/ruby-2.6.0@navigate/bin/puma:23:in `<main>'

Expected Behavior

The application should should be able to find and access the development.log file.

Actual Behavior

Semantic logger raises an exception (i.e. Exception: RuntimeError: :filter must be a Regexp or Proc) because the value of filter is an Enumerable. We tracked this back to the addition of Enumerable#filter in Ruby 2.6.0. Since Hash includes Enumerable and ActiveSupport::OrderedOptions extends Hash, the value of filter ends up being result of the Enumerable#filter method, not the filter configuration value. You can see this by immediately examining the value of filter right after it is set here.

Pull Request

We have consider a couple different solutions, but we aren't quite positive the impacts. Obviously changing the filter configuration value name is the easiest, but at the same time the most breaking change that could be made. We'll await guidance from you before sketching out a pull request.

On another note, now that Ruby 2.6.0 is stable, should we be testing against it without allowing failures? I would think so, but wanted to double check with you. I have already opened a pull request to semantic_logger to do this, but haven't received a response. If that does get merged, I'll open a pull request here to do the same. It does look like the builds for Ruby 2.6.0 are failing currently due to this very issue.

maniax89 commented 5 years ago

for anyone else out there, I wrote a hack fix by adding this line to my config.rb file:

config.rails_semantic_logger.define_singleton_method(:filter) { nil }

i figured I would leave this in until a fix is decided on. will be watching this issue for updates

reidmorrison commented 5 years ago

It looks like the way to fix this is to replace the use of the ordered hash with a custom module / class that has the necessary accessors. I wonder if maybe even a Struct would work in its place? https://github.com/rocketjob/rails_semantic_logger/blob/997e7cbae134e18d9787ae83f464e7a6bac798f3/lib/rails_semantic_logger/engine.rb#L21

codebycliff commented 5 years ago

That seems like an appropriate change to me, though I don't have a ton of context on the gem's source code. Are you going to be able to get around to it, or will you need some help from us?

codebycliff commented 5 years ago

Thanks for the fix! Any chance at getting a release cut?

reidmorrison commented 5 years ago

Gem v4.3.4 has been published with this fix