I was running into a pretty obscure issue in Rails logging in a production-mode app.
Symptoms: Default logging to log/production.log
is working fine, but any cron jobs (or anything executed via script/runner
) doesn't output anything to the logs.
Analysis: When Rails starts in production mode, it sets the [default] logger's auto_flushing
to false
. This works so long as RAILS_DEFAULT_LOGGER.flush
is called periodically. The problem is that in script/runner
it isn't, unless you do it yourself, which you probably don't know to do (and why should you?)
Solution: Apply the patch below to your vendor/rails
directory.
Index: vendor/rails/railties/lib/commands/runner.rb =================================================================== --- vendor/rails/railties/lib/commands/runner.rb (revision 182) +++ vendor/rails/railties/lib/commands/runner.rb (working copy) @@ -38,6 +38,9 @@ require RAILS_ROOT + '/config/environment' +# Set up the logger to flush automatically, because otherwise we won't see any mention of it in the logs! +RAILS_DEFAULT_LOGGER.auto_flushing = 1 + if code_or_file.nil? $stderr.puts "Run '#{$0} -h' for help." exit 1
script/console
is affected by this issue as well (as no doubt other scripts are as well), but the solution is quite different. Try:
[paul@tupper current]$ RAILS_ENV=production script/console Loading production environment (Rails 2.0.2) >> ActiveRecord::Base.logger = Logger.new(STDOUT) >> Document.count SQL (0.000780) SHOW client_min_messages SQL (0.000441) SET client_min_messages TO 'panic' SQL (0.000377) SHOW standard_conforming_strings SQL (0.000286) SET client_min_messages TO 'notice' SQL (0.000987) SELECT version() SQL (0.007113) SELECT a.attname, format_type(a.atttypid, a.atttypmod), d.adsrc, a.attnotnull FROM pg_attribute a LEFT JOIN pg_attrdef d ON a.attrelid = d.adrelid AND a.attnum = d.adnum WHERE a.attrelid = 'documents'::regclass AND a.attnum > 0 AND NOT a.attisdropped ORDER BY a.attnum SQL (0.000523) SHOW max_identifier_length SQL (0.001358) SELECT count(*) AS count_all FROM documents => 85
(This example obviously taken from my shell, and the solution was borrowed from Jamis Buck.) Although the logging still won't go to log/production.log
, at least you'll be able to see what's going on in your SQL queries. Actually, this is probably more useful.
I think this probably isn't worth submitting as a bug and patch to Rails. The auto_flushing
is [presumably] there for performance reasons, and changing the value defeats the point. On the other hand, logging not working in your cron jobs also defeats the point. If anyone thinks I should submit this one, let me know.