Improve log of p2p messages (#5542)

* Improve log of p2p messages

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

* [skip ci] Update ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/AbstractMessageData.java

Co-authored-by: Gabriel Fukushima <gabrielfukushima@gmail.com>
Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

* Use a more flexible way to trim logged data

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

* Sanitize user input before printing it in logs

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

---------

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>
Co-authored-by: Gabriel Fukushima <gabrielfukushima@gmail.com>
Co-authored-by: Sally MacFarlane <macfarla.github@gmail.com>

besu/src/main/resources/log4j2.xml

@@ -13,11 +13,21 @@
         <Property name="splunk.batch_size_count">${env:SPLUNK_BATCH_SIZE_COUNT:-1000}</Property>
         <Property name="splunk.batch_interval">${env:SPLUNK_BATCH_INTERVAL:-500}</Property>
         <Property name="splunk.disableCertificateValidation">${env:SPLUNK_SKIPTLSVERIFY:-false}</Property>
+        <Property name="console.pattern">%d{yyyy-MM-dd HH:mm:ss.SSSZZZ} | %t | %-5level | %c{1} | %msg</Property>
+        <Property name="console.msgdata.maxlen">1000</Property>
     </Properties>
 
     <Appenders>
+        <Console name="Console" target="SYSTEM_OUT">
+            <PatternLayout alwaysWriteExceptions="false">
+                <MarkerPatternSelector defaultPattern="${console.pattern}%n">
+                    <PatternMatch key="P2PMSG" pattern="${console.pattern} rawData=%maxLen{%X{rawData}}{${console.msgdata.maxlen}} decodedData=%maxLen{%X{decodedData}}{${console.msgdata.maxlen}}%n"/>
+                </MarkerPatternSelector>
+            </PatternLayout>
+        </Console>
         <Routing name="Router">
             <Routes pattern="$${sys:root.log.logger}">
+                <Route ref="Console" key="Console"/>
                 <Route key="Splunk">
                     <SplunkHttp name="Splunk"
                                 url="${sys:splunk.url}"

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/messages/NewBlockHashesMessage.java

@@ -78,8 +78,8 @@ public final class NewBlockHashesMessage extends AbstractMessageData {
   }
 
   @Override
-  public String toString() {
-    return String.format("NewBlockHashesMessage: [%s]", Iterators.toString(getNewHashes()));
+  public String toStringDecoded() {
+    return Iterators.toString(getNewHashes());
   }
 
   public static final class NewBlockHash {

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/messages/StatusMessage.java

@@ -218,7 +218,7 @@ public final class StatusMessage extends AbstractMessageData {
 
     @Override
     public String toString() {
-      return "EthStatus{"
+      return "{"
           + "protocolVersion="
           + protocolVersion
           + ", networkId="
@@ -236,7 +236,7 @@ public final class StatusMessage extends AbstractMessageData {
   }
 
   @Override
-  public String toString() {
+  public String toStringDecoded() {
     return status().toString();
   }
 }

ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/messages/snap/GetAccountRangeMessage.java

@@ -92,11 +92,6 @@ public final class GetAccountRangeMessage extends AbstractSnapMessageData {
     return range;
   }
 
-  @Override
-  public String toString() {
-    return "GetAccountRangeMessage{" + "data=" + data + '}';
-  }
-
   @Value.Immutable
   public interface Range {
 

ethereum/eth/src/test/java/org/hyperledger/besu/ethereum/eth/messages/StatusMessageTest.java

@@ -91,7 +91,7 @@ public class StatusMessageTest {
   }
 
   @Test
-  public void toStringHasExpectedInfo() {
+  public void toStringDecodedHasExpectedInfo() {
     final int version = EthProtocolVersion.V64;
     final BigInteger networkId = BigInteger.ONE;
     final Difficulty td = Difficulty.of(1000L);
@@ -103,10 +103,10 @@ public class StatusMessageTest {
         StatusMessage.create(version, networkId, td, bestHash, genesisHash, forkId);
 
     final StatusMessage copy = new StatusMessage(msg.getData());
-    final String copyToString = copy.toString();
+    final String copyToStringDecoded = copy.toStringDecoded();
 
-    assertThat(copyToString).contains("bestHash=" + bestHash);
-    assertThat(copyToString).contains("genesisHash=" + genesisHash);
+    assertThat(copyToStringDecoded).contains("bestHash=" + bestHash);
+    assertThat(copyToStringDecoded).contains("genesisHash=" + genesisHash);
   }
 
   private Hash randHash(final long seed) {

ethereum/p2p/build.gradle

@@ -57,6 +57,7 @@ dependencies {
   implementation 'io.tmio:tuweni-rlp'
   implementation 'io.tmio:tuweni-units'
   implementation 'org.jetbrains.kotlin:kotlin-stdlib'
+  implementation 'org.owasp.encoder:encoder'
   implementation 'org.xerial.snappy:snappy-java'
 
   annotationProcessor "org.immutables:value"

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/AbstractPeerConnection.java

@@ -35,10 +35,12 @@ import java.util.concurrent.atomic.AtomicBoolean;
 
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.Marker;
+import org.slf4j.MarkerFactory;
 
 public abstract class AbstractPeerConnection implements PeerConnection {
   private static final Logger LOG = LoggerFactory.getLogger(AbstractPeerConnection.class);
-
+  private static final Marker P2P_MESSAGE_MARKER = MarkerFactory.getMarker("P2PMSG");
   private final Peer peer;
   private final PeerInfo peerInfo;
   private final InetSocketAddress localAddress;
@@ -120,7 +122,15 @@ public abstract class AbstractPeerConnection implements PeerConnection {
           .inc();
     }
 
-    LOG.trace("Writing {} to {} via protocol {}", message, peerInfo, capability);
+    LOG.atTrace()
+        .addMarker(P2P_MESSAGE_MARKER)
+        .setMessage("Writing {} to {} via protocol {}")
+        .addArgument(message)
+        .addArgument(peerInfo)
+        .addArgument(capability)
+        .addKeyValue("rawData", message.getData())
+        .addKeyValue("decodedData", message::toStringDecoded)
+        .log();
     doSendMessage(capability, message);
   }
 

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/connections/netty/ApiHandler.java

@@ -29,10 +29,13 @@ import io.netty.channel.ChannelHandlerContext;
 import io.netty.channel.SimpleChannelInboundHandler;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.Marker;
+import org.slf4j.MarkerFactory;
 
 final class ApiHandler extends SimpleChannelInboundHandler<MessageData> {
 
   private static final Logger LOG = LoggerFactory.getLogger(ApiHandler.class);
+  private static final Marker P2P_MESSAGE_MARKER = MarkerFactory.getMarker("P2PMSG");
 
   private final CapabilityMultiplexer multiplexer;
   private final AtomicBoolean waitingForPong;
@@ -96,6 +99,16 @@ final class ApiHandler extends SimpleChannelInboundHandler<MessageData> {
       }
       return;
     }
+    LOG.atTrace()
+        .addMarker(P2P_MESSAGE_MARKER)
+        .setMessage("Received {} from {} via protocol {}")
+        .addArgument(message)
+        .addArgument(connection.getPeerInfo())
+        .addArgument(demultiplexed.getCapability())
+        .addKeyValue("rawData", message.getData())
+        .addKeyValue("decodedData", message::toStringDecoded)
+        .log();
+
     connectionEventDispatcher.dispatchMessage(demultiplexed.getCapability(), connection, message);
   }
 

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/AbstractMessageData.java

@@ -52,4 +52,9 @@ public abstract class AbstractMessageData implements MessageData {
   public int hashCode() {
     return Objects.hashCode(data);
   }
+
+  @Override
+  public String toString() {
+    return getClass().getSimpleName() + "{code=" + getCode() + ", size=" + getSize() + "}";
+  }
 }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/Capability.java

@@ -22,6 +22,8 @@ import org.hyperledger.besu.ethereum.rlp.RLPOutput;
 import java.nio.charset.StandardCharsets;
 import java.util.Objects;
 
+import org.owasp.encoder.Encode;
+
 /**
  * Represents a client capability.
  *
@@ -82,7 +84,8 @@ public class Capability {
   }
 
   @Override
+  /** Returned string is sanitized since it contains user input */
   public String toString() {
-    return name + "/" + version;
+    return Encode.forJava(name) + "/" + version;
   }
 }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/CapabilityMultiplexer.java

@@ -107,6 +107,11 @@ public class CapabilityMultiplexer {
       public Bytes getData() {
         return originalMessage.getData();
       }
+
+      @Override
+      public String toString() {
+        return "Message{ code=" + getCode() + ", size=" + getSize() + "}";
+      }
     };
   }
 

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/MessageData.java

@@ -26,7 +26,6 @@ import org.apache.tuweni.bytes.Bytes;
 
 /** A P2P Network Message's Data. */
 public interface MessageData {
-
   /**
    * Returns the size of the message.
    *
@@ -65,4 +64,13 @@ public interface MessageData {
     messageDataRLP.leaveList();
     return new AbstractMap.SimpleImmutableEntry<>(requestId, new RawMessage(getCode(), message));
   }
+
+  /**
+   * Subclasses can implement this method to return a human-readable version of the raw data.
+   *
+   * @return return a human-readable version of the raw data
+   */
+  default String toStringDecoded() {
+    return "N/A";
+  }
 }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/PeerInfo.java

@@ -30,6 +30,7 @@ import java.util.Objects;
 import javax.annotation.Nonnull;
 
 import org.apache.tuweni.bytes.Bytes;
+import org.owasp.encoder.Encode;
 
 /**
  * Encapsulates information about a peer, including their protocol version, client ID, capabilities
@@ -43,6 +44,7 @@ public class PeerInfo implements Comparable<PeerInfo> {
   private final List<Capability> capabilities;
   private final int port;
   private final Bytes nodeId;
+  private Address address = null;
 
   public PeerInfo(
       final int version,
@@ -97,9 +99,12 @@ public class PeerInfo implements Comparable<PeerInfo> {
   }
 
   public Address getAddress() {
-    final SECPPublicKey remotePublicKey =
-        SignatureAlgorithmFactory.getInstance().createPublicKey(nodeId);
-    return Util.publicKeyToAddress(remotePublicKey);
+    if (address == null) {
+      final SECPPublicKey remotePublicKey =
+          SignatureAlgorithmFactory.getInstance().createPublicKey(nodeId);
+      address = Util.publicKeyToAddress(remotePublicKey);
+    }
+    return address;
   }
 
   public void writeTo(final RLPOutput out) {
@@ -113,10 +118,11 @@ public class PeerInfo implements Comparable<PeerInfo> {
   }
 
   @Override
+  /** Returned string is sanitized since it contains user input */
   public String toString() {
     final StringBuilder sb = new StringBuilder("PeerInfo{");
     sb.append("version=").append(version);
-    sb.append(", clientId='").append(clientId).append('\'');
+    sb.append(", clientId='").append(Encode.forJava(clientId)).append('\'');
     sb.append(", capabilities=").append(capabilities);
     sb.append(", port=").append(port);
     sb.append(", nodeId=").append(nodeId);

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/RawMessage.java

@@ -29,9 +29,4 @@ public final class RawMessage extends AbstractMessageData {
   public int getCode() {
     return code;
   }
-
-  @Override
-  public String toString() {
-    return "RawMessage{" + "code=" + code + ", data=" + data + '}';
-  }
 }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/messages/DisconnectMessage.java

@@ -61,11 +61,6 @@ public final class DisconnectMessage extends AbstractMessageData {
     return Data.readFrom(RLP.input(data)).getReason();
   }
 
-  @Override
-  public String toString() {
-    return "DisconnectMessage{" + "data=" + data + '}';
-  }
-
   public static class Data {
     private final DisconnectReason reason;
 

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/messages/EmptyMessage.java

@@ -30,4 +30,9 @@ abstract class EmptyMessage implements MessageData {
   public Bytes getData() {
     return Bytes.EMPTY;
   }
+
+  @Override
+  public String toString() {
+    return getClass().getSimpleName() + "{ code=" + getCode() + ", size=0}";
+  }
 }

ethereum/p2p/src/main/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/messages/HelloMessage.java

@@ -55,9 +55,4 @@ public final class HelloMessage extends AbstractMessageData {
   public PeerInfo getPeerInfo() {
     return PeerInfo.readFrom(RLP.input(data));
   }
-
-  @Override
-  public String toString() {
-    return "HelloMessage{" + "data=" + data + '}';
-  }
 }

ethereum/p2p/src/test/java/org/hyperledger/besu/ethereum/p2p/rlpx/wire/PeerInfoTest.java

@@ -0,0 +1,40 @@
+/*
+ * Copyright Hyperledger Besu Contributors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on
+ * an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the
+ * specific language governing permissions and limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+package org.hyperledger.besu.ethereum.p2p.rlpx.wire;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+import java.util.List;
+
+import org.apache.tuweni.bytes.Bytes;
+import org.junit.jupiter.api.Test;
+
+class PeerInfoTest {
+
+  @Test
+  public void toStringIsSanitized() {
+    final PeerInfo maliciousPeer =
+        new PeerInfo(
+            1,
+            "ab\nc",
+            List.of(Capability.create("c\ba\rp", 4)),
+            30303,
+            Bytes.fromHexStringLenient("0x1234"));
+
+    final String toString = maliciousPeer.toString();
+
+    assertThat(toString).doesNotContain(List.of("\n", "\b", "\r"));
+  }
+}

gradle/verification-metadata.xml

@@ -5458,6 +5458,19 @@
             <sha256 value="ddd06913f147d70ae68e7a6e4356a55b33f14dde6162dbff2bd0e289581f1ad2" origin="Generated by Gradle"/>
          </artifact>
       </component>
+      <component group="org.owasp.encoder" name="encoder" version="1.2.3">
+         <artifact name="encoder-1.2.3.jar">
+            <sha256 value="b09e2cd5c36a7127e091df9be628278b1166b40bc08b9de8196ccddb0cccd67f" origin="Generated by Gradle"/>
+         </artifact>
+         <artifact name="encoder-1.2.3.pom">
+            <sha256 value="b963a3a2a7414fcd17e2826f60017023d2937e50793104db96d6a749d6a2f424" origin="Generated by Gradle"/>
+         </artifact>
+      </component>
+      <component group="org.owasp.encoder" name="encoder-parent" version="1.2.3">
+         <artifact name="encoder-parent-1.2.3.pom">
+            <sha256 value="732f62378e11feb11121d37dcb284ddf835938d617a13c34851ca2098e4d7866" origin="Generated by Gradle"/>
+         </artifact>
+      </component>
       <component group="org.pcollections" name="pcollections" version="3.1.4">
          <artifact name="pcollections-3.1.4.jar">
             <sha256 value="34f579ba075c8da2c8a0fedd0f04e21eac2fb6c660d90d0fabb573e8b4dc6918" origin="Generated by Gradle"/>

gradle/versions.gradle

@@ -204,6 +204,8 @@ dependencyManagement {
       entry 'jmh-generator-annprocess'
     }
 
+    dependency 'org.owasp.encoder:encoder:1.2.3'
+
     dependency 'org.rocksdb:rocksdbjni:8.0.0'
 
     dependencySet(group: 'org.slf4j', version:'2.0.7') {

testutil/src/main/resources/log4j2.xml

@@ -2,11 +2,18 @@
 <Configuration status="WARN">
   <Properties>
     <Property name="root.log.level">INFO</Property>
+    <Property name="console.pattern">%d{yyyy-MM-dd HH:mm:ss.SSSZZZ} | %t | %-5level | %c{1} | %msg</Property>
+    <Property name="console.msgdata.maxlen">1000</Property>
   </Properties>
 
   <Appenders>
     <Console name="Console" target="SYSTEM_OUT">
-      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSSZZZ} | %t | %-5level | %c{1} | %msg%n" />    </Console>
+      <PatternLayout alwaysWriteExceptions="false">
+        <MarkerPatternSelector defaultPattern="${console.pattern}%n">
+          <PatternMatch key="P2PMSG" pattern="${console.pattern} rawData=%maxLen{%X{rawData}}{${console.msgdata.maxlen}} decodedData=%maxLen{%X{decodedData}}{${console.msgdata.maxlen}}%n"/>
+        </MarkerPatternSelector>
+      </PatternLayout>
+    </Console>
   </Appenders>
   <Loggers>
     <Root level="${sys:root.log.level}">