In Part-2, we expanded on the basics created a few more variables and created a function ‘Write-Log’, which as the name suggests writes messages to the log file.

In Part-3, we saw how we can manage the multiple log files that get generated using ‘Switch-LogFile’ function.

In Part-4, we saw how we can tie all the components needed (and, then some) for the logger by creating a new object and adding methods that will help us use the newly created object. Also, remember that it is the caller that should instantiate the Logger object and set file properties based on script name.

In this final part we will be seeing how we can use this new module to log our script actions. Before, we start off you need the resources. You can download the zip file containing the scripts here.

Our example, consists of 3 files ‘GrandParent_RunMe.ps1’, ‘Parent.ps1’, ‘Child.ps1’ and of course, the module file ‘PS-Log.psm1’. Let us see, what GrandParent_Runme.ps1 is doing:

	#You need to change the below to match the path where PS-Log module is stored.
	Import-Module D:\Programming\PS-Modules\PS-Log\PS-Log.psm1 -Verbose

	#Get the caller info.
	$scriptInfo = Get-ScriptInfo
	$logFileName = $scriptInfo.Path + '\' + $scriptInfo.Name + '.log'

	#manage your log files before you start writing to them.
	Switch-LogFile -Name $logFileName

	#if you do not call the Get-ScriptInfo method, we can set the log file name
	#using the SetLogFileName method for the object. This way we can have each
	#script called from here have its own log file.
	$gplog = New-LogFile ($scriptInfo.Name, $logFileName)

	$gplog.WritePSInfo("ScriptName = $($scriptInfo.Name.ToString())")
	$gplog.WritePSInfo("Starting script: GrandParent.ps1")
	& .\Parent.ps1
	$gplog.WritePSInfo("Exiting script: GrandParent.ps1")
	Remove-Module PS-Log

As you can see, the script is pretty straight forward, it prints a couple of messages and calls another script in this case ‘Parent.ps1’. Similarly, ‘Parent.ps1’ calls ‘Child.ps1’. ‘Child.ps1’ prints a couple of messages and we pop off the stack returning to ‘GrandParent_RunMe.ps1’. For the Grandparent, we need to edit import-module statement to match the location where the module is.

Let us see what happens when we run ‘GrandParent_RunMe.ps1’…

GrandParent_RunMe First Run

As you can see in the image, we have a new file called ‘GrandParent_RunMe.log’ and all the scripts have logged their actions in this one log. Pretty cool!!

Let us see what happens when we run ‘GrandParent_RunMe.ps1’, again…

GrandParent_RunMe.ps1 second run

As you can see the Switch-LogFile statement did what it was supposed to. It renamed the ‘GrandParent_RunMe.log’ from the frist run to ‘GrandParent_RunMe.001.log’ and creates a new log with script name which is ‘GrandParent_RunMe.log’. Let us check what is written into the log files created in both the runs.

Content from both log files

As we worked through the whole series, we defined a framework and created a module that follows the guidelines set by the framework. Also, this modules allows for a consistent way to log your script actions. Until next time.

In Part-2, we expanded on the basics created a few more variables and created a function ‘Write-Log’, which as the name suggests writes messages to the log file.

InPart-3, we saw how we can manage the multiple log files that get generated using ‘Switch-LogFile’ function.

In this part we will tie everything up and put all the code into a neat little script module that we can use. But, before we do that we need a way to service more than one script in a given session.

In order to achieve this we need to consider the fact that the parent scope of the module is always that of the script that first calls it, unless you forcefully import the module in subsequent scripts. Even then, the statement about the parent scope of the module holds good because the last script that force imports the module is the parent. This is one of the reasons we use ‘Get-PsCallStack’ in the ‘Write-Log’ script. For the sake of example if you assume that we have grandparent.ps1, parent.ps1 and child.ps1. If in the test environment grandparent imports the module, calls parent then the parent scope of the module is grandparent. Now, if we extend this example by having parent call the child and, child force imports the module, then the parent scope of the module will be child instead of grandparent.

The other problem we have is, to know where to put the log file. That is the reason why we chose to put the script in the folder which contains it and then name the log file with the name of the calling script. As in the above example, the script log will always be in grandparent’s folder.

So in order to deal with both the issues, we will be creating custom object using new-object cmdlet and then adding members. This idea was the genius of Michael, Royzman, who is a very wise and respected colleague of mine.

Ok, there is one final function that we need to write before we go off putting everything in a module.

Function New-LogFile {
<#
  .SYNOPSIS
     Instantiate new emty object and adds properties and methods for Log.
  .DESCRIPTION
     This function Instantiate (creates new instance of an object) and adds
     properties and methods to support Logging. This is done to allow calling
     script to create it's own object with log file name specific to the script.
  .PARAMETER scriptName
     Name of the script/program to be used with logged messages.
  .PARAMETER logName
     Full Name of the file where messages will be written.
  .EXAMPLE
	$scriptInfo = Get-ScriptInfo
    $logFileName = $scriptInfo.Path + '\' + $scriptInfo.Name + '.log'
	Switch-LogFile -Name $logFileName
	$hlog = New-LogFile ($scriptInfo.Name, $logFileName)
#>
  	param(
        [string]
        $scriptName = $SCRIPT:ScriptName,
        [string]
        $logName = $SCRIPT:LogFileName
    )
		New-Object Object |
			Add-Member NoteProperty LogFileName $logName -PassThru |
			Add-Member NoteProperty ScriptBaseName $scriptName -PassThru |
			Add-Member ScriptMethod SetLogFileName {
				param([string] $logFileName)
					$this.LogFileName = $logFile
				} -PassThru |
			Add-Member ScriptMethod GetLogFileName {
				param([string] $logFileName)
					$this.LogFileName
				} -PassThru |
			Add-Member ScriptMethod WritePSInfo {
			<#
			   .SYNOPSIS
				Write entry to log file.
			#>
				param($message)
					Write-Log $this.ScriptBaseName $this.LogFileName $MSGTYPE_INFORMATION $message
				} -PassThru |
			Add-Member ScriptMethod WritePSWarning {
			<#
			   .SYNOPSIS
				Write warning entry to log file
			#>
				param($message)
					Write-Log $this.ScriptBaseName $this.LogFileName $MSGTYPE_WARNING $message
				} -PassThru |
			Add-Member ScriptMethod WritePSError {
			<#
			   .SYNOPSIS
				Write error entry to log file.
			#>
				param($message)
					Write-Log $this.ScriptBaseName $this.LogFileName $MSGTYPE_ERROR $message
				} -PassThru
}
# End Function New-LogFile

In Part-2, we expanded on the basics created a few more variables and created a function ‘Write-Log’, which as the name suggests writes messages to the log file.

In this part we will look at managing the logs that we will generate. What I mean is, we will need a way to archive the log files. For this we need a couple of functions:

• Add-BackSlashToPath, this function adds a backslash to a path.
• Switch-LogFile, this function archives the log files that are created for a script.

First let us look at Add-BackSlashToPath. The reason why we need this function is because PowerShell does not always return paths with a backslash appended at the end. So, we append it to the end of the path.

Function Add-BackSlashToPath ($Path){
 <#
  .SYNOPSIS
     Add a backslash to any given path if it is missing.
  .DESCRIPTION
Powershell usually returns path without a backslash.
	This function takes care of that.
	We need not expose this to the environment.
  .EXAMPLE
Add-BackSlashToPath -Path "C:\Test-PS-1"
	C:\Test-PS-1\
  .EXAMPLE
	Add-BackSlashToPath -Path C:\Windows\System32\
	C:\Windows\System32\
  .EXAMPLE
	Add-BackSlashToPath -Path \\comp1\C$\Windows\System32
	\\comp1\C$\Windows\System32\
 #>
	if(Test-Path -Path $Path -IsValid){
		if($Path -match "\\$"){
			$strPath = $Path
		}else{
			$strPath = $Path + "\"
		}
	} else{
		$strPath = ".\"
	}
	$strPath
}

The second function archives the log files. The assumption is that the log file name will be scriptname.log. So, when the program finds a log with the name scriptname.log it will rename the existing log file to scriptname.001.log and then creates a new file with the scriptname.log name. This process will continue until we have as many log files as defined by the number of archives parameter. Once, this limit is reached the function will delete the last log file and update the names for all existing log files in the folder.

Function Switch-LogFile {
<#
  .SYNOPSIS
     Archive the log files for the script.
  .DESCRIPTION
The number of archive files we maintain is determined by the numArch parameter.
	Log file name is ProgramName.log.
  .EXAMPLE
Switch-LogFile -Name "C:\Test-PS-1\First.log" -Arch 10
#>
  Param (
  	[Parameter(Mandatory=$true)][string]$Name,
    [Parameter(Mandatory=$false)][int]$Arch
  )
	try{
		$pathToFile = [System.IO.Path]::GetDirectoryName($Name)
if ( ! (Test-Path -Path "$pathToFile")) {
$pathToFile = New-Item -Path "$pathToFile" -type directory
        }
$pathToFile = Resolve-Path $pathToFile #Get full path for paths passed like '.\filename'
		$pathToFile = Add-BackSlashToPath $pathToFile.Path.ToString()
		$isValidPath = Test-Path -Path "$pathToFile" -IsValid
		Write-Debug $isValidPath
		if(!$Arch){
			$Arch = $NumOfArchives
		}
		if($isValidPath){

			#Get path that can be used by Get-ChildItem (gci) and Test-Path
			$gciLogPath = $pathToFile + "*"
			$Name = $Name.Substring($Name.LastIndexOf('\') + 1)
			$logName = $Name.Substring(0,$Name.Length - 4)
			Write-Debug $gciLogPath
			#Test if the logfile exists
			$defaultLogExists = Test-Path -Path $gciLogPath -include $Name

			#If the default log i.e. "ScriptName.Log" exists
			if($defaultLogExists){
				$dirContent = Get-ChildItem $gciLogPath -Filter "$logName*.log" |Sort-Object -Property Name -Descending| Select-Object Name
				ForEach($fileName in $dirContent){
					if($fileName.Name -match "^*`.\d{3}")
					{
						$matchVal = $Matches[0]
						if(([int]$matchVal.SubString(1,$matchVal.Length-1)) -eq ($Arch))
						{
							Write-Debug "Deleting log file: $($fileName.Name)"
							$fileToDel = $pathToFile + "$($fileName.Name)"
							Remove-Item -LiteralPath $fileToDel
						}else{
							$logNum = $matchVal.SubString(1,$matchVal.Length-1)
							$logNum = "{0:D3}" -f (([int] $logNum) + 1)
							$newName = "$logName.$logNum.log"
							$fullPath = $pathToFile + "$($fileName.Name)"
							Rename-Item -Path $fullPath -NewName "$newName"
						}
					}
				}
				#we are done with all the preprocessing so we can now rename "Log.log"
				#as Log.001.log and create a new default log file.
				$fullPath = $pathToFile + $Name
				Write-Debug $fullPath
				Rename-Item -Path $fullPath -NewName "$logName.001.log"
				$newLogFile = New-Item -Path "$fullPath" -ItemType File -Force

			} else { #default log does not exist go ahead and create the log file.
				$fullPath = $pathToFile + $Name
				$newLogFile = New-Item -Path $fullPath -ItemType File -Force
			}
		}
	} catch{
		Write-Error $_
	}
}
# End Function Switch-LogFile

We now have a way of managing log files.

In the blog posts till now we have seen how to define a set of guidelines, define our variables based on these guidlines. We also, created a function that will log the data to a log file and created functions that will help us manage the log files that are generated.

In the next part we will tie all of this together and put them in a module so that we can use this as a standard way to log script actions.

The last script block we looked at in the first part, we defined various message types that we wanted to log, we also define an array of severity descriptors and we defined a default logging level that can be overridden during initialization.

Since, one of the goals we set at the onset was to keep it simple; we should not be asking the user where the log file will be created by default, but, at the same time we should be flexible enough to accept any valid path they provide to setup the log file. So, let us by default use the module name and location for log file name. Oh! and the log file always have ‘.log’ extension. The code to do this would be:

# By Default use module name and location for LogFile Name and Script Name.
# Caller should instantiate Logger object and set file properties based on script name.
$SCRIPT:LogFileName = [System.IO.Path]::GetFilenameWithoutExtension($MyInvocation.MyCommand.Path.ToString())
$SCRIPT:ScriptName = [System.IO.Path]::GetFilenameWithoutExtension($MyInvocation.MyCommand.Path.ToString())
$SCRIPT:LogFileName += '.log'

The other thing we could do is maintain only a limited number of logfiles. Truth be told, having 200 logfiles is not going to help unless, you are looking for an anamoly that concerns counting. So, our code above gets a new line that can tell us how many log files we want. Again, we can use a default value if the user cannot be bothered or allow the user to manage this number if they are interested in this.

[int]$SCRIPT:NumOfArchives = 10

Now that we have some of the groundwork prepared, let us attmept to write a funciton that will eventually write the messages to the log file. At this point you might be thinking, should I be logging everything? Not necessarily. In order to avoid an overflow of information we will only log messages that have a severity level greater than or equal to the logging level we defined earlier. Also, not only should we write the messages to the log file, we also need to display the information on the host as well. In order to display the information on the host, we will write Information in magenta, warnings in yellow and errors in red.

Function Write-Log {
<#
  .SYNOPSIS
     Write a message to the Log file.
  .DESCRIPTION
    Logs a message to the logfile if the severity is higher than or equal to $LogLevel.
	Default severity level is information.
  .PARAMETER scriptName
     Name of the script/program to be used with logged messages.
     Use the $MSGTYPE_XXXX constants.
  .PARAMETER logName
     Full Name of the file where messages will be written.
  .PARAMETER severity
     The severity of the message.  Can be Information, Warning, or Error.
     Use the $MSGTYPE_XXXX constants.
  .PARAMETER message
     A string to be printed to the log.

  .EXAMPLE
     Write-Log $MSGTYPE_ERROR "Something has gone terribly wrong!"
#>
  	param(
        [string]
        $scriptName = $SCRIPT:ScriptName,
        [string]
        $logName = $SCRIPT:LogFileName,
        [Parameter(Mandatory=$true)]
        [int]
        [ValidateScript({$MSGTYPE_INFORMATION, $MSGTYPE_WARNING, $MSGTYPE_ERROR -contains $_})]
        $severity,
        [Parameter(Mandatory=$true)]
        [string]
        $message
    )
	try
	{
		if ($severity -ge $LogLevel)
		{
			$timestamp = Get-Date -Format 'yyyy-MM-dd HH:mm:ss'
			$callerName = (Get-PSCallStack)[2].InvocationInfo.MyCommand.Name
			$output = "$timestamp`t`[$($SEVERITY_DESC[$severity])`]: ($callerName)`t$message"

			Write-Output $output >> $logName

			switch($severity)
			{
				$MSGTYPE_INFORMATION {Write-Host $output -Fore Magenta; break}
				$MSGTYPE_WARNING 	{Write-Host $output -Fore Yellow; break}
				$MSGTYPE_ERROR 	    {Write-Host $output -Fore Red; break}
			}
		}
	}
	catch
	{
		$ex = $_.Exception
		$excMsg = $ex.Message.ToString()
		Write-Host "[Write-Log]: "$excMsg -Fore Red

		while ($ex.InnerException)
		{
			$ex = $ex.InnerException
			$excMsg = $ex.InnerException.Message.ToString()
			Write-Host "`t" $ex.InnerException.Message -Fore Red
		}
	}
}

In the next part we will talk about managing the log files. All the fun stuff with sweeping the files and keeping the correct number of log files available, so on and so forth.

How much logging you want to do depends on the kind of scripts you write. Exploratory scripting might not require you log everything but, during script development it is going to be useful to have knowledge of what your script is doing and it would be good to know what the hell is wrong is that one particular function that you can’t seem to quite figure out. When you are putting out a production script it may become mandatory to log what the script is doing or at the very least log what actions the script is performing.

How do we log what the script is doing?
There are several ways in which you can log your script actions. From using the Write-* cmdlets, adding a function for writing to the logs in all your scripts, using .NET solution like log4net or writing a module that does the logging for you.

Whichever approach you choose, the basic requirements are that it should be:

• Easy to use.
• Easy to extend to various targets.
• Portable.
• Possible to enable/disable certain components.

Where do we start?
Now that we established that logging your script actions is a good thing and formed some sort of rudimentary guidelines as to how we want to log our actions, we need to determine what we want to log.

The most common actions you would want to log would be errors, and then maybe warnings and some interesting informational messages as well could be worth putting out there for us to investigate at a later time. But, since one of the goals is to be able to make setup configurable, we should be able to configure the level of logging we do as well. So, we will use something to control the type of events we capture by default. Putting this into code we get

#Set severity constants
Set-Variable -Name MSGTYPE_INFORMATION -Value 0 -Option ReadOnly
Set-Variable -Name MSGTYPE_WARNING -Value 1 -Option ReadOnly
Set-Variable -Name MSGTYPE_ERROR -Value 2 -Option ReadOnly

# Set severity description
Set-Variable -Name SEVERITY_DESC -Value 'PS-Info', 'PS-Warn', 'PS-Error' -Option Constant

# Initialize configurable settings for logging
# These values will be be used as default unless overwritten by calling script.
[int]$LogLevel = $MSGTYPE_INFORMATION

Cool, we have a good start. Let us continue on this path for a few more days and see where we end up. It is 2:00 AM so, the next blog post has to wait for at least 6hrs..