Development.log log file isn't logging Rails SQL queries

Question

I am following Michael Hartl's Rails Tutorial Here:

http://ruby.railstutorial.org/chapters/modeling-and-viewing-users-one#top

I use this command to track the SQL queries in a separate window:

tail -f log/development.log

However while I am in the sandboxed rails console, the log is not updated with SQL statements, instead they show up within the rails console. How can I correct this behavior?

I should add that my database migrations and changes to the data model (new tables, etc) ARE reflected in the log. Only the SQL statements propagated by methods inside the rails console are omitted (and are displayed in the rails console instead).

Here is my Gemfile:

source 'http://rubygems.org'

gem 'rails', '3.1.0'

# Bundle edge Rails instead:
# gem 'rails',     :git => 'git://github.com/rails/rails.git'

gem 'sqlite3'

group :development do
  gem 'rspec-rails', '2.6.1'
  gem 'annotate', :git => 'git://github.com/ctran/annotate_models.git'
end

group :test do
  gem 'rspec-rails', '2.6.1'
  gem 'webrat', '0.7.3'
  gem 'spork', '0.9.0.rc8'
  gem 'guard-spork'
  gem 'autotest', '4.4.6'
  gem 'autotest-rails-pure', '4.1.2'
  gem 'autotest-fsevent', '0.2.4'
  gem 'autotest-growl', '0.2.9'
end

# Gems used only for assets and not required
# in production environments by default.
group :assets do
  gem 'sass-rails', "  ~> 3.1.0"
  gem 'coffee-rails', "~> 3.1.0"
  gem 'uglifier'
end

gem 'jquery-rails'

# Use unicorn as the web server
# gem 'unicorn'

# Deploy with Capistrano
# gem 'capistrano'

# To use debugger
# gem 'ruby-debug19', :require => 'ruby-debug'

Here is the output of the rails console:

Larson-2:sample larson$ rails console --sandbox
Loading development environment in sandbox (Rails 3.1.0)
Any modifications you make will be rolled back on exit
ruby-1.9.2-p290 :001 > user = User.create(:name => "A Nother", :email => "[email protected]")
   (0.1ms)  SAVEPOINT active_record_1
  SQL (13.4ms)  INSERT INTO "users" ("created_at", "email", "name", "updated_at") VALUES (?, ?, ?, ?)  [["created_at", Thu, 15 Sep 2011 20:34:09 UTC +00:00], ["email", "[email protected]"], ["name", "A Nother"], ["updated_at", Thu, 15 Sep 2011 20:34:09 UTC +00:00]]
   (0.1ms)  RELEASE SAVEPOINT active_record_1
 => #<User id: 1, name: "A Nother", email: "[email protected]", created_at: "2011-09-15 20:34:09", updated_at: "2011-09-15 20:34:09"> 
ruby-1.9.2-p290 :002 > user.destroy
   (0.1ms)  SAVEPOINT active_record_1
  SQL (0.3ms)  DELETE FROM "users" WHERE "users"."id" = ?  [["id", 1]]
   (0.1ms)  RELEASE SAVEPOINT active_record_1
 => #<User id: 1, name: "A Nother", email: "[email protected]", created_at: "2011-09-15 20:34:09", updated_at: "2011-09-15 20:34:09"> 
ruby-1.9.2-p290 :003 > 

And here are the settings in my config/environments/development.rb file

Sample::Application.configure do
  # Settings specified here will take precedence over those in config/application.rb

  # In the development environment your application's code is reloaded on
  # every request.  This slows down response time but is perfect for development
  # since you don't have to restart the web server when you make code changes.
  config.cache_classes = false

  # Log error messages when you accidentally call methods on nil.
  config.whiny_nils = true

  # Show full error reports and disable caching
  config.consider_all_requests_local       = true
  config.action_controller.perform_caching = false

  # Don't care if the mailer can't send
  config.action_mailer.raise_delivery_errors = false

  # Print deprecation notices to the Rails logger
  config.active_support.deprecation = :log

  # Only use best-standards-support built into browsers
  config.action_dispatch.best_standards_support = :builtin

  # Do not compress assets
  config.assets.compress = false

  # Expands the lines which load the assets
  config.assets.debug = true

    #Ensure that log level is set to capture ALL messages (from Stack Overflow)
    config.log_level = :debug

end

Finally here is the development.log output so far:

Larson-2:sample larson$ tail -f log/development.log       
   (0.1ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" 
   (0.0ms)  PRAGMA index_list("users")
   (0.1ms)  SELECT "schema_migrations"."version" FROM "schema_migrations" 
   (0.2ms)  select sqlite_version(*)
   (1.8ms)  CREATE TABLE "users" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "name" varchar(255), "email" varchar(255), "created_at" datetime, "updated_at" datetime) 
   (1.1ms)  CREATE TABLE "schema_migrations" ("version" varchar(255) NOT NULL) 
   (0.0ms)  PRAGMA index_list("schema_migrations")
   (1.6ms)  CREATE UNIQUE INDEX "unique_schema_migrations" ON "schema_migrations" ("version")
   (0.1ms)  SELECT version FROM "schema_migrations"
   (1.0ms)  INSERT INTO "schema_migrations" (version) VALUES ('20110915130358')

Answer 1

Ensure that your log level is set to :debug in config/environments/development.rb, like so:

 config.log_level = :debug

Answer 2

Apparently showing the SQL in the console rather than development.log is default behavior for Rails 3.1. I haven't found a configuration option for changing that behavior, but I have found that, once the console is running, you can just do:

irb(main):001:0> ActiveRecord::Base.logger = Rails.logger

and that will take the sql out of the console and put it back in development.log. Or, if you don't want to do that every time you fire up the console, you can edit gems/railties-(version)/lib/rails/console.rb, and make the above assignment after the line in the start method that reads:

@app.load_console

Not saying it's a good solution, but it'll tide me over until I find something better...

Answer 3

Combining KenB's answer and how can i load a file in ruby on rails console?,

simply create a .irbrc file and include the following line:

ActiveRecord::Base.logger = Rails.logger