From 99bc35b2b66c68f15824e1fd59e0f9d928129ed1 Mon Sep 17 00:00:00 2001
From: Andrew Arnott <andrew.arnott@microsoft.com>
Date: Fri, 9 Sep 2022 09:10:20 -0600
Subject: [PATCH] Fix method dispatch failure when args fail to deserialize for
 ETW verbose logging

Fixes #841
---
 src/StreamJsonRpc/JsonRpcEventSource.cs       | 40 +++++++++----
 .../JsonRpcMessagePackLengthTests.cs          | 59 ++++++++++++++++++-
 2 files changed, 88 insertions(+), 11 deletions(-)

diff --git a/src/StreamJsonRpc/JsonRpcEventSource.cs b/src/StreamJsonRpc/JsonRpcEventSource.cs
index 5cfc89de..92358a0d 100644
--- a/src/StreamJsonRpc/JsonRpcEventSource.cs
+++ b/src/StreamJsonRpc/JsonRpcEventSource.cs
@@ -292,12 +292,22 @@ internal static string GetArgumentsString(JsonRpcRequest request)
                 stringBuilder.Append('[');
                 for (int i = 0; i < request.ArgumentCount; ++i)
                 {
-                    if (request.TryGetArgumentByNameOrIndex(null, i, null, out object? value))
+                    bool formatted = false;
+                    try
                     {
-                        Format(stringBuilder, value);
-                        stringBuilder.Append(", ");
+                        if (request.TryGetArgumentByNameOrIndex(null, i, null, out object? value))
+                        {
+                            Format(stringBuilder, value);
+                            stringBuilder.Append(", ");
+                            formatted = true;
+                        }
                     }
-                    else
+                    catch
+                    {
+                        // Swallow exceptions when deserializing args for ETW logging. It's never worth causing a functional failure.
+                    }
+
+                    if (!formatted)
                     {
                         stringBuilder.Append("<unformattable>");
                     }
@@ -318,14 +328,24 @@ internal static string GetArgumentsString(JsonRpcRequest request)
                 stringBuilder.Append('{');
                 foreach (string key in request.ArgumentNames)
                 {
-                    if (request.TryGetArgumentByNameOrIndex(key, -1, null, out object? value))
+                    bool formatted = false;
+                    try
                     {
-                        stringBuilder.Append(key);
-                        stringBuilder.Append(": ");
-                        Format(stringBuilder, value);
-                        stringBuilder.Append(", ");
+                        if (request.TryGetArgumentByNameOrIndex(key, -1, null, out object? value))
+                        {
+                            stringBuilder.Append(key);
+                            stringBuilder.Append(": ");
+                            Format(stringBuilder, value);
+                            stringBuilder.Append(", ");
+                            formatted = true;
+                        }
                     }
-                    else
+                    catch
+                    {
+                        // Swallow exceptions when deserializing args for ETW logging. It's never worth causing a functional failure.
+                    }
+
+                    if (!formatted)
                     {
                         stringBuilder.Append("<unformattable>");
                     }
diff --git a/test/StreamJsonRpc.Tests/JsonRpcMessagePackLengthTests.cs b/test/StreamJsonRpc.Tests/JsonRpcMessagePackLengthTests.cs
index d97d8bab..5e8f2d04 100644
--- a/test/StreamJsonRpc.Tests/JsonRpcMessagePackLengthTests.cs
+++ b/test/StreamJsonRpc.Tests/JsonRpcMessagePackLengthTests.cs
@@ -35,6 +35,8 @@ internal interface IMessagePackServer
         Task ProgressUnionType(IProgress<UnionBaseClass> progress, CancellationToken cancellationToken);
 
         IAsyncEnumerable<UnionBaseClass> GetAsyncEnumerableOfUnionType(CancellationToken cancellationToken);
+
+        Task<bool> IsExtensionArgNonNull(CustomExtensionType extensionValue);
     }
 
     [Fact]
@@ -369,6 +371,25 @@ public async Task UnionType_AsAsyncEnumerableTypeArgument()
         Assert.IsType<UnionDerivedClass>(actualItem);
     }
 
+    /// <summary>
+    /// Verifies that an argument that cannot be deserialized by the msgpack primitive formatter will not cause a failure.
+    /// </summary>
+    /// <remarks>
+    /// <para>This is a regression test for <see href="https://github.com/microsoft/vs-streamjsonrpc/issues/841">a bug</see> where
+    /// verbose ETW tracing would fail to deserialize arguments with the primitive formatter that deserialize just fine for the actual method dispatch.</para>
+    /// <para>This test is effective because custom msgpack extensions cause the <see cref="PrimitiveObjectFormatter"/> to throw an exception when deserializing.</para>
+    /// </remarks>
+    [Theory, PairwiseData]
+    public async Task VerboseLoggingDoesNotFailWhenArgsDoNotDeserializePrimitively(bool namedArguments)
+    {
+        var server = new MessagePackServer();
+        this.serverRpc.AllowModificationWhileListening = true;
+        this.serverRpc.AddLocalRpcTarget(server);
+        var clientProxy = this.clientRpc.Attach<IMessagePackServer>(new JsonRpcProxyOptions { ServerRequiresNamedArguments = namedArguments });
+
+        Assert.True(await clientProxy.IsExtensionArgNonNull(new CustomExtensionType()));
+    }
+
     protected override void InitializeFormattersAndHandlers(bool controlledFlushingClient)
     {
         this.serverMessageFormatter = new MessagePackFormatter();
@@ -376,7 +397,7 @@ protected override void InitializeFormattersAndHandlers(bool controlledFlushingC
 
         var options = MessagePackFormatter.DefaultUserDataSerializationOptions
             .WithResolver(CompositeResolver.Create(
-                new IMessagePackFormatter[] { new UnserializableTypeFormatter(), new TypeThrowsWhenDeserializedFormatter() },
+                new IMessagePackFormatter[] { new UnserializableTypeFormatter(), new TypeThrowsWhenDeserializedFormatter(), new CustomExtensionFormatter() },
                 new IFormatterResolver[] { StandardResolverAllowPrivate.Instance }));
         ((MessagePackFormatter)this.serverMessageFormatter).SetMessagePackSerializerOptions(options);
         ((MessagePackFormatter)this.clientMessageFormatter).SetMessagePackSerializerOptions(options);
@@ -398,6 +419,40 @@ public class UnionDerivedClass : UnionBaseClass
     {
     }
 
+    internal class CustomExtensionType
+    {
+    }
+
+    private class CustomExtensionFormatter : IMessagePackFormatter<CustomExtensionType?>
+    {
+        public CustomExtensionType? Deserialize(ref MessagePackReader reader, MessagePackSerializerOptions options)
+        {
+            if (reader.TryReadNil())
+            {
+                return null;
+            }
+
+            if (reader.ReadExtensionFormat() is { Header: { TypeCode: 1, Length: 0 } })
+            {
+                return new();
+            }
+
+            throw new Exception("Unexpected extension header.");
+        }
+
+        public void Serialize(ref MessagePackWriter writer, CustomExtensionType? value, MessagePackSerializerOptions options)
+        {
+            if (value is null)
+            {
+                writer.WriteNil();
+            }
+            else
+            {
+                writer.WriteExtensionFormat(new ExtensionResult(1, default(Memory<byte>)));
+            }
+        }
+    }
+
     private class UnserializableTypeFormatter : IMessagePackFormatter<CustomSerializedType>
     {
         public CustomSerializedType Deserialize(ref MessagePackReader reader, MessagePackSerializerOptions options)
@@ -454,6 +509,8 @@ public async IAsyncEnumerable<UnionBaseClass> GetAsyncEnumerableOfUnionType([Enu
             await Task.Yield();
             yield return new UnionDerivedClass();
         }
+
+        public Task<bool> IsExtensionArgNonNull(CustomExtensionType extensionValue) => Task.FromResult(extensionValue is not null);
     }
 
     private class DelayedFlushingHandler : LengthHeaderMessageHandler, IControlledFlushHandler