Search code examples
log4netlog4net-configuration

Logging only top-most ThreadContext stack item


We're using Log4net's ThreadContext.Stacks and it is mostly working well. My problem comes if there have been multiple ThreadContext.Stacks["key"].Push(...).

With a simple ConversionPattern:

<param name="ConversionPattern value="... topProp=%properties{key} ..."/>

I see log entries like:

... topProp=first second third ...

I'd really like to see only the most recently pushed value rather than all the values. I had hoped I could put something like the following in my appender/layout/ConversionPattern:

<param name="ConversionPattern value="... topProp=%properties{key}{1} ..."/>

but that doesn't work. I can kludge it by assuming/requiring all values to be the same length (say 5) and doing:

<param name="ConversionPattern value="... topProp=%5.5properties{key} ..."/>

But that isn't real attractive. Any ideas?

Thanks!

[Edit to add very simple example]

using System;
using System.IO;
using log4net;
using log4net.Config;

namespace ThreadLocalExample {
class Program {
    private const string PropJobId = "Example:JobId";

    static void Main() {
        XmlConfigurator.Configure(new FileInfo("log4net.cfg"));
        var log = LogManager.GetLogger(typeof(Program));

        ThreadContext.Stacks[PropJobId].Push("Old");

        log.Debug("Enter using");
        using (ThreadContext.Stacks[PropJobId].Push("New")) {
            log.Debug("stuff");
        }
        log.Debug("Out of using");

        log.Debug("done.");
        Console.ReadKey();
    }
  }
}

With the log4net configuration:

<appender name="Console" type="log4net.Appender.ConsoleAppender">
    <threshold value="ALL" />
    <layout type="log4net.Layout.PatternLayout">
        <param name="ConversionPattern" value="[jobId=%P{Example:JobId}]: %m%n" />
    </layout>
</appender>

Produces:

[jobId=Old]: Enter using
[jobId=Old New]: stuff
[jobId=Old]: Out of using
[jobId=Old]: done.

But I'd like:

[jobId=Old]: Enter using
[jobId=New]: stuff
[jobId=Old]: Out of using
[jobId=Old]: done.

Solution

  • I had the same problem, and it was not only about 'bad formatting', because I used database appender (AdoNetAppender) which expects integers. So after joining all stacked values together the result is not an integer any more. Consider an appender like this:

    <appender name="DbAppender" type="log4net.Appender.AdoNetAppender">
    ...
    <commandText value="INSERT INTO Log ([Id]) VALUES (@Id)" />
    <parameter>
        <parameterName value="@Id" />
        <dbType value="Int32" />
        <layout type="log4net.Layout.PatternLayout" value="%P{someId}" />
    </parameter>
    

    This appender will not accept any log message, where 'someId' is stacked twice or more - no logs in database ...

    So, to solve this problem I gave up with stacks and turned back to flat properties. I've coded some short extension:

        public static class Log4NetExt {
            public static IDisposable ThreadContextPush(string key, object value) {
                object oldVal = ThreadContext.Properties[key];
                ThreadContext.Properties[key] = value;
                var topMostCleaner = new DispCleaner();
                topMostCleaner.EvDispose += () => {
                    // Pop = restore old value
                    ThreadContext.Properties[key] = oldVal;
                };
                return topMostCleaner;
            }
    
            private class DispCleaner : IDisposable {
                public event Action EvDispose;
    
                public void Dispose() {
                    if (EvDispose != null) EvDispose();
                }
            }
        }
    

    And now, instead of:

    using (ThreadContext.Stacks[PropJobId].Push("New")) {
    

    write:

    using (Log4NetExt.ThreadContextPush(PropJobId, "New")) {
    

    and it works ok ;)

    (This short code does not follow all best practises of building disposable objects, deleting event handlers and all this stuff, but it is short and I think it is safe in this simple case).