serilog-contrib / serilog-enrichers-clientinfo Goto Github PK

The enrichers provided by ClientInfo are not thread-safe. This is a problem when concurrent tasks are trying to log inside the scope of a request. For example in the following situation:

var httpClient = _httpClientFactory.CreateClient(HttpClientName);

var task1 = Task.Run(async () =>
{
    var response = await httpClient.GetAsync("/api/call1");
    return await response.Content.ReadAsStringAsync();
});

var task2 = Task.Run(async () =>
{
    var response = await httpClient.GetAsync($"/api/call2");
    return await response.Content.ReadAsStringAsync();
});

await Task.WhenAll(task1, task2);

Because the HttpClients are logging they both use a logger that is trying to enrich the event with some client info (e.g. using ClientIpEnricher). If the property (e.g. Serilog_ClientIp) is not yet available on the HttpContext.Items then both instances will try to write it concurrently, which may cause various exceptions to be thrown depending on when and how the conflicting access occurs.

In theory this problem should only occur if the property isn't already on the HttpContext.Items during the concurrent phase. In other words, if the first logs of the request are written in a concurrent situation then it might occur. This means a workaround fix would be to write a log message before going concurrent (e.g. with _logger.Information("workaround fix") before the tasks in the snippet above). In my own tests this indeed seems to work.

I think there is an (implicit) expectation that Serilog enrichers are thread-safe (as mentioned here: serilog/serilog#1144) so that's why I report this as a bug.

Is there any suggestion about how can I get and pass the current correlation id through HttpClient's from HttpClientFactory?
My objective is to propagate the current value to subsequent microservices.

First off, I am testing with Visual Studio 2022, this doesn't happen with Visual Studio 2019.

However, when running a xUnit test, clientinfo generates an exception that ClientIp and ClientAgent are null. I have tried to add them as headers but it did not make any difference. My testing code:

    public class UnitTest1
    {
        [Fact]
        public async Task Test1()
        {
            // Arrange
            var factory = new CustomWebApplicationFactory<EcommerceWebAPI.Startup>();
            var client = factory.CreateClient();

            // Act
            var request = new HttpRequestMessage(HttpMethod.Post, "/api/Users/AuthenticateUser")
            {
                Content = new StringContent("{\"Username\":\"[email protected]\",\"Password\":\"wrongPassword\"}",
                    Encoding.UTF8,
                    "application/json")
            };
            request.Headers.Add("X-Real-IP", "84.247.85.224");
            request.Headers.Add("ClientIp", "127.0.0.1");
            request.Headers.Add("ClientAgent",
                "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:91.0) Gecko/20100101 Firefox/91.0");

            var response = await client.SendAsync(request);
            var responseStatusCode = (int)response.StatusCode;
            var apiResponse = await response.Content.ReadAsStringAsync();
            dynamic thing = JObject.Parse(apiResponse);

            // Assert
            Assert.Equal(400, responseStatusCode);
            Assert.Equal("Account is Suspended", (string)thing.message);
        }
    }

What I did to the EcommerceWebAPI appsettings.json file get around this issue:

"Serilog": {
    "Using": [ "Serilog.Exceptions", "Serilog", "Serilog.Sinks.Seq" ],
    "MinimumLevel": {
      "Default": "Verbose",
      "Override": {
        "System": "Information",
        "Microsoft": "Information",
        "Microsoft.EntityFrameworkCore": "Debug",
        "Microsoft.AspNetCore": "Debug"
      }
    },
    "WriteTo": [
      {
        "Name": "Seq",
        "Args": {
          "serverUrl": "http://localhost:5341",
          "apiKey": "HAQif5iJVjIPDlM60yTL",
          "restrictedToMinimumLevel": "Verbose"
        }
      }
    ],
    //"Enrich": [ "WithClientIp", "WithClientAgent", "WithEnvironmentName", "WithMachineName", "WithEnvironmentUserName", "FromLogContext", "WithExceptionDetails" ],
    "Enrich": [ "WithEnvironmentName", "WithMachineName", "WithEnvironmentUserName", "FromLogContext", "WithExceptionDetails" ]
  }

I noticed in logs that ipv6 addresses are truncated. e.g. 2001:4860:7:505:

Looks like this code doesn't respect rules from RFC7239

Installing this package results in a transitive dependency on the deprecated package Microsoft.AspNetCore.Http. Please fix this so that the deprecated package is not referenced any more.

I assume this can be done similar to how Serilog.AspNetCore does it: https://github.com/serilog/serilog-aspnetcore/blob/e6e51d8f64f50833bb539734816a91d5efd669b4/src/Serilog.AspNetCore/Serilog.AspNetCore.csproj#L40-L48

I see XML documentation in the source here, but it doesn't show up in the published nuget packages.

Should be as simple as adding this to the csproj file:

<GenerateDocumentationFile>True</GenerateDocumentationFile>

Instead of directly reading the X-Forwarded-Header by default, it's much better to use the ForwardedHeaders middleware (https://learn.microsoft.com/en-us/aspnet/core/host-and-deploy/proxy-load-balancer?view=aspnetcore-7.0) and then let that middleware set the HttpContext.Connection.RemoteIpAddress so we only log that information instead.

If, for some reason someone don't want to use that, then the ClientIp enricher could read this by header. Since there's a danger of IP spoofing (which this enricher does not have any protection against), it's better to let the ForwardedHeader middleware and configuration take care of this (the KnownNetworks and KnownProxies configuration).

I can implement a suggestion for this (by making it possible to set a configuration to disable reading headers or similar), but I'd personally prefer if the default would be changed to not read X-Forwarded-For (which would be a breaking change).
Maybe something for a 3.0 release?

When I install the NuGet package on a full framework project it is including Serilog.dll (v2.4.0.0)

Obviously, this enricher shouldn't be deploying Serilog, just taking a dependency on it as it causes problems like this: MissingMethodException Serilog.Context.LogContext.Push

Seems to be related: Including assembly files

<files>
  <file src="src\Serilog.Enrichers.ClientInfo\bin\$target$\net452\*.dll" target="lib/net452" />
  <file src="src\Serilog.Enrichers.ClientInfo\bin\$target$\netstandard2.0\*.dll" target="lib/netstandard2.0" />
  <file src="src\Serilog.Enrichers.ClientInfo\bin\$target$\netstandard2.1\*.dll" target="lib/netstandard2.1" />
</files>  

If you follow the conventions described in Creating a Package, you do not have to explicitly specify a list of files in the .nuspec file. The nuget pack command automatically picks up the necessary files.

Was there a reason not to use the automatic behavior?

I see it puts Serilog.dll in the bin directory on net452:

I don't see it in the netstandard folders. I guess msbuild behaves differently? 🤔

Sorry in advance if I wrote something wrong but... is it possible to use both X-forwarded-for and CF-Connecting-IP or others?
something like

"Args": {
          "xForwardHeaderName": [ "CF-Connecting-IP", "X-Forwarded-For", "X-Real-IP" ]
        }

According to the nuspec, the Serilog dependency is 2.7.1:

<group targetFramework="netstandard2.0">
	<dependency id="Microsoft.AspNetCore.Http" version="2.1.1" />
	<dependency id="Serilog" version="2.7.1" />
</group>

but the csproj is referencing 2.9.0:

<ItemGroup Condition=" '$(TargetFramework)' == 'netstandard2.0'">
	<PackageReference Include="Microsoft.AspNetCore.Http" Version="2.1.1" />
	<PackageReference Include="Serilog" Version="2.9.0" />
</ItemGroup>

Currently this lib uses X-forwarded-for to get client ip, however in some proxy environments i.e. Cloudflare.
Ips are piped through custom http headers (CF-Connecting-IP)
https://developers.cloudflare.com/fundamentals/get-started/reference/http-request-headers/

Would it be possible to make this header variable name configurable with defaults to X-forwarded-for?

Regards

as of now, there is no way to specify the property name for WithRequestHeader extension.

it can be easily implemented using this code: #25

On startup of our 2.1 app we're getting:

FileLoadException: Could not load file or assembly 'Microsoft.AspNetCore.Http, Version=2.2.2.0, Culture=neutral, PublicKeyToken=adb9793829ddae60'. The located assembly's manifest definition does not match the assembly reference.

loggerConfiguration..Enrich.WithClientIp()

PS, thanks for creating this enricher! 🤝

Hi this is my serilog configuration in app.settings.json

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.File",
      "Serilog.Sinks.Seq",
      "Serilog.Enrichers.ClientInfo",
      "Serilog.Enrichers.CorrelationId",
      "Serilog.Enrichers.ExceptionStackTraceHash",
      "Serilog.Enrichers.Environment",
      "Serilog.Enrichers.Memory"
    ],
    "MinimumLevel": {
      "Default": "Verbose",
      "Override": {
        "Microsoft.AspNetCore": "Warning",
        "Microsoft": "Information",
        "Microsoft.EntityFrameworkCore.Database.Command": "Error",
        "Microsoft.AspNetCore.SignalR": "Information",
        "Microsoft.AspNetCore.Http.Connections": "Information"
      }
    },
    "WriteTo": [
      {
        "Name": "Console",
        "Args": {
          "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [correlationId: {CorrelationId} machineName:{MachineName} environmentName:{EnvironmentName} environmentUserName:{EnvironmentUserName} clientIp:{ClientIp} requestHeader:{RequestHeader} processId:{ProcessId} processName:{ProcessName} memory:{MemoryUsage} level:{Level: u3}] ({SourceContext}) {Message} {NewLine} {Exception} {NewLine}",
          "theme": "Serilog.Sinks.SystemConsole.Themes.Literate",
          "restrictedToMinimumLevel": "Information"
        }
      },
      {
        "Name": "Seq",
        "Args": {
          "serverUrl": "http://localhost:5341/",
          "apiKey": "none",
          "restrictedToMinimumLevel": "Information"
        }
      },
      {
        "Name": "File",
        "Args": {
          "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [correlationId: {CorrelationId} machineName:{MachineName} environmentName:{EnvironmentName} environmentUserName:{EnvironmentUserName} clientIp:{ClientIp} requestHeader:{RequestHeader} processId:{ProcessId} processName:{ProcessName} memory:{MemoryUsage} level:{Level: u3}] ({SourceContext}) {Message} {NewLine} {Exception} {NewLine}",
          "path": "C:\\Users\\Lenovo\\AppData\\Local\\Logs\\Cloud.log",
          "rollingInterval": "Day",
          "restrictedToMinimumLevel": "Verbose"
        }
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName",
      {
        "Name": "WithClientIp",
        "Args": {
          "headerName": "CF-Connecting-IP"
        }
      },
      {
        "Name": "WithRequestHeader",
        "Args": {
          "headerName": "User-Agent"
        }
      },
      "WithMessageTemplate",
      "WithEnvironmentUserName",
      "WithMemoryUsage",
      "WithEnvironmentName",
      "WithExceptionDetails",
      "ExceptionStackTraceHash",
      "WithExceptionProperties",
      "WithProcessName",
      "WithProcessId"
    ]
  }
}

I have updated the client agent to request header according to the enricher package change. But now, im not able to display the client agent details in log.

Please help me to fix the issue

Hello,
first of all, thank you for great enricher :)

I have a small problem with it - it doesn't work correctly for ASP.NET Core when proxy is used.
It works fine for full ASP.NET framework. It is caused by handling those cases differently with #if NETFULL macro.

Is there any reason for it? Couldn't also .NET Core version read X-Forwarded-For headers?

(Also, when used on Azure, azure adds also port number, but that's whole different issue)

#if NETFULL
        private string GetIpAddress()
        {
            var ipAddress = _contextAccessor.HttpContext.Request.ServerVariables["HTTP_X_FORWARDED_FOR"];

            if (!string.IsNullOrEmpty(ipAddress))
            {
                var addresses = ipAddress.Split(',');
                if (addresses.Length != 0)
                    return addresses[0];
            }

            return _contextAccessor.HttpContext.Request.ServerVariables["REMOTE_ADDR"];
        }

#else
     private string GetIpAddress()
     {
        return _contextAccessor.HttpContext.Connection.RemoteIpAddress.ToString();
     }
#endif

As of 2.0.3, building a Blazor WASM app with Serilog.Enrichers.ClientInfo referenced results in the following build error:

error NETSDK1082: There was no runtime pack for Microsoft.AspNetCore.App available for the specified RuntimeIdentifier 'browser-wasm'.

Downgrading the package to 2.0.1 works correctly.

I've tested the build process on Linux, Windows, and in docker, with the same results.

I'm wondering if it has anything to do with the <Project Sdk="Microsoft.NET.Sdk.BlazorWebAssembly"> required in WASM apps, vs <Project Sdk="Microsoft.NET.Sdk.Web"> in your sample app.

I needed those two properties in enriched.

Do you mind if I make PR to your library with those 2?