# Creating a better NSLog

So, generally when I write iOS code, I will start with a lot of calls to NSLog, which is a macro that with print the string you send it to the console.

There's a few problems with this.

First of all, whether you know it or not, you can see what's being printed to an iOS device's console even on apps you downloaded from the app store. Up till now, I've been preventing console printing by wrapping my NSLog calls with #if DEBUG followed by #endif. But this gets messy in a hurry, and it's quite easy to forget.

Plus, NSLog is quite busy. It has a lot of information in it, and a lot of it I don't need during development.

Here's what an example NSLog statement looks like:

2014-04-25 20:05:55.226 NHGLogger[5780:60b] Hello World!


Where the first set of numbers is the date and time. This is useful information to me.

The "NHGLogger" is the name of the application that created the log statement. This is completely useless to me while debugging... I know what app I'm running. However... this HAS to go into NSLog, because it's the only way to sort out one app from another when there are tons of apps out there all with developers who aren't courteous enough to wrap their debug log statements in #if DEBUG. The next bit, in the brackets? I literally have no idea what this is. It might be some sort of reference to the block of memory that the NSLog call originated from, or the thread? I have no clue. And the final part is the actual message I wanted to log.

What's more... the operating system considers NSLog statements to be warnings. I doesn't actually do anything about them, but as far as the OS is consider, an NSLog call means a program is trying to log some sort of non-normal behavior.

So, I set out to write my own logging macro, with a few criteria.

1. The log must be as easy to use as NSLog() is.
2. The log must include the time stamp... I always consider this useful information when logging stuff
3. The log must ONLY print to console in debug mode. It shouldn't print in release mode and I shouldn't have to write two extra lines of code every time I log anything to satisfy this criteria like I do with NSLog().

So, here's what I came up with:

# NHGLogger.h

@import Foundation.NSString;

void z_DebugLog(NSString *statement);

#define NHGLog(format_string,...) \
((z_DebugLog([NSString stringWithFormat:format_string,##__VA_ARGS__])))


# NHGLogger.m

#import "NHGLogger.h"
@import Foundation.NSDate;
@import Foundation.NSDateFormatter;

void z_DebugLog(NSString *statement) {
#if DEBUG
static NSDateFormatter *timeStampFormat;
if (!timeStampFormat) {
timeStampFormat = [[NSDateFormatter alloc] init];
[timeStampFormat setDateFormat:@"yyyy-MM-dd HH:mm:ss.SSS"];
[timeStampFormat setTimeZone:[NSTimeZone systemTimeZone]];
}

printf("%s\n",[[NSString stringWithFormat:@"<%@> %@",
[timeStampFormat stringFromDate:[NSDate date]],statement] UTF8String]);
#endif
}


The result is that in DEBUG (and only in DEBUG), stuff is printed to the console as such:

<2014-04-25 20:05:55.225> Hello World!


And the macro is used in the exact manner that NSLog is used.

Here are a few of my concerns with the code:

• z_DebugLog() --named slightly oddly because I don't intend this function to be called directly. I'm not completely rock-solid on the function naming rules of C99, and what the best way to name this so as to make it as unlikely as possible that it will pop up with autocomplete. Or better yet, is there possibly a way to make it so the macro still knows about the function but nothing outside this file does? Probably not, huh?
• Readability. Now, the whole point of this macro/function in the first place is to improve the readability of the code that calls this, but I'd like this code to be as readable as possible too. However, the readability can't trump my third concern:
• Efficiency. These statements absolutely need to go as quickly as possible. Absolutely anything that can be done to minimize the amount of time it takes to make it through this macro at runtime should be done. I don't know how efficient this is, or what, if anything, could be done to improve the speed.

The easiest way to avoid the extraneous function is going to be to use a function directly rather than using a macro. You do unfortunately have to drop down to a bit of C, but luckily since ObjC integrates rather pleasantly with C, it proves to not be very painful. The only C part is the use of the stdarg.h variable arugment list related items. (This is actually how NSLog works under the hood.)

Declaration:

void NHLog(NSString* format, ...);


Definition:

void NHLog(NSString* format, ...)
{
#if DEBUG
static NSDateFormatter* timeStampFormat;
if (!timeStampFormat) {
timeStampFormat = [[NSDateFormatter alloc] init];
[timeStampFormat setDateFormat:@"yyyy-MM-dd HH:mm:ss.SSS"];
[timeStampFormat setTimeZone:[NSTimeZone systemTimeZone]];
}

NSString* timestamp = [timeStampFormat stringFromDate:[NSDate date]];

va_list vargs;
va_start(vargs, format);
NSString* formattedMessage = [[NSString alloc] initWithFormat:format arguments:vargs];
va_end(vargs);

NSString* message = [NSString stringWithFormat:@"<%@> %@", timestamp, formattedMessage];

printf("%s\n", [message UTF8String]);
#endif
}


Anyway, on to a bit of a critique. The first problem that comes to mind is that I would always rather have too much information than not enough. Imagine if everyone used some kind of logging facility like this. Suddenly you'd have logging statements coming from who knows where for who knows what reason.

Yes, people realy shouldn't leave debug statements in production code, but unfortunately people do and they do it a lot (just look at the incredibly widespread abuse of NSLog...). Then again, as long as you don't leave any of these statements lying around, you're correct that there's no need for extra information. Considering you plan on using this only in your end applications and not leaving it in library type code, it's probably better to not put anything more than the bare essentials.

The other problem is perhaps a bit more obscure. Static variables are inherently unsafe in a non single threaded environment. Technically speaking, your timeStampFormat is unsafe unless you always run NHLog from the same thread (or you initialize it on one thread). The race condition only exists until timeStampFormat is actually created so it's a relatively small window, and the damage would likely be minimal, but considering how common threading is in ObjC applications, it seems an unacceptable flaw.

Unfortunately though, I'm not quite sure how to get around that in a non-expensive way. You could use a mutex, but that adds a very meaningful overhead, and you could use thread local storage, but that is going to bring you deep into C land since -[NSThread threadDictionary] is not available to iOS (you would have to use pthread_getspecific with a raw, non-managed, C-style pointer).

Since we're already edging into C, have you considered strftime? It's much more primitive than NSDateFormatter, but it should be fit your needs fine, and I can't imagine anything being faster than it. Also, it wouldn't have a costly formatting object to initialize, so you don't have to worry about thread safety.

• As to having more/less information, if there's something else I want to add to every message, that part is easy enough to format, and is probably purely a matter of opinion. I find stripping the unnecessary info makes the log more readable. As for the other comments, looks mostly good. I need to improve my pure C knowledge... Apr 26, 2014 at 3:59

There's another potential solution that relies on a feature of Xcode. For any other programming language, it's probably not a good idea to offer a potential solution that relies on an IDE-specific feature, but in the case of writing Cocoa/Cocoa-Touch apps (you'd have to be doing one or the other to be using NSLog), you're pretty much going to be using Xcode.

Xcode, like many other IDEs, has a code snippet library. The reason if statements, and all the loops, and many other things autocomplete for you is because they're preloaded snippets in your code snippet library. There's no reason why we shouldn't be using this code snippet library ourselves. For example, I like to put the default init pattern in there.

But here's a snippet we can do to keep our NSLog statements from showing up in our release code...

The title and summary for the snippet is pretty self-explanatory I think. It's worth noting that both of these things show up in the autocomplete context menu to help you know what you're about to autocomplete into.

The platform options let you choose between iOS and OSX (or All). Choosing one or the other prevents it from showing up when you're writing code for the other platform. (This is a nice way to give two bits of platform specific code the same auto-complete, one using UIView and the other using NSView for example.)

The language is pretty self-explanatory as well. Xcode is an IDE for numerous different languages, even if it is primarily used for Objective-C. This is the language that this snippet will autocomplete in.

The completion shortcut is what you actually type to get this code snippet to show up as autocompletion. In this example, I've used "DebugLog", so as I start to type "DebugLog", it will show up in my autocomplete list. You can make this anything, and in fact it might be a good idea to make it just "NSLog" here so we don't forget to use it.

The completion scopes tells Xcode in what code context to offer this autocompletion. Here, and with most of your code snippets this will be true, we have executable code, so "Function or Method" is the only option. But Xcode code snippets can autocomplete in any sort of scope (and the plus sign will let you give multiple scopes). You can have autocomplete comments, autocomplete preprocessor directives, etc, stuff for class interfaces and implementations, etc.

Now for the actual code. This is the important part to know about how to use Xcode's code snippet library.

The code is what Xcode will autocomplete into, regardless of anything else. But the important part is that little gray bubble with the words "debug statement" in there.

First thing to know, these gray bubbles take over the tab key. Hitting tab will cycle you through these until they're all filled out, just like when you autocomplete a method call. You'll tab through the argument placeholders until they're all filled out.

Second thing to know, now that you know how they work and when to use them, is how to create them.

It works like this:

<#Some text that serves as a hint to what gets filled in here#>


So in the example from the picture, the actual typed code for the snippet looks like this:

#if DEBUG
NSLog(<#debug statement#>);
#endif
`

When I autocomplete, it will show up almost exactly like the image I included. The difference is, when I tab to autocomplete, the "debug statement" bubble will be highlighted, and as soon as I start typing, it will replace that bubble with the format string I type to be logged in debug mode only.

Now, this solution doesn't completely resolve all the criteria in the question, but it is a simple solution to consider.