障害に強いscribeサーバ構成と設定

scribeによるログ配送についていくらか試したりしつつ実戦投入しているのでその話。
今のところピーク時で20Mbps程度の流量で、100Mbpsを超えてくるようになると流量制限をシビアに考えたり中継サーバを複数台構成にしたり考えることになるのかなーと思っているが、現状はまだそこまでやってない。世の中には考えている人がぜったいいるはずなので話を聞いてみたいなあ。なんか「動かしてみた」レベルの話しかぐぐっても見付からない。悲しい。

サーバ構成

各サーバからログを(ほぼ)リアルタイムにscribedに流すのはいいとして、1台立ててるだけだと障害があったら全て終了してしまう。これはまずいので、複数台構成にする。

scribedはdeliverとcentralの両方で起動する。(設定はもちろん異なる。後述。)
通常は各サーバはすべて deliver サーバに接続してログを送る。deliverサーバはバッファリングのみを担当し、受け取ったログは基本的にはそのまますべてcentralサーバへと中継する。centralサーバは保存を担当し、ディスクへの書き込み(と同時にhdfsへの書き込み)を行う。

centralサーバの障害時には、deliverサーバは受け取ったログをローカルディスクにバッファリングする。centralサーバが接続可能な状態に復帰したらバッファされたログは自動的に再送されるので、ローカルディスクが溢れる前にcentralを復帰さえさせれば何も問題はない。(再送については設定上の注意点がある。後述。)

deliverサーバの障害時には当然だが、各wwwサーバからのログ配送用コネクションが切れて送信不可能な状態になる。このため scribe_line では複数のscribedを指定可能なようにしてある。最初に指定したサーバへの通信が失敗する場合は自動的に2番目以降のサーバに接続する。実際に使用するときには2番目にcentralサーバを指定しておけば、deliverサーバ障害時には接続はcentralへフェイルオーバするため、問題なくログの収集が継続できる。*1

scribed設定

上述した構成で正常に動作させるため、以下のような感じで設定する。今のところ流量制御やパフォーマンス最大化に関してはチューニングしてない(ほぼデフォルトのまま)ので、そのあたりは信用しないこと。

deliver

port=1463
max_msg_per_second=1000000
check_interval=1
max_queue_size=100000000
num_thrift_server_threads=3

<store>
  category=default
  type=buffer

  target_write_size=20480
  max_write_interval=1
  retry_interval=120
  retry_interval_range=60
  buffer_send_rate=5

  <primary>
    type=network
    remote_host=central.scribe.server
    remote_port=1463
    add_newline=0
  </primary>

  <secondary>
    type=file
    fs_type=std
    file_path=/home/deliver_buffer
    base_filename=access_log
    max_size=100000000
    add_newline=0
  </secondary>
</store>

単純な buffer store で、通常は primary として設定した network store(central) へ配送する。primaryへの配送が不可能な場合、secondary(ローカルディスク)にバッファリングする。
ちゃんと運用する場合、secondaryのfile storeのパスは容量が十分にあるパーティションを指定すること。うっかりテスト時のまま /tmp とかしておくと長期運用時にロクでもないトラブルに見舞われる可能性がある。また secondary の max_size にも注意。(後述)

central

port=1463
max_msg_per_second=1000000
check_interval=1
max_queue_size=100000000
num_thrift_server_threads=3

<store>
  category=default
  type=multi
  target_write_size=20480
  max_write_interval=1
  <store0>
    type=file
    fs_type=hdfs
    file_path=hdfs://node01.hadoop-cluster:50071/scribe
    base_filename=access_log
    create_symlink=no
    rotate_period=hourly
    rotate_minute=0
    add_newline=0
  </store0>
  <store1>
    type=file
    fs_type=std
    file_path=/home/archive
    base_filename=access_log
    create_symlink=no
    rotate_period=hourly
    rotate_minute=0
    add_newline=0
  </store1>
</store>

こちらは単純な multi store で、保存先はhdfsとローカルディスクの2ヶ所。設定内容はあんまり何も考えてない。centralが障害から復帰したときに無制限に再送させてるとネットワークの帯域を使い潰しかねないので、それが怖い場合は max_msg_per_second の値を絞っておけば適当に制御しながら再送してくれる。
create_symlink=no にしてあるのは、symlinkあっても別に役に立った覚えがない割に障害試験やってたら復帰時にトラブルになることがあったため。別途 tail -f しつづけたいとかいう要望でもなければ no でいいと思う。
rotate_period は hourly 以外に指定していないが、デフォルトで max_size 1,000,000,000 bytes が定まっているため、1時間のうちにこれを超える量が書き込まれる場合は自動的にrotateされる。だから生成されるファイル名(日付+生成順の連番)は時刻とイコールにはならない。*2

deliverサーバにおける buffer store の設定と動作

deliverサーバの設定において、障害時に問題になる項目が1点わかっていて、secondary の max_size だ。うっかりすると割と致命的なので、最初から意識しておいた方がよさそう。(まあデフォルトのままで問題ないんだけど。)
簡単に言えば、buffer store の max_size に大きい値を指定してはいけない。8GBメモリを積んでいるマシンが2.4GBくらいで死亡したので多分GBのオーダは危険だ。デフォルトの100MBであれば極めて安定して動作したので、ここから変えないのが良い。

以下、buffer storeの再送メカニズムの説明をしながら説明する。

前にも書いたが、buffer storeは通常は何もせずに受け取ったログをそのまま primary store へと渡す。今の場合は primary に network を指定してあって、配送先は central サーバだ。secondaryに指定したパスには 0 byte のファイルが作られるだけとなる。

primaryへの書き込みが不可能な状態となったとき、buffer storeはsecodary storeを改めてopenし、受け取ったデータをそこに書き込む。

この書き込み先ファイルは容量が max_size になるとローテートされるが、max_size が大きい値に設定されている場合*3は単一ファイルのままもりもりと書き込みを続ける。

実際のところ、書いているだけのうちは特に問題はない。しかし primary store に指定していたcentralサーバが接続可能な状態に復帰すると問題が発生する。

buffer storeはprimary復帰時の再送(BUFFER_SENDING状態)において、次のように動作する。

• secondaryに存在するログファイルに対して
  1. いちばん古いログファイルを選択し
  2. そのファイルに対する書き込みをロックして
  3. ファイル全体を一気に primary に送る

このため以下の2点が注意すべきこととなる。

メモリの使用量

ファイル全体を送るとき、どうも一度メモリに読み込んじゃってるっぽい。ファイルサイズが大きいとscribedのメモリ使用量が跳ね上がる。2.4GBのファイルを再送しようとしたときは8GBあったメモリを使い潰して動作がスタックしているっぽかった。100MBのファイルに対しては1GBもメモリを使ってなかったように見えた。(問題にならない程度だったのであんまりちゃんと確認してない。)

再送中に受け取るログ

deliverサーバが再送中に新しく受け取ったログは secondary store における「最新のファイル」に書き込まれる。そして「最新のファイル」 == 「いちばん古いファイル」の状態(secondary storeにファイルがひとつだけの状態)では書き込み対象のファイルはロックされているため、クライアントは TRY_LATER レスポンスを受け取って書き込みはできない状態となる。

特に2点目については、どのように設定しても secondary store の最後の1ファイルを再送する時に一時的にはログを受け取れない状態となるのだが、再送処理に時間がかかるとログ受信が不可能な時間も長時間にわたってしまうため、どのような問題が起きるかわからない。*4

secondary store の max_size を小さい値(100MB程度)にしておくと primary store に書き込めない間に受け取ったログは100MBの小さいファイルに分割されながら格納される。

secondary storeのファイルが複数に分割されている状態でprimary storeが復帰すると再送が行われるが、対象はもっとも古いものから順番にとなるため、その間に送られてきたログは最新のファイルに引き続き書き込みが続けられ、ログの喪失は避けられる。

再送が終わったファイルは削除されるため徐々に残りのファイル数が減っていき、最後の1ファイルの再送(このときは新しいログの受信は待たされる)が完了すれば、最初の状態に戻って復帰完了だ。

手元の環境では secodary store の max_size が100MBのとき、1ファイルの再送にかかった時間は10秒程度だった。最後の1ファイルの処理で新規ログの受信が待たされる時間が最大でも10秒程度だとすると、まあ許容範囲内じゃないだろうか。

結論

デフォルト値を信じろ。意味もわからず迂闊にデカい値とか設定すんじゃねえ。
そんだけでした。ほんとすいません。いや障害テストやっててわかったからいいんだけどさ。

*1:なお30分前後でコネクションを張り直すようにしてあり、その際は1番目に指定されたサーバから順次接続を試行するため、deliverが復帰したらそのうち全てのコネクションがdeliverへの接続に自動でフェイルバックする。またscribe_line.pyへSIGHUPを送れば即座にフェイルバックする。

*2:どうしてもイコールにしたければ max_size に非現実的なサイズを書いておけばいいと思うけど、あんまりおすすめできないなあ。

*3:で、かつ rotate_period が指定されていない場合。buffer storeのsecondaryにrotate_periodを指定する意味は皆無なので、まあ考えなくていいだろう。

*4:具体的には、このときwwwサーバ側でログファイルがrotateされると、多分rotate前のログは送信対象から外れてしまう。いやどうかな、微妙かも。試してはいない。