この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。
アプリケーションで障害が発生したとき、アプリケーションログを調査して原因究明するのが有効な方法です。しかし、複数に分割されたアプリケーションログファイルの中から正確な障害発生時刻の特定や複数のサーバー間のタイムラインをトレースすることは困難です。
今回は、これらの課題を解決するため、Amazon Athenaでアプリケーションログを探索する方法をご紹介します。アプリケーションログはLogbackのデフォルトフォーマットで生成されるファイルを用います。
アプリケーションログファイル
アプリケーションログファイルの作成
サンプルのアプリケーションログファイルは、下記のコードで生成されたものを用います。
package com.example.app;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class LogbackSample {
/** logger */
static final Logger logger = LoggerFactory.getLogger(LogbackSample.class);
public String[] doSomething() {
String[] arr = null;
try {
arr = new String[2];
arr[2] = "error";
} catch (Exception e) {
logger.error("expected error: ", e);
}
return arr;
}
public static void main(String[] args) {
logger.info("--- アプリケーション開始 ---");
LogbackSample app = new LogbackSample();
app.doSomething();
logger.info("--- アプリケーション終了 ---");
}
}アプリケーションログファイルの内容
生成されたアプリケーションログファイルは、以下のとおりです。ログファイルの中には、メッセージに日本語やJavaのスタックトレースも含まれています。
2017-7-16 18:30:25.178 INFO com.example.app.LogbackSample - --- アプリケーション開始 ---
2017-7-16 18:30:25.186 ERROR com.example.app.LogbackSample - expected error:
java.lang.ArrayIndexOutOfBoundsException: 2
at com.example.app.LogbackSample.doSomething(LogbackSample.java:13)
at com.example.app.LogbackSample.main(LogbackSample.java:23)
2017-7-16 18:30:25.187 INFO com.example.app.LogbackSample - --- アプリケーション終了 ---テーブルの定義
上記のログファイルは、項目の順に出力されています。
- log_ts : ログの日時
- level : ログレベル
- class : ログ出力しているクラス名
- message : ログメッセージ
では、これらを順にカラムとして定義します。Amazon Athena は、ログが複数のファイルの場合でも、同じフォルダに配置することで同じテーブル内のデータとしてクエリーを実行できます。
CREATE EXTERNAL TABLE applogs1(
log_ts string,
level string,
class string,
message string)
ROW FORMAT SERDE 'org.apache.hadoop.hive.serde2.RegexSerDe'
WITH SERDEPROPERTIES (
'serialization.format' = '1',
'input.regex' = '(.{21,23}) (TRACE|DEBUG|INFO |WARN |ERROR|FATAL) ([\\s\\w-.]+) - ((?:[^\\n\\r]+)(?:[\\n\\r]{1,2}[^\\n\\r]+)*)'
)
LOCATION 's3://devio2017-handson/10-applogs/'
TBLPROPERTIES ('has_encrypted_data'='false');messageに Java スタックトレースを含む事ができる正規表現をinput.regex に指定しましたが、含めることはできませんでした。
執筆時点、Hive DDL は、ログを行毎に分割した後に、正規表現を適用する（行データをRegexserdeに渡す）ので message に Java のスタックトレースを含めることはできない様です。
参考：Multi line regex for Hive Regex Serde
アプリケーションログを探索
シンプルなログの探索
Amazon Athena のクエリエンジンである Presto は、正規表現と一致しない場合にnullのレコードとして出力されるようです。つまり、スタックトレースの箇所がnullのレコードとして出力されています。
この回避策としては、ログの日時（log_ts）がnullのカラムを除外(WHERE log_ts is not null 又は WHERE log_ts <> null)します。
スタックトレースなどのエラー原因の参照には該当のログファイルを参照してください。
複数のサーバー間のタイムラインをトレースするには？
Amazon Athenaは、複数のに分割されたログファイルでも同じフォルダに配置することで、ファイルが結合されたかのようにクエリを実行することが可能です。ログファイルが複数に分割されても問題ありません。
次に、出力されたサーバーを識別するには、ログの中に「ホスト名」などが含まれていれば、そのカラムを追加して、クエリを実行します。今回のサンプルデータにはそのようなカラムを含んでいませんので、テーブルをアプリケーションサーバー毎に定義して、複数のテーブルを UNION ALL することで、まとめて探索できます。以下の例では、サブクエリーの中でサーバーを識別するためのカラムを付与して、複数のログファイルを集約しています。
アプリケーションログの最適な形式
サーバーを識別する方法を付与する
"Design for failure" で設計されたシステムであれば、当然アプリケーションログも複数存在するはずです。出力されたサーバーを識別するには、ログの中に「ホスト名」等を含めるか、もしくはサーバー毎にログを出力するフォルダを分けてテーブルを作成しサーバーを識別するためのカラムを付与するなどの方法を検討してください。
ログファイルの出力先フォルダを日ごとに分ける
探索範囲のスコープが明らかな場合は、利用費の削減や応答時間の短縮の観点から探索するログの期間を限定することが望ましいです。そのためには、年月日で階層的なフォルダ構成になっているとより簡単に期間を限定できます。
例えば、
- 2017年1月1日の場合：s3://<logbacket>/2017/01/01/'
- 2017年1月の場合：s3://<logbacket>/2017/01/'
- 2017年の場合：s3://<logbacket>/2017/'
今回は触れていませんが、定常的にアプリケーションログを監視したい場合は、パーテイション設定することもご検討ください。
最後に
今回はアプリケーションログの例に、Logbackのデフォルト形式を用いました。ログファイルはLog4Jから派生した形式が多いので、必要に応じてホスト名やPIDが含んだり、セパレータ文字列が異なる場合があるかもしれませんが、上記の例に追加変更することで色々と応用できるはずです。アプリケーションログの探索は障害の事後調査に有効であることはご理解いただけたと思います。さらに障害が発生してからではなく定期的にログを自動探索して、障害の予兆を検知するプロアクティブな監視に活用できるのではないかと考えています。
22
