Незаменимый навык: смотреть в логи

An illustrated person sitting on the ground leaning against a wall, engrossed in reading a book. They're wearing a casual outfit with orange sneakers and a scarf.

Мы здесь на mkdev постоянно рекомендуем одни и те же вещи новым ученикам, потому что искренне считаем и уверены в том, что эти вещи помогут разобраться в программировании в разы быстрее. Одна из таких вещей – это навык внимательно изучать логи приложения.

Так уж сложилось, что в Ruby on Rails потрясающие логи. Они настолько хороши, то разобравшись в них вам больше никогда не придётся задавать следующие вопросы:

А куда отправилась форма?
А почему вьюха не срендерилась?
А чего это я кликнул на кнопку и ничего не произошло?

Логи в рельсах выводят вообще всю информацию о том, что происходит во время любого запроса в приложении: по какому пути и с какими параметрами ушёл запрос, какой контроллер его обработал, какие запросы в базу данных он отправил и какие страницы срендерил. Слишком хорошо, чтобы быть правдой? Хочется неопровержимых доказательств? Давайте разберём кусок логов mkdev.me, увидим как происходит сохранение курса после отправки формы.

Started PATCH "/admin/courses/1" for 127.0.0.1 at 2014-11-08 14:06:44 +0100
Processing by Admin::CoursesController#update as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"Ilz9+29frztKUStYqtgPCQOAfG9g5cYCmPCDisuo+Gs=", "course"=>{"title"=>"4 8 15 16 23 42"}, "commit"=>"Сохранить Course", "id"=>"1"}
  User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."id" = 1 ORDER BY "users"."id" ASC LIMIT 1
   (0.3ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
  Course Load (0.4ms) SELECT "courses".* FROM "courses" WHERE "courses"."id" = $1 LIMIT 1  [["id", 1]]
   (0.2ms) BEGIN
  Course Exists (1.5ms) SELECT 1 AS one FROM "courses" WHERE ("courses"."title" = '4 8 15 16 23 42' AND "courses"."id" != 1) LIMIT 1
  SQL (0.4ms) UPDATE "courses" SET "title" = $1, "updated_at" = $2 WHERE "courses"."id" = 1 [["title", "4 8 15 16 23 42"], ["updated_at", "2014-11-08 13:06:44.790635"]]
   (0.3ms) COMMIT
Redirected to http://localhost:3000/admin/courses
Completed 302 Found in 14ms (ActiveRecord: 3.7ms)

Ого, большая стена текста. Разберёмся по порядку, что там тут пытаются сказать.

Started PATCH "/admin/courses/1" for 127.0.0.1 at 2014-11-08 14:06:44 +0100

Судя по всему, мы отправляем PATCH-запрос по адресу /admin/courses/1. Отправляем мы его на хост 127.0.0.1, и делаем мы это в 2014-11-08 14:06:44 +0100. Было бы неплохо теперь узнать, какой контроллер обработает этот запрос.

Processing by Admin::CoursesController#update as HTML

Ага, это Admin::CoursesController, а точнее его метод update. И судя по всему мы запрашиваем данные в формате HTML. А что именно мы отправили в этом запросе?

Parameters: {"utf8"=>"✓", "authenticity_token"=>"Ilz9+29frztKUStYqtgPCQOAfG9g5cYCmPCDisuo+Gs=", "course"=>{"title"=>"4 8 15 16 23 42"}, "commit"=>"Сохранить Course", "id"=>"1"}

А, ну теперь понятно – мы отправили хэш course, в котором хранятся параметры курса. А ещё id курса, который мы пытаемся обновить. Ну и по мелочи - токен безопасности и всё такое.

Ладно, что там теперь пытается сделать наш контроллер? В логах мы не увидим код, но может примерно догадаться по логу SQL-запроса:

  User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."id" = 1 ORDER BY "users"."id" ASC LIMIT 1
   (0.3ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
  Course Load (0.4ms) SELECT "courses".* FROM "courses" WHERE "courses"."id" = $1 LIMIT 1  [["id", 1]]
   (0.2ms) BEGIN
  Course Exists (1.5ms) SELECT 1 AS one FROM "courses" WHERE ("courses"."title" = '4 8 15 16 23 42' AND "courses"."id" != 1) LIMIT 1
  SQL (0.4ms) UPDATE "courses" SET "title" = $1, "updated_at" = $2 WHERE "courses"."id" = 1 [["title", "4 8 15 16 23 42"], ["updated_at", "2014-11-08 13:06:44.790635"]]
   (0.3ms) COMMIT

Я могу ошибаться, но по-моему лог пытается мне сказать, что был выполнен SQL-запрос, который нашёл там что-то в таблице users, потом нашёл нужный курс, и обновил его в БД. Отлично, мы точно знаем какие изменения произошли в базе данных. Что было потом?

Redirected to http://localhost:3000/admin/courses
Completed 302 Found in 14ms (ActiveRecord: 3.7ms)

Всё ясно – потом был редирект на страницу со всеми курсами, и Rails вернула статус запроса 302. Всё это произошло за 14 миллисекунд, из которых 3.7 были потрачены на всякие там штуки с базой данных.

Фуф, ну, это была целая куча полезной информации для какого-то там лога, а? Кажется, там можно найти довольно таки много нужных для дебаггинга приложения данных. Например, мы видим, что вьюха не срендерилась, потому что не было даже попытки её срендерить – контроллер просто сделал редирект. Если бы редиректа не было, то мы бы смогли увидеть в логах какие именно вьюхи срендерит следующий контроллер:

Started GET "/admin/courses" for 127.0.0.1 at 2014-11-08 14:06:44 +0100
Processing by Admin::CoursesController#index as HTML
  User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."id" = 1 ORDER BY "users"."id" ASC LIMIT 1
   (0.4ms) SELECT COUNT(*) FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'admin') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL))) [["user_id", 1]]
  Course Load (0.4ms) SELECT "courses".* FROM "courses"
  Rendered admin/courses/index.html.erb within layouts/application (1.8ms)
  Rendered shared/_header.html.erb (0.4ms)
Completed 200 OK in 113ms (Views: 108.5ms | ActiveRecord: 1.4ms)

Так как вы теперь умеете читать логи, то я не буду указывать где в тексте выше строчка про рендеринг views, найдите сами :-)

Ну что, получилось у меня убедить вас, что надо всегда (всегда) смотреть в логи? А ведь я даже не упомянул о том, что вы сами можете выводить в логи какую угодно информацию, что ускоряет дебаггинг ещё сильнее.

Добавлю ещё кое-что: умение смотреть в логи это критически важный навык независимо от языка программирования или используемой технологии. Логи веб-сервера, логи системных запросов, логи базы данных, логи поведения пользователей – логи везде и всегда. Эти скромные парни тихо и незаметно хранят в себе тонны важной инфмормации, вам лишь нужно обратить на неё внимание.

А теперь бонус! Специально для подписчиков я зарылся в исходники Rails, и сделал так, чтобы они выводили логи более ярким и очевидным для новичка образом. Ценность такого хака в повседневной жизни сомнительна, но мы таким образом сможем увидеть как устроены логи внутри самих рельс и как писать грязные хаки поверх гемов.