| | | 1 | | using System.Diagnostics; |
| | | 2 | | using Microsoft.AspNetCore.Mvc.Filters; |
| | | 3 | | using Microsoft.Extensions.Logging; |
| | | 4 | | |
| | | 5 | | namespace ArturRios.Heimdall.WebApi.Security; |
| | | 6 | | |
| | | 7 | | /// <summary> |
| | | 8 | | /// Writes one log line for every 5xx response an action produces — at Error, with the route |
| | | 9 | | /// template, the status code and the trace id (#227). |
| | | 10 | | /// </summary> |
| | | 11 | | /// <remarks> |
| | | 12 | | /// <para> |
| | | 13 | | /// Handlers return persistence and other server faults to the client as a message and a status |
| | | 14 | | /// code, and nothing else wrote them down: the response said "failed" and the log said nothing, |
| | | 15 | | /// so the cause of a 500 could not be found from the trace id the caller held. A result filter |
| | | 16 | | /// sees every such response whatever produced it, so no handler has to remember to log. |
| | | 17 | | /// </para> |
| | | 18 | | /// <para> |
| | | 19 | | /// An exception that escapes the action never reaches a result filter: <c>ExceptionMiddleware</c> |
| | | 20 | | /// catches it and already logs it at Error with its stack trace, inside the request's activity, |
| | | 21 | | /// so this filter does not log it a second time. The two together leave one line per 5xx. |
| | | 22 | | /// </para> |
| | | 23 | | /// <para> |
| | | 24 | | /// The route is the template (<c>api/person/{publicId}</c>), never the raw path, and the line |
| | | 25 | | /// carries no query string, body, header or caller identity: ids and addresses in a log are |
| | | 26 | | /// personal data the retention schedule would then have to cover (NFR-22). 503 is logged at |
| | | 27 | | /// Warning instead — in this API it is always a deliberate answer (a saturated password-hash |
| | | 28 | | /// gate, which <see cref="PasswordHashSaturationFilter" /> keeps out of the error log, or a |
| | | 29 | | /// readiness probe reporting the database down), and a probe every few seconds would otherwise |
| | | 30 | | /// bury real faults. |
| | | 31 | | /// </para> |
| | | 32 | | /// <para> |
| | | 33 | | /// The readiness action carries <see cref="SuppressServerErrorLogAttribute" /> and gets no line |
| | | 34 | | /// here at all: <c>ReadinessCache</c> holds the answer for a window, and the database check |
| | | 35 | | /// writes one Warning per window with the cause, which is the only line an outage should cost. |
| | | 36 | | /// </para> |
| | | 37 | | /// </remarks> |
| | 1484 | 38 | | public class ServerErrorLoggingFilter(ILogger<ServerErrorLoggingFilter> logger) : IAlwaysRunResultFilter |
| | | 39 | | { |
| | | 40 | | public void OnResultExecuting(ResultExecutingContext context) |
| | | 41 | | { |
| | 1474 | 42 | | } |
| | | 43 | | |
| | | 44 | | public void OnResultExecuted(ResultExecutedContext context) |
| | | 45 | | { |
| | 1483 | 46 | | var statusCode = context.HttpContext.Response.StatusCode; |
| | | 47 | | |
| | 1483 | 48 | | if (statusCode < StatusCodes.Status500InternalServerError) |
| | | 49 | | { |
| | 1472 | 50 | | return; |
| | | 51 | | } |
| | | 52 | | |
| | 11 | 53 | | if (context.ActionDescriptor.EndpointMetadata?.OfType<SuppressServerErrorLogAttribute>().Any() == true) |
| | | 54 | | { |
| | 2 | 55 | | return; |
| | | 56 | | } |
| | | 57 | | |
| | 9 | 58 | | var route = context.ActionDescriptor.AttributeRouteInfo?.Template ?? context.ActionDescriptor.DisplayName; |
| | 9 | 59 | | var traceId = Activity.Current?.TraceId.ToString() ?? context.HttpContext.TraceIdentifier; |
| | 9 | 60 | | var level = statusCode == StatusCodes.Status503ServiceUnavailable ? LogLevel.Warning : LogLevel.Error; |
| | | 61 | | |
| | 9 | 62 | | logger.Log(level, "Request to {Route} answered {StatusCode} (trace {TraceId})", route, statusCode, traceId); |
| | 9 | 63 | | } |
| | | 64 | | } |