Fix method dispatch failure when args fail to deserialize for ETW ver…

…bose logging Fixes microsoft#841
AArnott · Sep 9, 2022 · 9f5945f · 9f5945f
1 parent 39a0710
commit 9f5945f
Show file tree

Hide file tree

Showing 2 changed files with 89 additions and 12 deletions.
diff --git a/src/StreamJsonRpc/JsonRpcEventSource.cs b/src/StreamJsonRpc/JsonRpcEventSource.cs
@@ -100,7 +100,7 @@ internal sealed class JsonRpcEventSource : EventSource
     /// <summary>
     /// A flag indicating whether to force tracing to be on.
     /// </summary>
-    private static readonly bool AlwaysOn = Environment.GetEnvironmentVariable("StreamJsonRpc_TestWithEventSource") == "1";
+    private static readonly bool AlwaysOn = true || Environment.GetEnvironmentVariable("StreamJsonRpc_TestWithEventSource") == "1";
 
     /// <summary>
     /// Initializes a new instance of the <see cref="JsonRpcEventSource"/> class.
@@ -291,12 +291,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>");
                 }
@@ -317,14 +327,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
@@ -29,6 +29,8 @@ internal interface IMessagePackServer
         Task ProgressUnionType(IProgress<UnionBaseClass> progress, CancellationToken cancellationToken);
 
         IAsyncEnumerable<UnionBaseClass> GetAsyncEnumerableOfUnionType(CancellationToken cancellationToken);
+
+        Task<bool> IsExtensionArgNonNull(CustomExtensionType extensionValue);
     }
 
     [Fact]
@@ -363,14 +365,33 @@ 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();
         this.clientMessageFormatter = new MessagePackFormatter();
 
         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);
@@ -392,6 +413,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)
@@ -448,6 +503,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