Improve logging for OIDC flow, fix HTTP 500 (#10662)

Author: joelverhagen

src/NuGetGallery/Controllers/TokenApiController.cs

@@ -7,6 +7,8 @@
 using System.Net.Http.Headers;
 using System.Threading.Tasks;
 using System.Web.Mvc;
+using Microsoft.Build.Framework;
+using Microsoft.Extensions.Logging;
 using NuGetGallery.Authentication;
 using NuGetGallery.Services.Authentication;
 
@@ -32,13 +34,16 @@ public class TokenApiController : AppController
 
         private readonly IFederatedCredentialService _federatedCredentialService;
         private readonly IFederatedCredentialConfiguration _configuration;
+        private readonly ILogger<TokenApiController> _logger;
 
         public TokenApiController(
             IFederatedCredentialService federatedCredentialService,
-            IFederatedCredentialConfiguration configuration)
+            IFederatedCredentialConfiguration configuration,
+            ILogger<TokenApiController> logger)
         {
             _federatedCredentialService = federatedCredentialService ?? throw new ArgumentNullException(nameof(federatedCredentialService));
             _configuration = configuration ?? throw new ArgumentNullException(nameof(configuration));
+            _logger = logger;
         }
 
 #pragma warning disable CA3147 // No need to validate Antiforgery Token with API request
@@ -86,6 +91,15 @@ public async Task<ActionResult> CreateToken(CreateTokenRequest request)
 
             var result = await _federatedCredentialService.GenerateApiKeyAsync(request!.Username!, bearerToken!, Request.Headers);
 
+            if (result.Type == GenerateApiKeyResultType.Created)
+            {
+                _logger.LogInformation("Token creation request for user {Username} succeeded. API key expires at {Expiration:O}.", request.Username, result.Expires);
+            }
+            else
+            {
+                _logger.LogWarning("Token creation request for user {Username} failed with result type {ResultType}. User message: {UserMessage}", request.Username, result.Type, result.UserMessage);
+            }
+
             return result.Type switch
             {
                 GenerateApiKeyResultType.BadRequest => ErrorJson(HttpStatusCode.BadRequest, result.UserMessage),
@@ -119,7 +133,15 @@ private JsonResult ErrorJson(HttpStatusCode status, string errorMessage)
         {
             // Show the error message in the HTTP reason phrase (status description) for compatibility with NuGet client error "protocol".
             // This, and the response body below, could be formalized with https://github.com/NuGet/NuGetGallery/issues/5818
-            Response.StatusDescription = errorMessage;
+            try
+            {
+                Response.StatusDescription = errorMessage;
+            }
+            catch
+            {
+                // Best effort: setting StatusDescription can fail based on the content of the error message.
+                _logger.LogWarning("Failed to set StatusDescription to '{ErrorMessage}'", errorMessage);
+            }
 
             return Json(status, new { error = errorMessage });
         }

tests/NuGetGallery.Facts/Controllers/TokenApiControllerFacts.cs

@@ -18,6 +18,7 @@
 using NuGetGallery.Services.Authentication;
 using Xunit;
 using System.Text.Json;
+using Microsoft.Extensions.Logging;
 
 #nullable enable
 
@@ -266,6 +267,7 @@ public TokenApiControllerFacts()
             Identity = new Mock<IIdentity>();
             FederatedCredentialService = new Mock<IFederatedCredentialService>();
             Configuration = new Mock<IFederatedCredentialConfiguration>();
+            Logger = new Mock<ILogger<TokenApiController>>();
 
             RequestHeaders = new NameValueCollection();
             ResponseHeaders = new NameValueCollection();
@@ -287,7 +289,7 @@ public TokenApiControllerFacts()
                 .Setup(x => x.GenerateApiKeyAsync(CreateTokenRequest.Username, BearerToken, RequestHeaders))
                 .ReturnsAsync(() => GenerateApiKeyResult);
 
-            Target = new TokenApiController(FederatedCredentialService.Object, Configuration.Object);
+            Target = new TokenApiController(FederatedCredentialService.Object, Configuration.Object, Logger.Object);
 
             Target.SetOwinContextOverride(OwinContext.Object);
             Response.SetupProperty(x => x.StatusCode);
@@ -312,6 +314,7 @@ public TokenApiControllerFacts()
         public Mock<IIdentity> Identity { get; }
         public Mock<IFederatedCredentialService> FederatedCredentialService { get; }
         public Mock<IFederatedCredentialConfiguration> Configuration { get; }
+        public Mock<ILogger<TokenApiController>> Logger { get; }
         public NameValueCollection RequestHeaders { get; }
         public NameValueCollection ResponseHeaders { get; }
         public string BearerToken { get; }