logging-log4net-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Steve Wranovsky" <wranov...@gmail.com>
Subject Re: Log File Naming Problem
Date Tue, 22 Jan 2008 23:06:35 GMT
Ron,

On your suggestion, I went ahead and created a new MutexLock locking
model within the FileAppender.  I made it so the OpenFile() method
opens the file in a shared write mode, and then I made AcquireLock and
ReleaseLock use a named Mutex (based on the filename), in an effort to
block concurrent writes to the log file across the app domains.  I
took a small section of code from NLog for naming the Mutex, so its
based on the complete path of the log file name.

With these changes, I discovered one hole, the logging mechanism does
not seek to the end of the file each time it writes.  Since I am
keeping the file open in each process, there may be other writes to
the file when I don't have the lock.  Because of this, in
LockingStream.AcquireLock(), I added some simple code to seek to the
end of the file, after a lock is acquired on the file like this:

                        if (m_realStream.CanSeek)
                            m_realStream.Seek(0, SeekOrigin.End);

So, after these changes, it appears that my problem is resolved, I can
now log from multiple app domains, without any conflicts.  Just as an
FYI, I had one other issue when testing the code:  In some cases,
after the stream is locked, the code actually closes the file before
releasing the lock.  I guess I'm up in the air, but it seems like you
might want to release the lock, then close the file.

In any case, below is the code I wrote.  Feel free to use it if you want.

Steve


        public class MutexLock : LockingModelBase, IDisposable
        {
            private string m_filename;
            private bool m_append;
            private bool m_mutexLocked = false;
            private Stream m_stream = null;
            private Mutex m_mutex;

            private static string GetMutexName(string fileName)
            {
                string canonicalName = ConvertToFullPath(fileName).ToLower();

                canonicalName = canonicalName.Replace('\\', '_');
                canonicalName = canonicalName.Replace('/', '_');
                canonicalName = canonicalName.Replace(':', '_');

                return "filelock-mutex-" + canonicalName;
            }

            /// <summary>
            /// Prepares to open the file when the first message is logged.
            /// </summary>
            /// <param name="filename">The filename to use</param>
            /// <param name="append">Whether to append to the file, or
overwrite</param>
            /// <param name="encoding">The encoding to use</param>
            /// <remarks>
            /// <para>
            /// Open the file specified and prepare for logging.
            /// No writes will be made until <see cref="AcquireLock"/>
is called.
            /// Must be called before any calls to <see cref="AcquireLock"/>,
            /// <see cref="ReleaseLock"/> and <see cref="CloseFile"/>.
            /// </para>
            /// </remarks>
            public override void OpenFile(string filename, bool
append, Encoding encoding)
            {
                m_filename = filename;
                m_append = append;

                if (m_stream == null)
                {
                    try
                    {
                        using
(CurrentAppender.SecurityContext.Impersonate(this))
                        {
                            // Ensure that the directory structure exists
                            string directoryFullName =
Path.GetDirectoryName(m_filename);

                            // Only create the directory if it does not exist
                            // doing this check here resolves some
permissions failures
                            if (!Directory.Exists(directoryFullName))
                            {
                                Directory.CreateDirectory(directoryFullName);
                            }

                            FileMode fileOpenMode = append ?
FileMode.Append : FileMode.Create;
                            m_stream = new FileStream(filename,
fileOpenMode, FileAccess.Write, FileShare.ReadWrite);

                            m_append = true;
                        }
                    }
                    catch (Exception e1)
                    {
                        CurrentAppender.ErrorHandler.Error("Unable to
open file " + m_filename + ". " + e1.Message);
                        if (m_stream != null)
                        {
                            m_stream.Close();
                            m_stream = null;
                        }
                    }
                }
            }

            /// <summary>
            /// Close the file
            /// </summary>
            /// <remarks>
            /// <para>
            /// Close the file. No further writes will be made.
            /// </para>
            /// </remarks>
            public override void CloseFile()
            {
                using (CurrentAppender.SecurityContext.Impersonate(this))
                {
                    if (m_stream != null)
                        m_stream.Close();
                    m_stream = null;
                }
            }

            /// <summary>
            /// Acquire the lock on the file
            /// </summary>
            /// <returns>A stream that is ready to be written to.</returns>
            /// <remarks>
            /// <para>
            /// Acquire the lock on the file in preparation for writing to it.
            /// Return a stream pointing to the file. <see cref="ReleaseLock"/>
            /// must be called to release the lock on the output file.
            /// </para>
            /// </remarks>
            public override Stream AcquireLock()
            {
                if (m_mutex == null)
                {
                    m_mutex = new Mutex(false, GetMutexName(m_filename));
                    m_mutexLocked = false;
                }

                if (m_stream == null)
                {
                    OpenFile(m_filename, m_append, Encoding.Default);

                    if (m_stream == null) return null;
                }

                m_mutex.WaitOne();
                m_mutexLocked = true;
                return m_stream;
            }

            /// <summary>
            /// Release the lock on the file
            /// </summary>
            /// <remarks>
            /// <para>
            /// Release the lock on the file. No further writes will
be made to the
            /// stream until <see cref="AcquireLock"/> is called again.
            /// </para>
            /// </remarks>
            public override void ReleaseLock()
            {
                if (m_mutex != null)
                {
                    m_mutexLocked = false;
                    m_mutex.ReleaseMutex();
                }
            }

            public void Dispose()
            {
                if (m_mutex != null)
                {
                    if (m_mutexLocked)
                        m_mutex.ReleaseMutex();
                    m_mutex.Close();
                    m_mutex = null;
                }

                if (m_stream != null)
                    m_stream.Close();
                m_stream = null;
            }
        }

On Jan 21, 2008 11:41 AM, Ron Grabowski <rongrabowski@yahoo.com> wrote:
> Maybe instead of the MinimalLock you could write a MutexLock locking model in conjunction
with opening the file in more of a shared mode so each plugin has write permission to the
file but the mutex (either at the locking model level or inside a special MutexFileAppender)
is the gatekeeper for file writes. I think the biggest challenge is the rolling file appender
requirement. Can you configure the host to use a FileAppender that writes to the current day's
log file? I recall nlog has some special ways to deal with multiple processes writing to the
same file. It uses Win32 apis to cooridnate multiple writes. I would imagine this is much
much faster than the MinimalLock model. I've not tried nlog's multiprocess write support in
conjunction with rolling the file.
>
> I've not done a lot with plugins and app domains but I think making the host responsible
for receiving/recording log messages from the plugins seems like a more managable solution.
You don't want a plugin to mess up the log file for the host.
>
> ----- Original Message ----
> From: Steve Wranovsky <wranovsky@gmail.com>
>
> To: Log4NET User <log4net-user@logging.apache.org>
> Sent: Monday, January 21, 2008 11:08:40 AM
> Subject: Re: Log File Naming Problem
>
>
> First, concerning our use of multiple App domains, we've implemented a
> plugin based Windows service that has several independently running
> plugin threads running.  We've decided to use an App domain per plugin
> thread so that if there is a problem with one of the plugins/threads,
> it doesn't bring down the other threads within the service.
>
> I took a look at the blog post, and our code is similar to what is
> described in that post.  We are initializing log4net in each app
> domain.  We potentially have a very large amount of logs being
> generated overall in our system.  I'd prefer to avoid having to save
> the data in a database, so routing the logs to a single
> RollingFileAppender seems to be the best solution.  It sounds like
> this would also be an added benefit from a performance standpoint if
> we were able to use the ExclusiveLock locking model.
>
> Thanks for the feedback.  It would be nice if this worked with the
> standard RollingFileAppender, but, this at least points me in a
> direction to find a solution to the problem I am having.
>
> Steve
>
>
> On Jan 20, 2008 1:42 PM, Ron Grabowski <rongrabowski@yahoo.com> wrote:
> > When a new app domain is created is log4net re-initialized in the new
>  app domain?
> >
> > It sounds like the problem is that you have a lot of threads trying
>  to open, close, and roll the log file. Can you delegate all the locking
>  issues to a database then extract data out at a later date?
> >
> > If using a database isn't an option I suggest trying to route all the
>  messages to a single RollingFileAppender instance configured to use
>  the default ExclusiveLock locking model (MinimalLock is noticeably slower
>  even for a small amount of logs). A comment from this blog:
> >
> >
>   http://www.jasonbock.net/JB/Default.aspx?blog=entry.f48ab22438bc4e35969ca6c559763e9c
> >
> > mentions using Remoting to channel all the messages from the threads
>  to a single RollingFileAppender so there is a single thread and class
>  controlling rolling. You coculd use the IpcChannel for inter-process
>  communications. Is your code similiar to the sample code in the blog post?
> >
> > If you don't mind me asking, what is the use case for having to
>  create new app domains in addition to the new threads?
> >
> >
> >  ----- Original Message ----
> > From: Steve Wranovsky <wranovsky@gmail.com>
> > To: log4net-user@logging.apache.org
> > Sent: Thursday, January 17, 2008 11:10:29 AM
> > Subject: Log File Naming Problem
> >
> >
> > Hello,
> >
> > I have a multi-threaded application using log4net 1.2.10 for logging.
> > There are a couple of points when the application runs where there
>  are
> > a large number of logs occurring simultaneously from multiple threads
> > (that happen to be in different App Domains).  On occasion, I will
>  end
> > up with two separate log files generated when this point in my
> > application occurs.  One of the log files will end up with a date
> > pattern twice in the name and will look something like this:
> >
> > Server_2008-01-16.log
> > Server_2008-01-16.log2008-01-16.log
> >
> > A few of the logs end up in the second log file from one of the
> > threads.  The remainder of the threads log to the first log file and
> > continue using it.  Occasionally this second log file will be used
> > again by another thread if the problem happens again.  Here's the
> > configuration file I'm using:
> >
> > <log4net>
> >                 <appender name="RollingLogFileAppender"
> > type="log4net.Appender.RollingFileAppender">
> >                                 <param name="File"
> >  value=".\\logs\\Server_" />
> >                                 <param name="AppendToFile"
>  value="true"
> >  />
> >                                 <param name="MaxSizeRollBackups"
> >  value="20" />
> >                                 <param name="MaximumFileSize"
> >  value="10MB" />
> >                                 <param name="RollingStyle"
> >  value="Composite" />
> >                                 <param name="datePattern"
> > value="yyyy-MM-dd.lo\g" />
> >                                 <param name="StaticLogFileName"
> >  value="false" />
> >                                 <layout
> >  type="log4net.Layout.PatternLayout">
> >                                                 <param
> > name="ConversionPattern" value="%d [%t] %-5p - %m%n" />
> >                                 </layout>
> >                                 <lockingModel
> > type="log4net.Appender.FileAppender+MinimalLock" />
> >                 </appender>
> >                 <root>
> >                                 <level value="INFO" />
> >                                 <appender-ref
> >  ref="RollingLogFileAppender" />
> >                 </root>
> > </log4net>
> >
> > It appears that perhaps a lock is failing in one of the threads, and
> > it by default tries to create another log file to log to.  Is it
> > possible to block this from happening and have the logs go into the
> > original log file?  If this is not possible, it would be nice if the
> > second log file didn't have the double date in it, or if the handling
> > of this was cleaner.
> >
> > Thanks,
> > Steve
> >
> >
> >
> >
>
>
>
>

Mime
View raw message