This is an automated email from the ASF dual-hosted git repository. FreeAndNil pushed a commit to branch Feature/security-audit-hardening in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
commit 9f5c955787ddeedf49792a4dd89156c40af87576 Author: Jan Friedrich <[email protected]> AuthorDate: Mon Aug 17 21:29:30 2026 +0200 contain per-event failures in AdoNetAppender.SendBuffer Events are removed from the CyclicBuffer by PopAll before SendBuffer runs, so they cannot be retried later. Neither ExecuteNonQuery loop contained per-event failures, and with UseTransactions (the default) a single event the provider rejects - npgsql refuses U+0000, for example - rolled back the whole batch of up to 512 events, including the ones logged before it. An attacker who gets one such byte logged per flush window could suppress the database audit trail indefinitely. Without a transaction each event is now reported and skipped individually. In transaction mode the exception still has to propagate, so the events are retried one by one after the rollback; only the events the database actually rejects are lost. This makes delivery at-least-once: if the batch failed after the database had already applied some statements, those events are written again. Duplicates are preferred over losing the whole buffer. Log4NetTransaction.Dispose threw NotImplementedException, which log4net swallowed in DoAppend, so no test ever exercised the rollback path. Real providers roll back on Dispose rather than throwing. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]> --- .../309-contain-per-event-adonet-failures.xml | 15 +++ .../Appender/AdoNet/Log4NetCommand.cs | 34 ++++++ .../Appender/AdoNet/Log4NetTransaction.cs | 16 +-- src/log4net.Tests/Appender/AdoNetAppenderTest.cs | 67 +++++++++++ src/log4net/Appender/AdoNetAppender.cs | 130 ++++++++++++++++----- 5 files changed, 228 insertions(+), 34 deletions(-) diff --git a/src/changelog/3.4.0/309-contain-per-event-adonet-failures.xml b/src/changelog/3.4.0/309-contain-per-event-adonet-failures.xml new file mode 100644 index 00000000..6cef7661 --- /dev/null +++ b/src/changelog/3.4.0/309-contain-per-event-adonet-failures.xml @@ -0,0 +1,15 @@ +<?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="309" link="https://github.com/apache/logging-log4net/pull/309"/> + <description format="asciidoc"> + stop a single logging event that the database rejects from discarding the whole buffer in + `AdoNetAppender`. The events have already been removed from the buffer when they are sent, so a + rolled back transaction lost up to `BufferSize` unrelated events, which an attacker could trigger + repeatedly with content the provider refuses, such as `U+0000` on npgsql (CWE-778). Delivery + becomes at-least-once: events already applied by a batch that then failed may be written again + (audit 1231d72-f004) + </description> +</entry> diff --git a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs b/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs index 161d4923..fee95a5d 100644 --- a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs +++ b/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs @@ -20,6 +20,7 @@ */ using System; +using System.Collections.Generic; using System.Data; namespace log4net.Tests.Appender.AdoNet; @@ -42,12 +43,45 @@ public void Dispose() public int ExecuteNonQuery() { + string? payload = null; + foreach (object? parameter in Parameters) + { + if (parameter is IDataParameter { Value: string value }) + { + payload = value; + break; + } + } + payload ??= CommandText; + + if (ExceptionTrigger is not null + && payload?.IndexOf(ExceptionTrigger, StringComparison.Ordinal) >= 0) + { + throw new InvalidOperationException($"Simulated database rejection of [{payload}]"); + } + ExecuteNonQueryCount++; + if (payload is not null) + { + ExecutedPayloads.Add(payload); + } return 0; } public int ExecuteNonQueryCount { get; private set; } + /// <summary> + /// When set, <see cref="ExecuteNonQuery"/> throws for every command whose payload + /// contains this string, simulating a database that rejects specific content. + /// </summary> + public static string? ExceptionTrigger { get; set; } + + /// <summary> + /// The payload - the first string parameter value, or the command text when there are no + /// parameters - of every successful <see cref="ExecuteNonQuery"/> across all instances. + /// </summary> + public static List<string> ExecutedPayloads { get; } = []; + public IDbDataParameter CreateParameter() => new Log4NetParameter(); #pragma warning disable CS8766 // Nullability of reference types in return type doesn't match implicitly implemented member (possibly because of nullability attributes). diff --git a/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs b/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs index 27b3bb9c..81afb218 100644 --- a/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs +++ b/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs @@ -26,19 +26,21 @@ namespace log4net.Tests.Appender.AdoNet; internal sealed class Log4NetTransaction : IDbTransaction { + /// <inheritdoc/> public void Commit() - { - // empty - } + { } + /// <inheritdoc/> public void Rollback() - { - // empty - } + { } + /// <inheritdoc/> public IDbConnection Connection => throw new NotImplementedException(); + /// <inheritdoc/> public IsolationLevel IsolationLevel => throw new NotImplementedException(); - public void Dispose() => throw new NotImplementedException(); + /// <inheritdoc/> + public void Dispose() + { } } diff --git a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs index 17b4119e..c42560d4 100644 --- a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs +++ b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs @@ -264,6 +264,73 @@ public void BufferingWebsiteExample() Assert.That(param.Value, Is.Empty); } + /// <summary> + /// An event the database rejects must only lose itself. The other events of the flushed + /// buffer have already been removed from it and cannot be retried later, so they have to + /// be written even though they shared a transaction with the rejected event. + /// </summary> + [Test] + [NonParallelizable] + public void RejectedEventDoesNotDiscardTheRestOfTheBuffer() + { + try + { + Log4NetCommand.ExceptionTrigger = "POISON"; + Log4NetCommand.ExecutedPayloads.Clear(); + + XmlDocument log4NetConfig = new(); + log4NetConfig.LoadXml( + """ + <log4net> + <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender"> + <bufferSize value="3" /> + <useTransactions value="true" /> + <connectionType value="log4net.Tests.Appender.AdoNet.Log4NetConnection" /> + <connectionString value="data source=[database server]" /> + <commandText value="INSERT INTO Log ([Message]) VALUES (@message)" /> + <parameter> + <parameterName value="@message" /> + <dbType value="String" /> + <size value="4000" /> + <layout type="log4net.Layout.PatternLayout"> + <conversionPattern value="%message" /> + </layout> + </parameter> + </appender> + <root> + <level value="ALL" /> + <appender-ref ref="AdoNetAppender" /> + </root> + </log4net> + """); + + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + XmlConfigurator.Configure(rep, log4NetConfig["log4net"]!); + ILog log = LogManager.GetLogger(rep.Name, "RejectedEventDoesNotDiscardTheRestOfTheBuffer"); + + // The appender reports the rejected event through its ErrorHandler; that is expected + // here and should not clutter the test output. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + log.Debug("before"); + log.Debug("a POISON message"); + log.Debug("after one"); + // The fourth event overflows the buffer of 3 and flushes all four events. + log.Debug("after two"); + }); + + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("before")); + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("after one")); + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("after two")); + Assert.That(Log4NetCommand.ExecutedPayloads, Has.No.Member("a POISON message")); + } + finally + { + Log4NetCommand.ExceptionTrigger = null; + Log4NetCommand.ExecutedPayloads.Clear(); + } + } + [Test] public void NullPropertyXmlConfig() { diff --git a/src/log4net/Appender/AdoNetAppender.cs b/src/log4net/Appender/AdoNetAppender.cs index 65d3e546..886c975d 100644 --- a/src/log4net/Appender/AdoNetAppender.cs +++ b/src/log4net/Appender/AdoNetAppender.cs @@ -394,6 +394,8 @@ protected override void OnClose() /// </remarks> protected override void SendBuffer(LoggingEvent[] events) { + events.EnsureNotNull(); + if (ReconnectOnError && (Connection is null || Connection.State != ConnectionState.Open)) { LogLog.Debug(_declaringType, $"Attempting to reconnect to database. Current Connection State: {((Connection is null) ? SystemInfo.NullText : Connection.State.ToString())}"); @@ -406,30 +408,45 @@ protected override void SendBuffer(LoggingEvent[] events) { if (UseTransactions) { + bool retryPerEvent = false; + // Create transaction // NJC - Do this on 2 lines because it can confuse the debugger - using IDbTransaction dbTran = Connection.BeginTransaction(); - try - { - SendBuffer(dbTran, events); - - // commit transaction - dbTran.Commit(); - } - catch (Exception ex) when (!ex.IsFatal()) + using (IDbTransaction dbTran = Connection.BeginTransaction()) { - // rollback the transaction try { - dbTran.Rollback(); + SendBuffer(dbTran, events); + + // commit transaction + dbTran.Commit(); } - catch (Exception inner) when (!inner.IsFatal()) + catch (Exception ex) when (!ex.IsFatal()) { - // Ignore exception + // rollback the transaction + try + { + dbTran.Rollback(); + } + catch (Exception inner) when (!inner.IsFatal()) + { + // Ignore exception + } + + // Can't insert into the database. That's a bad thing + ErrorHandler.Error("Exception while writing to database", ex); + + retryPerEvent = true; } + } - // Can't insert into the database. That's a bad thing - ErrorHandler.Error("Exception while writing to database", ex); + // The events have already been removed from the buffer, so a rolled back + // transaction would lose all of them - including the events logged before the one + // the database rejected. Retry them one by one, outside the failed transaction, + // so that only the events the database actually rejects are lost. + if (retryPerEvent) + { + SendBufferPerEvent(events); } } else @@ -493,15 +510,26 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events) // run for all events foreach (LoggingEvent e in events) { - // No need to clear dbCmd.Parameters, just use existing. - // Set the parameter values - foreach (AdoNetAppenderParameter param in m_parameters) + try { - param.FormatValue(dbCmd, e); - } + // No need to clear dbCmd.Parameters, just use existing. + // Set the parameter values + foreach (AdoNetAppenderParameter param in m_parameters) + { + param.FormatValue(dbCmd, e); + } - // Execute the query - dbCmd.ExecuteNonQuery(); + // Execute the query + dbCmd.ExecuteNonQuery(); + } + catch (Exception ex) when (dbTran is null && !ex.IsFatal()) + { + // Without a transaction every event stands alone, so an event the database + // rejects must not stop the remaining events from being written. In transaction + // mode the exception has to propagate - the transaction is in a failed state - + // and SendBuffer retries the events individually after the rollback. + ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex); + } } } else @@ -515,13 +543,61 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events) // run for all events foreach (LoggingEvent e in events) { - // Get the command text from the Layout - string logStatement = GetLogStatement(e); + try + { + // Get the command text from the Layout + string logStatement = GetLogStatement(e); - LogLog.Debug(_declaringType, $"LogStatement [{logStatement}]"); + LogLog.Debug(_declaringType, $"LogStatement [{logStatement}]"); - dbCmd.CommandText = logStatement; - dbCmd.ExecuteNonQuery(); + dbCmd.CommandText = logStatement; + dbCmd.ExecuteNonQuery(); + } + catch (Exception ex) when (dbTran is null && !ex.IsFatal()) + { + // See the parameterized path above: contain per-event failures outside transactions. + ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex); + } + } + } + } + + /// <summary> + /// Writes each event with its own command, so that an event the database rejects only + /// loses itself. + /// </summary> + /// <param name="events">The events to insert into the database.</param> + /// <remarks> + /// <para> + /// Used as the fallback after a transactional batch failed and was rolled back. The + /// events are sent without a transaction and failures are reported to the + /// <see cref="AppenderSkeleton.ErrorHandler"/> without affecting the remaining events. + /// </para> + /// <para> + /// Note that this makes delivery at-least-once rather than exactly-once: if the batch + /// failed after the database had already applied some of its statements - for example + /// when the commit itself failed but the rollback did not take effect - those events are + /// written a second time here. Duplicated events are preferred over silently losing the + /// whole buffer. + /// </para> + /// </remarks> + private void SendBufferPerEvent(LoggingEvent[] events) + { + foreach (LoggingEvent e in events) + { + if (Connection is not { State: ConnectionState.Open }) + { + // The connection failed rather than a single event - nothing more can be written. + return; + } + + try + { + SendBuffer(null, [e]); + } + catch (Exception ex) when (!ex.IsFatal()) + { + ErrorHandler.Error("Exception while writing a logging event to the database. The event has been dropped.", ex); } } }
