# Swift Logging By [Mattt](https://nshipster.com/authors/mattt). Published 2020-03-26. Canonical URL: In 2002, the United States Congress enacted the [Sarbanes–Oxley Act](https://en.wikipedia.org/wiki/Sarbanes%E2%80%93Oxley_Act), which introduced broad oversight to corporations in response to accounting scandals at companies like [Enron](https://en.wikipedia.org/wiki/Enron_scandal) and [MCI WorldCom](https://en.wikipedia.org/wiki/MCI_Inc.#Accounting_scandals) around that time. This act, [PCI ](https://en.wikipedia.org/wiki/PCI_DSS)and [HIPAA ](https://en.wikipedia.org/wiki/HIPAA), formed the regulatory backdrop for a new generation of IT companies emerging from the [dot-com bubble](https://en.wikipedia.org/wiki/Dot-com_bubble). Around the same time, we saw the emergence of ephemeral, distributed infrastructure — what we now call [“Cloud computing”](https://en.wikipedia.org/wiki/Cloud_computing) — a paradigm that made systems more capable but also more complex. To solve both the regulatory and logistical challenges of the 21st century, our field established best practices around application logging. And many of the same tools and standards are still in use today. > Just as `print` is a poor man’s [debugger](https://developer.apple.com/videos/play/wwdc2019/429/), it’s also a shallow replacement for a proper logging system, with distinct log levels and configurable output settings. > _Sarbanes–Oxley_ is notable for giving rise to _[Yates v. United States](https://www.oyez.org/cases/2014/13-7451)_: a delightful Supreme Court case that asked the question _“Are fish (🐟) tangible objects?”_ > > Although the Court found in a 5 – 4 decision that fish are _not_, in fact, “tangible objects” (for purposes of the statute), we remain unconvinced for the same reasons articulated in [Justice Kagan’s dissent](https://supreme.justia.com/cases/federal/us/574/528/#tab-opinion-3243031) _(and pretty much anything written by [Claude Shannon](https://en.wikipedia.org/wiki/Claude_Shannon), for that matter)_. --- This week on NSHipster, we’re taking a look at [`SwiftLog`](https://github.com/apple/swift-log): 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)](https://swift.org/server/), 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. > `SwiftLog` is distinct from the [Unified Logging System](https://developer.apple.com/documentation/os/logging) (`os_log`), which is specific to Apple platforms. > > Readers may already be familiar with `os_log` and its, _\*ahem\*_ [quirks](https://mjtsai.com/blog/2019/03/06/problems-with-os_log/) _(a topic for a future article, perhaps)_. But for the uninitiated, all you need to know is that `os_log` is for macOS and iOS apps and `SwiftLog` is for everything else. > > If you’re interested in learning more about Unified Logging, you can get a quick overview by skimming the [`os_log` docs](https://developer.apple.com/documentation/os/logging); for an in-depth look, check out [“Unified Logging and Activity Tracing”](https://developer.apple.com/videos/play/wwdc2016/721/) from WWDC 2016 and [“Measuring Performance Using Logging”](https://developer.apple.com/videos/play/wwdc2018/405/) from WWDC 2018. --- 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. ```swift import Foundation struct Auditor { func watch(directory: URL, extensions: [String]) 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`. > The implementation details aren’t important; only the interface is relevant to our discussion. Simple enough. We can run it from the command line like so: ```console $ 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 // 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: ```swift let logger = Logger(label: "com.NSHipster.Auditor2000") ``` In [POSIX](https://en.wikipedia.org/wiki/POSIX) systems, programs operate on three, predefined [streams](https://en.wikipedia.org/wiki/Standard_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`. ```swift let logger = Logger(label: "com.NSHipster.Auditor2000", factory: StreamLogHandler.standardError) ``` > Alternatively, you can set the default logger globally using the `LoggingSystem.bootstrap()` method. > > ```swift > LoggingSystem.bootstrap(StreamLogHandler.standardError) > let logger = Logger(label: "com.NSHipster.Auditor2000") > ``` > > After doing this, any subsequent `Logger` instances created using the `Logger(label:)` initializer will default to the specified handler. ### 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: ```swift 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 normally of use only when tracing the execution of 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: ```console $ 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. ```swift var logger = Logger(label: "com.NSHipster.Auditor2000") logger.logLevel = .trace ``` After making this change, the example output would instead look something like this: ```console $ swift run audit 2020-03-26T09:40:00-0700 trace: Starting up 2020-03-26T09:40:10-0700 critical: Couldn't connect to ftp://<#…#> 2020-03-26T09:40:11-0700 trace: Shutting down # (try again after plugging in loose ethernet cord) $ swift run audit 2020-03-26T09: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](https://12factor.net/logs) 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](https://en.wikipedia.org/wiki/Syslog) messages — and thanks to [this package by Ian Partridge](https://github.com/ianpartridge/swift-log-syslog), Swift can, as well. That said, few engineers have managed to retrieve this information from the likes of [Splunk](https://www.splunk.com/) and lived to tell the tale. For us mere mortals, we might prefer [this package by Will Lisac](https://github.com/wlisac/swift-log-slack), which sends log messages to [Slack](https://slack.com/). 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`. ```swift 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") ``` > Harkening to [another 12 Factor principle](https://12factor.net/config), we pull the webhook URL from an environment variable rather than hard-coding it. 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. > Granted, each of those examples would probably be better served by a separate monitoring service that ingests a log stream and reacts to events according to a more elaborate set of rules. 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`: ```swift 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 a [custom handler](https://github.com/NSHipster/swift-log-github-actions) that formats log messages for GitHub Actions so that they’re surfaced on GitHub’s UI like so: ![](https://nshipster.com/assets/github-actions-ui-29966d7466f9a450.png) > For more information, see [“Workflow commands for GitHub Actions.”](https://help.github.com/en/actions/reference/workflow-commands-for-github-actions) If you’re interested in making your own logging handler, you can learn a lot by just browsing [the code for this project](https://github.com/NSHipster/swift-log-github-actions). But I did want to call out a few points of interest here: ### Conditional Bootstrapping 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. ```swift 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. > Swift symbols have `internal` access control by default; the keyword is included here for clarity. ```swift 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`](https://docs.swift.org/swift-book/LanguageGuide/AccessControl.html#ID5) of the module declaring `GitHubActionsLogHandler`, we can access that `internal` initializer from before, and pass an instance of `MockTextOutputStream` to intercept logged messages. ```swift 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: ```swift 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("::😱")) } ``` > As to how or where messages are logged, `SwiftLog` is surprisingly tight-lipped. There’s [an internal type](https://github.com/apple/swift-log/blob/0e21dd789300fc37a43019fba68b4e97c9938142/Sources/Logging/Logging.swift#L524-L550) that buffers writes to `stdout`, but it’s not exposed by the module. > > If you’re in search of a replacement and would prefer not to copy-paste something as involved as that, here’s a dead-simple alternative: > > ```swift > struct StandardTextOutputStream: TextOutputStream { > mutating func write(_ string: String) { > print(string, terminator: "") > } > } > ```