diff --git a/CLAUDE.md b/CLAUDE.md index 09b3b901f..bba164a2f 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -229,9 +229,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/315-eventlog-nul.xml b/src/changelog/3.5.0/315-eventlog-nul.xml new file mode 100644 index 000000000..2ac7a56f3 --- /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) + + 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 000000000..faa41f348 --- /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) + + 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 000000000..4c7a6a47a --- /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) + + 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 000000000..b2adef687 --- /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) + + 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 000000000..8f952bf1f --- /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) + + 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 000000000..39ac95025 --- /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 000000000..e80201687 --- /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) + + 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 000000000..ad96651f1 --- /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) + + diff --git a/src/log4net.Tests/Appender/ContentEscapeTest.cs b/src/log4net.Tests/Appender/ContentEscapeTest.cs new file mode 100644 index 000000000..1935dfc58 --- /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 ad0cd7053..9abfc4b7f 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 be09b7f90..cd9210300 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 882b1d530..5d03f02e5 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 5b1878228..149d191b4 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 509b42a9b..5ba88f035 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 5d8f37cda..c0df92b44 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/Appender/EventLogAppender.cs b/src/log4net/Appender/EventLogAppender.cs index 48844cd35..fa0a23d5c 100644 --- a/src/log4net/Appender/EventLogAppender.cs +++ b/src/log4net/Appender/EventLogAppender.cs @@ -23,6 +23,7 @@ using System.Diagnostics; using log4net.Util; +using log4net.Appender.Internal; using log4net.Core; namespace log4net.Appender; @@ -377,12 +378,15 @@ protected override void Append(LoggingEvent loggingEvent) // Write to the event log try { - string eventTxt = RenderLoggingEvent(loggingEvent); - - // There is a limit of about 32K characters for an event log message - if (eventTxt.Length > _maxEventlogMessageSize) + string escaped = ContentEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); + int maxSize = GetMaxMessageSize(); + string eventTxt = PrepareEventText(escaped, maxSize); + if (eventTxt.Length < escaped.Length) { - eventTxt = eventTxt.Substring(0, _maxEventlogMessageSize); + // The only signal there is: the service reports neither a truncated nor a dropped record. + ErrorHandler.Error( + $"Truncated a logging event from {escaped.Length} to {maxSize} characters for log [{LogName}] " + + $"using source [{ApplicationName}]. What the layout rendered after that is not in the record."); } EventLogEntryType entryType = GetEntryType(loggingEvent.Level); @@ -398,6 +402,45 @@ protected override void Append(LoggingEvent loggingEvent) } } + /// + /// Escapes the NUL characters and then applies the message size limit. + /// + /// The rendered event. + /// The largest message the event log accepts. + /// The text to write. + /// + /// + /// The order matters. ReportEventW takes a null terminated string, so a NUL in content + /// ends the stored record there, and escaping doubles each NUL, so escaping after the limit was + /// applied could push the message back over it. + /// + /// + private static string PrepareEventText(string rendered, int maxSize) + { + string escaped = ContentEscape.EscapeNulCharacters(rendered); + return escaped.Length > maxSize ? escaped.Substring(0, maxSize) : escaped; + } + + /// + /// The largest message this appender may hand to the event log. + /// + /// What is left of the record budget once the names are spent from it. + /// + /// Computed, not a constant: defaults to the app domain name, so + /// the consumer's assembly name comes out of the budget. The machine name is subtracted on the + /// assumption that it counts, which cannot be tested without renaming a machine. + /// + private int GetMaxMessageSize() + { + string machineName = MachineName == "." ? Environment.MachineName : MachineName; + int budget = _maxEventlogMessageSize + - LogName.Length + - ApplicationName.Length + - machineName.Length + - MaxEventlogMessageSizeMargin; + return Math.Max(budget, 0); + } + /// /// This appender requires a to be set. /// @@ -513,12 +556,16 @@ public class Level2EventLogEntryType : LevelMappingEntry /// Going over this size may succeed a few times but the buffer will overrun and /// eventually corrupt the log (based on testing). /// - /// The maxEventMsgSize size is based on the max buffer size of the lpStrings parameter of the ReportEvent API. - /// The documented max size for EventLog.WriteEntry for Windows Vista and higher is 31839, but I'm leaving room for a - /// terminator of #0#0, as we cannot see the source of ReportEvent (though we could use an API monitor to examine the - /// buffer, given enough time). + /// Measured on Windows 11 build 26200: a record is stored while message plus log name plus + /// source stays within 31736 characters, and one character more stores nothing at all. /// - private const int MaxEventlogMessageSizeVistaOrNewer = 31839 - 2; + private const int MaxEventlogMessageSizeVistaOrNewer = 31736; + + /// + /// Held back from the computed limit. Crossing it discards the record silently, consumes the + /// log's space anyway, and has been seen to leave the log unreadable. + /// + private const int MaxEventlogMessageSizeMargin = 1024; /// /// The maximum size that the operating system supports for diff --git a/src/log4net/Appender/Internal/ContentEscape.cs b/src/log4net/Appender/Internal/ContentEscape.cs new file mode 100644 index 000000000..05021f8de --- /dev/null +++ b/src/log4net/Appender/Internal/ContentEscape.cs @@ -0,0 +1,103 @@ +#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.Globalization; +using System.Text; + +namespace log4net.Appender.Internal; + +/// +/// Makes rendered content safe for a sink, without discarding any of it. +/// +internal static class ContentEscape +{ + /// + /// Replaces NUL characters with a visible \0 escape. + /// + /// The rendered message. + /// The message with every NUL character escaped. + /// + /// + /// A NUL ends the string for the native sink, dropping everything the layout rendered after it, + /// trailing fields and exception text included. Logged content is not trusted and may well + /// contain a NUL, so the character is escaped rather than passed through. + /// + /// + internal static string EscapeNulCharacters(string message) + => message.IndexOf('\0') < 0 ? message : message.Replace("\0", "\\0"); + + /// + /// Replaces the surrogates that are not part of a pair with a visible \uXXXX escape. + /// + /// The rendered message. + /// The message with every unpaired surrogate escaped. + /// + /// An unpaired surrogate is a legal but cannot be encoded, and an encoder + /// that throws costs the whole event, so it is escaped rather than left to fail. + /// + internal static string EscapeUnpairedSurrogates(string message) + { + if (!ContainsUnpairedSurrogate(message)) + { + return message; + } + + StringBuilder builder = new(message.Length); + for (int i = 0; i < message.Length; i++) + { + char c = message[i]; + if (char.IsHighSurrogate(c) && i + 1 < message.Length && char.IsLowSurrogate(message[i + 1])) + { + builder.Append(c).Append(message[i + 1]); + i++; + } + else if (char.IsSurrogate(c)) + { + builder.Append("\\u").Append(((int)c).ToString("x4", CultureInfo.InvariantCulture)); + } + else + { + builder.Append(c); + } + } + + return builder.ToString(); + } + + private static bool ContainsUnpairedSurrogate(string message) + { + for (int i = 0; i < message.Length; i++) + { + if (!char.IsSurrogate(message[i])) + { + continue; + } + + if (char.IsHighSurrogate(message[i]) && i + 1 < message.Length && char.IsLowSurrogate(message[i + 1])) + { + i++; + continue; + } + + return true; + } + + return false; + } +} diff --git a/src/log4net/Appender/LocalSyslogAppender.cs b/src/log4net/Appender/LocalSyslogAppender.cs index 6c946a1be..dae7f5054 100644 --- a/src/log4net/Appender/LocalSyslogAppender.cs +++ b/src/log4net/Appender/LocalSyslogAppender.cs @@ -20,6 +20,7 @@ using System; using System.Runtime.InteropServices; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -353,32 +354,57 @@ public override void ActivateOptions() protected override void Append(LoggingEvent loggingEvent) { int priority = GeneratePriority(Facility, GetSeverity(loggingEvent.EnsureNotNull().Level)); - string message = EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); + string message = ContentEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); + + // The second argument is a printf style format string. + if (NewLineHandling == SyslogNewLineHandling.Split) + { + foreach (string line in SplitLines(message)) + { + NativeMethods.syslog(priority, "%s", line); + } + + return; + } + + if (NewLineHandling == SyslogNewLineHandling.Escape) + { + message = EscapeNewLines(message); + } - // Call the local libc syslog method - // The second argument is a printf style format string NativeMethods.syslog(priority, "%s", message); } /// - /// Replaces NUL characters with a visible \0 escape. + /// What to do with the newlines in logged content. Defaults to + /// . /// - /// The rendered message. - /// The message with every NUL character escaped. /// - /// - /// The message is marshaled to libc as a null-terminated string, so a NUL character anywhere in - /// it would end the record there and silently drop everything the layout rendered after it, - /// including trailing fields and exception text. Logged content is not trusted and may well - /// contain a NUL, so the character is escaped rather than passed through. - /// - /// - /// Other control characters are left alone: syslog(3) encodes them itself, and newlines - /// are needed for the multi-line output an exception layout produces. - /// + /// A newline in content ends the record for daemons that write the message through to a line + /// oriented log, letting content forge a second, authentic looking entry. /// - private static string EscapeNulCharacters(string message) - => message.IndexOf('\0') < 0 ? message : message.Replace("\0", "\\0"); + public SyslogNewLineHandling NewLineHandling { get; set; } + = SyslogNewLineHandling.Escape; + + /// + /// Replaces the newlines with a visible \r or \n escape. + /// + /// The rendered message. + /// The message with every newline escaped. + private static string EscapeNewLines(string message) + => message.IndexOf('\r') < 0 && message.IndexOf('\n') < 0 + ? message + : message.Replace("\r", "\\r").Replace("\n", "\\n"); + + /// + /// Splits the message into the lines to send as separate records, dropping the empty ones. + /// + /// The rendered message. + /// One entry per non-empty line. + private static string[] SplitLines(string message) + => message.Split(_newLines, StringSplitOptions.RemoveEmptyEntries); + + private static readonly string[] _newLines = ["\r\n", "\n", "\r"]; /// /// Close the syslog when the appender is closed diff --git a/src/log4net/Appender/OutputDebugStringAppender.cs b/src/log4net/Appender/OutputDebugStringAppender.cs index 44442e9dd..7a6b06171 100644 --- a/src/log4net/Appender/OutputDebugStringAppender.cs +++ b/src/log4net/Appender/OutputDebugStringAppender.cs @@ -18,6 +18,7 @@ #endregion using System; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -59,7 +60,7 @@ protected override void Append(LoggingEvent loggingEvent) } #endif - _outputDebugString(RenderLoggingEvent(loggingEvent)); + _outputDebugString(ContentEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent))); } /// diff --git a/src/log4net/Appender/RemoteSyslogAppender.cs b/src/log4net/Appender/RemoteSyslogAppender.cs index e2d6cd303..00a55dab6 100644 --- a/src/log4net/Appender/RemoteSyslogAppender.cs +++ b/src/log4net/Appender/RemoteSyslogAppender.cs @@ -18,6 +18,7 @@ #endregion using System; +using System.Globalization; using System.Text; using System.Threading; using log4net.Appender.Internal; @@ -256,27 +257,6 @@ public enum SyslogFacility Local7 = 23 } - /// - /// Options for handling newlines (\r or \n) in - /// - public enum SyslogNewLineHandling - { - /// - /// escape the newlines (\\r for \r and \\n for \n) - /// - Escape, - - /// - /// split the message at new lines - /// - Split, - - /// - /// keep newlines as is (many syslog servers can handle newlines in the message part) - /// - Keep - } - private const int CloseTimeoutMillis = 5_000; private IUdpConnection? _connection; private BackgroundSender? _sender; @@ -505,6 +485,12 @@ protected virtual void AppendMessage(string message, ref int characterIndex, Str break; } } + else + { + // Escaped, not dropped: content is masked visibly rather than deleted. RFC 3164 allows + // only 0x20 to 0x7E here, so the escape itself stays inside that range. + builder.Append("\\u").Append(((int)c).ToString("x4", CultureInfo.InvariantCulture)); + } } } diff --git a/src/log4net/Appender/SmtpPickupDirAppender.cs b/src/log4net/Appender/SmtpPickupDirAppender.cs index 6cb88c802..86c17c79d 100644 --- a/src/log4net/Appender/SmtpPickupDirAppender.cs +++ b/src/log4net/Appender/SmtpPickupDirAppender.cs @@ -20,6 +20,9 @@ using System; using System.IO; +using System.Globalization; +using System.Text; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -128,10 +131,15 @@ protected override void SendBuffer(LoggingEvent[] events) StreamWriter writer; // Impersonate to open the file + // Written under its final name, so a failure mid write leaves a partial mail for the pickup + // service. Accepted: no temporary name is safe for every service, and FileExtension is the + // operator's to choose. string filePath = Path.Combine(PickupDir.EnsureNotNull(), Guid.NewGuid().ToString("N") + _fileExtension); using (SecurityContext?.Impersonate(this)) { - writer = File.CreateText(filePath); + // Not File.CreateText: its encoding throws on content it cannot encode, which would + // abandon the whole batch and leave a truncated mail for the pickup service to send. + writer = new StreamWriter(filePath, false, new UTF8Encoding(false)); } using (writer) @@ -142,22 +150,21 @@ protected override void SendBuffer(LoggingEvent[] events) writer.WriteLine("Date: " + DateTime.UtcNow.ToString("r")); writer.WriteLine(); - string? t = Layout?.Header; - if (t is not null) + if (Layout?.Header is string header) { - writer.Write(t); + writer.Write(header); } for (int i = 0; i < events.Length; i++) { - // Render the event and append the text to the buffer - RenderLoggingEvent(writer, events[i]); + using StringWriter rendered = new(CultureInfo.InvariantCulture); + RenderLoggingEvent(rendered, events[i]); + writer.Write(ContentEscape.EscapeUnpairedSurrogates(rendered.ToString())); } - t = Layout?.Footer; - if (t is not null) + if (Layout?.Footer is string footer) { - writer.Write(t); + writer.Write(footer); } writer.WriteLine(); diff --git a/src/log4net/Appender/SyslogNewLineHandling.cs b/src/log4net/Appender/SyslogNewLineHandling.cs new file mode 100644 index 000000000..975af25a8 --- /dev/null +++ b/src/log4net/Appender/SyslogNewLineHandling.cs @@ -0,0 +1,48 @@ +#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 + +namespace log4net.Appender; + +/// +/// Options for handling the newlines (\r or \n) in logged content, used by +/// and . +/// +/// +/// +/// A newline ends the record for a syslog daemon that writes the message through to a line +/// oriented log, so content could otherwise forge a second, authentic looking entry. +/// +/// +public enum SyslogNewLineHandling +{ + /// + /// escape the newlines (\\r for \r and \\n for \n) + /// + Escape, + + /// + /// split the message at new lines + /// + Split, + + /// + /// keep newlines as is (many syslog servers can handle newlines in the message part) + /// + Keep +} diff --git a/src/log4net/Appender/TelnetAppender.cs b/src/log4net/Appender/TelnetAppender.cs index a0b04e131..903cd0d50 100644 --- a/src/log4net/Appender/TelnetAppender.cs +++ b/src/log4net/Appender/TelnetAppender.cs @@ -21,8 +21,10 @@ using System.Collections.Generic; using System.Net; using System.Net.Sockets; +using System.Text; using System.IO; using System.Linq; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -245,7 +247,9 @@ public SocketClient(Socket socket) _socket = socket; try { - _writer = new(new NetworkStream(socket)); + // Belt and braces. Send escapes what cannot be encoded; this keeps a future gap costing + // one character rather than every client, since Send reads a throw as a hung up client. + _writer = new(new NetworkStream(socket), new UTF8Encoding(false)); } catch (Exception e) when (!e.IsFatal()) { @@ -260,7 +264,7 @@ public SocketClient(Socket socket) /// string to send public void Send(string message) { - _writer.Write(message); + _writer.Write(ContentEscape.EscapeUnpairedSurrogates(message.EnsureNotNull())); _writer.Flush(); } diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc index 07459e967..5c5e9eea5 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc @@ -38,6 +38,13 @@ You can also specify: * Facility (default: user) * Identity (default: application name) +* NewLineHandling (default: Escape), one of `Escape`, `Split` or `Keep` + +A newline in logged content ends the record for a syslog daemon that writes the message through to +a line oriented log, so content can otherwise forge a second, authentic looking entry. `Escape` +writes them as `\r` and `\n`, `Split` sends one record per line, and `Keep` passes them through +for a daemon that handles multiline messages itself. Note that `syslog(3)` does no escaping of its +own: whatever escaping you see on a mainstream Linux comes from the daemon, not from libc. [source,xml] ---- diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc index 54e712f98..9fef8942b 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc @@ -45,6 +45,10 @@ You can also specify: * SendQueueSize (default: 500), how many datagrams may wait to be sent * EnqueueTimeoutMillis (default: 5000), how long a logging call waits for room in a full queue +RFC 3164 allows only the visible ASCII characters and space in the message, so anything else is +written as a `\uXXXX` escape rather than dropped: a message in a non-Latin script reaches the +collector readable instead of empty. `Encoding` therefore does not make the message body non-ASCII. + Datagrams are handed to a background thread, so a slow or unreachable syslog server does not hold up logging. Once the queue is full, a logging call waits `EnqueueTimeoutMillis` for room and the datagram is then discarded and counted, rather than growing the queue without limit. `Flush` waits