Adjust uTP log levels to be more user focused (#502)

Also cleanup several whitespace and line char limits
This commit is contained in:
Kim De Mey 2022-04-12 21:11:01 +02:00 committed by GitHub
parent 6d4b1f4fe1
commit 01684a2130
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 97 additions and 92 deletions

View File

@ -1,4 +1,4 @@
# Copyright (c) 2021 Status Research & Development GmbH # Copyright (c) 2021-2022 Status Research & Development GmbH
# Licensed and distributed under either of # Licensed and distributed under either of
# * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT). # * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT).
# * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0). # * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0).
@ -13,7 +13,7 @@ import
./utp_router, ./utp_router,
../keys ../keys
export utp_router, protocol, chronicles export utp_router, protocol
logScope: logScope:
topics = "utp_discv5_protocol" topics = "utp_discv5_protocol"

View File

@ -1,4 +1,4 @@
# Copyright (c) 2021 Status Research & Development GmbH # Copyright (c) 2021-2022 Status Research & Development GmbH
# Licensed and distributed under either of # Licensed and distributed under either of
# * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT). # * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT).
# * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0). # * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0).
@ -13,6 +13,11 @@ import
./utp_socket, ./utp_socket,
./packets ./packets
export utp_socket
logScope:
topics = "utp_router"
declareCounter utp_received_packets, declareCounter utp_received_packets,
"All correct received uTP packets" "All correct received uTP packets"
declareCounter utp_failed_packets, declareCounter utp_failed_packets,
@ -28,11 +33,6 @@ declareCounter utp_success_outgoing,
declareCounter utp_failed_outgoing, declareCounter utp_failed_outgoing,
"Total number of failed outgoing connections" "Total number of failed outgoing connections"
logScope:
topics = "utp_router"
export utp_socket
type type
# New remote client connection callback # New remote client connection callback
# ``server`` - UtpProtocol object. # ``server`` - UtpProtocol object.
@ -132,7 +132,8 @@ proc new*[A](
# There are different possibilities on how the connection got established, need # There are different possibilities on how the connection got established, need
# to check every case. # to check every case.
proc getSocketOnReset[A](r: UtpRouter[A], sender: A, id: uint16): Option[UtpSocket[A]] = proc getSocketOnReset[A](
r: UtpRouter[A], sender: A, id: uint16): Option[UtpSocket[A]] =
# id is our recv id # id is our recv id
let recvKey = UtpSocketKey[A].init(sender, id) let recvKey = UtpSocketKey[A].init(sender, id)
@ -146,7 +147,8 @@ proc getSocketOnReset[A](r: UtpRouter[A], sender: A, id: uint16): Option[UtpSock
.orElse(r.getUtpSocket(sendInitKey).filter(s => s.connectionIdSnd == id)) .orElse(r.getUtpSocket(sendInitKey).filter(s => s.connectionIdSnd == id))
.orElse(r.getUtpSocket(sendNoInitKey).filter(s => s.connectionIdSnd == id)) .orElse(r.getUtpSocket(sendNoInitKey).filter(s => s.connectionIdSnd == id))
proc shouldAllowConnection[A](r: UtpRouter[A], remoteAddress: A, connectionId: uint16): bool = proc shouldAllowConnection[A](
r: UtpRouter[A], remoteAddress: A, connectionId: uint16): bool =
if r.allowConnection == nil: if r.allowConnection == nil:
# if the callback is not configured it means all incoming connections are allowed # if the callback is not configured it means all incoming connections are allowed
true true
@ -183,14 +185,15 @@ proc processPacket[A](r: UtpRouter[A], p: Packet, sender: A) {.async.}=
debug "Received SYN for new connection. Initiating incoming connection", debug "Received SYN for new connection. Initiating incoming connection",
synSeqNr = p.header.seqNr synSeqNr = p.header.seqNr
# Initial ackNr is set to incoming packer seqNr # Initial ackNr is set to incoming packer seqNr
let incomingSocket = newIncomingSocket[A](sender, r.sendCb, r.socketConfig ,p.header.connectionId, p.header.seqNr, r.rng[]) let incomingSocket = newIncomingSocket[A](
sender, r.sendCb, r.socketConfig,
p.header.connectionId, p.header.seqNr, r.rng[])
r.registerUtpSocket(incomingSocket) r.registerUtpSocket(incomingSocket)
incomingSocket.startIncomingSocket() incomingSocket.startIncomingSocket()
# Based on configuration, socket is passed to upper layer either in SynRecv # Based on configuration, socket is passed to upper layer either in
# or Connected state # SynRecv or Connected state
utp_allowed_incoming.inc() utp_allowed_incoming.inc()
info "Accepting incoming connection", debug "Accepting incoming connection", src = incomingSocket.socketKey
to = incomingSocket.socketKey
asyncSpawn r.acceptConnection(r, incomingSocket) asyncSpawn r.acceptConnection(r, incomingSocket)
else: else:
utp_declined_incoming.inc() utp_declined_incoming.inc()
@ -203,13 +206,15 @@ proc processPacket[A](r: UtpRouter[A], p: Packet, sender: A) {.async.}=
let socket = maybeSocket.unsafeGet() let socket = maybeSocket.unsafeGet()
await socket.processPacket(p) await socket.processPacket(p)
else: else:
# TODO add keeping track of recently send reset packets and do not send reset # TODO add keeping track of recently send reset packets and do not send
# to peers which we recently send reset to. # reset to peers which we recently send reset to.
debug "Received FIN/DATA/ACK on not known socket sending reset" debug "Received FIN/DATA/ACK on not known socket sending reset"
let rstPacket = resetPacket(randUint16(r.rng[]), p.header.connectionId, p.header.seqNr) let rstPacket = resetPacket(
randUint16(r.rng[]), p.header.connectionId, p.header.seqNr)
await r.sendCb(sender, encodePacket(rstPacket)) await r.sendCb(sender, encodePacket(rstPacket))
proc processIncomingBytes*[A](r: UtpRouter[A], bytes: seq[byte], sender: A) {.async.} = proc processIncomingBytes*[A](
r: UtpRouter[A], bytes: seq[byte], sender: A) {.async.} =
if (not r.closed): if (not r.closed):
let dec = decodePacket(bytes) let dec = decodePacket(bytes)
if (dec.isOk()): if (dec.isOk()):
@ -218,15 +223,17 @@ proc processIncomingBytes*[A](r: UtpRouter[A], bytes: seq[byte], sender: A) {.as
else: else:
utp_failed_packets.inc() utp_failed_packets.inc()
let err = dec.error() let err = dec.error()
warn "failed to decode packet from address", address = sender, msg = err warn "Failed to decode packet from address", address = sender, msg = err
proc generateNewUniqueSocket[A](r: UtpRouter[A], address: A): Option[UtpSocket[A]] = proc generateNewUniqueSocket[A](
## Tries to generate unique socket, gives up after maxSocketGenerationTries tries r: UtpRouter[A], address: A):Option[UtpSocket[A]] =
## Try to generate unique socket, give up after maxSocketGenerationTries tries
var tryCount = 0 var tryCount = 0
while tryCount < maxSocketGenerationTries: while tryCount < maxSocketGenerationTries:
let rcvId = randUint16(r.rng[]) let rcvId = randUint16(r.rng[])
let socket = newOutgoingSocket[A](address, r.sendCb, r.socketConfig, rcvId, r.rng[]) let socket = newOutgoingSocket[A](
address, r.sendCb, r.socketConfig, rcvId, r.rng[])
if r.registerIfAbsent(socket): if r.registerIfAbsent(socket):
return some(socket) return some(socket)
@ -236,32 +243,31 @@ proc generateNewUniqueSocket[A](r: UtpRouter[A], address: A): Option[UtpSocket[A
return none[UtpSocket[A]]() return none[UtpSocket[A]]()
proc connect[A](s: UtpSocket[A]): Future[ConnectionResult[A]] {.async.}= proc connect[A](s: UtpSocket[A]): Future[ConnectionResult[A]] {.async.}=
info "Initiating connection", debug "Initiating connection", dst = s.socketKey
to = s.socketKey
let startFut = s.startOutgoingSocket() let startFut = s.startOutgoingSocket()
startFut.cancelCallback = proc(udata: pointer) {.gcsafe.} = startFut.cancelCallback = proc(udata: pointer) {.gcsafe.} =
# if for some reason future will be cancelled, destory socket to clear it from # if for some reason the future is cancelled, destroy socket to clear it
# active socket list # from the active socket list
s.destroy() s.destroy()
try: try:
await startFut await startFut
utp_success_outgoing.inc() utp_success_outgoing.inc()
info "Outgoing connection successful", debug "Outgoing connection successful", dst = s.socketKey
to = s.socketKey
return ok(s) return ok(s)
except ConnectionError: except ConnectionError:
utp_failed_outgoing.inc() utp_failed_outgoing.inc()
info "Outgoing connection timed-out", debug "Outgoing connection timed-out", dst = s.socketKey
to = s.socketKey
s.destroy() s.destroy()
return err(OutgoingConnectionError(kind: ConnectionTimedOut)) return err(OutgoingConnectionError(kind: ConnectionTimedOut))
# Connect to provided address # Connect to provided address
# Reference implementation: https://github.com/bittorrent/libutp/blob/master/utp_internal.cpp#L2732 # Reference implementation:
proc connectTo*[A](r: UtpRouter[A], address: A): Future[ConnectionResult[A]] {.async.} = # https://github.com/bittorrent/libutp/blob/master/utp_internal.cpp#L2732
proc connectTo*[A](
r: UtpRouter[A], address: A): Future[ConnectionResult[A]] {.async.} =
let maybeSocket = r.generateNewUniqueSocket(address) let maybeSocket = r.generateNewUniqueSocket(address)
if (maybeSocket.isNone()): if (maybeSocket.isNone()):
@ -272,8 +278,11 @@ proc connectTo*[A](r: UtpRouter[A], address: A): Future[ConnectionResult[A]] {.a
# Connect to provided address with provided connection id, if socket with this id # Connect to provided address with provided connection id, if socket with this id
# and address already exsits return error # and address already exsits return error
proc connectTo*[A](r: UtpRouter[A], address: A, connectionId: uint16): Future[ConnectionResult[A]] {.async.} = proc connectTo*[A](
let socket = newOutgoingSocket[A](address, r.sendCb, r.socketConfig, connectionId, r.rng[]) r: UtpRouter[A], address: A, connectionId: uint16):
Future[ConnectionResult[A]] {.async.} =
let socket = newOutgoingSocket[A](
address, r.sendCb, r.socketConfig, connectionId, r.rng[])
if (r.registerIfAbsent(socket)): if (r.registerIfAbsent(socket)):
return await socket.connect() return await socket.connect()
@ -282,7 +291,7 @@ proc connectTo*[A](r: UtpRouter[A], address: A, connectionId: uint16): Future[Co
proc shutdown*[A](r: UtpRouter[A]) = proc shutdown*[A](r: UtpRouter[A]) =
# stop processing any new packets and close all sockets in background without # stop processing any new packets and close all sockets in background without
# notifing remote peers # notifying remote peers
r.closed = true r.closed = true
for s in r.allSockets(): for s in r.allSockets():
s.destroy() s.destroy()
@ -290,12 +299,12 @@ proc shutdown*[A](r: UtpRouter[A]) =
proc shutdownWait*[A](r: UtpRouter[A]) {.async.} = proc shutdownWait*[A](r: UtpRouter[A]) {.async.} =
var activeSockets: seq[UtpSocket[A]] = @[] var activeSockets: seq[UtpSocket[A]] = @[]
# stop processing any new packets and close all sockets without # stop processing any new packets and close all sockets without
# notifing remote peers # notifying remote peers
r.closed = true r.closed = true
# we need to make copy as calling socket.destroyWait() removes socket from the table # Need to make a copy as calling socket.destroyWait() removes the socket from
# and iterator throws error. Antother option would be to wait until number of opensockets # the table and iterator throws error. Another option would be to wait until
# go to 0 # the number of open sockets drops to 0
for s in r.allSockets(): for s in r.allSockets():
activeSockets.add(s) activeSockets.add(s)

View File

@ -1,4 +1,4 @@
# Copyright (c) 2021 Status Research & Development GmbH # Copyright (c) 2021-2022 Status Research & Development GmbH
# Licensed and distributed under either of # Licensed and distributed under either of
# * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT). # * MIT license (license terms in the root directory or at https://opensource.org/licenses/MIT).
# * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0). # * Apache v2 license (license terms in the root directory or at https://www.apache.org/licenses/LICENSE-2.0).
@ -696,8 +696,7 @@ proc isClosedAndCleanedUpAllResources*(socket: UtpSocket): bool =
socket.isClosed() and socket.eventLoop.cancelled() and socket.checkTimeoutsLoop.cancelled() socket.isClosed() and socket.eventLoop.cancelled() and socket.checkTimeoutsLoop.cancelled()
proc destroy*(s: UtpSocket) = proc destroy*(s: UtpSocket) =
info "Destroying socket", debug "Destroying socket", to = s.socketKey
to = s.socketKey
## Moves socket to destroy state and clean all reasources. ## Moves socket to destroy state and clean all reasources.
## Remote is not notified in any way about socket end of life ## Remote is not notified in any way about socket end of life
s.state = Destroy s.state = Destroy
@ -1665,8 +1664,7 @@ proc close*(socket: UtpSocket) =
socket.readShutdown = true socket.readShutdown = true
if (not socket.sendFinRequested): if (not socket.sendFinRequested):
try: try:
info "Sending FIN", debug "Sending FIN", dst = socket.socketKey
to = socket.socketKey
# with this approach, all pending writes will be executed before sending fin packet # with this approach, all pending writes will be executed before sending fin packet
# we could also and method which places close request as first one to process # we could also and method which places close request as first one to process
# but it would complicate the write loop # but it would complicate the write loop
@ -1691,9 +1689,7 @@ proc closeWait*(socket: UtpSocket) {.async.} =
await socket.closeEvent.wait() await socket.closeEvent.wait()
proc write*(socket: UtpSocket, data: seq[byte]): Future[WriteResult] = proc write*(socket: UtpSocket, data: seq[byte]): Future[WriteResult] =
info "Write data", debug "Write data", dst = socket.socketKey, length = len(data)
to = socket.socketKey,
length = len(data)
let retFuture = newFuture[WriteResult]("UtpSocket.write") let retFuture = newFuture[WriteResult]("UtpSocket.write")