Serilog ThreadId is always output as 1

Question

I have a ThreadId in the outputTemplate but the log always records it as 1. I have several instances of the app running at the same time into the same log and so was hoping I could separate the instances based on the ThreadId.

Can anyone suggest how to work around this? The ThreadName gets assigned after the app sets up a few things and identifies the area it is running in so is not the best seperator. Also there can be multiple functions run in an area concurrently. Hence the need for the ThreadId

Log.Logger = new LoggerConfiguration()
            .ReadFrom.Configuration(builder.Build())
            .Enrich.FromLogContext()
            .Enrich.WithThreadId()
            .Enrich.WithThreadName()
            .WriteTo.Console(outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level:u3}] <{ThreadName}> <{ThreadId}> {Message:lj}{NewLine}{Exception}")      
            .WriteTo.File(@".\log\log.txt", 
                             rollingInterval: RollingInterval.Day, 
                             shared: true,
                             outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level:u3}] <{ThreadName}> <{ThreadId}> {Message:lj}{NewLine}{Exception}")
            .CreateLogger();

Log output

2021-04-09 06:30:09.059 [INF] <blackstone> <1> Action : Task A
2021-04-09 06:30:09.059 [INF] <wavell> <1> Action : Task A
2021-04-09 06:30:09.060 [INF] <forest> <1> Action : Task A
2021-04-09 06:30:09.130 [INF] <wavell> <1> Loading CentreDetails
2021-04-09 06:30:09.130 [INF] <forest> <1> Loading CentreDetails
2021-04-09 06:30:09.132 [INF] <blackstone> <1> Loading CentreDetails
2021-04-09 06:30:09.560 [INF] <wavell> <1> Loading ParentDetails
2021-04-09 06:30:09.554 [INF] <blackstone> <1> Loading ParentDetails
2021-04-09 06:30:09.560 [INF] <forest> <1> Loading ParentDetails

If you add `Thread.CurrentThread.ManagedThreadId` to your log messages what does it display? — tymtam, Apr 09 '21 at 04:18
@tymtam I want Serilog to put in it's pattern the Thread ID. Not explicitly log it each time I call Log.Information("Action : Task A"). — KAHartle, Apr 09 '21 at 05:17

score 4 · Answer 1 · answered Apr 09 '21 at 04:46

4

Sounds like you want Serilog.Enrichers.Process and Enrich.WithProcessId() instead of WithThreadId().

answered Apr 09 '21 at 04:46

Nicholas Blumhardt

30,271
4
90
101

Serilog.Enrichers.Process nuget is already in the solution. I already have .Enrich.WithThreadId() in the LoggerConfiguration(). Do you have an example of what you mean? – KAHartle Apr 09 '21 at 05:13

score 4 · Answer 2 · edited Jun 17 '23 at 11:08

This worked for me — it logs thread ids of currently running threads, not the one where Logger instance was created:

nuget package

<PackageReference Include="Serilog.Enrichers.Thread" Version="3.1.0" />

appsettings.json {ThreadId}

{
  "Logging": {
    "LogLevel": {
      "Default": "Information"
    }
  },
  "Serilog": {
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Error"
      }
    },
      {
        "Name": "File",
        "Args": {
          "path": "/log/api.log",
          "outputTemplate": "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level}] Th:{ThreadId} {Message} {NewLine}{Exception}",
          "rollingInterval": "Day"
        }
      }
    ],
    "Properties": {
      "Application": "acme"
    }
  }
}

startup .Enrich.WithThreadId()

public Startup(IConfiguration configuration)
{
    Log.Logger = new LoggerConfiguration().ReadFrom.Configuration(configuration).Enrich.WithThreadId()
        .CreateLogger();
    Configuration = configuration;
}

sample log

2022-03-11 14:49:25.425 -05:00 [Information] Th:27 foo
2022-03-11 14:49:25.428 -05:00 [Information] Th:5 Bar

I confirm that it logs current thread ids (not the one where the logger was created). I used Nuget packages: Serilog 2.12.0, Serilog.Enrichers.Thread 3.1.0, Serilog.Sinks.File 5.0.0 with .Net Framework 4.8. In my case I don't read configuration from json. I build it dynamically. `.Enrich.WithThreadId()` is required. — Vasiliy Zverev, Jun 08 '23 at 02:26

score 0 · Accepted Answer · answered Apr 09 '21 at 05:32

OK I follow what @Nicholas Blumhardt was aiming at...

Added the Serilog.Enrichers.Process nuget and updated the code to this

Log.Logger = new LoggerConfiguration()
                .ReadFrom.Configuration(builder.Build())
                .Enrich.FromLogContext()
                .Enrich.WithProcessId()
                .Enrich.WithThreadName()
                .WriteTo.Console(outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level:u3}] <{ThreadName}> <{ProcessId}> {Message:lj}{NewLine}{Exception}")      
                .WriteTo.File(@".\log\log.txt", 
                                 rollingInterval: RollingInterval.Day, 
                                 shared: true,
                                 outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff} [{Level:u3}] <{ThreadName}> <{ProcessId}> {Message:lj}{NewLine}{Exception}")
                .CreateLogger();

The log is now pushing out a unique Process ID

Serilog ThreadId is always output as 1

3 Answers3