Index Wildcards don't appear to work for Dictionaries stored in the event properties

[hobwell]

I'm using Serilog.Expressions (3.4.0) to try to filter SQL injection attacks appearing in the query string. I've enriched the log event with the query string as a dictionary. It appears in the log event as:

QueryString: {
    someKey: "UNION ALL SELECT NULL,NULL,NULL,NULL,NULL,NULL,NULL#"
}

I can successfully filter by specifying the key:

QueryString['someKey'] like '%UNION ALL SELECT%' ci

However, if I change the index to the "any" wildcard, the expression no longer matches the log event (and therefore isn't filtered):

QueryString[?] like '%UNION ALL SELECT%' ci

[nblumhardt]

Thanks for the note @hobwell ; I tried adding tests to reproduce this and didn't have any luck:

https://github.com/serilog/serilog-expressions/pull/77

Are you using the latest version of this package? Any other clues that might narrow it down? Cheers!

[hobwell]

Thanks for looking into this. I am using the latest version of this package (3.4.0) along with the latest SeriLog version (2.11.0). If it matters, we are using an older version of SeriLog.Sinks.MsSqlServer (5.4.0).

Could it be an issue with my setup? Apologies if this is too much information.

This is the method I call to initialize the logger:

private static void SetLogger() {
    LoggingLevelSwitch LevelSwitch = new LoggingLevelSwitch();
    LevelSwitch.MinimumLevel = Serilog.Events.LogEventLevel.Debug;
    LoggerConfiguration config = new LoggerConfiguration()
        .Destructure.JsonNetTypes()
        .MinimumLevel.ControlledBy(LevelSwitch)
        .Enrich.FromLogContext()
        .Enrich.With(new ExceptionEnricher());

    //This compiles the current list of filters into a single large filter string e.g. "(QueryString[?] like '%UNION ALL SELECT%' ci) or (QueryString[?] like '%DROP TABLE%' ci) or (Contains(@x, 'System.InvalidOperationException: The requested resource can only be accessed via SSL') ci)" etc.
    _FilterExpression = ExceptionFilters.CompileFilter(); //returns an empty string where not supported

    //output logging to debug window when debugging
    if (Debugger.IsAttached) {
        //This is how I was testing if the expression matched the event log while debugging.  Seeing False was always associated with an event being logged.
        string ExpressionDebugTemplate = "Expression Match: {#if @expression}True{#else}False{#end}\n@expression\n".Replace("@expression", FilterExpression);
        LevelSwitch.MinimumLevel = Serilog.Events.LogEventLevel.Verbose;
        config =  config.WriteTo.Debug(new ExpressionTemplate(ExpressionDebugTemplate), restrictedToMinimumLevel: Serilog.Events.LogEventLevel.Verbose, levelSwitch: null);
    }

    if (string.IsNullOrWhiteSpace(_FilterExpression)) { 
        //there is no filter, or filters aren't supported
        config = config.WriteTo.Logger(lc => lc.WriteTo.MSSqlServer(
                connectionString: ConnectionString,
                sinkOptions: SinkOptions,
                columnOptions: ColumnOptions
            )
        );
    } else { 
        //there is a filter, apply it
        //configure as a logger instead of an MSSqlServer sink directly so that we can apply the exception filter only to the database, while allowing the debug sink to always recieve logs (even if they were excluded by the filter)
        config = config.WriteTo.Logger(lc => lc.Filter.ByExcluding(_FilterExpression).WriteTo.MSSqlServer(
                connectionString: ConnectionString,
                sinkOptions: SinkOptions,
                columnOptions: ColumnOptions
            )
        );
    }

    Logger = config.CreateLogger();
}

The only other thing I can think of is that perhaps I'm enriching the log in a way that prevents the wildcard from working.

Enricher adds the querystring in this block:

...
string[] httpContextPropertyNames = { "Application", "Cookies", "Form", "Headers", "QueryString", "ServerVariables", "Session" };
foreach (string propertyName in httpContextPropertyNames) {
    try {
        logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
            propertyName,
            typeof(HttpContextHelper).GetProperty(propertyName).GetValue(null, null)
        ));
    } catch (Exception ex) {
        logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
            propertyName,
            ex
        ));
    }
}
...

Where the properties are defined in HttpContextHelper like so:

public static Dictionary<string, object> QueryString {
    get {
        return NameValueCollectionToDictionary(Current.Request.QueryString);
    }
}

And the collection converter:

private static Dictionary<string, object> NameValueCollectionToDictionary(NameValueCollection collection) {
    var result = new Dictionary<string, object>();

    // We loop by index instead of through collection.Keys because some keys can be null (ie a querystring like /Page?LFE_HASH&x=1 will have
    // a null key with value "LFE_HASH" and a "x" key with value "1"
    for (int i = 0; i < collection.Count; i++) {
        string key = collection.Keys[i] ?? "null key";
        object value = key.ToLower().Contains("password") ? "*redacted*" : collection[i];
        result.Add(key, value);
    }

    return result;
}

[nblumhardt]

Thanks for the extra details. Something doesn't look right here - as far as I can tell, the propertyFactory.CreateProperty() call is just serializing your dictionary to a string, rather than as a structured object (which it would if destructureObjects: true was passed). Paring the whole thing down to a very minimal repro (e.g. in a console app that logs out JSON so you can easily inspect it) should identify the problem. Hope this helps!

[hobwell]

Thank you for your patience!

As far as I can tell, setting the destructureObjects flag doesn't seem to have any effect on how the dictionary is serialized. The log event serializes the same either way:

{
    "Timestamp": "2022-09-12T16:59:51.8034964-04:00",
    "Level": 4,
    "MessageTemplate": {
        "Text": "Test",
        "Tokens": [
            {
                "Length": 4,
                "Text": "Test",
                "StartIndex": 0
            }
        ]
    },
    "Properties": {
        "QueryString": {
            "Elements": {
                "\"x\"": {
                    "Value": "NULL"
                },
                "\"y\"": {
                    "Value": "DROP"
                }
            }
        }
    },
    "Exception": null
}

The escaped quotes around the x and y keys looks unusual to me, is that expected?

I've created a minimal reproduction of the issue: here.

[nblumhardt]

I tried running the repro but unfortunately I'm not on a machine with old-style CSPROJ support ... Here's what I'd planned to try:

Instead of writing the log events out with JSON.NET (which doesn't know anything about how Serilog properties are structured; the Destructurama.JsonNet package works the opposite way and makes Serilog aware of JSON.NET types), use:

    .WriteTo.Console(new ExpressionTemplate("{@p}\n"))

This will give you Serilog's view of the data. HTH!

[hobwell]

Many thanks!

The output still generates the same, with or without the destructure flag:

QueryString[?] like '%DROP%' ci: False

QueryString['y'] like '%DROP%' ci: True

{"QueryString":{"x":"NULL","y":"DROP"}}

I'm not really sure what's going on. This looks like it should work, no?

[hobwell]

It seems relevant to mention that we're running on .NET Framework (4.6.2 and up).

[hobwell]

I've recreated the minimal reproduction as a .NET 6 console app here

[nblumhardt]

Awesome, thanks! I've got it - it's a bug :+1:

Will PR a fix and link it here.

[nblumhardt]

The fix for this is in 3.4.1-dev-00095; if you're able to test it out, it should be quick and easy to make an RTM from there. Thanks!

[hobwell]

That did the trick! Many many thanks! ♥

QueryString[?] like '%DROP%' ci: True

QueryString['y'] like '%DROP%' ci: True

{"QueryString":{"x":"NULL","y":"DROP"}}

[nblumhardt]

Awesome, thanks :+1: