VB のたまご

作成日: 2017/09/30, 更新日: 2017/09/30


AOPを利用して、メソッドの実行履歴を取ろう

  •  今まで .NET Remoting 系はあまり触ってきませんでしたが、これを利用したものに AOP(アスペクト指向プログラミング)というものがあり、 その概念に沿ってプログラミングすることで、タイトルのようなことができるようになるみたいですね。

  •  結構昔からある技術だったらしくて、.NET Remoting 系は得意ではなかったこともあり知りませんでした。 とりあえず、ソースと動作結果を見てみましょう。

  •  ここでは、Class1 クラスに魔法をかけるとします。属性を付与して ContextBoundObject クラスを継承します。
  • <Logging>
    Public Class Class1
        Inherits ContextBoundObject
    
        Public Sub ShowMessage(mes As String)
            Console.WriteLine(mes)
        End Sub
    
    End Class
    

  •  以下は、WinForms に Button を配置してクリックイベントを追加したものですが、コンソールアプリケーションでもOKです。 クリックイベント内でメソッドを呼び出します。
  • Public Class Form1
    
        Private Sub Button1_Click(sender As Object, e As EventArgs) Handles Button1.Click
    
            Dim obj = New Class1
            obj.ShowMessage("Hello")
    
        End Sub
    
    End Class
    

  •  すると、コンソール出力処理を書いていないのに、以下のようにメソッドの呼び出し履歴が表示されます。
  • [2017/09/29 16:10:42.295] info WindowsApplication4.Class1.ShowMessage() を実行します。
    Hello
    [2017/09/29 16:10:42.298] info WindowsApplication4.Class1.ShowMessage() を実行しました(0.2295 ミリ秒かかりました)。
    

  •  これはヤバい!もっと早く知りたかった技術です。

  •  今回は、これの作り方の紹介なのですが、勉強不足のため、どうしてこういう風に書くとこういう結果になるのか、.NET Framework 側の挙動を理解できていません。 なので、以降の内容は以下の参考サイトを VB.NET 版として書き直しただけのサンプル実装だけとなります。 興味がある方は以下のサイトや書籍などから勉強してみてください。

  •  参考
  • .NETにおいてAOPを実現する透過プロキシ
    https://techinfoofmicrosofttech.osscons.jp/index.php?.NET%E3%81%AB%E3%81%8A%E3%81%84%E3%81%A6AOP%E3%82%92%E5%AE%9F%E7%8F%BE%E3%81%99%E3%82%8B%E9%80%8F%E9%81%8E%E3%83%97%E3%83%AD%E3%82%AD%E3%82%B7
    
    学習B5デスノート
    [C#] RealProxyの使い方のサンプルコード
    http://fernweh.jp/b/csharp-realproxy-sample-code/
    
    Qiita
    C#でAOPのサンプル実装
    https://qiita.com/MakotoTaniguchi/items/f2b8a13ac21b5c56a3f1
    

  •  サンプルソース
  • GitHub
    https://github.com/sutefu7/AopTest1
    


全体構成

  •  通常は、インスタンスのメンバーを直接呼び出すのですが、この技術では間にプロキシを仲介しておいて、メンバー呼び出しはプロキシ経由で呼び出すことで実現しています。 よって、①ロギング対象のクラスを実行するクラス、②ロギング対象として作成したクラス、③ロギング属性クラス、④ロギングプロキシクラス、の4つを作成していきます。

  •  それぞれ次のクラスに依存しているので、④→③→②→①の順番で見ていきましょう。


ロギングプロキシクラス

  •  このクラスは、メンバー呼び出しを仲介する役割となるクラスです。属性クラス内で使います。
  • Imports System.Runtime.Remoting
    Imports System.Runtime.Remoting.Messaging
    Imports System.Runtime.Remoting.Proxies
    Imports System.Runtime.Remoting.Activation
    Imports System.Runtime.Remoting.Services
    Imports System.Runtime.Serialization.Formatters.Binary
    Imports System.IO
    Imports System.Diagnostics
    
    Public Class LoggingProxy
        Inherits RealProxy
    
        Private Property Target As MarshalByRefObject = Nothing
    
        Public Sub New(obj As MarshalByRefObject, t As Type)
            MyBase.New(t)
    
            Me.Target = obj
    
        End Sub
    
        Public Overrides Function Invoke(msg As IMessage) As IMessage
    
            Dim method = TryCast(msg, IMethodCallMessage)
            Dim ret As IMethodReturnMessage = Nothing
    
            ' コンストラクタを実行する場合
            If TypeOf method Is IConstructionCallMessage Then
    
                Dim constructor = TryCast(method, IConstructionCallMessage)
                Dim realProxy = RemotingServices.GetRealProxy(Me.Target)
                ret = realProxy.InitializeServerObject(constructor)
    
                Dim currentProxy = TryCast(Me.GetTransparentProxy(), MarshalByRefObject)
                ret = EnterpriseServicesHelper.CreateConstructionReturnMessage(constructor, currentProxy)
                Return ret
    
            End If
    
            ' プロパティが自動生成する、ゲッターメソッド・セッターメソッドはロギング対象外
            Dim mi = method.MethodBase
            Dim isProperty = mi.DeclaringType.GetProperties().Any(
            Function(x)
                Return x.GetGetMethod() Is mi OrElse x.GetSetMethod() Is mi
            End Function)
    
            If isProperty Then
                ret = RemotingServices.ExecuteMessage(Me.Target, method)
                Return ret
            End If
    
            ' 上記以外のメソッドを実行する場合
            Dim mes = $"[{DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff")}]"
            mes &= $" info"
            mes &= $" {method.TypeName.Split(","c)(0)}"
            mes &= $".{method.MethodName}() を実行します。"
            Console.WriteLine(mes)
    
            ' 処理時間を計測しつつ、実際のメソッドを実行
            Dim watch = New Stopwatch
            watch.Start()
            ret = RemotingServices.ExecuteMessage(Me.Target, method)
            watch.Stop()
    
            ' 処理結果を確認しつつ、後続処理を進める
            If ret.Exception Is Nothing Then
    
                ' メソッド実行が正常終了した場合
                mes = $"[{DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff")}]"
                mes &= $" info"
                mes &= $" {method.TypeName.Split(","c)(0)}"
                mes &= $".{method.MethodName}() を実行しました({watch.Elapsed.TotalMilliseconds} ミリ秒かかりました)。"
                Console.WriteLine(mes)
    
            Else
    
                ' メソッド実行中に例外エラーが発生した場合
                mes = $"[{DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff")}]"
                mes &= $" err "
                mes &= $" {method.TypeName.Split(","c)(0)}"
                mes &= $".{method.MethodName}() を実行中に例外エラーが発生しました。詳細は以下のファイルを参照してください。" & vbNewLine
    
                Dim mcFile = ""
                Dim mrFile = ""
                OutputData(method, ret, mcFile, mrFile)
                mes &= $"  ・{mcFile}" & vbNewLine
                mes &= $"  ・{mrFile}" & vbNewLine
                mes &= vbNewLine
                Console.WriteLine(mes)
    
            End If
    
            Return ret
    
    
            ' 以下のように、より細かく実行時のデータを取得できる
    
            '' 渡された引数値を取得
            'If 0 < method.ArgCount Then
    
            '    For i As Integer = 0 To method.ArgCount - 1
            '        Dim argumentName = method.GetInArgName(i)
            '        Dim argumentValue = method.GetInArg(i)
            '    Next
    
            'End If
    
            '' セットした結果が入った引数値を取得(ByRef など)
            'If 0 < ret.ArgCount Then
    
            '    For i As Integer = 0 To ret.ArgCount - 1
            '        Dim argumentName = ret.GetOutArgName(i)
            '        Dim argumentValue = ret.GetOutArg(i)
            '    Next
    
            'End If
    
            '' 処理中に例外エラーが発生した場合は、Exception が格納される
            'Dim ex = ret.Exception
    
            '' 戻り値がある場合、戻り値が格納される。無い場合は "System.Void"
            'Dim returnValue = ret.ReturnValue
    
        End Function
    
        Private Sub OutputData(method As IMethodCallMessage, ret As IMethodReturnMessage, ByRef mcFile As String, ByRef mrFile As String)
    
            ' IMethodCallMessage オブジェクトを出力
            Dim datName = DateTime.Now.ToString("yyyyMMdd_HHmmss_fff") & $"_{method.MethodName}"
            mcFile = datName & "_MethodCall.mcdata"
            mcFile = Path.GetFullPath(mcFile)
    
            Using stream = New FileStream(mcFile, FileMode.CreateNew, FileAccess.Write)
                Dim formatter = New BinaryFormatter
                formatter.Serialize(stream, method)
            End Using
    
            ' IMethodReturnMessage オブジェクトを出力
            mrFile = datName & "_MethodReturn.mrdata"
            mrFile = Path.GetFullPath(mrFile)
    
            Using stream = New FileStream(mrFile, FileMode.CreateNew, FileAccess.Write)
                Dim formatter = New BinaryFormatter
                formatter.Serialize(stream, ret)
            End Using
    
        End Sub
    
    End Class
    
    

  •  長々と書いてしまったので見づらいですね。 ポイントは RealProxy クラスを継承して、Invoke メソッドをオーバーライドして、メンバーが呼び出されたときの処理を実装していく点です。 コンストラクタの実行方法はこのように書くのが定石?みたいです。


ロギング属性クラス

  •  このクラスは、この属性を付与したクラスに対して、実行時にプロキシ経由で呼び出すように切り替える機能を提供するクラスです。
  • Imports System.Runtime.Remoting.Proxies
    
    <AttributeUsage(AttributeTargets.Class)>
    Public Class LoggingAttribute
        Inherits ProxyAttribute
    
        Public Sub New()
    
        End Sub
    
        Public Overrides Function CreateInstance(serverType As Type) As MarshalByRefObject
    
            Dim obj = MyBase.CreateInstance(serverType)
            Dim proxy = New LoggingProxy(obj, serverType)
            Return TryCast(proxy.GetTransparentProxy(), MarshalByRefObject)
    
        End Function
    
    End Class
    
    

  •  インスタンス生成時、プロキシを生成して返却します。具体的な処理内容はプロキシクラスを参照してください。


ロギング対象として作成したクラス

  •  今回実験対象となるクラスです。VB.NET では多重継承はできない仕様なので、(Form クラスを継承した画面クラスに対して ContextBoundObject クラスを継承することはできないので)画面クラスには適用できません。 となると、ロジック、またはデータストレージアクセス担当となるクラスに対して適用できるのかなと勝手に思いました。
  • ' 属性付与と ContextBoundObject を継承したクラス
    ' 必要な処理は属性内で完結しているため、クラス内には通常定義のみでOK
    
    <Logging>
    Public Class Class1
        Inherits ContextBoundObject
    
        ' プロパティ
        Private _Width As Integer = 0
        Public Property Width As Integer
            Get
                Return _Width
            End Get
            Set(value As Integer)
                _Width = value
            End Set
        End Property
    
        ' コンストラクタ
        Public Sub New()
    
        End Sub
    
        ' 戻り値無し
        Public Sub ShowMessage(mes As String)
            Console.WriteLine(mes)
        End Sub
    
        ' 戻り値あり
        Public Function Plus(i1 As Integer, i2 As Integer) As Integer
            Return i1 + i2
        End Function
    
        ' ByRef 引数あり
        Public Function GetFirstAndSecond(i1 As Integer, ByRef i2 As Integer) As Integer
            i2 = 12
            Return i1 * 2
        End Function
    
        ' 処理中に例外エラー発生(i2 が 0 の場合、DivideByZeroException)
        Public Function Divide(i1 As Integer, i2 As Integer) As Integer
            Return CInt(i1 / i2)
        End Function
    
        ' 複雑な引数で、例外エラー発生(i2 が null で、InvalidCastException)
        Public Sub Work(ds As DataSet)
    
            Dim i1 = ds.Tables(0).Rows(0).Field(Of Integer)("First")
            Dim i2 = ds.Tables(0).Rows(0).Field(Of Integer)("Second")
            Dim i3 = i1 / i2
            Console.WriteLine(i3)
    
        End Sub
    
    End Class
    
    

  •  このように、処理内では特別な処理は必要ありません。 デバッグ出力用の処理、例えば Console.WriteLine() が多用していて、本来の業務コードが見づらくなってしまうことが無いので、 思わず万歳三唱してしまいますね。


ロギング対象のクラスを実行するクラス

  •  ここでは、WinForms に Button を配置してクリックイベント時に実験してみましょう。 普段と同じように、Class1 クラスを扱うだけでOKです。
  • ' アスペクト指向プログラミングのサンプル
    ' メンバー呼び出しを直接呼び出すのではなく、プロキシ経由で間接的に呼び出すように作ることで、
    ' メンバー呼び出し前後に任意の処理を組み込んだり、引数や戻り値を操作できるようになる
    ' 
    ' これを利用して、メソッド実行の呼び出し履歴を表示することができる
    ' また、例外エラー発生時、メソッド情報をファイル出力することで、後から再現実行することができる
    
    '.NETにおいてAOPを実現する透過プロキシ
    'https://techinfoofmicrosofttech.osscons.jp/index.php?.NET%E3%81%AB%E3%81%8A%E3%81%84%E3%81%A6AOP%E3%82%92%E5%AE%9F%E7%8F%BE%E3%81%99%E3%82%8B%E9%80%8F%E9%81%8E%E3%83%97%E3%83%AD%E3%82%AD%E3%82%B7
    
    '学習B5デスノート
    '[C#] RealProxyの使い方のサンプルコード
    'http://fernweh.jp/b/csharp-realproxy-sample-code/
    
    'Qiita
    'C#でAOPのサンプル実装
    'https://qiita.com/MakotoTaniguchi/items/f2b8a13ac21b5c56a3f1
    
    ' 何でもできるわけではなく、以下の2点に該当するクラスのみできる
    '  ・Proxy 経由で実行するための属性を付ける
    '  ・ContextBoundObject クラスを継承する
    ' 属性を付与するだけなら簡単なのだが、ContextBoundObject クラスを継承しないといけない制限があるので、
    ' VB.NET では多重継承はできない仕様なので、製品プロダクトへの組み込みは厳しいかも(すでに何らかの基底クラスを継承していると思うので)
    ' また、プロキシ経由での実行となるので、処理速度が遅くなる
    
    
    
    Public Class Form1
    
        Private Sub Button1_Click(sender As Object, e As EventArgs) Handles Button1.Click
    
            Dim obj = New Class1
    
            ' テスト1
            obj.Width = 12
            Console.WriteLine(obj.Width)
    
            ' テスト2
            obj.ShowMessage("Hello")
    
            ' テスト3
            Dim x = obj.Plus(1, 2)
    
            ' テスト4
            Dim i = 0
            x = obj.GetFirstAndSecond(2, i)
    
            ' テスト5
            Try
                Dim z = obj.Divide(5, 0)
            Catch ex As Exception
    
            End Try
    
            ' テスト6
            Try
    
                Dim ds = New DataSet
                ds.Tables.Add("aaa")
                ds.Tables(0).Columns.Add("First", GetType(Integer))
                ds.Tables(0).Columns.Add("Second", GetType(Integer))
                ds.Tables(0).Rows.Add(New Object() {1, Nothing})
                obj.Work(ds)
    
            Catch ex As Exception
    
            End Try
    
    
        End Sub
    
    End Class
    
    


出力結果

  •  動かしただけで、以下のようにメンバー呼び出し(今回はメソッドのみ)の履歴が表示されるようになりました。 これでバグ調査の他、プログラム理解の補助に役立ちそうです!
  • 12
    [2017/09/29 16:10:42.295] info WindowsApplication4.Class1.ShowMessage() を実行します。
    Hello
    [2017/09/29 16:10:42.298] info WindowsApplication4.Class1.ShowMessage() を実行しました(0.2295 ミリ秒かかりました)。
    [2017/09/29 16:10:42.298] info WindowsApplication4.Class1.Plus() を実行します。
    [2017/09/29 16:10:42.298] info WindowsApplication4.Class1.Plus() を実行しました(0.2075 ミリ秒かかりました)。
    [2017/09/29 16:10:42.298] info WindowsApplication4.Class1.GetFirstAndSecond() を実行します。
    [2017/09/29 16:10:42.298] info WindowsApplication4.Class1.GetFirstAndSecond() を実行しました(0.2285 ミリ秒かかりました)。
    [2017/09/29 16:10:42.298] info WindowsApplication4.Class1.Divide() を実行します。
    'WindowsApplication4.vshost.exe' (CLR v4.0.30319: WindowsApplication4.vshost.exe): 'C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\mscorlib.resources\v4.0_4.0.0.0_ja_b77a5c561934e089\mscorlib.resources.dll' が読み込まれました。モジュールがシンボルなしでビルドされました。
    例外がスローされました: 'System.OverflowException' (WindowsApplication4.exe の中)
    例外がスローされました: 'System.OverflowException' (mscorlib.dll の中)
    [2017/09/29 16:10:46.461] err  WindowsApplication4.Class1.Divide() を実行中に例外エラーが発生しました。詳細は以下のファイルを参照してください。
      ・c:\~\bin\Debug\20170929_161046_462_Divide_MethodCall.mcdata
      ・c:\~\bin\Debug\20170929_161046_462_Divide_MethodReturn.mrdata
    
    
    'WindowsApplication4.vshost.exe' (CLR v4.0.30319: WindowsApplication4.vshost.exe): 'C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\System.Numerics\v4.0_4.0.0.0__b77a5c561934e089\System.Numerics.dll' が読み込まれました。シンボルの読み込みをスキップしました。モジュールは最適化されていて、デバッグ オプションの [マイ コードのみ] 設定が有効になっています。
    'WindowsApplication4.vshost.exe' (CLR v4.0.30319: WindowsApplication4.vshost.exe): 'C:\WINDOWS\Microsoft.Net\assembly\GAC_MSIL\System.Data.DataSetExtensions.resources\v4.0_4.0.0.0_ja_b77a5c561934e089\System.Data.DataSetExtensions.resources.dll' が読み込まれました。モジュールがシンボルなしでビルドされました。
    例外がスローされました: 'System.InvalidCastException' (System.Data.DataSetExtensions.dll の中)
    [2017/09/29 16:10:46.503] info WindowsApplication4.Class1.Work() を実行します。
    例外がスローされました: 'System.InvalidCastException' (mscorlib.dll の中)
    [2017/09/29 16:10:47.917] err  WindowsApplication4.Class1.Work() を実行中に例外エラーが発生しました。詳細は以下のファイルを参照してください。
      ・c:\~\bin\Debug\20170929_161047_917_Work_MethodCall.mcdata
      ・c:\~\bin\Debug\20170929_161047_917_Work_MethodReturn.mrdata
    


後からゆっくり現象再現させて、デバッグ調査する

  •  さらにさらに、上記ではメソッドの実行中に例外エラーが発生した場合、メソッド情報とエラー情報をファイル出力させています。 これは、現象が発生したユーザー側のパソコンから出して、開発側のパソコンに持ってきて、バグ調査できることを意味しています。

  •  現象再現するプログラムは、コンソールアプリケーションとして別プロジェクトで作成しています。
  • Imports System.IO
    Imports System.Reflection
    Imports System.Runtime.Remoting.Messaging
    Imports System.Runtime.Serialization.Formatters.Binary
    Imports System.Text
    
    ' ファイル出力された2つのデータファイルを読み込んで、
    ' 例外エラーを再現実行するサンプル
    
    Module Module1
    
        Sub Main()
    
            ' 自動読み込みできなかった dll を読み込むための措置(複雑な構成のプログラムなら必要なのかも)
            AddHandler AppDomain.CurrentDomain.AssemblyResolve, AddressOf CurrentDomain_AssemblyResolve
    
            ' 取得したメソッド情報を読み込む
            Dim datFiles = Directory.GetFiles(AppDomain.CurrentDomain.BaseDirectory)
            Dim method As IMethodCallMessage = Nothing
            Dim ret As IMethodReturnMessage = Nothing
    
            For Each datFile In datFiles
    
                If method Is Nothing AndAlso datFile.EndsWith(".mcdata") Then
    
                    Dim formatter = New BinaryFormatter
                    Dim bytes = File.ReadAllBytes(datFile)
                    Using stream = New MemoryStream(bytes)
                        method = TryCast(formatter.Deserialize(stream), IMethodCallMessage)
                    End Using
    
                End If
    
                If ret Is Nothing AndAlso datFile.EndsWith(".mrdata") Then
    
                    Dim formatter = New BinaryFormatter
                    Dim bytes = File.ReadAllBytes(datFile)
                    Using stream = New MemoryStream(bytes)
    
                        ret = TryCast(formatter.Deserialize(stream), IMethodReturnMessage)
                        Console.WriteLine("")
                        Console.WriteLine(ret.Exception.ToString())
                        Console.WriteLine("")
    
                    End Using
    
                End If
    
            Next
    
            ' 例外エラーを再現実行
            ' 受け取った引数や例外エラー直前の変数値などを見て調べることができる
            Try
    
                Dim t = Type.GetType(method.TypeName)
                Dim instance = Activator.CreateInstance(t)
                Dim returnValue = method.MethodBase.Invoke(instance, method.Args)
    
            Catch ex As Exception
    
            End Try
    
            Console.ReadKey()
    
        End Sub
    
        Function CurrentDomain_AssemblyResolve(sender As Object, e As ResolveEventArgs) As Assembly
    
            Dim asmName = Path.Combine(AppDomain.CurrentDomain.BaseDirectory, e.Name.Split(","c)(0))
            Dim asmFile = ""
    
            If File.Exists(asmName & ".dll") Then
    
                asmFile = asmName & ".dll"
                Console.WriteLine($"{asmFile} をロードします。")
                Dim asm = Assembly.LoadFrom(asmFile)
                Return asm
    
            End If
    
            If File.Exists(asmName & ".exe") Then
    
                asmFile = asmName & ".exe"
                Console.WriteLine($"{asmFile} をロードします。")
                Dim asm = Assembly.LoadFrom(asmFile)
                Return asm
    
            End If
    
            Return Nothing
    
        End Function
    
    End Module
    

  •  あらかじめ exe ファイルと同じフォルダ内に配置しておき、mcdata ファイルと mrdata ファイルを読み込んで、 例外エラーが発生するクラスをインスタンス生成して、例外エラーが発生するメソッドを実行させて調査します。 出力したファイルの他、調査対象のプログラムもデバッグ時必要となるので配置しておきます。

  •  このサンプルを考えて公開するなんて、めちゃくちゃ頭良いですよねこの方。自分もこのくらいになりたい・・・。 最後までこの記事を読んでいただき、ありがとうございました。