Trace shared-socket QUIC routing

Author: richard-ramos

lsquic/context/context.nim

@@ -1,7 +1,7 @@
 # SPDX-License-Identifier: Apache-2.0 OR MIT
 # Copyright (c) Status Research & Development GmbH 
 
-import std/[deques, hashes, sets]
+import std/[deques, hashes, sets, strutils]
 import boringssl
 import chronos
 import chronos/osdefs
@@ -49,6 +49,14 @@ func hash*(cid: CidKey): Hash =
     h = h !& hash(cid.bytes[i])
   !$h
 
+func shortLog*(cid: CidKey): string =
+  result = $cid.len & ":"
+  for i in 0 ..< min(cid.len.int, 8):
+    result.add(toHex(cid.bytes[i], 2))
+
+chronicles.formatIt(CidKey):
+  shortLog(it)
+
 func toCidKey(cid: RawLsquicCid, key: var CidKey): bool =
   if cid.len == 0 or cid.len.int > MAX_CID_LEN:
     return false
@@ -73,6 +81,8 @@ proc addCids*(
     var key: CidKey
     if toCidKey(cidsArr[i], key):
       quicCtx.ownedCids.incl(key)
+      trace "Registered CID", cid = key,
+        cidCount = quicCtx.ownedCids.len
 
 proc removeCids*(
     ctx: pointer, peerCtxs: ptr pointer, cids: ptr lsquic_cid_t, nCids: cuint
@@ -86,6 +96,8 @@ proc removeCids*(
     var key: CidKey
     if toCidKey(cidsArr[i], key):
       quicCtx.ownedCids.excl(key)
+      trace "Removed CID", cid = key,
+        cidCount = quicCtx.ownedCids.len
 
 proc trackConnectionCid*(
     ctx: QuicContext, conn: ptr lsquic_conn_t
@@ -100,6 +112,8 @@ proc trackConnectionCid*(
   var key: CidKey
   if toCidKey(cast[ptr RawLsquicCid](cid)[], key):
     ctx.ownedCids.incl(key)
+    trace "Tracked connection CID", cid = key,
+      cidCount = ctx.ownedCids.len
 
 proc ownsCid*(ctx: QuicContext, cid: CidKey): bool {.raises: [].} =
   not ctx.isNil and cid in ctx.ownedCids

lsquic/context/io.nim

@@ -3,6 +3,7 @@
 
 import chronos
 import chronos/osdefs
+import chronicles
 import ./context
 import ../[lsquic_ffi, datagram]
 import ../helpers/[openarray, sequninit, transportaddr]
@@ -71,7 +72,8 @@ proc receive*(
   local.toSAddr(localAddress, localAddrLen)
   remote.toSAddr(remoteAddress, remoteAddrLen)
 
-  discard lsquic_engine_packet_in(
+  trace "Packet in", bytes = datagram.data.len, local, remote
+  let rc = lsquic_engine_packet_in(
     ctx.engine,
     datagram.data.toPtr,
     datagram.data.len.csize_t,
@@ -80,6 +82,7 @@ proc receive*(
     cast[pointer](ctx),
     datagram.ecn,
   )
+  trace "Packet in returned", rc
 
   ctx.processWhenReady()
 
@@ -88,6 +91,7 @@ proc sendPacketsOut*(
 ): cint {.cdecl.} =
   let quicCtx = cast[QuicContext](ctx)
   var sent = 0
+  trace "Sending packets out", nspecs
   let specsArr = cast[ptr UncheckedArray[struct_lsquic_out_spec]](specs)
   for i in 0 ..< nspecs.int:
     let curr = specsArr[i]
@@ -118,6 +122,7 @@ proc sendPacketsOut*(
         nil, # no overlapped
       )
       if res != 0:
+        trace "WSASendTo failed", sent, nspecs
         break
     else:
       let msg =
@@ -144,8 +149,10 @@ proc sendPacketsOut*(
 
       let res = sendmsg(SocketHandle(quicCtx.fd), msg.addr, 0)
       if res < 0:
+        trace "sendmsg failed", sent, nspecs
         break
 
     sent.inc
 
+  trace "Sent packets out", sent, nspecs
   sent.cint

lsquic/endpoint.nim

@@ -79,16 +79,27 @@ proc receiveDatagram(
 
   var cid: CidKey
   if endpoint.packetDcid(data, cid):
-    if not endpoint.clientContext.isNil and endpoint.clientContext.ownsCid(cid):
+    let clientOwns =
+      not endpoint.clientContext.isNil and endpoint.clientContext.ownsCid(cid)
+    let serverOwns =
+      not endpoint.serverContext.isNil and endpoint.serverContext.ownsCid(cid)
+    trace "Routing datagram by CID", bytes = data.len, cid,
+      clientOwns, serverOwns, local, remote
+    if clientOwns:
+      trace "Routing datagram to client context", cid
       endpoint.clientContext.receive(Datagram(data: data), local, remote)
       return
 
-    if not endpoint.serverContext.isNil and endpoint.serverContext.ownsCid(cid):
+    if serverOwns:
+      trace "Routing datagram to server context", cid
       endpoint.serverContext.receive(Datagram(data: data), local, remote)
       return
 
   # Unknown CIDs can be new handshakes; each engine gets a chance to claim them.
   # Endpoints can have both contexts; each engine needs to see the packet.
+  trace "Routing datagram with unknown CID", bytes = data.len,
+    hasClientContext = not endpoint.clientContext.isNil,
+    hasServerContext = not endpoint.serverContext.isNil, local, remote
   if not endpoint.clientContext.isNil:
     endpoint.clientContext.receive(Datagram(data: data), local, remote)
   if not endpoint.serverContext.isNil: