Asakusa Frameworkでログを出力する方法のメモ。
|
|
Operatorクラスからは、レポートAPI（Reportクラス）を使ってログを出力することが出来る。
または、ログ出力用演算子（Loggingアノテーション）を作ることが出来る。
Asakusa Framework0.5.1から、データをログ出力（トレース）することが出来るようになった。[2013-07-27]
Reportクラスのstaticメソッドであるerror()・warn()・info()でログ出力する。
（Eclipse上のJUnitでテストを実行すると、Eclipseのコンソールに出力される）
import com.asakusafw.runtime.core.Report; import com.asakusafw.vocabulary.operator.Sticky;
public abstract class WordCountOperator {
@Sticky
@GroupSort
public void split(@Key(group = {}) List<TextModel> textList, Result<WordModel> out) {
for (TextModel tm : textList) {
String text = tm.getTextAsString();
Report.info("split.text=" + text);
〜
}
}
演算子をジョブフロー上で呼んでいても、場合によってはAsakusaFWの最適化で呼ばれなくなる事があるらしい。
その場合でも確実にログ出力したい（最適化を無効にする）場合は、Stickyアノテーションを付けておく。（そうでない場合は付ける必要は無い）
Report出力のあるOperatorをテストする場合、何もしないとReportの初期化がされず、エラーになる。
com.asakusafw.runtime.core.Report$FailedException: Reportの初期化は行われていません。初期化プラグインが登録されていない可能性があります。 at com.asakusafw.runtime.core.Report$1.initialValue(Report.java:64) 〜
AsakusaFW 0.10.2の場合[2019-06-02]
com.asakusafw.runtime.core.Report$FailedException: Report is not initialized (report plugin may be not registered) at com.asakusafw.runtime.core.legacy.LegacyReport.lambda$static$0(LegacyReport.java:65) at java.lang.ThreadLocal$SuppliedThreadLocal.initialValue(ThreadLocal.java:284) at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:180) at java.lang.ThreadLocal.get(ThreadLocal.java:170) at com.asakusafw.runtime.core.legacy.LegacyReport.info(LegacyReport.java:90) at com.asakusafw.runtime.core.legacy.LegacyReport$1.info(LegacyReport.java:44) at com.asakusafw.runtime.core.Report.info(Report.java:70) 〜
Operatorのテストクラスで（OperatorTestEnvironmentを使って）Reportを初期化してやる必要がある。
import org.junit.Rule; import com.asakusafw.testdriver.OperatorTestEnvironment;
public class WordCountOperatorTest {
@Rule
public OperatorTestEnvironment environment = new OperatorTestEnvironment();
@Test
public void testSplit() {
WordCountOperatorImpl operator = new WordCountOperatorImpl();
〜
}
}
Report APIの設定が足りないと、「com.asakusafw.runtime.core.Report$FailedException:
Report is not initialized (report plugin may be not registered)」の例外が発生する。[2013-09-13]
この例外が出た場合、asakusa-resources.xmlが無いか、あってもReportクラスの定義が無いと思われる。
（なお、新しいバージョンのAsakusaFWでは（明示的にクラスを指定したい場合を除いて）これらの設定は不要らしい。[2019-06-02]）
〜 <property> <name>com.asakusafw.runtime.core.Report.Delegate</name> <value>com.asakusafw.runtime.report.CommonsLoggingReport</value> </property> 〜
もしくは、OperatorTestEnvironmentに対してReportクラスを設定してやる。
public class WordCountOperatorTest {
@Rule
public OperatorTestEnvironment environment = new OperatorTestEnvironment();
@Test
public void testSplit() {
environment.configure(
"com.asakusafw.runtime.core.Report.Delegate",
"com.asakusafw.runtime.report.CommonsLoggingReport");
environment.reload();
WordCountOperatorImpl operator = new WordCountOperatorImpl();
〜
}
}
Reportというクラスには、com.asakusafw.runtime.core.Report以外にcom.asakusafw.bridge.api.Reportというクラスがある。[2019-06-02]
メソッドは同一なので、誤って後者のクラスを使ってもOperatorクラスのコンパイルは出来るが、
Operatorのテストを実行すると（OperatorTestEnvironmentがちゃんと定義されていても）以下のような例外が発生する。
java.lang.IllegalStateException: current session has not been started at com.asakusafw.bridge.broker.ResourceBroker.getCurrentSession(ResourceBroker.java:182) at com.asakusafw.bridge.broker.ResourceBroker.get(ResourceBroker.java:140) at com.asakusafw.bridge.api.ReportAdapter.lambda$delegate$0(ReportAdapter.java:109) at com.asakusafw.bridge.broker.ResourceCacheStorage.get(ResourceCacheStorage.java:53) at com.asakusafw.bridge.api.ReportAdapter.delegate(ReportAdapter.java:109) at com.asakusafw.bridge.api.Report.info(Report.java:51) 〜
com.asakusafw.bridge.api.ReportはAsakusaFW内部のクラスであり、プログラマーから見えないのが望ましいらしい。
こういう為にJava9でモジュールシステムが導入されたんだろうなぁ。
この問題を防ぐ為、AsakusaFW 0.10.3ではcom.asakusafw.bridge.api.Reportクラスはdeprecatedになった。[2019-06-14]
（importすると警告が出る）
（このdeprecatedの意味は、（廃止されるからではなく）ユーザーが使うべきものではない、という意味）
ジョブフローやバッチのテストではReportは自動的に初期化されるので、特に何もしなくてよい。
Loggingアノテーションを使って、ログ出力用の演算子（Operator）を作ることが出来る。→ロギング演算子（@Logging）
import com.asakusafw.vocabulary.operator.Logging;
public abstract class WordCountOperator {
〜
@Logging(Logging.Level.INFO)
public String mylog(WordModel wm) {
return "word=" + wm.getWordAsString();
}
}
Loggingアノテーションを付けたメソッドは、戻り値はStringになる。
つまりログに出力するメッセージを返すようにする。
@Override
protected void describe() {
Split split = operator.split(this.in);
operator.mylog(split.out);
Count count = operator.count(split.out);
out.add(count.out);
}
split.outの型は、Source<WordModel>。つまりmylogの引数の型であるWordModelと一致している。
public class WordCountOperatorTest {
〜
@Test
public void testLogging() {
WordCountOperatorImpl operator = new WordCountOperatorImpl();
WordModel wm = new WordModel();
wm.setWordAsString("www");
String r = operator.mylog(wm);
assertThat(r, is("word=www"));
}
}
Loggingアノテーションを使った演算子は、ログ出力時にはReportクラスの機構を使っているらしいが、
オペレーターのテストとしてはReportの初期化をする必要は無い。
（演算子としては、文字列を返すだけだから）
Asakusa Framework0.5.1から、TestDriverにおいて、データフローのトレースログを出力できるようになった。[2013-07-27]
ジョブフロー（やバッチ）のテスト時に、演算子（OperatorやFlowpart）の入出力ポートを指定すると、その入出力に使われたデータがログに出力される。
Operatorのメソッド内にReportログ出力を埋め込んだりロギング演算子をフローに追加したりすれば 自分でデータをログ出力できるが、
トレース機能では、プログラム（OperatorやJobflow・Flowpart）を変更せずに 外部からログ出力箇所を指定できる。
public class CategorySummaryJobTest {
private void run(String dataSet, long errors) {
JobFlowTester tester = new JobFlowTester(getClass());
〜
tester.addInputTrace(CategorySummaryOperator.class, "checkStore", "info");
tester.addOutputTrace(CategorySummaryOperator.class, "checkStore", "missed");
// tester.addInputTrace(HogeFlowpart.class, "salesDetail");
// tester.addOutputTrace(HogeFlowpart.class, "errorRecord");
tester.runTest(CategorySummaryJob.class);
}
}
addInputTrace()で演算子へのデータ入力箇所、addOutputTrace()で演算子からのデータ出力箇所を指定する。
Operatorの場合は、自分でコーディングしたOperatorクラスとメソッド名および入出力ポート名を指定する。
Flowpartの場合はFlowpartクラスと入出力ポート名を指定する。（Flowpartの場合、メソッド名は常にcreateだから指定する必要は無い）
（なお、コア演算子は指定できない）
入力ポート名を知るには、フロークラス内で該当演算子の引数を確認する。
例えば「CheckStore checkStore = operators.checkStore(〜);」のメソッド部分にマウスを当てると、ツールチップで「Parameters:
info 店舗マスタ sales 売上明細」と表示される。これで、入力ポートはinfoとsalesであることが分かる。
出力ポート名を知るには、フロークラス内の該当演算子の戻り値のクラスのフィールドを確認する。
例えば「CheckStore checkStore = operators.checkStore(〜);」では、CheckStoreのフィールドとしてfoundとmissedがある。これで、出力ポートはfoundとmissedであることが分かる。
ただ、個人的には、適当なポート名を指定して実行し、エラーメッセージを見る方が早いと思う(爆)
java.lang.IllegalStateException: java.io.IOException: 実行計画の作成に失敗しました ([グラフの書き換えに失敗しました (トレースで指定された入力ポート"zzzin"は存在しません。 指定可能な入力ポートは[info, sales]です (com.example.operator.CategorySummaryOperatorFactory#checkStore(...))) ([])]) java.lang.IllegalStateException: java.io.IOException: 実行計画の作成に失敗しました ([グラフの書き換えに失敗しました (トレースで指定された出力ポート"zzzout"は存在しません。 指定可能な出力ポートは[found, missed]です (com.example.operator.CategorySummaryOperatorFactory#checkStore(...))) ([])])
ちなみに、指定できるのは演算子クラスのメソッド名・ポート名なので、一つのフロー内で同一演算子を複数使っていた場合、フロー内のどの部分かまでは特定できない。
13/07/27 08:43:07 INFO trace.TraceDriverLifecycleManager: The configuration key "com.asakusafw.runtime.trace.TraceActionFactory" is not set, we use "com.asakusafw.runtime.trace.TraceReportActionFactory"
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0001, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0002, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0003, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0004, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0005, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0006, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0007, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0008, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0009, storeName=DUMMY}
13/07/27 08:43:07 INFO report.CommonsLoggingReport: [TRACE-0001] 1@com.example.operator.CategorySummaryOperator#checkStore.INPUT.info:com.example.modelgen.dmdl.model.StoreInfo: {class=store_info, storeCode=0010, storeName=DUMMY}
13/07/27 08:43:10 INFO report.CommonsLoggingReport: [TRACE-0002] 2@com.example.operator.CategorySummaryOperator#checkStore.OUTPUT.missed:com.example.modelgen.dmdl.model.SalesDetail: {class=sales_detail, salesDateTime=2011-01-01 00:00:00, storeCode=9999, itemCode=0001, amount=1, unitSellingPrice=null, sellingPrice=200, fileName=file:/home/hishidama/target/testing/directio/sales/__testing__/__testing__.csv}
トレースログはReport APIを使用してINFOレベルとして出力されるので、「INFO
report.CommonsLoggingReport」として表示される。
データモデルクラスのプロパティーが全て表示されるので、1行がかなり横長になってしまう＾＾；
「TRACE-0001」の数値は、トレース箇所に付けられたID。たぶんaddInputTrace/addOutputTraceする度に採番される。
「@」の直前の番号も同じIDだと思われる。
「@」の直後は、トレース箇所。演算子クラス名#メソッド名.INPUT/OUTPUT.ポート名。
最後に、データモデルのクラス名とデータそのもの。