You are viewing a plain text version of this content. The canonical link for it is here.

Posted to log4net-user@logging.apache.org by Gert Kello <ge...@gmail.com> on 2015/03/04 09:27:55 UTC

AppenderSkeletion lock in DoAppend

Hi.

I'm trying to create a database appender which high throughput... I looked
at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // 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).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of
issues I do not understand:
1. As I do not know the internals of log4net well enough I do not
understand why lock is important for message formatting? Is it because the
Layout.Format is not supposed to be thread safe? Or is it because the same
instance of m_renderWriter could be used by multiple threads (well, usage
of m_renderWriter is protected by another lock, added later. But AFAIK the
RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)
2. The comment does not mention that lock is crucial for m_recursiveGuard
to work correctly. That's my main complaint: I almost overlooked the issue
of potentially skipped logging events.
3. What about implementations of IFilter.Decide? Are those (supposed to be)
thread safe?

Gert

Re: AppenderSkeletion lock in DoAppend

Posted by Dominik Psenner <dp...@gmail.com>.

See the inlines below..

On 5 Mar 2015 19:46, "Gert Kello" <ge...@gmail.com> wrote:
>
> First this thead safety issue: IFilter.Decide is thread-safe it it can be
called from different threads at same time and it returns correct
answers.Special attention needs to be paid to other instance members used
during call: like, is the RegEx.Match method thread safe or not?

Correct.

> And now I understand the recursion issue, it can happen in case of
ILog.InfoFormat(), the actual formatting is done only when "Message"
actually needed. I was assuming it happens prior to calling appenders...
>
> Made a simple test code below.:
>
> using log4net;
> namespace ConsoleApplication2
> {
>   class A
>   {
>     private static readonly ILog log =
LogManager.GetLogger(typeof(Program));
>     private int toStrCount = 0;
>     public override string ToString()
>     {
>       toStrCount++;
>       log.DebugFormat("In A.Tostring(), A = {0}, ToString call count
{1}", this, toStrCount);
>       return this.Name;
>     }
>
>     public string Name { get; set; }
>   }
>
>   class Program
>   {
>     private static readonly ILog log =
LogManager.GetLogger(typeof(Program));
>     static void Main(string[] args)
>     {
>       log4net.Config.XmlConfigurator.Configure();
>       A a = new A() { Name = "A1" };
>       log.InfoFormat("We have a = {0}", a);
>     }
>   }
> }
>
> log4net:ERROR Exception while logging
> System.Threading.LockRecursionException: Recursive read lock acquisitions
not allowed in this mode.
>    at
System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker
timeout)
>    at
System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker
timeout)
>    at System.Threading.ReaderWriterLockSlim.EnterReadLock()
>    at log4net.Util.ReaderWriterLock.AcquireReaderLock() in
c:\Kolibri\log4net-1.2.13\src\Util\ReaderWriterLock.cs:line 90
>    at log4net.Repository.Hierarchy.Logger.CallAppenders(LoggingEvent
loggingEvent) in
c:\Kolibri\log4net-1.2.13\src\Repository\Hierarchy\Logger.cs:line 571
>    at log4net.Repository.Hierarchy.Logger.ForcedLog(Type
callerStackBoundaryDeclaringType, Level level, Object message, Exception
exception) in
c:\Kolibri\log4net-1.2.13\src\Repository\Hierarchy\Logger.cs:line 688
>    at log4net.Repository.Hierarchy.Logger.Log(Type
callerStackBoundaryDeclaringType, Level level, Object message, Exception
exception) in
c:\Kolibri\log4net-1.2.13\src\Repository\Hierarchy\Logger.cs:line 428
> 2015-03-05 20:25:18,083 [1] INFO  - We have a = A1

Expected.

> If I modify
>     public ReaderWriterLock()
>     {
> #if HAS_READERWRITERLOCK
> #if HAS_READERWRITERLOCKSLIM
>       m_lock = new
System.Threading.ReaderWriterLockSlim(System.Threading.LockRecursionPolicy.SupportsRecursion);
>
> then output is
> 2015-03-05 20:29:11,175 [1] INFO  - We have a = A1
>
> So recrusion is prevented
>
> If I add some additional (file) appenders to configuration file then some
recursion starts to happen:
> 1 file appender + console appender
> 2015-03-05 20:31:08,341 [1] INFO  - We have a = A1
> 2015-03-05 20:31:08,350 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 3
>
> 2 file appenders + cpnsole appender
> 2015-03-05 20:31:34,674 [1] INFO  - We have a = A1
> 2015-03-05 20:31:34,684 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 6
> 2015-03-05 20:31:34,685 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 9
> 2015-03-05 20:31:34,685 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 11
> 2015-03-05 20:31:34,686 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 14
>
> 3 file appenders + console appender:
> 2015-03-05 20:32:50,960 [1] INFO  - We have a = A1
> 2015-03-05 20:32:50,973 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 17
> 2015-03-05 20:32:50,975 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 23
> 2015-03-05 20:32:50,976 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 26
> 2015-03-05 20:32:50,977 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 28
> 2015-03-05 20:32:50,978 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 31
> 2015-03-05 20:32:50,979 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 33
> 2015-03-05 20:32:50,981 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 39
> 2015-03-05 20:32:50,981 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 42
> 2015-03-05 20:32:50,982 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 44
> 2015-03-05 20:32:50,983 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 47
> 2015-03-05 20:32:50,984 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 49
> 2015-03-05 20:32:50,985 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 55
> 2015-03-05 20:32:50,986 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 58
> 2015-03-05 20:32:50,987 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 60
> 2015-03-05 20:32:50,987 [1] DEBUG - In A.Tostring(), A = A1, ToString
call count 63
>
>
> It does not seem to work "correctly" in preventing recursions caused by
logging from ToString() overrides... But I'm not sure if it is worth
fixing.

To me there's not enough information tongrasp what's going on here. This
behavior might be wrong or not.

> Anyway, thanks for helping me to understand.

Happy to help.

Cheers

>
> Gert
>
>
> On 5 March 2015 at 15:02, Dominik Psenner <dp...@gmail.com> wrote:
>>
>> Taking this to log4net dev since this goes well beyond the usage of
log4net, too.
>>
>>
>>
>> Logs are typically written by software that is programmed, aren’t they?
Thus one could happen to recursively trying to log something in his source
code without being aware of it. Maybe the example was not clear enough and
I apologize for not being verbose enough.
>>
>>
>>
>> I tried to say that a log event could try to get a formatted message of
the event by doing an invoke of another method and that method could again
try to format the log message by calling the other method. This then ends
up in a cyclic/recursive invoke and I believe that the recursive check
tries to tackle this issue so that the application does not crash by trying
to log something that might be totally unimportant.
>>
>>
>>
>> I’m not sure if I understand what you mean with not threadsafe. A method
that is not threadsafe can only be not threadsafe if it modifies data that
is out of scope. It’s up to you how you implement the interface, but it
might well happen that data gets modified without you being aware of it.
One good example is the GlobalContext, which can easily be used in a manner
that is not threadsafe at all.
>>
>>
>>
>> Cheers
>>
>>
>>
>> Von: Gert Kello [mailto:gert.kello@gmail.com]
>> Gesendet: Donnerstag, 05. März 2015 12:09
>>
>>
>> An: Log4NET User
>> Betreff: Re: AppenderSkeletion lock in DoAppend
>>
>>
>>
>> Sorry but I fail to understand this example... Log event programmed? I
didn't know I can program it... (without changing log4net source).
>>
>> So far I know/see two cases where recursive logging can happen:
>>
>> 1. Something called from Appender.Append calls anu ILog logging methods
>>
>> 2. According to comment in
https://issues.apache.org/jira/browse/LOG4NET-288 the bad configuration can
also cause the recursion.
>>
>> I assume that's all that can cause recursions... As I plan to save logs
from another thread I have to pay special attention to item 1. as any
logging from database save procedure would cause the same logging to be
executed again (tested). Without recursion but still flooding log system
with endless messages.
>>
>> But what about IFilter.Decide? Should I assume it is not threadsafe?
>>
>>
>>
>> Gert
>>
>>
>>
>>
>>
>> On 4 March 2015 at 16:51, Dominik Psenner <dp...@gmail.com> wrote:
>>>
>>> A log event might be badly programmed and recursive by definition.
Think of two objects that try each to log while trying to format each other:
>>>
>>>
>>>
>>> A {
>>>
>>> DoWork() {
>>>
>>>    Log(“A: {0}”, B)
>>>
>>> }
>>>
>>> }
>>>
>>> B {
>>>
>>> DoWork () {
>>>
>>>    Log(“B: {0}”, A)
>>>
>>> }
>>>
>>> }
>>>
>>>
>>>
>>> I might be wrong, but something like that does the recursive guard
detect and resolve.
>>>
>>>
>>>
>>> For the other question you’ll have to accept my apologies because I
can’t answer the question „how to write code“. J
>>>
>>>
>>>
>>> Von: Gert Kello [mailto:gert.kello@gmail.com]
>>> Gesendet: Mittwoch, 04. März 2015 15:16
>>> An: Log4NET User
>>> Betreff: Re: AppenderSkeletion lock in DoAppend
>>>
>>>
>>>
>>> But what about this m_recursiveGuard? Is the recursion protection
needed? Perhaps it is, if log saving code logs something by itself? (Like
warning that database operation takes longer than expected)?
>>>
>>> Well, as I plan to make the database saving asyn I need to tackle this
problem anyway... I think I would like to log the performance problem. But
not when the problem occurs during saving log about the same performance
problem. Is there any guideline how to write such code? Something like
using OnlyOnceErrorHandler or is there anything similar for warnings?
>>>
>>>
>>>
>>> Gert
>>>
>>>
>>>
>>> On 4 March 2015 at 15:38, Dominik Psenner <dp...@gmail.com> wrote:
>>>>
>>>> Hi,
>>>>
>>>>
>>>>
>>>> from what I can recall it could happen that the formatted
representation of a logging event gets mixed up with data from other events
and thus the characters streamed to a sink become garbage (i.e. a file,
console, ..) if this lock is removed.
>>>>
>>>>
>>>>
>>>> Internally a lot of things are cached to improve performance and these
caches actually require proper locking.
>>>>
>>>>
>>>>
>>>> But my memory might be wrong, so feel free to remove the lock and let
several threads log events to your appender to see if it can handle it
properly. J
>>>>
>>>>
>>>>
>>>> Cheers
>>>>
>>>>
>>>>
>>>> Von: Gert Kello [mailto:gert.kello@gmail.com]
>>>> Gesendet: Mittwoch, 04. März 2015 09:28
>>>> An: log4net-user@logging.apache.org
>>>> Betreff: AppenderSkeletion lock in DoAppend
>>>>
>>>>
>>>>
>>>> Hi.
>>>>
>>>> I'm trying to create a database appender which high throughput... I
looked at code in AppenderSekeletion.DoAppend() method and saw following
comment:
>>>>
>>>>     public void DoAppend(LoggingEvent loggingEvent)
>>>>     {
>>>>       // 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).
>>>>
>>>>       lock (this)
>>>>       {
>>>>
>>>> I would like to remove this lock from my code but there's a couple of
issues I do not understand:
>>>>
>>>> 1. As I do not know the internals of log4net well enough I do not
understand why lock is important for message formatting? Is it because the
Layout.Format is not supposed to be thread safe? Or is it because the same
instance of m_renderWriter could be used by multiple threads (well, usage
of m_renderWriter is protected by another lock, added later. But AFAIK the
RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)
>>>>
>>>> 2. The comment does not mention that lock is crucial for
m_recursiveGuard to work correctly. That's my main complaint: I almost
overlooked the issue of potentially skipped logging events.
>>>>
>>>> 3. What about implementations of IFilter.Decide? Are those (supposed
to be) thread safe?
>>>>
>>>> Gert
>>>
>>>
>>
>>
>
>

Re: AppenderSkeletion lock in DoAppend

Posted by Gert Kello <ge...@gmail.com>.

First this thead safety issue: IFilter.Decide is thread-safe it it can be
called from different threads at same time and it returns correct
answers.Special attention needs to be paid to other instance members used
during call: like, is the RegEx.Match method thread safe or not?

And now I understand the recursion issue, it can happen in case of
ILog.InfoFormat(), the actual formatting is done only when "Message"
actually needed. I was assuming it happens prior to calling appenders...

Made a simple test code below.:

using log4net;
namespace ConsoleApplication2
{
  class A
  {
    private static readonly ILog log =
LogManager.GetLogger(typeof(Program));
    private int toStrCount = 0;
    public override string ToString()
    {
      toStrCount++;
      log.DebugFormat("In A.Tostring(), A = {0}, ToString call count {1}",
this, toStrCount);
      return this.Name;
    }

    public string Name { get; set; }
  }

  class Program
  {
    private static readonly ILog log =
LogManager.GetLogger(typeof(Program));
    static void Main(string[] args)
    {
      log4net.Config.XmlConfigurator.Configure();
      A a = new A() { Name = "A1" };
      log.InfoFormat("We have a = {0}", a);
    }
  }
}

log4net:ERROR Exception while logging
System.Threading.LockRecursionException: Recursive read lock acquisitions
not allowed in this mode.
   at
System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker
timeout)
   at System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker
timeout)
   at System.Threading.ReaderWriterLockSlim.EnterReadLock()
   at log4net.Util.ReaderWriterLock.AcquireReaderLock() in
c:\Kolibri\log4net-1.2.13\src\Util\ReaderWriterLock.cs:line 90
   at log4net.Repository.Hierarchy.Logger.CallAppenders(LoggingEvent
loggingEvent) in
c:\Kolibri\log4net-1.2.13\src\Repository\Hierarchy\Logger.cs:line 571
   at log4net.Repository.Hierarchy.Logger.ForcedLog(Type
callerStackBoundaryDeclaringType, Level level, Object message, Exception
exception) in
c:\Kolibri\log4net-1.2.13\src\Repository\Hierarchy\Logger.cs:line 688
   at log4net.Repository.Hierarchy.Logger.Log(Type
callerStackBoundaryDeclaringType, Level level, Object message, Exception
exception) in
c:\Kolibri\log4net-1.2.13\src\Repository\Hierarchy\Logger.cs:line 428
2015-03-05 20:25:18,083 [1] INFO  - We have a = A1


If I modify
    public ReaderWriterLock()
    {
#if HAS_READERWRITERLOCK
#if HAS_READERWRITERLOCKSLIM
      m_lock = new
System.Threading.ReaderWriterLockSlim(System.Threading.LockRecursionPolicy.SupportsRecursion);

then output is
2015-03-05 20:29:11,175 [1] INFO  - We have a = A1

So recrusion is prevented

If I add some additional (file) appenders to configuration file then some
recursion starts to happen:
1 file appender + console appender
2015-03-05 20:31:08,341 [1] INFO  - We have a = A1
2015-03-05 20:31:08,350 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 3

2 file appenders + cpnsole appender
2015-03-05 20:31:34,674 [1] INFO  - We have a = A1
2015-03-05 20:31:34,684 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 6
2015-03-05 20:31:34,685 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 9
2015-03-05 20:31:34,685 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 11
2015-03-05 20:31:34,686 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 14

3 file appenders + console appender:
2015-03-05 20:32:50,960 [1] INFO  - We have a = A1
2015-03-05 20:32:50,973 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 17
2015-03-05 20:32:50,975 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 23
2015-03-05 20:32:50,976 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 26
2015-03-05 20:32:50,977 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 28
2015-03-05 20:32:50,978 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 31
2015-03-05 20:32:50,979 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 33
2015-03-05 20:32:50,981 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 39
2015-03-05 20:32:50,981 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 42
2015-03-05 20:32:50,982 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 44
2015-03-05 20:32:50,983 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 47
2015-03-05 20:32:50,984 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 49
2015-03-05 20:32:50,985 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 55
2015-03-05 20:32:50,986 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 58
2015-03-05 20:32:50,987 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 60
2015-03-05 20:32:50,987 [1] DEBUG - In A.Tostring(), A = A1, ToString call
count 63


It does not seem to work "correctly" in preventing recursions caused by
logging from ToString() overrides... But I'm not sure if it is worth
fixing.

Anyway, thanks for helping me to understand.

Gert

On 5 March 2015 at 15:02, Dominik Psenner <dp...@gmail.com> wrote:

> Taking this to log4net dev since this goes well beyond the usage of
> log4net, too.
>
>
>
> Logs are typically written by software that is programmed, aren’t they?
> Thus one could happen to recursively trying to log something in his source
> code without being aware of it. Maybe the example was not clear enough and
> I apologize for not being verbose enough.
>
>
>
> I tried to say that a log event could try to get a formatted message of
> the event by doing an invoke of another method and that method could again
> try to format the log message by calling the other method. This then ends
> up in a cyclic/recursive invoke and I believe that the recursive check
> tries to tackle this issue so that the application does not crash by trying
> to log something that might be totally unimportant.
>
>
>
> I’m not sure if I understand what you mean with not threadsafe. A method
> that is not threadsafe can only be not threadsafe if it modifies data that
> is out of scope. It’s up to you how you implement the interface, but it
> might well happen that data gets modified without you being aware of it.
> One good example is the GlobalContext, which can easily be used in a manner
> that is not threadsafe at all.
>
>
>
> Cheers
>
>
>
> *Von:* Gert Kello [mailto:gert.kello@gmail.com]
> *Gesendet:* Donnerstag, 05. März 2015 12:09
>
> *An:* Log4NET User
> *Betreff:* Re: AppenderSkeletion lock in DoAppend
>
>
>
> Sorry but I fail to understand this example... Log event programmed? I
> didn't know I can program it... (without changing log4net source).
>
> So far I know/see two cases where recursive logging can happen:
>
> 1. Something called from Appender.Append calls anu ILog logging methods
>
> 2. According to comment in
> https://issues.apache.org/jira/browse/LOG4NET-288 the bad configuration
> can also cause the recursion.
>
> I assume that's all that can cause recursions... As I plan to save logs
> from another thread I have to pay special attention to item 1. as any
> logging from database save procedure would cause the same logging to be
> executed again (tested). Without recursion but still flooding log system
> with endless messages.
>
> But what about IFilter.Decide? Should I assume it is not threadsafe?
>
>
>
> Gert
>
>
>
>
>
> On 4 March 2015 at 16:51, Dominik Psenner <dp...@gmail.com> wrote:
>
> A log event might be badly programmed and recursive by definition. Think
> of two objects that try each to log while trying to format each other:
>
>
>
> A {
>
> DoWork() {
>
>    Log(“A: {0}”, B)
>
> }
>
> }
>
> B {
>
> DoWork () {
>
>    Log(“B: {0}”, A)
>
> }
>
> }
>
>
>
> I might be wrong, but something like that does the recursive guard detect
> and resolve.
>
>
>
> For the other question you’ll have to accept my apologies because I can’t
> answer the question „how to write code“. J
>
>
>
> *Von:* Gert Kello [mailto:gert.kello@gmail.com]
> *Gesendet:* Mittwoch, 04. März 2015 15:16
> *An:* Log4NET User
> *Betreff:* Re: AppenderSkeletion lock in DoAppend
>
>
>
> But what about this m_recursiveGuard? Is the recursion protection needed?
> Perhaps it is, if log saving code logs something by itself? (Like warning
> that database operation takes longer than expected)?
>
> Well, as I plan to make the database saving asyn I need to tackle this
> problem anyway... I think I would like to log the performance problem. But
> not when the problem occurs during saving log about the same performance
> problem. Is there any guideline how to write such code? Something like
> using OnlyOnceErrorHandler or is there anything similar for warnings?
>
>
>
> Gert
>
>
>
> On 4 March 2015 at 15:38, Dominik Psenner <dp...@gmail.com> wrote:
>
> Hi,
>
>
>
> from what I can recall it could happen that the formatted representation
> of a logging event gets mixed up with data from other events and thus the
> characters streamed to a sink become garbage (i.e. a file, console, ..) if
> this lock is removed.
>
>
>
> Internally a lot of things are cached to improve performance and these
> caches actually require proper locking.
>
>
>
> But my memory might be wrong, so feel free to remove the lock and let
> several threads log events to your appender to see if it can handle it
> properly. J
>
>
>
> Cheers
>
>
>
> *Von:* Gert Kello [mailto:gert.kello@gmail.com]
> *Gesendet:* Mittwoch, 04. März 2015 09:28
> *An:* log4net-user@logging.apache.org
> *Bet**reff:* AppenderSkeletion lock in DoAppend
>
>
>
> Hi.
>
> I'm trying to create a database appender which high throughput... I looked
> at code in AppenderSekeletion.DoAppend() method and saw following comment:
>
>     public void DoAppend(LoggingEvent loggingEvent)
>     {
>       // 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).
>
>       lock (this)
>       {
>
> I would like to remove this lock from my code but there's a couple of
> issues I do not understand:
>
> 1. As I do not know the internals of log4net well enough I do not
> understand why lock is important for message formatting? Is it because the
> Layout.Format is not supposed to be thread safe? Or is it because the same
> instance of m_renderWriter could be used by multiple threads (well, usage
> of m_renderWriter is protected by another lock, added later. But AFAIK the
> RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)
>
> 2. The comment does not mention that lock is crucial for m_recursiveGuard
> to work correctly. That's my main complaint: I almost overlooked the issue
> of potentially skipped logging events.
>
> 3. What about implementations of IFilter.Decide? Are those (supposed to
> be) thread safe?
>
> Gert
>
>
>
>
>

AW: AppenderSkeletion lock in DoAppend

Posted by Dominik Psenner <dp...@gmail.com>.

Taking this to log4net dev since this goes well beyond the usage of log4net, too.

Logs are typically written by software that is programmed, aren’t they? Thus one could happen to recursively trying to log something in his source code without being aware of it. Maybe the example was not clear enough and I apologize for not being verbose enough.

I tried to say that a log event could try to get a formatted message of the event by doing an invoke of another method and that method could again try to format the log message by calling the other method. This then ends up in a cyclic/recursive invoke and I believe that the recursive check tries to tackle this issue so that the application does not crash by trying to log something that might be totally unimportant.

I’m not sure if I understand what you mean with not threadsafe. A method that is not threadsafe can only be not threadsafe if it modifies data that is out of scope. It’s up to you how you implement the interface, but it might well happen that data gets modified without you being aware of it. One good example is the GlobalContext, which can easily be used in a manner that is not threadsafe at all.

Cheers

Von: Gert Kello [mailto:gert.kello@gmail.com]
Gesendet: Donnerstag, 05. März 2015 12:09
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

Sorry but I fail to understand this example... Log event programmed? I didn't know I can program it... (without changing log4net source).

So far I know/see two cases where recursive logging can happen:

1. Something called from Appender.Append calls anu ILog logging methods

2. According to comment in https://issues.apache.org/jira/browse/LOG4NET-288 the bad configuration can also cause the recursion.

I assume that's all that can cause recursions... As I plan to save logs from another thread I have to pay special attention to item 1. as any logging from database save procedure would cause the same logging to be executed again (tested). Without recursion but still flooding log system with endless messages.

But what about IFilter.Decide? Should I assume it is not threadsafe?

Gert

On 4 March 2015 at 16:51, Dominik Psenner <dpsenner@gmail.com <ma...@gmail.com> > wrote:

A log event might be badly programmed and recursive by definition. Think of two objects that try each to log while trying to format each other:

A {

DoWork() {

Log(“A: {0}”, B)

}

B {

DoWork () {

Log(“B: {0}”, A)

}

I might be wrong, but something like that does the recursive guard detect and resolve.

For the other question you’ll have to accept my apologies because I can’t answer the question „how to write code“. :)

Von: Gert Kello [mailto:gert.kello@gmail.com <ma...@gmail.com> ]
Gesendet: Mittwoch, 04. März 2015 15:16
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

But what about this m_recursiveGuard? Is the recursion protection needed? Perhaps it is, if log saving code logs something by itself? (Like warning that database operation takes longer than expected)?

Well, as I plan to make the database saving asyn I need to tackle this problem anyway... I think I would like to log the performance problem. But not when the problem occurs during saving log about the same performance problem. Is there any guideline how to write such code? Something like using OnlyOnceErrorHandler or is there anything similar for warnings?

Gert

On 4 March 2015 at 15:38, Dominik Psenner <dpsenner@gmail.com <ma...@gmail.com> > wrote:

Hi,

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. :)

Cheers

Von: Gert Kello [mailto:gert.kello@gmail.com <ma...@gmail.com> ]
Gesendet: Mittwoch, 04. März 2015 09:28
An: log4net-user@logging.apache.org <ma...@logging.apache.org>
Betreff: AppenderSkeletion lock in DoAppend

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

public void DoAppend(LoggingEvent loggingEvent)
{
// 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).

lock (this)
{

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert

AW: AppenderSkeletion lock in DoAppend

Posted by Dominik Psenner <dp...@gmail.com>.

Taking this to log4net dev since this goes well beyond the usage of log4net, too.

Cheers

Von: Gert Kello [mailto:gert.kello@gmail.com]
Gesendet: Donnerstag, 05. März 2015 12:09
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

Sorry but I fail to understand this example... Log event programmed? I didn't know I can program it... (without changing log4net source).

So far I know/see two cases where recursive logging can happen:

1. Something called from Appender.Append calls anu ILog logging methods

2. According to comment in https://issues.apache.org/jira/browse/LOG4NET-288 the bad configuration can also cause the recursion.

But what about IFilter.Decide? Should I assume it is not threadsafe?

Gert

On 4 March 2015 at 16:51, Dominik Psenner <dpsenner@gmail.com <ma...@gmail.com> > wrote:

A log event might be badly programmed and recursive by definition. Think of two objects that try each to log while trying to format each other:

A {

DoWork() {

Log(“A: {0}”, B)

}

B {

DoWork () {

Log(“B: {0}”, A)

}

I might be wrong, but something like that does the recursive guard detect and resolve.

For the other question you’ll have to accept my apologies because I can’t answer the question „how to write code“. :)

Von: Gert Kello [mailto:gert.kello@gmail.com <ma...@gmail.com> ]
Gesendet: Mittwoch, 04. März 2015 15:16
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

Gert

On 4 March 2015 at 15:38, Dominik Psenner <dpsenner@gmail.com <ma...@gmail.com> > wrote:

Hi,

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. :)

Cheers

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

lock (this)
{

I would like to remove this lock from my code but there's a couple of issues I do not understand:

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert

Re: AppenderSkeletion lock in DoAppend

Posted by Gert Kello <ge...@gmail.com>.

Sorry but I fail to understand this example... Log event programmed? I
didn't know I can program it... (without changing log4net source).

So far I know/see two cases where recursive logging can happen:
1. Something called from Appender.Append calls anu ILog logging methods
2. According to comment in https://issues.apache.org/jira/browse/LOG4NET-288
the bad configuration can also cause the recursion.

I assume that's all that can cause recursions... As I plan to save logs
from another thread I have to pay special attention to item 1. as any
logging from database save procedure would cause the same logging to be
executed again (tested). Without recursion but still flooding log system
with endless messages.

But what about IFilter.Decide? Should I assume it is not threadsafe?

Gert


On 4 March 2015 at 16:51, Dominik Psenner <dp...@gmail.com> wrote:

> A log event might be badly programmed and recursive by definition. Think
> of two objects that try each to log while trying to format each other:
>
>
>
> A {
>
> DoWork() {
>
>    Log(“A: {0}”, B)
>
> }
>
> }
>
> B {
>
> DoWork () {
>
>    Log(“B: {0}”, A)
>
> }
>
> }
>
>
>
> I might be wrong, but something like that does the recursive guard detect
> and resolve.
>
>
>
> For the other question you’ll have to accept my apologies because I can’t
> answer the question „how to write code“. J
>
>
>
> *Von:* Gert Kello [mailto:gert.kello@gmail.com]
> *Gesendet:* Mittwoch, 04. März 2015 15:16
> *An:* Log4NET User
> *Betreff:* Re: AppenderSkeletion lock in DoAppend
>
>
>
> But what about this m_recursiveGuard? Is the recursion protection needed?
> Perhaps it is, if log saving code logs something by itself? (Like warning
> that database operation takes longer than expected)?
>
> Well, as I plan to make the database saving asyn I need to tackle this
> problem anyway... I think I would like to log the performance problem. But
> not when the problem occurs during saving log about the same performance
> problem. Is there any guideline how to write such code? Something like
> using OnlyOnceErrorHandler or is there anything similar for warnings?
>
>
>
> Gert
>
>
>
> On 4 March 2015 at 15:38, Dominik Psenner <dp...@gmail.com> wrote:
>
> Hi,
>
>
>
> from what I can recall it could happen that the formatted representation
> of a logging event gets mixed up with data from other events and thus the
> characters streamed to a sink become garbage (i.e. a file, console, ..) if
> this lock is removed.
>
>
>
> Internally a lot of things are cached to improve performance and these
> caches actually require proper locking.
>
>
>
> But my memory might be wrong, so feel free to remove the lock and let
> several threads log events to your appender to see if it can handle it
> properly. J
>
>
>
> Cheers
>
>
>
> *Von:* Gert Kello [mailto:gert.kello@gmail.com]
> *Gesendet:* Mittwoch, 04. März 2015 09:28
> *An:* log4net-user@logging.apache.org
> *Bet**reff:* AppenderSkeletion lock in DoAppend
>
>
>
> Hi.
>
> I'm trying to create a database appender which high throughput... I looked
> at code in AppenderSekeletion.DoAppend() method and saw following comment:
>
>     public void DoAppend(LoggingEvent loggingEvent)
>     {
>       // 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).
>
>       lock (this)
>       {
>
> I would like to remove this lock from my code but there's a couple of
> issues I do not understand:
>
> 1. As I do not know the internals of log4net well enough I do not
> understand why lock is important for message formatting? Is it because the
> Layout.Format is not supposed to be thread safe? Or is it because the same
> instance of m_renderWriter could be used by multiple threads (well, usage
> of m_renderWriter is protected by another lock, added later. But AFAIK the
> RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)
>
> 2. The comment does not mention that lock is crucial for m_recursiveGuard
> to work correctly. That's my main complaint: I almost overlooked the issue
> of potentially skipped logging events.
>
> 3. What about implementations of IFilter.Decide? Are those (supposed to
> be) thread safe?
>
> Gert
>
>
>

AW: AppenderSkeletion lock in DoAppend

Posted by Dominik Psenner <dp...@gmail.com>.

A log event might be badly programmed and recursive by definition. Think of two objects that try each to log while trying to format each other:

 

A {

DoWork() {

   Log(“A: {0}”, B)

}

}

B {

DoWork () {

   Log(“B: {0}”, A)

}

}

 

I might be wrong, but something like that does the recursive guard detect and resolve.

 

For the other question you’ll have to accept my apologies because I can’t answer the question „how to write code“. :)

 

Von: Gert Kello [mailto:gert.kello@gmail.com] 
Gesendet: Mittwoch, 04. März 2015 15:16
An: Log4NET User
Betreff: Re: AppenderSkeletion lock in DoAppend

 

But what about this m_recursiveGuard? Is the recursion protection needed? Perhaps it is, if log saving code logs something by itself? (Like warning that database operation takes longer than expected)?

Well, as I plan to make the database saving asyn I need to tackle this problem anyway... I think I would like to log the performance problem. But not when the problem occurs during saving log about the same performance problem. Is there any guideline how to write such code? Something like using OnlyOnceErrorHandler or is there anything similar for warnings?

 

Gert

 

On 4 March 2015 at 15:38, Dominik Psenner <dpsenner@gmail.com <ma...@gmail.com> > wrote:

Hi,

 

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

 

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

 

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. :)

 

Cheers

 

Von: Gert Kello [mailto:gert.kello@gmail.com <ma...@gmail.com> ] 
Gesendet: Mittwoch, 04. März 2015 09:28
An: log4net-user@logging.apache.org <ma...@logging.apache.org> 
Betreff: AppenderSkeletion lock in DoAppend

 

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // 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).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert

Re: AppenderSkeletion lock in DoAppend

Posted by Gert Kello <ge...@gmail.com>.

But what about this m_recursiveGuard? Is the recursion protection needed?
Perhaps it is, if log saving code logs something by itself? (Like warning
that database operation takes longer than expected)?

Well, as I plan to make the database saving asyn I need to tackle this
problem anyway... I think I would like to log the performance problem. But
not when the problem occurs during saving log about the same performance
problem. Is there any guideline how to write such code? Something like
using OnlyOnceErrorHandler or is there anything similar for warnings?

Gert

On 4 March 2015 at 15:38, Dominik Psenner <dp...@gmail.com> wrote:

> Hi,
>
>
>
> from what I can recall it could happen that the formatted representation
> of a logging event gets mixed up with data from other events and thus the
> characters streamed to a sink become garbage (i.e. a file, console, ..) if
> this lock is removed.
>
>
>
> Internally a lot of things are cached to improve performance and these
> caches actually require proper locking.
>
>
>
> But my memory might be wrong, so feel free to remove the lock and let
> several threads log events to your appender to see if it can handle it
> properly. J
>
>
>
> Cheers
>
>
>
> *Von:* Gert Kello [mailto:gert.kello@gmail.com]
> *Gesendet:* Mittwoch, 04. März 2015 09:28
> *An:* log4net-user@logging.apache.org
> *Bet**reff:* AppenderSkeletion lock in DoAppend
>
>
>
> Hi.
>
> I'm trying to create a database appender which high throughput... I looked
> at code in AppenderSekeletion.DoAppend() method and saw following comment:
>
>     public void DoAppend(LoggingEvent loggingEvent)
>     {
>       // 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).
>
>       lock (this)
>       {
>
> I would like to remove this lock from my code but there's a couple of
> issues I do not understand:
>
> 1. As I do not know the internals of log4net well enough I do not
> understand why lock is important for message formatting? Is it because the
> Layout.Format is not supposed to be thread safe? Or is it because the same
> instance of m_renderWriter could be used by multiple threads (well, usage
> of m_renderWriter is protected by another lock, added later. But AFAIK the
> RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)
>
> 2. The comment does not mention that lock is crucial for m_recursiveGuard
> to work correctly. That's my main complaint: I almost overlooked the issue
> of potentially skipped logging events.
>
> 3. What about implementations of IFilter.Decide? Are those (supposed to
> be) thread safe?
>
> Gert
>

AW: AppenderSkeletion lock in DoAppend

Posted by Dominik Psenner <dp...@gmail.com>.

Hi,

 

from what I can recall it could happen that the formatted representation of a logging event gets mixed up with data from other events and thus the characters streamed to a sink become garbage (i.e. a file, console, ..) if this lock is removed.

 

Internally a lot of things are cached to improve performance and these caches actually require proper locking.

 

But my memory might be wrong, so feel free to remove the lock and let several threads log events to your appender to see if it can handle it properly. :)

 

Cheers

 

Von: Gert Kello [mailto:gert.kello@gmail.com] 
Gesendet: Mittwoch, 04. März 2015 09:28
An: log4net-user@logging.apache.org
Betreff: AppenderSkeletion lock in DoAppend

 

Hi.

I'm trying to create a database appender which high throughput... I looked at code in AppenderSekeletion.DoAppend() method and saw following comment:

    public void DoAppend(LoggingEvent loggingEvent)
    {
      // 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).

      lock (this)
      {

I would like to remove this lock from my code but there's a couple of issues I do not understand:

1. As I do not know the internals of log4net well enough I do not understand why lock is important for message formatting? Is it because the Layout.Format is not supposed to be thread safe? Or is it because the same instance of m_renderWriter could be used by multiple threads (well, usage of m_renderWriter is protected by another lock, added later. But AFAIK the RenderLoggingEvent(LoggingEvent loggingEvent) is still not 100% thread safe)

2. The comment does not mention that lock is crucial for m_recursiveGuard to work correctly. That's my main complaint: I almost overlooked the issue of potentially skipped logging events.

3. What about implementations of IFilter.Decide? Are those (supposed to be) thread safe?

Gert