For my little Vapor side project, I need to have some visibility into what’s going on when it’s deployed. There are lots of solutions for this sort of thing, but since this is side project, I don’t need anything fancy. I think some basic logging infrastructure will be more than adequate for now. There are two parts to my logging “strategy.” First, I need to decided what to log out, and second, where to log it out.
As far as what to log out, I’m going to start with the basic Request and response information. That is: the method and path of the request, the response status code, and how long it took for my server to process the request. This should give me some idea of the health of my server. I’m not going to log out request headers, or the request or response bodies. They could have sensitive information in them that I don’t want to end up in logs.
The question of where to log this information out to is a slightly more interesting question. I want a convenient place to get at the logs, plus the ability to easily search those logs. And, theoretically, if I needed to scale up my server to multiple instances (lol), I would want the logs all in one place. In the end, I decided on Papertrail for a couple of reasons:
- I’m hosting my side project on Heroku, and they provide a convenient Papertrail add on that I can trivially provision.
- Papertrail offers a free tier, appropriate for side projects
- Papertrail doesn’t require my app to know about it directly. Papertrail installs a daemon on the monitored system that grabs the syslog and sends it to its servers. Which means if my app logs out to syslog, Papertrail will take care of the rest.
My plan for adding logging to my Vapor 3 server: first, create a logger type that will log out to syslog. Second, create a Vapor Middleware that will intercept requests and responses, and log those out to the logger created in step one. Finally, update the configuration to include the logging middleware.
Logging out to syslog
Logging out to syslog turned out to be mildly interesting because I’m developing in Swift on a macOS system, but deploying to a Linux system.
The first thing I found out about syslog is Apple considers it deprecated on macOS, and would really rather I use os_log. os_log does sound fancy, but it doesn’t exist on Linux, and Papertrail doesn’t use it. So I have to ignore Apple’s advice on this one. Secondly, while syslog() the function is exposed in Swift, it doesn’t have convenient bindings, so I had to create one.
Here’s the start of my Vapor syslog logger:
import Foundation
import Vapor
final class SyslogLogger: Logger {
func log(_ string: String, at level: LogLevel, file: String, function: String, line: UInt, column: UInt) {
let message = "\(string) [\(function)@\(file):\(line):\(column)]"
syslog(message, at: level)
}
...
}
Logger is a protocol that Vapor defines, and the log() method here is its only requirement. I format the message given all the logging information, and then send the message with the log level to a helper function. That helper function takes care of actually calling syslog():
final class SyslogLogger: Logger {
...
private func syslog(_ message: String, at level: LogLevel) {
withVaList([]) { varArgs in
vsyslog(level.syslogLevel, message, varArgs)
}
}
}
I’m calling the vsyslog() variant of syslog because that’s the one exposed to Swift. It requires a C variable argument list. Fortunately, Swift provides a way to convert a Swift array into one of those with withVaList(). Since I’ve already formatted my message using Swift’s string interpolation, I don’t actually need any of the variable arguments, so I pass in an empty array. Finally, I convert Vapor’s LogLevel type into a level that syslog understands, and call vsyslog().
Here’s my log level mapping:
private extension LogLevel {
var syslogLevel: Int32 {
switch self {
case .verbose: return LOG_DEBUG
case .debug: return LOG_DEBUG
case .info: return LOG_INFO
case .warning: return LOG_WARNING
case .error: return LOG_ERR
case .fatal: return LOG_CRIT
case .custom(_): return LOG_NOTICE
}
}
}
I’m not entirely happy with the log level mapping, but from what I can gather from the docs, this is as close of a mapping as any. The .custom(String) log level in Vapor is a bit puzzling, but I guess the authors felt they needed an escape hatch in case they forgot a level. The other perhaps slightly surprising bit is that .verbose and .debug both map to syslog’s idea of LOG_DEBUG, since syslog doesn’t have a counterpart to ..
verbose
I have one final bit to my logger:
extension SyslogLogger: ServiceType {
static func makeService(for worker: Container) throws -> SyslogLogger {
return SyslogLogger()
}
}
This is some boilerplate code to make my SyslogLogger type able to be created by Vapor’s dependency injection system by conforming it to the ServiceType protocol. It’ll be used when I go to configure logging for the app.
Logging requests and responses
Now that I have a logger that will send information to syslog, I need to take advantage of it. As I mentioned at the start, I want to log: a request HTTP method and path, the response status code, and how long it took to service the request. Fortunately, Vapor’s middleware provides a convenient place to monitor requests and their responses.
I’ll start with declaring my middleware type and defining the middleware entry point:
import Foundation
import Vapor
final class LogMiddleware: Middleware {
private let logger: Logger
init(logger: Logger) {
self.logger = logger
}
func respond(to request: Request, chainingTo next: Responder) throws -> EventLoopFuture {
let startTime = Date()
return try next.respond(to: request).map { response in
self.log(response, for: request, whichStartedAt: startTime)
return response
}
}
...
}
My middleware class takes a generic Logger type in its init, so it can work any logger that I choose in the future. The respond(to:chainingTo:) method is the middleware entry point. The idea is to wrap the request processing so I know how long it takes. Once the request is processed and the response generated, then I can log all that information. To accomplish that, the code notes the current time, then calls through to the rest of stack to actually handle the request. It then grabs the response that results, and passes it along with the request and start time to a helper method called log():
final class LogMiddleware: Middleware {
...
private func log(_ response: Response, for request: Request, whichStartedAt startTime: Date) {
let requestInfo = "\(request.http.method.string) \(request.http.url.path)" + (request.http.url.query.map { "?\($0)" } ?? "")
let responseInfo = "\(response.http.status.code) \(response.http.status.reasonPhrase)"
let time = format(Date().timeIntervalSince(startTime))
logger.info("\(requestInfo) -> \(responseInfo) [\(time)]")
}
...
}
This is the method where I construct the message to be logged. I build it piecemeal by the three main parts: the request, the response, and the time it took. For the request, I put together the method, path, and the query parameters, if there are any. For the response, I put together the HTTP status code, plus the human readable version of the status code. Vapor helpfully provides that on the reasonPhrase property. Finally, I compute the time elapsed and format that. Once I have all three pieces, I put them together into one string. The resulting message looks something like GET /my/path?p1=y&p2 -> 200 OK [98.20ms].
Formatting time is a bit verbose, so I put that into its own method:
final class LogMiddleware: Middleware {
...
private let intervalFormatter: NumberFormatter = {
let formatter = NumberFormatter()
formatter.numberStyle = .decimal
formatter.maximumFractionDigits = 2
formatter.multiplier = 1000
return formatter
}()
...
private func format(_ interval: TimeInterval) -> String {
return intervalFormatter.string(for: interval).map { $0 + "ms" } ?? "???ms"
}
}
I’m leveraging NumberFormatter to do all the hard work. I set it up to create decimal numbers with no more than 2 digits after the decimal point, and 1000 as a multiplier. That’s because I’m giving the formatter seconds, but I want it displayed in milliseconds. My format() method simply calls the NumberFormatter, and appends “ms” as the units. The trailing ?? "???ms" shouldn’t ever be executed, and is there to satisfy the compiler, since string(for:) can technically return nil.
The final bit for the logging middleware is to hook into the dependency injection system:
extension LogMiddleware: ServiceType {
static func makeService(for worker: Container) throws -> LogMiddleware {
return try LogMiddleware(logger: worker.make())
}
}
This is also where the Logger used by the middleware will be instantiated and passed into the init method.
Configuring logging for the app
The last little bit is to register my logger and middleware with the dependency injection framework, and add the logging middleware in the correct order. That means modifying my configure() method:
/// Called before your application initializes.
public func configure(_ config: inout Config, _ env: inout Environment, _ services: inout Services, _ configuration: ConfigurationType) throws {
...
services.register(LogMiddleware.self)
services.register(SyslogLogger.self)
...
/// Register middleware
var middlewares = MiddlewareConfig()
middlewares.use(LogMiddleware.self)
...
}
Here I register LogMiddleware and SyslogLogger with the dependency injection framework. Then, in the middleware configuration, I add my log middleware first, before all other middlewares. This will allow it to measure as much of the time it takes processing the request as possible. It will be the first middleware called when a request is received, and the last to be called when the response is returned.
Conclusion
While I need to have some visibility into how my Vapor server is doing in production, my side project doesn’t need anything overly complicated. I chose to use Papertrail because it provided an easy and convenient place to aggregate my logs. To get logs to Papertrail, I added middleware to my app that logs out basic request and response information to syslog.
