diff --git a/CLAUDE.md b/CLAUDE.md index 09b3b901..0e7bcaa2 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -149,6 +149,12 @@ almost always be doing. the assertion is about control characters, use `Contains.Substring(x).Using(StringComparison.Ordinal)`, negated with the `!` operator that `Constraint` defines, or assert the whole value with `Is.EqualTo`, which is ordinal. +- **Give a `[TestCase]` an explicit `TestName` when an argument holds a control character.** + Otherwise the whole fixture can become invisible to `dotnet test --filter`, silently: it is + listed by `--list-tests` and runs in a full pass, but every filter reports "No test matches". + Reproduced with `[TestCase("one", "\x1b[0m")]`; a single argument holding the same escape is + fine, so it takes two arguments and an escape character. `AnsiColorTerminalAppenderTest` names + all ten of its cases for that reason, and a filtered run there is 54 ms against 9 s for the suite. - Mark a test `[NonParallelizable]` when it mutates static state (`LogLog.InternalDebugging`, a static field on a test double, a process-wide native registration). - Wrap expected internal logging in `LogLog.ExecuteWithoutEmittingInternalMessages(...)` and capture @@ -229,9 +235,15 @@ What that leaves for this file is where the answers live in the code: at the site with a link to the model rather than changing the code. `XmlConfigurator` and `XmlHierarchyConfigurator` carry these for the configuration-is-trusted paths, and `SystemStringFormat` for the format string. -- `LocalSyslogAppender.EscapeNulCharacters` and `RemoteSyslogAppender.ValidateIdentity` are the two +- `log4net.Appender.Internal.ContentEscape` and `RemoteSyslogAppender.ValidateIdentity` are the two sides of the content and structural-identifier rule: content is escaped and never rejected, a malformed identifier is reported rather than quietly repaired. +- **A sink that cannot carry a character escapes it visibly, and never drops the character, the + rest of the record, or the event.** The escapes already in use are `\0` for NUL, `\r` and `\n` + for newlines, and `\uXXXX` for anything else, in `ContentEscape` and in + `RemoteSyslogAppender.AppendMessage`. Put new ones in `ContentEscape` rather than in the + appender: four appenders have needed the same two so far. Escaping before a length limit, not + after, since an escape is longer than what it replaces. - Deliberate secure-default choices belong in the changelog with their opt-out named, so that an upgrade surprise is searchable. See the entries for `SendTimeoutMillis`, `MatchTimeoutMillis` and `LockTimeoutMillis`. diff --git a/src/changelog/3.5.0/313-redact-connection-string-allowlist.xml b/src/changelog/3.5.0/313-redact-connection-string-allowlist.xml index 0aec3b5d..e020b60a 100644 --- a/src/changelog/3.5.0/313-redact-connection-string-allowlist.xml +++ b/src/changelog/3.5.0/313-redact-connection-string-allowlist.xml @@ -8,6 +8,6 @@ keep secrets out of the `AdoNetAppender` message for a connection it could not open. Hiding password-bearing keywords missed `Extended Properties`, which nests a whole connection string, and keywords such as `AccessToken` (CWE-532). Only keywords naming the server and account are kept now - (audit da18b6fd-f028) + (audit da18b6fd-f028, fixed by @FreeAndNil) diff --git a/src/changelog/3.5.0/313-require-powershell-74.xml b/src/changelog/3.5.0/313-require-powershell-74.xml index 3222a5e4..e0ab2306 100644 --- a/src/changelog/3.5.0/313-require-powershell-74.xml +++ b/src/changelog/3.5.0/313-require-powershell-74.xml @@ -9,6 +9,6 @@ `$PSNativeCommandUseErrorActionPreference`, which exists only from 7.4, so under Windows PowerShell 5.1 a failing `gpg --verify` was ignored and `verify-release.ps1` reported success and exited 0. The scripts now refuse to start on an older host, and the review instructions install PowerShell 7 and - run the script with `pwsh` (audit 1231d72-f009) + run the script with `pwsh` (audit 1231d72-f009, implemented by @FreeAndNil) diff --git a/src/changelog/3.5.0/313-verify-release-keys-bypass.xml b/src/changelog/3.5.0/313-verify-release-keys-bypass.xml index e49e157c..215ad438 100644 --- a/src/changelog/3.5.0/313-verify-release-keys-bypass.xml +++ b/src/changelog/3.5.0/313-verify-release-keys-bypass.xml @@ -10,6 +10,6 @@ and was imported into the verification key ring, and artifacts signed by whoever placed it verified (CWE-347). The scripts now verify in a GnuPG home of their own, filled from a copy downloaded there, rather than with `--keyring`, which `gpg` ignores where `common.conf` sets `use-keyboxd`. - Present in 3.2.0 onward, since the script was added (audit da18b6fd-f003, reported by @swebb2066) + Present in 3.2.0 onward, since the script was added (audit da18b6fd-f003, reported by @swebb2066, fixed by @FreeAndNil) diff --git a/src/changelog/3.5.0/314-ext-mail-background-sender.xml b/src/changelog/3.5.0/314-ext-mail-background-sender.xml index f16ce22f..acbe9d09 100644 --- a/src/changelog/3.5.0/314-ext-mail-background-sender.xml +++ b/src/changelog/3.5.0/314-ext-mail-background-sender.xml @@ -10,6 +10,6 @@ for the SMTP server. The queue holds `sendQueueSize` mails (500) and a logging call waits at most `enqueueTimeoutMillis` (5000) for room in it. Failures are still reported to the error handler, but after the logging call has returned, and `Flush` now honours its timeout - (implemented by @FreeAndNil) + (audit da18b6fd-f004, implemented by @FreeAndNil) diff --git a/src/changelog/3.5.0/314-ext-mail-send-timeout.xml b/src/changelog/3.5.0/314-ext-mail-send-timeout.xml index 2a8a0469..8ec6b8f6 100644 --- a/src/changelog/3.5.0/314-ext-mail-send-timeout.xml +++ b/src/changelog/3.5.0/314-ext-mail-send-timeout.xml @@ -9,6 +9,6 @@ per operation by default, and the mail goes out while the appender lock is held, so an unresponsive server suspended every thread logging through the appender. `SendTimeoutMillis` is a deadline for the send as a whole, because a per operation timeout still allows a multiple of - itself overall (implemented by @FreeAndNil) + itself overall (audit da18b6fd-f004, implemented by @FreeAndNil) diff --git a/src/changelog/3.5.0/314-remote-syslog-background-sender.xml b/src/changelog/3.5.0/314-remote-syslog-background-sender.xml index 9ea954df..1894ef20 100644 --- a/src/changelog/3.5.0/314-remote-syslog-background-sender.xml +++ b/src/changelog/3.5.0/314-remote-syslog-background-sender.xml @@ -9,6 +9,6 @@ stopped accepting datagrams grew it until the process ran out of memory, and shutdown waited five seconds and then abandoned a drain that had no limit of its own. It now holds `sendQueueSize` datagrams (500), a logging call waits at most `enqueueTimeoutMillis` (5000) for room, losses are - counted and reported, and `Flush` honours its timeout (implemented by @FreeAndNil) + counted and reported, and `Flush` honours its timeout (audit da18b6fd-f034, implemented by @FreeAndNil) diff --git a/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml b/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml index fb2185c7..2785a792 100644 --- a/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml +++ b/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml @@ -9,6 +9,6 @@ connection its background pump owns, but also inherited one from `UdpAppender` that nothing ever used, which bound `localPort` twice. A pump that cannot connect now reports it as well, instead of ending unobserved and leaving every later event queued behind a sender that is gone - (implemented by @FreeAndNil) + (audit da18b6fd-f034, implemented by @FreeAndNil) diff --git a/src/changelog/3.5.0/315-eventlog-nul.xml b/src/changelog/3.5.0/315-eventlog-nul.xml new file mode 100644 index 00000000..117ad85f --- /dev/null +++ b/src/changelog/3.5.0/315-eventlog-nul.xml @@ -0,0 +1,15 @@ + + + + + escape NUL characters in `EventLogAppender` content. `ReportEventW` takes a null terminated + string, so a NUL in logged content ended the stored record there and silently dropped whatever + the layout rendered after it, exception text and trailing fields included (CWE-158). `WriteEntry` + raises nothing, so the record simply stored short. Measured on Windows 11 build 26200: of a 45 + character message with a NUL at 23, the 23 character prefix was stored and the rest was gone + (audit da18b6fd-f007, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/315-eventlog-size-budget.xml b/src/changelog/3.5.0/315-eventlog-size-budget.xml new file mode 100644 index 00000000..5a38f539 --- /dev/null +++ b/src/changelog/3.5.0/315-eventlog-size-budget.xml @@ -0,0 +1,17 @@ + + + + + stop `EventLogAppender` truncating to a size the event log then discards. The limit is a whole + record budget that the log name, the source and the machine name are spent from, so the fixed + 31837 was above the real ceiling: measured on Windows 11 build 26200, a record is stored while + `message + logName + applicationName` stays within 31736 characters, and one character beyond + that the service stores nothing and reports nothing. The whole event was lost rather than + shortened, and `applicationName` defaults to the app domain name, so a consumer with a long + assembly name lost more. The limit is now computed, and a truncation is reported through the + error handler, which is the only signal available (audit da18b6fd-f030, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/315-local-syslog-newlines.xml b/src/changelog/3.5.0/315-local-syslog-newlines.xml new file mode 100644 index 00000000..3b002e42 --- /dev/null +++ b/src/changelog/3.5.0/315-local-syslog-newlines.xml @@ -0,0 +1,15 @@ + + + + + escape the newlines in logged content in `LocalSyslogAppender`, which passed them to + `syslog(3)` unchanged. A daemon that writes the message through to a line oriented log then + records everything after the newline as its own entry, so content could forge an authentic + looking record (CWE-117). `NewLineHandling` mirrors the option of the same name on + `RemoteSyslogAppender`, which already escaped by default; set it to `Keep` for the previous + behaviour (audit da18b6fd-f008, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/315-outputdebugstring-nul.xml b/src/changelog/3.5.0/315-outputdebugstring-nul.xml new file mode 100644 index 00000000..0ed4c455 --- /dev/null +++ b/src/changelog/3.5.0/315-outputdebugstring-nul.xml @@ -0,0 +1,13 @@ + + + + + escape NUL characters in `OutputDebugStringAppender` content. `OutputDebugStringW` takes a null + terminated string, so a NUL in logged content ended the record there and silently dropped whatever + the layout rendered after it, exception text and trailing fields included (CWE-158). The escape + `LocalSyslogAppender` already applied is now shared between the two (audit da18b6fd-f009, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/315-pickup-dir-unencodable-content.xml b/src/changelog/3.5.0/315-pickup-dir-unencodable-content.xml new file mode 100644 index 00000000..7953e8bc --- /dev/null +++ b/src/changelog/3.5.0/315-pickup-dir-unencodable-content.xml @@ -0,0 +1,13 @@ + + + + + stop one logging event destroying a whole `SmtpPickupDirAppender` batch. `File.CreateText` + throws on content it cannot encode, such as an unpaired surrogate, which abandoned every buffered + event and left a truncated mail in the pickup directory for the service to send. Such content is + now written as a `\uXXXX` escape (audit da18b6fd-f011, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/315-syslog-newline-handling-type.xml b/src/changelog/3.5.0/315-syslog-newline-handling-type.xml new file mode 100644 index 00000000..39ac9502 --- /dev/null +++ b/src/changelog/3.5.0/315-syslog-newline-handling-type.xml @@ -0,0 +1,13 @@ + + + + + move `SyslogNewLineHandling` out of `RemoteSyslogAppender` to `log4net.Appender`, now that + `LocalSyslogAppender` uses it too. Configuration files are unaffected, they bind the value by + name, but code naming `RemoteSyslogAppender.SyslogNewLineHandling` has to drop the prefix + (implemented by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/315-syslog-non-ascii.xml b/src/changelog/3.5.0/315-syslog-non-ascii.xml new file mode 100644 index 00000000..edcf04df --- /dev/null +++ b/src/changelog/3.5.0/315-syslog-non-ascii.xml @@ -0,0 +1,14 @@ + + + + + escape the characters `RemoteSyslogAppender` cannot send instead of deleting them. RFC 3164 + allows only the visible ASCII characters and space, and everything else was dropped silently, so + `Schönwetter 你好` reached the collector as `Schnwetter ` and a tab disappeared + from between its neighbours. Such characters are now written as a `\uXXXX` escape, which keeps + the record inside the allowed range and readable (audit da18b6fd-f035, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/315-telnet-unencodable-content.xml b/src/changelog/3.5.0/315-telnet-unencodable-content.xml new file mode 100644 index 00000000..d1b44771 --- /dev/null +++ b/src/changelog/3.5.0/315-telnet-unencodable-content.xml @@ -0,0 +1,13 @@ + + + + + stop one logging event disconnecting every `TelnetAppender` client. The default writer encoding + throws on content it cannot encode, such as an unpaired surrogate, and `Send` reads any failure as + a client that hung up. Unpaired surrogates are now written as a `\uXXXX` escape, as elsewhere + (audit da18b6fd-f013, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/316-ansi-empty-render.xml b/src/changelog/3.5.0/316-ansi-empty-render.xml new file mode 100644 index 00000000..1f32068d --- /dev/null +++ b/src/changelog/3.5.0/316-ansi-empty-render.xml @@ -0,0 +1,13 @@ + + + + + stop `AnsiColorTerminalAppender` dropping an event that renders to nothing. The branch meant + for a single character read the first one without checking there was one, so an empty render + threw and the event was lost. The reset codes are now placed by one computed offset, which has no + special case to get wrong (audit da18b6fd-f029, fixed by @FreeAndNil) + + diff --git a/src/changelog/3.5.0/316-aspnet-request-event-loss.xml b/src/changelog/3.5.0/316-aspnet-request-event-loss.xml new file mode 100644 index 00000000..39dd62fc --- /dev/null +++ b/src/changelog/3.5.0/316-aspnet-request-event-loss.xml @@ -0,0 +1,13 @@ + + + + Stop `%aspnet-request` losing the whole event for a request that fails + ASP.NET request validation. Reading `HttpRequest.Params` validates the query string, form and + cookies on first access, so a request carrying `<script>` threw inside the layout and the + appender discarded the event: a sender could suppress the log record of their own request. The + converter now reads through `HttpRequest.Unvalidated`, which keeps the content instead of + dropping it (audit da18b6fd-f019, fixed by @FreeAndNil) + diff --git a/src/log4net.Tests/Appender/AnsiColorTerminalAppenderTest.cs b/src/log4net.Tests/Appender/AnsiColorTerminalAppenderTest.cs new file mode 100644 index 00000000..222dce26 --- /dev/null +++ b/src/log4net.Tests/Appender/AnsiColorTerminalAppenderTest.cs @@ -0,0 +1,104 @@ +#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 System.IO; + +using log4net.Appender; +using log4net.Core; +using log4net.Layout; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// +/// Tests for , which places the terminal reset codes +/// before any trailing line break so the colour ends with the text. +/// +[TestFixture] +[NonParallelizable] +public class AnsiColorTerminalAppenderTest +{ + /// Matches the appender's private PostEventCodes. + private const string Reset = "\x1b[0m"; + + /// The reset codes belong before the line break, whichever one it is. + // Explicit names: two arguments where one holds an escape character make the whole fixture + // invisible to "dotnet test --filter", reproduced with [TestCase("one", "\x1b[0m")]. + [TestCase("", Reset, TestName = "AnEmptyRender")] + [TestCase("x", "x" + Reset, TestName = "ASingleCharacter")] + [TestCase("\n", Reset + "\n", TestName = "NothingButALineFeed")] + [TestCase("text", "text" + Reset, TestName = "NoTrailingLineBreak")] + [TestCase("\r", Reset + "\r", TestName = "NothingButACarriageReturn")] + [TestCase("text\n", "text" + Reset + "\n", TestName = "TrailingLineFeed")] + [TestCase("text\r", "text" + Reset + "\r", TestName = "TrailingCarriageReturn")] + [TestCase("text\r\n", "text" + Reset + "\r\n", TestName = "TrailingCarriageReturnLineFeed")] + [TestCase("text\n\r", "text" + Reset + "\n\r", TestName = "TrailingLineFeedCarriageReturn")] + [TestCase("text\n\n", "text\n" + Reset + "\n", TestName = "TrailingDoubledLineFeedCountsAsOne")] + public void TheResetCodesGoBeforeATrailingLineBreak(string message, string expected) + { + RecordingErrorHandler errorHandler = new(); + // Level.Info has no colour mapping configured, so nothing is prepended and the rendered + // message is exactly what was logged, down to the empty string. + AnsiColorTerminalAppender appender = new() + { + Layout = new PatternLayout("%message"), + ErrorHandler = errorHandler + }; + appender.ActivateOptions(); + + TextWriter previous = Console.Out; + using StringWriter captured = new(); + try + { + Console.SetOut(captured); + // DoAppend is overloaded on LoggingEvent and LoggingEvent[], so this new cannot be short. + appender.DoAppend(new LoggingEvent(new() + { + Level = Level.Info, + Message = message, + LoggerName = nameof(AnsiColorTerminalAppenderTest) + })); + } + finally + { + Console.SetOut(previous); + } + + Assert.That(errorHandler.Message, Is.Empty, "the event must not be dropped"); + Assert.That(captured.ToString(), Is.EqualTo(expected)); + } + + /// Collects what the appender reports, so a dropped event is visible. + private sealed class RecordingErrorHandler : IErrorHandler + { + /// Everything reported so far. + internal string Message { get; private set; } = string.Empty; + + /// + public void Error(string message) => Message += message + '\n'; + + /// + public void Error(string message, Exception e) => Message += message + '\n'; + + /// + public void Error(string message, Exception? e, ErrorCode errorCode) => Message += message + '\n'; + } +} diff --git a/src/log4net.Tests/Appender/ContentEscapeTest.cs b/src/log4net.Tests/Appender/ContentEscapeTest.cs new file mode 100644 index 00000000..1935dfc5 --- /dev/null +++ b/src/log4net.Tests/Appender/ContentEscapeTest.cs @@ -0,0 +1,73 @@ +#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.Reflection; + +using log4net.Appender; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// +/// Tests for the internal ContentEscape helper. +/// +[TestFixture] +public class ContentEscapeTest +{ + /// + /// An unpaired surrogate cannot be encoded, and an encoder that throws costs the event. The + /// input is built here rather than in the attribute: an attribute argument lives in metadata as + /// UTF-8, so the compiler would replace the surrogate with U+FFFD before the test ran. + /// + [TestCase(0xd800)] + [TestCase(0xdbff)] + [TestCase(0xdc00)] + [TestCase(0xdfff)] + public void UnpairedSurrogatesAreEscaped(int surrogate) + { + string input = "before" + (char)surrogate + "after"; + + Assert.That(EscapeUnpairedSurrogates(input), Is.EqualTo($@"before\u{surrogate:x4}after")); + } + + /// Every one of them, not just the first. + [Test] + public void EveryUnpairedSurrogateIsEscaped() + => Assert.That(EscapeUnpairedSurrogates("a" + (char)0xd800 + "b" + (char)0xdc00 + "c"), + Is.EqualTo(@"a\ud800b\udc00c")); + + /// A valid pair is one character and must survive untouched. + [Test] + public void ValidSurrogatePairsAreLeftAlone() + => Assert.That(EscapeUnpairedSurrogates("emoji \U0001F600 here"), Is.EqualTo("emoji \U0001F600 here")); + + /// The common case takes a fast path that must not alter anything. + [TestCase("")] + [TestCase("plain ascii")] + [TestCase("Schönwetter 你好")] + public void MessagesWithoutSurrogatesAreUnchanged(string message) + => Assert.That(EscapeUnpairedSurrogates(message), Is.EqualTo(message)); + + private static string EscapeUnpairedSurrogates(string message) + => (string)typeof(TelnetAppender).Assembly + .GetType("log4net.Appender.Internal.ContentEscape")! + .GetMethod("EscapeUnpairedSurrogates", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [message])!; +} diff --git a/src/log4net.Tests/Appender/EventLogAppenderTest.cs b/src/log4net.Tests/Appender/EventLogAppenderTest.cs index ad0cd705..9abfc4b7 100644 --- a/src/log4net.Tests/Appender/EventLogAppenderTest.cs +++ b/src/log4net.Tests/Appender/EventLogAppenderTest.cs @@ -21,6 +21,7 @@ #if NET462_OR_GREATER using System.Diagnostics; +using System.Reflection; using log4net.Appender; using log4net.Core; @@ -81,6 +82,79 @@ public void ActivateOptionsDisablesAppenderIfSourceDoesntExist() eventAppender.ActivateOptions(); Assert.That(eventAppender.Threshold, Is.EqualTo(Level.Off)); } + + /// + /// ReportEventW takes a null terminated string, so a NUL in content ends the stored record + /// there and silently drops whatever the layout rendered after it. Measured on Windows 11 + /// 26200: WriteEntry does not throw, and only the prefix is stored. + /// + [Test] + public void NulCharactersAreEscaped() + => Assert.That(PrepareEventText("before\0after", 100), Is.EqualTo("before\\0after")); + + /// + /// The escape doubles each NUL, so it has to happen before the limit is applied. Escaping + /// afterwards would push a message near the limit back over it. + /// + [Test] + public void EscapingHappensBeforeTheLimitIsApplied() + { + const int maxSize = 4; + + string prepared = PrepareEventText("\0\0\0", maxSize); + + // Equality is ordinal, and pins the length and the absence of a NUL in one go. Escaping the + // three NULs gives six characters, so the limit has to cut it back to four. + Assert.That(prepared, Is.EqualTo(@"\0\0")); + } + + /// A message within the limit and without a NUL comes through untouched. + [Test] + public void MessagesWithinTheLimitAreUnchanged() + => Assert.That(PrepareEventText("field=1\tfield=2", 100), Is.EqualTo("field=1\tfield=2")); + + private static string PrepareEventText(string rendered, int maxSize) + => (string)typeof(EventLogAppender) + .GetMethod("PrepareEventText", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [rendered, maxSize])!; + + /// + /// The limit is a whole record budget: the source is spent from it one character for one, so a + /// longer ApplicationName has to leave less room for the message. + /// + [Test] + public void TheSourceNameIsSpentFromTheMessageBudget() + { + const int difference = 44; + int shortSource = GetMaxMessageSize(new() { LogName = "Application", ApplicationName = "abc" }); + int longSource = GetMaxMessageSize(new() { LogName = "Application", ApplicationName = new('a', 3 + difference) }); + + Assert.That(shortSource - longSource, Is.EqualTo(difference)); + } + + /// + /// And so is the log name, which is the half of the budget that was not expected. + /// + [Test] + public void TheLogNameIsSpentFromTheMessageBudgetToo() + { + const int difference = 7; + int shortLog = GetMaxMessageSize(new() { LogName = "Application", ApplicationName = "abc" }); + int longLog = GetMaxMessageSize(new() { LogName = new('L', 11 + difference), ApplicationName = "abc" }); + + Assert.That(shortLog - longLog, Is.EqualTo(difference)); + } + + /// Names long enough to exhaust the budget must not produce a negative length. + [Test] + public void TheLimitNeverGoesBelowZero() + => Assert.That(GetMaxMessageSize(new() { LogName = new('L', 40000), ApplicationName = "abc" }), + Is.EqualTo(0)); + + private static int GetMaxMessageSize(EventLogAppender appender) + => (int)typeof(EventLogAppender) + .GetMethod("GetMaxMessageSize", BindingFlags.Instance | BindingFlags.NonPublic)! + .Invoke(appender, [])!; } -#endif // NET462_OR_GREATER \ No newline at end of file +#endif // NET462_OR_GREATER diff --git a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs index be09b7f9..cd921030 100644 --- a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs @@ -55,8 +55,7 @@ public void EveryNulCharacterIsEscaped() => Assert.That(EscapeNulCharacters("a\0b\0c"), Is.EqualTo("a\\0b\\0c")); /// - /// A message without a NUL character has to come through untouched, including the newlines an - /// exception layout produces: syslog(3) deals with those itself. + /// This escape is only about NUL. Newlines are . /// [Test] public void MessagesWithoutNulCharactersAreUnchanged() @@ -114,8 +113,51 @@ private static IntPtr CurrentIdentityHandle() .GetField("_handleToIdentity", BindingFlags.Static | BindingFlags.NonPublic)! .GetValue(null)!; - private static string EscapeNulCharacters(string message) + /// + /// A newline ends the record for a daemon that writes the message through to a line oriented + /// log, so content could otherwise forge a second entry. glibc does not escape it. + /// + [Test] + public void NewLinesAreEscaped() + => Assert.That(EscapeNewLines("value\r\nJan 1 00:00:00 host sshd[1]: forged"), + Is.EqualTo("value\\r\\nJan 1 00:00:00 host sshd[1]: forged")); + + /// Both characters count, on their own as well as paired. + [TestCase("a\rb", "a\\rb")] + [TestCase("a\nb", "a\\nb")] + [TestCase("a\n\nb", "a\\n\\nb")] + public void EveryNewLineIsEscaped(string message, string expected) + => Assert.That(EscapeNewLines(message), Is.EqualTo(expected)); + + /// A message without newlines takes the fast path and comes through untouched. + [Test] + public void MessagesWithoutNewLinesAreUnchanged() + => Assert.That(EscapeNewLines("field=1\tfield=2"), Is.EqualTo("field=1\tfield=2")); + + /// Escaping is the default, because a daemon that splits the record is the common case. + [Test] + public void NewLineHandlingDefaultsToEscape() + => Assert.That(new LocalSyslogAppender().NewLineHandling, + Is.EqualTo(SyslogNewLineHandling.Escape)); + + /// One record per line, and a blank line is no record at all. + [Test] + public void SplittingDropsTheEmptyLines() + => Assert.That(SplitLines("first\r\nsecond\n\nthird\r"), Is.EqualTo(new[] { "first", "second", "third" })); + + private static string EscapeNewLines(string message) => (string)typeof(LocalSyslogAppender) + .GetMethod("EscapeNewLines", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [message])!; + + private static string[] SplitLines(string message) + => (string[])typeof(LocalSyslogAppender) + .GetMethod("SplitLines", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [message])!; + + private static string EscapeNulCharacters(string message) + => (string)typeof(LocalSyslogAppender).Assembly + .GetType("log4net.Appender.Internal.ContentEscape")! .GetMethod("EscapeNulCharacters", BindingFlags.Static | BindingFlags.NonPublic)! .Invoke(null, [message])!; } diff --git a/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs b/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs index 882b1d53..5d03f02e 100644 --- a/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs +++ b/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs @@ -58,6 +58,31 @@ public void AppendShouldNotCauseAnyErrors() log.Debug(DebugMessage); Assert.That(lastDebugString, Is.Not.Null.And.Contains(DebugMessage)); } + + /// + /// OutputDebugStringW takes a null terminated string, so a NUL in content would end the record + /// there and drop whatever the layout rendered after it. + /// + [Test] + public void NulCharactersAreEscapedBeforeTheNativeCall() + { + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + string? lastDebugString = null; + OutputAppender appender = new(value => lastDebugString = value) + { + Layout = new SimpleLayout(), + ErrorHandler = new FailOnError() + }; + appender.ActivateOptions(); + BasicConfigurator.Configure(rep, appender); + + LogManager.GetLogger(rep.Name, GetType()).Debug("before\0after"); + + // Ordinal throughout: a culture sensitive comparison treats NUL as ignorable, so it reports a + // match in a string that has none. + Assert.That(lastDebugString, Contains.Substring("before\\0after").Using(StringComparison.Ordinal)); + Assert.That(lastDebugString, !Contains.Substring("\0").Using(StringComparison.Ordinal)); + } } file sealed class OutputAppender(Action outputDebugString) diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index 5b187822..149d191b 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -69,6 +69,30 @@ private sealed class RecordingErrorHandler : IErrorHandler private const int FlushTimeoutMillis = 30_000; + /// + /// Content outside the RFC 3164 range used to be deleted with no marker, so a message written + /// in a non-Latin script reached the audit trail empty. + /// + [Test] + public void NonAsciiContentIsEscapedAndNotDeleted() + { + List sentBytes = ExecuteAppend("Sch\u00f6nwetter \u4f60\u597d"); + + Assert.That(sentBytes, Has.Count.EqualTo(1)); + Assert.That(Encoding.ASCII.GetString(sentBytes[0]), + Is.EqualTo(@"<14>TestDomain: INFO - Sch\u00f6nwetter \u4f60\u597d")); + } + + /// A control character other than CR or LF was dropped as well. + [Test] + public void OtherControlCharactersAreEscaped() + { + List sentBytes = ExecuteAppend("a\tb"); + + Assert.That(sentBytes, Has.Count.EqualTo(1)); + Assert.That(Encoding.ASCII.GetString(sentBytes[0]), Is.EqualTo(@"<14>TestDomain: INFO - a\u0009b")); + } + /// Bounded, so an unreachable server cannot grow the queue without limit. [Test] public void SendQueueSizeDefaultsTo500() @@ -154,7 +178,7 @@ public void RemoteSyslogTest() /// /// Test for the - /// with + /// with /// /// /// https://github.com/apache/logging-log4net/issues/274 @@ -171,7 +195,7 @@ public void RemoteSyslogNewLineHandlingEscapeTest() /// /// Test for the - /// with + /// with /// /// /// https://github.com/apache/logging-log4net/issues/274 @@ -180,7 +204,7 @@ public void RemoteSyslogNewLineHandlingEscapeTest() public void RemoteSyslogNewLineHandlingKeepTest() { List sentBytes = ExecuteAppend("Test\r\nmessage", - RemoteSyslogAppender.SyslogNewLineHandling.Keep); + SyslogNewLineHandling.Keep); // ReSharper disable once StringLiteralTypo const string expectedData = "<14>TestDomain: INFO - Test\r\nmessage"; Assert.That(sentBytes, Has.Count.EqualTo(1)); @@ -189,7 +213,7 @@ public void RemoteSyslogNewLineHandlingKeepTest() /// /// Test for the - /// with + /// with /// /// /// https://github.com/apache/logging-log4net/issues/274 @@ -198,7 +222,7 @@ public void RemoteSyslogNewLineHandlingKeepTest() public void RemoteSyslogNewLineHandlingSplitTest() { List sentBytes = ExecuteAppend("Test\r\nmessage", - RemoteSyslogAppender.SyslogNewLineHandling.Split); + SyslogNewLineHandling.Split); // ReSharper disable once StringLiteralTypo Assert.That(sentBytes, Has.Count.EqualTo(2)); const string expectedData0 = "<14>TestDomain: INFO - Test"; @@ -266,7 +290,7 @@ public void IdentityWithoutControlCharactersIsUnchangedAndNotReported() } private static List ExecuteAppend(string message, - RemoteSyslogAppender.SyslogNewLineHandling newLineHandling = default, + SyslogNewLineHandling newLineHandling = default, string? identity = null) { System.Net.IPAddress ipAddress = new([127, 0, 0, 1]); diff --git a/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs b/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs index 509b42a9..5ba88f03 100644 --- a/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs +++ b/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs @@ -153,6 +153,29 @@ private static void DestroyLogger() LoggerManager.RepositorySelector = new DefaultRepositorySelector(typeof(log4net.Repository.Hierarchy.Hierarchy)); } + /// + /// An unpaired surrogate used to abort the write, losing every buffered event with it and + /// leaving a truncated mail behind for the pickup service to send. + /// + [Test] + public void ContentThatCannotBeEncodedDoesNotDestroyTheBatch() + { + SilentErrorHandler sh = new(); + SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(sh); + ILogger log = CreateLogger(appender); + + log.Log(GetType(), Level.Info, "poison" + (char)0xd800 + "event", null); + log.Log(GetType(), Level.Info, "the event after it", null); + DestroyLogger(); + + Assert.That(Directory.GetFiles(_testPickupDir), Has.Length.EqualTo(1)); + string content = File.ReadAllText(Directory.GetFiles(_testPickupDir)[0]); + + Assert.That(content, Does.Contain(@"poison\ud800event")); + Assert.That(content, Does.Contain("the event after it")); + Assert.That(sh.Message, Is.EqualTo(string.Empty), "Unexpected error message"); + } + /// /// Tests if the sent message contained the date header. /// diff --git a/src/log4net.Tests/Appender/TelnetAppenderTest.cs b/src/log4net.Tests/Appender/TelnetAppenderTest.cs index 5d8f37cd..c0df92b4 100644 --- a/src/log4net.Tests/Appender/TelnetAppenderTest.cs +++ b/src/log4net.Tests/Appender/TelnetAppenderTest.cs @@ -47,6 +47,87 @@ public sealed class TelnetAppenderTest /// https://github.com/apache/logging-log4net/issues/194 /// https://stackoverflow.com/questions/79053363/log4net-telnetappender-doesnt-work-after-migrate-to-log4net-3 /// + /// + /// An unpaired surrogate used to throw while encoding, and Send reads any throw as a client + /// that hung up, so one such event reached nobody and disconnected everybody. + /// + [Test] + public void ContentThatCannotBeEncodedDoesNotDisconnectTheClient() + { + StringBuilder received = new(); + object receivedSyncRoot = new(); + + int port = FindFreeTcpPort(); + XmlDocument log4NetConfig = new(); + log4NetConfig.LoadXml( + $""" + + + + + + + + + + + + + """); + string marker = Guid.NewGuid().ToString(); + ILoggerRepository repository = LogManager.CreateRepository(marker); + XmlConfigurator.Configure(repository, log4NetConfig["log4net"]!); + try + { + using (SimpleTelnetClient telnetClient = new(Received, port)) + { + telnetClient.Run(TestContext.Out.WriteLine); + WaitFor("welcome message", WelcomeMessage); + + ILogger logger = repository.GetLogger("Telnet"); + logger.Log(typeof(TelnetAppenderTest), Level.Info, "poison\ud800event", null); + // The event after it only arrives if the client survived the one before. + logger.Log(typeof(TelnetAppenderTest), Level.Info, marker, null); + WaitFor("the event after the unencodable one", marker); + } + } + finally + { + repository.Shutdown(); + } + + Assert.That(ReceivedText(), Does.Contain(@"poison\ud800event")); + + void Received(string message) + { + lock (receivedSyncRoot) + { + received.Append(message); + } + } + + string ReceivedText() + { + lock (receivedSyncRoot) + { + return received.ToString(); + } + } + + void WaitFor(string what, string expected) + { + Stopwatch stopwatch = Stopwatch.StartNew(); + while (ReceivedText().IndexOf(expected, StringComparison.Ordinal) < 0) + { + if (stopwatch.Elapsed > _receiveTimeout) + { + Assert.Fail($"Timeout waiting for {what} - received so far: '{ReceivedText()}'"); + } + Thread.Sleep(20); + } + } + } + /// /// Maximum time to wait for a message to arrive at the client. /// diff --git a/src/log4net.Tests/Layout/Pattern/AspNetRequestPatternConverterTest.cs b/src/log4net.Tests/Layout/Pattern/AspNetRequestPatternConverterTest.cs new file mode 100644 index 00000000..115e164e --- /dev/null +++ b/src/log4net.Tests/Layout/Pattern/AspNetRequestPatternConverterTest.cs @@ -0,0 +1,147 @@ +#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 + +// netstandard has no System.Web +#if NET462_OR_GREATER + +using System; +using System.IO; +using System.Web; + +using log4net.Config; +using log4net.Layout; +using log4net.Repository; +using log4net.Tests.Appender; +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Layout.Pattern; + +/// +/// Tests that %aspnet-request survives content ASP.NET request validation rejects. +/// +[TestFixture] +public sealed class AspNetRequestPatternConverterTest +{ + private const string Payload = "