Pattern for adding entry and exit trace to a method

Question

I am trying to figure out the best way of tracing the return value of a method when the method has multiple exit points. I have dozens of methods I want to add tracing to. I'll run through what I have tried.

First I tried refactoring each method to have a single exit point like this:

StatusCode CreateResource(string name, string type)
{
    Trace.LogEvent("BEGIN CreateResource name=" + name + " type=" + type);
    StatusCode status = StatusCode.Ok;
    if (!IsValidResourceName(name))
        status = StatusCode.InvalidName;
    else
    {
        if (!IsValidResourceType(type))
            status = StatusCode.InvalidType;
        else
        {
            if (!SystemOnline())
                status = StatusCode.SystemOffline;
            //continues to nest with more conditions
        }
    }
    Trace.LogEvent("END CreateResource result=" + status);
    return status;
}

But the nested if statements make it ugly and less readable. I have made heavy use of early exit points as guard statements and refactoring it all just creates a mess, feels like de-refactoring.

Another thing I tried was to wrap each method in another method that traces the return value:

StatusCode CreateResource(string name, string type)
{
    Trace.LogEvent("BEGIN CreateResource name=" + name + " type=" + type);
    StatusCode status = CreateResource_DONT_CALL_THIS_METHOD(name, type);
    Trace.LogEvent("END CreateResource result=" + status);
    return status;
}

StatusCode CreateResource_DONT_CALL_THIS_METHOD(string name, string type)
{
    if (!IsValidResourceName(name))
        return StatusCode.InvalidName;
    if (!IsValidResourceType(type))
        return StatusCode.InvalidType;
    if (!SystemOnline())
        return StatusCode.SystemOffline;
    return StatusCode.Ok;
}

The problem is how to prevent in future other developers (or me) calling the wrapped method and bypassing the tracing, hence that ridiculous (and contradicting) name of the wrapped method. I could define and call an anonymous method for the internal method, but that's quite a messy pattern to use throughout the project.

The most solid and readable method I found was this, it's sort of OK IMO but I have doubts this use of a for statement is going to fly in a code review:

StatusCode CreateResource_Internal(string name, string type)
{
    Trace.LogEvent("BEGIN CreateResource name=" + name + " type=" + type);
    StatusCode status = StatusCode.Ok;
    for (int i = 0; i < 1; i++)
    {
        if (!IsValidResourceName(name))
        {
            status = StatusCode.InvalidName;
            break;
        }
        if (!IsValidResourceType(type))
        {
            status = StatusCode.InvalidType;
            break;
        }
        if (!SystemOnline())
        {
            status = StatusCode.SystemOffline;
            break;
        }
    }
    Trace.LogEvent("END CreateResource result=" + status);
    return status;
}

I tried a variation using a try finally block:

StatusCode CreateResource_Internal(string name, string type)
{
    Trace.LogEvent("BEGIN CreateResource name=" + name + " type=" + type);
    StatusCode status = StatusCode.Ok;
    try
    {
        if (!IsValidResourceName(name))
        {
            status = StatusCode.InvalidName;
            return status;
        }
        if (!IsValidResourceType(type))
        {
            status = StatusCode.InvalidType;
            return status;
        }
        if (!SystemOnline())
        {
            status = StatusCode.SystemOffline;
            return status;
        }
    }
    finally
    {
        Trace.LogEvent("END CreateResource result=" + status);
    }
    return StatusCode.Ok;
}

The downside here is that it's possible to forget to set the 'status' variable before returning in which case tracing will not be performed.

My question is, is there a best practice for doing this? Am I expected to refactor to a single exit point? Is there some way of preventing a wrapped method from being called from elsewhere? Is the danger of allowing tracing to be bypassed worse than the untidiness of refactoring to single exit point?

p.s I don't want to bring in something heavy like aspect oriented programming.

Answer 1

Writing trace files (or any form of logging for that matter) is a typical example of a Cross Cutting Concern and you should really try to avoid this type of code in your methods as it makes them A) less readable and B) duplicates a lot of code.

I know you mentioned in your question that you didn't want to add any AOP style programming to your application but I'd really recommend implementing Microsoft Unity for this. It supports Interception which is exactly the scenario that you're trying to solve here. As long as you follow good programming practice of coding to an interface you'd be surprised how easy it is to implement (and do some pretty cool stuff!).

Just some food for thought...

Answer 2

I'd use dependency injection - if each class implements an interface then the Decorator pattern is the best solution (just a code sketch):

interface A
{
  int method1(float x);
}

class AImpl : A
{
    public int method1(float x) { }
}

class LoggedAImpl : A
{
private AImpl innerA;

public int method1(float x) 
{
  //log method and parameters
  int result;
  try
  {
    result = innerA.method1(x);
  }
  finally
  {
    //log method exit
  }
}
}

And then, in the application setup:

new LoggedAImpl(new AImpl()); //pass it everywhere A is needed

Using this with unity seems elegant and relatively painless.

If you don't want to use unity, then at least the Factory pattern along with this above will suffice.

Answer 3

I've always used the try-finally scheme, but with the entire method wrapped in the try-block.

Something like this:

StatusCode CreateResource_Internal(string name, string type)
{
    try
    {
        Trace.LogEvent("BEGIN CreateResource name=" + name + " type=" + type);
        StatusCode status = StatusCode.Ok;

        if (!IsValidResourceName(name))
        {
            status = StatusCode.InvalidName;
            return status;
        }
        if (!IsValidResourceType(type))
        {
            status = StatusCode.InvalidType;
            return status;
        }
        if (!SystemOnline())
        {
            status = StatusCode.SystemOffline;
            return status;
        }
        status = StatusCode.Ok; // A bit silly, but that avoids the problem of status not being set.
        return status;
    }
    finally
    {
        Trace.LogEvent("END CreateResource result=" + status);
    }
}

Answer 4

As a side answer, you could look at implementing Log4PostSharp, you can see a tutorial in the link here. It may not directly answer your question, but it will help with your scenario.