Better logging

This commit is contained in:
Leon Böttger committed 2025-08-11 09:06:19 +02:00
1 parent aacd95570b
commit dc32e92d9a
4 files changed
+61 -61

No files matched your search

@@ -57,7 +57,7 @@ class InboundNearbyConnection: NearbyConnection {
override func processReceivedFrame(frameData: Data) {
if currentState != .receivingFiles {
log("[InboundNearbyConnection] Received frame in state \(currentState)...")
log("[InboundNearbyConnection \(self.id)] Received frame in state \(currentState)...")
}
do {
@@ -82,7 +82,7 @@ class InboundNearbyConnection: NearbyConnection {
do {
smsg = try Securemessage_SecureMessage(serializedBytes: frameData)
} catch {
log("[InboundNearbyConnection] Error deserializing secure message (probably due to packet filter)")
log("[InboundNearbyConnection \(self.id)] Error deserializing secure message (probably due to packet filter)")
lastError = NearbyError.packetFilterError
protocolError()
}
@@ -93,7 +93,7 @@ class InboundNearbyConnection: NearbyConnection {
}
} catch {
lastError = error
log("[InboundNearbyConnection] Error receiving frame: \(error) in state \(currentState).")
log("[InboundNearbyConnection \(self.id)] Error receiving frame: \(error) in state \(currentState).")
protocolError()
}
}
@@ -103,7 +103,7 @@ class InboundNearbyConnection: NearbyConnection {
if frame.hasV1 && frame.v1.hasType, case .cancel = frame.v1.type {
self.lastError = NearbyError.canceled(reason: .userCanceled)
self.cancelled = true
log("[InboundNearbyConnection] Transfer canceled")
log("[InboundNearbyConnection \(self.id)] Transfer canceled")
try sendDisconnectionAndDisconnect()
return
}
@@ -115,7 +115,7 @@ class InboundNearbyConnection: NearbyConnection {
case .receivedPairedKeyResult:
try processIntroductionFrame(frame)
default:
log("[InboundNearbyConnection] Unexpected connection state in processTransferSetupFrame: \(currentState)")
log("[InboundNearbyConnection \(self.id)] Unexpected connection state in processTransferSetupFrame: \(currentState)")
log(frame.debugDescription)
}
}
@@ -147,7 +147,7 @@ class InboundNearbyConnection: NearbyConnection {
// only for logging
self.bytesTransferred += Int64(frame.payloadChunk.body.count)
} catch {
log("[InboundNearbyConnection] Error occurred during writing file: \(error.localizedDescription)")
log("[InboundNearbyConnection \(self.id)] Error occurred during writing file: \(error.localizedDescription)")
throw NearbyError.protocolError(error.localizedDescription)
}
@@ -163,7 +163,7 @@ class InboundNearbyConnection: NearbyConnection {
filesToBeReceived.removeValue(forKey: id)
if filesToBeReceived.isEmpty {
log("[InboundNearbyConnection] All files received, sending disconnection frame and disconnecting.")
log("[InboundNearbyConnection \(self.id)] All files received, sending disconnection frame and disconnecting.")
try sendDisconnectionAndDisconnect()
}
}
@@ -199,7 +199,7 @@ class InboundNearbyConnection: NearbyConnection {
}
}
log("[InboundNearbyConnection] Received text payload. Disconnecting...")
log("[InboundNearbyConnection \(self.id)] Received text payload. Disconnecting...")
try sendDisconnectionAndDisconnect()
return true
}
@@ -215,7 +215,7 @@ class InboundNearbyConnection: NearbyConnection {
filesToBeReceived.removeValue(forKey: id)
SaveFilesManager.shared.registerFileFinishedDownloading(fileInfo.destinationURL)
log("[InboundNearbyConnection] Received file payload. Disconnecting...")
log("[InboundNearbyConnection \(self.id)] Received file payload. Disconnecting...")
try sendDisconnectionAndDisconnect()
return true
}
@@ -250,7 +250,7 @@ class InboundNearbyConnection: NearbyConnection {
guard msg.hasMessageType, msg.hasMessageData else { throw NearbyError.requiredFieldMissing("clientInit ukey2message.type|data") }
guard case .clientInit = msg.messageType else {
sendUkey2Alert(type: .badMessageType)
log("[InboundNearbyConnection] Unsupported message type: \(msg.messageType)")
log("[InboundNearbyConnection \(self.id)] Unsupported message type: \(msg.messageType)")
throw NearbyError.ukey2
}
let clientInit: Securegcm_Ukey2ClientInit
@@ -258,17 +258,17 @@ class InboundNearbyConnection: NearbyConnection {
clientInit = try Securegcm_Ukey2ClientInit(serializedBytes: msg.messageData)
} catch {
sendUkey2Alert(type: .badMessageData)
log("[InboundNearbyConnection] Failed to parse clientInit: \(error)")
log("[InboundNearbyConnection \(self.id)] Failed to parse clientInit: \(error)")
throw NearbyError.ukey2
}
guard clientInit.version == 1 else {
sendUkey2Alert(type: .badVersion)
log("[InboundNearbyConnection] Unsupported clientInit version: \(clientInit.version)")
log("[InboundNearbyConnection \(self.id)] Unsupported clientInit version: \(clientInit.version)")
throw NearbyError.ukey2
}
guard clientInit.random.count == 32 else {
sendUkey2Alert(type: .badRandom)
log("[InboundNearbyConnection] Unsupported clientInit random: \(clientInit.random.count)")
log("[InboundNearbyConnection \(self.id)] Unsupported clientInit random: \(clientInit.random.count)")
throw NearbyError.ukey2
}
var found = false
@@ -281,12 +281,12 @@ class InboundNearbyConnection: NearbyConnection {
}
guard found else {
sendUkey2Alert(type: .badHandshakeCipher)
log("[InboundNearbyConnection] Unsupported clientInit handshakeCipher: \(clientInit.cipherCommitments)")
log("[InboundNearbyConnection \(self.id)] Unsupported clientInit handshakeCipher: \(clientInit.cipherCommitments)")
throw NearbyError.ukey2
}
guard clientInit.nextProtocol == "AES_256_CBC-HMAC_SHA256" else {
sendUkey2Alert(type: .badNextProtocol)
log("[InboundNearbyConnection] Unsupported clientInit nextProtocol: \(clientInit.nextProtocol)")
log("[InboundNearbyConnection \(self.id)] Unsupported clientInit nextProtocol: \(clientInit.nextProtocol)")
throw NearbyError.ukey2
}
@@ -320,14 +320,14 @@ class InboundNearbyConnection: NearbyConnection {
private func processUkey2ClientFinish(_ msg: Securegcm_Ukey2Message, raw: Data) throws {
guard msg.hasMessageType, msg.hasMessageData else { throw NearbyError.requiredFieldMissing("clientFinish ukey2message.type|data") }
guard case .clientFinish = msg.messageType else {
log("[InboundNearbyConnection] Unexpected message type \(msg.messageType)")
log("[InboundNearbyConnection \(self.id)] Unexpected message type \(msg.messageType)")
throw NearbyError.ukey2
}
var sha = SHA512()
sha.update(data: raw)
guard cipherCommitment == Data(sha.finalize()) else {
log("[InboundNearbyConnection] Invalid cipherCommitment in clientFinish")
log("[InboundNearbyConnection \(self.id)] Invalid cipherCommitment in clientFinish")
throw NearbyError.ukey2
}
@@ -368,7 +368,7 @@ class InboundNearbyConnection: NearbyConnection {
try sendTransferSetupFrame(pairedEncryption)
currentState = .sentConnectionResponse
} else {
log("[InboundNearbyConnection] Unhandled offline frame plaintext: \(frame)")
log("[InboundNearbyConnection \(self.id)] Unhandled offline frame plaintext: \(frame)")
}
}
@@ -459,7 +459,7 @@ class InboundNearbyConnection: NearbyConnection {
func rejectDueToUnsupportedFileType(_ frame: Sharing_Nearby_Frame) {
log("[InboundNearbyConnection] Rejecting transfer due to unsupported file type. Frame is \(frame.debugDescription)")
log("[InboundNearbyConnection \(self.id)] Rejecting transfer due to unsupported file type. Frame is \(frame.debugDescription)")
NearbyConnectionManager.shared.mainAppDelegate?.showUnsupportedFileAlert(for: remoteDeviceInfo)
rejectTransfer(with: .unsupportedAttachmentType)
@@ -479,7 +479,7 @@ class InboundNearbyConnection: NearbyConnection {
private func acceptTransfer(storeInTemp: Bool) {
if currentState == .disconnected {
log("[InboundNearbyConnection] Detected timeout, not accepting transfer")
log("[InboundNearbyConnection \(self.id)] Detected timeout, not accepting transfer")
return
}
@@ -506,7 +506,7 @@ class InboundNearbyConnection: NearbyConnection {
filesToBeReceived[id]!.progress = progress
filesToBeReceived[id]!.created = true
log("[InboundNearbyConnection] Accepted file with size \(file.meta.size)")
log("[InboundNearbyConnection \(self.id)] Accepted file with size \(file.meta.size)")
}
var frame = Sharing_Nearby_Frame()
@@ -527,7 +527,7 @@ class InboundNearbyConnection: NearbyConnection {
self.wasRejected = true
log("[InboundNearbyConnection] Rejecting transfer because of \( reason)")
log("[InboundNearbyConnection \(self.id)] Rejecting transfer because of \( reason)")
var frame = Sharing_Nearby_Frame()
frame.version = .v1
@@ -537,7 +537,7 @@ class InboundNearbyConnection: NearbyConnection {
try sendTransferSetupFrame(frame)
try sendDisconnectionAndDisconnect()
} catch {
log("[InboundNearbyConnection] Error \(error)")
log("[InboundNearbyConnection \(self.id)] Error \(error)")
protocolError()
}
}
+26 -26
View File
@@ -28,7 +28,7 @@ class NearbyConnection {
var cancelled: Bool = false
var isTransferring: Bool = false {
didSet {
log("[NearbyConnection] Now transferring. Setting up data transfer inactivity timer.")
log("[NearbyConnection \(self.id)] Now transferring. Setting up data transfer inactivity timer.")
startDataTransferTimer(previousBytesTransferred: bytesTransferred)
}
}
@@ -76,7 +76,7 @@ class NearbyConnection {
// If connection reset by peer, it could still be a valid file transfer that has not been processed yet. => Wait
if err == .posix(.ECONNRESET) {
log("[NearbyConnection] Network connection reset error detected.")
log("[NearbyConnection \(self.id)] Network connection reset error detected.")
self.connectionClosedByPeer {
recordErrorAndDisconnect(err: err)
}
@@ -87,7 +87,7 @@ class NearbyConnection {
}
}
else {
log("[NearbyConnection] Connection already closed, ignoring state update: \(state)")
log("[NearbyConnection \(self.id)] Connection already closed, ignoring state update: \(state)")
}
}
@@ -95,18 +95,18 @@ class NearbyConnection {
func recordErrorAndDisconnect(err: NWError) {
self.lastError = err
log("[NearbyConnection] Connection Error: \(err)")
log("[NearbyConnection \(self.id)] Connection Error: \(err)")
// If the error is a connection reset, it could be due to firewall issues.
if err == .posix(.ENOTCONN) {
log("[NearbyConnection] Network not connected error detected.")
log("[NearbyConnection \(self.id)] Network not connected error detected.")
ConnectionFailureTracker.shared.recordFailure {
NearbyConnectionManager.shared.mainAppDelegate?.showFirewallAlert()
}
}
if err == .posix(.ENETDOWN) {
log("[NearbyConnection] Network down error detected.")
log("[NearbyConnection \(self.id)] Network down error detected.")
self.lastError = NearbyError.protocolError("Error.NetworkDown".localized())
}
@@ -130,7 +130,7 @@ class NearbyConnection {
func protocolError() {
log("[NearbyConnection] Protocol error: \(String(describing: lastError))")
log("[NearbyConnection \(self.id)] Protocol error: \(String(describing: lastError))")
disconnect()
}
@@ -166,7 +166,7 @@ class NearbyConnection {
return
}
if isComplete {
log("[NearbyConnection] Connection closed by peer during receiveFrameAsync()")
log("[NearbyConnection \(self.id)] Connection closed by peer during receiveFrameAsync()")
self.connectionClosedByPeer {
self.lastError = NearbyError.protocolError("Error.ClosedByPeer".localized())
self.disconnect()
@@ -174,13 +174,13 @@ class NearbyConnection {
return
}
if !(error == nil) {
log("[NearbyConnection] Error during receiveFrameAsync(): \(String(describing: error))")
log("[NearbyConnection \(self.id)] Error during receiveFrameAsync(): \(String(describing: error))")
self.lastError = error
self.protocolError()
return
}
guard let content = content else {
log("[NearbyConnection] Received nil content during receiveFrameAsync(). IsComplete: \(isComplete)")
log("[NearbyConnection \(self.id)] Received nil content during receiveFrameAsync(). IsComplete: \(isComplete)")
assertionFailure()
return
}
@@ -198,19 +198,19 @@ class NearbyConnection {
private func receiveFrameAsync(length: UInt32) {
connection.receive(minimumIncompleteLength: Int(length), maximumLength: Int(length)) { content, _, isComplete, _ in
connection.receive(minimumIncompleteLength: Int(length), maximumLength: Int(length)) { [self] content, _, isComplete, _ in
if self.connectionClosed {
return
}
if isComplete {
log("[NearbyConnection] Connection closed by peer during receiveFrameAsync(length:)")
log("[NearbyConnection \(self.id)] Connection closed by peer during receiveFrameAsync(length:)")
if let content = content, !content.isEmpty {
log("[NearbyConnection] Connection closed by peer during receiveFrameAsync(length:), but trying to process the frame anyway. Frame length: \(content.count)")
log("[NearbyConnection \(self.id)] Connection closed by peer during receiveFrameAsync(length:), but trying to process the frame anyway. Frame length: \(content.count)")
self.processReceivedFrame(frameData: content)
}
else {
log("[NearbyConnection] Connection closed by peer during receiveFrameAsync(length:), but no content received anymore (\(String(describing: content))).")
log("[NearbyConnection \(self.id)] Connection closed by peer during receiveFrameAsync(length:), but no content received anymore (\(String(describing: content))).")
}
self.connectionClosedByPeer {
@@ -221,7 +221,7 @@ class NearbyConnection {
return
}
guard let content = content else {
log("[NearbyConnection] Received nil content during receiveFrameAsync(length:). IsComplete: \(isComplete)")
log("[NearbyConnection \(self.id)] Received nil content during receiveFrameAsync(length:). IsComplete: \(isComplete)")
self.protocolError()
return
}
@@ -297,7 +297,7 @@ class NearbyConnection {
func sendTransferSetupFrame(_ frame: Sharing_Nearby_Frame) throws {
log("[NearbyConnection] Sending transfer setup frame.")
log("[NearbyConnection \(self.id)] Sending transfer setup frame.")
try sendBytesPayload(data: frame.serializedData(), id: Int64.random(in: Int64.min ... Int64.max))
}
@@ -374,11 +374,11 @@ class NearbyConnection {
guard payloadTransfer.hasPayloadChunk, chunk.hasOffset, chunk.hasFlags else {
if payloadTransfer.controlMessage.event == .payloadCanceled {
log("[NearbyConnection] Cancel control frame received.")
log("[NearbyConnection \(self.id)] Cancel control frame received.")
throw NearbyError.canceled(reason: .userCanceled)
}
log("[NearbyConnection] Payload transfer chunk is missing offset or flags. Frame is \(payloadTransfer.debugDescription)")
log("[NearbyConnection \(self.id)] Payload transfer chunk is missing offset or flags. Frame is \(payloadTransfer.debugDescription)")
throw NearbyError.requiredFieldMissing("payloadChunk.offset|flags")
}
@@ -423,11 +423,11 @@ class NearbyConnection {
}
else if offlineFrame.hasV1, offlineFrame.v1.hasType, case .keepAlive = offlineFrame.v1.type {
log("[NearbyConnection] Sent keep-alive, \(self.bytesTransferred) bytes sent")
log("[NearbyConnection \(self.id)] Sent keep-alive, \(self.bytesTransferred) bytes sent")
sendKeepAlive(ack: true)
} else {
log("[NearbyConnection] Unhandled offline frame encrypted: \(offlineFrame)")
log("[NearbyConnection \(self.id)] Unhandled offline frame encrypted: \(offlineFrame)")
}
}
@@ -531,7 +531,7 @@ class NearbyConnection {
func disconnect() {
log("[NearbyConnection] Disconnecting from connection.")
log("[NearbyConnection \(self.id)] Disconnecting from connection.")
connection.stateUpdateHandler = nil
inactivityTimer?.cancel()
@@ -553,7 +553,7 @@ class NearbyConnection {
try sendFrameAsync(offlineFrame.serializedData())
}
log("[NearbyConnection] Sent disconnection frame during sendDisconnectionAndDisconnect")
log("[NearbyConnection \(self.id)] Sent disconnection frame during sendDisconnectionAndDisconnect")
disconnect()
}
@@ -566,7 +566,7 @@ class NearbyConnection {
msg.messageData = try! alert.serializedData()
sendFrameAsync(try! msg.serializedData())
log("[NearbyConnection] Sent UKEY2 alert: \(type)")
log("[NearbyConnection \(self.id)] Sent UKEY2 alert: \(type)")
disconnect()
}
@@ -584,7 +584,7 @@ class NearbyConnection {
try sendFrameAsync(offlineFrame.serializedData())
}
} catch {
log("[NearbyConnection] Error sending KEEP_ALIVE: \(error)")
log("[NearbyConnection \(self.id)] Error sending KEEP_ALIVE: \(error)")
}
}
@@ -601,7 +601,7 @@ class NearbyConnection {
guard let self = self else { return }
if !self.connectionClosed {
log("[NearbyConnection] Connection timeout: No message received in \(self.timeoutInterval) seconds")
log("[NearbyConnection \(self.id)] Connection timeout: No message received in \(self.timeoutInterval) seconds")
self.lastError = NearbyError.canceled(reason: .timedOut)
self.disconnect()
}
@@ -621,7 +621,7 @@ class NearbyConnection {
else {
// connection stale, need to abort
if !self.connectionClosed {
log("[NearbyConnection] Connection timeout: No more data received in \(self.timeoutInterval) seconds")
log("[NearbyConnection \(self.id)] Connection timeout: No more data received in \(self.timeoutInterval) seconds")
self.lastError = NearbyError.canceled(reason: .timedOut)
self.disconnect()
}
@@ -135,7 +135,7 @@ public class NearbyConnectionManager: NSObject, NetServiceDelegate, InboundNearb
public func submitUserConsent(transferID: String, accept: Bool, storeInTemp: Bool = false) {
guard let conn = incomingConnections[transferID] else { return }
log("[NearbyConnectionManager] Submitting user consent for transfer, accepted: \(accept), store in temp: \(storeInTemp)")
log("[NearbyConnectionManager] Submitting user consent for transfer \(transferID), accepted: \(accept), store in temp: \(storeInTemp)")
conn.submitUserConsent(accepted: accept, storeInTemp: storeInTemp)
}
@@ -101,7 +101,7 @@ class OutboundNearbyConnection: NearbyConnection {
override func processReceivedFrame(frameData: Data) {
if currentState != .sendingFiles {
log("[OutboundNearbyConnection] Received frame in state \(currentState)...")
log("[OutboundNearbyConnection \(self.id)] Received frame in state \(currentState)...")
}
do {
@@ -118,7 +118,7 @@ class OutboundNearbyConnection: NearbyConnection {
}
} catch {
log("[OutboundNearbyConnection] Error occured while processing frame with data \(frameData.hex): \(error)")
log("[OutboundNearbyConnection \(self.id)] Error occured while processing frame with data \(frameData.hex): \(error)")
if case NearbyError.ukey2 = error {
// do nothing
@@ -137,7 +137,7 @@ class OutboundNearbyConnection: NearbyConnection {
if frame.hasV1 && frame.v1.hasType, case .cancel = frame.v1.type {
self.cancelled = true
self.lastError = NearbyError.canceled(reason: .userCanceled)
log("[OutboundNearbyConnection] Transfer canceled")
log("[OutboundNearbyConnection \(self.id)] Transfer canceled")
try sendDisconnectionAndDisconnect()
delegate?.outboundConnection(connection: self, failedWithError: self.lastError!)
return
@@ -153,7 +153,7 @@ class OutboundNearbyConnection: NearbyConnection {
case .sendingFiles:
break
default:
assertionFailure("[OutboundNearbyConnection] Unexpected state \(currentState)")
assertionFailure("[OutboundNearbyConnection \(self.id)] Unexpected state \(currentState)")
}
}
@@ -224,23 +224,23 @@ class OutboundNearbyConnection: NearbyConnection {
ukeyServerInitMsgData = raw
guard frame.messageType == .serverInit else {
sendUkey2Alert(type: .badMessageType)
log("[OutboundNearbyConnection] Invalid message type: \(frame.messageType)")
log("[OutboundNearbyConnection \(self.id)] Invalid message type: \(frame.messageType)")
throw NearbyError.ukey2
}
let serverInit = try Securegcm_Ukey2ServerInit(serializedBytes: frame.messageData)
guard serverInit.version == 1 else {
sendUkey2Alert(type: .badVersion)
log("[OutboundNearbyConnection] Invalid version: \(serverInit.version)")
log("[OutboundNearbyConnection \(self.id)] Invalid version: \(serverInit.version)")
throw NearbyError.ukey2
}
guard serverInit.random.count == 32 else {
sendUkey2Alert(type: .badRandom)
log("[OutboundNearbyConnection] Invalid random: \(serverInit.random.count)")
log("[OutboundNearbyConnection \(self.id)] Invalid random: \(serverInit.random.count)")
throw NearbyError.ukey2
}
guard serverInit.handshakeCipher == .p256Sha512 else {
sendUkey2Alert(type: .badHandshakeCipher)
log("[OutboundNearbyConnection] Invalid handshake cipher: \(serverInit.handshakeCipher)")
log("[OutboundNearbyConnection \(self.id)] Invalid handshake cipher: \(serverInit.handshakeCipher)")
throw NearbyError.ukey2
}
@@ -349,7 +349,7 @@ class OutboundNearbyConnection: NearbyConnection {
introduction.v1.introduction.fileMetadata.append(meta)
totalBytesToSend += meta.size
log("[OutboundNearbyConnection] Sending file with \(meta.size) bytes")
log("[OutboundNearbyConnection \(self.id)] Sending file with \(meta.size) bytes")
}
}
try sendTransferSetupFrame(introduction)
@@ -416,7 +416,7 @@ class OutboundNearbyConnection: NearbyConnection {
try currentTransfer?.handle?.close()
}
if queue.isEmpty {
log("[OutboundNearbyConnection] Disconnecting because all files have been transferred")
log("[OutboundNearbyConnection \(self.id)] Disconnecting because all files have been transferred")
try sendDisconnectionAndDisconnect()
delegate?.outboundConnectionTransferFinished(connection: self)
return
@@ -479,7 +479,7 @@ class OutboundNearbyConnection: NearbyConnection {
wrapper.v1.type = .payloadTransfer
wrapper.v1.payloadTransfer = transfer
try encryptAndSendOfflineFrame(wrapper)
log("[OutboundNearbyConnection] Sent EOF, current transfer: \(String(describing: currentTransfer))")
log("[OutboundNearbyConnection \(self.id)] Sent EOF, current transfer: \(String(describing: currentTransfer))")
}
}