PostSharp and Common.Logging Logger declaration

Question

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
}

Answer 1

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
}