fluentdをインストールしてRailsのログを見やすくする（前編）

環境

Ruby on RailsがセットアップされているCentOS 6.5

参考

fluentdでapacheログを収集する
CentOS 6.5 (Vagrant)に fluentd + elasticsearch + kibana をセットアップする
fluentdでrails logをtailで直接取得する方法
gemを使ってcentosにfluentdサーバを構築する
いまさらだけど fluentd に入門した

手順

fluentdをセットアップ

vagrantに接続する（vagrant環境の構築、vagrant upは別途行っているものとする）

$ vagrant ssh

gem installでfluentdをインストールする

$ gem install fluentd --no-ri --no-rdoc

インストールされたか確認する

$ fluentd

まだconfigを作成していないので下記のエラーが出る

/home/vagrant/.gem/ruby/2.1.0/gems/fluentd-0.14.9/lib/fluent/supervisor.rb:659:in `read': No such file or directory @ rb_sysopen - /etc/fluent/fluent.conf (Errno::ENOENT)
        from /home/vagrant/.gem/ruby/2.1.0/gems/fluentd-0.14.9/lib/fluent/supervisor.rb:659:in `read_config'
        from /home/vagrant/.gem/ruby/2.1.0/gems/fluentd-0.14.9/lib/fluent/supervisor.rb:416:in `run_supervisor'
        from /home/vagrant/.gem/ruby/2.1.0/gems/fluentd-0.14.9/lib/fluent/command/fluentd.rb:286:in `<top (required)>'
        from /opt/rubies/ruby-2.1.0/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:55:in `require'
        from /opt/rubies/ruby-2.1.0/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:55:in `require'
        from /home/vagrant/.gem/ruby/2.1.0/gems/fluentd-0.14.9/bin/fluentd:5:in`<top (required)>'
        from /home/vagrant/.gem/ruby/2.1.0/bin/fluentd:22:in `load'
        from /home/vagrant/.gem/ruby/2.1.0/bin/fluentd:22:in `<main>'

configを作成して権限を付与する

$ cd /etc/
$ sudo mkdir fluent
$ sudo chmod 775 fluent/
$ ls -ld fluent/
drwxrwxr-x 2 root root 4096 Nov 17 01:31 fluent/

fluentdコマンドで設定ファイルを作成する

$ cd ~/
$ fluentd --setup /etc/fluent/
Installed /etc/fluent/fluent.conf.
$ ls -l /etc/fluent/
total 8
-rw-rw-r-- 1 vagrant vagrant 2696 Nov 17 01:44 fluent.conf
drwxrwxr-x 2 vagrant vagrant 4096 Nov 17 01:44 plugin

fluentdを手動で起動する

$ fluentd -vv

下記のログが出て監視状態となる

      </server>
    </secondary>
  </match>
</ROOT>
2016-11-17 01:47:10 +0000 [debug]: plugin/buffer.rb:114:start: buffer started in
stance=70107182796180 stage_size=0 queue_size=0
2016-11-17 01:47:10 +0000 [debug]: plugin/out_forward.rb:250:rebuild_weight_arra
y: rebuilding weight array lost_weight=0
2016-11-17 01:47:10 +0000 [debug]: plugin/out_forward.rb:250:rebuild_weight_arra
y: rebuilding weight array lost_weight=0
2016-11-17 01:47:10 +0000 [info]: plugin/in_debug_agent.rb:53:start: listening d
Ruby uri="druby://127.0.0.1:24230" object="Fluent::Engine"
2016-11-17 01:47:10 +0000 [debug]: plugin/in_monitor_agent.rb:213:start: listeni
ng monitoring http server on http://0.0.0.0:24220/api/plugins
2016-11-17 01:47:10 +0000 [debug]: plugin/in_http.rb:119:start: listening http b
ind="0.0.0.0" port=8888
2016-11-17 01:47:10 +0000 [info]: plugin/in_forward.rb:159:listen: listening flu
ent socket on 0.0.0.0:24224

この状態に対して、別のターミナルからコマンドを実行する

$ echo '{"first":"hello"}' | fluent-cat debug.test

下記のログが確認できる

2016-11-17 01:52:43.465981469 +0000 debug.test: {"first":"hello"}

Railsのログを整形する（railsプロジェクトは別途作成しているものとする）

railsサーバを起動する(仮に/vagrant/rails_projectとする)

$ cd /vagrant/rails_project
$ bundle exec rails s

tailコマンドでログを監視する

$ tail -f log/development.log

ブラウザでhttp://localhost:4000にアクセスする

Started GET "/" for 10.0.2.2 at 2016-11-14 05:14:52 +0000

Gem::LoadError (Specified 'mysql2' for database adapter, but the gem is not loaded. Add `gem 'mysql2'` to your Gemfile (and ensure its version is at the minimum required by ActiveRecord).):
  /home.gem/ruby/2.1.0/gems/activerecord-4.1.0/lib/active_record/connection_adapters/connection_specification.rb:190:in `rescue in spec'
  /home.gem/ruby/2.1.0/gems/activerecord-4.1.0/lib/active_record/connection_adapters/connection_specification.rb:187:in `spec'
  /home.gem/ruby/2.1.0/gems/activerecord-4.1.0/lib/active_record/connection_handling.rb:50:in `establish_connection'
  /home.gem/ruby/2.1.0/gems/activerecord-4.1.0/lib/active_record/railtie.rb:129:in `block (2 levels) in <class:Railtie>'
  /home.gem/ruby/2.1.0/gems/activesupport-4.1.0/lib/active_support/lazy_load_hooks.rb:38:in `instance_eval'
  /home.gem/ruby/2.1.0/gems/activesupport-4.1.0/lib/active_support/lazy_load_hooks.rb:38:in `execute_hook'
  /home.gem/ruby/2.1.0/gems/activesupport-4.1.0/lib/active_support/lazy_load_hooks.rb:45:in `block in run_load_hooks'
  /home.gem/ruby/2.1.0/gems/activesupport-4.1.0/lib/active_support/lazy_load_hooks.rb:44:in `each'
:

railsプロジェクトのconfig/environments/development.rbを編集する

$ vi /vagrant/config/environments/development.rb

下記の2行を追加する

config.logger = Logger.new(config.paths["log"].first)
config.logger.formatter = Logger::Formatter.new

railsサーバを再起動する（Ctrl+Cで停止して下記コマンドで起動する）

$ bundle exec rails s

ブラウザに再度アクセスし、tail log を確認すると下記のようになる

Started GET "/" for 10.0.2.2 at 2016-11-14 05:21:58 +0000
Processing by Rails::WelcomeController#index as HTML
  Rendered /home.gem/ruby/2.1.0/gems/railties-4.1.0/lib/rails/templates/rails/welcome/index.html.erb (6.9ms)
Completed 200 OK in 201ms (Views: 63.4ms | ActiveRecord: 0.0ms)
D, [2016-11-17T02:13:25.598175 #3055] DEBUG -- :
D, [2016-11-17T02:13:25.608725 #3055] DEBUG -- :
I, [2016-11-17T02:13:25.611847 #3055]  INFO -- : Started GET "/" for 10.0.2.2 at 2016-11-17 02:13:25 +0000
I, [2016-11-17T02:13:26.766705 #3055]  INFO -- : Processing by Rails::WelcomeController#index as HTML
I, [2016-11-17T02:13:26.856320 #3055]  INFO -- :   Rendered /home.gem/ruby/2.1.0/gems/railties-4.1.0/lib/rails/templates/rails/welcome/index.html.erb (10.0ms)
I, [2016-11-17T02:13:26.857168 #3055]  INFO -- : Completed 200 OK in 90ms (Views: 59.1ms | ActiveRecord: 0.0ms)
D, [2016-11-17T02:14:52.731211 #3055] DEBUG -- :
D, [2016-11-17T02:14:52.732490 #3055] DEBUG -- :
I, [2016-11-17T02:14:52.732971 #3055]  INFO -- : Started GET "/" for 10.0.2.2 at 2016-11-17 02:14:52 +0000
I, [2016-11-17T02:14:52.782571 #3055]  INFO -- : Processing by Rails::WelcomeController#index as HTML
I, [2016-11-17T02:14:52.783872 #3055]  INFO -- :   Rendered /home.gem/ruby/2.1.0/gems/railties-4.1.0/lib/rails/templates/rails/welcome/index.html.erb (0.1ms)
:

railsプロジェクトのconfig/environment.rbを編集する

$ vi /vagrant/config/environment.rb

下記のコードを追加する

class Logger
  class Formatter
    def call(severity, time, progname, msg)
      if msg.class.to_s == "String"
        msg = msg.gsub(/\n/, "")
        if msg.present? && !msg.include?("assets") && !msg.include?("erb")
          format = "[%s %d] %5s -- %s: \'%s\'\n"
          format % ["#{time.strftime('%Y-%m-%d %H:%M:%S')}.#{'%06d' % time.usec.to_s}",$$, severity, progname, msg2str(msg)]
        end
      end
    end
  end
end

railsサーバを再起動する（Ctrl+Cで停止して下記コマンドで起動する）

$ bundle exec rails s

ブラウザに三度アクセスし、tail log を確認すると下記のようにフォーマットが変わる

[2016-11-17 02:18:33.262558 3086]  INFO -- : 'Started GET "/" for 10.0.2.2 at 2016-11-17 02:18:33 +0000'
[2016-11-17 02:18:33.935627 3086]  INFO -- : 'Processing by Rails::WelcomeController#index as HTML'
[2016-11-17 02:18:34.003082 3086]  INFO -- : 'Completed 200 OK in 67ms (Views: 33.7ms | ActiveRecord: 0.0ms)'
[2016-11-17 02:18:44.410584 3086]  INFO -- : 'Started GET "/test" for 10.0.2.2 at 2016-11-17 02:18:44 +0000'
[2016-11-17 02:19:26.674791 3086]  INFO -- : 'Started GET "/hello" for 10.0.2.2at 2016-11-17 02:19:26 +0000'
[2016-11-17 02:19:32.973006 3086]  INFO -- : 'Started GET "/admin" for 10.0.2.2at 2016-11-17 02:19:32 +0000'
[2016-11-17 02:19:49.132995 3086]  INFO -- : 'Started GET "/admin?id=1" for 10.0.2.2 at 2016-11-17 02:19:49 +0000'
[2016-11-17 02:20:28.717276 3086]  INFO -- : 'Started GET "/boukis" for 10.0.2.2 at 2016-11-17 02:20:28 +0000'
[2016-11-17 02:22:03.817191 3101]  INFO -- : 'Started GET "/" for 10.0.2.2 at 2016-11-17 02:22:03 +0000'
[2016-11-17 02:22:23.961576 3101]  INFO -- : 'Started GET "/welcome" for 10.0.2.2 at 2016-11-17 02:22:23 +0000'
:

fluentdの準備

fluent-plugin-rewriteをインストールする

$ gem install fluent-plugin-rewrite

fluentdログの格納先を作成する

$ sudo mkdir /var/log/fluent
$ sudo chown root:`whoami` /var/log/fluent/
$ sudo chmod 770 /var/log/fluent/

fluent.confを編集する

$ vi /etc/fluent/fluent.conf

下記内容を追記する

<source>
  type tail
  path /vagrant/log/development.log
  tag rails.log
  pos_file /var/log/fluent/rails.pos
  format /\[(?<date>\d{1,4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}.\d{1,6}) (?<process_id>[^ ]*)\] *(?<log_level>[^ ]*) -- : '(?<message>[^\']*[^\]]*)'/
</source>

<match rails.log>
  type rewrite
  remove_prefix rails.log
  add_prefix filtered
  <rule>
    key     message
    pattern \n
    replace
  </rule>
  <rule>
    key     message
    pattern \"
    replace \'
  </rule>
</match>

<match filtered>
  type file
  format json
  path /var/log/fluent/rails_log
  time_slice_format %Y%m%d
  time_slice_wait 1s
  compress gzip
</match>

手動でfluentdを起動する

$ fluentd -c /etc/fluent/fluent.conf

/var/logにfluentログが出力されている

$ cd /var/log/fluent/rails_log/
$ ls -ltr
total 8
-rw-r--r-- 1 vagrant vagrant  68 Nov 17 04:54 buffer.b54177fa819dc80d95a95ff652b
1f8476.log.meta
-rw-r--r-- 1 vagrant vagrant 757 Nov 17 04:54 buffer.b54177fa819dc80d95a95ff652b
1f8476.log

ログの中身も出力されていることが確認できる

[vagrant@vagrant-centos65 rails_log]$ cat buffer.b54177fa819dc80d95a95ff652b1f8476.log
{"date":"2016-11-17 04:54:03.247173","process_id":"3126","log_level":"INFO","message":"Started GET /\" for 10.0.2.2 at 2016-11-17 04:54:03 +0000/ for 10.0.2.2 at 2016-11-17 04:54:03 +0000 for 10.0.2.2 at 2016-11-17 04:54:03 +0000"}
{"date":"2016-11-17 04:54:21.783944","process_id":"3126","log_level":"INFO","message":"Started GET /\" for 10.0.2.2 at 2016-11-17 04:54:21 +0000/ for 10.0.2.2 at 2016-11-17 04:54:21 +0000 for 10.0.2.2 at 2016-11-17 04:54:21 +0000"}
{"date":"2016-11-17 04:54:22.044299","process_id":"3126","log_level":"INFO","message":"Processing by Rails::WelcomeController#index as HTML"}
{"date":"2016-11-17 04:54:22.081275","process_id":"3126","log_level":"INFO","message":"Completed 200 OK in 36ms (Views: 2.4ms | ActiveRecord: 0.0ms)"}

後編では、td-agentを試すよ。