A Better NSLog()

---

Special Guest Rant by AgentM, on February 14, 2005.

NSLog(NSString* format,...) works well for cases where the programmer is keeping track of program flow and variables without using breakpoints. Also, in a lot of cases, the Xcode debugger just shows an object's instance variables which may not give the programmer the best overview of what is going on. NSLog() makes checking program flow a breeze without the interruption of breakpoints. Behind the scenes, NSLog() ensures that all strings passing through it are written in a thread-safe manner to stderr, but other than that, it doesn't do much.

The problem

While developing a large framework, I soon found that I had too many NSLog() calls strewn throughout the code. I would typically perform a search and replace for NSLog()s that I no longer needed but that became tedious and error-prone. In addition, NSLog output includes a program name and timestamp, but fails to note where the NSLog() was called, making it difficult to quickly hone in and delete unnecessary NSLog()s. I decided I needed a better NSLog().

A typical NSLog() output looks like this:

2005-02-13 19:10:47.432 MyApp[<pid>] NSLog output

The information I would like to add is:

1. name of the source file where the NSLog() was called
2. line number in the source file where the NSLog() was called

MLog

To keep the benefits of NSLog(), I decided to wrap the function in an object: MLog. To keep it simple, I decided that MLog should be a singleton class (since there is only one stderr anyway). Here is the intital class interface:

//MLog.h
@interface MLog : NSObject
{
}
+(void)logFile:(char*)sourceFile lineNumber:(int)lineNumber 
       format:(NSString*)format, ...;
+(void)setLogOn:(BOOL)logOn;
@end

Here we see that MLog consists entirely of class methods. +logFile:lineNumber:format: will create a string with the extra information I wanted (see above) and pass it to NSLog(). +setLogOn: will allow me to turn the logging on and off at runtime. Also, I will want to be able to turn logging on and off with an environment variable "MLog".

Let's look at the simple implementation.

//MLog.m
static BOOL __MLogOn=NO;

@implementation MLog
+(void)initialize
{
	char * env=getenv("MLogOn");
	if(strcmp(env==NULL?"":env,"NO")!=0)
		__MLogOn=YES;
}

In the +initialize method, we simply check if the environment variable "MLogOn" would rather have logging off (when it is set to "NO"). The ternary operator is just shorthand for an if statement which replaces the first argument to strcmp() with the empty string if the environment variable wasn't specified. This is required because strcmp() doesn't handle NULL arguments. Note that I claimed above that MLog should be a singleton class. Because I never actually instantiate the class, this is technically false. However, the end result is the same.

+(void)logFile:(char*)sourceFile lineNumber:(int)lineNumber
       format:(NSString*)format, ...;
{
	va_list ap;
	NSString *print,*file;
	if(__MLogOn==NO)
		return;
	va_start(ap,format);
	file=[[NSString alloc] initWithBytes:sourceFile 
                  length:strlen(sourceFile) 
                  encoding:NSUTF8StringEncoding];
	print=[[NSString alloc] initWithFormat:format arguments:ap];
	va_end(ap);
        //NSLog handles synchronization issues
	NSLog(@"%s:%d %@",[[file lastPathComponent] UTF8String],
              lineNumber,print);
	[print release];
	[file release];
	
	return;
}

The +logFile:lineNumber:format: does the actual work of the class. First, it checks if it should print at all by checking the global variable. If so, it gathers the necessary information, creates the print string and sends it to NSLog. See stdarg.h for more information on variable arguments.

+(void)setLogOn:(BOOL)logOn
{
	__MLogOn=logOn;
}

@end

This pitifully simple routine turns logging on or off at runtime. This is useful if you want to turn logging on only for certain objects or states in the application. One potential improvement here could be to allow for logging "levels" such as "debug", "warn", or "fatal".

What Now?

Now we have a class that wraps NSLog() and adds some features, but I have made it a lot more tedious to actually log a message. Here's an example:

[MLog logFile:"MySource.m" lineNumber:10 
      format:@"An event occurred!"];

That's not an improvement! I would still rather use a simple function to cut down on typing. What if I change the file name or add a line in the source? Now I am expected to keep track of all line numbers and file names? This solution is less than ideal.

A Better NSLog()

When we left off with the above implementation, I ended up with a clunkier logging interface than I would like. Instead, I would like a function that I can call exactly like NSLog() while still reaping the benefits of the above MLog class. Solution: variadic macros.

Variadic macros allow the preprocessor to handle macro definitions with a variable number of arguments. This is handy everywhere variadic functions are, such as NSLog(), which takes a variable number of arguments. We, too, can define variadic functions and macros. See the GCC page on variadic macros for important information on portability and standards. Since I assume everyone is using a recent version of gcc, I took the liberty of using a GCC extension to the standard.

The MLogString macro should simply call +logFile:lineNumber:format: with everything required. Some macro magic will help us get exactly what we need. Here's the code:

#define MLogString(s,...) \
    [MLog logFile:__FILE__ lineNumber:__LINE__ \
          format:(s),##__VA_ARGS__]

This simple macro covers it, but let's look at exactly what is going on here. First, #define tells the preprocessor that we are defining a macro which is recognized as MLogString(s,...). This means the prepocessor will look for code which looks like the function call MLogString(). The preprocessor must also recognize that the macro takes a variable number of arguments.

The second half of the declaration define what the "function" should be replaced with. Clearly, we want to send a message to MLog, so we do that, but include some strange looking arguments. In fact, these arguments are themselves macros. __FILE__ is replaced with the current sourcecode file name and __LINE__ is replaced with the current line number in that source file. ##__VA_ARGS__ is a special preprocessor directive that lets the preprocessor know that it should fill in the variable arguments there. Note that this is a GNU GCC specific directive because it doesn't adhere to the C99 standard. This extension allows us to call MLogString() with only one string argument but still get meaningful output. See the GCC page on variadic macros for more information.

Note that I could have wrapped NSLog directly in the macro, however, macros are more difficult to add functionality to than to classes. Having a logging class around will allow me to fine tune formatting output or add those log levels I mentioned above. Also, the current code for MLog includes a race-condition around its global variable. In a multi-threaded application, this would need to be accounted for by using some form of synchronization around it.

Success!

So that's it! Now we have a NSLog() replacement that looks like NSLog() but adds line and file name information. Let's see what it can do:

MLogString(@"logged!");

2005-02-13 20:06:07.582 MyApp[1465] main.m:15 logged!

MLogString(@"logged an int %d",10);

2005-02-13 20:18:43.147 MyApp[1485] main.m:15 logged an int 10

It works great! Now you'll never have a "lost" NSLog() again!

This article is in the public domain.

You can download the code, code files courtesy of Doug Franklin.