feat(ping): NethermindEth#41 improve logging (NethermindEth#49)

src/libp2p/Libp2p.Protocols.Ping/LogMessages.cs

@@ -0,0 +1,93 @@
+// SPDX-FileCopyrightText: 2023 Demerzel Solutions Limited
+// SPDX-License-Identifier: MIT
+
+using Microsoft.Extensions.Logging;
+using Nethermind.Libp2p.Core;
+
+namespace Nethermind.Libp2p.Protocols.Ping;
+
+internal static partial class LogMessages
+{
+    private const int EventId = 200_000;
+
+    [LoggerMessage(
+        EventId = EventId + 1,
+        EventName = nameof(ReadingPong),
+        Message = "Reading pong {remotePeer}",
+        Level = LogLevel.Trace)]
+    internal static partial void ReadingPong(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 2,
+        EventName = nameof(VerifyingPong),
+        Message = "Verifying pong {remotePeer}",
+        Level = LogLevel.Trace)]
+    internal static partial void VerifyingPong(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 3,
+        EventName = nameof(ReadingPing),
+        Message = "Reading ping {remotePeer}",
+        Level = LogLevel.Trace)]
+    internal static partial void ReadingPing(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 4,
+        EventName = nameof(ReturningPong),
+        Message = "Returning pong {remotePeer}",
+        Level = LogLevel.Trace)]
+    internal static partial void ReturningPong(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 5,
+        EventName = nameof(LogPing),
+        Message = "Ping {remotePeer}",
+        Level = LogLevel.Debug)]
+    internal static partial void LogPing(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 6,
+        EventName = nameof(LogPinged),
+        Message = "Pinged {remotePeer}",
+        Level = LogLevel.Debug)]
+    internal static partial void LogPinged(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 7,
+        EventName = nameof(PingListenStarted),
+        Message = "Ping listen started from {remotePeer}",
+        Level = LogLevel.Debug)]
+    internal static partial void PingListenStarted(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 8,
+        EventName = nameof(PingFinished),
+        Message = "Ping finished {remotePeer}",
+        Level = LogLevel.Debug)]
+    internal static partial void PingFinished(
+        this ILogger logger,
+        Multiaddr remotePeer);
+
+    [LoggerMessage(
+        EventId = EventId + 9,
+        EventName = nameof(PingFailed),
+        Message = "Wrong response to ping from {remotePeer}",
+        Level = LogLevel.Warning)]
+    internal static partial void PingFailed(
+        this ILogger logger,
+        Multiaddr remotePeer);
+}

src/libp2p/Libp2p.Protocols.Ping/PingProtocol.cs

@@ -1,9 +1,10 @@
 // SPDX-FileCopyrightText: 2023 Demerzel Solutions Limited
 // SPDX-License-Identifier: MIT
 
+using System.Buffers;
 using Microsoft.Extensions.Logging;
 using Nethermind.Libp2p.Core;
-using System.Buffers;
+using Nethermind.Libp2p.Protocols.Ping;
 
 namespace Nethermind.Libp2p.Protocols;
 
@@ -12,6 +13,8 @@ namespace Nethermind.Libp2p.Protocols;
 /// </summary>
 public class PingProtocol : IProtocol
 {
+    private const int PayloadLength = 32;
+
     public string Id => "/ipfs/ping/1.0.0";
     private readonly Random _random = new();
     private readonly ILogger<PingProtocol>? _logger;
@@ -24,33 +27,42 @@ public PingProtocol(ILoggerFactory? loggerFactory = null)
     public async Task DialAsync(IChannel channel, IChannelFactory? channelFactory,
         IPeerContext context)
     {
-        byte[] bytes = new byte[32];
-        _random.NextBytes(bytes.AsSpan(0, 32));
-        _logger?.LogDebug("Ping {remotePeer}", context.RemotePeer.Address);
-        await channel.WriteAsync(new ReadOnlySequence<byte>(bytes));
-        _logger?.LogTrace("Reading pong");
-        ReadOnlySequence<byte> response = await channel.ReadAsync(32, ReadBlockingMode.WaitAll);
-        _logger?.LogTrace("Verifing pong");
-        if (!Enumerable.SequenceEqual(bytes[0..32], response.ToArray()))
+        byte[] byteArray = new byte[PayloadLength];
+        _random.NextBytes(byteArray.AsSpan(0, PayloadLength));
+        ReadOnlySequence<byte> bytes = new(byteArray);
+
+        _logger?.LogPing(context.RemotePeer.Address);
+        await channel.WriteAsync(bytes);
+
+        _logger?.ReadingPong(context.RemotePeer.Address);
+        ReadOnlySequence<byte> response = await channel.ReadAsync(PayloadLength, ReadBlockingMode.WaitAll);
+
+        _logger?.VerifyingPong(context.RemotePeer.Address);
+        if (!byteArray[0..PayloadLength].SequenceEqual(response.ToArray()))
         {
-            _logger?.LogWarning("Wrong response to ping from {from}", context.RemotePeer);
+            _logger?.PingFailed(context.RemotePeer.Address);
             throw new ApplicationException();
         }
-        _logger?.LogDebug("Pinged");
+
+        _logger?.LogPinged(context.RemotePeer.Address);
     }
 
     public async Task ListenAsync(IChannel channel, IChannelFactory? channelFactory,
         IPeerContext context)
     {
-        _logger?.LogDebug("Ping listen started from {remotePeer}", context.RemotePeer);
+        _logger?.PingListenStarted(context.RemotePeer.Address);
 
         while (!channel.IsClosed)
         {
-            _logger?.LogTrace("Reading ping");
-            byte[] request = (await channel.ReadAsync(32, ReadBlockingMode.WaitAll)).ToArray();
-            _logger?.LogTrace("Returning back");
-            await channel.WriteAsync(new ReadOnlySequence<byte>(request));
+            _logger?.ReadingPing(context.RemotePeer.Address);
+            ReadOnlySequence<byte> request = await channel.ReadAsync(PayloadLength, ReadBlockingMode.WaitAll);
+            byte[] byteArray = request.ToArray();
+            ReadOnlySequence<byte> bytes = new(byteArray);
+
+            _logger?.ReturningPong(context.RemotePeer.Address);
+            await channel.WriteAsync(bytes);
         }
-        _logger?.LogDebug("Ping finished");
+
+        _logger?.PingFinished(context.RemotePeer.Address);
     }
 }