How do I match a message with a newline in log4net with the stringToMatch filter?

Question

I'm having trouble with configuring a StringMatchFilter to match a string in a message with newlines. I want to skip some messages and I have added a filter like this and it works.

<filter type="log4net.Filter.StringMatchFilter">
  <param name="AcceptOnMatch" value="false" />
  <stringToMatch value="Unexpected exception in SocketThreadWorker" />
</filter>

But if I change the stringToMatch to "An existing connection was forcibly closed by the remote host" which occurs on the second row of the message the filter does not work. Is it because of the newline in the message or am I doing anything wrong here?

A typical message can look like this:

------ Example message ----------------------------

2011-05-04 16:22:24,078 [Client (connected from "127.0.0.1:4076" at 16:22)] ERROR - Unexpected exception in SocketThreadWorker System.Net.Sockets.SocketException:
An existing connection was forcibly closed by the remote host at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)

------ End example message ---------------------------

"Unexpected exception in SocketThreadWorker" is on the first row of the message and "An existing connection was forcibly closed" is on the second row.

Edit

The appender looks like this:

<appender name="SmtpAppender" type="log4net.Appender.SmtpAppender">
  <filter type="log4net.Filter.StringMatchFilter">
    <param name="AcceptOnMatch" value="false" /> 
    <stringToMatch value="An existing connection was forcibly closed by the remote host" />        
  </filter>
  <to value="..." />
  <from value="..." />
  <subject value="[... ${COMPUTERNAME}] An Error occurred" />
  <smtpHost value=".." />
  <bufferSize value="1024" />
  <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" />
  </layout>
</appender>

I don't want to notify anybody about this error message since it is really not that serious. The message is not produced by my own code but it comes from a library that I use.

Answer 1

Explanation of log4net Appending

The SocketThreadWorker is throwing a SocketException. The exception message, "An existing connection was forcibly closed by the remote host", is mapped by the error code.

throw new SocketException(10054);

The code producing the log statement looks like an unhandled exception handler (by the message printed "Unexpected exception... "). But, for this answer, imagine it looks like this

try
{
    ...
}
catch (Exception e)
{
    _log.Error("Unexpected exception in SocketThreadWorker", e);
}

What log4net produces under the covers is a LoggingEvent. It contains the provided log message and the exception object (separately). Each appender can decide how to write these two items to their final destinations (along with other properties, layout parameters, etc).

The StringToMatch filter works only on the log message. Not on the exception message! Check out this code below, we'll construct a system and a test that will help us debug the problem

Reproduction and Deep Dive

Here is a simple socket exception throwing class

public class SocketThreadWorker
{
    public void DoWork()
    {
        throw new SocketException(10054);
    }
}

We'll configure log4net to use a ConsoleAppender with a string match filter, matching the exception message string.

public static class LocalLoggingConfiguration
{
    public static void Configure()
    {
        var filter = new StringMatchFilter
        {
            StringToMatch = "An existing connection was forcibly closed by the remote host",
            AcceptOnMatch = false,
        };

        var appender = new ConsoleAppender
        {
            Layout = new SimpleLayout()
        };

        appender.AddFilter(filter);

        BasicConfigurator.Configure(appender);
    }
}

We configure log4net, get a logger, and make a failing call in the test. You'll notice a few log statements at other levels and another one at Error that won't match our filter (if it works). This way, we can be sure that we're not accidentally losing all messages.

[TestClass]
public class SocketLibraryTest
{
    private readonly ILog _log = LogManager.GetLogger(typeof(SocketLibraryTest));

    public SocketLibraryTest()
    {
        LocalLoggingConfiguration.Configure();
    }

    [TestMethod]
    public void CatchThatPeskyException()
    {
        _log.Debug("Testing...");

        try
        {
            new SocketThreadWorker().DoWork();
        }
        catch (Exception e)
        {
            _log.Info("An exception!");
            _log.Error("Unexpected exception in SocketThreadWorker", e);
            _log.Error("It wasn't that bad.");
        }
    }
}

The output of this test, in my environment, includes the exception on a separate line from the message, because, by default, an appender will print the exception object that way.

DEBUG - Testing...  
INFO - An exception!  
ERROR - Unexpected exception in SocketThreadWorker  
System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host  
   at SO5894291.SocketThreadWorker.DoWork() in d:\users\anthony.mastrean\documents\Projects\SO5894291\SO5894291\SocketLibraryTest.cs:line 16  
   at SO5894291.SocketLibraryTest.CatchThatPeskyException() in d:\users\anthony.mastrean\documents\Projects\SO5894291\SO5894291\SocketLibraryTest.cs:line 58  
ERROR - It wasn't that bad.

If you modify the appender filter to match on a part of a different message, you'll see that it is configured properly and does work. Change the string to match to "Testing" and you'll see the DEBUG statement disappear from the Console output!

Recommendations

You do not want to match on the generic log message "An unexpected exception... ". That has the chance to lose messages. Even introducting a logger match filter won't help, because that socket worker probably can and will throw other exceptions (again, potentially losing messages).

The only option I can think of is to implement your own ExceptionMessageToMatchFilter. I've copied the implementation of StringToMatchFilter, replacing the rendered message string for the exception message.

public class ExceptionMessageToMatchFilter : StringMatchFilter
{
    public override FilterDecision Decide(LoggingEvent loggingEvent)
    {
        if (loggingEvent == null)
            throw new ArgumentNullException("loggingEvent");

        if (loggingEvent.ExceptionObject == null)
            return FilterDecision.Neutral;

        var exceptionMessage = loggingEvent.GetExceptionString();

        if (m_regexToMatch != null)
        {
            if (!m_regexToMatch.Match(exceptionMessage).Success)
                return FilterDecision.Neutral;

            return m_acceptOnMatch ? FilterDecision.Accept : FilterDecision.Deny;
        }

        if (m_stringToMatch == null || exceptionMessage.IndexOf(m_stringToMatch) == -1)
        {
            return FilterDecision.Neutral;
        }

        return m_acceptOnMatch ? FilterDecision.Accept : FilterDecision.Deny;
    }
}

I would be careful around the GetExceptionString() call, I don't know if it can return null. Or what you want to do if there is no message (is it empty? should you return neutral or continue matching?).

It's quite easy to rig up in your log4net configuration (especially because it has all the properties from the string to match filter).

<filter type="MyNamespace.ExceptionMessageToMatchFilter, MyAssembly">
    <stringToMatch value="An existing connection was forcibly closed by the remote host" />
    <acceptOnMatch value="false" />
</filter>