Thursday, 10 August 2017

Introduction

         Logging is one of the very important factor in any application. You require it to analyse what when and how things went wrong. It serves as the log of the application. But when you have multiple instance of the same application running in parallel, then you don’t have the purpose served properly by the logging mechanism as it will be writing all the log entry into the same file and the log will be cluttered. Here in this post we will discuss how to handle this typical situation when you have multiple instances running at the same time and log4net writes all the logs into the same file.

Possible solutions

  1. Let log4net write each log entry with the process id.
  2. We can have log4net write the log in to different file appended by a process id or anything similar.
  3. Log it into a central location with process Id or something similar.
  4. Log everything into same file but append an identifier to each log entry.

     Here we are going to look at a solution which can be called as a combination of 1&2. We will have log4net write to a different file if another instance is running. If not then it will use the same log file. From management perspective it would be nice to have only one file because then we can have a log rotate and keep the file under manageable size. when we have another instance running then it will be logged into a file with the time appended to the file name. This way we can handle logging by second instance. Let us now see how this is achieved using log4net.

Drawback of this solution:

     When you have an application which has high probability of running multiple instances, then you are going to have many log files which will not be rotated or handled by the logging mechanism. So choose this solution if the situation where you have multiple instances running in parallel are rare.

To achieve this we will be using two concepts.

  1. Pattern Converter in log4net
  2. Inter process synchronization technique.

Pattern Converter in log4net

      Log4net has this pattern converter which you can use in the configuration. Here we will make use of it to handle the file name. Let us see how to achieve this. I will not be discussing the complete configuration of log4net and the below shown code is just a snippet from the configuration. This is as shown below.

<appender name="FileAppender" type="log4net.Appender.RollingFileAppender">
    <file type="log4net.Util.PatternString">
      <converter>
        <name value="fileName" />
        <type value="SampleApp.FilePatternConverter,SampleApp" />
      </converter>
      <conversionPattern value="${APPDATA}\LogFolder\%fileName" />
    </file>
</appender>

Here we have defined a converter for the file name. Conversion pattern is the format for the file name. Here "${APPDATA} specifies the system defined application folder and it has nothing to do with the pattern. %fileName is an identifier which redirects to the converter with name as filename. We have defined a converter with name as filename and value as SampleApp.FilePatternConverter,SampleApp. Here SampleApp.FilePatternConverter specifies the namespace and the class name of our converter class and SampleApp is the assembly name where we can find the converter. Now let us see how the converter class looks like. It is as shown below.

namespace SampleApp
{
    using System.IO;

    public class FilePatternConverter: log4net.Util.PatternConverter
    {
        protected override void Convert(TextWriter writer, object state)
        {
            String filename = “logfile.log”;
            var logFileName = LogFileNameConverter.GetLogFileName(filename);
            writer.Write(logFileName);
        }
    }
}

The text writer will then replace the pattern in the configuration. To be precise it will replace %fileName from the conversionPattern with the log file name. Here the core of the logic is in another file and lets have a look at it. It is as shown below.

public class LogFileNameConverter
    {
        private const string FileName = "application.log";
        private static readonly Mutex ApplicationSyncLock;
        private static readonly bool LockAcquired;
        private static string dateToAppend;
        
        static LogFileNameConverter()
        {
            try
            {
// register an application exit event and release the mutex lock.
                Application.Current.Exit += CurrentExit;
                bool created;
                ApplicationSyncLock = new Mutex(false, "ApplicationMutexName", out created);
                LockAcquired = ApplicationSyncLock.WaitOne(2000);
            }
            catch (AbandonedMutexException)
            {
// here will will release the abandoned mutex.
                ApplicationSyncLock.ReleaseMutex();

                //lets acquire the lock.
                LockAcquired = ApplicationSyncLock.WaitOne(2000);
            }
            catch (Exception)
            {
                LockAcquired = false;
            }
        }
 
        public static string GetLogFileName(string logFileName)
        {
            if (string.IsNullOrEmpty(logFileName))
            {
                logFileName = FileName;
            }
 
            if (LockAcquired)
            {   
                return logFileName;
            }
            else
            {
                var extension = Path.GetExtension(logFileName);
                var fileName = Path.GetFileNameWithoutExtension(logFileName);
                if (string.IsNullOrEmpty(dateToAppend))
                {
                    Regex rgx = new Regex("[^a-zA-Z0-9]");
                    dateToAppend = rgx.Replace(DateTime.Now.ToString(CultureInfo.InvariantCulture), "-");
                }
 
                fileName = (fileName + "-instance-at-" + dateToAppend + extension).Replace(' ', '-');
                return fileName;
            }
        }
 
        private static void CurrentExit(object sender, ExitEventArgs e)
        {
            ApplicationSyncLock.ReleaseMutex();
        }
    }


Here we use named Mutex as an inter-process synchronization or signalling. We acquire a mutex lock and keep it locked till the application exits. The new instance will not be able to acquire a lock and will move ahead and create a new logfile name with datetime append to the filename. Here we chose Mutex because it has a mechanism where we can handle the abandoned Mutex which results from an application which had the lock got terminated from task manager. When a new instance of application is launched we can handle this abandoned mutex.

This is all you need and when you run multiple instance, it will start to write to a different file. If you are running it in serial then you have all the log in one file and log rotate will make sure that you have only one file with the specified size.

Now if you like to pass the log file name from the configuration itself, then also it is possible. Let’s see how this is achieved. The converter should have property attribute defined and this will be available in the converter. Let’s see how this looks like. This is as shown below.

<appender name="FileAppender" type="log4net.Appender.RollingFileAppender">
      <file type="log4net.Util.PatternString">
        <converter>
          <name value="fileName">
          <type value="SampleApp.FilePatternConverter,SampleApp">
          <property>
            <key value="FileName">
            <value value="app.log">
            </value></key>
</property></type></name></converter>
        <conversionpattern value="${APPDATA}\LogFolder\%fileName">
      </conversionpattern></file>
</appender>

Here we have defied a property with key as “FileName” and value as “app.log”. This will be available in the converter class as shown below.

protected override void Convert(TextWriter writer, object state)
{
            string fileName = this.Properties["FileName"] as string;
            var logFileName = LogFileNameConverter.GetLogFileName(fileName);
            writer.Write(logFileName);
}


4.Log everything into same file but append an identifier to each log entry

Now that we have seen this solution, let us see how "Log everything into same file but append an identifier to each log entry" can be achieved. For simplicity I am using the exact same converter.
We can achieve this by modifying the layout of log by using the below mentioned configuration.

<layout type="log4net.Layout.PatternLayout">
<converter>
       <name value="fileName">
       <type value="SampleApp.FilePatternConverter,SampleApp">
       <property>
         <key value="FileName">
         <value value="app.log">
       </value></key></property>
    </type></name></converter>
    <param name="ConversionPattern" value="%fileName %d [%t] %-5p [%C %F %L] - %m%n" />
</layout>
    

Monday, 8 May 2017

Introduction:


   A recent encounter in windows server where a need for a folder alias was unavoidable, we made a discovery that unlike linux, folder alias is hard to achieve in windows command for windows version less than windows 10. Though it is achievable, it is hard to achieve when the target directory path is dynamic. This lead to a search for the alternative to deploy in this scenario. The scenario was when we have to use the editbin.exe and its LARGEADDRESSAWARE where we discovered that LARGEADDRESSAWARE take only a particular character length for the input file and if there are more then it will trim it. This was leading to an error:

The alternative was to CD into the folder and execute the command and get out of the folder. And we have something called as setlocal which help us achieve this by scoping the step in and out of a folder. Setlocal will help us scope the working directory and reverts the working directory when the scope is over. The below snippet shows how we can achieve this. I was using this in VisualStudio postbuild event.

setlocal
cd
cd $(TargetDir)
cd
IF EXIST C:\masm32\bin\editbin.exe (
  C:\masm32\bin\editbin.exe /LARGEADDRESSAWARE $(TargetFileName)
) 
endlocal