Log4net logs several times same line since MinimalLock setup

Question

I recently had to face some performance issues on my C# program and find out that log4net was the origin of those problems. I changed the configuration adding the MinimalLock and it really helped a lot.

This is how I have now configured my log4net:

var hierarchy = (Hierarchy)log4net.LogManager.GetRepository();

var patternLayout = new PatternLayout();
patternLayout.ConversionPattern = "%date [%thread] %-5level %logger - %message%newline";
patternLayout.ActivateOptions();

var roller = new RollingFileAppender();

roller.LockingModel = new FileAppender.MinimalLock();
roller.LockingModel.ActivateOptions();

roller.Encoding = System.Text.Encoding.UTF8;
roller.AppendToFile = true;
roller.File = Path.Combine(Logger.LogPath, "log.txt");
roller.Layout = patternLayout;
roller.MaxSizeRollBackups = 5;
roller.MaximumFileSize = "100MB";
roller.RollingStyle = RollingFileAppender.RollingMode.Size;
roller.StaticLogFileName = true;
roller.ActivateOptions();

hierarchy.Root.AddAppender(roller);
hierarchy.Root.Level = Level.Debug;
hierarchy.Configured = true;

The drawback from this is that now my logs contain the very same log lines repeated many times.

I suspect that I misunderstood something from the log4net configuration and now each log line I want to output is sent as much times as processes the application has (even, obviously, the rest of processes created are not logging anything, or at least not the same line at the same time!)

Here an example of log line:

2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,495 [1] DEBUG MetryViewModel - Reading dat: manuel.dat with config: None 2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol
2016-11-18 10:35:34,512 [1] INFO ViewModel - Operating mode: Lol

Are you running the code above multiple times? Also what do you mean by _as much times as processes the application has_ ?. — sgmoore, Nov 19 '16 at 10:53
I run the code just once. With _as much times as processes the application has_ I mean that the application is creating several processes, could this be somehow related? — juagicre, Nov 19 '16 at 13:41
Doesn't really make sense. To get multiple entries, you either need to be adding several loggers, or logging the event several times. If it was the latter, the events would show up without needing MininalLock and the timestamps would be different, so it would look like you are initialising log4net several times. To rule this out, can you try logging something (maybe `LogManager.GetRepository().GetAppenders().Length`) immediately after you call `hierarchy.Configured = true;` and see if this message is added multiple times immediately, or if it is added once, then twice, then three times, etc — sgmoore, Nov 19 '16 at 14:24
Maybe the Problem is this. You are calling your logging statement in several threads. When you do not have MinimalLock activated, the first thread who is writing to the File is locking it. So all other threads can not write to the file. As soon as you activated MinimalLock the Appender just locks the file and releases it again. So every Thread can now write to the file — jan-seins, Dec 05 '16 at 19:40

score 3 · Answer 1 · answered Sep 14 '17 at 15:46

In your case:
If the messages are all on the same time and same thread it's possible that one of your components is adding trace listeners. Check the System.Diagnostics.Trace.Listeners property.
In my case it was Owin Server that added them on startup.: OWIN interferes with log4net

For others:
Eliminate the possibility that it's cause by multiple appenders.
You can find out by using LogManager.GetRepository().GetAppenders().Length;
Remember that your logger will inherit the appenders of the root logger.

Make sure you're code is only called once (you can print thread id by adding [%thread] in your conversationPattern.

<layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%date [%thread] %message%newline" />
  </layout>

for me it is printing the same thread so the function is called only one time and i have one appender only, but the same line of log is being logged several times, do you have any idea why? note that i am using .net core — User7291, Jul 04 '19 at 05:28

Log4net logs several times same line since MinimalLock setup

1 Answers1