This blog post is about log4net which switches log configurations within a process as soon as two components are using their own log4net configuration.

As you can read from our numerous blogs we are using PowerShell in combination with C# quite extensively. In addition we are heavily relying on log4net for logging puposes (see our PowerShell module biz.dfch.PS.System.Logging (available at GitHub and NuGet) and the C# logging classes in biz.dfch.CS.System.Utilities also available on NuGet).

Basically when logging we are using two different log files:

1. a ‘high-level’ C# log destination (per application)
2. a ‘low-level’ PowerShell log destination (for all PowerShell scripts)

This is due to the different log formats we use for both technologies (e.g. thread information is not relevant in PowerShell scripts, but is the Host.InstanceId etc).

By default both application parts (C# and PowerShell) are using the root logger with a FileAppender section (each in its own log4net configuration file), which leads to the following strange situation:

Whenever we invoke a PowerShell script from the C# application (such as in the PowerShellScriptPlugin of the Appclusive Scheduler), the log destination of the C# application also switches to the PowerShell log destination – effectively mixing both log formats in the PowerShell log file. This is really unwanted!

An explanation of this might be, that the PowerShell script de facto run in the same process and the log4net.LogManager cannot handle multiple instances?! This does not really make sense as we are definitely using different logger instances.
I really do not know for sure.

To remedy this situation I started to use a different logger for PowerShell, so each part would log via the FileAppender into a different log file. But this did not really change the behaviour. The C# code was still logging to the PowerShell log as soon as we executed a PowerShell script that used the logging library.

The final solution for this (in addition to the changed logger name) was to rename the FileAppender ref in the C# project (inside the logger section). From this change on both applications then logged to their correct log destination (with each of them via its own logger name and uniquely named FileAppender).

And then it all made sense: as we are using ConfiguraAndWatch from inside the PowerShell module we are actually re-reading the whole log4net configuration. And as this method is in fact static we are effectively swapping the configuration file for log4net!

So in reality this does not have to anything with PowerShell but this could happen with any code that initialises its log4net configuration more than once.

We consequently released an updated version of our logging module as v1.3.0 (and while at it also updated the log4net library to 1.2.15 (2.0.5)).

An example configuration might look like this:

Log configuration for the PowerShell logging module

<appender name="FileAppender" type="log4net.Appender.FileAppender">
  <file type="log4net.Util.PatternString" value="%property{DirectoryBase}\\%date{yyyy-MM}\\%date{yyyy-MM-dd}.log" />
  <appendToFile value="true" />
  <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fffzzz}|%message%newline" />
  </layout>
</appender>
<logger name="biz.dfch.PS.System.Logging" additivity="False">
  <level value="ALL" />
  <appender-ref ref="FileAppender" />
</logger>

Log configuration for the C# application

<appender name="FileAppender-biz.dfch.CS.Applcusive.Scheduler" type="log4net.Appender.FileAppender">
  <file type="log4net.Util.PatternString" value="%property{DirectoryBase}\\%date{yyyy-MM}\\%date{yyyy-MM-dd}.log" />
  <appendToFile value="true" />
  <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date{yyyy-MM-dd HH:mm:ss.fffzzz}|%message%newline" />
  </layout>
</appender>
<logger name="biz.dfch.CS.Applcusive.Scheduler" additivity="False">
  <level value="ALL" />
  <appender-ref ref="FileAppender-biz.dfch.CS.Applcusive.Scheduler" />
</logger>