From 68b188e6e276be1ea1ca1cea2c0ed24ffca7fb9b Mon Sep 17 00:00:00 2001 From: Robert Johnson Date: Fri, 24 Oct 2025 08:05:41 -0700 Subject: [PATCH 1/5] Add logging and fix error message --- .../ActionResults/OperationOutcomeResult.cs | 0 .../Routing/SearchPostReroutingMiddleware.cs | 34 +++++++++++++++++-- .../Exceptions/BaseExceptionMiddleware.cs | 2 ++ ...Microsoft.Health.Fhir.Shared.Api.projitems | 1 - 4 files changed, 34 insertions(+), 3 deletions(-) rename src/{Microsoft.Health.Fhir.Shared.Api => Microsoft.Health.Fhir.Api}/Features/ActionResults/OperationOutcomeResult.cs (100%) diff --git a/src/Microsoft.Health.Fhir.Shared.Api/Features/ActionResults/OperationOutcomeResult.cs b/src/Microsoft.Health.Fhir.Api/Features/ActionResults/OperationOutcomeResult.cs similarity index 100% rename from src/Microsoft.Health.Fhir.Shared.Api/Features/ActionResults/OperationOutcomeResult.cs rename to src/Microsoft.Health.Fhir.Api/Features/ActionResults/OperationOutcomeResult.cs diff --git a/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs b/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs index e639fa1ee4..824a51743b 100644 --- a/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs +++ b/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs @@ -3,6 +3,7 @@ // Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. // ------------------------------------------------------------------------------------------------- +using System; using System.Collections.Generic; using System.Collections.Specialized; using System.Linq; @@ -10,8 +11,12 @@ using System.Threading.Tasks; using System.Web; using EnsureThat; +using Hl7.Fhir.Model; using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Primitives; +using Microsoft.Health.Fhir.Api.Features.ActionResults; +using Microsoft.Health.Fhir.Core.Extensions; using Microsoft.Health.Fhir.Core.Features.Routing; namespace Microsoft.Health.Fhir.Api.Features.Routing @@ -19,11 +24,13 @@ namespace Microsoft.Health.Fhir.Api.Features.Routing public class SearchPostReroutingMiddleware { private readonly RequestDelegate _next; + private readonly ILogger _logger; - public SearchPostReroutingMiddleware(RequestDelegate next) + public SearchPostReroutingMiddleware(RequestDelegate next, ILogger logger) { EnsureArg.IsNotNull(next); _next = next; + _logger = logger; } public async Task Invoke(HttpContext context) @@ -36,6 +43,8 @@ public async Task Invoke(HttpContext context) { if (request.ContentType is null || request.HasFormContentType) { + _logger.LogInformation("Rerouting POST {Path} to GET with query parameters from form body.", request.Path); + if (request.HasFormContentType) { var mergedPairs = GetUniqueFormAndQueryStringKeyValues(HttpUtility.ParseQueryString(request.QueryString.ToString()), request.Form); @@ -49,9 +58,30 @@ public async Task Invoke(HttpContext context) } else { + _logger.LogWarning("Rejecting POST {Path} with invalid Content-Type.", request.Path); + context.Response.Clear(); context.Response.StatusCode = (int)HttpStatusCode.BadRequest; - await context.Response.WriteAsync(Api.Resources.ContentTypeFormUrlEncodedExpected); + + var operationOutcome = new OperationOutcome + { + Id = Guid.NewGuid().ToString(), + Issue = new List() + { + new OperationOutcome.IssueComponent() + { + Severity = OperationOutcome.IssueSeverity.Error, + Code = OperationOutcome.IssueType.Invalid, + Diagnostics = Api.Resources.ContentTypeFormUrlEncodedExpected, + }, + }, + Meta = new Meta() + { + LastUpdated = Clock.UtcNow, + }, + }; + + await context.Response.WriteAsJsonAsync(operationOutcome); return; } } diff --git a/src/Microsoft.Health.Fhir.Shared.Api/Features/Exceptions/BaseExceptionMiddleware.cs b/src/Microsoft.Health.Fhir.Shared.Api/Features/Exceptions/BaseExceptionMiddleware.cs index 6d53abc136..aed4b83555 100644 --- a/src/Microsoft.Health.Fhir.Shared.Api/Features/Exceptions/BaseExceptionMiddleware.cs +++ b/src/Microsoft.Health.Fhir.Shared.Api/Features/Exceptions/BaseExceptionMiddleware.cs @@ -114,6 +114,8 @@ public async Task Invoke(HttpContext context) doesOperationOutcomeHaveError = true; + _logger.LogError(exception, "An unhandled exception occurred while processing the request"); + await ExecuteResultAsync(context, result); } finally diff --git a/src/Microsoft.Health.Fhir.Shared.Api/Microsoft.Health.Fhir.Shared.Api.projitems b/src/Microsoft.Health.Fhir.Shared.Api/Microsoft.Health.Fhir.Shared.Api.projitems index 000d1f841a..3e4fcd81b9 100644 --- a/src/Microsoft.Health.Fhir.Shared.Api/Microsoft.Health.Fhir.Shared.Api.projitems +++ b/src/Microsoft.Health.Fhir.Shared.Api/Microsoft.Health.Fhir.Shared.Api.projitems @@ -28,7 +28,6 @@ - From 583f6b1a5c484afacd4af352c6dece51f700619a Mon Sep 17 00:00:00 2001 From: Robert Johnson Date: Fri, 24 Oct 2025 10:16:45 -0700 Subject: [PATCH 2/5] Add try/catch --- .../Routing/SearchPostReroutingMiddleware.cs | 70 +++++++++++-------- .../Storage/SqlRetry/SqlRetryService.cs | 8 +-- 2 files changed, 43 insertions(+), 35 deletions(-) diff --git a/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs b/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs index 824a51743b..ba38b3155d 100644 --- a/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs +++ b/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs @@ -37,36 +37,38 @@ public async Task Invoke(HttpContext context) { var request = context.Request; - if (request != null - && request.Method == "POST" - && request.Path.Value.EndsWith(KnownRoutes.Search, System.StringComparison.OrdinalIgnoreCase)) + try { - if (request.ContentType is null || request.HasFormContentType) + if (request != null + && request.Method == "POST" + && request.Path.Value.EndsWith(KnownRoutes.Search, System.StringComparison.OrdinalIgnoreCase)) { - _logger.LogInformation("Rerouting POST {Path} to GET with query parameters from form body.", request.Path); - - if (request.HasFormContentType) + if (request.ContentType is null || request.HasFormContentType) { - var mergedPairs = GetUniqueFormAndQueryStringKeyValues(HttpUtility.ParseQueryString(request.QueryString.ToString()), request.Form); - request.Query = mergedPairs; - } + _logger.LogInformation("Rerouting POST {Path} to GET with query parameters from form body.", request.Path); - request.ContentType = null; - request.Form = null; - request.Path = request.Path.Value.Substring(0, request.Path.Value.Length - KnownRoutes.Search.Length); - request.Method = "GET"; - } - else - { - _logger.LogWarning("Rejecting POST {Path} with invalid Content-Type.", request.Path); + if (request.HasFormContentType) + { + var mergedPairs = GetUniqueFormAndQueryStringKeyValues(HttpUtility.ParseQueryString(request.QueryString.ToString()), request.Form); + request.Query = mergedPairs; + } + + request.ContentType = null; + request.Form = null; + request.Path = request.Path.Value.Substring(0, request.Path.Value.Length - KnownRoutes.Search.Length); + request.Method = "GET"; + } + else + { + _logger.LogDebug("Rejecting POST {Path} with invalid Content-Type.", request.Path); - context.Response.Clear(); - context.Response.StatusCode = (int)HttpStatusCode.BadRequest; + context.Response.Clear(); + context.Response.StatusCode = (int)HttpStatusCode.BadRequest; - var operationOutcome = new OperationOutcome - { - Id = Guid.NewGuid().ToString(), - Issue = new List() + var operationOutcome = new OperationOutcome + { + Id = Guid.NewGuid().ToString(), + Issue = new List() { new OperationOutcome.IssueComponent() { @@ -75,16 +77,22 @@ public async Task Invoke(HttpContext context) Diagnostics = Api.Resources.ContentTypeFormUrlEncodedExpected, }, }, - Meta = new Meta() - { - LastUpdated = Clock.UtcNow, - }, - }; + Meta = new Meta() + { + LastUpdated = Clock.UtcNow, + }, + }; - await context.Response.WriteAsJsonAsync(operationOutcome); - return; + await context.Response.WriteAsJsonAsync(operationOutcome); + return; + } } } + catch (Exception ex) + { + _logger.LogError(ex, "Error occurred while rerouting POST search to GET."); + throw; + } await _next.Invoke(context); } diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlRetry/SqlRetryService.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlRetry/SqlRetryService.cs index 6094e53677..701199d833 100644 --- a/src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlRetry/SqlRetryService.cs +++ b/src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlRetry/SqlRetryService.cs @@ -422,19 +422,19 @@ public async Task GetConnection(ISqlConnectionBuilder sqlConnecti { SqlConnection conn; var sw = Stopwatch.StartNew(); - var logSB = new StringBuilder("Long running retrieve SQL connection"); + var logSB = new StringBuilder("Long running retrieve SQL connection. "); var isReadOnlyConnection = isReadOnly ? "read-only " : string.Empty; if (!isReadOnly || !_coreFeatureConfiguration.SupportsSqlReplicas) { - logSB.AppendLine("Not read only"); + logSB.AppendLine("Not read only. "); conn = await sqlConnectionBuilder.GetSqlConnectionAsync(false, applicationName); } else { - logSB.AppendLine("Checking read only"); + logSB.AppendLine("Checking read only. "); var replicaTrafficRatio = GetReplicaTrafficRatio(sqlConnectionBuilder, logger); - logSB.AppendLine($"Got replica traffic ratio in {sw.Elapsed.TotalSeconds} seconds. Ratio is {replicaTrafficRatio}"); + logSB.AppendLine($"Got replica traffic ratio in {sw.Elapsed.TotalSeconds} seconds. Ratio is {replicaTrafficRatio}. "); if (replicaTrafficRatio < 0.5) // it does not make sense to use replica less than master at all { From 306db9f289c4e785078d8e4d7a928c701dd79655 Mon Sep 17 00:00:00 2001 From: Robert Johnson Date: Fri, 24 Oct 2025 10:50:28 -0700 Subject: [PATCH 3/5] Fix unit test --- .../Api/SearchPostReroutingMiddlewareTests.cs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs b/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs index 8cb10bc046..e2e9d855a4 100644 --- a/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs +++ b/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs @@ -8,6 +8,7 @@ using System.Net.Http; using System.Threading.Tasks; using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Health.Fhir.Api; using Microsoft.Health.Fhir.Api.Features.Routing; using Microsoft.Health.Fhir.Tests.Common; @@ -30,7 +31,7 @@ public SearchPostReroutingMiddlewareTests() { _httpContext = new DefaultHttpContext(); _requestDelegate = Substitute.For(); - _middleware = new SearchPostReroutingMiddleware(_requestDelegate); + _middleware = new SearchPostReroutingMiddleware(_requestDelegate, new NullLogger()); } [Theory] From a79f03ff14ff0aa44b3899ea87caf69116766817 Mon Sep 17 00:00:00 2001 From: Robert Johnson Date: Fri, 24 Oct 2025 13:55:47 -0700 Subject: [PATCH 4/5] Fix unit test --- .../Api/SearchPostReroutingMiddlewareTests.cs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs b/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs index e2e9d855a4..17dfae0cfb 100644 --- a/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs +++ b/src/Microsoft.Health.Fhir.Azure.UnitTests/Api/SearchPostReroutingMiddlewareTests.cs @@ -65,7 +65,9 @@ public async Task GivenSearchRequestViaPost_WhenContentTypeIsSpecified_InvalidCo _httpContext.Response.Body.Position = 0; using var reader = new StreamReader(_httpContext.Response.Body); var body = reader.ReadToEnd(); - Assert.Equal(ApiResources.ContentTypeFormUrlEncodedExpected, body); + var expectedString = ApiResources.ContentTypeFormUrlEncodedExpected.Replace("\"", "\\\""); + expectedString = $"\"{expectedString}\""; + Assert.Contains(expectedString, body); Assert.Equal((int)HttpStatusCode.BadRequest, _httpContext.Response.StatusCode); } } From f4eb4cc34c3e8e130bee16c9a1e62c93863f00ac Mon Sep 17 00:00:00 2001 From: Robert Johnson Date: Mon, 27 Oct 2025 07:39:03 -0700 Subject: [PATCH 5/5] Remove path from log --- .../Features/Routing/SearchPostReroutingMiddleware.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs b/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs index ba38b3155d..77033da784 100644 --- a/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs +++ b/src/Microsoft.Health.Fhir.Api/Features/Routing/SearchPostReroutingMiddleware.cs @@ -45,7 +45,7 @@ public async Task Invoke(HttpContext context) { if (request.ContentType is null || request.HasFormContentType) { - _logger.LogInformation("Rerouting POST {Path} to GET with query parameters from form body.", request.Path); + _logger.LogInformation("Rerouting POST to GET with query parameters from form body."); if (request.HasFormContentType) { @@ -60,7 +60,7 @@ public async Task Invoke(HttpContext context) } else { - _logger.LogDebug("Rejecting POST {Path} with invalid Content-Type.", request.Path); + _logger.LogDebug("Rejecting POST with invalid Content-Type."); context.Response.Clear(); context.Response.StatusCode = (int)HttpStatusCode.BadRequest;