[ODS-5985] Correlation IDs in the API error messages (#833)

* Added logic to populate log4net context with correlation id from either the query string ('correlationId') or a header ('correlation-id').

* Added specific CorrelationId Postman test coverage and a couple spot checks for other types of errors (pervasive correlation testing on error responses recommended).

* Added support for correlation ids in error response bodies.

* Remove CheckModelForNullAttribute, which appears to not be used. (May need to revert this after CI testing.)

* Added the lLogContextAccessor component to the controller constructors.

* Remove usage of obsolete filter.

* Fix compilation error in unit tests.

* Added missing DataMember attribute on the RESTError class, now used for all errors.

* Remove the correlationId from the query string before comparison with the response Location header.

* Remove the correlationId from the query string before comparison with the response Location header.

* Empty-commit

Application/EdFi.Ods.Api/Container/Modules/ApplicationModule.cs

@@ -38,6 +38,7 @@
 using EdFi.Ods.Common.Infrastructure.Extensibility;
 using EdFi.Ods.Common.Infrastructure.Pipelines;
 using EdFi.Ods.Common.IO;
+using EdFi.Ods.Common.Logging;
 using EdFi.Ods.Common.Models;
 using EdFi.Ods.Common.Models.Domain;
 using EdFi.Ods.Common.Models.Resource;
@@ -65,14 +66,18 @@ protected override void Load(ContainerBuilder builder)
         {
             RegisterMiddleware();
 
+            builder.RegisterType<Log4NetLogContextAccessor>()
+                .As<ILogContextAccessor>()
+                .SingleInstance();
+
             builder.RegisterType<ExceptionHandlingFilter>()
                 .As<IFilterMetadata>()
                 .SingleInstance();
 
             builder.RegisterType<DataManagementRequestContextFilter>()
                 .As<IFilterMetadata>()
                 .SingleInstance();
-            
+
             builder.RegisterType<EnforceAssignedProfileUsageFilter>()
                 .SingleInstance();
 
@@ -455,6 +460,11 @@ void RegisterPipeLineStepProviders()
 
             void RegisterMiddleware()
             {
+                builder.RegisterType<RequestCorrelationMiddleware>()
+                    .As<IMiddleware>()
+                    .AsSelf()
+                    .SingleInstance();
+
                 builder.RegisterType<RequestResponseDetailsLoggerMiddleware>()
                     .As<IMiddleware>()
                     .WithParameter(

Application/EdFi.Ods.Api/Controllers/DataManagementControllerBase.cs

@@ -23,6 +23,7 @@
 using EdFi.Ods.Common.Exceptions;
 using EdFi.Ods.Common.Infrastructure.Pipelines.Delete;
 using EdFi.Ods.Common.Infrastructure.Pipelines.GetMany;
+using EdFi.Ods.Common.Logging;
 using EdFi.Ods.Common.Models.Queries;
 using EdFi.Ods.Common.Profiles;
 using EdFi.Ods.Common.Utils.Profiles;
@@ -58,6 +59,7 @@ public abstract class DataManagementControllerBase<TResourceModel, TEntityInterf
 
         private readonly IRESTErrorProvider _restErrorProvider;
         private readonly IContextProvider<ProfileContentTypeContext> _profileContentTypeContextProvider;
+        private readonly ILogContextAccessor _logContextAccessor;
         private readonly int _defaultPageLimitSize;
         private readonly ReverseProxySettings _reverseProxySettings;
         private ILog _logger;
@@ -96,11 +98,12 @@ protected DataManagementControllerBase(
             IRESTErrorProvider restErrorProvider,
             IDefaultPageSizeLimitProvider defaultPageSizeLimitProvider,
             ApiSettings apiSettings,
-            IContextProvider<ProfileContentTypeContext> profileContentTypeContextProvider)
+            IContextProvider<ProfileContentTypeContext> profileContentTypeContextProvider,
+            ILogContextAccessor logContextAccessor)
         {
-            //this.repository = repository;
             _restErrorProvider = restErrorProvider;
             _profileContentTypeContextProvider = profileContentTypeContextProvider;
+            _logContextAccessor = logContextAccessor;
             _defaultPageLimitSize = defaultPageSizeLimitProvider.GetDefaultPageSizeLimit();
             _reverseProxySettings = apiSettings.GetReverseProxySettings();
 
@@ -142,11 +145,14 @@ private IActionResult CreateActionResultFromException(
                 // See RFC 5789 - Conflicting modification (with "If-Match" header)
                 restError.Code = StatusCodes.Status412PreconditionFailed;
                 restError.Message = "Resource was modified by another consumer.";
+                restError.CorrelationId = (string) _logContextAccessor.GetValue("CorrelationId");
             }
 
             return string.IsNullOrWhiteSpace(restError.Message)
-                ? (IActionResult) StatusCode(restError.Code)
-                : StatusCode(restError.Code, ErrorTranslator.GetErrorMessage(restError.Message));
+                ? (IActionResult)StatusCode(restError.Code ?? default)
+                : StatusCode(
+                    restError.Code ?? default,
+                    ErrorTranslator.GetErrorMessage(restError.Message, (string)_logContextAccessor.GetValue("CorrelationId")));
         }
 
         protected abstract void MapAll(TGetByExampleRequest request, TEntityInterface specification);
@@ -178,7 +184,8 @@ public virtual async Task<IActionResult> GetAll(
             {
                 return BadRequest(
                     ErrorTranslator.GetErrorMessage(
-                        $"Limit must be omitted or set to a value between 0 and { _defaultPageLimitSize }."));
+                        $"Limit must be omitted or set to a value between 0 and {_defaultPageLimitSize}.",
+                        (string)_logContextAccessor.GetValue("CorrelationId")));
             }
 
             var internalRequestAsResource = new TResourceModel();
@@ -245,7 +252,6 @@ public virtual async Task<IActionResult> Get(Guid id)
             return Ok(result.Resource);
         }
 
-        [CheckModelForNull]
         [HttpPut("{id}")]
         [ServiceFilter(typeof(EnforceAssignedProfileUsageFilter), IsReusable = true)]
         [ProducesResponseType(StatusCodes.Status201Created)]
@@ -296,7 +302,6 @@ public virtual async Task<IActionResult> Put([FromBody] TPutRequest request, Gui
             }
         }
 
-        [CheckModelForNull]
         [HttpPost]
         [ServiceFilter(typeof(EnforceAssignedProfileUsageFilter), IsReusable = true)]
         [ProducesResponseType(StatusCodes.Status200OK)]
@@ -311,7 +316,10 @@ public virtual async Task<IActionResult> Post([FromBody] TPostRequest request)
             // Make sure Id is not already set (no client-assigned Ids)
             if (request.Id != default(Guid))
             {
-                return BadRequest(ErrorTranslator.GetErrorMessage("Resource identifiers cannot be assigned by the client."));
+                return BadRequest(
+                    ErrorTranslator.GetErrorMessage(
+                        "Resource identifiers cannot be assigned by the client.",
+                        (string)_logContextAccessor.GetValue("CorrelationId")));
             }
 
             // Read the If-Match header and populate the resource DTO with an etag value.
@@ -348,7 +356,6 @@ public virtual async Task<IActionResult> Post([FromBody] TPostRequest request)
             }
         }
 
-        [CheckModelForNull]
         [HttpDelete("{id}")]
         [ProducesResponseType(StatusCodes.Status204NoContent)]
         [ProducesResponseType(StatusCodes.Status412PreconditionFailed)]

Application/EdFi.Ods.Api/ExceptionHandling/ErrorTranslator.cs

@@ -8,18 +8,23 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Security.Claims;
+using EdFi.Ods.Api.Models;
 using Microsoft.AspNetCore.Mvc.ModelBinding;
 
 namespace EdFi.Ods.Api.ExceptionHandling
 {
     public static class ErrorTranslator
     {
         // Attempts to translate the API error response to ASP.NET MVC error response format to maintain compatibility for the consumers. 
-        public static object GetErrorMessage(ModelStateDictionary modelState)
+        public static object GetErrorMessage(ModelStateDictionary modelState, string correlationId)
         {
             if (modelState.Keys.All(string.IsNullOrEmpty) && modelState.Values.Any())
             {
-                return new {Message = string.Join(",", modelState.Values.SelectMany(v => v.Errors.Select(e => e.ErrorMessage)))};
+                return new RESTError()
+                {
+                    Message = string.Join(",", modelState.Values.SelectMany(v => v.Errors.Select(e => e.ErrorMessage))),
+                    CorrelationId = correlationId
+                };
             }
 
             var modelStateMessage = modelState
@@ -28,16 +33,21 @@ public static object GetErrorMessage(ModelStateDictionary modelState)
                     kvp => kvp.Value.Errors.Select(e => e.ErrorMessage).ToArray()
                 );
 
-            return new
+            return new RESTError()
             {
                 Message = "The request is invalid.",
-                ModelState = modelStateMessage
+                ModelState = modelStateMessage,
+                CorrelationId = correlationId
             };
         }
 
-        public static object GetErrorMessage(string message)
+        public static object GetErrorMessage(string message, string correlationId)
         {
-            return new {Message = message};
+            return new RESTError()
+            {
+                Message = message,
+                CorrelationId = correlationId
+            };
         }
     }
 }

Application/EdFi.Ods.Api/ExceptionHandling/RESTErrorProvider.cs

@@ -7,6 +7,7 @@
 using System.Collections.Generic;
 using System.Net;
 using EdFi.Ods.Api.Models;
+using EdFi.Ods.Common.Logging;
 
 namespace EdFi.Ods.Api.ExceptionHandling
 {
@@ -17,11 +18,13 @@ public interface IRESTErrorProvider
 
     public class RESTErrorProvider : IRESTErrorProvider
     {
+        private readonly ILogContextAccessor _logContextAccessor;
         private readonly IEnumerable<IExceptionTranslator> _translators;
 
-        public RESTErrorProvider(IEnumerable<IExceptionTranslator> translators)
+        public RESTErrorProvider(IEnumerable<IExceptionTranslator> translators, ILogContextAccessor logContextAccessor)
         {
             _translators = translators;
+            _logContextAccessor = logContextAccessor;
         }
 
         public RESTError GetRestErrorFromException(Exception exception)
@@ -33,6 +36,9 @@ public RESTError GetRestErrorFromException(Exception exception)
 
                 if (translator.TryTranslateMessage(exception, out error))
                 {
+                    // Assign the correlation error (if it exists)
+                    error.CorrelationId = (string)_logContextAccessor.GetValue("CorrelationId");
+
                     return error;
                 }
             }
@@ -41,9 +47,10 @@ public RESTError GetRestErrorFromException(Exception exception)
             var response = new RESTError
             {
                 // This class translates into a serialized output that matches inBloom's approach to error handling.
-                Code = (int) HttpStatusCode.InternalServerError,
+                Code = (int)HttpStatusCode.InternalServerError,
                 Type = "Internal Server Error",
-                Message = "An unexpected error occurred on the server."
+                Message = "An unexpected error occurred on the server.",
+                CorrelationId = (string)_logContextAccessor.GetValue("CorrelationId")
             };
 
             return response;

Application/EdFi.Ods.Api/Extensions/ApplicationBuilderExtensions.cs

@@ -21,6 +21,9 @@ public static IApplicationBuilder UseOdsInstanceIdentification(this IApplication
         public static IApplicationBuilder UseTenantIdentification(this IApplicationBuilder builder)
             => builder.UseMiddleware<TenantIdentificationMiddleware>();
 
+        public static IApplicationBuilder UseRequestCorrelation(this IApplicationBuilder builder)
+            => builder.UseMiddleware<RequestCorrelationMiddleware>();
+
         /// <summary>
         /// Adds the <see cref="EdFiApiAuthenticationMiddleware"/> to the specified <see cref="IApplicationBuilder"/>, which enables authentication capabilities.
         /// </summary>

Application/EdFi.Ods.Api/Filters/EnforceAssignedProfileUsageFilter.cs

@@ -4,21 +4,20 @@
 // See the LICENSE and NOTICES files in the project root for more information.
 
 using System;
-using System.IO;
 using System.Linq;
-using System.Net.Mime;
 using System.Threading.Tasks;
+using EdFi.Ods.Api.Models;
 using EdFi.Ods.Common.Configuration;
 using EdFi.Ods.Common.Context;
+using EdFi.Ods.Common.Logging;
 using EdFi.Ods.Common.Models;
 using EdFi.Ods.Common.Profiles;
 using EdFi.Ods.Common.Security;
 using EdFi.Ods.Common.Security.Claims;
 using EdFi.Ods.Common.Utils.Profiles;
 using Microsoft.AspNetCore.Http;
+using Microsoft.AspNetCore.Mvc;
 using Microsoft.AspNetCore.Mvc.Filters;
-using Microsoft.Extensions.Primitives;
-using Newtonsoft.Json;
 
 namespace EdFi.Ods.Api.Filters;
 
@@ -27,6 +26,7 @@ public class EnforceAssignedProfileUsageFilter : IAsyncActionFilter
     private readonly IApiClientContextProvider _apiClientContextProvider;
     private readonly IContextProvider<DataManagementResourceContext> _dataManagementResourceContextProvider;
     private readonly IContextProvider<ProfileContentTypeContext> _profileContentTypeContextProvider;
+    private readonly ILogContextAccessor _logContextAccessor;
     private readonly IProfileResourceModelProvider _profileResourceModelProvider;
 
     private readonly bool _isEnabled;
@@ -36,11 +36,13 @@ public EnforceAssignedProfileUsageFilter(
         IProfileResourceModelProvider profileResourceModelProvider,
         IContextProvider<DataManagementResourceContext> dataManagementResourceContextProvider,
         IContextProvider<ProfileContentTypeContext> profileContentTypeContextProvider,
-        ApiSettings apiSettings)
+        ApiSettings apiSettings,
+        ILogContextAccessor logContextAccessor)
     {
         _apiClientContextProvider = apiClientContextProvider;
         _dataManagementResourceContextProvider = dataManagementResourceContextProvider;
         _profileContentTypeContextProvider = profileContentTypeContextProvider;
+        _logContextAccessor = logContextAccessor;
         _profileResourceModelProvider = profileResourceModelProvider;
 
         _isEnabled = apiSettings.IsFeatureEnabled("Profiles");
@@ -131,38 +133,34 @@ public async Task OnActionExecutionAsync(ActionExecutingContext context, ActionE
             // -------------------------------------------------------------------------------------------------------------------
 
             // If there's more than one possible Profile, the client is required to specify which one is in use.
-            await WriteForbiddenResponse();
+            SetForbiddenResponse();
 
             return;
         }
 
         // Ensure that the specified profile content type is using one of the assigned Profiles
         if (!assignedProfilesForRequest.Contains(profileContentTypeContext.ProfileName, StringComparer.OrdinalIgnoreCase))
         {
-            await WriteForbiddenResponse();
+            SetForbiddenResponse();
 
             return;
         }
 
         await next();
 
-        async Task WriteForbiddenResponse()
+        void SetForbiddenResponse()
         {
             string errorMessage = relevantContentTypeUsage == ContentTypeUsage.Readable
                 ? $"Based on profile assignments, one of the following profile-specific content types is required when requesting this resource: '{string.Join("', '", assignedProfilesForRequest.OrderBy(a => a).Select(p => ProfilesContentTypeHelper.CreateContentType(resourceFullName.Name, p, relevantContentTypeUsage)))}'"
                 : $"Based on profile assignments, one of the following profile-specific content types is required when updating this resource: '{string.Join("', '", assignedProfilesForRequest.OrderBy(a => a).Select(p => ProfilesContentTypeHelper.CreateContentType(resourceFullName.Name, p, relevantContentTypeUsage)))}'";
 
-            var response = context.HttpContext.Response;
-
-            response.StatusCode = StatusCodes.Status403Forbidden;
-            response.Headers.ContentType = new StringValues(MediaTypeNames.Application.Json);
-
-            await using (var sw = new StreamWriter(response.Body))
+            var error = new RESTError()
             {
-                string json = JsonConvert.SerializeObject(new { message = errorMessage });
-                response.Headers.ContentLength = json.Length;
-                await sw.WriteAsync(json);
-            }
+                Message = errorMessage,
+                CorrelationId = (string) _logContextAccessor.GetValue("CorrelationId")
+            };
+
+            context.Result = new ObjectResult(error) { StatusCode = StatusCodes.Status403Forbidden };
         }
     }
 }