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 <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
> *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
>
>
>
>
>
