Empty log file in production using rails 3.2.0.rc1

[ebeigarts]

In production log/production.log is empty and I have found out that 04ef93d forces f.sync to be false in production which somehow leaves production.log empty.

I am currently using this workaround to get logger working in production:

# config/environments/production.rb
App::Application.configure do
  path = config.paths["log"].first
  unless File.exist? File.dirname path
    FileUtils.mkdir_p File.dirname path
  end
  f = File.open path, 'w'
  f.binmode
  f.sync = true

  config.logger = ActiveSupport::TaggedLogging.new(
    ActiveSupport::BufferedLogger.new(f)
  )
  config.logger.level = ActiveSupport::BufferedLogger.const_get(config.log_level.to_s.upcase)
end

I have experienced this problem with:

• OS X 10.6.8 with ruby 1.9.3p0
• Ubuntu 11.04 with ruby 1.9.2p290

[ebeigarts]

Ok, my workaround doesn't work either.

I am using unicorn 4.1.1 with 2 workers.

[ebeigarts]

Steps to reproduce this

1. $ rails new test_app
2. Uncomment unicorn in Gemfile and run bundle
3. $ unicorn -p 3000 -E production
4. Run $ curl -I http://localhost:3000/ 5 times
5. log/production.log should now be around 8K
6. Stop the unicorn
7. And now if I start the unicorn again - log/production.log will get truncated (size 0) :(

[ebeigarts]

I have investigated this further, it looks like it also clears the log files on startup in development mode with webrick and it has nothing to do with sync.

[ebeigarts]

Shouldn't it be File.open path, 'a' instead of f = File.open path, 'w'?

[ebeigarts]

Should I create a pull request for this?

[tenderlove]

I think this was fixed with pull request #4279

[agrobbin]

I'm seeing this as partially fixed. It doesn't seem to write to production.log until the server is restarted. It then flushes out all of the logger data to the production.log file, which is a different behavior than Rails 3.1.3 and previous.

[ebeigarts]

It works with the patch in #4279 and in production it flushes after a while or on exit/restart.

[agrobbin]

Ohh good to know! Thanks ebeigarts

[collex]

Is there a way to force the log to flush either all the time or on demand (like a rake task)? It's a huge pain to look at the production.log file and not see the the latest log entries.

[ebeigarts]

@collex if you are using unicorn, sending USR1 might help

[collex]

No, using passenger in apache.

I tried restarting the apache service, but that didn't write anything new to the log, and I think it might have lost the data that it hadn't written yet (I'm not sure about that.)

My use case is: I get an email from ExceptionNotifier that a 500 error occurred. I immediately go to the server and tail the log. I don't see the latest activity.

[vihai]

Confirmed here for passenger 3.0.11 + rails 3.2.0.rc2: production.log is flushed when it reaches around 8 kB, then 16 kB. Log lines are not truncated however.

[ashchan]

@collex, @vihai: check if this does as you want:

config.logger.auto_flushing = true

As for rake task, use this:

Rails.logger.flush

But that might not be a good idea on production concerning the disk IO.

[collex]

Well, this is probably a dumb question, but I can't get either of the above lines to work. I'm now on Rails 3.2.1.

I put Rails.logger.flush in a rake task and also put it in one of the actions in my controller just to see if I could get it to work. Neither made the log file write.

I searched around the initialization code and couldn't find any place that config.logger was defined during initialization, so I have no idea where to put the auto_flushing code.

[collex]

Oh, I see a problem:

"DEPRECATION WARNING: flush is deprecated and will be removed from Rails 3.2."

Of course, that was written to the log file so I couldn't see it.

[vihai]

config.logger is not defined so setting auto_flush doesn't work

[felixbuenemann]

I think it should be possible to enable log flushing in production mode. Currently it is always disabled in production.

[tenderlove]

@fbuenemann can you add a config option for it? I'd be happy to apply.

[Bazai]

Ubuntu 10.04: Rails 3.2.1 + Unicorn : got empty production.log too

[felixbuenemann]

@tenderlove I'll give it a try.

[danrabinowitz]

I'm dealing with this bug too. Anyone found a fix or workaround?

[Juanmcuello]

@fbuenemann Have you had a chance to create a patch? I could try if you want.

[felixbuenemann]

@Juanmcuello not yet, but I'll tackle it once I find some free time, so hopefully some time this week.

[felixbuenemann]

I've finally come around to make this configurable. Maybe that's better than always flushing as introduced by commit 55cc16f from @tenderlove

[romanbsd]

As a temporary workaround:

Rails.logger.instance_variable_get(:@logger).instance_variable_get(:@log_dest).sync = true if Rails.logger

[workmaster2n]

@romanbsd - Where does the line:

Rails.logger.instance_variable_get(:@logger).instance_variable_get(:@log_dest).sync = true if Rails.logger

go? An initializer? The class that I want to log from?

[romanbsd]

@workmaster2n initializer

[Goles]

This problem persists on rails 3.2.0 + Unicorn,

@romanbsd line helped to fix it ( that plus a unicorn reboot ). I was wondering if this issue was fixed in 3.2.1 ? @Bazai is reporting the same thing in 3.2.1 .

Any news on this issue ?

[felixbuenemann]

Well log flushing is always enabled in 3.2.2 as the release notes state: http://weblog.rubyonrails.org/2012/3/1/ann-rails-3-2-2-has-been-released

[Goles]

Updated to 3.2.2 and seems to work fine now.

[HaNdTriX]

having the same issue width Rails 3.2.3 / unicorn / ubuntu 10.04 :(

[babatakao]

@HaNdTriX
I had same issue with Rails 3.2.3 / unicorn 4.2.0 / ubuntu 10.04 / ruby 1.9.3.

And solved by this code (in config/initializers).

Rails.logger.instance_variable_get(:@logger).instance_variable_get(:@log_dest).sync = true if Rails.logger

[mchavarriagam]

Confirmed with similar configuration to @babatakao's, solved using same initializer. Thanks.

Rails 3.2.3 / unicorn 4.3.1 / nginx 0.8.53.passenger300-5 / ubuntu 10.04 / ruby 1.9.3p194

[jamesw]

Is there any solution to this yet? I'm experiencing the same on Rails 3.2.9
Thanks

[heaven]

Rials 3.2.8, log is empty (only errors appears in it) even though the level has been set to :debug.

[efulet]

I seeing similar issue in Rails 3.1.11. Any idea?

Rails 3.1.11 / jruby 1.6.8 / torquebox 2.1.2 / apache 2

[yorch]

Same here (3.2.14) with Puma. The initializers solution did not work for me, getting the error undefined method sync='for nil:NilClass

[RajRoR]

+1 @yorch Using rails 4.1.2

[loicginoux]

I managed to fix this by removing the gem 'rails_12factor' and including only its dependency 'rails_serve_static_assets' as explained here:
http://blog.simontaranto.com/post/2013-12-05-rails_12factor-logging-problems.html/

[andrewhoglund]

@loicginoux - thanks for posting this, that was our issue as well since we moved off Heroku!