CoCoa Crumbs

Using NSLog() is probably the easiest and most used [first line] debuggingtool. However, the output of NSLog() was not really to my liking and I thought it could be made more useful. The output of:

NSLog(@"%s : generated = %d", _cmd, generated);

looks typically like this:

2008-11-09 19:00:41.223 CCLog[219:10b] generate: : generated = 88

It shows the date and time (with milliseconds precision) and the name of the project before it shows the text I want to print out. In this case the called method and the value of an int.

My preferred output would be capable of doing this:
1) Show on which thread CCLog() was called from.
2) Show from which sourcecode file CCLog() was called from.
3) Show the linenumber in the sourcecode file CCLog was called from.

My first preference might seem a bit weird but as a beginning developer I found it useful to have the possibility to quickly check if my code was running in the thread I intended to. CoCoa has the capability of giving a NSThread a name [on top of its threadnumber]. This can very easily be done like this:

[[NSThread currentThread] name];

A bit of searching brought me to a blog-entry of agentM which describes his own implementation of a better NSLog(). In short, his implementation is a very nice example on the usage of variadic macros and the C preprocessor. Using the C preprocessor, It’s possible to write the CCLog() class method like this:

#define CCLog(s,...)                           \
    [CCLog myLog:__FILE__                      \
      lineNumber:__LINE__                      \
          format:(s), ##__VA_ARGS__]

The above CCLog macro expands to a class method call:

[CCLog mylog:__FILE__ lineNumber:__LINE__ format:...];

At compile-time, the __FILE__ and __LINE__ arguments would be expanded to the filename and linenumber where CCLog() was called from just like I wanted. For those classes that have a methodname like ‘init’ which appear quite often, having the filename in the log makes it easy to follow which ‘init’ method from which implementation was called. The last argument is the string with our own text. Using the variadic macro (__VA_ARGS__) we can still format strings as we are used to for formating a NSString. E.g. the following is perfectly possible:

CCLog(@"%s : generated = %d", _cmd, generated);

As you can see, we can specify any number of parameters to format our textstring like we want. The processing of the variadic macro then happens like this:

va_start(listOfArguments, format);
formattedString = [[NSString alloc] initWithFormat:format
                                         arguments:listOfArguments];
va_end(listOfArguments);

The only other remaining problem is printing out the threadname. If the threadname is not set, then the threadnumber should be logged. Getting the threadname is pretty simple and can be done like this:

[[NSThread currentThread] name];

Getting to show the threadnumber was less easy. NSThread provides a method to get its name but not its number. This can be bit problematic in those cases a thread doesn’t have a name. Asking the threadname of a thread which is not named simply returns nil. In that case I simply send the output of the currentThread class message of NSThread to a NSString. That output contains the threadnumber and can be extracted with a bit of string manipulation.

The output of CCLog() now looks like this with a threadnumber:

Thread 1 | Foo.m[20] generate: : generated = 84

The output of CCLog() now looks like this with a named thread:

Foo Thread | Foo.m[22] generate: : generated = 84

The full implementation of CCLog() can be found below and a small Xcode project can be downloaded at the end of this blogentry.

As a last remark, when you define the USE_NSLOG preprocessor macro, then the familiar NSLog() will be used instead of printf() to print out the message. This means that the date, time and project name will be added in front of the threadname, filename, linenumber and the content of the logstring. The output of the same CCLog() calls as above becomes:

2008-11-09 20:37:59.177 CCLog[424:10b] Thread 1 | Foo.m[20] generate: : generated = 84
2008-11-09 20:37:59.178 CCLog[424:10b] Foo Thread | Foo.m[22] generate: : generated = 84

The header file:

//
//  CCLog.h
//  gitVersions
//
//  Created by Koenraad Van Nieuwenhove on 26/08/08.
//  Copyright 2008 CoCoa Crumbs. All rights reserved.
//
#import <Cocoa/Cocoa.h>

// idea from http://www.borkware.com/rants/agentm/mlog/

#define CCLog(s,...)                           \
    [CCLog myLog:__FILE__                      \
      lineNumber:__LINE__                      \
          format:(s), ##__VA_ARGS__]

@interface CCLog : NSObject
{
} 

+ (void)myLog:(char*)file
   lineNumber:(int)lineNumber
       format:(NSString*)format, ...;

@end /* interface CCLog */

The implementation:

//
//  CCLog.m
//  gitVersions
//
//  Created by Koenraad Van Nieuwenhove on 26/08/08.
//  Copyright 2008 CoCoa Crumbs. All rights reserved.
//
#import "CCLog.h"

#define USE_NSLOG

@implementation CCLog

+ (NSInteger)currentThreadNumber
{
    NSString    *threadString;
    NSRange      numRange;
    NSUInteger   numLength;

    // Somehow there doesn't seem to be an listOfArgumentsI call to return the
    // threadnumber only the name of the thread can be returned but this is NULL
    // if it is not set first!
    // Here is a bit of code to extract the thread number out of the string
    // an NSThread returns when you ask its description to be printed out
    // by NSLog. The format looks like:
    //     <NSThread: 0x10113a0>{name = (null), num = 1}
    // Basically I search for the "num = " substring, copy the remainder
    // excluding the '}' which gives me the threadnumber.
    threadString = [NSString stringWithFormat:@"%@", [NSThread currentThread]];

    numRange = [threadString rangeOfString:@"num = "];

    numLength = [threadString length] - numRange.location - numRange.length;
    numRange.location = numRange.location + numRange.length;
    numRange.length   = numLength - 1;

    threadString = [threadString substringWithRange:numRange];
    return [threadString integerValue];
} /* end currentThreadNumber */

+ (void)myLog:(char*)file
   lineNumber:(int)lineNumber
       format:(NSString*)format, ...
{
    va_list      listOfArguments;
    NSString    *formattedString;
    NSString    *sourceFile;
    NSString    *logString;

    va_start(listOfArguments, format);
    formattedString = [[NSString alloc] initWithFormat:format
                                             arguments:listOfArguments];
    va_end(listOfArguments);

    sourceFile = [[NSString alloc] initWithBytes:file
                                          length:strlen(file)
                                        encoding:NSUTF8StringEncoding];

    if([[NSThread currentThread] name] == nil)
    {
        // The thread has no name, try to find the threadnumber instead.
        logString = [NSString stringWithFormat:@"Thread %d | %s[%d] %@",
                    [self currentThreadNumber],
                    [[sourceFile lastPathComponent] UTF8String],
                    lineNumber,
                    formattedString];
    }
    else
    {
        logString = [NSString stringWithFormat:@"%@ | %s[%d] %@",
                    [[NSThread currentThread] name],
                    [[sourceFile lastPathComponent] UTF8String],
                    lineNumber,
                    formattedString];
    } /* end if */

#ifdef  USE_NSLOG
    NSLog(@"%@", logString);
#else
    printf("%s\n", [logString UTF8String]);
#endif /* USE_NSLOG */

    // cleanup
    [formattedString release];
    [sourceFile release];
} /* end myLog */

@end /* implementation CCLog */

A sample project can be downloaded here: CCLog sample project