status-im
/
nim-eth
mirror of https://github.com/status-im/nim-eth.git
2
0
Fork 0
Code Issues Projects Releases Wiki Activity

Reassign logging weights in RLPx handler (#725) 

why:
  Too much noise, updating sort of guided by
  https://github.com/status-im/nimbus-eth2/blob/unstable/docs/logging.md
This commit is contained in:
Jordan Hrycaj 2024-08-30 18:00:11 +00:00 committed by GitHub
parent 5ecbcb5886
commit 92c7bea807
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
1 changed files with 36 additions and 30 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

66
eth/p2p/rlpx.nim
View File

@ -153,7 +153,7 @@ proc requestResolver[MsgType](msg: pointer, future: FutureBase) {.gcsafe.} =
else: else:
doAssert false, "trying to resolve a timed out request with a value" doAssert false, "trying to resolve a timed out request with a value"
except CatchableError as e: except CatchableError as e:
debug "Exception in requestResolver()", exc = e.name, err = e.msg debug "Exception in requestResolver()", err = e.msg, errName = e.name
else: else:
try: try:
if not f.read.isSome: if not f.read.isSome:
@ -163,11 +163,11 @@ proc requestResolver[MsgType](msg: pointer, future: FutureBase) {.gcsafe.} =
# broken pipe # broken pipe
except TransportOsError as e: except TransportOsError as e:
# E.g. broken pipe # E.g. broken pipe
trace "TransportOsError during request", err = e.msg trace "TransportOsError during request", err = e.msg, errName = e.name
except TransportError: except TransportError:
trace "Transport got closed during request" trace "Transport got closed during request"
except CatchableError as e: except CatchableError as e:
debug "Exception in requestResolver()", exc = e.name, err = e.msg debug "Exception in requestResolver()", err = e.msg, errName = e.name
proc linkSendFailureToReqFuture[S, R](sendFut: Future[S], resFut: Future[R]) = proc linkSendFailureToReqFuture[S, R](sendFut: Future[S], resFut: Future[R]) =
sendFut.addCallback() do (arg: pointer): sendFut.addCallback() do (arg: pointer):
@ -439,10 +439,13 @@ proc registerRequest(peer: Peer,
discard setTimer(timeoutAt, timeoutExpired, nil) discard setTimer(timeoutAt, timeoutExpired, nil)
proc resolveResponseFuture(peer: Peer, msgId: uint, msg: pointer) = proc resolveResponseFuture(peer: Peer, msgId: uint, msg: pointer) =
## Split off from the non request ID version from the originally combined ## This function is a split off from the previously combined version with
## `resolveResponseFuture()` function. This seems cleaner to handle with macros ## the same name using optional request ID arguments. This here is the
## than a `int` or `Opt[uint]` request ID argument (yes, there is a second part ## version without a request ID (there is the other part below.).
## below.). ##
## Optional arguments for macro helpers seem easier to handle with
## polymorphic functions (than a `Opt[]` prototype argument.)
##
logScope: logScope:
msg = peer.dispatcher.messages[msgId].name msg = peer.dispatcher.messages[msgId].name
msgContents = peer.dispatcher.messages[msgId].printer(msg) msgContents = peer.dispatcher.messages[msgId].printer(msg)
@ -478,7 +481,7 @@ proc resolveResponseFuture(peer: Peer, msgId: uint, msg: pointer) =
let oldestReq = outstandingReqs.popFirst let oldestReq = outstandingReqs.popFirst
resolve oldestReq.future resolve oldestReq.future
else: else:
trace "late or duplicate reply for a RLPx request" trace "late or dup RPLx reply ignored", msgId
proc resolveResponseFuture(peer: Peer, msgId: uint, msg: pointer, reqId: uint) = proc resolveResponseFuture(peer: Peer, msgId: uint, msg: pointer, reqId: uint) =
## Variant of `resolveResponseFuture()` for request ID argument. ## Variant of `resolveResponseFuture()` for request ID argument.
@ -504,7 +507,7 @@ proc resolveResponseFuture(peer: Peer, msgId: uint, msg: pointer, reqId: uint) =
# types of requests). Alternatively, we can assign a separate interval in # types of requests). Alternatively, we can assign a separate interval in
# the `reqId` space for each type of response. # the `reqId` space for each type of response.
if peer.lastReqId.isNone or reqId > peer.lastReqId.value: if peer.lastReqId.isNone or reqId > peer.lastReqId.value:
warn "RLPx response without a matching request" debug "RLPx response without matching request", msgId, reqId
return return
var idx = 0 var idx = 0
@ -536,7 +539,7 @@ proc resolveResponseFuture(peer: Peer, msgId: uint, msg: pointer, reqId: uint) =
inc idx inc idx
debug "late or duplicate reply for a RLPx request" trace "late or dup RPLx reply ignored"
proc recvMsg*(peer: Peer): Future[tuple[msgId: uint, msgData: Rlp]] {.async.} = proc recvMsg*(peer: Peer): Future[tuple[msgId: uint, msgData: Rlp]] {.async.} =
@ -622,8 +625,9 @@ proc checkedRlpRead(peer: Peer, r: var Rlp, MsgType: type):
debug "Failed rlp.read", debug "Failed rlp.read",
peer = peer, peer = peer,
dataType = MsgType.name, dataType = MsgType.name,
exception = e.msg err = e.msg,
# rlpData = r.inspect -- don't use (might crash) errName = e.name
#, rlpData = r.inspect -- don't use (might crash)
raise e raise e
@ -649,8 +653,8 @@ proc waitSingleMsg(peer: Peer, MsgType: type): Future[MsgType] {.async.} =
trace "disconnect message received in waitSingleMsg", reason, peer trace "disconnect message received in waitSingleMsg", reason, peer
raisePeerDisconnected("Unexpected disconnect", reason) raisePeerDisconnected("Unexpected disconnect", reason)
else: else:
warn "Dropped RLPX message", debug "Dropped RLPX message",
msg = peer.dispatcher.messages[nextMsgId].name msg = peer.dispatcher.messages[nextMsgId].name
# TODO: This is breach of protocol? # TODO: This is breach of protocol?
proc nextMsg*(peer: Peer, MsgType: type): Future[MsgType] = proc nextMsg*(peer: Peer, MsgType: type): Future[MsgType] =
@ -702,14 +706,14 @@ proc dispatchMessages*(peer: Peer) {.async.} =
try: try:
await peer.invokeThunk(msgId, msgData) await peer.invokeThunk(msgId, msgData)
except RlpError: except RlpError as e:
debug "RlpError, ending dispatchMessages loop", peer, debug "RlpError, ending dispatchMessages loop", peer,
msg = peer.getMsgName(msgId) msg = peer.getMsgName(msgId), err = e.msg, errName = e.name
await peer.disconnect(BreachOfProtocol, true) await peer.disconnect(BreachOfProtocol, true)
return return
except EthP2PError as e: except EthP2PError as e:
warn "Error while handling RLPx message", peer, debug "Error while handling RLPx message", peer,
msg = peer.getMsgName(msgId), err = e.msg msg = peer.getMsgName(msgId), err = e.msg, errName = e.name
# TODO: Hmm, this can be safely moved into the message handler thunk. # TODO: Hmm, this can be safely moved into the message handler thunk.
# The documentation will need to be updated, explaining the fact that # The documentation will need to be updated, explaining the fact that
@ -725,7 +729,7 @@ proc dispatchMessages*(peer: Peer) {.async.} =
# They also are supposed to be handled at the call-site where # They also are supposed to be handled at the call-site where
# `nextMsg` is used. # `nextMsg` is used.
debug "nextMsg resolver failed, ending dispatchMessages loop", peer, debug "nextMsg resolver failed, ending dispatchMessages loop", peer,
err = e.msg msg = peer.getMsgName(msgId), err = e.msg
await peer.disconnect(BreachOfProtocol, true) await peer.disconnect(BreachOfProtocol, true)
return return
peer.awaitedMessages[msgId] = nil peer.awaitedMessages[msgId] = nil
@ -1038,8 +1042,9 @@ proc disconnect*(peer: Peer, reason: DisconnectionReason,
try: try:
await peer.sendDisconnectMsg(DisconnectionReasonList(value: reason)) await peer.sendDisconnectMsg(DisconnectionReasonList(value: reason))
except CatchableError as exc: except CatchableError as e:
debug "Failed to deliver disconnect message", peer, msg=exc.msg trace "Failed to deliver disconnect message", peer,
err = e.msg, errName = e.name
# Give the peer a chance to disconnect # Give the peer a chance to disconnect
traceAsyncErrors peer.waitAndClose(2.seconds) traceAsyncErrors peer.waitAndClose(2.seconds)
@ -1198,7 +1203,7 @@ proc rlpxConnect*(node: EthereumNode, remote: Node):
return err(TransportConnectError) return err(TransportConnectError)
except CatchableError as e: except CatchableError as e:
# Aside from TransportOsError, seems raw CatchableError can also occur? # Aside from TransportOsError, seems raw CatchableError can also occur?
debug "TCP connect with peer failed", err = $e.name, errMsg = $e.msg trace "TCP connect with peer failed", err = $e.name, errMsg = $e.msg
return err(TransportConnectError) return err(TransportConnectError)
# RLPx initial handshake # RLPx initial handshake
@ -1246,7 +1251,7 @@ proc rlpxConnect*(node: EthereumNode, remote: Node):
# TODO: Bullet 1 of https://github.com/status-im/nim-eth/issues/559 # TODO: Bullet 1 of https://github.com/status-im/nim-eth/issues/559
let res = handshake.decodeAckMessage(ackMsg) let res = handshake.decodeAckMessage(ackMsg)
if res.isErr(): if res.isErr():
debug "rlpxConnect handshake error", error = res.error trace "rlpxConnect handshake error", error = res.error
return err(RlpxHandshakeError) return err(RlpxHandshakeError)
peer.setSnappySupport(node, handshake) peer.setSnappySupport(node, handshake)
@ -1294,7 +1299,7 @@ proc rlpxConnect*(node: EthereumNode, remote: Node):
raiseAssert($e.name & " " & $e.msg) raiseAssert($e.name & " " & $e.msg)
if not validatePubKeyInHello(response, remote.node.pubkey): if not validatePubKeyInHello(response, remote.node.pubkey):
warn "Wrong devp2p identity in Hello message" trace "Wrong devp2p identity in Hello message"
return err(InvalidIdentityError) return err(InvalidIdentityError)
trace "DevP2P handshake completed", peer = remote, trace "DevP2P handshake completed", peer = remote,
@ -1394,7 +1399,7 @@ proc rlpxAccept*(
trace "Received Hello", version=response.version, id=response.clientId trace "Received Hello", version=response.version, id=response.clientId
if not validatePubKeyInHello(response, handshake.remoteHPubkey): if not validatePubKeyInHello(response, handshake.remoteHPubkey):
warn "A Remote nodeId is not its public key" # XXX: Do we care? trace "A Remote nodeId is not its public key" # XXX: Do we care?
let remote = transport.remoteAddress() let remote = transport.remoteAddress()
let address = Address(ip: remote.address, tcpPort: remote.port, let address = Address(ip: remote.address, tcpPort: remote.port,
@ -1421,9 +1426,9 @@ proc rlpxAccept*(
except PeerDisconnected as e: except PeerDisconnected as e:
case e.reason case e.reason
of AlreadyConnected, TooManyPeers, MessageTimeout: of AlreadyConnected, TooManyPeers, MessageTimeout:
trace "Disconnect during rlpxAccept", reason = e.reason, peer = peer.remote trace "RLPx disconnect", reason = e.reason, peer = peer.remote
else: else:
debug "Unexpected disconnect during rlpxAccept", reason = e.reason, debug "RLPx disconnect unexpected", reason = e.reason,
msg = e.msg, peer = peer.remote msg = e.msg, peer = peer.remote
rlpx_accept_failure.inc(labelValues = [$e.reason]) rlpx_accept_failure.inc(labelValues = [$e.reason])
@ -1436,16 +1441,17 @@ proc rlpxAccept*(
except RlpTypeMismatch as e: except RlpTypeMismatch as e:
# Some peers report capabilities with names longer than 3 chars. We ignore # Some peers report capabilities with names longer than 3 chars. We ignore
# those for now. Maybe we should allow this though. # those for now. Maybe we should allow this though.
debug "Rlp error in rlpxAccept", err = e.msg, errName = e.name trace "Rlp error in rlpxAccept", err = e.msg, errName = e.name
rlpx_accept_failure.inc(labelValues = [$RlpTypeMismatch]) rlpx_accept_failure.inc(labelValues = [$RlpTypeMismatch])
except TransportOsError as e: except TransportOsError as e:
trace "TransportOsError", err = e.msg, errName = e.name
if e.code == OSErrorCode(110): if e.code == OSErrorCode(110):
trace "RLPx timeout", err = e.msg, errName = e.name
rlpx_accept_failure.inc(labelValues = ["tcp_timeout"]) rlpx_accept_failure.inc(labelValues = ["tcp_timeout"])
else: else:
trace "TransportOsError", err = e.msg, errName = e.name
rlpx_accept_failure.inc(labelValues = [$e.name]) rlpx_accept_failure.inc(labelValues = [$e.name])
except CatchableError as e: except CatchableError as e:
error "Unexpected exception in rlpxAccept", exc = e.name, err = e.msg trace "RLPx error", err = e.msg, errName = e.name
rlpx_accept_failure.inc(labelValues = [$e.name]) rlpx_accept_failure.inc(labelValues = [$e.name])
if not ok: if not ok: