6

We inherited a somewhat poorly-designed WCF service that we want to improve. One problem with it is that it has over a hundred methods (on two different interfaces), most of which we suspect are not used. We decided to put some logging on each of the methods to track when and how they're called. To make the tracing code refactor-friendly and typo-proof, we implemented it like so:

public void LogUsage()
{
    try
    {
        MethodBase callingMethod = new StackTrace().GetFrame(1).GetMethod();
        string interfaceName = callingMethod.DeclaringType.GetInterfaces()[0].Name;
        _loggingDao.LogUsage(interfaceName, callingMethod.Name, GetClientAddress(), GetCallingUrl());
    }
    catch (Exception exception)
    {
        _legacyLogger.Error("Error in usage tracking", exception);
    }
}

LogUsage() is then called at the start of each method we want to trace.

The service is very high traffic, on the order of 500,000+ calls/day. 99.95% of the time, this code executes beautifully. But the other 0.05% of the time, GetInterfaces() returns an empty (but not null) array.

Why would GetInterfaces() occasionally return inconsistent results?

This may seem so trivial - a 0.05% error rate is something we can usually only dream of. But the whole point is to identify all the service touchpoints, and if this error is always coming out of one (or a few) method calls, then our tracing is incomplete. I've tried to reproduce this error in my development environment by calling each and every method on the service, but to no avail.

3
  • Incomplete stack trace caused by an improperly rethrown exception somewhere?
    – Tim M.
    Commented Sep 20, 2012 at 20:40
  • 1
    If you also log the callingMethod, you might find that its declaring type actually has no interfaces. Commented Sep 20, 2012 at 20:41
  • LogUsage is only called from methods inside two classes, and both those classes implement at least one interface.
    – nateirvin
    Commented Sep 20, 2012 at 20:48

2 Answers 2

4

StackTrace is notoriously unreliable, especially in multi-threaded environments. Or rather, it is highly reliable, but isn't very practical at times. Asking for the 'last method that was called' can have unexpected results. Try logging the DeclaringType. You might be surprised what you find there. Note that while this is a 0.05% failure rate now, it might easily increase with the complexity of your application.

In order to properly implement reusable tracing code, you'll need to rely on the .NET 4.5 feature Caller Information, by using a dynamic proxy (e.g. Castle Dynamic Proxy), or by using an AOP framework such as PostSharp. Alternatively, you can just code tracing by hand.

1
  • "StackFrame not being thread-safe" is a possibility I considered; however, the MSDN documentation says "The StackTrace is created with the caller's current thread", so I figured I could rely on it. So good to know. (FYI for political reason I'm not going to be able to make any changes to the service for a while so beefing up the logging isn't an option for now [sigh])
    – nateirvin
    Commented Sep 20, 2012 at 21:07
3

From Erik Lippert (who works on the C# compiler team for MS) in response to Getting Type T from a StackFrame:

The stack frame does not actually tell you who called your method. The stack frame tells you where control is going to return to. The stack frame is the reification of continuation. The fact that who called the method and where control will return to are almost always the same thing is the source of your confusion, but I assure you that they need not be the same.

The whole post is worth reading...

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.