Merge pull request #17 from Mordil/14-logging

Add initial `swift-log` support for most paths

Author: Mordil

Package.swift

@@ -8,10 +8,11 @@ let package = Package(
         .library(name: "NIORedis", targets: ["NIORedis"])
     ],
     dependencies: [
+        .package(url: "https://github.com/apple/swift-log.git", .branch("master")),
         .package(url: "https://github.com/apple/swift-nio.git", .branch("master"))
     ],
     targets: [
-        .target(name: "NIORedis", dependencies: ["NIO"]),
+        .target(name: "NIORedis", dependencies: ["NIO", "Logging"]),
         .testTarget(name: "NIORedisTests", dependencies: ["NIORedis", "NIO"])
     ]
 )

Sources/NIORedis/ChannelHandlers/RESPEncoder+M2BE.swift

@@ -7,5 +7,15 @@ extension RESPEncoder: MessageToByteEncoder {
     /// See `RESPEncoder.encode(data:out:)`
     public func encode(data: RESPValue, out: inout ByteBuffer) throws {
         encode(data, into: &out)
+
+        logger.debug("Encoded \(data) to \(getPrintableString(for: &out))")
+    }
+
+    // used only for debugging purposes where we build a formatted string for the encoded bytes
+    private func getPrintableString(for buffer: inout ByteBuffer) -> String {
+        return String(describing: buffer.getString(at: 0, length: buffer.readableBytes))
+            .dropFirst(9)
+            .dropLast()
+            .description
     }
 }

Sources/NIORedis/ChannelHandlers/RedisCommandHandler.swift

@@ -1,4 +1,5 @@
 import Foundation
+import Logging
 import NIO
 
 /// A context for `RedisCommandHandler` to operate within.
@@ -18,9 +19,17 @@ public struct RedisCommandContext {
 open class RedisCommandHandler {
     /// Queue of promises waiting to receive a response value from a sent command.
     private var commandResponseQueue: [EventLoopPromise<RESPValue>]
+    private var logger: Logger
 
-    public init() {
+    deinit {
+        guard commandResponseQueue.count > 0 else { return }
+        logger.warning("Command handler deinit when queue is not empty. Current size: \(commandResponseQueue.count)")
+    }
+
+    public init(logger: Logger = Logger(label: "NIORedis.CommandHandler")) {
         self.commandResponseQueue = []
+        self.logger = logger
+        self.logger[metadataKey: "CommandHandler"] = "\(UUID())"
     }
 }
 
@@ -49,7 +58,9 @@ extension RedisCommandHandler: ChannelInboundHandler {
         let value = unwrapInboundIn(data)
 
         guard let leadPromise = commandResponseQueue.last else {
-            return assertionFailure("Read triggered with an empty promise queue! Ignoring: \(value)")
+            assertionFailure("Read triggered with an empty promise queue! Ignoring: \(value)")
+            logger.emergency("Read triggered with no promise waiting in the queue!")
+            return
         }
 
         let popped = commandResponseQueue.popLast()

Sources/NIORedis/RESP/RESPEncoder.swift

@@ -1,8 +1,14 @@
+import Logging
+
 /// Encodes `RedisValue` into a raw `ByteBuffer`, formatted according to the Redis Serialization Protocol (RESP).
 ///
 /// See: [https://redis.io/topics/protocol](https://redis.io/topics/protocol)
 public final class RESPEncoder {
-    public init() { }
+    let logger: Logger
+
+    public init(logger: Logger = Logger(label: "NIORedis.RESPEncoder")) {
+        self.logger = logger
+    }
 
     /// Encodes the `RedisValue` to bytes, following the RESP specification.
     ///

Sources/NIORedis/RedisConnection.swift

@@ -1,3 +1,5 @@
+import Logging
+import Foundation
 import NIO
 import NIOConcurrencyHelpers
 
@@ -51,6 +53,8 @@ extension RedisConnection {
     public var eventLoop: EventLoop { return self.channel.eventLoop }
 }
 
+private let loggingKeyID = "RedisConnection"
+
 /// A basic `RedisConnection`.
 public final class NIORedisConnection: RedisConnection {
     /// See `RedisConnection.channel`.
@@ -60,36 +64,51 @@ public final class NIORedisConnection: RedisConnection {
     public var isClosed: Bool { return _isClosed.load() }
     private var _isClosed = Atomic<Bool>(value: false)
 
+    private var logger: Logger
+
     deinit { assert(_isClosed.load(), "Redis connection was not properly shut down!") }
 
     /// Creates a new connection on the provided channel.
     /// - Note: This connection will take ownership of the `Channel` object.
     /// - Important: Call `close()` before deinitializing to properly cleanup resources.
-    public init(channel: Channel) {
+    public init(channel: Channel, logger: Logger = Logger(label: "NIORedis.Connection")) {
         self.channel = channel
+        self.logger = logger
+
+        self.logger[metadataKey: loggingKeyID] = "\(UUID())"
+        self.logger.debug("Connection created.")
     }
 
     /// See `RedisConnection.close()`.
     @discardableResult
     public func close() -> EventLoopFuture<Void> {
-        guard !_isClosed.exchange(with: true) else { return channel.eventLoop.makeSucceededFuture(()) }
+        guard !_isClosed.exchange(with: true) else {
+            logger.notice("Connection received more than one close() request.")
+            return channel.eventLoop.makeSucceededFuture(())
+        }
 
         return send(command: "QUIT")
             .flatMap { _ in
                 let promise = self.channel.eventLoop.makePromise(of: Void.self)
                 self.channel.close(promise: promise)
                 return promise.futureResult
             }
+            .map { self.logger.debug("Connection closed.") }
     }
 
     /// See `RedisConnection.makePipeline()`.
     public func makePipeline() -> RedisPipeline {
-        return NIORedisPipeline(channel: channel)
+        var logger = Logger(label: "NIORedis.Pipeline")
+        logger[metadataKey: loggingKeyID] = self.logger[metadataKey: loggingKeyID]
+        return NIORedisPipeline(channel: channel, logger: logger)
     }
 
     /// See `RedisCommandExecutor.send(command:with:)`.
     public func send(command: String, with arguments: [RESPValueConvertible] = []) -> EventLoopFuture<RESPValue> {
-        guard !_isClosed.load() else { return channel.eventLoop.makeFailedFuture(RedisError.connectionClosed) }
+        guard !_isClosed.load() else {
+            logger.error("Received command when connection is closed.")
+            return channel.eventLoop.makeFailedFuture(RedisError.connectionClosed)
+        }
 
         let args = arguments.map { $0.convertedToRESPValue() }
 
@@ -99,6 +118,12 @@ public final class NIORedisConnection: RedisConnection {
             promise: promise
         )
 
+        promise.futureResult.whenComplete { result in
+            guard case let .failure(error) = result else { return }
+            self.logger.error("\(error)")
+        }
+        logger.debug("Sending command \"\(command)\" with \(arguments) encoded as \(args)")
+
         _ = channel.writeAndFlush(context)
 
         return promise.futureResult

Sources/NIORedis/RedisPipeline.swift

@@ -1,4 +1,5 @@
 import Foundation
+import Logging
 
 /// An object that provides a mechanism to "pipeline" multiple Redis commands in sequence,
 /// providing an aggregate response of all the Redis responses for each individual command.
@@ -36,6 +37,7 @@ public protocol RedisPipeline {
 }
 
 public final class NIORedisPipeline {
+    private var logger: Logger
     /// The channel being used to send commands with.
     private let channel: Channel
 
@@ -44,9 +46,13 @@ public final class NIORedisPipeline {
 
     /// Creates a new pipeline queue that will write to the channel provided.
     /// - Parameter channel: The `Channel` to write to.
-    public init(channel: Channel) {
+    public init(channel: Channel, logger: Logger = Logger(label: "NIORedis.Pipeline")) {
         self.channel = channel
+        self.logger = logger
         self.queuedCommandResults = []
+
+        self.logger[metadataKey: "RedisPipeline"] = "\(UUID())"
+        self.logger.debug("Pipeline created.")
     }
 }
 
@@ -62,22 +68,30 @@ extension NIORedisPipeline: RedisPipeline {
         // We are passing ourselves in as the executor instance,
         // and our implementation of `RedisCommandExecutor.send(command:with:) handles the actual queueing.
         _ = operation(self)
+        logger.debug("Command queued. Pipeline size: \(count)")
         return self
     }
 
     /// See `RedisPipeline.execute()`.
     /// - Important: If any of the commands fail, the remaining commands will not execute and the `EventLoopFuture` will fail.
     public func execute() -> EventLoopFuture<[RESPValue]> {
-        channel.flush()
-
         let response = EventLoopFuture<[RESPValue]>.reduce(
             into: [],
             queuedCommandResults,
             on: channel.eventLoop,
             { (results, response) in results.append(response) }
         )
 
-        response.whenComplete { _ in self.queuedCommandResults = [] }
+        response.whenComplete { result in
+            self.queuedCommandResults = []
+
+            switch result {
+            case .failure(let error): self.logger.error("\(error)")
+            case .success: self.logger.debug("Pipeline executed.")
+            }
+        }
+
+        channel.flush()
 
         return response
     }
@@ -101,6 +115,8 @@ extension NIORedisPipeline: RedisCommandExecutor {
 
         queuedCommandResults.append(promise.futureResult)
 
+        logger.debug("Enqueuing command \"\(command)\" with \(arguments) encoded as \(args)")
+
         _ = channel.write(context)
 
         return promise.futureResult