I believe that this is caused by a design issue with the RollingFileAppender. Basically the rolling file appender does not expect to operate in a shared mode where multiple processes are using the same output file via the FileAppender's MinimalLock.
Each RollingFileAppender believes that it is operating in isolation when it comes to rolling the log file. When several RollingFileAppenders are writing to the same file things can become quite messy at the point they decide to roll over. Each RollingFileAppender will decide to do that at a different time. If the file is rolled by size then each appender holds the starting size (when it thinks it opened the file) and the number of bytes written. When the total goes over the threshold the file is rolled. This byte count does not take into account any bytes written by other processes. If the file is rolled by date then each appender will decide to roll the file when a message is logged in a new date window. If the appender is configured to use a static log file name then when the appender rolls the file it will move the current file over the top of the date window file. If this has already been done before it will overwrite the existing one. If the appender is not configured to use a static log file name then it will truncate the new file and begin writing to it, events written to the log file before the last appender rolled over will be lost. There is a performance penalty using the MinimalLock because the file is opened and closed for each log event. If there are multiple processes using the same file then there is a single bottleneck for those processes. Perhaps we need to look at a different architecture for the FileAppender and the RollingFileAppender - preferably one that is less complex and more maintainable than the current implementation. For example; each process should write to a separate file, locked exclusively. Every so often the file should be closed and renamed. Another system (maybe within log4net) should then be responsible for coordinating the log file and maybe for triggering the FileAppender to rename the file. I think that for a distributed / multiprocess system a single shared log file is often not suitable, especially if you want to try to get the events into a logical order. Using a database, or some other form of centralised service to aggregate the logging from the separate processes may be a better solution. We need to investigate and document best practice in this area. Cheers, Nicko PS. This might not be the most useful mail ever, but I wanted to make sure that I brain dump something before it escapes by brain. > -----Original Message----- > From: Joanna Power [mailto:[EMAIL PROTECTED] > Sent: 29 September 2006 00:51 > To: log4net-user@logging.apache.org > Subject: race condition using RollingFileAppender with > multiple processes? > > Hi. > > I apologize in advance if I have missed the answer to this > question in my searches on the log4net website and the > internet in general. > > I am using log4net 1.2.9 to generate logs on an ASP.NET > <http://asp.net/> web client application. This app is > running on IIS with 20 processes. I am seeing what I believe > is a race condition when the logs roll over at the hour mark. > I can see the new log appear shortly after the hour turns > over, and I can see log entries appearing in the new log > file. Then, whoosh, all the entries disappear and new > entries start appearing. This happens some number of times > over the first minutes of the new hour, and then the new log > file stabilizes. It seems that each process is taking > responsibility for opening the new file when it detects that > the hour has changed, even if the new file already exists. > Once the file stabilizes, entries from all processes are appearing. > > Here is my appender configuration: > > <!-- Define rolling, timestamped file output appender. --> > <appender name="LogFileAppender" > type="log4net.Appender.RollingFileAppender"> > > <file value="log/service.log" /> > > <!-- Do not overwrite existing files. --> > <appendToFile value="true" /> > > <!-- Create new log files with timestamped name. --> > <StaticLogFileName value="false" /> > > <!-- Allow multiple processes to write to the same file. --> > <lockingModel > type="log4net.Appender.FileAppender+MinimalLock " /> > > <!-- Roll the log every hour --> > <rollingStyle value="Date" /> > <datePattern value=".yyyyMMdd-HH" /> > > <layout type=" log4net.Layout.PatternLayout"> > <conversionPattern value="%date [%thread] > %-5level %logger [%property{NDC}] - %message%newline" /> > </layout> > </appender> > > I haven't tried to enable error tracing since the problem is > hard to duplicate on low traffic systems, and I don't really > want to enable error tracing on our production systems. This > happens with StaticLogFileName set to "true" or "false." > I've considered turning on the ImmediateFlush option to > minimize the number of lost entries, but I don't really want > to take the performance hit and at low traffic times, we > could still end up losing a lot of data. > > My questions: > 1. Am I doing something obviously wrong or stupid? > 2. Is this a known issue? > 3. If this is a bug in log4net, is it fixed in 1.2.10? > 4. If this is a bug and it is not fixed in 1.2.10, is there a > workaround? > > Thanks in advance for any help. I'm losing hair and sleep over this. > > -JP >
