综合开发

Swift Logging

微信扫一扫,分享到朋友圈

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 straightforward.
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 simplest taking a single label
parameter:

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

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

File HandleDescriptionName
0 stdinStandard Input
1 stdoutStandard Output
2 stderrStandard 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
allows us to 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
:

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.
.warning Appropriate 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 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 the 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(":scream:")
}
XCTAssertGreaterThan(logLevel!, .trace)
XCTAssertEqual(expectation.lines.count, 1) // trace log is ignored
XCTAssertTrue(expectation.lines[0].hasPrefix("::error "))
XCTAssertTrue(expectation.lines[0].hasSuffix(":::scream:"))
}

微软推 Win10 KB4052623 更新,修复 Windows Defender 扫描错误

上一篇

Count of consecutive Fibonacci pairs in the given Array

下一篇

你也可能喜欢

评论已经被关闭。

插入图片
NSHipster 投稿者
我还没有学会写个人说明!
最近文章
  • 1 Static and Dynamic Callable Types in Swift
  • 2 RawRepresentable
  • 3 Objective-C Direct Methods
  • 热门栏目

    Swift Logging

    长按储存图像,分享给朋友