| | | 1 | | using System.Diagnostics; |
| | | 2 | | using System.Globalization; |
| | | 3 | | using System.Net; |
| | | 4 | | using System.Text; |
| | | 5 | | using Microsoft.Extensions.Options; |
| | | 6 | | using Microsoft.Extensions.Primitives; |
| | | 7 | | using Microsoft.Net.Http.Headers; |
| | | 8 | | |
| | | 9 | | namespace Kestrun.Middleware; |
| | | 10 | | |
| | | 11 | | /// <summary> |
| | | 12 | | /// ASP.NET Core middleware that emits Apache style common access log entries using Serilog. |
| | | 13 | | /// </summary> |
| | | 14 | | public sealed class CommonAccessLogMiddleware |
| | | 15 | | { |
| | | 16 | | private readonly RequestDelegate _next; |
| | | 17 | | private readonly IOptionsMonitor<CommonAccessLogOptions> _optionsMonitor; |
| | | 18 | | private readonly Serilog.ILogger _defaultLogger; |
| | | 19 | | |
| | | 20 | | /// <summary> |
| | | 21 | | /// Initializes a new instance of the <see cref="CommonAccessLogMiddleware"/> class. |
| | | 22 | | /// </summary> |
| | | 23 | | /// <param name="next">The next middleware in the pipeline.</param> |
| | | 24 | | /// <param name="optionsMonitor">The options monitor for <see cref="CommonAccessLogOptions"/>.</param> |
| | | 25 | | /// <param name="logger">The Serilog logger instance.</param> |
| | 3 | 26 | | public CommonAccessLogMiddleware( |
| | 3 | 27 | | RequestDelegate next, |
| | 3 | 28 | | IOptionsMonitor<CommonAccessLogOptions> optionsMonitor, |
| | 3 | 29 | | Serilog.ILogger logger) |
| | | 30 | | { |
| | 3 | 31 | | _next = next ?? throw new ArgumentNullException(nameof(next)); |
| | 3 | 32 | | _optionsMonitor = optionsMonitor ?? throw new ArgumentNullException(nameof(optionsMonitor)); |
| | 3 | 33 | | ArgumentNullException.ThrowIfNull(logger, nameof(logger)); |
| | | 34 | | |
| | 3 | 35 | | _defaultLogger = CreateScopedLogger(logger); |
| | 3 | 36 | | } |
| | | 37 | | |
| | | 38 | | /// <summary> |
| | | 39 | | /// Invokes the middleware for the specified HTTP context. |
| | | 40 | | /// </summary> |
| | | 41 | | /// <param name="context">The HTTP context.</param> |
| | | 42 | | public async Task InvokeAsync(HttpContext context) |
| | | 43 | | { |
| | 3 | 44 | | ArgumentNullException.ThrowIfNull(context); |
| | | 45 | | |
| | 3 | 46 | | var stopwatch = Stopwatch.StartNew(); |
| | | 47 | | try |
| | | 48 | | { |
| | 3 | 49 | | await _next(context); |
| | 3 | 50 | | } |
| | | 51 | | finally |
| | | 52 | | { |
| | 3 | 53 | | stopwatch.Stop(); |
| | 3 | 54 | | WriteAccessLog(context, stopwatch.Elapsed); |
| | | 55 | | } |
| | 3 | 56 | | } |
| | | 57 | | |
| | | 58 | | private void WriteAccessLog(HttpContext context, TimeSpan elapsed) |
| | | 59 | | { |
| | | 60 | | CommonAccessLogOptions options; |
| | | 61 | | try |
| | | 62 | | { |
| | 3 | 63 | | options = _optionsMonitor.CurrentValue ?? new CommonAccessLogOptions(); |
| | 3 | 64 | | } |
| | 0 | 65 | | catch |
| | | 66 | | { |
| | 0 | 67 | | options = new CommonAccessLogOptions(); |
| | 0 | 68 | | } |
| | | 69 | | |
| | 3 | 70 | | var logger = ResolveLogger(options); |
| | 3 | 71 | | if (!logger.IsEnabled(options.Level)) |
| | | 72 | | { |
| | 1 | 73 | | return; |
| | | 74 | | } |
| | | 75 | | |
| | 2 | 76 | | var (timestamp, usedFallbackFormat) = ResolveTimestamp(options); |
| | 2 | 77 | | if (usedFallbackFormat) |
| | | 78 | | { |
| | 0 | 79 | | _defaultLogger.Debug( |
| | 0 | 80 | | "Invalid common access log timestamp format '{TimestampFormat}' supplied – falling back to default.", |
| | 0 | 81 | | options.TimestampFormat); |
| | | 82 | | } |
| | | 83 | | |
| | | 84 | | try |
| | | 85 | | { |
| | 2 | 86 | | var logLine = BuildLogLine(context, options, elapsed, timestamp); |
| | 2 | 87 | | logger.Write(options.Level, "{CommonAccessLogLine}", logLine); |
| | 2 | 88 | | } |
| | 0 | 89 | | catch (Exception ex) |
| | | 90 | | { |
| | | 91 | | // Access logging should never take down the pipeline – swallow and trace. |
| | 0 | 92 | | _defaultLogger.Debug(ex, "Failed to emit common access log entry."); |
| | 0 | 93 | | } |
| | 2 | 94 | | } |
| | | 95 | | |
| | | 96 | | private Serilog.ILogger ResolveLogger(CommonAccessLogOptions options) |
| | | 97 | | { |
| | 3 | 98 | | ArgumentNullException.ThrowIfNull(options); |
| | | 99 | | |
| | 3 | 100 | | return options.Logger is { } customLogger ? CreateScopedLogger(customLogger) : _defaultLogger; |
| | | 101 | | } |
| | | 102 | | |
| | | 103 | | private static Serilog.ILogger CreateScopedLogger(Serilog.ILogger logger) |
| | | 104 | | { |
| | 3 | 105 | | ArgumentNullException.ThrowIfNull(logger); |
| | | 106 | | |
| | 3 | 107 | | return logger.ForContext("LogFormat", "CommonAccessLog") |
| | 3 | 108 | | .ForContext<CommonAccessLogMiddleware>(); |
| | | 109 | | } |
| | | 110 | | |
| | | 111 | | private static string BuildLogLine(HttpContext context, CommonAccessLogOptions options, TimeSpan elapsed, string tim |
| | | 112 | | { |
| | 2 | 113 | | var request = context.Request; |
| | 2 | 114 | | var response = context.Response; |
| | | 115 | | |
| | 2 | 116 | | var remoteHost = SanitizeToken(ResolveClientAddress(context, options)); |
| | 2 | 117 | | var remoteIdent = "-"; // identd is rarely used – emit dash per the spec. |
| | 2 | 118 | | var remoteUser = SanitizeToken(ResolveRemoteUser(context)); |
| | | 119 | | |
| | 2 | 120 | | var requestLine = SanitizeQuoted(BuildRequestLine(request, options)); |
| | 2 | 121 | | var statusCode = context.Response.StatusCode; |
| | 2 | 122 | | var responseBytes = ResolveContentLength(response); |
| | 2 | 123 | | var referer = SanitizeQuoted(GetHeaderValue(request.Headers, HeaderNames.Referer)); |
| | 2 | 124 | | var userAgent = SanitizeQuoted(GetHeaderValue(request.Headers, HeaderNames.UserAgent)); |
| | | 125 | | |
| | | 126 | | // Pre-size the StringBuilder to avoid unnecessary allocations. |
| | 2 | 127 | | var builder = new StringBuilder(remoteHost.Length |
| | 2 | 128 | | + remoteUser.Length |
| | 2 | 129 | | + requestLine.Length |
| | 2 | 130 | | + referer.Length |
| | 2 | 131 | | + userAgent.Length |
| | 2 | 132 | | + 96); |
| | | 133 | | |
| | 2 | 134 | | _ = builder.Append(remoteHost).Append(' ') |
| | 2 | 135 | | .Append(remoteIdent).Append(' ') |
| | 2 | 136 | | .Append(remoteUser).Append(" [") |
| | 2 | 137 | | .Append(timestamp).Append("] \"") |
| | 2 | 138 | | .Append(requestLine).Append("\" ") |
| | 2 | 139 | | .Append(statusCode.ToString(CultureInfo.InvariantCulture)).Append(' ') |
| | 2 | 140 | | .Append(responseBytes); |
| | | 141 | | |
| | 2 | 142 | | _ = builder.Append(' ') |
| | 2 | 143 | | .Append('"').Append(referer).Append('"') |
| | 2 | 144 | | .Append(' ') |
| | 2 | 145 | | .Append('"').Append(userAgent).Append('"'); |
| | | 146 | | |
| | 2 | 147 | | if (options.IncludeElapsedMilliseconds) |
| | | 148 | | { |
| | 1 | 149 | | var elapsedMs = elapsed.TotalMilliseconds.ToString("0.####", CultureInfo.InvariantCulture); |
| | 1 | 150 | | _ = builder.Append(' ').Append(elapsedMs); |
| | | 151 | | } |
| | | 152 | | |
| | 2 | 153 | | return builder.ToString(); |
| | | 154 | | } |
| | | 155 | | |
| | | 156 | | private static (string Timestamp, bool UsedFallbackFormat) ResolveTimestamp(CommonAccessLogOptions options) |
| | | 157 | | { |
| | 2 | 158 | | var provider = options.TimeProvider ?? TimeProvider.System; |
| | 2 | 159 | | var timestamp = options.UseUtcTimestamp |
| | 2 | 160 | | ? provider.GetUtcNow() |
| | 2 | 161 | | : provider.GetLocalNow(); |
| | | 162 | | |
| | 2 | 163 | | var format = string.IsNullOrWhiteSpace(options.TimestampFormat) |
| | 2 | 164 | | ? CommonAccessLogOptions.DefaultTimestampFormat |
| | 2 | 165 | | : options.TimestampFormat; |
| | | 166 | | |
| | | 167 | | try |
| | | 168 | | { |
| | 2 | 169 | | return (RenderTimestamp(timestamp, format), false); |
| | | 170 | | } |
| | 0 | 171 | | catch (FormatException) |
| | | 172 | | { |
| | 0 | 173 | | return (RenderTimestamp(timestamp, CommonAccessLogOptions.DefaultTimestampFormat), true); |
| | | 174 | | } |
| | 2 | 175 | | } |
| | | 176 | | |
| | | 177 | | private static string RenderTimestamp(DateTimeOffset timestamp, string format) |
| | | 178 | | { |
| | 2 | 179 | | var rendered = timestamp.ToString(format, CultureInfo.InvariantCulture); |
| | | 180 | | |
| | 2 | 181 | | if (string.Equals(format, CommonAccessLogOptions.DefaultTimestampFormat, StringComparison.Ordinal)) |
| | | 182 | | { |
| | 2 | 183 | | var lastColon = rendered.LastIndexOf(':'); |
| | 2 | 184 | | if (lastColon >= 0 && lastColon >= rendered.Length - 5) |
| | | 185 | | { |
| | 2 | 186 | | rendered = rendered.Remove(lastColon, 1); |
| | | 187 | | } |
| | | 188 | | } |
| | | 189 | | |
| | 2 | 190 | | return rendered; |
| | | 191 | | } |
| | | 192 | | |
| | | 193 | | private static string ResolveClientAddress(HttpContext context, CommonAccessLogOptions options) |
| | | 194 | | { |
| | 2 | 195 | | if (!string.IsNullOrWhiteSpace(options.ClientAddressHeader) |
| | 2 | 196 | | && context.Request.Headers.TryGetValue(options.ClientAddressHeader, out var forwarded)) |
| | | 197 | | { |
| | 0 | 198 | | var first = ExtractFirstHeaderValue(forwarded); |
| | 0 | 199 | | if (!string.IsNullOrWhiteSpace(first)) |
| | | 200 | | { |
| | 0 | 201 | | return first!; |
| | | 202 | | } |
| | | 203 | | } |
| | | 204 | | |
| | 2 | 205 | | var address = context.Connection.RemoteIpAddress; |
| | 2 | 206 | | if (address is null) |
| | | 207 | | { |
| | 2 | 208 | | return "-"; |
| | | 209 | | } |
| | | 210 | | |
| | | 211 | | // Format IPv6 addresses without scope ID to match Apache behaviour. |
| | 0 | 212 | | return address.AddressFamily == System.Net.Sockets.AddressFamily.InterNetworkV6 |
| | 0 | 213 | | ? address.ScopeId == 0 ? address.ToString() : new IPAddress(address.GetAddressBytes()).ToString() |
| | 0 | 214 | | : address.ToString(); |
| | | 215 | | } |
| | | 216 | | |
| | | 217 | | private static string ExtractFirstHeaderValue(StringValues values) |
| | | 218 | | { |
| | 0 | 219 | | if (StringValues.IsNullOrEmpty(values)) |
| | | 220 | | { |
| | 0 | 221 | | return ""; |
| | | 222 | | } |
| | | 223 | | |
| | 0 | 224 | | var span = values.ToString().AsSpan(); |
| | 0 | 225 | | var commaIndex = span.IndexOf(','); |
| | 0 | 226 | | var first = commaIndex >= 0 ? span[..commaIndex] : span; |
| | 0 | 227 | | return first.Trim().ToString(); |
| | | 228 | | } |
| | | 229 | | |
| | | 230 | | private static string ResolveRemoteUser(HttpContext context) |
| | | 231 | | { |
| | 2 | 232 | | var identity = context.User?.Identity; |
| | 2 | 233 | | return identity is { IsAuthenticated: true, Name.Length: > 0 } ? identity.Name! : "-"; |
| | | 234 | | } |
| | | 235 | | |
| | | 236 | | private static string BuildRequestLine(HttpRequest request, CommonAccessLogOptions options) |
| | | 237 | | { |
| | 2 | 238 | | var method = string.IsNullOrWhiteSpace(request.Method) ? "-" : request.Method; |
| | 2 | 239 | | var path = request.Path.HasValue ? request.Path.Value : "/"; |
| | 2 | 240 | | if (string.IsNullOrEmpty(path)) |
| | | 241 | | { |
| | 0 | 242 | | path = "/"; |
| | | 243 | | } |
| | | 244 | | |
| | 2 | 245 | | if (options.IncludeQueryString && request.QueryString.HasValue) |
| | | 246 | | { |
| | 0 | 247 | | path += request.QueryString.Value; |
| | | 248 | | } |
| | | 249 | | |
| | 2 | 250 | | return options.IncludeProtocol && !string.IsNullOrWhiteSpace(request.Protocol) |
| | 2 | 251 | | ? string.Concat(method, " ", path, " ", request.Protocol) |
| | 2 | 252 | | : string.Concat(method, " ", path); |
| | | 253 | | } |
| | | 254 | | |
| | | 255 | | private static string ResolveContentLength(HttpResponse? response) |
| | | 256 | | { |
| | 2 | 257 | | return response is null |
| | 2 | 258 | | ? "-" |
| | 2 | 259 | | : response.ContentLength.HasValue |
| | 2 | 260 | | ? response.ContentLength.Value.ToString(CultureInfo.InvariantCulture) |
| | 2 | 261 | | : response.Headers.ContentLength.HasValue ? response.Headers.ContentLength.Value.ToString(CultureInfo.Invari |
| | | 262 | | } |
| | | 263 | | |
| | | 264 | | private static string GetHeaderValue(IHeaderDictionary headers, string headerName) |
| | | 265 | | { |
| | 4 | 266 | | return !headers.TryGetValue(headerName, out var value) |
| | 4 | 267 | | ? "-" |
| | 4 | 268 | | : value.Count switch |
| | 4 | 269 | | { |
| | 0 | 270 | | 0 => "-", |
| | 0 | 271 | | 1 => value[0] ?? "-", |
| | 0 | 272 | | _ => value[0] ?? "-", |
| | 4 | 273 | | }; |
| | | 274 | | } |
| | | 275 | | |
| | | 276 | | private static string SanitizeToken(string? value) |
| | | 277 | | { |
| | 4 | 278 | | if (string.IsNullOrWhiteSpace(value) || value == "-") |
| | | 279 | | { |
| | 4 | 280 | | return "-"; |
| | | 281 | | } |
| | | 282 | | |
| | 0 | 283 | | var span = value.AsSpan(); |
| | 0 | 284 | | var builder = new StringBuilder(span.Length); |
| | 0 | 285 | | foreach (var ch in span) |
| | | 286 | | { |
| | 0 | 287 | | if (char.IsControl(ch)) |
| | | 288 | | { |
| | | 289 | | continue; |
| | | 290 | | } |
| | | 291 | | |
| | 0 | 292 | | _ = char.IsWhiteSpace(ch) ? builder.Append('_') : ch == '"' ? builder.Append('_') : builder.Append(ch); |
| | | 293 | | } |
| | | 294 | | |
| | 0 | 295 | | return builder.Length == 0 ? "-" : builder.ToString(); |
| | | 296 | | } |
| | | 297 | | |
| | | 298 | | private static string SanitizeQuoted(string? value) |
| | | 299 | | { |
| | 6 | 300 | | if (string.IsNullOrEmpty(value) || value == "-") |
| | | 301 | | { |
| | 4 | 302 | | return "-"; |
| | | 303 | | } |
| | | 304 | | |
| | 2 | 305 | | var builder = new StringBuilder(value.Length + 8); |
| | 46 | 306 | | foreach (var ch in value) |
| | | 307 | | { |
| | 21 | 308 | | if (ch is '\\' or '"') |
| | | 309 | | { |
| | 0 | 310 | | _ = builder.Append('\\').Append(ch); |
| | | 311 | | } |
| | 21 | 312 | | else if (ch is '\r' or '\n' || char.IsControl(ch)) |
| | | 313 | | { |
| | | 314 | | continue; |
| | | 315 | | } |
| | | 316 | | else |
| | | 317 | | { |
| | 21 | 318 | | _ = builder.Append(ch); |
| | | 319 | | } |
| | | 320 | | } |
| | | 321 | | |
| | 2 | 322 | | return builder.Length == 0 ? "-" : builder.ToString(); |
| | | 323 | | } |
| | | 324 | | } |