Invalid packets in discovery agent throw an error, but should only be logged as a debug message

[daniel-iobuilders]

Recently a lot of error messages appear in the log when Besu syncs one of the test nets. The error messages look like this:

2021-04-12 18:34:42.924+00:00 | vert.x-eventloop-thread-1 | ERROR | VertxPeerDiscoveryAgent | Encountered error while handling packet
java.lang.IllegalArgumentException: Could not recover public key
	at org.hyperledger.besu.crypto.SECP256K1.recoverFromSignatureNative(SECP256K1.java:420)
	at org.hyperledger.besu.crypto.SECP256K1$PublicKey.recoverFromSignature(SECP256K1.java:539)
	at org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.<init>(Packet.java:83)
	at org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.decode(Packet.java:119)
	at org.hyperledger.besu.ethereum.p2p.discovery.VertxPeerDiscoveryAgent.lambda$handlePacket$6(VertxPeerDiscoveryAgent.java:221)
	at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
	at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:832)

A PR of mine was changing SECP256K1, so the first assumption was that it was causing this error messages. After investigating it and testing it with different releases of Besu, I found out that the PR in question did not cause it. The same error messages appear with older releases of Besu, like 21.1.0 or 20.10.4, which were released before the PR was merged.

This can be verified and reproduced by using one of the mentioned releases or the current one with the following config file:

miner-enabled=false
graphql-http-enabled=false
sync-mode="FULL"
pruning-enabled=true
rpc-ws-enabled=false
data-path="/home/USER/chains/ropsten"
rpc-http-enabled=false
network="ROPSTEN"

After about 5 - 15 minutes of syncing the error messages will appear in the log.

The problem is that the discovery agent receives packets with invalid signatures and throws an exception afterwards. This packets are not causing any problems, they are simply invalid and should not create an error. I suggest that instead of throwing an exception it should just create a debug message, so it is not cluttering the logs.

This is the part of the code that I would suggest to change:

// org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.<init>(Packet.java:83)

    this.publicKey =
        SIGNATURE_ALGORITHM
            .get()
            .recoverPublicKeyFromSignature(keccak256(signedPayload), this.signature)
            .orElseThrow(
                () ->
                    new PeerDiscoveryPacketDecodingException(
                        "Invalid packet signature, " + "cannot recover public key"));

I suggest to catch the IllegalArgumentException thrown by org.hyperledger.besu.crypto.SignatureAlgorithm.recoverPublicKeyFromSignature* and create a debug log message with Invalid packet signature cannot recover public key instead.

Please tell me your thoughts about this change. If it is considered to be alright I could create the PR for it.

Original reporters of the issue: @matkt @3nprob

[RatanRSur]

I think that's a good solution and we would welcome a PR!

[shemnon]

I concur that the likely cause is some other client sending bogus packets. But because of the flow logic I think we need to keep the exception.

In VertexPeerDiscoveryAgent line 234 is where the handling of the logging occurs. We already have a check for a specific type of exception. I think the cleanest fix is to go into org.hyperleder.besu.ethereum.p2p.discovery.internal.Packet and move the return new Packet(...) statement inside of the try/catch at lines 120-124. That will result in all cases where a packet could not be produced resulting in a PeerDiscoveryPacketDecodingException, which will then be logged as debug.

[3nprob]

@shemnon Followed your directions in #2143

We are now instead hit by #1715 on mainnet nodes

[stevanlohja]

I get a similar error message with the classic network.

java.lang.IllegalArgumentException: Could not recover public key
	at org.hyperledger.besu.crypto.SECP256K1.recoverFromSignatureNative(SECP256K1.java:495)
	at org.hyperledger.besu.crypto.SECP256K1.recoverPublicKeyFromSignature(SECP256K1.java:370)
	at org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.<init>(Packet.java:90)
	at org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.decode(Packet.java:126)
	at org.hyperledger.besu.ethereum.p2p.discovery.VertxPeerDiscoveryAgent.lambda$handlePacket$6(VertxPeerDiscoveryAgent.java:221)
	at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
	at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Unknown Source)