Improve control channel log readability

- Use consistent convention in id logging.
- Describe packet codes.
- Encapsulate packet logging.

TunnelKit/Sources/Core/ControlChannel.swift

@@ -42,7 +42,13 @@ class ControlChannel {
     
     private(set) var sessionId: Data?
     
-    var remoteSessionId: Data?
+    var remoteSessionId: Data? {
+        didSet {
+            if let id = remoteSessionId {
+                log.debug("Control: Remote sessionId is \(id.toHex())")
+            }
+        }
+    }
 
     private var queue: BidirectionalState<[ControlPacket]>
 
@@ -138,9 +144,9 @@ class ControlChannel {
         // packet count
         let packetCount = currentPacketId.outbound - oldIdOut
         if (packetCount > 1) {
-            log.debug("Enqueued \(packetCount) control packets [\(oldIdOut)-\(currentPacketId.outbound - 1)]")
+            log.debug("Control: Enqueued \(packetCount) packets [\(oldIdOut)-\(currentPacketId.outbound - 1)]")
         } else {
-            log.debug("Enqueued 1 control packet [\(oldIdOut)]")
+            log.debug("Control: Enqueued 1 packet [\(oldIdOut)]")
         }
     }
     
@@ -150,7 +156,7 @@ class ControlChannel {
             if let sentDate = packet.sentDate {
                 let timeAgo = -sentDate.timeIntervalSinceNow
                 guard (timeAgo >= CoreConfiguration.retransmissionLimit) else {
-                    log.debug("Skip control packet with id \(packet.packetId) (sent on \(sentDate), \(timeAgo) seconds ago)")
+                    log.debug("Control: Skip writing packet with packetId \(packet.packetId) (sent on \(sentDate), \(timeAgo) seconds ago)")
                     continue
                 }
             }
@@ -178,7 +184,7 @@ class ControlChannel {
             throw SessionError.missingSessionId
         }
         guard acksRemoteSessionId == sessionId else {
-            log.error("Ack session mismatch (\(acksRemoteSessionId.toHex()) != \(sessionId.toHex()))")
+            log.error("Control: Ack session mismatch (\(acksRemoteSessionId.toHex()) != \(sessionId.toHex()))")
             throw SessionError.sessionMismatch
         }
         

TunnelKit/Sources/Core/ControlChannelSerializer.swift

@@ -93,8 +93,6 @@ extension ControlChannel {
                 let remoteSessionId = packet.subdata(offset: offset, count: PacketSessionIdLength)
                 offset += PacketSessionIdLength
 
-                log.debug("Server acked packetIds \(ids) with remoteSessionId \(remoteSessionId.toHex())")
-                
                 ackIds = ids
                 ackRemoteSessionId = remoteSessionId
             }
@@ -113,20 +111,11 @@ extension ControlChannel {
                 throw ControlChannelError("Missing packetId")
             }
             let packetId = packet.networkUInt32Value(from: offset)
-            log.debug("Control packet has packetId \(packetId)")
             offset += PacketIdLength
 
             var payload: Data?
             if offset < end {
                 payload = packet.subdata(in: offset..<end)
-
-                if let payload = payload {
-                    if CoreConfiguration.logsSensitiveData {
-                        log.debug("Control packet payload (\(payload.count) bytes): \(payload.toHex())")
-                    } else {
-                        log.debug("Control packet payload (\(payload.count) bytes)")
-                    }
-                }
             }
 
             let controlPacket = ControlPacket(code: code, key: key, sessionId: sessionId, packetId: packetId, payload: payload)

TunnelKit/Sources/Core/Packet.swift

@@ -100,6 +100,46 @@ public class PacketStream {
     }
 }
 
+/// :nodoc:
+extension ControlPacket {
+
+    /// :nodoc:
+    open override var description: String {
+        var msg: [String] = ["\(code) | \(key)"]
+        msg.append("sid: \(sessionId.toHex())")
+        if let ackIds = ackIds, let ackRemoteSessionId = ackRemoteSessionId {
+            msg.append("acks: {\(ackIds), \(ackRemoteSessionId.toHex())}")
+        }
+        if !isAck {
+            msg.append("pid: \(packetId)")
+        }
+        if let payload = payload {
+            if CoreConfiguration.logsSensitiveData {
+                msg.append("[\(payload.count) bytes] -> \(payload.toHex())")
+            } else {
+                msg.append("[\(payload.count) bytes]")
+            }
+        }
+        return "{\(msg.joined(separator: ", "))}"
+    }
+}
+
 class DataPacket {
     static let pingString = Data(hex: "2a187bf3641eb4cb07ed2d0a981fc748")
 }
+
+/// :nodoc:
+extension PacketCode: CustomStringConvertible {
+    public var description: String {
+        switch self {
+        case .softResetV1:          return "SOFT_RESET_V1"
+        case .controlV1:            return "CONTROL_V1"
+        case .ackV1:                return "ACK_V1"
+        case .dataV1:               return "DATA_V1"
+        case .hardResetClientV2:    return "HARD_RESET_CLIENT_V2"
+        case .hardResetServerV2:    return "HARD_RESET_SERVER_V2"
+        case .dataV2:               return "DATA_V2"
+        case .unknown:              return "UNKNOWN"
+        }
+    }
+}

TunnelKit/Sources/Core/SessionProxy.swift

@@ -426,7 +426,6 @@ public class SessionProxy {
                 log.warning("Dropped malformed packet (unknown code: \(codeValue))")
                 continue
             }
-            
 //            log.verbose("Parsed packet with code \(code)")
 
             var offset = 1
@@ -454,7 +453,6 @@ public class SessionProxy {
                 continue
             }
 
-            log.debug("Packet has code \(code.rawValue)")
             let controlPacket: ControlPacket
             do {
                 let parsedPacket = try controlChannel.readInboundPacket(withData: packet, offset: 0)
@@ -470,7 +468,6 @@ public class SessionProxy {
 //                return
             }
 
-            log.debug("Packet has sessionId \(controlPacket.sessionId.toHex()) and \(controlPacket.ackIds?.count ?? 0) acks entries")
             sendAck(for: controlPacket)
 
             let pendingInboundQueue = controlChannel.enqueueInboundPacket(packet: controlPacket)
@@ -663,8 +660,6 @@ public class SessionProxy {
             return
         }
         
-        log.debug("Handle control packet with code \(packet.code.rawValue) and id \(packet.packetId)")
-
         if (((packet.code == .hardResetServerV2) && (negotiationKey.state == .hardReset)) ||
             ((packet.code == .softResetV1) && (negotiationKey.state == .softReset))) {
             
@@ -672,7 +667,7 @@ public class SessionProxy {
                 controlChannel.remoteSessionId = packet.sessionId
             }
             guard let remoteSessionId = controlChannel.remoteSessionId else {
-                log.error("No remote session id (never set)")
+                log.error("No remote sessionId (never set)")
                 deferStop(.shutdown, SessionError.missingSessionId)
                 return
             }
@@ -684,7 +679,6 @@ public class SessionProxy {
 
             negotiationKey.state = .tls
 
-            log.debug("Remote sessionId is \(remoteSessionId.toHex())")
             log.debug("Start TLS handshake")
 
             negotiationKey.tlsOptional = TLSBox(
@@ -709,7 +703,7 @@ public class SessionProxy {
         }
         else if ((packet.code == .controlV1) && (negotiationKey.state == .tls)) {
             guard let remoteSessionId = controlChannel.remoteSessionId else {
-                log.error("No remote session id found in packet (control packets before server HARD_RESET)")
+                log.error("No remote sessionId found in packet (control packets before server HARD_RESET)")
                 deferStop(.shutdown, SessionError.missingSessionId)
                 return
             }