Using log4net to Log Powershell Output to Dynamic Database Variables

Question

I'm building a web UI to help automate our deployment process and am going to write a powershell script to do the deployment and would like it's Write-Debug (or any statement to log, just let me know which to use :) ) statements to be logged to the deployed package's database variable Log. I haven't really used log4net before so please don't laugh if I'm doing this completely wrong.

I figure since the location is dynamic, I'd have to code the log4net appenders, but would it be easier/better to do all of the log4net stuff inside of the powershell script? I read this and found I should use ps.Streams.Debug.DataAdded += new EventHandler<DataAddedEventArgs>(delegate(object sender, DataAddedEventArgs e) to get the write-debug information.

Here is what I have so far:

public static void Test(Package pkg)
    {
        //Do roll_out
        //Creates a cmd prompt
        PowerShell ps = PowerShell.Create();
        string myCommand = @"C:\Users\evan.layman\Desktop\test.ps1";

    ps.AddCommand(myCommand);

    ps.Streams.Debug.DataAdded += new EventHandler<DataAddedEventArgs>(delegate(object sender, DataAddedEventArgs e)
    {
        PSDataCollection<DebugRecord> debugStream = (PSDataCollection<DebugRecord>)sender;
        DebugRecord record = debugStream[e.Index];

        Hierarchy hierarchy = (Hierarchy)LogManager.GetRepository();
        hierarchy.Root.RemoveAllAppenders(); /*Remove any other appenders*/

        AdoNetAppender appender = new AdoNetAppender();
        appender.ConnectionString = ConfigurationManager.ConnectionStrings["DeploymentConnectionString"].ConnectionString;
        appender.CommandText = "with cte as (SELECT * FROM Package PackageID =" + pkg.PackageID + ") UPDATE cte SET (Log) VALUES (?logText)";
        AdoNetAppenderParameter param = new AdoNetAppenderParameter();
        param.DbType = System.Data.DbType.String;
        param.ParameterName = "logText";
        param.Layout = new log4net.Layout.RawTimeStampLayout();
        appender.AddParameter(param);
        BasicConfigurator.Configure(appender);

        ILog log = LogManager.GetLogger("PowerShell");
        log.Debug(record.Message);
        //log.DebugFormat("{0}:{1}", DateTime.UtcNow, record);
        //log.Warn(record, new Exception("Log failed"));
    });
    Collection<PSObject> commandResults = ps.Invoke();

Hopefully I can get this working :)

Answer 1

I would keep as much log4net config out of your code as possible. In your code, the config is being recreated on each debug statement, which is inefficient.

It's possible to do what you want using event context properties in log4net. I've blogged about log4net event context a bit on my blog.

Here's a quick example that's close to your existing codebase....

This C# code shows how to use log4net global properties to store custom event context data; note the setting of the "PackageID" global property value before the pipeline is executed...

using System;
using System.Management.Automation;
using log4net;

// load log4net configuration from app.config
[assembly:log4net.Config.XmlConfigurator]

namespace ConsoleApplication1
{
    class Program
    {
        private static PowerShell _ps;
        private static ILog Log = log4net.LogManager.GetLogger(typeof (Program));

        static void Main(string[] args)
        {
            string script = "write-debug 'this is a debug string' -debug";

            for (int packageId = 1; packageId <= 5; ++packageId)
            {
                using (_ps = PowerShell.Create())
                {
                    _ps.Commands.AddScript(script);
                    _ps.Streams.Debug.DataAdded += WriteDebugLog;

                    // set the PackageID global log4net property 
                    log4net.GlobalContext.Properties["PackageID"] = packageId;

                    // sync invoke your pipeline
                    _ps.Invoke();

                    // clear the PackageID global log4net property 
                    log4net.GlobalContext.Properties["PackageID"] = null;
                }
            }        
        }

        private static void WriteDebugLog(object sender, DataAddedEventArgs e)
        {
            // get the debug record and log the message
            var record = _ps.Streams.Debug[e.Index];
            Log.Debug(record.Message);            
        }
    }
}

And here is the app.config that drops the logs into the database; note the custom PackageID parameter in the SQL, and how the value is pulled from the log4net property stack:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<configSections>
  <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
</configSections>
<log4net>
  <appender name="Ado" type="log4net.Appender.AdoNetAppender">
    <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
    <connectionString value="data source=vbox-xp-sql;initial catalog=test1;integrated security=false;persist security info=True;User ID=test1;Password=password" />
    <commandText value="INSERT INTO Log ([Message],[PackageID]) VALUES (@message, @packageid)" />
    <parameter>
      <parameterName value="@message" />
      <dbType value="String" />
      <size value="4000" />
      <layout type="log4net.Layout.PatternLayout" value="%message" />
    </parameter>
    <parameter>
      <parameterName value="@packageid" />
      <dbType value="Int32" />
      <size value="4" />
      <!-- use the current value of the PackageID property -->
      <layout type="log4net.Layout.PatternLayout" value="%property{PackageID}" />
    </parameter>
  </appender>

  <root>
    <level value="ALL" />
    <appender-ref ref="Ado" />
  </root> 
</log4net>
</configuration>

Hope this helps.