Log request on invalid RPC JSON (#7621)

src/Nethermind/Nethermind.Core.Test/EncodingExtensionsTests.cs

@@ -0,0 +1,121 @@
+// SPDX-FileCopyrightText: 2024 Demerzel Solutions Limited
+// SPDX-License-Identifier: LGPL-3.0-only
+
+using System;
+using System.Buffers;
+using System.Linq;
+using FluentAssertions;
+using Nethermind.Core.Extensions;
+using NUnit.Framework;
+
+namespace Nethermind.Core.Test;
+
+public class EncodingExtensionsTests
+{
+    private class ReadOnlySequenceBuilder<T>
+    {
+        private ReadOnlyChunk<T>? _first;
+        private ReadOnlyChunk<T>? _current;
+
+        public ReadOnlySequenceBuilder()
+        {
+            _first = _current = null;
+        }
+
+        public ReadOnlySequenceBuilder<T> WithSegment(ReadOnlyMemory<T> memory)
+        {
+            if (_current == null) _first = _current = new(memory);
+            else _current = _current.Append(memory);
+
+            return this;
+        }
+
+        public ReadOnlySequenceBuilder<T> WithSegment(ReadOnlySequence<T> sequence)
+        {
+            SequencePosition pos = sequence.Start;
+            while (sequence.TryGet(ref pos, out ReadOnlyMemory<T> mem))
+                WithSegment(mem);
+            return this;
+        }
+
+        public ReadOnlySequenceBuilder<T> WithSegment(T[] array) => WithSegment(array.AsMemory());
+
+        public ReadOnlySequence<T> Build()
+        {
+            if (_first == null || _current == null) return new();
+            return new(_first, 0, _current, _current.Memory.Length);
+        }
+
+        private sealed class ReadOnlyChunk<TT> : ReadOnlySequenceSegment<TT>
+        {
+            public ReadOnlyChunk(ReadOnlyMemory<TT> memory)
+            {
+                Memory = memory;
+            }
+
+            public ReadOnlyChunk<TT> Append(ReadOnlyMemory<TT> memory)
+            {
+                var nextChunk = new ReadOnlyChunk<TT>(memory)
+                {
+                    RunningIndex = RunningIndex + Memory.Length
+                };
+
+                Next = nextChunk;
+                return nextChunk;
+            }
+        }
+    }
+
+    [Test]
+    // 1-byte chars
+    [TestCase("1234567890", 1)]
+    [TestCase("1234567890", 5)]
+    [TestCase("1234567890", 10)]
+    [TestCase("1234567890", 20)]
+    // JSON
+    [TestCase("""{"id":1,"jsonrpc":"2.0","method":"eth_blockNumber","params":[]}""", 10)]
+    [TestCase("""{"id":1,"jsonrpc":"2.0","method":"eth_blockNumber","params":[]}""", 63)]
+    [TestCase("""{"id":1,"jsonrpc":"2.0","method":"eth_blockNumber","params":[]}""", 64)]
+    // 2-bytes chars
+    [TestCase("\u0101\u0102\u0103\u0104\u0105", 1)]
+    [TestCase("\u0101\u0102\u0103\u0104\u0105", 3)]
+    [TestCase("\u0101\u0102\u0103\u0104\u0105", 5)]
+    [TestCase("\u0101\u0102\u0103\u0104\u0105", 10)]
+    public void TryGetStringSlice_Utf8_SingleSegment(string text, int charsLimit)
+    {
+        System.Text.Encoding encoding = System.Text.Encoding.UTF8;
+        string expected = charsLimit > text.Length ? text : text[..charsLimit];
+        var sequence = new ReadOnlySequence<byte>(encoding.GetBytes(text));
+
+        encoding.TryGetStringSlice(sequence, charsLimit, out var completed, out var result).Should().BeTrue();
+
+        result.Should().Be(expected);
+        completed.Should().Be(charsLimit >= text.Length);
+    }
+
+    [Test]
+    // 1-byte chars
+    [TestCase(new byte[] { 0x31 }, new byte[] { 0x32, 0x33, 0x34, 0x35 }, 1)]
+    [TestCase(new byte[] { 0x31, 0x32, 0x33 }, new byte[] { 0x34, 0x35 }, 5)]
+    [TestCase(new byte[] { 0x31, 0x32, 0x33 }, new byte[] { 0x34, 0x35 }, 10)]
+    // 2-bytes chars
+    [TestCase(new byte[] { 0xc4 }, new byte[] { 0x81 }, 1)]
+    [TestCase(new byte[] { 0xc4, 0x81, 0xc4, 0x82, 0xc4 }, new byte[] { 0x83, 0xc4, 0x84, 0xc4, 0x85 }, 3)]
+    [TestCase(new byte[] { 0xc4, 0x81, 0xc4, 0x82, 0xc4 }, new byte[] { 0x83, 0xc4, 0x84, 0xc4, 0x85 }, 5)]
+    [TestCase(new byte[] { 0xc4, 0x81, 0xc4, 0x82, 0xc4 }, new byte[] { 0x83, 0xc4, 0x84, 0xc4, 0x85 }, 10)]
+    public void TryGetStringSlice_Utf8_MultiSegment(byte[] segment1, byte[] segment2, int charsLimit)
+    {
+        System.Text.Encoding encoding = System.Text.Encoding.UTF8;
+        string text = encoding.GetString(segment1.Concat(segment2).ToArray());
+        string expected = charsLimit > text.Length ? text : text[..charsLimit];
+        ReadOnlySequence<byte> sequence = new ReadOnlySequenceBuilder<byte>()
+            .WithSegment(new ReadOnlySequence<byte>(segment1))
+            .WithSegment(new ReadOnlySequence<byte>(segment2))
+            .Build();
+
+        encoding.TryGetStringSlice(sequence, charsLimit, out var completed, out var result).Should().BeTrue();
+
+        result.Should().Be(expected);
+        completed.Should().Be(charsLimit >= text.Length);
+    }
+}

src/Nethermind/Nethermind.Core/Extensions/EncodingExtensions.cs

@@ -0,0 +1,77 @@
+// SPDX-FileCopyrightText: 2024 Demerzel Solutions Limited
+// SPDX-License-Identifier: LGPL-3.0-only
+
+using System;
+using System.Buffers;
+using System.Diagnostics.CodeAnalysis;
+using System.Text;
+
+namespace Nethermind.Core.Extensions;
+
+public static class EncodingExtensions
+{
+    private static string GetStringSlice(Encoding encoding, ReadOnlySpan<byte> span, Span<char> chars, out bool completed)
+    {
+        encoding.GetDecoder().Convert(span, chars, true, out _, out int charsUsed, out completed);
+        return new(chars[..charsUsed]);
+    }
+
+    private static string GetStringSliceMultiSegment(Encoding encoding, ref readonly ReadOnlySequence<byte> sequence, Span<char> chars, out bool completed)
+    {
+        try
+        {
+            var charsUsed = encoding.GetChars(sequence, chars);
+            completed = true;
+            return new(chars[..charsUsed]);
+        }
+        // Thrown when decoder detects that chars array is not enough to contain the result
+        // If this happens, whole array should already be filled
+        catch (ArgumentException exception) when (exception.ParamName == "chars")
+        {
+            completed = false;
+            return new(chars);
+        }
+    }
+
+    /// <summary>
+    /// Attempts to decode up to <paramref name="charCount"/> characters from byte <paramref name="sequence"/> using provided <paramref name="encoding"/>.
+    /// </summary>
+    /// <param name="charCount">Maximum number of characters to decode.</param>
+    /// <param name="encoding">Encoding to use.</param>
+    /// <param name="sequence">Bytes sequence.</param>
+    /// <param name="completed"><c>true</c> if the whole <paramref name="sequence"/> was decoded, <c>false</c> otherwise.</param>
+    /// <param name="result">Decoded string of up to <see cref="charCount"/> characters.</param>
+    /// <returns>
+    /// <c>true</c>, if successfully decoded whole string or the specified <paramref name="charCount"/>, <c>false</c> in case of an error.
+    /// </returns>
+    public static bool TryGetStringSlice(this Encoding encoding, in ReadOnlySequence<byte> sequence, int charCount,
+        out bool completed, [NotNullWhen(true)] out string? result)
+    {
+        char[] charArray = ArrayPool<char>.Shared.Rent(charCount);
+        Span<char> chars = charArray.AsSpan(0, charCount);
+
+        try
+        {
+            result = sequence.IsSingleSegment
+                ? GetStringSlice(encoding, sequence.FirstSpan, chars, out completed)
+                : GetStringSliceMultiSegment(encoding, in sequence, chars, out completed);
+
+            return true;
+        }
+        // Failed to parse, should only happen if bytes encoding is invalid
+        catch (Exception)
+        {
+            result = null;
+            completed = false;
+            return false;
+        }
+        finally
+        {
+            ArrayPool<char>.Shared.Return(charArray);
+        }
+    }
+
+    /// <inheritdoc cref="TryGetStringSlice(System.Text.Encoding,in System.Buffers.ReadOnlySequence{byte},int,out bool,out string?)"/>
+    public static bool TryGetStringSlice(this Encoding encoding, in ReadOnlySequence<byte> sequence, int charCount, [NotNullWhen(true)] out string? result) =>
+        TryGetStringSlice(encoding, in sequence, charCount, out _, out result);
+}

src/Nethermind/Nethermind.JsonRpc/JsonRpcProcessor.cs

@@ -5,10 +5,12 @@
 using System.Buffers;
 using System.Collections.Generic;
 using System.Diagnostics;
+using System.Diagnostics.CodeAnalysis;
 using System.IO;
 using System.IO.Abstractions;
 using System.IO.Pipelines;
 using System.Linq;
+using System.Text;
 using System.Text.Json;
 using System.Threading;
 using System.Threading.Tasks;
@@ -124,10 +126,29 @@ public async IAsyncEnumerable<JsonRpcResult> ProcessAsync(PipeReader reader, Jso
 
         // Handles general exceptions during parsing and validation.
         // Sends an error response and stops the stopwatch.
-        JsonRpcResult GetParsingError(string error, Exception? exception = null)
+        JsonRpcResult GetParsingError(ref readonly ReadOnlySequence<byte> buffer, string error, Exception? exception = null)
         {
             Metrics.JsonRpcRequestDeserializationFailures++;
-            if (_logger.IsError) _logger.Error(error, exception);
+
+            if (_logger.IsError)
+            {
+                _logger.Error(error, exception);
+            }
+
+            if (_logger.IsDebug)
+            {
+                // Attempt to get and log the request body from the bytes buffer if Debug logging is enabled
+                const int sliceSize = 1000;
+                if (Encoding.UTF8.TryGetStringSlice(in buffer, sliceSize, out bool isFullString, out string data))
+                {
+                    error = isFullString
+                        ? $"{error} Data:\n{data}\n"
+                        : $"{error} Data (first {sliceSize} chars):\n{data[..sliceSize]}\n";
+
+                    _logger.Debug(error);
+                }
+            }
+
             JsonRpcErrorResponse response = _jsonRpcService.GetErrorResponse(ErrorCodes.ParseError, "Incorrect message");
             TraceResult(response);
             return JsonRpcResult.Single(RecordResponse(response, new RpcReport("# parsing error #", (long)Stopwatch.GetElapsedTime(startTime).TotalMicroseconds, false)));
@@ -155,7 +176,7 @@ JsonRpcResult GetParsingError(string error, Exception? exception = null)
                     // Tries to parse the JSON from the buffer.
                     if (!TryParseJson(ref buffer, out jsonDocument))
                     {
-                        deserializationFailureResult = GetParsingError("Error during parsing/validation.");
+                        deserializationFailureResult = GetParsingError(in buffer, "Error during parsing/validation.");
                     }
                     else
                     {
@@ -178,7 +199,7 @@ JsonRpcResult GetParsingError(string error, Exception? exception = null)
                 }
                 catch (Exception ex)
                 {
-                    deserializationFailureResult = GetParsingError("Error during parsing/validation.", ex);
+                    deserializationFailureResult = GetParsingError(in buffer, "Error during parsing/validation.", ex);
                 }
 
                 // Checks for deserialization failure and yields the result.
@@ -251,7 +272,7 @@ JsonRpcResult GetParsingError(string error, Exception? exception = null)
             {
                 if (buffer.Length > 0 && HasNonWhitespace(buffer))
                 {
-                    yield return GetParsingError("Error during parsing/validation. Incomplete request");
+                    yield return GetParsingError(in buffer, "Error during parsing/validation: incomplete request.");
                 }
             }
         }
@@ -358,7 +379,7 @@ static bool HasNonWhitespace(ReadOnlySpan<byte> span)
         return result;
     }
 
-    private static bool TryParseJson(ref ReadOnlySequence<byte> buffer, out JsonDocument jsonDocument)
+    private static bool TryParseJson(ref ReadOnlySequence<byte> buffer, [NotNullWhen(true)] out JsonDocument? jsonDocument)
     {
         Utf8JsonReader reader = new(buffer);