Ruby Forum Ruby on Rails > Rake tasks not writing to log file anymore

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 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?

On Apr 9, 11:40 am, Daniel Waite <rails-mailing-l...@andreas-s.net>
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

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/

On Apr 10, 1:29 am, Julian Leviston <jul...@coretech.net.au> 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

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

On Apr 10, 8:43 am, Thorsten Mueller <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

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!

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.

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:

http://github.com/github/rails/tree/c8da518bbfedc2a06b1d96912ddae00e57f21748/railties/lib/initializer.rb#L254

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

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

http://github.com/github/rails/tree/c8da518bbfedc2a06b1d96912ddae00e57f21748/activesupport/lib/active_support/buffered_logger.rb#L41

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

"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. :)

Just say

  RAILS_DEFAULT_LOGGER.flush

at the end of your Rake task.