リフレクションを利用したロギング

「リフレクションを利用したロギング」の編集履歴（バックアップ）一覧はこちら

「リフレクションを利用したロギング」(2012/07/27 (金) 16:12:20) の最新版変更点

追加された行は緑色になります。

削除された行は赤色になります。

通常のロギング処理では、各メソッドの呼び出し開始時、終了時にそれぞれLog4jなどを利用して出力する。
場合によってはフレームワーク側である程度のログ出力制御を行なっているものもあるが、実際のモジュールでのメソッド実行や引数、返り値の確認は各モジュールにログ出力処理を組み込むことで行うことになる。

その為、リリース前（もしくは単体テスト完了時等）に不要なログ出力の抑制の為に、「単体テストの完了している各モジュールに修正を行う」事になってしまう。

これらは抽象クラスとリフレクションを利用する事で影響を最小限に収めることができる。

尚、今回はサンプルとして「抽象クラスで定義したメソッドが実行される度に、実行したメソッド、及びメソッドの引数と返り値をログ出力する」とする。
フレームワーク側で行うべき事、各モジュール側で意識して行うべき事は以下の通り。

&bold(){【フレームワーク側】}
-Proxyインスタンス経由でオブジェクトを取得する共通クラス（抽象クラスを元に実装したクラスを取得する）
-抽象クラスの各メソッドが実行された時にログ出力を行うクラス

&bold(){【各モジュール側】}
-ログ出力を行うメソッドを抽象クラスとして作成
-抽象クラスをimplementsしたメインクラスの実装
-共通のDataSetクラスを継承した、各モジュール用のDataSetクラス（※1）
※1：詳細は後述


&bold(){【Proxyインスタンス経由でオブジェクトを取得する共通クラス】}

 package test.generic;
 
 import java.lang.reflect.InvocationHandler;
 import java.lang.reflect.Proxy;
 
 public class GenericProxyFactory {
 
     public static <T> T getProxy(Class<T> intf, final T obj) {
         
         InvocationHandler handler = new LoggingHandler(obj);
         
         return (T) Proxy.newProxyInstance(
                         obj.getClass().getClassLoader(),
                         new Class[] { intf },
                         handler);
     }
 }

上記クラスを実装するだけ。
各モジュールの実装側は、通常のインスタンス生成（new ～）ではなく、上記クラス経由でオブジェクトを取得する事になる。

 AnotationTestActionInterface action = GenericProxyFactory.getProxy(
     AnotationTestActionInterface.class, new AnotationTestAction());

&bold(){【抽象クラスの各メソッドが実行された時にログ出力を行うクラス】}

実装は長いので[[こちらを参照>LoggingHandler]]
抜粋すると以下の処理がメインとなる。

     /**
      * <pre>
      * 動的Profileを利用したロギング処理
      * </pre>
      */
     @Override
     public Object invoke(Object proxy, Method method, Object[] args)
             throws Throwable {
 
         boolean logging = isLogging();
         
         if (logging) startTrace(method, args);
         
         Object ret = method.invoke(target, args);
 
         if (logging) endTrace(method, ret);
         
         return ret;
     }

GenericProxyFactory#getProxy() 経由で取得したクラスは、通常に実装したクラスと同様に使用することができる。しかし、実際に抽象クラスのメソッドが実行される度に上記のメソッドが実行される事になる。
イメージ的には以下のとおり。

 各実装モジュールのクラス
 　↓
 実装クラス（実際には抽象クラス）のメソッド
 　↓
 LoggingHandler#invoke()
 　↓
 実装クラスのメソッド
 　↓
 LoggingHandler#invoke()
 　↓
 実装クラス（実際には抽象クラス）のメソッド
 　↓
 各実装モジュールのクラス

といった感じで、「普通に実装、実行したはずがいつの間にかログ出力処理が間に挟まっている」。
非常に便利に思えるが『割と重い』という話もある（未検証）なので、要所要所で使う程度が望ましいと思われる。

&bold(){【ログ出力を行うメソッドを抽象クラスとして作成】}

必要に応じてメソッド定義を行う。
今回はサンプルなのでメインの実行処理だけ。

--Action抽象クラス
 package test.action;
 
 import test.AnotationTestDataSet;
 
 public interface AnotationTestActionInterface {
 
     AnotationTestDataSet exec();
 }

--Business抽象クラス
 package test.business;
 
 import java.util.Map;
 
 import test.AnotationTestDataSet;
 
 public interface AnotationTestBusinessInterface {
 
     boolean exec(AnotationTestDataSet dataSet, Map<String, String> map);
 }

&bold(){【抽象クラスをimplementsしたメインクラスの実装】}

割と長いのと、普通のテスト用ロジックなので割愛。
詳細はリンク先を参照。

--[[Actionクラス>AnotationTestAction]]
--[[Businessクラス>AnotationTestBusiness]]

&bold(){【共通のDataSetクラスを継承した、各モジュール用のDataSetクラス】}

※1。
なぜ共通のDataSetクラスを継承する必要があるのか、と言うと……
引数、返り値のDataSetクラスのSuperクラスを確認し、特定クラスの場合にのみDataSetクラスと判断、フィールド変数の解析、及びログ出力を行なっている為。
Seaser2やStruts等、フレームワークを正しく使用してあげればこんなことも必要なく、また、各ActionやBusinessで定義した抽象クラスも必要ないと思われる。
このあたりは実際に使用するフレームワークがどの程度可能なのかを踏まえた上で判断するべき。

ちなみにこちらの実装も割りと長い＆普通のBeanなので割愛。

-[[DataSetのSuperクラス>AbstractAnotationDataSet]]
-[[DataSetクラス>AnotationTestDataSet]]

&bold(){【メイン処理の実装とログ出力】}

以上で各モジュールと共通処理の実装は完了。
後は下記のようなメイン処理を実装し、ログ出力をしてみる。

 package test;
 
 import java.util.HashMap;
 import java.util.Map;
 
 import test.action.AnotationTestAction;
 import test.action.AnotationTestActionInterface;
 import test.business.AnotationTestBusiness;
 import test.business.AnotationTestBusinessInterface;
 import test.generic.GenericProxyFactory;
 import logger.TraceLogger;
 
 @TraceLogger
 public class AnotationTestMain {
 
     /**
      * 多分メインクラス
      * @param args
      */
     public static void main(String[] args) {
 
         // アクション層
         AnotationTestActionInterface action = GenericProxyFactory.getProxy(
                 AnotationTestActionInterface.class, new AnotationTestAction());
 
         AnotationTestDataSet dataSet = action.exec();
 
         // 内部ロジック的な何か
         Map map = GenericProxyFactory.getProxy(Map.class, new HashMap<String, String>());
         
         map.put("test", "test");
         map.put("test2", "test2");
         
         map.containsKey("test");
         
         map.get("test2");
         
         // DataSetの中身を変えてしまいましょう。
         dataSet.setCode(888);
         
         dataSet.setName(dataSet.getName() + "　ただし、演算子での文字列結合は非常に遅いので厳禁！" );
         
         // ビジネスロジック層
         AnotationTestBusinessInterface business = GenericProxyFactory.getProxy(
                 AnotationTestBusinessInterface.class, new AnotationTestBusiness());
 
         business.exec(dataSet, map);
         
     }
 }

以上。
こちらを実行すると、以下の様なログ出力となる。

 AnotationTestActionコンストラクタ
 ENTER:test.action.AnotationTestAction#exec() class test.AnotationTestDataSet
 test_test
 RETURN:test.action.AnotationTestAction#exec() test.AnotationTestDataSet{int code=9999,java.lang.String name=動的Profileでのロギング確認,java.util.Date date=Fri Jul 27 10:48:46 JST 2012,java.math.BigDecimal money=1234567890}
 AnotationTestBusinessコンストラクタ
 ENTER:test.business.AnotationTestBusiness#exec(test.AnotationTestDataSet{int code=888,java.lang.String name=動的Profileでのロギング確認　ただし、演算子での文字列結合は非常に遅いので厳禁！,java.util.Date date=Fri Jul 27 10:48:46 JST 2012,java.math.BigDecimal money=1234567890},{test=test, test2=test2}) boolean
 test_test
 RETURN:test.business.AnotationTestBusiness#exec() true

"ENTER:"以降の内容がメソッド実行時のログ。実行対象となるクラス、メソッド名の出力と引数の内容がログ出力されている。
"RETURN:"以降の内容がメソッド終了時のログ。実行したクラス、メソッドと返り値の内容がログ出力されている。
これらを出力するだけで、エラー発生時の処理の流れや引数、返り値の内容確認が容易になる。

また、上記のログは[[TraceLogger]]という独自のアノテーションが記載されているクラスの抽象メソッドのみ、ログ出力するようになっている。
この条件を除外すると、以下の様なログになる。

 AnotationTestActionコンストラクタ
 ENTER:test.action.AnotationTestAction#exec() class test.AnotationTestDataSet
 test_test
 RETURN:test.action.AnotationTestAction#exec() test.AnotationTestDataSet{int code=9999,java.lang.String name=動的Profileでのロギング確認,java.util.Date date=Fri Jul 27 16:09:07 JST 2012,java.math.BigDecimal money=1234567890}
 ENTER:java.util.HashMap#put(test,test) class java.lang.Object
 RETURN:java.util.HashMap#put() null
 ENTER:java.util.HashMap#put(test2,test2) class java.lang.Object
 RETURN:java.util.HashMap#put() null
 ENTER:java.util.HashMap#containsKey(test) boolean
 RETURN:java.util.HashMap#containsKey() true
 ENTER:java.util.HashMap#get(test2) class java.lang.Object
 RETURN:java.util.HashMap#get() test2
 AnotationTestBusinessコンストラクタ
 ENTER:java.util.HashMap#toString() class java.lang.String
 RETURN:java.util.HashMap#toString() {test=test, test2=test2}
 ENTER:test.business.AnotationTestBusiness#exec(test.AnotationTestDataSet{int code=888,java.lang.String name=動的Profileでのロギング確認　ただし、演算子での文字列結合は非常に遅いので厳禁！,java.util.Date date=Fri Jul 27 16:09:07 JST 2012,java.math.BigDecimal money=1234567890},{test=test, test2=test2}) boolean
 test_test
 RETURN:test.business.AnotationTestBusiness#exec() true

このように、TraceLoggerを設定しているクラス・メソッド以外でもGenericProxyFactory#getProxy() 経由で取得した抽象クラスを要するクラスであればなんでも出力する。

このあたりのアノテーションとリフレクションを利用した応用は後日。

&bold(){【参考資料】}
-[[リフレクションとは？>http://muimi.com/j/reflection/#WhatIs]]

通常のロギング処理では、各メソッドの呼び出し開始時、終了時にそれぞれLog4jなどを利用して出力する。
場合によってはフレームワーク側である程度のログ出力制御を行なっているものもあるが、実際のモジュールでのメソッド実行や引数、返り値の確認は各モジュールにログ出力処理を組み込むことで行うことになる。

その為、リリース前（もしくは単体テスト完了時等）に不要なログ出力の抑制の為に、「単体テストの完了している各モジュールに修正を行う」事になってしまう。

これらは抽象クラスとリフレクションを利用する事で影響を最小限に収めることができる。

尚、今回はサンプルとして「抽象クラスで定義したメソッドが実行される度に、実行したメソッド、及びメソッドの引数と返り値をログ出力する」とする。
フレームワーク側で行うべき事、各モジュール側で意識して行うべき事は以下の通り。

&bold(){【フレームワーク側】}
-Proxyインスタンス経由でオブジェクトを取得する共通クラス（抽象クラスを元に実装したクラスを取得する）
-抽象クラスの各メソッドが実行された時にログ出力を行うクラス

&bold(){【各モジュール側】}
-ログ出力を行うメソッドを抽象クラスとして作成
-抽象クラスをimplementsしたメインクラスの実装
-共通のDataSetクラスを継承した、各モジュール用のDataSetクラス（※1）
※1：詳細は後述


&bold(){【Proxyインスタンス経由でオブジェクトを取得する共通クラス】}

 package test.generic;
 
 import java.lang.reflect.InvocationHandler;
 import java.lang.reflect.Proxy;
 
 public class GenericProxyFactory {
 
     public static <T> T getProxy(Class<T> intf, final T obj) {
         
         InvocationHandler handler = new LoggingHandler(obj);
         
         return (T) Proxy.newProxyInstance(
                         obj.getClass().getClassLoader(),
                         new Class[] { intf },
                         handler);
     }
 }

上記クラスを実装するだけ。
各モジュールの実装側は、通常のインスタンス生成（new ～）ではなく、上記クラス経由でオブジェクトを取得する事になる。

 AnotationTestActionInterface action = GenericProxyFactory.getProxy(
     AnotationTestActionInterface.class, new AnotationTestAction());

&bold(){【抽象クラスの各メソッドが実行された時にログ出力を行うクラス】}

実装は長いので[[こちらを参照>LoggingHandler]]
抜粋すると以下の処理がメインとなる。

     /**
      * <pre>
      * 動的Profileを利用したロギング処理
      * </pre>
      */
     @Override
     public Object invoke(Object proxy, Method method, Object[] args)
             throws Throwable {
 
         boolean logging = isLogging();
         
         if (logging) startTrace(method, args);
         
         Object ret = method.invoke(target, args);
 
         if (logging) endTrace(method, ret);
         
         return ret;
     }

GenericProxyFactory#getProxy() 経由で取得したクラスは、通常に実装したクラスと同様に使用することができる。しかし、実際に抽象クラスのメソッドが実行される度に上記のメソッドが実行される事になる。
イメージ的には以下のとおり。

 各実装モジュールのクラス
 　↓
 実装クラス（実際には抽象クラス）のメソッド
 　↓
 LoggingHandler#invoke()
 　↓
 実装クラスのメソッド
 　↓
 LoggingHandler#invoke()
 　↓
 実装クラス（実際には抽象クラス）のメソッド
 　↓
 各実装モジュールのクラス

といった感じで、「普通に実装、実行したはずがいつの間にかログ出力処理が間に挟まっている」。
非常に便利に思えるが『割と重い』という話もある（未検証）なので、要所要所で使う程度が望ましいと思われる。

&bold(){【ログ出力を行うメソッドを抽象クラスとして作成】}

必要に応じてメソッド定義を行う。
今回はサンプルなのでメインの実行処理だけ。

--Action抽象クラス
 package test.action;
 
 import test.AnotationTestDataSet;
 
 public interface AnotationTestActionInterface {
 
     AnotationTestDataSet exec();
 }

--Business抽象クラス
 package test.business;
 
 import java.util.Map;
 
 import test.AnotationTestDataSet;
 
 public interface AnotationTestBusinessInterface {
 
     boolean exec(AnotationTestDataSet dataSet, Map<String, String> map);
 }

&bold(){【抽象クラスをimplementsしたメインクラスの実装】}

割と長いのと、普通のテスト用ロジックなので割愛。
詳細はリンク先を参照。

--[[Actionクラス>AnotationTestAction]]
--[[Businessクラス>AnotationTestBusiness]]

&bold(){【共通のDataSetクラスを継承した、各モジュール用のDataSetクラス】}

※1。
なぜ共通のDataSetクラスを継承する必要があるのか、と言うと……
引数、返り値のDataSetクラスのSuperクラスを確認し、特定クラスの場合にのみDataSetクラスと判断、フィールド変数の解析、及びログ出力を行なっている為。
Seaser2やStruts等、フレームワークを正しく使用してあげればこんなことも必要なく、また、各ActionやBusinessで定義した抽象クラスも必要ないと思われる。
このあたりは実際に使用するフレームワークがどの程度可能なのかを踏まえた上で判断するべき。

ちなみにこちらの実装も割りと長い＆普通のBeanなので割愛。

-[[DataSetのSuperクラス>AbstractAnotationDataSet]]
-[[DataSetクラス>AnotationTestDataSet]]

&bold(){【メイン処理の実装とログ出力】}

以上で各モジュールと共通処理の実装は完了。
後は下記のようなメイン処理を実装し、ログ出力をしてみる。

 package test;
 
 import java.util.HashMap;
 import java.util.Map;
 
 import test.action.AnotationTestAction;
 import test.action.AnotationTestActionInterface;
 import test.business.AnotationTestBusiness;
 import test.business.AnotationTestBusinessInterface;
 import test.generic.GenericProxyFactory;
 import logger.TraceLogger;
 
 @TraceLogger
 public class AnotationTestMain {
 
     /**
      * 多分メインクラス
      * @param args
      */
     public static void main(String[] args) {
 
         // アクション層
         AnotationTestActionInterface action = GenericProxyFactory.getProxy(
                 AnotationTestActionInterface.class, new AnotationTestAction());
 
         AnotationTestDataSet dataSet = action.exec();
 
         // 内部ロジック的な何か
         Map map = GenericProxyFactory.getProxy(Map.class, new HashMap<String, String>());
         
         map.put("test", "test");
         map.put("test2", "test2");
         
         map.containsKey("test");
         
         map.get("test2");
         
         // DataSetの中身を変えてしまいましょう。
         dataSet.setCode(888);
         
         dataSet.setName(dataSet.getName() + "　ただし、演算子での文字列結合は非常に遅いので厳禁！" );
         
         // ビジネスロジック層
         AnotationTestBusinessInterface business = GenericProxyFactory.getProxy(
                 AnotationTestBusinessInterface.class, new AnotationTestBusiness());
 
         business.exec(dataSet, map);
         
     }
 }

以上。
こちらを実行すると、以下の様なログ出力となる。

 AnotationTestActionコンストラクタ
 ENTER:test.action.AnotationTestAction#exec() class test.AnotationTestDataSet
 test_test
 RETURN:test.action.AnotationTestAction#exec() test.AnotationTestDataSet{int code=9999,java.lang.String name=動的Profileでのロギング確認,java.util.Date date=Fri Jul 27 10:48:46 JST 2012,java.math.BigDecimal money=1234567890}
 AnotationTestBusinessコンストラクタ
 ENTER:test.business.AnotationTestBusiness#exec(test.AnotationTestDataSet{int code=888,java.lang.String name=動的Profileでのロギング確認　ただし、演算子での文字列結合は非常に遅いので厳禁！,java.util.Date date=Fri Jul 27 10:48:46 JST 2012,java.math.BigDecimal money=1234567890},{test=test, test2=test2}) boolean
 test_test
 RETURN:test.business.AnotationTestBusiness#exec() true

"ENTER:"以降の内容がメソッド実行時のログ。実行対象となるクラス、メソッド名の出力と引数の内容がログ出力されている。
"RETURN:"以降の内容がメソッド終了時のログ。実行したクラス、メソッドと返り値の内容がログ出力されている。
これらを出力するだけで、エラー発生時の処理の流れや引数、返り値の内容確認が容易になる。

また、上記のログは[[TraceLogger]]という独自のアノテーションが記載されているクラスの抽象メソッドのみ、ログ出力するようになっている。
この条件を除外すると、以下の様なログになる。

 AnotationTestActionコンストラクタ
 ENTER:test.action.AnotationTestAction#exec() class test.AnotationTestDataSet
 test_test
 RETURN:test.action.AnotationTestAction#exec() test.AnotationTestDataSet{int code=9999,java.lang.String name=動的Profileでのロギング確認,java.util.Date date=Fri Jul 27 16:09:07 JST 2012,java.math.BigDecimal money=1234567890}
 ENTER:java.util.HashMap#put(test,test) class java.lang.Object
 RETURN:java.util.HashMap#put() null
 ENTER:java.util.HashMap#put(test2,test2) class java.lang.Object
 RETURN:java.util.HashMap#put() null
 ENTER:java.util.HashMap#containsKey(test) boolean
 RETURN:java.util.HashMap#containsKey() true
 ENTER:java.util.HashMap#get(test2) class java.lang.Object
 RETURN:java.util.HashMap#get() test2
 AnotationTestBusinessコンストラクタ
 ENTER:java.util.HashMap#toString() class java.lang.String
 RETURN:java.util.HashMap#toString() {test=test, test2=test2}
 ENTER:test.business.AnotationTestBusiness#exec(test.AnotationTestDataSet{int code=888,java.lang.String name=動的Profileでのロギング確認　ただし、演算子での文字列結合は非常に遅いので厳禁！,java.util.Date date=Fri Jul 27 16:09:07 JST 2012,java.math.BigDecimal money=1234567890},{test=test, test2=test2}) boolean
 test_test
 RETURN:test.business.AnotationTestBusiness#exec() true

このように、TraceLoggerを設定しているクラス・メソッド以外でもGenericProxyFactory#getProxy() 経由で取得した抽象クラスを要するクラスであればなんでも出力する。

このあたりのアノテーションとリフレクションを利用した応用は後日。

&bold(){【参考資料】}
-[[リフレクションとは？>http://muimi.com/j/reflection/#WhatIs]]

#comment