This is an automated email from the ASF dual-hosted git repository. FreeAndNil pushed a commit to branch Feature/317-filters in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
commit 27a0548638e7580d70b3b8d998e5a2061fbab107 Author: Jan Friedrich <[email protected]> AuthorDate: Fri Sep 4 00:06:35 2026 +0200 decide filter matches deterministically #317 - Substring matching was culture sensitive, so a NUL, soft hyphen or zero-width space inside StringToMatch still matched. Ordinal now. - An abandoned regex match counted as a non-match, so content that forced the timeout could suppress its own record. TimeoutDecision decides it, still Neutral by default. - Default deadline 1000ms to 50ms. The match holds the appender lock. - StringMatchFilter and PropertyFilter had near-identical Decide bodies, which is why each finding existed twice. Shared now. audit da18b6fd-f017, da18b6fd-f018, da18b6fd-f041 --- .../3.5.0/317-filter-ordinal-substring.xml | 12 ++ .../3.5.0/317-filter-timeout-decision.xml | 13 ++ src/changelog/3.5.0/317-filter-timeout-default.xml | 12 ++ src/log4net.Tests/Filter/PropertyFilterTest.cs | 119 +++++++++++++++++ src/log4net.Tests/Filter/StringMatchFilterTest.cs | 70 +++++++++- src/log4net/Filter/PropertyFilter.cs | 39 +----- src/log4net/Filter/StringMatchFilter.cs | 146 ++++++++++++--------- 7 files changed, 310 insertions(+), 101 deletions(-) diff --git a/src/changelog/3.5.0/317-filter-ordinal-substring.xml b/src/changelog/3.5.0/317-filter-ordinal-substring.xml new file mode 100644 index 00000000..46f85331 --- /dev/null +++ b/src/changelog/3.5.0/317-filter-ordinal-substring.xml @@ -0,0 +1,12 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xmlns="https://logging.apache.org/xml/ns"; + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"; + type="fixed"> + <issue id="317" link="https://github.com/apache/logging-log4net/pull/317"/> + <description format="asciidoc">Compare `StringToMatch` ordinally in `StringMatchFilter` and `PropertyFilter`. + The substring search was culture sensitive, and a linguistic search skips ignorable characters, so + content holding a NUL, a soft hyphen or a zero-width space between the letters of the configured + text still matched it, and the decision varied with the host culture. The filter now decides the + same way a reader of the log would (audit da18b6fd-f018, fixed by @FreeAndNil)</description> +</entry> diff --git a/src/changelog/3.5.0/317-filter-timeout-decision.xml b/src/changelog/3.5.0/317-filter-timeout-decision.xml new file mode 100644 index 00000000..1e6e88c2 --- /dev/null +++ b/src/changelog/3.5.0/317-filter-timeout-decision.xml @@ -0,0 +1,13 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xmlns="https://logging.apache.org/xml/ns"; + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"; + type="added"> + <issue id="317" link="https://github.com/apache/logging-log4net/pull/317"/> + <description format="asciidoc">`TimeoutDecision` on `StringMatchFilter` and `PropertyFilter`, deciding an + event whose regular expression match was abandoned. An abandoned match was treated as a non-match, + but the content decides whether the deadline is reached, so in an `AcceptOnMatch` allowlist + followed by a deny-all it let content suppress its own record. The default stays `Neutral`; + `Accept` makes such a chain fail towards logging (audit da18b6fd-f017, implemented by + @FreeAndNil)</description> +</entry> diff --git a/src/changelog/3.5.0/317-filter-timeout-default.xml b/src/changelog/3.5.0/317-filter-timeout-default.xml new file mode 100644 index 00000000..aed27a53 --- /dev/null +++ b/src/changelog/3.5.0/317-filter-timeout-default.xml @@ -0,0 +1,12 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xmlns="https://logging.apache.org/xml/ns"; + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"; + type="changed"> + <issue id="317" link="https://github.com/apache/logging-log4net/pull/317"/> + <description format="asciidoc">The default `MatchTimeoutMillis` on `StringMatchFilter` and + `PropertyFilter` is now 50 instead of 1000. The match runs while the appender lock is held, so the + deadline is the bound on how long one crafted event can stall everything logging through the + appender. A legitimate match over an event takes a fraction of 50ms; raise the property if a + pattern genuinely needs longer (audit da18b6fd-f041, implemented by @FreeAndNil)</description> +</entry> diff --git a/src/log4net.Tests/Filter/PropertyFilterTest.cs b/src/log4net.Tests/Filter/PropertyFilterTest.cs new file mode 100644 index 00000000..c77b447b --- /dev/null +++ b/src/log4net.Tests/Filter/PropertyFilterTest.cs @@ -0,0 +1,119 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +using System; + +using log4net.Core; +using log4net.Filter; +using log4net.Repository; +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Filter; + +/// <summary> +/// Tests for <see cref="PropertyFilter"/>, which decides a property value through the same +/// matching as <see cref="StringMatchFilter"/>. +/// </summary> +[TestFixture] +public class PropertyFilterTest +{ + private const string Key = "user"; + + /// <summary> + /// A pattern that backtracks, with a value that makes it do so. + /// </summary> + private const string CatastrophicPattern = "^(a+)+$"; + + private const string CraftedValue = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"; + + /// <summary> + /// A property value is content too, so an ignorable character must not force a match here + /// either. + /// </summary> + [TestCase("\0", TestName = "ANulDoesNotForceAPropertyMatch")] + [TestCase("", TestName = "ASoftHyphenDoesNotForceAPropertyMatch")] + public void AnIgnorableCharacterDoesNotForceAPropertyMatch(string ignorable) + { + PropertyFilter filter = new() { Key = Key, StringToMatch = "admin", AcceptOnMatch = true }; + filter.ActivateOptions(); + + Assert.That(filter.Decide(CreateEvent($"adm{ignorable}in")), Is.EqualTo(FilterDecision.Neutral)); + } + + /// <summary> + /// The exact value still decides, so the ordinal comparison has not broken the filter. + /// </summary> + [Test] + public void AnExactPropertyValueStillMatches() + { + PropertyFilter filter = new() { Key = Key, StringToMatch = "admin", AcceptOnMatch = false }; + filter.ActivateOptions(); + + Assert.That(filter.Decide(CreateEvent("admin")), Is.EqualTo(FilterDecision.Deny)); + Assert.That(filter.Decide(CreateEvent("guest")), Is.EqualTo(FilterDecision.Neutral)); + } + + /// <summary> + /// An abandoned match is decided the same way as in the base filter. + /// </summary> + [Test] + public void AnAbandonedPropertyMatchHonoursTimeoutDecision() + { + PropertyFilter filter = new() + { + Key = Key, + RegexToMatch = CatastrophicPattern, + MatchTimeoutMillis = 50, + TimeoutDecision = FilterDecision.Accept + }; + filter.ActivateOptions(); + + FilterDecision decision = FilterDecision.Neutral; + LogLog.ExecuteWithoutEmittingInternalMessages(() => decision = filter.Decide(CreateEvent(CraftedValue))); + + Assert.That(decision, Is.EqualTo(FilterDecision.Accept)); + } + + /// <summary> + /// Without a key there is nothing to look up, so the chain continues. + /// </summary> + [Test] + public void AFilterWithoutAKeyIsNeutral() + { + PropertyFilter filter = new() { StringToMatch = "admin" }; + filter.ActivateOptions(); + + Assert.That(filter.Decide(CreateEvent("admin")), Is.EqualTo(FilterDecision.Neutral)); + } + + /// <summary> + /// Builds an event carrying <paramref name="value"/> under <see cref="Key"/>. The filter renders + /// the property through the repository, so the event needs one. + /// </summary> + private static LoggingEvent CreateEvent(string value) + { + ILoggerRepository repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + LoggingEventData data = new() { Level = Level.Info, Message = "TestMessage", LoggerName = "TestLogger" }; + LoggingEvent loggingEvent = new(null, repository, data); + loggingEvent.Properties[Key] = value; + return loggingEvent; + } +} diff --git a/src/log4net.Tests/Filter/StringMatchFilterTest.cs b/src/log4net.Tests/Filter/StringMatchFilterTest.cs index ff3eced6..641d58fa 100644 --- a/src/log4net.Tests/Filter/StringMatchFilterTest.cs +++ b/src/log4net.Tests/Filter/StringMatchFilterTest.cs @@ -50,7 +50,7 @@ public class StringMatchFilterTest [Test] public void AMatchThatBacktracksIsAbandoned() { - StringMatchFilter filter = new() { RegexToMatch = CatastrophicPattern, MatchTimeoutMillis = 100 }; + StringMatchFilter filter = new() { RegexToMatch = CatastrophicPattern, MatchTimeoutMillis = 50 }; filter.ActivateOptions(); Stopwatch stopwatch = Stopwatch.StartNew(); @@ -70,7 +70,7 @@ public void AMatchThatBacktracksIsAbandoned() [NonParallelizable] public void AnAbandonedMatchIsReportedOnce() { - StringMatchFilter filter = new() { RegexToMatch = CatastrophicPattern, MatchTimeoutMillis = 100 }; + StringMatchFilter filter = new() { RegexToMatch = CatastrophicPattern, MatchTimeoutMillis = 50 }; filter.ActivateOptions(); List<LogLog> messages = []; @@ -101,12 +101,72 @@ public void AMatchingPatternStillDecides() } /// <summary> - /// The deadline has to be finite by default, so that an expensive pattern cannot hold the - /// appender lock indefinitely without the operator having opted into that. + /// The deadline bounds how long one crafted event holds the appender lock, so it has to be + /// finite by default and short enough to matter. /// </summary> [Test] public void MatchTimeoutMillisDefaultsToAFiniteValue() - => Assert.That(new StringMatchFilter().MatchTimeoutMillis, Is.EqualTo(1000)); + => Assert.That(new StringMatchFilter().MatchTimeoutMillis, Is.EqualTo(50)); + + /// <summary> + /// An abandoned match leaves the chain to decide unless the operator says otherwise, so the + /// default has to stay Neutral. + /// </summary> + [Test] + public void TimeoutDecisionDefaultsToNeutral() + => Assert.That(new StringMatchFilter().TimeoutDecision, Is.EqualTo(FilterDecision.Neutral)); + + /// <summary> + /// The content decides whether the deadline is reached, so an allowlist that treats an abandoned + /// match as a non-match lets content suppress its own record. TimeoutDecision is how such a + /// chain fails towards logging instead. + /// </summary> + [TestCase(FilterDecision.Deny, TestName = "AnAbandonedMatchIsDecidedByTimeoutDecisionDeny")] + [TestCase(FilterDecision.Accept, TestName = "AnAbandonedMatchIsDecidedByTimeoutDecisionAccept")] + [TestCase(FilterDecision.Neutral, TestName = "AnAbandonedMatchIsDecidedByTimeoutDecisionNeutral")] + public void AnAbandonedMatchIsDecidedByTimeoutDecision(FilterDecision timeoutDecision) + { + StringMatchFilter filter = new() + { + RegexToMatch = CatastrophicPattern, + MatchTimeoutMillis = 50, + TimeoutDecision = timeoutDecision + }; + filter.ActivateOptions(); + + FilterDecision decision = FilterDecision.Accept; + LogLog.ExecuteWithoutEmittingInternalMessages(() => decision = filter.Decide(CreateEvent(CraftedMessage))); + + Assert.That(decision, Is.EqualTo(timeoutDecision)); + } + + /// <summary> + /// A linguistic search skips ignorable characters, so content could otherwise force a substring + /// match that no ordinal reader of the same log would make. + /// </summary> + [TestCase("\0", TestName = "ANulDoesNotForceASubstringMatch")] + [TestCase("", TestName = "ASoftHyphenDoesNotForceASubstringMatch")] + [TestCase("", TestName = "AZeroWidthSpaceDoesNotForceASubstringMatch")] + public void AnIgnorableCharacterDoesNotForceASubstringMatch(string ignorable) + { + StringMatchFilter filter = new() { StringToMatch = "password", AcceptOnMatch = true }; + filter.ActivateOptions(); + + Assert.That(filter.Decide(CreateEvent($"pass{ignorable}word")), Is.EqualTo(FilterDecision.Neutral)); + } + + /// <summary> + /// The ordinal comparison must not break the match it exists to protect. + /// </summary> + [Test] + public void AnExactSubstringStillMatches() + { + StringMatchFilter filter = new() { StringToMatch = "password", AcceptOnMatch = true }; + filter.ActivateOptions(); + + Assert.That(filter.Decide(CreateEvent("a password here")), Is.EqualTo(FilterDecision.Accept)); + Assert.That(filter.Decide(CreateEvent("nothing here")), Is.EqualTo(FilterDecision.Neutral)); + } /// <summary> /// 0 is the documented opt-out that restores unbounded matching; a negative deadline has no diff --git a/src/log4net/Filter/PropertyFilter.cs b/src/log4net/Filter/PropertyFilter.cs index c487682b..d22638ed 100644 --- a/src/log4net/Filter/PropertyFilter.cs +++ b/src/log4net/Filter/PropertyFilter.cs @@ -76,46 +76,11 @@ public override FilterDecision Decide(LoggingEvent loggingEvent) return FilterDecision.Neutral; } - // Lookup the string to match in from the properties using + // Lookup the string to match in from the properties using // the key specified. object? msgObj = loggingEvent.LookupProperty(Key); // Use an ObjectRenderer to convert the property value to a string - string? msg = loggingEvent.Repository?.RendererMap.FindAndRender(msgObj); - - // Check if we have been setup to filter - if (msg is null || (StringToMatch is null && m_regexToMatch is null)) - { - // We cannot filter so allow the filter chain - // to continue processing - return FilterDecision.Neutral; - } - - // Firstly check if we are matching using a regex - if (m_regexToMatch is not null) - { - // Check the regex - if (!IsRegexMatch(msg)) - { - // No match, continue processing - return FilterDecision.Neutral; - } - - // we've got a match - return AcceptOnMatch ? FilterDecision.Accept : FilterDecision.Deny; - } - else if (StringToMatch is not null) - { - // Check substring match - if (msg.IndexOf(StringToMatch) == -1) - { - // No match, continue processing - return FilterDecision.Neutral; - } - - // we've got a match - return AcceptOnMatch ? FilterDecision.Accept : FilterDecision.Deny; - } - return FilterDecision.Neutral; + return DecideOnValue(loggingEvent.Repository?.RendererMap.FindAndRender(msgObj)); } } diff --git a/src/log4net/Filter/StringMatchFilter.cs b/src/log4net/Filter/StringMatchFilter.cs index d0c79c42..06a525da 100644 --- a/src/log4net/Filter/StringMatchFilter.cs +++ b/src/log4net/Filter/StringMatchFilter.cs @@ -76,16 +76,18 @@ public override void ActivateOptions() /// <para> /// A regular expression that backtracks can take a very long time on some inputs. The pattern is /// matched while the appender lock is held, so an unbounded match would stall everything logging - /// through the appender, and matching is therefore given a deadline. A match that reaches it is - /// treated as no match, leaving the rest of the filter chain to decide. + /// through the appender, and matching is therefore given a deadline. <see cref="TimeoutDecision"/> + /// decides an event whose match is abandoned. /// </para> /// <para> - /// The pattern comes from configuration and is trusted, so this is a guard against a pattern that - /// turns out to be expensive rather than protection against untrusted input. + /// The pattern comes from configuration and is trusted, but the content it is matched against is + /// not, and the content decides whether the deadline is reached. This is therefore the bound on + /// how long one crafted event can hold the appender lock. /// </para> /// <para> - /// The default value is 1000 (one second). Setting the value to 0 restores unbounded matching and - /// is not recommended. Changing it takes effect when <see cref="ActivateOptions"/> is called. + /// The default value is 50. A legitimate match over an event runs in a fraction of that; raise it + /// if a pattern genuinely needs longer. Setting the value to 0 restores unbounded matching and is + /// not recommended. Changing it takes effect when <see cref="ActivateOptions"/> is called. /// </para> /// </remarks> /// <exception cref="ArgumentOutOfRangeException">The value specified is negative.</exception> @@ -103,9 +105,34 @@ public int MatchTimeoutMillis } } - private int _matchTimeoutMillis = 1000; + private int _matchTimeoutMillis = 50; private bool _matchTimeoutReported; + /// <summary> + /// Gets or sets the decision for an event whose match was abandoned because it reached + /// <see cref="MatchTimeoutMillis"/>. + /// </summary> + /// <remarks> + /// <para> + /// An abandoned match is not a non-match: the content being matched decides whether the deadline + /// is reached, so treating it as "did not match" lets content choose its own outcome. In an + /// <see cref="AcceptOnMatch"/> allowlist followed by a deny-all, that means content can suppress + /// its own record. + /// </para> + /// <para> + /// The default is <see cref="FilterDecision.Neutral"/>, which leaves the rest of the chain to + /// decide. Set <see cref="FilterDecision.Accept"/> to make an allowlist fail towards logging, or + /// <see cref="FilterDecision.Deny"/> in a deny-on-match chain. No one direction is right for + /// every chain, which is why this is configured rather than chosen here. + /// </para> + /// </remarks> + public FilterDecision TimeoutDecision { get; set; } = FilterDecision.Neutral; + + /// <summary> + /// The decision a match produces, per <see cref="AcceptOnMatch"/>. + /// </summary> + private FilterDecision MatchDecision => AcceptOnMatch ? FilterDecision.Accept : FilterDecision.Deny; + /// <summary> /// Matches <paramref name="value"/> against <see cref="m_regexToMatch"/>. /// </summary> @@ -114,27 +141,74 @@ public int MatchTimeoutMillis /// <see langword="true"/> when the pattern matches, and <see langword="false"/> when it does not /// or when matching took longer than <see cref="MatchTimeoutMillis"/>. /// </returns> - protected bool IsRegexMatch(string value) + protected bool IsRegexMatch(string value) => TryRegexMatch(value, out bool isMatch) && isMatch; + + /// <summary> + /// Decides <paramref name="value"/> on the pattern, honouring <see cref="TimeoutDecision"/>. + /// </summary> + /// <param name="value">The text to match.</param> + /// <returns>The decision for the event the text came from.</returns> + protected FilterDecision DecideRegexMatch(string value) + => TryRegexMatch(value, out bool isMatch) + ? isMatch + ? MatchDecision + : FilterDecision.Neutral + : TimeoutDecision; + + /// <summary> + /// Matches <paramref name="value"/>, reporting an abandoned match once per filter. + /// </summary> + /// <returns><see langword="false"/> when the match was abandoned.</returns> + private bool TryRegexMatch(string value, out bool isMatch) { try { - return m_regexToMatch!.IsMatch(value); + isMatch = m_regexToMatch!.IsMatch(value); + return true; } catch (RegexMatchTimeoutException) { + isMatch = false; if (!_matchTimeoutReported) { // Once per filter. The condition repeats for every event that reaches it, and a warning // per event would be a denial of service of its own. _matchTimeoutReported = true; LogLog.Warn(_declaringType, - $"Matching the pattern [{RegexToMatch}] took longer than {MatchTimeoutMillis}ms and was abandoned, so the event was not filtered by it. " - + "A pattern that backtracks can take arbitrarily long on some inputs; consider rewriting it or raising MatchTimeoutMillis."); + $"Matching the pattern [{RegexToMatch}] took longer than {MatchTimeoutMillis}ms and was abandoned, so the event was decided as {TimeoutDecision}. " + + "A pattern that backtracks can take arbitrarily long on some inputs; consider rewriting it, raising MatchTimeoutMillis or setting TimeoutDecision."); } return false; } } + /// <summary> + /// Decides <paramref name="value"/> on <see cref="RegexToMatch"/> or <see cref="StringToMatch"/>. + /// </summary> + /// <param name="value">The text to match, or <see langword="null"/> when there is none.</param> + /// <returns> + /// <see cref="FilterDecision.Neutral"/> when there is nothing to match or nothing to match it + /// against, otherwise the decision for the event the text came from. + /// </returns> + protected FilterDecision DecideOnValue(string? value) + { + if (value is null) + { + return FilterDecision.Neutral; + } + + if (m_regexToMatch is not null) + { + return DecideRegexMatch(value); + } + + // Ordinal: a linguistic search skips ignorable characters, so content holding a NUL, a soft + // hyphen or a combining mark could otherwise flip the decision. + return StringToMatch is not null && value.IndexOf(StringToMatch, StringComparison.Ordinal) >= 0 + ? MatchDecision + : FilterDecision.Neutral; + } + /// <summary> /// The fully qualified type of the <see cref="StringMatchFilter"/> class. /// </summary> @@ -207,52 +281,6 @@ protected bool IsRegexMatch(string value) /// <see cref="FilterDecision.Deny"/> is returned. /// </para> /// </remarks> - public override FilterDecision Decide(LoggingEvent loggingEvent) - { - string? msg = loggingEvent.EnsureNotNull().RenderedMessage; - - // Check if we have been setup to filter - if (msg is null || (StringToMatch is null && m_regexToMatch is null)) - { - // We cannot filter so allow the filter chain - // to continue processing - return FilterDecision.Neutral; - } - - // Firstly check if we are matching using a regex - if (m_regexToMatch is not null) - { - // Check the regex - if (!IsRegexMatch(msg)) - { - // No match, continue processing - return FilterDecision.Neutral; - } - - // we've got a match - if (AcceptOnMatch) - { - return FilterDecision.Accept; - } - return FilterDecision.Deny; - } - else if (StringToMatch is not null) - { - // Check substring match - if (msg.IndexOf(StringToMatch) == -1) - { - // No match, continue processing - return FilterDecision.Neutral; - } - - // we've got a match - if (AcceptOnMatch) - { - return FilterDecision.Accept; - } - return FilterDecision.Deny; - } - - return FilterDecision.Neutral; - } + public override FilterDecision Decide(LoggingEvent loggingEvent) + => DecideOnValue(loggingEvent.EnsureNotNull().RenderedMessage); }
