Pranav Kasetti

Why you shouldn't be using print()

11 August 2021

This blog post is about how to use the new os Logger class in iOS 14.0+ to create a useful, privacy-friendly, scalable logging solution for Swift apps without resorting to 3rd Party logging services.

OS Logging is now preferred over NSLog and print statements due to multiple reasons which we outline. os_log has also been further improved and makes OS Logging more appealing because we can support devices > iOS 10.

Requirements:

iOS 14.0+
Any Physical Apple device (iPad, iPhone, and Mac recommended rather than Watch due to more stable frameworks). Simulators could work in Release mode, but we can't test out how we'd view the logs from an actual device).
Apple Developer Program account to run on iOS or iPadOS device

Introduction

The screenshot below shows device log messages from a real iPhone 8 Plus:

The screenshot shows the Console.app macOS Application running on a Catalina machine connected to an iPhone via USB-C (we could also use wireless debugging though). We can see timestamps and associated log messages from various iPhone processes (think of these as running apps or daemons). As we can infer from the title, this post focuses on best practices for these types of log messages (focusing on OS Logging rather than print).

End-users are able to view these logs by simply connecting the device to a Mac and opening Console.app. These logs cannot be viewed on the device itself, except in sysdiagnose logs.

TIP: Trigger Spotlight with CMD Space and type Cons to jump quickly to Console.

Why use `os_log` and `Logger` instead of `print` statements?

Apple recommend using OS Logging which is why I have used this approach rather than print statements. The new Logger API in iOS 14 is really easy to use with support for string interpolation. os_log is still needed for devices running iOS 10 - 13 however.

OS Logging is also called the Unified Logging System.

OS Logging is a great way to efficiently print out information and has much lower overhead than print or NSLog. That being said, the .fault and .error messages have higher overhead than .debug because they are persisted.

OS Logs are easy to filter through in Console by category, subsystem, log level and time. They also show up in the Xcode console as we'd expect for print statements. Thus they perform the same function but are more customisable.

OS Logs are persisted on the device for more important log levels like .fault and .error. They are not uploaded to a server, and thus maintain user privacy.

OS Logging makes it easy to redact private information using the .public and .private modifiers. This prevents malicious actors from gaining personal information even with the device in hand.

We can now format messages using hexadecimal, octal, exponential representations and even encrypt messages with hash functions. Decimal places and number of columns can also be configured for pretty printed output. String interpolation (added in iOS 14) makes the API even easier to use.

As can be inferred from the name, OS Logs can be used across all Apple devices including Darwin, iPad, iPhone and Apple Watch. They can also be used seamlessly in Swift and Objective-C codebases. Most devices these days are newer than iOS 10, so logging will work for the majority of applications.

What is the `os` framework?

os is a framework produced by Apple in 2014, which has been steadily been improving every year with more features. In case you have never heard of this framework, that's fine. Most iOS developers should never need to use this framework because as it's name suggests, it is a low-level library. os is also more useful in macOS development rather than iOS.

From the os documentation:

Coordinate the scheduling and synchronization of your app’s tasks, and log information to the console to diagnose issues.

We will be using the os framework to enable OS Logging for our apps with os_log and Logger.

How do I write good OS Logs?

"OS Logging sounds cool. Can you share some code?" - You

I'm glad you asked. Let's go through an example.

Create a file called LoggingService.swift with the following code:

import os.log

@available(macOS 11.0, iOS 14.0, *)
extension Logger {
  private static var subsystem = {
    Bundle(for: ViewController.self).bundleIdentifier!
  }()

  @available(macOS 11.0, iOS 14.0, *)
  static let payments = Logger(subsystem: subsystem, category: "payments")
}

extension OSLog {
  static let payments: String = "payments"
}

This is an extension on Logger that we can use for logging payment flows in our app e.g. Apple Pay. Notice how we've used the bundle of a class in our desired target:

Bundle(for: ViewController.self)

If you haven't seen .self before that's a way of getting the type of a class. self is an instance of the type, and Self is the type itself. The return type of ViewController.self is a metatype named Type.

Debug logs

Below the above extension, we can define custom Debug logging for our payments flow:

@available(macOS 10.12, iOS 10.0, *)
func DLog(message: StaticString, file: StaticString = #file,
          function: StaticString = #function, line: UInt = #line,
          column: UInt = #column, type: OSLogType = .info,
          bundle: Bundle = .main, category: String = OSLog.payments) {

  // This method is only for iOS 14+
  let customLog = OSLog(subsystem: bundle.bundleIdentifier!,
                        category: category)
  Logger.payments.debug("File: \(file) :: Function: \(function) :: Line: \(line) :: Column: \(column) - \(message, privacy: .private)")
  
  // Fallback on earlier versions
  os_log("%@", log: customLog, type: type, ["File: \(file)", "Function: \(function)", "Line: \(line)", "Column: \(column)", message] as CVarArg)

}

Notice how we have only used Logger for iOS 14+ and used OSLog for versions above iOS 10.

Logger.payments.debug("File: \(file) :: Function: \(function) :: Line: \(line) :: Column: \(column) - \(message, privacy: .private)")

We could also use the os_log method with string interpolation as below for the same log:

os_log(log: customLog, "File: \(file) :: Function: \(function) :: Line: \(line) :: Column: \(column) - \(message)")

However, this function only supports iOS 14+. We have used the string format version above because we want to support iOS 10.0+ as well rather than only iOS 14.

The older version of os_log was cumbersome to write and also doesn't provide the same clean formatting.

OLD:

NEW:

We can see below that to print out lots of arguments, we needed to use format specifiers, and Objective-C (CVarArg):

os_log("%@", log: customLog, type: type, ["File: \(file)", "Function: \(function)", "Line: \(line)", "Column: \(column)", message] as CVarArg)

The above function prints out the filename, function name, line number and column for every message automatically. I've added these extra bells and whistles to make it easier to debug bugs. We only need to call:

DLog(message: "Payment accepted")

to print out a log message with lots of juicy debug information.

Debug logging means the message doesn't get printed in live apps. The .private modifier makes message unreadable even in Debug schemes if the Xcode debugger isn't attached. Let's now look at how to log sensitive information while protecting user privacy.

Logging sensitive information

Let's now look at how to redact sensitive information for a Logger instance and os_log.

@available(macOS 10.12, iOS 10.0, *)
func ELog(message: StaticString, userID: Int, file: StaticString = #file,
          function: StaticString = #function, line: UInt = #line,
          column: UInt = #column, type: OSLogType = .error,
          bundle: Bundle = .main, category: String = OSLog.payments) {

  // This method is only for iOS 14+
  let customLog = OSLog(subsystem: bundle.bundleIdentifier!,
                        category: category)
  Logger.payments.error("File: \(file) :: Function: \(function) :: Line: \(line) :: Column: \(column) - \(message) :: UserID : \(userID, privacy: .private)")

  // Fallback on earlier versions
  os_log("%{public}@ :: UserID: %{private}d", log: customLog, type: type, ["File: \(file)", "Function: \(function)", "Line: \(line)", "Column: \(column)", message] as CVarArg, userID as CVarArg)

}

Notice how we only have the userID marked with the .private modifier when we log using Logger. The newer APIs are clearer and simpler to hide sensitive information.

With the new os_log overloads in iOS 14, we could also write:

os_log("File: \(file) :: Function: \(function) :: Line: \(line) :: Column: \(column) - \(message) :: UserID : \(userID, privacy: .private)")

The os_log prior to iOS 14 is more cumbersome to use, as seen above:

os_log("%{public}@ :: UserID: %{private}d", log: customLog, type: type, ["File: \(file)", "Function: \(function)", "Line: \(line)", "Column: \(column)", message] as CVarArg, userID as CVarArg)

The key modifier to use is %{private}d to redact sensitive information in the legacy API.

To see Info level and Debug level logs in console, we need to select Enable debug logging and Enable info logging in the Console.app View menu.

This won't be necessary since we are testing .error level logs, but info logs can be helpful to view. They have a shorter lifetime in memory than .error logs. Note that if we don't specify a public visibility for messages, then the system decides whether to redact the information automatically.

In order to test redaction, we need to use a physical device without the debugger attached. Run the app from Xcode once, wait a few seconds, then stop the app in Xcode. Now, re-launch it by finger launching it on the home screen of the device.

Simulators are essentially debug devices, so the logs won't be redacted in the Console.

First, let's select our device on the left sidebar. We can then set the subsystem to our bundle identifier to filter through the logs.

The Logger error message can also be hashed for sensitive information like the UserID. Hashes can be useful to hide sensitive information but still enable us to correlate the same UserID via the same hash value:

Logger.payments.error("File: \(file, privacy: .public) :: Function: \(function, privacy: .public) :: Line: \(line) :: Column: \(column) - \(message, privacy: .public) :: UserID : \(userID, privacy: .sensitive(mask: .hash))")

How much logging should I do?

We've all been in that situation where we have a bug but can't understand how to reproduce it. In these edge cases, it can be helpful to view logs in addition to crash reports. While it could be cumbersome to ask the user for a sysdiagnose, the advantages of protecting user privacy and adhering to GDPR outweigh the minor inconvenience IMHO.

That being said, we shouldn't log too much to avoid 3 things:

Overwhelming the logging system: The logging system is usually very robust and can handle a few logging statements per second. That being said, if we log too much, more important log messages could be pushed out due to OOM errors.
Privacy: Apple's Logging APIs have options to redact sensitive information, but we should always avoid logging even non-sensitive information too much. This is because the app could be reverse-engineered and hacked. A compromised (rooted) device can also steal personal data by viewing files inside the app sandbox. Logging encrypted/redacted private information is fine in moderation to filter events with the same hash.
Size of the compiled binary: Adding lots of logging statements means there is more code to compile. The os library (required for OS Logging) is fairly sizable and thus increases the binary size further because it is linked statically.

General logging advice

General advice for OS logging differs from debugging locally because the logs persist in production. We need to consider several factors when OS Logging because we don't want to disable logs in production (via preprocessor directives for example).

Look at each higher-level log entries to make sure they contain info that might potentially useful while debugging. There are 5 log levels, and those above .default have more overhead. We need to use these levels sparingly and effectively.
Make sure to set the subsystem and category. The unified logging system processes a lot of log entries and the subsystem and category make it much easier for you to focus on specific problems. In Console (as we saw above), we see log entries from all device processes.

How to choose the category and subsystem?

There is no official guidance on this, so I will focus on what I think about when naming.

1. By feature (product-specific): For example, if you are a shopping app, maybe organise the subsystem by the payment, login or other app flows. If you aren't already using a modular codebase for organisation into features (or frameworks for shared code) then I can recommend this tutorial series.

2. By technology: What I mean by this is the domain of the code, is it for Push Notifications, Deep Links, User Defaults (or persistence) logic. This could be helpful for the category parameter.

3. By target: I like to also use the bundleIdentifier of the current Bundle if I can for the subsystem. This makes even more sense if you have Extension Targets (Push Notifications), multiple Targets, or different Platforms (like WatchOS, SiriKit extensions and similar). You can get the bundle of a class using this code:

let myBundle = Bundle(for: MyClass.self)

Other implications?

If you are an Apple Early-Adopter then you know how buggy some of the iOS Betas can be 🧪. When posting bug reports to Apple, the OS Logs get included in sysdiagnose files, so you may get a faster turnaround time if your bug reports have less noise.

Should I use a third-party logging service?

Depends if you can afford it and whether you really need it. I prefer to minimise the number of third-party dependencies I import in my code if I can control this. The native Apple Logging APIs are designed to be efficient and work well even without Internet access.

These services charge extra per month, but the advantage is that malicious actors cannot view the logs even if they want to by hooking the device to Console. Note that this is NOT an issue if you apply the .private log levels, so I don't use third-party services.

Three reasons to go for web-logging are simplicity for fetching logs, more security against reverse-engineering and lower restrictions for the amount of logging. In general, I would still recommend redacting or encrypting user data. Even if you trust the third-party vendor against data breaches, storing user data on servers is more risky. The important thing is to ensure user privacy and anonymisation as much as possible.

However, web logging is not as eco-friendly. It is possible to roll your own Logging server without a third-party, however this takes a lot of setup and is non-trivial. I personally use native logging in my apps, but I have worked on larger apps where third-party services helped speeded up bug-fixes (SwiftyBeaver).

You're now ready to log THE RIGHT WAY! 👏

You should find that diagnosing bugs just became a whole lot easier!

Resources

P.S Maybe I'll see you at WWDC 2022 👀 or I/O 22 😱. 😄

Software Developer