fluentd」カテゴリーアーカイブ

fluentdでrailsなどのアプリケーションのログをtailする

この記事は【2016年11月5日】と作成から2年以上経っているため、記事の内容が古い可能性があります。最新の情報を合わせてご確認されることを推奨いたします。

fluentdでは、v0.10.45から複数行にまたがるログをparseするための機能 multiline parser が実装されているようです。multiline parserを使えば、railsやその他様々なアプリケーションで複数行にまたがるログを1つのイベントとして扱うことができます。ここでは、in_tailプラグインでformatにmultilineを指定してrailsアプリケーションのログのパースを試してみたいと思います。

tailプラグインでrailsアプリケーションのログをパースして見る

tailプラグインでは、multilineの指定をformatオプションを使って指定します。

multiline parser[1]https://github.com/fluent/fluentd/blob/master/lib/fluent/parser.rbでは、formatNとformat_firstlineというオプションを指定することができます。formatNのNは、1〜20の範囲で指定可能となっています。format_firstlineは、複数行のログの開始位置を示す表現を指定することになっています。

公式のドキュメントのRailsアプリケーションのformat例を参照しながら設定を書いて見ると以下のようになりました。長く複雑な正規表現指定となっているので、私のように自信のない方は公式のサンプルを参照しながらカスタマイズした方が良いかもしれません。

この設定を送信側のfluentdに加えた上でrailsアプリケーションを起動しアクセスしてみます。この時、development.logに出力されるログは例えば以下のようになります。

送信側で正しくパースされていれば、受信側のfluentdで以下のようなイベントを受信できているのを確認できます。複数行にわたるログを1つのメッセージとして受信できているのがわかります。どうやら上手くいっているようです。

norikraでViewのレンダリングに最も時間のかかったテンプレートを探す

norikra[2]http://norikra.github.ioは、ストリームデータをSQLライクな問い合わせ言語で処理することができるソフトウェアです。ストリームデータを一定時間ごとに集計したり、ある閾値を超えるデータをチェックしたりといった処理を馴染みのあるSQLライクに記述することができるので大変便利です。また、スキーマレスでデータを柔軟に扱うことができるといった特徴もあります。

早速、norikraをインストールして試してみます。

続いて起動してみます。

無事起動できていれば、Webブラウザでhttp://localhost:26578/にアクセスすると以下のようなWebUIを確認できます。以下の画面では、すでに私がクエリを登録しているのでQueriesにクエリが表示されています。

%e3%82%b9%e3%82%af%e3%83%aa%e3%83%bc%e3%83%b3%e3%82%b7%e3%83%a7%e3%83%83%e3%83%88-2016-11-05-14-28-41

続いてnorikraにクエリを登録します。ここでは、1 minuteごとにViewのレンダリングで15.0 msecを超えるtemplateを抽出し、レンダリングにかかった最大時間と共に取り出すよう設定してみます。

%e3%82%b9%e3%82%af%e3%83%aa%e3%83%bc%e3%83%b3%e3%82%b7%e3%83%a7%e3%83%83%e3%83%88-2016-11-05-14-13-34

fluentdのデータストリームでnorikraとやりとりするように、fluent-plugin-norikra[3]https://github.com/norikra/fluent-plugin-norikraをインストールします。続いて、norikraにイベントを送信し、結果を取り出す設定を追記します。

railsアプリケーションに何回かアクセスしてみると、以下のようなnorikraの実行結果をfluentdで確認することができます。

参考リンク

脚注

fluentdのin_tailプラグインの動作について理解する

この記事は【2016年11月3日】と作成から2年以上経っているため、記事の内容が古い可能性があります。最新の情報を合わせてご確認されることを推奨いたします。

fluentdは、ログ収集ツールで人気のソフトウェアとして広く知られており、私も以前から大変お世話になっているOSSのひとつです。ログファイルからデータを読み取り後続の処理にデータを流すfluentdに標準で組み込まれているtailプラグインは、最も良く使われる機能のひとつだと思いますが、内部の動作について理解が不十分だと、あれ??と想定通りの結果が得られずハマってしまうこともあるかもしれません(私がそうでした。。)。ドキュメントを参照しながら設定するだけですぐに使い始められるのですが、何か障害がおきた時に内部動作についてある程度把握していることによって、その後の原因調査をスムースに進められることができると思います。そこで、備忘録の意味も込めて、tailプラグインについて自分なりに調べた内容をまとめてみました。

内容に間違いあれば指摘していただけると幸いです。

tail Input Pluginの動作概要

主に公式のドキュメントを参照して和訳したものです。

  • tail -F に類似した振る舞いをする(tail -f でなくtail -Fに注意、-F オプションでは、tailはファイルのrenameやrotateを追跡し、inode numberが変わった場合はファイルをreopenし、tailを再開してくれる)。
  • tail開始時、デフォルトではtail対象のファイルの先頭でなく末尾からデータの読み込みを開始する。
  • positionファイルを指定することでtailしていたファイルの最終の読み込み位置(pos)を記録し、次回開始時にpos以降のデータから読み込みを開始する。

http://docs.fluentd.org/articles/in_tail

tail Input Pluginの内部を追ってみる

in_tailでは、libev[1]http://libev.schmorp.de/bench.htmlというイベントライブラリベースのCool.io[2]https://github.com/tarcieri/cool.ioというライブラリを使って、TimerやStat(ファイルやディレクトリの変更)のイベントを監視している。以下全体像を図にしてみる(概要把握のため省略部分あり)。

fluentd v0.12.12のソースを参考。

newtailinput-overview

  1. NewTailInputは、fluentd起動時にrefresh_intervalで指定された間隔で発火されるTimerイベントを生成し、Cool.ioのイベントループに登録する。
  2. その後はrefresh_intervalごとにTimerイベントが通知され、refresh_watchersメソッドが呼び出される。その中で、既存の古いwatcherの停止や新しくtailに追加されるpathのファイルを監視するためのTailWatcherを新しくセットアップする。
  3. TailWatcherは1つ1つのpath(ワイルドカードを含む場合は展開されたもの)に対して生成され、初期化時にデフォルトで1secごとのTimerイベント、Statイベント及びファイルローテートのためのハンドラなどが割り当てられる。
  4. TailWatcherのTimer及びStatのイベントが通知されるとTailWatcher#on_notifyメソッドが呼ばれ、登録された各種ハンドラが呼び出される。
  5. pathのファイルに読み取るべきデータがあれば、IOHandlerによって一回の処理で最大行数がread_lines_limitを超えないようバッファされ、parserによってパースされ、tag付けされイベントとしてemitされる。

rotateの判定

rotateは、以下のステップで判定される。

  1. pos_fileのinodeと新しく検出されたファイルのinode番号が同じ場合は、1) renameした後元に戻された、2) 同じファイルに対するシンボリックリンク・ハードリンクが再作成された、とみなしpos_fileに記録されていたposから読み込みを開始する。
  2. pos_fileにあるinode番号が0でない場合、pos_fileを指定しfluentdを以前に起動していたケースと想定し、rotateされたファイルの先頭からデータの読み込みを開始する。
  3. 上記以外の場合、read_from_headがtrueであればファイルの先頭から、そうでない場合はファイルの末尾からデータの読み込みを開始する。

pathに時間のformat文字列を含む指定の場合

以下のような指定の場合は、上記の判定ステップの3に該当するため、read_from_headオプションをtrueにしていなかった場合は初期のデータの読み込みをスキップしログを取りこぼしてしまう可能性がある。これは、動作概要にあったようにtailでは末尾からデータの読み込みを開始する事になっているためである

上記の場合は、時間単位で新しくtail対象のファイルがrefresh_watcherメソッドの呼び出しの中で検出される。この時、pos_fileにtail対象のpathとpos及びinode番号が初期値で記録される。read_from_headオプションがtrueでinode番号が初期値(=0)から更新されていなければ、新しいpathのinode番号とpos(=0)でpos_fileの上書きを試みる。ただし、pathのファイルが存在しない場合は上書きされず、次のようなログを確認できるだろう。

続けて、pathに対するTailWatcherのイベント監視がセットされる。tail対象のpathがファイルシステム上に見つかれば、TailWatcher#on_rotateメソッドの中でinode番号とpos(read_from_headがfalseの場合はstat.size、trueでは0)が更新され、そのpathのIOHandlerが生成される。

pathが固定の場合

以下のようにpathが固定の場合、通常はrotateして新規にファイルを生成する事になるが、この場合は上記判定ステップの2に該当する。

pos_file中のpath名は変わらないが、inode番号とposは更新される。

pos_fileの構造

pos_fileの中はテキストで読める形式になっており、構造は以下の通り。

時間のformat文字列を指定した場合のpos_fileは以下のようになっている。

fff...ffは、pathがunwatch状態であることを示している。

pathが実際に存在しない場合は、posもinodeも0になっている。

in_tailのオプション

tag (必須)

emitするイベントに使われるtag名を指定する。

path (必須)

tail対象のpath。時間のformat文字列や*を指定することもできる。

exclude_path

除外したいpathをarrayで指定する。デフォルトは空。

refresh_interval

pathに対するwatcherを更新するリフレッシュ間隔(秒)を指定する。デフォルトは60

read_from_head

このオプションが指定されていると、新規にtailされるpathのファイルの先頭からデータの読み込みを開始する。デフォルトはfalse

pathに時間のformat文字列が含まれるような場合にはtrueにしておくことで、時間単位などのpath指定でファイルの先頭のログだけ送られていないといった思わぬ事態に陥らずに済む。

read_lines_limit

IOHanlderが一回のステップ(IOHandler#on_notify)でログを処理する最大行数。デフォルトで1000

multiline_flush_interval

formatがmultiline指定の場合に有効で、複数行にまたぐログを扱う時のバッファのflush間隔(秒)。デフォルトは5

pos_file

pathの読み込み位置(pos)を記録するファイル。

fluentdを再起動しても、最後に記録したpos以降からデータの読み込みを開始できる。できるだけ指定するよう推奨されている。

format (必須)

レコードのparse方式を指定する。noneでログをそのまま扱う。

time_format

timeフィールドが含まれる場合の時間を解釈するための時間のformat文字列。

rotate_wait

rotateされた後に監視を停止するまでの間隔(秒)を指定する。デフォルトで5

rotateされた後もここで指定された時間の間はtailを継続してくれる。

enable_watch_timer

TailWatcherで1secのTimerイベントを使うか否かを指定する。inotify[3]https://linuxjm.osdn.jp/html/LDP_man-pages/man7/inotify.7.htmlをサポートしていないシステムのために用意されている。デフォルトはtrue

その他

pos_fileを誤って削除してしまった場合

LinuxやUnixでは、rmコマンドでpos_fileを削除してもプロセスが生きている限り実態は存在しておりエラーにならない。稼働中はpos_fileが再作成されることはないので、次回起動時に新規にpos_fileが作成される事になる。この時pos_file中のposは、pathで新しくtailを開始した時の値(前出のrotate判定の3)で更新され、read_from_headがtrueの場合はファイルの先頭からデータの読み込みを開始するためデータの重複が起きてしまう。くれぐれもpos_fileを削除しないよう注意するとともに、誤削除防止の意味でもpos_fileは通常のログディレクトリとは別に専用のディレクトリに書くようにした方が良いと思う。

read_from_headオプションtrue時の挙動

read_from_headをtrueにしていた場合、pos_file指定がないとpathで指定されたファイルの先頭からデータの読み込みを開始するので、送られるデータが重複してしまうかもしれない。pos_fileを指定している場合、 read_from_headがtrueだとしても、すでに読み込みされていれば最終のpos以降からデータが読み込まれるのでデータの重複は起こらない。

重複を回避するための方法として、ログにuuidのような一意な識別子を振りアプリケーションで処理する際に重複カットするなどがある。

pathをシンボリックリンクにしリンク先をつけ変えた場合

この場合、前出のrotate判定で2に該当する。inode番号は新規、posは0でpos_fileのエントリが更新され、新しいpathのファイルの先頭からデータの読み込みが開始される。

pathのファイルをrenameした後元に戻した場合

通常行わない操作だと思うが、この場合前出のrotate判定で1に該当する。pathのファイルをrenameした後、pathに対するTailWatcherによる監視はrotate_waitの時間だけ継続される。同時に新しくpathに対するTailWatcherが生成されイベント監視を開始する。mvでrenameしたファイルを元のpathに戻すと、pos_fileに記録されているinode番号が同じであるため、pos_fileに記録されていたpos以降からデータの読み込みを再開する。この時、renameした後のrotate_waitの期間内にデータが追記されていた場合、posはメモリ上更新されるがその変更はpos_fileには反映されない。よって、pos_fileの最後に記録されていたposからデータの読み込みが開始され、既送信済みデータとの重複が起きる可能性があるので注意する。

rotate-position-entry

rotateする前にfluentdがダウンして、rotate後にfluentdを開始した場合

この場合は、前出のrotate判定2にあたる。rotateする前にfluentdがダウンしてpathのファイルにデータが追記された後、pathのファイルがrotateされfluentdを再起動した場合は、新しくポイントされたpathのファイルの先頭からデータの読み込みが開始されるので、fluentdダウン後に追記されたデータは送られてこない。

設定例

時間のformat文字列を含む場合

  • formatは指定なしで、{"message": "<line>"}の形式でイベントをemitする。
  • pathは時間単位のformat文字列を指定し、時間単位で分けられたファイルをtailする。新規pathの検出の間隔は30sec。
  • pos_fileを指定し、再起動後も最終のpos以降からデータの読み込みを開始する。
  • read_from_headをtrueに設定し、新しいtail対象のpathが検出された時は、pathで指定されたファイルの先頭から読み込みを開始する。

format jsonでtime_key、time_format指定がある場合

  • timeフィールドは、time_formatで指定されたformat文字列で解釈される。
  • pathは固定のファイルで、rotateされた後は新しくポイントされたファイルの先頭から読み込みを開始する。

参考リンク

fluentd multiprocessプラグインを使う

この記事は【2014年8月3日】と作成から2年以上経っているため、記事の内容が古い可能性があります。最新の情報を合わせてご確認されることを推奨いたします。

fluentdでマルチコアのサーバーリソースを生かすため、fluentdのmultiprocessプラグインを導入することにした。multiprocessプラグインについては、以下の公式ドキュメントに書かれているとおりに設定すれば、無事複数プロセスを起動することができる。

http://docs.fluentd.org/ja/articles/in_multiprocess

ただ、今までの設定を複数プロセスから共通で使うように指定したい場合には注意が必要かと思う。例えば、out_fileなどを使っていて、うっかり以下のようにすると複数プロセスからの同一ファイルへの操作が発生してしまう。

これについては、以下のページでも言及されているように、同一ファイルへの指定は避けた方が良い。

http://d.hatena.ne.jp/sfujiwara/20121027/1351330488

何故なのか、理解を深めるために備忘録を含めソースを追ってみる。(バージョンは、v0.10.39、間違ってたらすみません)

まず、上記でも言及されているように、out_fileは設定ファイルの指定ごとにFileOutputオブジェクトで管理される。FileOutputクラスは、BufferedOutputを継承しているので、送られてくるデータはバッファにたまり、BufferedOutputOutputThreadによるループのサイクルでフラッシュされる(チャンクはキューに入り、最終的にファイルへ書き出される)。

FileBuffer#resumeを見ると、fluendの起動時、FileBufferBasicBufferを継承している)はpath文字列を元に既存のバッファファイルを探し、バッファファイルが見つかれば、chunkのkeyとchunkからなるマップを生成する。仮に、out_fileによる同一のpath指定が存在し、タイミングによっては前回停止時のバッファファイルが複数存在している場合、生成するマップのkeyが重複するため、一方のバッファはマップから漏れてしまうこともある。また、同一のバッファファイルを参照している時、フラッシュのタイミングによっては、バッファをキューに入れる際のrenameの処理で失敗し、知らない間にOutputThreadが死んでしまっていることもある。

access_log.20140801.b4ffb8ecb73040f17

しかし、同じプロセスであれば、FileBufferのクラス変数@@buffer_pathsで重複パスが存在している場合、fluentdの起動時の処理でConfigErrorがraiseされpathの重複は報告されるようになっている。(コミット:fbcfaa7

また、webhdfsでHDFSへ書き込んでいる場合にも、同一ファイルに対しての複数のHTTPリクエストが発生するので、注意が必要かと思う。

ということから、multiprocessで複数プロセスで処理するときには、設定を慎重に行なう(当たり前と突っ込まれそうだが)必要がありそうだ。

BufferedOutput of Fluentd

この記事は【2014年5月8日】と作成から2年以上経っているため、記事の内容が古い可能性があります。最新の情報を合わせてご確認されることを推奨いたします。

fluentdのBufferedOutputについて理解が浅かった。。

fluentdでアプリケーションサーバーからのログを集約するAggregatorノードの設定をメモリ容量をもとに見直していたところ,出力先に何らかの障害が発生し出力不可になった場合,Aggregatorノード上のfluentdが再送上限回数に到達する前に物理メモリを食い潰し詰まってしまいそうだった。

BufferedOuputを継承するクラス(ObjectBufferedOutput やTimeSlicedOutputはこのクラスを継承している)は,出力先に何らかの障害が発生し,転送不可になった場合でも,データをバッファリングすることで極力データをロストしないような仕組みになっており,BufferedOutputクラスは以下のような動作をする。以下,備忘録を兼ねて記載しておく(間違ってたらごめんなさい。v0.10.39より)

  • 出力に失敗し,失敗回数がretry_limitより小さい場合,BufferedOutput#calc_retry_waitで計算される時間後までwaitする。
  • secondaryが設定されていないかつ出力に失敗した場合,失敗回数がretry_limitに達すると,キューに溜まったチャンクは破棄され,失敗履歴もクリアされる。
  • secondaryが設定されているかつ出力に失敗した場合,失敗回数がretry_limitに達すると,即座にretryされ(BefferedOutput#try_flushのbegin…end),next_rety_time後にsecondaryへflushされる。secondaryへの出力にも失敗しsecondary_limitを超えると,キューに溜まったチャンクは破棄され,失敗履歴もクリアされる。
  • キュー内のチャンク数がbuffer_queue_limitに達していて,新たにキューにチャンクを追加しようとするとBufferQueueLimitErrorが投げられ新たなチャンクは拒否される。
  • キュー内のチャンク数がbuffer_queue_limit以下で,”現在のチャンクのサイズ+emitされるデータのサイズ”がbuffer_chunk_limitを超えた場合,新しいチャンクが生成される。
  • リトライに成功した場合で,キュー内に複数のチャンクが蓄積されていた場合は,queued_chunk_flush_intervalの間隔でflushされる。

secondaryの指定は,ドキュメントではforwardout_fileを指定する例が紹介されているけれど,参考リンクでも言及されているように,なんでも指定可能なようである。ただし,secondaryを指定した場合,primaryとクラスが異なるとconfigtestやfluentdの起動時に警告が表示される(Output#secondary_init)。しかし,out_fileではsecondary_initがオーバーライドされており,具体的な処理は定義されていないため警告は表示されない。

僕の場合は,お世話になっているout_fileと互換のfile_alternativeプラグインをsecondaryに設定したが,out_fileのようにsecondary_initがオーバーライドされていないため警告が表示されてしまう(組み込みのOutputプラグインでないため,あえてそのようになっているものだと勝手に推測している。。)。しかし,少し様子を見てみるが,処理自体は正常に動作しているようだった。

この設定では,失敗回数が13回に達し,次のリトライ時間(約2時間強くらい?)になった時に即座にsecondaryへflushされる。

正しく扱えるようになるには,やはり細部を知る必要があると改めて実感。

参考