From f0c6b0549858df2a9c4ae9c9afd9602c66adc425 Mon Sep 17 00:00:00 2001 From: diegomrsantos Date: Wed, 14 Aug 2024 16:07:26 +0200 Subject: [PATCH] chore: add initial logging (#42) This PR adds the logs used to find the cause of the deadlock fixed in https://github.com/status-im/nim-quic/commit/ca9a029b63a2c00e3b936928846af9233abd13d6. Related to https://github.com/status-im/nim-quic/pull/41 --- .tool-versions | 2 +- quic.nimble | 1 + quic/connection.nim | 28 +++++++++++++++++++ .../ngtcp2/connection/closedstate.nim | 7 +++++ .../ngtcp2/connection/disconnectingstate.nim | 15 ++++++++++ .../transport/ngtcp2/connection/openstate.nim | 11 ++++++++ quic/transport/quicconnection.nim | 12 ++++++-- tests/helpers/udp.nim | 6 ++++ 8 files changed, 79 insertions(+), 3 deletions(-) diff --git a/.tool-versions b/.tool-versions index fffdde3..96f95dc 100644 --- a/.tool-versions +++ b/.tool-versions @@ -1 +1 @@ -nim 1.4.8 +nim 1.6.20 diff --git a/quic.nimble b/quic.nimble index 6c1e48d..b7974e9 100644 --- a/quic.nimble +++ b/quic.nimble @@ -11,3 +11,4 @@ requires "nimcrypto >= 0.6.0 & < 0.7.0" requires "ngtcp2 >= 0.32.0 & < 0.34.0" requires "upraises >= 0.1.0 & < 0.2.0" requires "unittest2 >= 0.2.2 & < 0.3.0" +requires "chronicles >= 0.10.2" diff --git a/quic/connection.nim b/quic/connection.nim index 1338e3d..6cc452e 100644 --- a/quic/connection.nim +++ b/quic/connection.nim @@ -1,3 +1,5 @@ +import chronicles + import ./basics import ./transport/connectionid import ./transport/stream @@ -7,6 +9,9 @@ import ./helpers/asyncloop export Stream, close, read, write +logScope: + topics = "quic connection" + type Connection* = ref object of RootObj udp: DatagramTransport @@ -31,7 +36,9 @@ proc `onClose=`*(connection: Connection, callback: proc() {.gcsafe, upraises: [] connection.onClose = Opt.some(callback) proc drop*(connection: Connection) {.async.} = + trace "Dropping connection" await connection.quic.drop() + trace "Dropped connection" proc close*(connection: Connection) {.async.} = await connection.quic.close() @@ -40,17 +47,25 @@ proc waitClosed*(connection: Connection) {.async.} = await connection.closed.wait() proc startSending(connection: Connection, remote: TransportAddress) = + trace "Starting sending loop" proc send {.async.} = try: + trace "Getting datagram" let datagram = await connection.quic.outgoing.get() + trace "Sending datagraom", remote await connection.udp.sendTo(remote, datagram.data) + trace "Sent datagraom" except TransportError as e: + trace "Failed to send datagram", errorMsg = e.msg + trace "Failing connection loop future with error" connection.loop.fail(e) # This might need to be revisited, see https://github.com/status-im/nim-quic/pull/41 for more details await connection.drop() connection.loop = asyncLoop(send) proc stopSending(connection: Connection) {.async.} = + trace "Stopping sending loop" await connection.loop.cancelAndWait() + trace "Stopped sending loop" method closeUdp(connection: Connection) {.async, base, upraises: [].} = discard @@ -59,11 +74,20 @@ method closeUdp(connection: OutgoingConnection) {.async.} = await connection.udp.closeWait() proc disconnect(connection: Connection) {.async.} = + trace "Disconnecting connection" + trace "Stop sending in the connection" await connection.stopSending() + trace "Stopped sending in the connection" + trace "Closing udp" await connection.closeUdp() + trace "Closed udp" if connection.onClose.isSome(): + trace "Calling onClose" (connection.onClose.unsafeGet())() + trace "Called onClose" + trace "Firing closed event" connection.closed.fire() + trace "Fired closed event" proc newIncomingConnection*(udp: DatagramTransport, remote: TransportAddress): Connection = @@ -72,7 +96,9 @@ proc newIncomingConnection*(udp: DatagramTransport, let closed = newAsyncEvent() let connection = IncomingConnection(udp: udp, quic: quic, closed: closed) proc onDisconnect {.async.} = + trace "Calling onDisconnect for newIncomingConnection" await connection.disconnect() + trace "Called onDisconnect for newIncomingConnection" connection.remote = remote quic.disconnect = Opt.some(onDisconnect) connection.startSending(remote) @@ -84,7 +110,9 @@ proc newOutgoingConnection*(udp: DatagramTransport, let closed = newAsyncEvent() let connection = OutgoingConnection(udp: udp, quic: quic, closed: closed) proc onDisconnect {.async.} = + trace "Calling onDisconnect for newOutgoingConnection" await connection.disconnect() + trace "Called onDisconnect for newOutgoingConnection" connection.remote = remote quic.disconnect = Opt.some(onDisconnect) connection.startSending(remote) diff --git a/quic/transport/ngtcp2/connection/closedstate.nim b/quic/transport/ngtcp2/connection/closedstate.nim index be2aa00..349d9b5 100644 --- a/quic/transport/ngtcp2/connection/closedstate.nim +++ b/quic/transport/ngtcp2/connection/closedstate.nim @@ -1,8 +1,13 @@ +import chronicles + import ../../../basics import ../../quicconnection import ../../connectionid import ../../stream +logScope: + topics = "quic closedstate" + type ClosedConnection* = ref object of ConnectionState ClosedConnectionError* = object of ConnectionError @@ -29,6 +34,8 @@ method close(state: ClosedConnection) {.async.} = discard method drop(state: ClosedConnection) {.async.} = + trace "Dropping ClosedConnection state" discard + trace "Dropped ClosedConnection state" {.pop.} diff --git a/quic/transport/ngtcp2/connection/disconnectingstate.nim b/quic/transport/ngtcp2/connection/disconnectingstate.nim index 87935c5..72217e4 100644 --- a/quic/transport/ngtcp2/connection/disconnectingstate.nim +++ b/quic/transport/ngtcp2/connection/disconnectingstate.nim @@ -1,9 +1,14 @@ +import chronicles + import ../../../basics import ../../quicconnection import ../../connectionid import ../../stream import ./closedstate +logScope: + topics = "quic disconnectingstate" + type DisconnectingConnection* = ref object of ConnectionState connection: Opt[QuicConnection] @@ -16,7 +21,9 @@ proc newDisconnectingConnection*(ids: seq[ConnectionId]): proc callDisconnect(connection: QuicConnection) {.async.} = let disconnect = connection.disconnect.valueOr: return + trace "Calling disconnect proc on QuicConnection" await disconnect() + trace "Called disconnect proc on QuicConnection" {.push locks: "unknown".} @@ -24,13 +31,17 @@ method ids*(state: DisconnectingConnection): seq[ConnectionId] = state.ids method enter(state: DisconnectingConnection, connection: QuicConnection) = + trace "Entering DisconnectingConnection state" procCall enter(ConnectionState(state), connection) state.connection = Opt.some(connection) state.disconnect = callDisconnect(connection) + trace "Entered DisconnectingConnection state" method leave(state: DisconnectingConnection) = + trace "Leaving DisconnectingConnection state" procCall leave(ConnectionState(state)) state.connection = Opt.none(QuicConnection) + trace "Left DisconnectingConnection state" method send(state: DisconnectingConnection) = raise newException(ClosedConnectionError, "connection is disconnecting") @@ -48,8 +59,12 @@ method close(state: DisconnectingConnection) {.async.} = connection.switch(newClosedConnection()) method drop(state: DisconnectingConnection) {.async.} = + trace "Dropping DisconnectingConnection state" + trace "Awaiting quic disconnecton" await state.disconnect + trace "Quic disconnecton finished" let connection = state.connection.valueOr: return connection.switch(newClosedConnection()) + trace "dropped DisconnectingConnection state" {.pop.} diff --git a/quic/transport/ngtcp2/connection/openstate.nim b/quic/transport/ngtcp2/connection/openstate.nim index 7cd9906..2aa9aaf 100644 --- a/quic/transport/ngtcp2/connection/openstate.nim +++ b/quic/transport/ngtcp2/connection/openstate.nim @@ -1,3 +1,5 @@ +import chronicles + import ../../../basics import ../../quicconnection import ../../connectionid @@ -11,6 +13,9 @@ import ./drainingstate import ./disconnectingstate import ./openstreams +logScope: + topics = "quic disconnectingstate" + type OpenConnection* = ref object of ConnectionState quicConnection: Opt[QuicConnection] @@ -30,6 +35,7 @@ proc openServerConnection*(local, remote: TransportAddress, {.push locks: "unknown".} method enter(state: OpenConnection, connection: QuicConnection) = + trace "Entering OpenConnection state" procCall enter(ConnectionState(state), connection) state.quicConnection = Opt.some(connection) # Workaround weird bug @@ -50,12 +56,15 @@ method enter(state: OpenConnection, connection: QuicConnection) = connection.incoming.putNoWait(stream) state.ngtcp2Connection.onHandshakeDone = proc = connection.handshake.fire() + trace "Entered OpenConnection state" method leave(state: OpenConnection) = + trace "Leaving OpenConnection state" procCall leave(ConnectionState(state)) state.streams.closeAll() state.ngtcp2Connection.destroy() state.quicConnection = Opt.none(QuicConnection) + trace "Left OpenConnection state" method ids(state: OpenConnection): seq[ConnectionId] {.upraises: [].} = state.ngtcp2Connection.ids @@ -91,9 +100,11 @@ method close(state: OpenConnection) {.async.} = await closing.close() method drop(state: OpenConnection) {.async.} = + trace "Dropping OpenConnection state" let quicConnection = state.quicConnection.valueOr: return let disconnecting = newDisconnectingConnection(state.ids) quicConnection.switch(disconnecting) await disconnecting.drop() + trace "Dropped OpenConnection state" {.pop.} diff --git a/quic/transport/quicconnection.nim b/quic/transport/quicconnection.nim index 397b3ab..af89d42 100644 --- a/quic/transport/quicconnection.nim +++ b/quic/transport/quicconnection.nim @@ -1,7 +1,11 @@ +import pkg/chronicles import ../basics import ./connectionid import ./stream +logScope: + topics = "quic quicconnection" + type QuicConnection* = ref object state: ConnectionState @@ -57,9 +61,11 @@ proc newQuicConnection*(state: ConnectionState): QuicConnection = connection proc switch*(connection: QuicConnection, newState: ConnectionState) = + trace "Switching quic connection state" connection.state.leave() connection.state = newState connection.state.enter(connection) + trace "Switched quic connection state" proc ids*(connection: QuicConnection): seq[ConnectionId] = connection.state.ids() @@ -80,5 +86,7 @@ proc incomingStream*(connection: QuicConnection): Future[Stream] = proc close*(connection: QuicConnection): Future[void] = connection.state.close() -proc drop*(connection: QuicConnection): Future[void] = - connection.state.drop() +proc drop*(connection: QuicConnection): Future[void] {.async.} = + trace "Dropping quic connection" + await connection.state.drop() + trace "Drop quic connection done" diff --git a/tests/helpers/udp.nim b/tests/helpers/udp.nim index 32cf4ab..80de4d6 100644 --- a/tests/helpers/udp.nim +++ b/tests/helpers/udp.nim @@ -1,8 +1,12 @@ import pkg/chronos +import pkg/chronicles import pkg/quic/transport/packets import pkg/quic/transport/version import pkg/quic/helpers/openarray +logScope: + topics = "quic udp" + proc exampleQuicDatagram*: seq[byte] = var packet = initialPacket(CurrentQuicVersion) packet.destination = randomConnectionId() @@ -16,6 +20,8 @@ proc newDatagramTransport*: DatagramTransport = newDatagramTransport(onReceive) proc sendTo*(datagram: seq[byte], remote: TransportAddress) {.async.} = + trace "Sending datagram", remote let udp = newDatagramTransport() await udp.sendTo(remote, datagram.toUnsafePtr, datagram.len) + trace "Sent datagram", remote await udp.closeWait()