Merge pull request #1040 from AArnott/fix1038

Fix ETW logging of named arguments in System.Text.Json formatter

azure-pipelines/dotnet.yml

@@ -17,13 +17,23 @@ steps:
     condition: and(succeeded(), ${{ parameters.RunTests }})
 
 - task: DotNetCoreCLI@2
-  displayName: 🧪 dotnet test -f net472 (+EventSource)
+  displayName: 🧪 dotnet test -f net472 (+EventSource throw)
   inputs:
     command: test
     arguments: --no-build -c $(BuildConfiguration) -f net472 --filter "TestCategory!=FailsInCloudTest$(FailsOnMonoFilter)" -v n /p:CollectCoverage=true /bl:"$(Build.ArtifactStagingDirectory)/build_logs/test_net472_etw.binlog" --diag "$(Build.ArtifactStagingDirectory)/test_logs/net472_etw.txt"
     testRunTitle: streamjsonrpc.tests-etw (net472, $(Agent.JobName))
   env:
-    StreamJsonRpc_TestWithEventSource: 1
+    StreamJsonRpc_TestWithEventSource: 1 # allow exceptions from EventSource to propagate
+  condition: and(succeeded(), ne(variables['OptProf'], 'true'), eq(variables['Agent.OS'], 'Windows_NT'))
+
+- task: DotNetCoreCLI@2
+  displayName: 🧪 dotnet test -f net472 (+EventSource production)
+  inputs:
+    command: test
+    arguments: --no-build -c $(BuildConfiguration) -f net472 --filter "TestCategory!=FailsInCloudTest$(FailsOnMonoFilter)" -v n /p:CollectCoverage=true /bl:"$(Build.ArtifactStagingDirectory)/build_logs/test_net472_etw.binlog" --diag "$(Build.ArtifactStagingDirectory)/test_logs/net472_etw.txt"
+    testRunTitle: streamjsonrpc.tests-etw (net472, $(Agent.JobName))
+  env:
+    StreamJsonRpc_TestWithEventSource: 2 # swallow exceptions from EventSource, as is done in production
   condition: and(succeeded(), ne(variables['OptProf'], 'true'), eq(variables['Agent.OS'], 'Windows_NT'))
 
 - ${{ if parameters.IsOptProf }}:

src/StreamJsonRpc/JsonRpcEventSource.cs

@@ -20,7 +20,7 @@ internal sealed class JsonRpcEventSource : EventSource
     /// <summary>
     /// The singleton instance of this event source.
     /// </summary>
-    internal static readonly JsonRpcEventSource Instance = new JsonRpcEventSource();
+    internal static readonly JsonRpcEventSource Instance = new();
 
     /// <summary>
     /// The event ID for the <see cref="SendingNotification"/>.
@@ -98,9 +98,9 @@ internal sealed class JsonRpcEventSource : EventSource
     private const int MessageHandlerReceivedEvent = 33;
 
     /// <summary>
-    /// A flag indicating whether to force tracing to be on.
+    /// Gets the testing mode that ETW tracing is running under.
     /// </summary>
-    private static readonly bool AlwaysOn = Environment.GetEnvironmentVariable("StreamJsonRpc_TestWithEventSource") == "1";
+    private static readonly SharedUtilities.EventSourceTestMode EventSourceTestingActive = SharedUtilities.GetEventSourceTestMode();
 
     /// <summary>
     /// Initializes a new instance of the <see cref="JsonRpcEventSource"/> class.
@@ -113,7 +113,7 @@ private JsonRpcEventSource()
     }
 
     /// <inheritdoc cref="EventSource.IsEnabled(EventLevel, EventKeywords)"/>
-    public new bool IsEnabled(EventLevel level, EventKeywords keywords) => AlwaysOn || base.IsEnabled(level, keywords);
+    public new bool IsEnabled(EventLevel level, EventKeywords keywords) => EventSourceTestingActive != SharedUtilities.EventSourceTestMode.None || base.IsEnabled(level, keywords);
 
     /// <summary>
     /// Signals the transmission of a notification.
@@ -301,7 +301,7 @@ internal static string GetArgumentsString(JsonRpcRequest request)
                         formatted = true;
                     }
                 }
-                catch
+                catch when (EventSourceTestingActive != SharedUtilities.EventSourceTestMode.DoNotSwallowExceptions)
                 {
                     // Swallow exceptions when deserializing args for ETW logging. It's never worth causing a functional failure.
                 }
@@ -339,7 +339,7 @@ internal static string GetArgumentsString(JsonRpcRequest request)
                         formatted = true;
                     }
                 }
-                catch
+                catch when (EventSourceTestingActive != SharedUtilities.EventSourceTestMode.DoNotSwallowExceptions)
                 {
                     // Swallow exceptions when deserializing args for ETW logging. It's never worth causing a functional failure.
                 }
@@ -368,9 +368,9 @@ static void Format(StringBuilder builder, object? value)
                     builder.Append("null");
                     break;
                 case string s:
-                    builder.Append("\"");
+                    builder.Append('"');
                     builder.Append(s);
-                    builder.Append("\"");
+                    builder.Append('"');
                     break;
                 default:
                     builder.Append(value);

src/StreamJsonRpc/SharedUtilities.cs

@@ -0,0 +1,38 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+
+namespace StreamJsonRpc;
+
+/// <summary>
+/// Utilities that are source-shared between the library and its tests.
+/// </summary>
+internal static class SharedUtilities
+{
+    /// <summary>
+    /// The various modes that can be used to test the <see cref="JsonRpcEventSource"/> class.
+    /// </summary>
+    internal enum EventSourceTestMode
+    {
+        /// <summary>
+        /// ETW events are not forced on.
+        /// </summary>
+        None,
+
+        /// <summary>
+        /// ETW events are forced on and exceptions are swallowed as they would be in production.
+        /// </summary>
+        EmulateProduction,
+
+        /// <summary>
+        /// ETW events are forced on and exceptions are not swallowed, allowing tests to detect errors in ETW logging.
+        /// </summary>
+        DoNotSwallowExceptions,
+    }
+
+    internal static EventSourceTestMode GetEventSourceTestMode() => Environment.GetEnvironmentVariable("StreamJsonRpc_TestWithEventSource") switch
+    {
+        "1" => EventSourceTestMode.EmulateProduction,
+        "2" => EventSourceTestMode.DoNotSwallowExceptions,
+        _ => EventSourceTestMode.None,
+    };
+}

src/StreamJsonRpc/SystemTextJsonFormatter.cs

@@ -469,6 +469,16 @@ internal JsonRpcRequest(SystemTextJsonFormatter formatter)
 
         public override int ArgumentCount => this.argumentCount ?? base.ArgumentCount;
 
+        public override IEnumerable<string>? ArgumentNames
+        {
+            get
+            {
+                return this.JsonArguments?.ValueKind is JsonValueKind.Object
+                    ? this.JsonArguments.Value.EnumerateObject().Select(p => p.Name)
+                    : null;
+            }
+        }
+
         internal JsonElement? JsonArguments
         {
             get => this.jsonArguments;
@@ -516,7 +526,7 @@ public override bool TryGetArgumentByNameOrIndex(string? name, int position, Typ
                     }
 
                     break;
-                case JsonValueKind.Array:
+                case JsonValueKind.Array when position >= 0:
                     int elementIndex = 0;
                     foreach (JsonElement arrayElement in this.JsonArguments.Value.EnumerateArray())
                     {
@@ -528,8 +538,6 @@ public override bool TryGetArgumentByNameOrIndex(string? name, int position, Typ
                     }
 
                     break;
-                default:
-                    throw new JsonException("Unexpected value kind for arguments: " + (this.JsonArguments?.ValueKind.ToString() ?? "null"));
             }
 
             try

test/StreamJsonRpc.Tests/JsonRpcMessagePackLengthTests.cs

@@ -372,9 +372,10 @@ public async Task UnionType_AsAsyncEnumerableTypeArgument()
     /// 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]
+    [SkippableTheory, PairwiseData]
     public async Task VerboseLoggingDoesNotFailWhenArgsDoNotDeserializePrimitively(bool namedArguments)
     {
+        Skip.IfNot(SharedUtilities.GetEventSourceTestMode() == SharedUtilities.EventSourceTestMode.EmulateProduction, $"This test specifically verifies behavior when the EventSource should swallow exceptions. Current mode: {SharedUtilities.GetEventSourceTestMode()}.");
         var server = new MessagePackServer();
         this.serverRpc.AllowModificationWhileListening = true;
         this.serverRpc.AddLocalRpcTarget(server);

test/StreamJsonRpc.Tests/StreamJsonRpc.Tests.csproj

@@ -8,6 +8,7 @@
 
   <ItemGroup>
     <Compile Include="..\..\src\StreamJsonRpc\DisposableAction.cs" Link="DisposableAction.cs" />
+    <Compile Include="..\..\src\StreamJsonRpc\SharedUtilities.cs" Link="SharedUtilities.cs" />
     <Compile Update="DisposableProxyJsonTests.cs" DependentUpon="DisposableProxyTests.cs" />
     <Compile Update="DisposableProxyMessagePackTests.cs" DependentUpon="DisposableProxyTests.cs" />
     <Compile Update="DisposableProxySystemTextJsonTests.cs" DependentUpon="DisposableProxyTests.cs" />