1. fk_2000

    Posted

    fk_2000
Changes in title
+fluentdをインストールしてRailsのログを見やすくする(前編)
Changes in tags
Changes in body
Source | HTML | Preview
@@ -0,0 +1,290 @@
+## 環境
+Ruby on RailsがセットアップされているCentOS 6.5
+
+
+## 参考
+
+[fluentdでapacheログを収集する](http://j-caw.co.jp/blog/?p=1311)
+[CentOS 6.5 (Vagrant)に fluentd + elasticsearch + kibana をセットアップする](http://j-caw.co.jp/blog/?p=1380)
+[fluentdでrails logをtailで直接取得する方法](https://joppot.info/2014/08/27/1936)
+[gemを使ってcentosにfluentdサーバを構築する](https://joppot.info/2014/07/23/1795)
+[いまさらだけど fluentd に入門した](http://blog.a-know.me/entry/2015/06/14/094945)
+
+## 手順
+
+### 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を試すよ。
+