<p>11/27にリリースされた新機能<a href="https://aws.amazon.com/jp/blogs/news/new-amazon-cloudwatch-logs-insights-fast-interactive-log-analytics/" target="_blank" rel="nofollow noopener noreferrer">Cloudwatch Logs Insights</a><br>
が障害調査を進める上で有用だったため紹介したい。</p>
<h2 id="cloudwatch-logs%E3%81%AE%E8%AA%B2%E9%A1%8C">
<a class="header-anchor-link" href="#cloudwatch-logs%E3%81%AE%E8%AA%B2%E9%A1%8C" aria-hidden="true"></a> Cloudwatch Logsの課題</h2>
<p>AWSのイベントログやその他のログ等を管理するサービスとしてCloudwatch Logsは有用であるが、実際にサービス運用を始めて、データ量が増えてくるにつれて、だんだんと使いづらい部分が見えてくる。</p>
<ul>
<li>障害の発生状況を細かく条件設定して見る</li>
<li>ログから障害の傾向を分析したいが、集計するのが億劫</li>
</ul>
<p>もちろんアラームでログ監視をする方が効果的な場合もあるが、今回はCloudwatch Logs Insightsで効率的に分析できた事例を紹介する。</p>
<h2 id="cloudwatch-logs-insights%E3%81%A8%E3%81%AF">
<a class="header-anchor-link" href="#cloudwatch-logs-insights%E3%81%A8%E3%81%AF" aria-hidden="true"></a> Cloudwatch Logs Insightsとは</h2>
<p>誤解を恐れず言うと、Cloudwatch Logsに対してデータベースのようにクエリを発行して検索できる機能と思っていただければ良い。</p>
<p>料金はデータのスキャン量に対しての従量課金で、1GBあたり0.005ドルとなっている。<br>
不用意にスキャンしすぎないように、スキャン対象を日時で絞る必要がある。</p>
<h2 id="case1.-%E3%82%A8%E3%83%A9%E3%83%BC%E3%81%AE%E5%8E%9F%E5%9B%A0%E3%82%92%E5%88%87%E3%82%8A%E5%88%86%E3%81%91%E3%82%8B">
<a class="header-anchor-link" href="#case1.-%E3%82%A8%E3%83%A9%E3%83%BC%E3%81%AE%E5%8E%9F%E5%9B%A0%E3%82%92%E5%88%87%E3%82%8A%E5%88%86%E3%81%91%E3%82%8B" aria-hidden="true"></a> Case1. エラーの原因を切り分ける</h2>
<h3 id="%E4%BA%8B%E8%B1%A1">
<a class="header-anchor-link" href="#%E4%BA%8B%E8%B1%A1" aria-hidden="true"></a> 事象</h3>
<p>ログを斜め読みしていたら、とあるAPIでエラーが頻発していたので、下記のクエリを流してみた。</p>
<div class="code-block-container"><pre><code>fields @message
| filter @message LIKE "ERROR"
</code></pre></div><p>クエリのポイントは下記の通り。</p>
<ul>
<li>
<code>fields &lt;A&gt;</code> を使うと <code>A</code> の内容を出力することができる</li>
<li>
<code>filter &lt;A&gt; LIKE &lt;B&gt;</code> で <code>A</code> の内容から <code>B</code> の内容を部分一致検索できる</li>
<li>
<code>@message</code>はログ本文の変数である</li>
</ul>
<p>結果は下記の通り。</p>
<p><img src="https://res.cloudinary.com/zenn/image/fetch/s--kIizLY7M--/c_limit%2Cf_auto%2Cfl_progressive%2Cq_auto%2Cw_1200/https://storage.googleapis.com/zenn-user-upload/deployed-images/e88c166b92565bb7fa2e8126.png%3Fsha%3Dc0c16cd9400fca2e53db119b9f7576a788ce7095" alt="image" loading="lazy" class="md-img"></p>
<p>この期間だけで3,950行あることが分かる。</p>
<h3 id="%E8%AA%BF%E6%9F%BB">
<a class="header-anchor-link" href="#%E8%AA%BF%E6%9F%BB" aria-hidden="true"></a> 調査</h3>
<p>下側に表示されたリストの内容をざっとみたところ <code>ECOM-403-001</code> というエラーが多く発生していそうであったため、一旦検索対象から外してみた。</p>
<div class="code-block-container"><pre><code>fields @message
| filter @message LIKE "ERROR"
| filter @message NOT LIKE "ECOM-403-001"
</code></pre></div><p><img src="https://res.cloudinary.com/zenn/image/fetch/s--ARp4ClF0--/c_limit%2Cf_auto%2Cfl_progressive%2Cq_auto%2Cw_1200/https://storage.googleapis.com/zenn-user-upload/deployed-images/85e94362da94a9bf38a4224c.png%3Fsha%3De99f1d68537f8953d689fdb95a8ec217527e7607" alt="image" loading="lazy" class="md-img"></p>
<p>...2件！<br>
実は <code>ECOM-403-001</code> 以外のエラーがほとんど発生していないことが判明した。</p>
<h3 id="%E5%AF%BE%E7%AD%96">
<a class="header-anchor-link" href="#%E5%AF%BE%E7%AD%96" aria-hidden="true"></a> 対策</h3>
<p><code>ECOM-403-001</code> についてはクライアント側の問題、かつ、クライアント側での対処方法が明確なエラーであったため、検知しないようにすべくエラーのレベルを引き下げる対応を19:30ごろに行った。</p>
<p>翌日、再度エラー発生状況の集計を行った。</p>
<div class="code-block-container"><pre><code>fields @message
| filter @message LIKE "ERROR"
</code></pre></div><p>結果は下記の通り。</p>
<p><img src="https://res.cloudinary.com/zenn/image/fetch/s--M6lzJV9B--/c_limit%2Cf_auto%2Cfl_progressive%2Cq_auto%2Cw_1200/https://storage.googleapis.com/zenn-user-upload/deployed-images/09bbc5e93c6908df008a654e.png%3Fsha%3Dd030529b7685ba0c97fe652065a6b10c99cd18af" alt="image" loading="lazy" class="md-img"></p>
<p>明らかに19:30を境にエラーが出てこなくなっていることが確認できた。</p>
<h2 id="case2.-%E5%AF%BE%E7%AD%96%E3%81%AE%E5%8A%B9%E6%9E%9C%E3%82%92%E8%A8%88%E6%B8%AC%E3%81%99%E3%82%8B">
<a class="header-anchor-link" href="#case2.-%E5%AF%BE%E7%AD%96%E3%81%AE%E5%8A%B9%E6%9E%9C%E3%82%92%E8%A8%88%E6%B8%AC%E3%81%99%E3%82%8B" aria-hidden="true"></a> Case2. 対策の効果を計測する</h2>
<h3 id="%E4%BA%8B%E8%B1%A1-1">
<a class="header-anchor-link" href="#%E4%BA%8B%E8%B1%A1-1" aria-hidden="true"></a> 事象</h3>
<p>しばらくすると、とあるAPIについて、API Gatewayから413 Request Entity Too Largeエラーが返却されてくるようになった。</p>
<p>とあるAPIのログを見ると、確かにエラーとなっているログが存在していた。<br>
ログを確認すると、カスタムヘッダ <em>x-cookie</em> の値が異様に長くなっているものがエラーになっていることが判明した。<br>
結果的には呼び出し側のアプリの問題であることが分かり修正したが、修正後はどのような経過になっているのか調査することにした。</p>
<h3 id="cloudwatch-logs-insights%E3%81%A7%E3%81%AE%E7%A2%BA%E8%AA%8D">
<a class="header-anchor-link" href="#cloudwatch-logs-insights%E3%81%A7%E3%81%AE%E7%A2%BA%E8%AA%8D" aria-hidden="true"></a> Cloudwatch Logs Insightsでの確認</h3>
<p>下記のようなクエリを発行した。</p>
<p><strong>問題発生 （アプリ v4.0.3）</strong></p>
<div class="code-block-container"><pre><code>fields strlen(`headers.x-cookie`) as CookieLength, floor(CookieLength/100)*100 as AmbiguousCookieLength
| filter `headers.x-app-version` = "4.0.3"
| stats count(AmbiguousCookieLength) as AmbiguousCookieLengthCount by AmbiguousCookieLength
| sort AmbiguousCookieLength desc
</code></pre></div><p>集計期間 11/28 17:00:00 〜 17:59:59</p>
<p><img src="https://res.cloudinary.com/zenn/image/fetch/s--CEd94bbG--/c_limit%2Cf_auto%2Cfl_progressive%2Cq_auto%2Cw_1200/https://storage.googleapis.com/zenn-user-upload/deployed-images/21d37a5e4a501c93ba884544.png%3Fsha%3D2458f2ade047db06fc210d28f11984b8b9fa74c3" alt="image" loading="lazy" class="md-img"></p>
<p><strong>対策後 （アプリ v4.0.4）</strong></p>
<div class="code-block-container"><pre><code>fields strlen(`headers.x-cookie`) as CookieLength, floor(CookieLength/100)*100 as AmbiguousCookieLength
| filter `headers.x-app-version` = "4.0.4"
| stats count(AmbiguousCookieLength) as AmbiguousCookieLengthCount by AmbiguousCookieLength
| sort AmbiguousCookieLength desc
</code></pre></div><p>集計期間 11/29 17:00:00 〜 17:59:59</p>
<p><img src="https://res.cloudinary.com/zenn/image/fetch/s--GfldI8gA--/c_limit%2Cf_auto%2Cfl_progressive%2Cq_auto%2Cw_1200/https://storage.googleapis.com/zenn-user-upload/deployed-images/45ddd7569c6df0ebe7e2554a.png%3Fsha%3D69edaac6526999017804bd55d326237a62243dd8" alt="image" loading="lazy" class="md-img"></p>
<p>クエリのポイントは下記の通り。</p>
<ul>
<li>
<code>strlen &lt;A&gt;</code> を使うと <code>A</code> の文字数を数えることができる</li>
<li>
<code>&lt;A&gt; as &lt;B&gt;</code>で <code>A</code> に <code>B</code> という名前を付けられる</li>
<li>
<code>floor(&lt;M&gt;/&lt;N&gt;)*&lt;N&gt;</code> で <code>M</code> を <code>N</code> 単位の概算値に変換する（今回はN=100）</li>
<li>
<code>stats count(&lt;A&gt;) by &lt;A&gt;</code> で <code>A</code> ごとの合計を集計する</li>
<li>
<code>sort &lt;A&gt;</code> を使うと <code>A</code> を昇順(asc)か降順(desc)で並び替えられる</li>
<li>
<code>head &lt;N&gt;</code> を使うと上位 <code>N</code> 個分のデータを取得することができる</li>
</ul>
<p>2つを見比べ、この対処により改善されていることが分かった。</p>
<h3 id="%E3%83%A9%E3%83%B3%E3%82%AD%E3%83%B3%E3%82%B0%E9%9B%86%E8%A8%88%E3%81%97%E3%81%A6%E3%83%80%E3%83%83%E3%82%B7%E3%83%A5%E3%83%9C%E3%83%BC%E3%83%89%E3%81%A7%E7%A2%BA%E8%AA%8D%E3%81%99%E3%82%8B">
<a class="header-anchor-link" href="#%E3%83%A9%E3%83%B3%E3%82%AD%E3%83%B3%E3%82%B0%E9%9B%86%E8%A8%88%E3%81%97%E3%81%A6%E3%83%80%E3%83%83%E3%82%B7%E3%83%A5%E3%83%9C%E3%83%BC%E3%83%89%E3%81%A7%E7%A2%BA%E8%AA%8D%E3%81%99%E3%82%8B" aria-hidden="true"></a> ランキング集計してダッシュボードで確認する</h3>
<p>次に、今後も長くなっているものがあれば見つけやすいようにランキングを表示するクエリを発行した。</p>
<div class="code-block-container"><pre><code>fields @requestId, strlen(`headers.x-cookie`) as CookieLength
| filter `headers.x-app-version` = "4.0.4"
| sort CookieLength desc
| limit 10
</code></pre></div><p><img src="https://res.cloudinary.com/zenn/image/fetch/s--P0BMQkDi--/c_limit%2Cf_auto%2Cfl_progressive%2Cq_auto%2Cw_1200/https://storage.googleapis.com/zenn-user-upload/deployed-images/f032315d2e86da0531842b46.png%3Fsha%3Df8359303a844161f822d9333349faaefb10588b5" alt="image" loading="lazy" class="md-img"></p>
<p>requestIdを表示しておき、必要に応じてログを調査できるようにした。</p>
<p>あとは、「ダッシュボードに追加」ボタンを押せば、好きなダッシュボードに追加して監視することができる。</p>
<p><img src="https://res.cloudinary.com/zenn/image/fetch/s--P9f0gCLH--/c_limit%2Cf_auto%2Cfl_progressive%2Cq_auto%2Cw_1200/https://storage.googleapis.com/zenn-user-upload/deployed-images/afa453255d49e18a51ff0af4.png%3Fsha%3D5ba9e49e0bf4b502ba6b4eb0f24178e58c743d7b" alt="image" loading="lazy" class="md-img"></p>
<h2 id="case3.-%E9%81%8B%E7%94%A8%E3%81%A7%E3%81%AE%E3%83%AA%E3%82%AB%E3%83%90%E3%83%AA%E3%82%92%E8%80%83%E3%81%88%E3%82%8B">
<a class="header-anchor-link" href="#case3.-%E9%81%8B%E7%94%A8%E3%81%A7%E3%81%AE%E3%83%AA%E3%82%AB%E3%83%90%E3%83%AA%E3%82%92%E8%80%83%E3%81%88%E3%82%8B" aria-hidden="true"></a> Case3. 運用でのリカバリを考える</h2>
<h3 id="%E4%BA%8B%E8%B1%A1-2">
<a class="header-anchor-link" href="#%E4%BA%8B%E8%B1%A1-2" aria-hidden="true"></a> 事象</h3>
<p>サーバサイドの不具合で、11/28にログインしたユーザについては、メールアドレスが正しくなく、その後の使用でデータ不整合を起こす可能性があることが判明した。<br>
影響を受けるユーザを抽出する必要が出てきた。</p>
<h3 id="cloudwatch-logs-insights%E3%81%A7%E3%81%AE%E7%A2%BA%E8%AA%8D-1">
<a class="header-anchor-link" href="#cloudwatch-logs-insights%E3%81%A7%E3%81%AE%E7%A2%BA%E8%AA%8D-1" aria-hidden="true"></a> Cloudwatch Logs Insightsでの確認</h3>
<p>調査した結果、</p>
<ul>
<li>11/28にログインしたユーザについては、メールアドレスが <code>dummy@example.com</code> になっている</li>
<li>bodyに含まれる <code>accountNo</code> でユーザを一意に特定できる<br>
ことがわかったため、メールアドレスが <code>dummy@example.com</code> になっているユーザの <code>accountNo</code> を抽出することにした。</li>
</ul>
<p>現状、AWSのコンソールではクエリの結果をファイルにエクスポートすることができないため、AWS CLIを使う。</p>
<p><code>start-query</code> コマンドでクエリ発行を行う。クエリ発行に成功すると <code>queryId</code> が返却されてくる。</p>
<div class="code-block-container"><pre><code>$ aws logs start-query --log-group-name="/aws/lambda/foobarApi" --start-time=0 --end-time=1543755820 --limit=10000 --query-string='fields @timestamp, body.accountNo | filter body.email = "dummy@example.com" | filter @timestamp &gt; 1543330800000 | filter @timestamp &lt; 1543417199000 | limit 10000'
{
    "queryId": "00000000-c482-48c8-9968-b256593f0b69"
}
</code></pre></div><p><code>get-query-results</code> コマンドでjsonを取得できるので、csvに変換してリスト化した。</p>
<div class="code-block-container"><pre><code>$ aws logs get-query-results --query-id="00000000-c482-48c8-9968-b256593f0b69" &gt; results.json
$ cat results.json | jq -r '.results[] | [.[0].value, .[1].value] | @csv' &gt; results.csv
</code></pre></div><h3 id="%E3%82%B3%E3%83%9E%E3%83%B3%E3%83%89%E3%83%A9%E3%82%A4%E3%83%B3%E3%81%8B%E3%82%89%E5%AE%9F%E8%A1%8C%E3%81%99%E3%82%8B%E5%A0%B4%E5%90%88%E3%81%AE%E7%95%99%E6%84%8F%E7%82%B9">
<a class="header-anchor-link" href="#%E3%82%B3%E3%83%9E%E3%83%B3%E3%83%89%E3%83%A9%E3%82%A4%E3%83%B3%E3%81%8B%E3%82%89%E5%AE%9F%E8%A1%8C%E3%81%99%E3%82%8B%E5%A0%B4%E5%90%88%E3%81%AE%E7%95%99%E6%84%8F%E7%82%B9" aria-hidden="true"></a> コマンドラインから実行する場合の留意点</h3>
<ul>
<li>
<code>start-time</code> , <code>end-time</code> はGMT（日本ならば-9時間した時間）を秒の単位で指定する（クエリの中の変数はミリ秒単位なので、間違えないように）</li>
<li>現状はスキャン対象を絞るためのパラメータがないため、全件スキャンになってしまう</li>
<li>
<code>limit</code> を省略すると1000件までの取得となる</li>
<li>
<code>limit</code> はパラメータだけでなくクエリにも必要である</li>
<li>
<code>limit</code> の上限は10,000件になっている</li>
</ul>
<h2 id="%E6%B0%97%E3%81%AB%E3%81%AA%E3%81%A3%E3%81%9F%E3%81%93%E3%81%A8">
<a class="header-anchor-link" href="#%E6%B0%97%E3%81%AB%E3%81%AA%E3%81%A3%E3%81%9F%E3%81%93%E3%81%A8" aria-hidden="true"></a> 気になったこと</h2>
<ul>
<li>ログが分割されていると分析がしづらい
<ul>
<li>1トランザクションのログの行が複数行ある場合でも、検索対象の行しか見られないため、例えば「レスポンスがエラーになっているトランザクションのリクエストのログを確認する」と言ったことはやりづらい</li>
<li>活用しやすいようなログ出力設計が必要かもしれない</li>
</ul>
</li>
<li>結果のファイル出力が弱い
<ul>
<li>クリップボードにコピーする機能はあったりするが、検索結果が大きくなってくるとマシンの負荷が高くなりなかなか難しくなってくる</li>
<li>今回はAWS CLIでやれる範囲だったが、使い勝手やコンソールと比べても機能が弱いので今後の改善に期待したい</li>
</ul>
</li>
<li>ダッシュボードに貼り付けると定期的に実行される
<ul>
<li>検索範囲は絞ることができるが、定期的にクエリが実行されていることを忘れると思わぬ料金になったりする可能性がある</li>
<li>ダッシュボードの更新頻度は確認しておいたほうが良い</li>
</ul>
</li>
<li>クエリの同時実行数が4である（数値は今後変わるのかもしれないが）
<ul>
<li>ダッシュボードに貼り付けると定期的に実行されるため、ダッシュボードに結果を貼りまくっていると、いざコンソールからクエリを流そうとしたときに実行エラーになることがある</li>
</ul>
</li>
<li>ロググループを横断する調査についてはどうすればいいのか分からない
<ul>
<li>これもログ出力設計になるのだろうか...勉強中である</li>
</ul>
</li>
</ul>
<h2 id="%E3%81%BE%E3%81%A8%E3%82%81">
<a class="header-anchor-link" href="#%E3%81%BE%E3%81%A8%E3%82%81" aria-hidden="true"></a> まとめ</h2>
<p>エラー調査では、CloudWatchの検索窓から頑張って検索するか、アラーム設定するかで乗り切っていたが、特定の時間にだけ多く発生しているエラーがあるのかどうかとか、どんなエラーが多く発生しているのかとか、集計したいと思うときが多く、そこそこ限界を感じていたので、いいサービスだなと思った。</p>


Cloudwatch Logs Insightsの活用事例

Case1. エラーの原因を切り分ける

ランキング集計してダッシュボードで確認する

コマンドラインから実行する場合の留意点

Case3. 運用でのリカバリを考える

Discussion