アプリリリース時に起きた「ログの欠損」と「データの齟齬」　“復旧できない”施策もあるからこそ重要な事前確認

ゲームアプリのシステムの概要

菅澤要平氏：続いて、グリーエンターテインメント社が開発したゲームアプリのシステムの概要について話します。

（スライドを示して）記載のとおりですが、インフラは「AWS」で、メインの言語はPHP7.4、Webサーバーに「Apache」、DBサーバーはAmazonの「Aurora」、キャッシュサーバーに「ElastiCache」を使用しています。CDNには、「Akamai CDN」を使っています。なので、けっこう一般的な構成かなと思っています。

そのほか、オーケストレーションツールとして「Kubernetes」、デプロイのツールとしては「Argo CD」を使用しています。先ほどからちょくちょく名前は出ていますが、BIツールとして「Redash」、その裏側にあるデータウェアハウスとしてはAmazonの「Athena」を使用しています。

ログ周りの構成

続いて、ログ周りの構成について少し詳しく話していこうかと思います。まず、今回扱うログに関しては、大まかにPHPやApacheが出すエラーログと、KPIの分析に使用するアプリケーションログの2つを取り扱っています。

（スライドを示して）構成に関しては、図で記載するとこのようになっています。向かって左側は「EKS」で、各ノードが立ち上がっています。その各ノードにDeamonSetとして「Fluent Bit」がノードと1対1のかたちで配置しています。

PHPとApacheのログに関しては、Fluent Bitから「CloudWatch」に送信しています。

アプリケーションのログに関しては、Fluent BitからAmazonの「Kinesis Data Firehose」を経由して「S3」へ配置しています。どのようなルールでS3に配置するかに関しては、Firehoseで制御をしています。

アプリケーションログを参照する際は、Athena経由で参照するようにしています。先ほどから話しているように、分析をプランナーの人もやるところなので、エンジニア以外でもデータの参照や加工をしやすいように、RedashからAthenaを参照するようにしています。

エラーログとアプリケーションログ

続いて、今話したPHPとApacheのエラーログについてです。（スライドを示して）書いてあるとおりすごく単純で、主に、loggerを含むPHPで出力されるWarningやErrorログのことです。こちらは各Podが標準出力に出力していて、それをFluent BitでCloudWatchに送信しています。

基本的にこれらのアプリのエラーログ的なものは、エンジニアが確認できれば良く、かつ複雑な集計なども特に必要ないので、AWSの標準の機能であるCloudWatch経由で参照させるという簡単なかたちにしています。

続いてアプリケーションのログです。こちらがけっこう重要だと話しています。分析に使用するログで、アクセスのログやガチャの実行ログです。それぞれのログを組み合わせて集計して、分析に活用しています。

SQLでそれぞれログを操作できると、プランナーだけで分析が完結できるようになるので、Athena経由で参照できるようにしています。

SQLに関して、エンジニアはもちろん扱えるかなと思っているのですが、グリーエンターテインメントでは各プロダクトに少なくとも1人はSQLを扱えるプランナーの方がいるので、自由に参照できるようにして利便性を高めています。

（スライドを示して）「アプリケーションログは、実際どんなのを取っているのかな？」ということを抜粋すると、このようになっています。だいたい一般的なものかなと思いますが、アクセスログや課金のログや各種アイテムの増減ログです。あとは、それぞれイベントがあればイベントごとのログを随時取っています。

アプリケーションログをどういうふうに出力しているか

続いて、アプリケーションログについて、もう少し詳しく話そう思います。実際にアプリケーションログをどういうふうに出力しているかというところですが、JSONの形式でログ別にファイルを出力しています。出力先のディレクトリは、各ノードのストレージに出力していて、例で書いてあるとおりです。

それぞれのノードの中にPodごとのディレクトリが作られて、そこにaccessやpayなど、先ほどアプリケーションログの例を出しましたが、その種類別にログをファイルに出力しています。

そのファイルを出力した後は、Fluent BitからKinesis Firehose（Kinesis Data Firehose）を経由して、S3に配置をしています。

Athenaは、みなさん知っているかと思いますが、実際SQLを実行した時には、スキャンをしたデータ量による従量課金なので、時間でパーティションを切るような構成にしています。

（スライドを示して）こちらも例を記載してありますが、S3の配置先ですね。ログごとのディレクトリの配下にdatehourでパーティションを切って、その配下に配置をしています。YYYYMMDDHHの形式で置いています。

Athenaから検索する際は、WHERE句に「datahour =」と、時間までを入れて検索するようなかたちで入れています。

パーティションの設定をどうやっているかに関しては、AthenaでCREATE TABLEする時のオプションで設定をしています。

まず「PARTITIONED BY」で、パーティションに使うカラム名を設定しています。その下の「TBLPROPERTIES」で、「projection.enabled' = true'」と「projection.datehour」となっています。datehourがパーティションに使用するカラム名となっているのですが、それぞれで設定を記載しています。

このかたちでAthenaでテーブルを作っておくと、S3にファイルを配置した時に自動で配置したディレクトリに応じてパーティションを切ってくれます。

中間テーブルの作成

続いて、中間テーブルについても話そうと思います。分析をする際には、利便性のために、日次の積み上げデータとして中間テーブルを作っておくと分析しやすいということはよくあると思います。

（スライドを示して）例えば、上はガチャが実行されるたびに保存されるログです。「誰が何のガチャを引いたんだっけ？」みたいなログですね。これを日次で日付ごと、ガチャの種類ごとで実行回数のユーザーや消費した石の中間テーブルを作っています。

なので、中間テーブルのパーティションは、基本的にYYYYMMDDの日次の形式で保存しています。実際に分析する時は、こちらのサマライズされたテーブルを見るようにしています。

この中間テーブルの作成自体は「Lambda」から日次、AthenaでINSERT-SELECT文を実行して、作成しています。中間テーブルを作成することでSQLが簡素になって分析しやすく、スキャンするデータ量も減らせるので、Athena自体の費用の削減にもつながります。

アプリリリースで起きた事象　アプリケーションログの欠損

基本的なログの出力から保存までを説明したので、次に、実際にアプリのリリースをした時に発生した事象の紹介をしようと思います。

1つ目の事象です。先ほどaccessやpayのログについて話したのですが、こちらが欠損する事象がありました。

実際に発生したことは、「アプリをリリースした」となって（その時の）アプリケーションのログを見ていたのですが、明らかに「格納されているべきログが、Athenaから検索してもぜんぜんSELECTされないよね」ということがあって、「あれ？」ってなっていました。

（スライドを示して）原因が書いてあります。先ほどFluent Bitを使っていると話しましたが、それぞれ2つエラーが出ていました。2つが発生したタイミングは実際は違うのですが、両方Fluent Bit系のエラーで、リリース後に出ていたので記載しています。

1つ目が「Thoughput limits may have been exceeded.」、2つ目が「xxx have long lines. Skipping long lines.」です。

どうでもいいことではあるんですが、「Throughput」のスペルが間違っているなと、たぶん気づく人は気づくのですが。エラーログを見ていて、「エラーが出ているな」と思ってそれをコピーしたのですが、それでも「Throughput」のスペルが間違っています。Fluent Bitの「GitHub」を見たら3ヶ月前ぐらいにtypoが修正されていて、「あっ、そういうことか」という感じですね。

1つ目のエラーに関しては、Fluent BitからのKinesis Firehoseへログを送っている時に、Kinesis Firehose側の受信時のスループットの上限に引っかかっているために出ているログでした。

2つ目のエラーに関しては、先ほどの「access.json」のログがあるのですが、1行のサイズが、Fluent Bitの読み込みのバッファサイズの上限を超えていたためにスキップされています。

（スライドを示して）原因でいうとこういうことです。1つ目がFluent Bitが取り込むところのエラーで、1と2が逆なんですけど、発生場所はこんな感じです。

（スライドを示して）これらが発生した時、暫定対応として、それぞれこのような対応を実施しました。

上限を超えているので、出力するログを課金などの重要なもののみにして、いったんそのほかのログを止めて、ログの量を減らしました。

WAF（Web Application Firewall）も使っていて、WAFのログは欠損していませんでした。WAFのログを見ればある程度どのユーザーがどのAPIを実行したかはわかるので、そちらでなにかあった時の調査はカバーしました。

最後に、課金周りのことで、やはりプロダクトの初速や売上を見るのはとても大事なので、ここがずれるとけっこう痛いなというところです。課金周りのログに関しては、課金基盤のチームがあるので、そちらが別途取得しているログやクライアントのアプリに「Adjust」を入れていたので、そちらの課金のログで対応をしました。

それぞれの根本対応です。1つ目の上限に関しては、Kinesis Firehoseの「Delivery Stream Throughput」という値があるのですが、そちらの値についてAWSに上限の緩和申請を出して、上限の引き上げを行って対応しました。

2つ目の「xxx have long lines. Skipping long lines.」に関しては、Fluent Bit側の設定で読み込みのバッファサイズの上限値があるので、そこを引き上げることで対応しています。

アプリリリースで起きた事象　サポートツールのデータと集計データの齟齬

2つ目は若干凡ミスなのですが、ログインユーザーの現在のレベルがわからないというものがありました。

具体的には、ほかのアプリとの連動施策でアプリをプレイしようというものがあって、別のアプリをプレイしているユーザーがグリーエンターテインメントで開発したアプリをプレイした時に、グリーエンターテインメント側のアプリのキャラクターのレベルに応じて、別のアプリでアイテムがもらえる施策をやっていました。

施策が終了した時に、ログイン時に記録される「user_data」というログが今回のアプリにはあって、そこにレベルが保存されているので、そちらを参考に集計をしました。

集計をした後に、確認のために何件かピックアップして、実際にゲームのサポートツールで出てくるレベルと集計したレベルが合っているかを比較したのですが、ちょっとずれているユーザーがいました。

原因は、施策をした時に、施策のためにその日だけインストールしてプレイしたユーザーの方がいて、その場合に最終的なレベルがuser_dataテーブルに保存されていなかったからでした。

（スライドを示して）もうちょっとわかりやすく書くと、これはゲームをチュートリアルから始めた時ですが、ゲームを開始して、チュートリアルが完了しました。ログインボーナスが動きます。その際に今回のアプリは、これをログインと判定して、その時のレベルを保存しています。その後プレイしてレベルアップして、「よしよし、達成したぞ」みたいな。

もうそれ以降プレイしないとなった時にどうなるかというと、レベル1の時のデータしかないので、レベル1として集計されてしまうということが起きていました。

ここはもう、正直過ぎてしまったことで復旧などできなかったので諦めて、データベースがシャーディングされていて、数は多いのですが、そこから直接SELECTしてがんばって集計しました。

根本対応は未実施ですが、一番簡単なところでいうとアクセスログにレベルを追加するとか、別途レベルアップ時のログを追加するとか、いろいろ考えられるかなと思っているので、今後は対応していきたいと思っています。

教訓的なところは、ログを使用して施策を実施する際は、実施前にはきちんとユースケースを洗い出して、「そのログを利用するのが妥当なのか」という確認をしっかり行うべきだったかなと思います。

ログがちょっとおかしかった時は、分析用途であれば最悪「次回からきれいにしよう」で済むのですが、施策で使う場合はそういうわけにはいかないので、事前確認の重要性を再認識しました。

ちなみに、今回のように、ほかのシステムからIDの情報をCSVのファイルでもらって自分たちで運営しているアプリのログと突き合わせることは、まあまあよくある事象かなと思っています。

単純にそれをやるとすると、いわゆるスプレッドシートで突き合わせるのでコピペミスなどが怖いかなと思います。しかし、今回のようにAthenaとRedashを使っているような環境で、かつSQLに知見があって、またAthenaの簡単な「CREATE TABLE」の文を理解していれば、エンジニア以外のプランナーの方でも、もらったIDのリストをS3に置いて、CREATE TABLEして、Redash上でJOINして集計すると、そういうことがミスなくできます。こういう使い方もできるので、とても便利かなと思っています。

ログ取得から運用までのまとめ

最後にまとめです。最初からずっと話していることですが、必要なログについてはリリース前に定義をきちんとしておくといいと思っています。

その後も、「どういうログを取るんだっけ？　どう使うんだっけ？」みたいな話は、運用フローに組み込めるとベストかなと思っています。運用が始まってからも必要なログは変動するので、後から追加しやすい構成にしておくと良いと思っています。

当然ですが、追加をする際に、アプリそのもの、実際のゲームの内容や動作に影響を与えないように、ログの保存や集計をできるようにしておくのも重要かと思っています。

アプリケーションのログに関しては、プロダクトの方針決定に使用するものなので、Redashなどのツールを用いて、全員が手軽に参照できるようにしておくといいと思います。

また、全員が同じそういう認識を持てるよう、「アプリの状況は今どういう状況なんだっけ？」というところの関心度を上げるために、地道な共有などいろいろあると思うのですが、そういう取り組みも必要になってくると思っています。

最後に、ログについても、意図したログが保存できているのかとか、負荷が高まった時にも問題なくログが保存できているかといった観点でも、施策のリリース時に検証を行ったり、アプリそのものの負荷試験を行う時にも、実際のログの保存がきちんとされているか、「漏れていないんだっけ？」みたいなことも見ておくのがとても重要だと思っています。

発表は以上です。ご清聴ありがとうございました。