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 Ώ] DEBUG XXX.Communications.Messages.ReadMemoryMessage - Downloading memory. Start: 5120 -- Length: 1024

2009-08-04 04:42:54,046 Ώ] DEBUG XXX.Communications.Messages.ReadMemoryMessage - Downloading memory. Start: 6144 -- Length: 412

2009-08-04 04:42:42,073 Ώ] INFO  XXX.UI.Admin.Win.MainForm - Test completed OK!

2009-08-04 04:42:54,049 Ώ] INFO  XXX.UI.Admin.Win.MainForm - -----------------------------------------------------

2009-08-04 04:42:54,050 Ώ] 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

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

Yes, it is.

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

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