Log4net sometimes creating two logs, one empty

Question

Using the below configuration, about half of the time, I'm getting two logs per one, one empty. They differ in filename by one second (log.2015-03-09_11-50-25 vs log.2015-03-09_11-50-26)

I'm trying to have one log per run of the console application.

<log4net>

  <appender name="Log" type="log4net.Appender.FileAppender">
    <file type="log4net.Util.PatternString" value="C:\env\QA\Logs\consoleapp\log.%date{yyyy-MM-dd_HH-mm-ss}.txt"/>
    <appendToFile value="true"/>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date    %message%newline"/>
    </layout>
  </appender>

  <root>
    <level value="INFO"/>
    <appender-ref ref="Log"/>
  </root>
</log4net>

The latter log is the only one that's populated/written to.

Why is this happening? How do I fix it?

EDIT: Turns out i was instantiating a second logger in my code. When the instantiation occurred during a different second, a second log was created. The appender was working correctly.

your approch may be suboptimal. Try using username/pid/something else beeing unique to a time period small enough for your logs as "primary key" of you log-file-naming — swe, Mar 09 '15 at 16:05
@swe timestamp is good for logfile names - allows easily readable filenames and places them in context. — user1666620, Mar 09 '15 at 16:08
Turns out i was instantiating a second logger in my code. When the instantiation occurred during a different second, a second log was created. The appender was working correctly. — b15, Mar 09 '15 at 16:58

score 3 · Answer 1 · edited May 23 '17 at 11:46

I've seen something similar before - it's due to the second being specified in the filename, and the writes are occuring during the end of one second and the start of another.

<file type="log4net.Util.PatternString" value="C:\env\QA\Logs\consoleapp\log.%date{yyyy-MM-dd_HH-mm-ss}.txt"/>

should be

<file type="log4net.Util.PatternString" value="C:\env\QA\Logs\consoleapp\log.%date{yyyy-MM-dd}.txt"/>

In my last job, somebody set the second specifier in the log file name, and the production server came close to crashing trying the render the 150,000 files contained in the log folder.

Edit:

If you want to write once per run, you can add the following to your log4net configuration:

<rollingStyle value="Once" />

and you might need to set the appendToFile attribute to be false.

log4net one file per run

so your config would look like this:

<appender name="Log" type="log4net.Appender.FileAppender">
    <file type="log4net.Util.PatternString" value="C:\env\QA\Logs\consoleapp\log.%date{yyyy-MM-dd_HH-mm-ss}.txt"/>
    <appendToFile value="false" />    
    <maxSizeRollBackups value="-1" /> <!--infinite-->
    <rollingStyle value="Once" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date    %message%newline"/>
    </layout>
  </appender>

I don't want to overwrite or append to the previous log. I want a separate file for each run. Your suggestion causes the log to be appended to if it falls in the same day. — b15, Mar 09 '15 at 16:07
Same problem as my original post, but noticed when the second file is in the same second, it still creates two, one with a ".1" appended to the filename — b15, Mar 09 '15 at 16:18

score 1 · Answer 2 · answered Nov 11 '15 at 00:27

I used user1666620's solution, but still got a .log.1 file. Turns out I had the following line in my AssemblyInfo.cs file:

[assembly: log4net.Config.XmlConfigurator(Watch = true)]

Removing the above line fixed my issue. By the way, my program.cs looks like:

public static class Program
{
    static Program()
    {
        // Initialize logging
        log4net.Config.XmlConfigurator.Configure();
    }

    private static readonly ILog log =
        LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

    ...
}

Log4net sometimes creating two logs, one empty

2 Answers2