You're Doing It Wrong #3: error:NULL

This week's post is going to be short and simple, and it relates to error handling.

In Objective-C, a common way to report error information to the caller of a method is to use an NSError output argument. For example, here is the declaration of the writeToFile:options:error method on NSData:

- (BOOL)writeToFile:(NSString *)path
            options:(NSDataWritingOptions)mask
              error:(__autoreleasing NSError **)errorPtr;

The method returns a boolean to indicate success or failure. On failure, a pointer to an NSError object will be written to the error output argument (note the double stars). All very standard.

What I see too often is code that simply passes NULL to the error argument and doesn't bother to check the return value. This ignores or hides any errors that may be generated by the method:

NSData *data = [self makeData];
[data writeToFile:outputFile
          options:NSDataWritingAtomic
            error:NULL];

In my opinion this is just as bad as gobbling up exceptions in Java:

try {
    doSomething();
} catch (Throwable e) {
}

Swallowing errors like this is very much frowned upon. It can lead to nightmares in terms of maintainability and debugging, especially in a language like Objective-C where nil return values can go unnoticed and delay the symptoms of an error.

Laziness

I think the reason so many developers fall into this habit is due to laziness. In order to do things properly, you have to declare a new variable, wrap the method you are calling in an if statement, and somehow deal with the error. You may decide you have to pass the error up a level, which would require you to add error feedback to your own interface.

These annoying details crop up when you are already half-way through writing the method call, so it's almost understandable that people get frustrated and stuff in a NULL to get it over and done with.

It's still wrong, however. And you know it's wrong. So please, for the sake of professionalism and your fellow developers, get into the habit of always providing a value to the error argument. At the very least you should be logging the error:

NSData *data = [self makeData];
NSError *error;
if (![data writeToFile:outputFile
               options:NSDataWritingAtomic
                 error:&error]) {
    MyLogError(@"%@", error);
}

I don't even care whether or not you describe what you were doing in the message. Just stuff a @"%@" in there and get it done as quickly as possible. At least the error will be seen. This is the absolute minimum, and you should do this for every method call that provides error information.

Even if you are writing quick prototype or test code, I would also suggest you follow this rule. Indeed, these are the situations where you are most likely to make mistakes, and breaking into the debugger to see which method failed is a huge waste of time. It is much faster to write the code properly and get quick feedback on any problems.

Rules are there to be broken

Yes yes, OK. Rules are there to be broken, so what follows is one example where it may (may) be acceptable to ignore an error:

- (void)copySourceFileToDestination {
    NSString *source = [self sourcePath];
    NSString *destination [self destPath];

    NSFileManager *manager = [NSFileManager defaultManager];

    // Delete/overwrite destination
    // ignore error because destination might not exist
    [manager removeItemAtPath:destination
                        error:NULL];

    NSError *error;
    if (![manager copyItemAtPath:source
                          toPath:destination
                           error:&error]) { 
        MyLogError(@"Error copying file: %@", error);
        // ...
    }

    // ...

}

In this example we want to copy path source to destination, overwriting destination if necessary.

The copyItemAtPath:toPath:error: method will fail if destination already exists. To get proper overwriting behaviour we either have to implement NSFileManagerDelegate, or instead (as in this example) delete destination first with a call to removeItemAtPath:error.

In all likelihood, destination will not exist, so the call to removeItemAtPath:error is going to fail. We don't care about this particular failure case, so we ignore it. If anything else does go wrong, we still check the result of copyItemAtPath:toPath:error:, so we seem to be in the clear.

Implementing methods that return errors

I'm going to close this off by giving a little tip for when you write your own methods that return error information.

If somebody calls your code with a NULL error value, you want to be as helpful as possible and log the error for them:

- (BOOL)myAPIMethod:(__autoreleasing NSError **)errorOut
{
    // do some work
    // ...

    if (weGotErrors) {
        if (errorOut) {
            *errorOut = theErrorWeGot;
        } else {
            MyLogError(@"Error doing something: %@",
                theErrorWeGot);
        }
    }

    // ...
}

If we are provided with a non-NULL output argument, we write out the error and it is up to the caller to log, handle or ignore the error as they wish.

If we are given NULL, we're going to assume the developer is lazy and log the error for them. If they really want to ignore the error, they can provide an output argument and do the ignoring in their own code. In our code we are going to be responsible developers and make sure errors are visible by default.

Be responsible

Things can get tedious in Objective-C. Error handing can be annoying and can make an already ugly block of code even uglier. But stay true to your core values, be responsible, and put in that extra bit of effort to write robust and programmer-friendly code.

That's the end. Thanks for reading.

You're Doing It Wrong #2: Sizing labels with -[NSString sizeWithFont:...]

Author's note: Well, I've already blown my one-post-per-week target. UIButton's insets behaviour finally got the best of me and I had to take a major detour to settle the issue once and for all. I hope it was worth it!

---

It's very common to want to adjust the bounds of a UILabel to fit its contents. The most common technique I've seen from developers looks something like this:

UILabel *label = [[UILabel alloc] initWithFrame:...];
label.text = NSLocalizedString(@"Some long text here...");
label.numberOfLines = 0;

CGSize maxSize = CGSizeMake(label.bounds.size.width, CGFLOAT_MAX);

CGSize textSize = [label.text sizeWithFont:label.font
                         constrainedToSize:maxSize];

label.frame = CGRectMake(10, 10, textSize.width, textSize.height);

This code is using one of NSString's sizeWithFont:... methods to calculate the bounds of the label's text, taking its font and width into consideration.

If you are sizing your labels like this, you need to read on because you are doing it wrong.

A smell

Let's take a step back and think about this for a moment.

We want to know how much space the label needs to display its text. Surely that logic belongs in UILabel? Only the label itself really knows how it renders its content and what offsets or margins it may be applying.

It seems like a bit of a smell to me that we have to calculate this stuff ourselves using methods on another class.

Now in the case of UILabel, it turns out that -sizeWithFont: returns exactly the size we need. The label is probably doing a simple -[NSString drawAtPoint:...] which matches up perfectly with the results we get back from the sizeWithFont:... methods. But is this always going to be true?

What if UILabel decides to add support for special borders, or configurable line heights, or some other visual effects that will change the required bounds? The above code is going to break. It isn't future proof, and we are essentially duplicating or even worse guessing the behaviour of UILabel's rendering.

Is UILabel really going to change in such a manner? Well, it just did. As of iOS 6, UILabel supports the rendering of attributed strings. This means arbitrary ranges in the label's text can have different fonts and styles applied to them. If there is word in the middle of the label with a very large font, bounds required to fit that string in the label are going to increase.

If you use the previous code unmodified on a label containing an attributed string, you are going to get incorrect results.

As it turns out, that there are UIKit additions to NSAttributedString, namely boundingRectWithSize:options:context:, which provide similar functionality to NSString's -sizeWithFont: methods. But our code still should not be duplicating this kind of logic, especially when there is a far better and simpler solution...

sizeToFit and sizeThatFits:

If we want to resize a label to fit its contents, we can just tell it to do so:

[label sizeToFit];

Bam. Done. The label will take its current width, and adjust its height to fit its contents (assuming it is a multi-line label). If the label has a width of 0, its size is adjusted to fit everything on a single line.

If you wish to size the label without setting a frame beforehand, you can ask the label for the size it needs like this:

CGSize maxSize = CGSizeMake(200.0f, CGFLOAT_MAX);
CGSize requiredSize = [label sizeThatFits:maxSize];
label.frame = CGRectMake(10, 10, size.width, size.height);

Note the use of CGFLOAT_MAX here to mean "unbounded".

Both sizeToFit and sizeThatFits: are standard in UIKit and have existed for a very long time. They work with the new attributed string support in iOS 6, and will continue to work no matter what changes are made to UILabel.

It pains me to see people writing useless (and often times incorrect) categories on UILabel for something as standard as this. I guess the lesson to take away is to explore as much of the documentation as you can. I'm sure there are many useful methods out there that I've overlooked.

Going a little deeper

The documentation for sizeToFit and sizeThatFits: can be found in the UIView class reference.

What you need to know is that sizeThatFits: is overridable and returns the "most appropriate" size for the control that fits the constraints passed to it. The method can decide to ignore the constraints if they cannot be met.

sizeToFit will simply call through to sizeThatFits: passing the view's current size as the argument. It will then update the view's frame based on the value it gets back. So all the important logic goes in sizeThatFits:, and this is the method you should override for your own custom controls.

A major detour: UIButton insets demystified

Many of the standard UIKit controls implement sizeThatFits:, one of which is UIButton. However, things can get a little tricky with UIButton, especially when when you throw insets into the mix.

We'll start by creating a button with an image, a stretchable background image, and some text:

UIButton *b = [UIButton buttonWithType:UIButtonTypeCustom];

[b setBackgroundImage:[self buttonBackgroundImage]
             forState:UIControlStateNormal];

[b setImage:[self buttonImage]
   forState:UIControlStateNormal];

[b setTitle:NSLocalizedString(@"Click me!", nil)
   forState:UIControlStateNormal];

[b sizeToFit];

We call sizeToFit and end up with this:

The button elements are all crammed together with no spacing. This is expected, and to fix this we need to give the button some insets.

UIButton provides three UIEdgeInsets properties that you can play with to adjust the spacing of the elements in the button. These are contentEdgeInsets, imageEdgeInsets and titleEdgeInsets.

If you've ever tried adjusting these in Interface Builder, you'll know things can get a little... interesting. For example, you may have tried increasing imageEdgeInsets.left 1 point at a time and seen how the button image seems to move unpredictably, sometimes making big steps between values:

The reason for this is that a positive inset value will shrink the layout rectangle for the image and give you you unpredictable results as the button tries to fit the image into a bounding box which is too small.

The documentation for UIEdgeInsets describes what insets represent:

Edge inset values are applied to a rectangle to shrink or expand the area represented by that rectangle. Typically, edge insets are used during view layout to modify the view’s frame. Positive values cause the frame to be inset (or shrunk) by the specified amount. Negative values cause the frame to be outset (or expanded) by the specified amount.

What this means is that if we want to reliably shift the image or text, we must add or subtract equal (but opposite) amounts to both left/right or top/bottom insets.

Confused? I'm not surprised. To help you visualize all this more easily and see the effect of sizeToFit at the same time, I've written a little iPhone app called ButtonInsetsPlayground. The source is available on github.

Please forgive the made-by-a-programmer UI, this is purely for testing.

If you play around with this UI for a while, you should end up even more confused than you were before. I seriously considered cracking out IDA and diving in to the UIButton internals to figure out what is going on, but I really want to finish this post. (hint to the curious: the relevant selectors are -[UIButton contentRectForBounds:], -[UIButton titleRectForContentRect:] and -[UIButton imageRectForContentRect:])

What you need to know is the following...

contentEdgeInsets

contentEdgeInsets is pretty intuitive and will behave as you expect. You can easily add space around both the image and text to pad things out nicely. Use positive values to inset the content. The implementation of sizeThatFits: causes the button to grow appropriately when we call sizeToFit:

UPDATE: I originally wrote about how it's possible to get pixel misaligned images with certain content insets. Naturally, this turned out to be my own fault.

imageEdgeInsets and titleEdgeInsets

The golden rule when it comes to these two insets is to add equal and opposite offsets to the left and right insets. So if you add 5pt to the left title inset, you must apply -5pt to the right. This means you are using these insets only to offset the image or text, not to resize them in any way.

If you do not follow this rule, the calculated layout rect for the title (or image) may become too small and you risk text truncation and other unexpected results:

This problem may not reveal itself until you have a string of the appropriate length, so if the text in your buttons is dynamic or localization-aware you need to be careful.

The top/bottom insets do not seem to have any major issues, but you should probably follow the same rule for these as well.

UIButton's mystical insets behaviour could be the topic of an entire blog post of its own, but I think we have enough information to continue on our way.

Finishing up

Back to our button.

We want to space out the elements a little better, and make sure sizeToFit does the right thing.

First we'll add some left and right content insets:

// ...
UIEdgeInsets contentInsets =
    UIEdgeInsetsMake(0.0f, 15.0f, 0.0f, 15.0f);

[b setContentEdgeInsets:contentInsets];
[b sizeToFit];

Next we want to shift the text to the right, to create some space between it and the image. Following our golden rule, we add equal but opposite amounts to the left and right insets:

// ...
UIEdgeInsets titleInsets =
    UIEdgeInsetsMake(0.0f, 8.0f, 0.0f, -8.0f);

UIEdgeInsets contentInsets =
    UIEdgeInsetsMake(0.0f, 15.0f, 0.0f, 15.0f);

[b setTitleEdgeInsets:titleInsets];
[b setContentEdgeInsets:contentInsets];

[b sizeToFit];

Finally, we adjust the content insets again to add some extra space on the right for our inset text:

UIEdgeInsets titleInsets =
    UIEdgeInsetsMake(0.0f, 8.0f, 0.0f, -8.0f);

UIEdgeInsets contentInsets =
    UIEdgeInsetsMake(0.0f, 15.0f, 0.0f, 15.0f);

CGFloat extraWidthRequiredForTitle =
    titleInsets.left - titleInsets.right;

contentInsets.right += extraWidthRequiredForTitle;

[b setTitleEdgeInsets:titleInsets];
[b setContentEdgeInsets:contentInsets];

[b sizeToFit];

And at long last, we're finished. We can set arbitrarily long titles on the button, call sizeToFit, and we get correct results.

I hope this has been useful. If you can provide further insight into UIButton's layout behaviour, I'd love to hear from you!

You're Doing It Wrong #1: NSLog("Debug"); (iOS Development)

Logging. Ah, yes... the age-old problem.

In the world of iOS development, the trusty NSLog macro is used by many to print out debug information.

It's not uncommon to see delights such as this in a battle-worn developer's code:

NSLog(@"DEBUG: got here 2");
while ([self retainCount]) {
    [self release];
    NSLog(@"DEBUG: retain count is now: %u", [self retainCount]);
    // lol i have no idea what i am doing
}

If we look past the egregious memory management techniques being employed here, we see some pretty typical NSLog usage. The problem here is that NSLog is not actually meant for debug messages such as these.

If we read the NSLog documentation we find this description:

NSLog

Logs an error message to the Apple System Log facility.

Logs an error to the Apple System Log facility. Not a debug message, an error.

So what does this matter as long as we see the message in the debug console?

Well, the problem is that NSLog messages will appear in a device's log even in release builds.

To demonstrate this, I tapped around some of the apps on my iPhone. Looking at the device console via Xcode's Organizer, I saw a bunch of messages which are clearly meant for debugging purposes:

Flight Control

FlightControl[12724] <Warning>: Free space on file system: 2537136128 bytes
FlightControl[12724] <Warning>: authenticateWithCompletionHandler: enter
FlightControl[12724] <Warning>: authenticateWithCompletionHandler: exit
FlightControl[12724] <Warning>: ---URLSTR: file:///var/mobile/Applications/.../Library/Caches/CC_Data/index.htm
FlightControl[12724] <Warning>: query: (null)
FlightControl[12724] <Warning>: ---URLSTR: file:///var/mobile/Applications/.../FlightControl.app/res/more_games/index.htm
FlightControl[12724] <Warning>: query: (null)
FlightControl[12724] <Warning>: Web cache local version (v-1) is out of date, getting new version (v11)
FlightControl[12724] <Warning>: Wrote 856 bytes to '/var/mobile/Applications/.../Library/Caches/CC_Data/index.htm'
FlightControl[12724] <Warning>: Wrote 736 bytes to '/var/mobile/Applications/.../Library/Caches/CC_Data/0.jpg'
FlightControl[12724] <Warning>: Wrote 66787 bytes to '/var/mobile/Applications/.../Library/Caches/CC_Data/1.jpg'
FlightControl[12724] <Warning>: Wrote 105286 bytes to '/var/mobile/Applications/.../Library/Caches/CC_Data/2.jpg'
FlightControl[12724] <Warning>: Wrote 736 bytes to '/var/mobile/Applications/.../Library/Caches/CC_Data/3.jpg'
FlightControl[12724] <Warning>: Wrote 736 bytes to '/var/mobile/Applications/.../Library/Caches/CC_Data/4.jpg'
FlightControl[12724] <Warning>: Wrote 736 bytes to '/var/mobile/Applications/.../Library/Caches/CC_Data/5.jpg'

PONS English <-> Deutsch Dictionary

...
Phrasebook[15109] <Warning>: Morphologies: (
            {
            Basename = 4001;
            Filename = "4001.sdc";
            LanguageFrom = 1818717797;
            Path = "Phrasebook.app/4001.sdc";
            Type = 3;
        },
            {
            Basename = 4004;
            Filename = "4004.sdc";
            LanguageFrom = 1836213607;
            Path = "Phrasebook.app/4004.sdc";
            Type = 3;
        }
    )
Phrasebook[15109] <Warning>: Image test_background can't be loaded!
Phrasebook[15109] <Warning>: Image test_background can't be loaded!

Angry Birds

AngryBirds[15177] <Warning>: --> activateCrystalSetting: [set 2][val YES]
AngryBirds[15177] <Warning>: --> activateCrystalSetting: [set 2][val NO]
AngryBirds[15177] <Warning>: --> activateCrystalSetting: [set 2][val YES]
AngryBirds[15177] <Warning>: --> activateCrystalSetting: [set 2][val NO]

Red laser

RedLaser[15191] <Warning>: textLabel width: 0.000000
RedLaser[15191] <Warning>: textLabel height: 0.000000

Justin.tv

Justin.tv[15256] <Warning>: [Log Level: 4]; My Base URL is (null)
Justin.tv[15256] <Warning>: [Log Level: 4]; Final URL = https://ws.tapjoyads.com/get_vg_store_items/user_account?country_code=GB&display_multiplier=1.000000&library_version=8.1.7&udid=6e5e93e74df482fbf7f583d8c734d2ef32a1038c&app_id=48d87890-12f9-4a3e-9091-ec7d6d67beb1&lad=0&mobile_country_code=262&device_type=iPhone&connection_type=wifi&carrier_name=Telekom.de&language_code=en&os_version=5.1.1&publisher_user_id=6e5e93e74df482fbf7f583d8c734d2ef32a1038c&verifier=981aeeb7e59cd9f79ecb20390578c13906ca821c777f93541fb2e4959a8b91dc×tamp=1339496108&allows_voip=yes&app_version=3.7.4&mobile_network_code=01&carrier_country_code=de&platform=iOS&mac_address=145a059a0c78&device_name=iPhone3%2C1 
Justin.tv[15256] <Warning>: [Log Level: 4]; Update Account Info Response Returned
Justin.tv[15256] <Warning>: [Log Level: 4]; TJC: Updating Currency Name in Cache

Dropbox

Dropbox[12755] <Warning>: [ANALYTICS] {"retry":0,"favorite":false,"extension":"txt","id":[snip],"cached":false,"ts":"1341324832.83","event":"file.view.start","size":133}
Dropbox[12755] <Warning>: [INFO] DocumentViewController -(void)startLoading
Dropbox[12755] <Warning>: [ANALYTICS] {"id":[snip],"ts":"1341324832.88","size":133,"event":"download.start","extension":"txt","connection":"wifi"}
Dropbox[12755] <Warning>: [INFO] FileViewController - (BOOL)shouldAutorotateToInterfaceOrientation:(UIInterfaceOrientation)interfaceOrientation orientation = 1
Dropbox[12755] <Warning>: [ANALYTICS] {"path_hash":[snip],"event":"metadata.load.success","ts":"1341324833.14"}
Dropbox[12755] <Warning>: [ANALYTICS] {"ts":"1341324833.56","screen":"DocumentViewController","event":"screen.view"}
Dropbox[12755] <Warning>: [INFO] FileViewController - (BOOL)shouldAutorotateToInterfaceOrientation:(UIInterfaceOrientation)interfaceOrientation orientation = 4
Dropbox[12755] <Warning>: [INFO] DocumentViewController - (void)willAnimateRotationToInterfaceOrientation:(UIInterfaceOrientation)interfaceOrientation duration:(NSTimeInterval)duration
Dropbox[12755] <Warning>: [INFO] FileViewController - (void)willAnimateRotationToInterfaceOrientation:(UIInterfaceOrientation)interfaceOrientation duration:(NSTimeInterval)duration
Dropbox[12755] <Warning>: [ANALYTICS] {"id":[snip],"ts":"1341324834.89","size":133,"event":"download.success","extension":"txt"}
Dropbox[12755] <Warning>: [INFO] DocumentViewController - (BOOL)webView:(UIWebView *)webView shouldStartLoadWithRequest:(NSURLRequest *)request navigationType:(UIWebViewNavigationType)navigationType 5 url = about:blank
Dropbox[12755] <Warning>: [INFO] DocumentViewController 0x4bb4640 - (void)webViewDidStartLoad:(UIWebView *)webView 0x4bbf870
Dropbox[12755] <Warning>: [ANALYTICS] {"id":[snip],"event":"file.view.success","ts":"1341324835.41"}
Dropbox[12755] <Warning>: [INFO] DocumentViewController 0x4bb4640 - (void)webViewDidFinishLoad:(UIWebView *)webView 0x4bbf870

This is messy. And this blog post post was looking pretty slick before I pasted this crap in.

Debug messages like this should never appear in a release build, at least by default. They clutter up the device log with unimportant developer left-overs, and can potentially reveal sensitive information about an app or user.

Now sure, the logs shouldn't really be accessible to outside parties, but it's still a bad idea to allow this kind of information to leak from your app. Quite simply, it's unprofessional.

As you can see from the logs above (and by testing this yourself), NSLog will post a message to the system log with the <Warning> priority.

Apple's description of the various logging levels describes a warning as meaning:

Something is amiss and might fail if not corrected.

This isn't what we want for our debug messages. If we read a little further in the documentation, Apple gives us their logging best-practices. It's worth reading it all if you have the time:

Adopt Best Practices for Logging

Treat your log messages as a potentially customer-facing portion of your application, not as purely an internal debugging tool. Follow good logging practices to make your logs as useful as possible:

• Provide the right amount of information; no more, no less. Avoid creating clutter.
• Avoid logging messages that the user can't do anything about.
• Use hashtags and log levels to make your log messages easier to search and filter.

In order for the log files to be useful (to developers and users), they must contain the right level of detail. If applications log too much, the log files quickly fill up with uninteresting and meaningless messages, overwhelming any useful content. If they log too little, the logs lack the details needed to identify and diagnose issues.

It's at this point that you probably got tired of reading this excerpt. So here's a cute picture of a kitten to keep you going.

If you looked ahead and got distracted by the kitten, I apologize.

Logging excessively makes the log files much harder to use, and decreases the value of the logs to your user (who can't easily find the important log messages), to you (who can't easily use the log messages to aid in debugging), and to other developers (whose applications' log messages are buried under yours).

[...]

If you log debugging information, you should either disable these messages by default or log them at the Debug level. This ensures that your debugging messages don't clutter up your (and your users') logs.

So you kinda get the feeling that this stuff applies more to the desktop than a mobile device, right? Wrong. We're professionals, and it's clear we need a better solution than NSLog. Even the kitten agrees.

Quick and Dirty

One quick and dirty way to improve things is to write a custom logging macro that will still use NSLog, but that turns into a NOP during a release build:

#ifdef NDEBUG
    // do nothing
    #define MyLog(...)
#else
    #define MyLog NSLog
#endif

NDEBUG is a standard macro that means "no debug" or "release mode". This will usually be defined in the Release configuration of your target's build settings.

With this little snippet of code we get a new MyLog macro which is a simple alias to NSLog when debugging, and which will turn into a no-op in our release builds. For genuine error conditions, we can stick with NSLog and the error output will always be sent to the device log. Hurrah!

There's one niggling detail, though. Our debug statements and our error messages are both going to be logged with the <Warning> priority. What the hell, NSLog? And I thought the documentation said you were supposed to log errors, not warnings. Just who the hell do you think you are?

This doesn't sit right with me. This doesn't sit right with me at all. I want to see <Debug> and <Error> in my logs, gosh-darn-it.

The Apple System Log facility

So Apple has just been telling us that we should use the APIs™ and that we get a bunch of awesome advantages when doing so. The API that Apple is referring to is the Apple System Log facility, or ASL.

Now it's at this point that some people would jump into a well thought-out introduction to the Apple System Log: its history, how it works, and maybe a few flow diagrams. I'm too lazy for that right now, so I'm just going to show you this "Hello, World!" example from the asl man pages:

#include <asl.h>
// ...
asl_log(NULL, NULL, ASL_LEVEL_INFO, "Hello World!");

OK, so we include a header... call asl_log... ignore a bunch of arguments we aren't interested in, and- oh hey, look. We can specify a logging level. Neat.

ASL has a lot of features, but all we're interested today is creating a bunch of simple logging functions so we can distinguish between debug messages, errors, warnings, natural disasters, etc. We aren't going to worry about fancy features like logging to custom files or network sockets.

If we use asl_log as in the above code sample (with the first argument as NULL), we get a simple thread-safe way (albeit through locking) to log messages to the system log at different levels.

The full list of log levels can be found in asl.h. I've listed these below, along with the corresponding descriptions from Apple's guidelines:

ASL_LEVEL_EMERG

The highest priority, usually reserved for catastrophic failures and reboot notices.

ASL_LEVEL_ALERT

A serious failure in a key system.

ASL_LEVEL_CRIT

A failure in a key system.

ASL_LEVEL_ERR

Something has failed.

ASL_LEVEL_WARNING

Something is amiss and might fail if not corrected.

ASL_LEVEL_NOTICE

Things of moderate interest to the user or administrator.

ASL_LEVEL_INFO

The lowest priority that you would normally log, and purely informational in nature.

ASL_LEVEL_DEBUG

The lowest priority, and normally not logged except for messages from the kernel.

This is looking more and more like the typical logging frameworks we see on other platforms.

By default, ASL will only record messages at priority ASL_LEVEL_NOTICE and above. This means that although we will be using the ASL system, our debug messages will not be visible in the device logs by default. This is good, but it's still a good idea to turn our debug statements into no-ops in a release build. One reason is performance: we don't want logging commands to affect performance sensitive areas of our code.

Getting down to it

So with all that out of the way, we can begin to implement some new logging macros using the ASL API.

The first thing we'll do is define a macro which will let us compile-out log statements at a certain level when in release mode:

#ifndef MW_COMPILE_TIME_LOG_LEVEL
    #ifdef NDEBUG
        #define MW_COMPILE_TIME_LOG_LEVEL ASL_LEVEL_NOTICE
    #else
        #define MW_COMPILE_TIME_LOG_LEVEL ASL_LEVEL_DEBUG
    #endif
#endif

When we are in release mode the default compile-time log level will be ASL_LEVEL_NOTICE. We want messages at "notice" and above to be sent to the system log, and everything else to be completely compiled out of our code by the preprocessor. We'll see how this is done in a moment.

When we are in debug mode, the log level will be ASL_LEVEL_DEBUG so messages at "debug" and above (i.e. all messages) will be compiled into our code.

We can also override the default value of MW_COMPILE_TIME_LOG_LEVEL with custom compiler flags in our application's build settings. This lets us control the log level for different targets and configurations.

Next we define macros for each log level that we want to support. Starting with the "emergency" level we get:

#if MW_COMPILE_TIME_LOG_LEVEL >= ASL_LEVEL_EMERG
    void MWLogEmergency(NSString *format, ...);
#else
    #define MWLogEmergency(...)
#endif

If the "emergency" log level is allowed by the value in MW_COMPILE_TIME_LOG_LEVEL, we define a typical log function which accepts a format string and arguments. Otherwise we turn it into a no-op and the statement will get compiled away by the preprocessor.

We repeat similar code for each of the different log levels:

#if MW_COMPILE_TIME_LOG_LEVEL >= ASL_LEVEL_ALERT
    void MWLogAlert(NSString *format, ...);
#else
    #define MWLogAlert(...)
#endif

//
// ... SNIP ...
//

#if MW_COMPILE_TIME_LOG_LEVEL >= ASL_LEVEL_DEBUG
    void MWLogDebug(NSString *format, ...);
#else
    #define MWLogDebug(...)
#endif

Next we write the implementations for all of these functions. We can use some more macro hackery to avoid duplicated code. In small confined situations like this, macros actually aren't pure evil:

#define __MW_MAKE_LOG_FUNCTION(LEVEL, NAME) \
void NAME (NSString *format, ...) \
{ \
    va_list args; \
    va_start(args, format); \
    NSString *message = [[NSString alloc] initWithFormat:format
                                               arguments:args]; \
    asl_log(NULL, NULL, (LEVEL), "%s", [message UTF8String]); \
    va_end(args); \
}

__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_EMERG, MWLogEmergency)
__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_ALERT, MWLogAlert)
__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_CRIT, MWLogCritical)
__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_ERR, MWLogError)
__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_WARNING, MWLogWarning)
__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_NOTICE, MWLogNotice)
__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_INFO, MWLogInfo)
__MW_MAKE_LOG_FUNCTION(ASL_LEVEL_DEBUG, MWLogDebug)

#undef __MW_MAKE_LOG_FUNCTION

If we expand out one of the macro invocations we can see what is generated for the MWLogDebug function:

void MWLogDebug (NSString *format, ...)
{
    va_list args;
    va_start(args, format);
    NSString *message = [[NSString alloc] initWithFormat:format
                                               arguments:args];
    asl_log(NULL, NULL, (ASL_LEVEL_DEBUG), "%s", [message UTF8String]);
    va_end(args);
}

This is pretty straight forward. Note that by passing a NULL client as the first argument to asl_log we get the default concurrency behaviour:

Multiple threads may log messages safely using a NULL aslclient argument, but the library will use an internal lock, so that in fact only one thread will log at a time.

For a simple NSLog replacement, this fine. If you wished, you could create a new client for each thread that you encounter, although managing the lifetime of this object might be a little tricky.

OK, we're almost done. I mentioned that by default, messages below the "notice" level will not be visible in the system log. Additionally, if we tried using the MWLogDebug as it is now, we wouldn't see anything in the debug console.

Fortunately ASL let's us send our messages to additional file descriptors. If we add the STDERR file descriptor to the logging facility, we'll be able to see our messages in the debugger:

asl_add_log_file(NULL, STDERR_FILENO);

We only need to call this once, so with the help of GCD's dispatch_once we'll add the following function to our implementation file:

static void AddStderrOnce()
{
    static dispatch_once_t onceToken;
    dispatch_once(&onceToken, ^{
        asl_add_log_file(NULL, STDERR_FILENO);
    });
}

...and then modify our logging function to call it:

#define __MW_MAKE_LOG_FUNCTION(LEVEL, NAME) \
void NAME (NSString *format, ...) \
{ \
    AddStderrOnce(); \
    va_list args; \
    va_start(args, format); \
    NSString *message = [[NSString alloc] initWithFormat:format arguments:args]; \
    asl_log(NULL, NULL, (LEVEL), "%s", [message UTF8String]); \
    va_end(args); \
}

And we're done. We can now test this stuff out. If we run the following code:

MWLogError(@"This is an error");
MWLogDebug(@"This is a debug statement");
MWLogWarning(@"This is a warning");

We'll see this in our device log:

Example[12268] <Error>: This is an error
Example[12268] <Warning>: This is a warning

And we'll see this in our debug console:

Example[12268] <Error>: This is an error
Example[12268] <Debug>: This is a debug statement
Example[12268] <Warning>: This is a warning

Each message is marked with the appropriate level, and the debug message is only output to the debug console, not the device log. If you do want to change the level at which messages are sent to the device log, you can call the asl_set_filter function with an appropriate mask like this:

asl_set_filter(NULL, ASL_FILTER_MASK_UPTO(ASL_LEVEL_DEBUG));

After calling this, all messages (including at the DEBUG level) will be sent to the device log.

So after all that, we've implemented a very simple alternative to NSLog which uses the standard Apple System Log facility, and ensures your debug messages will not appear in customer device logs.

You can find the source code at github which you can use without restriction.

Working more efficiently by using Breakpoints

Now that we've got our brand-spanking-new logging functions, I'd like to take a few moments to discuss efficiency.

Think about how much time you waste every day writing debug statements in code. Imagine you are looking at your app running on a device, and you want to examine the value of a variable or see how it changes over time.

We all know the debugger can do this for us, but it's so easy to revert to bad habits and write a log statement instead. Think about the steps involved. You have to stop your running app, write some code like MWLogDebug(@"myValue is now %@", myValue), recompile, run your app again, and then navigate back to the view that triggers the code.

This isn't a huge amount of time when you look at just one instance. But over the course of an entire day, week, or year, this edit/compile/debug cycle is wasting a huge amount of your development time.

There is a far more efficient way to get this kind of information, without stopping your app, by using breakpoints. I would highly recommend you watch Session 412 - Debugging in Xcode from WWDC 2012 for more information about this. If you aren't using breakpoints in your day-to-day development, you should really watch this video.

Comments?

So that rounds up the first post of this series. If you have comments or suggestions please use the form below or email me.

You're Doing It Wrong #0: Introduction

Hi there. I've started this blog so I can post articles on iOS development.

I've been developing for the iOS platform for a few years now, and though I'm still learning new things every day I feel like it's time I shared some of the things I've learnt.

The general theme is "You're Doing It Wrong", and each post will tackle one of the many anti-patterns or bad practices that I've witnessed over the years, and hopefully provide you with a better solution.

I will be updating this post with links to each entry as they are published. Stay tuned.

The posts so far:

• You're Doing It Wrong #1: NSLog("Debug");