See the inlines below..
On 5 Mar 2015 19:46, "Gert Kello" <gert.ke...@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 <dpsen...@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.ke...@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 <dpsen...@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.ke...@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 <dpsen...@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.ke...@gmail.com]
>>>> Gesendet: Mittwoch, 04. März 2015 09:28
>>>> An: log4net-u...@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
>>>
>>>
>>
>>
>
>
