CanCan breaks rails logger on Heroku

[emiltin]

When cancan is installed on a rails 3 app deployed on Heroku's new cedar stack, calling logger.error(), logger.info(), etc doesn't write anything to the log file.

I've been in touch with their support, and here what they say:

To make logging work we inject a plugin that redirects logger input to STDOUT.

https://github.com/ddollar/rails_log_stdout

Some gems interfere with that if they make changes to the default rails logger. I had some free time today, so I went ahead an debugged this. The two gems that are causing problems are 'cancan' and 'simple-navigation'.

There is a way to work around this if you want to keep those gems. You can disable the plugin by creating a vendor/plugins/rails_log_stdout dir in your application, and add a dummy file to it (like a .gitignore) so the directory will end up in git. This will stop this plugin being installed, so you can set the logger in production.rb to log to STDOUT yourself:

config.logger = Logger.new(STDOUT)
config.log_level = :info

Please let me know if this doesn't work for you.

[johnsome]

Thanks for this. I tried your suggestion on our heroku app and it started logging everything again - although the log also included all the sql queries etc.

After a bit of googling, I found this thread: http://groups.google.com/group/heroku/browse_thread/thread/119c52ba08d173b4

After updating my production.rb with:
config.logger = Logger.new(STDOUT)
config.logger.level = Logger::INFO # use logger.level, not log_level

it started logging w/o the sql etc - much better. Turns out you dont need to disable the plugin by adding vendor/plugins/rails_log_stdout if you use the config settings above.

So - I think this is more of an heroku issue than cancan...

[emiltin]

i agree. this is a heroku issue, and quite annoying that such a basic thing doesn't work well.

[nextofsearch]

Hi guys,
If I put "config.logger = Logger.new(STDOUT)" this line in production.rb, I can get the following errors:

2012-01-02T10:11:34+00:00 app[web.2]: /app/vendor/bundle/ruby/1.9.1/gems/railties-3.1.1/lib/rails/rack/log_tailer.rb:8:in size': No such file or directory - log/production.log (Errno::ENOENT) 2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/railties-3.1.1/lib/rails/rack/log_tailer.rb:8:ininitialize'
2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.5/lib/rack/server.rb:295:in new' 2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.5/lib/rack/server.rb:295:inblock in build_app'
2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.5/lib/rack/server.rb:291:in reverse_each' 2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.5/lib/rack/server.rb:291:inbuild_app'
2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.5/lib/rack/server.rb:301:in wrapped_app' 2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/rack-1.3.5/lib/rack/server.rb:252:instart'
2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/railties-3.1.1/lib/rails/commands/server.rb:70:in start' 2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/railties-3.1.1/lib/rails/commands.rb:54:inblock in <top (required)>'
2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/railties-3.1.1/lib/rails/commands.rb:49:in tap' 2012-01-02T10:11:34+00:00 app[web.2]: from /app/vendor/bundle/ruby/1.9.1/gems/railties-3.1.1/lib/rails/commands.rb:49:in<top (required)>'
2012-01-02T10:11:34+00:00 app[web.2]: from script/rails:6:in require' 2012-01-02T10:11:34+00:00 app[web.2]: from script/rails:6:in

'
2012-01-02T10:11:36+00:00 heroku[web.2]: Process exited

I am clueless here. Any idea?

[latortuga]

I was having this issue as well and adding

config.logger = Logger.new(STDOUT)
config.logger.level = Logger::INFO # use logger.level, not log_level

fixed my problem. I have not tried it but I imagine you could change it to respect the heroku environment variable as well by doing something like this:

config.logger.level = ENV['LOG_LEVEL'] ? Logger.class_eval(ENV['LOG_LEVEL']) : Logger::INFO

@heroku any chance you all could look into this particular issue and potentially update the rails_log_stdout plugin?

[derekprior]

I was curious what CanCan would be doing to the Rails logger. I didn't find any references to Rails.logger or logger anywhere. In any event, this does sound like an issue with how Heroku handles logging rather than with CanCan. I'm going to close, but if there's disagreement let me know and we can re-open and discuss.

[emiltin]

this is (was) a bug with heroku. simply adding the following lines to application.rb caused logging to stop working:

module MyModule
end
ActionController::Base.send(:include, MyModule)