log4net ColoredConsoleAppender: log levels and its problems

I was playing around with the ColoredConsoleAppender of log4net. It allows you to display a certain log level in another color. For instance messages with an error level can be displayed red in the console. But I encountered some problems with it.

To display error messages in red and debug messages in yellow, the appender configuration will look like this:

<appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
  <mapping>
    <level value="ERROR" />
    <forecolor value="Red" />
  </mapping>
  <mapping>
    <level value="DEBUG" />
    <forecolor value="Yellow" />
  </mapping>
  <layout type="log4net.Layout.PatternLayout">
    <conversionpattern value="%date [%thread] %-5level - %message%newline" />
  </layout>
</appender>

In your code, you’ll have something like this:

ILog logger = LogManager.GetLogger("Test");
logger.Info("Info message");
logger.Debug("Debug message");
logger.Error("Error message");

This generates the following output:



As you can see, the info message is also in yellow although there is no color defined for the info level. I expected that the info message would have the default console color. You may have noticed that the colors of my console window are different than the default ones. It is blue text on white background. I prefer a bright background. The output has a black background, even though I did not specify a background color in the ColoredConsoleAppender configuration.

The project I was working on had already a reference to the source of log4net. I’ve made already some changes to make log4net run on .NET 4.0, so why not change – or should I say fix? – the behavior of the ColoredConsoleAppender?

Having set a breakpoint at the beginning of the Append() method in the log4net.Appender.ColoredConsoleAppender class, I stepped through the code to see what was happening. Eventually I noticed the following line of code in the Append() method:

// see if there is a specified lookup
LevelColors levelColors = m_levelMapping.Lookup(loggingEvent.Level) as LevelColors;
//
//

I went to the definition of that Lookup() method (it’s in the log4net.Util.LevelMapping class) and saw the following comment:

Lookup the value for the specified level. Finds the nearest mapping value for the level that is equal to or less than the level specified.

For colors, I want an exact match and not the nearest (or less) one. So I changed the Lookup() method to call a new overloaded method. The overloaded method has a boolean parameter which tells the method to look for an exact level match (true) or to find it by the default behavior (false). To preserve the default behavior and to not break existing code, the original Lookup() method calls the new overloaded method with ‘false’ for the boolean parameter.

public LevelMappingEntry Lookup(Level level)
{
  return Lookup(level, false);
}

public LevelMappingEntry Lookup(Level level, bool exactMatch)
{
  if (m_entries != null)
  {
    foreach (LevelMappingEntry entry in m_entries)
    {
      if ((exactMatch && level == entry.Level) || (!exactMatch && level >= entry.Level))
      {
        return entry;
      }
    }
  }
  return null;
}

Back in the ColoredConsoleAppender class, I changed the line with the Lookup() call as follows:

// see if there is a specified lookup
LevelColors levelColors = m_levelMapping.Lookup(loggingEvent.Level, true) as LevelColors;
//
//

With these changes to the code, the output looks like this:



The info message is not in yellow anymore, but it still doesn’t respect my default colors of the console because it’s white text on a black background! Something else is still wrong, let’s debug the Append() method again. The following lines got my attention:

// Default to white on black
ushort colorInfo = (ushort)Colors.White;

Like comment says log4net assumes that white on black is default. To fix this issue, several lines of code must be changed. You can find the complete changed Append() method here below. I hope the comments should be enough for you to understand the changes that are made. All changes are marked with a "//CHANGE" comment.

override protected void Append(log4net.Core.LoggingEvent loggingEvent) 
{
    if (m_consoleOutputWriter != null)
    {
        IntPtr consoleHandle = IntPtr.Zero;
        if (m_writeToErrorStream)
        {
            // Write to the error stream
            consoleHandle = GetStdHandle(STD_ERROR_HANDLE);
        }
        else
        {
            // Write to the output stream
            consoleHandle = GetStdHandle(STD_OUTPUT_HANDLE);
        }

        //CHANGE: Read the current console info here instead of later
        // get the current console color - to restore later
        CONSOLE_SCREEN_BUFFER_INFO bufferInfo;
        GetConsoleScreenBufferInfo(consoleHandle, out bufferInfo);

        //CHANGE: Do not assume white on black is default
        // Default to white on black
        //ushort colorInfo = (ushort)Colors.White;

        //CHANGE: Read the color attributes of the console info
        // wAttributes:
        // - More info at http://msdn.microsoft.com/en-us/library/ms682088(v=VS.85).aspx#_win32_character_attributes
        // - bit 1 to 4: forecolor
        // - bit 5 to 8: backcolor
        ushort colorInfo = (ushort)((int)bufferInfo.wAttributes & 255);

        //CHANGE: Lookup with exact match
        // see if there is a specified lookup
        LevelColors levelColors = m_levelMapping.Lookup(loggingEvent.Level, true) as LevelColors;
        if (levelColors != null)
        {
            colorInfo = levelColors.CombinedColor;
        }

        // Render the event to a string
        string strLoggingMessage = RenderLoggingEvent(loggingEvent);

        //CHANGE: Moved up in order to get console default color
        // get the current console color - to restore later
        //CONSOLE_SCREEN_BUFFER_INFO bufferInfo;
        //GetConsoleScreenBufferInfo(consoleHandle, out bufferInfo);

        // set the console colors
        SetConsoleTextAttribute(consoleHandle, colorInfo);

        // [skip]A long comment about WriteConsoleW[/skip]

        char[] messageCharArray = strLoggingMessage.ToCharArray();
        int arrayLength = messageCharArray.Length;
        bool appendNewline = false;

        // Trim off last newline, if it exists
        if (arrayLength > 1 && messageCharArray[arrayLength-2] == '\r' && messageCharArray[arrayLength-1] == '\n')
        {
            arrayLength -= 2;
            appendNewline = true;
        }

        // Write to the output stream
        m_consoleOutputWriter.Write(messageCharArray, 0, arrayLength);

        // Restore the console back to its previous color scheme
        SetConsoleTextAttribute(consoleHandle, bufferInfo.wAttributes);

        if (appendNewline)
        {
            // Write the newline, after changing the color scheme
            m_consoleOutputWriter.Write(s_windowsNewline, 0, 2);
        }
    }
}

Having changed that, the output is like this:



One more thing that is still not correct: the background color of the debug and error levels. I did not specify a background color, so it should be white instead of black. Changing that would mean significant changes in the inner class LevelColors because the default color of the background is set as black. That class should then know about the default colors of the console. A workaround is to specify also a background color when specifying a forecolor and I’m willing to accept that workaround for now! However, if you would feel the need to investigate this issue, please do so and let me know.