[IOSP-296] [IOSP-297] Logz.io-compatible JSON Logs (#53)

* Migrate to LogzIOLogger

* Switch to new LogzIOLogger

* Added AppTests/LogsTests

* swift test --generate-linuxmain

* Cleanup

* Fix Linux compilation issue (hopefully)

* Fix wrong Logger resolved at runtime

* Fix Logger runtime resolution bug for Middleware

+ Add comment on necessary `print` call

* Update Sources/App/Logger/LogzIOLogger.swift

Co-Authored-By: David Rodrigues <[email protected]>

* Rename LogzIOLogger -> JSONLogger

* Rename, pass 2

* Provide minimumLevel comparisons

* Provide minimum log level via ENV var

* Cleanup

* swift test --generate-linuxmain

* 🧹

* test update

* Defaults minimumLogLevel to info

* allLevels -> allPredefinedLevels

* Cut dependency to Vapor Logging framework

* swift test --generate-linuxmain

* Use rawValue for LogLevel <-> String

* import

* Fix rawValue (uppercase)

* uppercase env var to be case insensitive in config

* Relative paths in logs

* Comment fix

Co-authored-by: David Rodrigues <[email protected]>

Package.swift

@@ -14,7 +14,7 @@ let package = Package(
         .target(name: "Bot", dependencies: ["ReactiveSwift", "ReactiveFeedback", "CryptoSwift"]),
         .target(name: "App", dependencies: ["Bot", "Vapor"]),
         .target(name: "Run", dependencies: ["App"]),
-        .testTarget(name: "BotTests", dependencies: ["Bot", "Nimble"])
+        .testTarget(name: "BotTests", dependencies: ["Bot", "Nimble"]),
+        .testTarget(name: "AppTests", dependencies: ["App"])
     ]
 )
-

Sources/App/Extensions/EnvironmentProperties.swift

@@ -59,6 +59,22 @@ extension Environment {
         }
     }
 
+    /// Name of the minimum log level to start logging. Defaults to "INFO" level
+    ///
+    /// Valid values are, in decreasing order of verbosity:
+    ///  - `DEBUG`
+    ///  - `INFO`
+    ///  - `ERROR`
+    ///
+    /// Any log that is higher that the `minimumLogLevel` in this list will be filtered out.
+    /// e.g. a `minimumLogLevel` of `INFO` will filter out `DEBUG` logs and will only print `INFO` and `ERROR` logs
+    static func minimumLogLevel() -> Bot.LogLevel {
+        let value: String? = Environment.get("MINIMUM_LOG_LEVEL")
+        return value
+            .map { $0.uppercased() }
+            .flatMap(Bot.LogLevel.init(rawValue:)) ?? .info
+    }
+
     static func get(_ key: String) throws -> String {
         guard let value = Environment.get(key) as String?
             else { throw ConfigurationError.missingConfiguration(message: "💥 key `\(key)` not found in environment") }

Sources/App/Logger/JSONLogger.swift

@@ -0,0 +1,75 @@
+import Vapor
+import Bot
+
+private let basePath = #file.components(separatedBy: "/").dropLast(4).joined(separator: "/") + "/"
+
+final class JSONLogger: LoggerProtocol, Service {
+    private let serializer = JSONEncoder()
+    let minimumLogLevel: Bot.LogLevel
+
+    init(minimumLogLevel: Bot.LogLevel = .info) {
+        self.minimumLogLevel = minimumLogLevel
+    }
+
+    public func log(_ string: String, at level: Bot.LogLevel,
+                    file: String = #file, function: String = #function, line: UInt = #line, column: UInt = #column
+    ) {
+        guard level >= minimumLogLevel else { return }
+        let formatted: String
+        do {
+            let message = LogMessage(
+                timestamp: Date(),
+                message: string,
+                level: level,
+                file: file,
+                function: function,
+                line: line,
+                column: column
+            )
+            let data = try serializer.encode(message)
+            formatted = String(data: data, encoding: .utf8)!
+        } catch {
+            formatted = "[\(Date())] [\(level.rawValue)] \(string)"
+        }
+
+        print(formatted)
+    }
+}
+
+// MARK: Private structure of LogMessage
+
+extension JSONLogger {
+    struct LogMessage: Encodable {
+        let timestamp: Date
+        let message: String
+        let level: Bot.LogLevel
+        let file: String
+        let function: String
+        let line: UInt
+        let column: UInt
+
+        static var dateFormatter: DateFormatter = {
+            let df = DateFormatter()
+            df.dateFormat = "yyyy-MM-dd'T'hh:mm:ss.SSSZ"
+            df.locale = Locale(identifier: "en_US_POSIX")
+            return df
+        }()
+
+        enum CodingKeys: String, CodingKey {
+            case timestamp = "@timestamp"
+            case message = "message"
+            case level = "level"
+            case context = "context"
+        }
+
+        public func encode(to encoder: Encoder) throws {
+            var container = encoder.container(keyedBy: CodingKeys.self)
+            try container.encode(LogMessage.dateFormatter.string(from: self.timestamp), forKey: .timestamp)
+            try container.encode(self.message, forKey: .message)
+            try container.encode(self.level.rawValue, forKey: .level)
+            let relativePathIndex = file.index(file.startIndex, offsetBy: file.hasPrefix(basePath) ? basePath.count : 0)
+            let context = "\(file[relativePathIndex...]):\(line):\(column) - \(function)"
+            try container.encode(context, forKey: .context)
+        }
+    }
+}

Sources/App/Middleware/RequestLoggerMiddleware.swift

@@ -9,15 +9,16 @@ final class RequestLoggerMiddleware: Middleware, ServiceType {
     }
 
     func respond(to request: Request, chainingTo next: Responder) throws -> Future<Vapor.Response> {
-        logger.log("""
-        📝 Request logger 📝
-        \(request)
-        ===========================
-        """)
+        logger.debug("""
+            📝 Request logger 📝
+            \(request)
+            ===========================
+            """
+        )
         return try next.respond(to: request)
     }
 
     static func makeService(for container: Container) throws -> RequestLoggerMiddleware {
-        return RequestLoggerMiddleware(logger: try container.make(PrintLogger.self))
+        return RequestLoggerMiddleware(logger: try container.make(LoggerProtocol.self))
     }
 }

Sources/App/configure.swift

@@ -11,15 +11,16 @@ enum ConfigurationError: Error {
 /// Called before your application initializes.
 public func configure(_ config: inout Config, _ env: inout Environment, _ services: inout Services) throws {
 
-    let logger = PrintLogger()
+    // Our Logz.io instance parses JSON output to feed searchable logs to Kibana & ElasticSearch
+    let logger = JSONLogger(minimumLogLevel: Environment.minimumLogLevel())
     let gitHubEventsService = GitHubEventsService(signatureToken: try Environment.gitHubWebhookSecret())
 
-    logger.log("👟 Starting up...")
+    logger.info("👟 Starting up...")
 
-    let dispatchService = try makeDispatchService(with: logger, gitHubEventsService)
+    let dispatchService = try makeDispatchService(logger: logger, gitHubEventsService: gitHubEventsService)
 
     services.register(dispatchService)
-    services.register(logger, as: PrintLogger.self)
+    services.register(logger, as: LoggerProtocol.self)
     services.register(RequestLoggerMiddleware.self)
 
     // Register routes to the router
@@ -31,13 +32,13 @@ public func configure(_ config: inout Config, _ env: inout Environment, _ servic
     var middlewares = MiddlewareConfig() // Create _empty_ middleware config
     // middlewares.use(FileMiddleware.self) // Serves files from `Public/` directory
     middlewares.use(ErrorMiddleware.self) // Catches errors and converts to HTTP response
-    middlewares.use(RequestLoggerMiddleware.self)
+    middlewares.use(RequestLoggerMiddleware(logger: logger))
     services.register(middlewares)
 
-    logger.log("🏁 Ready")
+    logger.info("🏁 Ready")
 }
 
-private func makeDispatchService(with logger: LoggerProtocol, _ gitHubEventsService: GitHubEventsService) throws -> DispatchService {
+private func makeDispatchService(logger: LoggerProtocol, gitHubEventsService: GitHubEventsService) throws -> DispatchService {
 
     let gitHubAPI = GitHubClient(session: URLSession(configuration: .default), token: try Environment.gitHubToken())
         .api(for: Repository(owner: try Environment.gitHubOrganization(), name: try Environment.gitHubRepository()))

Sources/Bot/Logging/Logger.swift

@@ -1,5 +1,48 @@
 import Foundation
 
+// MARK: LogLevel
+
+/// Different log levels
+public enum LogLevel: String, Equatable, CaseIterable {
+    /// For more verbose logs used when debugging in depth. Usually provides a lot of details
+    case debug = "DEBUG"
+    /// For informative logs, like state changes
+    case info = "INFO"
+    /// For reporting errors and failures
+    case error = "ERROR"
+}
+
+extension LogLevel: Comparable {
+    public static func < (lhs: LogLevel, rhs: LogLevel) -> Bool {
+        let index = LogLevel.allCases.firstIndex(of:)
+        return index(lhs)! < index(rhs)!
+    }
+}
+
+
+// MARK: LoggerProtocol
+
 public protocol LoggerProtocol {
-    func log(_ message: String)
+    /// Logs an encodable at the provided log level The encodable can be encoded to the required format.
+    /// The log level indicates the type of log and/or severity
+    ///
+    /// Normally, you will use one of the convenience methods (i.e., `verbose(...)`, `info(...)`).
+    func log(_ string: String, at level: LogLevel, file: String, function: String, line: UInt, column: UInt)
+}
+
+extension LoggerProtocol {
+    /// Debug logs are used to debug problems
+    public func debug(_ string: String, file: String = #file, function: String = #function, line: UInt = #line, column: UInt = #column) {
+        self.log(string, at: .debug, file: file, function: function, line: line, column: column)
+    }
+
+    /// Info logs are used to indicate a specific infrequent event occurring.
+    public func info(_ string: String, file: String = #file, function: String = #function, line: UInt = #line, column: UInt = #column) {
+        self.log(string, at: .info, file: file, function: function, line: line, column: column)
+    }
+
+    /// Error, indicates something went wrong and a part of the execution was failed.
+    public func error(_ string: String, file: String = #file, function: String = #function, line: UInt = #line, column: UInt = #column) {
+        self.log(string, at: .error, file: file, function: function, line: line, column: column)
+    }
 }

Sources/Bot/Services/DispatchService.swift

@@ -78,7 +78,7 @@ public final class DispatchService {
     }
 
     private func pullRequestDidChange(event: PullRequestEvent) {
-        logger.log("📣 Pull Request did change \(event.pullRequestMetadata) with action `\(event.action)`")
+        logger.info("📣 Pull Request did change \(event.pullRequestMetadata) with action `\(event.action)`")
 
         let targetBranch = event.pullRequestMetadata.reference.target.ref
         let mergeService = mergeServices.modify { (dict: inout [String: MergeService]) -> MergeService in
@@ -109,7 +109,7 @@ public final class DispatchService {
         scheduler: DateScheduler,
         initialPullRequests: [PullRequest] = []
     ) -> MergeService {
-        logger.log("🆕 New MergeService created for target branch `\(targetBranch)`")
+        logger.info("🆕 New MergeService created for target branch `\(targetBranch)`")
         let mergeService = MergeService(
             targetBranch: targetBranch,
             integrationLabel: integrationLabel,
@@ -137,7 +137,7 @@ public final class DispatchService {
             .startWithValues { [weak self, service = mergeService, logger = logger] state in
                 guard let self = self else { return }
 
-                logger.log("👋 MergeService for target branch `\(targetBranch)` has been idle for \(self.idleMergeServiceCleanupDelay)s, destroying")
+                logger.info("👋 MergeService for target branch `\(targetBranch)` has been idle for \(self.idleMergeServiceCleanupDelay)s, destroying")
                 self.mergeServices.modify { dict in
                     dict[targetBranch] = nil
                 }

Sources/Bot/Services/MergeService.swift

@@ -85,8 +85,8 @@ public final class MergeService {
 
         state.producer
             .combinePrevious()
-            .startWithValues { old, new in
-                logger.log("♻️ [\(new.targetBranch) queue] Did change state\n - 📜 \(old) \n - 📄 \(new)")
+            .startWithValues { (old, new) in
+                logger.info("♻️ [\(new.targetBranch) queue] Did change state\n - 📜 \(old) \n - 📄 \(new)")
             }
     }
 
@@ -535,7 +535,7 @@ extension MergeService {
                 .observe(on: scheduler)
                 .filter { change in change.state != .pending && change.isRelative(toBranch: pullRequest.source.ref) }
                 .on { change in
-                    logger.log("📣 Status check `\(change.context)` finished with result: `\(change.state)` (SHA: `\(change.sha)`)")
+                    logger.info("📣 Status check `\(change.context)` finished with result: `\(change.state)` (SHA: `\(change.sha)`)")
                 }
                 .debounce(additionalStatusChecksGracePeriod, on: scheduler)
                 .flatMap(.latest) { change in
@@ -595,9 +595,13 @@ extension MergeService {
         return Feedback(skippingRepeated: IntegrationHandler.init) { handler -> SignalProducer<Event, Never> in
             return SignalProducer.merge(
                 github.postComment(handler.failureMessage, in: handler.pullRequest)
-                    .on(failed: { error in logger.log("🚨 Failed to post failure message in PR #\(handler.pullRequest.number) with error: \(error)") }),
+                    .on(failed: { error in
+                        logger.error("🚨 Failed to post failure message in PR #\(handler.pullRequest.number) with error: \(error)")
+                    }),
                 github.removeLabel(handler.integrationLabel, from: handler.pullRequest)
-                    .on(failed: { error in logger.log("🚨 Failed to remove integration label from PR #\(handler.pullRequest.number) with error: \(error)") })
+                    .on(failed: { error in
+                        logger.error("🚨 Failed to remove integration label from PR #\(handler.pullRequest.number) with error: \(error)")
+                    })
                 )
                 .flatMapError { _ in .empty }
                 .then(SignalProducer(value: Event.integrationFailureHandled))

Tests/AppTests/Logger/JSONLoggerTests.swift

@@ -0,0 +1,75 @@
+import XCTest
+@testable import App
+import Bot
+
+class JSONLoggerTests: XCTestCase {
+    func test_json_logs_formatting() throws {
+        let message = JSONLogger.LogMessage(
+            timestamp: JSONLoggerTests.fixedDate,
+            message: JSONLoggerTests.message,
+            level: .debug,
+            file: #file,
+            function: "somefunction",
+            line: 1337,
+            column: 42
+        )
+
+        let serializer = JSONEncoder()
+        let data = try serializer.encode(message)
+
+        XCTAssertEqualJSON(data, JSONLoggerTests.cannedLog)
+    }
+
+    // Check that we print everything if minimum log level is .debug
+    func test_loglevel_compare_debug_level() {
+        XCTAssertEqual(LogLevel.debug >= .debug, true)
+        XCTAssertEqual(LogLevel.info  >= .debug, true)
+        XCTAssertEqual(LogLevel.error >= .debug, true)
+    }
+
+    // Check that we print anything above but nothing below the .info level
+    func test_loglevel_compare_info_level() {
+        XCTAssertEqual(LogLevel.debug >= .info, false)
+        XCTAssertEqual(LogLevel.info  >= .info, true)
+        XCTAssertEqual(LogLevel.error >= .info, true)
+    }
+
+    // Check that we print only error logs when minimum level is .error
+    func test_loglevel_compare_error_level() {
+        XCTAssertEqual(LogLevel.debug >= .error, false)
+        XCTAssertEqual(LogLevel.info  >= .error, false)
+        XCTAssertEqual(LogLevel.error >= .error, true)
+    }
+
+    // MARK: Canned data
+
+    private static let fixedDate: Date = {
+        return DateComponents(
+            calendar: Calendar(identifier: .gregorian),
+            timeZone: TimeZone(secondsFromGMT: 0),
+            year: 2020, month: 2, day: 1,
+            hour: 10, minute: 20, second: 30,
+            nanosecond: 456_000_000
+        ).date!
+    }()
+
+    private static let message = """
+        Some long log message
+
+        For example, one spanning multiple lines
+        like an HTTP request body for example
+        """
+
+    private static let escapedMessage = message
+        .split(separator: "\n", omittingEmptySubsequences: false)
+        .joined(separator: "\\n")
+
+    private static let cannedLog = """
+        {
+            "@timestamp": "2020-02-01T10:20:30.456+0000",
+            "message": "\(escapedMessage)",
+            "level": "DEBUG",
+            "context": "Tests/AppTests/Logger/JSONLoggerTests.swift:1337:42 - somefunction"
+        }
+        """.data(using: .utf8)!
+}

Tests/AppTests/TestUtils.swift

@@ -0,0 +1 @@
+../TestUtils.swift

Tests/AppTests/XCTestManifests.swift

@@ -0,0 +1,21 @@
+#if !canImport(ObjectiveC)
+import XCTest
+
+extension JSONLoggerTests {
+    // DO NOT MODIFY: This is autogenerated, use:
+    //   `swift test --generate-linuxmain`
+    // to regenerate.
+    static let __allTests__JSONLoggerTests = [
+        ("test_json_logs_formatting", test_json_logs_formatting),
+        ("test_loglevel_compare_debug_level", test_loglevel_compare_debug_level),
+        ("test_loglevel_compare_error_level", test_loglevel_compare_error_level),
+        ("test_loglevel_compare_info_level", test_loglevel_compare_info_level),
+    ]
+}
+
+public func __allTests() -> [XCTestCaseEntry] {
+    return [
+        testCase(JSONLoggerTests.__allTests__JSONLoggerTests),
+    ]
+}
+#endif