Serilog: How do I further enhance a filter express

Question

I have two loggers with Serilog and they save to different files. I want to create the loggers through the appsettings.json as opposed to code.

When I create my loggers through the Startup.cs configuration, I get a much more specific log and I prefer to have it that way as it's much clearer and will allow others to check the logs and understand what's going on without needing much technical knowledge. However, I want to apply this to the appsettings so that I can migrate the code to any other project that I may use. FYI: I don't want to override the log level.

For example, with code I create my loggers like so:

Log.Logger = new LoggerConfiguration()
    .WriteTo.ColoredConsole()
    .WriteTo.Logger(lc => lc
    .Filter.ByExcluding(Matching.FromSource("Microsoft"))
    .WriteTo.File("Serilogs/Program_log_.txt", rollingInterval: RollingInterval.Day)
    .MinimumLevel.Information()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information))

    .WriteTo.Logger(lc => lc
    .Filter.ByIncludingOnly(Matching.FromSource("Microsoft"))
    .WriteTo.File("Serilogs/ServerTrace_log_.txt", rollingInterval: RollingInterval.Day)
    .MinimumLevel.Information()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information))

    .CreateLogger();

This generates the two separate outputs that I like the formatting of: File 1: Readable, custom logs:

2019-01-18 11:18:09.873 +00:00 [INF] //Some custom log information
2019-01-18 11:18:09.875 +00:00 [INF] //Some more custom log information

File 2: Stack trace, server information:

2019-01-18 11:17:56.378 +00:00 [INF] User profile is available. Using '//A path' as key repository and Windows DPAPI to encrypt keys at rest.
2019-01-18 11:17:57.840 +00:00 [INF] Request starting HTTP/1.1 GET https://localhost:5001/swagger/index.html  
2019-01-18 11:17:58.074 +00:00 [INF] Request finished in 235.5796ms 200 text/html
2019-01-18 11:17:58.326 +00:00 [INF] Request starting HTTP/1.1 GET https://localhost:5001/swagger/v1/swagger.json  
2019-01-18 11:17:58.452 +00:00 [INF] Request finished in 126.2127ms 200 application/json;charset=utf-8 

When I do it by using the JSON appsettings it looks like so:

 "Serilog": {
    "Using": [
      "Serilog.Sinks.File",
      "Serilog.Filters.Expressions",
      "Serilog.Settings.Configuration"
    ],
    "WriteTo": [
      {
        "Name": "Logger",
        "Args": {
          "configureLogger": {
            "Filter": [
              {
                "Name": "ByIncluding",
                "Args": {
                  "expression": "SourceContext = 'Microsoft'"
                }
              }
            ],
            "WriteTo": [
              {
                "Name": "File",
                "Args": {
                  "path": "./Serilogs/server_logs_.log",
                  "rollingInterval": "Day"
                }
              }
            ]
          }
        }
      },
      {
        "Name": "Logger",
        "Args": {
          "configureLogger": {
            "Filter": [
              {
                "Name": "ByExcluding",
                "Args": {
                  "expression": "SourceContext = 'Microsoft.AspNetCore.Hosting.Internal.WebHost'"
                }
              }
            ],
            "WriteTo": [
              {
                "Name": "File",
                "Args": {
                  "path": "./Serilogs/program_logs_.log",
                  "rollingInterval": "Day"
                }
              }
            ]
          }
        }
      }
    ]
  }

And this generates the two files. File 1: Readable, custom logs:

2019-01-18 11:22:52.903 +00:00 [INF] User profile is available. Using '// A path' as key repository and Windows DPAPI to encrypt keys at rest.
2019-01-18 11:22:59.229 +00:00 [INF] Route matched with {action = "PollForStatusUpdate", controller = "StatusMessage"}. Executing action {apiname}.{controller}.{method}.PollForStatusUpdate ({apiname})
2019-01-18 11:22:59.505 +00:00 [INF] Executing action method {apiname}.{controller}.{method}.PollForStatusUpdate ({apiname}) with arguments (["{apiname}.{controller}.{method}.MessageResult"]) - Validation state: "Valid"
2019-01-18 11:22:59.632 +00:00 [INF] //Some custom log information
2019-01-18 11:22:59.639 +00:00 [INF] //Some more custom log information
{apiname}.{controller}.{method}.PollForStatusUpdate ({apiname}), returned result Microsoft.AspNetCore.Mvc.OkObjectResult in 516.8129ms.
2019-01-18 11:23:00.040 +00:00 [INF] Executing ObjectResult, writing value of type '{apiname}.{controller}.{method}.MessageResult'.
2019-01-18 11:23:00.048 +00:00 [INF] Executed action {apiname}.{controller}.{method}.PollForStatusUpdate ({apiname}) in 813.08940000000007ms

File 2: Stack trace, server information:

2019-01-18 11:22:52.903 +00:00 [INF] User profile is available. Using 'C:\Users\msharp\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
2019-01-18 11:22:54.263 +00:00 [INF] Request starting HTTP/1.1 GET https://localhost:5001/swagger/index.html  
2019-01-18 11:22:54.473 +00:00 [INF] Request finished in 211.831ms 200 text/html
2019-01-18 11:22:54.737 +00:00 [INF] Request starting HTTP/1.1 GET https://localhost:5001/swagger/v1/swagger.json  
2019-01-18 11:22:54.838 +00:00 [INF] Request finished in 100.8892ms 200 application/json;charset=utf-8
2019-01-18 11:22:59.205 +00:00 [INF] Request starting HTTP/1.1 POST https://localhost:5001/api/StatusMessage/PollForStatusUpdate application/json-patch+json 180
2019-01-18 11:22:59.229 +00:00 [INF] Route matched with {action = "PollForStatusUpdate", controller = "StatusMessage"}. Executing action PureValuationsApi.Controllers.StatusMessageController.PollForStatusUpdate (PureValuationsApi)
2019-01-18 11:22:59.505 +00:00 [INF] Executing action method {apiname}.{controller}.{method}.PollForStatusUpdate ({apiname}) with arguments (["{apiname}.{controller}.{method}.MessageResult"]) - Validation state: "Valid"
2019-01-18 11:22:59.632 +00:00 [INF] //Some custom lof information
2019-01-18 11:22:59.639 +00:00 [INF] //Some more custom log information
{apiname}.{controller}.{method}.PollForStatusUpdate ({apiname}), returned result Microsoft.AspNetCore.Mvc.OkObjectResult in 516.8129ms.
2019-01-18 11:23:00.040 +00:00 [INF] Executing ObjectResult, writing value of type '{apiname}.{controller}.{method}.MessageResult'.
2019-01-18 11:23:00.048 +00:00 [INF] Executed action {apiname}.{controller}.{method}.PollForStatusUpdate ({apiname}) in 813.08940000000007ms
2019-01-18 11:23:00.052 +00:00 [INF] Request finished in 847.5964ms 200 application/json; charset=utf-8

So, by applying what feels the same technique, the outcome of the results are different as File 1 now contains more action information and File 2 contains the stack plus the custom log information although I want them completely separate.

Answer 1

I think your filters are not quite right.

The filter expression should be :

"expression": "SourceContext = 'Microsoft' or StartsWith(SourceContext, 'Microsoft.')"

(I guess you could just do StartsWith(SourceContext, 'Microsoft') without the last dot , but then that may not behave properly for namespaces like MicrosoftOrIsItReally.MyNamespace)

(internally Matching.ForSource does a SourceContext.StartsWith(..) kind of filtering , as seen in the source)

To confirm it, you may want to edit the outputTemplate of your File sink to display the SourceContext property and see the origin of the log events. (the default is "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}") . You could change it to "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}]<{SourceContext}> {Message:lj}{NewLine}{Exception}" to include the SourceContext property.

---

By the way, you have an extra, unneeded "Using" directive. The "Serilog.Settings.Configuration" is not necessary