The Joys of Logging

It’s no secret that I’m a huge fan of what I call “caveman” debugging, also known as logging. Real debugging involves breakpoints, stepping, examining the call stack, looking at variables, talking to LLDB; it’s powerful stuff, and should be part of every Xcode programmer’s toolbox. But sometimes the simplest way is to drop yourself a message in the console. Sometimes, in fact, it’s the best way — for example, when you’re debugging asynchronous code, or even when you just want to confirm, on the fly, that you’re passing through the path of execution you expect.

To the average busy Swift programmer, logging to the console means print. But print has its limitations.

Take, for instance, what happens when you want to test how your app behaves when your app is launched by the receipt of a message from the system: a universal link, for instance, or a local or push notification. You can’t build and run from Xcode, because that defeats the purpose, namely to permit the app to be launched by the system. You can still debug, in the sense of pausing at a breakpoint, because you can tell Xcode to wait for the app to be launched and than attach to it. But under those conditions, you can’t print to the Xcode console; print statements don’t work.

Or you might launch the app yourself, by tapping it in the springboard. That actually happened to a co-worker the other day: he launched the app, manipulated it into the right situation, looked at the Xcode console, and saw — nothing. His print statements weren’t printing. It took him a while to figure out what had happened.

But here’s the thing. You can log under those circumstances. You just can’t do it with print. Instead, use unified logging, informally known as OSLog.

There are pros and cons to using OSLog. On the minus side, it’s kind of a pain to use, and the documentation is appallingly bad. But on the plus side, it works all the time. It works even if you didn’t launch from Xcode. It works even if you’re not connected to Xcode. It works even if Xcode isn’t even running!

How to log with OSLog

The standard approach to logging with OSLog is as follows:

  1. You import os.

  2. You define one or more global OSLog objects specifying a subsystem and a category. These are arbitrary strings that you can use for filtering messages later on, when the time comes to read your own logging.

  3. In code, at the point where you want to log, instead of print, you call os_log. There are various versions of this function, but I recommend the one that takes these parameters:

    • A static string, which may be a format string.
    • An OSLog object that you’ve previously defined. This parameter must be labelled log:.
    • Optionally, a variadic list of arguments for the format string.

Let’s try it! Here’s a simple complete example:

import UIKit
import os.log
class ViewController: UIViewController {
    let myLog = OSLog(subsystem: "testing", category: "exploring")
    override func viewDidLoad() {
        super.viewDidLoad()
        os_log(#function, log: myLog)
    }
}

We launch our app from Xcode, and we see this in the Xcode console:

2020-06-19 17:20:48.966790-0700 LogTest[17660:981322] [exploring] viewDidLoad()

Why is that better than simple print? Well, so far, perhaps it isn’t; remember, our goal is to log when print doesn’t work at all, and if print doesn’t work in the Xcode console, neither will os_log. Nevertheless, even this form of entry into the Xcode console has some advantages.

For one thing, it includes the same prefix as an NSLog call would give us. We get a timestamp, so when we’re doing things where a timestamp is useful, we don’t need to log Date(). We also get a thread number (after the colon, in the square brackets), which is very helpful when we’re checking whether things are happening on the same thread.

Another feature of this form of logging is that our OSLog category, namely "exploring", appears in square brackets. Why is that good? Well, let me ask you this: have you ever been annoyed by how much unwanted dross appears in the Xcode console when you run your app? There are all sorts of messages from the runtime and the simulator, ranging from minor notifications such as “Simulator user has requested new graphics quality” to big dumps of networking information or autolayout constraint conflicts that are not your doing (as when you show a UIAlertController’s view in .actionSheet style). But the Xcode console can be filtered; there’s a filter field at the bottom. Well, now you’ve got something to filter on, namely [exploring], letting you restrict the display to your own deliberate log messages.

(Just remember to remove your filter when you’re finished with it. Leaving a filter in place, and then wondering why nothing appears in the Xcode console, is a common mistake.)

Static strings and format strings

Now let’s try to form a more elaborate message:

        os_log("logging at \(#function)", log: myLog)

Surprise! That doesn’t compile (in iOS 13 and earlier). The reason is that we’re not permitted to calculate our message string; it has to be a static string. The solution is to treat the string as a format string. You can use the standard NSLog format strings here:

        os_log("logging at %@", log: myLog, #function)

Now we’re logging logging at viewDidLoad(). The #function expression is an argument that is substituted for the first (and in this case, only) format specifier in the format string. If you have more format specifiers, supply more arguments, separated by comma; this is a variadic parameter.

I’m going to assume that you know how to use the NSLog format specifiers. There are some caveats that apply when you’re calling NSLog, and the same caveats apply here. Make sure your format specifiers are correct for the number and type of arguments. The compiler isn’t going to help you with this, as it would with an NSLog call; that’s a definite flaw in os_log. If you make a mistake, you’ll see nonsense at best and you’ll crash at worst. Also, the variadic arguments must be compatible with Objective-C; for example, to log a Date, you’ll either have to add as NSDate or just transform it into a string manually.

Reading log messages without Xcode

We come now to the point of the discussion: how to read your os_log messages without Xcode. Instead, you use your Mac’s Console application. You’re probably familiar with it; it’s in the Utilities folder (inside Applications). But you may not have noticed that in recent years the Console application has been revamped specifically to help you read your os_log messages. Let me call your attention to two features of the Console:

  • Your simulated and real devices are listed (under Devices, in the Sources pane). Select one to see the log messages coming from that device. Astonishingly, this works for real devices even if they are not directly connected by a cable to your Mac! That’s because (usually) your Mac and your devices share a WiFi network, so the Console application can see them and will, perhaps with some delay, report your logs. (You do not have to configure your device for wireless Xcode debugging for this to work!)

  • The display can be filtered. This is perhaps the most important feature of the Console application. You type a term into the search field at the top right and hit Return; now you can use the little pop-up menu to the left of your term to specify what this term signifies. Among other things, you can filter on Process (the name of your app), on Subsystem (specified in your OSLog object, remember?), and on Category (also specified in your OSLog object).

So, launch the Console application, click on your simulated or real device in the Sources pane, and filter the display on, say the Category “exploring”. Now run the app on that simulated or real device, and watch the Console. There are your os_log messages. And this display of your messages works even when print does not.

In addition, you can use the log command-line tool to extract the logs from a device after the fact and explore them with the Console application or at the command line. So if you didn’t have the Console application configured and ready at the time you ran your app, you can still retrieve your log messages. For example:

$ sudo log collect --device-name "TheMattPhone" --last 1h

The result is that my home directory now contains a file called _systemlogs.logarchive. I can open this file with the Console application and explore it with filtering in exactly the same way as I’ve just described for a live logging stream. Alternatively, I can continue filtering with another log command:

$ log show --predicate 'category == "exploring"' system_logs.logarchive

Public and private

There’s one final turn of the screw. Keep in mind that one of the places os_log works where print does not is in a released app. If you don’t want your logging messages to appear in the log — where, after all, the user can see them using the Console application every bit as well as you can — you might want to take precautions.

Interestingly, the unified logging mechanism has already taken some precautions. When your app is not launched through Xcode, arguments to format specifiers, by default, are redacted. For instance, the example log message from earlier in this discussion logs as logging at <private>. The idea here is to prevent sensitive information from leaking out into the logs.

Sometimes, however, that is obviously what you want to have happen. After all, the whole point is to allow you to log messages in a way that can work even when your app is not launched through Xcode. The solution is to insert the word {public} after the percent-sign in your format specifier, like this:

        os_log("logging at %{public}@", log: myLog, #function)

That prints the #function output in the Console application or the log file, even when the app is not launched from Xcode.

Levels

Another way to mediate between public and private logging is by specifying the logging level at which messages are to be sent. To do so, add a type: parameter just after the log: parameter. Types are debug, info, default, error, and fault, in order of what we might call noisiness, with fault being the noisiest — it means, if we log this at all, there is an unexpected bug in the program.

The significance of logging levels is three-fold:

  • First, the levels represent degrees of persistence. A debug message is not written into the log file at all, and thus doesn’t propagate to the Console application, so it works more like print: only you can see it, and only while running the app from Xcode. The others are written into the log file, and the level reflects how hard the message will resist being expunged as time elapses and further data is accumulated.

  • Second, the levels increase in lagginess; a debug message has the least overhead, because there is no need to talk to the file-writing mechanism, and on the user’s device the format specifier arguments won’t even be evaluated, so the expense is effectively zero.

  • Finally, the levels correspond to markings in the Console app that will help you spot them. A fault message gets a red filled dot.

Simplify, simplify

At this point you’re probably wishing for a simpler formulation of an os_log call — you know, like print. Starting in iOS 14, you get it. In the first place, if you’re compiling against the iOS 14 SDK, the first parameter of an os_log call is allowed to do string interpolation; this becomes legal (though deprecated for other reasons):

        os_log("logging at \(#function)", log: myLog)

Even better, you don’t have to call os_log directly at all. Instead, replace your use of the OSLog class with the new Logger class:

    let myLog = Logger(subsystem: "testing", category: "exploring")

You can then call a method directly on your Logger object to log with that subsystem and category:

        myLog.log("logging at \(#function)")

To log at a level other than the default, use that level as the name of the method:

        myLog.debug("logging at \(#function)")

In the message string, Swift string interpolation is legal for Int, Double, Objective-C objects with a description, and Swift objects that conform to CustomStringConvertible.

The legality of Swift string interpolation here is surprising, because the point of os_log format specifiers is to postpone evaluation of the arguments, pushing it out of your app (so that your app is not slowed down by logging) and into the logging mechanism itself. Well, surprise! Thanks to the custom Swift string interpolation hooks that were introduced in Swift 5, the interpolation is postponed.

The use of custom string interpolation has two further benefits here. First, the custom string interpolation mechanism allows an interpolation to be accompanied by additional parameters specifying its behavior. That’s how you prevent a value from being redacted:

        myLog.log("logging at \(#function, privacy: .public)")

You can also use additional parameters to perform various sorts of string formatting that you would otherwise have had to perform using NSLog format specifiers, such as dictating the number of digits after the decimal point and other sorts of padding and alignment:

        myLog.log("the number is \(i, format: .decimal(minDigits: 5))") // e.g. 00001

There’s more

What I have said is not, by any means, the whole of what unified logging can do for you.
For instance, a really cool feature is the ability to inject signposts bracketing stretches of code; these can be picked up when you’re debugging with Instruments, to correlate, say, where your app is spending time or using memory with what you were actually doing at that moment.

You Might Also Like…

Rant: Xcode and the Protocol Paradox

This is a rant about an extremely useful Xcode feature that completely stops working just when you most need it to work. At the risk of giving the whole story away right at the start, I’ll just give the whole story away right at the start! The useful feature is Xcode’s ability to show you …

Rant: Xcode and the Protocol Paradox Read More »

    Sign Up

    Get more articles and exclusive content that takes your iOS skills to the next level.