Rails console does not send any output to the development.log

Question

I am using Rails 3.2.13

More specifically, whenever I do a item.destroy via the console....it doesn't send the output to my development.log.

E.g.:

> note = Item.last
  Item Load (31.0ms)  SELECT "items".* FROM "items" ORDER BY "items"."id" DESC LIMIT 1
 => #<Item id: 10, name: "Notepad", link: "Notepad-in-CSS---HTML.zip", description: "Awesome notepad piece of paper.", price: 10.0, user_id: 2, created_at: "2013-05-05 21:22:47", updated_at: "2013-05-05 21:22:47", image: "notepad.png"> 
2.0.0p0 :051 > note
 => #<Item id: 10, name: "Notepad", link: "Notepad-in-CSS---HTML.zip", description: "Awesome notepad piece of paper.", price: 10.0, user_id: 2, created_at: "2013-05-05 21:22:47", updated_at: "2013-05-05 21:22:47", image: "notepad.png"> 
2.0.0p0 :052 > note.destroy
   (0.1ms)  BEGIN
  SQL (0.5ms)  DELETE FROM "items" WHERE "items"."id" = $1  [["id", 10]]
   (70.8ms)  COMMIT
 => #<Item id: 10, name: "Notepad", link: "Notepad-in-CSS---HTML.zip", description: "Awesome notepad piece of paper.", price: 10.0, user_id: 2, created_at: "2013-05-05 21:22:47", updated_at: "2013-05-05 21:22:47", image: "notepad.png"> 
> Item.count
   (13.3ms)  SELECT COUNT(*) FROM "items" 
 => 0 

But here are the last entries of my development.log which just shows the creation of the note Item I used in the console above. But it doesn't show any of the operations I did in the console above.

Started GET "/items" for 127.0.0.1 at 2013-05-05 16:19:58 -0500
Processing by ItemsController#index as HTML
  [1m[36mItem Load (0.5ms)[0m  [1mSELECT "items".* FROM "items" [0m
  Rendered items/index.html.erb within layouts/item (0.7ms)
  [1m[35mUser Load (0.5ms)[0m  SELECT "users".* FROM "users" WHERE "users"."id" = 2 LIMIT 1
  [1m[36m (1.0ms)[0m  [1mSELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = 2 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))[0m
  [1m[35m (0.6ms)[0m  SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = 2 AND (((roles.name = 'seller') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))
  Rendered layouts/_site_nav.html.erb (11.3ms)
  Rendered layouts/_messages.html.erb (0.1ms)
  Rendered layouts/_footer.html.erb (0.1ms)
Completed 200 OK in 583ms (Views: 579.5ms | ActiveRecord: 2.7ms)


Started GET "/items/new" for 127.0.0.1 at 2013-05-05 16:22:11 -0500
Processing by ItemsController#new as HTML
  Rendered items/_form.html.erb (12.1ms)
  Rendered items/new.html.erb within layouts/item (13.9ms)
  [1m[36mUser Load (0.6ms)[0m  [1mSELECT "users".* FROM "users" WHERE "users"."id" = 2 LIMIT 1[0m
  [1m[35m (0.6ms)[0m  SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = 2 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))
  [1m[36m (0.7ms)[0m  [1mSELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = 2 AND (((roles.name = 'seller') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))[0m
  Rendered layouts/_site_nav.html.erb (10.1ms)
  Rendered layouts/_messages.html.erb (0.2ms)
  Rendered layouts/_footer.html.erb (0.1ms)
Completed 200 OK in 721ms (Views: 718.2ms | ActiveRecord: 1.9ms)


Started POST "/items" for 127.0.0.1 at 2013-05-05 16:22:47 -0500
Processing by ItemsController#create as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"kelL30xMc/=", "item"=>{"name"=>"Notepad", "link"=>#<ActionDispatch::Http::UploadedFile:0x007e18 @original_filename="Notepad-in-CSS---HTML.zip", @content_type="application/zip", @headers="Content-Disposition: form-data; name=\"item[link]\"; filename=\"Notepad-in-CSS---HTML.zip\"\r\nContent-Type: application/zip\r\n", @tempfile=#<Tempfile:/var/folders/0f/hgpl/T/RackMultipart20130505-36246-1xmqytf>>, "image"=>#<ActionDispatch::Http::UploadedFile:0x007fa65cfc4f18 @original_filename="notepad.png", @content_type="image/png", @headers="Content-Disposition: form-data; name=\"item[image]\"; filename=\"notepad.png\"\r\nContent-Type: image/png\r\n", @tempfile=#<Tempfile:/var/folders/0f/000gn/T/RackMultipart21n9jo5w>>, "price"=>"10", "description"=>"Awesome notepad piece of paper."}, "_wysihtml5_mode"=>"1", "commit"=>"Create Item"}
  [1m[35mUser Load (1.9ms)[0m  SELECT "users".* FROM "users" WHERE "users"."id" = 2 LIMIT 1
  [1m[36m (0.2ms)[0m  [1mBEGIN[0m
  [1m[35mSQL (373.1ms)[0m  INSERT INTO "items" ("created_at", "description", "image", "link", "name", "price", "updated_at", "user_id") VALUES ($1, $2, $3, $4, $5, $6, $7, $8) RETURNING "id"  [["created_at", Sun, 05 May 2013 21:22:47 UTC +00:00], ["description", "Awesome notepad piece of paper."], ["image", "notepad.png"], ["link", "Notepad-in-CSS---HTML.zip"], ["name", "Notepad"], ["price", 10.0], ["updated_at", Sun, 05 May 2013 21:22:47 UTC +00:00], ["user_id", 2]]
Store! is executed
Store! is executed
  [1m[36m (162.5ms)[0m  [1mCOMMIT[0m
Redirected to http://localhost:3000/items/10
Completed 302 Found in 3362ms (ActiveRecord: 537.6ms)


Started GET "/items/10" for 127.0.0.1 at 2013-05-05 16:22:50 -0500
Processing by ItemsController#show as HTML
  Parameters: {"id"=>"10"}
  [1m[35mItem Load (1.3ms)[0m  SELECT "items".* FROM "items" WHERE "items"."id" = $1 LIMIT 1  [["id", "10"]]
  [1m[36mUser Load (0.5ms)[0m  [1mSELECT "users".* FROM "users" WHERE "users"."id" = 2 LIMIT 1[0m
  Rendered items/show.html.erb within layouts/item (4.0ms)
  [1m[35mCACHE (0.0ms)[0m  SELECT "users".* FROM "users" WHERE "users"."id" = 2 LIMIT 1
  [1m[36m (0.7ms)[0m  [1mSELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = 2 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))[0m
  [1m[35m (0.6ms)[0m  SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = 2 AND (((roles.name = 'seller') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))
  Rendered layouts/_site_nav.html.erb (9.2ms)
  Rendered layouts/_messages.html.erb (0.2ms)
  Rendered layouts/_footer.html.erb (0.1ms)
Completed 200 OK in 1259ms (Views: 1253.6ms | ActiveRecord: 3.0ms)

Answer 1

For what it's worth, I don't believe it is supposed to send entries to my development.log in Rails 3.2.13 - the version I am running.

I thought it should, but it appears not.

Maybe it did in versions past, and it does in Rails 4, but not in this build.

Answer 2

Please look at Rails console is not outputting SQL Statements to my Development Log. Rails console initially do not output anything to development.log