Logging in PowerShell with System.Diagnostics.TraceSource and log4net

Microsoft .NET offers a very flexible logging system exposed via the System.Diagnostics namespace. Unfortunately (and not surprisingly), by default the pre-packaged listeners do not support writing messages to log4net directly.

However, we can extend the logging outputs by implementing custom TraceListeners and when asking our favourite search engine for “TraceListener log4net” we find there are already plenty of implementations of this.

With System.Diagnostics.TraceSource being an integral part of .NET we can start logging right away without the need for any modules to be loaded:

# (in case you do not use PoSH 5, you have to use New-Object instead of new)
$ts1 = [System.Diagnostics.TraceSource]::new("myTraceSource1"); 
$ts1.TraceInformation("tralala");

This looks quite similar to the older System.Diagnostics.Trace facility:

[System.Diagnostics.Trace]::WriteLine("tralala");

In order to actually get some output we have to modify the PowerShell.exe.config (which is the app.config for our PowerShell scripts):

<!-- C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe.config -->
<?xml version="1.0" encoding="utf-8" ?> 
<configuration>
  <!-- ... -->
  <system.diagnostics>
    <sources>
      <source name="myTraceSource1" switchName="SourceSwitch" >
        <listeners>
          <clear />
          <add name="DefaultTraceListener" />
        </listeners>
      </source>
    </sources>
    <switches>
      <add name="SourceSwitch" value="All" />
    </switches>
    <sharedListeners>
      <add name="DefaultTraceListener"
        type="System.Diagnostics.DefaultTraceListener, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
        traceOutputOptions="Callstack, DateTime" >
        <filter type="System.Diagnostics.EventTypeFilter" initializeData="Verbose" />
      </add>
    </sharedListeners>
  </system.diagnostics>
  <!-- ... -->
</configuration>

With these settings we specify the following:

  1. ALL messages from the TraceSource myTraceSource1 will be sent to the TraceListener DefaultTraceListener
  2. The TraceListener DefaultTraceListener only logs messages of type Verbose or higher

Now we can see all the log entries with our favourite debug log viewer such as DebugView.

In order to be able to log to log4net we have to define or specify a TraceListener that can forward messages such as our Log4NetTraceListener.

There are several options for PowerShell (or better: the Fusion loader) to find this assembly:

  1. place it into the GAC
  2. place it into the PowerShell application directory
  3. place it into a subdirectory of the PowerShell application directory

I personally go for the third option and place all resources into a subdirectory called dfch (the TraceListener assembly and the log4net files):

C:\Windows\System32\WindowsPowerShell\v1.0\dfch
  biz.dfch.CS.Commons.dll
  log4net.config
  log4net.dll
  log4net.xml

Now we have to add a probing directive to the PowerShell.exe.config …:

<?xml version="1.0" encoding="utf-8" ?> 
<configuration>
  <!-- ... -->
  <runtime>
    <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">
      <probing privatePath="dfch"/>
    </assemblyBinding>
  </runtime>
  <!-- ... -->
</configuration>

… and add a reference to out TraceListener as a SharedListener:

<sharedListeners>
  <add name="Log4NetTraceListener"
    type="biz.dfch.CS.Commons.Diagnostics.Log4NetTraceListener, biz.dfch.CS.Commons, PublicKeyToken=ddc350d26de1d0d9"
    initializeData="C:\Windows\System32\WindowsPowerShell\v1.0\dfch\log4net.config"
    traceOutputOptions="Callstack, LogicalOperationStack" logger="biz.dfch.CS.Commons.Diagnostics.Log4NetTraceListener" >
    <filter type="System.Diagnostics.EventTypeFilter" initializeData="All" />
  </add>
</sharedListeners>

So our complete PowerShell.exe.config could look like this:

<!-- C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe.config -->
<?xml version="1.0" encoding="utf-8" ?> 
<configuration>
  <runtime>
    <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">
      <probing privatePath="dfch"/>
    </assemblyBinding>
  </runtime>
  <system.diagnostics>
    <sources>
      <source name="myTraceSource1" switchName="SourceSwitch" >
        <listeners>
          <clear />
          <add name="DefaultTraceListener" />
        </listeners>
      </source>
    </sources>
    <switches>
      <add name="SourceSwitch" value="All" />
    </switches>
    <sharedListeners>
      <add name="DefaultTraceListener"
        type="System.Diagnostics.DefaultTraceListener, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089"
        traceOutputOptions="Callstack, DateTime" >
        <filter type="System.Diagnostics.EventTypeFilter" initializeData="Verbose" />
      </add>
      <add name="Log4NetTraceListener"
        type="biz.dfch.CS.Commons.Diagnostics.Log4NetTraceListener, biz.dfch.CS.Commons, PublicKeyToken=ddc350d26de1d0d9"
        initializeData="C:\Windows\System32\WindowsPowerShell\v1.0\dfch\log4net.config"
        logger="biz.dfch.CS.Commons.Diagnostics.Log4NetTraceListener" >
        <filter type="System.Diagnostics.EventTypeFilter" initializeData="All" />
      </add>
    </sharedListeners>
  </system.diagnostics>
</configuration>

Note: initializeData contains a path to a log4net configuration file (which could theoretically be the same file as the PowerShell.exe.config but I would keep it separate).

This is actually everything it needs to start logging in PowerShell in a consistent way and manner.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: