Menu

Logging Methods As They Are Called

Been meaning to write this blog entry for a while.

When I saw a recent blog post by Guy English about creating scoped objects in Objective-C, I thought to myself “Finally!! I have JUST the problem for this solution!” and then I filed it away for when I would eventually get around to actually using it.

And time passed…

Until today.

Wait… rewind… some back story…

I started coding C++ in 1992. (Wow.. damn… that’s a long time.) Obviously, over the years, I built up a lot of utility code that helped me in debugging and in using various design patterns in C++. In particular, one of the very handy little utility modules that found it’s way into my toolbox was a method for logging the name of a method as you enter and leave it.

Of particular importance here: Note that I said as you enter and leave the method. So in other words, the goal of this module was to enable me to code something like this:

void SomeClass::someMethod()
{
    TRACE;
    // ... logic and code ....
}

and then you’d get in your log files:

2009-09-21 11:37: Entered: void SomeClass::someMethod();
2009-09-21 11:38: Exited: void SomeClass::someMethod();

So, the nice thing here is that with just one extra line of code, you get a log entry when you enter the method, and then you get another log entry showing exiting the method. This can be really helpful when trying to chase down weird pointer bugs (Hello C++!).

Now, the pattern for the implementation of this code is pretty straight forward. The way it works is it exploits scoping to generate the desired log messages. There’s an object hidden in that TRACE macro, and the entry log message is in it’s constructor, and the exit log message is in the destructor. So when the TRACE macro is used, a new instance of the class is created on the stack, the constructor is called, and the entry message is logged. When that instance goes out of scope, the destructor is called, and the exit message is logged.

Ok, got all that? Cool! I’m not gonna show you the C++ code, because C++ is something only certain types of masochists enjoy. I speak as someone who’s personally accepted that particular burden for many years. Take it from me… if your project can use Objective-C instead of C++, then do it!

That said… having been writing Objective-C now for about 8 years… there have been times… rarely.. when I really wanted something just like this. Unfortunately, since Objective-C objects are all always dynamically allocated on the heap, it’s really not been possible… until I saw Guy’s post… and then I said “Aha!!! That’s how I can do it!”

Well, I finally had a bug today which called for this form of primitive caveman debugging. That is, I really needed to just toss a bunch of logging into the app and see the interaction between the methods that are being called and the crash itself. So I decided to put Guy’s idea to the test and see if I could make it work like my old C++ mechanism.

And it did.

Here’s the code… the header:

//
//  MethodLogger.h
//
//  Created by Jiva DeVoe on 9/21/09.
//  Copyright 2009 Random Ideas, LLC. Free for any use commercial or personal
//

#import <Foundation/Foundation.h>

@interface MethodLogger : NSObject 
{
    NSString *methodSig;
}
@property (retain, nonatomic) NSString * methodSig;
-(id)initWithMethodSignature:(const char *)inMethodSig;

@end
extern void $kb_scopeReleaseObject( id *scopeReleasedObject );

#define KBScopeReleased __attribute__((cleanup($kb_scopeReleaseObject)))
#define TRACE MethodLogger *logger KBScopeReleased = [[MethodLogger alloc] \
initWithMethodSignature:__PRETTY_FUNCTION__]

And the implementation:

//
//  MethodLogger.m
//
//  Created by Jiva DeVoe on 9/21/09.
//  Copyright 2009 Random Ideas, LLC. Free for any use, commercial or personal
//

#import "MethodLogger.h"

void $kb_scopeReleaseObject( id *scopeReleasedObject )
{
    [*scopeReleasedObject release];
    *scopeReleasedObject = nil;
}

@implementation MethodLogger
@synthesize methodSig;
-(id)initWithMethodSignature:(const char *)inMethodSig;
{
    if(self == [super init])
    {
        [self setMethodSig:[NSString stringWithUTF8String:inMethodSig]];
        NSLog(@"-=> %@", methodSig);
    }
    return self;
    
}

-(void)dealloc;
{
    NSLog(@"<=- %@", methodSig);
    [self setMethodSig:nil];
    [super dealloc];
}

@end

So there it is! Now one thing to note, CLANG will complain that you have an unfreed object in your TRACE macro. Maybe there’s some annotations to get rid of that, but I haven’t figured it out. So that said, I wouldn’t leave these in your code permanently. But in those cases where you need something like this, it’s nice to know you can do it.

PS: What About Using Autorelease Instead?

Guy touches on this a little bit, but more specific to our little solution here, I’ll say a word or two about it as well.

We can’t use autorelease here, because autorelease just means that your object will receive a release call when your application’s runloop gets around to it. We really want to know when we left the method. So what we really want to see is a hard release at the end of the method. Using the scoped object mechanism gives us that.