Logging. Ah, yes… the age-old problem.
In the world of iOS development, the trusty
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:
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:
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:
PONS English <-> Deutsch Dictionary
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
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.
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.
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:
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
<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 .
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:
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:
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:
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 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:
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:
If we expand out one of the macro invocations we can see what is generated for the
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:
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:
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:
And we’re done. We can now test this stuff out. If we run the following code:
We’ll see this in our device log:
And we’ll see this in our debug console:
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:
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.