Tag Archives: Logging

My Write-Verbose Best Practice

Leave a reply

If you’ve read this post, and perhaps the ones before it, then you know that my advanced function templates have always used Write-Verbose statements for logging purposes. Anytime you want to log something using my template, it’s using Write-Verbose whether you know it or not. There’s multiple places you can log, and it’s all based on the value of the Log parameter (in 2.0 and greater). As of the 2.x versions, you can use … -Log ToScreen, … -Log ToScreenAndFile, and … -Log ToFile. Again, regardless of which way you choose to log, it’s Write-Verbose that’s doing the work. Okay fine, it’s really Out-File if you’re writing to a file, although my nested function is still called Write-Verbose. That said, there actually was a time when it was all Write-Verbose, even when writing to a file.

So, I’ve always had a specific way to write my logging statements. There’s no agreed upon best practice for Write-Verbose statements, but for me there is, and that’s why I’m writing again today. Maybe it’ll make sense to use this model for yourself, as well.

In the instance where something is about to happen (think, happens right after the current logging statement ends), I strive to use an “ing” word. From what I remember about my grade school years, I remember this as a present progressive. Here’s a few examples.

Write-Verbose -Message "$BlockLocation Setting required variables."
Write-Verbose -Message "$BlockLocation Checking if the current time zone is $DesiredTimeZone."
Write-Verbose -Message "$BlockLocation Collecting Forest FSMO Roles."
Write-Verbose -Message "$BlockLocation Displaying all FSMO Roles."
Write-Verbose -Message "$BlockLocation Downloading $Application installer from S3."
Write-Verbose -Message "$BlockLocation Installing $Application silently."
Write-Verbose -Message "$BlockLocation Invoking user is ""$env:USERDOMAIN\$env:USERNAME"" on the ""$env:COMPUTERNAME"" computer."

In my experience I tent to use an “ing” words about 80 – 90% of the time. There is, however, one other verb form I find myself using, and that’s the past tense verb form. Sometimes, it makes sense to indicate that something has completed even when a new logging, “ing” statement would indicated the previous logging topic had ended. Here’s a few examples from some of my functions.

Write-Verbose -Message "$BlockLocation Determined the time zone is not correctly set for $DesiredTimeZone."
Write-Verbose -Message "$BlockLocation Unhandled exception ($($Error[0].Exception.GetType().FullName))."
Write-Verbose -Message "Connected to Exchange Server: $ExchServ."

While looking for other worthy examples, I did find a few Write-Verbose statements that didn’t include either an “ing,” or “ed” verb. These are very rare for me, but they have been included at times to indicate information to whomever is reading the logging statements.

Notice, however, that they come just before a statement that uses “ing.” They probably shouldn’t be there, and wouldn’t be there if I was writing that tool today. Then again, they might be, as now that I think about it, and look over this older code, the logging differed because of its audience. In this case, having indicated the key and value already existed, did not exist, or did exist and needed correction, was important enough to convey. So much so, the “ing” word didn’t feel as though it was enough.

#region Create Registy Key(s) and add value (if necessary).
If (-Not($Exists)) {
	Write-Verbose -Message "$BlockLocation Registry key and value do not yet exist."
	Write-Verbose -Message "$BlockLocation Creating new Registry key and value."
	[System.Void](New-Item $RegKey -Force | New-ItemProperty -Name $RegName -Value $RegValue -Force)
	$CheckChange = $true
	$FixType = 'changed'

} ElseIf ((Get-ItemProperty -Path $RegKey -Name $RegName -ErrorAction SilentlyContinue).$RegName -ne $RegValue) {
	Write-Verbose -Message "$BlockLocation Registry key and value already exist, but the value is not correct."
	Write-Verbose -Message "$BlockLocation Correcting the Registry value."
	[System.Void](New-Item $RegKey -Force | New-ItemProperty -Name $RegName -Value $RegValue -Force)
	$CheckChange = $true
	$FixType = 'corrected'

} Else {
	Write-Verbose -Message "$BlockLocation Registry key and value already exist, and the value is correct."
}
#endregion

So, there’s that: My Write-Verbose best practice. While it wasn’t a stupid draft so much, there’s one less in the drafts!

Function Logging via Write-Verbose

2 Replies

It wasn’t but a couple weeks ago that I wrote a PowerShell function. That’s nothing new — I write them all the time — but I really liked this function. It was a rewrite on something that I rewrote three years ago. Yes, you read that correctly. Back then I was asked to add error checking and logging, which makes this post all that much more interesting.

So, I’m that guy that wants all my functions to produce objects. I don’t want anything different from my functions, your functions, or any I find anywhere else, either. The script I rewrote as a function, does just that, as they all do. It writes objects to the screen, that you can pipe to an output function, or cmdlet, such as Export-Csv. There’s no need to wrap something like Export-Csv inside a function. In fact, please don’t (unless you have a really solid reason for it, such as making things extremely easy for your not-as-skilled users). Instead, just create objects, and let them be piped. Let the user decided what to do with the objects your functions return.

At some point, it dawns on me: I don’t need my function to do logging now; these objects, whether in a CSV or not, tell me what happened. See, I’m actually collecting errors, and making those an object property, too (when they appear, and they haven’t yet). As of late, I’ve been adding a Notes property to my objects in which to store these errors.

I went along with this thought for a day, or so. I’ll never have to log again, right? I mentioned this to my coworker, and he mildly bursts my bubble, “I like to know what my function is doing.” He was right. Just because I was creating thorough objects didn’t guarantee my objects would completely point to a failure. I still needed a back end file that might aid in troubleshooting the function someday. Ugh, the cheer was gone.

I mentioned Write-Verbose to my coworker, and that’s why we’re here today. I’m not going to introduce you to Write-Verbose, as much as I’m going to show you what I’ve decided to do going forward (for now). My functions will still create objects, that I can export if I want to, but now I’m going to optionally log my Write-Verbose statements. They’re already there, why should I add logging, when I can instead choose to push those verbose statements out to a file? Sounds easy, right? No, it was a pain. Unless of course I’ve overlooked something simple, as that’s always a possibility.

In PowerShell, we have streams and redirection operators. Like, take my verbose stream and send it to a file. Nothing I tried, and it’s possible I missed something, allowed me to write the Verbose stream to the host and to my file, at the same time, until I wrote this function. I’m just going to dump this test of a function here, and walk you through it, in order to show you how I got this to work for me. This is it for me: my functions will continue to create objects and my Write-Verbose statements are going to be available for logging.

If you want to download this function inside of a .ps1 file, click below. I don’t typically make my functions available this way; however, it may be easier to follow if you have your own copy. The download includes both the 1.0 and 1.1 version. Follow along in the 1.1 version.

Function Logging via Write-Verbose Examples (3402 downloads )

This post has evolved into something newer, and better.

Function Logging via Write-Verbose

Function Write-VerboseToLogExample {
# Version: 1.1
# 1.0 : Basic example of Write-Verbose to Log file. It doesn't create objects, too, as I was getting this part working.
# 1.1 : Added objects, too, using Get-Service.
    [CmdletBinding()]
    Param (
    )

    DynamicParam {
        # Create dynamic, Log parameter.
        If ($PSBoundParameters.Verbose) {
            $SingleAttribute = New-Object System.Management.Automation.ParameterAttribute
            $SingleAttribute.Position = 1

            $AttributeCollection = New-Object System.Collections.ObjectModel.Collection[System.Attribute]
            $AttributeCollection.Add($SingleAttribute)

            $LogParameter = New-Object System.Management.Automation.RuntimeDefinedParameter('Log',[switch],$AttributeCollection)
            $LogParameter.Value = $true
 
            $ParamDictionary = New-Object System.Management.Automation.RuntimeDefinedParameterDictionary
            $ParamDictionary.Add('Log',$LogParameter)
            return $ParamDictionary
        } # End If.
    } # End DynamicParam.

    Begin {
        If ($PSBoundParameters.Verbose -and $PSBoundParameters.Log) {
            $Path = "$(Get-Date -Format 'DyyyyMMddThhmmsstt').txt"
            Function Write-Verbose {
                Param ($Message)
                Microsoft.PowerShell.Utility\Write-Verbose -Message "[$(Get-Date)]: $Message"
                Microsoft.PowerShell.Utility\Write-Verbose -Message "[$(Get-Date)]: $Message" 4>> $Path
            }
        }
        Write-Verbose -Message 'Entering the Begin block.'
    } # End Begin.

    Process {
        Write-Verbose -Message 'Entering the Process block.'
        $Services = Get-Service | Select-Object -First 3
        Foreach ($Service in $Services) {
            Write-Verbose -Message "Starting loop/object creation ($($Service.Name))."

            [PSCustomObject]@{
                Status = $Service.Status
                Name = $Service.Name
                DisplayName = $Service.DisplayName 
            }
        }
    } # End Process.

    End {
        Write-Verbose -Message 'Entering the End block.'
    } # End End.
} # End Function: Write-VerboseToLogExample.

# Write-VerboseToLogExample

# Write-VerboseToLogExample -Verbose

# Write-VerboseToLogExample -Log

# Write-VerboseToLogExample -Verbose -Log

Line 1: Declare (or create) the Write-VerboseToLogExample advanced function.

Line 2 – 4: Function info. Help wasn’t included, as this is a Proof of Concept function.

Line 5 – 7: CmdletBinding attribute and Parameter attribute.

Line 9 – 25: Dynamic, Log parameter. This parameter is only available, if the Verbose parameter is included when the function is invoked.

Line 27 – 37: Begin block: This block includes an If statement that results in True if both the Verbose and Log parameters are included when the function is invoked. Providing both are True, we create a $Path variable that holds the name of a text file that’s based on the current date and time. Next, we write a nested function to memory called Write-Verbose. This means that if Write-Verbose is used later in the function, it’ll use our newly defined function instead of the builtin Write-Verbose cmdlet. The function contains two calls to the original Write-Verbose cmdlet, by using its full path. One command writes the Write-Verbose message to the host and the other redirects to a file. This is the entire “magic” behind writing to both the host and a file at the same time. At the end of this Begin block we have a single Write-Verbose statement, that again, will use the new Write-Verbose function, if both parameters were included.

Line 39 – 51: Process block: This block has a opening Write-Verbose statement. Following this, we return the first three services using Get-Service. Then we use the results to create our own custom object from the results. This is simply for demonstration purposes. It’s proof we’re creating objects and writing our Write-Verbose message to two places.

Line 53 – 55: End block: This block has a single Write-Verbose command.

Line 56: Close function declaration from line 1.

The next several lines run the function in one of four ways. The first option runs the function in a standard fashion (no parameters). The second option includes the Verbose parameter which indicates that verbose statements will be written to the host. The third option include a Log parameter without the Verbose parameter. This fails, as the Log parameter is dynamic: It doesn’t exist unless the Verbose parameter is included. The final option includes both the Verbose and Log parameters. Because of our custom, nested function it’ll write verbose messages in our host and in a log file at nearly the same time.

Simple, yet powerful. Here’s the results of those four different function invocations.

PS > Write-VerboseToLogExample

 Status Name                      DisplayName                      
 ------ ----                      -----------                      
Running AdobeARMservice           Adobe Acrobat Update Service     
Stopped AdobeFlashPlayerUpdateSvc Adobe Flash Player Update Service
Stopped AeLookupSvc               Application Experience

—

PS > Write-VerboseToLogExample -Verbose

VERBOSE: Entering the Begin block.
VERBOSE: Entering the Process block.
VERBOSE: Starting loop/object creation (AdobeARMservice).

VERBOSE: Starting loop/object creation (AdobeFlashPlayerUpdateSvc).
VERBOSE: Starting loop/object creation (AeLookupSvc).
VERBOSE: Entering the End block.
 Status Name                      DisplayName                      
 ------ ----                      -----------                      
Running AdobeARMservice           Adobe Acrobat Update Service     
Stopped AdobeFlashPlayerUpdateSvc Adobe Flash Player Update Service
Stopped AeLookupSvc               Application Experience

—

PS > Write-VerboseToLogExample -Log
Write-VerboseToLogExample : A parameter cannot be found that matches parameter name 'Log'.
At line:1 char:27
+ Write-VerboseToLogExample -Log
+                           ~~~~
    + CategoryInfo          : InvalidArgument: (:) [Write-VerboseToLogExample], ParameterBindingException
    + FullyQualifiedErrorId : NamedParameterNotFound,Write-VerboseToLogExample

—

PS > Write-VerboseToLogExample -Verbose -Log
VERBOSE: [11/23/2016 23:07:30]: Entering the Begin block.
VERBOSE: [11/23/2016 23:07:30]: Entering the Process block.
VERBOSE: [11/23/2016 23:07:30]: Starting loop/object creation (AdobeARMservice).

VERBOSE: [11/23/2016 23:07:30]: Starting loop/object creation (AdobeFlashPlayerUpdateSvc).
VERBOSE: [11/23/2016 23:07:30]: Starting loop/object creation (AeLookupSvc).
VERBOSE: [11/23/2016 23:07:30]: Entering the End block.
 Status Name                      DisplayName                      
 ------ ----                      -----------                      
Running AdobeARMservice           Adobe Acrobat Update Service     
Stopped AdobeFlashPlayerUpdateSvc Adobe Flash Player Update Service
Stopped AeLookupSvc               Application Experience

This final example also creates our log file in my current directory.

function-logging-via-write-verbose01

Update: I’ve made a few changes since I first wrote and shared this post. The only change from the above posted and linked version is removing “[$(Get-Date): ” from the first Write-Verbose command inside the nested Write-Verbose function (line 32). After giving it some time, and thought, I didn’t believe it was ever going to be necessary to include the date and time on the screen when Write-Verbose ran. It doesn’t happen when you don’t include the -Log parameter, and so it shouldn’t happen when you do. I left it as a part of the Write-Verbose commands that are written to file, because the date and time are more important there.