Friday, December 9, 2016

Powershell Logging - The professional way

I've seen many PowerShell scripts in my career.  Fantastic ones and awful ones.  But I have very very rarely seen scripts where proper logging has been done.  Everyone seems to know write-output.  The clever ones know write-verbose and write-warning.  Some are really smart and write their own logging functions, allowing some level of customization.

But...

If you really want to show off with your logging, you need the full monty.  You want screen logging, rolling log files with automated time-stamps and you want event viewer logging.  Obviously, you want to have control of what and when.
Well, today is you lucky day, because I've written it for you :)

Log4Net

If you want professional logging, why re-invent the wheel in the first place.  Microsoft wrote this dll ages ago and it does the job flawlessly.  But you need to know how it works.  It took me a very long time to have it configured correctly.
I could post the code here, but do you really want to see it ?  I've made you a nice module.  Just copy it to your modules and you should be all set.

WriteLog module

Don't like to RTFM ?  Fair enough, download here

Download

Make sure it's in a single WriteLog Directory.  (unzipping tends to wrap an additional directory).  Copy the folder to your powershell modules.  Either, user-bound, under documents\WindowPowerShell\Modules.  Or globally, under c:\Windows32\WindowsPowerShell\Modules

RTFM

Ah, you do like a manual huh... here it is.

The cmdlets


PS C:\jumpstart\wfaguy> get-help Write-Log*

Name                              Category  Module                    Synopsis                                                  
----                              --------  ------                    --------                                                  
Write-LogWarning                  Function  WriteLog                  Logs a warning message                                    
Write-LogVerbose                  Function  WriteLog                  Logs a verbose message                                    
Write-LogTitle                    Function  WriteLog                  Logs a nice title                                         
Write-LogSuccess                  Function  WriteLog                  Logs a success message (in green)                         
Write-LogObject                   Function  WriteLog                  Logs a powershell object                                  
Write-LogInfo                     Function  WriteLog                  Logs a message                                            
Write-LogErrorObject              Function  WriteLog                  Logs an error object                                      
Write-LogError                    Function  WriteLog                  Logs an error message (in red)

PS C:\jumpstart\wfaguy> Write-LogTitle "This is a nice title"
This is a nice title
--------------------

PS C:\jumpstart\wfaguy> Write-LogInfo "This is a message"
This is a message

PS C:\jumpstart\wfaguy> Write-LogWarning "Watch out!"
WARNING: Watch out!

PS C:\jumpstart\wfaguy> Write-LogError "Ouch, that wasn't ok"
Ouch, that wasn't ok

PS C:\jumpstart\wfaguy> $service = Get-Service W32Time

PS C:\jumpstart\wfaguy> $service | Select Name,DisplayName,Status

Name    DisplayName   Status
----    -----------   ------
W32Time Windows Time Running


PS C:\jumpstart\wfaguy> Write-LogObject ($service | Select Name,DisplayName,Status)

Name        : [W32Time]
DisplayName : [Windows Time]
Status      : [Running]

PS C:\jumpstart\wfaguy> try { this_is_going_wrong } catch { Write-LogErrorObject $_ }
PS C:\jumpstart\wfaguy> Write-LogError "Ouch, that wasn't ok"
ENDED WITH ERROR
Message               : [The term 'this_is_going_wrong' is not recognized as the name of a cmdlet, function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again.]
Type                  : [System.Management.Automation.CommandNotFoundException]
CategoryInfo          : [ObjectNotFound: (this_is_going_wrong:String) [], CommandNotFoundException]
Exception             : [System.Management.Automation.CommandNotFoundException: The term 'this_is_going_wrong' is not recognized as the name of a cmdlet,  function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again.
   at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext funcContext, Exception exception)
   at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)
   at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
   at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)]
FullyQualifiedErrorId : [CommandNotFoundException]
InvocationInfo        : [System.Management.Automation.InvocationInfo]
ScriptStackTrace      : [at <ScriptBlock>, <No file>: line 1]
TargetObject          : [this_is_going_wrong] 

Awesome right ?  Now I can hear you think... That's it ?  This guy is nuts.  But... read on.

Initialize-Logger

Watch what happens, if you initialize the logger...  Note that I have added help in the code, get-help is your friend.

PS C:\jumpstart\wfaguy> get-help Initialize-Logger -full

NAME
    Initialize-Logger
    
SYNOPSIS
    Initialize log4net
    
    
SYNTAX
    Initialize-Logger [-LoggerName] <String> [[-LogPattern] <String>] [[-eventPattern] <String>] [[-maxLogsize] <String>] [[-max
    LogfileCount] <String>] [[-logLevel] <String>] [[-eventLevel] <String>] [<CommonParameters>]
    
    
DESCRIPTION
    Run this once, the logger must be initialized to write to logfiles or eventviewer
    

PARAMETERS
    -LoggerName <String>
        A unique name for your logging events
        
        Required?                    true
         
    -LogPattern <String>
        A pattern of the log messages
        
        Required?                    false
        
    -eventPattern <String>
        
        Required?                    false
         
    -maxLogsize <String>
        Maximum logfile size in megabyte
        
        Required?                    false
        
    -maxLogfileCount <String>
        Maximum number of logfiles (rolling)
        
        Required?                    false
      
    -logLevel <String>
        The logging level for logfiles
        
        Required?                    false
       
    -eventLevel <String>
        The logging level for eventviewer
        
        Required?                    false




PS C:\jumpstart\wfaguy> Initialize-Logger -LoggerName "WfaGuy"


EmittedNoAppenderWarning : False
Root                     : log4net.Repository.Hierarchy.RootLogger
LoggerFactory            : log4net.Repository.Hierarchy.DefaultLoggerFactory
Name                     : WfaGuyLogger
Threshold                : ALL
RendererMap              : log4net.ObjectRenderer.RendererMap
PluginMap                : log4net.Plugin.PluginMap
LevelMap                 : log4net.Core.LevelMap
Configured               : False
ConfigurationMessages    : {}
Properties               : {}

LastWriteTime : 9/12/2016 18:50:41
Length        : 0
Name          : WfaGuy.log


PS C:\jumpstart\wfaguy> Write-LogTitle "This is a nice title"
This is a nice title
--------------------

PS C:\jumpstart\wfaguy> Write-LogInfo "This is a message"
This is a message

PS C:\jumpstart\wfaguy> Write-LogVerbose "This is a verbose message"

PS C:\jumpstart\wfaguy> Write-LogWarning "Watch out!"
WARNING: Watch out!

PS C:\jumpstart\wfaguy> Write-LogError "Oooh, that hurts"
Oooh, that hurts

PS C:\jumpstart\wfaguy> type .\WfaGuy.log

2016-12-09 18:51:07,663 INFO  WfaGuy : This is a nice title
2016-12-09 18:51:07,679 INFO  WfaGuy : --------------------
2016-12-09 18:51:15,235 INFO  WfaGuy : This is a message
2016-12-09 18:51:37,116 WARN  WfaGuy : Watch out!
2016-12-09 18:51:47,554 ERROR WfaGuy : Oooh, that hurts

PS C:\jumpstart\wfaguy> Remove-Logger

PS C:\jumpstart\wfaguy> Initialize-Logger "WfaGuy" -logLevel debug

PS C:\jumpstart\wfaguy> Write-LogVerbose "This is a verbose message"

PS C:\jumpstart\wfaguy> type .\WfaGuy.log

2016-12-09 18:51:07,663 INFO  WfaGuy : This is a nice title
2016-12-09 18:51:07,679 INFO  WfaGuy : --------------------
2016-12-09 18:51:15,235 INFO  WfaGuy : This is a message
2016-12-09 18:51:37,116 WARN  WfaGuy : Watch out!
2016-12-09 18:51:47,554 ERROR WfaGuy : Oooh, that hurts
2016-12-09 18:53:38,748 DEBUG WfaGuy : This is a verbose message

PS C:\jumpstart\wfaguy> 

Like that already ?  Watch the eventlog !


EventViewer Tip

Now, if the eventviewer doesn't show anything, first check your EventLevel setting, because default is set to "Warn", when you initialize.  But second, the "eventsource" can only be created with administrative privileges, so first time to log the eventview, run your PowerShell as "administrator".

You like ?  Do me a favour and leave some comment, so I know someone actually reads this :)

You want to set the eventid ?  Well, how about this, all the logging functions support parameters "eventid" & "category".

What about WFA ?

I already use this in my WFA code as well, adapted with the Get-WFALogger built in.

8 comments :

  1. Hi WFAGUY,

    so, I initialize a logger for a source like "TestApp" with powershell run as admin. Now, when I schedule the script to run every night at 3 AM, how can I log to the previously initialized logger "TestApp"?

    Cheers,
    Olli

    ReplyDelete
    Replies
    1. You just initialize again. Just do it once in each powershell session. It will reuse the same logfile. The initialized is just initializing the log4net.dll, nothing more. I always use log-append, so no worries there. the log file is created where your master script is.

      Delete
    2. Have you tested this on Windows Server 2012 R2? I can't get it to work. Works like a charm when I start PS as admin, but initializing it in a non-admin session and performing a Write-LogError does not show in the eventlog.

      Delete
    3. Well, I've been using this code for quite a while. Agreed, I just recently put it in a single module, but I haven't had any issues. As the article says, the first time you must run it as admin, that's for the eventsource to be created, but afterwards it works find without "run as admin". obviously you need write access to the log and I guess you would need some rights to write to the eventlog. Maybe you need to set-executionpolicy unrestricted ?

      Delete
  2. PS : Just checked : By default, any authenticated user is able to write to application event log. However only administrators can create new event Sources. So it should work as advertised.

    ReplyDelete
  3. Hello WFAGUY,

    I have a question, I can see event viewer entries for Warnings and Errors, however, Information level events are not showing up. I feel like I am missing something?

    Thanks

    ReplyDelete
  4. Hey, yes that's correct. The default eventlevel is set to "warn", assuming you only want to log there when something is wrong. When you initialize the logger, you can set the eventlevel. for example : Initialize-Logger "WfaGuy" -logLevel debug -eventLevel info.

    ReplyDelete