Swift Logging

In 2002, the United States Congress enacted the Sarbanes–Oxley Act, which introduced broad oversight to corporations in response to accounting scandals at companies like Enron and MCI WorldCom around that time. This act, PCI and HIPAA , formed the regulatory backdrop for a new generation of IT companies emerging from the dot-com bubble.

Around the same time, we saw the emergence of ephemeral, distributed infrastructure — what we now call “Cloud computing” — a paradigm that made systems more capable but also more complex.

To solve both the regulatory and logistical challenges of the 21^st century, our field established best practices around application logging. And many of the same tools and standards are still in use today.

---

This week on NSHipster, we’re taking a look at SwiftLog: a community-driven, open-source standard for logging in Swift.

Developed by the Swift on Server community and endorsed by the SSWG (Swift Server Work Group), its benefit isn’t limited to use on the server. Indeed, any Swift code intended to be run from the command line would benefit from adopting SwiftLog. Read on to learn how.

---

As always, an example would be helpful in guiding our discussion. In the spirit of transparency and nostalgia, let’s imagine writing a Swift program that audits the finances of a ’00s Fortune 500 company.

import Foundation

struct Auditor {
    func watch(_ directory: URL) throws { … }
    func cleanup() { … }
}

do {
    let auditor = Auditor()

    defer { auditor.cleanup() }
    try auditor.watch(directory: URL(string: "ftp://…/reports")!,
                     extensions: ["xls", "ods", "qdf"]) // poll for changes
} catch {
    print("error: \(error)")
}

An Auditor type polls for changes to a directory (an FTP server, because remember: it’s 2003). Each time a file is added, removed, or changed, its contents are audited for discrepancies. If any financial oddities are encountered, they’re logged using the print function. The same goes for issues connecting to the FTP, or any other problems the program might encounter — everything’s logged using print.

Simple enough. We can run it from the command line like so:

$ swift run audit
starting up...
ERROR: unable to reconnect to FTP

# (try again after restarting PC under our desk)

$ swift run audit
+ connected to FTP server
! accounting discrepancy in balance sheet 
** Quicken database corruption! **
^C
shutting down...

Such a program might be technically compliant, but it leaves a lot of room for improvement:

• For one, our output doesn’t have any timestamps associated with it. There’s no way to know whether a problem was detected an hour ago or last week.
• Another problem is that our output lacks any coherent structure. At a glance, there’s no straightforward way to isolate program noise from real issues.
• Finally, — and this is mostly due to an under-specified example — it’s unclear how this output is handled. Where is this output going? How is it collected, aggregated, and analyzed?

---

The good news is that all of these problems (and many others) can be solved by adopting a formal logging infrastructure in your project.

---

Adopting SwiftLog in Your Swift Program

Adding SwiftLog to an existing Swift package is a breeze. You can incorporate it incrementally without making any fundamental changes to your code and have it working in a matter of minutes.

Add swift-log as a Package Dependency

In your Package.swift manifest, add swift-log as a package dependency and add the Logging module to your target’s list of dependencies.

// swift-tools-version:5.1

import PackageDescription

let package = Package(
    name: "Auditor2000",
    products: [
        .executable(name: "audit", targets: ["audit"])
    ],
    dependencies: [
        .package(url: "https://github.com/apple/swift-log.git", from: "1.2.0"),
    ],
    targets: [
        .target(name: "audit", dependencies: ["Logging"])
    ]
)

Create a Shared, Global Logger

Logger provides two initializers, the simpler of them taking a single label parameter:

let logger = Logger(label: "com.NSHipster.Auditor2000")

In POSIX systems, programs operate on three, predefined streams:

File Handle	Description	Name
0	stdin	Standard Input
1	stdout	Standard Output
2	stderr	Standard Error

By default, Logger uses the built-in StreamLogHandler type to write logged messages to standard output (stdout). We can override this behavior to instead write to standard error (stderr) by using the more complex initializer, which takes a factory parameter: a closure that takes a single String parameter (the label) and returns an object conforming to LogHandler.

let logger = Logger(label: "com.NSHipster.Auditor2000",
                    factory: StreamLogHandler.standardError)

Replacing Print Statements with Logging Statements

Declaring our logger as a top-level constant lets us call it anywhere within our module. Let’s revisit our example and spruce it up with our new logger:

do {
    let auditor = Auditor()

    defer {
        logger.trace("Shutting down")
        auditor.cleanup()
    }

    logger.trace("Starting up")
    try auditor.watch(directory: URL(string: "ftp://…/reports")!,
                      extensions: ["xls", "ods", "qdf"]) // poll for changes
} catch {
    logger.critical("\(error)")
}

The trace, debug, and critical methods log a message at their respective log level. SwiftLog defines seven levels, ranked in ascending order of severity from trace to critical:

Level	Description
.trace	Appropriate for messages that contain information only when debugging a program.
.debug	Appropriate for messages that contain information normally of use only when debugging a program.
.info	Appropriate for informational messages.
.notice	Appropriate for conditions that are not error conditions, but that may require special handling.
.warning	Appropriate for messages that are not error conditions, but more severe than .notice
.error	Appropriate for error conditions.
.critical	Appropriate for critical error conditions that usually require immediate attention.

If we re-run our audit example with our new logging framework in place, we can see the immediate benefit of clearly-labeled, distinct severity levels in log lines:

$ swift run audit
2020-03-26T09:40:10-0700 critical: Couldn't connect to ftp://…

# (try again after plugging in loose ethernet cord)

$ swift run audit
2020-03-26T10:21:22-0700 warning: Discrepancy in balance sheet
2020-03-26T10:21:22-0700 error: Quicken database corruption
^C

Beyond merely labeling messages, which — don’t get us wrong — is sufficient benefit on its own, log levels provide a configurable level of disclosure. Notice that the messages logged with the trace method don’t appear in the example output. That’s because Logger defaults to showing only messages logged as info level or higher.

You can configure that by setting the Logger’s logLevel property.

var logger = Logger(label: "com.NSHipster.Auditor2000")
logger.logLevel = .trace

After making this change, the example output would instead look something like this:

$ swift run audit
2020-03-25T09:40:00-0700 trace: Starting up
2020-03-26T09:40:10-0700 critical: Couldn't connect to ftp://…
2020-03-25T09:40:11-0700 trace: Shutting down

# (try again after plugging in loose ethernet cord)

$ swift run audit
2020-03-25T09:41:00-0700 trace: Starting up
2020-03-26T09:41:01-0700 debug: Connected to ftp://…/reports
2020-03-26T09:41:01-0700 debug: Watching file extensions ["xls", "ods", "qdf"]
2020-03-26T10:21:22-0700 warning: Discrepancy in balance sheet
2020-03-26T10:21:22-0700 error: Quicken database corruption
^C
2020-03-26T10:30:00-0700 trace: Shutting down

Using Multiple Logging Handlers at Once

Thinking back to our objections in the original example, the only remaining concern is what we actually do with these logs.

According to 12 Factor App principles:

XI. Logs

[…]

A twelve-factor app never concerns itself with routing or storage of its output stream. It should not attempt to write to or manage logfiles. Instead, each running process writes its event stream, unbuffered, to stdout.

Collecting, routing, indexing, and analyzing logs across a distributed system often requires a constellation of open-source libraries and commercial products. Fortunately, most of these components traffic in a shared currency of syslog messages — and thanks to this package by Ian Partridge, Swift can, as well.

That said, few engineers have managed to retrieve this information from the likes of Splunk and lived to tell the tale. For us mere mortals, we might prefer this package by Will Lisac, which sends log messages to Slack.

The good news is that we can use both at once, without changing how messages are logged at the call site by using another piece of the Logging module: MultiplexLogHandler.

import struct Foundation.ProcessInfo
import Logging
import LoggingSyslog
import LoggingSlack

LoggingSystem.bootstrap { label in
    let webhookURL = URL(string:
        ProcessInfo.processInfo.environment["SLACK_LOGGING_WEBHOOK_URL"]!
    )!
    var slackHandler = SlackLogHandler(label: label, webhookURL: webhookURL)
    slackHandler.logLevel = .critical

    let syslogHandler = SyslogLogHandler(label: label)

    return MultiplexLogHandler([
        syslogHandler,
        slackHandler
    ])
}

let logger = Logger(label: "com.NSHipster.Auditor2000")

With all of this in place, our system will log everything in syslog format to standard out (stdout), where it can be collected and analyzed by some other system.

---

But the real strength of this approach to logging is that it can be extended to meet the specific needs of any environment. Instead of writing syslog to stdout or Slack messages, your system could send emails, open SalesForce tickets, or trigger a webhook to activate some IoT device.

Here’s how you can extend SwiftLog to fit your needs by writing a custom log handler:

Creating a Custom Log Handler

The LogHandler protocol specifies the requirements for types that can be registered as message handlers by Logger:

protocol LogHandler {
    subscript(metadataKey _: String) -> Logger.Metadata.Value? { get set }
    var metadata: Logger.Metadata { get set }

    var logLevel: Logger.Level { get set }

    func log(level: Logger.Level,
             message: Logger.Message,
             metadata: Logger.Metadata?,
             file: String, function: String, line: UInt)
}

In the process of writing this article, I created custom handler that formats log messages for GitHub Actions so that they’re surfaced on GitHub’s UI like so:

If you’re interested in making your own logging handler, you can learn a lot by just browsing the code for this project. But I did want to call out a few points of interest here:

Conditional Boostrapping

When bootstrapping your logging system, you can define some logic for how things are configured. For logging formatters specific to a particular CI vendor, for example, you might check the environment to see if you’re running locally or on CI and adjust accordingly.

import Logging
import LoggingGitHubActions
import struct Foundation.ProcessInfo

LoggingSystem.bootstrap { label in
    // Are we running in a GitHub Actions workflow?
    if ProcessInfo.processInfo.environment["GITHUB_ACTIONS"] == "true" {
        return GitHubActionsLogHandler.standardOutput(label: label)
    } else {
        return StreamLogHandler.standardOutput(label: label)
    }
}

Testing Custom Log Handlers

Testing turned out to be more of a challenge than originally anticipated. I could be missing something obvious, but there doesn’t seem to be a way to create assertions about text written to standard output. So here’s what I did instead:

First, create an internal initializer that takes a TextOutputStream parameter, and store it in a private property.

public struct GitHubActionsLogHandler: LogHandler {
    private var outputStream: TextOutputStream

    internal init(outputStream: TextOutputStream) {
        self.outputStream = outputStream
    }

    …
}

Then, in the test target, create a type that adopts TextOutputStream and collects logged messages to a stored property for later inspection. By using a @testable import of the module declaring GitHubActionsLogHandler, we can access that internal initializer from before, and pass an instance of MockTextOutputStream to intercept logged messages.

import Logging
@testable import LoggingGitHubActions

final class MockTextOutputStream: TextOutputStream {
    public private(set) var lines: [String] = []

    public init(_ body: (Logger) -> Void) {
        let logger = Logger(label: #file) { label in
            GitHubActionsLogHandler(outputStream: self)
        }

        body(logger)
    }

    // MARK: - TextOutputStream

    func write(_ string: String) {
        lines.append(string)
    }
}

With these pieces in place, we can finally test that our handler works as expected:

func testLogging() {
    var logLevel: Logger.Level?
    let expectation = MockTextOutputStream { logger in
        logLevel = logger.handler.logLevel

        logger.trace("🥱")
        logger.error("😱")
    }

    XCTAssertGreaterThan(logLevel!, .trace)
    XCTAssertEqual(expectation.lines.count, 1) // trace log is ignored
    XCTAssertTrue(expectation.lines[0].hasPrefix("::error "))
    XCTAssertTrue(expectation.lines[0].hasSuffix("::😱"))
}