新しく AWS の CloudWatch Logs Insights を使い始める人に向けての演習資料を目指します。
CloudWatch Logs Insights とは
ログファイルの監視、保存、アクセスができます。
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時間がスキャン範囲なので、そこまでびくびくしなくていいです。
はじめの一歩
- AWSコンソールにログイン
- CloudWatch > CloudWatch Logs Insights
- 調査対象の loggroupを選択 (例: homura/tomcat/current)
[Run Query]
fields @timestamp, @message
| sort @timestamp desc
| limit 20
対象ロググループの最新ログが20行表示されます。
クエリーは、pipe で単純な処理を連結して組み立ててます。json処理する jq にちょっと感じが似てるか。
疑似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までは簡単に指定できます。
hitすると、時間軸とhit数のヒストグラムも出てくるので、いつから出始めたのか、頻度はどれくらいか、すぐに把握できます。
- あるデプロイの直後からなら、そのデプロイでの変更点が第1容疑者
- 毎正時に出ているなら、なにかの定期実行jobかな
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 に構造化する演習はまたこんど。