tech.kayac.com

Lobiチームの長田です。

あらゆるWebサービスがそうであるように、Lobiでも日々大量のログが出力されています。 今回はこのログをどのように集約・解析しているかを紹介します。

TL;DR

  • アクセスログ・アプリログなど、毎秒10000行以上のログが生成されている
  • Fluentdを使用しログを集約
  • consul serviceを利用した集約サーバーの冗長化
  • ログ中のイベント検知・集約にはNorikraを使用
  • アクセスログの各種解析にはAmazon Redshiftを利用

ログの集約

aggregate.png

ログ収集エージェント

Lobiではログの集約にFluentdを利用しています。

ログファイルの集約にはfluent-agent-hydraを、Perlアプリケーション内からのログ送信にはFluent::Loggerモジュールをそれぞれ使用しています。

fluent-agent-hydraはGo言語で書かれたログ収集エージェントです。 Fluentdよりも高速・低リソースで動作します。 詳しくはfluent-agent-hydraのベンチマークディレクトリを参照して下さい。

同じくFluentdの代わりとなるエージェントとしてはPerl製のfluent-agent-liteが有名ですが、 これに対してfluent-agent-hydraはビルド済みのバイナリを配置するだけでセットアップが完了するというメリットがあります。

Fluent::LoggerからはPerlアプリケーションから同ホストのFluentdにログを送信、 更にそこからforwardしてログ集約サーバーのFluentdに送信しています。 この仕組はファイルとして保存されるアクセスログよりも粒度の細かいログを記録する場合に使用します。

ログ集約サーバーの冗長化

Lobiでは現在計4台のログ集約サーバーが稼働しており、それぞれにFluentdが起動しています。 各集約サーバーで集約されたログは1時間単位でファイルとして保存され、 最終的にはAmazon S3にアップロードされます。

各ホストのfluent-agent-hydra、Fluntedからの送信先はconsul service にログ集約サーバーを登録し、それをconsulが提供するDNS機能で名前解決することで決定しています。 consulによるログ集約サーバーのヘルスチェックが失敗した場合は名前解決の対象からは除外されるため、 常に正常稼働しているサーバーにログを送信することができます。 送信中にログ集約サーバーがダウンした場合はFluentdが再送処理を行うためログの集約漏れが発生することはありません。 Fluent::Loggerから直接ログ集約サーバーのFluentdにログ送信を行わないのはこの再送処理を利用するためです。

consulのDNSで送信先を決定する手法には、

  • ログ集約サーバーの切り離しをconsul maintだけで行える
  • ログ集約サーバーを追加する際にはconsul serviceの追加のみでよく、Fluentdの設定変更は不要

などのメリットもあります。

集約したログファイルのtail

集約サーバーが複数あることで冗長化されているのは安心感があるのですが、 ログファイルが複数のサーバーに分散するため「ちょっとログファイルをtailする」といった操作が行えません。 本番環境での動作を確認したい場合、これでは不便です。

この問題を解消するために、nsshというツールを使用しています。

nsshは複数のサーバーに対してssh経由でコマンド発行を行い、出力をまとめて表示するツールです。 たとえば全ての集約サーバーを対象に以下のようなコマンドを発行すれば、 全てのログに対してまとめてtailをかけることができます。


nssh -t host1 -t host2 -t ... tail -F /var/log/aggregated/api.log

毎回ホスト名を書くのは手間なので、 実際にはconsul membersと連携するラッパースクリプトを通して nsshコマンドを使用しています。

アクセスログの解析

Norikra

analyze.png

NorikraはSQLでログストリームを処理することができるアプリケーションです。

LobiではNorikraを以下のような各種イベントの検知や、

  • HTTPリクエスト処理時に発生したエラー
  • バックグラウンドで動作しているworkerプロセスのエラー
  • 不自然なチャットメッセージ連投
  • 不自然な連続アカウント作成
  • DoS攻撃

集計処理に利用しています。

  • HTTPリクエストステータスコード別集計

Lobiで生成されるログのほぼ全てがNorikraに渡されており、 その10000行/秒のログをNorikraのプロセスひとつで処理しています(動作ホストはAmazon EC2のm4.2xlarge)。

加工されたログストリームは、専用のFluentdが動作しているサーバーに再度送信されます。 そこで必要な物はファイルに保存され、蓄積・監視が必要な値はzabbixに送信され、迅速な対応が必要な物はSlack等に通知を行います。

以下の例ではアプリケーションのログを1分単位でクエリし、 500番台のエラーが現れたらSlackに通知しています。


# Norikra query
SELECT 'notification' AS host,
 'app_status_5xx' AS title,
 'warn' AS level,
 count(*) AS count,
 last(_hostname) AS _hostname,
 last(message) AS message
FROM app.win:time_batch(1 min)
WHERE
  message LIKE '%status:5%'

# Fluentd conf
<match norikra.notification.**>
  type slack
  webhook_url https://hooks.slack.com/services/***/******
  parse none
  channel lobi
  username nuko
  message_keys level,title,count,_hostname,message
  message ":%s: %s count:%s %s %s"
  flush_interval 1s
</match>

HTTPリクエストのステータスコード集計は、以前はCounter系のFluent Pluginを組み合わせて実現していましたが、

  • ログ流量増加に伴い集計処理の負荷に耐えられなくなった
  • 設定変更には設定ファイルの変更とfluentdの再起動が必要で、本番環境のデータを用いた試行錯誤が難しかった

などの理由からNorikra導入に至りました。 特に後者については、ちょっとした集計方法の改善や実験的な値取得がWebコンソール上から手軽に行えるため大変重宝しています。 もちろんNorikraで定常的に使用するクエリはコードとしてリポジトリ管理下に置き、誤操作などでクエリが失われてもすぐに復旧できるようになっています。

Amazon Redshift

DAU(Daily Active Users: 1日のアクティブユーザー数)の算出やユーザーの動向調査など、アクセスログの解析が必要になる場合は多々あります。 Lobiでは全てのアクセスログをAmazon Redshiftに投入し、それをクエリすることで解析を行っています。

Redshiftを使用する前はファイルとして保存した圧縮しても数GBあるアクセスログを、 1行ずつ走査して、パースして、メモリ上に中間結果を保持しつつ各項目を集計する、ということを行なっていました。 当然この処理には非常に長い時間とマシンパワーが必要で、末期には午前2時に始めた解析処理が昼ごろにようやく完了する状態でした。

アクセスログをRedshiftに投入し、クエリで集計結果を得るようにしてからは 1時間程度で同等の解析処理を行うことができています。

Redshiftへのログ投入はRinを使用しています。

15分おきに最新のログが投入されるよう設定しているため、 たとえば本番反映したAPI軽量化施策の効果を十数分後には集計結果として得られるようになっています。

Rinについては以下を参照下さい。

また、以前のtech.kayacの記事でも触れていますので、そちらも合わせてご覧下さい。

おわり

次回はAngularJSを使用しているLobi Web版のSEOについて紹介します。

カヤックではログの集約・活用に興味があるエンジニアも募集しています!

主にemacsを使っている長田です。

新卒が入社して2ヶ月が経ちました。 先日社内勉強会で新卒エンジニアへ見せびらかしヒントを与える機会として 普段使っている開発環境がどんなものかをシェアする場が設けられました。

その際の資料として、主にサーバーサイドエンジニアを対象に普段使用しているエディタについて アンケートを取ったのでまとめてみました。

アンケートについて

有効回答数は36でした。

先に書いたようにサーバーサイドエンジニアを対象に実施しましたが、 厳密に制限はしていないのと、フロントエンドも兼務しているひとも混ざっていることもあり 目安として考えていただければいいでしょう。

使用者が一番多いのはVim

エディタシェアは以下のとおりでした。

share_graph.png

エディタ使用者数
Vim14
Emacs8
Atom5
SublimeText4
Neovim2
Vsual Studio Code1
Xcode1
サクラエディタ1

各エディタについて、「そのエディタを使っている理由」を紹介していきましょう。

Vim

サーバー上でも使える、という意見が目立ちました。

terminalで使える、サーバに大体入ってる

ターミナルから使えるから

また、Vim以外のエディタをメインに使っているひとでもサーバー上での作業のために 必要最低限の使い方は抑えているようです。

サーバでemacsは使えないので、vi(vim)は.vimrc空でもで最低限の操作ができるようにしています

Emacs

Vimに馴染めなかった、という意見が複数ありました。

Vim が合わなかったから。Shell と同じキーバインドなのが使いやすい

vimも触ったけど結局emacsに戻ってきてそれからemacs

MacがEmacsキーバインドをサポートしていることも理由のひとつのようです。

拡張しやすい・keybind覚えるとMacの操作全般が速くなる

あとlisp好きの人も。

elisp 友達探しています

Atom

新しもの好きのひとが使っている印象。

新しい物をとりあえず使ってみてそのまま定着してる

流行りだしたときに試しに使ってみて、そのまま。

Atomを使ってはいるものの、キーバインドはVimという人もいるようです。

ファイルを同時にいくつか開いておきたいことが多々あるのでなんとなくvim->sublime->atomとなった。キーバインドはvim。

SublimeText

プラグイン管理の仕組みがあるのがいいとのこと。

プラグイン管理が楽だから

4票入っているにもかかわらず、理由を書いていたのはひとりだけでした。 なにかひとには言えない理由があるんでしょうか・・・。

今回のアンケートは主にサーバーサイドエンジニア向けでしたが、 SublimeTextはJSerがよく使っているとの情報もありました。

Neovim

Vimのいけてないところをいろいろ改善したエディタのようです。

市民、闇の力を使うのは義務です。

ちょっと何を言っているのかわからない。

Visual Studio Code, Xcode, サクラエディタ

1票ずつなのでまとめて紹介。

かっちょいい(VSCode)

openFrameworksを使った開発がメインのため(Xcode)

前職での名残り。ショートカットキーが1タッチで可能。編集も簡単(サクラエディタ)

はじめに使ったエディタに体が慣れている?

エディタによらず、同系統エディタを使い続けるパターンが多いようです。 使い慣れている道具を使うのが一番ですからね。

最初に教わったものをそのまま使っています。

入社直後に先輩に勧められてそのまま使い続けている。

20年前からEmacs系(最初はMule)

長年の付き合い

おわり

と、いうわけでカヤック(主に)サーバーエンジニアのエディタ事情でした。 最後にアンケートの自由記述欄に書かれていたものを紹介しておきましょう。

VimやEmEditorやAtomもすばらしいエディタだとおもいます。慣れの問題なのでエディタで戦争してるヒマがあったらなじみのエディタでコード書いたらいいとおもう(ただし、より生産性を高めるために乗り換えるのは意味があるのでやったほうがいいですね)。戦争せずに世界平和

平和が一番。

ちなみにぼくはカスタマイズをspacemacsにまるなげしてEmacsをVimキーバインドで使ってます:)

カヤックではエディタにこだわりがあるエンジニアも募集しています!

Lobiチームの吉村です。

今回はチャットサービスの品質を高める上で重要になってくる「Push通知」について、Lobiのアプローチのひとつである「Gunfish」を紹介します。 Push通知はユーザが「自分に返信が来た」「運営からお知らせが来た」などの情報をリアルタイムに知ることができる機能で、チャットをメインコンテンツとして展開しているLobiにおいて非常に重要な要素となっています。 Gunfishは「Push通知を漏れなくすべてのユーザへ届けたい」という想いを込めて開発したアプリケーションです。

LobiのPush通知と今までの実装

Lobiのアプリでは、ユーザに気づいて欲しいイベントが発生したとき、ユーザにPush通知が届きます。例えば、

  • 自分のコメントにレスがついたとき
  • 自分のコメントに「ぐー(※1)」をされたとき
  • ユーザが所属するグループ内で「シャウト(※2)」がなされたとき
  • 運営からお知らせが届いたとき

などがあります。

スマートフォンアプリのPush通知を届けるために、多くの場合APNs(※3)(iOS)やGCM(※4)(Android)などのサービスが利用されます。 LobiでもiOS端末のPush通知にはAPNsを利用しており、iOS端末に発行されたデバイストークン(※5)とPush通知の内容となるペイロード(※6)をAPNsへPostします。 本記事ではこのリクエストをAPNsリクエストと呼称します。

Providerサーバ

Lobiでは、APNsとの通信を行うための仲介サーバ(Provider)を置いて、Push通知機能を提供しています。 今までのLobiでは、Providerサーバの実装にはPerlの「AnyEvent::APNS」モジュールを使用していました。AnyEvent::APNSはAPNsのAPIをラップしてくれており、Providerサーバを比較的簡単に実装できます。

LobiのAPIサーバはPreforkモデルで実装されており、

  • APNsとのTCP接続のプロセスごとの永続化
  • IOを非同期化するAnyEventとの同居

等の難しさから、APIサーバと切り離したPush通知専用のProviderサーバを置いています。

トークンのスクリーニング

APNsでは1つのTCPセッションで複数のリクエストを送信することが出来ます。 この中に不正なトークンが含まれていた場合エラーがあったことを示すレスポンスを返しますが、レスポンスを受け取るまでに行われたリクエストも巻き込まれて失敗してしまいます。

push_error.png

したがって、失敗するとわかっているデバイストークンは速やかに送信対象から除外する必要があります(LobiではデバイストークンはDBで管理しているため、DBのレコードを削除します)。

また、送信に失敗したPush通知については再送処理を行います。 再送処理についての詳細は今回は割愛します。

しかしながら、今までのLobiの実装では全てのエラーを検知することができず、不正なトークンをスクリーニングしきれていませんでした。

※1: コメントに「ぐー」というリアクションができる機能
※2: 投稿するコメントをグループ全体にPush通知できる機能
※3: Apple Push Notification Serviceの略称で、iOS端末にPush Notifcationを届けるためのAPIを提供してくれるサービス
※4: Google Cloud Messagingの略称で、Android端末にPush Notificationを届けるためのサービス
※5: アプリ単位で各iOS端末に対して一意となるトークン
※6: メタ情報やユーザに表示するメッセージ

新しいProviderサーバ「Gunfish」

2015/8/26にAppleのWWDCの発表で、APNsのAPIが新しくなり、

  1. エラーレスポンスがより詳細に
  2. HTTP/2のプロトコルのサポート

などの変更がおこなわれました。

これを機にかねてよりの懸案事項であったPush通知の送信漏れを改善するため、新しいProviderサーバ開発の機運が高まりました。 Goのバージョン1.6でHTTP/2のパッケージがデフォルトパッケージになることもあり、実装言語はGoになりました。

概要

Gunfishの設計思想は、「漏れなくPush通知をユーザエンドに届けること」となります。 基本的にレガシーなAPNsを用いたときの実装と考慮すべきことは同じで、

  • エラーが発生したときにデバイストークンを削除できること
  • 送信失敗したPush通知は再送処理をすること

となります。

以下はLobiにおけるGunfishを用いたPush通知機能の概要図です。

gunfish_overview.png

Push通知を伴うイベントがAP1サーバに送られたとき、AP1サーバからGunfishにデバイストークンとペイロードの組の配列がPOSTされます。 Gunfishはそのリクエストを使ってAPNsにPOSTします。 Push通知に失敗した場合のエラー処理もGunfishで行います。 この時エラーの種類がデバイストークンの不正であった場合は、APサーバのいずれか(図ではAP2サーバ)にそのトークンをDBから削除するようリクエストを送ります。 通信エラーだった場合は失敗したPush通知の再送を行います。

Gunfishの内部では、

  1. APサーバからデバイストークンとペイロードが組となるデータ配列を受け付けるためのqueue(POST受付queue)
  2. APNsへ送信予定のPush通知内容を受け付けるqueue(worker受付queue)
  3. workerからsenderへAPNsリクエストを受け渡すqueue(sender受付queue)
  4. APNsからのレスポンスを受け付けるqueue(レスポンスqueue)
  5. 再送のためのqueue(再送queue)
  6. errorハンドリング用のqueue(コマンドqueue)

が用意されており、これらのqueueを取り扱うための複数のworkerが非同期で動作しています。 workerは以下の種類があります。

  1. provider
  2. supervisor
  3. worker
  4. sender
  5. resend worker
  6. command worker (error hook用)

provider

providerはTCPポートをListenして、HTTPで会話するサーバを起動します。 providerが提供するAPIは、Push通知を受け付けるPOSTのエンドポイントとGunfishの内部状態を確認するためのstatsのエンドポイントがあります。

provider.png

supervisor

supervisorは、providerが起動するときに1つだけ立ち上げます。 providerから受け取ったPush通知内容をworker受付queueに詰め込みます。

supervisor.png

supervisorは複数のworkerを所有しており、Gunfishが終了あるいは再起動されるときに、所有するworkerの処理が全て完了するまで待機する役割を担っています。

workerとsender

まず、workerがworker受付queueからAPNsリクエストを取り出し、sender受付queueに送ります。 senderはworker1つに付き複数立ち上げることができ、実際にAPNsにリクエストを送信する部分を受け持っています。

sender受付queueからAPNsリクエストを受け取ったsenderは、HTTP/2コネクションを用いてAPNsにPush通知を届け、そのレスポンスを受け取ります。 このコネクションはworkerがそれぞれ1つずつ持っているもので、senderは送信時にそれを利用する仕組みとなっています。

senderはAPNsからのレスポンスを受け取った後、そのレスポンスをレスポンスqueueに詰めていきます。 workerはレスポンスqueueを見てエラーハンドリングをします。

worker_sender.png

resend worker

何かしらの通信エラーが発生して送信に失敗した場合、失敗したAPNsリクエストは再送queueに詰め込まれます。 resend workerは、一定周期で再送queueから一定数のAPNsリクエストをworker受付queueに詰め直します。

resend_worker.png

command worker

前述の通り、トークン不正によるエラーを受け取った際にはスクリーニング処理を行う必要がありますが、その処理はアプリケーション毎に異なります。 そのためsenderがスクリーニングを必要とするエラーを受け取ると、そのレスポンスは一旦コマンドqueueに詰め込まれます。 command workerはコマンドqueueからレスポンスを取り出して、外部コマンドをhookします。 Lobiでは、トークンをDBから削除する処理をhookに設定しています。

command_worker.png

外部コマンドではなく、Goでエラーハンドラーの実装・組み込みを行うことも可能です。

Gunfishのチューニング

開発中は次の観点でベンチを走らせつつ、Gunfishの状態を確認しました。

  1. 送信失敗数
  2. CPUの使用率
  3. メモリ使用状況

ベンチ用のluaスクリプトをwrkコマンドから実行し、送信失敗数などを計測しました(wrkで回すluaスクリプト)。 このスクリプトはAPサーバからGunfishへのPOSTを行うもので、1回のリクエストに付き200個のAPNsリクエストを送信します。 また、Gunfishの内部APIによるstats取得も行いました。

$ wrk2 -t2 -c20 -d10 -s bench/scripts/err_and_success.lua -L -R25 http://localhost:38103
Running 10s test @ http://localhost:38103
  2 threads and 20 connections

  ...

  242 requests in 10.00s, 31.43KB read
Requests/sec:     24.19
Transfer/sec:      3.14KB

上記はAPサーバからGunfishへPOSTする様子です。 今回、最も注目する箇所はリクエスト数で、242のPOSTリクエストを送信しており、全て捌けていることがわかります。 また、Gunfishのstatsの状態は以下となります。

{
  "pid": 6020,
  "debug_port": 20166,
  "uptime": 46,
  "start_at": 1464691415,
  "su_at": 0,
  "period": 1,
  "retry_after": 10,
  "workers": 8,
  "senders": 400,
  "queue_size": 0,
  "retry_queue_size": 0,
  "workers_queue_size": 0,
  "cmdq_queue_size": 0,
  "retry_count": 0,
  "req_count": 242,
  "sent_count": 47432,
  "err_count": 968
}

このとき送信されるAPNsリクエストの総数は 242 * 200 = 48400 となります。 実際にAPNsへ送信できた数は、 sent_count + err_count = 47432 + 968 = 48400 となり、漏れなく送信できていることがわかります。

CPUはベンチを回す際に、topなどで監視して、全てのコアの使用率が100%に達するような異常な状態にならないかをチェックしました。

またベンチ実行前後でメモリの使用状況を内部のstatsと外部(topコマンド)の両方から観測し、メモリリーク等が起きていないことを確認しました。

ベンチに用いるAPNsサーバは自前のMockを用意しました。 APNsのMockはh2oを用いて実装しました(Mockのソース)

これらを考慮しつつ、Gunfishのチューニングを行います。 以下に設定の1例を示します。

[provider]
port = 8203
worker_num = 8
queue_size = 2000
max_request_size = 1000
max_connections = 2000

[apns]
skip_insecure = true
key_file = "/path/to/server.key"
cert_file = "/path/to/server.crt"
sender_num = 50
request_per_sec = 5000
error_hook = "echo -e 'Hello Gunfish at error hook!'"

Gunfish内部では request_per_sec に指定されたリクエストを捌ききれるよう、内部の各種queueサイズを自動で調整します。 サービスが利用するAPNsリクエストの流量に応じて設定すると良いでしょう。 さらにこのqueueサイズに応じた数のworkerを用意する必要があるため、合わせて sender_numworker_num を調整してください。

Gunfishリリース時の話

レガシーなProviderサーバからGunfishへの切替えに際してまず、複数台が稼働しているAPサーバの1台について実施し、実際の流量で検証を行いました。 このとき以下のこちらのissueにも取り上げられているメモリリークの問題が発見されたため、定期的にGunfishを再起動させることでこれを回避していた時期がありました。 現在はメモリリークの問題は修正されており、その他動作にも問題が見られなかったため、全てのAPサーバーでGunfishが稼働しています。

以下はメモリリークの解消前後のメモリ使用量の遷移になります。

gunfish-1.6-memory.png

既存のPush Providerサーバとの違い

Goで実装された既存のProviderサーバではMercariさんのGaurunがあります。 Gaurunとの違いは、生成するHTTP/2コネクション数をconfigファイルから設定できることです。 流量が多い場合だと、1つのHTTP/2コネクションでは捌ききれない場合があります。 また、1コネクションにおける多重度にも限界があり、多重送信しすぎるとエラーが発生します。 APNsのドキュメントでも、パフォーマンスを考慮するのであれば複数のHTTP/2コネクションを使うことが推奨されているようです(Best Practices for Managing Connections)。

Gunfishの0.1.0(2016/05/31時点の最新版)ではHTTP/2のAPNsしか対応していません。 対してGaurunはGCMにも対応しているため、iOS・Androidの両OSに対応させることが出来ます。 今後GunfishもGCMに対応する予定です。

おまけ

Yokohama.(pm|go) #14で発表させていただきました。その時の資料はこちらになります。

現在、GunfishはGithubにて公開中です。

次回

今回はLobiのiOSのPush通知を送信するために開発されたGunfishについて紹介しました。 次回は、「ログ集約」について書こうと思います。

LobiではGoを書きたいエンジニアも募集しています!