開発者が運用を経験すべき一つの理由
はじめに
小室です。2017年も最後の日になりました。
ここ最近は読書によるインプットが少なくなったことによって、文章の質が自ら目を背けたくなる程度に低下していたため、仕事納めから数日はひたすら本を読む生活をしていました。まだまだインプットが足りていないので充電が完了していないのですが、年末恒例になったエントリーを書かないことが自分の中でモヤモヤとして残っていたので、重い腰を上げて文章を書いてみようと思います。
ここ数年は珍しく1つのプロジェクトにつきっきりで設計／実装から運用までを通して担当しています。 *1特に運用を担当するようになって多くを学んだ一年でした。もはや設計・実装者が一人も残っていないアプリケーションのメンテナンス、改修に関わったり、インフラ側とアプリケーション側の狭間を埋めるように動くためにAWSのサービスについて本格的に勉強をしたりするなど、1アプリケーションエンジニアとして設計／実装を行っていた時期では想像だにしなかった領域にて活動していました。 *2
さて、今回はこの1年のサービス運用・改善・新機能の設計／実装に関わった立場から、開発者 *3が一度は運用を経験した方が良いと思う理由の一つについて書いていきます。
サービス運用において最重要項目の一つ
それは ログ です。アプリケーションログ、アクセスログ、インフラストラクチャのアクティビティログなど、システムを運用する上ではありとあらゆるログが必要です。特に開発者が関わるのは、 アプリケーションログ, アクセスログ あたりではないでしょうか。障害が発生した場合はこれら保存しているログが唯一の手がかりになります。これらがないシステムは、障害解析は全くできないと断言しても過言ではありません。障害の結果のみからすべて原因まで推測できるならば不要でしょう。しかし、現在のシステムはマイクロサービスなどにより責務が細かく分断された上、膨大なコンポーネントの集合体によって動作しているものがほとんどかと思います。これら、数百、数千コンポーネントが複雑に絡んだ集合体での障害調査をログなしで行うのは事実上不可能に近いというのは想像に難くないのではないでしょうか。 *4
しかし不思議なことに、アプリケーションエンジニアの多くは、ログ設計・実装について、さして優先度の高い事項だと認識している人は少数ではないかと思っています。あくまで機能が正しく動作するように実装すること、論理構造を設計／実装するだけで満足していまい、ログについては後で適当に追加すればいいやと思っている空気すら感じられます。
なぜログが重要視されないのか
これは自分の経験に基づくもので特に根拠があるわけではありませんが、以下のような理由からだと考えています。
- システム運用でどのようにログが利用されているのかよくわからない
- 障害解析時にはどのような作業が必要になるのか知らない
- どういった情報が必要なのかがよくわからない
いまだ存在しないシステム全体の運用を想像するのは容易ではありません。――まだ作っている途中だし―― 特に受託案件の場合、お客様に納品した後、どのように運用されるのかは自社サービスよりも不透明で想像しづらいものかもしれません。しかし、機能を設計／実装している以上、対象の業務ドメインについての知識や運用について全く無知でいて良いはずがありません。
システムは運用されて初めて価値を生み出します。障害が起きて停止した場合、その時間分のビジネスが停止することになり、規模によりますが大規模な機会損失、または直接的な損失に繋がることを想像するのは難しくありません。100%の正常稼働を保証することは不可能であることをエンジニアならば知っているはずです。障害が発生した場合に、どのような情報があれば障害に気づくことができ、データに不整合が発生した場合には復旧することができるかを考えれば、自ずと適切なログを出力しておくことが重要であることに気づくのではないでしょうか。 *5
適切なログが分からない
前段でも触れましたが、 適切なログ とはなんでしょうか？これは開発のみに携わっているとなかなか実感することができないことです。運用からログをこうしてほしいというフィードバックがあれば非常に幸運ですが、実際はそういったフィードバックは ――特に受託案件では―― 非常に稀ではないでしょうか。実際に一度運用を経験してみると、自分自身が出力したログがいかに情報不足で、いかに不要な情報を含んでいて、肝心な箇所のログが存在しない（ログ出力のタイミング）、などたくさんの気づきを得ることができます。
では、運用を経験した上で適切なログってなんだよ？という話になります。しかし「これが俺の考えた史上最高のベストなログだ！」と提示することができません。なぜならば ーこれもまた非常に卑怯な言い方ですがー 何がベストかはそのケースごとに異なります。アンチパターンのようにこのようなログは最低である、と指摘することはできますが、この世で最高のログはこれだと言い切ることが現時点で自分にはできません。そこで、運用を経験した上でこういう情報があるととても助かった、逆にこういうログは非常に困った、という観点でいくつか例示します。
[Bad] ログレベルがメチャクチャである
一般的にアプリケーションログには、その重要度に応じてログレベルが指定できます。TRACE, DEBUG, INFO, WARN, ERRORなど。恐らく開発者がよく利用するのが、DEBUG, ERRORあたりではないでしょうか。他のINFOやWARNについてきちんと使い分けをプロジェクトごとにできているでしょうか？
これはある期間の間に更新されたユーザー情報をすべて取得し、集計、整形した上でTSVファイルを出力する機能のログです。
{
"message": "2017-09-14 17:00:28.104 INFO 16976 --- [main] hoge.fuga.moge.Application : requestId: hashId: clientId: INFO : 処理開始......",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:28.112 DEBUG 16976 --- [main] hoge.fuga.moge.service.HogeService : requestId: hashId: clientId: DEBUG : process begin.",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:28.113 DEBUG 16976 --- [main] hoge.fuga.moge.service.HogeService : requestId: hashId: clientId: DEBUG : get data from db and create tsv file",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: DEBUG : PathNotFound $.xxxx.yyyyyyy",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:31.406 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: DEBUG : PathNotFound $.xxxx.yyyyyyy",
"host": "ip-xx-xxxx-xx-xx"
}
.....
{
"message": "2017-09-14 17:05:12.444 INFO 16976 --- [main] hoge.fuga.moge.Application : requestId: hashId: clientId: INFO : 処理終了......",
"host": "ip-xx-xxxx-xx-xx"
}
このログを見た時仰天し椅子から転がり落ちそうになりました。なぜならば出力するログレベルをINFOにした瞬間に出力されるのは 処理開始.... と 処理終了..... だけなのですから。これから一体何を読み取れば良いのでしょうか。
本当に必要だった情報
このログを改善するには以下の観点で改善する必要があります。
- どのユーザーを処理しているのか
- エラーが発生した場合、どのユーザーで何が原因で失敗したのか
- 何をしようとしているのかを知りたい
このログから読み取るのはとても難しいですが、処理内容はDBから取得したユーザー情報の中にJSONオブジェクトが含まれており、その中から指定されたJsonPathの値を読み取り、TSV形式に整形しています。これらの処理を一通りログから読み取れるようにして欲しい。でなければ、プログラムの実装を一通り読む必要があります。それを運用サイドの責務とするのはお門違いではないでしょうか。さらに障害発生時にはそんな悠長にプログラムを一通りすべて読んで理解する時間などありません。
ざっと改善のイメージを書いてみます。
{
"message": "2017-09-14 17:00:28.104 INFO 16976 --- [main] hoge.fuga.moge.Application : requestId: hashId: clientId: INFO : Output Hoge TSV File 2017-09-14",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:28.112 DEBUG 16976 --- [main] hoge.fuga.moge.service.HogeService : requestId: hashId: clientId: DEBUG : SELECT ~~~ FROM xxxxx WHERE ~~~~~",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:28.112 DEBUG 16976 --- [main] hoge.fuga.moge.service.HogeService : requestId: hashId: clientId: INFO : Target User Count: 36",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: INFO : User: aaaaaaaaaaaa==",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: DEBUG : Json: {hogehoge: fugaufa, ......}",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:31.406 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: DEBUG : PathNotFound $.xxxx.yyyyyyy",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: INFO : User: aaaaaaaaaaaa== completed",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: INFO : User: bbbbbbbbbbbb==",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: INFO : Json: {hogehoge: fugaufa, ......}",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: WARN : Need hash_id, But not exist. $.aaaa.hash_id",
"host": "ip-xx-xxxx-xx-xx"
}
{
"message": "2017-09-14 17:00:30.998 DEBUG 16976 --- [main] hoge.fuga.moge.util.FugaUtil : requestId: hashId: clientId: WARN : User: aaaaaaaaaaaa== skipped",
"host": "ip-xx-xxxx-xx-xx"
}
このような改善が最低限必要かと思います。まだどのようなイベントが発生し、どのような処理が行われてかの見通しは良くなっているかと思います（とはいえ、まだ改善の余地は多分に残っていますが。）
[Good] トレース可能なログである
AWSなどのクラウドが活用されるようになり、容易にスケールアウト、スケールインができるようになりました。そのため、アプリケーションは容易にスケールに対応できるようにステートレスなアプリケーションフレームワークを活用していることが多いかと思います。容易にスケールするということはすなわち、いつ生まれ、いつ死ぬか分からないサーバーが無数にあるということです。それ故にサーバーのログはローカルに抱え込まず、各ログストレージへ様々な方法で転送していることでしょう。fluentdを利用したり、CloudWatch Logsエージェントを利用することが多いかと思います。
複数のサーバーが一つのログストレージに書き込むということはどういうことでしょうか。当然ながら１つのサーバーのログが書き終わるまで待ってくれるようなことはありません。順不同で様々なサーバーのログが非同期に書きまれてきます。行儀よく整列などしてくれませんので、同時刻、ミリ秒単位の範囲で絞り込んだとしても、同じサーバーからの一連のログを探し出すのは至難の業です。そこでRequestからResponseまでを一貫のイベントとしてトレース可能な一意なIDをログに付与しておけば、そのトレースIDにより1つのRequestのイベントのみを抽出することが可能です。
例えばこんな具合に。この機能のお陰で同一時刻の同一スレッドの同一Requestの一連のイベントを目grepで探し出す、といった地獄のような作業をすることがありませんでした。例えサーバーが20台近くスケールしていたとしても。
ログの原則
全く情報が出力されていなかったり、意味のないゴミ情報ばかり出力されるログが実装されたシステムの運用は誰も担当したくありません。しかし、納品後は誰かが運用をしているはずです。運用サイドの方々にいらぬヘイトを溜めさせたり、障害解析の依頼が来ても自分が困らないように、最低限以下の原則を意識すると良いのではないでしょうか。
- 出力するログを確認すると以下が読み取れるかどうか
- 最低限INFOレベル以上の情報のみでそのリクエストによって何の処理が行われたかがトレースできるか
出力するログを確認すると以下が読み取れるかどうか
以下が読み取れるかを意識してログを実装すると、運用時にも情報不足で困るといったことはさしあたってなさそうです。
- いつその処理が実行されているのか
- 誰がその処理を呼び出したのか
- どこで実行されているのか
- 何をしようとしてその処理を呼び出しているのか
- なぜそれが実行されたのか（特にエラーの場合）
いわゆる会話と同じく5W1Hを意識するべきと教えられました。アプリケーション開発を行っていると、自分の担当した機能に対しては論理構造の設計／実装を共に自らが行っているため、どうしても暗黙の知識ができてしまいます。それらは当然、ログに出力したり、ドキュメントに記載しなければ誰にも伝わりません。ログは運用サイドへの非同期メッセージです。自分だけが分かる暗号のようなメッセージや開発メモを埋め込まれても困ります。必要ならばそういった開発ログはDEBUGレベルで記述をすべきでしょう。
INFOレベル以上の情報のみでそのリクエストによって何の処理が行われたかがトレースできるか
ログレベルは、開発時と運用時では当然変わります。DEBUGレベルで出してるからいいだろう、ではないのです。膨大なログが日々蓄積するため、障害発生時には当然ながらログレベルのフィルタは有効に利用しなければ素早い状況分析や解析はできません。エラーも何もかもすべてDEBUGレベルで記載されてしまっては何も意味がありません。膨大なジャングルの中から1本だけ腐った木が存在するのでそれを見つけてください、と言われるようなものです。
またTRACEレベルでの記載は論外です。アプリケーションフレームワークを利用しているアプリケーションの場合、TRACEレベルではフレームワークの出力する大量のログが出力されます。その数は膨大です。わざと隠してるのか！という気持ちになります。ちなみに実績値ですが、SpringBootアプリケーションで分間3万アクセス程度のOAuth認証基盤のアプリケーションの場合、TRACEレベルを有効にしていたところ、5分間で800MB近いログが出力されていました。
まとめ
サービス運用をサポートする立場になり、いかに自分勝手に開発していたかがよくわかった一年でした。意識をしているつもりであっても、所詮机上の空論。実際の現場で障害の解析や分析を行うと、「なぜこの情報が出力されていないのか」「なぜこのログがERRORレベルで検出されているのか」「なぜこの時間帯のログが存在しないのか」など、ログに関してのトラブルについては枚挙に暇がありません。しかし、これらは運用の立場にならなければ気づかなかったことです。これらの学びをフィードバックし、ログ出力内容の改善やログレベルの見直しなどは逐次行いアップデートを行っています。そのため、ここ数ヶ月はかなりスムーズに状況解析を行うことができるようになり、障害発生した際にも極力データ復旧を行うことができるようにもなっています。開発オンリーでは気づけなかった視点です。自分としてもここまで改善や運用に抵抗がないとは思っていませんでした。
受託案件という性質上、なかなか運用フェーズでの気づきからのフィードバックは難しいかもしれません。しかし、自分の担当しているプロジェクトは幸運なことに運用に深く関わらせてもらうことができています。なかなか自社サービス以外で設計・実装から運用まで経験する機会がなかったため、今まで自分の関わっていた領域以外をたくさん知識を得ることが出来ました。来年も引き続き、運用サイドで得た知識を開発時にも活かせるように切磋琢磨し、関わっているプロジェクトのさらなる改善と安定稼働を目指していこうと思います。
