From 959bdc7196ac09ab13368e0ed12031b6bd26eda0 Mon Sep 17 00:00:00 2001 From: Shyam Gupta Date: Thu, 15 Aug 2019 12:12:37 -0700 Subject: [PATCH 1/2] Added ETW events --- src/StreamJsonRpc/JsonRpc.cs | 87 +++++++++ src/StreamJsonRpc/JsonRpcEventSource.cs | 241 ++++++++++++++++++++++++ 2 files changed, 328 insertions(+) create mode 100644 src/StreamJsonRpc/JsonRpcEventSource.cs diff --git a/src/StreamJsonRpc/JsonRpc.cs b/src/StreamJsonRpc/JsonRpc.cs index 44e28f76..1393fafc 100644 --- a/src/StreamJsonRpc/JsonRpc.cs +++ b/src/StreamJsonRpc/JsonRpc.cs @@ -1108,12 +1108,25 @@ protected async Task InvokeCoreAsync(long? id, string targetNa { if (!request.IsResponseExpected) { + if (JsonRpcEventSource.Instance.IsEnabled()) + { + JsonRpcEventSource.Instance.SendNotificationStart($"Request Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + } + await this.TransmitAsync(request, cts.Token).ConfigureAwait(false); + + if (JsonRpcEventSource.Instance.IsEnabled()) + { + JsonRpcEventSource.Instance.SendNotificationStop($"Request Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + } + return default; } Verify.Operation(this.readLinesTask != null, Resources.InvalidBeforeListenHasStarted); var tcs = new TaskCompletionSource(); + string responseDetails = string.Empty; + Action dispatcher = (response) => { lock (this.dispatcherMapLock) @@ -1123,6 +1136,8 @@ protected async Task InvokeCoreAsync(long? id, string targetNa try { + responseDetails = string.Empty; + if (response == null) { if (this.TraceSource.Switch.ShouldTrace(TraceEventType.Warning)) @@ -1139,6 +1154,11 @@ protected async Task InvokeCoreAsync(long? id, string targetNa { tcs.TrySetException(new ConnectionLostException()); } + + if (JsonRpcEventSource.Instance.IsEnabled()) + { + responseDetails = $"Aborting pending request \"{id}\" because the connection was lost."; + } } else if (response is JsonRpcError error) { @@ -1150,10 +1170,25 @@ protected async Task InvokeCoreAsync(long? id, string targetNa { tcs.TrySetException(CreateExceptionFromRpcError(error, targetName)); } + + if (JsonRpcEventSource.Instance.IsEnabled()) + { + responseDetails = JsonRpcEventSource.GetErrorDetails(error); + } } else if (response is JsonRpcResult result) { tcs.TrySetResult(result.GetResult()); + + if (JsonRpcEventSource.Instance.IsEnabled()) + { + responseDetails = $"Success!"; + } + } + + if (JsonRpcEventSource.Instance.IsEnabled()) + { + JsonRpcEventSource.Instance.SendRequestStop($"ResponseDetails: {responseDetails}; RequestDetails: Id: \"{request.Id}\", Method: \"{request.Method}\""); } } catch (Exception ex) @@ -1170,6 +1205,11 @@ protected async Task InvokeCoreAsync(long? id, string targetNa try { + if (JsonRpcEventSource.Instance.IsEnabled()) + { + JsonRpcEventSource.Instance.SendRequestStart($"Request Id: \"{request.Id}\", Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + } + await this.TransmitAsync(request, cts.Token).ConfigureAwait(false); } catch @@ -1507,6 +1547,18 @@ private async ValueTask DispatchIncomingRequestAsync(JsonRpcRequ this.TraceSource.TraceEvent(TraceEventType.Information, (int)TraceEvents.LocalInvocation, "Invoking {0}", targetMethod); } + if (JsonRpcEventSource.Instance.IsEnabled()) + { + if (request.IsResponseExpected) + { + JsonRpcEventSource.Instance.InvokeMethodStart($"TargetMethod = {targetMethod}; RequestDetails: Id = \"{request.Id}\", Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + } + else + { + JsonRpcEventSource.Instance.InvokeNotificationStart($"TargetMethod = {targetMethod}; RequestDetails: Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + } + } + // Yield now so method invocation is async and we can proceed to handle other requests meanwhile. // IMPORTANT: This should be the first await in this async method, // and no other await should be between this one and actually invoking the target method. @@ -1522,6 +1574,18 @@ private async ValueTask DispatchIncomingRequestAsync(JsonRpcRequ if (!(result is Task resultingTask)) { + if (JsonRpcEventSource.Instance.IsEnabled()) + { + if (request.IsResponseExpected) + { + JsonRpcEventSource.Instance.InvokeMethodStop($"TargetMethod = {targetMethod}; Result: {result}; RequestDetails: Id = \"{request.Id}\", Method = \"{request.Method}\""); + } + else + { + JsonRpcEventSource.Instance.InvokeNotificationStop($"TargetMethod = {targetMethod}; Result: {result}; RequestDetails: Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + } + } + return new JsonRpcResult { Id = request.Id, @@ -1602,6 +1666,18 @@ private JsonRpcMessage HandleInvocationTaskResult(JsonRpcRequest request, Task t }; } + if (JsonRpcEventSource.Instance.IsEnabled()) + { + if (request.IsResponseExpected) + { + JsonRpcEventSource.Instance.InvokeMethodStop($"Result: Id = \"{request.Id}\", Method = \"{request.Method}\""); + } + else + { + JsonRpcEventSource.Instance.InvokeNotificationStop($"Result: Method = \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + } + } + return new JsonRpcResult { Id = request.Id, @@ -1934,7 +2010,18 @@ private void CancelPendingOutboundRequest(object state) { "id", state }, }, }; + + if (JsonRpcEventSource.Instance.IsEnabled()) + { + JsonRpcEventSource.Instance.CancelRequestStart($"Cancellation request: Id = \"{state}\", Method = \"{cancellationMessage.Method}\""); + } + await this.TransmitAsync(cancellationMessage, this.DisconnectedToken).ConfigureAwait(false); + + if (JsonRpcEventSource.Instance.IsEnabled()) + { + JsonRpcEventSource.Instance.CancelRequestStop($"Cancellation request: Id = \"{state}\", Method = \"{cancellationMessage.Method}\""); + } } }).Forget(); } diff --git a/src/StreamJsonRpc/JsonRpcEventSource.cs b/src/StreamJsonRpc/JsonRpcEventSource.cs new file mode 100644 index 00000000..7f7269e6 --- /dev/null +++ b/src/StreamJsonRpc/JsonRpcEventSource.cs @@ -0,0 +1,241 @@ +// 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 +{ + using System.Diagnostics.Tracing; + using System.Text; + using StreamJsonRpc.Protocol; + + [EventSource(Name = "Microsoft-VisualStudio-StreamJsonRpc")] + internal sealed class JsonRpcEventSource : EventSource + { + /// + /// The singleton instance used for logging ETW events. + /// + internal static readonly JsonRpcEventSource Instance = new JsonRpcEventSource(); + + /// + /// The event ID for the . + /// + private const int SendNotificationStartEvent = 1; + + /// + /// The event ID for the . + /// + private const int SendNotificationStopEvent = 2; + + /// + /// The event ID for the . + /// + private const int SendRequestStartEvent = 3; + + /// + /// The event ID for the . + /// + private const int SendRequestStopEvent = 4; + + /// + /// The event ID for the . + /// + private const int InvokeMethodStartEvent = 5; + + /// + /// The event ID for the . + /// + private const int InvokeMethodStopEvent = 6; + + /// + /// The event ID for the . + /// + private const int CancelRequestStartEvent = 7; + + /// + /// The event ID for the . + /// + private const int CancelRequestStopEvent = 8; + + /// + /// The event ID for the . + /// + private const int InvokeNotificationStartEvent = 9; + + /// + /// The event ID for the . + /// + private const int InvokeNotificationStopEvent = 10; + + /// + /// Send Notification start. + /// + /// Notification details. + [Event(SendNotificationStartEvent, Task = Tasks.SendNotification, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] + public void SendNotificationStart(string message) + { + this.WriteEvent(SendNotificationStartEvent, message); + } + + /// + /// Send Notification end. + /// + /// Notification details. + [Event(SendNotificationStopEvent, Task = Tasks.SendNotification, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] + public void SendNotificationStop(string message) + { + this.WriteEvent(SendNotificationStopEvent, message); + } + + /// + /// Send Request start. + /// + /// Request details. + [Event(SendRequestStartEvent, Task = Tasks.SendRequest, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] + public void SendRequestStart(string message) + { + this.WriteEvent(SendRequestStartEvent, message); + } + + /// + /// Send Request end. + /// + /// Request details. + [Event(SendRequestStopEvent, Task = Tasks.SendRequest, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] + public void SendRequestStop(string message) + { + this.WriteEvent(SendRequestStopEvent, message); + } + + /// + /// Invoke Method start. + /// + /// Request and method details. + [Event(InvokeMethodStartEvent, Task = Tasks.InvokeMethod, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] + public void InvokeMethodStart(string message) + { + this.WriteEvent(InvokeMethodStartEvent, message); + } + + /// + /// Invoke Method end. + /// + /// Request and method details. + [Event(InvokeMethodStopEvent, Task = Tasks.InvokeMethod, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] + public void InvokeMethodStop(string message) + { + this.WriteEvent(InvokeMethodStopEvent, message); + } + + /// + /// Cancel Request start. + /// + /// Cancellation message. + [Event(CancelRequestStartEvent, Task = Tasks.CancelRequest, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] + public void CancelRequestStart(string message) + { + this.WriteEvent(CancelRequestStartEvent, message); + } + + /// + /// Cancel Request end. + /// + /// Cancellation message. + [Event(CancelRequestStopEvent, Task = Tasks.CancelRequest, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] + public void CancelRequestStop(string message) + { + this.WriteEvent(CancelRequestStopEvent, message); + } + + /// + /// Invoke Notification. + /// + /// Details of the Notification. + [Event(InvokeNotificationStartEvent, Task = Tasks.InvokeNotification, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] + public void InvokeNotificationStart(string message) + { + this.WriteEvent(InvokeNotificationStartEvent, message); + } + + /// + /// Notification completed. + /// + /// Details of the Notification. + [Event(InvokeNotificationStopEvent, Task = Tasks.InvokeNotification, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] + public void InvokeNotificationStop(string message) + { + this.WriteEvent(InvokeNotificationStopEvent, message); + } + + /// + /// Creates a string representation of arguments of max 200 characters for logging. + /// + /// A single argument or an array of arguments. + /// String representation of first argument only. + internal static string GetArgumentsString(object arguments) + { + if (arguments == null) + { + return string.Empty; + } + + const int maxLength = 128; + + if (arguments is object[] args) + { + var stringBuilder = new StringBuilder(); + if (args != null && args.Length > 0) + { + for (int i = 0; i < args.Length; ++i) + { + stringBuilder.Append($"arg{i}: {args[i]}, "); + if (stringBuilder.Length > maxLength) + { + return $"{stringBuilder.ToString(0, maxLength)}...(truncated)"; + } + } + } + + return stringBuilder.ToString(); + } + else + { + string retVal = arguments.ToString(); + return (retVal.Length > maxLength) ? $"{retVal.Substring(0, maxLength)}...(truncated)" : retVal; + } + } + + internal static string GetErrorDetails(JsonRpcError error) + { + if (error == null) + { + return string.Empty; + } + + string errorDetails = "Error:"; + if (error.Id != null) + { + errorDetails += $" Id = \"{error.Id}\", "; + } + + if (error.Error != null) + { + errorDetails += $"Error.Code = \"{error.Error.Code}\", "; + } + + return errorDetails; + } + + /// + /// Names of constants in this class make up the middle term in the event name + /// E.g.: Microsoft-VisualStudio-StreamJsonRpc/InvokeMethod/Start. + /// + /// Name of this class is important for EventSource. + public static class Tasks + { + public const EventTask SendNotification = (EventTask)1; + public const EventTask SendRequest = (EventTask)2; + public const EventTask InvokeMethod = (EventTask)3; + public const EventTask CancelRequest = (EventTask)4; + public const EventTask InvokeNotification = (EventTask)5; + } + } +} From a0ba0d7f841cc107845832ad19f7f7fe20524214 Mon Sep 17 00:00:00 2001 From: Andrew Arnott Date: Fri, 16 Aug 2019 22:44:47 -0600 Subject: [PATCH 2/2] Revise ETWs so we capture data in columns By providing method names and args as separate parameters instead of a pre-formatted string, ETW recognizes it as distinct data, allowing us to filter and sort on it, etc. --- src/StreamJsonRpc/JsonRpc.cs | 132 ++++++------ src/StreamJsonRpc/JsonRpcEventSource.cs | 254 +++++++++++++++--------- 2 files changed, 227 insertions(+), 159 deletions(-) diff --git a/src/StreamJsonRpc/JsonRpc.cs b/src/StreamJsonRpc/JsonRpc.cs index 1393fafc..9d36625e 100644 --- a/src/StreamJsonRpc/JsonRpc.cs +++ b/src/StreamJsonRpc/JsonRpc.cs @@ -1108,18 +1108,13 @@ protected async Task InvokeCoreAsync(long? id, string targetNa { if (!request.IsResponseExpected) { - if (JsonRpcEventSource.Instance.IsEnabled()) + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Verbose, System.Diagnostics.Tracing.EventKeywords.None)) { - JsonRpcEventSource.Instance.SendNotificationStart($"Request Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + JsonRpcEventSource.Instance.SendingNotification(targetName, JsonRpcEventSource.GetArgumentsString(arguments)); } await this.TransmitAsync(request, cts.Token).ConfigureAwait(false); - if (JsonRpcEventSource.Instance.IsEnabled()) - { - JsonRpcEventSource.Instance.SendNotificationStop($"Request Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); - } - return default; } @@ -1136,8 +1131,6 @@ protected async Task InvokeCoreAsync(long? id, string targetNa try { - responseDetails = string.Empty; - if (response == null) { if (this.TraceSource.Switch.ShouldTrace(TraceEventType.Warning)) @@ -1145,6 +1138,11 @@ protected async Task InvokeCoreAsync(long? id, string targetNa this.TraceSource.TraceEvent(TraceEventType.Warning, (int)TraceEvents.RequestAbandonedByRemote, "Aborting pending request \"{0}\" because the connection was lost.", id); } + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None)) + { + JsonRpcEventSource.Instance.ReceivedNoResponse(id.Value); + } + if (cancellationToken.IsCancellationRequested) { // Consider lost connection to be result of task canceled and set state to canceled. @@ -1154,14 +1152,14 @@ protected async Task InvokeCoreAsync(long? id, string targetNa { tcs.TrySetException(new ConnectionLostException()); } - - if (JsonRpcEventSource.Instance.IsEnabled()) - { - responseDetails = $"Aborting pending request \"{id}\" because the connection was lost."; - } } else if (response is JsonRpcError error) { + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None)) + { + JsonRpcEventSource.Instance.ReceivedError(id.Value, error.Error.Code); + } + if (error.Error?.Code == JsonRpcErrorCode.RequestCanceled) { tcs.TrySetCanceled(cancellationToken.IsCancellationRequested ? cancellationToken : CancellationToken.None); @@ -1170,25 +1168,15 @@ protected async Task InvokeCoreAsync(long? id, string targetNa { tcs.TrySetException(CreateExceptionFromRpcError(error, targetName)); } - - if (JsonRpcEventSource.Instance.IsEnabled()) - { - responseDetails = JsonRpcEventSource.GetErrorDetails(error); - } } else if (response is JsonRpcResult result) { - tcs.TrySetResult(result.GetResult()); - - if (JsonRpcEventSource.Instance.IsEnabled()) + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None)) { - responseDetails = $"Success!"; + JsonRpcEventSource.Instance.ReceivedResult(id.Value); } - } - if (JsonRpcEventSource.Instance.IsEnabled()) - { - JsonRpcEventSource.Instance.SendRequestStop($"ResponseDetails: {responseDetails}; RequestDetails: Id: \"{request.Id}\", Method: \"{request.Method}\""); + tcs.TrySetResult(result.GetResult()); } } catch (Exception ex) @@ -1205,9 +1193,9 @@ protected async Task InvokeCoreAsync(long? id, string targetNa try { - if (JsonRpcEventSource.Instance.IsEnabled()) + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Verbose, System.Diagnostics.Tracing.EventKeywords.None)) { - JsonRpcEventSource.Instance.SendRequestStart($"Request Id: \"{request.Id}\", Method: \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + JsonRpcEventSource.Instance.SendingRequest(id.Value, targetName, JsonRpcEventSource.GetArgumentsString(arguments)); } await this.TransmitAsync(request, cts.Token).ConfigureAwait(false); @@ -1461,6 +1449,7 @@ private async ValueTask DispatchIncomingRequestAsync(JsonRpcRequ Requires.NotNull(request, nameof(request)); CancellationTokenSource localMethodCancellationSource = null; + long idAsLongIfPossible = request.Id is long id ? id : -1; try { TargetMethod targetMethod = null; @@ -1547,15 +1536,15 @@ private async ValueTask DispatchIncomingRequestAsync(JsonRpcRequ this.TraceSource.TraceEvent(TraceEventType.Information, (int)TraceEvents.LocalInvocation, "Invoking {0}", targetMethod); } - if (JsonRpcEventSource.Instance.IsEnabled()) + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Verbose, System.Diagnostics.Tracing.EventKeywords.None)) { if (request.IsResponseExpected) { - JsonRpcEventSource.Instance.InvokeMethodStart($"TargetMethod = {targetMethod}; RequestDetails: Id = \"{request.Id}\", Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + JsonRpcEventSource.Instance.ReceivedRequest(idAsLongIfPossible, request.Method, JsonRpcEventSource.GetArgumentsString(request.Arguments)); } else { - JsonRpcEventSource.Instance.InvokeNotificationStart($"TargetMethod = {targetMethod}; RequestDetails: Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + JsonRpcEventSource.Instance.ReceivedNotification(request.Method, JsonRpcEventSource.GetArgumentsString(request.Arguments)); } } @@ -1574,16 +1563,9 @@ private async ValueTask DispatchIncomingRequestAsync(JsonRpcRequ if (!(result is Task resultingTask)) { - if (JsonRpcEventSource.Instance.IsEnabled()) + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None)) { - if (request.IsResponseExpected) - { - JsonRpcEventSource.Instance.InvokeMethodStop($"TargetMethod = {targetMethod}; Result: {result}; RequestDetails: Id = \"{request.Id}\", Method = \"{request.Method}\""); - } - else - { - JsonRpcEventSource.Instance.InvokeNotificationStop($"TargetMethod = {targetMethod}; Result: {result}; RequestDetails: Method = \"{request.Method}\", Arguments = \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); - } + JsonRpcEventSource.Instance.SendingResult(idAsLongIfPossible); } return new JsonRpcResult @@ -1610,7 +1592,14 @@ private async ValueTask DispatchIncomingRequestAsync(JsonRpcRequ } catch (Exception ex) when (!this.IsFatalException(StripExceptionToInnerException(ex))) { - return this.CreateError(request, ex); + JsonRpcError error = this.CreateError(request, ex); + + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None)) + { + JsonRpcEventSource.Instance.SendingError(idAsLongIfPossible, error.Error.Code); + } + + return error; } finally { @@ -1637,6 +1626,7 @@ private JsonRpcMessage HandleInvocationTaskResult(JsonRpcRequest request, Task t throw new ArgumentException(Resources.TaskNotCompleted, nameof(t)); } + JsonRpcMessage result; if (t.IsFaulted) { var exception = StripExceptionToInnerException(t.Exception); @@ -1650,12 +1640,11 @@ private JsonRpcMessage HandleInvocationTaskResult(JsonRpcRequest request, Task t this.OnJsonRpcDisconnected(e); } - return this.CreateError(request, t.Exception); + result = this.CreateError(request, t.Exception); } - - if (t.IsCanceled) + else if (t.IsCanceled) { - return new JsonRpcError + result = new JsonRpcError { Id = request.Id, Error = new JsonRpcError.ErrorDetail @@ -1665,23 +1654,31 @@ private JsonRpcMessage HandleInvocationTaskResult(JsonRpcRequest request, Task t }, }; } + else + { + result = new JsonRpcResult + { + Id = request.Id, + }; + } - if (JsonRpcEventSource.Instance.IsEnabled()) + long idIfPossible = request.Id is long id ? id : -1; + if (result is JsonRpcError error) { - if (request.IsResponseExpected) + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Warning, System.Diagnostics.Tracing.EventKeywords.None)) { - JsonRpcEventSource.Instance.InvokeMethodStop($"Result: Id = \"{request.Id}\", Method = \"{request.Method}\""); + JsonRpcEventSource.Instance.SendingError(idIfPossible, error.Error.Code); } - else + } + else + { + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None)) { - JsonRpcEventSource.Instance.InvokeNotificationStop($"Result: Method = \"{request.Method}\", Arguments: \"{JsonRpcEventSource.GetArgumentsString(request.Arguments)}\""); + JsonRpcEventSource.Instance.SendingResult(idIfPossible); } } - return new JsonRpcResult - { - Id = request.Id, - }; + return result; } private JsonRpcMessage HandleInvocationTaskOfTResult(JsonRpcRequest request, Task t) @@ -1951,6 +1948,11 @@ private async Task HandleCancellationNotificationAsync(JsonRpcRequest request) this.TraceSource.TraceEvent(TraceEventType.Information, (int)TraceEvents.ReceivedCancellation, "Cancellation request received for \"{0}\".", id); } + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None)) + { + JsonRpcEventSource.Instance.ReceivedCancellationRequest(id is long v ? v : -1); + } + CancellationTokenSource cts; lock (this.dispatcherMapLock) { @@ -2011,17 +2013,12 @@ private void CancelPendingOutboundRequest(object state) }, }; - if (JsonRpcEventSource.Instance.IsEnabled()) + if (JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None)) { - JsonRpcEventSource.Instance.CancelRequestStart($"Cancellation request: Id = \"{state}\", Method = \"{cancellationMessage.Method}\""); + JsonRpcEventSource.Instance.SendingCancellationRequest(state is long v ? v : -1); } await this.TransmitAsync(cancellationMessage, this.DisconnectedToken).ConfigureAwait(false); - - if (JsonRpcEventSource.Instance.IsEnabled()) - { - JsonRpcEventSource.Instance.CancelRequestStop($"Cancellation request: Id = \"{state}\", Method = \"{cancellationMessage.Method}\""); - } } }).Forget(); } @@ -2079,7 +2076,18 @@ private async ValueTask TransmitAsync(JsonRpcMessage message, CancellationToken try { this.TraceMessageSent(message); + bool etwEnabled = JsonRpcEventSource.Instance.IsEnabled(System.Diagnostics.Tracing.EventLevel.Informational, System.Diagnostics.Tracing.EventKeywords.None); + if (etwEnabled) + { + JsonRpcEventSource.Instance.TransmissionQueued(); + } + await this.MessageHandler.WriteAsync(message, cancellationToken).ConfigureAwait(false); + + if (etwEnabled) + { + JsonRpcEventSource.Instance.TransmissionCompleted(); + } } catch (Exception exception) { diff --git a/src/StreamJsonRpc/JsonRpcEventSource.cs b/src/StreamJsonRpc/JsonRpcEventSource.cs index 7f7269e6..8250f251 100644 --- a/src/StreamJsonRpc/JsonRpcEventSource.cs +++ b/src/StreamJsonRpc/JsonRpcEventSource.cs @@ -3,166 +3,235 @@ namespace StreamJsonRpc { + using System.Collections.Generic; using System.Diagnostics.Tracing; using System.Text; using StreamJsonRpc.Protocol; - [EventSource(Name = "Microsoft-VisualStudio-StreamJsonRpc")] + /// + /// The ETW source for logging events for this library. + /// + /// + /// We use a fully-descriptive type name because the type name becomes the name + /// of the ETW Provider. + /// + [EventSource(Name = "StreamJsonRpc")] internal sealed class JsonRpcEventSource : EventSource { /// - /// The singleton instance used for logging ETW events. + /// The singleton instance of this event source. /// internal static readonly JsonRpcEventSource Instance = new JsonRpcEventSource(); /// - /// The event ID for the . + /// The event ID for the . /// - private const int SendNotificationStartEvent = 1; + private const int SendingNotificationEvent = 1; /// - /// The event ID for the . + /// The event ID for the . /// - private const int SendNotificationStopEvent = 2; + private const int SendingRequestEvent = 2; /// - /// The event ID for the . + /// The event ID for the . /// - private const int SendRequestStartEvent = 3; + private const int SendingCancellationRequestEvent = 3; /// - /// The event ID for the . + /// The event ID for the . /// - private const int SendRequestStopEvent = 4; + private const int ReceivedResultEvent = 4; /// - /// The event ID for the . + /// The event ID for the . /// - private const int InvokeMethodStartEvent = 5; + private const int ReceivedErrorEvent = 5; /// - /// The event ID for the . + /// The event ID for the . /// - private const int InvokeMethodStopEvent = 6; + private const int ReceivedNoResponseEvent = 6; /// - /// The event ID for the . + /// The event ID for the . /// - private const int CancelRequestStartEvent = 7; + private const int ReceivedNotificationEvent = 20; /// - /// The event ID for the . + /// The event ID for the . /// - private const int CancelRequestStopEvent = 8; + private const int ReceivedRequestEvent = 21; /// - /// The event ID for the . + /// The event ID for the . /// - private const int InvokeNotificationStartEvent = 9; + private const int ReceivedCancellationRequestEvent = 22; /// - /// The event ID for the . + /// The event ID for the . /// - private const int InvokeNotificationStopEvent = 10; + private const int SendingResultEvent = 23; /// - /// Send Notification start. + /// The event ID for the . /// - /// Notification details. - [Event(SendNotificationStartEvent, Task = Tasks.SendNotification, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] - public void SendNotificationStart(string message) + private const int SendingErrorEvent = 24; + + /// + /// The event ID for the . + /// + private const int TransmissionQueuedEvent = 30; + + /// + /// The event ID for the . + /// + private const int TransmissionCompletedEvent = 31; + + /// + /// Initializes a new instance of the class. + /// + /// + /// ETW wants to see no more than one instance of this class. + /// + private JsonRpcEventSource() { - this.WriteEvent(SendNotificationStartEvent, message); } /// - /// Send Notification end. + /// Signals the transmission of a notification. /// - /// Notification details. - [Event(SendNotificationStopEvent, Task = Tasks.SendNotification, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] - public void SendNotificationStop(string message) + /// The name of the method. + /// A snippet representing the arguments. + [Event(SendingNotificationEvent, Task = Tasks.Notification, Opcode = EventOpcode.Send, Level = EventLevel.Verbose)] + public void SendingNotification(string method, string args) { - this.WriteEvent(SendNotificationStopEvent, message); + this.WriteEvent(SendingNotificationEvent, method, args); } /// - /// Send Request start. + /// Signals the transmission of a request. /// - /// Request details. - [Event(SendRequestStartEvent, Task = Tasks.SendRequest, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] - public void SendRequestStart(string message) + /// The id of the request, if any. + /// The name of the method. + /// A snippet representing the arguments. + [Event(SendingRequestEvent, Task = Tasks.OutboundCall, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] + public void SendingRequest(long requestId, string method, string args) { - this.WriteEvent(SendRequestStartEvent, message); + this.WriteEvent(SendingRequestEvent, requestId, method, args); } /// - /// Send Request end. + /// Signals the receipt of a successful response. /// - /// Request details. - [Event(SendRequestStopEvent, Task = Tasks.SendRequest, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] - public void SendRequestStop(string message) + /// The ID of the request being responded to. + [Event(ReceivedResultEvent, Task = Tasks.OutboundCall, Opcode = EventOpcode.Stop, Tags = Tags.Success, Level = EventLevel.Informational)] + public void ReceivedResult(long requestId) { - this.WriteEvent(SendRequestStopEvent, message); + this.WriteEvent(ReceivedResultEvent, requestId); } /// - /// Invoke Method start. + /// Signals the receipt of a response. /// - /// Request and method details. - [Event(InvokeMethodStartEvent, Task = Tasks.InvokeMethod, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] - public void InvokeMethodStart(string message) + /// The ID of the request being responded to. + /// The on the error response. + [Event(ReceivedErrorEvent, Task = Tasks.OutboundCall, Opcode = EventOpcode.Stop, Message = "Request {0} failed with: {1}", Tags = Tags.Error, Level = EventLevel.Warning)] + public void ReceivedError(long requestId, JsonRpcErrorCode errorCode) { - this.WriteEvent(InvokeMethodStartEvent, message); + this.WriteEvent(ReceivedErrorEvent, requestId, (long)errorCode); } /// - /// Invoke Method end. + /// Signals that the connection dropped before a response to a request was received. /// - /// Request and method details. - [Event(InvokeMethodStopEvent, Task = Tasks.InvokeMethod, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] - public void InvokeMethodStop(string message) + /// The ID of the request that did not receive a response. + [Event(ReceivedNoResponseEvent, Task = Tasks.OutboundCall, Opcode = EventOpcode.Stop, Message = "Request {0} received no response.", Tags = Tags.Dropped, Level = EventLevel.Warning)] + public void ReceivedNoResponse(long requestId) { - this.WriteEvent(InvokeMethodStopEvent, message); + this.WriteEvent(ReceivedNoResponseEvent, requestId); } /// - /// Cancel Request start. + /// Signals that a previously transmitted request is being canceled. /// - /// Cancellation message. - [Event(CancelRequestStartEvent, Task = Tasks.CancelRequest, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] - public void CancelRequestStart(string message) + /// The ID of the request being canceled. + [Event(SendingCancellationRequestEvent, Task = Tasks.Cancellation, Opcode = EventOpcode.Send, Level = EventLevel.Informational)] + public void SendingCancellationRequest(long requestId) { - this.WriteEvent(CancelRequestStartEvent, message); + this.WriteEvent(SendingCancellationRequestEvent, requestId); } /// - /// Cancel Request end. + /// Signals the receipt of a notification. /// - /// Cancellation message. - [Event(CancelRequestStopEvent, Task = Tasks.CancelRequest, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] - public void CancelRequestStop(string message) + /// The name of the method. + /// A snippet representing the arguments. + [Event(ReceivedNotificationEvent, Task = Tasks.Notification, Opcode = EventOpcode.Receive, Level = EventLevel.Verbose)] + public void ReceivedNotification(string method, string args) { - this.WriteEvent(CancelRequestStopEvent, message); + this.WriteEvent(ReceivedNotificationEvent, method, args); } /// - /// Invoke Notification. + /// Signals the receipt of a request. /// - /// Details of the Notification. - [Event(InvokeNotificationStartEvent, Task = Tasks.InvokeNotification, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] - public void InvokeNotificationStart(string message) + /// The id of the request, if any. + /// The name of the method. + /// A snippet representing the arguments. + [Event(ReceivedRequestEvent, Task = Tasks.InboundCall, Opcode = EventOpcode.Start, Level = EventLevel.Verbose)] + public void ReceivedRequest(long requestId, string method, string args) { - this.WriteEvent(InvokeNotificationStartEvent, message); + this.WriteEvent(ReceivedRequestEvent, requestId, method, args); } /// - /// Notification completed. + /// Signals the transmission of a successful response. /// - /// Details of the Notification. - [Event(InvokeNotificationStopEvent, Task = Tasks.InvokeNotification, Opcode = EventOpcode.Stop, Level = EventLevel.Verbose)] - public void InvokeNotificationStop(string message) + /// The ID of the request being responded to. + [Event(SendingResultEvent, Task = Tasks.InboundCall, Opcode = EventOpcode.Stop, Tags = Tags.Success, Level = EventLevel.Informational)] + public void SendingResult(long requestId) { - this.WriteEvent(InvokeNotificationStopEvent, message); + this.WriteEvent(SendingResultEvent, requestId); + } + + /// + /// Signals the receipt of a response. + /// + /// The ID of the request being responded to. + /// The on the error response. + [Event(SendingErrorEvent, Task = Tasks.InboundCall, Opcode = EventOpcode.Stop, Message = "Request {0} failed with: {1}", Tags = Tags.Error, Level = EventLevel.Warning)] + public void SendingError(long requestId, JsonRpcErrorCode errorCode) + { + this.WriteEvent(SendingErrorEvent, requestId, (long)errorCode); + } + + /// + /// Signals that a previously transmitted request is being canceled. + /// + /// The ID of the request being canceled. + [Event(ReceivedCancellationRequestEvent, Task = Tasks.Cancellation, Opcode = EventOpcode.Receive, Level = EventLevel.Informational)] + public void ReceivedCancellationRequest(long requestId) + { + this.WriteEvent(ReceivedCancellationRequestEvent, requestId); + } + + /// + /// Signals that a message has been queued for transmission. + /// + [Event(TransmissionQueuedEvent, Task = Tasks.MessageTransmission, Opcode = EventOpcode.Start, Level = EventLevel.Informational)] + public void TransmissionQueued() + { + this.WriteEvent(TransmissionQueuedEvent); + } + + /// + /// Signals that a message has been transmitted. + /// + [Event(TransmissionCompletedEvent, Task = Tasks.MessageTransmission, Opcode = EventOpcode.Stop, Level = EventLevel.Informational)] + public void TransmissionCompleted() + { + this.WriteEvent(TransmissionCompletedEvent); } /// @@ -203,39 +272,30 @@ internal static string GetArgumentsString(object arguments) } } - internal static string GetErrorDetails(JsonRpcError error) + /// + /// Names of constants in this class make up the middle term in the event name + /// E.g.: StreamJsonRpc/InvokeMethod/Start. + /// + /// Name of this class is important for EventSource. + public static class Tasks { - if (error == null) - { - return string.Empty; - } - - string errorDetails = "Error:"; - if (error.Id != null) - { - errorDetails += $" Id = \"{error.Id}\", "; - } - - if (error.Error != null) - { - errorDetails += $"Error.Code = \"{error.Error.Code}\", "; - } - - return errorDetails; + public const EventTask OutboundCall = (EventTask)1; + public const EventTask InboundCall = (EventTask)2; + public const EventTask MessageTransmission = (EventTask)3; + public const EventTask Cancellation = (EventTask)4; + public const EventTask Notification = (EventTask)5; } /// /// Names of constants in this class make up the middle term in the event name - /// E.g.: Microsoft-VisualStudio-StreamJsonRpc/InvokeMethod/Start. + /// E.g.: StreamJsonRpc/InvokeMethod/Start. /// /// Name of this class is important for EventSource. - public static class Tasks + public static class Tags { - public const EventTask SendNotification = (EventTask)1; - public const EventTask SendRequest = (EventTask)2; - public const EventTask InvokeMethod = (EventTask)3; - public const EventTask CancelRequest = (EventTask)4; - public const EventTask InvokeNotification = (EventTask)5; + public const EventTags Success = (EventTags)0x1; + public const EventTags Error = (EventTags)0x2; + public const EventTags Dropped = (EventTags)0x4; } } }