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.

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.