diff --git a/doc/MailTemplate.Announce.txt b/doc/MailTemplate.Announce.txt index 16cc17ff..1a240b07 100644 --- a/doc/MailTemplate.Announce.txt +++ b/doc/MailTemplate.Announce.txt @@ -1,16 +1,16 @@ To: announce@apache.org, dev@logging.apache.org -Subject: [ANNOUNCE] Apache log4net 3.4.1 released +Subject: [ANNOUNCE] Apache log4net 3.5.0 released Hi, -the Apache log4net team is pleased to announce the 3.4.1 release. +the Apache log4net team is pleased to announce the 3.5.0 release. For further information (support, download, etc.) see - https://logging.apache.org/log4net/release-notes.html -- https://github.com/apache/logging-log4net/releases/tag/rel%2F3.4.1 -- https://www.nuget.org/packages/log4net/3.4.1 -- https://www.nuget.org/packages/log4net.Ext.Mail/3.4.1 +- https://github.com/apache/logging-log4net/releases/tag/rel%2F3.5.0 +- https://www.nuget.org/packages/log4net/3.5.0 +- https://www.nuget.org/packages/log4net.Ext.Mail/3.5.0 Highlights of this release: diff --git a/doc/MailTemplate.Result.txt b/doc/MailTemplate.Result.txt index 1fced0d7..cb5bd438 100644 --- a/doc/MailTemplate.Result.txt +++ b/doc/MailTemplate.Result.txt @@ -1,5 +1,5 @@ To: dev@logging.apache.org -Subject: [RESULT][VOTE] Release Apache Log4net 3.4.1 +Subject: [RESULT][VOTE] Release Apache Log4net 3.5.0 and here is my +1. @@ -9,6 +9,6 @@ I will continue the release process. Jan --------------------------------------------------------------------------------------------------- -This is a vote to release the Apache Log4net 3.4.1. +This is a vote to release the Apache Log4net 3.5.0. ... diff --git a/doc/MailTemplate.txt b/doc/MailTemplate.txt index 51b1bc53..43e3480e 100644 --- a/doc/MailTemplate.txt +++ b/doc/MailTemplate.txt @@ -1,12 +1,12 @@ To: dev@logging.apache.org -Subject: [VOTE] Release Apache Log4net 3.4.1 +Subject: [VOTE] Release Apache Log4net 3.5.0 -This is a vote to release the Apache Log4net 3.4.1. +This is a vote to release the Apache Log4net 3.5.0. Website: https://logging.staged.apache.org/log4net/release-notes.html GitHub: https://github.com/apache/logging-log4net Commit: -Distribution: https://dist.apache.org/repos/dist/dev/logging/log4net/3.4.1 +Distribution: https://dist.apache.org/repos/dist/dev/logging/log4net/3.5.0 Signing key: 0x7D24496A230E29D6349A99EF583E491578F02D5D Review kit: https://logging.staged.apache.org/log4net/release-review.html diff --git a/package-lock.json b/package-lock.json index 20a6862c..ddbe14eb 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "log4net", - "version": "3.4.1", + "version": "3.5.0", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "log4net", - "version": "3.4.1", + "version": "3.5.0", "license": "Apache-2.0", "devDependencies": { "@antora/cli": "^3.2.0-rc.2", diff --git a/package.json b/package.json index 5c751db7..f64eacca 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "log4net", - "version": "3.4.1", + "version": "3.5.0", "description": "Log4Net is a logging framework for .NET", "repository": { "type": "git", diff --git a/pom.xml b/pom.xml index 08b56804..b3ac80f1 100644 --- a/pom.xml +++ b/pom.xml @@ -25,7 +25,7 @@ pom org.apache.logging.log4net apache-log4net - 3.4.1 + 3.5.0 Apache log4net Logging framework for Microsoft .NET Framework. https://logging.apache.org/log4net diff --git a/scripts/build-preview.ps1 b/scripts/build-preview.ps1 index 7c6926ad..4b535934 100644 --- a/scripts/build-preview.ps1 +++ b/scripts/build-preview.ps1 @@ -1,7 +1,7 @@ #Requires -Version 7.4 param( - $Version = '3.4.1', + $Version = '3.5.0', $Preview = '1' ) diff --git a/scripts/build-release.ps1 b/scripts/build-release.ps1 index d5bbfd51..de2f0c1e 100644 --- a/scripts/build-release.ps1 +++ b/scripts/build-release.ps1 @@ -1,7 +1,7 @@ #Requires -Version 7.4 param( - $Version = '3.4.1' + $Version = '3.5.0' ) Set-StrictMode -Version Latest diff --git a/src/Directory.Build.props b/src/Directory.Build.props index 90cfaa4b..5b60be69 100644 --- a/src/Directory.Build.props +++ b/src/Directory.Build.props @@ -22,7 +22,7 @@ $(NoWarn);CS1591 - 3.4.1 + 3.5.0 3.4.0 4.17.0 4.5.0 diff --git a/src/changelog/3.4.1/.release-notes.adoc.ftl b/src/changelog/3.5.0/.release-notes.adoc.ftl similarity index 100% rename from src/changelog/3.4.1/.release-notes.adoc.ftl rename to src/changelog/3.5.0/.release-notes.adoc.ftl diff --git a/src/changelog/3.4.1/.release.xml b/src/changelog/3.5.0/.release.xml similarity index 83% rename from src/changelog/3.4.1/.release.xml rename to src/changelog/3.5.0/.release.xml index 85240f86..4bba497b 100644 --- a/src/changelog/3.4.1/.release.xml +++ b/src/changelog/3.5.0/.release.xml @@ -2,5 +2,5 @@ \ No newline at end of file + date="2026-11-01" + version="3.5.0"/> \ No newline at end of file diff --git a/src/changelog/3.4.1/162-quiet-app-settings-in-a-native-host.xml b/src/changelog/3.5.0/162-quiet-app-settings-in-a-native-host.xml similarity index 100% rename from src/changelog/3.4.1/162-quiet-app-settings-in-a-native-host.xml rename to src/changelog/3.5.0/162-quiet-app-settings-in-a-native-host.xml diff --git a/src/changelog/3.4.1/313-redact-connection-string-allowlist.xml b/src/changelog/3.5.0/313-redact-connection-string-allowlist.xml similarity index 100% rename from src/changelog/3.4.1/313-redact-connection-string-allowlist.xml rename to src/changelog/3.5.0/313-redact-connection-string-allowlist.xml diff --git a/src/changelog/3.4.1/313-require-powershell-74.xml b/src/changelog/3.5.0/313-require-powershell-74.xml similarity index 94% rename from src/changelog/3.4.1/313-require-powershell-74.xml rename to src/changelog/3.5.0/313-require-powershell-74.xml index 9b3636ee..3222a5e4 100644 --- a/src/changelog/3.4.1/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 da18b6fd-f004) + run the script with `pwsh` (audit 1231d72-f009) diff --git a/src/changelog/3.4.1/313-verify-release-keys-bypass.xml b/src/changelog/3.5.0/313-verify-release-keys-bypass.xml similarity index 100% rename from src/changelog/3.4.1/313-verify-release-keys-bypass.xml rename to src/changelog/3.5.0/313-verify-release-keys-bypass.xml diff --git a/src/changelog/3.5.0/314-adonet-retry-cap.xml b/src/changelog/3.5.0/314-adonet-retry-cap.xml new file mode 100644 index 00000000..4a32b49b --- /dev/null +++ b/src/changelog/3.5.0/314-adonet-retry-cap.xml @@ -0,0 +1,14 @@ + + + + + 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) + + 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 new file mode 100644 index 00000000..f16ce22f --- /dev/null +++ b/src/changelog/3.5.0/314-ext-mail-background-sender.xml @@ -0,0 +1,15 @@ + + + + + send mail from a background thread in the MailKit based `SmtpAppender`. The mail used to go out + while the appender lock was held, so the thread that logged, and every thread behind it, waited + 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) + + 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 new file mode 100644 index 00000000..2a8a0469 --- /dev/null +++ b/src/changelog/3.5.0/314-ext-mail-send-timeout.xml @@ -0,0 +1,14 @@ + + + + + bound a whole send in the MailKit based `SmtpAppender` to 15 seconds. MailKit waits 100 seconds + 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) + + diff --git a/src/changelog/3.5.0/314-flush-reports-buffered-events.xml b/src/changelog/3.5.0/314-flush-reports-buffered-events.xml new file mode 100644 index 00000000..535f067d --- /dev/null +++ b/src/changelog/3.5.0/314-flush-reports-buffered-events.xml @@ -0,0 +1,12 @@ + + + + + report a buffering appender that is still holding events from `Flush`. It returned `true` + unconditionally, including for a `lossy` appender, where flushing deliberately does nothing and + every buffered event stays where it was (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 new file mode 100644 index 00000000..9ea954df --- /dev/null +++ b/src/changelog/3.5.0/314-remote-syslog-background-sender.xml @@ -0,0 +1,14 @@ + + + + + bound the queue `RemoteSyslogAppender` sends from. It was unbounded, so a syslog server that + 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) + + 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 new file mode 100644 index 00000000..fb2185c7 --- /dev/null +++ b/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml @@ -0,0 +1,14 @@ + + + + + stop `RemoteSyslogAppender` from opening a second, unused UDP socket. It sends through the + 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) + + diff --git a/src/changelog/3.5.0/314-smtpappender-send-timeout.xml b/src/changelog/3.5.0/314-smtpappender-send-timeout.xml new file mode 100644 index 00000000..17fa2805 --- /dev/null +++ b/src/changelog/3.5.0/314-smtpappender-send-timeout.xml @@ -0,0 +1,13 @@ + + + + + bound a single send in `SmtpAppender` to 15 seconds. `SmtpClient.Timeout` defaults to 100 + seconds and the appender never set it, and the mail goes out while the appender lock is held, so + a server that accepted the connection and then stopped answering suspended every thread logging + through the appender. Configurable with `SendTimeoutMillis` (implemented by @FreeAndNil) + + diff --git a/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs b/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs index 47ba1e5f..a8f50c3d 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs @@ -21,6 +21,7 @@ using System.Collections.Generic; using System.Linq; using System.Net; +using System.Threading; using System.Text; using log4net.Ext.Mail.Appender.Internal; @@ -67,36 +68,46 @@ internal sealed class FakeSmtpTransport : ISmtpTransport /// internal Exception? SendException { get; set; } + /// When set, every call that takes a token waits this long, honouring it. + internal int DelayMillisPerCall { get; set; } + + public int Timeout { get; set; } + public bool IsConnected { get; private set; } public bool IsAuthenticated { get; private set; } - public void Connect(string host, int port, SecureSocketOptions secureSocketOptions) + public void Connect(string host, int port, SecureSocketOptions secureSocketOptions, + CancellationToken cancellationToken) { Calls.Add(nameof(Connect)); + Delay(cancellationToken); ConnectedHost = host; ConnectedPort = port; SecureSocketOptions = secureSocketOptions; IsConnected = true; } - public void Authenticate(ICredentials credentials) + public void Authenticate(ICredentials credentials, CancellationToken cancellationToken) { Calls.Add(nameof(Authenticate)); + Delay(cancellationToken); Credentials = credentials; IsAuthenticated = true; } - public void Authenticate(SaslMechanism mechanism) + public void Authenticate(SaslMechanism mechanism, CancellationToken cancellationToken) { Calls.Add(nameof(Authenticate)); + Delay(cancellationToken); SaslMechanism = mechanism; IsAuthenticated = true; } - public void Send(MimeMessage message) + public void Send(MimeMessage message, CancellationToken cancellationToken) { Calls.Add(nameof(Send)); + Delay(cancellationToken); if (SendException is Exception exception) { throw exception; @@ -116,6 +127,16 @@ public void Dispose() Calls.Add(nameof(Dispose)); IsDisposed = true; } + + private void Delay(CancellationToken cancellationToken) + { + if (DelayMillisPerCall > 0) + { + cancellationToken.WaitHandle.WaitOne(DelayMillisPerCall); + } + + cancellationToken.ThrowIfCancellationRequested(); + } } /// diff --git a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs index 33810395..24da27ee 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs @@ -21,6 +21,7 @@ using System.Collections.Generic; using System.Net; using System.Net.Mail; +using System.Diagnostics; using System.Text; using log4net.Core; using log4net.Ext.Mail.Appender; @@ -106,8 +107,12 @@ private static void Append(SmtpAppender appender, string message = "log message" { appender.ActivateOptions(); appender.DoAppend(CreateEvent(message)); + // Sending is asynchronous. + appender.Flush(FlushTimeoutMillis); } + private const int FlushTimeoutMillis = 30_000; + [Test] public void SendsOneMailPerEventWhenNotBuffering() { @@ -497,7 +502,7 @@ public void SendFailureIsReportedToTheErrorHandlerAndNotThrown() Assert.DoesNotThrow(() => Append(appender)); - Assert.That(_errorHandler.Message, Does.Contain("Error occurred while sending e-mail notification.")); + Assert.That(_errorHandler.Message, Does.Contain("Failed to send a logging event.")); Assert.That(_errorHandler.Message, Does.Contain("relay refused")); } @@ -550,6 +555,7 @@ public void EachSendUsesAFreshTransport() appender.DoAppend(CreateEvent("first")); appender.DoAppend(CreateEvent("second")); + appender.Flush(FlushTimeoutMillis); Assert.That(transports, Has.Count.EqualTo(2)); Assert.That(transports[0].SentMails[0].Body, Does.Contain("first")); @@ -568,7 +574,7 @@ public void BufferedEventsAreSentInASingleMail() appender.DoAppend(CreateEvent("three")); Assert.That(_transport.SentMails, Is.Empty, "the buffer is not full yet"); - appender.Flush(true); + Assert.That(appender.Flush(FlushTimeoutMillis), Is.True); Assert.That(_transport.SentMails, Has.Count.EqualTo(1)); string body = _transport.SentMails[0].Body; @@ -593,6 +599,7 @@ public void RequiresALayout() appender.ActivateOptions(); appender.DoAppend(CreateEvent("no layout")); + appender.Flush(FlushTimeoutMillis); Assert.That(_transport.SentMails, Is.Empty); Assert.That(_errorHandler.Message, Is.Not.Empty); @@ -615,4 +622,76 @@ public void DefaultConstructorUsesTheMailKitTransport() Assert.That(appender.BodyEncoding, Is.EqualTo(Encoding.UTF8)); Assert.That(appender.EnableSsl, Is.False); } + + /// An unbounded send stalls every thread logging through the appender. + [Test] + public void SendTimeoutMillisDefaultsToFifteenSeconds() + => Assert.That(CreateAppender().SendTimeoutMillis, Is.EqualTo(15_000)); + + /// Neither 0 nor a negative value is a usable deadline. + [TestCase(0)] + [TestCase(-1)] + public void SendTimeoutMillisRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => CreateAppender().SendTimeoutMillis = value, + Throws.TypeOf()); + + /// MailKit needs it too, for the reads and writes between the cancellation checks. + [Test] + public void TheTimeoutReachesTheTransport() + { + const int sendTimeoutMillis = 1_234; + SmtpAppender appender = CreateAppender(); + appender.SendTimeoutMillis = sendTimeoutMillis; + + Append(appender); + + Assert.That(_transport.Timeout, Is.EqualTo(sendTimeoutMillis)); + } + + /// + /// Every single operation stays inside the timeout here, their sum does not. A per operation + /// timeout would let this run on; the deadline stops it. + /// + [Test] + public void TheDeadlineCoversTheWholeSendAndNotOneOperation() + { + const int sendTimeoutMillis = 300; + const int delayMillisPerCall = 200; + const int generousBoundMillis = 5_000; + + SmtpAppender appender = CreateAppender(); + appender.SendTimeoutMillis = sendTimeoutMillis; + _transport.DelayMillisPerCall = delayMillisPerCall; + + Stopwatch stopwatch = Stopwatch.StartNew(); + Append(appender); + stopwatch.Stop(); + + Assert.That(_transport.SentMails, Is.Empty); + Assert.That(_errorHandler.Message, Does.Contain("Failed to send a logging event.")); + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(generousBoundMillis)); + } + + /// Bounded, so an unreachable server cannot grow the queue without limit. + [Test] + public void SendQueueSizeDefaultsTo500() + => Assert.That(CreateAppender().SendQueueSize, Is.EqualTo(500)); + + /// The longest a logging call waits when the queue is full. + [Test] + public void EnqueueTimeoutMillisDefaultsTo5000() + => Assert.That(CreateAppender().EnqueueTimeoutMillis, Is.EqualTo(5_000)); + + /// A queue with no room for anything cannot work. + [TestCase(0)] + [TestCase(-1)] + public void SendQueueSizeRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => CreateAppender().SendQueueSize = value, + Throws.TypeOf()); + + /// 0 is allowed and never waits, a negative wait is meaningless. + [Test] + public void EnqueueTimeoutMillisRejectsANegativeValue() + => Assert.That(() => CreateAppender().EnqueueTimeoutMillis = -1, + Throws.TypeOf()); } diff --git a/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs b/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs index 65ef28c6..6f470f38 100644 --- a/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs +++ b/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs @@ -19,6 +19,7 @@ using System; using System.Net; +using System.Threading; using MailKit.Security; using MimeKit; @@ -40,6 +41,11 @@ namespace log4net.Ext.Mail.Appender.Internal; /// internal interface ISmtpTransport : IDisposable { + /// + /// The timeout for a single network operation, in milliseconds. + /// + int Timeout { get; set; } + /// /// Gets a value indicating whether the transport is connected to a server. /// @@ -56,26 +62,31 @@ internal interface ISmtpTransport : IDisposable /// The name or address of the SMTP server. /// The port the SMTP server is listening on. /// The transport security to use. - void Connect(string host, int port, SecureSocketOptions secureSocketOptions); + /// Abandons the operation when the deadline passes. + void Connect(string host, int port, SecureSocketOptions secureSocketOptions, + CancellationToken cancellationToken); /// /// Authenticates using the supplied and whichever /// SASL mechanism the server and client agree on. /// /// The credentials to authenticate with. - void Authenticate(ICredentials credentials); + /// Abandons the operation when the deadline passes. + void Authenticate(ICredentials credentials, CancellationToken cancellationToken); /// /// Authenticates using an explicit SASL . /// /// The SASL mechanism to authenticate with. - void Authenticate(SaslMechanism mechanism); + /// Abandons the operation when the deadline passes. + void Authenticate(SaslMechanism mechanism, CancellationToken cancellationToken); /// /// Sends the specified . /// /// The message to send. - void Send(MimeMessage message); + /// Abandons the operation when the deadline passes. + void Send(MimeMessage message, CancellationToken cancellationToken); /// /// Disconnects from the SMTP server. diff --git a/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs b/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs index 69768242..3381ed77 100644 --- a/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs +++ b/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs @@ -18,6 +18,7 @@ #endregion using System.Net; +using System.Threading; using MailKit.Net.Smtp; using MailKit.Security; using MimeKit; @@ -32,6 +33,13 @@ internal sealed class MailKitSmtpTransport : ISmtpTransport { private readonly SmtpClient _client = new(); + /// + public int Timeout + { + get => _client.Timeout; + set => _client.Timeout = value; + } + /// public bool IsConnected => _client.IsConnected; @@ -39,17 +47,21 @@ internal sealed class MailKitSmtpTransport : ISmtpTransport public bool IsAuthenticated => _client.IsAuthenticated; /// - public void Connect(string host, int port, SecureSocketOptions secureSocketOptions) - => _client.Connect(host, port, secureSocketOptions); + public void Connect(string host, int port, SecureSocketOptions secureSocketOptions, + CancellationToken cancellationToken) + => _client.Connect(host, port, secureSocketOptions, cancellationToken); /// - public void Authenticate(ICredentials credentials) => _client.Authenticate(credentials); + public void Authenticate(ICredentials credentials, CancellationToken cancellationToken) + => _client.Authenticate(credentials, cancellationToken); /// - public void Authenticate(SaslMechanism mechanism) => _client.Authenticate(mechanism); + public void Authenticate(SaslMechanism mechanism, CancellationToken cancellationToken) + => _client.Authenticate(mechanism, cancellationToken); /// - public void Send(MimeMessage message) => _client.Send(message); + public void Send(MimeMessage message, CancellationToken cancellationToken) + => _client.Send(message, cancellationToken); /// public void Disconnect(bool quit) => _client.Disconnect(quit); diff --git a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs index e2d631a4..1c2bd3da 100644 --- a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs +++ b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs @@ -20,6 +20,7 @@ using System; using System.IO; using System.Net; +using System.Threading; using System.Net.Mail; using System.Text; @@ -330,7 +331,16 @@ protected override void SendBuffer(LoggingEvent[] events) writer.Write(footer); } - SendEmail(writer.ToString()); + string body = writer.ToString(); + if (_sender is BackgroundSender sender) + { + // A full queue is reported by the sender itself. + sender.TryEnqueue(body, EnqueueTimeoutMillis); + } + else + { + SendEmail(body); + } } catch (Exception e) when (!e.IsFatal()) { @@ -338,6 +348,91 @@ protected override void SendBuffer(LoggingEvent[] events) } } + /// + public override void ActivateOptions() + { + base.ActivateOptions(); + CloseSender(); + _sender = new(nameof(SmtpAppender), SendQueueSize, (body, _) => SendEmail(body), Report); + } + + /// + public override bool Flush(int millisecondsTimeout) + { + bool buffered = base.Flush(millisecondsTimeout); + bool queued = _sender?.Flush(millisecondsTimeout) ?? true; + return buffered && queued; + } + + /// + protected override void OnClose() + { + base.OnClose(); + CloseSender(); + } + + /// + /// How many rendered mails may wait to be sent. Defaults to 500. + /// + /// The value specified is not positive. + public int SendQueueSize + { + get => _sendQueueSize; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendQueueSize is not positive."); + } + _sendQueueSize = value; + } + } + + /// + /// How long a logging call waits for room in a full queue. Defaults to 5000, 0 never waits. + /// + /// The value specified is negative. + public int EnqueueTimeoutMillis + { + get => _enqueueTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for EnqueueTimeoutMillis is negative."); + } + _enqueueTimeoutMillis = value; + } + } + + private void CloseSender() + { + if (_sender is BackgroundSender sender) + { + _sender = null; + sender.Close(SendTimeoutMillis); + sender.Dispose(); + } + } + + private void Report(string message, Exception? exception) + { + if (exception is null) + { + ErrorHandler.Error(message); + } + else + { + ErrorHandler.Error(message, exception); + } + } + + private BackgroundSender? _sender; + private int _sendQueueSize = 500; + private int _enqueueTimeoutMillis = 5_000; + /// /// This appender requires a to be set. /// @@ -375,33 +470,60 @@ protected override void SendBuffer(LoggingEvent[] events) /// the body text to include in the mail protected virtual void SendEmail(string messageBody) { + using CancellationTokenSource deadline = new(SendTimeoutMillis); using MimeMessage message = CreateMessage(messageBody); using ISmtpTransport transport = _transportFactory().EnsureNotNull(); + transport.Timeout = SendTimeoutMillis; - transport.Connect(SmtpHost.EnsureNotNullOrEmpty(), Port, ResolveSecureSocketOptions()); + transport.Connect(SmtpHost.EnsureNotNullOrEmpty(), Port, ResolveSecureSocketOptions(), deadline.Token); try { switch (Authentication) { case SmtpAuthentication.Basic: - transport.Authenticate(new NetworkCredential(Username, Password)); + transport.Authenticate(new NetworkCredential(Username, Password), deadline.Token); break; case SmtpAuthentication.Ntlm: - transport.Authenticate(new SaslMechanismNtlm(new NetworkCredential(Username, Password))); + transport.Authenticate(new SaslMechanismNtlm(new NetworkCredential(Username, Password)), deadline.Token); break; case SmtpAuthentication.None: default: break; } - transport.Send(message); + transport.Send(message, deadline.Token); } finally { + // No token: already cancelled, it would replace the failure that got us here. transport.Disconnect(true); } } + /// + /// A deadline for the whole send, in milliseconds. Defaults to 15000. + /// + /// + /// MailKit's own timeout applies per operation, so a server answering just inside it can still + /// take a multiple of it. The mail goes out under the appender lock. + /// + /// The value specified is not positive. + public int SendTimeoutMillis + { + get => _sendTimeoutMillis; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendTimeoutMillis is not positive."); + } + _sendTimeoutMillis = value; + } + } + + private int _sendTimeoutMillis = 15_000; + /// /// Builds the for the given body text from the configured options. /// diff --git a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs b/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs index 7a44dea2..280f484f 100644 --- a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs +++ b/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() /// public int ExecuteNonQueryCount { get; private set; } + /// + /// Every attempt across all instances, failed ones included. + /// + internal static int AttemptCount { get; set; } + /// /// When set, throws for every command whose payload /// contains this string, simulating a database that rejects specific content. diff --git a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs index af339681..c03f99b4 100644 --- a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs +++ b/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)); } + + /// + /// 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. + /// + [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( + """ + + + + + + + + + + + + + + + + + + + + + + """); + + 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(); + } + } + + /// + /// 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. + /// + [Test] + public void RetryingPerEventKeepsGoingWhileFailuresAreSpreadOut() + { + const int bufferSize = 9; + const int expectedWrites = 5; + + Log4NetCommand.AttemptCount = 0; + Log4NetCommand.ExceptionTrigger = "POISON"; + try + { + XmlDocument log4NetConfig = new(); + log4NetConfig.LoadXml( + """ + + + + + + + + + + + + + + + + + + + + + + """); + + 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(); + } + } } diff --git a/src/log4net.Tests/Appender/BufferingAppenderTest.cs b/src/log4net.Tests/Appender/BufferingAppenderTest.cs index 6a9cf1d5..0040ced9 100644 --- a/src/log4net.Tests/Appender/BufferingAppenderTest.cs +++ b/src/log4net.Tests/Appender/BufferingAppenderTest.cs @@ -100,4 +100,39 @@ public void TestBufferSize5() logger.Log(typeof(BufferingAppenderTest), Level.Warn, "Message 8", null); Assert.That(_countingAppender.Counter, Is.EqualTo(6), "Test 2 event in buffer. 6 event sent"); } -} \ No newline at end of file + + /// The buffer is emptied, so the answer is yes. + [Test] + public void FlushReportsSuccessWhenTheBufferIsEmptied() + { + SetupRepository(); + _bufferingForwardingAppender.BufferSize = 5; + _bufferingForwardingAppender.ActivateOptions(); + + ILogger logger = _hierarchy.GetLogger("test"); + logger.Log(typeof(BufferingAppenderTest), Level.Warn, "Message", null); + + Assert.That(_bufferingForwardingAppender.Flush(0), Is.True); + Assert.That(_countingAppender.Counter, Is.EqualTo(1)); + } + + /// + /// A lossy appender keeps its events until something triggers them, so reporting that they + /// were flushed would be untrue. + /// + [Test] + public void FlushReportsFailureWhileALossyBufferKeepsItsEvents() + { + SetupRepository(); + _bufferingForwardingAppender.BufferSize = 5; + _bufferingForwardingAppender.Lossy = true; + _bufferingForwardingAppender.Evaluator = new LevelEvaluator(Level.Off); + _bufferingForwardingAppender.ActivateOptions(); + + ILogger logger = _hierarchy.GetLogger("test"); + logger.Log(typeof(BufferingAppenderTest), Level.Warn, "Message", null); + + Assert.That(_bufferingForwardingAppender.Flush(0), Is.False); + Assert.That(_countingAppender.Counter, Is.EqualTo(0)); + } +} diff --git a/src/log4net.Tests/Appender/Internal/UdpMock.cs b/src/log4net.Tests/Appender/Internal/UdpMock.cs index 152c625e..3d06e74f 100644 --- a/src/log4net.Tests/Appender/Internal/UdpMock.cs +++ b/src/log4net.Tests/Appender/Internal/UdpMock.cs @@ -17,6 +17,7 @@ // #endregion +using System; using System.Collections.Generic; using System.Net; using System.Threading.Tasks; @@ -44,9 +45,20 @@ internal sealed class UdpMock : IUdpConnection /// internal (int LocalPort, IPAddress Host, int RemotePort)? ConnectedTo { get; private set; } + /// + /// When set, throws this. + /// + internal Exception? ConnectException { get; set; } + /// - public void Connect(int localPort, IPAddress host, int remotePort) - => ConnectedTo = (localPort, host, remotePort); + public void Connect(int localPort, IPAddress host, int remotePort) + { + ConnectedTo = (localPort, host, remotePort); + if (ConnectException is Exception exception) + { + throw exception; + } + } /// public void Dispose() => WasDisposed = true; diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index a9f6ed44..5b187822 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -17,10 +17,10 @@ // #endregion +using System; using System.Collections.Generic; using System.Linq; using System.Text; -using System.Threading; using log4net.Appender; using log4net.Appender.Internal; using log4net.Core; @@ -46,6 +46,95 @@ private sealed class RemoteAppender : RemoteSyslogAppender /// protected override IUdpConnection CreateUdpConnection() => Mock; + + /// The socket the base class would have opened. + internal System.Net.Sockets.UdpClient? InheritedClient => Client; + } + + /// Collects reported errors instead of letting them reach the console. + private sealed class RecordingErrorHandler : IErrorHandler + { + /// Reported messages. + internal List Messages { get; } = []; + + /// + public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message); + + /// + public void Error(string message, Exception e) => Messages.Add(message); + + /// + public void Error(string message) => Messages.Add(message); + } + + private const int FlushTimeoutMillis = 30_000; + + /// Bounded, so an unreachable server cannot grow the queue without limit. + [Test] + public void SendQueueSizeDefaultsTo500() + => Assert.That(new RemoteSyslogAppender().SendQueueSize, Is.EqualTo(500)); + + /// The longest a logging call waits when the queue is full. + [Test] + public void EnqueueTimeoutMillisDefaultsTo5000() + => Assert.That(new RemoteSyslogAppender().EnqueueTimeoutMillis, Is.EqualTo(5_000)); + + /// A queue with no room for anything cannot work. + [TestCase(0)] + [TestCase(-1)] + public void SendQueueSizeRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => new RemoteSyslogAppender().SendQueueSize = value, + Throws.TypeOf()); + + /// 0 is allowed and never waits, a negative wait is meaningless. + [Test] + public void EnqueueTimeoutMillisRejectsANegativeValue() + => Assert.That(() => new RemoteSyslogAppender().EnqueueTimeoutMillis = -1, + Throws.TypeOf()); + + /// + /// This appender sends through the connection its pump owns, so the inherited one would be a + /// second socket, holding a second binding of LocalPort, that nothing ever uses. + /// + [Test] + public void TheInheritedSocketIsNotOpened() + { + RemoteAppender appender = new() + { + RemoteAddress = new System.Net.IPAddress([127, 0, 0, 1]), + Layout = new PatternLayout("%message") + }; + appender.ActivateOptions(); + try + { + Assert.That(appender.InheritedClient, Is.Null); + } + finally + { + appender.Close(); + } + } + + /// + /// Connecting happens outside the send loop, so a failure there used to fault the pump with + /// nobody watching and every later event queued behind a sender that was gone. + /// + [Test] + public void AConnectFailureIsReported() + { + RecordingErrorHandler errorHandler = new(); + RemoteAppender appender = new() + { + RemoteAddress = new System.Net.IPAddress([127, 0, 0, 1]), + Layout = new PatternLayout("%message"), + ErrorHandler = errorHandler + }; + appender.Mock.ConnectException = new InvalidOperationException("simulated connect failure"); + + appender.ActivateOptions(); + appender.Close(); + + Assert.That(errorHandler.Messages, Has.Some.Contains("Unable to connect to remote syslog")); } /// @@ -197,13 +286,7 @@ private static List ExecuteAppend(string message, Domain = "TestDomain", }); appender.DoAppend(loggingEvent); - for (int i = 0; i < 20; i++) - { - if (appender.Mock.Sent.Count == 0) - { - Thread.Sleep(10); - } - } + Assert.That(appender.Flush(FlushTimeoutMillis), Is.True); appender.Close(); Assert.That(appender.Mock.ConnectedTo, Is.EqualTo((0, ipAddress, 514))); Assert.That(appender.Mock.WasDisposed, Is.True); diff --git a/src/log4net.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Tests/Appender/SmtpAppenderTest.cs new file mode 100644 index 00000000..259cfd9c --- /dev/null +++ b/src/log4net.Tests/Appender/SmtpAppenderTest.cs @@ -0,0 +1,138 @@ +#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.Collections.Generic; +using System.Diagnostics; +using System.Net; +using System.Net.Sockets; +using System.Threading; +using System.Threading.Tasks; + +using log4net.Appender; +using log4net.Config; +using log4net.Core; +using log4net.Layout; +using log4net.Repository; +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +#pragma warning disable CS0618 // obsolete, but still shipped + +/// +/// Tests for . +/// +[TestFixture] +public class SmtpAppenderTest +{ + /// An unbounded send stalls every thread logging through the appender. + [Test] + public void SendTimeoutMillisDefaultsToFifteenSeconds() + => Assert.That(new SmtpAppender().SendTimeoutMillis, Is.EqualTo(15_000)); + + /// treats 0 as "do not wait". + [TestCase(0)] + [TestCase(-1)] + public void SendTimeoutMillisRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => new SmtpAppender().SendTimeoutMillis = value, + Throws.TypeOf()); + + /// A silent server must not hold the logging call for the 100 second default. + [Test] + [System.Diagnostics.CodeAnalysis.SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", + Justification = "TcpListener is not IDisposable on net462. Stop() in the finally.")] + public void AnUnresponsiveServerDoesNotStallTheLoggingCall() + { + const int sendTimeoutMillis = 1_000; + const int generousBoundMillis = 30_000; + + using ManualResetEventSlim finished = new(false); + TcpListener listener = new(IPAddress.Loopback, 0); + listener.Start(); + int port = ((IPEndPoint)listener.LocalEndpoint).Port; + + // Accepts, then stays silent: the greeting never comes. + Task stub = Task.Run(() => + { + try + { + using TcpClient client = listener.AcceptTcpClient(); + finished.Wait(generousBoundMillis); + } + catch (Exception e) when (!e.IsFatal()) + { + // Stopped while the accept was pending. + } + }); + + RecordingErrorHandler errorHandler = new(); + try + { + SmtpAppender appender = new() + { + SmtpHost = "127.0.0.1", + Port = port, + From = "from@example.com", + To = "to@example.com", + Subject = "test", + BufferSize = 1, + Layout = new PatternLayout("%message"), + SendTimeoutMillis = sendTimeoutMillis, + ErrorHandler = errorHandler + }; + appender.ActivateOptions(); + + ILoggerRepository repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + BasicConfigurator.Configure(repository, appender); + ILog log = LogManager.GetLogger(repository.Name, nameof(AnUnresponsiveServerDoesNotStallTheLoggingCall)); + + Stopwatch stopwatch = Stopwatch.StartNew(); + log.Error("Message"); + stopwatch.Stop(); + + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(generousBoundMillis)); + Assert.That(errorHandler.Messages, Is.Not.Empty); + } + finally + { + finished.Set(); + listener.Stop(); + stub.Wait(generousBoundMillis); + } + } + + /// Collects reported errors instead of letting them reach the console. + private sealed class RecordingErrorHandler : IErrorHandler + { + /// Reported messages. + internal List Messages { get; } = []; + + /// + public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message); + + /// + public void Error(string message, Exception e) => Messages.Add(message); + + /// + public void Error(string message) => Messages.Add(message); + } +} diff --git a/src/log4net.Tests/Util/BackgroundSenderTest.cs b/src/log4net.Tests/Util/BackgroundSenderTest.cs new file mode 100644 index 00000000..a4280f32 --- /dev/null +++ b/src/log4net.Tests/Util/BackgroundSenderTest.cs @@ -0,0 +1,308 @@ +#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.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Threading; + +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Util; + +/// +/// Tests for . +/// +[TestFixture] +public class BackgroundSenderTest +{ + /// How long a test waits for the background thread before calling it a failure. + private const int WaitMillis = 30_000; + + private readonly List _sent = []; + private readonly List _reported = []; + + /// + /// NUnit reuses one fixture instance for every test in it, so the recordings have to be + /// cleared between them. + /// + [SetUp] + public void ClearRecordings() + { + lock (_sent) + { + _sent.Clear(); + } + + lock (_reported) + { + _reported.Clear(); + } + } + + private int[] Sent + { + get + { + lock (_sent) + { + return [.. _sent]; + } + } + } + + private void Record(int item) + { + lock (_sent) + { + _sent.Add(item); + } + } + + private void Report(string message, Exception? exception) + { + lock (_reported) + { + _reported.Add(message); + } + } + + private BackgroundSender CreateSender(int capacity, Action send) + => new("test", capacity, send, Report); + + /// + /// A queue without room for at least one item cannot work. + /// + [TestCase(0)] + [TestCase(-1)] + public void ConstructorRejectsCapacityBelowOne(int capacity) + => Assert.That(() => CreateSender(capacity, (_, _) => { }), + Throws.TypeOf()); + + /// + /// One thread delivers, so order is the order the items were queued in. + /// + [Test] + public void ItemsAreSentInTheOrderTheyWereQueued() + { + const int itemCount = 100; + using BackgroundSender sender = CreateSender(itemCount, (item, _) => Record(item)); + + for (int i = 0; i < itemCount; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(Sent, Is.EqualTo(Enumerable.Range(0, itemCount).ToArray())); + Assert.That(sender.DroppedItemCount, Is.EqualTo(0)); + } + + /// + /// A full queue must not hold the logging call up when the caller allows no wait. + /// + [Test] + [System.Diagnostics.CodeAnalysis.SuppressMessage("Reliability", "CA2016:Forward the CancellationToken parameter to methods that take one", + Justification = "Stands for a sink that does not cooperate with cancellation.")] + public void AFullQueueDropsInsteadOfBlockingTheCaller() + { + using ManualResetEventSlim sendEntered = new(false); + using ManualResetEventSlim release = new(false); + using BackgroundSender sender = CreateSender(2, (item, _) => + { + sendEntered.Set(); + release.Wait(WaitMillis); + Record(item); + }); + + // Park the only sending thread, so that nothing leaves the queue from here on. + Assert.That(sender.TryEnqueue(1, WaitMillis), Is.True); + Assert.That(sendEntered.Wait(WaitMillis), Is.True); + + // Fill the two slots, then prove the next one is dropped rather than waited for. + Assert.That(sender.TryEnqueue(2, WaitMillis), Is.True); + Assert.That(sender.TryEnqueue(3, WaitMillis), Is.True); + + Stopwatch stopwatch = Stopwatch.StartNew(); + Assert.That(sender.TryEnqueue(4, 0), Is.False); + stopwatch.Stop(); + + Assert.That(sender.DroppedItemCount, Is.EqualTo(1)); + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(WaitMillis)); + + release.Set(); + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(Sent, Is.EqualTo(new[] { 1, 2, 3 })); + } + + /// + /// Closing sends what is still queued, rather than discarding it like the popped batch did. + /// + [Test] + public void CloseSendsWhatIsStillQueued() + { + const int itemCount = 10; + BackgroundSender sender = CreateSender(itemCount, (item, _) => Record(item)); + try + { + for (int i = 0; i < itemCount; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + sender.Close(WaitMillis); + Assert.That(Sent, Has.Length.EqualTo(itemCount)); + Assert.That(sender.DroppedItemCount, Is.EqualTo(0)); + } + finally + { + sender.Dispose(); + } + } + + /// + /// An unresponsive sink must not make closing the appender hang. What is left is dropped, + /// counted and reported. + /// + [Test] + public void CloseGivesUpOnAnUnresponsiveSink() + { + const int closeTimeoutMillis = 200; + using ManualResetEventSlim sendEntered = new(false); + BackgroundSender sender = CreateSender(5, (item, token) => + { + sendEntered.Set(); + // Answers only when Close runs out of patience and cancels. + token.WaitHandle.WaitOne(WaitMillis); + Record(item); + }); + try + { + Assert.That(sender.TryEnqueue(1, WaitMillis), Is.True); + Assert.That(sendEntered.Wait(WaitMillis), Is.True); + Assert.That(sender.TryEnqueue(2, WaitMillis), Is.True); + Assert.That(sender.TryEnqueue(3, WaitMillis), Is.True); + + Stopwatch stopwatch = Stopwatch.StartNew(); + sender.Close(closeTimeoutMillis); + stopwatch.Stop(); + + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(WaitMillis)); + Assert.That(sender.DroppedItemCount, Is.EqualTo(2)); + Assert.That(_reported, Is.Not.Empty); + } + finally + { + sender.Dispose(); + } + } + + /// + /// Once the sender has stopped, queueing fails instead of filling a queue nobody empties. + /// + [Test] + public void NothingIsAcceptedAfterClose() + { + BackgroundSender sender = CreateSender(5, (item, _) => Record(item)); + try + { + sender.Close(WaitMillis); + + Assert.That(sender.IsFaulted, Is.True); + Assert.That(sender.TryEnqueue(1, WaitMillis), Is.False); + Assert.That(sender.Flush(WaitMillis), Is.False); + Assert.That(Sent, Is.Empty); + } + finally + { + sender.Dispose(); + } + } + + /// + /// A send that throws costs its own item and nothing else. + /// + [Test] + public void AFailedSendDoesNotStopTheOnesAfterIt() + { + using BackgroundSender sender = CreateSender(10, (item, _) => + { + if (item == 1) + { + throw new InvalidOperationException("simulated send failure"); + } + + Record(item); + }); + + for (int i = 0; i < 4; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(Sent, Is.EqualTo(new[] { 0, 2, 3 })); + Assert.That(sender.DroppedItemCount, Is.EqualTo(1)); + + // A failed send is not queue pressure and must not be reported as such. + Assert.That(_reported, Has.Some.Contains("Failed to send")); + Assert.That(_reported, Has.None.Contains("queue is full")); + } + + /// + /// An error handler that throws must not take the sending thread, and with it the process, down. + /// + [Test] + [NonParallelizable] + public void AnErrorHandlerThatThrowsDoesNotStopTheSender() + { + List internalMessages = []; + + // The sender is disposed inside the wrapped action, because closing it reports the drop + // total through the same throwing handler. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter adapter = new(internalMessages); + using BackgroundSender sender = new("test", 10, (item, _) => + { + if (item == 1) + { + throw new InvalidOperationException("simulated send failure"); + } + + Record(item); + }, + (_, _) => throw new InvalidOperationException("simulated error handler failure")); + + for (int i = 0; i < 4; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(sender.IsFaulted, Is.False); + }); + + Assert.That(Sent, Is.EqualTo(new[] { 0, 2, 3 })); + Assert.That(internalMessages, Is.Not.Empty); + } +} diff --git a/src/log4net.Tests/log4net.Tests.csproj b/src/log4net.Tests/log4net.Tests.csproj index 38b00638..50ee6553 100644 --- a/src/log4net.Tests/log4net.Tests.csproj +++ b/src/log4net.Tests/log4net.Tests.csproj @@ -22,6 +22,9 @@ + + + diff --git a/src/log4net/Appender/AdoNetAppender.cs b/src/log4net/Appender/AdoNetAppender.cs index c3fd833a..08b69726 100644 --- a/src/log4net/Appender/AdoNetAppender.cs +++ b/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) /// 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; + } } } + /// + /// Set by the contained per-event failure path in , + /// which reports rather than throws, so can count failures. + /// + private bool _eventFailed; + + private const int MaxFailuresInARow = 5; + /// /// Prepare entire database command object to be executed. /// diff --git a/src/log4net/Appender/BufferingAppenderSkeleton.cs b/src/log4net/Appender/BufferingAppenderSkeleton.cs index 31fff5b9..eb1154a0 100644 --- a/src/log4net/Appender/BufferingAppenderSkeleton.cs +++ b/src/log4net/Appender/BufferingAppenderSkeleton.cs @@ -201,12 +201,20 @@ protected BufferingAppenderSkeleton(bool eventMustBeFixed) /// /// Flushes any buffered log data. /// - /// The maximum time to wait for logging events to be flushed. - /// if all logging events were flushed successfully, else . + /// + /// Unused: the buffer is sent on the calling thread, so there is nothing to wait for. + /// + /// + /// when events are still buffered afterwards, which is what a + /// appender does: it keeps them until a triggering event arrives. + /// public override bool Flush(int millisecondsTimeout) { Flush(); - return true; + lock (LockObj) + { + return _cyclicBuffer is null || _cyclicBuffer.Length == 0; + } } /// diff --git a/src/log4net/Appender/RemoteSyslogAppender.cs b/src/log4net/Appender/RemoteSyslogAppender.cs index 3d30c526..e2d6cd30 100644 --- a/src/log4net/Appender/RemoteSyslogAppender.cs +++ b/src/log4net/Appender/RemoteSyslogAppender.cs @@ -18,10 +18,8 @@ #endregion using System; -using System.Collections.Concurrent; using System.Text; using System.Threading; -using System.Threading.Tasks; using log4net.Appender.Internal; using log4net.Core; using log4net.Layout; @@ -279,9 +277,11 @@ public enum SyslogNewLineHandling Keep } - private readonly BlockingCollection _sendQueue = new(); - private CancellationTokenSource? _cancellationTokenSource; - private Task? _pumpTask; + private const int CloseTimeoutMillis = 5_000; + private IUdpConnection? _connection; + private BackgroundSender? _sender; + private int _sendQueueSize = 500; + private int _enqueueTimeoutMillis = 5_000; /// /// Initializes a new instance of the class. @@ -389,7 +389,8 @@ protected override void Append(LoggingEvent loggingEvent) // Grab as a byte array byte[] buffer = Encoding.GetBytes(builder.ToString()); - _sendQueue.Add(buffer); + // A full queue is reported by the sender itself. + _sender?.TryEnqueue(buffer, EnqueueTimeoutMillis); } } catch (Exception e) when (!e.IsFatal()) @@ -524,10 +525,89 @@ public override void ActivateOptions() $"The NewLineHandling is not {SyslogNewLineHandling.Escape} or {SyslogNewLineHandling.Keep} or {SyslogNewLineHandling.Split}."); } _levelMapping.ActivateOptions(); - // Start the background pump - _cancellationTokenSource = new(); - _pumpTask = Task.Factory.StartNew(() => ProcessQueueAsync(_cancellationTokenSource.Token), CancellationToken.None, - TaskCreationOptions.LongRunning, TaskScheduler.Default); + StopSending(); + + IUdpConnection connection = CreateUdpConnection(); + try + { + connection.Connect(LocalPort, RemoteAddress.EnsureNotNull(), RemotePort); + } + catch (Exception e) when (!e.IsFatal()) + { + ErrorHandler.Error( + $"Unable to connect to remote syslog {RemoteAddress} on port {RemotePort} from local port {LocalPort}. " + + "No logging event will be sent.", + e, ErrorCode.GenericFailure); + connection.Dispose(); + return; + } + + _connection = connection; + _sender = new(nameof(RemoteSyslogAppender), SendQueueSize, Send, Report); + } + + /// + /// How many datagrams may wait to be sent. Defaults to 500. + /// + /// The value specified is not positive. + public int SendQueueSize + { + get => _sendQueueSize; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendQueueSize is not positive."); + } + _sendQueueSize = value; + } + } + + /// + /// How long a logging call waits for room in a full queue. Defaults to 5000, 0 never waits. + /// + /// The value specified is negative. + public int EnqueueTimeoutMillis + { + get => _enqueueTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for EnqueueTimeoutMillis is negative."); + } + _enqueueTimeoutMillis = value; + } + } + + private void Send(byte[] datagram, CancellationToken cancellationToken) + => _connection?.SendAsync(datagram, datagram.Length).GetAwaiter().GetResult(); + + private void Report(string message, Exception? exception) + { + if (exception is null) + { + ErrorHandler.Error(message); + } + else + { + ErrorHandler.Error(message, exception); + } + } + + private void StopSending() + { + if (_sender is BackgroundSender sender) + { + _sender = null; + sender.Close(CloseTimeoutMillis); + sender.Dispose(); + } + + _connection?.Dispose(); + _connection = null; } /// @@ -636,51 +716,26 @@ public class LevelSeverity : LevelMappingEntry public SyslogSeverity Severity { get; set; } } + /// + /// Waits until everything queued so far has been sent. + /// + /// The maximum time to wait. + /// on timeout, or when the sender is no longer running. + public override bool Flush(int millisecondsTimeout) => _sender?.Flush(millisecondsTimeout) ?? true; + /// protected override void OnClose() { - // Signal shutdown and wait for the pump to drain - _cancellationTokenSource?.Cancel(); - _pumpTask?.Wait(TimeSpan.FromSeconds(5)); + StopSending(); base.OnClose(); } - private async Task ProcessQueueAsync(CancellationToken token) + /// + /// + /// Deliberately empty: this appender sends through the connection its pump owns, so the + /// inherited client would be a second socket that nothing ever uses. + /// + protected override void InitializeClientConnection() { - // We create our own UdpClient here, so that client lifetime is tied to this task - using IUdpConnection udpClient = CreateUdpConnection(); - udpClient.Connect(LocalPort, RemoteAddress.EnsureNotNull(), RemotePort); - - try - { - while (!token.IsCancellationRequested) - { - // Take next message or throw when canceled - byte[] datagram = _sendQueue.Take(token); - try - { - await udpClient.SendAsync(datagram, datagram.Length).ConfigureAwait(false); - } - catch (Exception ex) when (!ex.IsFatal()) - { - ErrorHandler.Error("RemoteSyslogAppender: send failed", ex, ErrorCode.WriteFailure); - } - } - } - catch (OperationCanceledException) - { - // Clean shutdown: drain remaining items if desired - while (_sendQueue.TryTake(out byte[]? leftover)) - { - try - { - await udpClient.SendAsync(leftover, leftover.Length).ConfigureAwait(false); - } - catch (Exception ex) when (!ex.IsFatal()) - { - ErrorHandler.Error("RemoteSyslogAppender: send failed during shutdown", ex, ErrorCode.FlushFailure); - } - } - } } } \ No newline at end of file diff --git a/src/log4net/Appender/SmtpAppender.cs b/src/log4net/Appender/SmtpAppender.cs index 65dc221a..face8aec 100644 --- a/src/log4net/Appender/SmtpAppender.cs +++ b/src/log4net/Appender/SmtpAppender.cs @@ -295,6 +295,28 @@ protected override void SendBuffer(LoggingEvent[] events) /// protected override bool RequiresLayout => true; + /// + /// How long one send may take before it is abandoned. Defaults to 15000. + /// + /// + /// The mail goes out under the appender lock, and + /// waits 100 seconds by default. There is no "wait forever" value: 0 means "do not wait". + /// + /// The value specified is not positive. + public int SendTimeoutMillis + { + get => _sendTimeoutMillis; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendTimeoutMillis is not positive."); + } + _sendTimeoutMillis = value; + } + } + /// /// Send the email message /// @@ -312,6 +334,7 @@ protected virtual void SendEmail(string messageBody) smtpClient.Port = Port; smtpClient.DeliveryMethod = SmtpDeliveryMethod.Network; smtpClient.EnableSsl = EnableSsl; + smtpClient.Timeout = SendTimeoutMillis; if (Authentication == SmtpAuthentication.Basic) { @@ -349,6 +372,7 @@ protected virtual void SendEmail(string messageBody) smtpClient.Send(mailMessage); } + private int _sendTimeoutMillis = 15_000; private string? _to; private string? _cc; private string? _bcc; diff --git a/src/log4net/Util/BackgroundSender.cs b/src/log4net/Util/BackgroundSender.cs new file mode 100644 index 00000000..81e37446 --- /dev/null +++ b/src/log4net/Util/BackgroundSender.cs @@ -0,0 +1,354 @@ +#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.Collections.Concurrent; +using System.ComponentModel; +using System.Threading; +using System.Threading.Tasks; + +namespace log4net.Util; + +/// +/// Hands work to a single background thread so that an appender does not perform +/// slow I/O while it holds the appender lock. +/// +/// The type of the queued work items. +/// +/// +/// An appender that sends over the network blocks the thread that made the logging call, +/// and every other thread logging to the same appender behind it, for as long as the sink +/// takes to answer. Queueing the work instead bounds that wait to the enqueue timeout. +/// +/// +/// The queue has a fixed capacity. Work is delivered in the order it was queued, by one +/// thread, so a send implementation does not need to be thread safe. Items that could not +/// be queued or sent are counted in . +/// +/// +/// Public only because log4net.Ext.Mail is deliberately not strong named and so cannot be +/// a friend assembly. It is infrastructure, not part of the surface an application configures. +/// +/// +[EditorBrowsable(EditorBrowsableState.Never)] +public sealed class BackgroundSender : IDisposable +{ + private readonly BlockingCollection _queue; + private readonly Action _send; + private readonly Action _reportError; + private readonly string _name; + private readonly Thread _pump; + private readonly CancellationTokenSource _shutdown = new(); + private int _droppedItemCount; + private int _dropReported; + private int _faultReported; + private volatile bool _isFaulted; + + /// + /// Creates a queue and starts its background thread. + /// + /// Name of the owning appender, used in error messages. + /// The maximum number of items the queue holds. Must be positive. + /// + /// Delivers one item. Called on the background thread only. May throw: the exception is + /// reported and the item dropped. The token is cancelled once has run + /// out of time, so an implementation that can abort its I/O should pass it on. + /// + /// Reports a message and its optional exception, typically to an error handler. + public BackgroundSender(string name, int capacity, Action send, + Action reportError) + { + _name = name.EnsureNotNull(); + _send = send.EnsureNotNull(); + _reportError = reportError.EnsureNotNull(); + if (capacity <= 0) + { + throw new ArgumentOutOfRangeException(nameof(capacity), capacity, "The capacity must be positive."); + } + + _queue = new(capacity); + _pump = new(Pump) + { + IsBackground = true, + Name = $"log4net {name} sender" + }; + _pump.Start(); + } + + /// + /// The number of items that were not delivered, because the queue was full, closed or faulted, + /// or because sending them threw. + /// + public int DroppedItemCount => Volatile.Read(ref _droppedItemCount); + + /// + /// Whether the background thread has stopped for good. Nothing more will be delivered. + /// + public bool IsFaulted => _isFaulted; + + /// + /// Queues one item for delivery. + /// + /// The item to deliver. + /// + /// How long to wait for room in a full queue. Zero returns immediately, which loses the item + /// rather than delaying the logging call. + /// + /// if the item was queued, if it was dropped. + public bool TryEnqueue(T item, int millisecondsTimeout) + { + if (!_isFaulted) + { + try + { + if (_queue.TryAdd(new Item(item), millisecondsTimeout)) + { + return true; + } + } + catch (Exception e) when (!e.IsFatal()) + { + // Closed, or CompleteAdding ran, while this call was in flight. + } + } + + ReportQueueFull(); + return false; + } + + /// + /// Waits until everything queued before this call has been sent. + /// + /// The maximum time to wait. + /// + /// if the queue drained in time, on timeout + /// or if the background thread is no longer running. + /// + /// + /// + /// A marker is placed at the end of the queue and awaited, so a caller is not held up by + /// items queued after it asked. + /// + /// + public bool Flush(int millisecondsTimeout) + { + if (_isFaulted) + { + return false; + } + + TaskCompletionSource marker = new(TaskCreationOptions.RunContinuationsAsynchronously); + int startTicks = Environment.TickCount; + try + { + if (!_queue.TryAdd(new Item(marker), millisecondsTimeout)) + { + return false; + } + } + catch (Exception e) when (!e.IsFatal()) + { + // Closed while this call was in flight. + return false; + } + + return marker.Task.Wait(Remaining(startTicks, millisecondsTimeout)); + } + + /// + /// Stops the queue, sending what is still in it until the time runs out. + /// + /// The maximum time to spend draining. + /// + /// + /// Never throws. Once the time is up the send in flight is cancelled and the remaining items + /// are counted as dropped, so closing an appender cannot hang on an unresponsive sink. + /// + /// + public void Close(int millisecondsTimeout) + { + try + { + _queue.CompleteAdding(); + if (!_pump.Join(Math.Max(millisecondsTimeout, 0))) + { + // Out of time: stop the send in flight and let the pump drop the rest. + _shutdown.Cancel(); + _pump.Join(CancelGraceMillis); + } + } + catch (Exception e) when (!e.IsFatal()) + { + Report($"[{_name}] Failed to shut the background sender down.", e); + } + + int dropped = DroppedItemCount; + if (dropped > 0) + { + Report($"[{_name}] {dropped} logging event(s) were not sent.", null); + } + } + + /// + public void Dispose() + { + Close(0); + + // Disposing these while the pump still runs would throw on the pump thread, which is + // an unhandled exception. If it did not stop in time, leave them to the finalizers. + if (!_pump.IsAlive) + { + _shutdown.Dispose(); + _queue.Dispose(); + } + } + + /// + /// Reports without ever throwing. An supplied by a caller may + /// throw, and on the pump thread that would be an unhandled exception. + /// + private void Report(string message, Exception? exception) + { + try + { + _reportError(message, exception); + } + catch (Exception e) when (!e.IsFatal()) + { + LogLog.Error(_declaringType, $"[{_name}] The error handler threw.", e); + } + } + + private void Pump() + { + try + { + foreach (Item item in _queue.GetConsumingEnumerable()) + { + if (item.Marker is TaskCompletionSource marker) + { + marker.TrySetResult(true); + continue; + } + + if (_shutdown.IsCancellationRequested) + { + // Closing and out of time. Drain without sending, so that Close returns. + CountLost(); + continue; + } + + try + { + _send(item.Payload!, _shutdown.Token); + } + catch (Exception e) when (!e.IsFatal()) + { + CountLost(); + Report($"[{_name}] Failed to send a logging event.", e); + } + } + } + catch (Exception e) when (!e.IsFatal()) + { + // Nothing will be sent from here on, so say so once and let TryEnqueue fail fast + // instead of filling a queue that nobody empties. + _isFaulted = true; + if (Interlocked.Exchange(ref _faultReported, 1) == 0) + { + Report($"[{_name}] The background sender stopped. No further events will be sent.", e); + } + } + finally + { + _isFaulted = true; + ReleaseWaiters(); + } + } + + /// + /// Releases anyone waiting in once the pump is gone, rather than + /// letting them wait out their timeout for a marker that will never be reached. + /// + private void ReleaseWaiters() + { + try + { + while (_queue.TryTake(out Item item)) + { + if (item.Marker is TaskCompletionSource marker) + { + marker.TrySetResult(true); + } + else + { + CountLost(); + } + } + } + catch (Exception e) when (!e.IsFatal()) + { + // The queue may already be disposed. Nothing left to release. + LogLog.Debug(_declaringType, $"[{_name}] Could not drain the queue on shutdown.", e); + } + } + + private void CountLost() => Interlocked.Increment(ref _droppedItemCount); + + /// + /// A full or closed queue, unlike a failed send, which reports for itself. + /// + private void ReportQueueFull() + { + CountLost(); + if (Interlocked.Exchange(ref _dropReported, 1) == 0) + { + Report($"[{_name}] A logging event was dropped: the queue is full or closed. " + + "Further losses are counted and reported when the sender closes.", null); + } + } + + private static int Remaining(int startTicks, int millisecondsTimeout) + { + if (millisecondsTimeout == Timeout.Infinite) + { + return Timeout.Infinite; + } + + int elapsed = unchecked(Environment.TickCount - startTicks); + return Math.Max(millisecondsTimeout - elapsed, 0); + } + + private const int CancelGraceMillis = 1_000; + + private static readonly Type _declaringType = typeof(BackgroundSender); + + /// + /// Either a payload or a flush marker: markers travel in the queue so that they observe + /// the order the items were queued in. + /// + private readonly record struct Item(T? Payload, TaskCompletionSource? Marker) + { + internal Item(T payload) : this(payload, null) + { } + + internal Item(TaskCompletionSource marker) : this(default, marker) + { } + } +} 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 ee03fa78..54e712f9 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 @@ -42,6 +42,13 @@ You can also specify: * Facility (default: user) * Identity (default: application name) +* 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 + +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 +for the queue to drain. [source,xml] ---- diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc index 0c33679b..e28f30cd 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc @@ -189,6 +189,10 @@ This example authenticates against a mail server that requires an encrypted conn |`port` |The port the SMTP server listens on. Defaults to `25`. +|`sendTimeoutMillis` +|How long one send may take before it is abandoned, in milliseconds. Defaults to `15000`. +The mail goes out under the appender lock, so an unresponsive server would otherwise stall logging. + |`enableSsl` |Whether to require transport security. Defaults to `false`. Shorthand for `transportSecurity`: `true` selects `Required`, `false` selects `None`. @@ -215,6 +219,13 @@ See xref:#mailkit-smtpappender-transport-security[]. |`bodyEncoding` |The encoding of the message body, for example `utf-8`. Defaults to `utf-8`. +|`sendQueueSize` +|How many rendered mails may wait to be sent. Defaults to `500`. + +|`enqueueTimeoutMillis` +|How long a logging call waits for room in a full queue, in milliseconds. Defaults to `5000`. +`0` never waits and discards the mail instead. + |`bufferSize` |How many log events to buffer into one email. See xref:manual/configuration/appenders.adoc[]. @@ -280,6 +291,12 @@ The options above are named exactly as in the legacy appender, but a few behave MailKit cannot reuse the Windows logon session of the current thread or process, which the legacy appender did. * Semicolon-delimited recipient lists in `to`, `cc` and `bcc` are parsed correctly. * `transportSecurity` has no counterpart in the legacy appender, which offers only `enableSsl`. +* `sendTimeoutMillis` is a deadline for the whole send here, while in the legacy appender it bounds +the one `SmtpClient.Send` call. Both default to `15000`. +* The mail is handed to a background thread rather than sent by the thread that logged, so a slow +server no longer stalls logging. Failures are reported to the error handler as before, but after +the logging call has returned, and mail still queued is lost if the process is killed. +`sendQueueSize` and `enqueueTimeoutMillis` bound the queue. `enableSsl` keeps its meaning, so a migrated configuration secures the connection exactly as before. If the legacy appender reached your server with `enableSsl` set to `true`, so does this one. diff --git a/src/site/antora/modules/ROOT/partials/supported-versions.adoc b/src/site/antora/modules/ROOT/partials/supported-versions.adoc index fe4a816a..00233dce 100644 --- a/src/site/antora/modules/ROOT/partials/supported-versions.adoc +++ b/src/site/antora/modules/ROOT/partials/supported-versions.adoc @@ -25,7 +25,7 @@ | 3.x | **[active]#Active#** -| 3.4.1 +| 3.5.0 | 2024-09-12 | |