Why am I getting two log files per day using log4net with ASMX web service?

Question

I have a ASMX web service running IIS 10 and have added log4net to the project with the following configuration:

<appender name="AsmxDebugLogFile" type="log4net.Appender.RollingFileAppender">
  <file value="App_Data/ASMX.DEBUG_" type="log4net.Util.PatternString" />
  <appendToFile value="true" />
  <rollingStyle value="Composite" />
  <datePattern value="yyyy-MM-dd'.log'" />
  <maximumFileSize value="5GB" />
  <staticLogFileName value="false" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
  </layout>
</appender>
<logger name="AsmxDebugLogFile">
  <level value="DEBUG" />
  <appender-ref ref="AsmxDebugLogFile" />
</logger>

But for some reason, I'm getting two log files per day in the format of yyyy-MM-dd.log.yyyy-MM-dd.log as per the screenshot below, seemingly at random times as well, whereby the log file will switch to the newly created log file, and then will start logging again in the log file at was created at midnight of the day in question. All log files are way below the 5GB max file size as well.

Below is an updated list of log files

It seems that initially, log4net logs to the file yyyy-MM-dd.log, and then after a random amount of time creates a new log file yyyy-MM-dd.log.yyyy-MM-dd.log starts writing to this log file and then goes back and logs to yyyy-MM-dd.log which was created at the start of the day.

These are the IIS recycle settings

I am wanting 1 log file per day in the format of ASMX.DEBUG_yyyy-MM-dd.log. Where am I going wrong with this configuration?

UPDATE

It seems that because we are recycling the application pool every 60 minutes depending on whether the log file is being written to at this time, depends on whether a new one is created. Any suggestions as to how to overcome this issue. At the minute I've now added the process_id in the log file name and it seems to work in that I get a new log file created every hour, but ideally I want just 1 log file a day.

Maybe look at file info (ownership?) of the two different file name formats to see if they are being created by the same user. — GaTechThomas, Apr 29 '21 at 16:38
@GaTechThomas -- no, OP [has it correct](https://logging.apache.org/log4net/release/manual/configuration.html). — Andy, Apr 29 '21 at 17:00
My guess would be that you are running this on IIS and that the App Pool is recycled after 20 minutes of inactivty. To disprove this you could check if the behaviour changes if you change the IIS Idle Time-out to 0. — ZiggZagg, Apr 29 '21 at 20:06
Can you also show how do the files for the 28.4 and 29.4 currently look? If you can, watch what happens at 00:00 30.4. — OfirD, Apr 29 '21 at 20:08
@ZiggZagg Yes, it is a ASMX web service (using same Application Pool) which is recycled every 60 minutes. I will add recycle settings to the question. — neildt, Apr 29 '21 at 20:09
If the AppPool is restarted then the file names shouldn't change in such a way, and the created/modified times would not overlap. — GaTechThomas, Apr 29 '21 at 23:01
Do two web apps run on the same machine with similar configs? — GaTechThomas, Apr 29 '21 at 23:04
As a troubleshooting step, try temporarily disabling overlapped recycle and see if you still get two files. — John Wu, Apr 30 '21 at 02:20
@JohnWu I can't really change this setting as it will result in the service being unavailable whilst the application pool is recycled. — neildt, Apr 30 '21 at 07:51
Can you also post your nuget package config? since i just tried your config locally and all works as expected :( — Vova Bilyachat, Apr 30 '21 at 08:40
This honestly looks like a bug in Log4Net. I would change `staticLogFileName` to `true` and run it that way for a couple days and see what happens. — Andy, Apr 30 '21 at 15:15
you should not recycle application pool every hour. what happens to a process which is already running. This can cause issues when using in-memory sessions.Stay with default . Any way I did not downvote your uestion. — Jin Thakur, May 04 '21 at 17:16

score 2 · Accepted Answer · answered May 04 '21 at 09:03

I use log4net for all my applications and I never encountered this re-creation of file after a pool recycling.

Here are my parameter that differ from yours :

<appendToFile value="true"/>
<staticLogFileName value="true" />
<lockingModel type="log4net.Appender.FileAppender+MinimalLock"/>

And here's how the behaviour will be different :

staticLogFileName means current day's file name will always be the same (ASMX.DEBUG_.log here). It will be automatically renamed with the date pattern on the day after.
appendToFile means it will not overwrite current day's file, but rather append to it.

I think those first two parameters will avoid the creation of multiple file for the current day which may fix your problem.

MinimalLock's role is less clear to me, but I should mention it anyway :

Opens the file once for each AcquireLock()/ReleaseLock() cycle, thus holding the lock for the minimal amount of time. This method of locking is considerably slower than FileAppender. ExclusiveLock but allows other processes to move/delete the log file whilst logging continues.

score 1 · Answer 2 · answered Apr 30 '21 at 17:22

1

<appender name="AsmxDebugLogFile" type="log4net.Appender.RollingFileAppender">
  <lockingModel type="log4net.Appender.FileAppender+MinimalLock"/>

I think you need Locking model which will not lock your file.I think when main file gets created and get locked. The File appender creates file name with same date time stamp over the exisiting file. You should also use Remote path for logging like \\server\file\debug since you might have load balancer for IIS or Web server is hosted with static IP or F5.

answered Apr 30 '21 at 17:22

Jin Thakur

2,711
18
15

1

Wow, I've been using log4net for years and never realized I could change the locking model. Regardless of whether this fixes the OP's problem, this is a useful answer! – John Wu Apr 30 '21 at 17:40
I've updated my question, but the issue is to do with IIS application pool being recycled every 60 minutes. – neildt May 04 '21 at 07:38
Yes APP pool recycle can cause a new file. check this link for adding new process id https://stackoverflow.com/questions/2075603/log4net-process-id-information. adding processid will create same file pattern – Jin Thakur May 04 '21 at 17:24

score 0 · Answer 3 · edited Apr 30 '21 at 06:51

0

Try with this parameters.

  <param name="File" value="C:\YourLogFilePath\" />
  <rollingStyle value="Composite" />
  <param name="DatePattern" value="dd.MM.yyyy'.log'" />
  <param name="AppendToFile" value="true" />
  <maxSizeRollBackups value="2" />
  <maximumFileSize value="5GB" />
  <staticLogFileName value="false" />
  <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />

edited Apr 30 '21 at 06:51

Sebastian

1,569
1
17
20

answered Apr 29 '21 at 20:41

Muhammed Ahsan

26
6

3

and why would this work for OP? Code-only answers help no one. – Andy Apr 29 '21 at 21:01
because of param file name and value, I haven't specified the file name to append I just define the path of the log file and it worked. – Muhammed Ahsan Apr 29 '21 at 21:10

score 0 · Answer 4 · answered May 04 '21 at 01:48

0

You are using the "RollingFileAppender" which as its name suggests rolls to a new file on dates, try using the FileAppender, more information about how to use FileAppender you can refer to this link: FileAppender.

answered May 04 '21 at 01:48

samwu

3,857
3
11
25

I am wanting 1 log file per day in the format of ASMX.DEBUG_yyyy-MM-dd.log, using `FileAppender` creates just 1 log file in its entirety. – neildt May 04 '21 at 07:37

Why am I getting two log files per day using log4net with ASMX web service?

4 Answers4