Using CleanroomLogger

The main public API for CleanroomLogger is provided by Log.

Log maintains five static read-only LogChannel properties that correspond to one of five severity levels indicating the importance of messages sent through that channel. When sending a message, you would select a severity appropriate for that message, and use the corresponding channel:

  • Log.error — The highest severity; something has gone wrong and a fatal error may be imminent
  • Log.warning — Something appears amiss and might bear looking into before a larger problem arises
  • Log.info — Something notable happened, but it isn’t anything to worry about
  • Log.debug — Used for debugging and diagnostic information (not intended for use in production code)
  • Log.verbose - The lowest severity; used for detailed or frequently occurring debugging and diagnostic information (not intended for use in production code)

Each of these LogChannels provide three functions to record log messages:

  • trace() — This function records a log message with program execution trace information including the source code filename, line number and name of the calling function.
  • message(String) — This function records the log message passed to it.
  • value(Any?) — This function attempts to record a log message containing a string representation of the optional Any value passed to it.

Enabling logging

By default, logging is disabled, meaning that none of the Log’s channels have been populated. As a result, they have nil values and any attempts to perform logging will silently fail.

In order to use CleanroomLogger, you must explicitly enable logging, which is done by calling one of the Log.enable() functions.

Ideally, logging is enabled at the first possible point in the application’s launch cycle. Otherwise, critical log messages may be missed during launch because the logger wasn’t yet initialized.

The best place to put the call to Log.enable() is at the first line of your app delegate’s init().

If you’d rather not do that for some reason, the next best place to put it is in the application(_:willFinishLaunchingWithOptions:) function of your app delegate. You’ll notice that we’re specifically recommending the will function, not the typical did, because the former is called earlier in the application’s launch cycle.

Note: During the running lifetime of an application process, only the first call to Log.enable() function will have any effect. All subsequent calls are ignored silently. You can also prevent CleanroomLogger from being enabled altogether by calling Log.neverEnable().

Logging examples

To record items in the log, simply select the appropriate channel and call the appropriate function.

Here are a few examples:

Logging an arbitrary text message

Let’s say your application just finished launching. This is a significant event, but it isn’t an error. You also might want to see this information in production app logs. Therefore, you decide the appropriate LogSeverity is .info and you select the corresponding LogChannel, which is Log.info. Then, to log a message, just call the channel’s message() function:

Log.info?.message("The application has finished launching.")

Logging a trace message

If you’re working on some code and you’re curious about the order of execution, you can sprinkle some trace() calls around.

This function outputs the filename, line number and name of the calling function.

For example, if you put the following code on line 364 of a file called ModularTable.swift in a function with the signature tableView(_:cellForRowAt:):

Log.debug?.trace()

Assuming logging is enabled for the .debug severity, the following message would be logged when that line gets executed:

ModularTable.swift:364 — tableView(_:cellForRowAt:)

Logging an arbitrary value

The value() function can be used for outputting information about a specific value. The function takes an argument of type Any? and is intended to accept any valid runtime value.

For example, you might want to output the IndexPath value passed to your UITableViewDataSource’s tableView(_:cellForRowAt:) function:

Log.verbose?.value(indexPath)

This would result in output looking like:

= IndexPath: [0, 2]

The function also handles optionals:

var str: String?
Log.verbose?.value(str)

The output for this would be:

= nil

CleanroomLogger In Depth

This section delves into the particulars of configuring and customizing CleanroomLogger to suit your needs.

Configuring CleanroomLogger

CleanroomLogger is configured when one of the Log.enable() function variants is called. Configuration can occur at most once within the lifetime of the running process. And once set, the configuration can’t be changed; it’s immutable.

The LogConfiguration protocol represents the mechanism by which CleanroomLogger can be configured. LogConfigurations allow encapsulating related settings and behavior within a single entity, and CleanroomLogger can be configured with multiple LogConfiguration instances to allow combining behaviors.

Each LogConfiguration specifies:

  • The minimumSeverity, a LogSeverity value that determines which log entries get recorded. Any LogEntry with a severity less than the configuration’s mimimumSeverity will not be passed along to any LogRecorders specified by that configuration.
  • An array of LogFilters. Each LogFilter is given a chance to cause a given log entry to be ignored.
  • A synchronousMode property, which determines whether synchronous logging should be used when processing log entries for the given configuration. This feature is intended to be used during debugging and is not recommended for production code.
  • Zero or more contained LogConfigurations. For organizational purposes, each LogConfiguration can in turn contain additional LogConfigurations. The hierarchy is not meaningful, however, and is flattened at configuration time.
  • An array of LogRecorders that will be used to write log entries to the underlying logging facility. If a configuration has no LogRecorders, it is assumed to be a container of other LogConfigurations only, and is ignored when the configuration hierarchy is flattened.

When CleanroomLogger receives a request to log something, zero or more LogConfigurations are selected to handle the request:

  1. The severity of the incoming LogEntry is compared against the minimumSeverity of each LogConfiguration. Any LogConfiguration whose minimumSeverity is equal to or less than the severity of the LogEntry is selected for further consideration.
  2. The LogEntry is then passed sequentially to the shouldRecord(entry:) function of each of the LogConfiguration’s filters. If any LogFilter returns false, the associated configuration will not be selected to record that log entry.
XcodeLogConfiguration

Ideally suited for live viewing during development, the XcodeLogConfiguration examines the runtime environment to optimize CleanroomLogger for use within Xcode.

XcodeLogConfiguration takes into account:

  • Whether the new Unified Logging System (also known as “OSLog”) is available; it is only present as of iOS 10.0, macOS 10.12, tvOS 10.0, and watchOS 3.0. By default, logging falls back to stdout and stderr if Unified Logging is unavailable.

  • The value of the OS_ACTIVITY_MODE environment variable; when it is set to “disable”, attempts to log via OSLog are silently ignored. In such cases, log output is echoed to stdout and stderr to ensure that messages are visible in Xcode.

  • The severity of the message. For UNIX-friendly behavior, .verbose, .debug and .info messages are directed to the stdout stream of the running process, while .warning and .error messages are sent to stderr.

When using the Unified Logging System, messages in the Xcode console appear prefixed with an informational header that looks like:

2017-01-04 22:56:47.448224 Gilt[5031:89847] [CleanroomLogger]   
2017-01-04 22:56:47.448718 Gilt[5031:89847] [CleanroomLogger]   
2017-01-04 22:56:47.449487 Gilt[5031:89847] [CleanroomLogger]   
2017-01-04 22:56:47.450127 Gilt[5031:89847] [CleanroomLogger]   
2017-01-04 22:56:47.450722 Gilt[5031:89847] [CleanroomLogger]

This header is not added by CleanroomLogger; it is added as a result of using OSLog within Xcode. It shows the timestamp of the log entry, followed by the process name, the process ID, the calling thread ID, and the logging system name.

To ensure consistent output across platforms, the XcodeLogConfiguration will mimic this header even when logging to stdout and stderr. You can disable this behavior by passing false as the mimicOSLogOutput argument. When disabled, a more concise header is used, showing just the timestamp and the calling thread ID:

2017-01-04 23:46:17.225 -05:00 | 00071095
2017-01-04 23:46:17.227 -05:00 | 00071095
2017-01-04 23:46:17.227 -05:00 | 000716CA
2017-01-04 23:46:17.228 -05:00 | 000716CA
2017-01-04 23:46:17.258 -05:00 | 00071095

To make it easier to quickly identify important log messages at runtime, the XcodeLogConfiguration makes use of the XcodeLogFormatter, which embeds a color-coded representation of each message’s severity:

◽️ Verbose messages are tagged with a small gray square — easy to ignore
◾️ Debug messages have a black square; easier to spot, but still de-emphasized
🔷 Info messages add a splash of color in the form of a blue diamond
🔶 Warnings are highlighted with a fire-orange diamond
❌ Error messages stand out with a big red X — hard to miss!

The simplest way to enable CleanroomLogger using the XcodeLogConfiguration is by calling:

Log.enable()

Thanks to the magic of default parameter values, this is equivalent to the following Log.enable() call:

Log.enable(minimumSeverity: .info,
                 debugMode: false,
          verboseDebugMode: false,
            stdStreamsMode: .useAsFallback,
          mimicOSLogOutput: true,
              showCallSite: true,
                   filters: [])

This configures CleanroomLogger using an XcodeLogConfiguration with default settings.

Note: If either debugMode or verboseDebugMode is true, the XcodeLogConfiguration will be used in synchronousMode, which is not recommended for production code.

The call above is also equivalent to:

Log.enable(configuration: XcodeLogConfiguration())
RotatingLogFileConfiguration

The RotatingLogFileConfiguration can be used to maintain a directory of log files that are rotated daily.

Warning: The RotatingLogFileRecorder created by the RotatingLogFileConfiguration assumes full control over the log directory. Any file not recognized as an active log file will be deleted during the automatic pruning process, which may occur at any time. This means if you’re not careful about the directoryPath you pass, you may lose valuable data!

At a minimum, the RotatingLogFileConfiguration requires you to specify the minimumSeverity for logging, the number of days to keep log files, and a directory in which to store those files:

// logDir is a String holding the filesystem path to the log directory
let rotatingConf = RotatingLogFileConfiguration(minimumSeverity: .info,
                                                     daysToKeep: 7,
                                                  directoryPath: logDir)

Log.enable(configuration: rotatingConf)

The code above would record any log entry with a severity of .info or higher in a file that would be kept for at least 7 days before being pruned. This particular configuration uses the ReadableLogFormatter to format log entries.

The RotatingLogFileConfiguration can also be used to specify synchronousMode, a set of LogFilters to apply, and one or more custom LogFormatters.

Multiple Configurations

CleanroomLogger also supports multiple configurations, allowing different logging behaviors to be in use simultaneously.

Whenever a message is logged, every LogConfiguration is consulted separately and given a chance to process the message. By supplying a minimumSeverity and unique set of LogFilters, each configuration can specify its own logic for screening out unwanted messages. Surviving messages are then passed to the configuration’s LogFormatters, each in turn, until one returns a non-nil string. That string—the formatted log message—is ultimately passed to one or more LogRecorders for writing to some underlying logging facility.

Note that each configuration is a self-contained, stand-alone entity. None of the settings, behaviors or actions of a given LogConfiguration will affect any other.

For an example of how this works, imagine adding a debug mode XcodeLogConfiguration to the rotatingConf declared above. You could do this by writing:

Log.enable(configuration: [XcodeLogConfiguration(debugMode: true), rotatingConf])

In this example, both the XcodeLogConfiguration and the RotatingLogFileConfiguration will be consulted as each logging call occurs. Because the XcodeLogConfiguration is declared with debugMode: true, it will operate in synchronousMode while rotatingConf will operate asynchronously.

Further, the XcodeLogConfiguration will result in messages being logged via the Unified Logging System (if available) and/or the running process’s stdout and stderr streams. The RotatingLogFileConfiguration, on the other hand, results in messages being written to a file.

Finally, each configuration results in a different message format being used.

Implementing Your Own Configuration

Although you can provide your own implementation of the LogConfiguration protocol, it may be simpler to create a BasicLogConfiguration instance and pass the relevant parameters to the initializer.

You can also subclass BasicLogConfiguration if you’d like to encapsulate your configuration further.

A Complicated Example

Let’s say you want configure CleanroomLogger to:

  1. Print .verbose, .debug and .info messages to stdout while directing .warning and .error messages to stderr
  2. Mirror all messages to OSLog, if it is available on the runtime platform
  3. Create a rotating log file directory at the path /tmp/CleanroomLogger to store .info, .warning and .error messages for up to 15 days

Further, you want the log entries for each to be formatted differently:

  1. An XcodeLogFormatter for stdout and stderr
  2. A ReadableLogFormatter for OSLog
  3. A ParsableLogFormatter for the log files

To configure CleanroomLogger to do all this, you could write:

var configs = [LogConfiguration]()

// create a recorder for logging to stdout & stderr
// and add a configuration that references it
let stderr = StandardStreamsLogRecorder(formatters: [XcodeLogFormatter()])
configs.append(BasicLogConfiguration(recorders: [stderr]))

// create a recorder for logging via OSLog (if possible)
// and add a configuration that references it
if let osLog = OSLogRecorder(formatters: [ReadableLogFormatter()]) {
    // the OSLogRecorder initializer will fail if running on 
    // a platform that doesn’t support the os_log() function
    configs.append(BasicLogConfiguration(recorders: [osLog]))
}

// create a configuration for a 15-day rotating log directory
let fileCfg = RotatingLogFileConfiguration(minimumSeverity: .info,
                                                daysToKeep: 15,
                                             directoryPath: "/tmp/CleanroomLogger",
                                                formatters: [ParsableLogFormatter()])

// crash if the log directory doesn’t exist yet & can’t be created
try! fileCfg.createLogDirectory()

configs.append(fileCfg)

// enable logging using the LogRecorders created above
Log.enable(configuration: configs)

Customized Log Formatting

The LogFormatter protocol is consulted when attempting to convert a LogEntry into a string.

CleanroomLogger ships with several high-level LogFormatter implementations for specific purposes:

  • XcodeLogFormatter — Optimized for live viewing of a log stream in Xcode. Used by the XcodeLogConfiguration by default.
  • ParsableLogFormatter — Ideal for logs intended to be ingested for parsing by other processes.
  • ReadableLogFormatter — Ideal for logs intended to be read by humans.

The latter two LogFormatters are both subclasses of StandardLogFormatter, which provides a basic mechanism for customizing the behavior of formatting.

You can also assemble an entirely custom formatter quite easily using the FieldBasedLogFormatter, which lets you mix and match Fields to roll your own formatter.