ThreadContext property does not write to AdoNetAppender

Question

I am using log4net 1.2.10.0. I have extended ILog and LogManager to include a new level, 'AUDIT'. I want to use an AdoNetAppender to log the %message to a database. I need other information logged and I tried using log4net.ThreadContext.Properties.

I get no output when I try to use a context property as a value for a SQL parameter.

<log4net>
  <level>
    <name value="AUDIT" />
    <value value="35000" />
  </level>
  <appender name="AdoNetAppender.Audit" type="log4net.Appender.AdoNetAppender">
    <filter type="log4net.Filter.LevelMatchFilter">
      <levelToMatch value="AUDIT" />
    </filter>
    <filter type="log4net.Filter.DenyAllFilter" />
    <connectionType value="System.Data.OracleClient.OracleConnection, System.Data.OracleClient, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
    <connectionString value="data source=db1;User ID=user;Password=pass" />
    <commandText value="INSERT INTO table1 VALUES(:custom_prop, :message)" />
    <parameter>
      <parameterName value=":custom_prop" />
      <dbType value="String" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%property{custom_prop}" />
      </layout>
    </parameter>
    <parameter>
      <parameterName value=":message" />
      <dbType value="String" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%message" />
      </layout>
    </parameter>
  </appender>
  <root>
    <level value="ALL" />
    <appender-ref ref="AdoNetAppender.Audit" />
  </root>
</log4net>

The executing code is (assuming log4net has been init'ed and a logger, 'log', has been created).

log4net.ThreadContext.Properties["custom_prop"] = "value";
log.Audit("a message");

The appender works with the AUDIT filter if I hard-code a value instead of using a SQL parameter.

...
<commandText value="INSERT INTO table1 VALUES('value', :message)" />
...

The appender works with the context property if I filter on a built-in level, like INFO.

...
<filter type="log4net.Filter.LevelMatchFilter">
  <levelToMatch value="INFO" />
</filter>
...

A FileAppender works with the AUDIT filter and context property!

<appender name="FileAppender" type="log4net.Appender.FileAppender" >
  <filter type="log4net.Filter.LevelMatchFilter">
    <levelToMatch value="AUDIT" />
    </filter>
  <filter type="log4net.Filter.DenyAllFilter" />
  <file value="test.log" />
  <layout type="log4net.Layout.PatternLayout" >
    <conversionPattern value="%-5level [%property{custom_prop}] - %message%newline" />
  </layout>
</appender>

Resulting in

AUDIT [value] - a message

Using a global context property works with the AdoNetAppender and AUDIT filter. But, I need thread context resolution.

log4net.GlobalContext.Properties["custom_prop"] = "value";
log.Audit("a message");

Resulting in

table1
custom_prop message
=========== =======
value       a message

So, I don't know if it's a problem with the AdoNetAppender or my extended classes or my configuration.

Answer 1

The problem was caused by early abortion of the foreground thread. I think log4net was running an async operation. Putting a sleep at the end of the test app fixed the problem

...
log4net.ThreadContext.Properties["custom_prop"] = "value";
log.Audit("a message");
...
Thread.Sleep(1000);

or, when in a separate thread, joining on it

Thread t = new Thread(new ThreadStart(delegate
{
    log4net.ThreadContext.Properties["custom_prop"] = "value";
    log.Audit("a message");        
}));
t.Start();
...
t.Join();

In normal operation, log4net should have enough time between the latest AUDIT call and the end of execution.