Explore logging in Swift

Hello and welcome to WWDC.

Welcome to Explore Logging in Swift. I am Ravi Kandhadai Madhavan, an engineer at Apple. In this talk, I will show you how to make your apps easier to debug using Apple's unified logging APIs, also known as os_log. I will talk about how to collect logs from a device you have access to. I will demonstrate the tools available to analyze logs in order to understand and fix problems with your app.

I will cover how to control performance of log calls and improve readability of log messages using formatting options.

Bugs are important to fix. Users expect quality apps to be reliable and have few bugs. Even minor bugs can lead to a poor user experience. However, some bugs are more difficult to fix than others. Often, the most elusive are those that are hard to reproduce during development. Logs are a valuable tool for finding and fixing hard-to-reproduce bugs. They provide a trail of clues that you can follow to understand a bug without even having to reproduce it. I will now show you a hard-to-reproduce bug in an app that I'm developing. I will later show how I can add logging to help understand and fix this bug.

My app, called Fruta, lets users purchase smoothies. I can browse through these smoothies, tap on a smoothie, and also purchase one.

I've recently added a "Gift Cards" feature to my app. I've created a new tab for browsing through gift cards. I can tap on a card to purchase it using Apple Pay. When I scroll through the cards and reach the end, my app will start loading more cards by communicating with a server. When I select a card by tapping on it, my app will stop the loading of cards and any ongoing communication. However, I can go back and continue looking at more cards. This works most of the time. Unfortunately, sometimes I see a bug. When my app is loading more cards, if I tap on a card, the loading occasionally fails with an error.

This is frustrating because it doesn't happen near my development machine. It happens very rarely, so I am not able to reproduce this under the debugger. Adding logging to your app can help you understand errors like this one without needing to reproduce them at your desk. In Xcode 12, we have introduced new Swift APIs for unified logging. You can use these APIs to record important events happening in your app as it runs. These logs are archived by the operating system so you can retrieve them later from the device. Because these new APIs are very efficient, they can be widely used without slowing down your app.

All it takes to add logging to your app is three simple steps. First, import the "os" module which defines the new logging APIs. Second, create an instance of the type "Logger," passing it a subsystem and category. These will be attached to every message logged by the Logger.

Subsystem is typically a bundle identifier which helps identify a message coming from your app. You can use the category to further distinguish messages coming from different parts of your program.

Here, I've used the "Gift Cards" category for my Logger.

Third, add logging to interesting places in the code by calling a method on the logger instance. Here, I've added a log every time my app downloads data from a server.

With Logger, you can add runtime data to the log message using string interpolation. For instance, here I'm adding a task identifier to the log message. This is similar to calling the print function.

However, log messages are different in a key way. Unlike with print, the log message is not fully converted to a string, as that would be too slow. Instead, the compiler and the logging library work together to produce a heavily optimized representation of the log message that leverages the type of the logged data. With the optimized representation, you pay the cost of converting to a string only when the log message is actually displayed. Log messages can contain a wide variety of data types. You can log numeric types like Int and Double, Objective-C objects, as well as any type that conforms to Swift's CustomStringConvertible protocol. This means to add your own type to a log message, all you need to do is make it conform to CustomStringConvertible. When adding runtime data to a log message, you should be aware that a non-numeric type, like a string or an object, will be redacted in the logs by default. This is done to ensure that after your app ships and is running on your user's device, the logs do not show any personal information.

For instance, here I'm logging a message along with the bank account number of a user which is represented by a string. In the output logs, the account number will be redacted as private.

However, data that does not handle any sensitive information can be made visible in the logs. When you log runtime data, pass a value .public to an optional parameter privacy, as shown here.

Now the logs will display the contents of the data. Here, it's the name of a smoothie. I will say more about privacy later.

When your app logs a message, the operating system stores it on device in a compressed form. You can use the "log collect" command on your Mac to retrieve those logs. First, connect your device to your Mac. Next, run the "log collect" command from the terminal with the device option.

Provide a start time from when you need the logs, typically, a few minutes before you first saw a bug. Also, provide a file name for storing the log archive. You can open log archives in Console app by double-clicking on them. This app makes it easy to browse logs and filter them. Let us see how I can use logging to understand the hard-to-reproduce bug in the Fruta app I showed previously. I have already added logging to the source code of the gift cards view.

I imported the os module to get access to the logging APIs and created a logger with a bundle identifier and "Gift Cards" category. I have added logging to record interesting events performed by this view. For instance, when the app starts a task to communicate with the server, it now logs a UUID that uniquely identifies the task. Since the identifier does not contain sensitive information, I made it public so that it's visible in the logs. Using log collect, I've extracted the logs of the Fruta app to a log archive. Now I will open it in Console app.

There are lots of log entries here. This is because the log archive contains messages logged by all processes in the system. I can use the "search" and "filter" features of the Console to narrow down on the logs I am interested in. First, I'll filter by subsystem-- in this case, my app's bundle identifier-- to limit the display to only messages from my Fruta app.

I will click on the search field at the top right, enter the subsystem...

and select "subsystem" from the drop-down list.

I can scroll through just my app's logs and find the message that corresponds to the failure.

But since my app is logging so much, there are still too many entries for me to understand what else has gone wrong. What I really need is a way to narrow down on the problem. My logged task identifiers provide the solution.

I can filter by the task identifier of the failed task to see only logs that are relevant to the failure. I will do that now by adding the task identifier as another keyword to the search field.

Now there are only a few logs. I can read through them and understand the error.

The first entry shows that the app is starting a task to fetch more gift cards. Then I see that the task is completed due to a network error and is waiting to retry after a timeout.

The next entry shows that in the meantime, the user has selected a gift card, which attempts to stop the task. But since there is no active task at this point, the app finds itself in an inconsistent state and fails.

This is enough for me to reconstruct what has actually happened. By selecting a card, I attempted to stop a task from loading more gift cards at a time it had already stopped due to a network error. This explains why this bug was so hard to reproduce. It's dependent on the timing of events and a network error. Thanks to the logs, I am now able to understand the bug and fix it.

We saw that using "log collect" command, you can collect logs after your app has finished running. It is also possible to stream logs while your app is running. If your device is connected to your Mac, you can stream log messages as they happen in Console app. If your app is launched from Xcode, you will also see them in Xcode's console. This is a helpful alternative to "printf" debugging with more structured output that can be easily filtered.

You might have noticed when I was browsing through logs in Console app that the "failure" message was highlighted. This is because I logged it with the fault log level. The logging APIs provide five log levels for indicating importance of messages.

In the increasing order of their importance, they are debug, info, notice, which is also the default level, error, and fault.

Use the debug level for messages that are useful only during debugging. The info level is for messages that are helpful but not essential for troubleshooting errors. Notices indicate that the message is absolutely essential for troubleshooting. You can use the error level to record errors that happen during execution. The fault level is the most severe. You should use it to record situations that arise due to a potential bug in the program. For example, to record that an assumption that the program expects to hold is violated at runtime. The error and fault levels are highlighted with yellow and red bubbles in Console app.

The Logger type has methods for each log level. For example, to log a debug message, call the debug function on a logger. While choosing a log level, an important thing you must consider is persistence. That is, whether a log message is archived and can be retrieved later after the app has finished executing. The logs that aren't persisted can only be streamed while the app is running. Whether a message is persisted or not depends on the log level. Persistence increases with the method's importance.

Debug level messages are not persisted, which means they cannot be retrieved after the app has completed execution. Info error messages are mostly not persisted, except when they are generated a few moments before a log collect command. Messages logged at every other level are persisted, and you can retrieve them later. There is, however, a storage limit on how many messages are archived. Once that limit is exceeded, the older ones are purged and become unavailable. The error and fault level messages are persisted even longer than notice level messages. Typically, the messages will be persisted for a few days. However, it depends on the storage space on your device.

The log levels also affect performance. Even though logging in general has low overhead, the log levels have different performance relative to each other. The levels that are less important are faster. The fault level is the slowest, and the debug level is the most performant.

Logging at the debug level is so fast because debug messages are not persisted at all. They are discarded when the logs aren't being streamed. Further, the Swift compiler uses sophisticated optimizations to ensure that the code that creates the messages is not even executed when the debug messages are discarded. This means that you can log verbose messages at the debug level and call expensive functions to construct messages. Your users won't pay the cost for them.

As I showed with my Fruta app, including runtime data, such as task identifiers, in a log message made it more useful for debugging. However, raw data such as numbers and strings can be hard to understand and interpret. The Logging APIs offer many ways to format data for readability with no runtime cost. Let us return to the Fruta app to see how formatting of log messages can help with debugging. I see a performance problem in the gift cards view. Sometimes loading cards takes too long. The app uses multiple servers to load gift cards. I suspect that the performance problem is related to which servers are chosen. To investigate this, I've added some logging to gather some statistics about the communication with servers.

For each task, I log the task identifier, the identifier of the gift card that was fetched, the server that served the request, and the total duration the task took to complete.

Now I will plug in my iPhone to my Mac and run the app from Xcode and view the logs in Xcode's console.

Unfortunately, the logs are very hard to understand, as they are not aligned well. I will now use the formatting options to make this look better.

First, let me make the gift card identifier fixed-width by displaying the maximum number of characters a card identifier can have.

I will also round off the duration to two decimal places, since I don't need that much precision.

Let me relaunch the app and view the logs again.

Now you see that the logs are much easier to read. In fact, since they are aligned well, I can even hold down the option key and copy the fields using "column select." I will paste them in Numbers and visualize the data.

With this graph, I can immediately notice that the slow tasks are all served by server three, so I will take that server off-line for maintenance.

To recap, you can use the optional "format" and "align" parameter to format data. Since formatting data using the Logging APIs doesn't add to the cost of a log call, you can use formatting as much as you like to make your data look pretty and easy to understand. The Logging APIs provide many formatting options, of which I only showed you a few.

You can see the full range of options using Xcode's code completion, including formatting numbers as hexadecimal, octal, exponential, and others.

As we saw before, you can use privacy options to control the visibility of data in the logs. It is really important to take seriously the privacy of the logged data. This is because logging happens all the time, even after your app has shipped and is in the hands of your users. Logs can be collected by anyone who has physical access to the device and also its passcode. Therefore, it is important that the log messages do not mark any personal information public, which could expose it in the logs.

You can get a lot of the same benefits as using public without actually doing so by using an equality-preserving hash. This does not reveal the content of the data but still allows you to know when the logged values are the same, which can help in filtering logs.

For example, here I'm passing a mask parameter to the .private privacy option in order to log a customer's bank account number with a hash. This lets me find out when two log messages refer to the same account without revealing the account number.

The Logger APIs I described are available in iOS 14. If your app targets prior releases, you can use the os_log function that accepts printf-style format strings. Starting in this release, string interpolations can also be passed to the os_log function, just like with Logger.

To summarize, you can take advantage of new Swift logging APIs to debug problems that would otherwise be almost impossible to understand and fix. This is possible because you can retrieve logs from your development device and drill down into them without even having to reproduce the bug. The logging APIs offer you both high performance and at the same time rich formatting. Therefore, you can log informative messages, secure in the knowledge that you won't make your apps slow for your end users. Thanks for watching.