Rake tasks not writing to log file anymore

Jeff1 · April 9, 2008, 3:45pm

I have a Rails app, and some custom rake tasks which are called by cron jobs every hour or so. The rake tasks would just call some methods on my models to perform some work. The models in turn use RAILS_DEFAULT_LOGGER.info to emit messages to the log file as needed.

For a good long time everything was working fine, but recently I noticed that my rake tasks are not resulting in any log file messages. I know that they are running because the database is getting get updated as expected.

I then tried to manually run script/console in production mode, and manually did this:

RAILS_DEFAULT_LOGGER.info "hello world"

and this did not appear in the log file either.

Anyone have any ideas?

Thanks! Jeff

11175 · April 9, 2008, 4:40pm

Jeff Cohen wrote:

I then tried to manually run script/console in production mode, and manually did this:

RAILS_DEFAULT_LOGGER.info "hello world"

and this did not appear in the log file either.

Anyone have any ideas?

What response to you get in console?

Maybe clear your log file?

Jeff1 · April 9, 2008, 5:56pm

What response to you get in console?

Maybe clear your log file? --

Sorry I should have mentioned that originally. I get a good response from the console:

$ script/console production Loading production environment (Rails 2.0.2)

RAILS_DEFAULT_LOGGER.info "hello world"

=> "hello world\n"

but when I tail the log I don't see "hello world" anywhere (even a full grep fails).

I also tried stopping the mongrel cluster, then rake log:clear, then started the cluster again, and still no output.

Output from the Rails app itself is working great - I see all the usual rails logging as it processes requests, etc.

Truly stumped on this one.

Jeff

Julian_Leviston · April 10, 2008, 6:29am

What have you got your log level set to? Try sending your logger
object the method error "hello world"

Julian.

Learn Ruby on Rails! Check out the FREE VIDS (for a limited time)
VIDEO #3 out NOW! http://sensei.zenunit.com/

Jeff1 · April 10, 2008, 1:20pm

What have you got your log level set to?

I haven't knowingly changed it from the way Rails configures it for production. I can do this script/console:

RAILS_DEFAULT_LOGGER.info? true

That was a good thought, though... any others?

Jeff

11175 · April 10, 2008, 1:43pm

did you delete an recreate the log file? you may have messed the file permissions.

Jeff1 · April 10, 2008, 2:21pm

Another good suggestion! But file permissions seem to be ok.

The good news is I've somehow worked around it by putting this as the first line in all of my rake tasks:

RAILS_DEFAULT_LOGGER.auto_flushing = true

Now I'm seeing all my output again, yay!

But why should I have to do this? I think (but can't prove) that this broke when I upgraded from 1.2.6 to 2.0.2. But if it was a Rails bug, I would think this would be biting a lot of people, not just me.

Also I'm concerned about the effect this change will have on performance, so I hope someone can shed some light here.

Thanks! Jeff

Michael_Meckler · April 29, 2008, 2:39am

This bit me too. It started happening when I upgraded from 1.2.6 to 2.0.0, just like you.

Thanks for finding the workaround!

Jared_Mehle · May 6, 2008, 9:15pm

I just spent hours trying to figure out why my rake task was not logging in production mode. This has to be a Rails bug. I haven't found any tickets on it yet though. The thing about ths is that it seems to work OK in development mode. Does auto_loading get set to true somewhere in the development environment? It's not set in my file but I don't know if it gets set somewhere in the bowels of Rails.

11175 · May 31, 2008, 4:13pm

Jared Mehle wrote:

The thing about ths is that it seems to work OK in development mode. Does auto_loading get set to true somewhere in the development environment?

I guess you're asking about "auto_flushing", not "auto_loading"?

In 2.0.2, /railties/lib/initializer.rb, line 254:

github.com

github/rails/blob/c8da518bbfedc2a06b1d96912ddae00e57f21748/railties/lib/initializer.rb#L254


      
          # If the log could not be created, the log will be set to output to
          # +STDERR+, with a log level of +WARN+.
          def initialize_logger
            # if the environment has explicitly defined a logger, use it
            return if defined?(RAILS_DEFAULT_LOGGER)
          
            unless logger = configuration.logger
              begin
                logger = ActiveSupport::BufferedLogger.new(configuration.log_path)
                logger.level = ActiveSupport::BufferedLogger.const_get(configuration.log_level.to_s.upcase)
                logger.auto_flushing = false if configuration.environment == "production"
              rescue StandardError =>e
                logger = ActiveSupport::BufferedLogger.new(STDERR)
                logger.level = ActiveSupport::BufferedLogger::WARN
                logger.warn(
                  "Rails Error: Unable to access log file. Please ensure that #{configuration.log_path} exists and is chmod 0666. " +
                  "The log level has been raised to WARN and the output directed to STDERR until the problem is fixed."
                )
              end
            end

logger.auto_flushing = false if configuration.environment == "production"

This overwrites the default as set in active_support/buffered_logger, line 41:

github.com

github/rails/blob/c8da518bbfedc2a06b1d96912ddae00e57f21748/activesupport/lib/active_support/buffered_logger.rb#L41


      
            end
          end
          
          attr_accessor :level
          attr_reader :auto_flushing
          attr_reader :buffer
          
          def initialize(log, level = DEBUG)
            @level         = level
            @buffer        = []
            @auto_flushing = 1
          
            if log.respond_to?(:write)
              @log = log
            elsif File.exist?(log)
              @log = open(log, (File::WRONLY | File::APPEND))
              @log.sync = true
            else
              @log = open(log, (File::WRONLY | File::APPEND | File::CREAT))
              @log.sync = true
              @log.write("# Logfile created on %s" % [Time.now.to_s])

@auto_flushing = 1

By the way: in upcoming releases you'll find an additional different default:

http://github.com/github/rails/tree/master/railties/lib/initializer.rb#L345-348

if configuration.environment == "production" logger.auto_flushing = false logger.set_non_blocking_io end

Arjan.

peter19 · June 4, 2008, 10:28pm

"But if it was a Rails bug, I would think this would be biting a lot of people, not just me."

Thanks for your post. It took me all day just to find this page. It took the morning just to figure out that this was the problem. Since I upgraded to Rail 2.0.2, all "rake db:migrate RAILS_ENV=production" commands will fail if the migration contains any ActiveRecord commands (that would normally be logged in development mode) -- i.e. commands like [Model].find(:all), [object].update_attribute(...), etc. No problem if the migration file contains only regular migration commands (e.g. add_column, drop_table, etc.).

I tried your suggestion (RAILS_DEFAULT_LOGGER.auto_flushing = true) but that only made things worse for me. That is, without that command, the rake command would eventually break and die (MySql lock would time out). But with this command, rake just hangs there forever.

Why this bug hasn't been found yet? I suspect it's a pretty narrow case involving ActiveRecord, rake, and logger. My situation would seem common enough to have been found by others. But one can alway work around elegance to keep the trains moving.

As for me, after 7 hours of banging my head on this obscure issue, I'll just go back to a truly awful workaround (i.e. sftp 'get' the production db to my local machine, slurp that data into my local devlopment db, run the migration locally, sftp 'put' the updated db back up to the server, slurp it in into the production db). Maybe on another day I'll do more than browse through the rails code in bewilderment, and actually find, fix, and publish the bug/fix. But that day is not today.

11175 · October 4, 2008, 2:44am

Just say

RAILS_DEFAULT_LOGGER.flush

at the end of your Rake task.