Over a million developers have joined DZone.
{{announcement.body}}
{{announcement.title}}

Aspect Oriented Programming in C# With RealProxy

DZone's Guide to

Aspect Oriented Programming in C# With RealProxy

This article goes through an example of implementing logging in C# using the RealProxy class.

Free Resource

Should you build your own web experimentation solution? Download this whitepaper by Optimizely to find out.

Introduction

Aspect Oriented Programming (AOP) is a very powerful approach to avoid boilerplate code and archive better modularity. The main idea is to add behavior (advice) to the existing code without making any changes in the code itself. In Java, this idea was implemented in the AspectJ and Spring frameworks. There are PostSharp (not free), NConcern, and some other frameworks (not very popular and easy to use) to do almost the same thing in .NET.

It is also possible to use a RealProxy class to implement AOP. You can find some examples on how to do this:

Example1: Aspect-Oriented Programming: Aspect-Oriented Programming with the RealProxy Class  

Example2: MSDN.

Unfortunately, these examples have some significant drawbacks. Example1 does not support out parameters. Example2 has limitations. A Decorated class should be inherited from MarshalByRefObject (it could be a problem if it is not your class). Also, both examples do not support asynchronous functions. Ok, technically it is supported. But I’m expecting “after” code execution AFTER task completion, and if “after” code tries to get the value of the Result property from the Task object (for example during result serialization) it makes asynchronous code synchronous (not cool).

I tried to fix the first example.

Before You Continue Reading

This article is about how to fix some problems in a solution provided by Bruno Sonnino (Example1). That article has a great explanation of how code is supposed to work and what kind of problems it solves. Please read Aspect-Oriented Programming: Aspect-Oriented Programming with the RealProxy Class first.

Solution

This solution is an example of logging implementation. The code could be found here.

Differences with original code:

  1. The extension method GetDescription was added to log Exception data (Extensions.cs).
  2. The DynamicProxy class was renamed to LoggingAdvice.
  3. The constructor was made private. The static function Create creates a class instance and returns TransparentProxy (LoggingAdvice.cs - lines 35-41). It makes it impossible to create an instance of the LoggingAdvice class, because only the proxy, created by this class, is going to be used.
  4. LoggingAdvice receives actions to log function calls and errors, and function to serialize complex type values as parameters (LoggingAdvice.cs - lines 19-20).
  5. TaskScheduler was added as an optional parameter to support task results logging using different task schedulers. TaskScheduler.FromCurrentSynchronizationContext() will be used by default (LoggingAdvice.cs - line 36).
  6. The functions LogException, LogBefore and LogAfter were added to log corresponding data (LoggingAdvice.cs - lines 150-209).
  7. Try/catch blocks were added to handle the situation when the logInfo function throws an exception (LoggingAdvice.cs - lines 53-61, 99-107).
  8. If the resulting value of the function is Task, the execution result will be logged after the task is completed (LoggingAdvice.cs - lines 69-96).
  9. Added output parameters support (LoggingAdvice.cs - lines 63, 110-111).

Extension to Log Exception (Extensions.cs)

using System;
using System.Text;

namespace AOP
{
    public static class Extensions
    {
        public static string GetDescription(this Exception e)
        {
            var builder = new StringBuilder();
            AddException(builder, e);

            return builder.ToString();
        }

        private static void AddException(StringBuilder builder, Exception e)
        {
            builder.AppendLine($"Message: {e.Message}");
            builder.AppendLine($"Stack Trace: {e.StackTrace}");
            if (e.InnerException != null)
            {
                builder.AppendLine("Inner Exception");
                AddException(builder, e.InnerException);
            }
        }
    }
}

Logging Advice (LoggingAdvice.cs)

using System;
using System.Linq;
using System.Reflection;
using System.Runtime.Remoting.Messaging;
using System.Runtime.Remoting.Proxies;
using System.Text;
using System.Threading.Tasks;

namespace AOP
{
    public class LoggingAdvice<T> : RealProxy
    {
        private readonly T _decorated;
        private readonly Action<string> _logInfo;
        private readonly Action<string> _logError;
        private readonly Func<object, string> _serializeFunction;
        private readonly TaskScheduler _loggingScheduler;

        private LoggingAdvice(T decorated, Action<string> logInfo, Action<string> logError,
            Func<object, string> serializeFunction, TaskScheduler loggingScheduler)
            : base(typeof(T))
        {
            if (decorated == null)
            {
                throw new ArgumentNullException(nameof(decorated));
            }

            _decorated = decorated;
            _logInfo = logInfo;
            _logError = logError;
            _serializeFunction = serializeFunction;
            _loggingScheduler = loggingScheduler ?? TaskScheduler.FromCurrentSynchronizationContext();
        }

        public static T Create(T decorated, Action<string> logInfo, Action<string> logError,
            Func<object, string> serializeFunction, TaskScheduler loggingScheduler = null)
        {
            var advice = new LoggingAdvice<T>(decorated, logInfo, logError, serializeFunction, loggingScheduler);

            return (T)advice.GetTransparentProxy();
        }

        public override IMessage Invoke(IMessage msg)
        {
            var methodCall = msg as IMethodCallMessage;
            if (methodCall != null)
            {
                var methodInfo = methodCall.MethodBase as MethodInfo;
                if (methodInfo != null)
                {
                    try
                    {
                        try
                        {
                            LogBefore(methodCall, methodInfo);
                        }
                        catch (Exception ex)
                        {
                            //Do not stop method execution if exception
                            LogException(ex);
                        }

                        var args = methodCall.Args;

                        var result = typeof(T).InvokeMember(
                            methodCall.MethodName,
                            BindingFlags.InvokeMethod | BindingFlags.Public | BindingFlags.Instance, null, _decorated, args);

                        if (result is Task)
                        {
                            ((Task)result).ContinueWith(task =>
                           {
                               if (task.Exception != null)
                               {
                                   LogException(task.Exception.InnerException ?? task.Exception, methodCall);
                               }
                               else
                               {
                                   object taskResult = null;

                                   if (task.GetType().IsGenericType && task.GetType().GetGenericTypeDefinition() == typeof(Task<>))
                                   {
                                       var property = task.GetType().GetProperties()
                                           .FirstOrDefault(p => p.Name == "Result");

                                       if (property != null)
                                       {
                                           taskResult = property.GetValue(task);
                                       }
                                   }

                                   LogAfter(methodCall, methodCall.Args, methodInfo, taskResult);
                               }
                           },
                           _loggingScheduler);
                        }
                        else
                        {
                            try
                            {
                                LogAfter(methodCall, args, methodInfo, result);
                            }
                            catch (Exception ex)
                            {
                                //Do not stop method execution if exception
                                LogException(ex);
                            }
                        }

                        return new ReturnMessage(result, args, args.Length,
                            methodCall.LogicalCallContext, methodCall);
                    }
                    catch (Exception ex)
                    {
                        if (ex is TargetInvocationException)
                        {
                            LogException(ex.InnerException ?? ex, methodCall);

                            return new ReturnMessage(ex.InnerException ?? ex, methodCall);
                        }
                    }
                }
            }

            throw new ArgumentException(nameof(msg));
        }

        private string GetStringValue(object obj)
        {
            if (obj == null)
            {
                return "null";
            }

            if (obj.GetType().IsPrimitive || obj.GetType().IsEnum || obj is string)
            {
                return obj.ToString();
            }

            try
            {
                return _serializeFunction?.Invoke(obj) ?? obj.ToString();
            }
            catch
            {
                return obj.ToString();
            }
        }

        private void LogException(Exception exception, IMethodCallMessage methodCall = null)
        {
            try
            {
                var errorMessage = new StringBuilder();
                errorMessage.AppendLine($"Class {_decorated.GetType().FullName}");
                errorMessage.AppendLine($"Method {methodCall?.MethodName} threw exception");
                errorMessage.AppendLine(exception.GetDescription());

                _logError?.Invoke(errorMessage.ToString());
            }
            catch (Exception)
            {
                // ignored
                //Method should return original exception
            }
        }

        private void LogAfter(IMethodCallMessage methodCall, object[] args, MethodInfo methodInfo, object result)
        {
            var afterMessage = new StringBuilder();
            afterMessage.AppendLine($"Class {_decorated.GetType().FullName}");
            afterMessage.AppendLine($"Method {methodCall.MethodName} executed");
            afterMessage.AppendLine("Output:");
            afterMessage.AppendLine(GetStringValue(result));
            var parameters = methodInfo.GetParameters();
            if (parameters.Any())
            {
                afterMessage.AppendLine("Parameters:");
                for (var i = 0; i < parameters.Length; i++)
                {
                    var parameter = parameters[i];
                    var arg = args[i];
                    afterMessage.AppendLine($"{parameter.Name}:{GetStringValue(arg)}");
                }
            }

            _logInfo?.Invoke(afterMessage.ToString());
        }

        private void LogBefore(IMethodCallMessage methodCall, MethodInfo methodInfo)
        {
            var beforeMessage = new StringBuilder();
            beforeMessage.AppendLine($"Class {_decorated.GetType().FullName}");
            beforeMessage.AppendLine($"Method {methodCall.MethodName} executing");
            var parameters = methodInfo.GetParameters();
            if (parameters.Any())
            {
                beforeMessage.AppendLine("Parameters:");
                for (var i = 0; i < parameters.Length; i++)
                {
                    var parameter = parameters[i];
                    var arg = methodCall.Args[i];
                    beforeMessage.AppendLine($"{parameter.Name}:{GetStringValue(arg)}");
                }
            }

            _logInfo?.Invoke(beforeMessage.ToString());
        }
    }
}

How to use

var decoratedInstance = LoggingAdvice<IInstanceInteface>.Create(
                instance,
                s => Console.WriteLine(“Info:” + s),
                s => Console.WriteLine(“Error:” + s),
                o => o?.ToString());

Example

Let assume that we are going to implement calculator which adds and subtracts integer numbers.

namespace AOP.Example  
{  
    public interface ICalculator  
    {  
        int Add(int a, int b);  
        int Subtract(int a, int b);  
    }  
}


namespace AOP.Example  
{  
    public class Calculator : ICalculator  
    {  
        public int Add(int a, int b)  
        {  
            return a + b;  
        }  
  
        public int Subtract(int a, int b)  
        {  
            return a - b;  
        }  
    }  
}

Is is easy. Each method has only one responsiblility.

One day some users start complaining that sometimes Add(2, 2) returns 4. You don't understand what's going on and decide to add logging. 

namespace AOP.Example  
{  
    public class CalculatorWithoutAop: ICalculator  
    {  
        private readonly ILogger _logger;  
  
        public CalculatorWithoutAop(ILogger logger)  
        {  
            _logger = logger;  
        }  
  
        public int Add(int a, int b)  
        {  
            _logger.Log($"Adding {a} + {b}");  
            var result = a + b;  
            _logger.Log($"Result is {result}");  
  
            return result;  
        }  
  
        public int Subtract(int a, int b)  
        {  
            _logger.Log($"Subtracting {a} - {b}");  
            var result = a - b;  
            _logger.Log($"Result is {result}");  
  
            return result;  
        }  
  
    }  
}

There are 3 problems with this solution. 

  1. Calculator class coupled with logging. Loosely coupled (because ILoger it is an interface), but coupled. Every time you make changes in this interface it affects Calculator.
  2. Code become more complex.
  3. It breaks Single Responsibility principle. Add function don't just add numbers. It logs input values, add values and logs result. The same for Subtract.
  4. Code in this article allows you don't touch Calculator class at all.

 You just need to change creation of the class.

Tests (LoggingAdviceTests.cs)

NUnit and NSubstitute are used to write Unit Tests.

CurrentThreadTaskScheduler allows you to schedule tasks in the current thread in the test project.

using System;
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using NSubstitute;
using NUnit.Framework;

namespace AOP.Tests
{
    public interface ITestClass2
    {
        void Method();

        void MethodWithException();

        Task AsyncMethodWithException();
    }

    public class TestClass2 : ITestClass2
    {
        public void Method()
        {

        }

        public void MethodWithException()
        {
            throw new Exception();
        }

        public Task AsyncMethodWithException()
        {
            return Task.Factory.StartNew(() => { throw new Exception(); });
        }
    }

    [TestFixture]
    public class LoggingAdviceTests
    {
        private TaskScheduler _taskScheduler;

        public class Data
        {
            public string Prop { get; set; }
        }

        public interface ITestClass
        {
            string Property { get; set; }

            void MethodWithVoidResult();

            string MethodWithStringResultAndIntParameter(int intParam);

            Data MethodWithClassResultAndClassParameter(Data dataParam);

            int MethodWithOutParameter(out string stringParam);

            int MethodWithRefParameter(ref string stringParam);

            int MethodWithOutParameter(out int intParam);

            int MethodWithRefParameter(ref int intParam);

            int MethodWithMixedParameter(ref int refParam, out string outParam, bool param);

            Task MethodWithTaskResult();

            Task<string> MethodWithTaskStringResult();
        }

        [SetUp]
        public void SetUp()
        {
            SynchronizationContext.SetSynchronizationContext(new SynchronizationContext());
            _taskScheduler = new CurrentThreadTaskScheduler();
        }

        [Test]
        public void ThrowException_WhenDecoratedClassNull()
        {
            Assert.Throws<ArgumentNullException>(() =>
            {
                var decorated = LoggingAdvice<ITestClass>.Create(
                    null,
                    s => { },
                    s => { },
                    o => o?.ToString());
            });
        }

        [Test]
        public void LogInfo()
        {
            var testClass = Substitute.For<ITestClass>();
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass, 
                s => infoMassages.Add(s), 
                s => errorMassages.Add(s),
                o => o?.ToString());

            decorated.MethodWithVoidResult();

            testClass.Received().MethodWithVoidResult();
            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("MethodWithVoidResult"));
            Assert.IsTrue(infoMassages[1].Contains("MethodWithVoidResult"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void DoNotStop_WhenLogInfoThrowsException()
        {
            var testClass = Substitute.For<ITestClass>();
            var errorMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => { throw new Exception(); },
                s => errorMassages.Add(s),
                o => o?.ToString());

            decorated.MethodWithVoidResult();

            testClass.Received().MethodWithVoidResult();
            Assert.AreEqual(2, errorMassages.Count);
        }

        [Test]
        public void LogInfo_WhenClassResultAndClassParameter()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.MethodWithClassResultAndClassParameter(Arg.Any<Data>()).Returns(new Data { Prop = "Result12345" });
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass, 
                s => infoMassages.Add(s), 
                s => errorMassages.Add(s), 
                o => ((Data)o).Prop);

            var result = decorated.MethodWithClassResultAndClassParameter(new Data { Prop = "Parameter12345"});

            testClass.Received().MethodWithClassResultAndClassParameter(Arg.Any<Data>());
            Assert.AreEqual("Result12345", result.Prop);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("dataParam:Parameter12345"));
            Assert.IsTrue(infoMassages[1].Contains("dataParam:Parameter12345"));
            Assert.IsTrue(infoMassages[1].Contains("Result12345"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void LogInfo_WhenParameters()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.MethodWithStringResultAndIntParameter(Arg.Any<int>()).Returns("Result12345");
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                    testClass, 
                    s => infoMassages.Add(s), 
                    s => errorMassages.Add(s),
                    o => o?.ToString());

            var result = decorated.MethodWithStringResultAndIntParameter(12345);

            testClass.Received().MethodWithStringResultAndIntParameter(Arg.Any<int>());
            Assert.AreEqual("Result12345", result);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("intParam:12345"));
            Assert.IsTrue(infoMassages[1].Contains("Result12345"));
            Assert.IsTrue(infoMassages[1].Contains("intParam:12345"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void DoNotStop_WhenSerializerThrowsException()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.MethodWithClassResultAndClassParameter(Arg.Any<Data>()).Returns(new Data { Prop = "Result12345" });
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                    testClass, 
                    s => infoMassages.Add(s), 
                    s => errorMassages.Add(s), 
                    o => { throw new Exception();});
            Data result = null;

            Assert.DoesNotThrow(() => result = decorated.MethodWithClassResultAndClassParameter(new Data { Prop = "Parameter12345"}));
            testClass.Received().MethodWithClassResultAndClassParameter(Arg.Any<Data>());
            Assert.AreEqual("Result12345", result?.Prop);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("Data"));
            Assert.IsTrue(infoMassages[1].Contains("Data"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void LogError()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.When(t => t.MethodWithVoidResult()).Do(info => { throw new Exception(); });
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                    testClass, 
                    s => infoMassages.Add(s), 
                    s => errorMassages.Add(s),
                    o => o?.ToString());

            Assert.Throws<Exception>(() => decorated.MethodWithVoidResult());
            testClass.Received().MethodWithVoidResult();
            Assert.AreEqual(1, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("MethodWithVoidResult"));
            Assert.AreEqual(1, errorMassages.Count);
            Assert.IsTrue(errorMassages[0].Contains("MethodWithVoidResult"));
        }

        [Test]
        public void DoNotStop_WhenLogErrorThrowsException()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.When(t => t.MethodWithVoidResult()).Do(info => { throw new Exception(); });
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => { throw new ArgumentNullException(); },
                o => o?.ToString());

            Assert.Throws<Exception>(() => decorated.MethodWithVoidResult());

            testClass.Received().MethodWithVoidResult();
            Assert.AreEqual(1, infoMassages.Count);
        }

        [Test]
        public void LogInfo_WhenTaskMethodCall()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.MethodWithTaskResult().Returns(Task.CompletedTask);
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString(),
                _taskScheduler);

            decorated.MethodWithTaskResult().Wait();
            ReleaseContext();

            testClass.Received().MethodWithTaskResult();
            Assert.AreEqual(2, infoMassages.Count);
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void LogInfo_WhenTaskMethodCallWithException()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.MethodWithTaskResult().Returns(Task.FromException(new Exception("ERROR!!!!")));
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString(),
                _taskScheduler);

            Assert.Throws<AggregateException>(() => decorated.MethodWithTaskResult().Wait());
            ReleaseContext();

            testClass.Received().MethodWithTaskResult();
            Assert.AreEqual(1, infoMassages.Count);
            Assert.AreEqual(1, errorMassages.Count);
            Assert.IsTrue(errorMassages[0].Contains("ERROR!!!!"));
        }

        [Test]
        public void LogInfo_WhenTaskHasResult()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.MethodWithTaskStringResult().Returns("String result");
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString(),
                _taskScheduler);

            var result = decorated.MethodWithTaskStringResult().Result;
            ReleaseContext();

            Assert.AreEqual("String result", result);
            testClass.Received().MethodWithTaskStringResult();
            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[1].Contains("String result"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void LogInfo_WhenTaskWithResultThrowException()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.MethodWithTaskStringResult().Returns(Task.FromException<string>(new Exception("ERROR!!!!")));
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString(),
                _taskScheduler);

            Assert.Throws<AggregateException>(() => decorated.MethodWithTaskStringResult().Wait());
            ReleaseContext();

            testClass.Received().MethodWithTaskStringResult();
            Assert.AreEqual(1, infoMassages.Count);
            Assert.AreEqual(1, errorMassages.Count);
            Assert.IsTrue(errorMassages[0].Contains("ERROR!!!!"));
        }

        [Test]
        public void LogInfo_WhenOutParameter()
        {
            var testClass = Substitute.For<ITestClass>();
            var val = "s2";
            testClass.MethodWithOutParameter(out val)
                .Returns(x =>
                {
                    x[0] = "s5";

                    return 25;
                });

            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            var result = decorated.MethodWithOutParameter(out val);

            var val2 = "s2";
            testClass.Received().MethodWithOutParameter(out val2);
            Assert.AreEqual(0, errorMassages.Count);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.AreEqual(25, result);
            Assert.AreEqual("s5", val);
            Assert.IsTrue(infoMassages[1].Contains("25"));
            Assert.IsTrue(infoMassages[1].Contains("stringParam:s5"));
        }

        [Test]
        public void LogInfo_WhenRefParameter()
        {
            var testClass = Substitute.For<ITestClass>();
            var val = "s2";
            testClass.MethodWithRefParameter(ref val)
                .Returns(x =>
                {
                    x[0] = "s5";

                    return 25;
                });

            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            var result = decorated.MethodWithRefParameter(ref val);

            var val2 = "s2";
            testClass.Received().MethodWithRefParameter(ref val2);
            Assert.AreEqual(0, errorMassages.Count);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.AreEqual(25, result);
            Assert.AreEqual("s5", val);
            Assert.IsTrue(infoMassages[0].Contains("stringParam:s2"));
            Assert.IsTrue(infoMassages[1].Contains("25"));
            Assert.IsTrue(infoMassages[1].Contains("stringParam:s5"));
        }

        [Test]
        public void LogInfo_WhenOutParameterOfValueType()
        {
            var testClass = Substitute.For<ITestClass>();
            var val = 2;
            testClass.MethodWithOutParameter(out val)
                .Returns(x =>
                {
                    x[0] = 5;

                    return 25;
                });

            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            var result = decorated.MethodWithOutParameter(out val);

            var val2 = 2;
            testClass.Received().MethodWithOutParameter(out val2);
            Assert.AreEqual(0, errorMassages.Count);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.AreEqual(25, result);
            Assert.AreEqual(5, val);
            Assert.IsTrue(infoMassages[1].Contains("25"));
            Assert.IsTrue(infoMassages[1].Contains("intParam:5"));
        }

        [Test]
        public void LogInfo_WhenRefParameterOfValueType()
        {
            var testClass = Substitute.For<ITestClass>();
            var val = 2;
            testClass.MethodWithRefParameter(ref val)
                .Returns(x =>
                {
                    x[0] = 5;

                    return 25;
                });

            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            var result = decorated.MethodWithRefParameter(ref val);

            var val2 = 2;
            testClass.Received().MethodWithRefParameter(ref val2);
            Assert.AreEqual(0, errorMassages.Count);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.AreEqual(25, result);
            Assert.AreEqual(5, val);
            Assert.IsTrue(infoMassages[0].Contains("intParam:2"));
            Assert.IsTrue(infoMassages[1].Contains("25"));
            Assert.IsTrue(infoMassages[1].Contains("intParam:5"));
        }

        [Test]
        public void LogInfo_WhenMixedParameters()
        {
            var testClass = Substitute.For<ITestClass>();
            var refParam = 0;
            var outParam = "s2";
            testClass.MethodWithMixedParameter(ref refParam, out outParam, true)
                .Returns(x =>
                {
                    x[0] = 5;
                    x[1] = "s5";

                    return 25;
                });

            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            var result = decorated.MethodWithMixedParameter(ref refParam, out outParam, true);

            var refParam2 = 0;
            var outParam2 = "s2";
            testClass.Received().MethodWithMixedParameter(ref refParam2, out outParam2, true);
            Assert.AreEqual(0, errorMassages.Count);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.AreEqual(25, result);
            Assert.AreEqual(5, refParam);
            Assert.AreEqual("s5", outParam);
            Assert.IsTrue(infoMassages[0].Contains("refParam:0"));
            Assert.IsTrue(infoMassages[0].Contains("outParam:s2"));
            Assert.IsTrue(infoMassages[0].Contains("param:True"));
            Assert.IsTrue(infoMassages[1].Contains("25"));
            Assert.IsTrue(infoMassages[1].Contains("refParam:5"));
            Assert.IsTrue(infoMassages[1].Contains("outParam:s5"));
            Assert.IsTrue(infoMassages[1].Contains("param:True"));
        }

        [Test]
        public void LogInfoWithProperClassName()
        {
            var testClass = new TestClass2();
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass2>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            decorated.Method();

            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("Class AOP.Tests.TestClass2"));
            Assert.IsTrue(infoMassages[1].Contains("Class AOP.Tests.TestClass2"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void LogInfoWithProperStackTrace()
        {
            var testClass = new TestClass2();
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass2>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            Assert.Throws<Exception>(() => decorated.MethodWithException());

            Assert.AreEqual(1, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("Class AOP.Tests.TestClass2"));
            Assert.AreEqual(1, errorMassages.Count);
            Assert.IsTrue(errorMassages[0].Contains("Class AOP.Tests.TestClass2"));
            //Only original Exception should be logged
            Assert.IsFalse(errorMassages[0].Contains("LoggingAdvice.cs"));
            Assert.IsTrue(errorMassages[0].Contains("LoggingAdviceTests.cs"));
        }

        [Test]
        public void LogInfoWithProperStackTrace_WhenTask()
        {
            var testClass = new TestClass2();
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass2>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString(),
                _taskScheduler);

            Assert.Throws<AggregateException>(() => decorated.AsyncMethodWithException().Wait());

            Assert.AreEqual(1, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("Class AOP.Tests.TestClass2"));
            Assert.AreEqual(1, errorMassages.Count);
            Assert.IsTrue(errorMassages[0].Contains("Class AOP.Tests.TestClass2"));
            //Only original Exception should be logged
            Assert.IsFalse(errorMassages[0].Contains("LoggingAdvice.cs"));
            Assert.IsTrue(errorMassages[0].Contains("LoggingAdviceTests.cs"));
        }

        [Test]
        public void LogInfo_WhenPropertySet()
        {
            var testClass = Substitute.For<ITestClass>();
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            decorated.Property = "Str1";

            testClass.Received().Property = "Str1";
            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("set_Property"));
            Assert.IsTrue(infoMassages[1].Contains("set_Property"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        [Test]
        public void LogInfo_WhenPropertyGet()
        {
            var testClass = Substitute.For<ITestClass>();
            testClass.Property.Returns("Str1");
            var errorMassages = new List<string>();
            var infoMassages = new List<string>();
            var decorated = LoggingAdvice<ITestClass>.Create(
                testClass,
                s => infoMassages.Add(s),
                s => errorMassages.Add(s),
                o => o?.ToString());

            var value = decorated.Property;

            var tmp = testClass.Received().Property;
            Assert.AreEqual("Str1", value);
            Assert.AreEqual(2, infoMassages.Count);
            Assert.IsTrue(infoMassages[0].Contains("get_Property"));
            Assert.IsTrue(infoMassages[1].Contains("get_Property"));
            Assert.AreEqual(0, errorMassages.Count);
        }

        /// <summary>
        /// Call to process scheduled tasks
        /// </summary>
        protected void ReleaseContext()
        {
            Task.Delay(1).Wait();
        }
    }
}

Image title

Conclusion

This code works for my cases. If you have any examples when this code does not work or how this code could be improved – feel free to contact me in any way.

That's it — enjoy!

Implementing an Experimentation Solution: Choosing whether to build or buy?

Topics:
c# ,aspect oriented programming ,logging

Published at DZone with permission of Valerii Tereshchenko. See the original article here.

Opinions expressed by DZone contributors are their own.

{{ parent.title || parent.header.title}}

{{ parent.tldr }}

{{ parent.urlSource.name }}