Add more verbose logging

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.11</CredentialProviderVersion>
+    <CredentialProviderVersion>0.1.12</CredentialProviderVersion>
   </PropertyGroup>
 </Project>

CredentialProvider.Microsoft/CredentialProviders/VstsBuildTask/VstsBuildTaskCredentialProvider.cs

@@ -49,6 +49,8 @@ public override Task<GetAuthenticationCredentialsResponse> HandleRequestAsync(Ge
             string uriPrefixesString = Environment.GetEnvironmentVariable(EnvUtil.BuildTaskUriPrefixes);
             string accessToken = Environment.GetEnvironmentVariable(EnvUtil.BuildTaskAccessToken);
 
+            Verbose(string.Format(Resources.IsRetry, request.IsRetry));
+
             string[] uriPrefixes = uriPrefixesString.Split(new[] { ';' }, StringSplitOptions.RemoveEmptyEntries);
             Verbose(Resources.BuildTaskUriPrefixes);
             foreach (var uriPrefix in uriPrefixes)
@@ -58,7 +60,7 @@ public override Task<GetAuthenticationCredentialsResponse> HandleRequestAsync(Ge
 
             string uriString = request.Uri.ToString();
             string matchedPrefix = uriPrefixes.FirstOrDefault(prefix => uriString.StartsWith(prefix, StringComparison.OrdinalIgnoreCase));
-            Verbose(string.Format(Resources.BuildTaskMatchedPrefix, matchedPrefix));
+            Verbose(string.Format(Resources.BuildTaskMatchedPrefix, matchedPrefix != null  ? matchedPrefix : Resources.NoMatches));
 
             if (matchedPrefix == null)
             {
@@ -70,6 +72,7 @@ public override Task<GetAuthenticationCredentialsResponse> HandleRequestAsync(Ge
                     MessageResponseCode.Error);
             }
 
+            Verbose(string.Format(Resources.BuildTaskEndpointMatchingUrlFound, uriString));
             return this.GetResponse(
                     Username,
                     accessToken,

CredentialProvider.Microsoft/CredentialProviders/VstsBuildTaskServiceEndpoint/VstsBuildTaskServiceEndpointCredentialProvider.cs

@@ -65,6 +65,8 @@ public override Task<GetAuthenticationCredentialsResponse> HandleRequestAsync(Ge
         {
             cancellationToken.ThrowIfCancellationRequested();
 
+            Verbose(string.Format(Resources.IsRetry, request.IsRetry));
+
             string uriString = request.Uri.ToString();
             bool endpointFound = Credentials.TryGetValue(uriString, out EndpointCredentials matchingEndpoint);
             if (endpointFound)

CredentialProvider.Microsoft/RequestHandlers/RequestHandlerBase.cs

@@ -64,16 +64,19 @@ public async Task HandleResponseAsync(IConnection connection, Message message, I
                 }
                 catch (Exception ex) when (cancellationToken.IsCancellationRequested)
                 {
+                    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);
-
-                    Logger.Verbose(ex.ToString());
-
+
                     // 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));
                 // 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);
             }
@@ -87,6 +90,7 @@ bool LogExceptionAndReturnFalse(Exception ex)
                 // don't report cancellations during shutdown, they're most likely not interesting.
                 if (ex is OperationCanceledException && Program.IsShuttingDown && !Debugger.IsAttached)
                 {
+                    Logger.Verbose(Resources.ShuttingDown);
                     return false;
                 }
 

CredentialProvider.Microsoft/Resources.resx

@@ -230,7 +230,7 @@
     <value>Running in stand-alone mode</value>
   </data>
   <data name="SendingResponse" xml:space="preserve">
-    <value>Sending response: '{0}'</value>
+    <value>Sending response: '{0}' '{1}'</value>
   </data>
   <data name="SessionTokenCacheDisabled" xml:space="preserve">
     <value>SessionToken cache disabled by environment</value>
@@ -418,4 +418,16 @@ 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="NoMatches" xml:space="preserve">
+    <value>none</value>
+  </data>
+  <data name="RequestHandlerCancelingExceptionMessage" xml:space="preserve">
+    <value>Exception happened while handling request. Exception: {0}, Message: {1}</value>
+  </data>
+  <data name="ShuttingDown" xml:space="preserve">
+    <value>Credential provider shutting down.</value>
+  </data>
 </root>