Heroku: see params and sql activity in logs?

Question

When i view my heroku logs on the server (with heroku logs --tail --app myapp) i see something like this:

2011-06-21T14:09:25+00:00 app[web.1]: Started PUT "/reports/19.xml" for 77.89.149.137 at 2011-06-21 07:09:25 -0700
2011-06-21T14:09:25+00:00 heroku[router]: PUT myapp.heroku.com/reports/19.xml dyno=web.1 queue=0 wait=0ms service=7ms status=401 bytes=28
2011-06-21T14:09:26+00:00 heroku[nginx]: PUT /reports/19.xml HTTP/1.1 | 77.89.149.137 | 656 | http | 401

While in my local log i'd see something like this:

Started PUT "/reports/19" for 127.0.0.1 at 2011-06-21 15:27:01 +0100
  Processing by ReportsController#update as XML
  Parameters: {"report"=>{"workflow_status"=>"3"}, "id"=>"19"}
  Person Load (0.9ms)  SELECT "people".* FROM "people" WHERE "people"."email" = '[email protected]' LIMIT 1
  Report Load (0.4ms)  SELECT "reports".* FROM "reports" WHERE "reports"."id" = 19 LIMIT 1
DEPRECATION WARNING: Object#returning has been deprecated in favor of Object#tap. (called from update_report at /home/max/work/rails_apps/flamingo_container/flamingo/vendor/plugins/resource_this/lib/resource_this.rb:135)
Creating scope :open. Overwriting existing method Task.open.
  Task Load (2.0ms)  SELECT "tasks".* FROM "tasks" WHERE "tasks"."id" = 14 LIMIT 1
Completed 200 OK in 1648ms (Views: 568.2ms | ActiveRecord: 3.2ms)

Ie with a lot more information, particularly the params, info from the router, generated sql, any templates rendered etc etc.

Does anyone know how i can get my heroku log to be as verbose as my development one? I've done the following already:

1) Set the log level in the relevant (rails 3) environment file:

config.log_level = :debug

2) Told heroku to use a different logger level, as described on http://devcenter.heroku.com/articles/logging

heroku config:add LOG_LEVEL=DEBUG --app myapp #from CLI

Neither has made any difference...any ideas anyone?
thanks, max

Answer 1

You're essentially wanting to show the SQL / params output in the Heroku logs. You can do this by adding the line shown below to the config block within your production.rb file:

MyAppNameHere::Application.configure do

  # add this line
  config.logger = Logger.new(STDOUT)

end

By the way, setting the log level to debug just means that Rails.logger.debug will output to the logs when you're on Heroku

Answer 2

In your production.rb add config.log_level = :debug and redeploy. That will give you the same logs as development mode :)

Answer 3

The detailed log you want is generated by the function start_processing in log_subscriber.rb.

action_controller/log_subscriber.rb:

def start_processing(event)
  payload = event.payload
  params  = payload[:params].except(*INTERNAL_PARAMS)

  info "  Processing by #{payload[:controller]}##{payload[:action]} as #{payload[:formats].first.to_s.upcase}"
  info "  Parameters: #{params.inspect}" unless params.empty?
end

I checked with rails 3.0.4 in development and production environment. In both environments, we have the detailed logs.

This is an info level log. That's why the debug log level is not changing the output.

I installed the plugin used by heroku rails_log_stdout (Heroku logging) but I still have the desired output.

Right now, I can't test with heroku to find out why you don't have all the logs.

In the heroku example (see Heroku logging, section log retrieval), we don't see the "Processing" and "Parameters" lines. I think that either this method is not called when the app is running on heroku (it is somehow disabled) or heroku skips logs starting with whitespaces. Could you try to log messages starting with whitespaces and see if heroku is showing them?