CODEWITHSUNDEEP
log4netlog4net-configurationlog4net-appender
juagicre
juagicre

Reputation: 1074

Log4net logs several times same line since MinimalLock setup

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

Upvotes: 1

Views: 1622

Answers (1)

AgathoSAreS
AgathoSAreS

Reputation: 476

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>

Upvotes: 3

Related Questions