Help us understand the problem. What is going on with this article?

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

More than 3 years have passed since last update.

環境

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を試すよ。

fk_2000
最近の関心事:YouTube、aws、IoT、マイコンボード エンジニア採用、IT導入担当、ブログメディア編集長( https://avatarworld.info/ )、 ↓こちらのYouTubeチャンネルで動画をアップしています。 https://www.youtube.com/channel/UCFM7KsJZC8uGJ1BRMT-4dFg
https://twitter.com/fk_2000
orylab
オリィ研究所は距離や身体的問題を克服し、あいたい人に会え、行きたいところに行ける未来を実現します。
http://orylab.com
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away