Log4Net: When is the file handle acquired and released?

Question

I am a Log4Net newbie and trying to get a basic/safe understanding of how it works. If I configure my Logger to a FileAppender, and I have multiple statements like below, one after the other:

this.GetLogger().Info("...");
this.GetLogger().Error("....");

Does each call actually open the file, write string and closes it? Every time? Or is there anything else that goes on? I want to know when the file resource is in use. How does it work?

Answer 1

The docs:

This appender will first try to open the file for writing when ActivateOptions is called. This will typically be during configuration. If the file cannot be opened for writing the appender will attempt to open the file again each time a message is logged to the appender. If the file cannot be opened for writing when a message is logged then the message will be discarded by this appender.

In other words: it will try to open the file as early as possible so no extra overhead occurs whenever you're trying to log. If that fails, it will attempt to open the file every time you try to log anything.

You can easily check how logging behaves in your specific instance - whenever the file is opened, the layout's Header value will be written to the file, whenever it's closed the layout's Footer value will be written.

Note, however, that this is the default behavior. FileAppender uses the FileAppender.ExclusiveLock locking model by default. Another option is the FileAppender.MinimalLock locking model, which tries to acquire the lock before each logging operation and releasing it afterwards. You can configure your appender as follows to use it.

<appender name="FileAppender" type="log4net.Appender.FileAppender">
    <file value="${TMP}\log-file.txt" />
    <appendToFile value="true" />
    <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
    </layout>
</appender>

Acquiring the lock on each and every logging operation is obviously more time-consuming than the default "acquire once, release once" model. There are valid reasons for doing so, though - for example if the logfile needs to be rotated during excecution of a long-running application.