From 5361558b167e3215b4080c10bef2115988a64489 Mon Sep 17 00:00:00 2001 From: MacOMNI <414294494@qq.com> Date: Tue, 14 Jan 2025 17:23:10 +0800 Subject: [PATCH] add some logger --- .../Sources/MsQuicSwift/QuicStream.swift | 3 +- .../Sources/Networking/Connection.swift | 20 ++++-- Networking/Sources/Networking/Peer.swift | 4 +- .../BlockAnnouncementDecoderTests.swift | 66 +++++++++++++++++++ Node/Tests/NodeTests/NodeTests.swift | 2 +- Node/Tests/NodeTests/Topology.swift | 4 ++ 6 files changed, 88 insertions(+), 11 deletions(-) create mode 100644 Node/Tests/NodeTests/BlockAnnouncementDecoderTests.swift diff --git a/Networking/Sources/MsQuicSwift/QuicStream.swift b/Networking/Sources/MsQuicSwift/QuicStream.swift index 8f094f88..50a62012 100644 --- a/Networking/Sources/MsQuicSwift/QuicStream.swift +++ b/Networking/Sources/MsQuicSwift/QuicStream.swift @@ -94,8 +94,7 @@ public final class QuicStream: Sendable { } public func send(data: Data, start: Bool = false, finish: Bool = false) throws { - logger.debug("Sending \(data.count) bytes") - + logger.debug("Stream \(id) sending \(data.count) bytes data \(data.toHexString())") try storage.read { storage in guard let storage, let api = storage.connection.api else { throw QuicError.alreadyClosed diff --git a/Networking/Sources/Networking/Connection.swift b/Networking/Sources/Networking/Connection.swift index 6b4adc47..5934c6b2 100644 --- a/Networking/Sources/Networking/Connection.swift +++ b/Networking/Sources/Networking/Connection.swift @@ -234,7 +234,7 @@ public final class Connection: Sendable, ConnectionInfoP impl.addStream(stream) Task { guard let byte = await stream.receiveByte() else { - logger.debug("stream closed without receiving kind. status: \(stream.status)") + logger.info("stream closed without receiving kind. status: \(stream.status)") return } if let upKind = Handler.PresistentHandler.StreamKind(rawValue: byte) { @@ -246,14 +246,14 @@ public final class Connection: Sendable, ConnectionInfoP if existingStream.stream.id < stream.stream.id { // The new stream has a higher ID, so reset the existing one existingStream.close(abort: false) - logger.debug( + logger.info( "Reset older UP stream with lower ID", metadata: ["existingStreamId": "\(existingStream.stream.id)", "newStreamId": "\(stream.stream.id)"] ) } else { // The existing stream has a higher ID or is equal, so reset the new one stream.close(abort: false) - logger.debug( + logger.info( "Duplicate UP stream detected, closing new stream with lower or equal ID", metadata: ["existingStreamId": "\(existingStream.stream.id)", "newStreamId": "\(stream.stream.id)"] ) @@ -278,9 +278,13 @@ public final class Connection: Sendable, ConnectionInfoP let data = try await receiveData(stream: stream) let request = try decoder.decode(data: data) let resp = try await impl.ephemeralStreamHandler.handle(connection: self, request: request) +// logger +// .info( +// "sending addr \(remoteAddress.description) request data \(resp.toHexString()) with \(resp.count) bytes " +// ) try stream.send(message: resp, finish: true) } catch { - logger.info("Failed to handle request", metadata: ["error": "\(error)"]) + logger.error("Failed to handle request", metadata: ["error": "\(error)"]) stream.close(abort: true) } } @@ -348,13 +352,15 @@ func presistentStreamRunLoop( var decoder = handler.createDecoder(kind: kind) do { while let data = try await receiveMaybeData(stream: stream) { - logger.debug("receiveMaybeData length: \(data.count) from \(connection.id)") + logger + .debug( + "receiveMaybeData \(data.count) length from \(connection.id) stream \(stream.id) data \(String(describing: data.toHexString()))" + ) let msg = try decoder.decode(data: data) - logger.debug("handling message: \(msg) from \(connection.id)") try await handler.handle(connection: connection, message: msg) } } catch { - logger.error("UP stream run loop failed: \(error) from \(connection.id)") + logger.error("UP stream run loop failed: \(error) from \(connection.remoteAddress) \(connection.id) \(stream.id)") stream.close(abort: true) } diff --git a/Networking/Sources/Networking/Peer.swift b/Networking/Sources/Networking/Peer.swift index 5ca00014..0e880276 100644 --- a/Networking/Sources/Networking/Peer.swift +++ b/Networking/Sources/Networking/Peer.swift @@ -196,6 +196,7 @@ public final class Peer: Sendable { metadata: [ "connectionId": "\(connection.id)", "kind": "\(kind)", + "message": "\(messageData)", "error": "\(error)", ] ) @@ -298,7 +299,7 @@ final class PeerImpl: Sendable { var state = reconnectStates.read { reconnectStates in reconnectStates[address] ?? .init() } - + logger.info("reconnecting to \(address) \(state.attempt) attempts") guard state.attempt < maxRetryAttempts else { logger.warning("reconnecting to \(address) exceeded max attempts") return @@ -338,6 +339,7 @@ final class PeerImpl: Sendable { states[connection.id] ?? .init() } + logger.info("Reopen attempt for stream \(kind) on connection \(connection.id) \(state.attempt) attempts") guard state.attempt < maxRetryAttempts else { logger.warning("Reopen attempt for stream \(kind) on connection \(connection.id) exceeded max attempts") return diff --git a/Node/Tests/NodeTests/BlockAnnouncementDecoderTests.swift b/Node/Tests/NodeTests/BlockAnnouncementDecoderTests.swift new file mode 100644 index 00000000..e63419c9 --- /dev/null +++ b/Node/Tests/NodeTests/BlockAnnouncementDecoderTests.swift @@ -0,0 +1,66 @@ +import Blockchain +import Codec +import Foundation +import Testing +import Utils + +@testable import Node + +final class BlockAnnouncementDecoderTests { + @Test + func decodeInvalidEpoch() throws { + let hexString = """ + ed0100007d810035df13056b2e28c4c331a7a53094e97a2b8bceff223ecd34b6cffd2d9ab69998d70\ + 574f759fc057a99604de71d302cb16d365985a180bd8f3387d2d736189d15af832dfe4f67744008b6\ + 2c334b569fcbb4c261e0f065655697306ca252ff000000010000000000000000000000000000000000\ + 0000000000000000000000000000000000000000000000000000000000000000000000000000000000\ + 5e465beb01dbafe160ce8216047f2155dd0569f058afd52dcea601025a8d161d2c5da3a09d66a5d43\ + e7d523e6108736db99d2c2f08fbdcb72a4e8e5aced3482a8552b36000b454fdf6b5418e22ef5d6609\ + e8fc6b816822f02727e085c514d560000000004fbacc2baea15e2e69185623e37a51ee9372ebd80dd\ + 405a34d24a0a40f79e1d92d49a247d13acca8ccaf7cb6d3eb9ef10b3ef29a93e01e9ddce0a4266c4a\ + 2c0e96a3b8c26c8ac6c9063ed7dcdb18479736c7c7be7fbfd006b4cb4b44ffa948154fbacc2baea15\ + e2e69185623e37a51ee9372ebd80dd405a34d24a0a40f79e1d993ccc91f31f5d8657ef98d203ddcc7\ + 38482fe2caaa41f51d983239ac0dbbba04ca820ff3eb8d2ab3b9e1421f7955d876776b0c293f2e31e\ + aa2da18c3b580f5067d810035df13056b2e28c4c331a7a53094e97a2b8bceff223ecd34b6cffd2d9a + """ + let hex = hexString.replacingOccurrences(of: "\\s+", with: "", options: .regularExpression) + let data = Data(fromHexString: hex)! + let config = ProtocolConfigRef.minimal + #expect(throws: DecodingError.self) { + _ = try JamDecoder.decode(BlockAnnouncement.self, from: data, withConfig: config) + } + } + + @Test + func decodeNotEnoughDataToDecode() throws { + let hexString = """ + 371134fcf189799fea21d2b9a50bd8352c7814a120617700e1f984af1cb3698fb1aed1999185b3800\ + 51235aa97f33306a9682e486b12c6016e6df19ea71f1ff6189d15af832dfe4f67744008b62c334b56\ + 9fcbb4c261e0f065655697306ca252ab00000001000000000000000000000000000000000000000000\ + 0000000000000000000000000000000000000000000000000000000000000000000000000000000000\ + 5e465beb01dbafe160ce8216047f2155dd0569f058afd52dcea601025a8d161d2c5da3a09d66a5d43\ + e7d523e6108736db99d2c2f08fbdcb72a4e8e5aced3482a8552b36000b454fdf6b5418e22ef5d6609\ + e8fc6b816822f02727e085c514d5605d069d7591ea55d9cc7adb9e8eaff66a1688d075c69fa94815e\ + f0fe9a56025699a565d486952598747cb9b3b78bb97694100a1cbf8d7af4eb2ea740b844b41d19a99\ + 09db141ee10d89f9bff13d651831cc91098bdf30c917ce89d1b8416af719000000004fbacc2baea15\ + e2e69185623e37a51ee9372ebd80dd405a34d24a0a40f79e1d92d49a247d13acca8ccaf7cb6d3eb9e\ + f10b3ef29a93e01e9ddce0a4266c4a2c0e96a3b8c26c8ac6c9063ed7dcdb18479736c7c7be7fbfd00\ + 6b4cb4b44ffa948154fbacc2baea15e2e69185623e37a51ee9372ebd80dd405a34d24a0a40f79e1d9\ + 575f1115fe3f8a903ac06a3578eeb154ef3f75d2d18fcabfafa4f14530a27f050258515937b7f7bfe\ + f6bf7aa67adf39b59057bbbe0433c9e8a057917c836f814371134fcf189799fea21d2b9a50bd8352c\ + 7814a120617700e1f984af1cb3698f00000000 + """ + let hex = hexString.replacingOccurrences(of: "\\s+", with: "", options: .regularExpression) + let data = Data(fromHexString: hex)! + let config = ProtocolConfigRef.minimal + #expect(throws: DecodingError.self) { + _ = try JamDecoder.decode(BlockAnnouncement.self, from: data, withConfig: config) + } + } + + @Test + func decodeNotAllDataWasConsumed() throws {} + + @Test + func decodeNilValue() throws {} +} diff --git a/Node/Tests/NodeTests/NodeTests.swift b/Node/Tests/NodeTests/NodeTests.swift index b4585bfa..d03a98b3 100644 --- a/Node/Tests/NodeTests/NodeTests.swift +++ b/Node/Tests/NodeTests/NodeTests.swift @@ -228,7 +228,7 @@ final class NodeTests { for (_, middleware) in nonValidatorNodes { await middleware.wait() } - try await Task.sleep(for: .milliseconds(500)) + try await Task.sleep(for: .milliseconds(100)) } try await Task.sleep(for: .milliseconds(nodes.count * 100)) let validator1BestHead = await validator1.dataProvider.bestHead diff --git a/Node/Tests/NodeTests/Topology.swift b/Node/Tests/NodeTests/Topology.swift index 7b42fb14..025e6f89 100644 --- a/Node/Tests/NodeTests/Topology.swift +++ b/Node/Tests/NodeTests/Topology.swift @@ -64,6 +64,10 @@ struct Topology { let fromNode = ret[from].0 let toNode = ret[to].0 let conn = try fromNode.network.network.connect(to: toNode.network.network.listenAddress(), role: .validator) + try print( + "connect from \(fromNode.network.network.listenAddress().description) to \(toNode.network.network.listenAddress().description)" + ) + print("connect \(conn.id) address: \(conn.remoteAddress)") try? await conn.ready() } return (ret, scheduler)