chore: add initial logging (#42)

This PR adds the logs used to find the cause of the deadlock fixed in
ca9a029b63.

Related to https://github.com/status-im/nim-quic/pull/41

.tool-versions

@@ -1 +1 @@
-nim 1.4.8
+nim 1.6.20

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"

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)

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.}

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.}

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.}

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"

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()