Yahoo! JAPANアプリの通知系バックエンドシステムを主に担当しているエンジニアの福盛です。
Yahoo! JAPANアプリの通知系バックエンドシステムについては、以下の記事でも紹介しています。もし興味があればこちらも参照ください。
- チームのスキル向上にもつながるシステム刷新 〜 Yahoo! JAPANアプリ「お知らせ」機能の開発事例
- Scalaで使うMessage Queue 〜 Yahoo! JAPANアプリのお知らせ送信でのApache Pulsarの活用
今回は開発とトラブルシュートの効率を大幅に向上する、アプリケーションログの埋め込みと活用方法について紹介いたします。
本記事では「JavaおよびScalaで構築され」「クラウド上で動作するバックエンドのアプリケーション」の事例を中心に説明していますが、それ以外のケースでもいくつかの要素は参考になるかと思います。
アプリケーションログの威力〜トラブルシュートのコストを1/10以下に
効果的なアプリケーションログはトラブルシュートのコストを大幅に低減してくれます。
アプリケーションログを活用することにより、従来不具合の調査に20分、場合によっては半日を要していたトラブルが、2分から5分程度で解決するようになりました。必要な運用コストは1/10以下となり、ストレスも大幅に減りました。運用で泣かないための切り札がアプリケーションログなのです。
このトラブルシュート工数削減効果を実現するには、「適切なアプリケーションログの出力」「ログ検索・解析インフラの利用」という前提を押さえておく必要があります。まずは「適切なアプリケーションログの出力」から。
適切なアプリケーションログの出力
良いアプリケーションログを実現するには、開発時からいくつかのポイントを押さえておくことが必要です。ここでは特に重要ないくつかの要素について説明します。
ログ出力用ライブラリの利用
アプリケーションログではログ出力用ライブラリを使うことが大前提です。われわれのプロジェクトではSLF4JとLogbackを採用しています。
ログ出力用ライブラリにより、「ログ時刻が自動的に記録される」「ログを出力したクラスが自動的に記録される」「例外クラスの詳細表示が自動的にサポートされる」「debug,info,warn,errorなどレベルに応じた出力の出し分けを行える」といったメリットが受けられます。
ログ出力用クラスの初期化はいちいちクラスのコンストラクタに書くと煩雑になりがちですが、JavaではLombokによる@Slf4jアノテーションを使ったり、ScalaでPlay Frameworkを使っている場合はplay.api.Loggingトレイトを活用することにより、コードはかなり簡潔になります。
// JavaでLombok+SLF4Jを使う例
import lombok.extern.slf4j.Slf4j;
...
@Slf4j
...
public class ... {// ScalaでPlay FrameworkのLoggingトレイトを使う例
import play.api.Logging
...
class ... extends Logging {ScalaでPlay Frameworkを使わない場合でも、同様の動作をするLoggingトレイトは簡単に作れるので、それを使うのも良いでしょう。
ログ出力先はファイルではなく標準出力へ
ログはファイルではなく、標準出力（stdout）、標準エラー出力（stderr）へ出すようにします。現代のクラウド環境では通常、標準出力、標準エラー出力に出されたログの内容を自動的に収集する仕組みが用意されているので、これを活用しましょう。また標準出力、標準エラー出力に出しておくと開発時にログの内容をただちに確認できるため、スムーズに作業をすすめられます。
オブジェクトの内容が確認できるようにする
アプリケーションログ出力にあたっては、関係するオブジェクトの中の値を出力して確認できるようにしておきましょう。Javaの場合であれば
- Lombokの
@ToStringアノテーションを使う - IntelliJなど、IDEのtoString自動生成機能を使う
などの手段で、オブジェクトの内容を容易に表示できます。Scalaの場合、case classのtoStringは属性値を自動的に出力してくれるのでこれを活用するのがよいでしょう。
役に立つアプリケーションログの原則
アプリケーションログを有効に使うには、開発やトラブルシュートに必要な情報がカバーされていることが大切です。ここではいくつかの原則を紹介します。
その1.正常系処理にも積極的にログ出力を埋め込む
ありがちな事例として、プログラム内で例外などの異常が発生した場合のコードにみログ出力を実装していたが、実運用に入ると原因不明のバグに悩まされた結果、調査用のログを暫定的に入れて対処、というものがあります。調査用のログ埋め込みはアプリケーションの再ビルド、再デプロイを必要とし、工数および心理的負担が非常に大きいものです。
また、一見するとエラーは発生していないように見えるが、実際には処理が進んでいないといったケースもあります。正常に動作しているかの確証を得るにもログは重要な役割を果たします。
正常系処理でもアプリケーションログを積極的に埋め込んでおきましょう。特にメソッドの開始、終了、条件分岐にかかわる部分にログ出力用のコードを埋め込んでおくと開発時、運用時のトラブルの解決に非常に役立ちます。
...
public void aMethod(String param) {
log.debug("aMethod start {}", param);
...
if (conditionA) {
log.info("returning with conditionA");
return;
}
...
log.debug("aMethod finished");
}この際、運用時に流れるログの量が過大にならないように注意しましょう。上記の例では「条件分岐にかかわるログをinfoレベルで」また「開始終了にかかわるログをdebugレベルで」出力していますが、実際の開発および運用では、パフォーマンスおよびログ分析への影響を考慮しつつ、コード内のログの出力レベルおよびシステム上のログ出力設定を継続的に調整することで、ログの流量を適切にコントロールしていきます。
以上、あらためてまとめると
- 「ログ埋め込みを積極的に」行いつつ、同時に
- 「ログ出力量を適切にコントロールする」
ことが重要となります。
その2.関係するデータ（オブジェクト）の情報を入れる
ログが出力されるようになっても、その内容が単なる固定の文字列であるならば、開発やトラブルシュートへの効果は限られてしまいます。
- 条件分岐にかかわる変数
- メソッドの入力パラメータ
- メソッドを呼び出した際の返り値
といった、関係するデータ（オブジェクト）の情報をログに入れることで、状況をより把握できるようにしましょう。
これにより、意図しない挙動が発生したときに、関係する条件分岐の周辺のログに記録されているデータ（オブジェクト）の情報を見ることで、なぜその動作が起きたのかの原因究明がすぐにできるようになります。また、外部のAPIを呼び出すような場合にも「呼び出しパラメータは正しいか」「返り値は期待したものか」を迅速に確認できます。
以下、Scalaによるアプリケーションログの記述例です。バイナリ形式で流れてきたメッセージをパース（デシリアライズ）し、後続のPush送信処理に渡すというものですが、パース（デシリアライズ）成功、失敗の各場合について、さらに、エラーではないもののシステムではサポートしていないタイプのメッセージの場合について、ログを出力するようにしています。
def processMessage(rawMessage: Message[Array[Byte]]): Unit = {
logger.debug("message processing start")
parseMessage(rawMessage) match {
case Success(parsedMessage, _) =>
logger.debug("message parsed: {}", parsedMessage)
toPushRequestMessage(parsedMessage) match {
// 本システムで送信がサポートされていないタイプのメッセージの場合はinfoレベルでログを出し、送信は行わない
case Left(noticeText) =>
logger.info(s"did not send pushRequestMessage: $noticeText, parsedMessage=$parsedMessage")
case Right(pushRequestMessage) =>
pushMessage(pushRequestMessage)
}
case Failure(errors) => logger.warn("could not parse message: {}", errors)
}
logger.debug("message processing end")
}ここまで、アプリケーションログの原則について紹介しました。このようにして入れていったアプリケーションログを有効に活用するには、この次に述べるログ検索・解析インフラが重要です。次の項ではそのような機能を提供する“Splunk”を題材に、その利用法について説明します。
アプリケーションログを活用するためのインフラ
ログをきちんと出力しても、それが容易に確認できなれければトラブルシュートは困難です。かつてログの出力先はファイル、その内容の確認はgrep,tail,lessなどのコマンドの組み合わせで行っていた時代もありましたが、仮想環境上で数十台から数百台のサーバーが稼働している世界ではもはやそのような手作業でのログの確認は現実的ではありません。
Yahoo! JAPANでは数年前から全社をあげてクラウド化にもとづくシステム刷新を行っています。アプリケーションの構築はクラウド上のPaaS（Platform as a Service）やKaaS（Kubernetes as a Service）上で行う方式に全面的に切り替わりました。結果、アプリケーションをデプロイすると同時にログ集約・検索・解析のインフラストラクチャーを無条件に使えるようになりました。ヤフーでのPaaS、KaaSへの取り組みについては以下の記事もぜひ参照ください。
現在Yahoo! JAPANでは、アプリケーションが稼働しているインスタンス（通常は数十台、場合によっては数百台）のアプリケーションログがログ検索・解析プラットフォームである“Splunk”にリアルタイムで収集されます。トラブルシュートなどの際にはSplunkのWeb画面から「実行アプリケーション名などの環境の絞り込み」「時間帯での絞り込み」「ログ内の文字列での絞り込み」による検索を実行することで、探したいログの情報を即時に引き出せます。
一例として、Scalaで使うMessage Queue 〜 Yahoo! JAPANアプリのお知らせ送信でのApache Pulsarの活用という記事で紹介した、Message Queueを使ったプログラムを以下に再掲します。ここではMesage Queueからメッセージを受け取るごとに、parseメソッドが呼ばれる仕組みになっています。
class Main(...) extends Logging {
...
// Message Queueからメッセージを受け取るごとにparseメソッドが呼ばれる
def parse(m: Message[Array[Byte]]): Try[PushRequestMessage] = {
Try {
val pushRequestMessage = PushRequest.parseFrom(m.getData).toScala
logger.info("message parsed. pushRequest={}", pushRequestMessage)
...アプリケーションログには以下のような内容が出力されます（イメージ）
time:2020-12-07T16:29:07.652+09:00 level:INFO (...) message parsed. pushRequest=PushRequestMessage(...,Some(PushAndList),Some(serviceName),Some(メッセージが届きました),Some(https://...),Some(https://...),...)Splunkでは通常のWebの検索エンジンのように、アプリケーションログを検索できます。ヤフオク!由来の通知であれば検索窓に
(source=app_out OR source=app_err) auctionと入れるだけでオークション関連のアプリケーションログが検索されます。検索の前半の(source=app_out OR source=app_err)はアプリケーションログのみの絞り込み、後半は検索したいキーワードを入れる、というかたちです。絞り込みは特定のアプリケーション名なども条件にできます。これにより迅速なログ確認が可能です。
ここまで本番環境で稼働を始めたアプリケーションを念頭に、運用コストを低減させるためのログ出力および確認方法について説明してきました。しかしアプリケーションログはリリース後だけでなく、開発時にも大いに役立ちます。次の項ではこれについてお話しします。
アプリケーションログを使って開発をスムーズに
アプリケーションログで開発をスムーズにする題材として、今回は「外部のAPIを使うクラスの開発」を取り上げます。
開発において、外部のAPIを使うクラスの動作検証は開発のなかでも難しい部分です。APIのエラーレスポンスを参照して修正する、というステップを繰り返すことでクラスを組み上げていく必要があり、外部へリクエストを発行しないと確認ができない、ということから、ユニットテストによる確認・修正も使えません。ということで途中経過をコンソールに表示して確認する、いわゆる「printfデバッグ」に頼りがちな状況となりますが、これをアプリケーションログにすること、さらに対象クラスを対話型環境で単体実行させることで、開発をスムーズに進めつつ、リリース後にもアプリケーションログを活用できる状態を実現できます。
以下Javaを使った例を示します。
まず外部のAPIを使うクラスについて、リクエストボディーとレスポンスを出力するよう、コードにログを入れておきます。
public class ApiService {
...
public ApiResponse sendRequest() {
... // requestBodyを構築
log.debug("requestBody={}", requestBody);
try {
... // API呼び出しを実行、responseを取得
log.info("web request successful response={}", response);
...
} catch (WebClientResponseException e) {
// 上位のエラーハンドラでも例外のスタックトレースはログに出力されるが、
// エラーレスポンスの内容はここで出しておく
log.error("web request error. response={}", e.getResponseBodyAsString());
throw e;
}
...次にクラスがかたちになったところで、対話型実行環境から実行、検証を行います。Javaの場合、JDK 9以降でJShellによる対話型実行環境が提供されるようになりました。これを活用すると開発中のクラスのみを対象に実行と修正を繰り返せます。
Mavenを使ったプロジェクトではjshell-maven-pluginを利用します。
# jshellを起動。関連クラスのimportも行う
...
jshell> ApiService apiService = new ApiService();
jshell> ApiResponse response = apiService.sendRequest();APIのリクエストとレスポンスを確認しながら、実行と修正を行うことで、開発の効率は大きく上がります。入力の手間を省くためにスクリプト化したものをjshellからロードするようにするととさらに良いでしょう。
正常に動作する状態になったところで、ログのレベルや内容を調整すると、以後の開発、運用でもこのアプリケーションログをそのまま活用できます。
以上、アプリケーションログの埋め込みから活用までひととおりお話ししてきましたが、最後に具体的なトラブルシュートの事例をいくつか紹介します。
アプリケーションログによるトラブルシュート事例
サービス連携型Push通知システムの調査
Yahoo! JAPANアプリでは社内外のサービスと連携したPush通知システムを提供しています。このシステムの詳細については以前の記事「Scalaで使うMessage Queue 〜 Yahoo! JAPANアプリのお知らせ送信でのApache Pulsarの活用」も参照ください。
今回はこのシステムの中でPush送信を担当する“Push Consumer”のトラブルシュートについて取り上げます。
Push Consumerはユーザに対するPush送信リクエストを受けてからPush送信の要否を決定し、Push送信プラットフォームAPIへリクエストを送る仕組みとなっています。Push送信が実行されるためには以下に示す条件が全て満たされていることが必要です。
- 連携元からMQのメッセージが送信され、正常に受信されているか
- Push送信に必要なデバイスID（DID）を設定しているか
- ユーザーが該当のPush種別に対し通知を許可（optin）しているか
- Push送信対象であった場合にはPushPFへのリクエストが正常に実行されているか
システム刷新前の旧システムではこれらの各段階が成功しているか否かを、データベースへの検索により手作業で確認していました。また最後のPush送信プラットフォームへのリクエスト処理の内容はログに出力されていたものの、約50台のサーバーに分散されたログファイルから該当の情報を探し出すという非常に手間のかかる作業を行う必要がありました。そのため原因究明まで一時間、場合によっては半日ほどを要することも数多くありました。
システム刷新後はSplunkにてログ内容を検索することで原因を一瞬で把握と対処ができるようになり、解決までの時間は数分単位にまで大幅に短縮されました。
具体的な例として「新規追加された連携サービスのPushが送信されない」という事象に対する調査のイメージ図を以下に示します。このケースではSplunkでのアプリケーションログ検索の結果、新規追加された連携サービスで、通知許可（optin）確認のステップが常に「通知許可設定なし」と返していることから、通知許可の設定データに誤りがあることが判明し、直ちに対策をとることができました。このケースでの調査開始から原因判明までに要した時間は約5分ほどでした。
メッセージ文言不具合の有無の確認
サービスを運用していると「関連サービスにて不具合が発見された場合に、自分たちのサービスに影響がないことを確認する」という状況が発生することがあります。
一例として、同じデータソース（Message Queue）からデータを受け取っている別サービスで「日付と曜日が一致していない」という不具合が発見されたケースを紹介します。このケースでは日付情報の文字列はサービス（アプリケーション側）で作っていましたが、文字列生成部分の問題により該当の不具合が発生していました。われわれのサービスでは別の文字列生成方法を使っていたため、問題はないものと一応予想はされていたものの、念のため確認し大丈夫であることを報告する必要がありました。
さっそく該当サービスのアプリケーションログで送信文言が含まれるものをSplunkで検索し、どの文言でも日付と曜日が一致していることを確認、5分ほどで問題なしと報告を出せました。
最後に
以上、アプリケーションログの埋め込みとその効果について、実戦的な内容を意識した解説でした。効果的なアプリケーションログの埋め込みは運用で泣かないための第一歩です。皆さまの環境でも意識してみてもらえるきっかけとなれば幸いです。
こちらの記事のご感想を聞かせください。
- 学びがある
- わかりやすい
- 新しい視点
ご感想ありがとうございました
- 福盛 秀雄
- Yahoo! JAPANアプリ バックエンドエンジニア
- アプリのバックエンドを主に手掛けています。Scala, Javaが中心ですが、JavaScript(TypeScript), Pythonもたまに触ります。
