Heroku scheduler, Rails, and logging

scheduler-rails-logging.md

Script

puts "Plain puts"
warn "Plain warn"

$stdout.puts "Explicit stdout puts"
$stderr.puts "Explicit stderr puts"

# Rails log level is set to INFO (although future versions of Rails will default to DEBUG in production)
Rails.logger.debug "Rails debug"
Rails.logger.info "Rails info"
Rails.logger.warn "Rails warn"
Rails.logger.error "Rails error"

# This logger defaults to DEBUG
Rails.logger = Logger.new($stdout)

Rails.logger.debug "Rails debug to stdout logger"
Rails.logger.info "Rails info to stdout logger"
Rails.logger.warn "Rails warn to stdout logger"
Rails.logger.error "Rails error to stdout logger"

heroku run

Nothing recorded.

heroku run:detached

Everything but existing Rails logger debug (expected, as log level is set to INFO):

2015-06-30T21:02:49.368384+00:00 app[run.3372]: Plain puts
2015-06-30T21:02:49.368416+00:00 app[run.3372]: Plain warn
2015-06-30T21:02:49.368418+00:00 app[run.3372]: Explicit stdout puts
2015-06-30T21:02:49.368420+00:00 app[run.3372]: Explicit stderr puts
2015-06-30T21:02:49.368459+00:00 app[run.3372]: Rails info
2015-06-30T21:02:49.368484+00:00 app[run.3372]: Rails warn
2015-06-30T21:02:49.368504+00:00 app[run.3372]: Rails error
2015-06-30T21:02:49.368596+00:00 app[run.3372]: D, [2015-06-30T21:02:49.368521 #3] DEBUG -- : Rails debug to stdout logger
2015-06-30T21:02:49.368634+00:00 app[run.3372]: I, [2015-06-30T21:02:49.368594 #3]  INFO -- : Rails info to stdout logger
2015-06-30T21:02:49.368674+00:00 app[run.3372]: W, [2015-06-30T21:02:49.368630 #3]  WARN -- : Rails warn to stdout logger
2015-06-30T21:02:49.368706+00:00 app[run.3372]: E, [2015-06-30T21:02:49.368670 #3] ERROR -- : Rails error to stdout logger

Scheduled task

Everything but existing Rails logger debug (expected, as log level is set to INFO):

2015-06-30T21:09:26.266282+00:00 app[scheduler.4964]: Plain puts
2015-06-30T21:09:26.266294+00:00 app[scheduler.4964]: Explicit stdout puts
2015-06-30T21:09:26.266287+00:00 app[scheduler.4964]: Plain warn
2015-06-30T21:09:26.266296+00:00 app[scheduler.4964]: Explicit stderr puts
2015-06-30T21:09:26.266417+00:00 app[scheduler.4964]: Rails info
2015-06-30T21:09:26.266419+00:00 app[scheduler.4964]: Rails warn
2015-06-30T21:09:26.266486+00:00 app[scheduler.4964]: I, [2015-06-30T21:09:26.266450 #3]  INFO -- : Rails info to stdout logger
2015-06-30T21:09:26.266420+00:00 app[scheduler.4964]: Rails error
2015-06-30T21:09:26.266519+00:00 app[scheduler.4964]: W, [2015-06-30T21:09:26.266486 #3]  WARN -- : Rails warn to stdout logger
2015-06-30T21:09:26.266452+00:00 app[scheduler.4964]: D, [2015-06-30T21:09:26.266381 #3] DEBUG -- : Rails debug to stdout logger
2015-06-30T21:09:26.266551+00:00 app[scheduler.4964]: E, [2015-06-30T21:09:26.266518 #3] ERROR -- : Rails error to stdout logger