PowerShell logging using Apache log4net

PowerShell offers the possibility to log the output of your scripts. A combination of Start-Transcript, Stop-Transcript, Write-Debug, Write-Verbose, Write-Warning, Write-Error, or a simple Write-Host based function can provide you enough for a decent PowerShell logging.

However, those who are coming with a .NET background heard and probably used the Apache log4net library. Now using Apache log4net for PowerShell logging is a preference thing. There are already available some modules (like Log4Posh) who are using log4net as base for the PowerShell logging.

I personally prefer to stay as close as possible to the base and “play” there. In other words I prefer to have less dependencies as possible (even if that requires more lines of code).
So in this post I will present how fast and easy as possible you can have powerful logging with PowerShell and Apache log4net. Again, this is a preference, not a best practice. If you already know the benefits of using log4net you much likely will jump in the PowerShell examples posted bellow. If you haven’t worked with log4net, but you would like to use a logging who gives you a bit more than what PowerShell provides out of the box, then simple follow the step by step and guaranteed you’re PowerShell scripts will start “talk back” to you.

You can download all the PowerShell scripts used in this article from here, but please be aware of the file zone information issue.

1. For those who want to read a bit more about Apache log4net (click here and here).

2. You will need the log4net.dll to “follow” your scripts, or be centrally placed in the systems where you will run the PowerShell scripts.
I am providing you the ability to download a compiled version of Apache log4net. In case you don’t want to download them from here, you can simply download the source from the official site and compile it. Please be aware the latest versions of Apache log4net (1.2.15 – at the moment when this article was written) are based on .NET Framework 4.5. That means the functionality provided by the log4net.dll compiled using .NET Framework 4.5 will actually run only with PowerShell 4.0.
However there are situations where you need to run in lower versions of PowerShell (like PowerShell 2.0, when you want to use the SharePoint 2010 PowerShell Snapin, or simply on a computer who is not ready with PowerShell 4.0), case in which you will need the log4net.dll compiled using .NET Framework 2.0 – so is necessary to use an older version of Apache log4net (version 1.2.10).
You want to simplify your life? -> Download the log4net.dll (version 1.2.10) from here and go to the next step (it will run with PowerShell 2.0, 3.0 and 4.0).
You want to simplify your life, but want to use log4net 1.2.15 (the latest release at the moment when this article was written)? Download the log4net.dll (version 1.2.15) from here and go to the next step, but keep in mind it will work only with PowerShell 4.0.

3. Place the .dll into the folder where your script will be hosted.
PowerShellLoggingUsingApacheLog4net_01

4. Save the following PowerShell code as LogOutputInConsoleAndFile.ps1 and execute the script.

[void][Reflection.Assembly]::LoadFile(([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+"\log4net.dll");
[log4net.LogManager]::ResetConfiguration();

#Example of File Appender initialization
$FileApndr = new-object log4net.Appender.FileAppender(([log4net.Layout.ILayout](new-object log4net.Layout.PatternLayout('[%date{yyyy-MM-dd HH:mm:ss.fff} (%utcdate{yyyy-MM-dd HH:mm:ss.fff})] [%level] [%message]%n')),(([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+'\LogOutputInConsoleAndFile.log'),$True));
$FileApndr.Threshold = [log4net.Core.Level]::All;
[log4net.Config.BasicConfigurator]::Configure($FileApndr);

#Example of Colored Console Appender initialization
$ColConsApndr = new-object log4net.Appender.ColoredConsoleAppender(([log4net.Layout.ILayout](new-object log4net.Layout.PatternLayout('[%date{yyyy-MM-dd HH:mm:ss.fff}] %message%n'))));
$ColConsApndrDebugCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrDebugCollorScheme.Level=[log4net.Core.Level]::Debug; $ColConsApndrDebugCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Green;
$ColConsApndr.AddMapping($ColConsApndrDebugCollorScheme);
$ColConsApndrInfoCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrInfoCollorScheme.level=[log4net.Core.Level]::Info; $ColConsApndrInfoCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::White;
$ColConsApndr.AddMapping($ColConsApndrInfoCollorScheme);
$ColConsApndrWarnCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrWarnCollorScheme.level=[log4net.Core.Level]::Warn; $ColConsApndrWarnCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Yellow;
$ColConsApndr.AddMapping($ColConsApndrWarnCollorScheme);
$ColConsApndrErrorCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrErrorCollorScheme.level=[log4net.Core.Level]::Error; $ColConsApndrErrorCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Red;
$ColConsApndr.AddMapping($ColConsApndrErrorCollorScheme);
$ColConsApndrFatalCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrFatalCollorScheme.level=[log4net.Core.Level]::Fatal; $ColConsApndrFatalCollorScheme.ForeColor=([log4net.Appender.ColoredConsoleAppender+Colors]::HighIntensity -bxor [log4net.Appender.ColoredConsoleAppender+Colors]::Red);
$ColConsApndr.AddMapping($ColConsApndrFatalCollorScheme);
$ColConsApndr.ActivateOptions();
$ColConsApndr.Threshold = [log4net.Core.Level]::All;
[log4net.Config.BasicConfigurator]::Configure($ColConsApndr);

$Log=[log4net.LogManager]::GetLogger("root");

#Debug
#Info
#Warn
#Error
#Fatal

$Log.Debug('Debug message.');
$Log.Info('Info message.');
$Log.Warn('Warn message.');
$Log.Error('Error message.');
$Log.Fatal('Fatal message.');

[log4net.LogManager]::ResetConfiguration();


5. As result of the script execution, the log will be available in the console (each level of severity having its own color for easy distinguishing) and also in the new LogOutputInConsoleAndFile.log file generated in the same folder as the PowerShell script.
PowerShellLoggingUsingApacheLog4net_02
PowerShellLoggingUsingApacheLog4net_03
PowerShellLoggingUsingApacheLog4net_04

 

Maybe the output of the first script was not that impressive, but if we look carefully at the Threshold property part of $FileApndr and $ColConsApndr we realize we can actually achieve functionality like -> in console to log only what is Warn and higher from severity point of view, while into the log files to have the full log (including Debug + Info). Well actually this is a pretty good functionality if you consider those scripts who are producing thousands of log entries and in console you are interested to capture only the warn, error and fatal messages.

Here is another example:

[void][Reflection.Assembly]::LoadFile(([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+"\log4net.dll");
[log4net.LogManager]::ResetConfiguration();

#Example of File Appender initialization
$FileApndr = new-object log4net.Appender.FileAppender(([log4net.Layout.ILayout](new-object log4net.Layout.PatternLayout('[%date{yyyy-MM-dd HH:mm:ss.fff} (%utcdate{yyyy-MM-dd HH:mm:ss.fff})] [%level] [%message]%n')),(([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+'\LogOutputInConsoleAndFileHavingDifferentThresolds.log'),$True));
$FileApndr.Threshold = [log4net.Core.Level]::All;
[log4net.Config.BasicConfigurator]::Configure($FileApndr);

#Example of Colored Console Appender initialization
$ColConsApndr = new-object log4net.Appender.ColoredConsoleAppender(([log4net.Layout.ILayout](new-object log4net.Layout.PatternLayout('[%date{yyyy-MM-dd HH:mm:ss.fff}] %message%n'))));
$ColConsApndrDebugCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrDebugCollorScheme.Level=[log4net.Core.Level]::Debug; $ColConsApndrDebugCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Green;
$ColConsApndr.AddMapping($ColConsApndrDebugCollorScheme);
$ColConsApndrInfoCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrInfoCollorScheme.level=[log4net.Core.Level]::Info; $ColConsApndrInfoCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::White;
$ColConsApndr.AddMapping($ColConsApndrInfoCollorScheme);
$ColConsApndrWarnCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrWarnCollorScheme.level=[log4net.Core.Level]::Warn; $ColConsApndrWarnCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Yellow;
$ColConsApndr.AddMapping($ColConsApndrWarnCollorScheme);
$ColConsApndrErrorCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrErrorCollorScheme.level=[log4net.Core.Level]::Error; $ColConsApndrErrorCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Red;
$ColConsApndr.AddMapping($ColConsApndrErrorCollorScheme);
$ColConsApndrFatalCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrFatalCollorScheme.level=[log4net.Core.Level]::Fatal; $ColConsApndrFatalCollorScheme.ForeColor=([log4net.Appender.ColoredConsoleAppender+Colors]::HighIntensity -bxor [log4net.Appender.ColoredConsoleAppender+Colors]::Red);
$ColConsApndr.AddMapping($ColConsApndrFatalCollorScheme);
$ColConsApndr.ActivateOptions();
$ColConsApndr.Threshold = [log4net.Core.Level]::Warn;
[log4net.Config.BasicConfigurator]::Configure($ColConsApndr);

$Log=[log4net.LogManager]::GetLogger("root");

#Debug
#Info
#Warn
#Error
#Fatal

$Log.Debug('Debug message.');
$Log.Info('Info message.');
$Log.Warn('Warn message.');
$Log.Error('Error message.');
$Log.Fatal('Fatal message.');


[log4net.LogManager]::ResetConfiguration();

PowerShellLoggingUsingApacheLog4net_05
PowerShellLoggingUsingApacheLog4net_06

 

You can go further than this. For example, if the file log becomes too large and is becoming hard to be analyzed, you can perform a logical split of the log into multiple files, being able to control even the log filenames. How awesome is this one?
A real use scenario: from time to time I am performing files version cleaning in all site collections hosted by some SharePoint farms and because I am dealing with thousands of them I am interested to have a log file per each site collection while still have the console ready to report just info, warning and error messages. In this way the log from the console is relatively short and is providing the progress, while the debug details are going into the log files (one log file per each site collection). In case I need all the details related to a single site collection, I just need to identify the GUID associated to that site collection and the next step is to open the log file who has that GUID part of the name.

Here is another example:

[void][Reflection.Assembly]::LoadFile(([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+"\log4net.dll");
[log4net.LogManager]::ResetConfiguration();

#Example of File Appender initialization
$MainFileLogPath=([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+'\LogOutputInConsoleAndMultipleFiles.log';
$FileApndr = new-object log4net.Appender.FileAppender(([log4net.Layout.ILayout](new-object log4net.Layout.PatternLayout('[%date{yyyy-MM-dd HH:mm:ss.fff} (%utcdate{yyyy-MM-dd HH:mm:ss.fff})] [%level] [%message]%n')),$MainFileLogPath,$True));
$FileApndr.Threshold = [log4net.Core.Level]::All;
[log4net.Config.BasicConfigurator]::Configure($FileApndr);

#Example of Colored Console Appender initialization
$ColConsApndr = new-object log4net.Appender.ColoredConsoleAppender(([log4net.Layout.ILayout](new-object log4net.Layout.PatternLayout('[%date{yyyy-MM-dd HH:mm:ss.fff}] %message%n'))));
$ColConsApndrDebugCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrDebugCollorScheme.Level=[log4net.Core.Level]::Debug; $ColConsApndrDebugCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Green;
$ColConsApndr.AddMapping($ColConsApndrDebugCollorScheme);
$ColConsApndrInfoCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrInfoCollorScheme.level=[log4net.Core.Level]::Info; $ColConsApndrInfoCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::White;
$ColConsApndr.AddMapping($ColConsApndrInfoCollorScheme);
$ColConsApndrWarnCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrWarnCollorScheme.level=[log4net.Core.Level]::Warn; $ColConsApndrWarnCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Yellow;
$ColConsApndr.AddMapping($ColConsApndrWarnCollorScheme);
$ColConsApndrErrorCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrErrorCollorScheme.level=[log4net.Core.Level]::Error; $ColConsApndrErrorCollorScheme.ForeColor=[log4net.Appender.ColoredConsoleAppender+Colors]::Red;
$ColConsApndr.AddMapping($ColConsApndrErrorCollorScheme);
$ColConsApndrFatalCollorScheme=new-object log4net.Appender.ColoredConsoleAppender+LevelColors; $ColConsApndrFatalCollorScheme.level=[log4net.Core.Level]::Fatal; $ColConsApndrFatalCollorScheme.ForeColor=([log4net.Appender.ColoredConsoleAppender+Colors]::HighIntensity -bxor [log4net.Appender.ColoredConsoleAppender+Colors]::Red);
$ColConsApndr.AddMapping($ColConsApndrFatalCollorScheme);
$ColConsApndr.ActivateOptions();
$ColConsApndr.Threshold = [log4net.Core.Level]::Info;
[log4net.Config.BasicConfigurator]::Configure($ColConsApndr);

$Log=[log4net.LogManager]::GetLogger("root");

#Debug
#Info
#Warn
#Error
#Fatal

$Log.Debug('01. Debug message.'); #This will be written to the main log file.
$Log.Info('02. Info message.'); #This will be written to the console + main log file.
$Log.Warn('03. Warn message.'); #This will be written to the console + main log file.
$Log.Error('04. Error message.'); #This will be written to the console + main log file.
$Log.Fatal('05. Fatal message.'); #This will be written to the console + main log file.

$Appenders=([log4net.LogManager]::GetRepository()).GetAppenders();

$SecondaryFilePath=(([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+'\41a4b05a-5bd8-42fe-9fd6-02279015b4d2.log');
$Log.Info('06. Switch logging for /sites/site01 to '+$SecondaryFilePath); #This will be written to the console + main log file.
$Appenders[0].File=$SecondaryFilePath;
$Appenders[0].ActivateOptions();

$Log.Debug('07. Debug message.'); #This will be written to the secondary log file.
$Log.Info('08. Info message.'); #This will be written to the console + secondary log file.
$Log.Warn('09. Warn message.'); #This will be written to the console + secondary log file.
$Log.Error('10. Error message.'); #This will be written to the console + secondary log file.
$Log.Fatal('11. Fatal message.'); #This will be written to the console + secondary log file.


$SecondaryFilePath=(([System.IO.Directory]::GetParent($MyInvocation.MyCommand.Path)).FullName+'\c5add83b-f7ad-4736-a025-bb2a24d5ff82.log');
$Appenders[0].File=$MainFileLogPath;
$Appenders[0].ActivateOptions();
$Log.Info('12. Switch logging for /sites/site02 to '+$SecondaryFilePath); #This will be written to the console + main log file.
$Appenders[0].File=$SecondaryFilePath;
$Appenders[0].ActivateOptions();

$Log.Debug('13. Debug message.'); #This will be written to the secondary log file.
$Log.Info('14. Info message.'); #This will be written to the console + secondary log file.
$Log.Warn('15. Warn message.'); #This will be written to the console + secondary log file.
$Log.Error('16. Error message.'); #This will be written to the console + secondary log file.
$Log.Fatal('17. Fatal message.'); #This will be written to the console + secondary log file.

$Appenders[0].File=$MainFileLogPath;
$Appenders[0].ActivateOptions();

$Log.Debug('18. Debug message.'); #This will be written to the main log file.
$Log.Info('19. Info message.'); #This will be written to the console + main log file.
$Log.Warn('20. Warn message.'); #This will be written to the console + main log file.
$Log.Error('21. Error message.'); #This will be written to the console + main log file.
$Log.Fatal('22. Fatal message.'); #This will be written to the console + main log file.

[log4net.LogManager]::ResetConfiguration();

PowerShellLoggingUsingApacheLog4net_07
PowerShellLoggingUsingApacheLog4net_08
PowerShellLoggingUsingApacheLog4net_09
PowerShellLoggingUsingApacheLog4net_10
PowerShellLoggingUsingApacheLog4net_11

 


Just in case when you run these scripts you encounter the following PowerShell error message, please be aware of the file zone information. You need to unblock the .dll.
Exception calling “LoadFile” with “1” argument(s): “An attempt was made to load an assembly from a network location which would have caused the assembly to be sandboxed in previous versions of the .NET Framework. This release of the .NET Framework does not enable CAS policy by default, so this load may be dangerous. If this load is not intended to sandbox the assembly, please enable the loadFromRemoteSources switch. See http://go.microsoft.com/fwlink/?LinkId=155569 for more information.”
PowerShellLoggingUsingApacheLog4net_12
PowerShellLoggingUsingApacheLog4net_13