Rake tasks not writing to log file anymore

jeff · April 9, 2008, 5:46pm

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

jeff · April 9, 2008, 6:40pm

Jeff C. 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?

jeff · April 9, 2008, 7:57pm

On Apr 9, 11:40 am, Daniel W. [email protected]
wrote:

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

jeff · April 10, 2008, 8:30am

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/

jeff · April 10, 2008, 3:21pm

On Apr 10, 1:29 am, Julian L. [email protected] wrote:

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

jeff · April 10, 2008, 4:22pm

On Apr 10, 8:43 am, Thorsten M. <rails-mailing-l…@andreas-
s.net> wrote:

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

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

jeff · April 29, 2008, 4:40am

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!

jeff · April 10, 2008, 3:43pm

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

jeff · May 6, 2008, 11:42pm

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.

jeff · May 31, 2008, 6: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.

jeff · October 4, 2008, 4:44am

Just say

RAILS_DEFAULT_LOGGER.flush

at the end of your Rake task.

jeff · June 5, 2008, 11:32am

“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.