Mono.Cecilで黒魔術を行う。〜トレースログをインジェクション編〜
.net開発者のみなさん。
時々、こんな事を思ったりしませんか？
あー、全部のメソッドをフックして開始時と終了時にトレースログ吐きたいー。
特に、
運用チーム > ﾊﾞｸﾞｶﾞｰ、ﾊﾞｸﾞｶﾞｰ
ボク > どういったオペレーションで発生したのでしょうか？
運用チーム > ﾊﾞｸﾞｶﾞｰ、ﾊﾞｸﾞｶﾞｰ
ボク > なにそれ怖い。
って状況の時に。
AOPの範疇なのでしょうが、そんな設計が全くされていないソフトウェアが目の前にあるのが現状でしょう。
今から全部のメソッドにログを仕込む？
・・・無理。
今回はそんな時に使える黒魔術をお教えしましょう。
※黒魔術なので、まっとうにコードを書きたい人は見ない方が良いかもしれません。
黒魔術をするために、Mono.Cecilというライブラリを使用します。
まず、Monoとはいったい何なのかというと、
マルチプラットフォームで.NET Freamworkを動かすという狂気じみたプロジェクトであります。
私は、普段mac使いなので良くお世話になって・・・・いません。(homebrewがエラー吐くんだもん)
このMonoを利用して、C#でiOSを作っちゃうXamarinなんてのもあります。
で、このMonoの一部にCecilというライブラリがある。
Cecilは一体何なのかというと、大雑把に言ってしまえば
既存のアセンブリを読み込む
↓
任意のIL(中間言語)を注入
↓
アセンブリを出力
が行えるライブラリです。
ILとは何ぞやというと、奥深く深淵なる世界なので、
自分で調べるか、良くわかんないけどとりあえず続きを読むか考えて下さい。
今回やろうとしていることは、
- 既存のexe(dllでも可)を読み込む
- 全てのメソッドを抽出する
- メソッドの先頭にトレースログを出力するコードをインジェクションする
- 引数がある場合は、引数の名前と値をログ出力する(暫定)コードをインジェクションする
- メソッドの終了時にトレースログを出力するコードをインジェクションする
- exeを上書きする
ってな感じです。
ログ出力にはlog4netを利用します。
環境は
Windows7のVisual Studio Express 2012 for Windows Desktopです。
では、まずインジェクションされる側のexeを用意しましょう。
TestAppという名前のWindowsフォームアプリケーションを作成しましょう。
そして、
ツール > ライブラリパッケージマネージャ > ソリューションのNugetパッケージの管理
の右上のテキストボックスに log4net と入れてGetしましょう。
Getしたら、ソリューションエクスプローラから
TestApp > Properties > AssemblyInfo.cs
を選択して、一番下に
[assembly: log4net.Config.XmlConfigurator(Watch = true)]
と追加して下さい。
追加したら、App.configを開いて、
適当にlog4netの設定をします。
<?xml version="1.0" encoding="utf-8" ?> <configuration> <configSections> <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" /> </configSections> <startup> <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5" /> </startup> <log4net> <!-- コンソール出力用 (VS 上 [出力] ウインドウへの出力) --> <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender"> <!-- 出力文字列のフォーマット --> <layout type="log4net.Layout.PatternLayout"> <!--^「日付、スレッド、レベル、logger名、メッセージ」が出力^--> <!--^「%-5p」というのは5文字以下の場合、右側に空白を入れる設定^--> <param name="ConversionPattern" value="%d [%t] %-5p %c - %m%n"/> </layout> </appender> <!-- ファイル出力用 --> <appender name="DailyFileAppender" type="log4net.Appender.RollingFileAppender"> <!-- ログファイルの切替 { サイズ: Size, 日付: Date } --> <param name="RollingStyle" value="Date"/> <!-- ファイル名 --> <param name="File" value="log/"/> <!-- ファイル名に付加する日付パターン --> <param name="DatePattern" value="yyyyMMdd"_log.log""/> <!-- ファイル名の固定 --> <param name="StaticLogFileName" value="false"/> <!-- ファイル書き込み { 追記: true, 上書き: false } --> <param name="AppendToFile" value="true"/> <!-- 最大保存ファイル数 (古い順に削除) --> <param name="MaxSizeRollBackups" value="32"/> <!-- 出力文字列のフォーマット --> <layout type="log4net.Layout.PatternLayout"> <header type="log4net.Util.PatternString" value="[task time = "%date{HH:mm:ss,fff}"]%newline"/> <footer type="log4net.Util.PatternString" value="[/task]%newline"/> <conversionPattern value="%-5level %date{yyyy/MM/dd HH:mm:ss, fff} [%thread] %logger - %message%newline"/> </layout> <!-- 出力するログ レベルのフィルタ --> <!-- Level : Fatal, Error, Warn, Info, Debug --> <filter type="log4net.Filter.LevelRangeFilter"> <levelMin value="DEBUG"/> <levelMax value="FATAL"/> </filter> </appender> <!-- イベント ログ出力用 --> <appender name="EventLogAppender" type="log4net.Appender.EventLogAppender"> <!-- イベント ログ上のアプリケーション名 --> <applicationName value="AppName"/> <!-- 出力文字列のフォーマット --> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%-5level %date{yyyy/MM/dd_HH:mm:ss,fff} [%thread] %logger [%property{NDC}] - %message%newline"/> </layout> <!-- 出力するログ レベルのフィルタ --> <filter type="log4net.Filter.LevelRangeFilter"> <levelMin value="DEBUG"/> <levelMax value="FATAL"/> </filter> </appender> <!-- デフォルトの出力設定 --> <root> <appender-ref ref="DailyFileAppender"/> </root> </log4net> </configuration>
log4netも深遠なる世界が広がっているので、よく解らない人は調べて下さい。
今回はこれが本題では無いので・・・。
Form1にボタンを2つ設置して、ソースコードを下記のように書き換えます。
using System; using System.Windows.Forms; namespace TestApp { public partial class Form1 : Form { public Form1() { InitializeComponent(); } private void btnMethod1Call_Click(object sender, EventArgs e) { Greet("hello", "Cecil"); } private void btnMethod2Call_Click(object sender, EventArgs e) { Greet("byebye", "contextbound"); } private void Greet(string greeting, string name) { MessageBox.Show(string.Format("{0} {1}!!", greeting, name)); } } }
それから、log4netが使用できるように、
TestAppにUtilというフォルダを追加してLogging.csを追加します。
ソースは下記
namespace TestApp.Util { /// <summary> /// ログ出力クラスです。 /// </summary> internal static class Logging { internal static readonly log4net.ILog Logger = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType); } }
これで一旦、インジェクションされる側の準備は終わりです。
このコードには、ログを吐くソースコードは一切記述されていない事を確認して下さい。
では、いよいよインジェクションする側です。
後で拡張するために、インジェクター本体と、インジェクター実行は別プロジェクトで用意します。
まず、インジェクター本体
黒魔術らしく、VooDooInjectというクラスライブラリを用意します。
プロジェクトを用意したら、NugetでMono.CecilをGetしましょう。
あっさりインストールされますね。
さらに、log4netのリファレンスを取得する必要があるので、
ツール > ライブラリパッケージマネージャ > ソリューションのNugetパッケージの管理
インストール済みのパッケージからVooDooInjectにもlog4netをインストールしておきましょう。
AssemblyInfo.csとapp.confgの編集は必要ありません。
(こいつがログを吐くわけでは無いので。)
ソースを用意します。
Injector.cs
using System; using System.Collections.Generic; using System.Linq; using Mono.Cecil; using Mono.Cecil.Cil; using log4net; namespace VooDooInject { /// <summary> /// コンパイル後のアセンブリに特定のILを挿入する機能を提供します。 /// </summary> public class Injector { /// <summary> /// Type毎のConvert.ToStringキャッシュ /// </summary> private Dictionary<Type, Instruction> _dicTypeToString = new Dictionary<Type, Instruction>(); /// <summary> /// メソッドにログ出力機能をインジェクションします。 /// </summary> /// <param name="assemblyPath">インジェクション対象のアセンブリのパス</param> public void InjectMethodTraceLog(string assemblyPath, string assemblyWritePath = "") { // アセンブリを読み込む var assembly = AssemblyDefinition.ReadAssembly(assemblyPath); // 使用するメソッドのリファレンスを取得する // 文字列結合('+'オペレータが実際に呼び出しているメソッド) var concat = typeof(string).GetMethod("Concat", new[] { typeof(string), typeof(string) }); // log4netのDebug var log4Debug = typeof(ILog).GetMethod("Debug", new[] { typeof(object) }); // log4netを定義しているフィールドを取得する。 var loggingtypeDef = assembly.MainModule.Types.First(t => t.Name == "Logging"); var loggerFldRef = loggingtypeDef.Fields.First(f => f.Name == "Logger"); // log4netの静的コンストラクタはインジェクション対象外とする var log4CctrName = string.Format("System.Void {0}::.cctor()", loggingtypeDef.FullName); // 全メソッドを抽出する assembly.Modules .SelectMany(x => x.Types) .SelectMany(x => x.Methods) .ToList() .ForEach(method => { // log4netのコンストラクタは処理対象外とする if (log4CctrName == method.FullName) return; // 繰り返し使うオペコードを生成しておく var il = method.Body.GetILProcessor(); var callCon = il.Create(OpCodes.Call, method.Module.Import(concat)); var ldsfldLogger = il.Create(OpCodes.Ldsfld, loggerFldRef); var callLog4Debug = il.Create(OpCodes.Callvirt, method.Module.Import(log4Debug)); // メソッド開始時 var first = method.Body.Instructions.First(); var ldstr_Start = il.Create(OpCodes.Ldstr, "Start => " + method.FullName); il.InsertBefore(first, ldsfldLogger); // Loggerフィールドをロード il.InsertBefore(first, ldstr_Start); // 文字列をロード il.InsertBefore(first, callLog4Debug); // Logger.Debugを呼び出す // 引数の数だけ、Ldarg_nオペコードを生成する for (int i = 0; i < method.Parameters.Count; i++) { // type毎のToStringをキャッシュ化する。 var t = Type.GetType(method.Parameters[i].ParameterType.FullName); Instruction callToString = null; if (t!= null && !_dicTypeToString.TryGetValue(t, out callToString)) { var ts = typeof(Convert).GetMethod("ToString", new[] { t }); callToString = il.Create(OpCodes.Call, method.Module.Import(ts)); _dicTypeToString.Add(t, callToString); } var ldastrPrmInfo = il.Create(OpCodes.Ldstr, "\t" + method.Parameters[i].Name + ":" + method.Parameters[i].ParameterType.ToString() + " => "); il.InsertBefore(first, ldsfldLogger); // Loggerフィールドをロード il.InsertBefore(first, ldastrPrmInfo); // 文字列をロード if (t != null) { il.InsertBefore(first, il.Create(OpCodes.Ldarg, method.Parameters[i])); // パラメータをロード il.InsertBefore(first, il.Create(OpCodes.Box, method.Module.Import(t))); // Box化(Guid等の参照対策) il.InsertBefore(first, callToString); // ToStringを呼び出す il.InsertBefore(first, callCon); // 文字を結合する } il.InsertBefore(first, callLog4Debug); // Logger.Debugを呼び出す } // メソッド終了時 var ldstr_End = il.Create(OpCodes.Ldstr, "End => " + method.FullName); method.Body.Instructions .Where(i => i.OpCode == OpCodes.Ret) .ToList() .ForEach(end => { il.InsertBefore(end, ldsfldLogger); // Loggerフィールドをロード il.InsertBefore(end, ldstr_End); // 文字列をロード il.InsertBefore(end, callLog4Debug); // Logger.Debugを呼び出す }); }); // 書き込み assembly.Write(string.IsNullOrEmpty(assemblyWritePath)? assemblyPath: assemblyWritePath); } } }
インジェクター実行はVDIExcuterという名前のコンソールアプリケーションを用意します。
参照設定で、VooDooInjectを参照して下さい。
Program.cs
namespace VDIExcuter { class Program { static void Main(string[] args) { var injector = new VooDooInject.Injector(); injector.InjectMethodTraceLog("TestApp.exe"); } } }
VDIExcuterを実行すると、TestApp.exeにインジェクションが実行される仕組みです。
自動化については、次回の記事で書こうと思っています。
とりあえず、今回はTestAppの出力先をVDIExcuterのフォルダーに設定します。
ソリューションエクスプローラから
TestAppを右クリック > プロパテイ > ビルドタブ > 出力パス
に
..\VDIExcuter\bin\Debug
と入力してビルドして下さい。
これで、VDIExcuter\VDIExcuter\bin\Debugフォルダの中にTestApp.exeが出力されます。
VDIExcuter.exeとTestApp.exeが同一階層にある状態で
VDIExcuter.exeを実行しましょう。
TestApp.exeが書き換えられます。
TestApp.exeを実行してみると・・・。
VDIExcuter\VDIExcuter\bin\Debug\log
にログが出力されているはず！！
このVooDooInjectの利用は自己責任でお願いします。
因みに、引数の値を出力する部分は未完成です。
IL部分の解説はそのうちするかもしれません。
最近メタプログラミングしてる時間が、子どもと遊ぶ時間の次くらいに楽しい・・。ﾌﾋﾋ。
この黒魔術に迷える技術者が魂を売りますように・・・！！
