cap the per-event retry in AdoNetAppender #314

Retrying after a rolled back transaction was added in 3.4.0 to save the events
around the one the database rejected. A batch that fails outright, a missing table
or permission, then cost one round trip per event: measured 21 for a batch of 20,
so 513 for a full buffer where there had been 1.

It gives up after five consecutive failures. Failures spread through a batch do not
count towards that, so a single rejected event still costs only itself.

SendBuffer contains per-event failures and returns normally, so the retry loop had
no way to tell one from a success. A private flag gives it one.

Author: FreeAndNil

src/changelog/3.5.0/314-adonet-retry-cap.xml

@@ -0,0 +1,14 @@
+<?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="314" link="https://github.com/apache/logging-log4net/pull/314"/>
+  <description format="asciidoc">
+    stop `AdoNetAppender` from retrying a whole batch one event at a time when none of them can be
+ written. Retrying after a rolled back transaction was added in 3.4.0 to save the events around
+ the one the database rejected, but a batch that fails outright, such as a missing table or a
+ missing permission, then cost one round trip per event: 513 instead of 1 for a full buffer. It
+ now gives up after five consecutive failures (implemented by @FreeAndNil)
+  </description>
+</entry>

src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs

@@ -60,6 +60,7 @@ public int ExecuteNonQuery()
     }
     payload ??= CommandText;
 
+    AttemptCount++;
     if (ExceptionTrigger is not null
         && payload?.IndexOf(ExceptionTrigger, StringComparison.Ordinal) >= 0)
     {
@@ -79,6 +80,11 @@ public int ExecuteNonQuery()
   /// </summary>
   public int ExecuteNonQueryCount { get; private set; }
 
+  /// <summary>
+  /// Every <see cref="ExecuteNonQuery"/> attempt across all instances, failed ones included.
+  /// </summary>
+  internal static int AttemptCount { get; set; }
+
   /// <summary>
   /// When set, <see cref="ExecuteNonQuery"/> throws for every command whose payload
   /// contains this string, simulating a database that rejects specific content.

src/log4net.Tests/Appender/AdoNetAppenderTest.cs

@@ -501,4 +501,130 @@ public void NullPropertyProgrammaticConfig()
     Assert.That(param.Value, Is.Not.EqualTo(SystemInfo.NullText));
     Assert.That(param.Value, Is.EqualTo(DBNull.Value));
   }
+
+  /// <summary>
+  /// Retrying one by one exists to save the events around the one the database rejected. When
+  /// every one of them fails, the batch is not the problem and each further round trip only
+  /// learns that again.
+  /// </summary>
+  [Test]
+  public void RetryingPerEventGivesUpAfterRepeatedFailures()
+  {
+    const int bufferSize = 19;
+    // One inside the transaction, then five one by one before it gives up.
+    const int expectedAttempts = 6;
+
+    Log4NetCommand.AttemptCount = 0;
+    Log4NetCommand.ExceptionTrigger = "Message";
+    try
+    {
+      XmlDocument log4NetConfig = new();
+      log4NetConfig.LoadXml(
+        """
+        <log4net>
+        <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
+          <bufferSize value="19" />
+          <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, nameof(RetryingPerEventGivesUpAfterRepeatedFailures));
+
+      LogLog.ExecuteWithoutEmittingInternalMessages(() =>
+      {
+        // The event after the buffer is full flushes all twenty.
+        for (int i = 0; i <= bufferSize; i++)
+        {
+          log.Debug("Message");
+        }
+      });
+
+      Assert.That(Log4NetCommand.AttemptCount, Is.EqualTo(expectedAttempts));
+    }
+    finally
+    {
+      Log4NetCommand.ExceptionTrigger = null;
+      Log4NetCommand.ExecutedPayloads.Clear();
+    }
+  }
+
+  /// <summary>
+  /// Giving up must not cost the events around a rejected one, which is the whole point of
+  /// retrying: five failures spread out are not five in a row.
+  /// </summary>
+  [Test]
+  public void RetryingPerEventKeepsGoingWhileFailuresAreSpreadOut()
+  {
+    const int bufferSize = 9;
+    const int expectedWrites = 5;
+
+    Log4NetCommand.AttemptCount = 0;
+    Log4NetCommand.ExceptionTrigger = "POISON";
+    try
+    {
+      XmlDocument log4NetConfig = new();
+      log4NetConfig.LoadXml(
+        """
+        <log4net>
+        <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
+          <bufferSize value="9" />
+          <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, nameof(RetryingPerEventKeepsGoingWhileFailuresAreSpreadOut));
+
+      LogLog.ExecuteWithoutEmittingInternalMessages(() =>
+      {
+        for (int i = 0; i <= bufferSize; i++)
+        {
+          log.Debug(i % 2 == 0 ? "POISON" : $"good {i}");
+        }
+      });
+
+      Assert.That(Log4NetCommand.ExecutedPayloads, Has.Count.EqualTo(expectedWrites));
+      Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("good 9"));
+    }
+    finally
+    {
+      Log4NetCommand.ExceptionTrigger = null;
+      Log4NetCommand.ExecutedPayloads.Clear();
+    }
+  }
 }

src/log4net/Appender/AdoNetAppender.cs

@@ -549,6 +549,7 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events)
           // 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.
+          _eventFailed = true;
           ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex);
         }
       }
@@ -577,6 +578,7 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events)
         catch (Exception ex) when (dbTran is null && !ex.IsFatal())
         {
           // See the parameterized path above: contain per-event failures outside transactions.
+          _eventFailed = true;
           ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex);
         }
       }
@@ -604,6 +606,7 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events)
   /// </remarks>
   private void SendBufferPerEvent(LoggingEvent[] events)
   {
+    int failuresInARow = 0;
     foreach (LoggingEvent e in events)
     {
       if (Connection is not { State: ConnectionState.Open })
@@ -612,17 +615,41 @@ private void SendBufferPerEvent(LoggingEvent[] events)
         return;
       }
 
+      _eventFailed = false;
       try
       {
         SendBuffer(null, [e]);
       }
       catch (Exception ex) when (!ex.IsFatal())
       {
+        _eventFailed = true;
         ErrorHandler.Error("Exception while writing a logging event to the database. The event has been dropped.", ex);
       }
+
+      if (!_eventFailed)
+      {
+        failuresInARow = 0;
+      }
+      else if (++failuresInARow >= MaxFailuresInARow)
+      {
+        // Retrying one by one is meant to save the events around the one the database rejected.
+        // This many in a row means the batch is not the problem, and the remaining events would
+        // cost one round trip each to learn the same thing.
+        ErrorHandler.Error(
+          $"Giving up on the remaining logging events after {failuresInARow} consecutive failures.");
+        return;
+      }
     }
   }
 
+  /// <summary>
+  /// Set by the contained per-event failure path in <see cref="SendBuffer(IDbTransaction, LoggingEvent[])"/>,
+  /// which reports rather than throws, so <see cref="SendBufferPerEvent"/> can count failures.
+  /// </summary>
+  private bool _eventFailed;
+
+  private const int MaxFailuresInARow = 5;
+
   /// <summary>
   /// Prepare entire database command object to be executed.
   /// </summary>