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 Diego Jancic <di...@engineerica.com> on 2009/08/04 15:51:28 UTC
Mixed Logs
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
RE: Mixed Logs
Posted by Diego Jancic <di...@engineerica.com>.
No Ross, I forgot to say this, but it's a single process (maybe multiple
threads running when that fails) on a single machine with logging in a text
file.
We've developed a USB device that stores information among other things, and
the app is running a test like this hundreds of times (not in parallel):
- Clear all the information in the device
- Create information
- Download it
- Verify it
Threads might exist because of the USB driver, the UI, and other things, but
the tests run always one at a time.
Thanks,
Diego
From: Ross Hinkley [mailto:rosshinkley@gmail.com]
Sent: Tuesday, August 04, 2009 11:05
To: Log4NET User
Subject: Re: Mixed Logs
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
FW: Mixed Logs
Posted by Diego Jancic <di...@engineerica.com>.
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
RE: Mixed Logs
Posted by Diego Jancic <di...@engineerica.com>.
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 Them Now <http://clk.atdmt.com/UKM/go/157562755/direct/01/>
RE: Mixed Logs
Posted by Diego Jancic <di...@engineerica.com>.
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
Re: Mixed Logs
Posted by Ross Hinkley <ro...@gmail.com>.
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 Them Now <http://clk.atdmt.com/UKM/go/157562755/direct/01/>
>
RE: Mixed Logs
Posted by Diego Jancic <di...@engineerica.com>.
Yes, it is.
From: Karim Bourouba [mailto:karym6@hotmail.com]
Sent: Tuesday, August 04, 2009 11:22
To: log4net-user@logging.apache.org
Subject: RE: Mixed Logs
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 Them <http://clk.atdmt.com/UKM/go/157562755/direct/01/> Now
RE: Mixed Logs
Posted by Karim Bourouba <ka...@hotmail.com>.
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: Celebrate 10 amazing years with free winks and emoticons.
http://clk.atdmt.com/UKM/go/157562755/direct/01/
Re: Mixed Logs
Posted by Ross Hinkley <ro...@gmail.com>.
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
>
>
>