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 Joe <Jo...@hotmail.com> on 2016/10/31 07:15:09 UTC
AsyncAppenderSkeleton
I have some ideas for developing a new AsyncAppenderSkeleton, based on recent experience developing a custom async appender that sends logging events to a Web API.
My current thoughts are:
1. A new base class AsyncAppenderSkeleton that can be configured to work in synchronous mode (identical to AppenderSkeleton) or asynchronous mode, where DoAppend queues events on to a FIFO queue, and has a single background thread that dequeues events and calls the existing Append methods.
2. When in asynchronous mode, there will be customizable and configurable retry logic that can call Append if it throws an exception. The retry login will be able to inspect the exception that was thrown and keep a count of the number of retries so far. For example, a derived appender that logs to a Web API might want to retry 5xx HTTP status codes, but treat 4xx status codes as permanent errors. There will no retry logic in synchronous mode as this would impact performance.
3. The default queue implementation would be a lossy in-memory Queue with a configurable maximum length. It might be nice to provide the possibility to plug in alternate queue implementations, such as a persistent queue using MSMQ.
4. A class AsyncForwardingAppender would derive from AsyncAppenderSkeleton and implement IAppenderAttachable.
5. It would be easy to create asynchronous versions of existing custom appenders, by changing the base class from AppenderSkeleton to AsyncAppenderSkeleton and optionally implementing some retry logic. E.g. we could have a new AdoNetAppender that can be configured to operate in synchronous mode when logging to a local database, or in asynchronous mode when logging to a cloud-based database.
In terms of timescales, I think it would be possible to produce something by the end of 2016.
To do it I need to reimplement AppenderSkeleton's DoAppend methods, to enqueue events if in asynchronous mode, or call Append in synchronous mode.
I don't want to duplicate code by reimplementing the rest of AppenderSkeleton, so I would like to do one of the following:
Option 1:
- Refactor all of AppenderSkeleton's implementation except IAppender and IBulkAppender into a new base class AppenderSkeletonBase. This includes filtering, IOptionHandler, layout.
- Derive AppenderSkeleton and later the new AsyncAppenderSkeleton from AppenderSkeletonBase.
Option 2:
- Make AppenderSkeleton's DoAppend methods virtual, and derive AsyncAppenderSkeleton from AppenderSkeleton.
Option 1 seems the cleanest to me; any thoughts?
RE: AsyncAppenderSkeleton
Posted by Joe <Jo...@hotmail.com>.
I think it's much easier to discuss something concrete, so I've put up an incomplete version of the AsyncAppenderSkeleton I envisage on the following branch:
https://github.com/JJoe2/log4net/tree/wip/AsyncAppender
I would appreciate it if you could review this and let me know if you're happy to go in this direction before I invest more time in it.
Some notes on this implementation:
1. I've created a new class AppenderBase into which I've extracted all the code from AppenderSkeleton that I want to reuse in AsyncAppenderSkeleton. AppenderSkeleton derives from this class. The purpose here is twofold (a) to avoid duplication of code between AppenderSkeleton and AsyncAppenderSkeleton and (b) to make it easier to review the AsyncAppenderSkeleton class.
2. The queue implementation is a separate class that implements IAppenderQueue which I haven't implemented yet. I plan to write three classes (a) a base AppenderQueueSkeleton class with common stuff to be shared by all queues (default error / retry handling etc); (b) a class that uses a simple lossy in-memory FIFO queue (System.Collections.Queue); (c) a class that uses MSMQ so the queue can be made persistent.
3. The class operates in synchronous mode by default, and is intended to be functionally identical to AppenderSkeleton.
4. When in asynchronous mode, by default LoggingEvents are queued after being fixed, and the Append method of the derived class is called as logging events are dequeued.
5. Alternatively, a derived class can override FormatLoggingEvent to format the logging event before it is queued. In this case, a new method AppendFormattedEvents of the derived class is called instead of Append as events are dequeued. This can improve performance, because it avoids the need to fix properties of LoggingEvent.
6. The IOptionHandler.ActivateOptions implementation has error handling. If the appender is not configured successfully, it will ignore any logging events it receives.
7. I haven't done any work on the locking yet, but the intention is to hold a lock while Append is called, so that the derived class can rely on the fact that Apppend will never be called concurrently by multiple threads.
Re: AsyncAppenderSkeleton
Posted by Dominik Psenner <dp...@gmail.com>.
On 2016-11-04 10:37, Stefan Bodewig wrote:
> On 2016-11-03, Joe wrote:
>
>> However I don\u2019t understand your point about event formatters \u2013 are
>> there any formatters that aren\u2019t thread safe? It doesn\u2019t seem to be
>> an unreasonable restriction to require writers of formatters / layout
>> implementations to be thread-safe.
> It may not be unreasonable, but it has never been imposed, I'm
> afraid. Some of the layouts and formatters out there may not be
> thread-safe.
True.
>
> If I'm taking away one thing of the discussion between Dominik and
> yourself it is that log4net's internals would look different if done
> today *and* the people that are here today don't really know why certain
> design decisions have been taken.
True, too. :-)
Re: AsyncAppenderSkeleton
Posted by Stefan Bodewig <bo...@apache.org>.
On 2016-11-03, Joe wrote:
> However I don’t understand your point about event formatters – are
> there any formatters that aren’t thread safe? It doesn’t seem to be
> an unreasonable restriction to require writers of formatters / layout
> implementations to be thread-safe.
It may not be unreasonable, but it has never been imposed, I'm
afraid. Some of the layouts and formatters out there may not be
thread-safe.
If I'm taking away one thing of the discussion between Dominik and
yourself it is that log4net's internals would look different if done
today *and* the people that are here today don't really know why certain
design decisions have been taken.
Stefan
Re: AsyncAppenderSkeleton
Posted by Dominik Psenner <dp...@gmail.com>.
On 2016-11-03 22:06, Joe wrote:
>
> OK I understand the point about potential corruption when a derived
> class is writing logging events in a non-atomic way, which is probably
> typical of most appenders.
>
> However I don\u2019t understand your point about event formatters \u2013 are
> there any formatters that aren\u2019t thread safe? It doesn\u2019t seem to be
> an unreasonable restriction to require writers of formatters / layout
> implementations to be thread-safe.
>
> I looked at the implementation of AbsoluteTimeDateFormatter, which
> uses a static buffer internally. It seems to be thread-safe, but if I
> understood the code correctly, it seems to have a superfluous lock on
> s_lastTimeBuf, since it is only ever accessed when the current thread
> is already holding a lock on s_lastTimeStrings. Also it seems to me
> that any performance gains achieved by reusing a static buffer could
> easily be cancelled out by the overhead of holding locks if an
> application does a lot of concurrent logging from multiple threads.
> Perhaps a better implementation would be to use a ThreadStatic buffer,
> which I think would give the same result without locking.
>
You are right about this. Locking must be avoided where ever it is
possible. Unless populating caches altogether with locking is faster
than recalculating things on every run. The former is probably the case
for the formatters. The AbsoluteTimeDateFormatter is a good example for
that. It has to update the formatted date/time string only once in a
while which is way less frequent than the frequency of generated log
events and for all log events in between it can reuse the cached string
representation.
> As for an async appender: I still think the best approach is to write
> a new base class AsyncAppenderSkeleton, that doesn\u2019t inherit from
> either BufferingAppenderSkeleton or AppenderSkeleton. I\u2019ll give it
> some more thought and post again to justify this opinion soon(ish).
>
> *From:*Dominik Psenner [mailto:dpsenner@gmail.com]
> *Sent:* 03 November 2016 00:14
> *To:* Log4NET Dev
> *Subject:* Re: AsyncAppenderSkeleton
>
> As far as I can recall, log4net logs to an appender in the thread that
> the log event was created on unless there is buffering of log events
> in between (BufferingAppenderSkeleton). This in general means that
> multiple threads write content to an appender at the same time and
> that in turn means that there is a chance that log events get mixed up.
>
> Think of two threads A and B that try to write to the same sink at the
> same time. Thread A begins to write the timestamp of his log event and
> gets interrupted. B wakes up and writes another timestamp. Now there
> are two timestamps after each other and the outcome is not two
> distinct log messages but garbage.
>
> And the issues can go even further. What if the event formatter
> populates a (not thread safe) local cache while processing log events?
> The outcome is unpredictable. I can imagine that back then it was
> decided to better be safe than sorry. A pessimistic lock fixes this
> issue for good at the cost of performance.
>
> Writing this down today in 2016, one major question jumps into my
> mind: why is locking not left up to the appender or a event formatter?
> There are appenders out there that append log events to sinks that can
> handle concurrency very well (databases for example). It would
> definitely result in more locks; more locks cost more and thus a
> single (outer) lock is better.
>
> Still, today I would not bother about locking and rather configure a
> buffering appender and let that appender append events into another
> appender that must not care about locking because the buffering
> appender already does. If one knows that locking/buffering is not
> needed because his application does no multithreading at all, he could
> still configure the other appender all alone.
>
> 2016-11-02 20:55 GMT+01:00 Joe <JocularJoe@hotmail.com
> <ma...@hotmail.com>>:
>
> I\u2019m trying to understand what locking is necessary in AppenderSkeleton
> and its derived classes. There is a lock(this) in AppenderSkeleton\u2019s
> DoAppend and Close methods, which ensure that the appender can\u2019t be
> closed while an Append is in progress. Implementing Append in a
> derived class is easier, because the lock ensures it can never be
> called concurrently by more than one thread.
>
> That\u2019s all fairly clear, but I don\u2019t understand the comment in the
> AppenderSkeleton.DoAppend method:
>
> // This lock is absolutely critical for correct formatting
>
> // of the message in a multi-threaded environment. Without
>
> // this, the message may be broken up into elements from
>
> // multiple thread contexts (like get the wrong thread ID).
>
> The lock is clearly necessary for the above reasons, but I don\u2019t see
> what race condition could cause a message to be \u201cbroken up into
> elements from multiple thread contexts\u201d?
>
> Can you throw any light on that?
>
> *From:*Dominik Psenner [mailto:dpsenner@apache.org
> <ma...@apache.org>]
> *Sent:* 31 October 2016 15:31
> *To:* log4net-dev@logging.apache.org
> <ma...@logging.apache.org>
> *Subject:* Re: AsyncAppenderSkeleton
>
> See inlines.
>
> On 2016-10-31 11:30, Joe wrote:
>
> Hi Dominik,
>
> Thanks for the feedback
>
> > Please note also that MSMQ sounds like a MS only service and that would in turn mean that
> the .net core variant would no longer be able to benefit from the
> AsyncAppenderSkeleton. To me this outlines a path that we would
> not like to walk on
>
> I don\u2019t see the problem here.
>
> I\u2019m proposing that we could implement the queue as a separate
> class implementing a suitable interface (ILoggingEventQueue,
> IAppenderQueue or whatever \u2013 I\u2019m with Philip Karlton on naming).
> The default implementation would be an in-memory queue, would not
> depend on MSMQ and would be available for .net core etc.
>
>
> Sorry, my fault, the sentence was TL;DR it's entirety. I had it read
> it as "The default implementation could be MSMQ". ;-) Thanks for the
> clarification.
>
> Then there could be an alternate implementation with a persistent
> queue using MSMQ, or users could provide their own custom
> implementations using some other persistent queueing technology if
> they wish.
>
> The alternative of a persistent queue is useful to reduce the risk of
> (probably the last and therefore most important) logging events being
> lost when an application crashes: with a persistent queue they could
> be picked up again from the queue when the application restarts, or by
> an independent utility.
>
> > This sounds mostly like the BufferingAppenderSkeleton, which only
> misses the background worker thread to send the buffer.
>
> I\u2019m not convinced that BufferingAppenderSkeleton is a good candidate.
> For example:
>
> - Locking is problematic. The appender would need to lock(this) while
> it is forwarding logging events to the sink
> (BufferingAppenderSkeleton.SendBuffer). This could hold the lock for
> an extended period (e.g. due to a communication timeout). Therefore
> DoAppend should not lock(this) while enqueueing logging events or
> we\u2019ll be unnecessarily blocking the calling application. This is one
> of the main reasons I want to implement my own DoEvents rather than
> deriving from AppenderSkeleton.
>
>
> If the implementation requires lock(this) to work, the implementation
> is broken. The queue itself has to be thread safe. Hence, a true async
> appender should block the calling application only to fix a few
> logging event properties that would otherwise be lost (i.e. stacktrace
> or thread information).
>
> - I see the buffering and triggering logic being implemented in a
> pluggable ILoggingEventQueue. By default, there would be no
> buffering, except what is implicit in the fact that events may be
> enqueued faster than they can be dequeued. I.e. whenever the
> background thread detects events in the queue, by default it processes
> all available events immediately, in blocks whose maximum size is a
> configurable SendBufferSize. A custom queue implementation could
> implement triggering logic akin to BufferingAppenderSkeleton, e.g.
> wait for a timeout defined by TimeEvaluator if there are fewer than
> SendBufferSize events in the queue.
>
>
> A async appender working in async mode always buffers, by definition.
> If it wouldn't buffer, there would be nothing that a background thread
> could work on and it would block the calling application.
>
> > System.Threading.Task.Run().
>
> The TPL could be one way of implementing the queue, though I\u2019m not
> convinced that it adds much value. The custom implementation I did
> recently didn\u2019t use TPL, and that would be my starting point. This
> also means it would be compatible with .NET 3.5.
>
>
> If .net 3.5 is a target for async logging, then the implementation
> cannot use the System.Threading.Tasks namespace. Otherwise I would
> build upon the default task scheduler implementation or provide a
> custom task scheduler implementation that derives from
> System.Threading.Tasks.TaskScheduler and let all logging tasks run on
> that task scheduler.
>
> I found having a single background thread made it easier to
> implement things like flushing.
>
>
> Mileage may vary but to me, this is not the case.
>
> Flush was implemented to:
>
> - return true immediately if the queue is empty and all events have
> been successfully sent to the sink.
>
> - return false immediately if the last attempt to send events to the
> sink failed.
>
> - else wait for the background thread to set a ManualResetEvent when
> it\u2019s finished processing all events in the queue.
>
>
> That could read as:
>
> bool Flush() {
> return await Task.Run(() => {
> return doFlush();
> });
> }
>
> or:
>
> bool Flush() {
> Task<bool> task = Task.Run() => {
> return doFlush();
> });
> task.Wait();
> return task.Result;
> }
>
> or even:
>
> Task<bool> FlushAsync() {
> return Task.Run() => {
> return doFlush();
> });
> }
>
> > The default implementation should probably be able to operate
> asynchronously or synchronously and change mode of operation based on
> a configuration flag "Asynchronous=True"
>
> That\u2019s exactly what I had in mind.
>
>
> Cheers
>
>
>
> --
>
> Dominik Psenner
>
RE: AsyncAppenderSkeleton
Posted by Joe <Jo...@hotmail.com>.
OK I understand the point about potential corruption when a derived class is writing logging events in a non-atomic way, which is probably typical of most appenders.
However I don’t understand your point about event formatters – are there any formatters that aren’t thread safe? It doesn’t seem to be an unreasonable restriction to require writers of formatters / layout implementations to be thread-safe.
I looked at the implementation of AbsoluteTimeDateFormatter, which uses a static buffer internally. It seems to be thread-safe, but if I understood the code correctly, it seems to have a superfluous lock on s_lastTimeBuf, since it is only ever accessed when the current thread is already holding a lock on s_lastTimeStrings. Also it seems to me that any performance gains achieved by reusing a static buffer could easily be cancelled out by the overhead of holding locks if an application does a lot of concurrent logging from multiple threads. Perhaps a better implementation would be to use a ThreadStatic buffer, which I think would give the same result without locking.
As for an async appender: I still think the best approach is to write a new base class AsyncAppenderSkeleton, that doesn’t inherit from either BufferingAppenderSkeleton or AppenderSkeleton. I’ll give it some more thought and post again to justify this opinion soon(ish).
From: Dominik Psenner [mailto:dpsenner@gmail.com]
Sent: 03 November 2016 00:14
To: Log4NET Dev
Subject: Re: AsyncAppenderSkeleton
As far as I can recall, log4net logs to an appender in the thread that the log event was created on unless there is buffering of log events in between (BufferingAppenderSkeleton). This in general means that multiple threads write content to an appender at the same time and that in turn means that there is a chance that log events get mixed up.
Think of two threads A and B that try to write to the same sink at the same time. Thread A begins to write the timestamp of his log event and gets interrupted. B wakes up and writes another timestamp. Now there are two timestamps after each other and the outcome is not two distinct log messages but garbage.
And the issues can go even further. What if the event formatter populates a (not thread safe) local cache while processing log events? The outcome is unpredictable. I can imagine that back then it was decided to better be safe than sorry. A pessimistic lock fixes this issue for good at the cost of performance.
Writing this down today in 2016, one major question jumps into my mind: why is locking not left up to the appender or a event formatter? There are appenders out there that append log events to sinks that can handle concurrency very well (databases for example). It would definitely result in more locks; more locks cost more and thus a single (outer) lock is better.
Still, today I would not bother about locking and rather configure a buffering appender and let that appender append events into another appender that must not care about locking because the buffering appender already does. If one knows that locking/buffering is not needed because his application does no multithreading at all, he could still configure the other appender all alone.
2016-11-02 20:55 GMT+01:00 Joe <Jo...@hotmail.com>>:
I’m trying to understand what locking is necessary in AppenderSkeleton and its derived classes. There is a lock(this) in AppenderSkeleton’s DoAppend and Close methods, which ensure that the appender can’t be closed while an Append is in progress. Implementing Append in a derived class is easier, because the lock ensures it can never be called concurrently by more than one thread.
That’s all fairly clear, but I don’t understand the comment in the AppenderSkeleton.DoAppend method:
// This lock is absolutely critical for correct formatting
// of the message in a multi-threaded environment. Without
// this, the message may be broken up into elements from
// multiple thread contexts (like get the wrong thread ID).
The lock is clearly necessary for the above reasons, but I don’t see what race condition could cause a message to be “broken up into elements from multiple thread contexts”?
Can you throw any light on that?
From: Dominik Psenner [mailto:dpsenner@apache.org<ma...@apache.org>]
Sent: 31 October 2016 15:31
To: log4net-dev@logging.apache.org<ma...@logging.apache.org>
Subject: Re: AsyncAppenderSkeleton
See inlines.
On 2016-10-31 11:30, Joe wrote:
Hi Dominik,
Thanks for the feedback
> Please note also that MSMQ sounds like a MS only service and that would in turn mean that the .net core variant would no longer be able to benefit from the AsyncAppenderSkeleton. To me this outlines a path that we would not like to walk on
I don’t see the problem here.
I’m proposing that we could implement the queue as a separate class implementing a suitable interface (ILoggingEventQueue, IAppenderQueue or whatever – I’m with Philip Karlton on naming). The default implementation would be an in-memory queue, would not depend on MSMQ and would be available for .net core etc.
Sorry, my fault, the sentence was TL;DR it's entirety. I had it read it as "The default implementation could be MSMQ". ;-) Thanks for the clarification.
Then there could be an alternate implementation with a persistent queue using MSMQ, or users could provide their own custom implementations using some other persistent queueing technology if they wish.
The alternative of a persistent queue is useful to reduce the risk of (probably the last and therefore most important) logging events being lost when an application crashes: with a persistent queue they could be picked up again from the queue when the application restarts, or by an independent utility.
> This sounds mostly like the BufferingAppenderSkeleton, which only misses the background worker thread to send the buffer.
I’m not convinced that BufferingAppenderSkeleton is a good candidate. For example:
- Locking is problematic. The appender would need to lock(this) while it is forwarding logging events to the sink (BufferingAppenderSkeleton.SendBuffer). This could hold the lock for an extended period (e.g. due to a communication timeout). Therefore DoAppend should not lock(this) while enqueueing logging events or we’ll be unnecessarily blocking the calling application. This is one of the main reasons I want to implement my own DoEvents rather than deriving from AppenderSkeleton.
If the implementation requires lock(this) to work, the implementation is broken. The queue itself has to be thread safe. Hence, a true async appender should block the calling application only to fix a few logging event properties that would otherwise be lost (i.e. stacktrace or thread information).
- I see the buffering and triggering logic being implemented in a pluggable ILoggingEventQueue. By default, there would be no buffering, except what is implicit in the fact that events may be enqueued faster than they can be dequeued. I.e. whenever the background thread detects events in the queue, by default it processes all available events immediately, in blocks whose maximum size is a configurable SendBufferSize. A custom queue implementation could implement triggering logic akin to BufferingAppenderSkeleton, e.g. wait for a timeout defined by TimeEvaluator if there are fewer than SendBufferSize events in the queue.
A async appender working in async mode always buffers, by definition. If it wouldn't buffer, there would be nothing that a background thread could work on and it would block the calling application.
> System.Threading.Task.Run().
The TPL could be one way of implementing the queue, though I’m not convinced that it adds much value. The custom implementation I did recently didn’t use TPL, and that would be my starting point. This also means it would be compatible with .NET 3.5.
If .net 3.5 is a target for async logging, then the implementation cannot use the System.Threading.Tasks namespace. Otherwise I would build upon the default task scheduler implementation or provide a custom task scheduler implementation that derives from System.Threading.Tasks.TaskScheduler and let all logging tasks run on that task scheduler.
I found having a single background thread made it easier to implement things like flushing.
Mileage may vary but to me, this is not the case.
Flush was implemented to:
- return true immediately if the queue is empty and all events have been successfully sent to the sink.
- return false immediately if the last attempt to send events to the sink failed.
- else wait for the background thread to set a ManualResetEvent when it’s finished processing all events in the queue.
That could read as:
bool Flush() {
return await Task.Run(() => {
return doFlush();
});
}
or:
bool Flush() {
Task<bool> task = Task.Run() => {
return doFlush();
});
task.Wait();
return task.Result;
}
or even:
Task<bool> FlushAsync() {
return Task.Run() => {
return doFlush();
});
}
> The default implementation should probably be able to operate asynchronously or synchronously and change mode of operation based on a configuration flag "Asynchronous=True"
That’s exactly what I had in mind.
Cheers
--
Dominik Psenner
Re: AsyncAppenderSkeleton
Posted by Dominik Psenner <dp...@gmail.com>.
As far as I can recall, log4net logs to an appender in the thread that the
log event was created on unless there is buffering of log events in between
(BufferingAppenderSkeleton). This in general means that multiple threads
write content to an appender at the same time and that in turn means that
there is a chance that log events get mixed up.
Think of two threads A and B that try to write to the same sink at the same
time. Thread A begins to write the timestamp of his log event and gets
interrupted. B wakes up and writes another timestamp. Now there are two
timestamps after each other and the outcome is not two distinct log
messages but garbage.
And the issues can go even further. What if the event formatter populates a
(not thread safe) local cache while processing log events? The outcome is
unpredictable. I can imagine that back then it was decided to better be
safe than sorry. A pessimistic lock fixes this issue for good at the cost
of performance.
Writing this down today in 2016, one major question jumps into my mind: why
is locking not left up to the appender or a event formatter? There are
appenders out there that append log events to sinks that can handle
concurrency very well (databases for example). It would definitely result
in more locks; more locks cost more and thus a single (outer) lock is
better.
Still, today I would not bother about locking and rather configure a
buffering appender and let that appender append events into another
appender that must not care about locking because the buffering appender
already does. If one knows that locking/buffering is not needed because his
application does no multithreading at all, he could still configure the
other appender all alone.
2016-11-02 20:55 GMT+01:00 Joe <Jo...@hotmail.com>:
> I’m trying to understand what locking is necessary in AppenderSkeleton and
> its derived classes. There is a lock(this) in AppenderSkeleton’s DoAppend
> and Close methods, which ensure that the appender can’t be closed while an
> Append is in progress. Implementing Append in a derived class is easier,
> because the lock ensures it can never be called concurrently by more than
> one thread.
>
>
>
> That’s all fairly clear, but I don’t understand the comment in the
> AppenderSkeleton.DoAppend method:
>
>
>
> // This lock is absolutely critical for correct formatting
>
> // of the message in a multi-threaded environment. Without
>
> // this, the message may be broken up into elements from
>
> // multiple thread contexts (like get the wrong thread ID).
>
>
>
> The lock is clearly necessary for the above reasons, but I don’t see what
> race condition could cause a message to be “broken up into elements from
> multiple thread contexts”?
>
>
>
> Can you throw any light on that?
>
>
>
>
>
>
>
> *From:* Dominik Psenner [mailto:dpsenner@apache.org]
> *Sent:* 31 October 2016 15:31
> *To:* log4net-dev@logging.apache.org
> *Subject:* Re: AsyncAppenderSkeleton
>
>
>
> See inlines.
>
> On 2016-10-31 11:30, Joe wrote:
>
> Hi Dominik,
>
>
>
> Thanks for the feedback
>
>
>
> > Please note also that MSMQ sounds like a MS only service and that would
> in turn mean that the .net core variant would no longer be able to benefit
> from the AsyncAppenderSkeleton. To me this outlines a path that we would
> not like to walk on
>
>
>
> I don’t see the problem here.
>
>
>
> I’m proposing that we could implement the queue as a separate class
> implementing a suitable interface (ILoggingEventQueue, IAppenderQueue or
> whatever – I’m with Philip Karlton on naming). The default
> implementation would be an in-memory queue, would not depend on MSMQ and
> would be available for .net core etc.
>
>
>
>
> Sorry, my fault, the sentence was TL;DR it's entirety. I had it read it as
> "The default implementation could be MSMQ". ;-) Thanks for the
> clarification.
>
>
> Then there could be an alternate implementation with a persistent queue
> using MSMQ, or users could provide their own custom implementations using
> some other persistent queueing technology if they wish.
>
>
>
> The alternative of a persistent queue is useful to reduce the risk of
> (probably the last and therefore most important) logging events being lost
> when an application crashes: with a persistent queue they could be picked
> up again from the queue when the application restarts, or by an independent
> utility.
>
>
>
>
>
> > This sounds mostly like the BufferingAppenderSkeleton, which only
> misses the background worker thread to send the buffer.
>
>
>
> I’m not convinced that BufferingAppenderSkeleton is a good candidate. For
> example:
>
>
>
> - Locking is problematic. The appender would need to lock(this) while it
> is forwarding logging events to the sink (BufferingAppenderSkeleton.SendBuffer).
> This could hold the lock for an extended period (e.g. due to a
> communication timeout). Therefore DoAppend should not lock(this) while
> enqueueing logging events or we’ll be unnecessarily blocking the calling
> application. This is one of the main reasons I want to implement my own
> DoEvents rather than deriving from AppenderSkeleton.
>
>
> If the implementation requires lock(this) to work, the implementation is
> broken. The queue itself has to be thread safe. Hence, a true async
> appender should block the calling application only to fix a few logging
> event properties that would otherwise be lost (i.e. stacktrace or thread
> information).
>
>
> - I see the buffering and triggering logic being implemented in a
> pluggable ILoggingEventQueue. By default, there would be no buffering,
> except what is implicit in the fact that events may be enqueued faster than
> they can be dequeued. I.e. whenever the background thread detects events
> in the queue, by default it processes all available events immediately, in
> blocks whose maximum size is a configurable SendBufferSize. A custom
> queue implementation could implement triggering logic akin to
> BufferingAppenderSkeleton, e.g. wait for a timeout defined by TimeEvaluator
> if there are fewer than SendBufferSize events in the queue.
>
>
> A async appender working in async mode always buffers, by definition. If
> it wouldn't buffer, there would be nothing that a background thread could
> work on and it would block the calling application.
>
>
>
>
> > System.Threading.Task.Run().
>
>
>
> The TPL could be one way of implementing the queue, though I’m not
> convinced that it adds much value. The custom implementation I did
> recently didn’t use TPL, and that would be my starting point. This also
> means it would be compatible with .NET 3.5.
>
>
> If .net 3.5 is a target for async logging, then the implementation cannot
> use the System.Threading.Tasks namespace. Otherwise I would build upon the
> default task scheduler implementation or provide a custom task scheduler
> implementation that derives from System.Threading.Tasks.TaskScheduler and
> let all logging tasks run on that task scheduler.
>
>
> I found having a single background thread made it easier to implement
> things like flushing.
>
>
> Mileage may vary but to me, this is not the case.
>
>
> Flush was implemented to:
>
> - return true immediately if the queue is empty and all events have been
> successfully sent to the sink.
>
> - return false immediately if the last attempt to send events to the sink
> failed.
>
> - else wait for the background thread to set a ManualResetEvent when it’s
> finished processing all events in the queue.
>
>
> That could read as:
>
> bool Flush() {
> return await Task.Run(() => {
> return doFlush();
> });
> }
>
> or:
>
> bool Flush() {
> Task<bool> task = Task.Run() => {
> return doFlush();
> });
> task.Wait();
> return task.Result;
> }
>
> or even:
>
> Task<bool> FlushAsync() {
> return Task.Run() => {
> return doFlush();
> });
> }
>
>
>
>
> > The default implementation should probably be able to operate
> asynchronously or synchronously and change mode of operation based on a
> configuration flag "Asynchronous=True"
>
>
>
> That’s exactly what I had in mind.
>
>
> Cheers
>
--
Dominik Psenner
RE: AsyncAppenderSkeleton
Posted by Joe <Jo...@hotmail.com>.
I'm trying to understand what locking is necessary in AppenderSkeleton and its derived classes. There is a lock(this) in AppenderSkeleton's DoAppend and Close methods, which ensure that the appender can't be closed while an Append is in progress. Implementing Append in a derived class is easier, because the lock ensures it can never be called concurrently by more than one thread.
That's all fairly clear, but I don't understand the comment in the AppenderSkeleton.DoAppend method:
// This lock is absolutely critical for correct formatting
// of the message in a multi-threaded environment. Without
// this, the message may be broken up into elements from
// multiple thread contexts (like get the wrong thread ID).
The lock is clearly necessary for the above reasons, but I don't see what race condition could cause a message to be "broken up into elements from multiple thread contexts"?
Can you throw any light on that?
From: Dominik Psenner [mailto:dpsenner@apache.org]
Sent: 31 October 2016 15:31
To: log4net-dev@logging.apache.org
Subject: Re: AsyncAppenderSkeleton
See inlines.
On 2016-10-31 11:30, Joe wrote:
Hi Dominik,
Thanks for the feedback
> Please note also that MSMQ sounds like a MS only service and that would in turn mean that the .net core variant would no longer be able to benefit from the AsyncAppenderSkeleton. To me this outlines a path that we would not like to walk on
I don't see the problem here.
I'm proposing that we could implement the queue as a separate class implementing a suitable interface (ILoggingEventQueue, IAppenderQueue or whatever - I'm with Philip Karlton on naming). The default implementation would be an in-memory queue, would not depend on MSMQ and would be available for .net core etc.
Sorry, my fault, the sentence was TL;DR it's entirety. I had it read it as "The default implementation could be MSMQ". ;-) Thanks for the clarification.
Then there could be an alternate implementation with a persistent queue using MSMQ, or users could provide their own custom implementations using some other persistent queueing technology if they wish.
The alternative of a persistent queue is useful to reduce the risk of (probably the last and therefore most important) logging events being lost when an application crashes: with a persistent queue they could be picked up again from the queue when the application restarts, or by an independent utility.
> This sounds mostly like the BufferingAppenderSkeleton, which only misses the background worker thread to send the buffer.
I'm not convinced that BufferingAppenderSkeleton is a good candidate. For example:
- Locking is problematic. The appender would need to lock(this) while it is forwarding logging events to the sink (BufferingAppenderSkeleton.SendBuffer). This could hold the lock for an extended period (e.g. due to a communication timeout). Therefore DoAppend should not lock(this) while enqueueing logging events or we'll be unnecessarily blocking the calling application. This is one of the main reasons I want to implement my own DoEvents rather than deriving from AppenderSkeleton.
If the implementation requires lock(this) to work, the implementation is broken. The queue itself has to be thread safe. Hence, a true async appender should block the calling application only to fix a few logging event properties that would otherwise be lost (i.e. stacktrace or thread information).
- I see the buffering and triggering logic being implemented in a pluggable ILoggingEventQueue. By default, there would be no buffering, except what is implicit in the fact that events may be enqueued faster than they can be dequeued. I.e. whenever the background thread detects events in the queue, by default it processes all available events immediately, in blocks whose maximum size is a configurable SendBufferSize. A custom queue implementation could implement triggering logic akin to BufferingAppenderSkeleton, e.g. wait for a timeout defined by TimeEvaluator if there are fewer than SendBufferSize events in the queue.
A async appender working in async mode always buffers, by definition. If it wouldn't buffer, there would be nothing that a background thread could work on and it would block the calling application.
> System.Threading.Task.Run().
The TPL could be one way of implementing the queue, though I'm not convinced that it adds much value. The custom implementation I did recently didn't use TPL, and that would be my starting point. This also means it would be compatible with .NET 3.5.
If .net 3.5 is a target for async logging, then the implementation cannot use the System.Threading.Tasks namespace. Otherwise I would build upon the default task scheduler implementation or provide a custom task scheduler implementation that derives from System.Threading.Tasks.TaskScheduler and let all logging tasks run on that task scheduler.
I found having a single background thread made it easier to implement things like flushing.
Mileage may vary but to me, this is not the case.
Flush was implemented to:
- return true immediately if the queue is empty and all events have been successfully sent to the sink.
- return false immediately if the last attempt to send events to the sink failed.
- else wait for the background thread to set a ManualResetEvent when it's finished processing all events in the queue.
That could read as:
bool Flush() {
return await Task.Run(() => {
return doFlush();
});
}
or:
bool Flush() {
Task<bool> task = Task.Run() => {
return doFlush();
});
task.Wait();
return task.Result;
}
or even:
Task<bool> FlushAsync() {
return Task.Run() => {
return doFlush();
});
}
> The default implementation should probably be able to operate asynchronously or synchronously and change mode of operation based on a configuration flag "Asynchronous=True"
That's exactly what I had in mind.
Cheers
Re: AsyncAppenderSkeleton
Posted by Dominik Psenner <dp...@apache.org>.
See inlines.
On 2016-10-31 11:30, Joe wrote:
>
> Hi Dominik,
>
> Thanks for the feedback
>
> > Please note also that MSMQ sounds like a MS only service and that would in turn mean that the .net core
> variant would no longer be able to benefit from the
> AsyncAppenderSkeleton. To me this outlines a path that we would not
> like to walk on
>
> I dont see the problem here.
>
> Im proposing that we could implement the queue as a separate class
> implementing a suitable interface (ILoggingEventQueue, IAppenderQueue
> or whatever Im with Philip Karlton on naming). The default
> implementation would be an in-memory queue, would not depend on MSMQ
> and would be available for .net core etc.
>
Sorry, my fault, the sentence was TL;DR it's entirety. I had it read it
as "The default implementation could be MSMQ". ;-) Thanks for the
clarification.
> Then there could be an alternate implementation with a persistent
> queue using MSMQ, or users could provide their own custom
> implementations using some other persistent queueing technology if
> they wish.
>
> The alternative of a persistent queue is useful to reduce the risk of
> (probably the last and therefore most important) logging events being
> lost when an application crashes: with a persistent queue they could
> be picked up again from the queue when the application restarts, or by
> an independent utility.
>
> > This sounds mostly like the BufferingAppenderSkeleton, which only
> misses the background worker thread to send the buffer.
>
> Im not convinced that BufferingAppenderSkeleton is a good candidate.
> For example:
>
> - Locking is problematic. The appender would need to lock(this) while
> it is forwarding logging events to the sink
> (BufferingAppenderSkeleton.SendBuffer). This could hold the lock for
> an extended period (e.g. due to a communication timeout). Therefore
> DoAppend should not lock(this) while enqueueing logging events or
> well be unnecessarily blocking the calling application. This is one
> of the main reasons I want to implement my own DoEvents rather than
> deriving from AppenderSkeleton.
>
If the implementation requires lock(this) to work, the implementation is
broken. The queue itself has to be thread safe. Hence, a true async
appender should block the calling application only to fix a few logging
event properties that would otherwise be lost (i.e. stacktrace or thread
information).
> - I see the buffering and triggering logic being implemented in a
> pluggable ILoggingEventQueue. By default, there would be no
> buffering, except what is implicit in the fact that events may be
> enqueued faster than they can be dequeued. I.e. whenever the
> background thread detects events in the queue, by default it processes
> all available events immediately, in blocks whose maximum size is a
> configurable SendBufferSize. A custom queue implementation could
> implement triggering logic akin to BufferingAppenderSkeleton, e.g.
> wait for a timeout defined by TimeEvaluator if there are fewer than
> SendBufferSize events in the queue.
>
A async appender working in async mode always buffers, by definition. If
it wouldn't buffer, there would be nothing that a background thread
could work on and it would block the calling application.
> > System.Threading.Task.Run().
>
> The TPL could be one way of implementing the queue, though Im not
> convinced that it adds much value. The custom implementation I did
> recently didnt use TPL, and that would be my starting point. This
> also means it would be compatible with .NET 3.5.
>
If .net 3.5 is a target for async logging, then the implementation
cannot use the System.Threading.Tasks namespace. Otherwise I would build
upon the default task scheduler implementation or provide a custom task
scheduler implementation that derives from
System.Threading.Tasks.TaskScheduler and let all logging tasks run on
that task scheduler.
> I found having a single background thread made it easier to
> implement things like flushing.
>
Mileage may vary but to me, this is not the case.
> Flush was implemented to:
>
> - return true immediately if the queue is empty and all events have
> been successfully sent to the sink.
>
> - return false immediately if the last attempt to send events to the
> sink failed.
>
> - else wait for the background thread to set a ManualResetEvent when
> its finished processing all events in the queue.
>
That could read as:
bool Flush() {
return await Task.Run(() => {
return doFlush();
});
}
or:
bool Flush() {
Task<bool> task = Task.Run() => {
return doFlush();
});
task.Wait();
return task.Result;
}
or even:
Task<bool> FlushAsync() {
return Task.Run() => {
return doFlush();
});
}
> > The default implementation should probably be able to operate
> asynchronously or synchronously and change mode of operation based on
> a configuration flag "Asynchronous=True"
>
> Thats exactly what I had in mind.
>
Cheers
RE: AsyncAppenderSkeleton
Posted by Joe <Jo...@hotmail.com>.
I've created https://issues.apache.org/jira/browse/LOG4NET-529 for this
From: Dominik Psenner [mailto:dpsenner@gmail.com]
Sent: 31 October 2016 15:33
To: log4net-dev@logging.apache.org
Subject: Re: AsyncAppenderSkeleton
These few lines alone are very suspicious indeed. Without further investigations I'm unable to give any sensible feedback.
On 2016-10-31 11:54, Joe wrote:
Another point is that for any asynchronous appender implementation, it's a sine qua non that the LoggingEvent class be thread-safe.
At least for the manipulations an appender might do: layout, accessing properties, fixing properties.
I had a quick browse through the source and found what looks to me like a race condition here:
public object LookupProperty(string key)
{
if (m_data.Properties != null)
{
return m_data.Properties[key];
}
if (m_compositeProperties == null)
{
CreateCompositeProperties();
}
return m_compositeProperties[key];
}
private void CreateCompositeProperties()
{
m_compositeProperties = new CompositeProperties();
if (m_eventProperties != null)
{
m_compositeProperties.Add(m_eventProperties);
}
... etc
If two threads call LookupProperty concurrently, one may start executing CreateCompositeProperties and the other might access m_compositeProperties before it's fully created.
If I'm right, the fix is simple - don't set m_compositeProperties until it's completely created.
Re: AsyncAppenderSkeleton
Posted by Dominik Psenner <dp...@gmail.com>.
These few lines alone are very suspicious indeed. Without further
investigations I'm unable to give any sensible feedback.
On 2016-10-31 11:54, Joe wrote:
>
> Another point is that for any asynchronous appender implementation,
> its a sine qua non that the LoggingEvent class be thread-safe.
>
> At least for the manipulations an appender might do: layout, accessing
> properties, fixing properties.
>
> I had a quick browse through the source and found what looks to me
> like a race condition here:
>
> publicobjectLookupProperty(stringkey)
>
> {
>
> if(m_data.Properties != null)
>
> {
>
> returnm_data.Properties[key];
>
> }
>
> if(m_compositeProperties == null)
>
> {
>
> CreateCompositeProperties();
>
> }
>
> returnm_compositeProperties[key];
>
> }
>
> privatevoidCreateCompositeProperties()
>
> {
>
> m_compositeProperties = newCompositeProperties();
>
> if(m_eventProperties != null)
>
> {
>
> m_compositeProperties.Add(m_eventProperties);
>
> }
>
> ... etc
>
> If two threads call LookupProperty concurrently, one may start
> executing CreateCompositeProperties and the other might access
> m_compositeProperties before its fully created.
>
> If Im right, the fix is simple dont set m_compositeProperties
> until its completely created.
>
RE: AsyncAppenderSkeleton
Posted by Joe <Jo...@hotmail.com>.
Another point is that for any asynchronous appender implementation, it's a sine qua non that the LoggingEvent class be thread-safe.
At least for the manipulations an appender might do: layout, accessing properties, fixing properties.
I had a quick browse through the source and found what looks to me like a race condition here:
public object LookupProperty(string key)
{
if (m_data.Properties != null)
{
return m_data.Properties[key];
}
if (m_compositeProperties == null)
{
CreateCompositeProperties();
}
return m_compositeProperties[key];
}
private void CreateCompositeProperties()
{
m_compositeProperties = new CompositeProperties();
if (m_eventProperties != null)
{
m_compositeProperties.Add(m_eventProperties);
}
... etc
If two threads call LookupProperty concurrently, one may start executing CreateCompositeProperties and the other might access m_compositeProperties before it's fully created.
If I'm right, the fix is simple - don't set m_compositeProperties until it's completely created.
RE: AsyncAppenderSkeleton
Posted by Joe <Jo...@hotmail.com>.
Hi Dominik,
Thanks for the feedback
> Please note also that MSMQ sounds like a MS only service and that would in turn mean that the .net core variant would no longer be able to benefit from the AsyncAppenderSkeleton. To me this outlines a path that we would not like to walk on
I don't see the problem here.
I'm proposing that we could implement the queue as a separate class implementing a suitable interface (ILoggingEventQueue, IAppenderQueue or whatever - I'm with Philip Karlton on naming). The default implementation would be an in-memory queue, would not depend on MSMQ and would be available for .net core etc.
Then there could be an alternate implementation with a persistent queue using MSMQ, or users could provide their own custom implementations using some other persistent queueing technology if they wish.
The alternative of a persistent queue is useful to reduce the risk of (probably the last and therefore most important) logging events being lost when an application crashes: with a persistent queue they could be picked up again from the queue when the application restarts, or by an independent utility.
> This sounds mostly like the BufferingAppenderSkeleton, which only misses the background worker thread to send the buffer.
I'm not convinced that BufferingAppenderSkeleton is a good candidate. For example:
- Locking is problematic. The appender would need to lock(this) while it is forwarding logging events to the sink (BufferingAppenderSkeleton.SendBuffer). This could hold the lock for an extended period (e.g. due to a communication timeout). Therefore DoAppend should not lock(this) while enqueueing logging events or we'll be unnecessarily blocking the calling application. This is one of the main reasons I want to implement my own DoEvents rather than deriving from AppenderSkeleton.
- I see the buffering and triggering logic being implemented in a pluggable ILoggingEventQueue. By default, there would be no buffering, except what is implicit in the fact that events may be enqueued faster than they can be dequeued. I.e. whenever the background thread detects events in the queue, by default it processes all available events immediately, in blocks whose maximum size is a configurable SendBufferSize. A custom queue implementation could implement triggering logic akin to BufferingAppenderSkeleton, e.g. wait for a timeout defined by TimeEvaluator if there are fewer than SendBufferSize events in the queue.
> System.Threading.Task.Run().
The TPL could be one way of implementing the queue, though I'm not convinced that it adds much value. The custom implementation I did recently didn't use TPL, and that would be my starting point. This also means it would be compatible with .NET 3.5. I found having a single background thread made it easier to implement things like flushing. Flush was implemented to:
- return true immediately if the queue is empty and all events have been successfully sent to the sink.
- return false immediately if the last attempt to send events to the sink failed.
- else wait for the background thread to set a ManualResetEvent when it's finished processing all events in the queue.
> The default implementation should probably be able to operate asynchronously or synchronously and change mode of operation based on a configuration flag "Asynchronous=True"
That's exactly what I had in mind.
Joe
Re: AsyncAppenderSkeleton
Posted by Dominik Psenner <dp...@apache.org>.
Hi Joe!
On 2016-10-31 08:15, Joe wrote:
>
> I have some ideas for developing a new AsyncAppenderSkeleton, based on
> recent experience developing a custom async appender that sends
> logging events to a Web API.
>
> My current thoughts are:
>
> 1.A new base class AsyncAppenderSkeleton that can be configured to
> work in synchronous mode (identical to AppenderSkeleton) or
> asynchronous mode, where DoAppend queues events on to a FIFO queue,
> and has a single background thread that dequeues events and calls the
> existing Append methods.
>
This sounds mostly like the BufferingAppenderSkeleton, which only misses
the background worker thread to send the buffer. Therefore the
AsyncAppenderSkeleton could derive from BufferingAppenderSkeleton and
override a few methods that would additionally dispatch the job to a
background thread. See System.Threading.Task.Run().
> 2.When in asynchronous mode, there will be customizable and
> configurable retry logic that can call Append if it throws an
> exception. The retry login will be able to inspect the exception that
> was thrown and keep a count of the number of retries so far. For
> example, a derived appender that logs to a Web API might want to retry
> 5xx HTTP status codes, but treat 4xx status codes as permanent
> errors. There will no retry logic in synchronous mode as this would
> impact performance.
>
When running a task with System.Threading.Task.Run() it returns a
System.Threading.Tasks.Task object that allows to inspect the outcome of
the task. See:
https://msdn.microsoft.com/en-us/library/system.threading.tasks.task(v=vs.110).aspx
> 3.The default queue implementation would be a lossy in-memory Queue
> with a configurable maximum length. It might be nice to provide the
> possibility to plug in alternate queue implementations, such as a
> persistent queue using MSMQ.
>
We would reuse the BufferingAppenderSkeleton implementation of the queue
which does (not yet) persist the queue. Please note also that MSMQ
sounds like a MS only service and that would in turn mean that the .net
core variant would no longer be able to benefit from the
AsyncAppenderSkeleton. To me this outlines a path that we would not like
to walk on.
> 4.A class AsyncForwardingAppender would derive from
> AsyncAppenderSkeleton and implement IAppenderAttachable.
>
That's sensible to me. Looking at the class hierarchy of other
ForwardingAppender implementations composition sounds more sensible and
could be preferred over inheritance. We could try and work out a generic
ForwardingAppenderSkeleton implementation that can take arbitrary
appenders and must no longer be derived by every appender that should
become a Forwarding one.
> 5.It would be easy to create asynchronous versions of existing custom
> appenders, by changing the base class from AppenderSkeleton to
> AsyncAppenderSkeleton and optionally implementing some retry logic.
> E.g. we could have a new AdoNetAppender that can be configured to
> operate in synchronous mode when logging to a local database, or in
> asynchronous mode when logging to a cloud-based database.
>
The default implementation should probably be able to operate
asynchronously or synchronously and change mode of operation based on a
configuration flag "Asynchronous=True". This levers easy reconfiguration
at runtime and has probably other benefits too.
> In terms of timescales, I think it would be possible to produce
> something by the end of 2016.
>
> To do it I need to reimplement AppenderSkeletons DoAppend methods, to
> enqueue events if in asynchronous mode, or call Append in synchronous
> mode.
>
> I dont want to duplicate code by reimplementing the rest of
> AppenderSkeleton, so I would like to do one of the following:
>
> Option 1:
>
> -Refactor all of AppenderSkeletons implementation except IAppender
> and IBulkAppender into a new base class AppenderSkeletonBase. This
> includes filtering, IOptionHandler, layout.
>
> -Derive AppenderSkeleton and later the new AsyncAppenderSkeleton from
> AppenderSkeletonBase.
>
> Option 2:
>
> -Make AppenderSkeletons DoAppend methods virtual, and derive
> AsyncAppenderSkeleton from AppenderSkeleton.
>
> Option 1 seems the cleanest to me; any thoughts?
>
Let's first write out a few thoughts and concepts. When we have a
concept, the best way to get it done will hopefully be obvious.
Cheers