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 Diego Jancic <di...@engineerica.com> on 2009/08/06 17:50:45 UTC
FW: Mixed Logs
Hi,
Can you help with this? I don't know if log4net is using thread inside or
something that can produce such behavior when locking in an appender.
What happens if an appender takes much time to complete or throws an
exception, are the other ones going to success?
Thanks,
Diego
From: Diego Jancic [mailto:diegoj@engineerica.com]
Sent: Wednesday, August 05, 2009 13:12
To: 'Log4NET User'
Subject: RE: Mixed Logs
Hi again,
I've removed that appender and looks to be working fine now.
Now, the question is how should I do that lock?
Thanks,
Diego
From: Diego Jancic [mailto:diegoj@engineerica.com]
Sent: Tuesday, August 04, 2009 11:38
To: 'Log4NET User'
Subject: RE: Mixed Logs
No, the configurations are pretty simple, although I have a custom appender.
I guess it should not affect the file appender, but here it is:
Appender code:
public class FormAppender : AppenderSkeleton
{
public static Dictionary<string, ListBox> outputLists = new
Dictionary<string, ListBox>();
public static InvokeDelegate Invoke;
protected override void Append(LoggingEvent loggingEvent)
{
if (MyOutputList != null)
{
AddItemThreadSafeDelegate del = AddItemThreadSafe;
Invoke(del, new object[] { loggingEvent });
}
}
protected override bool RequiresLayout
{
get { return true; }
}
private delegate void AddItemThreadSafeDelegate(LoggingEvent
loggingEvent);
private void AddItemThreadSafe(LoggingEvent loggingEvent)
{
string text = RenderLoggingEvent(loggingEvent);
text = text.Trim('\n', '\r', ' ');
MyOutputList.Items.Insert(0, text);
// Purge old message
lock (MyOutputList)
{
if (MyOutputList.Items.Count > 1500)
{
while (MyOutputList.Items.Count > 1400)
MyOutputList.Items.RemoveAt(MyOutputList.Items.Count - 1);
}
}
}
private ListBox MyOutputList
{
get { return outputLists[Name]; }
}
}
To Setup the appender by code:
FormAppender.outputLists.Add("WinAppender-MainLog", lbLog);
FormAppender.outputLists.Add("WinAppender-DeviceLog", lbDeviceOutput);
FormAppender.Invoke = Invoke;
XmlConfigurator.ConfigureAndWatch(new FileInfo("log4net.config"));
log = LogManager.GetLogger(GetType());
The config file:
<!-- WINDOW APPENDER -->
<appender name="WinAppender-MainLog"
type="RollCaller.UI.Admin.Win.FormAppender">
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date %-5level %logger -
%message%newline" />
</layout>
</appender>
<appender name="WinAppender-DeviceLog"
type="RollCaller.UI.Admin.Win.FormAppender">
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date - %message%newline" />
</layout>
</appender>
<!-- FILE APPENDER -->
<appender name="FileAppender"
type="log4net.Appender.RollingFileAppender">
<file value="Logs\Log.txt" />
<appendToFile value="true" />
<rollingStyle value="Size" />
<maxSizeRollBackups value="10" />
<maximumFileSize value="2MB" />
<staticLogFileName value="true" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %-5level %logger
- %message%newline" />
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="WinAppender-MainLog" />
<appender-ref ref="FileAppender" />
</root>
... other loggers ...
Now I'm wondering if the lock may cause a delay in all appenders and produce
such weird behavior. I'll disable it, but it'll take me all the day to
figure out if it keeps failing.
Thanks,
Diego
From: Ross Hinkley [mailto:rosshinkley@gmail.com]
Sent: Tuesday, August 04, 2009 11:28
To: Log4NET User
Subject: Re: Mixed Logs
Karim,
I believe that's the [1], which is interesting to point out. I didn't look
that far. My gut reaction to seeing something like that was multiple
processes. I leapt before I looked.
Hm. That is an interesting anomaly.
Diego, do you have buffer values set up in your configuration? I guess my
next gut feeling is something odd happening with message buffering.
-Ross
On Tue, Aug 4, 2009 at 9:21 AM, Karim Bourouba <ka...@hotmail.com> wrote:
I may be mis-reading this, but isnt the value after the timestamp the thread
ID?
_____
Date: Tue, 4 Aug 2009 09:05:09 -0500
Subject: Re: Mixed Logs
From: rosshinkley@gmail.com
To: log4net-user@logging.apache.org
Do these processes run on different computers?
Correct me if I'm wrong, doesn't log4net use local system time for
timestamps (the time from the logging machine, not necessarily where the log
is located)?
-Ross
On Tue, Aug 4, 2009 at 8:51 AM, Diego Jancic <di...@engineerica.com> wrote:
Hi Guys,
I've got an application that uses log4net everywhere and logs a lot of
things. Yesterday I leave running some hardware stress tests all the night,
and today I found something weird in the logs.
The app ran near 1000 test, and 2 of them failed, but just before the failed
test it logged something like this:
2009-08-04 04:42:41,846 [1] DEBUG
XXX.Communications.Messages.ReadMemoryMessage - Downloading memory. Start:
5120 -- Length: 1024
2009-08-04 04:42:54,046 [1] DEBUG
XXX.Communications.Messages.ReadMemoryMessage - Downloading memory. Start:
6144 -- Length: 412
2009-08-04 04:42:42,073 [1] INFO XXX.UI.Admin.Win.MainForm - Test completed
OK!
2009-08-04 04:42:54,049 [1] INFO XXX.UI.Admin.Win.MainForm -
-----------------------------------------------------
2009-08-04 04:42:54,050 [1] INFO XXX.UI.Admin.Win.MainForm - Cleaning scans
before start.
Look at the 3rd log, it's second part (42) is between 2 logs that happened
after it (second 54)
Well, it's hard to reproduce the problem in the application. Do you know why
it could happen?
Thanks,
Diego
_____
Windows Live Messenger: Thanks for 10 great years-enjoy free winks and
emoticons. Get <http://clk.atdmt.com/UKM/go/157562755/direct/01/> Them Now