Add stopwatch logging to request handler (#70)

Author: satbai

Build.props

@@ -1,6 +1,6 @@
 <?xml version="1.0" encoding="utf-8"?>
 <Project xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
   <PropertyGroup>
-    <CredentialProviderVersion>0.1.12</CredentialProviderVersion>
+    <CredentialProviderVersion>0.1.13</CredentialProviderVersion>
   </PropertyGroup>
 </Project>

CredentialProvider.Microsoft/RequestHandlers/RequestHandlerBase.cs

@@ -48,14 +48,17 @@ protected RequestHandlerBase(ILogger logger)
         /// <inheritdoc cref="IRequestHandler.HandleResponseAsync"/>
         public async Task HandleResponseAsync(IConnection connection, Message message, IResponseHandler responseHandler, CancellationToken cancellationToken)
         {
+            Stopwatch timer = new Stopwatch();
+            timer.Start();
+
             Connection = connection;
             CancellationToken = cancellationToken;
 
             TRequest request = MessageUtilities.DeserializePayload<TRequest>(message);
 
             try {
                 TResponse response = null;
-                Logger.Verbose(string.Format(Resources.HandlingRequest, message.Type, message.Method, message.Payload.ToString(Formatting.None)));
+                Logger.Verbose(string.Format(Resources.HandlingRequest, message.Type, message.Method, timer.ElapsedMilliseconds, message.Payload.ToString(Formatting.None)));
                 try {
                     using (GetProgressReporter(connection, message, cancellationToken))
                     {
@@ -64,21 +67,15 @@ public async Task HandleResponseAsync(IConnection connection, Message message, I
                 }
                 catch (Exception ex) when (cancellationToken.IsCancellationRequested)
                 {
+                    // NuGet will handle canceling event but verbose logs in this case might be interesting.
                     Logger.Verbose(string.Format(Resources.RequestHandlerCancelingExceptionMessage, ex.InnerException, ex.Message));
-                    Logger.Verbose(Resources.CancellationRequested);
-
-                    // We have been canceled by NuGet. Send a cancellation response.
-                    var cancelMessage = MessageUtilities.Create(message.RequestId, MessageType.Cancel, message.Method);
-                    await connection.SendAsync(cancelMessage, CancellationToken.None);
-                    
-                    // We must guarantee that exactly one terminating message is sent, so do not fall through to send
-                    // the normal response, but also do not rethrow.
                     return;
                 }
-
-                Logger.Verbose(string.Format(Resources.SendingResponse, message.Type, message.Method));
+                Logger.Verbose(string.Format(Resources.SendingResponse, message.Type, message.Method, timer.ElapsedMilliseconds));
                 // If we did not send a cancel message, we must submit the response even if cancellationToken is canceled.
                 await responseHandler.SendResponseAsync(message, response, CancellationToken.None).ConfigureAwait(continueOnCapturedContext: false);
+
+                Logger.Verbose(string.Format(Resources.TimeElapsedAfterSendingResponse, message.Type, message.Method, timer.ElapsedMilliseconds));
             }
             catch (Exception ex) when (LogExceptionAndReturnFalse(ex))
             {
@@ -100,6 +97,7 @@ bool LogExceptionAndReturnFalse(Exception ex)
             }
 
             CancellationToken = CancellationToken.None;
+            timer.Stop();
         }
 
         public abstract Task<TResponse> HandleRequestAsync(TRequest request);

CredentialProvider.Microsoft/Resources.Designer.cs

@@ -203,7 +203,7 @@
     <value>Handling auth request, Uri: {0}, IsRetry: {1}, IsNonInteractive: {2}, CanShowDialog: {3}</value>
   </data>
   <data name="HandlingRequest" xml:space="preserve">
-    <value>Handling '{0}' '{1}' - {2}</value>
+    <value>Handling '{0}' '{1}'. Time elapsed in ms: {2} - Payload: {3}</value>
   </data>
   <data name="InvalidatingCachedSessionToken" xml:space="preserve">
     <value>Invalidating SessionToken cache for {0}</value>
@@ -230,7 +230,7 @@
     <value>Running in stand-alone mode</value>
   </data>
   <data name="SendingResponse" xml:space="preserve">
-    <value>Sending response: '{0}' '{1}'</value>
+    <value>Sending response: '{0}' '{1}'. Time elapsed in ms: {2}</value>
   </data>
   <data name="SessionTokenCacheDisabled" xml:space="preserve">
     <value>SessionToken cache disabled by environment</value>
@@ -418,16 +418,19 @@ Device Flow Authentication Timeout
   <data name="CacheException" xml:space="preserve">
     <value>Exception happened when trying to get cached token. Invalidating cache. Message: {0}</value>
   </data>
-  <data name="CancellationRequested" xml:space="preserve">
-    <value>Cancellation requested. Sending cancellation response.</value>
-  </data>
   <data name="BuildTaskNoMatchingPrefixes" xml:space="preserve">
     <value>none</value>
   </data>
   <data name="RequestHandlerCancelingExceptionMessage" xml:space="preserve">
-    <value>Cancellation exception happened while handling request. Exception: {0}, Message: {1}</value>
+    <value>Ignoring a cancellation exception during request handling. Exception: {0}, Message: {1}</value>
   </data>
   <data name="ShuttingDown" xml:space="preserve">
     <value>Credential provider shutting down.</value>
   </data>
+  <data name="StartRequestHandlerStopwatch" xml:space="preserve">
+    <value>Starting stopwatch for {1} {2}</value>
+  </data>
+  <data name="TimeElapsedAfterSendingResponse" xml:space="preserve">
+    <value>Time elapsed in milliseconds after sending response '{0}' '{1}': {2}</value>
+  </data>
 </root>