Intermittent log4net RollingFileAppender locked file issue

Question

We are seeing an intermittent issue on development and production machines whereby our log files are not getting logged to.

When running in development and debugging using Visual Studio we get the following log4net error messages in the VS output window:

log4net:ERROR [RollingFileAppender] Unable to acquire lock on file C:\folder\file.log.

The process cannot access the file 'C:\folder\file.log' because it is being used by another process.

log4net:ERROR XmlConfigurator: Failed to find configuration section 'log4net' in the application's .config file.
Check your .config file for the <log4net> and <configSections> elements.

The configuration section should look like:

<section
  name="log4net"
  type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />

Our current workaround for the issue is to rename the last log file. We would of course expect this to fail (due to the aforementioned file lock), but it normally doesn't. Once or twice the rename has failed due to a lock from the aspnet_wp.exe process.

Our log4net configuration section is shown below:

<log4net>
  <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="C:\folder\file.log"/>
    <appendToFile value="true" />
    <datePattern value="yyyyMMdd" />
    <rollingStyle value="Date" />
    <maximumFileSize value="10MB" />
    <maxSizeRollBackups value="100" />
    <layout type="log4net.Layout.PatternLayout">
      <header value="[Header]&#xA;"/>
      <footer value="[Footer]&#xA;"/>
      <conversionPattern value="%date %-5level %logger ${COMPUTERNAME} %property{UserHostAddress} [%property{SessionID}] - %message%newline"/>
    </layout>
  </appender>
  <root>
    <level value="INFO"/>
    <appender-ref ref="RollingLogFileAppender"/>
  </root>
</log4net>

As mentioned, we are seeing this intermittently on machines, but once the issue happens it persists.

Leanaleanard

Answer 1

Try adding

<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />

to your <appender /> element. There is some performance impact because this means that log4net will lock the file, write to it, and unlock it for each write operation (as opposed to the default behavior, which acquires and holds onto the lock for a long time).

One implication of the default behavior is that if you're using it under a Web site that is being executed under multiple worker processes running on the same machine, each one will try to acquire and hold onto that lock indefinitely, and two of them are just going to lose. Changing the locking model to the minimal lock works around this issue.

(When debugging, ungraceful terminations and spinning up lots of new worker processes is exactly the type of thing that's likely to happen.)

Good luck!

Retain

Saved me a lot of head scratching as to why my logger was working intermittently. I added worker processes to the app pool, duh! – Gurgitation

I am using this in a service and in addition to this change, the user the service ran as needed permission to write as well. Thanks! – Skat

I'd just want to read the file, but log4net locks for reading as well... it could lock just for writing and share reading – Quenby

Answer 2

Also be aware of the log4net FAQ:

How do I get multiple process to log to the same file?

Before you even start trying any of the alternatives provided, ask yourself whether you really need to have multiple processes log to the same file, then don't do it ;-).

FileAppender offers pluggable locking models for this usecase but all existing implementations have issues and drawbacks.

By default the FileAppender holds an exclusive write lock on the log file while it is logging. This prevents other processes from writing to the file. This model is known to break down with (at least on some versions of) Mono on Linux and log files may get corrupted as soon as another process tries to access the log file.

MinimalLock only acquires the write lock while a log is being written. This allows multiple processes to interleave writes to the same file, albeit with a considerable loss in performance.

InterProcessLock doesn't lock the file at all but synchronizes using a system wide Mutex. This will only work if all processes cooperate (and use the same locking model). The acquisition and release of a Mutex for every log entry to be written will result in a loss of performance, but the Mutex is preferable to the use of MinimalLock.

If you use RollingFileAppender things become even worse as several process may try to start rolling the log file concurrently. RollingFileAppender completely ignores the locking model when rolling files, rolling files is simply not compatible with this scenario.

A better alternative is to have your processes log to RemotingAppenders. Using the RemoteLoggingServerPlugin (or IRemoteLoggingSink) a process can receive all the events and log them to a single log file. One of the examples shows how to use the RemoteLoggingServerPlugin.

Kight

Answer 3

If you have

<staticLogFileName value="true" />
<rollingStyle value="Date" />
<datePattern value="yyyyMMdd" />

and add

<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />

then there will be an error while the rolling happens. The first process will create the new file and the rename the current file. Then next proces will do the same and take the newly created file and overwrite the newly renamed file. Resulting in the logfiel for the last day being empty.

Stull

This is true only when multiple processes are accessing the same rolling file. It is safe within the same process. hectorcorrea.com/blog/log4net-thread-safe-but-not-process-safe – Bonfire

@MikeChamberlain According to the OP (See his comment to answer) there will be multiple workers working simultaneously, using log4net to log. Therefore this issue is pertinent! – Elviaelvie