serilog-contrib / serilog-enrichers-clientinfo

Enrich logs with client IP, correlation id and HTTP request headers.
MIT License
99 stars 22 forks source link

ClientIpEnricher ignores updated HttpContext.Connection.RemoteIpAddress #39

Closed smusenok closed 4 months ago

smusenok commented 4 months ago

Hello! First of all, thank you for the great enricher!

I tried to handle forwarded headers in the latest version (v2.1.0, net8, win11) using ForwardedHeadersMiddleware and it seems it doesn't work properly. Looks like the updated by ForwardedHeadersMiddleware value of HttpContext.Connection.RemoteIpAddress property is ignored by ClientIpEnricher:

using Microsoft.AspNetCore.HttpOverrides;
using Serilog;
using Serilog.Events;
using Serilog.Formatting.Compact;

Log.Logger = new LoggerConfiguration()
    .Enrich.WithClientIp()
    .Enrich.WithRequestHeader("X-Forwarded-For")
    .WriteTo.Console(new RenderedCompactJsonFormatter())
    .CreateLogger();

var builder = WebApplication.CreateBuilder(args);
builder.Host.UseSerilog();
builder.Services
    .AddHttpContextAccessor()
    .Configure<ForwardedHeadersOptions>(
        options =>
        {
            options.ForwardedHeaders = ForwardedHeaders.XForwardedFor;
            options.KnownNetworks.Clear();
            options.KnownProxies.Clear();
        });

var app = builder.Build();

app
    .UseForwardedHeaders()
    .Use(
        async (context, next) =>
        {
            app.Logger.LogInformation(
                "HttpContext.Connection.RemoteIpAddress: {RemoteIpAddress}, HttpContext.Items[\"Serilog_ClientIp\"]: {Serilog_ClientIp}",
                context.Connection.RemoteIpAddress,
                (context.Items["Serilog_ClientIp"] as LogEventProperty)?.Value);

            await next(context);
        });

app.MapGet("/", () => "hello world");

app.Run();

If I send a GET request with X-Forwarded-For: "1.2.3.4" header I can see the following log message:

{"@t":"2024-07-29T15:32:35.9065925Z","@m":"HttpContext.Connection.RemoteIpAddress: \"1.2.3.4\", HttpContext.Items[\"Serilog_ClientIp\"]: \"\\\"::1\\\"\"","@i":"850409ce","@tr":"9ab944cc8759b6f1a2d81852e8f436d6","@sp":"d2cbef152611b290","RemoteIpAddress":"1.2.3.4","Serilog_ClientIp":"\"::1\"","SourceContext":"WebApplication1","RequestId":"0HN5FSEM0CVRT:00000001","RequestPath":"/","ConnectionId":"0HN5FSEM0CVRT","ClientIp":"::1","XForwardedFor":"1.2.3.4"}

RemoteIpAddress and XForwardedFor properties contain the expected value "1.2.3.4", but HttpContext.Items["Serilog_ClientIp"] and as the result ClientIp property both have "::1".

mo-esmp commented 4 months ago

Thanks for reporting the issue. You’re right. For the first time before the middleware sets the IP, the enricher logs the IP and caches the IP address log property in HttpConext, and it will be used for the rest of the logs in a request. I will fix it.

mo-esmp commented 4 months ago

Could you please review the PR if you have time? https://github.com/serilog-contrib/serilog-enrichers-clientinfo/pull/40 Please keep in mind that always the first client IP log would be "unknown" or "::1" before the middleware sets the IP.