Liquid Media's Apps

Rails logging doesn't work in script/runner in production

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

Tagged bug, logging, and rails.
blog comments powered by Disqus