Not filtering by property

[zachrybaker]

Description With 4.0 Upgrade, filtering by code stopped working (smoking gun?) So I took a stab at filtering by configuration, using this project along with appsettings.json package. I have not been able to get the configuration to respect my filter json configuration, after careful reading of the readme.

Reproduction

string shadow_requestSeparator  = "";
public static ShadowLogInfo LogRequest(string programName, dynamic parameters = null)
{
    ShadowLogInfo shadowLogInfo = new ShadowLogInfo(programName); // POCO

    var event_type = "shadow";

    Log.Information("{@shadow_requestSeparator}{\n\t\"Request\": {\n\t\t\"ProgramInfo\": {@shadowLogInfo},\n\t\t\"CallData\":{@parameters},\n\t\t\"EventType\":\"{@event_type}\"\n\t}",  
        shadow_requestSeparator, shadowLogInfo, parameters, event_type);

    if (shadow_requestSeparator == "")
        shadow_requestSeparator = ",";

    return shadowLogInfo;
}

log configuration json:

{
  "Serilog": {
    "Using": [
      "Serilog",
      "Serilog.Sinks.Async",
      "Serilog.Sinks.Console",
      "Serilog.Sinks.Debug",
      "Serilog.Sinks.File",
      "Serilog.Enrichers.Context",
      "Serilog.Enrichers.Environment",
      "Serilog.Enrichers.Process",
      "Serilog.Enrichers.Thread",
      "Serilog.Exceptions",
      "Serilog.Exceptions.EntityFrameworkCore",
      "Serilog.Exceptions.SqlServer",
      "Serilog.Formatting.Compact",
      "Serilog.Settings.Configuration",
      "ESILogging.Core",
      "Serilog.Expressions"
    ],
    "Enrich": [ "FromLogContext", "WithThreadId", "WithThreadName" ],
    // https://github.com/RehanSaeed/Serilog.Exceptions -> should make destructuring faster.
    "Destructure": [
      {
        "Name": "ToMaximumDepth",
        "Args": { "maximumDestructuringDepth": 4 }
      },
      {
        "Name": "ToMaximumStringLength",
        "Args": { "maximumStringLength": 200 }
      },
      {
        "Name": "ToMaximumCollectionCount",
        "Args": { "maximumCollectionCount": 20 }
      }
    ],
    "MinimumLevel": {
      "Default": "Verbose",
      "Override": {
        "Microsoft": "Warning",
        "Microsoft.Hosting.Lifetime": "Information",
        "System": "Warning",
        "Microsoft.AspNetCore": "Warning", // tame HTTP logging from aspnetcore.
        "EsiServices.WebApi_NetStandard.Core.MiddleWare.HmacAuthenticationMiddleware": "Information"
      }
    },
    "WriteTo": [
      {
        "Name": "Async",
        "Args": {
          "configure": [
            {
              "Name": "Debug",
              "Args": {
                "outputTemplate": "[{Timestamp:HH:mm:ss} {Level:u5} s:{SourceContext} <{ThreadId}><{ThreadName}>] {Message:lj} {NewLine}{Exception} {Properties:j}{NewLine}"
              }
            },
            {
              "Name": "Console",
              "Args": {
                "outputTemplate": "[{Timestamp:HH:mm:ss} {Level:u5} s:{SourceContext} <{ThreadId}><{ThreadName}>] {Message:lj} {NewLine}{Exception} {Properties:j}{NewLine}"
              }
            },
            {
              "Name": "Logger",
              "Args": {
                "configureLogger": {
                  "Filter": [
                    {
                      "Name": "ByExcluding",
                      "Args": {
                        "expression": "@p['event-type'] in ['shadow', '\"shadow\"','audit', '\"audit\"']"
                      }
                    }
                  ],
                  "WriteTo": [
                    {
                      "Name": "File",
                      "Args": {
                        "path": "C:\\AppLogFiles\\Canopy.Next\\App\\CanopyNextApp.log",
                        "outputTemplate": "{NewLine}{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz}{NewLine} [{Level:u3}] {Message:lj}{NewLine}{Exception}{Properties:lj}",
                        "fileSizeLimitBytes": 2097152,
                        "buffered": false,
                        "rollOnFileSizeLimit": true,
                        "retainedFileCountLimit": 10000000
                      }
                    }
                  ]
                }
              }
            },
            {
              "Name": "Logger",
              "Args": {
                "configureLogger": {
                  "Filter": [
                    {
                      "Name": "ByIncludingOnly",
                      "Args": {
                        "expression": "@p['event-type'] in ['shadow', '\"shadow\"']"
                      }
                    }
                  ],
                  "WriteTo": [
                    {
                      "Name": "File",
                      "Args": {
                        "path": "C:\\AppLogFiles\\Canopy.Next\\Shadow\\Shadow.log",
                        "outputTemplate": "{Message:lj}{Exception}{NewLine}",
                        "fileSizeLimitBytes": 2097152,
                        "buffered": false,
                        "rollOnFileSizeLimit": true,
                        "retainedFileCountLimit": 10000000
                      }
                    }
                  ]
                }
              }
            },
            {
              "Name": "Logger",
              "Args": {
                "configureLogger": {
                  "Filter": [
                    {
                      "Name": "ByIncludingOnly",
                      "Args": {
                        "expression": "@p['event-type'] in['audit', '\"audit\"']"
                      }
                    }
                  ],
                  "WriteTo": [
                    {
                      "Name": "File",
                      "Args": {
                        "path": "C:\\AppLogFiles\\Canopy.Next\\Audit\\CanopyNextAuditLog.log",
                        "outputTemplate": "{Message:lj}{Exception}{NewLine}",
                        "fileSizeLimitBytes": 2097152,
                        "buffered": false,
                        "rollOnFileSizeLimit": true,
                        "retainedFileCountLimit": 10000000
                      }
                    }
                  ]
                }
              }
            }
          ]
        }
      }
    ]
  }
}

this will return the log in the wrong file, also formatted very wrongly (note the miss on the 2nd parameter):

2024-09-09 15:22:05.514 -05:00
 [INF] {
    "Request": {
        "ProgramInfo": {@shadowLogInfo},
        "CallData":{"Id":"8e91b973-6473-40f3-b3b2-50b46cba4e3f","Program":"ZNNPCCS","StartTimestamp":20424887337546,"EndTimestamp":null,"DurationMs":null,"StartDateString":"9/9/2024 3:22:05 PM","ShadowLibrary":null,"CanopyClass":null,"IPCRequestClass":null,"IPCResponseClass":null,"$type":"ShadowLogInfo"},
        "EventType":"{ callId = 3246d8b2-7234-426d-9b4a-103419494eb0, operUin = 701005790, racfId = K156AZB }"
    }

Expected behavior It would look like this if working correctly.

2024-09-09 15:22:05.514 -05:00
 {
    "Request": {
        "ProgramInfo": {"Id":"8e91b973-6473-40f3-b3b2-50b46cba4e3f","Program":"ZNNPCCS","StartTimestamp":20424887337546,"EndTimestamp":null,"DurationMs":null,"StartDateString":"9/9/2024 3:22:05 PM","ShadowLibrary":null,"CanopyClass":null,"IPCRequestClass":null,"IPCResponseClass":null,"$type":"ShadowLogInfo"},
        "CallData": { "callId": "3246d8b2-7234-426d-9b4a-103419494eb0", "operUin": "701005790", "racfId": "K156AZB" }
        "EventType": "shadow"
    }
}

Relevant package, tooling and runtime versions What Serilog version are you using, on what platform? 4.0.1 on Windows.

Additional context That Log entry worked fine with this below mix of appsettings-based and code-based configuration prior to 4.0:

private const string EventFilterKey = "event_type";
public static LoggerConfiguration ApplySerilogConfigurationAndFiltering(this LoggerConfiguration loggerConfiguration, 
    FileLoggingConfiguration cfg, AppVersion appVersion)
{
    loggerConfiguration.WriteTo.File(
        cfg.LogFilePath,
        cfg.LogEventLevel,
        cfg.MessageTemplate,
        null,
        cfg.FileSizeLimitBytes,
        null,
        cfg.Buffered,
        false,
        cfg._FlushToDiskInterval,
        cfg._RollingInterval,
        true,
        cfg.RetainedFileCountLimit);

    if (cfg.LoggingCategory == LoggingCategory.App)

        loggerConfiguration.Filter.ByIncludingOnly(f => {
            return !f.Properties.ContainsKey(EventFilterKey) ||
                f.Properties[EventFilterKey]?.ToString() ==
                $"\"{cfg.event_type}\"" ||
                f.Properties[EventFilterKey]?.ToString() ==
                cfg.event_type;
        });
    else
        loggerConfiguration.Filter.ByIncludingOnly(f => {
            return f.Properties.ContainsKey(EventFilterKey) && (
                f.Properties[EventFilterKey]?.ToString() ==
                $"\"{cfg.event_type}\"" ||
                f.Properties[EventFilterKey]?.ToString() ==
                cfg.event_type);
        });

    loggerConfiguration.EnrichWithBuildAndLocationAndEnvironment( appVersion,cfg.LogEventLevel );

    // stopped working in 4.0:
    //foreach(var levelOveride in cfg.LevelOverrides)
    //    loggerConfiguration.MinimumLevel.Override(levelOveride.Key, levelOveride.Value);

    return loggerConfiguration;
}

I have tried event-type, event_type etc in the property name DSL, to no avail.

[zachrybaker]

Note, I also tried explicitly pushing the property....to no avail. Hoping someone just sees an obvious configuration issue on my end!.

using (LogContext.PushProperty("event_type", event_type))
{
    Log.Information("{shadow_requestSeparator}{\n\t\"Request\": {\n\t\t\"ProgramInfo\": {@shadowLogInfo},\n\t\t\"CallData\":{@parameters},\n\t\t\"EventType\":\"{event_type}\"\n\t}",  
    shadow_requestSeparator, shadowLogInfo, parameters, event_type);
}

[nblumhardt]

Hi!

With 4.0 Upgrade, filtering by code stopped working (smoking gun?)

This will be an easier place to start investigating than the config example, which is a lot bulkier to dig through.

A minimal code-based repro (just Serilog and one sink) would help narrow this down. Getting everything into a single, minimal, Program.cs with nothing extra (no enrichers, no app-specific setup) is ideal. Thanks!

[zachrybaker]

Upgrading to 4.0, this property name became invalid: "event_type" I had used it for years, without complaint.

Changed it to EventType, all is well again.

[nblumhardt]

Thanks for the follow-up! event_type still works as a property name for me:

Log.Information("Test {event_type}", 2);

prints:

[09:19:58 INF] Test 2

• am I missing something? (This would be a bug, otherwise, I think.)