Ruby on Rails c нуля!

Rails 3 снабжен очень мощной системой уведомлений о происходящем внутри приложения. Давайте на примере простого приложения рассмотрим то, что есть уведомления и как с ними работать.

Мною было создано простое приложение с одной моделью и контроллером:

$ rails g scaffold User name:string email:string login:string

Именно на примере такого простого приложения мы и рассмотрим уведомления. Давайте запустим наше приложение:

После запуска приложения мы увидим в консоли следущее:

$ rails s
=> Booting WEBrick
=> Rails 3.0.7 application starting in development on http://0.0.0.0:3000
=> Call with -d to detach
=> Ctrl-C to shutdown server
[2011-05-22 11:48:04] INFO  WEBrick 1.3.1
[2011-05-22 11:48:04] INFO  ruby 1.9.2 (2010-08-18) [i686-linux]
[2011-05-22 11:48:04] INFO  WEBrick::HTTPServer#start: pid=3670 port=3000

Это означает, что приложение загружено в память и что сервер приложения был запущен, однако само приложение ничего не выполняет. При переходе на http://localhost:3000/ мы также ничего нового в консоли не убидим, поскольку мы перешли на статическую страницу приветствия, которая нам была отдана нашим сервером, по умолчанию, а не приложением. Однако, когда мы перейдем по адресу http://localhost:3000/users/ то есть приложение выполнит экшен index в контроллере UsersController, то в консоли мы увидим следущее:

Started GET «/users» for 127.0.0.1 at 2011-05-22 11:52:59 +0300
Processing by UsersController#index as HTML
User Load (0.8ms)  SELECT «users».* FROM «users»
Rendered users/index.html.erb within layouts/application (4.4ms)
Completed 200 OK in 158ms (Views: 11.4ms | ActiveRecord: 0.8ms)

Это называется записью логфайла, которая создается на основе уведомлений (Rails Notifications). Если интересно, то файлы логов можно найти в ../log/ в нашем случае это development.log по названию окружения в котором мы работаем. Файл логов содержит абсолютно то же, что было напечатано в консоли.

Если мы перейдем по ссылке создания нового пользователя, то в лог-файле и в консоли появится еще одно сообщение логера:

Started GET «/users/new» for 127.0.0.1 at 2011-05-22 14:20:03 +0300
Processing by UsersController#new as HTML
Rendered users/_form.html.erb (87.8ms)
Rendered users/new.html.erb within layouts/application (107.4ms)
Completed 200 OK in 431ms (Views: 153.4ms | ActiveRecord: 0.0ms)

Также как и при создании пользователя:

Started POST «/users» for 127.0.0.1 at 2011-05-22 14:21:23 +0300
Processing by UsersController#create as HTML
Parameters: {«utf8″=>»✓», «authenticity_token»=>»SS+EAk301jEk/iYUGDgKO3he9Xm94/tvY66J6i+T+w4=», «user»=>{«name»=>»Vladimir», «email»=>»egotraumatic@gmail.com», «login»=>»mylogin»}, «commit»=>»Create User»}
SQL (0.2ms)   SELECT name
FROM sqlite_master
WHERE type = ‘table’ AND NOT name = ‘sqlite_sequence’
AREL (0.5ms)  INSERT INTO «users» («name», «email», «login», «created_at», «updated_at») VALUES (‘Vladimir’, ‘egotraumatic@gmail.com’, ‘mylogin’, ’2011-05-22 11:21:23.859654′, ’2011-05-22 11:21:23.859654′)
Redirected to http://localhost:3000/users/1
Completed 302 Found in 326ms

Started GET «/users/1″ for 127.0.0.1 at 2011-05-22 14:21:24 +0300
Processing by UsersController#show as HTML
Parameters: {«id»=>»1″}
User Load (0.3ms)  SELECT «users».* FROM «users» WHERE «users».»id» = 1 LIMIT 1
Rendered users/show.html.erb within layouts/application (22.0ms)
Completed 200 OK in 56ms (Views: 37.1ms | ActiveRecord: 1.0ms)

Откуда берутся эти сообщения?

Эти сообщения — передаются в логер из уведомлений, а точнее строятся на основе уведомлений. В этой статье мы как раз рассмотрим уведомления в Rails.

Уведомления — это подробные отчеты о произведенных в приложении инструментами действиях. Инструмент — это определенный кусок кода, который выполняет какую-то определенную работу. Каждый запрос пользователя к приложению = инструмент, для которого создается несколько уведомлений.

Подпись на уведомления

Для того, чтобы подписаться на уведомления, то есть получать уведомления и выполнять с ними какие-то действия, например вести по ним логи, следует использовать метод ActiveSupport::Notifications.subscribe. Суть метода проста, он передает уведомления в блок кода, в котором с этими уведомлениями можно работать. По умолчанию выдаются все уведомления, однако .subscribe может принимать параметр — фильтр, который позволяет получать уведомления по определенному инструменту.

Давайте выполним простую подписку на стандартные уведомления для предопределенных инструментов:

В файл ../config/environment.rb необходимо добавить следущий код:

Rails.logger = Logger.new("#{Rails.root}/log/notifications.log")

ActiveSupport::Notifications.subscribe do |name, start, finish, id, payload|
  Rails.logger.info([name, start, finish, id, payload])
end

Этим кодом мы переписали логер Rails и теперь логи не печатаются в консоль и не записываются в лог-файлы. Вместо этого логер занимается тем, что записывает уведомления в файл ../log/notifications.log. Если мы откроем этот файл, то увидим набор уведомлений для одного инструмента:

Started GET «/users/1″ for 127.0.0.1 at 2011-05-22 15:18:56 +0300
["start_processing.action_controller", 2011-05-22 15:18:58 +0300, 2011-05-22 15:18:58 +0300, "e6f8545eff7742cce6a1", {:controller=>"UsersController", :action=>"show", :params=>{"action"=>"show", "controller"=>"users", "id"=>"1"}, :formats=>[:html], :method=>»GET», :path=>»/users/1″}]
Processing by UsersController#show as HTML
Parameters: {«id»=>»1″}
["sql.active_record", 2011-05-22 15:18:58 +0300, 2011-05-22 15:18:58 +0300, "e6f8545eff7742cce6a1", {:sql=>"          SELECT name\n          FROM sqlite_master\n          WHERE type = 'table' AND NOT name = 'sqlite_sequence'\n", :name=>"SQL", :connection_id=>91608110}]
SQL (0.6ms)   SELECT name
FROM sqlite_master
WHERE type = 'table' AND NOT name = 'sqlite_sequence'

["sql.active_record", 2011-05-22 15:18:58 +0300, 2011-05-22 15:18:58 +0300, "e6f8545eff7742cce6a1", {:sql=>"SELECT  \"users\".* FROM \"users\" WHERE \"users\".\"id\" = 1 LIMIT 1", :name=>"User Load", :connection_id=>91608110}]
User Load (0.3ms)  SELECT "users".* FROM "users" WHERE "users"."id" = 1 LIMIT 1
["!render_template.action_view", 2011-05-22 15:18:58 +0300, 2011-05-22 15:18:58 +0300, "e6f8545eff7742cce6a1", {:virtual_path=>"users/show"}]
["!render_template.action_view", 2011-05-22 15:18:58 +0300, 2011-05-22 15:18:58 +0300, "e6f8545eff7742cce6a1", {:virtual_path=>"layouts/application"}]
["render_template.action_view", 2011-05-22 15:18:58 +0300, 2011-05-22 15:18:58 +0300, "e6f8545eff7742cce6a1", {:identifier=>"/home/vladimir/tuts/notification/app/views/users/show.html.erb", :layout=>"layouts/application"}]
Rendered users/show.html.erb within layouts/application (17.3ms)
["process_action.action_controller", 2011-05-22 15:18:58 +0300, 2011-05-22 15:18:58 +0300, "e6f8545eff7742cce6a1", {:controller=>"UsersController", :action=>"show", :params=>{"action"=>"show", "controller"=>"users", "id"=>"1"}, :formats=>[:html], :method=>»GET», :path=>»/users/1″, :status=>200, :view_runtime=>27.109384536743164, :db_runtime=>0.9153389999999999}]
Completed 200 OK in 224ms (Views: 27.1ms | ActiveRecord: 0.9ms)

Каждое уведомление состоит из имени уведомления (name), времени запуска (start) и окончания работы (finish) инструмента, id — уникальный идентификатор instrumenter’а, а также хэша payload с более подробными сведениями о работе инструмента. Instrumenter — это, проще говоря владелец инструментов, другими словами процесс. Когда пользователь переходит по определенному адресу, это является одним единственным процессом, который состоит из нескольких инструментов, для которых (для некоторых из которых) определены уведомления.

Изучение всех уведомлений вашего приложения — это безусловно самое интересное, чем можно заняться при отладке и тестировании приложения, однако метод .subscribe может помочь вам фильтруя уведомления. В качестве параметра для фильтрации .subscribe принимает имя уведомления, пример:

ActiveSupport::Notifications.subscribe "sql.active_record" do |name, start, finish, id, payload|
  Rails.logger.info([name, start, finish, id, payload])
end

Если теперь перезапустить приложение и перейти по адресу http://localhost:3000/users, то notifications.log будет содержать следущую информацию:

Started GET «/users/» for 127.0.0.1 at 2011-05-22 15:31:30 +0300
Processing by UsersController#index as HTML
["sql.active_record", 2011-05-22 15:31:31 +0300, 2011-05-22 15:31:31 +0300, "acefadb7a8aa113636f8", {:sql=>"SELECT \"users\".* FROM \"users\"", :name=>"User Load", :connection_id=>80761450}]
User Load (0.7ms)  SELECT "users".* FROM "users"
Rendered users/index.html.erb within layouts/application (21.9ms)
Completed 200 OK in 277ms (Views: 30.8ms | ActiveRecord: 0.7ms)

То есть было записана одно единственное уведомление:

["sql.active_record", 2011-05-22 15:31:31 +0300, 2011-05-22 15:31:31 +0300, "acefadb7a8aa113636f8", {:sql=>"SELECT \"users\".* FROM \"users\"", :name=>"User Load", :connection_id=>80761450}]

Вы также можете использовать в качестве параметра для фильтра регулярные выражения, например когда вам необходимо отфильтровать несколько подобных по имени уведомлений.

Кстати, чуть не забыл, каждое уведомление является экземпляром класса .

Вы можете спросить, почему кроме уведомлений в notifications.log записывается прочая информация, например:
Started GET "/users/" for 127.0.0.1 at 2011-05-22 15:31:30 +0300
Processing by UsersController#index as HTML

или

User Load (0.7ms)  SELECT "users".* FROM "users"
Rendered users/index.html.erb within layouts/application (21.9ms)
Completed 200 OK in 277ms (Views: 30.8ms | ActiveRecord: 0.7ms)

Ответ: Сообщение, с которым работает логер автоматически дополняется информацией, которую Rails считает необходимой. Если бы мы записывали уведомления в файл без использования логера, то дополнительные данные, которые дописывает Rails в логи, не попали в файл с записями уведомлений.

Изучение уведомлений - очень крутое занятие и напоминает занятия магией в результате которых вы более подробно можете разобраться с работой Rails.

Создание инструмента = создание уведомлений о его работе

Инструмент - это "прослушиваемый" блок кода, для которого определяется время запуска и время конца выполнения, а затем вся информация о нем передается в умедомление - экземпляр класса ActiveSupport::Notifications::Event. Давайте рассмотрим создание инструмента:

Создадим инструмент в экшене UsersController#show:

def show
  ActiveSupport::Notifications.instrument(:"sql.find_a_single_user", controller: params[:controller], action: params[:action]) do
    @user = User.find(params[:id])
  end

  respond_to do |format|
    format.html # show.html.erb
    format.xml  { render :xml => @user }
  end
end

...и не забудем подправить фильтр в environments.rb для большего удобства:

ActiveSupport::Notifications.subscribe "sql.find_a_single_user" do |name, start, finish, id, payload|
  Rails.logger.info([name, start, finish, id, payload])
end

А теперь, давайте взглянем на уведомление, которое было записано в ../log/notifications.log после перехода на http://localhost:3000/users/1/:

[:"sql.find_a_single_user", 2011-05-22 16:10:06 +0300, 2011-05-22 16:10:07 +0300, "a4615b383ebd474ad571", {:controller=>"users", :action=>"show"}]

Теперь вы знаете, как работают уведомления и логи в Rails и можете поэкспериментировать с ними!

Лучшая благодарность автору - ваши комментарии!