You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4net-dev@logging.apache.org by Hendrik Dev <he...@gmail.com> on 2012/11/04 15:25:53 UTC
AsynchronousBufferingForwardingAppender with flooding
prevention/message throttling
Hi everybody,
i just wrote a first sketch for an Asynchronous Buffering Forwarding
Appender with flooding prevention.
I need three things in my project:
1) async logging (so that the ILog.Debug/Info/Error() call will not
block) if, for example the underlying ADO Appender does currently slow
inserts into database because of database locks
2) Flooding detection/prevention: If a log4net enabled application
gets wild and issue, for example, 10000 logging events per minute i
want to suppress further messages, issue a message that now messages
will be discarded, and if the flooding is over the appender should
automatically resume with normal logging behavior (sometimes this is
also called message throttling)
3) All the capabilities of the BufferingForwardingAppender
The appender is always async, flooding prevention can be configured
with two parameters
<maxEventsPeriod value="100"/> <!-- set to 0 to disable flood protection -->
<periodInSeconds value="5"/>
Note regarding async behavior: If one of the attached appenders will
block for a while this cause that logmessage delivery to the other
appenders will also be delayed - but although its async from the
perspective of the log4net enabled application which is using this
appender.
So here is the code i want to share with you, asking for
comments/feedback/review.
You also can use the code (without any warranty etc) for your own projects:
(build upon .NET 4 and log4net 1.2.11)
using System;
using System.Diagnostics;
using System.Threading.Tasks;
using log4net.Appender;
using log4net.Core;
using log4net.Util;
namespace Dev.Log4net
{
public class AsynchronousBufferingForwardingAppender :
BufferingForwardingAppender
{
private readonly Object _lock = new Object();
private Stopwatch _watch = new Stopwatch();
private int _countLastPeriod = 0;
private int _currentCount = 0;
private bool _isFlodding = false;
private bool _floodMessageSend = false;
private int c_MaxEventsPeriod = 0;
private int c_PeriodInSeconds = 5;
public AsynchronousBufferingForwardingAppender()
{
}
public int MaxEventsPeriod
{
get { return this.c_MaxEventsPeriod; }
set { this.c_MaxEventsPeriod = value; }
}
public int PeriodInSeconds
{
get { return this.c_PeriodInSeconds; }
set { this.c_PeriodInSeconds = value; }
}
public override void ActivateOptions()
{
if (c_MaxEventsPeriod > 0)
{
_countLastPeriod = 0;
_currentCount = 0;
_isFlodding = false;
_watch.Restart();
}
base.ActivateOptions();
}
override protected void SendBuffer(LoggingEvent[] events)
{
if (events == null || events.Length == 0)
return;
if (c_MaxEventsPeriod > 0)
{ //flodding detection enabled
double elapsed = _watch.Elapsed.TotalSeconds;
if (elapsed > 0)
{
if (elapsed >= c_PeriodInSeconds)
{ //period end, check flodding
if (_currentCount > c_MaxEventsPeriod)
{
//flodding
_isFlodding = true;
}
else
{
if (_isFlodding)
{
LogLog.Warn(GetType(), "Flooding stop
detected, resume to normal logging operation");
}
_isFlodding = false;
_floodMessageSend = false;
}
_countLastPeriod = _currentCount;
_currentCount = 0;
_watch.Restart();
}
else
{//period not ended, just count
_currentCount += events.Length;
}
if (_isFlodding)
{
//emmit warning message
if (!_floodMessageSend)
{
string floddingMessage = "Log Flodding
detected! Messages gets discarded! Received " + _countLastPeriod + "
messages within " + c_PeriodInSeconds + " secs.";
LogLog.Error(GetType(), floddingMessage);
LoggingEvent floddingErrorLoggingEvent =
new LoggingEvent(GetType(), events[0].Repository,
"Dev.Log4net.AsynchronousBufferingForwardingAppender.FloodingDetection",
Level.Fatal, floddingMessage, null);//null = Message, Exception
base.SendBuffer(new LoggingEvent[] {
floddingErrorLoggingEvent });
_floodMessageSend = true;
}
return;
}//endif isflodding
}
}
Task logTask = Task.Factory.StartNew(() =>
{
_SendBuffer(events);
});
}
protected void _SendBuffer(LoggingEvent[] events)
{
lock (_lock)
{
base.SendBuffer(events);
}
}
}
}
<appender name="AsynchronousBufferingForwardingAppender"
type="Dev.Log4net.AsynchronousBufferingForwardingAppender,
Dev.AsynchronousBufferingForwardingAppender">
<bufferSize value="1" />
<lossy value="false" />
<maxEventsPeriod value="100"/>
<periodInSeconds value="5"/>
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="ALL" />
</evaluator>
<appender-ref ref="UdpAppender" />
<appender-ref ref="TraceAppender" />
</appender>
PS: Sorry for cross posting, but i think its relevant for either
developers and users
-H. Dev
Re: AsynchronousBufferingForwardingAppender with flooding
prevention/message throttling
Posted by George Chung <ge...@glympse.com>.
That's a pretty cool idea. I hacked Ado Appender to be async for my needs,
but this is a nice way to generalize async across the existing appenders.
Subscribed.
On Sun, Nov 4, 2012 at 6:25 AM, Hendrik Dev <he...@gmail.com> wrote:
> Hi everybody,
>
> i just wrote a first sketch for an Asynchronous Buffering Forwarding
> Appender with flooding prevention.
> I need three things in my project:
> 1) async logging (so that the ILog.Debug/Info/Error() call will not
> block) if, for example the underlying ADO Appender does currently slow
> inserts into database because of database locks
> 2) Flooding detection/prevention: If a log4net enabled application
> gets wild and issue, for example, 10000 logging events per minute i
> want to suppress further messages, issue a message that now messages
> will be discarded, and if the flooding is over the appender should
> automatically resume with normal logging behavior (sometimes this is
> also called message throttling)
> 3) All the capabilities of the BufferingForwardingAppender
>
> The appender is always async, flooding prevention can be configured
> with two parameters
> <maxEventsPeriod value="100"/> <!-- set to 0 to disable flood protection
> -->
> <periodInSeconds value="5"/>
>
> Note regarding async behavior: If one of the attached appenders will
> block for a while this cause that logmessage delivery to the other
> appenders will also be delayed - but although its async from the
> perspective of the log4net enabled application which is using this
> appender.
>
>
> So here is the code i want to share with you, asking for
> comments/feedback/review.
> You also can use the code (without any warranty etc) for your own projects:
> (build upon .NET 4 and log4net 1.2.11)
>
> using System;
> using System.Diagnostics;
> using System.Threading.Tasks;
> using log4net.Appender;
> using log4net.Core;
> using log4net.Util;
>
> namespace Dev.Log4net
> {
>
> public class AsynchronousBufferingForwardingAppender :
> BufferingForwardingAppender
> {
>
> private readonly Object _lock = new Object();
> private Stopwatch _watch = new Stopwatch();
> private int _countLastPeriod = 0;
> private int _currentCount = 0;
> private bool _isFlodding = false;
> private bool _floodMessageSend = false;
>
> private int c_MaxEventsPeriod = 0;
> private int c_PeriodInSeconds = 5;
>
> public AsynchronousBufferingForwardingAppender()
> {
>
> }
>
>
> public int MaxEventsPeriod
> {
>
> get { return this.c_MaxEventsPeriod; }
>
> set { this.c_MaxEventsPeriod = value; }
>
> }
>
> public int PeriodInSeconds
> {
>
> get { return this.c_PeriodInSeconds; }
>
> set { this.c_PeriodInSeconds = value; }
>
> }
>
> public override void ActivateOptions()
> {
>
> if (c_MaxEventsPeriod > 0)
> {
>
> _countLastPeriod = 0;
> _currentCount = 0;
> _isFlodding = false;
> _watch.Restart();
>
>
> }
>
> base.ActivateOptions();
>
>
> }
>
>
> override protected void SendBuffer(LoggingEvent[] events)
> {
>
>
> if (events == null || events.Length == 0)
> return;
>
>
> if (c_MaxEventsPeriod > 0)
> { //flodding detection enabled
>
>
> double elapsed = _watch.Elapsed.TotalSeconds;
>
> if (elapsed > 0)
> {
>
> if (elapsed >= c_PeriodInSeconds)
> { //period end, check flodding
>
>
>
> if (_currentCount > c_MaxEventsPeriod)
> {
> //flodding
> _isFlodding = true;
>
>
> }
> else
> {
>
>
> if (_isFlodding)
> {
> LogLog.Warn(GetType(), "Flooding stop
> detected, resume to normal logging operation");
> }
>
> _isFlodding = false;
> _floodMessageSend = false;
> }
>
>
> _countLastPeriod = _currentCount;
> _currentCount = 0;
> _watch.Restart();
>
> }
> else
> {//period not ended, just count
> _currentCount += events.Length;
> }
>
>
> if (_isFlodding)
> {
>
> //emmit warning message
> if (!_floodMessageSend)
> {
> string floddingMessage = "Log Flodding
> detected! Messages gets discarded! Received " + _countLastPeriod + "
> messages within " + c_PeriodInSeconds + " secs.";
> LogLog.Error(GetType(), floddingMessage);
>
> LoggingEvent floddingErrorLoggingEvent =
> new LoggingEvent(GetType(), events[0].Repository,
> "Dev.Log4net.AsynchronousBufferingForwardingAppender.FloodingDetection",
> Level.Fatal, floddingMessage, null);//null = Message, Exception
>
> base.SendBuffer(new LoggingEvent[] {
> floddingErrorLoggingEvent });
>
> _floodMessageSend = true;
>
> }
> return;
>
> }//endif isflodding
> }
> }
>
> Task logTask = Task.Factory.StartNew(() =>
> {
> _SendBuffer(events);
> });
>
> }
>
> protected void _SendBuffer(LoggingEvent[] events)
> {
> lock (_lock)
> {
> base.SendBuffer(events);
> }
> }
>
>
>
> }
> }
>
>
>
>
> <appender name="AsynchronousBufferingForwardingAppender"
> type="Dev.Log4net.AsynchronousBufferingForwardingAppender,
> Dev.AsynchronousBufferingForwardingAppender">
> <bufferSize value="1" />
> <lossy value="false" />
> <maxEventsPeriod value="100"/>
> <periodInSeconds value="5"/>
> <evaluator type="log4net.Core.LevelEvaluator">
> <threshold value="ALL" />
> </evaluator>
>
> <appender-ref ref="UdpAppender" />
> <appender-ref ref="TraceAppender" />
> </appender>
>
>
> PS: Sorry for cross posting, but i think its relevant for either
> developers and users
>
> -H. Dev
>