Use log4net filter to dispatch email notification based on string match

  • filter type set to log4net.Filter.StringMatchFilter
  • each filter section can only have one stringToMatch element
  • end with a “log4net.Filter.DenyAllFilter” filter to switch from the default “accept all unless instructed otherwise” filtering behavior to a “deny all unless instructed otherwise” behavior.
<?xml version="1.0" encoding="utf-8"?>
<log4net debug="false">

  <appender name="SmtpAppender_WebTeam" type="log4net.Appender.SmtpAppender">
    <to value="goodguy@me.com" />
    <from value="log4net@me.ca" />
    <subject value="!!!Web Exception happened!!!" />
    <smtpHost value="mail.server.ds" />
    <bufferSize value="512" />
    <lossy value="true" />
    <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="ERROR"/>
    </evaluator>
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%newline%date [%thread] %-5level %logger [%property{NDC}] - %message%newline%newline%newline" />
    </layout>
 	<filter type="log4net.Filter.StringMatchFilter">
		<stringToMatch value="RequestManagement" />
 	</filter>
 	<filter type="log4net.Filter.StringMatchFilter">
		<stringToMatch value="VineOnLine" />
 	</filter>
	<filter type="log4net.Filter.DenyAllFilter" />
  </appender>
  <appender name="SmtpAppender_VSE" type="log4net.Appender.SmtpAppender">
    <to value="nice@me.ca" />
    <from value="log4net@mr.ca" />
    <subject value="!!!VSE Exception happened!!!" />
    <smtpHost value="mail.server.ds" />
    <bufferSize value="512" />
    <lossy value="true" />
    <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="ERROR"/>
    </evaluator>
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%newline%date [%thread] %-5level %logger [%property{NDC}] - %message%newline%newline%newline" />
    </layout>
	<filter type="log4net.Filter.StringMatchFilter">
		<stringToMatch value="VSE" />
	</filter>
    <filter type="log4net.Filter.DenyAllFilter" />
  </appender>

  <root>
    <level value="INFO" />

    <appender-ref ref="SmtpAppender_WebTeam" />
    <appender-ref ref="SmtpAppender_VSE" />

  </root>
  <logger name="NHibernate">
    <level value="ERROR"/>
  </logger>

</log4net>

Advertisements

Using log4net and Ninject auto-binding in FitNesse

FitNesse executes dotnet assembly through (Syterra) runner (for fitSharp), this brought up some path related problems. One problem we faced is log4net configuration, putting log4net.config in assembly path doesn’t work.

From fit content page we can see:


!define COMMAND_PATTERN {%m -a C:\Source\project\TestHelper\App.config -r fitnesse.fitserver.FitServer,dotnet4\fit.dll %p}
!define TEST_RUNNER {dotnet4\Runner.exe}
!path C:\Source\project\TestSuite\bin\Release\TestSuite.dll

!contents
'''Prerequisites:'''

'''Test Case:'''

The only config file runner can take is the one from test helper, putting log4net in runner’s path might work, but it will introduce maintenance headache. The cleaner way to configure log4net might be to do it through code, idea from this post.

 public static class SimpleLogger
    {
        static SimpleLogger()
        {
            ConfigureLog();
        }
        public static ILog For(object objectToLog)
        {
            return For(objectToLog.GetType());
        }
        public static ILog For(Type typeToLog)
        {
            return LogManager.GetLogger(typeToLog);
        }

        private static void ConfigureLog()
        {
            Logger root;
            root = ((Hierarchy)LogManager.GetRepository()).Root;

            root.AddAppender(GetFileAppender());
            root.Repository.Configured = true;
        }

        private static FileAppender GetFileAppender()
        {
            FileAppender lAppender = new FileAppender();
            lAppender.Name = "File";
            lAppender.AppendToFile = true;
            lAppender.File = @"c:\tmp\log.txt";
            lAppender.Layout = new
            log4net.Layout.PatternLayout("%date{dd-MM-yyyy HH:mm:ss,fff} %5level [%2thread] %message (%logger{1}:%line)%n");
            lAppender.Threshold = log4net.Core.Level.All;
            lAppender.ActivateOptions();

            return lAppender;
        }
    }

Another problem we got is Ninject convention extension, aka auto-binding. This code works in application but not in fitnesse runner:

 Kernel.Scan(x =>
              {
//                x.FromAssemblyContaining<SampleClass>();  // This works in fitnesse runner, but will be messy if sample classes are too many.
//                string path = Path.GetDirectoryName((new System.Uri(Assembly.GetExecutingAssembly().CodeBase)).AbsolutePath);
//               x.FromAssembliesInPath(path);
//               x.FromAssembliesInPath(".");
                  x.FromAssembliesMatching("*");  // Doesn't work in fitnesse runner
//                  x.AutoLoadModules();  // Don't do it if you have multiple modules defined.
                x.BindWithDefaultConventions();
                x.InTransientScope();
            });

The way Ninject doing auto-binding is to create a temporary appDomain, then try to load it into this temp domain.

 // private static IEnumerable FindAssemblies(IEnumerable filenames,
 // Predicate filter)
 {
 AppDomain temporaryDomain = CreateTemporaryAppDomain();

foreach (string file in filenames)
 {
 Assembly assembly = null;

if (File.Exists(file))
 {
 try
 {
 var name = new AssemblyName { CodeBase = file };
 assembly = temporaryDomain.Load(name);
 // assembly = Assembly.ReflectionOnlyLoadFrom(file); // this works in fitnesse
 }
 catch (.....
 

The construct of AssemblyName by setting file string to CodeBase actually failed in fitnesse environment, this can be proven by checking the AssemblyName.FullName. In this case, it’s empty.
Google search found a different way to construct Assembly simply by calling Assembly.ReflectionOnlyLoadFrom(file);
Our new IoC setup code looks then like this:

        static void Scan()
        {
              Kernel.Scan(x =>
              {
                x.From(get_all_assembly_instances());
                x.BindWithDefaultConventions();
                x.InTransientScope();
            });
        }

        static IEnumerable<Assembly> get_all_assembly_instances()
        {
            string path = Path.GetDirectoryName(Path.GetFullPath(new System.Uri(Assembly.GetExecutingAssembly().CodeBase)).AbsolutePath));
            IEnumerable<string> assemblies = Directory.GetFiles(path).Where(IsAssemblyFile);

            IEnumerable<AssemblyName> assemblyNames = FindAssemblies(assemblies, y=>true);
            return assemblyNames.Select(name => Assembly.Load(name));
        }
// IsAssemblyFile, FindAssemblies can be copied from https://github.com/ninject/ninject.extensions.conventions/blob/master/src/Ninject.Extensions.Conventions/AssemblyScanner.cs
// While FindAssemblies needs to tweet to use  Assembly.ReflectionOnlyLoadFrom(file); to get Assembly instance.
        private static IEnumerable<AssemblyName> FindAssemblies(IEnumerable<string> filenames,
                                                                 Predicate<Assembly> filter)
        {
            return
                filenames.Select(Assembly.ReflectionOnlyLoadFrom).Where(assembly => filter(assembly)).
                    Select(assembly => assembly.GetName());
        }

log4r and Gateway pattern

Finally, I’m tired of adding and removing puts, pp, print, … etc in my ruby code, and decided to go to log4r.

With log4net experience, it makes sense to apply the same gateway pattern in log4r, so my usage of log4r syntax should look like:

Logger.for(self).debug(msg)

Here is my code:

require 'log4r'
include Log4r

class MyLogger

  def self.for(obj)
    Logger[obj.class.name] || self.create_logger_for(obj.class.name)
  end

  private

  def self.create_logger_for(key)
    mylog =  Logger.new(key)

    mylog.level = $DEBUG ? DEBUG : INFO

    mylog.add Outputter.stdout

    file_format = PatternFormatter.new(:pattern => "[ %d ] %l\t %C %m")
    mylog.add FileOutputter.new("fileOutputter_for_#{key}", :filename => "./log/#{key}.log", :formatter=>file_format)
    mylog
  end

end

Calling ruby with -d parm can run in Debug mode, and $DEBUG global variable is the catcher.

Using memory appender to test logger

I found a bug in IglooCoder.Commons, the Logger doesn’t log the correct class. The fix is easy, but I want to create a test before fixing it, in case the next release the problem came back.

How to test the logger without logging at the log files generated? This is the perfect situation we should use memory appender.

  [TestFixture]
    public class LogTests
    {
        private MemoryAppender _appender;
        private LoggingEvent _event;

        [TestFixtureSetUp]
        public void Init()
        {
            Log.Initialize(new AglcLog4NetLogger(SystemInfo.ApplicationBaseDirectory + "\\Log4Net.config"));
            _appender = new MemoryAppender();

            _appender.Name = "Unit Testing Appender";

            _appender.Layout =
                new PatternLayout("%date{dd-MM-yyyy HH:mm:ss,fff} %5level [%2thread] %message (%logger{1}:%line)%n");

            _appender.Threshold = Level.All;

            _appender.ActivateOptions();

            Logger root = ((Hierarchy) LogManager.GetRepository()).Root;

            root.AddAppender(_appender);

            root.Repository.Configured = true;
        }

        [Test]
        public void should_get_the_correct_class_name_to_log()
        {
            _appender.Clear();
            Log.For(this).Info("testing");

            _event = _appender.GetEvents()[0];

            var data = _event.GetLoggingEventData();

            Assert.AreEqual(this.GetType().ToString(), data.LoggerName);
        }
    }

Read the doc before diving, log4net on demand

My boss gave me a task, creating something like log-on-demand feature in our apps.

Spec:

  1. Be able to define a global threshold for all classes to log.
  2. Be able to add some exception classes with threshold override the predefined global one.

As usually, I google, tried, iisreset, re-try… filter, chained, …

It turns out this is a STANDARD out-of-box feature from log4net, and I actually have been used this since day 1, to control the NHibernate logger threshold in our app.

 	  <root>
 	    <level value="INFO" />
 	    <appender-ref ref="AdoNetAppender" />
 	  </root>
 	  <logger name="NHibernate">
 	    <level value="ERROR"/>
 	  </logger>
 	  <logger name="OneProblemClass">
 	    <level value="DEBUG"/>
 	  </logger>

See logger section from official log4net configuration doc.

Internal variables in Log4Net conversation pattern

I couldn’t find those from log4Net official doc, I’ve already used MDC.Set and ThreadContext.Properties to add some app_domain info into log4Net context, later I found those out-of-box variables from a blog post.

expression value
%appdomain the friendly name of the appdomain from which the log entry was made
%date the local datetime when the log entry was made
%exception a formatted form of the exception object in the log entry, if the entry contains an exception; otherwise, this format expression adds nothing to the log entry
%file the file name from which the log entry was made; note that using %file has a significant performance impact and I don’t recommend using it
%identity the user name of the active user logging the entry; this one is less reliable than %username; note that using %identity has a significant performance impact and I don’t recommend using it
%level the severity level of the log entry (DEBUG,INFO, etc)
%line the source code line number from which the log entry was made; slow
%location some rudimentary call stack information, including file name and line number at which the log entry was made; using
%logger the name of the logger making the entry; more on this in a bit
%method the name of the method in which the log entry was made; also slow
%message the log message itself (don’t forget this part!)
%newline the value of Environment.NewLine
%timestamp the milliseconds between the start of the application and the time the log entry was made
%type the full typename of the object from which the log entry was made
%username the Windows identity of user making the log entry; slow
%utcdate the UTC datetime when the log entry was made
%% a percent sign (%)

Notes:

  • Because we are logging at server/service side, the username is always NT AUTHORITY\SYSTEM.
  • The static gateway/adapter hides the actually location/method one level down, right now it shows Error/Debug.
  • There is a built-in HostName in log4Net.MDC which can be used by %X{log4net:HostName} pattern.
<?xml version="1.0" encoding="utf-8"?>
<log4net debug="false">
   <!--
CREATE TABLE [dbo].[Log4Net] (
 [Id] [int] IDENTITY (1, 1) NOT NULL,
 [Date] [datetime] NOT NULL,
 [Thread] [varchar] (255) NOT NULL,
 [Level] [varchar] (50) NOT NULL,
 [Logger] [varchar] (255) NOT NULL,
 [Host] [varchar] (50) NULL,
 [User] [varchar] (50) NULL,
 [AppDomain] [varchar] (50) NULL,
 [Message] [varchar] (4000) NOT NULL,
 [Exception] [varchar] (2000) NULL
)
-->
  <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
    <bufferSize value="1" />
    <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
    <connectionString value="data source=dbtest\test2005;initial catalog=WebDB;integrated security=True;persist security info=True />
    <commandText value="INSERT INTO [dbo].[Log4Net] ([Date],[Thread],[Level],[Logger],[Message],[Exception],[AppDomain],[User], [Host]) VALUES (@log_date, @thread, @log_level, @logger, @message, @exception, @appdomain, @currentUser, @host)" />
    <parameter>
      <parameterName value="@log_date" />
      <dbType value="DateTime" />
      <layout type="log4net.Layout.RawTimeStampLayout" />
    </parameter>
    <parameter>
      <parameterName value="@thread" />
      <dbType value="String" />
      <size value="255" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%thread" />
      </layout>
    </parameter>
    <parameter>
      <parameterName value="@log_level" />
      <dbType value="String" />
      <size value="50" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%level" />
      </layout>
    </parameter>
    <parameter>
      <parameterName value="@logger" />
      <dbType value="String" />
      <size value="255" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%logger" />
      </layout>
    </parameter>
    <parameter>
      <parameterName value="@message" />
      <dbType value="String" />
      <size value="4000" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%message" />
      </layout>
    </parameter>
    <parameter>
      <parameterName value="@exception" />
      <dbType value="String" />
      <size value="2000" />
      <layout type="log4net.Layout.ExceptionLayout" />
    </parameter>
    <parameter>
      <parameterName value="@appdomain" />
      <dbType value="String" />
      <size value="50" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%appdomain" />
      </layout>
    </parameter>
     <parameter>
      <parameterName value="@currentUser" />
      <dbType value="String" />
      <size value="50" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%username" />
      </layout>
    </parameter>
    <parameter>
    <parameterName value="@host" />
      <dbType value="String" />
      <size value="50" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%X{log4net:HostName}" />
      </layout>
    </parameter>
  </appender>
  <root>
    <level value="DEBUG" />
    <appender-ref ref="AdoNetAppender" />
  </root>
  <logger name="NHibernate">
    <level value="ERROR"/>
  </logger>
</log4net>