RSS

FluentdとNorikraを使ったLINE BusinessConnectエラー検知&通知の仕組み

by Yoichiro on 2014.8.6


LINE技術戦略室のYoichiroです。今回は、徐々に数が増えてきたLINE BusinessConnectのエラー検知とその通知の仕組みについて紹介してみたいと思います。

LINE BusinessConnectって何ですか?

まず「LINE BusinessConnectの技術話」をご覧ください。

「メッセージが届かない」原因は?

LINE BusinessConnectは、今年の2月26日に行った「LINE Showcase 2014 Feb.」イベントで発表されました。既に半年近く経っていますが、いくつかの事例も登場していますので、LINEをお使いの方々に「企業サービスの新しい使い方」を体験していただくことができつつあるのかな、と嬉しく思っています。単なるメッセージングサービスの域を超えて、僕らも「え、そんな使い方がっ!?」と思う機会も多いです。今後もLINE BusinessConnectの事例を楽しみにしていて欲しいと思っています。

さて、LINE BusinessConnectの大きな特徴は、「LINE株式会社だけで開発が完結しない」ということです。LINE BusinessConnectにおけるLINE Platformの役割は「土管」です。その土管から流れてくるLINEユーザからのメッセージを処理するのは、LINE BusinessConnectを使って具体的なサービスを提供する各企業のサーバになります。ユーザが投稿したメッセージやスタンプなどは、文字通りLINE Platformを「右から左に」受け流され、対象の企業のサーバに届けられます。そして、メッセージの内容やスタンプの種類などが解析され、それに応じた返信がその企業のサーバから送られます。

LINE BusinessConnectに対応するための第一歩は、LINE Platformに登録を行い、LINE Platformから企業のサーバに情報を流すための技術的な設定を行うことです。つまり、LINE Platformに企業のサーバのEndpoint URLを登録します。その後、LINE PLatformから各種メッセージや友だち追加されたことなどの通知が送られてくるわけです。順調にいけば、登録したEndpoint URLに対してLINE Platformから接続が行われ、JSON文字列があっさりと流れてきます。

・・・順調にいけば、の話です。

しかし、いつも順調に事が進むとは限りません。正しく設定を施したつもりでも、うまく動かないといった経験は誰しもお持ちのことかと思います。LINE BusinessConnectの場合、「LINE Platformから来るはずのものが来ない」という現象として問題が表面化します。ちゃんとEndpoint URLも設定した、リクエストを受け取るサーバプログラムも起動している、ファイアーウォールも穴を開けた、なのにメッセージが来ない!おかしい!何故?という状況が発生するわけです。

「最初のリクエストを受け取る」という疎通確認がLINE BusinessConnectの第一歩になるわけですが、メッセージが来ないという状況になった場合、企業側の開発担当者が「何が起きているのかわからない」と困ってしまうことがほとんどでしょう。それは一体、何故でしょうか?

LINE Platform側の「見える化」

ユーザがメッセージなどの投稿を行った後、LINE Platformは受け取ったメッセージを対象のEndpoint URLに送信します。つまり、LINE Platformと企業のサーバとの接続を行うのは、LINE側からになります。

「最初のメッセージが受け取れない」状況になってしまう原因は、例えば以下が考えられます。

  • 登録されたEndpoint URLが間違っている。
  • HTTPSでの通信のために必要になるSSL証明書がオレオレ証明書だった。
  • 企業側のファイアーウォールに穴が開いていなかった。
  • 企業側のプログラムに不具合があった。
  • Endpoint URLを変更したが、LINE Platform側で反映されていない。
  • 登録されたEndpoint URLで書かれたドメインがDNS登録されていない。
  • テスト用と本番用のアカウントを間違えていた。

これらの原因のうち、実際に起きているのはどの原因だったのか、これをLINE BusinessConnectを採用した企業側で調査を行うことには限界があります。そもそもLINE Platformから企業のサーバへの接続に失敗してしまった場合は、企業のサーバ側には何の形跡も残らないでしょう。その場合は、LINE Platform側で調査を行う必要があります。もちろんそれは、LINE社員しかできないことです。コミュニケーションに時間がかかり、問題解決が迅速に行えないことは、火を見るよりも明らかです。

メッセージが正しく配送されなかったケースだけではなく、例えば、

  • 企業のサーバ側で予期せぬエラーが発生し、LINE Platformに200以外のResponseが返却された。
  • 企業のサーバ側の負荷が増大し、LINE PlatformへResponseを返すのに10秒以上かかってしまった。

といった状況もあり得ます。これは企業のサーバ側でログを注意深く調査すれば状況を把握することは十分可能だと考えられます。ただし、LINE Platform側においても、上記の状況は監視という観点においてリアルタイムで検知しています。

つまり、LINE Platform側で検知されたエラー状況について、企業側の開発担当者に「見える化」することで、問題解決を迅速にし、そしてLINE BusinessConnectを使った事例のサービスインをより確実にできるはずです。

集計サーバをどう構築する?

LINE Platformにおいて、GameやFamilyアプリといったLINEと連携する様々なアプリケーションや、LINE BusinessConnectでの企業側のサーバとの通信を担当する部分は、Channel Gatewayと呼ばれています。LINE BusinessConnectでのLINE側から企業側へのメッセージ送信についても、もちろんChannel Gatewayがその処理を担当しています。

つまり、上述のエラー状況を検知するには、LINEからの出口であるChannel Gatewayの対象処理部分に検知ロジックを仕掛ければ良いということになります。具体的には、Channel Gatewayが登録されたEndpoint URLに対して接続を確立し、情報を送信し、そして相手からの結果を得る、という流れになります。この一連の処理について、通信例外や相手から返送されたHTTPステータスコード、そして一連の処理が終わるまでの時間を計測し、10秒以上かかったかどうかを判断します。

さて、Channel Gatewayにて検出されたエラー情報は、何らかの単位で集計を行った方が良いと考えられます。多くの場合において、エラーはその原因が取り除かれるまで連続して発生します。最終的に企業側に発生したエラー情報を報告する際には、発生した事象全てではなく、例えば「1分あたりの発生回数」といった粒度にまとめることが好ましいでしょう。Channel Gatewayは複数台が同時に稼働していますので、そういった集計処理は、各Channel Gatewayの責務とするのではなく、別途集計サーバの責務としたいところです。

集計サーバとして、今回のケースでは「ある程度のリアルタイムな集計処理」が求められます。単位時間ごとに次々と結果を出していく、そんなイメージですね。これを満たすためのアーキテクチャとしては、以下が考えられます。

  • エラーの情報をファイルに書き出していって、単位時間ごとにその内容を解析し集計する。
  • 一時的にmemcachedなどにエラー情報を記録していき、単位時間ごとにmemcachedからかき集めて集計する。
  • Apache Stormといったフレームワークを利用して集計処理を記述し運用する。
  • リアルタイム集計をやってくれるプロダクトを探してきて、それに集計処理を任せる。

アクセス量の多いサーバ群に対して、全てのリクエストの回数の算出やリアルタイム分析をしていくのであれば、Apache Stormの適用が適しているかも知れません。しかし、今回の場合は「エラーが検出された場合にのみ集計対象となる」という点で、集計対象データの発生頻度はそう高くありません。

そこで今回は、「リアルタイム集計をやってくれるプロダクトを探してきて、それに集計処理を任せる」という選択肢を取ることにしました。つまり、大規模にスケール可能な仕組みを自分の手でコーディングしていくのではなく、少ない工数で集計処理を実現可能、つまり「準備から稼働開始までの時間短縮」を優先することにしました。また、自分でコーディングする量が少なければ少ないほど、もちろん品質も向上します。その分、採用するプロダクトの実績が重要になってきます。

FluentdとNorikraを使ったエラー状況の集計

最終的に採用を決定したプロダクトは、以下の2つです。

  • Fluentd – An open source data collector to unify log management.
  • Norikra – An open source server software provides “Stream Processing” with SQL, written in JRuby, runs on JVM.

Fluentdは「ログある場所にFluentdあり」と言っても決して過言ではない、ログ管理のためのプロダクトですね。様々なIN/OUTプラグインを組み合わせることで、膨大なログデータから価値のある情報を抽出して生み出していくことができます。Channel Gatewayで検知されたエラー情報は、まずFluentdに投げられます。

そして、実際の集計処理を行っているのが、Norikraです。FAQsによると、読み方は”No-rick-la”だそうです(個人的には「のりかさん」と呼ぶこともあります)。NorikraはFluentd向けのIN/OUTプラグインも提供されていて、Fluentdに次々と入ってくるデータをNorikraに流し込み、予め登録された「SQLライクな集計のための定義」に従って単位時間ごとに集計を行い、その結果をFluentdに戻してくれる、ということが手軽に実現可能です。Norikraは内部でEsperが使われています。そして、その作者はLINE社内にいます。LINE社内では既に様々な箇所で利用されていて十分な実績がありますので、採用しました。

現在稼働しているLINE BusnessConnectのエラー検知に関するシステム構成は、以下の図のようになっています。

fluentd_norikra_1

前述したとおり、集計対象はそれほど高い頻度で発生するわけではないので、FluentdとNorikraのセットを2つ作り、それぞれ「アクティブサーバ」と「スタンバイサーバ」として構築しました。本稼働サーバは定期的に生きているか監視されていて、応答がなくなった時点でスタンバイサーバに切り替わるようになっています。

Norikraが行っている集計処理

今回集計対象としたいエラー情報は、以下の組み合わせから構成されます。

  • Channel ID: Channel Gatewayが扱うクライアントに付与されるID。
  • Reason: エラーの原因(接続できなかった、エラーステータスコードが返された、など)。
  • Detail: エラーの詳細情報(接続できなかった原因、返されたエラーステータスコードの具体的な値、など)。
  • Timestamp: エラーが検出された日時。

これらの情報がChannel GatewayからFluentdに流れてきます。そして、そのままNorikraに流されます。そして、Norikraは予め登録された集計定義に従って、集計処理を行います。LINE BusinessConnect向けに、今回は2つの集計定義を登録しました。

  • エラー発生状況を1分ごとに集計 – 開発者向けサイト(LINE Developers)にて掲載。
  • エラー発生状況を5分ごとに集計 – 5分間以内に1回でもエラーが検出された際に、メールにて開発担当者に通知。

Norikraでは、SQLに似た文法を持つ「EPL(Esper Processing Language)」を使って、集計処理を定義します。これは、Norikraに入力される情報を「2次元の表」と見立て、SQLにあるような集計関数を使って集計処理を定義します。そして特徴的なのが、集計対象の母集団を決定するための条件として「時間」の概念が導入されています。これは「ウィンドウ」と呼ばれるのですが、情報の流れをストリームと呼ぶならば、ストリームを「60分ごとに区切る」というように指定することで集計単位を決定することが可能です。

実際に使用しているEPLは、以下になります。

SELECT
  current_timestamp() AS collected_timestamp, // 集計日時
  channelId AS channel_id,
  reason,
  detail,
  count(*) AS error_count, // エラー発生件数
  min(timestamp) AS first_timestamp, // 単位時間内で検出された最初のエラー発生日時
  max(timestamp) AS last_timestamp // 単位時間内で検出された最後のエラー発生日時
FROM
  event_endpoint_error_log.win:time_batch(60 sec) // ウィンドウを1分ごとに定義
GROUP BY
  channelId, reason, detail
HAVING
  count(*) > 0 // エラー件数が1件以上あった場合に限定

すごく見慣れたSQL文だと思います。SQLと違う箇所は、FROM句の部分ですね。テーブル名っぽい記述の後に、”.win:time_batch(60 sec)”と書かれています。これがウィンドウの定義です。time_batch以外にも、指定されたサイズをウィンドウ定義に使うlength_batchなどもあります。

上記は1分ごとの集計なので、LINE Developersに掲載するための集計を行う定義です。これとは別に、内容は全く同じですが、ウィンドウの定義が”.win:time_batch(300 sec)”という定義も登録しています。こちらは、メール通知用に5分間隔で集計を行っています。

集計結果の転送と利用

集計結果は、内部的なAPIをHTTP経由で呼び出して転送しています。そのAPIのEndpointは、集計結果をどう使うかによって異なるEndpointを指定しています。具体的には、以下のようにfluent.confを記載しています。

<!-- LINE Developers掲載用 -->
<match norikra.query.error_info>
  type http_buffered
  flush_interval 2s
  endpoint_url http://../api/bcErrorLog/store
  http_read_timeout 10
  http_open_timeout 3
</match>

<!-- メール通知用 -->
<match norikra.query.notify_info>
  type http_buffered
  flush_interval 2s
  endpoint_url http://../api/bcErrorLog/notify
  http_read_timeout 10
  http_open_timeout 3
</match>

集計結果は1分ごと、5分ごと、となるので、上記のAPIの呼び出し頻度は「同時にエラーが発生したLINE BusinessConnectアカウント数」になります。つまり、それほど多くありません。それぞれ、MySQLに格納、LINE Developersに登録された開発担当者のメールアドレス宛にエラー内容をメール送信、という処理が行われます。具体的には、以下のようなメールが送信されます。

fluentd_norikra_2

また、LINE Developersサイト上では、以下のように表示されます。

fluentd_norikra_3

これらの処理は単純なコーディングで実現可能なので、今回のシステム全体で書いたコードの量は、本当に少ないものとなっています。

Norikraの動作確認

NorikraはJRuby環境で動作します。つまり、JavaVM上で動作するため、GCの挙動が気になります。今回の利用ケースにおいては、正常時は集計対象の量は非常に少ない(もちろん企業側のサーバがちゃんと動作していれば、です)はずです。しかし、ネットワークの途中の経路で何らかの障害が発生した場合などは、全ての通信に失敗し続ける状況も考えられます。その場合においても、この集計サーバは動き続けて欲しいわけです。そのためには、どこまで大丈夫なのか、ある程度知っておく必要がありますし、特にその場合のGCの挙動は見ておく必要があるでしょう。

まずは、Norikraに何もオプションを与えず、初期設定状態で起動させて、ストレスをかけてみます。GCの挙動を見るためにJavaVM向けのオプションを指定してNorikraを起動しておきます(本当は”–gc-log”オプションで簡単に指定可能なのですが、下記を実施時にはそれを知りませんでした)。その後、約3,000/secのリクエスト(上記の1分ごとの集計定義が登録された状態で実施)をかけ続けてみます。

norikra start ... -Xloggc:norikra_gc.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails

結果は・・・2分と持たずFull GCかかりまくり状態に陥りました。全然ダメです。以下はその時のログです。日時の出力など一部削っています。

...
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.336/0.336 secs] [Times: user=1.69 sys=0.00, real=0.34 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.690/0.690 secs] [Times: user=1.38 sys=0.01, real=0.69 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC[YG occupancy: 185057 K (192000 K)]257.267: [Rescan (parallel) , 0.2725640 secs]257.539: [weak refs processing, 0.0000130 secs] [1 CMS-remark: 255999K(256000K)] 441057K(448000K), 0.2726680 secs] [Times: user=2.97 sys=0.01, real=0.27 secs]
[CMS-concurrent-sweep-start]
[Full GC 257.653: [CMS...: 257.937: [CMS-concurrent-sweep: 0.397/0.398 secs] [Times: user=0.51 sys=0.00, real=0.40 secs]
 (concurrent mode failure): 255999K->255999K(256000K), 2.5638670 secs] 447999K->367189K(448000K), [CMS Perm : 55094K->55094K(83968K)], 2.5639810 secs] [Times: user=2.55 sys=0.02, real=2.57 secs]
[GC [1 CMS-initial-mark: 255999K(256000K)] 438249K(448000K), 0.5103370 secs] [Times: user=0.51 sys=0.00, real=0.51 secs]
[CMS-concurrent-mark-start]
[Full GC 261.884: [CMS...: 262.145: [CMS-concurrent-mark: 0.416/0.417 secs] [Times: user=1.81 sys=0.01, real=0.42 secs]
 (concurrent mode failure): 255999K->255999K(256000K), 2.6813440 secs] 447999K->381849K(448000K), [CMS Perm : 55094K->55094K(83968K)], 2.6814830 secs] [Times: user=3.46 sys=0.00, real=2.69 secs]
[Full GC 265.579: [CMS: 255999K->255999K(256000K), 2.2155670 secs] 447999K->408257K(448000K), [CMS Perm : 55094K->55094K(83968K)], 2.2157040 secs] [Times: user=2.22 sys=0.00, real=2.22 secs]
[GC [1 CMS-initial-mark: 255999K(256000K)] 408257K(448000K), 0.2598430 secs] [Times: user=0.26 sys=0.00, real=0.26 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.390/0.390 secs] [Times: user=1.94 sys=0.01, real=0.39 secs]
[CMS-concurrent-preclean-start]
[Full GC 268.730: [CMS...: 269.144: [CMS-concurrent-preclean: 0.698/0.699 secs] [Times: user=0.98 sys=0.00, real=0.69 secs]
 (concurrent mode failure): 255999K->255999K(256000K), 2.5817600 secs] 447999K->423795K(448000K), [CMS Perm : 55094K->55094K(83968K)], 2.5818850 secs] [Times: user=2.56 sys=0.02, real=2.58 secs]
...以下Full GCが続く...

Norikraの起動スクリプトには、今までNorikraが培ってきた実例に基づいて決定されたJavaVMへの各種パラメータ値が設定されています。基本的によほどのことがなければ、きっとその値を変更することはないでしょう。しかし、パラメータ値が指定がされていないものがあります。それは「ヒープサイズ」です。

実は、上記の実施は、ヒープサイズは500MBの状態で起動したものでした。そのため、GCよりもリクエストの流量が大きく、あっという間にFull GCの嵐になっていたわけです。やはり、事前に動作を確認しておくことは重要ですね。

ヒープサイズを3GBに指定(サーバの物理メモリは4GB)して、再度負荷をかけ続けてみます。

norikra start ... -Xmx3g -Xms3g -Xmn2g -Xloggc:norikra_gc.log -XX:+PrintGCDateStamps -XX:+PrintGCDetails

3,000/secのリクエスト負荷を1時間以上かけ続けてみましたが、その結果は全く問題なく、安定稼働するようになりました。

...
[GC 3860.433: [ParNew: 1533788K->377399K(1572864K), 0.2588920 secs] 1681160K->524771K(2621440K), 0.2590400 secs] [Times: user=2.61 sys=0.00, real=0.26 secs]
[GC 3877.872: [ParNew: 1425975K->524288K(1572864K), 0.2940130 secs] 1573347K->672210K(2621440K), 0.2941390 secs] [Times: user=3.17 sys=0.01, real=0.29 secs]
[GC 3894.437: [ParNew: 1572864K->380689K(1572864K), 0.1914270 secs] 1720786K->528611K(2621440K), 0.1915510 secs] [Times: user=2.07 sys=0.01, real=0.19 secs]
[GC 3914.932: [ParNew: 1429265K->395123K(1572864K), 0.2320380 secs] 1577187K->543045K(2621440K), 0.2321520 secs] [Times: user=2.45 sys=0.01, real=0.23 secs]
[GC 3935.819: [ParNew: 1443699K->480220K(1572864K), 0.2667290 secs] 1591621K->628143K(2621440K), 0.2668640 secs] [Times: user=2.88 sys=0.01, real=0.26 secs]
[GC 3950.107: [ParNew: 1528796K->349695K(1572864K), 0.1869800 secs] 1676719K->497618K(2621440K), 0.1871150 secs] [Times: user=2.00 sys=0.01, real=0.19 secs]
[GC 3970.718: [ParNew: 1398271K->370334K(1572864K), 0.2378780 secs] 1546194K->518257K(2621440K), 0.2380120 secs] [Times: user=2.48 sys=0.01, real=0.24 secs]
[GC 3992.460: [ParNew: 1418910K->524288K(1572864K), 0.2530590 secs] 1566833K->672301K(2621440K), 0.2531760 secs] [Times: user=2.79 sys=0.01, real=0.25 secs]
[GC 4004.683: [ParNew: 1572864K->362898K(1572864K), 0.1929120 secs] 1720877K->510912K(2621440K), 0.1930450 secs] [Times: user=2.10 sys=0.01, real=0.19 secs]
[GC 4026.351: [ParNew: 1411474K->371001K(1572864K), 0.2261900 secs] 1559488K->519025K(2621440K), 0.2263580 secs] [Times: user=2.33 sys=0.00, real=0.23 secs]
[GC 4046.745: [ParNew: 1419577K->473794K(1572864K), 0.2521100 secs] 1567601K->621969K(2621440K), 0.2522300 secs] [Times: user=2.63 sys=0.02, real=0.26 secs]
...

また、同時接続数の確認として5,000/sec以上の負荷を一気にかけたりしてみましたが、いとも簡単に処理をしてしまいました(ロストした集計対象はゼロ)。もっと負荷を上げて確認をしたかったところですが、「LINE BusinessConnectの利用企業数がそれほど多くない」「Channel Gatewayからの再送間隔が5秒」という条件があるので、全ての通信に失敗した場合でも現状であれば余裕を持って運用可能なことは確認できたとして、これ以上の負荷試験は実施していません。機会があれば試してみたいと思っています。

まとめ

今回のエントリでは、FluentdとNorikraを使ったLINE BusinessConnectのエラー検知&通知の仕組みを簡単に紹介してみました。とにかく「迅速に必要なものを作って運用していく」ということはとても重要です。実績のあるものを採用して最小限で最大の効果を出していく、これを今後も実践していきたいと思います。

上記の例ではエラー検知がFluentd+Norikraの手前のサーバが行っていますが、もちろん全ての事象をFluentd+Norikra側に送って、その中でエラー検知や統計情報を作っていくことは十分可能なことです。その場合のスケール方法もFluentd+Norikraのセットを如何に複数組み合わせいくか、というパズルになると思います(その規模を超えたらApache Stormの登場ですね)。リアルタイム集計を実施することが本当に手軽なところまで来ていますので、ぜひ本エントリを読んでいただいた方々もチャレンジしていただきたいと願っています。

Click here to read in English

LINE株式会社ではサーバサイドエンジニアを募集しています。私たちと一緒にプラットフォーム・グローバル展開を発展させていきたい方は是非ご応募ください。エントリーはこちら