ログファイルから特定の文字列を抽出しグラフ化

◆ 目的
アプリケーションが出力するログファイル内に
特定キーワードがどの程度含まれているのかを
ほぼリアルタイムにモニタリングできるようにする。

モニタリング手段はいろいろあるだろうが、ここではcactiを使って
グラフ化させるところまでを目的とする。



◆ 手順概要
ログから抽出したいキーワードをカウントするツールを
cronで定期的に動作させる。

その結果を、snmpdのexec行を利用して外部(グラフ描画サーバ)から取得する。

カウントするツールをsnmpで実行するようなことはしない。時間がかかるためである。
カウントさせるツールはcronを利用して定期的に動作させておき、
snmpdのexecでは、そのツールが出力したファイルをオープンさせることで値を参照する。



◆ 事前準備
特定のログをカウントするツールを用意する。

(1) 読み込むログファイルと検索する文字列の指定
適当な名称のファイル(ここではkeywordファイル)に、下のフォーマットで指定する。
"ログファイル名 : 検索文字列1, 検索文字列2"

mta.log からreceived, delivered ログを、
imap.log からconnectedとdisconnected ログを探す場合は下のように書く。

# vi /usr/local/log/keyword
/var/log/mta.log : received, delivered
/var/log/imap.log : connected, disconnected

シンボリックリンクになっている場合もリンク名を書いておけばよい。
# ls -lF log/hoge.log
(略) /var/log/hoge.log -> /var/log/hoge.201108160000+0900.log
ファイルに記載するのは"/var/log/log/hoge.log"でよい、ということである。

(2) 検索ワードカウントツール
先ほどのファイルに記載した各ログファイルから、指定した時間内に
それぞれの検索対象のワードが何回出てきたかを数え上げるツールを用意する。

単純にログファイルを一行ずつ流しながら、
各行に検索ワードがマッチするかどうかを
判定させてカウントアップさせるだけである。
ポイントは次の２点。
・ ファイルポインタを覚えておき、次回検索時はそこからログを集計する。
毎回ファイルの先頭から検索していては時間がかかりすぎるため、
ファイルポインタをファイルに記録させ、
次回はそのポインタから読み始める。
ログ数が多少多くても数秒程度で実行し終えれるだろう。

・ ファイルの切り替え(ローテート)にも対応させる。
実装方法は単純で、いまいまの検索対象のログファイル名をファイルに記録しておき、
次回ツールが動く際に確認する。
記録していたファイル名とオープンしたファイル名に相違があれば、
前者は別途記録していたファイルポインタからファイルの末尾までを、
後者はファイルの先頭から読み始めカウントさせる。
(注意)
このツールはログファイルの先頭が下のように日付で出力されている場合にのみ有効である。
そうでない場合は書き換えが必要である。
どこをどう変えればいいかはコードを見てもらえればすぐに分かるだろう。

YYYYMMDD hhmmss
(例)
20010101 123050

#!/usr/bin/ruby

require 'timeout'

$end_time = (Time.now).strftime("%Y%m%d %H%M")


def get_file(tmp_file)
  if FileTest.exist?("/var/tmp/file#{tmp_file}") == false
    return nil
  end

  open("/var/tmp/file#{tmp_file}", 'r') do | fp |
    fp.each do | saved_file |
      return saved_file
    end
  end
end


def get_pointer(tmp_file)
  if FileTest.exist?("/var/tmp/pointer#{tmp_file}") == false
    return 0
  end

  open("/var/tmp/pointer#{tmp_file}", 'r') do | fp |
    fp.each do | pointer |
      return pointer.to_i
    end
  end
end


def set_file(tmp_file, file)
  open("/var/tmp/file#{tmp_file}", 'w') do | fp |
    fp.print(file)
  end
end


def set_pointer(tmp_file, pointer)
  open("/var/tmp/pointer#{tmp_file}", 'w') do | fp |
    fp.print(pointer)
  end
end


def extract(keyword)
  open(keyword) do | kw |
    kw.each do | file_words |
      cnt = Hash.new

      file_words.scan(/(.*?):(.*)/) do | symbolic_file, words |
        words.split(',').each do | word |
          cnt[word.strip] = 0
        end

        dir = File.dirname(symbolic_file.strip!)
        now_basename = File.readlink(symbolic_file)

        now_file = dir + '/' + now_basename

        tmp_file = symbolic_file.gsub(/\//, '_').strip

        saved_file = get_file(tmp_file)
        saved_file.chomp! if saved_file != nil

        # saved file
        if saved_file != now_file && saved_file != nil
          pointer = get_pointer(tmp_file)
          open(saved_file) do | fp |
            fp.seek(pointer, IO::SEEK_SET)
            count_saved(fp, words, cnt, tmp_file)
          end
        end

        # now file
        pointer = get_pointer(tmp_file)
        open(now_file) do | fp |
          fp.seek(pointer, IO::SEEK_SET)
          count_now(fp, words, cnt, tmp_file)
        end

        set_file(tmp_file, now_file)
        output(symbolic_file, words, cnt)
      end
    end
  end
end


def count_saved(fp, words, cnt, tmp_file)
  begin
    timeout(30) do
      fp.each do | line |
        time = line.scan(/^\d{8} \d{6}/)[0]

        words.split(',').each do | word |
          word.strip!
          cnt[word] += 1 if line =~ /#{word}/
        end
      end

      set_pointer(tmp_file, 0)
    end

  rescue Timeout::Error
    puts "ERROR : Timeout"
    exit 1
  end
end


def count_now(fp, words, cnt, tmp_file)
  begin
    timeout(30) do
      fp.each do | line |
        time = line.scan(/^\d{8} \d{6}/)[0]

        if time == nil || time >= $end_time
          break
        end

        words.split(',').each do | word |
          word.strip!
          cnt[word] += 1 if line =~ /#{word}/
        end
      end

      set_pointer(tmp_file, fp.pos)
    end

  rescue Timeout::Error
    puts "ERROR : Timeout"
    exit 1
  end
end


def output(file, words, cnt)
  file.gsub!(/_/, '/')

  words.split(',').each do | word |
    word.strip!

    print file, "  : ", word, " : ", cnt[word], "\n"
  end
end


extract(ARGV.shift)

(3) 使い方
実行権限を与える。
# chmod 755 /usr/local/bin/log_count.rb

実行する。
# /usr/local/bin/log_count.rb /usr/local/log/keyword
/var/log/imap.log : connected : 34514
/var/log/imap.log : disconnected : 33082
/var/log/mta.log : received : 17695
/var/log/mta.log : delivered : 18579

結果は"ファイル名：検索ワード：回数"というフォーマットで出る。



◆ 手順
(1) cronへの登録
先ほどのツールをcronに登録する。
cronの実行間隔はグラフの描画間隔にあわせればいいだろう。

出力にはファイル名と検索文字列は不要で、件数だけ記録できればいい。
そのため強引にcutとsedコマンドを使って整形している。
もちろんログ取得ツールの中でやってもよい。

# crontab -e
*/5 * * * * ionice -c2 -n7 nice -n19 /usr/local/bin/log_count.rb /usr/local/log/keyword | cut -d ':' -f 3 | sed 's/ //g' > /usr/local/log/log_count


(2) snmpd.confへの登録
snmpd.conf内のexec行で外部から実行させるスクリプトを作成する。

# vi /etc/snmp/snmpd.conf
(略)
exec .1.3.6.1.4.1.2021.50.1 log /bin/cat /usr/local/log/log_name
exec .1.3.6.1.4.1.2021.50.2 log /bin/cat /usr/local/log/log_count
(略)


log_nameファイルには下の内容を書いておく。
log_countの値がどのログに対応しているか分かるようになっていればいいだろう。
# vi /usr/local/log/log_name
imap.log connected
imap.log disconnected
mta.log received
mta.log delivered


再起動する。
# /etc/init.d/snmpd restart


(3) snmpwalkでデータを取得できることの確認
目的の値を個別にsnmpgetするのは賢くない。
snmpwalkで一括で取得すべきである。

ローカルホスト、また情報を取得するグラフ描画サーバからsnmpwalkする。

$ snmpwalk -v 2c -c $COMMUNITY $ホスト名 .1.3.6.1.4.1.2021.50.1
UCD-SNMP-MIB::ucdavis.50.1.1.1 = INTEGER: 1
UCD-SNMP-MIB::ucdavis.50.1.2.1 = STRING: "log"
UCD-SNMP-MIB::ucdavis.50.1.3.1 = STRING: "/bin/cat /usr/local/log/log_name"
UCD-SNMP-MIB::ucdavis.50.1.100.1 = INTEGER: 0
UCD-SNMP-MIB::ucdavis.50.1.101.1 = STRING: "imap.log connected" ← ①
UCD-SNMP-MIB::ucdavis.50.1.101.2 = STRING: "imap.log disconnected" ← ②
UCD-SNMP-MIB::ucdavis.50.1.101.3 = STRING: "mta.log received" ← ③
UCD-SNMP-MIB::ucdavis.50.1.101.4 = STRING: "mta.log delivered" ← ④
UCD-SNMP-MIB::ucdavis.50.1.102.1 = INTEGER: 0
UCD-SNMP-MIB::ucdavis.50.1.103.1 = ""

$ snmpwalk -v 2c -c $COMMUNITY $ホスト名 .1.3.6.1.4.1.2021.50.2
UCD-SNMP-MIB::ucdavis.50.2.1.1 = INTEGER: 1
UCD-SNMP-MIB::ucdavis.50.2.2.1 = STRING: "log"
UCD-SNMP-MIB::ucdavis.50.2.3.1 = STRING: "/bin/cat /usr/local/log/log_count"
UCD-SNMP-MIB::ucdavis.50.2.100.1 = INTEGER: 0
UCD-SNMP-MIB::ucdavis.50.2.101.1 = STRING: "32318" ← ①の値
UCD-SNMP-MIB::ucdavis.50.2.101.2 = STRING: "29973" ← ②の値
UCD-SNMP-MIB::ucdavis.50.2.101.3 = STRING: "16714" ← ③の値
UCD-SNMP-MIB::ucdavis.50.2.101.4 = STRING: "19682" ← ④の値
UCD-SNMP-MIB::ucdavis.50.2.102.1 = INTEGER: 0
UCD-SNMP-MIB::ucdavis.50.2.103.1 = ""



(4) cacti側の設定
ここまでできればあとはcacti側の設定でグラフを描けるようにするだけである。
cactiではCacti Data Query用のXMLファイルを使う。
その手順は別ページにまとめているのでそちらを参照されたい。