CloudWatch Logs Insights 新人演習


新しく AWS の CloudWatch Logs Insights を使い始める人に向けての演習資料を目指します。

## CloudWatch Logs Insights とは

https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/logs/WhatIsCloudWatchLogs.html

> ログファイルの監視、保存、アクセスができます。

> CloudWatch Logs Insights を使用して、ログデータをインタラクティブに検索および分析できます。クエリを実行することで、運用上の問題に効率的かつ効果的に対応できます。

EC2 instance の Apache access_log とか tomcat log を収集・保存して、AWSコンソール上でクエリによる参照・分析ができます。

## なにが嬉しいの

- 各EC2 instanceに loginせずにログを参照できる
    - ログ参照できる権限でログインしてると、ログ参照以外の操作もできたりして、いろいろとあやうい
- 負荷分散・高可用性で複数台並列構成にしているとき、ワンストップで全部のログを調査分析できる
    - 2台ならまだいいけど、運用の 2n台、3n台構成だとうんざりでしょ？
- クエリがそれなりに強力
    - ログの各フィールドを adhoc に構造化したりとか

## クラウド破産は怖くない？

ほい、料金表。
https://aws.amazon.com/jp/cloudwatch/pricing/

無料利用枠
> ログ	5 GB データ (取り込み、ストレージのアーカイブ、Logs Insights クエリによってスキャンされたデータ)

従量料金
> 分析 (Logs Insights のクエリ)	スキャンしたデータ 1 GB あたり 0.0076USD

料金の例
> ウェブアプリケーションのアクセスログ 1 GB x 30 日 = 30 GB
> CloudWatch の月額料金 = 12.53 USD

上記は無料枠の 5GB は引いてます。あなたの時給の 0.x時間分ですね。
ログ調査は直近のログだけで済む場合が殆どなので、スキャンデータの範囲を限定すれば怖くない。

> 1 日間～10 年間の保持期間を選択することができます

Administrator が調査可能範囲とコストを秤にかけて、適切な保持期間にしてるし、コンソールのデフォールトだと直近1時間がスキャン範囲なので、そこまでびくびくしなくていいです。

## はじめの一歩

1. AWSコンソールにログイン
1. CloudWatch > CloudWatch Logs Insights
1. 調査対象の loggroupを選択 (例: homura/tomcat/current)
1. `[Run Query]`

![image (3).png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/47549/a225ee82-70b1-b0fd-5c4b-f612e0536457.png)

```
fields @timestamp, @message
| sort @timestamp desc
| limit 20
```

対象ロググループの最新ログが20行表示されます。
クエリーは、pipe で単純な処理を連結して組み立ててます。json処理する jq にちょっと感じが似てるか。

疑似SQLで表現しなおすと、こんな感じでしょう。

```sql
SELECT timestamp_, message_ FROM 'homura/tomcat/current'
ORDER BY timestamp_ DESC
LIMIT 20;
```

各行の詳細を行頭の `▶`をクリックして表示させてみましょう。

```
▶ 2 2021-01-23T14:56:02.045+09:00 @40000000600bba7b34e32194 SCIM [HTTP Response Header]:Content-Type=application/scim+json;charset=UTF-8

Field	　　　　　Value
@ingestionTime   1611381366827
@log             <account>:homura/tomcat/current
@logStream       101a
@message         @40000000600bba7b34e32194 SCIM [HTTP Response Header]:Content-Type=application/scim+json;charset=UTF-8
@timestamp       1611381362045
```

`fields` で指定した以外の属性も見えました。
> @ingestionTime は、ログイベントが CloudWatch Logs によって受信された時間を示します。

`@logstream` はログ発生元を表すための文字列で、各instance の aws-cloudwatch-agent の設定ファイル由来です。
設定のデフォールトは instance-id ですが、AutoScaleとかしないでずっと同じ少数の instance を使う開発・試験環境では、
instanceの pet-nameで設定していることもあるでしょう。

二歩目では `fields` に `@logStream` も追加することにしましょう。

## SEVERE/ERRORログの特定

500 Internal Server Errorなどが返ってきてるという想定で、ログ調査演習してみましょう。

```
fields @timestamp, @logStream, @message
| filter @message like /(SEVERE|ERROR)/
| sort @timestamp desc
| limit 10
```

みつかりました？
該当がでてこなったら、ログの探索範囲を広げてみましょう。初期値は過去1hになっているので、3h, 12hと。
もっと過去までみるなら Custom から4weekまでは簡単に指定できます。

![cloudwatchlogsinsights_range.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/47549/e2156fe5-81de-de13-acf4-ff8bef91794b.png)


hitすると、時間軸とhit数のヒストグラムも出てくるので、いつから出始めたのか、頻度はどれくらいか、すぐに把握できます。

- あるデプロイの直後からなら、そのデプロイでの変更点が第1容疑者
- 毎正時に出ているなら、なにかの定期実行jobかな

![cloudwatchlogsinsights_histo.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/47549/106c20c4-136e-3f75-b918-e79fb9282bde.png)


## SEVERE/ERRORログの直後のstack trace

Exceptionが出てるかも。その stack trace からExceptionの発生場所をつきとめましょう。

起点とする `ERROR` 行がこうだとすると

```
@logStream	101b
@message	@40000000600a66f41b958bdc 22-Jan-2021 05:47:22.461 INFO [ajp-nio-8009-exec-9] com.example.servlet.ScimUsersServlet.httpMethod end(69ms)--->HTTP 500 INTERNAL_SERVER_ERROR
@timestamp	1611294447291
```

```
fields @timestamp, @logStream, @message
| filter @logStream = "101b"
| filter @timestamp >= 1611294447291
| sort @timestamp asc
| limit 30
```

- `ERROR` 行と、同じ logStream（同じinstance）
- `ERROR` 行のtimsstampの直後の30行
- timsstamp の昇順ソート

`at javax.` のライブラリや、 `at org.apache.` のミドルウェアのところじゃなくて、開発・試験中の package が出ていれば、その Class と行番号からソースでの調査が始められます。
stack trace がやたらと長いときには、 `limit` 行数を調整します。

## Export results

うまく拾えたら、 コンソールの `Export results` を使いましょう。ここでは markdown 結果を貼っておきます。
CSVでのクリップ|ダウンロードもできます。

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|       @timestamp        | @logStream |                                                                                          @message                                                                                          |
|-------------------------|------------|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| 2021-01-22 05:47:27.291 | 101b       | @40000000600a66f41b958bdc 22-Jan-2021 05:47:22.461 情報 [ajp-nio-8009-exec-9] com.example.servlet.ScimUsersServlet.httpMethod end(69ms)--->HTTP 500 INTERNAL_SERVER_ERROR                   |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a6748232cff4c  at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)                                                                                       |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a67482331ae84  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)                                                            |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822dc1474 java.lang.NullPointerException                                                                                                                                   |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a67482336c734  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)                                                                    |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a6748233e77f4  at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)                                                                          |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a67482343a814  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)                                                                           |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674823486ebc  at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)                                                                       |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822e1f45c  at com.example.common.service.mybatis.MybatisUserServiceImpl.getSystemSqlSession(MybatisUserServiceImpl.java:277)                                           |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822e53c34  at com.example.common.service.mybatis.MybatisUserService3Impl.getUser(MybatisUserService3Impl.java:430)                                                     |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822e9f33c  at com.example.common.service.mybatis.MybatisUserService3Impl.getUser(MybatisUserService3Impl.java:422)                                                     |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a6748234d4504  at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)                                                                                |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a67482351f43c  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)                                                                             |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a67482356c2b4  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)                                                                                  |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a6748235da084  at org.apache.coyote.ajp.AjpProcessor.service(AjpProcessor.java:486)                                                                                            |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674823628284  at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)                                                                             |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a6748236735a4  at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)                                                                      |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a6748236cbbb4  at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459)                                                                          |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822f009d4  at com.example.documentservice.servlet.documentmanagerservlet.UserService3.login(UserService3.java:1341)                                                       |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

調査Issue にはこの結果をそのまま貼ればいいでしょう。
それとは別に Slack とかにも貼るなら、 `com.example.*` の開発package部分だけの短縮版がいいでしょう。長すぎる log が貼られるとチャンネル自体が読みづらくなってしまうので。

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|       @timestamp        | @logStream |                                                                                          @message                                                                                          |
|-------------------------|------------|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| 2021-01-22 05:47:27.291 | 101b       | @40000000600a66f41b958bdc 22-Jan-2021 05:47:22.461 情報 [ajp-nio-8009-exec-9] com.example.servlet.ScimUsersServlet.httpMethod end(69ms)--->HTTP 500 INTERNAL_SERVER_ERROR                   |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822dc1474 java.lang.NullPointerException                                                                                                                                   |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822e1f45c  at com.example.common.service.mybatis.MybatisUserServiceImpl.getSystemSqlSession(MybatisUserServiceImpl.java:277)                                           |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822e53c34  at com.example.common.service.mybatis.MybatisUserService3Impl.getUser(MybatisUserService3Impl.java:430)                                                     |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822e9f33c  at com.example.common.service.mybatis.MybatisUserService3Impl.getUser(MybatisUserService3Impl.java:422)                                                     |
| 2021-01-22 05:48:46.663 | 101b       | @40000000600a674822f009d4  at com.example.documentservice.servlet.documentmanagerservlet.UserService3.login(UserService3.java:1341)                                                       |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

いかがでしたか。ssh login して grep , less でログ調査してる時代じゃないでしょう？
`@message` フィールドを adhoc に構造化する演習はまたこんど。