postsharpcommon.logging

PostSharp and Common.Logging Logger declaration


I'm using OnMethodBoundryAspect to create a simple logging and execution timing aspect. I would like to create a logger per method. however, if the Logger is not declared as static member it doesn't work. it's impossible to create a logger per method if it's declared as static.

here is my aspect:

[Serializable]
public class MonitorAttribute : OnMethodBoundaryAspect
{
    [NonSerialized]
    private Stopwatch _stopwatch;

    private string _methodName;
    private ILog _log;

    public MonitorAttribute()
    {
    }

    /// <summary>
    /// overrides the method name in the logs
    /// </summary>
    /// <param name="method"></param>
    public MonitorAttribute(string method)
    {
        _methodName = method;
    }

    #region Overrides

    public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
    {
        if (string.IsNullOrEmpty(_methodName))
            _methodName = method.Name;

        _log = LogManager.GetLogger(_methodName);
    }

    public override void OnEntry(MethodExecutionArgs args)
    {
        _stopwatch = Stopwatch.StartNew();
        _log.InfoFormat("Method {0} called", _methodName);
    }

    public override void OnExit(MethodExecutionArgs args)
    {
        _stopwatch.Stop();
        _log.InfoFormat("Method {0} exited successfully. execution time {1} milliseconds", _methodName, _stopwatch.ElapsedMilliseconds);
    }

    public override void OnSuccess(MethodExecutionArgs args)
    {
        _stopwatch.Stop();
        _log.InfoFormat("Method {0} executed successfully. execution time {1} milliseconds", _methodName, _stopwatch.ElapsedMilliseconds);
    }

    #endregion
}

Solution

  • The correct place to initialize the instance of the logger _log would be the RuntimeInitialize method. In your current example you create the logger only during the compile time.

    I'd also suggest that initializing a new instance of _stopwatch for each OnEntry is not thread-safe and may cause incorrect results.

    You can use a static stopwatch and a MethodExecutionArgs.MethodExecutionTag property to store the current time in the OnEntry. This value will be passed to your OnSuccess and OnExit methods afterwards.

    So the modified example may look like this:

    [Serializable]
    public class MonitorAttribute : OnMethodBoundaryAspect
    {
        private static Stopwatch _stopwatch = Stopwatch.StartNew();
    
        [NonSerialized] private ILog _log;
    
        private string _methodName;
    
        public MonitorAttribute()
        {
        }
    
        /// <summary>
        /// overrides the method name in the logs
        /// </summary>
        /// <param name="method"></param>
        public MonitorAttribute(string method)
        {
            _methodName = method;
        }
    
        #region Overrides
    
        public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
        {
            if (string.IsNullOrEmpty(_methodName))
                _methodName = method.Name;
        }
    
        public override void RuntimeInitialize(MethodBase method)
        {
            _log = LogManager.GetLogger(_methodName);
        }
    
        public override void OnEntry(MethodExecutionArgs args)
        {
            _log.InfoFormat("Method {0} called", _methodName);
            args.MethodExecutionTag = _stopwatch.ElapsedMilliseconds;
        }
    
        public override void OnExit(MethodExecutionArgs args)
        {
            long stopwatchStart = (long) args.MethodExecutionTag;
            _log.InfoFormat("Method {0} exited successfully. execution time {1} milliseconds", _methodName,
                _stopwatch.ElapsedMilliseconds - stopwatchStart);
        }
    
        public override void OnSuccess(MethodExecutionArgs args)
        {
            long stopwatchStart = (long) args.MethodExecutionTag;
            _log.InfoFormat("Method {0} executed successfully. execution time {1} milliseconds", _methodName,
                _stopwatch.ElapsedMilliseconds - stopwatchStart);
        }
    
        #endregion
    }