The original address is Swift Logging
In 2002 America’s Congress enacted the Sarbanes-Oxley Act, which introduced broad corporate oversight in response to accounting scandals at companies such as Enron and MCI Worldcom. The act, PCI and HIPAA, formed the regulatory backdrop for a new generation of information technology companies that emerged from the dotcom bubble.
Around the same time, we saw the short-lived emergence of distributed infrastructure — what we now call “cloud computing” — as an paradigm for making systems more capable but also more complex.
To address the regulatory and logistics challenges of the 21st century, our field has established best practices around application logging. Many of the same tools and standards are still in use today.
This week on NS Hipster, we take a look at Swift Log: a community-driven, open source Swift login standard.
Developed by the Swift on **Server community and endorsed by the SSWG (Swift Server Working Group), its benefits are limited to use on Server **. In fact, any Swift code that is intended to run from the command line will benefit from adopting Swift Logs. Read on to learn how to use it.
As always, an example will help guide our discussion. In the spirit of transparency and nostalgia, let’s imagine writing a Swift program to audit the finances of a Fortune 500 company in the 2000s.
Import Foundationstruct Auditor {func watch(_ directory: URL) throws {... } 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)")}Copy the codeThe auditor type polls the directory * (FTP server as it is 2003) for changes. Each time a file is added, deleted, or changed, its contents are reviewed for differences. If you encounter any financial problems, ‘use the print function to re-record. The same goes for problems connecting to FTP* or any other problems your program might encounter — everything uses a printed record.
Very simple. We can run it from the command line like this:
$ swift run auditstarting 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! **^Cshutting down...Copy the codeSuch a program might be technically compatible, but it leaves a lot of room for improvement:
-
First, our output ‘does not have any timestamp associated with it. There is no way to know if a problem was detected an hour ago or last week.
-
Another problem is the lack of any coherent structure to our output. At first glance, there is no easy way to isolate program noise from real problems.
-
Finally, – this is mainly due to an unspecified example – it is not clear what to do with this output. Where does this output go? How is it collected, aggregated, and analyzed?
The good news is that all of these issues (and many others) can be addressed by adopting a formal logging infrastructure in your projects.
Adopt Swift Log in your Swift program
Adding Swift logs to an existing Swift package is a snap. You can incrementally merge it without making any fundamental changes to the code and have it working in a matter of minutes.
Add swift logs as package dependencies
In your package.swift manifest, add the Swift log as a Package dependency and add the log module to the target’s dependency list.
// swift-tools-version:5.1import PackageDescriptionlet package = package (name: "Auditor2000", products: [ .executable(name: "audit", targets: ["audit"]) ], dependencies: [ .package(url: "Https://github.com/apple/swift-log.git" from: "1.2.0),"], the targets: [. Target (name: "audit", dependencies: ["Logging"]) ])Copy the codeCreate a shared global logger
Loggers provide two initializers, the simpler of which takes a single tag argument:
let logger = Logger(label: "com.NSHipster.Auditor2000")
Copy the code** In POSIX systems, programs run on three predefined streams ** :
File HandleDescriptionName0stdinStandard Input1stdoutStandard Output2stderrStandard Error
By default, loggers write recorded messages to standard output (STDOUT) using a built-in Stream Log Handler type. Instead of writing the standard error (STderr), we can override this behavior by using a more complex initializer that takes a factory argument: a closure that takes a single string argument (label) and returns an object that conforms to the Log Handler.
let logger = Logger(label: "com.NSHipster.Auditor2000", factory: StreamLogHandler.standardError)
Copy the codeReplace print statements with log statements
Declaring the logger as a top-level constant lets us call it from anywhere in the module. Let’s revisit our example and dress 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)")}Copy the codeTrace, debug, and critical methods log messages at their respective log levels. The Swift Log defines seven levels, in ascending order of severity from trace to critical:
LevelDescription.traceAppropriate for messages that contain information only when debugging a program.. debugAppropriate for messages that contain information normally of use only when debugging a program.. infoAppropriate for informational messages.. noticeAppropriate for conditions that are not error conditions, but that may require special handling.. warningAppropriate for messages that are not error conditions, but more severe than .notice.errorAppropriate for error conditions.. criticalAppropriate for critical error conditions that usually require immediate attention.
If we re-run the audit example using the new logging framework, we can see the immediate benefits of different severity levels clearly marked in the log lines:
$SWIFT Run audit2020-03-26T09:40:10-0700 Critical: Couldn't connect to ftp://... # (try again after plugging in loose ethernet cord)$ swift run audit2020-03-26T10:21:22-0700 warning: Discrepancy in balance sheet2020-03-26T10:21:22-0700 error: Quicken database corruption^CCopy the codeIn addition to simply marking messages, the logging level itself — not to mislead us * — is good enough to provide a configurable level of disclosure. Notice that the * message ‘logged using the trace method appears in the sample output. This is because loggers by default only show messages recorded as information level or higher.
You can configure the logger by setting its Log Level property.
var logger = Logger(label: "com.NSHipster.Auditor2000")logger.logLevel = .trace
Copy the codeAfter making this change, the sample output would look like this:
$ swift run audit2020-03-25T09:40:00-0700 trace: Starting up2020-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 audit2020-03-25T09:41:00-0700 trace: Starting UP2020-03-26T09:41:01-0700 DEBUG: Connected to ftp://... /reports2020-03-26T09:41:01-0700 debug: Watching file extensions ["xls", "ods", "qdf"]2020-03-26T10:21:22-0700 warning: Discrepancy in balance sheet2020-03-26T10:21:22-0700 error: Quicken database corruption^C2020-03-26T10:30:00-0700 trace: Shutting downCopy the codeUse multiple log handlers at once
Recalling our objections in the original example, the only question that remains is what we actually do with the logs.
According to the **12 Factor App** principle:
Xi. Log
[…].
A 12-factor application never cares about routing or storage of its output streams. It should not attempt to write to or manage log files. Instead, each running process writes its event stream to STdout unbuffered.
Collecting, routing, indexing, and analyzing logs in distributed systems typically requires a set of open source libraries and commercial products. Fortunately, most of these components flow as shared syslog messages-so can Swift, thanks to this package from Ian Partridge.
That said, very few engineers could retrieve this information from someone like **Splunk and live to tell the story. For the rest of us, we might prefer Will Lisak’s package, which sends log messages to Slack.
The good news is that we can use both without having to change how messages are logged at the calling site by using another part of the logging module: Multi LEX Log Handler.
import struct Foundation.ProcessInfoimport Loggingimport LoggingSyslogimport LoggingSlackLoggingSystem.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")Copy the codeWith all of this, our system logs everything in syslog format to standard output (STDOUT), where it can be collected and analyzed by other systems.
But the real advantage of this recording approach 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 can send an email, open a sales force ticket, or trigger a network hook to activate some iot device.
Here’s how to extend Swift Log to suit your needs by writing a custom Log handler:
Create a custom log handler
The Log Handler protocol specifies requirements for the type of message Handler that can be registered 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)}Copy the codeIn the course of writing this article, I created a custom ** processing ** program that formats GitHub Actions log messages so that they appear on GitHub’s UI like this:
If you are interested in making your own log handlers, you can learn a lot by browsing the code for this project. But I do want to point out a few points of interest here:
Conditions to guide
When booting the logging system, you can define some logic on how to configure it. For example, for a particular CI vendor’s log formatter, you can check the environment to see if you are running locally or on CI and adjust accordingly.
import Loggingimport LoggingGitHubActionsimport struct Foundation.ProcessInfoLoggingSystem.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) }}
Copy the codeTest custom log handlers
The test was more challenging than initially expected. I may be missing something obvious, but it seems like a way to create an assertion about writing text to standard output. So I did the following:
First, create an internal initializer that takes the Text Output Stream argument and stores it in a private property.
public struct GitHubActionsLogHandler: LogHandler { private var outputStream: TextOutputStream internal init(outputStream: TextOutputStream) { self.outputStream = outputStream } …}
Copy the codeThen, in the test target, create a type that takes the Text Output Stream and collect the recorded messages into stored properties for later review. By using the @teable** import ** of the module that declares the GitHub Actions Log Handler, we can access the internal initializer from before and pass an instance of the Mock Text Output Stream to intercept logged messages.
import Logging@testable import LoggingGitHubActionsfinal 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) }}
Copy the codeWith these parts, we can finally test whether our handler works as expected:
func testLogging() { var logLevel: Logger.Level? Let expectation = MockTextOutputStream {logger in logLevel = logger.handler.loglevel logger.trace("🥱") Logger. The error (" 😱 ")} XCTAssertGreaterThan (logLevel! , .trace) XCTAssertEqual(expectation.lines.count, 1) // trace log is ignored XCTAssertTrue(expectation.lines[0].hasPrefix("::error ")) XCTAssertTrue (expectation. Lines [0]. HasSuffix (" : : 😱 ")}Copy the code